Rails runaway process in initialize!

Debugging an issue with the ruby 3 branch

This was an in-progress working document while I centered in on the issues with starting rails on the ruby 3 branch. The core issue was https://bugs.ruby-lang.org/issues/17494#note-9arrow-up-right and is still pending (our move to ruby 3.0 is blocked by this issue with refined method resolution. The patch from Jeremy Evans was effective when tested (but has not been submitted to ruby-lang for inclusion in 3.0.x yet).

Checked out the citizen428/ruby3 branch

bundle

run the following (cribbed from boot or other binstubs to load the app):

require File.expand_path("config/application", __dir__)
@app = PracticalDeveloper::Application.new
@app.initialize! 
# rails freezes here and cpu goes wild

At this point rails freezes up - the cpu goes to 100% - strace records no activity - and a stack trace dump shows this:

djuber@forem:~$ rbspy snapshot -p 3803
# SNIPPED all the code running pry - initialize! is the message I sent last

initialize! - /home/djuber/src/forem/vendor/cache/ruby/3.0.0/gems/railties-6.1.3.1/lib/rails/application.rb:387
run_initializers - /home/djuber/src/forem/vendor/cache/ruby/3.0.0/gems/railties-6.1.3.1/lib/rails/initializable.rb:64
tsort_each - /home/djuber/.rbenv/versions/3.0.0/lib/ruby/3.0.0/tsort.rb:206
tsort_each - /home/djuber/.rbenv/versions/3.0.0/lib/ruby/3.0.0/tsort.rb:233
each_strongly_connected_component - /home/djuber/.rbenv/versions/3.0.0/lib/ruby/3.0.0/tsort.rb:355
call [c function] - (unknown):0
each [c function] - (unknown):0
block in each_strongly_connected_component - /home/djuber/.rbenv/versions/3.0.0/lib/ruby/3.0.0/tsort.rb:353
each_strongly_connected_component_from - /home/djuber/.rbenv/versions/3.0.0/lib/ruby/3.0.0/tsort.rb:435
block (2 levels) in each_strongly_connected_component - /home/djuber/.rbenv/versions/3.0.0/lib/ruby/3.0.0/tsort.rb:351
block in tsort_each - /home/djuber/.rbenv/versions/3.0.0/lib/ruby/3.0.0/tsort.rb:232
block in run_initializers - /home/djuber/src/forem/vendor/cache/ruby/3.0.0/gems/railties-6.1.3.1/lib/rails/initializable.rb:62
run - /home/djuber/src/forem/vendor/cache/ruby/3.0.0/gems/railties-6.1.3.1/lib/rails/initializable.rb:33
instance_exec [c function] - (unknown):0
block in <module:Finisher> - /home/djuber/src/forem/vendor/cache/ruby/3.0.0/gems/railties-6.1.3.1/lib/rails/application/finisher.rb:141
run_load_hooks - /home/djuber/src/forem/vendor/cache/ruby/3.0.0/gems/activesupport-6.1.3.1/lib/active_support/lazy_load_hooks.rb:54
each [c function] - (unknown):0
block in run_load_hooks - /home/djuber/src/forem/vendor/cache/ruby/3.0.0/gems/activesupport-6.1.3.1/lib/active_support/lazy_load_hooks.rb:53
execute_hook - /home/djuber/src/forem/vendor/cache/ruby/3.0.0/gems/activesupport-6.1.3.1/lib/active_support/lazy_load_hooks.rb:77
with_execution_control - /home/djuber/src/forem/vendor/cache/ruby/3.0.0/gems/activesupport-6.1.3.1/lib/active_support/lazy_load_hooks.rb:63
block in execute_hook - /home/djuber/src/forem/vendor/cache/ruby/3.0.0/gems/activesupport-6.1.3.1/lib/active_support/lazy_load_hooks.rb:76
instance_eval [c function] - (unknown):0
block in patch_after_intialize - /home/djuber/src/forem/vendor/cache/ruby/3.0.0/gems/ddtrace-0.47.0/lib/ddtrace/contrib/rails/patcher.rb:89
after_intialize - /home/djuber/src/forem/vendor/cache/ruby/3.0.0/gems/ddtrace-0.47.0/lib/ddtrace/contrib/rails/patcher.rb:98
run - /home/djuber/src/forem/vendor/cache/ruby/3.0.0/gems/ddtrace-0.47.0/lib/ddtrace/utils/only_once.rb:27
synchronize [c function] - (unknown):0
block in run - /home/djuber/src/forem/vendor/cache/ruby/3.0.0/gems/ddtrace-0.47.0/lib/ddtrace/utils/only_once.rb:26
block in after_intialize - /home/djuber/src/forem/vendor/cache/ruby/3.0.0/gems/ddtrace-0.47.0/lib/ddtrace/contrib/rails/patcher.rb:97
setup_tracer - /home/djuber/src/forem/vendor/cache/ruby/3.0.0/gems/ddtrace-0.47.0/lib/ddtrace/contrib/rails/patcher.rb:103
setup - /home/djuber/src/forem/vendor/cache/ruby/3.0.0/gems/ddtrace-0.47.0/lib/ddtrace/contrib/rails/framework.rb:50
configure - /home/djuber/src/forem/vendor/cache/ruby/3.0.0/gems/ddtrace-0.47.0/lib/ddtrace/contrib/extensions.rb:57
each - /home/djuber/.rbenv/versions/3.0.0/lib/ruby/3.0.0/set.rb:346
each_key [c function] - (unknown):0
block in configure - /home/djuber/src/forem/vendor/cache/ruby/3.0.0/gems/ddtrace-0.47.0/lib/ddtrace/contrib/extensions.rb:51
patch - /home/djuber/src/forem/vendor/cache/ruby/3.0.0/gems/ddtrace-0.47.0/lib/ddtrace/contrib/patchable.rb:56
patch - /home/djuber/src/forem/vendor/cache/ruby/3.0.0/gems/ddtrace-0.47.0/lib/ddtrace/contrib/patcher.rb:35
run - /home/djuber/src/forem/vendor/cache/ruby/3.0.0/gems/ddtrace-0.47.0/lib/ddtrace/utils/only_once.rb:27
synchronize [c function] - (unknown):0
block in run - /home/djuber/src/forem/vendor/cache/ruby/3.0.0/gems/ddtrace-0.47.0/lib/ddtrace/utils/only_once.rb:26
block in patch - /home/djuber/src/forem/vendor/cache/ruby/3.0.0/gems/ddtrace-0.47.0/lib/ddtrace/contrib/patcher.rb:34
patch - /home/djuber/src/forem/vendor/cache/ruby/3.0.0/gems/ddtrace-0.47.0/lib/ddtrace/contrib/action_pack/patcher.rb:19
patch - /home/djuber/src/forem/vendor/cache/ruby/3.0.0/gems/ddtrace-0.47.0/lib/ddtrace/contrib/patcher.rb:35
run - /home/djuber/src/forem/vendor/cache/ruby/3.0.0/gems/ddtrace-0.47.0/lib/ddtrace/utils/only_once.rb:27
synchronize [c function] - (unknown):0
block in run - /home/djuber/src/forem/vendor/cache/ruby/3.0.0/gems/ddtrace-0.47.0/lib/ddtrace/utils/only_once.rb:26
block in patch - /home/djuber/src/forem/vendor/cache/ruby/3.0.0/gems/ddtrace-0.47.0/lib/ddtrace/contrib/patcher.rb:34
patch - /home/djuber/src/forem/vendor/cache/ruby/3.0.0/gems/ddtrace-0.47.0/lib/ddtrace/contrib/action_pack/action_controller/patcher.rb:20
require - /home/djuber/src/forem/vendor/cache/ruby/3.0.0/gems/activesupport-6.1.3.1/lib/active_support/dependencies.rb:334
load_dependency - /home/djuber/src/forem/vendor/cache/ruby/3.0.0/gems/activesupport-6.1.3.1/lib/active_support/dependencies.rb:304
block in require - /home/djuber/src/forem/vendor/cache/ruby/3.0.0/gems/activesupport-6.1.3.1/lib/active_support/dependencies.rb:332
require - /home/djuber/src/forem/vendor/cache/ruby/3.0.0/gems/zeitwerk-2.4.2/lib/zeitwerk/kernel.rb:43
require - /home/djuber/src/forem/vendor/cache/ruby/3.0.0/gems/bootsnap-1.7.3/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:46
require_with_bootsnap_lfi - /home/djuber/src/forem/vendor/cache/ruby/3.0.0/gems/bootsnap-1.7.3/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:25
register - /home/djuber/src/forem/vendor/cache/ruby/3.0.0/gems/bootsnap-1.7.3/lib/bootsnap/load_path_cache/loaded_features_index.rb:114
block in require_with_bootsnap_lfi - /home/djuber/src/forem/vendor/cache/ruby/3.0.0/gems/bootsnap-1.7.3/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:24
require [c function] - (unknown):0
<main> - /home/djuber/src/forem/vendor/cache/ruby/3.0.0/gems/actionpack-6.1.3.1/lib/action_controller/metal.rb:8
require - /home/djuber/src/forem/vendor/cache/ruby/3.0.0/gems/activesupport-6.1.3.1/lib/active_support/dependencies.rb:334
load_dependency - /home/djuber/src/forem/vendor/cache/ruby/3.0.0/gems/activesupport-6.1.3.1/lib/active_support/dependencies.rb:304
block in require - /home/djuber/src/forem/vendor/cache/ruby/3.0.0/gems/activesupport-6.1.3.1/lib/active_support/dependencies.rb:332
require - /home/djuber/src/forem/vendor/cache/ruby/3.0.0/gems/zeitwerk-2.4.2/lib/zeitwerk/kernel.rb:43
require - /home/djuber/src/forem/vendor/cache/ruby/3.0.0/gems/bootsnap-1.7.3/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:46
require_with_bootsnap_lfi - /home/djuber/src/forem/vendor/cache/ruby/3.0.0/gems/bootsnap-1.7.3/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:25
register - /home/djuber/src/forem/vendor/cache/ruby/3.0.0/gems/bootsnap-1.7.3/lib/bootsnap/load_path_cache/loaded_features_index.rb:114
block in require_with_bootsnap_lfi - /home/djuber/src/forem/vendor/cache/ruby/3.0.0/gems/bootsnap-1.7.3/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:24
require [c function] - (unknown):0
<main> - /home/djuber/src/forem/vendor/cache/ruby/3.0.0/gems/actionpack-6.1.3.1/lib/action_dispatch/http/response.rb:8
<module:ActionDispatch> - /home/djuber/src/forem/vendor/cache/ruby/3.0.0/gems/actionpack-6.1.3.1/lib/action_dispatch/http/response.rb:540
<class:Response> - /home/djuber/src/forem/vendor/cache/ruby/3.0.0/gems/actionpack-6.1.3.1/lib/action_dispatch/http/response.rb:537
DelegateClass - /home/djuber/.rbenv/versions/3.0.0/lib/ruby/3.0.0/delegate.rb:444
protected_instance_methods [c function] - (unknown):0

Record suggests protected_instance_methods is the hotspot (not sure if something else is happening here). Initially the call stack included a wrapper for amazing print which I commented out in the gemfile - I'm going to remove bootsnap next and possibly zeitwerk.

If you comment out bootsnap - remove from config/boot.rb as well.

At this point I reverted all of my changes (disabling gems and configurations) and am going to do two things

Considerations

There doesn't seem to be any link between the reported yarn issue and the rails isse

Test case setup - nothing bad happened here:

I noticed there was no bundle config in the test project, so I copied forem's

The existence of the test elasticsearch doesn't seem related - it's definitely hanging in initialize! and the fact that some particular rails command is getting called is not the issue. Booting the app is the problem here, and a loop or infinite loop is happening within.

Next refinement - comment out all group :development or group :test blocks - leaving only prod and the core app - rerun bundle - rerun setup. Effectively - everything after line 116 in the Gemfile is removed from bundle.

So this fails because listen is expected in development but not available (at least it fails):

Let's only add listen back, with no version restriction:

And test again

And we're back were we started. I now have a run-away rails process. Seems like listen in development plus something in our gemset is problematic.

Can we isolate that

Listen is there by default in a vanilla rails program (which does not exhibit this problem).

Also, it's important to clarify what we've seen - the app won't boot without listen (since that's configured in the dev env) but freezes when listen is put back, rather than pointing to listen being the problem, it only points to listen being required at dev time. I don't think this means what I wanted it to - only that something in the gemset is a problem, and you have to keep listen installed to make that possible.

circle-info

Question at this point: why doesn't this happen on the Forem app (ruby 2.7.2 and rails 6.1 with more or less the same gems)? It's either ruby 3 or a gem or both.

What about commenting out all of the gems I can from the dummy app (since apparently requiring the gems, without adding any initializer code, is sufficient to introduce this issue in a clean project)?

Commented out all core (non-group specific) gems except bootsnap, pg, puma, rails, sprockets, webpacker

bundle, bin/setup, here we go!

This still includes the gems labeled production (including the nakayoshi fork) and listen, and rails and its dependencies.

Okay, this is helpful - somewhere between 200 gems and 55 gems is our problem.

Bisection search to the rescue! Uncomment down to fastly - 108 gems now installed - all is well - rails db:prepare works fine.

Uncomment down to jsonapi-serializer. bundle. 145 gems now installed. rails db:prepare still works.

Uncomment down to redis-actionpack, bundle, 187 gems now installed - freezes

Between jsonapi-serializer and redis-actionpack is an issue.

This included these (except pg, puma, and rails, which were not skipped initially) - one of these, especially if one of them is injecting itself into action dispatch, is a problem.

Recomment down to pg (so kaminari through patron). bundle - 164 gems installed. setup: Success

Uncomment omniauth to patron (leaving kaminari through oj commented). bundle. 177 gems now installed. setup hangs

Comment omniauth* gems (omniauth through omniauth-twitter, 6 gems total). 166 gems now installed. Setup succeeds.

Uncomment only omniauth. brings in hashie as a dependency. Works.

Uncomment the four providers (apple, facebook, github, twitter) leaving the csrf protection gem commented.

This froze as well during loading. So it's one of those four I guess. This is really good stuff.

Just backing up to the last known safe point to confirm we're okay (we are). I'm going to uncomment everything except these four gems before I go any closer (I want to ensure this isn't one of many problems, that it's the one and only problem, before I go too much farther). I hit a snag running bundle when I added redis-rack back - it looks like without the explicit versioning it floated up to 2.1.3 - deleting the Gemfile.lock and bundling fresh works.

Restating the situation:

all the test/development convenience gems are commented out - listen is installed in development as a dependency (installed by vanilla rails) - all "normal" or top level gems, except the four omniauth providers, are enabled.

Setup works - so it's (definitely?) one of the gems - or one of it's dependencies.

Let's install the dependencies first (oauth2 and oauth) one by one to control for effects, before we enable the omniauth providers.

Freezes. rbspy snapshot shows the same location - protected_instance_methods [c function]

Switching to my "mostly clean" gemfile in listener and adding that single gem to the default install brings in these gems (but does not introduce the problem):

So it looks like it's not only this omniauth-oauth gem but some interaction between something else (which is frustrating, but fine.) Before I go any farther, I'm going to relax any version constraints on the omniauth-oauth gem, and call update (`bundler attempted to update omniauth-oauth, but its version stayed the same). Well that's too bad, there's not some silver bullet laying around uninstalled.

Remove omniauth-oauth gem, add omniauth-oauth2, leave oauth installed since that didn't seem to be the problem.

Reading the code that looks like it's related to where things are going awry - we have class Response which has a Header which is a DelegateClass(Hash) which appears to be the next thing called

Fairly sure this call to protected_instance_methods is part of the problem (or definitely the thing going wrong) - is there something with a Hash causing issues? Did more than one thing define a DelegateClass in some cyclical way? Why would that break Rails?

circle-info

Hashie defines a Hash class - we want to make sure that's not what Rails is trying to wrap the response headers in. Hashie also doesn't have a test suite against ruby 3 yet? https://github.com/hashie/hashie/releases/tag/v4.1.0arrow-up-right is what we have in the gemset.

Omniauth includes Hashie as a dependency.

Buffer also includes Hashie as a dependency through faraday_middleware:

however - bin/setup worked here (leaving omniauth commented- including buffer which was removed in the last commit).

Remove imgproxy, leave buffer, uncomment omniauth.

Works.

Can I introduce the issue by including imgproxy and omniauth-twitter in listener?

Rewinding the state - checking against current master for differences in the Gemfile (aggravatingly I got this working with a slightly different Gemfile.lock)

Last updated