We use Ruby 2.1.2, Rails 3.2.19 with JQuery 1.11, the resource pipeline is not used (therefore, do not use JQuery-ujs, but we explicitly use the appropriate rails.js). For most users, jQuery and other related common plugins are extracted from the Google CDN (including jquery.form 3.50). The web server is affected by Ubuntu 14.04, Nginx 1.6 and Passenger 4.x.
About 10% of the users of our production server (the load seems unimportant), we get a stack dump, like this, mainly for one URL, but there are others:
/gems/rack-1.4.5/lib/rack/multipart/parser.rb:74 in "block in fast_forward_to_first_boundary" /gems/rack-1.4.5/lib/rack/multipart/parser.rb:72 in "loop" /gems/rack-1.4.5/lib/rack/multipart/parser.rb:72 in "fast_forward_to_first_boundary" /gems/rack-1.4.5/lib/rack/multipart/parser.rb:15 in "parse" /gems/rack-1.4.5/lib/rack/multipart.rb:25 in "parse_multipart" /gems/rack-1.4.5/lib/rack/request.rb:336 in "parse_multipart" /gems/rack-1.4.5/lib/rack/request.rb:201 in "POST" /gems/actionpack-3.2.19/lib/action_dispatch/http/request.rb:237 in "POST" /gems/actionpack-3.2.19/lib/action_dispatch/http/parameters.rb:10 in "parameters" /gems/actionpack-3.2.19/lib/action_dispatch/http/filter_parameters.rb:31 in "filtered_parameters" /gems/newrelic_rpm-3.9.3.241/lib/new_relic/agent/instrumentation/rails3/action_controller.rb:31 in "process_action" /gems/actionpack-3.2.19/lib/abstract_controller/base.rb:121 in "process" /gems/actionpack-3.2.19/lib/abstract_controller/rendering.rb:45 in "process" /gems/actionpack-3.2.19/lib/action_controller/metal.rb:203 in "dispatch" /gems/actionpack-3.2.19/lib/action_controller/metal/rack_delegation.rb:14 in "dispatch" /gems/actionpack-3.2.19/lib/action_controller/metal.rb:246 in "block in action" /gems/actionpack-3.2.19/lib/action_dispatch/routing/route_set.rb:73 in "call" /gems/actionpack-3.2.19/lib/action_dispatch/routing/route_set.rb:73 in "dispatch" /gems/actionpack-3.2.19/lib/action_dispatch/routing/route_set.rb:36 in "call" /gems/journey-1.0.4/lib/journey/router.rb:68 in "block in call" /gems/journey-1.0.4/lib/journey/router.rb:56 in "each" /gems/journey-1.0.4/lib/journey/router.rb:56 in "call" /gems/actionpack-3.2.19/lib/action_dispatch/routing/route_set.rb:608 in "call" /gems/newrelic_rpm-3.9.3.241/lib/new_relic/agent/instrumentation/middleware_tracing.rb:57 in "call" /gems/newrelic_rpm-3.9.3.241/lib/new_relic/rack/error_collector.rb:50 in "traced_call" /gems/newrelic_rpm-3.9.3.241/lib/new_relic/agent/instrumentation/middleware_tracing.rb:55 in "call" /gems/newrelic_rpm-3.9.3.241/lib/new_relic/rack/agent_hooks.rb:26 in "traced_call" /gems/newrelic_rpm-3.9.3.241/lib/new_relic/agent/instrumentation/middleware_tracing.rb:55 in "call" /gems/newrelic_rpm-3.9.3.241/lib/new_relic/rack/browser_monitoring.rb:23 in "traced_call" /gems/newrelic_rpm-3.9.3.241/lib/new_relic/agent/instrumentation/middleware_tracing.rb:55 in "call" /gems/oink-0.10.1/lib/oink/middleware.rb:17 in "call" /gems/newrelic_rpm-3.9.3.241/lib/new_relic/agent/instrumentation/middleware_tracing.rb:57 in "call" /gems/warden-1.2.3/lib/warden/manager.rb:35 in "block in call" /gems/warden-1.2.3/lib/warden/manager.rb:34 in "catch" /gems/warden-1.2.3/lib/warden/manager.rb:34 in "call" /gems/newrelic_rpm-3.9.3.241/lib/new_relic/agent/instrumentation/middleware_tracing.rb:57 in "call" /gems/actionpack-3.2.19/lib/action_dispatch/middleware/best_standards_support.rb:17 in "call" /gems/newrelic_rpm-3.9.3.241/lib/new_relic/agent/instrumentation/middleware_tracing.rb:57 in "call" /gems/rack-1.4.5/lib/rack/etag.rb:23 in "call" /gems/newrelic_rpm-3.9.3.241/lib/new_relic/agent/instrumentation/middleware_tracing.rb:57 in "call" /gems/rack-1.4.5/lib/rack/conditionalget.rb:25 in "call" /gems/newrelic_rpm-3.9.3.241/lib/new_relic/agent/instrumentation/middleware_tracing.rb:57 in "call" /gems/actionpack-3.2.19/lib/action_dispatch/middleware/head.rb:14 in "call" /gems/newrelic_rpm-3.9.3.241/lib/new_relic/agent/instrumentation/middleware_tracing.rb:57 in "call" /gems/actionpack-3.2.19/lib/action_dispatch/middleware/params_parser.rb:21 in "call" /gems/newrelic_rpm-3.9.3.241/lib/new_relic/agent/instrumentation/middleware_tracing.rb:57 in "call" /gems/actionpack-3.2.19/lib/action_dispatch/middleware/flash.rb:242 in "call" /gems/newrelic_rpm-3.9.3.241/lib/new_relic/agent/instrumentation/middleware_tracing.rb:57 in "call" /gems/rack-1.4.5/lib/rack/session/abstract/id.rb:210 in "context" /gems/rack-1.4.5/lib/rack/session/abstract/id.rb:205 in "call" /gems/newrelic_rpm-3.9.3.241/lib/new_relic/agent/instrumentation/middleware_tracing.rb:57 in "call" /gems/actionpack-3.2.19/lib/action_dispatch/middleware/cookies.rb:341 in "call" /gems/newrelic_rpm-3.9.3.241/lib/new_relic/agent/instrumentation/middleware_tracing.rb:57 in "call" /gems/activerecord-3.2.19/lib/active_record/query_cache.rb:64 in "call" /gems/newrelic_rpm-3.9.3.241/lib/new_relic/agent/instrumentation/middleware_tracing.rb:57 in "call" /gems/activerecord-3.2.19/lib/active_record/connection_adapters/abstract/connection_pool.rb:479 in "call" /gems/newrelic_rpm-3.9.3.241/lib/new_relic/agent/instrumentation/middleware_tracing.rb:57 in "call" /gems/actionpack-3.2.19/lib/action_dispatch/middleware/callbacks.rb:28 in "block in call" /gems/activesupport-3.2.19/lib/active_support/callbacks.rb:405 in "_run__3807242266783802268__call__1942732928323145202__callbacks" /gems/activesupport-3.2.19/lib/active_support/callbacks.rb:405 in "__run_callback" /gems/activesupport-3.2.19/lib/active_support/callbacks.rb:385 in "_run_call_callbacks" /gems/activesupport-3.2.19/lib/active_support/callbacks.rb:81 in "run_callbacks" /gems/actionpack-3.2.19/lib/action_dispatch/middleware/callbacks.rb:27 in "call" /gems/newrelic_rpm-3.9.3.241/lib/new_relic/agent/instrumentation/middleware_tracing.rb:57 in "call" /gems/rack-1.4.5/lib/rack/sendfile.rb:102 in "call" /gems/newrelic_rpm-3.9.3.241/lib/new_relic/agent/instrumentation/middleware_tracing.rb:57 in "call" /gems/actionpack-3.2.19/lib/action_dispatch/middleware/remote_ip.rb:31 in "call" /gems/newrelic_rpm-3.9.3.241/lib/new_relic/agent/instrumentation/middleware_tracing.rb:57 in "call" /gems/newrelic_rpm-3.9.3.241/lib/new_relic/agent/instrumentation/middleware_tracing.rb:57 in "call" /gems/actionpack-3.2.19/lib/action_dispatch/middleware/debug_exceptions.rb:16 in "call" /gems/newrelic_rpm-3.9.3.241/lib/new_relic/agent/instrumentation/middleware_tracing.rb:57 in "call" /gems/actionpack-3.2.19/lib/action_dispatch/middleware/show_exceptions.rb:56 in "call" /gems/newrelic_rpm-3.9.3.241/lib/new_relic/agent/instrumentation/middleware_tracing.rb:57 in "call" /gems/railties-3.2.19/lib/rails/rack/logger.rb:32 in "call_app" /gems/railties-3.2.19/lib/rails/rack/logger.rb:18 in "call" /gems/newrelic_rpm-3.9.3.241/lib/new_relic/agent/instrumentation/middleware_tracing.rb:57 in "call" /gems/actionpack-3.2.19/lib/action_dispatch/middleware/request_id.rb:22 in "call" /gems/newrelic_rpm-3.9.3.241/lib/new_relic/agent/instrumentation/middleware_tracing.rb:57 in "call" /gems/rack-1.4.5/lib/rack/methodoverride.rb:21 in "call" /gems/newrelic_rpm-3.9.3.241/lib/new_relic/agent/instrumentation/middleware_tracing.rb:57 in "call" /gems/rack-1.4.5/lib/rack/runtime.rb:17 in "call" /gems/newrelic_rpm-3.9.3.241/lib/new_relic/agent/instrumentation/middleware_tracing.rb:57 in "call" /gems/activesupport-3.2.19/lib/active_support/cache/strategy/local_cache.rb:72 in "call" /gems/newrelic_rpm-3.9.3.241/lib/new_relic/agent/instrumentation/middleware_tracing.rb:57 in "call" /gems/rack-1.4.5/lib/rack/lock.rb:15 in "call" /gems/newrelic_rpm-3.9.3.241/lib/new_relic/agent/instrumentation/middleware_tracing.rb:57 in "call" /gems/rack-cache-1.2/lib/rack/cache/context.rb:136 in "forward" /gems/rack-cache-1.2/lib/rack/cache/context.rb:245 in "fetch" /gems/rack-cache-1.2/lib/rack/cache/context.rb:185 in "lookup" /gems/rack-cache-1.2/lib/rack/cache/context.rb:66 in "call!" /gems/rack-cache-1.2/lib/rack/cache/context.rb:51 in "call" /gems/newrelic_rpm-3.9.3.241/lib/new_relic/agent/instrumentation/middleware_tracing.rb:57 in "call" /gems/newrelic_rpm-3.9.3.241/lib/new_relic/agent/instrumentation/middleware_tracing.rb:57 in "call" /gems/railties-3.2.19/lib/rails/engine.rb:484 in "call" /gems/railties-3.2.19/lib/rails/application.rb:231 in "call" /gems/railties-3.2.19/lib/rails/railtie/configurable.rb:30 in "method_missing" /gems/rack-1.4.5/lib/rack/urlmap.rb:64 in "block in call" /gems/rack-1.4.5/lib/rack/urlmap.rb:49 in "each" /gems/rack-1.4.5/lib/rack/urlmap.rb:49 in "call" /gems/newrelic_rpm-3.9.3.241/lib/new_relic/agent/instrumentation/middleware_tracing.rb:57 in "call" /gems/sass-3.2.19/lib/sass/plugin/rack.rb:54 in "call" /gems/newrelic_rpm-3.9.3.241/lib/new_relic/agent/instrumentation/middleware_tracing.rb:57 in "call" /var/www/.rvm/gems/ruby-2.1.2/gems/passenger-4.0.45/lib/phusion_passenger/rack/thread_handler_extension.rb:74 in "process_request" /var/www/.rvm/gems/ruby-2.1.2/gems/passenger-4.0.45/lib/phusion_passenger/request_handler/thread_handler.rb:141 in "accept_and_process_next_request" /var/www/.rvm/gems/ruby-2.1.2/gems/passenger-4.0.45/lib/phusion_passenger/request_handler/thread_handler.rb:109 in "main_loop" /var/www/.rvm/gems/ruby-2.1.2/gems/passenger-4.0.45/lib/phusion_passenger/request_handler.rb:448 in "block (3 levels) in start_threads"
Before upgrading to jQuery 1.11 from 1.5 (!), This error did not occur (or, if it was, it was very rare). We still have not been able to reproduce this error either on our intermediate server or in the development environment. One support person saw him in production once (I tried it several times), but could not replicate during production (this is the same environment as production, although fewer resources). JQuery porting does not show any problems at startup, and, as I said, it works for most users; during debugging sessions nothing seems wrong. There is no visible picture for the OS / platform or browser (they tried to reproduce several, and the logs do not indicate a template, although it is difficult to sift to be sure). The main URL is linked by C # with a new action on the form controller. We have several other forms on the platform, and they do not show any problems.
Since I cannot reproduce it, it is impossible to give a piece of code - I do not know what to determine exactly.
My interpretation of the error so far (based on the first line in the stack dump) is one of three things:
- the content is otherwise correct, but not completely formed in any way,
- the content is poorly formed, suggesting a Ruby error (although possibly JS)
- bad coding (I use form_for in Ruby and even threw "multipart: true" to be explicit)
I see that Rack is dealing with the related multiple EOFError issue in 4.x, but we are launching Rails 3.2.19, which blocks us in an older version and upgrading to Rails 4.x is currently impractical. As a test, I tried jQuery to 1.7, but did not seem to change its behavior (everything is older, and I will have to abandon the code updates needed for jQuery 1.8 +).
Since the jQuery code caused changes in our JS, I suspected that I had missed some necessary JS changes, but nothing seems to be wrong. There have also been some CSS changes, but I don’t see how this can affect things (since everything went in different test environments, other changes were also included in the deployment).
I suspected JS problems in the first place, but some limited production tests (I have to be careful on a real server, therefore cannot be too aggressive) did not find any hints or did not cause any errors that seem to be related.
As a background, I have about a year of experience working with Ruby and JS (albeit many years on other programming platforms), so it’s quite possible that this is something basic that I am not familiar with.
It’s hard for me to narrow down where to focus in order to deal with this. Any advice to diagnose or decide?
UPDATE (10/11/14) I monkey paid Rack::Multipart::Parser.fast_forward_to_first_boundary (thanks, Isaac Betesh!) To add traces of the log and confirmed that the content passed to the parser is empty when it reaches this (i.e. e. StringIO, pointed to by @env['rack.input'] during multi- @env['rack.input'] parsing, does not return data). My theory is that it mistakenly expects multipart data when there is none. Again, this only happens periodically and is well versed in many other calls to the same page. Since we are running Passenger 4.x and Nginx, I did not rule out a buffering problem.