brentd / nstance

🔶 Ruby library for running arbitrary shell commands in Docker containers
MIT License
2 stars 0 forks source link

Exception raised when output limit is exceeded 🙅‍♀️ #1

Open mason-stewart opened 4 years ago

mason-stewart commented 4 years ago

Hi @brentd. Thanks for working on this gem. It's great 🎉

I've noticed that nstance seems to handle exceeded output limits in unexpected ways. Given a limit of 30KB bytes with container output that's roughly 107KB, I got an error about trying to map over nil, and the result object's status and error attributes weren't set. Here's an example stack trace with the output santized:

[5] pry(main)> result = instance.run("cool_parser input.csv", output_limit: 30000)
D, [2019-10-30T13:04:14.229620 #32749] DEBUG -- nstance: Command e6564917 scheduled: "cool_parser input.csv"
D, [2019-10-30T13:04:14.230081 #32749] DEBUG -- nstance: Creating container: {:Image=>"amazing-docker-image:latest", :Cmd=>["sh"], :Labels=>{"nstance"=>"6feb191d-9e1b-4a78-b0a8-5a9b474cb4f9"}, :OpenStdin=>true, :StdinOnce=>true, "name"=>"nstance_6feb191d-9e1b-4a78-b0a8-5a9b474cb4f9"}
D, [2019-10-30T13:04:14.271251 #32749] DEBUG -- nstance: Creating container: {:Image=>"amazing-docker-image:latest", :Cmd=>["sh"], :Labels=>{"nstance"=>"a8ada766-fd3c-4772-a914-61783afffb9e"}, :OpenStdin=>true, :StdinOnce=>true}
D, [2019-10-30T13:04:17.004523 #32749] DEBUG -- nstance: Command 9e0631a0 received data: [stdout] "lots of cool data"
D, [2019-10-30T13:04:17.005046 #32749] DEBUG -- nstance: Command 9e0631a0 event:chunk, payload:[:stdout, "even more cool data"]
D, [2019-10-30T13:04:17.006066 #32749] DEBUG -- nstance: Command 9e0631a0 event:line, payload:[:stdout, "wow that's a lot of cool data"]
(Imagine tons of cool data here)
D, [2019-10-30T13:04:18.265945 #32749] DEBUG -- nstance: Command e6564917 event:complete, payload:[---
stdout | "lots of cool data"
stdout | "even more cool data"
stdout | "wow that's a lot of cool data"
(Imagine tons of cool data here)
--- exit status: output_limit_exceeded]
#<Thread:0x00007fef3b87b608@~/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/bundler/gems/nstance-0f5ed4d1f1a9/lib/nstance/drivers/docker_api/attach_driver.rb:21 run> terminated with exception (report_on_exception is true):
Traceback (most recent call last):
  9: from ~/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/bundler/gems/nstance-0f5ed4d1f1a9/lib/nstance/drivers/docker_api/attach_driver.rb:21:in `block (2 levels) in run'
  8: from ~/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/bundler/gems/nstance-0f5ed4d1f1a9/lib/nstance/drivers/docker_api/attach_driver.rb:52:in `perform'
  7: from ~/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/bundler/gems/nstance-0f5ed4d1f1a9/lib/nstance/drivers/docker_api/attach_driver.rb:52:in `loop'
  6: from ~/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/bundler/gems/nstance-0f5ed4d1f1a9/lib/nstance/drivers/docker_api/attach_driver.rb:60:in `block in perform'
  5: from ~/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/bundler/gems/nstance-0f5ed4d1f1a9/lib/nstance/drivers/docker_api/attach_driver.rb:65:in `rescue in block in perform'
  4: from ~/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/bundler/gems/nstance-0f5ed4d1f1a9/lib/nstance/run_emitter.rb:103:in `receive_error'
  3: from ~/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/bundler/gems/nstance-0f5ed4d1f1a9/lib/nstance/run_emitter.rb:119:in `complete'
  2: from ~/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/bundler/gems/nstance-0f5ed4d1f1a9/lib/nstance/run_emitter.rb:146:in `emit'
  1: from ~/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/bundler/gems/nstance-0f5ed4d1f1a9/lib/nstance/run_emitter.rb:146:in `inspect'
~/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/bundler/gems/nstance-0f5ed4d1f1a9/lib/nstance/result.rb:15:in `inspect': undefined method `map' for nil:NilClass (NoMethodError)
D, [2019-10-30T13:04:18.198825 #32749] DEBUG -- nstance: Command 9e0631a0 event:complete, payload:[---
stdout | "lots of cool data"
stdout | "even more cool data"
stdout | "wow that's a lot of cool data"--- exit status: output_limit_exceeded]
=> #<Nstance::Result:0x3ff7a07ccd24>
#<Thread:0x00007fef3ff4b290@~/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/bundler/gems/nstance-0f5ed4d1f1a9/lib/nstance/drivers/docker_api/attach_driver.rb:21 run> terminated with exception (report_on_exception is true):
Traceback (most recent call last):
  9: from ~/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/bundler/gems/nstance-0f5ed4d1f1a9/lib/nstance/drivers/docker_api/attach_driver.rb:21:in `block (2 levels) in run'
  8: from ~/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/bundler/gems/nstance-0f5ed4d1f1a9/lib/nstance/drivers/docker_api/attach_driver.rb:52:in `perform'
  7: from ~/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/bundler/gems/nstance-0f5ed4d1f1a9/lib/nstance/drivers/docker_api/attach_driver.rb:52:in `loop'
  6: from ~/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/bundler/gems/nstance-0f5ed4d1f1a9/lib/nstance/drivers/docker_api/attach_driver.rb:60:in `block in perform'
  5: from ~/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/bundler/gems/nstance-0f5ed4d1f1a9/lib/nstance/drivers/docker_api/attach_driver.rb:65:in `rescue in block in perform'
  4: from ~/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/bundler/gems/nstance-0f5ed4d1f1a9/lib/nstance/run_emitter.rb:103:in `receive_error'
  3: from ~/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/bundler/gems/nstance-0f5ed4d1f1a9/lib/nstance/run_emitter.rb:119:in `complete'
  2: from ~/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/bundler/gems/nstance-0f5ed4d1f1a9/lib/nstance/run_emitter.rb:146:in `emit'
  1: from ~/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/bundler/gems/nstance-0f5ed4d1f1a9/lib/nstance/run_emitter.rb:146:in `inspect'
~/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/bundler/gems/nstance-0f5ed4d1f1a9/lib/nstance/result.rb:15:in `inspect': undefined method `map' for nil:NilClass (NoMethodError)
[6] pry(main)> result.status
=> nil
[7] pry(main)> result
=> #<Nstance::Result:0x3ff7a07ccd24>
[8] pry(main)> result.error
=> #<NoMethodError: undefined method `<<' for nil:NilClass>
[9] pry(main)> result.lines
=> nil
[10] pry(main)> result.success?
=> false
[11] pry(main)> result.output_limit_exceeded?
=> false

For the time being I've just bumped the allowed output size to resolve the issue in production. Any clue what's happening here?

brentd commented 4 years ago

Thx for the report @masondesu !

I fiddled with this and couldn't reproduce your error. I tried the following:

>> Nstance.log.level = :debug
=> :debug
>> instance = Nstance.create(image: "ruby")
=> #<Nstance::Instance:0x00007ffc1ba18e88 @driver=#<Nstance::Drivers::DockerAPI::AttachDriver:0x00007ffc1ba192c0 @uuid="f900bbd6-ce44-4118-a386-15b940edc773", @image="ruby", @manager=#<Nstance::Drivers::DockerAPI::ContainerManager:0x00007ffc1ba18f78 @image="ruby", @container_opts={:Image=>"ruby", :Cmd=>["sh"], :Labels=>{"nstance"=>"f900bbd6-ce44-4118-a386-15b940edc773"}, :OpenStdin=>true, :StdinOnce=>true, "name"=>"nstance_f900bbd6-ce44-4118-a386-15b940edc773"}, @lock=#<Thread::Mutex:0x00007ffc1ba18f50>>, @parser=#<Nstance::Drivers::DockerAPI::AttachLogParser:0x00007ffc1ba18f28 @buffer="">, @lock=#<Thread::Mutex:0x00007ffc1ba18ed8>, @queue=[]>>
>> instance.run("ruby -e 'puts \"a\" * 300'", output_limit: 100)
D, [2019-10-31T20:47:55.309297 #28722] DEBUG -- nstance: Command 4b6933e9 scheduled: "ruby -e 'puts \"a\" * 300'"
D, [2019-10-31T20:47:55.309569 #28722] DEBUG -- nstance: Creating container: {:Image=>"ruby", :Cmd=>["sh"], :Labels=>{"nstance"=>"f900bbd6-ce44-4118-a386-15b940edc773"}, :OpenStdin=>true, :StdinOnce=>true, "name"=>"nstance_f900bbd6-ce44-4118-a386-15b940edc773"}
D, [2019-10-31T20:47:55.977992 #28722] DEBUG -- nstance: Command 4b6933e9 received data: [stdout] "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa\n"
D, [2019-10-31T20:47:55.978079 #28722] DEBUG -- nstance: Command 4b6933e9 event:chunk, payload:[:stdout, "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa\n"]
D, [2019-10-31T20:47:55.978114 #28722] DEBUG -- nstance: Command 4b6933e9 event:line, payload:[:stdout, "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa\n"]
D, [2019-10-31T20:47:55.978141 #28722] DEBUG -- nstance: Command 4b6933e9 event:complete, payload:[---
stdout | aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa
--- exit status: output_limit_exceeded]
D, [2019-10-31T20:47:55.978176 #28722] DEBUG -- nstance: Removing container: {:Image=>"ruby", :Cmd=>["sh"], :Labels=>{"nstance"=>"f900bbd6-ce44-4118-a386-15b940edc773"}, :OpenStdin=>true, :StdinOnce=>true}
=> ---
stdout | aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa
--- exit status: output_limit_exceeded
>> result = _
=> ---
stdout | aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa
--- exit status: output_limit_exceeded
>> result.status
=> :output_limit_exceeded
>> result.lines
=> [[:stdout, "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa\n"]]

However based on your stack trace it seems like the problem occurs in Result#inspect when lines is nil for some reason, so I pushed 6818722.

Give that sha a try please and let me know if this is fixed. It would be great to have a reproducing test case in the spec suite (that now passes if my commit works) if you have time and you're able to reproduce this consistently.