Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

ThreadError (deadlock; recursive locking) #1865

Closed
vitalinfo opened this issue Jul 28, 2019 · 3 comments
Closed

ThreadError (deadlock; recursive locking) #1865

vitalinfo opened this issue Jul 28, 2019 · 3 comments

Comments

@vitalinfo
Copy link

System configuration

Ruby version: 2.6.3
Rails version: 5.2.3
Puma version: 4.0.1

Recently I've noticed in the log batch of such exceptions (Aribrake doesn't track them), does anybody has any idea why it could happened and how to fix this?

p.s. we are using ActionCable, can be it a reason?

2019-07-26T21:21:27.473567+00:00 app[web.1]: 
2019-07-26T21:21:27.473590+00:00 app[web.1]: ThreadError (deadlock; recursive locking):
2019-07-26T21:21:27.473591+00:00 app[web.1]: 
2019-07-26T21:21:27.473664+00:00 app[web.1]: vendor/ruby-2.6.3/lib/ruby/2.6.0/monitor.rb:189:in `lock'
2019-07-26T21:21:27.473666+00:00 app[web.1]: vendor/ruby-2.6.3/lib/ruby/2.6.0/monitor.rb:189:in `mon_enter'
2019-07-26T21:21:27.473667+00:00 app[web.1]: vendor/ruby-2.6.3/lib/ruby/2.6.0/monitor.rb:228:in `mon_synchronize'
2019-07-26T21:21:27.473671+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.3/lib/active_support/concurrency/share_lock.rb:173:in `yield_shares'
2019-07-26T21:21:27.473673+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.3/lib/active_support/dependencies/interlock.rb:47:in `permit_concurrent_loads'
2019-07-26T21:21:27.473675+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.3/lib/active_record/connection_adapters/abstract/connection_pool.rb:191:in `block in wait_poll'
2019-07-26T21:21:27.473676+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.3/lib/active_record/connection_adapters/abstract/connection_pool.rb:190:in `loop'
2019-07-26T21:21:27.473677+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.3/lib/active_record/connection_adapters/abstract/connection_pool.rb:190:in `wait_poll'
2019-07-26T21:21:27.473678+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.3/lib/active_record/connection_adapters/abstract/connection_pool.rb:151:in `internal_poll'
2019-07-26T21:21:27.473679+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.3/lib/active_record/connection_adapters/abstract/connection_pool.rb:277:in `internal_poll'
2019-07-26T21:21:27.473680+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.3/lib/active_record/connection_adapters/abstract/connection_pool.rb:145:in `block in poll'
2019-07-26T21:21:27.473681+00:00 app[web.1]: vendor/ruby-2.6.3/lib/ruby/2.6.0/monitor.rb:230:in `mon_synchronize'
2019-07-26T21:21:27.473682+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.3/lib/active_record/connection_adapters/abstract/connection_pool.rb:155:in `synchronize'
2019-07-26T21:21:27.473683+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.3/lib/active_record/connection_adapters/abstract/connection_pool.rb:145:in `poll'
2019-07-26T21:21:27.473684+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.3/lib/active_record/connection_adapters/abstract/connection_pool.rb:799:in `acquire_connection'
2019-07-26T21:21:27.473685+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.3/lib/active_record/connection_adapters/abstract/connection_pool.rb:523:in `checkout'
2019-07-26T21:21:27.473686+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.3/lib/active_record/connection_adapters/abstract/connection_pool.rb:382:in `connection'
2019-07-26T21:21:27.473687+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.3/lib/active_record/connection_adapters/abstract/connection_pool.rb:1014:in `retrieve_connection'
2019-07-26T21:21:27.473688+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.3/lib/active_record/connection_handling.rb:118:in `retrieve_connection'
2019-07-26T21:21:27.473690+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.3/lib/active_record/connection_handling.rb:90:in `connection'
2019-07-26T21:21:27.473691+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.3/lib/active_record/relation/delegation.rb:76:in `connection'
2019-07-26T21:21:27.473692+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.3/lib/active_record/relation/query_methods.rb:937:in `build_arel'
2019-07-26T21:21:27.473693+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.3/lib/active_record/relation/query_methods.rb:903:in `arel'
2019-07-26T21:21:27.473694+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.3/lib/active_record/relation.rb:560:in `block in exec_queries'
2019-07-26T21:21:27.473695+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.3/lib/active_record/relation.rb:584:in `skip_query_cache_if_necessary'
2019-07-26T21:21:27.473696+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.3/lib/active_record/relation.rb:547:in `exec_queries'
2019-07-26T21:21:27.473697+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.3/lib/active_record/relation.rb:422:in `load'
2019-07-26T21:21:27.473698+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.3/lib/active_record/relation.rb:200:in `records'
2019-07-26T21:21:27.473699+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.3/lib/active_record/relation.rb:195:in `to_ary'
2019-07-26T21:21:27.473700+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.3/lib/active_record/relation/finder_methods.rb:532:in `find_nth_with_limit'
2019-07-26T21:21:27.473701+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.3/lib/active_record/relation/finder_methods.rb:517:in `find_nth'
2019-07-26T21:21:27.473702+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.3/lib/active_record/relation/finder_methods.rb:125:in `first'
2019-07-26T21:21:27.473703+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/orm_adapter-0.5.0/lib/orm_adapter/adapters/active_record.rb:17:in `get'
2019-07-26T21:21:27.473703+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/bundler/gems/devise-19045a483dd0/lib/devise/models/authenticatable.rb:237:in `serialize_from_session'
2019-07-26T21:21:27.473704+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/bundler/gems/devise-19045a483dd0/lib/devise.rb:485:in `block (2 levels) in configure_warden!'
2019-07-26T21:21:27.473705+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/warden-1.2.8/lib/warden/session_serializer.rb:35:in `fetch'
2019-07-26T21:21:27.473709+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/warden-1.2.8/lib/warden/proxy.rb:224:in `user'
2019-07-26T21:21:27.473710+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/airbrake-9.3.0/lib/airbrake/rack/user.rb:13:in `extract'
2019-07-26T21:21:27.473711+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/airbrake-9.3.0/lib/airbrake/rack/user_filter.rb:18:in `call'
2019-07-26T21:21:27.473712+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/airbrake-ruby-4.5.0/lib/airbrake-ruby/filter_chain.rb:73:in `block in refine'
2019-07-26T21:21:27.473713+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/airbrake-ruby-4.5.0/lib/airbrake-ruby/filter_chain.rb:71:in `each'
2019-07-26T21:21:27.473714+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/airbrake-ruby-4.5.0/lib/airbrake-ruby/filter_chain.rb:71:in `refine'
2019-07-26T21:21:27.473715+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/airbrake-ruby-4.5.0/lib/airbrake-ruby/notice_notifier.rb:106:in `send_notice'
2019-07-26T21:21:27.473716+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/airbrake-ruby-4.5.0/lib/airbrake-ruby/notice_notifier.rb:36:in `notify'
2019-07-26T21:21:27.473717+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/airbrake-ruby-4.5.0/lib/airbrake-ruby.rb:158:in `notify'
2019-07-26T21:21:27.473718+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/airbrake-9.3.0/lib/airbrake/rack/middleware.rb:73:in `notify_airbrake'
2019-07-26T21:21:27.473719+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/airbrake-9.3.0/lib/airbrake/rack/middleware.rb:34:in `rescue in call!'
2019-07-26T21:21:27.473720+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/airbrake-9.3.0/lib/airbrake/rack/middleware.rb:31:in `call!'
2019-07-26T21:21:27.473721+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/airbrake-9.3.0/lib/airbrake/rack/middleware.rb:21:in `call'
2019-07-26T21:21:27.473722+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/newrelic_rpm-6.5.0.357/lib/new_relic/agent/instrumentation/middleware_tracing.rb:99:in `call'
2019-07-26T21:21:27.473723+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.3/lib/action_dispatch/middleware/debug_exceptions.rb:61:in `call'
2019-07-26T21:21:27.473724+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/newrelic_rpm-6.5.0.357/lib/new_relic/agent/instrumentation/middleware_tracing.rb:99:in `call'
2019-07-26T21:21:27.473725+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.3/lib/action_dispatch/middleware/show_exceptions.rb:33:in `call'
2019-07-26T21:21:27.473725+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/newrelic_rpm-6.5.0.357/lib/new_relic/agent/instrumentation/middleware_tracing.rb:99:in `call'
2019-07-26T21:21:27.473726+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/railties-5.2.3/lib/rails/rack/logger.rb:38:in `call_app'
2019-07-26T21:21:27.473727+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/railties-5.2.3/lib/rails/rack/logger.rb:26:in `block in call'
2019-07-26T21:21:27.473729+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.3/lib/active_support/tagged_logging.rb:71:in `block in tagged'
2019-07-26T21:21:27.473729+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.3/lib/active_support/tagged_logging.rb:28:in `tagged'
2019-07-26T21:21:27.473730+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.3/lib/active_support/tagged_logging.rb:71:in `tagged'
2019-07-26T21:21:27.473731+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/railties-5.2.3/lib/rails/rack/logger.rb:26:in `call'
2019-07-26T21:21:27.473732+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/newrelic_rpm-6.5.0.357/lib/new_relic/agent/instrumentation/middleware_tracing.rb:99:in `call'
2019-07-26T21:21:27.473733+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.3/lib/action_dispatch/middleware/remote_ip.rb:81:in `call'
2019-07-26T21:21:27.473739+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/newrelic_rpm-6.5.0.357/lib/new_relic/agent/instrumentation/middleware_tracing.rb:99:in `call'
2019-07-26T21:21:27.473740+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/request_store-1.4.1/lib/request_store/middleware.rb:19:in `call'
2019-07-26T21:21:27.473741+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/newrelic_rpm-6.5.0.357/lib/new_relic/agent/instrumentation/middleware_tracing.rb:99:in `call'
2019-07-26T21:21:27.473742+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/rack-timeout-0.5.1/lib/rack/timeout/core.rb:123:in `block in call'
2019-07-26T21:21:27.473743+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/rack-timeout-0.5.1/lib/rack/timeout/support/timeout.rb:19:in `timeout'
2019-07-26T21:21:27.473744+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/rack-timeout-0.5.1/lib/rack/timeout/core.rb:122:in `call'
2019-07-26T21:21:27.473745+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/newrelic_rpm-6.5.0.357/lib/new_relic/agent/instrumentation/middleware_tracing.rb:99:in `call'
2019-07-26T21:21:27.473746+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.3/lib/action_dispatch/middleware/request_id.rb:27:in `call'
2019-07-26T21:21:27.473747+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/newrelic_rpm-6.5.0.357/lib/new_relic/agent/instrumentation/middleware_tracing.rb:99:in `call'
2019-07-26T21:21:27.473748+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/rack-2.0.7/lib/rack/method_override.rb:22:in `call'
2019-07-26T21:21:27.473749+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/newrelic_rpm-6.5.0.357/lib/new_relic/agent/instrumentation/middleware_tracing.rb:99:in `call'
2019-07-26T21:21:27.473750+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/rack-2.0.7/lib/rack/runtime.rb:22:in `call'
2019-07-26T21:21:27.473751+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/newrelic_rpm-6.5.0.357/lib/new_relic/agent/instrumentation/middleware_tracing.rb:99:in `call'
2019-07-26T21:21:27.473754+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.3/lib/active_support/cache/strategy/local_cache_middleware.rb:29:in `call'
2019-07-26T21:21:27.473755+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/newrelic_rpm-6.5.0.357/lib/new_relic/agent/instrumentation/middleware_tracing.rb:99:in `call'
2019-07-26T21:21:27.473755+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.3/lib/action_dispatch/middleware/executor.rb:14:in `call'
2019-07-26T21:21:27.473756+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/newrelic_rpm-6.5.0.357/lib/new_relic/agent/instrumentation/middleware_tracing.rb:99:in `call'
2019-07-26T21:21:27.473757+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.3/lib/action_dispatch/middleware/static.rb:127:in `call'
2019-07-26T21:21:27.473758+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/newrelic_rpm-6.5.0.357/lib/new_relic/agent/instrumentation/middleware_tracing.rb:99:in `call'
2019-07-26T21:21:27.473759+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/heroku-deflater-0.6.3/lib/heroku-deflater/skip_binary.rb:19:in `call'
2019-07-26T21:21:27.473760+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/newrelic_rpm-6.5.0.357/lib/new_relic/agent/instrumentation/middleware_tracing.rb:99:in `call'
2019-07-26T21:21:27.473761+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/rack-2.0.7/lib/rack/deflater.rb:34:in `call'
2019-07-26T21:21:27.473762+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/newrelic_rpm-6.5.0.357/lib/new_relic/agent/instrumentation/middleware_tracing.rb:99:in `call'
2019-07-26T21:21:27.473763+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/heroku-deflater-0.6.3/lib/heroku-deflater/serve_zipped_assets.rb:54:in `call'
2019-07-26T21:21:27.473764+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/newrelic_rpm-6.5.0.357/lib/new_relic/agent/instrumentation/middleware_tracing.rb:99:in `call'
2019-07-26T21:21:27.473765+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/rack-2.0.7/lib/rack/sendfile.rb:111:in `call'
2019-07-26T21:21:27.473766+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/newrelic_rpm-6.5.0.357/lib/new_relic/agent/instrumentation/middleware_tracing.rb:99:in `call'
2019-07-26T21:21:27.473767+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.3/lib/action_dispatch/middleware/ssl.rb:74:in `call'
2019-07-26T21:21:27.473768+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/newrelic_rpm-6.5.0.357/lib/new_relic/agent/instrumentation/middleware_tracing.rb:99:in `call'
2019-07-26T21:21:27.473769+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/rack-canonical-hostname-0.2/lib/rack/canonical_host.rb:26:in `call'
2019-07-26T21:21:27.473770+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/newrelic_rpm-6.5.0.357/lib/new_relic/agent/instrumentation/middleware_tracing.rb:99:in `call'
2019-07-26T21:21:27.473771+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/railties-5.2.3/lib/rails/engine.rb:524:in `call'
2019-07-26T21:21:27.473772+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/newrelic_rpm-6.5.0.357/lib/new_relic/agent/instrumentation/middleware_tracing.rb:99:in `call'
2019-07-26T21:21:27.473773+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/rack-cors-1.0.3/lib/rack/cors.rb:95:in `call'
2019-07-26T21:21:27.473774+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/newrelic_rpm-6.5.0.357/lib/new_relic/agent/instrumentation/middleware_tracing.rb:99:in `call'
2019-07-26T21:21:27.473775+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/puma-4.0.1/lib/puma/configuration.rb:228:in `call'
2019-07-26T21:21:27.473776+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/puma-4.0.1/lib/puma/server.rb:657:in `handle_request'
2019-07-26T21:21:27.473777+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/puma-4.0.1/lib/puma/server.rb:467:in `process_client'
2019-07-26T21:21:27.473778+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/puma-4.0.1/lib/puma/server.rb:328:in `block in run'
2019-07-26T21:21:27.473779+00:00 app[web.1]: vendor/bundle/ruby/2.6.0/gems/puma-4.0.1/lib/puma/thread_pool.rb:135:in `block in spawn_thread'
@nateberkopec
Copy link
Member

Standard advice for debugging deadlocks in Rails is to use https://api.rubyonrails.org/classes/ActionDispatch/DebugLocks.html

@MSP-Greg
Copy link
Member

(shameless plug) also:

https://msp-greg.github.io/rails_gem_5/ActionDispatch/DebugLocks.html

https://msp-greg.github.io/rails_master/ActionDispatch/DebugLocks.html

Puma Master:

https://msp-greg.github.io/puma/

@vitalinfo
Copy link
Author

@nateberkopec @MSP-Greg Thanks

@nateberkopec nateberkopec mentioned this issue Jul 30, 2019
Closed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@nateberkopec @vitalinfo @MSP-Greg