Puma: 401 Unauthorized - server hangs when do multiple requests in same time

[kesha-antonov]

Hello!
Thanks for the amazing Puma!

When I send multiple (4) requests in same time from my app to api sometimes server hangs forever. And I need to do ctrl+c and then I see something like:

^CExiting
Completed 401 Unauthorized in 5348ms (ActiveRecord: 75.9ms)

All requests have authorization header (with Token) so they 100% authorized.

And I don't have enough knowledge to know where to go from here.

My solution for now - restart server again and again. Sometimes server can respond normally for these requests and sometimes it hangs forever.

Could you give some advice?

[evanphx]

Sounds like there is a threading issue in your applications code that is causing the hang. What is the app?

[kesha-antonov]

App - ios application on ReactNative.

Backend - rails. I'm using websockets (ActionCable) and fetch/ajax.

[m1lt0n]

@kesha-antonov I'm facing the same issue with a rails-api (rails 5.0) application used as an API and probably the issue has to do with threading indeed. The problem never occurs when runing the application with 1 thread only. Also, the problem does occur only while restarting the server (either manually via rails restart or when code changes in the application and listen gem causes it to be restarted). So, if requests are done while restarting the server they may hang forever, but if I wait a few seconds while restarting and then make requests, everything works properly.

[kesha-antonov]

Some more info:

I have mount ActionCable.server => '/cable' in routes. I start only 1 server. Not 2 (for http requests and websockets)

1) I change some files and if I see that server not responding I restart server
2) If I reload app immediately and it sends 4 requests to server - server hangs.
3) If I wait while app connects with websockets first and only then I reload app and it send 4 request - all ok. Requests served and websockets connected

Maybe It depends of 1 server running for ActionCable + ActionController and code reloading.

[pharmmd-rich]

@evanphx there is definitely something to this. I'm having the exact same issue with a Rails application. My Rails code is never hit, making it very hard to debug. Advice?

Only when I hit CTRL-C do I get the following message:

Completed 401 Unauthorized in 85675ms (ActiveRecord: 0.3ms)

Puma 3.7.1. Rails 5.0.2. No ActionCable.

[nateberkopec]

There's not much for the maintainers to go on in this thread. We need some kind of reproduction app.

[pharmmd-rich]

Edit: Nevermind, it's something else. A gem possibly. I just tried WEBrick and I have the same issue.

[gertig]

@pharmmd-rich I'm experiencing a similar issue where my Rails code is never hit, ie no logs. Were you able to track down the culprit? Banging my head against a wall here.

After a CTRL-C and restart I can get the app to receive one request then it hangs.

Puma 3.8.2, Rails 5.0.2

UPDATE: I think I may have figured out my issue had to do with Rails not autoloading some of my constants but not telling it wasn't doing so because it disliked how I was naming things.

I have controllers in this structure controllers>api>v1>users_controller and before upgrading to Rails 5 I was using an inflection initializer to allow me to name my controllers API::V1::UsersController rather than Api::V1::UsersController. Purely an aesthetics thing. I decided to rename all those to Api::V1::UsersController and so far the issue seems to have stopped. Will update if I notice this is not an accurate fix.

UPDATE I was wrong, that was only a temporary fix for some reason.

[kengreeff]

Rails 5.0.2
Puma 3.7.1 (ruby 2.3.1-p112)
Min threads: 5, max threads: 5
Environment: development

I'm also experiencing hanging in dev when firing off multiple javascript fetch requests at the same time. I can prevent the hangs by changing the RAILS_MAX_THREADS env variable from 5 to 1.

It doesn't happen all the time - a restart and page reload will sometimes work.

@nateberkopec Hey Nate, how would I go about debugging this to try and provide more info?

[gertig]

@kengreeff I'm experiencing the same issue with the exact same configuration except I'm on Puma 3.8.2 (I thought I had found the culprit earlier but I had not, see my previous comment).

@nateberkopec any thoughts on how we can go about debugging this highly frustrating issue?

[collimarco]

After upgrading to Puma 3.8.2 in development I am experiencing a similar issue. When multiple requests are triggered at the same time, some of them hangs forever and you need to stop and restart puma.

Is there any way to debug this issue?

[nateberkopec]

There's a 10% chance that this fixes anything, but can anyone experiencing this issue try adding:

queue_requests false

... to their puma.rb files or try the latest master and report back if that fixes anything?

If that doesn't help, try and follow this guide from New Relic about debugging stuck Ruby processes and post any output/information you can pull out of your stuck processes.

[collimarco]

Puma is stuck again in development. CPU usage is low (Puma is not in top processes). Looks like gdb is not available on macOS by default, so I have used the sample utility. Here's a gist with the result.

[collimarco]

Btw it looks like starvation and not a deadlock: I have noticed that after some minutes Puma has completed the request.

[collimarco]

I have found this error after the request was completed:

Puma starting in single mode...
* Version 3.8.2 (ruby 2.2.2-p95), codename: Sassy Salamander
* Min threads: 0, max threads: 16
* Environment: development
* Listening on ssl://127.0.0.1:443?cert=/Users/collimarco/Sites/pushpad/config/cert/ssl-wildcard.crt&key=/Users/collimarco/Sites/pushpad/config/cert/ssl-wildcard.key&verify_mode=none
Use Ctrl-C to stop
Error in reactor loop escaped: undefined method `closed?' for #<Puma::MiniSSL::Socket:0x007fd39967e138> (NoMethodError)
(eval):2:in `closed?'
/Users/collimarco/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/puma-3.8.2/lib/puma/reactor.rb:31:in `block in run_internal'
/Users/collimarco/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/puma-3.8.2/lib/puma/reactor.rb:31:in `any?'
/Users/collimarco/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/puma-3.8.2/lib/puma/reactor.rb:31:in `rescue in run_internal'
/Users/collimarco/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/puma-3.8.2/lib/puma/reactor.rb:28:in `run_internal'
/Users/collimarco/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/puma-3.8.2/lib/puma/reactor.rb:153:in `block in run_in_thread'

[kesha-antonov]

In my app scenario is (as I remember):
1) connect to puma with websockets
2) send multiple requests
3) everything is OK now
4) change something in rails app

5-a) try connect to puma again immediately -> stuck
OR
5-b) wait while websockets reconnect to puma via ActionCable -> send requests -> all OK

Maybe it's related to ActionCable and code reloading of rails

I did not debug further for now

[bviloria]

I'm facing the same issue. This is my environment:

Puma starting in single mode...

• Version 3.8.2 (ruby 2.3.3-p222), codename: Sassy Salamander
• Min threads: 5, max threads: 5
• Environment: development
• Listening on tcp://localhost:3000

Started GET "/api/v1/reason_types" for ::1 at 2017-05-09 16:33:15 +0800
Started GET "/api/v1/reasons" for ::1 at 2017-05-09 16:33:15 +0800
Exiting
Terminate batch job (Y/N)? y

when i do multiple ajax/fetch call the server hangs. But its working fine if just call 1 at a time.

Started GET "/api/v1/sites" for ::1 at 2017-05-09 16:33:00 +0800
Processing by Api::V1::SitesController#index as JSON
Parameters: {"site"=>{}}
User Load (0.0ms) SELECT users.*........
Completed 200 OK

[beverlycodes]

I know this isn't going to add much new info, and I haven't been able to reproduce this with a bare-bones app, but I appear to be having the same or a related problem.

Rails 5.0.1, Puma 3.9.1, ruby 2.3.1-p112

When my web client loads and hits DOMContentLoaded, four requests are sent to my Rails server in rapid succession (as quickly as the JS interpreter allows).

On a fresh rails s with max threads > 1, one or none of these requests will complete. The rest remain pending in the browser until I hit Ctrl-C to kill the server.

On a fresh rails s with max threads = 1, all requests will complete.

In the former scenario, I can mitigate by waiting until the first request completes before sending any further requests. Once an initial request has completed, I can spam the server with as many simultaneous requests as I please and they all complete. It's only after a fresh load of Puma does it hang on rapid-fire incoming requests.

[nateberkopec]

@ryanfields sounds like autoloading deadlocks. Please try http://api.rubyonrails.org/classes/ActionDispatch/DebugLocks.html.

[shssoichiro]

I am having the same issue as above, sending 4 requests simultaneously using Promise.all, also using 5 threads in Puma. The first request completes, and the others never complete. I get the following output from /rails/locks when adding DebugLocks to my middleware and experiencing the issue:

Thread 0 [0x3fde2918cd78 sleep]  No lock (yielded share)
  Waiting in start_exclusive to "load"
  may be pre-empted for: "load"
  blocked by: 1

/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/2.4.0/monitor.rb:111:in `sleep'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/2.4.0/monitor.rb:111:in `wait'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/2.4.0/monitor.rb:111:in `wait'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/2.4.0/monitor.rb:123:in `wait_while'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activesupport-5.1.1/lib/active_support/concurrency/share_lock.rb:219:in `wait_for'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activesupport-5.1.1/lib/active_support/concurrency/share_lock.rb:81:in `block (2 levels) in start_exclusive'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activesupport-5.1.1/lib/active_support/concurrency/share_lock.rb:185:in `yield_shares'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activesupport-5.1.1/lib/active_support/concurrency/share_lock.rb:80:in `block in start_exclusive'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/2.4.0/monitor.rb:214:in `mon_synchronize'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activesupport-5.1.1/lib/active_support/concurrency/share_lock.rb:75:in `start_exclusive'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activesupport-5.1.1/lib/active_support/concurrency/share_lock.rb:147:in `exclusive'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activesupport-5.1.1/lib/active_support/dependencies/interlock.rb:11:in `loading'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activesupport-5.1.1/lib/active_support/dependencies.rb:36:in `load_interlock'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activesupport-5.1.1/lib/active_support/dependencies.rb:357:in `require_or_load'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activesupport-5.1.1/lib/active_support/dependencies.rb:510:in `load_missing_constant'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activesupport-5.1.1/lib/active_support/dependencies.rb:202:in `const_missing'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activesupport-5.1.1/lib/active_support/inflector/methods.rb:269:in `const_get'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activesupport-5.1.1/lib/active_support/inflector/methods.rb:269:in `block in constantize'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activesupport-5.1.1/lib/active_support/inflector/methods.rb:267:in `each'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activesupport-5.1.1/lib/active_support/inflector/methods.rb:267:in `inject'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activesupport-5.1.1/lib/active_support/inflector/methods.rb:267:in `constantize'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activesupport-5.1.1/lib/active_support/inflector/methods.rb:312:in `safe_constantize'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activesupport-5.1.1/lib/active_support/core_ext/string/inflections.rb:77:in `safe_constantize'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/actionpack-5.1.1/lib/action_controller/metal/params_wrapper.rb:147:in `_default_wrap_model'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/actionpack-5.1.1/lib/action_controller/metal/params_wrapper.rb:94:in `block in model'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/2.4.0/mutex_m.rb:74:in `synchronize'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/2.4.0/mutex_m.rb:74:in `mu_synchronize'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/actionpack-5.1.1/lib/action_controller/metal/params_wrapper.rb:94:in `model'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/actionpack-5.1.1/lib/action_controller/metal/params_wrapper.rb:121:in `name'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/actionpack-5.1.1/lib/action_controller/metal/params_wrapper.rb:259:in `_wrapper_key'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/actionpack-5.1.1/lib/action_controller/metal/params_wrapper.rb:286:in `_wrapper_enabled?'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/actionpack-5.1.1/lib/action_controller/metal/params_wrapper.rb:235:in `process_action'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activerecord-5.1.1/lib/active_record/railties/controller_runtime.rb:22:in `process_action'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/actionpack-5.1.1/lib/abstract_controller/base.rb:124:in `process'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/actionpack-5.1.1/lib/action_controller/metal.rb:189:in `dispatch'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/actionpack-5.1.1/lib/action_controller/metal.rb:253:in `dispatch'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/actionpack-5.1.1/lib/action_dispatch/routing/route_set.rb:49:in `dispatch'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/actionpack-5.1.1/lib/action_dispatch/routing/route_set.rb:31:in `serve'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/actionpack-5.1.1/lib/action_dispatch/journey/router.rb:46:in `block in serve'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/actionpack-5.1.1/lib/action_dispatch/journey/router.rb:33:in `each'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/actionpack-5.1.1/lib/action_dispatch/journey/router.rb:33:in `serve'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/actionpack-5.1.1/lib/action_dispatch/routing/route_set.rb:832:in `call'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/bullet-5.5.1/lib/bullet/rack.rb:12:in `call'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rack-2.0.3/lib/rack/etag.rb:25:in `call'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rack-2.0.3/lib/rack/conditional_get.rb:25:in `call'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rack-2.0.3/lib/rack/head.rb:12:in `call'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activerecord-5.1.1/lib/active_record/migration.rb:556:in `call'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/actionpack-5.1.1/lib/action_dispatch/middleware/callbacks.rb:26:in `block in call'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activesupport-5.1.1/lib/active_support/callbacks.rb:97:in `run_callbacks'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/actionpack-5.1.1/lib/action_dispatch/middleware/callbacks.rb:24:in `call'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/actionpack-5.1.1/lib/action_dispatch/middleware/executor.rb:12:in `call'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/actionpack-5.1.1/lib/action_dispatch/middleware/debug_exceptions.rb:59:in `call'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/actionpack-5.1.1/lib/action_dispatch/middleware/show_exceptions.rb:31:in `call'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/railties-5.1.1/lib/rails/rack/logger.rb:36:in `call_app'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/railties-5.1.1/lib/rails/rack/logger.rb:24:in `block in call'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activesupport-5.1.1/lib/active_support/tagged_logging.rb:69:in `block in tagged'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activesupport-5.1.1/lib/active_support/tagged_logging.rb:26:in `tagged'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activesupport-5.1.1/lib/active_support/tagged_logging.rb:69:in `tagged'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/railties-5.1.1/lib/rails/rack/logger.rb:24:in `call'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/actionpack-5.1.1/lib/action_dispatch/middleware/remote_ip.rb:79:in `call'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/actionpack-5.1.1/lib/action_dispatch/middleware/request_id.rb:25:in `call'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rack-2.0.3/lib/rack/runtime.rb:22:in `call'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activesupport-5.1.1/lib/active_support/cache/strategy/local_cache_middleware.rb:27:in `call'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/actionpack-5.1.1/lib/action_dispatch/middleware/executor.rb:12:in `call'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/actionpack-5.1.1/lib/action_dispatch/middleware/static.rb:125:in `call'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rack-2.0.3/lib/rack/sendfile.rb:111:in `call'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/actionpack-5.1.1/lib/action_dispatch/middleware/debug_locks.rb:39:in `call'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/railties-5.1.1/lib/rails/engine.rb:522:in `call'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/puma-3.9.1/lib/puma/configuration.rb:224:in `call'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/puma-3.9.1/lib/puma/server.rb:602:in `handle_request'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/puma-3.9.1/lib/puma/server.rb:435:in `process_client'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/puma-3.9.1/lib/puma/server.rb:299:in `block in run'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/puma-3.9.1/lib/puma/thread_pool.rb:120:in `block in spawn_thread'


---


Thread 1 [0x3fde2918cf1c sleep]  Sharing
  blocking: 0

/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/2.4.0/mutex_m.rb:74:in `synchronize'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/2.4.0/mutex_m.rb:74:in `mu_synchronize'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/actionpack-5.1.1/lib/action_controller/metal/params_wrapper.rb:94:in `model'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/actionpack-5.1.1/lib/action_controller/metal/params_wrapper.rb:121:in `name'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/actionpack-5.1.1/lib/action_controller/metal/params_wrapper.rb:259:in `_wrapper_key'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/actionpack-5.1.1/lib/action_controller/metal/params_wrapper.rb:286:in `_wrapper_enabled?'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/actionpack-5.1.1/lib/action_controller/metal/params_wrapper.rb:235:in `process_action'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activerecord-5.1.1/lib/active_record/railties/controller_runtime.rb:22:in `process_action'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/actionpack-5.1.1/lib/abstract_controller/base.rb:124:in `process'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/actionpack-5.1.1/lib/action_controller/metal.rb:189:in `dispatch'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/actionpack-5.1.1/lib/action_controller/metal.rb:253:in `dispatch'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/actionpack-5.1.1/lib/action_dispatch/routing/route_set.rb:49:in `dispatch'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/actionpack-5.1.1/lib/action_dispatch/routing/route_set.rb:31:in `serve'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/actionpack-5.1.1/lib/action_dispatch/journey/router.rb:46:in `block in serve'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/actionpack-5.1.1/lib/action_dispatch/journey/router.rb:33:in `each'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/actionpack-5.1.1/lib/action_dispatch/journey/router.rb:33:in `serve'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/actionpack-5.1.1/lib/action_dispatch/routing/route_set.rb:832:in `call'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/bullet-5.5.1/lib/bullet/rack.rb:12:in `call'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rack-2.0.3/lib/rack/etag.rb:25:in `call'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rack-2.0.3/lib/rack/conditional_get.rb:25:in `call'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rack-2.0.3/lib/rack/head.rb:12:in `call'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activerecord-5.1.1/lib/active_record/migration.rb:556:in `call'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/actionpack-5.1.1/lib/action_dispatch/middleware/callbacks.rb:26:in `block in call'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activesupport-5.1.1/lib/active_support/callbacks.rb:97:in `run_callbacks'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/actionpack-5.1.1/lib/action_dispatch/middleware/callbacks.rb:24:in `call'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/actionpack-5.1.1/lib/action_dispatch/middleware/executor.rb:12:in `call'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/actionpack-5.1.1/lib/action_dispatch/middleware/debug_exceptions.rb:59:in `call'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/actionpack-5.1.1/lib/action_dispatch/middleware/show_exceptions.rb:31:in `call'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/railties-5.1.1/lib/rails/rack/logger.rb:36:in `call_app'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/railties-5.1.1/lib/rails/rack/logger.rb:24:in `block in call'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activesupport-5.1.1/lib/active_support/tagged_logging.rb:69:in `block in tagged'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activesupport-5.1.1/lib/active_support/tagged_logging.rb:26:in `tagged'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activesupport-5.1.1/lib/active_support/tagged_logging.rb:69:in `tagged'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/railties-5.1.1/lib/rails/rack/logger.rb:24:in `call'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/actionpack-5.1.1/lib/action_dispatch/middleware/remote_ip.rb:79:in `call'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/actionpack-5.1.1/lib/action_dispatch/middleware/request_id.rb:25:in `call'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rack-2.0.3/lib/rack/runtime.rb:22:in `call'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/activesupport-5.1.1/lib/active_support/cache/strategy/local_cache_middleware.rb:27:in `call'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/actionpack-5.1.1/lib/action_dispatch/middleware/executor.rb:12:in `call'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/actionpack-5.1.1/lib/action_dispatch/middleware/static.rb:125:in `call'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/rack-2.0.3/lib/rack/sendfile.rb:111:in `call'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/actionpack-5.1.1/lib/action_dispatch/middleware/debug_locks.rb:39:in `call'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/railties-5.1.1/lib/rails/engine.rb:522:in `call'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/puma-3.9.1/lib/puma/configuration.rb:224:in `call'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/puma-3.9.1/lib/puma/server.rb:602:in `handle_request'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/puma-3.9.1/lib/puma/server.rb:435:in `process_client'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/puma-3.9.1/lib/puma/server.rb:299:in `block in run'
/Users/joshua.holmer/.rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/puma-3.9.1/lib/puma/thread_pool.rb:120:in `block in spawn_thread'

[nateberkopec]

@shssoichiro That looks like a Rails issue, I'd report it over there. If specifying the params key like this solves the issue, that would be a red flag.

[pharmmd-rich]

The way that I was triggering it is via a gem which makes a callback to the API part of the app. If I have time I will try and create a barebones app + gem and see if I can reproduce it that way.

[stuartc]

I'm also experiencing this issue - at least in development mode (can't reproduce in production).
I'm wondering if suckerpunch or some other actor/thread based gem has something to do with this.

[pharmmd-rich]

@stuartc I don't think so. We aren't using anything like that on our end.

[nateberkopec]

I'm going to close and lock this thread, so that this message isn't buried.

If you experience this behavior, try using the DebugLocks middleware in Rails. If it shows there's an issue in Puma (or shows nothing at all), please open a new issue.