Lancio rack EOFError (corpo con contenuto errato)

Question

Stiamo utilizzando Ruby 2.1.2, Rails 3.2.19 con JQuery 1.11, la pipeline delle risorse non viene utilizzata (quindi non si utilizza JQuery-ujs, ma si utilizzano esplicitamente i file rails rilevanti.). Per la maggior parte degli utenti, JQuery e altri plugin comuni correlati vengono estratti da Google CDN (incluso jquery.form 3.50). Il server Web interessato è Ubuntu 14.04, Nginx 1.6 e Passenger 4.x.

Per circa il 10% degli utenti sul nostro server di produzione (carichi sembrano poco importa), stiamo ottenendo un dump di stack come questo, in primo luogo per un URL, ma ce ne sono altri:

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

Prima di una aggiornamento a JQuery 1.11 da 1.5 (!), questo errore non si è verificato (o se lo ha fatto, era molto raro). Fino ad ora non siamo riusciti a riprodurre questo errore sul nostro server di gestione temporanea o in un ambiente di sviluppo. Una persona di supporto l'ha visto in produzione una volta (l'ho provato diverse volte), ma non è riuscito a replicare sulla staging (che è lo stesso ambiente della produzione, anche se risorse più piccole). La migrazione di JQuery non mostra problemi durante l'esecuzione e, come ho detto, sembra funzionare per la maggior parte degli utenti; durante le sessioni di debug niente sembra sbagliato. Non vi è alcun apparente schema per OS/piattaforma o browser (tentato di riprodurlo su diversi e log non indicano un pattern sebbene difficile da setacciare abbastanza per essere sicuri). L'URL principale coinvolto è per una nuova azione su un controller di modulo. Abbiamo diverse altre forme nella piattaforma e non mostrano alcun problema.

Poiché non riesco a riprodurlo, non è possibile fornire uno snippet di codice - non saprei cosa individuare.

La mia interpretazione dell'errore finora (sulla base di prima linea in dump dello stack) è una delle tre cose:

1. il contenuto è altrimenti corretta, ma non completamente formato in qualche modo,
2. il contenuto è scarsamente formato suggerendo un bug di Ruby (anche se forse JS)
3. cattiva codifica (sto usando form_for in Ruby e anche buttato in "multipart: true" per essere espliciti)

01.235.164,106174 millions

Vedo che Rack ha affrontato un problema EOFError multipart relativo in 4.x, ma stiamo usando Rails 3.2.19 che ci blocca su una versione precedente e l'aggiornamento a Rails 4.x non è pratico al momento. Come test, ho provato a tornare a JQuery a partire da 1.7, ma non sembra aver cambiato il comportamento (più vecchio e avrei dovuto eliminare gli aggiornamenti di codice necessari per JQuery 1.8+).

Poiché il codice JQuery richiedeva modifiche al nostro JS, sospettavo che mi mancassero alcune modifiche necessarie al JS, ma nulla sembra sbagliato. C'erano anche alcune modifiche CSS nelle vicinanze, ma non vedo come ciò potrebbe influenzare le cose (dato che tutto stava passando nei nostri vari ambienti di test, anche altre modifiche erano incluse nella distribuzione).

Ho sospettato principalmente problemi JS, ma alcuni test limitati sulla produzione (devo stare attento sul server live in modo da non diventare troppo aggressivo) non hanno mostrato alcun indizio o generato errori che sembrano correlati .

Come sfondo, ho circa un anno di esperienza con Ruby e JS (anche se molti altri anni su altre piattaforme di programmazione) così completamente possibile è qualcosa di semplice che non conosco.

Sto attraversando un periodo difficile con il restringimento verso il basso per mettere a fuoco il problema. Qualche consiglio o di diagnosticare o risolvere?

UPDATE (10/11/14) I scimmia patchato Rack::Multipart::Parser.fast_forward_to_first_boundary (grazie, Isaac Betesh!) Per aggiungere le tracce di registro e ha confermato che il contenuto passato al parser è vuoto quando raggiunge quella funzione (cioè il StringIO a cui si fa riferimento per @env['rack.input'] durante l'analisi multipart non restituisce dati). La mia teoria ora è che si aspetta erroneamente dati multipart quando non ce ne sono. Ancora una volta, questo accade solo in modo intermittente e analizza bene per molte altre invocazioni di questa stessa pagina. Poiché siamo in esecuzione su Passenger 4.xe Nginx, non ho escluso un problema di buffering.

Answer 1

Questo è stato finalmente risolto e sto postando cosa è successo nel caso sia utile per gli altri.

Sintesi Il codice originale conteneva un ajaxSubmit (tramite plug jquery.form) nella JS che ha presentato un modulo (come POST) con la codifica multipart/form-data (finora così buono). Il controller di rails che gestiva l'invio elaborava i dati normalmente e quindi reindirizzava a un secondo href (come GET). Il browser (che può ancora essere elaborato tramite il plugin jquery.form prima di tornare al suo gestore di callback success) ha ricevuto il reindirizzamento e ha mantenuto il tipo di codifica multipart/form-data. Quando il rack ha ricevuto il GET con codifica multipart ancora specificata, viene respinto perché non sono stati analizzati dati multipart.

Siamo spiacenti, gran parte di questo non era evidente nel mio OP. E non mi è chiaro il motivo per cui questo ha funzionato con una versione precedente di JQuery e con il plugin JQuery.form o perché a volte è riuscito con il nuovo JQuery/JQuery.form.

Soluzione riscritta il controller per reindirizzare non è più, ma piuttosto restituire un URL (come un testo rendering) per il gestore success callback del ajaxSubmit originale. Il gestore success esegue quindi un AJAX GET sull'URL restituito, lasciando intatto il flusso di lavoro ma evitando qualsiasi codifica multipart nella richiesta GET.

tl; dr:

Prima che il codice è stato mai cambiato, abbiamo avuto un percorso che coinvolge Jquery.forma che è andato qualcosa di simile (esempio di codice non è pensato per essere eseguibile, ma solo come illustrazione):

Rubino vista (in HAML per la forma viene presentato):

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

regolatore di Rubino:

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

---

Questo è stato riscritta come segue (di nuovo, solo un esempio):

vista rubino (in HAML per essere inviato form): invariato

regolatore rubino:

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: (! Grazie, Dan Axtman)

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

---

Questa soluzione è stata trovata con qualche aiuto con uno sviluppatore locale e non senza una buona dose di tempo nella registrazione di scimmia-patched in cremagliera (grazie, Isaac Betesh!). Almeno ho imparato qualcosa su Rack e scimmia patching nel processo ...