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 `'

How does your script timeout? Does Unicorn timeout-kill your app or does the timeout block do that? — Hongli
I'm not sure what is causing the timeout. It shouldn't be the unicorn timeout or the timeout block. When the user clicks the button that launches the action the request times out after roughly 18-20 seconds. Which is well before the unicorn timeout of 60s and the timeout block of 120s. Could the request itself be timing itself out if it doesn't hear back from the server for too long? — Chris
I don't know without more details. You should provide a stack trace or something. — Hongli
I've added the backtrace from the timeout error caught. Sorry it took so long. — Chris

Hongli Hongli · Accepted Answer · 2013-05-08T21:05:37

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.

Ruby on Rails call to perl script timing out

1 Answers