Ruby on Rails call to perl script timing out

Question

I'm am writing a Ruby on Rails application that is calling a perl script using Open3. However, when calling the perl script my app keeps raising a Timeout::Error sooner than I want. The code where I call the script looks like this:

  Timeout::timeout(120){
       @stdout, @stderr, @exit_code  = Open3.capture3(@command)
      [@exit_code.to_i, @stdout, @stderr]
  }

I realize calling a potentially "long" running script (maybe 20-30 seconds tops) isn't ideal for a ruby on rails application, but I don't have much of an option.

I am using unicorn to get concurrency and I have the unicorn timeout set to 60s. Despite the 60second timeout in my unicorn file and the 120second timeout wrapped around the Open3 call, my request keeps timing out at around 18 seconds. I know the script is finishing successfully because I see the results on the other side but I need my app to wait for the return of the script.

Is there any other way I can force my rails app to wait and not timeout?

Thanks!

Backtrace from caught error:

execution expired
/opt/sen/ruby/lib/ruby/1.9.1/open3.rb:280:in `value'
/opt/sen/ruby/lib/ruby/1.9.1/open3.rb:280:in `block in capture3'
/opt/sen/ruby/lib/ruby/1.9.1/open3.rb:208:in `popen_run'
/opt/sen/ruby/lib/ruby/1.9.1/open3.rb:90:in `popen3'
/opt/sen/ruby/lib/ruby/1.9.1/open3.rb:270:in `capture3'
/opt/sen/bpt/releases/aa47354a897077a6600349fd6c473704bb17f929/app/models/perl_exec.rb:23:in `block in execute'
/opt/sen/ruby/lib/ruby/1.9.1/timeout.rb:68:in `timeout'
/opt/sen/bpt/releases/aa47354a897077a6600349fd6c473704bb17f929/app/models/perl_exec.rb:22:in `execute'
/opt/sen/bpt/releases/aa47354a897077a6600349fd6c473704bb17f929/app/models/reservoir.rb:47:in `execute!'
/opt/sen/bpt/releases/aa47354a897077a6600349fd6c473704bb17f929/app/models/reservation.rb:93:in `commit!'
/opt/sen/bpt/releases/aa47354a897077a6600349fd6c473704bb17f929/app/controllers/reservations_controller.rb:106:in `block in commit'
/opt/sen/ruby/lib/ruby/1.9.1/timeout.rb:68:in `timeout'
/opt/sen/bpt/releases/aa47354a897077a6600349fd6c473704bb17f929/app/controllers/reservations_controller.rb:105:in `commit'
/opt/sen/ruby/lib/ruby/gems/1.9.1/gems/actionpack-3.2.9/lib/action_controller/metal/implicit_render.rb:4:in `send_action'
/opt/sen/ruby/lib/ruby/gems/1.9.1/gems/actionpack-3.2.9/lib/abstract_controller/base.rb:167:in `process_action'
/opt/sen/ruby/lib/ruby/gems/1.9.1/gems/actionpack-3.2.9/lib/action_controller/metal/rendering.rb:10:in `process_action'
/opt/sen/ruby/lib/ruby/gems/1.9.1/gems/actionpack-3.2.9/lib/abstract_controller/callbacks.rb:18:in `block in process_action'
/opt/sen/ruby/lib/ruby/gems/1.9.1/gems/activesupport-3.2.9/lib/active_support/callbacks.rb:469:in `_run__3753465240598785610__process_action__3320622668841691210__callbacks'
/opt/sen/ruby/lib/ruby/gems/1.9.1/gems/activesupport-3.2.9/lib/active_support/callbacks.rb:405:in `__run_callback'
/opt/sen/ruby/lib/ruby/gems/1.9.1/gems/activesupport-3.2.9/lib/active_support/callbacks.rb:385:in `_run_process_action_callbacks'
/opt/sen/ruby/lib/ruby/gems/1.9.1/gems/activesupport-3.2.9/lib/active_support/callbacks.rb:81:in `run_callbacks'
/opt/sen/ruby/lib/ruby/gems/1.9.1/gems/actionpack-3.2.9/lib/abstract_controller/callbacks.rb:17:in `process_action'
/opt/sen/ruby/lib/ruby/gems/1.9.1/gems/actionpack-3.2.9/lib/action_controller/metal/rescue.rb:29:in `process_action'
/opt/sen/ruby/lib/ruby/gems/1.9.1/gems/actionpack-3.2.9/lib/action_controller/metal/instrumentation.rb:30:in `block in process_action'
/opt/sen/ruby/lib/ruby/gems/1.9.1/gems/activesupport-3.2.9/lib/active_support/notifications.rb:123:in `block in instrument'
/opt/sen/ruby/lib/ruby/gems/1.9.1/gems/activesupport-3.2.9/lib/active_support/notifications/instrumenter.rb:20:in `instrument'
/opt/sen/ruby/lib/ruby/gems/1.9.1/gems/activesupport-3.2.9/lib/active_support/notifications.rb:123:in `instrument'
/opt/sen/ruby/lib/ruby/gems/1.9.1/gems/actionpack-3.2.9/lib/action_controller/metal/instrumentation.rb:29:in `process_action'
/opt/sen/ruby/lib/ruby/gems/1.9.1/gems/actionpack-3.2.9/lib/action_controller/metal/params_wrapper.rb:207:in `process_action'
/opt/sen/ruby/lib/ruby/gems/1.9.1/gems/activerecord-3.2.9/lib/active_record/railties/controller_runtime.rb:18:in `process_action'
/opt/sen/ruby/lib/ruby/gems/1.9.1/gems/actionpack-3.2.9/lib/abstract_controller/base.rb:121:in `process'
/opt/sen/ruby/lib/ruby/gems/1.9.1/gems/actionpack-3.2.9/lib/abstract_controller/rendering.rb:45:in `process'
/opt/sen/ruby/lib/ruby/gems/1.9.1/gems/actionpack-3.2.9/lib/action_controller/metal.rb:203:in `dispatch'
/opt/sen/ruby/lib/ruby/gems/1.9.1/gems/actionpack-3.2.9/lib/action_controller/metal/rack_delegation.rb:14:in `dispatch'
/opt/sen/ruby/lib/ruby/gems/1.9.1/gems/actionpack-3.2.9/lib/action_controller/metal.rb:246:in `block in action'
/opt/sen/ruby/lib/ruby/gems/1.9.1/gems/actionpack-3.2.9/lib/action_dispatch/routing/route_set.rb:73:in `call'
/opt/sen/ruby/lib/ruby/gems/1.9.1/gems/actionpack-3.2.9/lib/action_dispatch/routing/route_set.rb:73:in `dispatch'
/opt/sen/ruby/lib/ruby/gems/1.9.1/gems/actionpack-3.2.9/lib/action_dispatch/routing/route_set.rb:36:in `call'
/opt/sen/ruby/lib/ruby/gems/1.9.1/gems/journey-1.0.4/lib/journey/router.rb:68:in `block in call'
/opt/sen/ruby/lib/ruby/gems/1.9.1/gems/journey-1.0.4/lib/journey/router.rb:56:in `each'
/opt/sen/ruby/lib/ruby/gems/1.9.1/gems/journey-1.0.4/lib/journey/router.rb:56:in `call'
/opt/sen/ruby/lib/ruby/gems/1.9.1/gems/actionpack-3.2.9/lib/action_dispatch/routing/route_set.rb:601:in `call'
/opt/sen/ruby/lib/ruby/gems/1.9.1/gems/rack-timeout-0.0.3/lib/rack/timeout.rb:16:in `block in call'
/opt/sen/ruby/lib/ruby/1.9.1/timeout.rb:68:in `timeout'
/opt/sen/ruby/lib/ruby/gems/1.9.1/gems/rack-timeout-0.0.3/lib/rack/timeout.rb:16:in `call'
/opt/sen/bpt/releases/aa47354a897077a6600349fd6c473704bb17f929/app/middleware/nestful.rb:18:in `call'
/opt/sen/ruby/lib/ruby/gems/1.9.1/gems/actionpack-3.2.9/lib/action_dispatch/middleware/best_standards_support.rb:17:in `call'
/opt/sen/ruby/lib/ruby/gems/1.9.1/gems/rack-1.4.1/lib/rack/etag.rb:23:in `call'
/opt/sen/ruby/lib/ruby/gems/1.9.1/gems/rack-1.4.1/lib/rack/conditionalget.rb:35:in `call'
/opt/sen/ruby/lib/ruby/gems/1.9.1/gems/actionpack-3.2.9/lib/action_dispatch/middleware/head.rb:14:in `call'
/opt/sen/ruby/lib/ruby/gems/1.9.1/gems/actionpack-3.2.9/lib/action_dispatch/middleware/params_parser.rb:21:in `call'
/opt/sen/ruby/lib/ruby/gems/1.9.1/gems/actionpack-3.2.9/lib/action_dispatch/middleware/flash.rb:242:in `call'
/opt/sen/ruby/lib/ruby/gems/1.9.1/gems/rack-1.4.1/lib/rack/session/abstract/id.rb:205:in `context'
/opt/sen/ruby/lib/ruby/gems/1.9.1/gems/rack-1.4.1/lib/rack/session/abstract/id.rb:200:in `call'
/opt/sen/ruby/lib/ruby/gems/1.9.1/gems/actionpack-3.2.9/lib/action_dispatch/middleware/cookies.rb:341:in `call'
/opt/sen/ruby/lib/ruby/gems/1.9.1/gems/activerecord-3.2.9/lib/active_record/query_cache.rb:64:in `call'
/opt/sen/ruby/lib/ruby/gems/1.9.1/gems/activerecord-3.2.9/lib/active_record/connection_adapters/abstract/connection_pool.rb:479:in `call'
/opt/sen/ruby/lib/ruby/gems/1.9.1/gems/actionpack-3.2.9/lib/action_dispatch/middleware/callbacks.rb:28:in `block in call'
/opt/sen/ruby/lib/ruby/gems/1.9.1/gems/activesupport-3.2.9/lib/active_support/callbacks.rb:405:in `_run__4121137639594084607__call__1985817909290506524__callbacks'
/opt/sen/ruby/lib/ruby/gems/1.9.1/gems/activesupport-3.2.9/lib/active_support/callbacks.rb:405:in `__run_callback'
/opt/sen/ruby/lib/ruby/gems/1.9.1/gems/activesupport-3.2.9/lib/active_support/callbacks.rb:385:in `_run_call_callbacks'
/opt/sen/ruby/lib/ruby/gems/1.9.1/gems/activesupport-3.2.9/lib/active_support/callbacks.rb:81:in `run_callbacks'
/opt/sen/ruby/lib/ruby/gems/1.9.1/gems/actionpack-3.2.9/lib/action_dispatch/middleware/callbacks.rb:27:in `call'
/opt/sen/ruby/lib/ruby/gems/1.9.1/gems/actionpack-3.2.9/lib/action_dispatch/middleware/remote_ip.rb:31:in `call'
/opt/sen/ruby/lib/ruby/gems/1.9.1/gems/actionpack-3.2.9/lib/action_dispatch/middleware/debug_exceptions.rb:16:in `call'
/opt/sen/ruby/lib/ruby/gems/1.9.1/gems/actionpack-3.2.9/lib/action_dispatch/middleware/show_exceptions.rb:56:in `call'
/opt/sen/ruby/lib/ruby/gems/1.9.1/gems/railties-3.2.9/lib/rails/rack/logger.rb:32:in `call_app'
/opt/sen/ruby/lib/ruby/gems/1.9.1/gems/railties-3.2.9/lib/rails/rack/logger.rb:16:in `block in call'
/opt/sen/ruby/lib/ruby/gems/1.9.1/gems/activesupport-3.2.9/lib/active_support/tagged_logging.rb:22:in `tagged'
/opt/sen/ruby/lib/ruby/gems/1.9.1/gems/railties-3.2.9/lib/rails/rack/logger.rb:16:in `call'
/opt/sen/ruby/lib/ruby/gems/1.9.1/gems/actionpack-3.2.9/lib/action_dispatch/middleware/request_id.rb:22:in `call'
/opt/sen/ruby/lib/ruby/gems/1.9.1/gems/rack-1.4.1/lib/rack/methodoverride.rb:21:in `call'
/opt/sen/ruby/lib/ruby/gems/1.9.1/gems/rack-1.4.1/lib/rack/runtime.rb:17:in `call'
/opt/sen/ruby/lib/ruby/gems/1.9.1/gems/activesupport-3.2.9/lib/active_support/cache/strategy/local_cache.rb:72:in `call'
/opt/sen/ruby/lib/ruby/gems/1.9.1/gems/rack-1.4.1/lib/rack/lock.rb:15:in `call'
/opt/sen/ruby/lib/ruby/gems/1.9.1/gems/actionpack-3.2.9/lib/action_dispatch/middleware/static.rb:62:in `call'
/opt/sen/ruby/lib/ruby/gems/1.9.1/gems/rack-cache-1.2/lib/rack/cache/context.rb:136:in `forward'
/opt/sen/ruby/lib/ruby/gems/1.9.1/gems/rack-cache-1.2/lib/rack/cache/context.rb:143:in `pass'
/opt/sen/ruby/lib/ruby/gems/1.9.1/gems/rack-cache-1.2/lib/rack/cache/context.rb:155:in `invalidate'
/opt/sen/ruby/lib/ruby/gems/1.9.1/gems/rack-cache-1.2/lib/rack/cache/context.rb:71:in `call!'
/opt/sen/ruby/lib/ruby/gems/1.9.1/gems/rack-cache-1.2/lib/rack/cache/context.rb:51:in `call'
/opt/sen/ruby/lib/ruby/gems/1.9.1/gems/railties-3.2.9/lib/rails/engine.rb:479:in `call'
/opt/sen/ruby/lib/ruby/gems/1.9.1/gems/railties-3.2.9/lib/rails/application.rb:223:in `call'
/opt/sen/ruby/lib/ruby/gems/1.9.1/gems/railties-3.2.9/lib/rails/railtie/configurable.rb:30:in `method_missing'
/opt/sen/ruby/lib/ruby/gems/1.9.1/gems/unicorn-4.6.2/lib/unicorn/http_server.rb:552:in `process_client'
/opt/sen/ruby/lib/ruby/gems/1.9.1/gems/unicorn-4.6.2/lib/unicorn/http_server.rb:632:in `worker_loop'
/opt/sen/ruby/lib/ruby/gems/1.9.1/gems/unicorn-4.6.2/lib/unicorn/http_server.rb:500:in `spawn_missing_workers'
/opt/sen/ruby/lib/ruby/gems/1.9.1/gems/unicorn-4.6.2/lib/unicorn/http_server.rb:142:in `start'
/opt/sen/ruby/lib/ruby/gems/1.9.1/gems/unicorn-4.6.2/bin/unicorn_rails:209:in `'
/opt/sen/ruby/bin/unicorn_rails:23:in `load'
/opt/sen/ruby/bin/unicorn_rails:23:in `'

Answer 1

As you can see in the stack trace

/opt/sen/ruby/lib/ruby/gems/1.9.1/gems/rack-timeout-0.0.3/lib/rack/timeout.rb:16:in `call'

you have a Rack middleware (rack-timeout) that forces an additional timeout over the entire request. Configure or remove that middleware and you should be fine.