EOFError de lançamento em rack (corpo de conteúdo incorreto)

Estamos usando Ruby 2.1.2, Rails 3.2.19 com JQuery 1.11, o pipeline de ativos não está sendo usado (portanto, não usando JQuery-ujs, mas usando explicitamente rails.js relevantes). Para a maioria dos usuários, o JQuery e outros plugins comuns relacionados estão sendo extraídos do CDN do Google (incluindo o jquery.form 3.50). O servidor da Web afetado é o Ubuntu 14.04, Nginx 1.6 e Passenger 4.x.

Para cerca de 10% dos usuários em nosso servidor de produção (cargas parecem não importar), estamos recebendo um despejo de pilha como este, principalmente para um URL, mas existem outros:

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

Antes de uma atualização para o JQuery 1.11 da 1.5 (!), Esse erro não ocorria (ou, se ocorria, era muito raro). Até o momento, não foi possível reproduzir esse erro em nosso servidor intermediário ou em um ambiente de desenvolvimento. Uma pessoa de suporte viu na produção uma vez (tentei várias vezes), mas não conseguiu replicar na preparação (que é o mesmo ambiente da produção, embora com recursos menores). O JQuery migrate não mostra nenhum problema quando é executado e, como eu disse, parece funcionar para a maioria dos usuários; durante as sessões de depuração, nada parece errado. Não há um padrão aparente para o SO / plataforma ou navegador (tentei reproduzir em vários e os logs não indicam um padrão, embora seja difícil filtrar o suficiente para ter certeza). O URL principal envolvido é para uma #nova ação em um controlador de formulário. Temos várias outras formas na plataforma e elas não mostram nenhum problema.

Como não posso reproduzi-lo, não é possível fornecer um trecho de código - eu não saberia o que identificar.

Minha interpretação do erro até agora (com base na primeira linha no despejo de pilha) é uma das três coisas:

caso contrário, o conteúdo está correto, mas não totalmente formado,o conteúdo está mal formado, sugerindo um bug do Ruby (embora talvez JS)codificação incorreta (estou usando form_for em Ruby e até joguei "multipart: true" para ser explícito)

Vejo que o Rack lidou com um problema relacionado ao EOFError com várias partes no 4.x, mas estamos executando o Rails 3.2.19, que nos bloqueia em uma versão mais antiga e a atualização para o Rails 4.x não é prática no momento. Como teste, tentei o JQuery tão baixo quanto 1,7, mas não parecia mudar o comportamento (mais antigo e eu teria que descartar as atualizações de código necessárias para o JQuery 1.8+).

Como o código JQuery exigia alterações em nosso JS, suspeitei ter perdido algumas alterações necessárias em JS, mas nada parece errado. Havia também algumas alterações de CSS nas proximidades, mas não vejo como isso poderia afetar as coisas (como tudo estava passando em nossos vários ambientes de teste, outras alterações também foram incluídas na implantação).

Suspeitei principalmente de problemas de JS, mas alguns testes limitados na produção (eu tenho que ter cuidado no servidor ativo, para que não seja muito agressivo) não mostraram pistas nem lançaram erros que pareçam relacionados.

Como pano de fundo, tenho cerca de um ano de experiência com Ruby e JS (apesar de muitos outros anos em outras plataformas de programação), então é perfeitamente possível que seja algo básico que eu não conheça.

Estou tendo dificuldade em restringir onde focar para lidar com isso. Algum conselho para diagnosticar ou resolver?

ATUALIZAÇÃO (11/10/14) Eu macaco remendadoRack::Multipart::Parser.fast_forward_to_first_boundary (obrigado, Isaac Betesh!) por adicionar rastreamentos de log e confirmar que o conteúdo transmitido ao analisador está vazio quando atinge essa função (ou seja, o StringIO referido por@env['rack.input'] durante a análise multipartes não retorna dados). Minha teoria agora é que, erroneamente, se espera dados com várias partes quando não existem. Novamente, isso acontece apenas de forma intermitente e analisa bem muitas outras invocações dessa mesma página. Como estamos rodando no Passenger 4.xe Nginx, não descartei um problema de buffer.

questionAnswers(1)

yourAnswerToTheQuestion