Open alexdelgado opened 1 year ago
This happen on every single restart?
Steps to reproduce
Sorry, but if it was this simple thousands of people would have ran into it.
Any idea what the Ruby process hang onto?
Can you try adding something like this in config/boot.rb
:
main_thread = Thread.current
Thread.new do
loop
puts '-' * 40
puts main_thread.backtrace
sleep 1
end
end
If it's stuck with the GVL released that should print the backtrace, if it's stuck in C land with the GVL held, it probably won't output anything once stuck. We'd at least know that.
Also are you using NFS or some kind of shared volume (e.g. Docker Desktop or something)? bootsnap
does some raw C IOs for performance without releasing the GVL, so it's possible it's getting stuck on file system operations.
Experiencing similar issues
```
[LDClient] Stream initialized
[44525] - Worker 0 (PID: 44656) booted in 0.23s, phase: 0
----------------------------------------
/Users/kyle/.asdf/installs/ruby/3.2.1/lib/ruby/gems/3.2.0/gems/puma-5.6.5/lib/puma/cluster.rb:437:in `wait_readable'
/Users/kyle/.asdf/installs/ruby/3.2.1/lib/ruby/gems/3.2.0/gems/puma-5.6.5/lib/puma/cluster.rb:437:in `run'
/Users/kyle/.asdf/installs/ruby/3.2.1/lib/ruby/gems/3.2.0/gems/puma-5.6.5/lib/puma/launcher.rb:193:in `run'
/Users/kyle/.asdf/installs/ruby/3.2.1/lib/ruby/gems/3.2.0/gems/puma-5.6.5/lib/rack/handler/puma.rb:72:in `run'
/Users/kyle/.asdf/installs/ruby/3.2.1/lib/ruby/gems/3.2.0/gems/rack-2.2.6.4/lib/rack/server.rb:327:in `start'
/Users/kyle/.asdf/installs/ruby/3.2.1/lib/ruby/gems/3.2.0/gems/railties-7.0.4.3/lib/rails/commands/server/server_command.rb:38:in `start'
/Users/kyle/.asdf/installs/ruby/3.2.1/lib/ruby/gems/3.2.0/gems/railties-7.0.4.3/lib/rails/commands/server/server_command.rb:143:in `block in perform'
Sorry, but if it was this simple thousands of people would have ran into it.
I get the sentiment here, but it's not super helpful. This has been reproduced on multiple machines. I'll add some more information that might help us see if this truly is something specific to bootsnap or not. I'm trying to understand more about the caching that bootsnap is doing to see why things work fine on that first app boot, but fail on the second. It's wrecking my brain trying to find what could be different/wrong on that second boot.
It seems to be specific to Rails 7 and Ruby 3.2.X. Switching back to Ruby 3.1.2 with no other changes, resolves the issue. I haven't tried this with a lower version of Rails.
This looks to be something specific to puma. I've found that bootsnap is working fine when using webrick. rails s -u webrick
. Using thin
also works fine.
When I boot the app the second time after clearing the bootsnap cache, I start getting this error. Commenting out require 'bootsnap/setup'
in boot.rb
and restarting the server immediately resolves this.
Puma caught this error: undefined method `execute_if_updated' for nil:NilClass (NoMethodError)
/Users/myusername/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/actionview-7.0.4.3/lib/action_view/cache_expiry.rb:51:in `block in execute_if_updated'
/Users/myusername/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/actionview-7.0.4.3/lib/action_view/cache_expiry.rb:42:in `synchronize'
/Users/myusername/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/actionview-7.0.4.3/lib/action_view/cache_expiry.rb:42:in `execute_if_updated'
/Users/myusername/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/actionview-7.0.4.3/lib/action_view/cache_expiry.rb:15:in `block in run'
/Users/myusername/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/activesupport-7.0.4.3/lib/active_support/concurrency/share_lock.rb:187:in `yield_shares'
/Users/myusername/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/activesupport-7.0.4.3/lib/active_support/dependencies/interlock.rb:41:in `permit_concurrent_loads'
/Users/myusername/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/actionview-7.0.4.3/lib/action_view/cache_expiry.rb:14:in `run'
/Users/myusername/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/activesupport-7.0.4.3/lib/active_support/execution_wrapper.rb:29:in `before'
/Users/myusername/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/activesupport-7.0.4.3/lib/active_support/callbacks.rb:423:in `block in make_lambda'
/Users/myusername/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/activesupport-7.0.4.3/lib/active_support/callbacks.rb:199:in `block (2 levels) in halting'
/Users/myusername/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/activesupport-7.0.4.3/lib/active_support/callbacks.rb:687:in `block (2 levels) in default_terminator'
/Users/myusername/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/activesupport-7.0.4.3/lib/active_support/callbacks.rb:686:in `catch'
/Users/myusername/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/activesupport-7.0.4.3/lib/active_support/callbacks.rb:686:in `block in default_terminator'
/Users/myusername/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/activesupport-7.0.4.3/lib/active_support/callbacks.rb:200:in `block in halting'
/Users/myusername/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/activesupport-7.0.4.3/lib/active_support/callbacks.rb:595:in `block in invoke_before'
/Users/myusername/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/activesupport-7.0.4.3/lib/active_support/callbacks.rb:595:in `each'
/Users/myusername/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/activesupport-7.0.4.3/lib/active_support/callbacks.rb:595:in `invoke_before'
/Users/myusername/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/activesupport-7.0.4.3/lib/active_support/callbacks.rb:106:in `run_callbacks'
/Users/myusername/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/activesupport-7.0.4.3/lib/active_support/execution_wrapper.rb:129:in `run'
/Users/myusername/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/activesupport-7.0.4.3/lib/active_support/execution_wrapper.rb:125:in `run!'
/Users/myusername/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/activesupport-7.0.4.3/lib/active_support/execution_wrapper.rb:78:in `block in run!'
<internal:kernel>:90:in `tap'
/Users/myusername/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/activesupport-7.0.4.3/lib/active_support/execution_wrapper.rb:75:in `run!'
/Users/myusername/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/actionpack-7.0.4.3/lib/action_dispatch/middleware/executor.rb:12:in `call'
/Users/myusername/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/rack-livereload-0.3.17/lib/rack/livereload.rb:23:in `_call'
/Users/myusername/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/rack-livereload-0.3.17/lib/rack/livereload.rb:14:in `call'
/Users/myusername/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/actionpack-7.0.4.3/lib/action_dispatch/middleware/static.rb:23:in `call'
/Users/myusername/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/rack-2.2.6.4/lib/rack/sendfile.rb:110:in `call'
/Users/myusername/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/actionpack-7.0.4.3/lib/action_dispatch/middleware/host_authorization.rb:137:in `call'
/Users/myusername/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/railties-7.0.4.3/lib/rails/engine.rb:530:in `call'
/Users/myusername/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/puma-5.6.5/lib/puma/configuration.rb:252:in `call'
/Users/myusername/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/puma-5.6.5/lib/puma/request.rb:77:in `block in handle_request'
/Users/myusername/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/puma-5.6.5/lib/puma/thread_pool.rb:340:in `with_force_shutdown'
/Users/myusername/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/puma-5.6.5/lib/puma/request.rb:76:in `handle_request'
/Users/myusername/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/puma-5.6.5/lib/puma/server.rb:443:in `process_client'
/Users/myusername/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/puma-5.6.5/lib/puma/thread_pool.rb:147:in `block in spawn_thread'
I'm also going to try the suggestions you made for checking more things. Thanks for sharing that too. I'll report back on that shortly.
I added the snippet you suggested (thanks for that!) and here's what I see being printed every 1 second
/Users/my_user/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/puma-5.6.5/lib/puma/cluster.rb:437:in `wait_readable'
/Users/my_user/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/puma-5.6.5/lib/puma/cluster.rb:437:in `run'
/Users/my_user/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/puma-5.6.5/lib/puma/launcher.rb:193:in `run'
/Users/my_user/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/puma-5.6.5/lib/rack/handler/puma.rb:72:in `run'
/Users/my_user/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/rack-2.2.6.4/lib/rack/server.rb:327:in `start'
/Users/my_user/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/railties-7.0.4.3/lib/rails/commands/server/server_command.rb:38:in `start'
/Users/my_user/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/railties-7.0.4.3/lib/rails/commands/server/server_command.rb:143:in `block in perform'
<internal:kernel>:90:in `tap'
/Users/my_user/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/railties-7.0.4.3/lib/rails/commands/server/server_command.rb:134:in `perform'
/Users/my_user/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/thor-1.2.1/lib/thor/command.rb:27:in `run'
/Users/my_user/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/thor-1.2.1/lib/thor/invocation.rb:127:in `invoke_command'
/Users/my_user/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/thor-1.2.1/lib/thor.rb:392:in `dispatch'
/Users/my_user/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/railties-7.0.4.3/lib/rails/command/base.rb:87:in `perform'
/Users/my_user/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/railties-7.0.4.3/lib/rails/command.rb:48:in `invoke'
/Users/my_user/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/railties-7.0.4.3/lib/rails/commands.rb:18:in `<main>'
/Users/my_user/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/bootsnap-1.15.0/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:32:in `require'
/Users/my_user/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/bootsnap-1.15.0/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:32:in `require'
bin/rails:4:in `<main>'
Thanks for the answers, I'll have another round of questions.
Experiencing similar issues
@kyle-annen is this a totally different app, or are you @themoffatt coworker? I'm a bit surprised to see two persons hitting such huge bug I never heard of the same week.
I get the sentiment here, but it's not super helpful.
Apologies, I didn't mean to be snarky or anything, I just meant that these steps weren't actionable.
This has been reproduced on multiple machines.
But same application, right?
It seems to be specific to Rails 7 and Ruby 3.2.X. Switching back to Ruby 3.1.2 with no other changes, resolves the issue.
That's a very useful information, thank you. If it's not too much trouble, trying 3.1.4
and 3.2.0
could be interesting. If some 3.1.x patch version also fail, or some 3.2.x patch versions works, It would mean this is caused by a change in Ruby that was backported, and that would make it easier to pinpoint it.
This looks to be something specific to puma. I've found that bootsnap is working fine when using webrick. rails s -u webrick. Using thin also works fine.
Also very interesting, that hints at a Mutex or Monitor issue. Initially I thought it could be another fallout from https://bugs.ruby-lang.org/issues/17827, but if that was the case, I think 3.1.2
would also be broken.
undefined method `execute_if_updated' for nil:NilClass (NoMethodError)
Hum, so @watcher
would be nil
here:
https://github.com/rails/rails/blob/c15ee6e7b5065db3c46afa1f025b8e45f443604e/actionview/lib/action_view/cache_expiry.rb#L51
That is very weird, I don't get how that could possibly happen.
Another question: Are you using spring
? If so does spring stop
also solve the issue?
here's what I see being printed every 1 second
Thank you, however I realize my snippet was a bit incorrect, as since you are using Puma, the main thread isn't the one we care for. Here we simply see puma waiting for another request.
Can you try this instead:
Thread.new do
loop
puts '-' * 40
Thread.list.each do |thr|
puts main_thread.backtrace
sleep 1
end
end
This will print the backtraces of all threads, so it should include the Rails request one, and that should tell us where it's stuck.
Thanks @casperisfine. No worries, sorry we didn't post more info in the original. I've actually spun up a fresh rails app and don't see this issue with bootsnap on 3.2.1 either. So it has to be something specific with our app or the Gems we're using. My suspicion is GoodJob or LaunchDarkly. I'm going to try your suggestion above and report back.
If nothing else, if we can find exactly what's causing this issue maybe it'll help someone in the future who has a similar setup to us. :)
I made sure the issue is in bootsnap
Yes, deleting bootsnap cache folder consistently resolves the isssue.
Steps to reproduce
3.2.1
(or3.2.2
)rails s
tmp/cache/bootsnap
Expected behavior
Browser shouldn't hang on restart
Actual behavior
Browser hangs on restart
System configuration
Bootsnap version:
1.16.0
,1.15.0
Ruby version:
3.2.1
,3.2.2
Rails version:
7.0.4.3