|
# Sample program to repro a bug that causes ruby to crash in a call to
|
|
# Process.wait2. The program simulates a server controller scenario, in which
|
|
# the parent process starts a daemon process which itself manages a "server"
|
|
# process, in this case just another ruby that sleeps forever. The desire is to
|
|
# send a signal (USR1 here) to the daemon process informing it that it should
|
|
# shut down the server.
|
|
#
|
|
# What is observed is that Time.strftime is causing this. Originally it was
|
|
# thought that the problem was in the Logger class, but attempts to workaround
|
|
# that class by rolling a custom logger that used Time.strftime to do its work
|
|
# revealed the problem once again. When strftime is used from debug statements
|
|
# issued from within the trap handler, the trap handler completes but the
|
|
# subsequent call to Process.wait2 crashes the interpreter. If the log
|
|
# statements don't use strftime everything works as expected. Note also that
|
|
# the crash behavior is nondeterministic, though anecdotally it happens 70-80%
|
|
# of the time.
|
|
#
|
|
# To run this program 10 times and see what the daemon prints, including stack
|
|
# traces, here is a quick shell script:
|
|
#
|
|
# for (( i = 0; i < 10; ++i )); do if [ -e /tmp/test.log ]; then rm
|
|
# /tmp/test.log; fi; ruby /tmp/wait2_fail_test.rb ; sleep 1; kill -USR1 `cat
|
|
# /tmp/test.pid `; sleep 2; cat /tmp/test.log; done
|
|
#
|
|
# See the bottom of this script for a sample crash trace
|
|
#
|
|
STDOUT.sync = true
|
|
|
|
# Set this to true to use strftime in debug statements making the interpreter
|
|
# crash; set to false to skip them and never crash
|
|
$use_strftime = true
|
|
|
|
def debug( msg )
|
|
|
|
tm = $use_strftime ? Time.now.strftime( "%H:%M:%S" ) : Time.now.to_s
|
|
puts "[#{tm} ##$$]: #{msg}"
|
|
end
|
|
|
|
# Here we go...
|
|
|
|
if pid = Kernel.fork
|
|
Process.detach( pid )
|
|
debug( "Detached from child" )
|
|
else
|
|
Process.daemon
|
|
|
|
io = File.open( "/tmp/test.log", "a" )
|
|
STDOUT.reopen( io )
|
|
STDERR.reopen( io )
|
|
|
|
File.open( "/tmp/test.pid", "w" ) { |io| io.puts $$ }
|
|
|
|
debug( "Starting server" )
|
|
server_pid = Process.spawn( "ruby", "-e", "sleep" )
|
|
debug( "Started server with pid #{server_pid}" )
|
|
|
|
trap( "USR1" ) {
|
|
debug( "Inside trap; killing server" )
|
|
Process.kill( "USR2", server_pid )
|
|
debug( "Did kill" )
|
|
}
|
|
|
|
debug( "Waiting for server: #{server_pid}" )
|
|
Process.wait2( server_pid )
|
|
debug( "Wait done; exiting" )
|
|
|
|
exit
|
|
end
|
|
|
|
# ----------------------------------------------------------------
|
|
# Here is a sample of one of the crash messages from /tmp/test.log
|
|
# ----------------------------------------------------------------
|
|
#
|
|
#
|
|
# /tmp/wait2_fail_test.rb:50: [BUG] rb_sys_fail() - errno == 0
|
|
# ruby 1.9.1p0 (2009-01-30 revision 21907) [i386-darwin9.6.0]
|
|
#
|
|
# -- control frame ----------
|
|
# c:0004 p:---- s:0015 b:0015 l:000014 d:000014 CFUNC :wait2
|
|
# c:0003 p:0314 s:0011 b:0011 l:002644 d:000c08 EVAL /tmp/wait2_fail_test.rb:50
|
|
# c:0002 p:---- s:0004 b:0004 l:000003 d:000003 FINISH
|
|
# c:0001 p:0000 s:0002 b:0002 l:002644 d:002644 TOP <main>:38964
|
|
# ---------------------------
|
|
# -- Ruby level backtrace information-----------------------------------------
|
|
# /tmp/wait2_fail_test.rb:50:in `wait2'
|
|
# /tmp/wait2_fail_test.rb:50:in `<main>'
|
|
#
|
|
# -- C level backtrace information -------------------------------------------
|
|
# 0x115fb2 0 ruby 0x00115fb2 rb_vm_bugreport + 82
|
|
# 0x2b70c 1 ruby 0x0002b70c rb_warning + 444
|
|
# 0x2b76b 2 ruby 0x0002b76b rb_bug + 43
|
|
# 0x2cd3b 3 ruby 0x0002cd3b rb_sys_fail + 75
|
|
# 0x8bcd0 4 ruby 0x0008bcd0 rb_f_exit + 672
|
|
# 0x8bcf9 5 ruby 0x0008bcf9 rb_f_exit + 713
|
|
# 0x1019f5 6 ruby 0x001019f5 rb_iseq_compile + 1125
|
|
# 0x10646d 7 ruby 0x0010646d rb_funcall2 + 1773
|
|
# 0x108bdb 8 ruby 0x00108bdb rb_funcall2 + 11867
|
|
# 0x10dfcb 9 ruby 0x0010dfcb rb_funcall2 + 33355
|
|
# 0x10e1df 10 ruby 0x0010e1df rb_iseq_eval_main + 159
|
|
# 0x2e869 11 ruby 0x0002e869 ruby_exec_node + 169
|
|
# 0x30eee 12 ruby 0x00030eee ruby_run_node + 94
|
|
# 0x184f 13 ruby 0x0000184f main + 95
|
|
# 0x17b6 14 ruby 0x000017b6 start + 54
|
|
#
|
|
# [NOTE]
|
|
# You may encounter a bug of Ruby interpreter. Bug reports are welcome.
|
|
# For details: http://www.ruby-lang.org/bugreport.html
|
|
#
|