机架投掷EOFError(坏内容正文)

我们使用Ruby 2.1.2,Rails 3.2.19和JQuery 1.11,资源管道没有被使用(所以不使用JQuery-ujs,但显式使用了相关的rails.js)。 对于大多数用户来说,JQuery和其他相关的常见插件都是从Google CDN中提取的(包括jquery.form 3.50)。 受影响的Web服务器是Ubuntu 14.04,Nginx 1.6和Passenger 4.x.

对于我们生产服务器上大约10%的用户(负载似乎无关紧要),我们正在获得这样的堆栈转储,主要用于一个URL,但还有其他一些:

/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" 

在从1.5(!)升级到JQuery 1.11之前,没有发生此错误(或者如果它发生,则非常罕见)。 到目前为止,我们无法在登台服务器或开发环境中重现此错误。 一个支持人员曾经在生产过程中看过它(我已经尝试了好几次),但无法复制(与生产相同的环境,尽管资源较少)。 JQuery migrate在运行时没有显示任何问题,正如我所说,它似乎适用于大多数用户; 在调试会话期间似乎没有什么不妥。 操作系统/平台或浏览器没有明显的模式(试图在几个和日志上重现并不表示模式虽然很难筛选到足以确定)。 涉及的主要URL是表单控制器上的#new操作。 我们在平台中有其他几种forms,它们没有显示任何问题。

由于我无法重现它,因此无法提供代码片段 – 我不知道该指出什么。

到目前为止,我对错误的解释(基于堆栈转储中的第一行)是以下三个方面之一:

  1. 内容是正确的,但不完全形成,
  2. 内容形成不良表明Ruby漏洞(尽管可能是JS)
  3. 糟糕的编码(我在Ruby中使用form_for,甚至将“multipart:true”用于显式)

我看到Rack在4.x中处理了一个相关的多部分EOFError问题,但是我们正在运行Rails 3.2.19,它将我们锁定在旧版本并升级到Rails 4.x目前不实用。 作为一个测试,我已经尝试将JQuery恢复到低至1.7,但似乎没有改变行为(任何旧的,我不得不删除JQuery 1.8+所需的代码更新)。

由于JQuery代码需要更改我们的JS,我怀疑我错过了一些必要的JS更改,但似乎没有什么不妥。 附近还有一些CSS更改,但我不知道这会如何影响事情(因为一切都在我们的各种测试环境中传递,其他更改也包含在部署中)。

我一直怀疑JS问题,但是一些有限的生产测试(我必须小心在实时服务器上,所以不能过于激进)没有显示任何线索或抛出任何看似相关的错误。

作为背景,我有大约一年的Ruby和JS经验(虽然在其他编程平台上还有很多年),所以完全有可能它是我不熟悉的基础。

我正在努力缩小在哪里集中精力来处理这个问题。 有任何建议可以诊断或解决?

更新(10/11/14)我修补了Rack::Multipart::Parser.fast_forward_to_first_boundary (谢谢,Isaac Betesh!)添加日志跟踪并确认传递给解析器的内容在到达该函数时是空的(即,在多部分解析期间由@env['rack.input']不返回数据)。 我现在的理论是,当没有数据时,它会错误地预期多部分数据。 同样,这只是间歇性地发生,并且对于同一页面的许多其他调用进行解析。 由于我们在Passenger 4.x和Nginx下运行,我没有排除缓冲问题。

这终于解决了,我发布了发生的事情,以防它对别人有帮助。

总结原始代码在JS中包含一个ajaxSubmit(通过jquery.form插件),它提交了一个带有multipart / form-data编码的表单(作为POST)(到目前为止一直很好)。 处理提交的rails控制器正常处理数据,然后重定向到第二个href(作为GET)。 浏览器(可能仍然在返回它的success回调处理程序之前通过jquery.form插件进行处理)接收到重定向并保留了multipart / form-data编码类型。 当机架收到仍然指定了多部分编码的GET时,它会拒绝,因为没有要解析的多部分数据。

对不起,我的OP中没有证据certificate这一点。 我不清楚为什么它在旧版本的JQuery和JQuery.form插件下工作,或者为什么它有时在新的JQuery / JQuery.form下成功。

解决方案将控制器重构为不再重定向,而是返回原始ajaxSubmit的success回调处理程序的URL(作为文本呈现)。 然后, success处理程序在返回的URL上执行AJAX GET,从而使工作流保持不变,但避免在GET请求上进行任何多部分编码。

tl;博士

在代码被更改之前,我们有一个涉及Jquery.form的路径就是这样的(代码示例并不意味着可执行,但仅作为说明):

Ruby视图 (在HAML中提交表单):

 = 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控制器

 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; }); 

这被重构如下(再次,只是一个例子):

Ruby视图 (在提交表单的HAML中): 不变

Ruby控制器

 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; }); 

在本地开发人员的帮助下找到了这个解决方案(感谢Dan Axtman!)并且在Rack中进行猴子修补记录并不是没有相当多的时间(谢谢,Isaac Betesh!)。 至少我在这个过程中学到了一些关于Rack和Monkey补丁的知识......