Ruby » ruby-trunk

# 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

#