Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Ctrl-C doesn't stop puma and SIGTERM does not work #1951

Closed
alecgorge opened this issue Mar 3, 2020 · 11 comments
Closed

Ctrl-C doesn't stop puma and SIGTERM does not work #1951

alecgorge opened this issue Mar 3, 2020 · 11 comments
Assignees
@eregon
Labels
bug priority
Milestone
20.1.0

Comments

@alecgorge
Copy link

Truffleruby version (happens on native with or without JIT too)

$ set -Ux RUBYOPT "--jvm --experimental-options --engine.Compilation=false"
$ ruby -v
truffleruby 20.0.0, like ruby 2.6.5, GraalVM CE JVM [x86_64-darwin]

Start command:

bundle exec puma -v -C config/puma.rb config.ru -p 7777

Once the server finally starts, CPU is pegged at about 400% for a few minutes and then drops to ~100% for another few minutes.

Pressing Ctrl-C does nothing--even when pressed multiple times:

* Listening on tcp://0.0.0.0:7777
Use Ctrl-C to stop
^C^C^C^C^C^C^C^C^C^C- Gracefully stopping, waiting for requests to finish
fish: 'bundle exec puma -v -C config/p…' terminated by signal SIGKILL (Forced quit)

- Gracefully stopping, waiting for requests to finish appears when I did kill 49851. the last line appeared when I did kill -9 49851.

I have not (yet) spent the time to create a minimally reproducible case
@eregon eregon added the bug label Mar 3, 2020
@eregon
Copy link
Member

eregon commented Mar 3, 2020

Thank you for the report.

Could you try sending SIGALRM (kill -ARLM $PID) to the process after Ctrl+C?
That should dump the Ruby backtraces to $stderr.

If running in --jvm mode, it would also be helpful if you can run jstack $PID and share the output, that gives the Java-level stracktraces.

@eregon eregon self-assigned this Mar 3, 2020
@jaimerave
Copy link

This is the backtrace I got:

=> Booting Puma
=> Rails 6.0.2.1 application starting in development 
=> Run `rails server --help` for more startup options
Puma starting in single mode...
* Version 4.3.1 (truffleruby 20.1.0-dev-1ff2bd4a - ruby 2.6.5), codename: Mysterious Traveller
* Min threads: 5, max threads: 5
* Environment: development
* Listening on tcp://127.0.0.1:3000
* Listening on tcp://[::1]:3000
Use Ctrl-C to stop
^C^C^C^C^C^C^C^C^C^CThreads and backtraces:
#<Thread:0x1d528@<foreign thread> run>


#<Thread:0x1d530@/Users/rave/.rbenv/versions/truffleruby-dev/lib/gems/gems/listen-3.2.1/lib/listen/internals/thread_pool.rb:6 sleep>
/Users/rave/.rbenv/versions/truffleruby-dev/lib/gems/gems/listen-3.2.1/lib/listen/event/config.rb:19:in `sleep'
/Users/rave/.rbenv/versions/truffleruby-dev/lib/gems/gems/listen-3.2.1/lib/listen/event/config.rb:19:in `sleep'
/Users/rave/.rbenv/versions/truffleruby-dev/lib/gems/gems/listen-3.2.1/lib/listen/event/processor.rb:59:in `_sleep'
/Users/rave/.rbenv/versions/truffleruby-dev/lib/gems/gems/listen-3.2.1/lib/listen/event/processor.rb:84:in `_wait_until_events'
/Users/rave/.rbenv/versions/truffleruby-dev/lib/gems/gems/listen-3.2.1/lib/listen/event/processor.rb:16:in `block in loop_for'
/Users/rave/.rbenv/versions/truffleruby-dev/lib/gems/gems/listen-3.2.1/lib/listen/event/processor.rb:15:in `loop'
/Users/rave/.rbenv/versions/truffleruby-dev/lib/gems/gems/listen-3.2.1/lib/listen/event/processor.rb:15:in `loop_for'
/Users/rave/.rbenv/versions/truffleruby-dev/lib/gems/gems/listen-3.2.1/lib/listen/event/loop.rb:84:in `_wait_for_changes'
/Users/rave/.rbenv/versions/truffleruby-dev/lib/gems/gems/listen-3.2.1/lib/listen/event/loop.rb:42:in `block in setup'
/Users/rave/.rbenv/versions/truffleruby-dev/lib/gems/gems/listen-3.2.1/lib/listen/internals/thread_pool.rb:6:in `call'
/Users/rave/.rbenv/versions/truffleruby-dev/lib/gems/gems/listen-3.2.1/lib/listen/internals/thread_pool.rb:6:in `block in add'

#<Thread:0x1d540@<foreign thread> run>


#<Thread:0x1d548@/Users/rave/.rbenv/versions/truffleruby-dev/lib/gems/gems/puma-4.3.1/lib/puma/plugin.rb:66 sleep>
/Users/rave/.rbenv/versions/truffleruby-dev/lib/gems/gems/puma-4.3.1/lib/puma/plugin/tmp_restart.rb:21:in `sleep'
/Users/rave/.rbenv/versions/truffleruby-dev/lib/gems/gems/puma-4.3.1/lib/puma/plugin/tmp_restart.rb:21:in `block in start'
/Users/rave/.rbenv/versions/truffleruby-dev/lib/gems/gems/puma-4.3.1/lib/puma/plugin.rb:68:in `call'
/Users/rave/.rbenv/versions/truffleruby-dev/lib/gems/gems/puma-4.3.1/lib/puma/plugin.rb:68:in `block (2 levels) in fire_background'

#<Thread:0x1d558@<foreign thread> run>


#<Thread:0x1d560@/Users/rave/.rbenv/versions/truffleruby-dev/lib/gems/gems/puma-4.3.1/lib/puma/server.rb:354 sleep>
/Users/rave/.rbenv/versions/truffleruby-dev/lib/gems/gems/puma-4.3.1/lib/puma/reactor.rb:397:in `join'
/Users/rave/.rbenv/versions/truffleruby-dev/lib/gems/gems/puma-4.3.1/lib/puma/reactor.rb:397:in `shutdown'
/Users/rave/.rbenv/versions/truffleruby-dev/lib/gems/gems/puma-4.3.1/lib/puma/server.rb:425:in `handle_servers'
/Users/rave/.rbenv/versions/truffleruby-dev/lib/gems/gems/puma-4.3.1/lib/puma/server.rb:356:in `block in run'

#<Thread:0x1d570@/Users/rave/.rbenv/versions/truffleruby-dev/lib/gems/gems/listen-3.2.1/lib/listen/internals/thread_pool.rb:6 sleep>
/Users/rave/.rbenv/versions/truffleruby-dev/lib/gems/gems/listen-3.2.1/lib/listen/adapter/polling.rb:27:in `sleep'
/Users/rave/.rbenv/versions/truffleruby-dev/lib/gems/gems/listen-3.2.1/lib/listen/adapter/polling.rb:27:in `block (2 levels) in _run'
/Users/rave/.rbenv/versions/truffleruby-dev/lib/gems/gems/listen-3.2.1/lib/listen/adapter/polling.rb:23:in `each'
/Users/rave/.rbenv/versions/truffleruby-dev/lib/gems/gems/listen-3.2.1/lib/listen/adapter/polling.rb:23:in `block in _run'
/Users/rave/.rbenv/versions/truffleruby-dev/lib/gems/gems/listen-3.2.1/lib/listen/adapter/polling.rb:21:in `loop'
/Users/rave/.rbenv/versions/truffleruby-dev/lib/gems/gems/listen-3.2.1/lib/listen/adapter/polling.rb:21:in `_run'
/Users/rave/.rbenv/versions/truffleruby-dev/lib/gems/gems/listen-3.2.1/lib/listen/adapter/base.rb:78:in `block in start'
/Users/rave/.rbenv/versions/truffleruby-dev/lib/gems/gems/listen-3.2.1/lib/listen/internals/thread_pool.rb:6:in `call'
/Users/rave/.rbenv/versions/truffleruby-dev/lib/gems/gems/listen-3.2.1/lib/listen/internals/thread_pool.rb:6:in `block in add'

#<Thread:0x1d580@/Users/rave/.rbenv/versions/truffleruby-dev/lib/truffle/timeout.rb:125 sleep>
/Users/rave/.rbenv/versions/truffleruby-dev/lib/truffle/timeout.rb:90:in `pop'
/Users/rave/.rbenv/versions/truffleruby-dev/lib/truffle/timeout.rb:90:in `receive'
/Users/rave/.rbenv/versions/truffleruby-dev/lib/truffle/timeout.rb:90:in `block in watch_channel'
/Users/rave/.rbenv/versions/truffleruby-dev/lib/truffle/timeout.rb:87:in `loop'
/Users/rave/.rbenv/versions/truffleruby-dev/lib/truffle/timeout.rb:87:in `watch_channel'
/Users/rave/.rbenv/versions/truffleruby-dev/lib/truffle/timeout.rb:125:in `block (2 levels) in ensure_timeout_thread_running'

#<Thread:0x1d590@Ruby-reference-processor sleep>

#<Thread:0x1d5a0@main run>
/Users/rave/.rbenv/versions/truffleruby-dev/lib/gems/gems/puma-4.3.1/lib/puma/single.rb:117:in `join'
/Users/rave/.rbenv/versions/truffleruby-dev/lib/gems/gems/puma-4.3.1/lib/puma/single.rb:117:in `run'
/Users/rave/.rbenv/versions/truffleruby-dev/lib/gems/gems/puma-4.3.1/lib/puma/launcher.rb:172:in `run'
/Users/rave/.rbenv/versions/truffleruby-dev/lib/gems/gems/puma-4.3.1/lib/rack/handler/puma.rb:73:in `run'
/Users/rave/.rbenv/versions/truffleruby-dev/lib/gems/gems/rack-2.1.1/lib/rack/server.rb:329:in `start'
/Users/rave/.rbenv/versions/truffleruby-dev/lib/gems/gems/railties-6.0.2.1/lib/rails/commands/server/server_command.rb:39:in `start'
/Users/rave/.rbenv/versions/truffleruby-dev/lib/gems/gems/railties-6.0.2.1/lib/rails/commands/server/server_command.rb:147:in `block in perform'
/Users/rave/.rbenv/versions/truffleruby-dev/lib/gems/gems/railties-6.0.2.1/lib/rails/commands/server/server_command.rb:138:in `tap'
/Users/rave/.rbenv/versions/truffleruby-dev/lib/gems/gems/railties-6.0.2.1/lib/rails/commands/server/server_command.rb:138:in `perform'
/Users/rave/.rbenv/versions/truffleruby-dev/lib/gems/gems/thor-1.0.1/lib/thor/command.rb:27:in `run'
/Users/rave/.rbenv/versions/truffleruby-dev/lib/gems/gems/thor-1.0.1/lib/thor/invocation.rb:127:in `invoke_command'
/Users/rave/.rbenv/versions/truffleruby-dev/lib/gems/gems/thor-1.0.1/lib/thor.rb:392:in `dispatch'
/Users/rave/.rbenv/versions/truffleruby-dev/lib/gems/gems/railties-6.0.2.1/lib/rails/command/base.rb:69:in `perform'
/Users/rave/.rbenv/versions/truffleruby-dev/lib/gems/gems/railties-6.0.2.1/lib/rails/command.rb:46:in `invoke'
/Users/rave/.rbenv/versions/truffleruby-dev/lib/gems/gems/railties-6.0.2.1/lib/rails/commands.rb:18:in `<top (required)>'
bin/rails:9:in `require'
bin/rails:9:in `<main>'

#<Thread:0x1d5b0@<foreign thread> run>


#<Thread:0x1d5b8@<foreign thread> run>


#<Thread:0x1d5c0@<foreign thread> run>


#<Thread:0x1d5c8@<foreign thread> run>


#<Thread:0x1d5d0@/Users/rave/.rbenv/versions/truffleruby-dev/lib/gems/gems/puma-4.3.1/lib/puma/reactor.rb:310 sleep>
ruby.c:1942:in `rb_block_proc'
ruby.c:1942:in `rb_block_proc'
ruby.c:1938:in `rb_block_given_p'
/Users/rave/.rbenv/versions/truffleruby-dev/lib/gems/gems/nio4r-2.5.2/ext/nio4r/selector.c:1:in `NIO_Selector_select_synchronized'
/Users/rave/.rbenv/versions/truffleruby-dev/lib/truffle/truffle/cext.rb:1662:in `rb_ensure'
ruby.c:2155:in `rb_ensure'
/Users/rave/.rbenv/versions/truffleruby-dev/lib/gems/gems/nio4r-2.5.2/ext/nio4r/selector.c:286:in `NIO_Selector_synchronize'
/Users/rave/.rbenv/versions/truffleruby-dev/lib/gems/gems/nio4r-2.5.2/ext/nio4r/selector.c:395:in `NIO_Selector_select'
/Users/rave/.rbenv/versions/truffleruby-dev/lib/truffle/truffle/cext_ruby.rb:39:in `select'
/Users/rave/.rbenv/versions/truffleruby-dev/lib/gems/gems/puma-4.3.1/lib/puma/reactor.rb:136:in `run_internal'
/Users/rave/.rbenv/versions/truffleruby-dev/lib/gems/gems/puma-4.3.1/lib/puma/reactor.rb:313:in `block in run_in_thread'

#<Thread:0x1d5e0@<foreign thread> run>


#<Rack::MiniProfiler::FileStore::CacheCleanupThread:0x1d5e8@/Users/rave/.rbenv/versions/truffleruby-dev/lib/gems/gems/rack-mini-profiler-1.1.4/lib/mini_profiler/storage/file_store.rb:63 sleep>
/Users/rave/.rbenv/versions/truffleruby-dev/lib/gems/gems/rack-mini-profiler-1.1.4/lib/mini_profiler/storage/file_store.rb:81:in `sleep'
/Users/rave/.rbenv/versions/truffleruby-dev/lib/gems/gems/rack-mini-profiler-1.1.4/lib/mini_profiler/storage/file_store.rb:81:in `block in initialize'

#<Thread:0x1d5f8@<foreign thread> run>


#<Thread:0x1d600@/Users/rave/.rbenv/versions/truffleruby-dev/lib/gems/gems/listen-3.2.1/lib/listen/internals/thread_pool.rb:6 sleep>
/Users/rave/.rbenv/versions/truffleruby-dev/lib/gems/gems/listen-3.2.1/lib/listen/adapter/polling.rb:27:in `sleep'
/Users/rave/.rbenv/versions/truffleruby-dev/lib/gems/gems/listen-3.2.1/lib/listen/adapter/polling.rb:27:in `block (2 levels) in _run'
/Users/rave/.rbenv/versions/truffleruby-dev/lib/gems/gems/listen-3.2.1/lib/listen/adapter/polling.rb:23:in `each'
/Users/rave/.rbenv/versions/truffleruby-dev/lib/gems/gems/listen-3.2.1/lib/listen/adapter/polling.rb:23:in `block in _run'
/Users/rave/.rbenv/versions/truffleruby-dev/lib/gems/gems/listen-3.2.1/lib/listen/adapter/polling.rb:21:in `loop'
/Users/rave/.rbenv/versions/truffleruby-dev/lib/gems/gems/listen-3.2.1/lib/listen/adapter/polling.rb:21:in `_run'
/Users/rave/.rbenv/versions/truffleruby-dev/lib/gems/gems/listen-3.2.1/lib/listen/adapter/base.rb:78:in `block in start'
/Users/rave/.rbenv/versions/truffleruby-dev/lib/gems/gems/listen-3.2.1/lib/listen/internals/thread_pool.rb:6:in `call'
/Users/rave/.rbenv/versions/truffleruby-dev/lib/gems/gems/listen-3.2.1/lib/listen/internals/thread_pool.rb:6:in `block in add'

#<Thread:0x1d610@<foreign thread> run>


#<Thread:0x1d618@<foreign thread> run>


#<Thread:0x1d620@/Users/rave/.rbenv/versions/truffleruby-dev/lib/gems/gems/listen-3.2.1/lib/listen/internals/thread_pool.rb:6 sleep>
/Users/rave/.rbenv/versions/truffleruby-dev/lib/gems/gems/listen-3.2.1/lib/listen/event/config.rb:19:in `sleep'
/Users/rave/.rbenv/versions/truffleruby-dev/lib/gems/gems/listen-3.2.1/lib/listen/event/config.rb:19:in `sleep'
/Users/rave/.rbenv/versions/truffleruby-dev/lib/gems/gems/listen-3.2.1/lib/listen/event/processor.rb:59:in `_sleep'
/Users/rave/.rbenv/versions/truffleruby-dev/lib/gems/gems/listen-3.2.1/lib/listen/event/processor.rb:84:in `_wait_until_events'
/Users/rave/.rbenv/versions/truffleruby-dev/lib/gems/gems/listen-3.2.1/lib/listen/event/processor.rb:16:in `block in loop_for'
/Users/rave/.rbenv/versions/truffleruby-dev/lib/gems/gems/listen-3.2.1/lib/listen/event/processor.rb:15:in `loop'
/Users/rave/.rbenv/versions/truffleruby-dev/lib/gems/gems/listen-3.2.1/lib/listen/event/processor.rb:15:in `loop_for'
/Users/rave/.rbenv/versions/truffleruby-dev/lib/gems/gems/listen-3.2.1/lib/listen/event/loop.rb:84:in `_wait_for_changes'
/Users/rave/.rbenv/versions/truffleruby-dev/lib/gems/gems/listen-3.2.1/lib/listen/event/loop.rb:42:in `block in setup'
/Users/rave/.rbenv/versions/truffleruby-dev/lib/gems/gems/listen-3.2.1/lib/listen/internals/thread_pool.rb:6:in `call'
/Users/rave/.rbenv/versions/truffleruby-dev/lib/gems/gems/listen-3.2.1/lib/listen/internals/thread_pool.rb:6:in `block in add'

@eregon
Copy link
Member

eregon commented Mar 5, 2020

Thanks, I'll try to reproduce with a fresh Rails 6 app in dev mode with listen, nio4r and rack-mini-profiler.

@eregon eregon added the priority label Mar 5, 2020
@eregon
Copy link
Member

eregon commented Mar 7, 2020

I can reproduce with the setup in #1962 (comment)

@eregon
Copy link
Member

eregon commented Mar 8, 2020

It seems quite a few gems are competing for overriding the handler for SIGINT (with bundle exec rails server):

Installing signal handler for SIGINT: #<Proc:0x1930@lib/gems/gems/bundler-1.17.2/exe/bundle:5>
Installing signal handler for SIGINT: "DEFAULT"
Installing signal handler for SIGINT: #<Proc:0xb8a0@gems/railties-6.0.2.1/lib/rails/commands/server/server_command.rb:34>
Installing signal handler for SIGINT: #<Proc:0xc008@gems/rack-2.2.2/lib/rack/server.rb:319>
Installing signal handler for SIGINT: #<Proc:0xc0a8@gems/puma-4.3.3/lib/puma/launcher.rb:439>

So the Puma one wins (and doesn't use the previous handlers), but it doesn't seem to work as expected.

@eregon
Copy link
Member

eregon commented Mar 8, 2020

It's getting stuck when the Puma server thread is waiting for the Puma reactor thread, which seems stuck in NIO_Selector_select_synchronized(), as shown above:

#<Thread:0x1d5d0@/Users/rave/.rbenv/versions/truffleruby-dev/lib/gems/gems/puma-4.3.1/lib/puma/reactor.rb:310 sleep>
ruby.c:1942:in `rb_block_proc'
ruby.c:1942:in `rb_block_proc'
ruby.c:1938:in `rb_block_given_p'
/Users/rave/.rbenv/versions/truffleruby-dev/lib/gems/gems/nio4r-2.5.2/ext/nio4r/selector.c:1:in `NIO_Selector_select_synchronized'
/Users/rave/.rbenv/versions/truffleruby-dev/lib/truffle/truffle/cext.rb:1662:in `rb_ensure'
ruby.c:2155:in `rb_ensure'
/Users/rave/.rbenv/versions/truffleruby-dev/lib/gems/gems/nio4r-2.5.2/ext/nio4r/selector.c:286:in `NIO_Selector_synchronize'
/Users/rave/.rbenv/versions/truffleruby-dev/lib/gems/gems/nio4r-2.5.2/ext/nio4r/selector.c:395:in `NIO_Selector_select'
/Users/rave/.rbenv/versions/truffleruby-dev/lib/truffle/truffle/cext_ruby.rb:39:in `select'
/Users/rave/.rbenv/versions/truffleruby-dev/lib/gems/gems/puma-4.3.1/lib/puma/reactor.rb:136:in `run_internal'
/Users/rave/.rbenv/versions/truffleruby-dev/lib/gems/gems/puma-4.3.1/lib/puma/reactor.rb:313:in `block in run_in_thread'

Using NIO4R_PURE=true seems to stop correctly, so it seems related the nio4r C extension.

@eregon
Copy link
Member

eregon commented Mar 8, 2020

The issue is that IO#read(n_bytes) seems to always read as much as possible, and buffer the result, even for IO#sync = true. That means epoll in nio4r will only notice the fd is available for reading once, and read one byte out of it, but never notice it's ready to read again since natively everything has been read, yet there is a unread byte in the Ruby's IO buffer.

@eregon
Copy link
Member

eregon commented Mar 8, 2020

That code is from Rubinius. FWIW it seems this was fixed in Rubinius by removing buffering (IO::InternalBuffer) entirely in rubinius/rubinius@a8f23c1

@eregon
Copy link
Member

eregon commented Mar 8, 2020

Replacing https://github.com/puma/puma/blob/4f555a18c1d9c81d89fc715e96434359afee02a3/lib/puma/reactor.rb#L160 in Puma with sysread(1) works.
Probably that should be done so it works regardless of whether the IO is sync=true or not.

@eregon
Copy link
Member

eregon commented Mar 8, 2020

A snippet to reproduce the buffering issue, which also shows the problem on MRI when a read buffer is used:

require 'nio'

r, w = IO.pipe
# r.sync = false

selector = NIO::Selector.new
selector.register(r, :r)

w.write "pre\n"
w.write "a"
w.write "b"

p r.gets # causes buffering to be used, also reads a and b in the buffer

p IO.select([r]) # IO.select knows to look inside the buffer
p selector.select(3) # but epoll does not!

p r.read(1)

@eregon
Copy link
Member

eregon commented Mar 10, 2020

I've got a fix for this, testing it in CI, it quits nicely now.

graalvmbot pushed a commit that referenced this issue Mar 11, 2020
@eregon
Add spec for IO#read(n) to ensure it does not buffer internally
20d672b 
* See #1951
@eregon eregon added this to the 20.1.0 milestone Mar 11, 2020
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@eregon eregon

Labels
bug priority
Projects
None yet
Milestone
20.1.0
Development

No branches or pull requests
3 participants
@eregon @jaimerave @alecgorge