我们使用
Ruby 2.1.2,Rails 3.2.19和
JQuery 1.11,资源管道没有被使用(所以不使用JQuery-ujs,但显式使用了相关的rails.js).对于大多数用户来说,JQuery和其他相关的常见插件都是从谷歌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操作.我们在平台上有其他几种形式,它们没有显示任何问题.
由于我无法重现它,因此无法提供代码片段 – 我不知道该指出什么.
到目前为止,我对错误的解释(基于堆栈转储中的第一行)是以下三个方面之一：
>内容是正确的,但不完全形成,
>内容形成不良表明存在Ruby错误(尽管如此)
也许是JS)
>糟糕的编码(我在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’]引用的StringIO不返回数据).我现在的理论是,当没有数据时,它会错误地预期多部分数据.同样,这只是间歇性地发生并且对于同一页面的许多其他调用进行解析.由于我们在Passenger 4.x和Nginx下运行,我没有排除缓冲问题.
解决方法
这终于解决了,我发布了发生的事情,以防它对别人有帮助.
总结原始代码在JS中包含一个ajaxSubmit(通过jquery.form插件),它提交了一个带有multipart / form-data编码的表单(作为POST)(到目前为止一直很好).处理提交的rails控制器正常处理数据,然后重定向到第二个href(作为GET).浏览器(可能仍然在返回到成功回调处理程序之前通过jquery.form插件进行处理)接收到重定向并保留了multipart / form-data编码类型.当机架收到仍然指定了多部分编码的GET时,它会拒绝,因为没有要解析的多部分数据.
对不起,我的OP中没有证据证明这一点.我不清楚为什么它在旧版本的JQuery和JQuery.form插件下工作,或者为什么它有时在新的JQuery / JQuery.form下成功.
解决方案将控制器重构为不再重定向,而是返回原始ajaxSubmit的成功回调处理程序的URL(作为文本呈现).然后,成功处理程序在返回的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',success: function(responseText) {
// ... code to display flash message
$.get(responseText,function(data) { // NEW LINE
if (typeof(window.history.pushState) == 'function') {
window.history.pushState('html',$.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补丁的知识……