rails new and rails server sometime hangs and crashes on busy F5(reloading) while starting

[yoshiokatsuneo]

Steps to reproduce

1. Creating a new rails project using "rails new" using rails 5.0.1

% rails new huga
% cd huga

2. Start the server (puma) with default settings (5 Threading)

% rails server

3. Send HTTP request twice at the same time, by running a command below:

$ wget -O /dev/null http://localhost:3000/ & wget -O /dev/null http://localhost:3000/

Or, on the browser(Safari, Chrome), just push F5(reloading) button many times(like 3 times / sec).
But, in this case, I can reproduce the issue once in 3-10 times.

4. Normally, rails response to the request, but sometimes, rails hangs and never response for the connection after that. And, in rare case(once in 20-30 times?), after pushing "Ctrl-C", ruby crashes with a segmentation fault error.

The problem does not happens if I change the number of puma thread from 5 to 1. So, I guess it is related to multi threading.
I see the issue on both Mac OS Sierra, and Ubuntu16.04.
I see the issue on both sqlite3 and mysql database.

Expected behavior

Rails should not crash and response like:

$ rails server 
=> Booting Puma
=> Rails 5.0.1 application starting in development on http://localhost:3000
=> Run `rails server -h` for more startup options
Puma starting in single mode...
* Version 3.6.2 (ruby 2.3.3-p222), codename: Sleepy Sunday Serenity
* Min threads: 5, max threads: 5
* Environment: development
* Listening on tcp://localhost:3000
Use Ctrl-C to stop
Started GET "/" for ::1 at 2016-12-26 15:28:15 +0900
Processing by Rails::WelcomeController#index as HTML
  Parameters: {"internal"=>true}
  Rendering /Users/tsuneo/.rvm/gems/ruby-2.3.3@rails5/gems/railties-5.0.1/lib/rails/templates/rails/welcome/index.html.erb
  Rendered /Users/tsuneo/.rvm/gems/ruby-2.3.3@rails5/gems/railties-5.0.1/lib/rails/templates/rails/welcome/index.html.erb (4.7ms)
Completed 200 OK in 25ms (Views: 12.3ms | ActiveRecord: 0.0ms)

Actual behavior

Sometimes, (like once in 3-10 times) Rails hang up and never response, and output log like below:

$ rails server 
=> Booting Puma
=> Rails 5.0.1 application starting in development on http://localhost:3000
=> Run `rails server -h` for more startup options
Puma starting in single mode...
* Version 3.6.2 (ruby 2.3.3-p222), codename: Sleepy Sunday Serenity
* Min threads: 5, max threads: 5
* Environment: development
* Listening on tcp://localhost:3000
Use Ctrl-C to stop
Started GET "/" for ::1 at 2016-12-26 15:29:24 +0900
Started GET "/" for ::1 at 2016-12-26 15:29:24 +0900

In rare case, after pushing Ctrl-C, following crashing report follows.

^CExiting
/Users/tsuneo/.rvm/gems/ruby-2.3.3@rails5/gems/activesupport-5.0.1/lib/active_support/inflector/methods.rb:270: [BUG] Segmentation fault at 0x0070000d11d938
ruby 2.3.3p222 (2016-11-21 revision 56859) [x86_64-darwin16]

-- Crash Report log information --------------------------------------------
   See Crash Report log file under the one of following:                    
     * ~/Library/Logs/CrashReporter                                         
     * /Library/Logs/CrashReporter                                          
     * ~/Library/Logs/DiagnosticReports                                     
     * /Library/Logs/DiagnosticReports                                      
   for more details.                                                        
Don't forget to include the above Crash Report log file in bug reports.     

-- Control frame information -----------------------------------------------
c:0056 p:---- s:0348 e:000347 CFUNC  :const_get
c:0055 p:0038 s:0344 e:000343 BLOCK  /Users/tsuneo/.rvm/gems/ruby-2.3.3@rails5/gems/activesupport-5.0.1/lib/active_support/inflector/methods.rb:270 [FINISH]
c:0054 p:---- s:0339 e:000338 IFUNC 
...

I attached the full crashing message, and diagnose report.

System configuration

Rails version:
5.0.1

Ruby version:
ruby 2.3.3p222 (2016-11-21 revision 56859) [x86_64-darwin16]

ruby_2016-12-26-152934_MacBook-Pro-2.crash.txt
rails_server_crash_output.txt
rails_server_crash_output_linux.txt

[utilum]

Can't reproduce.

Rails 5.0.1
ruby 2.3.3p222 (2016-11-21 revision 56859) [x86_64-linux]
as well as ruby 2.4.0p0 (2016-12-24 revision 57164) [x86_64-linux]

[matthewd]

The crash sounds like a ruby bug.

The unresponsive hang is probably a deadlock; you might be able to better identify it using ActionDispatch::DebugLocks.

[yoshiokatsuneo]

I could reproduce the hanging and crashing issue on Rails5.0.1/ruby2.4 .
I attached the crash report.
rails_server_crash_ruby2.4.txt
ruby_2016-12-27-103331_MacBook-Pro-2.crash.txt

[yoshiokatsuneo]

@matthewd Thank you !
So, I got the ActionDispatch::DebugLocks output.
locks.txt

It looks, multiple thread(Thread0, 2) calls const_get at the same time,
and the "const_get" loads modules using a lock.

Thread 0 [0x3fedce1b30cc sleep]  No lock (yielded share)
  Waiting in start_exclusive to "load"
  may be pre-empted for: "load"
  blocked by: 2
  blocking: 1

/Users/tsuneo/.rvm/rubies/ruby-2.4.0/lib/ruby/2.4.0/monitor.rb:111:in `sleep'
/Users/tsuneo/.rvm/rubies/ruby-2.4.0/lib/ruby/2.4.0/monitor.rb:111:in `wait'
/Users/tsuneo/.rvm/rubies/ruby-2.4.0/lib/ruby/2.4.0/monitor.rb:111:in `wait'
/Users/tsuneo/.rvm/rubies/ruby-2.4.0/lib/ruby/2.4.0/monitor.rb:123:in `wait_while'
/Users/tsuneo/.rvm/gems/ruby-2.4.0/gems/activesupport-5.0.1/lib/active_support/concurrency/share_lock.rb:220:in `wait_for'
/Users/tsuneo/.rvm/gems/ruby-2.4.0/gems/activesupport-5.0.1/lib/active_support/concurrency/share_lock.rb:82:in `block (2 levels) in start_exclusive'
...
/Users/tsuneo/.rvm/gems/ruby-2.4.0/gems/activesupport-5.0.1/lib/active_support/dependencies.rb:293:in `require'
/Users/tsuneo/.rvm/gems/ruby-2.4.0/gems/activesupport-5.0.1/lib/active_support/dependencies.rb:293:in `block in require'
/Users/tsuneo/.rvm/gems/ruby-2.4.0/gems/activesupport-5.0.1/lib/active_support/dependencies.rb:259:in `load_dependency'
/Users/tsuneo/.rvm/gems/ruby-2.4.0/gems/activesupport-5.0.1/lib/active_support/dependencies.rb:293:in `require'
/Users/tsuneo/.rvm/gems/ruby-2.4.0/gems/activesupport-5.0.1/lib/active_support/inflector/methods.rb:270:in `const_get'
...

Thread 2 [0x3fedce1b3040 sleep]  Sharing
  blocking: 0

/Users/tsuneo/.rvm/gems/ruby-2.4.0/gems/activesupport-5.0.1/lib/active_support/inflector/methods.rb:270:in `const_get'
...

Crash report also says it locked on "autoload_reset" called on "rb_mod_const_get".

-- C level backtrace information -------------------------------------------
0   libruby.2.4.0.dylib                 0x00000001099a0f74 rb_vm_bugreport + 388
1   libruby.2.4.0.dylib                 0x000000010983b0aa rb_bug_context + 490
2   libruby.2.4.0.dylib                 0x000000010991cc98 sigbus + 72
3   libsystem_platform.dylib            0x00007fffb4760bba _sigtramp + 26
4   libruby.2.4.0.dylib                 0x00000001099789a7 autoload_reset + 183
5   libruby.2.4.0.dylib                 0x0000000109844e05 rb_ensure + 213
6   libruby.2.4.0.dylib                 0x0000000109978715 rb_autoload_load + 357
7   libruby.2.4.0.dylib                 0x0000000109975b0c rb_const_search + 396
8   libruby.2.4.0.dylib                 0x0000000109978bdf rb_const_get + 31
9   libruby.2.4.0.dylib                 0x00000001098a7750 rb_mod_const_get + 624

I can guess, "const_get" may not always thread safe when it causes autloading, and need to be synchronized ?

[yoshiokatsuneo]

And, the issue does not happens if I set "config.eager_load = true".
So, it looks about autoloading.

[yoshiokatsuneo]

Better way to reproduce the hanging issue (I could reproduce 100%).

Run the following command just after running "rails server".

$ wget -O /dev/null http://localhost:3000/ & wget -O /dev/null http://localhost:3000/

[nateberkopec]

Wondering if we can get someone to take another look at @yoshiokatsuneo's info here. We have people reporting this at puma/puma#1184, but none of them have the problem if a) threading is off or b) eager_load is on.

[matthewd]

@nateberkopec this particular issue is a problem specific to the built-in Rails::WelcomeController.

Other threading issues should be investigated with DebugLocks and reported separately.

[rails-bot]

This issue has been automatically marked as stale because it has not been commented on for at least three months.
The resources of the Rails team are limited, and so we are asking for your help.
If you can still reproduce this error on the 5-1-stable branch or on master, please reply with all of the information you have about it in order to keep the issue open.
Thank you for all your contributions.

[dehjli85]

I'm still running into this issue on 5.1.4, running Puma 3.11.2, and ruby 2.4.3. Even when running the server with Webrick, it hangs so pretty sure this is a Rails issue.

I'm running the Rails server as a JSON API project. Our front-end code makes multiple Ajax requests to the Rails server without waiting for a response before sending the next request, and this seems to be causing the hanging. If I throttle/decrease the number of requests, the server does not hang.

I did try to set config.eager_load = true in my development.rb file, this seemed to resolve the issue for me, but I don't have enough expertise to understand why that helped.

[ArielAleksandrus]

I'm going through this with rails 5.1.6 and puma 3.11.3
I can't find a way to fix this!!!

[scrooloose]

We are running into this issue on Ruby 2.4.4p296, Rails 5.1.4, Puma 3.9.1. We can also reproduce it on later versions of ruby.

The config.eager_load = true workaround fixes it for us, but this is obviously not ideal.

[edmundtfy]

Same, with Rails 6.0

[fsufitch]

Happening here as well. Specs:

Ruby: ruby 2.6.2p47 (2019-03-13 revision 67232) [x86_64-linux]
Rails: 5.2
Puma: 4.3

Even with the eager_load workaround, the server appears to hang, since no "server started" logs get printed. However, the port does get opened, and the messages get printed as soon as any HTTP traffic arrives.

[Shalashtein]

Running into this issue as well, it should be reoppened

Ruby: ruby 2.6.6p146 (2020-03-31 revision 67876) [x86_64-linux]
Rails: Rails 6.0.3.4
Puma: 4.3.7

I tried isolating the issue, but I run into it in several conditions, when I get multiple requests, when I run into an error, fix the code and go back to the app I find that the server is hanging

I tried the suggested fixes related to eager load and asset debugging but nothing helped

[ilvez]

Ruby: ruby 2.6.6p146 (2020-03-31 revision 67876) [x86_64-linux]
Rails: Rails 6.0.3.4
Puma: 4.3.7

Really similar versions for a project I'm working with as well (running on Ruby 2.7 and soon upgrading to Ruby 3.0/Rails 6.1, but I'm quite sure this issue won't disappear). There we have connected the issue with Webpack dev-server. But now reading this issue here, the root cause may reside else.

[ilvez]

Maybe worth mentioning what autoloader is being used as well, since this may be autoloader issue.

We are currently stuck with classic autoloader and I cannot reproduce this with zeitwerk, since we need to port to it.

[eddiesiegel]

I am having this issue as well.
Rails: 6.1.3.1
Ruby: ruby 3.0.1p64 (2021-04-05 revision 0fb782ee38) [x86_64-darwin20]