search

scoutapp / scout_apm_ruby

ScoutAPM Ruby Agent. Supports Rails, Sinatra, Grape, Rack, and many other frameworks
https://scoutapm.com
Other
200 stars 97 forks source link

hang on startup with 5.3.5+ and carrierwave #512

Open Roguelazer opened 1 week ago

Roguelazer commented 1 week ago

After upgrading a simple Rails app from scout 5.3.3 to 5.4.0, puma now hangs on initialization. strace shows that it's spinning on a futex; the process also ignores SIGINT, which seems kind of rude (but does respond to SIGTERM). Everything works fine if starting a rails console or other interactive process; it's something unhappy between scout and puma.

Downgrading to 5.3.3 fixes the problem; upgrading to 5.3.5 or 5.4.0 reproduces it.

Bisection points to 37c88b8ef160727a89793e1cf5f069a73897688d as the offending commit; everything works in 679670e990e07820b928d46c52a4740933e21d0f but and hangs in 37c88b8ef160727a89793e1cf5f069a73897688d.

Relevant specs

Ruby: 3.3.5 Rails: 7.2.1.2

lancetarn commented 6 days ago

Sorry for the trouble there, and thanks for narrowing it down. Based on the context of that commit, I wonder if there are other things in your app that were using the hook (Rails.configuration.after_initialize) that are causing some kind of contention/deadlock with the ActiveRecord instrumentation now that it is being added with it.

If you post a Gemfile or otherwise dump things that are registered to that hook, we might be able to narrow it down farther/see what is executing before it wedges. Meanwhile we'll put an environment together with those specs. This is the first we have heard of this particular issue and it makes me very curious about what is going on.

Roguelazer commented 6 days ago

Nothing in our codebase is using after_initialize directly, but I wouldn't be entirely surprised if some dependency did. I hacked up rails to print out everything that calls after_initialize and got the following

after_initialize callers ``` /src/vendor/bundle/ruby/3.3.0/gems/activesupport-7.2.1.2/lib/active_support/i18n_railtie.rb:19:in `' /src/vendor/bundle/ruby/3.3.0/gems/actionview-7.2.1.2/lib/action_view/railtie.rb:20:in `' /src/vendor/bundle/ruby/3.3.0/gems/actionview-7.2.1.2/lib/action_view/railtie.rb:25:in `' /src/vendor/bundle/ruby/3.3.0/gems/actionview-7.2.1.2/lib/action_view/railtie.rb:30:in `' /src/vendor/bundle/ruby/3.3.0/gems/actionview-7.2.1.2/lib/action_view/railtie.rb:37:in `' /src/vendor/bundle/ruby/3.3.0/gems/actionview-7.2.1.2/lib/action_view/railtie.rb:44:in `' /src/vendor/bundle/ruby/3.3.0/gems/actionview-7.2.1.2/lib/action_view/railtie.rb:49:in `' /src/vendor/bundle/ruby/3.3.0/gems/actionview-7.2.1.2/lib/action_view/railtie.rb:55:in `' /src/vendor/bundle/ruby/3.3.0/gems/actionview-7.2.1.2/lib/action_view/railtie.rb:62:in `' /src/vendor/bundle/ruby/3.3.0/gems/actionview-7.2.1.2/lib/action_view/railtie.rb:67:in `' /src/vendor/bundle/ruby/3.3.0/gems/actionview-7.2.1.2/lib/action_view/railtie.rb:74:in `' /src/vendor/bundle/ruby/3.3.0/gems/actionview-7.2.1.2/lib/action_view/railtie.rb:108:in `' /src/vendor/bundle/ruby/3.3.0/gems/actionmailer-7.2.1.2/lib/action_mailer/railtie.rb:82:in `' /src/vendor/bundle/ruby/3.3.0/gems/actiontext-7.2.1.2/lib/action_text/engine.rb:88:in `' /src/vendor/bundle/ruby/3.3.0/gems/sprockets-rails-3.4.2/lib/sprockets/railtie.rb:219:in `' /src/vendor/bundle/ruby/3.3.0/gems/sassc-rails-2.1.2/lib/sassc/rails/railtie.rb:30:in `' /src/vendor/bundle/ruby/3.3.0/gems/bugsnag-6.27.1/lib/bugsnag/integrations/railtie.rb:122:in `' /src/vendor/bundle/ruby/3.3.0/gems/sidekiq-7.3.4/lib/sidekiq/rails.rb:62:in `' /src/vendor/bundle/ruby/3.3.0/gems/draper-4.0.2/lib/draper/railtie.rb:14:in `' /src/vendor/bundle/ruby/3.3.0/gems/simple_form-5.3.1/lib/simple_form/railtie.rb:8:in `' /src/vendor/bundle/ruby/3.3.0/gems/activesupport-7.2.1.2/lib/active_support/railtie.rb:17:in `block in ' /src/vendor/bundle/ruby/3.3.0/gems/activesupport-7.2.1.2/lib/active_support/railtie.rb:25:in `block in ' /src/vendor/bundle/ruby/3.3.0/gems/activesupport-7.2.1.2/lib/active_support/railtie.rb:33:in `block in ' /src/vendor/bundle/ruby/3.3.0/gems/activesupport-7.2.1.2/lib/active_support/railtie.rb:127:in `block in ' /src/vendor/bundle/ruby/3.3.0/gems/activesupport-7.2.1.2/lib/active_support/railtie.rb:135:in `block in ' /src/vendor/bundle/ruby/3.3.0/gems/activesupport-7.2.1.2/lib/active_support/railtie.rb:143:in `block in ' /src/vendor/bundle/ruby/3.3.0/gems/activesupport-7.2.1.2/lib/active_support/railtie.rb:151:in `block in ' /src/vendor/bundle/ruby/3.3.0/gems/activerecord-7.2.1.2/lib/active_record/railtie.rb:113:in `block in ' /src/vendor/bundle/ruby/3.3.0/gems/activerecord-7.2.1.2/lib/active_record/railtie.rb:156:in `block in ' /src/vendor/bundle/ruby/3.3.0/gems/activerecord-7.2.1.2/lib/active_record/railtie.rb:211:in `block in ' /src/vendor/bundle/ruby/3.3.0/gems/activerecord-7.2.1.2/lib/active_record/railtie.rb:221:in `block in ' /src/vendor/bundle/ruby/3.3.0/gems/activerecord-7.2.1.2/lib/active_record/railtie.rb:233:in `block in ' /src/vendor/bundle/ruby/3.3.0/gems/activerecord-7.2.1.2/lib/active_record/railtie.rb:322:in `block in ' /src/vendor/bundle/ruby/3.3.0/gems/activerecord-7.2.1.2/lib/active_record/railtie.rb:351:in `block in ' /src/vendor/bundle/ruby/3.3.0/gems/activerecord-7.2.1.2/lib/active_record/railtie.rb:385:in `block in ' /src/vendor/bundle/ruby/3.3.0/gems/activerecord-7.2.1.2/lib/active_record/railtie.rb:414:in `block in ' /src/vendor/bundle/ruby/3.3.0/gems/globalid-1.2.1/lib/global_id/railtie.rb:23:in `block in ' /src/vendor/bundle/ruby/3.3.0/gems/activejob-7.2.1.2/lib/active_job/railtie.rb:22:in `block in ' /src/vendor/bundle/ruby/3.3.0/gems/activejob-7.2.1.2/lib/active_job/railtie.rb:44:in `block in ' /src/vendor/bundle/ruby/3.3.0/gems/scout_apm-5.4.0/lib/scout_apm/instruments/active_record.rb:55:in `install' ```

What's interesting is that the ScoutApm::Instruments::ActiveRecord#add_instruments method actually never seems to be called; I stuck a breakpoint there and it never hits.

Nonetheless, I think this was fruitful, because this pointed me to instrumenting the ActiveSupport::LazyLoadHooks class, which revealed that the hanging code appears to be a deadlock between carrierwave/orm/activerecord and scout_apm/instruments/active_record. Removing carrierwave fixes the problem, even with scoutapm 5.4.0.

In this case, we're migrating to ActiveStorage anyway, so dropping Carrierwave seems like straightforward solution. Perhaps someone cleverer than I can figure out why carrierwave and scout_apm are fighting this way.

lancetarn commented 6 days ago

Nicely done. Thank you again for taking the time. Updated the issue title to highlight the conflict while we take a look.