rails: Sidekiq hangs using Rails 6 app with "classic" autoloader

Originally discussed on https://github.com/mperham/sidekiq/issues/4216 . This appears to be caused by a deadlock within actiontext.

Steps to reproduce

Create a new rails app using Rails 6.0.0.rc2
Add Sidekiq and create some jobs (I used the instructions here https://github.com/mperham/sidekiq/wiki/Getting-Started#rails)
Run bundle exec sidekiq
Watch as it completes the jobs
Switch to the classic autoloader (and do a spring stop)
Create more jobs
Run bundle exec sidekiq
Watch as it starts jobs, but never completes any.

Here is a test app based on the instructions above: https://github.com/langsharpe/test_sidekiq_activetext

Here is a gist of the output of the process after sending the TTIN signal https://gist.githubusercontent.com/langsharpe/8ca50bca283f863e09c226b0b88a3f57/raw/f8d6343fe2e388b6b2a16988dd281b29c57c332f/Sidekiq.log

Our use case is an existing app we upgraded to Rails 6, but is not Zeitwerk compatible (yet). The problem only occurs when code is autoloaded. It doesn’t occur when code is eager loaded (e.g. in production mode)

Expected behavior

Jobs should complete when using the classic autoloader.

Actual behavior

Jobs start, but never finish.

System configuration

Rails version: 6.0.0.rc2 Ruby version: 2.6.2p47 (2019-03-13 revision 67232) [x86_64-darwin18]

About this issue

Original URL
State: closed
Created 5 years ago
Reactions: 10
Comments: 21 (13 by maintainers)

Commits related to this issue

Bugfix: Sidekiq queues getting stuck [#411] ref: https://github.com/rails/rails/issues/36810 closes: #411 — committed to chatwoot/chatwoot by sojan-official 4 years ago
Fix sidekiq version 6 issue with classic autoloader Related issue found here https://github.com/rails/rails/issues/36810 — committed to ministryofjustice/laa-apply-for-legal-aid by Obsiye 4 years ago

Most upvoted comments

The deadlocks only occurred in development, we never saw them in prod.

Running the sidekiq process with concurrency of 1 prevents the deadlocks

Do these match your observations as well?

Yes. Our workaround in development is to use a concurrency of 1.

langsharpe on Jul 31, 2019

I managed to capture a backtrace of all the threads (using method described in http://le-huy.blogspot.com/2012/04/dump-backtrace-of-all-threads-in-ruby.html)

~/.asdf/installs/ruby/2.6.5/lib/ruby/2.6.0/monitor.rb:114:in `sleep'
~/.asdf/installs/ruby/2.6.5/lib/ruby/2.6.0/monitor.rb:114:in `wait'
~/.asdf/installs/ruby/2.6.5/lib/ruby/2.6.0/monitor.rb:114:in `block (2 levels) in wait'
~/.asdf/installs/ruby/2.6.5/lib/ruby/2.6.0/monitor.rb:113:in `handle_interrupt'
~/.asdf/installs/ruby/2.6.5/lib/ruby/2.6.0/monitor.rb:113:in `block in wait'
~/.asdf/installs/ruby/2.6.5/lib/ruby/2.6.0/monitor.rb:109:in `handle_interrupt'
~/.asdf/installs/ruby/2.6.5/lib/ruby/2.6.0/monitor.rb:109:in `wait'
~/.asdf/installs/ruby/2.6.5/lib/ruby/2.6.0/monitor.rb:128:in `wait_while'
~/.asdf/installs/ruby/2.6.5/lib/ruby/gems/2.6.0/gems/activesupport-6.0.2.1/lib/active_support/concurrency/share_lock.rb:221:in `wait_for'
~/.asdf/installs/ruby/2.6.5/lib/ruby/gems/2.6.0/gems/activesupport-6.0.2.1/lib/active_support/concurrency/share_lock.rb:83:in `block (2 levels) in start_exclusive'
~/.asdf/installs/ruby/2.6.5/lib/ruby/gems/2.6.0/gems/activesupport-6.0.2.1/lib/active_support/concurrency/share_lock.rb:187:in `yield_shares'
~/.asdf/installs/ruby/2.6.5/lib/ruby/gems/2.6.0/gems/activesupport-6.0.2.1/lib/active_support/concurrency/share_lock.rb:82:in `block in start_exclusive'
~/.asdf/installs/ruby/2.6.5/lib/ruby/2.6.0/monitor.rb:235:in `mon_synchronize'
~/.asdf/installs/ruby/2.6.5/lib/ruby/gems/2.6.0/gems/activesupport-6.0.2.1/lib/active_support/concurrency/share_lock.rb:77:in `start_exclusive'
~/.asdf/installs/ruby/2.6.5/lib/ruby/gems/2.6.0/gems/activesupport-6.0.2.1/lib/active_support/concurrency/share_lock.rb:149:in `exclusive'
~/.asdf/installs/ruby/2.6.5/lib/ruby/gems/2.6.0/gems/activesupport-6.0.2.1/lib/active_support/dependencies/interlock.rb:13:in `loading'
~/.asdf/installs/ruby/2.6.5/lib/ruby/gems/2.6.0/gems/activesupport-6.0.2.1/lib/active_support/dependencies.rb:40:in `load_interlock'
~/.asdf/installs/ruby/2.6.5/lib/ruby/gems/2.6.0/gems/activesupport-6.0.2.1/lib/active_support/dependencies.rb:390:in `require_or_load'
~/.asdf/installs/ruby/2.6.5/lib/ruby/gems/2.6.0/gems/bootsnap-1.4.5/lib/bootsnap/load_path_cache/core_ext/active_support.rb:48:in `block in require_or_load'
~/.asdf/installs/ruby/2.6.5/lib/ruby/gems/2.6.0/gems/bootsnap-1.4.5/lib/bootsnap/load_path_cache/core_ext/active_support.rb:16:in `allow_bootsnap_retry'
~/.asdf/installs/ruby/2.6.5/lib/ruby/gems/2.6.0/gems/bootsnap-1.4.5/lib/bootsnap/load_path_cache/core_ext/active_support.rb:47:in `require_or_load'
~/.asdf/installs/ruby/2.6.5/lib/ruby/gems/2.6.0/gems/activesupport-6.0.2.1/lib/active_support/dependencies.rb:545:in `load_missing_constant'
~/.asdf/installs/ruby/2.6.5/lib/ruby/gems/2.6.0/gems/bootsnap-1.4.5/lib/bootsnap/load_path_cache/core_ext/active_support.rb:60:in `block in load_missing_constant'
~/.asdf/installs/ruby/2.6.5/lib/ruby/gems/2.6.0/gems/bootsnap-1.4.5/lib/bootsnap/load_path_cache/core_ext/active_support.rb:16:in `allow_bootsnap_retry'
~/.asdf/installs/ruby/2.6.5/lib/ruby/gems/2.6.0/gems/bootsnap-1.4.5/lib/bootsnap/load_path_cache/core_ext/active_support.rb:59:in `load_missing_constant'
~/.asdf/installs/ruby/2.6.5/lib/ruby/gems/2.6.0/gems/activesupport-6.0.2.1/lib/active_support/dependencies.rb:214:in `const_missing'
~/.asdf/installs/ruby/2.6.5/lib/ruby/gems/2.6.0/gems/activesupport-6.0.2.1/lib/active_support/dependencies.rb:582:in `load_missing_constant'
~/.asdf/installs/ruby/2.6.5/lib/ruby/gems/2.6.0/gems/bootsnap-1.4.5/lib/bootsnap/load_path_cache/core_ext/active_support.rb:60:in `block in load_missing_constant'
~/.asdf/installs/ruby/2.6.5/lib/ruby/gems/2.6.0/gems/bootsnap-1.4.5/lib/bootsnap/load_path_cache/core_ext/active_support.rb:16:in `allow_bootsnap_retry'
~/.asdf/installs/ruby/2.6.5/lib/ruby/gems/2.6.0/gems/bootsnap-1.4.5/lib/bootsnap/load_path_cache/core_ext/active_support.rb:59:in `load_missing_constant'
~/.asdf/installs/ruby/2.6.5/lib/ruby/gems/2.6.0/gems/activesupport-6.0.2.1/lib/active_support/dependencies.rb:214:in `const_missing'
~/.asdf/installs/ruby/2.6.5/lib/ruby/gems/2.6.0/gems/activesupport-6.0.2.1/lib/active_support/dependencies.rb:582:in `load_missing_constant'
~/.asdf/installs/ruby/2.6.5/lib/ruby/gems/2.6.0/gems/bootsnap-1.4.5/lib/bootsnap/load_path_cache/core_ext/active_support.rb:60:in `block in load_missing_constant'
~/.asdf/installs/ruby/2.6.5/lib/ruby/gems/2.6.0/gems/bootsnap-1.4.5/lib/bootsnap/load_path_cache/core_ext/active_support.rb:16:in `allow_bootsnap_retry'
~/.asdf/installs/ruby/2.6.5/lib/ruby/gems/2.6.0/gems/bootsnap-1.4.5/lib/bootsnap/load_path_cache/core_ext/active_support.rb:59:in `load_missing_constant'
~/.asdf/installs/ruby/2.6.5/lib/ruby/gems/2.6.0/gems/activesupport-6.0.2.1/lib/active_support/dependencies.rb:214:in `const_missing'
~/.asdf/installs/ruby/2.6.5/lib/ruby/gems/2.6.0/gems/actiontext-6.0.2.1/lib/action_text/engine.rb:46:in `block (2 levels) in <class:Engine>'
~/.asdf/installs/ruby/2.6.5/lib/ruby/gems/2.6.0/gems/activesupport-6.0.2.1/lib/active_support/lazy_load_hooks.rb:72:in `class_eval'
~/.asdf/installs/ruby/2.6.5/lib/ruby/gems/2.6.0/gems/activesupport-6.0.2.1/lib/active_support/lazy_load_hooks.rb:72:in `block in execute_hook'
~/.asdf/installs/ruby/2.6.5/lib/ruby/gems/2.6.0/gems/activesupport-6.0.2.1/lib/active_support/lazy_load_hooks.rb:62:in `with_execution_control'
~/.asdf/installs/ruby/2.6.5/lib/ruby/gems/2.6.0/gems/activesupport-6.0.2.1/lib/active_support/lazy_load_hooks.rb:67:in `execute_hook'
~/.asdf/installs/ruby/2.6.5/lib/ruby/gems/2.6.0/gems/activesupport-6.0.2.1/lib/active_support/lazy_load_hooks.rb:52:in `block in run_load_hooks'
~/.asdf/installs/ruby/2.6.5/lib/ruby/gems/2.6.0/gems/activesupport-6.0.2.1/lib/active_support/lazy_load_hooks.rb:51:in `each'
~/.asdf/installs/ruby/2.6.5/lib/ruby/gems/2.6.0/gems/activesupport-6.0.2.1/lib/active_support/lazy_load_hooks.rb:51:in `run_load_hooks'
~/.asdf/installs/ruby/2.6.5/lib/ruby/gems/2.6.0/gems/actiontext-6.0.2.1/lib/action_text/content.rb:132:in `<main>'
~/.asdf/installs/ruby/2.6.5/lib/ruby/gems/2.6.0/gems/bootsnap-1.4.5/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:22:in `require'
~/.asdf/installs/ruby/2.6.5/lib/ruby/gems/2.6.0/gems/bootsnap-1.4.5/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:22:in `block in require_with_bootsnap_lfi'
~/.asdf/installs/ruby/2.6.5/lib/ruby/gems/2.6.0/gems/bootsnap-1.4.5/lib/bootsnap/load_path_cache/loaded_features_index.rb:92:in `register'
~/.asdf/installs/ruby/2.6.5/lib/ruby/gems/2.6.0/gems/bootsnap-1.4.5/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:21:in `require_with_bootsnap_lfi'
~/.asdf/installs/ruby/2.6.5/lib/ruby/gems/2.6.0/gems/bootsnap-1.4.5/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:30:in `require'
~/.asdf/installs/ruby/2.6.5/lib/ruby/gems/2.6.0/gems/activesupport-6.0.2.1/lib/active_support/dependencies.rb:325:in `block in require'
~/.asdf/installs/ruby/2.6.5/lib/ruby/gems/2.6.0/gems/activesupport-6.0.2.1/lib/active_support/dependencies.rb:291:in `load_dependency'
~/.asdf/installs/ruby/2.6.5/lib/ruby/gems/2.6.0/gems/activesupport-6.0.2.1/lib/active_support/dependencies.rb:325:in `require'
~/.asdf/installs/ruby/2.6.5/lib/ruby/gems/2.6.0/gems/actiontext-6.0.2.1/lib/action_text/engine.rb:42:in `block (2 levels) in <class:Engine>'
~/.asdf/installs/ruby/2.6.5/lib/ruby/gems/2.6.0/gems/activesupport-6.0.2.1/lib/active_support/callbacks.rb:429:in `instance_exec'
~/.asdf/installs/ruby/2.6.5/lib/ruby/gems/2.6.0/gems/activesupport-6.0.2.1/lib/active_support/callbacks.rb:429:in `block in make_lambda'
~/.asdf/installs/ruby/2.6.5/lib/ruby/gems/2.6.0/gems/activesupport-6.0.2.1/lib/active_support/callbacks.rb:201:in `block (2 levels) in halting'
~/.asdf/installs/ruby/2.6.5/lib/ruby/gems/2.6.0/gems/activesupport-6.0.2.1/lib/active_support/callbacks.rb:607:in `block (2 levels) in default_terminator'
~/.asdf/installs/ruby/2.6.5/lib/ruby/gems/2.6.0/gems/activesupport-6.0.2.1/lib/active_support/callbacks.rb:606:in `catch'
~/.asdf/installs/ruby/2.6.5/lib/ruby/gems/2.6.0/gems/activesupport-6.0.2.1/lib/active_support/callbacks.rb:606:in `block in default_terminator'
~/.asdf/installs/ruby/2.6.5/lib/ruby/gems/2.6.0/gems/activesupport-6.0.2.1/lib/active_support/callbacks.rb:202:in `block in halting'
~/.asdf/installs/ruby/2.6.5/lib/ruby/gems/2.6.0/gems/activesupport-6.0.2.1/lib/active_support/callbacks.rb:514:in `block in invoke_before'
~/.asdf/installs/ruby/2.6.5/lib/ruby/gems/2.6.0/gems/activesupport-6.0.2.1/lib/active_support/callbacks.rb:514:in `each'
~/.asdf/installs/ruby/2.6.5/lib/ruby/gems/2.6.0/gems/activesupport-6.0.2.1/lib/active_support/callbacks.rb:514:in `invoke_before'
~/.asdf/installs/ruby/2.6.5/lib/ruby/gems/2.6.0/gems/activesupport-6.0.2.1/lib/active_support/callbacks.rb:134:in `run_callbacks'
~/.asdf/installs/ruby/2.6.5/lib/ruby/gems/2.6.0/gems/activesupport-6.0.2.1/lib/active_support/execution_wrapper.rb:111:in `run!'
~/.asdf/installs/ruby/2.6.5/lib/ruby/gems/2.6.0/gems/activesupport-6.0.2.1/lib/active_support/execution_wrapper.rb:73:in `block in run!'
~/.asdf/installs/ruby/2.6.5/lib/ruby/gems/2.6.0/gems/activesupport-6.0.2.1/lib/active_support/execution_wrapper.rb:70:in `tap'
~/.asdf/installs/ruby/2.6.5/lib/ruby/gems/2.6.0/gems/activesupport-6.0.2.1/lib/active_support/execution_wrapper.rb:70:in `run!'
~/.asdf/installs/ruby/2.6.5/lib/ruby/gems/2.6.0/gems/activesupport-6.0.2.1/lib/active_support/execution_wrapper.rb:86:in `wrap'
~/.asdf/installs/ruby/2.6.5/lib/ruby/gems/2.6.0/gems/activesupport-6.0.2.1/lib/active_support/reloader.rb:71:in `wrap'
~/.asdf/installs/ruby/2.6.5/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/rails.rb:42:in `call'
~/.asdf/installs/ruby/2.6.5/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:132:in `block (4 levels) in dispatch'
~/.asdf/installs/ruby/2.6.5/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:250:in `stats'
~/.asdf/installs/ruby/2.6.5/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:127:in `block (3 levels) in dispatch'
~/.asdf/installs/ruby/2.6.5/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/job_logger.rb:8:in `call'
~/.asdf/installs/ruby/2.6.5/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:126:in `block (2 levels) in dispatch'
~/.asdf/installs/ruby/2.6.5/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/job_retry.rb:74:in `global'
~/.asdf/installs/ruby/2.6.5/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:125:in `block in dispatch'
~/.asdf/installs/ruby/2.6.5/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/logging.rb:48:in `with_context'
~/.asdf/installs/ruby/2.6.5/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/logging.rb:42:in `with_job_hash_context'
~/.asdf/installs/ruby/2.6.5/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:124:in `dispatch'
~/.asdf/installs/ruby/2.6.5/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:163:in `process'
~/.asdf/installs/ruby/2.6.5/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:83:in `process_one'
~/.asdf/installs/ruby/2.6.5/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:71:in `run'
~/.asdf/installs/ruby/2.6.5/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/util.rb:16:in `watchdog'
~/.asdf/installs/ruby/2.6.5/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/util.rb:25:in `block in safe_thread'

Lots of noise here, but looking at actiontext-6.0.2.1/lib/action_text/engine.rb:46 this might lead to the issue:

    initializer "action_text.renderer" do |app|
      app.executor.to_run      { ActionText::Content.renderer = ApplicationController.renderer }
      app.executor.to_complete { ActionText::Content.renderer = ApplicationController.renderer }

      ActiveSupport.on_load(:action_text_content) do
        self.renderer = ApplicationController.renderer # <<= line 46
      end

      ActiveSupport.on_load(:action_controller_base) do
        before_action { ActionText::Content.renderer = ApplicationController.renderer.new(request.env) }
      end
    end

When I blindly comment out that line, it works.

siebertm on Feb 27, 2020

I am seeing this bug, every time I make a change in my code Sidekiq freezes and won’t proces any jobs until I restart the proces. Setting the concurrency to 1 seems to fix the problem.

Initially it looked like my problem was fixed, but unfortunately setting the concurrency to 1 did not fix it. The bug just takes a bit longer to show up.

jankeesvw on Jul 8, 2022

I am seeing this bug, every time I make a change in my code Sidekiq freezes and won’t proces any jobs until I restart the proces. Setting the concurrency to 1 seems to fix the problem.

jankeesvw on Jul 7, 2022

I also commented this in the sidekiq github but:

Hi everyone - I’ve had similar situations and found this thread. I, like others potentially, cheated while upgrading and as-of 6.0 I began to see jobs stuck in busy as well. Moving to “load_defaults 6.0” seemed to work for me until I removed my old new_framework_defaults.rb (which I didn’t think I needed anymore). Then the problem reappeared. Restored the file and traced to see what might have exposed this for me.

In my case I have it narrowed down to: ActiveSupport.to_time_preserves_timezone = false

If the above is set, I see no hangs. If I comment this out or revert to the default true as-of 5.0, then I see the jobs stuck in the busy state again.

Perhaps I have something else wrongly or inconsistently configured - but wanted to share this in case it sheds any light on what might be the root cause and how to resolve it.

ruby 2.7.0 rails 6.0.2.2 sidekiq 6.0.6

jmaino on Mar 29, 2020