nil error in merging get and post data #430

Closed
michaeleconomy opened this Issue Sep 12, 2012 · 93 comments
@michaeleconomy

I'm seeing this error on a very small percentage of our requests (like 25 per day), i don't have very good data, but it could be related to multipart posts.

TypeError: can't convert nil into Hash

[GEM_ROOT]/gems/rack-1.4.1/lib/rack/request.rb:221:in merge'
[GEM_ROOT]/gems/rack-1.4.1/lib/rack/request.rb:221:in
params'

Any idea whats up?

Running RoR 3.2.8, unicorn 4.3.1.

@bogdan

+1

For me it is related to omniauth-twitter authentication. It might be bug in this lib. but as long as @michaeleconomy don't use it, it could bug in rack itself.

@michaeleconomy

We're not using omniauth for this app.

@msaffitz

Seeing this as well. Same setup-- Rails 3.2.8, Unicorn 4.3.1 on Heroku with Mongoid 2.x. Ruby 1.9.3.

@lgierth
@msaffitz

@lgierth I'm seeing this on requests with an empty query string. Our usage pattern is such that our endpoint is called from a controlled set of clients-- the vast majority succeed but there are a persist few that hit this error. I've tried turning on debug level logging for both Rails & Rack to capture the actual request, but I haven't had much luck with it (on Heroku)-- any guidance on how to better debug or capture the invalid query string? (The method is POST, it's weird to me that the POST params would merge into GET params here: https://github.com/rack/rack/blob/master/lib/rack/request.rb#L223, which is where this is failing).

@msaffitz

Here's a full stack trace:

2012-10-03T05:28:46+00:00 app[web.1]: TypeError (can't convert nil into Hash):
2012-10-03T05:28:46+00:00 app[web.1]:   vendor/bundle/ruby/1.9.1/gems/rack-1.4.1/lib/rack/request.rb:221:in `merge'
2012-10-03T05:28:46+00:00 app[web.1]:   vendor/bundle/ruby/1.9.1/gems/rack-1.4.1/lib/rack/request.rb:221:in `params'
2012-10-03T05:28:46+00:00 app[web.1]:   vendor/bundle/ruby/1.9.1/gems/rack-openid-1.3.1/lib/rack/openid.rb:94:in `call'
2012-10-03T05:28:46+00:00 app[web.1]:   vendor/bundle/ruby/1.9.1/gems/actionpack-3.2.8/lib/action_dispatch/middleware/best_standards_support.rb:17:in `call'
2012-10-03T05:28:46+00:00 app[web.1]:   vendor/bundle/ruby/1.9.1/gems/rack-1.4.1/lib/rack/etag.rb:23:in `call'
2012-10-03T05:28:46+00:00 app[web.1]:   vendor/bundle/ruby/1.9.1/gems/rack-1.4.1/lib/rack/conditionalget.rb:35:in `call'
2012-10-03T05:28:46+00:00 app[web.1]:   vendor/bundle/ruby/1.9.1/gems/actionpack-3.2.8/lib/action_dispatch/middleware/head.rb:14:in `call'
2012-10-03T05:28:46+00:00 app[web.1]:   vendor/bundle/ruby/1.9.1/gems/actionpack-3.2.8/lib/action_dispatch/middleware/params_parser.rb:21:in `call'
2012-10-03T05:28:46+00:00 app[web.1]:   vendor/bundle/ruby/1.9.1/gems/actionpack-3.2.8/lib/action_dispatch/middleware/flash.rb:242:in `call'
2012-10-03T05:28:46+00:00 app[web.1]:   vendor/bundle/ruby/1.9.1/gems/rack-1.4.1/lib/rack/session/abstract/id.rb:205:in `context'
2012-10-03T05:28:46+00:00 app[web.1]:   vendor/bundle/ruby/1.9.1/gems/rack-1.4.1/lib/rack/session/abstract/id.rb:200:in `call'
2012-10-03T05:28:46+00:00 app[web.1]:   vendor/bundle/ruby/1.9.1/gems/actionpack-3.2.8/lib/action_dispatch/middleware/cookies.rb:339:in `call'
2012-10-03T05:28:46+00:00 app[web.1]:   vendor/bundle/ruby/1.9.1/gems/actionpack-3.2.8/lib/action_dispatch/middleware/callbacks.rb:28:in `block in call'
2012-10-03T05:28:46+00:00 app[web.1]:   vendor/bundle/ruby/1.9.1/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:405:in `_run__813155958147975408__call__3271509603735835264__callbacks'
2012-10-03T05:28:46+00:00 app[web.1]:   vendor/bundle/ruby/1.9.1/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:405:in `__run_callback'
2012-10-03T05:28:46+00:00 app[web.1]:   vendor/bundle/ruby/1.9.1/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:385:in `_run_call_callbacks'
2012-10-03T05:28:46+00:00 app[web.1]:   vendor/bundle/ruby/1.9.1/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:81:in `run_callbacks'
2012-10-03T05:28:46+00:00 app[web.1]:   vendor/bundle/ruby/1.9.1/gems/actionpack-3.2.8/lib/action_dispatch/middleware/callbacks.rb:27:in `call'
2012-10-03T05:28:46+00:00 app[web.1]:   vendor/bundle/ruby/1.9.1/gems/rack-1.4.1/lib/rack/sendfile.rb:102:in `call'
2012-10-03T05:28:46+00:00 app[web.1]:   vendor/bundle/ruby/1.9.1/gems/actionpack-3.2.8/lib/action_dispatch/middleware/remote_ip.rb:31:in `call'
2012-10-03T05:28:46+00:00 app[web.1]:   vendor/bundle/ruby/1.9.1/gems/actionpack-3.2.8/lib/action_dispatch/middleware/debug_exceptions.rb:16:in `call'
2012-10-03T05:28:46+00:00 app[web.1]:   vendor/bundle/ruby/1.9.1/gems/actionpack-3.2.8/lib/action_dispatch/middleware/show_exceptions.rb:56:in `call'
2012-10-03T05:28:46+00:00 app[web.1]:   vendor/bundle/ruby/1.9.1/gems/railties-3.2.8/lib/rails/rack/logger.rb:26:in `call_app'
2012-10-03T05:28:46+00:00 app[web.1]:   vendor/bundle/ruby/1.9.1/gems/railties-3.2.8/lib/rails/rack/logger.rb:16:in `call'
2012-10-03T05:28:46+00:00 app[web.1]:   vendor/bundle/ruby/1.9.1/gems/actionpack-3.2.8/lib/action_dispatch/middleware/request_id.rb:22:in `call'
2012-10-03T05:28:46+00:00 app[web.1]:   vendor/bundle/ruby/1.9.1/gems/rack-1.4.1/lib/rack/methodoverride.rb:21:in `call'
2012-10-03T05:28:46+00:00 app[web.1]:   vendor/bundle/ruby/1.9.1/gems/rack-1.4.1/lib/rack/runtime.rb:17:in `call'
2012-10-03T05:28:46+00:00 app[web.1]:   vendor/bundle/ruby/1.9.1/gems/actionpack-3.2.8/lib/action_dispatch/middleware/static.rb:62:in `call'
2012-10-03T05:28:46+00:00 app[web.1]:   vendor/bundle/ruby/1.9.1/gems/rack-cache-1.2/lib/rack/cache/context.rb:136:in `forward'
2012-10-03T05:28:46+00:00 app[web.1]:   vendor/bundle/ruby/1.9.1/gems/rack-cache-1.2/lib/rack/cache/context.rb:143:in `pass'
2012-10-03T05:28:46+00:00 app[web.1]:   vendor/bundle/ruby/1.9.1/gems/rack-cache-1.2/lib/rack/cache/context.rb:155:in `invalidate'
2012-10-03T05:28:46+00:00 app[web.1]:   vendor/bundle/ruby/1.9.1/gems/rack-cache-1.2/lib/rack/cache/context.rb:71:in `call!'
2012-10-03T05:28:46+00:00 app[web.1]:   vendor/bundle/ruby/1.9.1/gems/rack-cache-1.2/lib/rack/cache/context.rb:51:in `call'
2012-10-03T05:28:46+00:00 app[web.1]:   vendor/bundle/ruby/1.9.1/gems/railties-3.2.8/lib/rails/engine.rb:479:in `call'
2012-10-03T05:28:46+00:00 app[web.1]:   vendor/bundle/ruby/1.9.1/gems/railties-3.2.8/lib/rails/application.rb:223:in `call'
2012-10-03T05:28:46+00:00 app[web.1]:   vendor/bundle/ruby/1.9.1/gems/railties-3.2.8/lib/rails/railtie/configurable.rb:30:in `method_missing'
2012-10-03T05:28:46+00:00 app[web.1]:   vendor/bundle/ruby/1.9.1/gems/rack-1.4.1/lib/rack/urlmap.rb:64:in `block in call'
2012-10-03T05:28:46+00:00 app[web.1]:   vendor/bundle/ruby/1.9.1/gems/rack-1.4.1/lib/rack/urlmap.rb:49:in `each'
2012-10-03T05:28:46+00:00 app[web.1]:   vendor/bundle/ruby/1.9.1/gems/rack-1.4.1/lib/rack/urlmap.rb:49:in `call'
2012-10-03T05:28:46+00:00 app[web.1]:   vendor/bundle/ruby/1.9.1/gems/rack-1.4.1/lib/rack/static.rb:66:in `call'
2012-10-03T05:28:46+00:00 app[web.1]:   vendor/bundle/ruby/1.9.1/bundler/gems/rack-reverse-proxy-93c91f519997/lib/rack/reverse_proxy.rb:16:in `call'
2012-10-03T05:28:46+00:00 app[web.1]:   vendor/bundle/ruby/1.9.1/gems/unicorn-4.3.1/lib/unicorn/http_server.rb:531:in `process_client'
2012-10-03T05:28:46+00:00 app[web.1]:   vendor/bundle/ruby/1.9.1/gems/unicorn-4.3.1/lib/unicorn/http_server.rb:606:in `worker_loop'
2012-10-03T05:28:46+00:00 app[web.1]:   vendor/bundle/ruby/1.9.1/gems/unicorn-4.3.1/lib/unicorn/http_server.rb:487:in `spawn_missing_workers'
2012-10-03T05:28:46+00:00 app[web.1]:   vendor/bundle/ruby/1.9.1/gems/unicorn-4.3.1/lib/unicorn/http_server.rb:137:in `start'
2012-10-03T05:28:46+00:00 app[web.1]:   vendor/bundle/ruby/1.9.1/gems/unicorn-4.3.1/bin/unicorn:121:in `<top (required)>'
2012-10-03T05:28:46+00:00 app[web.1]:   vendor/bundle/ruby/1.9.1/bin/unicorn:23:in `load'
2012-10-03T05:28:46+00:00 app[web.1]:   vendor/bundle/ruby/1.9.1/bin/unicorn:23:in `<main>'
20
@michaeleconomy
@msaffitz

I think I have this tracked down to the request.POST method returning nil, and specifically this clause (https://github.com/rack/rack/blob/master/lib/rack/request.rb#L197) of the request returning nil:

      elsif @env["rack.request.form_input"].eql? @env["rack.input"]
        @env["rack.request.form_hash"]

My Rack environment has rack.request.form_hash as nil. I'm stumped at the moment about why that's nil.

@raggi
Official Rack repositories member

I don't have enough information to replicate right now. Please reopen when a replication case is available. Thank you!

@raggi raggi closed this Nov 3, 2012
@tompesman

I've got some more information on this error: http://goo.gl/La9tK

The error occurs with PUT requests with an image upload.

Do you need more information?

@tompesman

I'm running on heroku with unicorn, which also gives a separate stacktrace.

TypeError (can't convert nil into Hash):
  vendor/bundle/ruby/1.9.1/gems/rack-1.4.1/lib/rack/request.rb:221:in `merge'
  vendor/bundle/ruby/1.9.1/gems/rack-1.4.1/lib/rack/request.rb:221:in `params'
  vendor/bundle/ruby/1.9.1/gems/newrelic_rpm-3.5.0.1/lib/new_relic/rack/error_collector.rb:15:in `rescue in call'
  vendor/bundle/ruby/1.9.1/gems/newrelic_rpm-3.5.0.1/lib/new_relic/rack/error_collector.rb:8:in `call'
  vendor/bundle/ruby/1.9.1/gems/newrelic_rpm-3.5.0.1/lib/new_relic/rack/browser_monitoring.rb:12:in `call'
  vendor/bundle/ruby/1.9.1/gems/rack-timeout-0.0.3/lib/rack/timeout.rb:16:in `block in call'
  vendor/ruby-1.9.3/lib/ruby/1.9.1/timeout.rb:68:in `timeout'
  vendor/bundle/ruby/1.9.1/gems/rack-timeout-0.0.3/lib/rack/timeout.rb:16:in `call'
  vendor/bundle/ruby/1.9.1/gems/warden-1.2.1/lib/warden/manager.rb:35:in `block in call'
  vendor/bundle/ruby/1.9.1/gems/warden-1.2.1/lib/warden/manager.rb:34:in `catch'
  vendor/bundle/ruby/1.9.1/gems/warden-1.2.1/lib/warden/manager.rb:34:in `call'
  vendor/bundle/ruby/1.9.1/gems/actionpack-3.2.8/lib/action_dispatch/middleware/head.rb:14:in `call'
  vendor/bundle/ruby/1.9.1/gems/actionpack-3.2.8/lib/action_dispatch/middleware/params_parser.rb:21:in `call'
  vendor/bundle/ruby/1.9.1/gems/rack-1.4.1/lib/rack/session/abstract/id.rb:205:in `context'
  vendor/bundle/ruby/1.9.1/gems/rack-1.4.1/lib/rack/session/abstract/id.rb:200:in `call'
  vendor/bundle/ruby/1.9.1/gems/actionpack-3.2.8/lib/action_dispatch/middleware/cookies.rb:339:in `call'
  vendor/bundle/ruby/1.9.1/gems/activerecord-3.2.8/lib/active_record/query_cache.rb:64:in `call'
  vendor/bundle/ruby/1.9.1/gems/activerecord-3.2.8/lib/active_record/connection_adapters/abstract/connection_pool.rb:473:in `call'
  vendor/bundle/ruby/1.9.1/gems/actionpack-3.2.8/lib/action_dispatch/middleware/callbacks.rb:28:in `block in call'
  vendor/bundle/ruby/1.9.1/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:405:in `_run__4068654253604228006__call__3028303917099887697__callbacks'
  vendor/bundle/ruby/1.9.1/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:405:in `__run_callback'
  vendor/bundle/ruby/1.9.1/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:385:in `_run_call_callbacks'
  vendor/bundle/ruby/1.9.1/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:81:in `run_callbacks'
  vendor/bundle/ruby/1.9.1/gems/actionpack-3.2.8/lib/action_dispatch/middleware/callbacks.rb:27:in `call'
  vendor/bundle/ruby/1.9.1/gems/actionpack-3.2.8/lib/action_dispatch/middleware/remote_ip.rb:31:in `call'
  vendor/bundle/ruby/1.9.1/gems/actionpack-3.2.8/lib/action_dispatch/middleware/debug_exceptions.rb:16:in `call'
  vendor/bundle/ruby/1.9.1/gems/actionpack-3.2.8/lib/action_dispatch/middleware/show_exceptions.rb:56:in `call'
  vendor/bundle/ruby/1.9.1/gems/railties-3.2.8/lib/rails/rack/logger.rb:26:in `call_app'
  vendor/bundle/ruby/1.9.1/gems/railties-3.2.8/lib/rails/rack/logger.rb:16:in `call'
  vendor/bundle/ruby/1.9.1/gems/actionpack-3.2.8/lib/action_dispatch/middleware/request_id.rb:22:in `call'
  vendor/bundle/ruby/1.9.1/gems/rack-1.4.1/lib/rack/methodoverride.rb:21:in `call'
  vendor/bundle/ruby/1.9.1/gems/rack-1.4.1/lib/rack/runtime.rb:17:in `call'
  vendor/bundle/ruby/1.9.1/gems/rack-1.4.1/lib/rack/lock.rb:15:in `call'
  vendor/bundle/ruby/1.9.1/gems/actionpack-3.2.8/lib/action_dispatch/middleware/static.rb:62:in `call'
  vendor/bundle/ruby/1.9.1/gems/airbrake-3.1.6/lib/airbrake/rack.rb:41:in `call'
  vendor/bundle/ruby/1.9.1/gems/airbrake-3.1.6/lib/airbrake/user_informer.rb:12:in `call'
  vendor/bundle/ruby/1.9.1/gems/railties-3.2.8/lib/rails/engine.rb:479:in `call'
  vendor/bundle/ruby/1.9.1/gems/railties-3.2.8/lib/rails/application.rb:223:in `call'
  vendor/bundle/ruby/1.9.1/gems/railties-3.2.8/lib/rails/railtie/configurable.rb:30:in `method_missing'
  vendor/bundle/ruby/1.9.1/gems/rack-1.4.1/lib/rack/deflater.rb:13:in `call'
  vendor/bundle/ruby/1.9.1/gems/unicorn-4.4.0/lib/unicorn/http_server.rb:535:in `process_client'
  vendor/bundle/ruby/1.9.1/gems/unicorn-4.4.0/lib/unicorn/http_server.rb:610:in `worker_loop'
  vendor/bundle/ruby/1.9.1/gems/newrelic_rpm-3.5.0.1/lib/new_relic/agent/instrumentation/unicorn_instrumentation.rb:18:in `call'
  vendor/bundle/ruby/1.9.1/gems/newrelic_rpm-3.5.0.1/lib/new_relic/agent/instrumentation/unicorn_instrumentation.rb:18:in `block (4 levels) in <top (required)>'
  vendor/bundle/ruby/1.9.1/gems/unicorn-4.4.0/lib/unicorn/http_server.rb:491:in `spawn_missing_workers'
  vendor/bundle/ruby/1.9.1/gems/unicorn-4.4.0/lib/unicorn/http_server.rb:141:in `start'
  vendor/bundle/ruby/1.9.1/gems/unicorn-4.4.0/bin/unicorn:121:in `<top (required)>'
  vendor/bundle/ruby/1.9.1/bin/unicorn:23:in `load'
  vendor/bundle/ruby/1.9.1/bin/unicorn:23:in `<main>'

E, [2012-11-08T15:46:20.392295 #40] ERROR -- : app error: closed stream (IOError)
E, [2012-11-08T15:46:20.392380 #40] ERROR -- : /app/vendor/bundle/ruby/1.9.1/gems/unicorn-4.4.0/lib/unicorn/http_response.rb:38:in `write'
E, [2012-11-08T15:46:20.392435 #40] ERROR -- : /app/vendor/bundle/ruby/1.9.1/gems/unicorn-4.4.0/lib/unicorn/http_response.rb:38:in `http_response_write'
E, [2012-11-08T15:46:20.392488 #40] ERROR -- : /app/vendor/bundle/ruby/1.9.1/gems/unicorn-4.4.0/lib/unicorn/http_server.rb:543:in `process_client'
E, [2012-11-08T15:46:20.392539 #40] ERROR -- : /app/vendor/bundle/ruby/1.9.1/gems/unicorn-4.4.0/lib/unicorn/http_server.rb:610:in `worker_loop'
E, [2012-11-08T15:46:20.392608 #40] ERROR -- : /app/vendor/bundle/ruby/1.9.1/gems/newrelic_rpm-3.5.0.1/lib/new_relic/agent/instrumentation/unicorn_instrumentation.rb:18:in `call'
E, [2012-11-08T15:46:20.392709 #40] ERROR -- : /app/vendor/bundle/ruby/1.9.1/gems/newrelic_rpm-3.5.0.1/lib/new_relic/agent/instrumentation/unicorn_instrumentation.rb:18:in `block (4 levels) in <top (required)>'
E, [2012-11-08T15:46:20.392762 #40] ERROR -- : /app/vendor/bundle/ruby/1.9.1/gems/unicorn-4.4.0/lib/unicorn/http_server.rb:491:in `spawn_missing_workers'
E, [2012-11-08T15:46:20.392818 #40] ERROR -- : /app/vendor/bundle/ruby/1.9.1/gems/unicorn-4.4.0/lib/unicorn/http_server.rb:141:in `start'
E, [2012-11-08T15:46:20.392869 #40] ERROR -- : /app/vendor/bundle/ruby/1.9.1/gems/unicorn-4.4.0/bin/unicorn:121:in `<top (required)>'
E, [2012-11-08T15:46:20.393391 #40] ERROR -- : /app/vendor/bundle/ruby/1.9.1/bin/unicorn:23:in `load'
E, [2012-11-08T15:46:20.393518 #40] ERROR -- : /app/vendor/bundle/ruby/1.9.1/bin/unicorn:23:in `<main>'
@ognevsky

+1 for this issue and really have no idea about the reason.

@ognevsky

Btw, it appears for me on two pages, both with simple_form gem: sessions#new and something like account#edit.

And the browser is:

BROWSER
45.5%    Android
54.5%    Opera 9.80

© Errbit

Do anybody have same env?

@tiegz

I'm seeing this same issue. Rails 3.2.10, Unicorn 4.4.0, Ruby 1.9.3... Are you guys using Airbrake by chance?

@oscardelben

I think the problem is that sometimes @env["rack.request.form_hash"] is nil but it still gets returned by self.POST.

I'll spend some time in the next few days to understand when this can happen as I have some ideas for things to look at.

@raggi
Official Rack repositories member

I think, but I have not replicated, that this is being caused by an earlier exception in the stack that's being caught by your various other middleware. In essence there's likely a middleware object in your stack that's violating https://github.com/rack/rack/blob/master/SPEC#L101

I would recommend that you put most Rack middleware below the Rails middleware, as I suspect this may be related to Rack::Request and ActionDispatch::Middleware::ParamParser conflicting. n.b. I'm predicting based on insufficient information, so I may be wrong. If someone could produce an actual replication case (bootable app repo, request command) then it would be easier. Having stack traces with multiple account requiring 3rd party middleware makes this too time consuming - make it easy and I can help faster.

@raggi
Official Rack repositories member

It's also possible that an exception is occurring during multipart parsing, that's being squashed by an exception catching middleware (like airbrake or newrelic) that are then subsequently failing to grab the POST data because the exception left the world in a corrupt state - a typical "damage reporting machine is damaged" scenario. If this is the case (and even if it isn't), I would recommend that the implementors of such middleware objects replace their logic to do raw dumps based on SPEC alone, not based on rack utilities like Rack::Request - they're designed for exceptional conditions - where anything might have failed, and so shouldn't have any dependencies.

@johnmetta

Strangely, I just started seeing this happen a few days ago, without any changes to my codebase in the middleware layer, so I'm leaning toward Airbrake/NewRelic/Other as the culprit as @raggi suggested.

@johnmetta

Sorry, meant to say "leaning toward confirming." Turned off airbrake and found out almost immediately that it was a malformed POST from a broken form.

@tiegz

Thx for the suggestion @raggi.

The reason I asked about Airbrake is because I noticed that it clears out the 'rack.request.form_vars' variable, so even though I didn't see that in my request data, it could be that it existed at some point (which might indicate POST took a different code path than @msaffitz suggested)

@oscardelben

@lgierth rack.request.form_vars is expected to be there. Can you point me to the code where they're clearing it out?

@lgierth

@tiegz that is

@tiegz

@oscardelben that is ;)

@oscardelben

Correct me if I'm wrong, but I think the issue is that airbrake sets rack.request.form_vars to nil instead of an empty hash.

@tiegz

@oscardelben the only thing is that I can't see where else in rack that rack.request.form_vars is used... is it in another gem?

@tiegz

Oh, you must've meant rack.request.form_hash instead of rack.request.form_vars then. I agree, but I don't think airbrake touches rack.request.form_hash :\

@oscardelben

You're right. I'm trying to see if I can replicate it in some way. Sorry about the misunderstanding.

@tiegz

Np! I'll probably look at this again tomorrow too. This one's hard to track down.

@nextofsearch

I am in the same boat but I can not replicate it either.
It occurs about 3,000 times per day in our production server, which drives me crazy. :(

My set up is Rails 3.2.9, Ruby 1.9.3, unicorn 4.5.0 on Heroku cedar stack with newrelic 3.5.4.33.

@raggi
Official Rack repositories member

Is everyone on this ticket running new_relic? I see a pattern here.

@billkauf

I'm seeing it running newrelic_rpm 3.5.3.25, unicorn 4.3.1, airbrake 3.1.6. Could be any of them...

@tiegz

newrelic_rpm 3.5.3.25 here too

@tiegz

(I can reproduce this locally with NewRelic disabled, using POW as a server)

@tiegz

(ack, sorry, I was repro'ing another Rack error we get commonly; but we're still getting this one)

@msaffitz

New Relic here too. We moved from unicorn back to thin, and the errors went away.

@oscardelben

If someone can reproduce locally please try this before your app is loaded:

class Hash                                                                                                     
  def []=(key, value)
    if key =~ /.*form_hash.*/ && value.nil?
      warn "*********"
      warn " Setting form_hash to nil"
      warn "#{caller}"
      warn "*********"
    end
  end
end

There are a multitude of reasons why this may not detect the problem but it's a start. I want to know if someone is explicitly messing with form_hash.

@michaeleconomy

we have new relic also.

@raggi
Official Rack repositories member

This may be related: airbrake/airbrake@2975e8e

@tiegz

Ah, good find! I'll disable that middleware and see if this goes away.

@msaffitz

FWIW, we had the issues without Airbrake-- we use Sentry (https://github.com/getsentry/raven-ruby) instead.

@nextofsearch

We removed newrelic from our production server and it didn't go away.
I really start to think that it is unicorn + Rack combo.

I can't reproduce it on local or staging server. It only occurs in production sever.

@nextofsearch

Screen Shot 2013-01-09 at 8 42 16 PM

It was newrelic that caused the issue. I was confused with the some other issue.
As you can see in the image, the dark brown 'x' marks are gone during the period when we removed newrelic gem.
I just turned newrelic on and a 'x' mark is back on the right side. duh...

Please ignore my previous comment.

@nextofsearch

newrelic gave us the new beta version (3.5.5.39.beta) of newrelic_rpm which they claim should address this issue:
http://rubygems.org/gems/newrelic_rpm/versions/3.5.5.39.beta

Please share your result. Thanks,

@tiegz

@nextofsearch thanks, upgraded but still getting this error.

@chtrinh

Any updates? Started to see this after I upgrading to newrelic_rpm 3.5.5.38.

@raggi
Official Rack repositories member

now that it's clearly identified as newrelic, maybe you can contact newrelic support. /cc @gnarg @samg @jasonrclark (some folks with larger volumes of recent contributions)

@samg

Yes, feel free to open a ticket at support.newrelic.com, referencing this thread, and ask that it be escalated to the ruby agent team. @jasonrclark should be able to take a look at it this week. If anyone has a simplified replication case they can provide that would help us get to the bottom of what's going on more quickly.

@jasonrclark

@chtrinh The patch is only on the beta release, 3.5.5.39.beta. 3.5.5.38 was still effected by request.params raising an exception.

@tiegz Could you get a support ticket opened and ask to escalate? The beta version should be capturing more information around this error, and I can dig into that data once I know your account via the support ticket. Thanks!

Any other pointers on a simple replication case for this would be greatly appreciated.

@tiegz

thx @jasonrclark, just filed the ticket.

@jelder

@tiegz Can you share a link to the ticket you created, assuming it's public?

@tiegz

@jelder sorry, NR tix are not public.

@jasonrclark

@jelder Although you can't see the ticket in progress, I will report back here as soon as we reach any conclusions.

@masterkain

I'm not using newrelic, I'm using the ExceptionNotifier gem, seeing this error too, using Unicorn.

@nextofsearch

I don't see it any longer after upgrading to 3.5.6.48.beta.
Thanks,

@jasonrclark

@nextofsearch Glad to hear that resolved things for you. We're aiming to have a full release of the 3.5.6 agent in the next week or two, so I'll call that out here so anyone encountering the issue can try upgrading.

@atombender

@nextofsearch: That's a lovely graph, where is that from? gaug.es?

@jelder

@alexstaubo I think that's actually https://logentries.com/

@nextofsearch

@alexstaubo yes it's logentries

@digitalextremist

I'm getting this too. jRuby 1.7.3, Reel 0.3.0 (but also Trinidad), Rack 1.5.2 (but also 1.4.1), Sinatra 1.3.5.
I don't use newrelic, I don't have any exception notification going.
Do have isolated circumstance though... see after stack track(s)

Getting stack trace in triplicate:

TypeError - can't convert nil into Hash:
org/jruby/RubyHash.java:1681:in merge'
/usr/local/rvm/gems/jruby-1.7.3/gems/rack-1.5.2/lib/rack/request.rb:225:in
params'
/mu/zero/mu/deup.rb:72:in fork_environment!'
/mu/zero/mu/ma.rb:35:in
before (?-mix:)'
org/jruby/RubyMethod.java:118:in call'
/usr/local/rvm/gems/jruby-1.7.3/gems/sinatra-1.3.5/lib/sinatra/base.rb:1293:in
compile!'
org/jruby/RubyProc.java:249:in call'
/usr/local/rvm/gems/jruby-1.7.3/gems/sinatra-1.3.5/lib/sinatra/base.rb:897:in
process_route'
org/jruby/RubyKernel.java:1174:in catch'
/usr/local/rvm/gems/jruby-1.7.3/gems/sinatra-1.3.5/lib/sinatra/base.rb:895:in
process_route'
/usr/local/rvm/gems/jruby-1.7.3/gems/sinatra-1.3.5/lib/sinatra/base.rb:852:in filter!'
org/jruby/RubyArray.java:1613:in
each'
/usr/local/rvm/gems/jruby-1.7.3/gems/sinatra-1.3.5/lib/sinatra/base.rb:852:in filter!'
/usr/local/rvm/gems/jruby-1.7.3/gems/sinatra-1.3.5/lib/sinatra/base.rb:851:in
filter!'
/usr/local/rvm/gems/jruby-1.7.3/gems/sinatra-1.3.5/lib/sinatra/base.rb:962:in dispatch!'
/usr/local/rvm/gems/jruby-1.7.3/gems/sinatra-1.3.5/lib/sinatra/base.rb:946:in
invoke'
org/jruby/RubyKernel.java:1174:in catch'
/usr/local/rvm/gems/jruby-1.7.3/gems/sinatra-1.3.5/lib/sinatra/base.rb:946:in
invoke'
/usr/local/rvm/gems/jruby-1.7.3/gems/sinatra-1.3.5/lib/sinatra/base.rb:960:in dispatch!'
/usr/local/rvm/gems/jruby-1.7.3/gems/sinatra-1.3.5/lib/sinatra/base.rb:794:in
call!'
/usr/local/rvm/gems/jruby-1.7.3/gems/sinatra-1.3.5/lib/sinatra/base.rb:946:in invoke'
org/jruby/RubyKernel.java:1174:in
catch'
/usr/local/rvm/gems/jruby-1.7.3/gems/sinatra-1.3.5/lib/sinatra/base.rb:946:in invoke'
/usr/local/rvm/gems/jruby-1.7.3/gems/sinatra-1.3.5/lib/sinatra/base.rb:794:in
call!'
/usr/local/rvm/gems/jruby-1.7.3/gems/sinatra-1.3.5/lib/sinatra/base.rb:780:in call'
org/jruby/RubyKernel.java:1826:in
public_send'
/usr/local/rvm/gems/jruby-1.7.3/gems/celluloid-0.12.4/lib/celluloid/calls.rb:23:in dispatch'
/usr/local/rvm/gems/jruby-1.7.3/gems/celluloid-0.12.4/lib/celluloid/actor.rb:327:in
handle_message'
/usr/local/rvm/gems/jruby-1.7.3/gems/celluloid-0.12.4/lib/celluloid/tasks/task_fiber.rb:24:in initialize'
Exception in thread "JRubyWorker-8" TypeError: can't convert nil into Hash
org/jruby/RubyHash.java:1681:in
merge'
/usr/local/rvm/gems/jruby-1.7.3/gems/rack-1.5.2/lib/rack/request.rb:225:in params'
/mu/zero/mu/deup.rb:72:in
fork_environment!'
/mu/zero/mu/ma.rb:35:in before (?-mix:)'
org/jruby/RubyMethod.java:118:in
call'
/usr/local/rvm/gems/jruby-1.7.3/gems/sinatra-1.3.5/lib/sinatra/base.rb:1293:in compile!'
org/jruby/RubyProc.java:249:in
call'
/usr/local/rvm/gems/jruby-1.7.3/gems/sinatra-1.3.5/lib/sinatra/base.rb:897:in process_route'
org/jruby/RubyKernel.java:1174:in
catch'
/usr/local/rvm/gems/jruby-1.7.3/gems/sinatra-1.3.5/lib/sinatra/base.rb:895:in process_route'
/usr/local/rvm/gems/jruby-1.7.3/gems/sinatra-1.3.5/lib/sinatra/base.rb:852:in
filter!'
org/jruby/RubyArray.java:1613:in each'
/usr/local/rvm/gems/jruby-1.7.3/gems/sinatra-1.3.5/lib/sinatra/base.rb:852:in
filter!'
/usr/local/rvm/gems/jruby-1.7.3/gems/sinatra-1.3.5/lib/sinatra/base.rb:851:in filter!'
/usr/local/rvm/gems/jruby-1.7.3/gems/sinatra-1.3.5/lib/sinatra/base.rb:962:in
dispatch!'
/usr/local/rvm/gems/jruby-1.7.3/gems/sinatra-1.3.5/lib/sinatra/base.rb:946:in invoke'
org/jruby/RubyKernel.java:1174:in
catch'
/usr/local/rvm/gems/jruby-1.7.3/gems/sinatra-1.3.5/lib/sinatra/base.rb:946:in invoke'
/usr/local/rvm/gems/jruby-1.7.3/gems/sinatra-1.3.5/lib/sinatra/base.rb:960:in
dispatch!'
/usr/local/rvm/gems/jruby-1.7.3/gems/sinatra-1.3.5/lib/sinatra/base.rb:794:in call!'
/usr/local/rvm/gems/jruby-1.7.3/gems/sinatra-1.3.5/lib/sinatra/base.rb:946:in
invoke'
org/jruby/RubyKernel.java:1174:in catch'
/usr/local/rvm/gems/jruby-1.7.3/gems/sinatra-1.3.5/lib/sinatra/base.rb:946:in
invoke'
/usr/local/rvm/gems/jruby-1.7.3/gems/sinatra-1.3.5/lib/sinatra/base.rb:794:in call!'
/usr/local/rvm/gems/jruby-1.7.3/gems/sinatra-1.3.5/lib/sinatra/base.rb:780:in
call'
org/jruby/RubyKernel.java:1826:in public_send'
/usr/local/rvm/gems/jruby-1.7.3/gems/celluloid-0.12.4/lib/celluloid/calls.rb:23:in
dispatch'
/usr/local/rvm/gems/jruby-1.7.3/gems/celluloid-0.12.4/lib/celluloid/actor.rb:327:in handle_message'
/usr/local/rvm/gems/jruby-1.7.3/gems/celluloid-0.12.4/lib/celluloid/tasks/task_fiber.rb:24:in
initialize'
org.jruby.exceptions.RaiseException: (TypeError) can't convert nil into Hash
at org.jruby.RubyHash.merge(org/jruby/RubyHash.java:1681)
at RUBY.params(/usr/local/rvm/gems/jruby-1.7.3/gems/rack-1.5.2/lib/rack/request.rb:225)
at RUBY.fork_environment!(/mu/zero/mu/deup.rb:72)
at RUBY.before (?-mix:)(/mu/zero/mu/ma.rb:35)
at org.jruby.RubyMethod.call(org/jruby/RubyMethod.java:118)
at RUBY.compile!(/usr/local/rvm/gems/jruby-1.7.3/gems/sinatra-1.3.5/lib/sinatra/base.rb:1293)
at org.jruby.RubyProc.call(org/jruby/RubyProc.java:249)
at Sinatra::Base.process_route(/usr/local/rvm/gems/jruby-1.7.3/gems/sinatra-1.3.5/lib/sinatra/base.rb:897)
at org.jruby.RubyKernel.catch(org/jruby/RubyKernel.java:1174)
at Sinatra::Base.process_route(/usr/local/rvm/gems/jruby-1.7.3/gems/sinatra-1.3.5/lib/sinatra/base.rb:895)
at RUBY.filter!(/usr/local/rvm/gems/jruby-1.7.3/gems/sinatra-1.3.5/lib/sinatra/base.rb:852)
at org.jruby.RubyArray.each(org/jruby/RubyArray.java:1613)
at RUBY.filter!(/usr/local/rvm/gems/jruby-1.7.3/gems/sinatra-1.3.5/lib/sinatra/base.rb:852)
at RUBY.filter!(/usr/local/rvm/gems/jruby-1.7.3/gems/sinatra-1.3.5/lib/sinatra/base.rb:851)
at RUBY.dispatch!(/usr/local/rvm/gems/jruby-1.7.3/gems/sinatra-1.3.5/lib/sinatra/base.rb:962)
at RUBY.invoke(/usr/local/rvm/gems/jruby-1.7.3/gems/sinatra-1.3.5/lib/sinatra/base.rb:946)
at org.jruby.RubyKernel.catch(org/jruby/RubyKernel.java:1174)
at RUBY.invoke(/usr/local/rvm/gems/jruby-1.7.3/gems/sinatra-1.3.5/lib/sinatra/base.rb:946)
at RUBY.dispatch!(/usr/local/rvm/gems/jruby-1.7.3/gems/sinatra-1.3.5/lib/sinatra/base.rb:960)
at RUBY.call!(/usr/local/rvm/gems/jruby-1.7.3/gems/sinatra-1.3.5/lib/sinatra/base.rb:794)
at RUBY.invoke(/usr/local/rvm/gems/jruby-1.7.3/gems/sinatra-1.3.5/lib/sinatra/base.rb:946)
at org.jruby.RubyKernel.catch(org/jruby/RubyKernel.java:1174)
at RUBY.invoke(/usr/local/rvm/gems/jruby-1.7.3/gems/sinatra-1.3.5/lib/sinatra/base.rb:946)
at RUBY.call!(/usr/local/rvm/gems/jruby-1.7.3/gems/sinatra-1.3.5/lib/sinatra/base.rb:794)
at RUBY.call(/usr/local/rvm/gems/jruby-1.7.3/gems/sinatra-1.3.5/lib/sinatra/base.rb:780)
at org.jruby.RubyKernel.public_send(org/jruby/RubyKernel.java:1826)
at RUBY.dispatch(/usr/local/rvm/gems/jruby-1.7.3/gems/celluloid-0.12.4/lib/celluloid/calls.rb:23)
at Celluloid::Actor.handle_message(/usr/local/rvm/gems/jruby-1.7.3/gems/celluloid-0.12.4/lib/celluloid/actor.rb:327)
at RUBY.initialize(/usr/local/rvm/gems/jruby-1.7.3/gems/celluloid-0.12.4/lib/celluloid/tasks/task_fiber.rb:24)
10.126.130.1 - - [10/Mar/2013 19:16:52] "POST /.assets/513:fd2:744:t?01E=513d3e8e0cf2920e3518df72 1.1" 500 64624 0.2220

I get this when I upload images and video through plupload into a POST route. Seems like large multi-part file transfers. Doesn't happen when I upload a text file. If I was running an ASCII-based BBS this wouldn't be an issue. Shame on me.

@digitalextremist

@oscardelben I tried to inject your watcher by the way, and rack won't even completely initialize after that. It destroys the Hash class. I modified it to be this and I could initialize:

class Hash                                                                                                     
  def []=(key, value)
    if key =~ /.*form_hash.*/ && value.nil?
      warn "*********"
      warn " Setting form_hash to nil"
      warn "#{caller}"
      warn "*********"
    end
    self.update({ key => value })  #de
  end
end

Then, I got the warning:


Setting form_hash to nil
[
"/usr/local/rvm/gems/jruby-1.7.3/gems/rack-1.5.2/lib/rack/request.rb:203:in POST'",
"/usr/local/rvm/gems/jruby-1.7.3/gems/rack-1.5.2/lib/rack/request.rb:225:in
params'",
"/usr/local/rvm/gems/jruby-1.7.3/gems/sinatra-1.3.5/lib/sinatra/base.rb:789:in call!'",
"/usr/local/rvm/gems/jruby-1.7.3/gems/sinatra-1.3.5/lib/sinatra/base.rb:780:in
call'",
"/usr/local/rvm/gems/jruby-1.7.3/gems/celluloid-0.12.4/lib/celluloid/calls.rb:23:in public_send'",
"/usr/local/rvm/gems/jruby-1.7.3/gems/celluloid-0.12.4/lib/celluloid/calls.rb:23:in
dispatch'",
"/usr/local/rvm/gems/jruby-1.7.3/gems/celluloid-0.12.4/lib/celluloid/actor.rb:327:in handle_message'",
"/usr/local/rvm/gems/jruby-1.7.3/gems/celluloid-0.12.4/lib/celluloid/tasks/task_fiber.rb:24:in
initialize'",
"/usr/local/rvm/gems/jruby-1.7.3/gems/celluloid-0.12.4/lib/celluloid/tasks/task_fiber.rb:23:in `initialize'"
]


But not where I expected it. It happens somewhere which later recovers, which I had been trying to troubleshoot already but didn't stop to really solve. For some reason it recovers, so I just let that sleeping dog lie.

@digitalextremist

At @oscardelben's request (on twitter) I double checked all my gems, and they are at the newest version.
Still getting the error. Upon further investigation, it seems like form_hash is never set in ENV at all. Here's a new stack track which is very succinct...

TypeError: can't convert nil into Hash
org/jruby/RubyHash.java:1681:in merge'
/usr/local/rvm/gems/jruby-1.7.3/gems/rack-1.5.2/lib/rack/request.rb:225:in
params'
/usr/local/rvm/gems/jruby-1.7.3/gems/rack-jsonp-1.3.1/lib/rack/jsonp.rb:29:in call'
/usr/local/rvm/gems/jruby-1.7.3/gems/rack-1.5.2/lib/rack/content_length.rb:14:in
call'
/usr/local/rvm/gems/jruby-1.7.3/gems/rack-1.5.2/lib/rack/session/abstract/id.rb:225:in context'
/usr/local/rvm/gems/jruby-1.7.3/gems/rack-1.5.2/lib/rack/session/abstract/id.rb:220:in
call'
/usr/local/rvm/gems/jruby-1.7.3/gems/rack-1.5.2/lib/rack/lint.rb:49:in _call'
/usr/local/rvm/gems/jruby-1.7.3/gems/rack-1.5.2/lib/rack/lint.rb:37:in
call'
/usr/local/rvm/gems/jruby-1.7.3/gems/rack-1.5.2/lib/rack/showexceptions.rb:24:in call'
/usr/local/rvm/gems/jruby-1.7.3/gems/rack-1.5.2/lib/rack/commonlogger.rb:33:in
call'
/usr/local/rvm/gems/jruby-1.7.3/gems/sinatra-1.3.5/lib/sinatra/base.rb:161:in call'
/usr/local/rvm/gems/jruby-1.7.3/gems/rack-1.5.2/lib/rack/chunked.rb:43:in
call'
/usr/local/rvm/gems/jruby-1.7.3/gems/rack-1.5.2/lib/rack/content_length.rb:14:in call'
/usr/local/rvm/gems/jruby-1.7.3/gems/reel-0.3.0/lib/reel/rack_worker.rb:73:in
handle_request'
/usr/local/rvm/gems/jruby-1.7.3/gems/reel-0.3.0/lib/reel/rack_worker.rb:65:in handle'
org/jruby/RubyBasicObject.java:1704:in
send'
org/jruby/RubyKernel.java:1826:in public_send'
/usr/local/rvm/gems/jruby-1.7.3/gems/celluloid-0.12.4/lib/celluloid/calls.rb:23:in
dispatch'
/usr/local/rvm/gems/jruby-1.7.3/gems/celluloid-0.12.4/lib/celluloid/actor.rb:327:in handle_message'
/usr/local/rvm/gems/jruby-1.7.3/gems/celluloid-0.12.4/lib/celluloid/tasks/task_fiber.rb:24:in
initialize'
10.126.130.1 - - [12/Mar/2013 21:07:22] "POST /.assets/513:fd2:744:t?01E=513ffb6b0cf25d7c809ad6fb 1.1" 500 53176 0.0610

Might migrate to webmachine-ruby away from rack from this to try to turn this into an opportunity, but still not convinced I need to.

Again, this seems isolated to certain kinds of upload. Uploading a .txt file is not a problem, but upload a .png or .mp4?Crash. Very large .xml file worked. PDF crashed.

@digitalextremist

By the way, here's a successful stack track for reference... makes it all the way to a store! method call:

/mu/zero/mu/maai/assets.rb:136:in `store!'
/mu/zero/mu/ma/assets.rb:154:in `POST /:id'
/usr/local/rvm/gems/jruby-1.7.3/gems/sinatra-1.3.5/lib/sinatra/base.rb:1293:in `call'
/usr/local/rvm/gems/jruby-1.7.3/gems/sinatra-1.3.5/lib/sinatra/base.rb:1293:in `compile!'
/usr/local/rvm/gems/jruby-1.7.3/gems/sinatra-1.3.5/lib/sinatra/base.rb:860:in `call'
/usr/local/rvm/gems/jruby-1.7.3/gems/sinatra-1.3.5/lib/sinatra/base.rb:860:in `route!'
/usr/local/rvm/gems/jruby-1.7.3/gems/sinatra-1.3.5/lib/sinatra/base.rb:876:in `route_eval'
/usr/local/rvm/gems/jruby-1.7.3/gems/sinatra-1.3.5/lib/sinatra/base.rb:860:in `route!'
/usr/local/rvm/gems/jruby-1.7.3/gems/sinatra-1.3.5/lib/sinatra/base.rb:897:in `process_route'
/usr/local/rvm/gems/jruby-1.7.3/gems/sinatra-1.3.5/lib/sinatra/base.rb:895:in `catch'
/usr/local/rvm/gems/jruby-1.7.3/gems/sinatra-1.3.5/lib/sinatra/base.rb:895:in `process_route'
/usr/local/rvm/gems/jruby-1.7.3/gems/sinatra-1.3.5/lib/sinatra/base.rb:859:in `route!'
/usr/local/rvm/gems/jruby-1.7.3/gems/sinatra-1.3.5/lib/sinatra/base.rb:858:in `each'
/usr/local/rvm/gems/jruby-1.7.3/gems/sinatra-1.3.5/lib/sinatra/base.rb:858:in `route!'
/usr/local/rvm/gems/jruby-1.7.3/gems/sinatra-1.3.5/lib/sinatra/base.rb:963:in `dispatch!'
/usr/local/rvm/gems/jruby-1.7.3/gems/sinatra-1.3.5/lib/sinatra/base.rb:946:in `invoke'
/usr/local/rvm/gems/jruby-1.7.3/gems/sinatra-1.3.5/lib/sinatra/base.rb:946:in `catch'
/usr/local/rvm/gems/jruby-1.7.3/gems/sinatra-1.3.5/lib/sinatra/base.rb:946:in `invoke'
/usr/local/rvm/gems/jruby-1.7.3/gems/sinatra-1.3.5/lib/sinatra/base.rb:960:in `dispatch!'
/usr/local/rvm/gems/jruby-1.7.3/gems/sinatra-1.3.5/lib/sinatra/base.rb:794:in `call!'
/usr/local/rvm/gems/jruby-1.7.3/gems/sinatra-1.3.5/lib/sinatra/base.rb:946:in `invoke'
/usr/local/rvm/gems/jruby-1.7.3/gems/sinatra-1.3.5/lib/sinatra/base.rb:946:in `catch'
/usr/local/rvm/gems/jruby-1.7.3/gems/sinatra-1.3.5/lib/sinatra/base.rb:946:in `invoke'
/usr/local/rvm/gems/jruby-1.7.3/gems/sinatra-1.3.5/lib/sinatra/base.rb:794:in `call!'
/usr/local/rvm/gems/jruby-1.7.3/gems/sinatra-1.3.5/lib/sinatra/base.rb:780:in `call'
/usr/local/rvm/gems/jruby-1.7.3/gems/rack-protection-1.4.0/lib/rack/protection/xss_header.rb:18:in `call'
/usr/local/rvm/gems/jruby-1.7.3/gems/rack-protection-1.4.0/lib/rack/protection/path_traversal.rb:16:in `call'
/usr/local/rvm/gems/jruby-1.7.3/gems/rack-protection-1.4.0/lib/rack/protection/json_csrf.rb:18:in `call'
/usr/local/rvm/gems/jruby-1.7.3/gems/rack-protection-1.4.0/lib/rack/protection/base.rb:48:in `call'
/usr/local/rvm/gems/jruby-1.7.3/gems/rack-protection-1.4.0/lib/rack/protection/base.rb:48:in `call'
/usr/local/rvm/gems/jruby-1.7.3/gems/rack-protection-1.4.0/lib/rack/protection/frame_options.rb:31:in `call'
/usr/local/rvm/gems/jruby-1.7.3/gems/rack-1.5.2/lib/rack/logger.rb:15:in `call'
/usr/local/rvm/gems/jruby-1.7.3/gems/sinatra-1.3.5/lib/sinatra/base.rb:154:in `call'
/usr/local/rvm/gems/jruby-1.7.3/gems/rack-1.5.2/lib/rack/head.rb:11:in `call'
/usr/local/rvm/gems/jruby-1.7.3/gems/sinatra-1.3.5/lib/sinatra/showexceptions.rb:21:in `call'
/usr/local/rvm/gems/jruby-1.7.3/gems/sinatra-1.3.5/lib/sinatra/base.rb:124:in `call'
/usr/local/rvm/gems/jruby-1.7.3/gems/sinatra-1.3.5/lib/sinatra/base.rb:1417:in `call'
/usr/local/rvm/gems/jruby-1.7.3/gems/sinatra-1.3.5/lib/sinatra/base.rb:1499:in `synchronize'
/usr/local/rvm/gems/jruby-1.7.3/gems/sinatra-1.3.5/lib/sinatra/base.rb:1417:in `call'
/usr/local/rvm/gems/jruby-1.7.3/gems/rack-1.5.2/lib/rack/builder.rb:138:in `call'
/usr/local/rvm/gems/jruby-1.7.3/gems/rack-1.5.2/lib/rack/urlmap.rb:65:in `call'
/usr/local/rvm/gems/jruby-1.7.3/gems/rack-1.5.2/lib/rack/urlmap.rb:50:in `each'
/usr/local/rvm/gems/jruby-1.7.3/gems/rack-1.5.2/lib/rack/urlmap.rb:50:in `call'
/usr/local/rvm/gems/jruby-1.7.3/gems/rack-1.5.2/lib/rack/reloader.rb:44:in `call'
/usr/local/rvm/gems/jruby-1.7.3/gems/rack-1.5.2/lib/rack/deflater.rb:25:in `call'
/usr/local/rvm/gems/jruby-1.7.3/gems/rack-jsonp-1.3.1/lib/rack/jsonp.rb:36:in `call'
/usr/local/rvm/gems/jruby-1.7.3/gems/rack-1.5.2/lib/rack/content_length.rb:14:in `call'
/usr/local/rvm/gems/jruby-1.7.3/gems/rack-1.5.2/lib/rack/session/abstract/id.rb:225:in `context'
/usr/local/rvm/gems/jruby-1.7.3/gems/rack-1.5.2/lib/rack/session/abstract/id.rb:220:in `call'
/usr/local/rvm/gems/jruby-1.7.3/gems/rack-1.5.2/lib/rack/lint.rb:49:in `_call'
/usr/local/rvm/gems/jruby-1.7.3/gems/rack-1.5.2/lib/rack/lint.rb:37:in `call'
/usr/local/rvm/gems/jruby-1.7.3/gems/rack-1.5.2/lib/rack/showexceptions.rb:24:in `call'
/usr/local/rvm/gems/jruby-1.7.3/gems/rack-1.5.2/lib/rack/commonlogger.rb:33:in `call'
/usr/local/rvm/gems/jruby-1.7.3/gems/sinatra-1.3.5/lib/sinatra/base.rb:161:in `call'
/usr/local/rvm/gems/jruby-1.7.3/gems/rack-1.5.2/lib/rack/chunked.rb:43:in `call'
/usr/local/rvm/gems/jruby-1.7.3/gems/rack-1.5.2/lib/rack/content_length.rb:14:in `call'
/usr/local/rvm/gems/jruby-1.7.3/gems/reel-0.3.0/lib/reel/rack_worker.rb:73:in `handle_request'
/usr/local/rvm/gems/jruby-1.7.3/gems/reel-0.3.0/lib/reel/rack_worker.rb:65:in `handle'
/usr/local/rvm/gems/jruby-1.7.3/gems/celluloid-0.12.4/lib/celluloid/calls.rb:23:in `public_send'
/usr/local/rvm/gems/jruby-1.7.3/gems/celluloid-0.12.4/lib/celluloid/calls.rb:23:in `dispatch'
/usr/local/rvm/gems/jruby-1.7.3/gems/celluloid-0.12.4/lib/celluloid/actor.rb:327:in `handle_message'
/usr/local/rvm/gems/jruby-1.7.3/gems/celluloid-0.12.4/lib/celluloid/tasks/task_fiber.rb:24:in `initialize'
@digitalextremist

Reverted from Rack 1.5.2 to 1.5.0, to 1.4.5.. no change. Then 1.4.1... seems to work now. Figuring out why... and do notice it fails with Reel 0.3.0 but works with Trinidad 1.4.4

@digitalextremist

Baffled now. I reverted many gems to get to where it worked again.
After getting it working, I tried to break it again to duplicate the error.

I went back up to 1.4.5 and it worked. And then 1.5.2 worked.
I went from rack-protection 1.3.0 to 1.4.0, then 1.5.0. Each worked.
Went back from trinidad_jars 1.1.1 to 1.2.2 and it still worked.
Went back from sinatra 1.3.3 to 1.3.5 ... works.
jruby-rack 1.1.10 to 1.1.13.1 ...works.

The only other change I made to resolve the issue is to store a key of a Hash as a string rather than an integer, which caused the Java undercarriage of jRuby to revolt with a failure to cast a Java::Long as a RubyObject.

Seems unrelated to why params would fail to contain a sane POST hash, but that is the only other change I made.

Very strange. I can remove my stack traces (or someone with rights to is welcome to) since they now seem to lead nowhere. No scientific method, just magically working... but, Reel 0.3.0 still does die, versus Trinidad 1.4.4 //

@zimbatm

In our code base, the only references to 'form_input' and 'form_hash' are in rack/request.rb:

def POST
  if @env["rack.input"].nil?
    raise "Missing rack.input"
  elsif @env["rack.request.form_input"].eql? @env["rack.input"]
    @env["rack.request.form_hash"]
  elsif form_data? || parseable_data?
    @env["rack.request.form_input"] = @env["rack.input"]
    unless @env["rack.request.form_hash"] = parse_multipart(env)
      form_vars = @env["rack.input"].read

      # Fix for Safari Ajax postings that always append \0
      # form_vars.sub!(/\0\z/, '') # performance replacement:
      form_vars.slice!(-1) if form_vars[-1] == ?\0

      @env["rack.request.form_vars"] = form_vars
      @env["rack.request.form_hash"] = parse_query(form_vars)

      @env["rack.input"].rewind
    end
    @env["rack.request.form_hash"]
  else
    {}
  end
end

The only logic explanation that I've found is that somehow that method gets invoked and interrupts around #parse_multipart with an exception. Then a second call is made and we end up in the second branch with no data (the key isn't even set here)

@digitalextremist

@zimbatm thanks for commenting. I've sat staring at POST() as you pasted for a long time.

I do see parse_multipart() is invoked, fails down the line at get_current_head_and_filename_and_content_type_and_name_and_body() called by multipart/parser.rb's parse() with "bad content body" ... but only under certain cases. Other times it works.

This file works:
belej3btojimoxjun-009 9Lb1

So does this:
9Hw1

This file does not:
belejebkemetijaxbelejeb-009 9Lb1

Cannot see the difference between the files which causes that. It's not filename length.

BUT: Right now, no matter whether it works or not, the file saved is corrupted, after the multipart is parsed and provided through params() in a TempFile. The resulting file is usually around double the proper size.

@digitalextremist

Text files work, without error or corruption... but binary files are unreliable and disturbed.

@zimbatm

@digitalextremist : how minimal can you make the test case ? It's would be great to reduce it to a StringIO containing the multipart data and the MultiPart::Parser.

Unfortunately I can't reproduce the issue on my side and it's initiated by a customer on our API.

Maybe it's an encoding issue, can you try to put this middleware on top of the stack ? :

class BinMode
  def initialize(app)
    @app = app
  end
  def call(env)
     @env['rack.input'].binmode
     @app.call(env)
  end
end
@digitalextremist

Yes, I have the data views you are talking about. I can post those after trying your piece of code.

Do I invoke that with a simple use BinMode after declaring it?

@digitalextremist

Ok I have invoked the Middleware and am adapting it to test with it.

@digitalextremist

No change when I inserted this into my stack:

class BinMode
  def initialize(app)
    @app = app
  end
  def call(env)
    if !env['rack.input'].nil?
        env['rack.input'].binmode
    end
    @app.call(env)
  end
end
use BinMode
@digitalextremist

Here is an example of env on a failed upload:

{
  "rack.version": [
    1,
    2
  ],
  "rack.errors": "#<IO:0x33d650f6>",
  "rack.multithread": true,
  "rack.multiprocess": false,
  "rack.run_once": false,
  "rack.url_scheme": "http",
  "SCRIPT_NAME": "",
  "SERVER_PROTOCOL": "HTTP/1.1",
  "SERVER_SOFTWARE": "Reel/0.3.0",
  "GATEWAY_INTERFACE": "CGI/1.1",
  "rack.input": "#<StringIO:0x349021f8>",
  "SERVER_NAME": "0.zero",
  "SERVER_PORT": "88",
  "HTTP_VERSION": "1.1",
  "REQUEST_METHOD": "POST",
  "PATH_INFO": "/uploading",
  "QUERY_STRING": "",
  "CONTENT_TYPE": "multipart/form-data; boundary=----WebKitFormBoundaryeRQxmIqx4AbkFAWa",
  "CONTENT_LENGTH": "131559",
  "HTTP_HOST": "0.zero:88",
  "HTTP_CONNECTION": "keep-alive",
  "HTTP_ORIGIN": "http://0.zero:88",
  "HTTP_USER_AGENT": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_6_8) AppleWebKit/537.31 (KHTML, like Gecko) Chrome/26.0.1410.65 Safari/537.31",
  "HTTP_ACCEPT": "*/*",
  "HTTP_REFERER": "http://0.zero:88/uploader.html",
  "HTTP_ACCEPT_ENCODING": "gzip,deflate,sdch",
  "HTTP_ACCEPT_LANGUAGE": "en-US,en;q=0.8",
  "HTTP_ACCEPT_CHARSET": "ISO-8859-1,utf-8;q=0.7,*;q=0.3",
  "REMOTE_ADDR": "10.126.130.1",
  "rack.request.form_input": "#<StringIO:0x349021f8>"
}

Then EOFError: bad content body.

rack.input contains something like:

rack.input:
------WebKitFormBoundaryeRQxmIqx4AbkFAWa
Content-Disposition: form-data; name="name"

OrphenBackup.zip
------WebKitFormBoundaryeRQxmIqx4AbkFAWa
Content-Disposition: form-data; name="chunk"

0
------WebKitFormBoundaryeRQxmIqx4AbkFAWa
Content-Disposition: form-data; name="chunks"

97
------WebKitFormBoundaryeRQxmIqx4AbkFAWa
Content-Disposition: form-data; name="file"; filename="blob"
Content-Type: application/octet-stream

.... binary data ....
------WebKitFormBoundaryeRQxmIqx4AbkFAWa--

The binary data looks like this to me:
binary-data 017-4Vr9

@digitalextremist

I've gotten down to a very small test case: https://gist.github.com/digitalextremist/5404953

I've removed the reference to PLUpload, since an ordinary upload with <input type='file'> also fails the same.

@zimbatm

@digitalextremist sweet, can you also add your Gemfile and the failing / working files to the gist too ?

@digitalextremist

I have an extremely bloated Gemfile filled with things I am not using, because I brought it over from the larger application I want to work properly, after multipart parsing is healed, but OK: Adding that and the other files to the gist.

@digitalextremist

Gemfile added, and the files I used are up above in this thread. The first two "work" the third does not. Remember though, all those files which succeed are still corrupted.

@zimbatm

@digitalextremist I've tried to reproduce but it seems to be working here. Here's the gist after a couple of fixes: https://gist.github.com/zimbatm/5405399

@zimbatm

Can you change the middleware to dump the data ?

class BinMode
  def initialize(app)
    @app = app
  end
  def call(env)
    if env['rack.input']
      File.open('dump', 'w:b') do |f|
        f.write env['rack.input'].read
      end
      env['rack.input'].rewind
    end
    @app.call(env)
  end
end
use BinMode
@digitalextremist

OK, done. I had to take the colon out of "w:b" for it to work, but dump appears empty.

@digitalextremist

Something still arrives in my uploads/ folder though, so not sure how or why rack.input is empty.

@digitalextremist
class BinMode
  def initialize(app)
    @app = app
  end
  def call(env)
    if env['rack.input']
      env['rack.input'].rewind
      _de caller, "Using BinMode //" + env['rack.input'].size.to_s
      File.open('dump', 'wb') do |f|
        f.write env['rack.input'].read
      end
      env['rack.input'].rewind
    end
    @app.call(env)
  end
end
use BinMode

console output:

Parsing multipart data //
> > > > test-reel - - - - - - - - - - - -

filename // binary-data.017-4Vr9.png
> > > > test-reel - - - - - - - - - - - -

/mu/tweaking/rack/lib/rack/reloader.rb:44:in `call'
/usr/local/rvm/gems/jruby-1.7.2/gems/rack-protection-1.5.0/lib/rack/protection/xss_header.rb:18:in `call'
/usr/local/rvm/gems/jruby-1.7.2/gems/rack-protection-1.5.0/lib/rack/protection/path_traversal.rb:16:in `call'
/usr/local/rvm/gems/jruby-1.7.2/gems/rack-protection-1.5.0/lib/rack/protection/json_csrf.rb:18:in `call'
/usr/local/rvm/gems/jruby-1.7.2/gems/rack-protection-1.5.0/lib/rack/protection/base.rb:49:in `call'
/usr/local/rvm/gems/jruby-1.7.2/gems/rack-protection-1.5.0/lib/rack/protection/base.rb:49:in `call'
/usr/local/rvm/gems/jruby-1.7.2/gems/rack-protection-1.5.0/lib/rack/protection/frame_options.rb:31:in `call'
/mu/tweaking/rack/lib/rack/logger.rb:15:in `call'
/mu/tweaking/rack/lib/rack/commonlogger.rb:33:in `call'
/usr/local/rvm/gems/jruby-1.7.2/gems/sinatra-1.3.5/lib/sinatra/base.rb:161:in `call'
/usr/local/rvm/gems/jruby-1.7.2/gems/sinatra-1.3.5/lib/sinatra/base.rb:154:in `call'
/mu/tweaking/rack/lib/rack/head.rb:11:in `call'
/mu/tweaking/rack/lib/rack/methodoverride.rb:21:in `call'
/usr/local/rvm/gems/jruby-1.7.2/gems/sinatra-1.3.5/lib/sinatra/showexceptions.rb:21:in `call'
/usr/local/rvm/gems/jruby-1.7.2/gems/sinatra-1.3.5/lib/sinatra/base.rb:124:in `call'
/usr/local/rvm/gems/jruby-1.7.2/gems/sinatra-1.3.5/lib/sinatra/base.rb:1417:in `call'
/usr/local/rvm/gems/jruby-1.7.2/gems/sinatra-1.3.5/lib/sinatra/base.rb:1499:in `synchronize'
/usr/local/rvm/gems/jruby-1.7.2/gems/sinatra-1.3.5/lib/sinatra/base.rb:1417:in `call'
/mu/rack-reel/reel/lib/reel/rack_worker.rb:73:in `handle_request'
/mu/rack-reel/reel/lib/reel/rack_worker.rb:65:in `handle'
/usr/local/rvm/gems/jruby-1.7.2/bundler/gems/celluloid-b5488427f600/lib/celluloid/calls.rb:25:in `public_send'
/usr/local/rvm/gems/jruby-1.7.2/bundler/gems/celluloid-b5488427f600/lib/celluloid/calls.rb:25:in `dispatch'
/usr/local/rvm/gems/jruby-1.7.2/bundler/gems/celluloid-b5488427f600/lib/celluloid/calls.rb:67:in `dispatch'
/usr/local/rvm/gems/jruby-1.7.2/bundler/gems/celluloid-b5488427f600/lib/celluloid/actor.rb:322:in `handle_message'
/usr/local/rvm/gems/jruby-1.7.2/bundler/gems/celluloid-b5488427f600/lib/celluloid/tasks.rb:44:in `initialize'
/usr/local/rvm/gems/jruby-1.7.2/bundler/gems/celluloid-b5488427f600/lib/celluloid/tasks/task_fiber.rb:9:in `create'
> > > > test-reel - - - - - - - - - - - - END: Using BinMode //0
@zimbatm

@digitalextremist if you run my gist you'll get a EOFError in the parser, probably a reel or celluloid bug.

@digitalextremist

Thanks @zimbatm. I confirmed it is an issue with http_parser.rb and not Reel or Celluloid. jRuby support for that parser is truncating or somehow altering rack.input by the time it reaches Rack.

Carried on here:

@zimbatm

In my case I've recently upgraded unicorn from v4.3.1 to v4.6.2 and there are changes in the http parser too. I'm using sentry-raven to report exception and it's using req.POST while constructing rack exception messages.

@jdelStrother

I added a pull request #561 which is related to this. While it won't fix the underlying problem of having unparseable multipart content, it does fix things so that request.POST consistently raises EOFError on failing to parse, rather than sometimes raising it and sometimes returning nil.

@volx7577

Did anyone ever find a workaround to this issue? I'm getting it using unicorn and new relic:

[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/gems/rack-1.4.5/lib/rack/request.rb:221 :in `merge`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/gems/rack-1.4.5/lib/rack/request.rb:221 :in `params`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/gems/jquery-fileupload-rails-0.4.1/lib/jquery/fileupload/rails/middleware.rb:32 :in `iframe_transport?`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/gems/jquery-fileupload-rails-0.4.1/lib/jquery/fileupload/rails/middleware.rb:17 :in `_call`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/gems/jquery-fileupload-rails-0.4.1/lib/jquery/fileupload/rails/middleware.rb:10 :in `call`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/gems/newrelic_rpm-3.9.1.236/lib/new_relic/agent/instrumentation/middleware_tracing.rb:57 :in `call`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/gems/newrelic_rpm-3.9.1.236/lib/new_relic/rack/error_collector.rb:50 :in `traced_call`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/gems/newrelic_rpm-3.9.1.236/lib/new_relic/agent/instrumentation/middleware_tracing.rb:55 :in `call`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/gems/newrelic_rpm-3.9.1.236/lib/new_relic/rack/agent_hooks.rb:26 :in `traced_call`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/gems/newrelic_rpm-3.9.1.236/lib/new_relic/agent/instrumentation/middleware_tracing.rb:55 :in `call`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/gems/newrelic_rpm-3.9.1.236/lib/new_relic/rack/browser_monitoring.rb:23 :in `traced_call`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/gems/newrelic_rpm-3.9.1.236/lib/new_relic/agent/instrumentation/middleware_tracing.rb:55 :in `call`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/gems/rack-ssl-enforcer-0.2.8/lib/rack/ssl-enforcer.rb:52 :in `call`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/gems/newrelic_rpm-3.9.1.236/lib/new_relic/agent/instrumentation/middleware_tracing.rb:57 :in `call`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/gems/warden-1.2.3/lib/warden/manager.rb:35 :in `block in call`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/gems/warden-1.2.3/lib/warden/manager.rb:34 :in `catch`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/gems/warden-1.2.3/lib/warden/manager.rb:34 :in `call`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/gems/newrelic_rpm-3.9.1.236/lib/new_relic/agent/instrumentation/middleware_tracing.rb:57 :in `call`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/gems/actionpack-3.2.18/lib/action_dispatch/middleware/best_standards_support.rb:17 :in `call`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/gems/newrelic_rpm-3.9.1.236/lib/new_relic/agent/instrumentation/middleware_tracing.rb:57 :in `call`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/gems/rack-1.4.5/lib/rack/etag.rb:23 :in `call`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/gems/newrelic_rpm-3.9.1.236/lib/new_relic/agent/instrumentation/middleware_tracing.rb:57 :in `call`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/gems/rack-1.4.5/lib/rack/conditionalget.rb:35 :in `call`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/gems/newrelic_rpm-3.9.1.236/lib/new_relic/agent/instrumentation/middleware_tracing.rb:57 :in `call`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/gems/actionpack-3.2.18/lib/action_dispatch/middleware/head.rb:14 :in `call`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/gems/newrelic_rpm-3.9.1.236/lib/new_relic/agent/instrumentation/middleware_tracing.rb:57 :in `call`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/gems/actionpack-3.2.18/lib/action_dispatch/middleware/params_parser.rb:21 :in `call`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/gems/newrelic_rpm-3.9.1.236/lib/new_relic/agent/instrumentation/middleware_tracing.rb:57 :in `call`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/gems/actionpack-3.2.18/lib/action_dispatch/middleware/flash.rb:242 :in `call`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/gems/newrelic_rpm-3.9.1.236/lib/new_relic/agent/instrumentation/middleware_tracing.rb:57 :in `call`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/gems/rack-1.4.5/lib/rack/session/abstract/id.rb:210 :in `context`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/gems/rack-1.4.5/lib/rack/session/abstract/id.rb:205 :in `call`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/gems/newrelic_rpm-3.9.1.236/lib/new_relic/agent/instrumentation/middleware_tracing.rb:57 :in `call`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/gems/actionpack-3.2.18/lib/action_dispatch/middleware/cookies.rb:341 :in `call`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/gems/newrelic_rpm-3.9.1.236/lib/new_relic/agent/instrumentation/middleware_tracing.rb:57 :in `call`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/gems/activerecord-3.2.18/lib/active_record/query_cache.rb:64 :in `call`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/gems/newrelic_rpm-3.9.1.236/lib/new_relic/agent/instrumentation/middleware_tracing.rb:57 :in `call`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/gems/activerecord-3.2.18/lib/active_record/connection_adapters/abstract/connection_pool.rb:479 :in `call`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/gems/newrelic_rpm-3.9.1.236/lib/new_relic/agent/instrumentation/middleware_tracing.rb:57 :in `call`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/gems/actionpack-3.2.18/lib/action_dispatch/middleware/callbacks.rb:28 :in `block in call`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/gems/activesupport-3.2.18/lib/active_support/callbacks.rb:405 :in `_run__3158766179523798800__call__1830933626558231124__callbacks`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/gems/activesupport-3.2.18/lib/active_support/callbacks.rb:405 :in `__run_callback`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/gems/activesupport-3.2.18/lib/active_support/callbacks.rb:385 :in `_run_call_callbacks`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/gems/activesupport-3.2.18/lib/active_support/callbacks.rb:81 :in `run_callbacks`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/gems/actionpack-3.2.18/lib/action_dispatch/middleware/callbacks.rb:27 :in `call`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/gems/newrelic_rpm-3.9.1.236/lib/new_relic/agent/instrumentation/middleware_tracing.rb:57 :in `call`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/gems/actionpack-3.2.18/lib/action_dispatch/middleware/remote_ip.rb:31 :in `call`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/gems/newrelic_rpm-3.9.1.236/lib/new_relic/agent/instrumentation/middleware_tracing.rb:57 :in `call`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/gems/actionpack-3.2.18/lib/action_dispatch/middleware/debug_exceptions.rb:16 :in `call`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/gems/newrelic_rpm-3.9.1.236/lib/new_relic/agent/instrumentation/middleware_tracing.rb:57 :in `call`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/gems/actionpack-3.2.18/lib/action_dispatch/middleware/show_exceptions.rb:56 :in `call`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/gems/newrelic_rpm-3.9.1.236/lib/new_relic/agent/instrumentation/middleware_tracing.rb:57 :in `call`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/gems/railties-3.2.18/lib/rails/rack/logger.rb:32 :in `call_app`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/gems/railties-3.2.18/lib/rails/rack/logger.rb:16 :in `block in call`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/gems/activesupport-3.2.18/lib/active_support/tagged_logging.rb:22 :in `tagged`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/gems/railties-3.2.18/lib/rails/rack/logger.rb:16 :in `call`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/gems/newrelic_rpm-3.9.1.236/lib/new_relic/agent/instrumentation/middleware_tracing.rb:57 :in `call`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/gems/actionpack-3.2.18/lib/action_dispatch/middleware/request_id.rb:22 :in `call`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/gems/newrelic_rpm-3.9.1.236/lib/new_relic/agent/instrumentation/middleware_tracing.rb:57 :in `call`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/gems/rack-1.4.5/lib/rack/methodoverride.rb:21 :in `call`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/gems/newrelic_rpm-3.9.1.236/lib/new_relic/agent/instrumentation/middleware_tracing.rb:57 :in `call`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/gems/rack-1.4.5/lib/rack/runtime.rb:17 :in `call`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/gems/newrelic_rpm-3.9.1.236/lib/new_relic/agent/instrumentation/middleware_tracing.rb:57 :in `call`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/gems/activesupport-3.2.18/lib/active_support/cache/strategy/local_cache.rb:72 :in `call`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/gems/newrelic_rpm-3.9.1.236/lib/new_relic/agent/instrumentation/middleware_tracing.rb:57 :in `call`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/gems/rack-1.4.5/lib/rack/lock.rb:15 :in `call`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/gems/newrelic_rpm-3.9.1.236/lib/new_relic/agent/instrumentation/middleware_tracing.rb:57 :in `call`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/gems/actionpack-3.2.18/lib/action_dispatch/middleware/static.rb:63 :in `call`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/gems/newrelic_rpm-3.9.1.236/lib/new_relic/agent/instrumentation/middleware_tracing.rb:57 :in `call`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/gems/rack-cache-1.2/lib/rack/cache/context.rb:136 :in `forward`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/gems/rack-cache-1.2/lib/rack/cache/context.rb:143 :in `pass`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/gems/rack-cache-1.2/lib/rack/cache/context.rb:155 :in `invalidate`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/gems/rack-cache-1.2/lib/rack/cache/context.rb:71 :in `call!`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/gems/rack-cache-1.2/lib/rack/cache/context.rb:51 :in `call`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/gems/newrelic_rpm-3.9.1.236/lib/new_relic/agent/instrumentation/middleware_tracing.rb:57 :in `call`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/gems/newrelic_rpm-3.9.1.236/lib/new_relic/agent/instrumentation/middleware_tracing.rb:57 :in `call`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/gems/newrelic_rpm-3.9.1.236/lib/new_relic/agent/instrumentation/middleware_tracing.rb:57 :in `call`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/gems/newrelic_rpm-3.9.1.236/lib/new_relic/agent/instrumentation/middleware_tracing.rb:57 :in `call`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/gems/rack-timeout-0.0.4/lib/rack/timeout.rb:16 :in `block in call`
[PROJECT_ROOT]/vendor/ruby-1.9.3/lib/ruby/1.9.1/timeout.rb:69 :in `timeout`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/gems/rack-timeout-0.0.4/lib/rack/timeout.rb:16 :in `call`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/gems/newrelic_rpm-3.9.1.236/lib/new_relic/agent/instrumentation/middleware_tracing.rb:57 :in `call`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/gems/railties-3.2.18/lib/rails/engine.rb:484 :in `call`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/gems/railties-3.2.18/lib/rails/application.rb:231 :in `call`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/gems/railties-3.2.18/lib/rails/railtie/configurable.rb:30 :in `method_missing`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/gems/newrelic_rpm-3.9.1.236/lib/new_relic/agent/instrumentation/middleware_tracing.rb:57 :in `call`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/gems/unicorn-4.8.3/lib/unicorn/http_server.rb:576 :in `process_client`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/gems/unicorn-4.8.3/lib/unicorn/http_server.rb:670 :in `worker_loop`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/gems/unicorn-4.8.3/lib/unicorn/http_server.rb:525 :in `spawn_missing_workers`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/gems/unicorn-4.8.3/lib/unicorn/http_server.rb:140 :in `start`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/gems/unicorn-4.8.3/bin/unicorn:126 :in `<top (required)>`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/bin/unicorn:23 :in `load`
[PROJECT_ROOT]/vendor/bundle/ruby/1.9.1/bin/unicorn:23 :in `<main>`

and here's my env:

"REQUEST_METHOD" => "POST",

"SERVER_PROTOCOL" => "HTTP/1.1",
"HTTP_VERSION" => "HTTP/1.1",
"HTTP_CONNECTION" => "close",
"HTTP_ACCEPT" => "/",
"HTTP_X_CSRF_TOKEN" => "S4avD6tueTXTai3j2STC8rW22VHu61Oy481CDoVTYH8=",
"HTTP_X_REQUESTED_WITH" => "XMLHttpRequest",
"CONTENT_TYPE" => "multipart/form-data; boundary=---------------------------7df33c3b30576",
"HTTP_ACCEPT_LANGUAGE" => "en-US",
"HTTP_ACCEPT_ENCODING" => "gzip, deflate",
"HTTP_USER_AGENT" => "Mozilla/5.0 (Windows NT 6.1; WOW64; Trident/7.0; NP09; NP09; MAAU; rv:11.0) like Gecko",
"HTTP_DNT" => "1",
"HTTP_CACHE_CONTROL" => "no-cache",
"HTTP_X_REQUEST_ID" => "82952cd0-e783-4c70-8213-431c90e331bf",
"HTTP_X_FORWARDED_FOR" => "204.111.22.5",
"HTTP_X_FORWARDED_PROTO" => "https",
"HTTP_X_FORWARDED_PORT" => "443",
"HTTP_VIA" => "1.1 vegur",
"HTTP_CONNECT_TIME" => "2",
"HTTP_X_REQUEST_START" => "1424193899923",
"HTTP_TOTAL_ROUTE_TIME" => "0",
"CONTENT_LENGTH" => "3675",
"SCRIPT_NAME" => "",
"SERVER_SOFTWARE" => "Unicorn 4.8.3"

Same as others, I can't reproduce this locally, it only occurs in production.

@zimbatm

Make sure that rack is v1.5.2 or more

@volx7577

Ok, will do. Is this a known fix or just a good idea moving forward?

@zimbatm

Read the thread. #561 is a fix to the issue, then check in the history after which version is has been merged

@mkllnk mkllnk referenced this issue in openfoodfoundation/openfoodnetwork Jun 4, 2015
Open

TypeError in gems/rack-1.4.5/lib/rack/request.rb:221 #597

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment