Menu
We're using Ruby 2.1.2, Rails 3.2.19 with JQuery 1.11, asset pipeline is not being used (so not using JQuery-ujs, but are using relevant rails.js explicitly). For most users, JQuery and other related common plugins are being pulled from Google CDN (including jquery.form 3.50). The web server affected is Ubuntu 14.04, Nginx 1.6, and Passenger 4.x.
For about 10% of users on our production server (loads seem to not matter), we're getting a stack dump like this, primarily 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 an upgrade to JQuery 1.11 from 1.5(!), this error didn't occur (or if it did, it was very rare). We so far have been unable to reproduce this error either on our staging server or in a development environment. A support person saw it on production once (I've tried several times), but couldn't replicate on staging (which is same environment as production, though smaller resourcing). JQuery migrate is not showing any issues when it runs and, as I said, it seems to work for most users; during debug sessions nothing seems amiss. There is no apparent pattern to OS/platform or browser (tried to reproduce on several and logs don't indicate a pattern though hard to sift enough to be sure). The primary URL involved is for a #new action on a form controller. We have several other forms in the platform and they do not show any issues.
Since I can't reproduce it, giving a code snippet is not possible -- I wouldn't know what to pinpoint.
My interpretation of the error so far (based on first line in stack dump) is one of the three things:
I see Rack has dealt with a related multipart EOFError issue in 4.x, but we're running Rails 3.2.19 which locks us at an older version and upgrading to Rails 4.x is not practical at this time. As a test, I've tried JQuery back to as low as 1.7 but didn't seem to change the behavior (any older and I'd have to drop code updates needed for JQuery 1.8+).
Since the JQuery code necessitated changes to our JS, I suspected I missed some necessary JS changes, but nothing seems amiss. There were also some CSS changes nearby, but I don't see how that could affect things (since everything was passing in our various test environments, other changes were also included in the deploy).
I've been suspecting JS issues primarily, but some limited tests on production (I have to be careful on the live server so can't get too aggressive) haven't shown any clues or thrown any errors that seem related.
As background, I have about a year's experience with Ruby and JS (though many more years on other programming platforms) so entirely possible it's something basic I'm unfamiliar with.
I'm having a hard time with narrowing down where to focus to get a handle on this. Any advice either to diagnose or solve?
UPDATE (10/11/14) I monkey patched Rack::Multipart::Parser.fast_forward_to_first_boundary (thanks, Isaac Betesh!) to add log traces and confirmed that the content passed to the parser is empty when it reaches that function (that is, the StringIO referred to by @env['rack.input'] during multipart parsing returns no data). My theory now is that it erroneously expects multipart data when there is there is none. Again, this only happens intermittently and parses fine for many other invocations of this same page. Since we're running under Passenger 4.x and Nginx, I haven't ruled out a buffering issue.
561
This was finally solved and I'm posting what happened in case it's helpful to others.
Summary The original code contained an ajaxSubmit (via jquery.form plugin) in the JS which submitted a form (as a POST) with multipart/form-data encoding (so far so good). The rails controller handling the submission processed the data normally and then redirected to a second href (as a GET). The browser (perhaps still processing through the jquery.form plugin before returning to it's success callback handler) received the redirect and retained the multipart/form-data encoding type. When rack received the GET with multipart encoding still specified, it balked because there was no multipart data to parse.
Sorry, much of this wasn't in evidence in my OP. And it's not clear to me why this worked under an older version of JQuery and the JQuery.form plugin or why it sometimes succeeded under the new JQuery/JQuery.form.
Solution Refactored the controller to no longer redirect, but rather return a URL (as a text render) for the success callback handler of the original ajaxSubmit. The success handler now then does an AJAX GET on the returned URL thereby leaving the workflow intact but avoiding any multipart encoding on the GET request.
tl;dr :
Before the code was ever changed, we had a path involving Jquery.form that went something like this (code example is not meant to be executable, but just as an illustration):
Ruby view (in HAML for form being submitted):
= form_for @someObject, html: {:multipart => true, :class => "someformclass"} do |f|
= f.error_messages
= hidden_field_tag :submitted, true
=# some more fields
%p.submits
= f.submit "Submit", class: "submit"
Ruby controller:
class OurController < ApplicationController
layout false
before_filter :authenticate_user!
# some other actions
def create
# some processing
someObject.save
redirect_to new_feedback_path, :method => :get, :notice => "notice text", status: 303
end
# some other actions
end
JS:
$(document).on('click', '.someformclass .submit', function() {
...
$(this).parents('form').ajaxSubmit({ // uses jquery.form
...
beforeSubmit: function(someargs) {
... blah blah
},
success: function(responseText) {
// ... code to display flash message
if (typeof(window.history.pushState) == 'function') {
window.history.pushState('html', 'sometext', $.cookie('current_url'));
matchFiltersClass(window.location.pathname);
} else {
window.location.hash = '#!' + $.cookie('current_path');
matchFiltersClass($.cookie('current_path'));
}
$('#main_content').html(responseText);
}
});
return false;
});
This was refactored as follows (again, just an illustration):
Ruby view (in HAML for form being submitted): unchanged
Ruby controller:
class OurController < ApplicationController
layout false
before_filter :authenticate_user!
# some other actions
def create
# some processing
someObject.save
flash[:notice] = 'notice text' # NEW LINE
render text: new_feedback path, status: accepted #CHANGED LINE
end
# some other actions
end
JS:
$(document).on('click', '.someformclass .submit', function() {
...
$(this).parents('form').ajaxSubmit({ // uses jquery.form
...
beforeSubmit: function(someargs) {
... blah blah
},
success: function(responseText) {
// ... code to display flash message
$.get(responseText, function(data) { // NEW LINE
if (typeof(window.history.pushState) == 'function') {
window.history.pushState('html', 'sometext', $.cookie('current_url'));
matchFiltersClass(window.location.pathname);
} else {
window.location.hash = '#!' + $.cookie('current_path');
matchFiltersClass($.cookie('current_path'));
}
$('#main_content').html(responseText);
}); // NEW LINE
}
});
return false;
});
This solution was found with some help with a local developer (thanks, Dan Axtman!) and not without a fair amount of time in monkey-patched logging in Rack (thanks, Isaac Betesh!). At least I learned something about Rack and monkey patching in the process...
89
If you love us? You can donate to us via Paypal or buy me a coffee so we can maintain and grow! Thank you!
Donate Us With