Intermittent segfault on SIGTERM

[TaylorChristie]

Rails: 3.0.5p211
Puma: 6.3.1

Hi, I'm currently investigating an issue with a dockerized rails app that when sent a SIGTERM (graceful shutdown) most of the time it throws a segfault - I have had it gracefully shutdown before, but more often than not it doesn't. This is causing 502s/504s in our application as our load balancers/cluster is expecting the requests to complete. I'm not sure if this is an application related problem, where we have a gem that isn't handling forks/threads properly - or if its a ruby/puma related problem. Any insight would be greatly appreciated!

I've attached the dump:

[1] === puma shutdown: 2024-03-27 16:48:31 +0000 ===
[1] - Goodbye!
[1] - Gracefully shutting down workers...
/usr/local/bundle/gems/puma-6.3.1/lib/puma/cluster/worker.rb:102: [BUG] Segmentation fault at 0x0000000000000000
ruby 3.0.5p211 (2022-11-24 revision ba5cf0f7c5) [x86_64-linux]

-- Control frame information -----------------------------------------------
c:0018 p:0032 s:0102 e:000099 BLOCK  /usr/local/bundle/gems/puma-6.3.1/lib/puma/cluster/worker.rb:102 [FINISH]
c:0017 p:---- s:0097 e:000096 CFUNC  :fork
c:0016 p:0013 s:0093 e:000092 METHOD /usr/local/bundle/gems/activesupport-6.1.7.6/lib/active_support/fork_tracker.rb:8
c:0015 p:0008 s:0087 e:000086 METHOD /usr/local/bundle/gems/activesupport-6.1.7.6/lib/active_support/fork_tracker.rb:27
c:0014 p:0013 s:0082 e:000081 METHOD /usr/local/bundle/gems/activesupport-6.1.7.6/lib/active_support/fork_tracker.rb:8
c:0013 p:0008 s:0076 e:000075 METHOD /usr/local/bundle/gems/activesupport-6.1.7.6/lib/active_support/fork_tracker.rb:27
c:0012 p:0033 s:0071 E:001cb0 METHOD /usr/local/bundle/gems/ddtrace-1.13.1/lib/datadog/profiling/ext/forking.rb:49
c:0011 p:0017 s:0065 E:000548 METHOD /usr/local/bundle/gems/puma-6.3.1/lib/puma/cluster.rb:99
c:0010 p:0056 s:0058 e:000057 BLOCK  /usr/local/bundle/gems/puma-6.3.1/lib/puma/cluster.rb:81 [FINISH]
c:0009 p:---- s:0053 e:000052 CFUNC  :times
c:0008 p:0060 s:0049 e:000048 METHOD /usr/local/bundle/gems/puma-6.3.1/lib/puma/cluster.rb:74
c:0007 p:0374 s:0043 E:002698 METHOD /usr/local/bundle/gems/puma-6.3.1/lib/puma/cluster.rb:416
c:0006 p:0033 s:0026 e:000025 METHOD /usr/local/bundle/gems/puma-6.3.1/lib/puma/launcher.rb:194
c:0005 p:0005 s:0021 e:000020 METHOD /usr/local/bundle/gems/puma-6.3.1/lib/puma/cli.rb:75
c:0004 p:0036 s:0017 e:000016 TOP    /usr/local/bundle/gems/puma-6.3.1/bin/puma:10 [FINISH]
c:0003 p:---- s:0013 e:000012 CFUNC  :load
c:0002 p:0124 s:0008 E:002620 EVAL   /usr/local/bundle/bin/puma:25 [FINISH]
c:0001 p:0000 s:0003 E:0026c0 (none) [FINISH]

-- Ruby level backtrace information ----------------------------------------
/usr/local/bundle/bin/puma:25:in `<main>'
/usr/local/bundle/bin/puma:25:in `load'
/usr/local/bundle/gems/puma-6.3.1/bin/puma:10:in `<top (required)>'
/usr/local/bundle/gems/puma-6.3.1/lib/puma/cli.rb:75:in `run'
/usr/local/bundle/gems/puma-6.3.1/lib/puma/launcher.rb:194:in `run'
/usr/local/bundle/gems/puma-6.3.1/lib/puma/cluster.rb:416:in `run'
/usr/local/bundle/gems/puma-6.3.1/lib/puma/cluster.rb:74:in `spawn_workers'
/usr/local/bundle/gems/puma-6.3.1/lib/puma/cluster.rb:74:in `times'
/usr/local/bundle/gems/puma-6.3.1/lib/puma/cluster.rb:81:in `block in spawn_workers'
/usr/local/bundle/gems/puma-6.3.1/lib/puma/cluster.rb:99:in `spawn_worker'
/usr/local/bundle/gems/ddtrace-1.13.1/lib/datadog/profiling/ext/forking.rb:49:in `fork'
/usr/local/bundle/gems/activesupport-6.1.7.6/lib/active_support/fork_tracker.rb:27:in `fork'
/usr/local/bundle/gems/activesupport-6.1.7.6/lib/active_support/fork_tracker.rb:8:in `fork'
/usr/local/bundle/gems/activesupport-6.1.7.6/lib/active_support/fork_tracker.rb:27:in `fork'
/usr/local/bundle/gems/activesupport-6.1.7.6/lib/active_support/fork_tracker.rb:8:in `fork'
/usr/local/bundle/gems/activesupport-6.1.7.6/lib/active_support/fork_tracker.rb:8:in `fork'
/usr/local/bundle/gems/puma-6.3.1/lib/puma/cluster/worker.rb:102:in `block in run'

-- Machine register context ------------------------------------------------
 RIP: 0x00007f70de6348c6 RBP: 0x00007f70a639afd0 RSP: 0x00007ffc2d405ad8
 RAX: 0x0000000000000088 RBX: 0x00007f70de4f1580 RCX: 0x48447d8b48000000
 RDX: 0x00007ffc2d405b00 RDI: 0x48447d8b48000000 RSI: 0x0000000000000088
  R8: 0x0000000000000000  R9: 0x0000000000000001 R10: 0x00007f70903e98b8
 R11: 0x0000000000000000 R12: 0x0000008800100003 R13: 0x00007f70de7cc4a8
 R14: 0x0000000000000088 R15: 0x48447d8b48000000 EFL: 0x0000000000010206

-- C level backtrace information -------------------------------------------
/usr/local/lib/libruby.so.3.0(rb_print_backtrace+0x11) [0x7f70de69d9ec] vm_dump.c:758
/usr/local/lib/libruby.so.3.0(rb_vm_bugreport) vm_dump.c:998
/usr/local/lib/libruby.so.3.0(rb_bug_for_fatal_signal+0xf0) [0x7f70de4a7f60] error.c:787
/usr/local/lib/libruby.so.3.0(sigsegv+0x49) [0x7f70de5f5239] signal.c:963
/lib/x86_64-linux-gnu/libpthread.so.0(__restore_rt+0x0) [0x7f70de3a8140]
/usr/local/lib/libruby.so.3.0(hash_table_index+0x0) [0x7f70de6348c6] id_table.c:228
/usr/local/lib/libruby.so.3.0(rb_id_table_lookup) id_table.c:230
/usr/local/lib/libruby.so.3.0(vm_search_cc+0x3b) [0x7f70de678871] vm_insnhelper.c:1642
/usr/local/lib/libruby.so.3.0(rb_vm_search_method_slowpath) vm_insnhelper.c:1737
/usr/local/lib/libruby.so.3.0(vm_search_method_slowpath0+0x8) [0x7f70de67f915] vm_insnhelper.c:1759
/usr/local/lib/libruby.so.3.0(vm_search_method_fastpath) vm_insnhelper.c:1826
/usr/local/lib/libruby.so.3.0(vm_sendish) vm_insnhelper.c:4528
/usr/local/lib/libruby.so.3.0(vm_exec_core+0x94) [0x7f70de682664] insns.def:789
/usr/local/lib/libruby.so.3.0(rb_vm_exec+0x182) [0x7f70de687bd2] vm.c:2162
/usr/local/lib/libruby.so.3.0(rb_vm_invoke_proc+0x57) [0x7f70de68ab47] vm.c:1485
/usr/local/lib/libruby.so.3.0(vm_call0_body+0x677) [0x7f70de68b1d7] vm_eval.c:241
/usr/local/lib/libruby.so.3.0(rb_call0+0x1e5) [0x7f70de68d5d5] vm_eval.c:72
/usr/local/lib/libruby.so.3.0(rb_call+0x32) [0x7f70de68e022] vm_eval.c:832
/usr/local/lib/libruby.so.3.0(rb_funcallv_kw) vm_eval.c:1032
/usr/local/lib/libruby.so.3.0(rb_eval_cmd_kw+0x129) [0x7f70de68e159] vm_eval.c:1918
/usr/local/lib/libruby.so.3.0(signal_exec+0xea) [0x7f70de5f4f2a] signal.c:1063
/usr/local/lib/libruby.so.3.0(rb_threadptr_execute_interrupts+0x70) [0x7f70de63d0b8] thread.c:2467
/usr/local/lib/libruby.so.3.0(rb_threadptr_execute_interrupts) thread.c:2424
/usr/local/lib/libruby.so.3.0(vm_check_ints_blocking+0x3a) [0x7f70de641231] thread.c:218
/usr/local/lib/libruby.so.3.0(rb_nogvl) thread.c:1703
/usr/local/bundle/gems/ruby-odbc-0.99999/lib/odbc.so(SQLDISCONNECT+0x20) [0x7f70bef1ddab] odbc.c:486
/usr/local/bundle/gems/ruby-odbc-0.99999/lib/odbc.so(free_dbc) odbc.c:1716
/usr/local/bundle/gems/ruby-odbc-0.99999/lib/odbc.so(free_dbc) odbc.c:1707
/usr/local/lib/libruby.so.3.0(run_final+0xb) [0x7f70de4c687d] gc.c:3674
/usr/local/lib/libruby.so.3.0(finalize_list) gc.c:3693
/usr/local/lib/libruby.so.3.0(rb_objspace_call_finalizer+0x348) [0x7f70de4d10f8] gc.c:3856
/usr/local/lib/libruby.so.3.0(rb_ec_finalize+0x2b) [0x7f70de4b27d1] eval.c:184
/usr/local/lib/libruby.so.3.0(rb_ec_cleanup) eval.c:295
/usr/local/lib/libruby.so.3.0(ruby_stop+0x9) [0x7f70de4b2a79] eval.c:329
/usr/local/lib/libruby.so.3.0(rb_f_fork+0x1f) [0x7f70de5a11c8] process.c:4348
/usr/local/lib/libruby.so.3.0(rb_f_fork) process.c:4338
/usr/local/lib/libruby.so.3.0(vm_cfp_consistent_p+0x0) [0x7f70de6747dc] vm_insnhelper.c:2928
/usr/local/lib/libruby.so.3.0(vm_call_cfunc_with_frame) vm_insnhelper.c:2930
/usr/local/lib/libruby.so.3.0(vm_sendish+0x2be) [0x7f70de67f6be] vm_insnhelper.c:4534
/usr/local/lib/libruby.so.3.0(vm_exec_core+0x2ec2) [0x7f70de685492] insns.def:876
/usr/local/lib/libruby.so.3.0(rb_vm_exec+0x182) [0x7f70de687bd2] vm.c:2162
/usr/local/lib/libruby.so.3.0(rb_yield_1+0x2bc) [0x7f70de689e1c] vm.c:1263
/usr/local/lib/libruby.so.3.0(int_dotimes+0x54) [0x7f70de548d84] numeric.c:5127
/usr/local/lib/libruby.so.3.0(vm_cfp_consistent_p+0x0) [0x7f70de6747dc] vm_insnhelper.c:2928
/usr/local/lib/libruby.so.3.0(vm_call_cfunc_with_frame) vm_insnhelper.c:2930
/usr/local/lib/libruby.so.3.0(vm_sendish+0x37f) [0x7f70de67f77f] vm_insnhelper.c:4529
/usr/local/lib/libruby.so.3.0(vm_exec_core+0x103) [0x7f70de6826d3] insns.def:770
/usr/local/lib/libruby.so.3.0(rb_vm_exec+0x9be) [0x7f70de68840e] vm.c:2171
/usr/local/lib/libruby.so.3.0(raise_load_if_failed+0x0) [0x7f70de509a79] load.c:638
/usr/local/lib/libruby.so.3.0(rb_load_internal) load.c:698
/usr/local/lib/libruby.so.3.0(rb_f_load) load.c:770
/usr/local/lib/libruby.so.3.0(vm_cfp_consistent_p+0x0) [0x7f70de6747dc] vm_insnhelper.c:2928
/usr/local/lib/libruby.so.3.0(vm_call_cfunc_with_frame) vm_insnhelper.c:2930
/usr/local/lib/libruby.so.3.0(vm_sendish+0x37f) [0x7f70de67f77f] vm_insnhelper.c:4529
/usr/local/lib/libruby.so.3.0(vm_exec_core+0x94) [0x7f70de682664] insns.def:789
/usr/local/lib/libruby.so.3.0(rb_vm_exec+0x182) [0x7f70de687bd2] vm.c:2162
/usr/local/lib/libruby.so.3.0(rb_ec_exec_node+0xc6) [0x7f70de4ace06] eval.c:317
/usr/local/lib/libruby.so.3.0(ruby_run_node+0x56) [0x7f70de4b2ad6] eval.c:375
/usr/local/bin/ruby(main+0x5b) [0x56248421910b] ./main.c:50

[dentarg]

It is a problem in Ruby, not Puma. It looks like it has been reported at https://bugs.ruby-lang.org/issues/19865 already (the bug report explains very well what's happening). Even looks like there's a suggested patch for it (ruby/ruby@master...nobu:ruby:signal-at-cleanup).

[TaylorChristie]

Thank you, much appreciated!