[ruby-core:17341] Re: Release Plan: Ruby 1.9.0-2

From: "SASADA Koichi" <[e-mail]>
> SASADA Koichi wrote:
>> Could you try on your environment?  I have tried on Linux
>> (i386/amd64), and trying on mswin32, cygwin.
>
> We'll release 1.9.0-2 on next morning (JST).  We have 12 hours to
> try it.

Hi,

I updated to revision 17425 in trunk, and built on WinXP using
Visual Studio .NET 2003.

I did `nmake clean`, then:

.\win32\configure.bat --prefix=m:/dev/ruby-build/trunk

Then `nmake`, then `nmake test`.

I'm getting a crash on `make test` in: test_thread.rb ...

  4652  rb_thread_execute_interrupts    _getptd             Normal  0
  5524  timer_thread_func               timer_thread_func   Normal  0
> 5080  Win32 Thread                    00000000            Normal  0
  4248  thread_start_func_1             native_mutex_lock   Normal  0

  EAX = 00000000 EBX = 009E2ED0 ECX = 009E4008 EDX = 009E4008 ESI = 00B4A1B0
  EDI = 7C911538 EIP = 00000000 ESP = 012AFED0 EBP = 012AFED8 EFL = 00000202
  CS = 001B DS = 0023 ES = 0023 SS = 0023 FS = 003B GS = 0000
  OV = 0 UP = 0 EI = 1 PL = 0 ZR = 0 AC = 0 PE = 0 CY = 0

It seems "Win32 Thread" has jumped to address 0x00000000.

Unfortuantely, the debugger displays an empty call stack for "Win32 Thread".

However, [ESP] is 0x004e1677, which is:

--- p:\code\ruby-svn\trunk\thread.c --------------------------------------------

  static void
  rb_thread_interrupt(rb_thread_t *th)
  {
  004E1640  push        ebp
  004E1641  mov         ebp,esp
      native_mutex_lock(&th->interrupt_lock);
  004E1643  mov         eax,dword ptr [th]
  004E1646  add         eax,60h
  004E1649  push        eax
  004E164A  call        native_mutex_lock (4E12A0h)
  004E164F  add         esp,4
      RUBY_VM_SET_INTERRUPT(th);
  004E1652  mov         ecx,dword ptr [th]
  004E1655  mov         edx,dword ptr [ecx+5Ch]
  004E1658  or          edx,2
  004E165B  mov         eax,dword ptr [th]
  004E165E  mov         dword ptr [eax+5Ch],edx
      if (th->unblock.func) {
  004E1661  mov         ecx,dword ptr [th]
  004E1664  cmp         dword ptr [ecx+78h],0
  004E1668  je          rb_thread_interrupt+3Ah (4E167Ah)
      (th->unblock.func)(th->unblock.arg);
  004E166A  mov         edx,dword ptr [th]
  004E166D  mov         eax,dword ptr [edx+7Ch]
  004E1670  push        eax
  004E1671  mov         ecx,dword ptr [th]
  004E1674  call        dword ptr [ecx+78h]
> 004E1677  add         esp,4
      }
      else {
      /* none */
      }
      native_mutex_unlock(&th->interrupt_lock);
  004E167A  mov         edx,dword ptr [th]
  004E167D  add         edx,60h
  004E1680  push        edx
  004E1681  call        native_mutex_unlock (4E12C0h)
  004E1686  add         esp,4
  }
  004E1689  pop         ebp
  004E168A  ret


The memory at ECX is:  (ecx+78h marked with [00000000])

0x009E4008  00ae9994 009e2df0 00a50020 00020000 00acfdf0 00000000 00000000 00000000
0x009E4028  00000000 00b05964 00000000 00000000 00000000 00000000 000007ac 00000003
0x009E4048  00000000 000007a8 00ae8aa8 00000000 00000004 00000000 00000000 00000002
0x009E4068  00145758 00000000 00000001 000013d8 00000000 00000000[00000000]00000000
0x009E4088  00000000 00000000 0012d32c 00000000 00000000 00000000 00000000 00000000
0x009E40A8  00000000 00000000 00000000 0012fffc 0012d2ac 000ccccd 0012d2bc 7ffde000
0x009E40C8  00000000 0012e2ac 0012d2b0 004e3205 0012ffb0 00000000 56433230 00000000
0x009E40E8  00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000


So it appears th->unblock.func was cleared, in between:

  004E1664  cmp         dword ptr [ecx+78h],0

and

  004E1674  call        dword ptr [ecx+78h]

??

Either that or something stomped on [th] which is really [ebp+8] ... but it doesn't look
like garbage, to me:

0x012AFED8  012aff64 004e1ce3[009e4008]00000000 00000000 00b38b40 00bd0448 012aff64
0x012AFEF8  009e2ed0 7c911538 00b4a1b0 012afed8 004e1ac5 012affa4 00000000 56433230
0x012AFF18  00000000 012aff3c 012aff3c 0000001c 012aff68 004e16c6 012aff3c 00000000



The other threads are at:

thread 4652  rb_thread_execute_interrupts    _getptd             Normal  0
----
  [...]
  msvcr71.dll!_getptd()  Line 319 C
  miniruby.exe!rb_thread_schedule()  Line 783 + 0x5   C
  miniruby.exe!rb_thread_execute_interrupts(rb_thread_struct * th=)  Line 890 C

  void
  rb_thread_schedule(void)
  {
  004E2140  push        ebp
  004E2141  mov         ebp,esp
  004E2143  push        ecx
      thread_debug("rb_thread_schedule\n");
  004E2144  xor         eax,eax
  004E2146  je          rb_thread_schedule+16h (4E2156h)
  004E2148  push        offset string "rb_thread_schedule\n" (50D060h)
  004E214D  call        dword ptr [__imp__printf (4F12B8h)]
  004E2153  add         esp,4
      if (!rb_thread_alone()) {
  004E2156  call        rb_thread_alone (4E2AC0h)
> 004E215B  test        eax,eax
  004E215D  jne         rb_thread_schedule+0BFh (4E21FFh)
    rb_thread_t *th = GET_THREAD();


thread 5524  timer_thread_func               timer_thread_func   Normal  0
----
  [...]
  ntdll.dll!7c90eb94()
  ntdll.dll!7c90d85c()
  kernel32.dll!7c8023ed()
  kernel32.dll!7c802451()
  miniruby.exe!timer_thread_func(void * dummy=0x00000000)  Line 546 C
  msvcr71.dll!_threadstartex(void * ptd=0x00b3a780)  Line 241 + 0x6 C

  static unsigned long _stdcall
  timer_thread_func(void *dummy)
  {
  004E13A0  push        ebp
  004E13A1  mov         ebp,esp
      thread_debug("timer_thread\n");
  004E13A3  xor         eax,eax
  004E13A5  je          timer_thread_func+15h (4E13B5h)
  004E13A7  push        offset string "timer_thread\n" (50CD74h)
  004E13AC  call        dword ptr [__imp__printf (4F12B8h)]
  004E13B2  add         esp,4
      while (system_working) {
  004E13B5  cmp         dword ptr [system_working (52AC24h)],0
  004E13BC  je          timer_thread_func+2Dh (4E13CDh)
    Sleep(WIN32_WAIT_TIMEOUT);
  004E13BE  push        0Ah
  004E13C0  call        dword ptr [__imp__Sleep@4 (4F10E8h)]
    timer_thread_function();
> 004E13C6  call        timer_thread_function (4E3210h)
      }
  004E13CB  jmp         timer_thread_func+15h (4E13B5h)
      thread_debug("timer killed\n");


thread 4248  thread_start_func_1             native_mutex_lock   Normal  0
----
  [...]
  ntdll.dll!7c90104b()
  miniruby.exe!native_mutex_lock(_RTL_CRITICAL_SECTION * lock=0x009e2df4)  Line 285   C
  miniruby.exe!thread_start_func_2(rb_thread_struct * th=0x00b80818, unsigned long * stack_start=0x013aff7c)  Line 334 + 0xf  C
  miniruby.exe!thread_start_func_1(void * th_ptr=0x00b80818)  Line 476 + 0xd  C
  msvcr71.dll!_threadstartex(void * ptd=0x00b4a338)  Line 241 + 0x6   C

  static int
  thread_start_func_2(rb_thread_t *th, VALUE *stack_start, VALUE *register_stack_start)
  {
  004E1A10  push        ebp
  004E1A11  mov         ebp,esp
  004E1A13  sub         esp,80h
      int state;
      VALUE args = th->first_args;
  004E1A19  mov         eax,dword ptr [th]
  004E1A1C  mov         ecx,dword ptr [eax+0A4h]
  004E1A22  mov         dword ptr [args],ecx
      rb_proc_t *proc;
      rb_thread_t *join_th;
      rb_thread_t *main_th;
      VALUE errinfo = Qnil;
  004E1A25  mov         dword ptr [errinfo],4

      th->machine_stack_start = stack_start;
  004E1A2C  mov         edx,dword ptr [th]
  004E1A2F  mov         eax,dword ptr [stack_start]
  004E1A32  mov         dword ptr [edx+0ACh],eax
  #ifdef __ia64
      th->machine_register_stack_start = register_stack_start;
  #endif
      thread_debug("thread start: %p\n", th);
  004E1A38  xor         ecx,ecx
  004E1A3A  je          thread_start_func_2+3Eh (4E1A4Eh)
  004E1A3C  mov         edx,dword ptr [th]
  004E1A3F  push        edx
  004E1A40  push        offset string "thread start: %p\n" (50CF90h)
  004E1A45  call        dword ptr [__imp__printf (4F12B8h)]
  004E1A4B  add         esp,8

      native_mutex_lock(&th->vm->global_vm_lock);
  004E1A4E  mov         eax,dword ptr [th]
  004E1A51  mov         ecx,dword ptr [eax+4]
  004E1A54  add         ecx,4
  004E1A57  push        ecx
  004E1A58  call        native_mutex_lock (4E12A0h)
> 004E1A5D  add         esp,4
      {
    thread_debug("thread start (get lock): %p\n", th);
  004E1A60  xor         edx,edx


Here's the [th] structure from the crashed Win32 Thread:

-   th      0x009e4008
    self    11442580        unsigned long
-   vm      0x009e2df0
        self    11442600        unsigned long
-       global_vm_lock
+           DebugInfo       0x00145730
            LockCount       2       long
            RecursionCount  1       long
            OwningThread    0x000013d8      void *
            LockSemaphore   0x00000774      void *
            SpinCount       0       unsigned long
+       main_thread     0x009e4008 {self=11442580 vm=0x009e2df0 [...]
+       running_thread  0x00b80558 {self=12387400 vm=0x009e2df0 [...]
+       living_threads  0x00b38b40 {type=0x00508b58 type_numhash num_bins=11 entries_packed=1 ...}      st_table *
        thgroup_default 11438760        unsigned long
        last_status     0       unsigned long
        running 1       int
        thread_abort_on_exception       0       int
        trace_flag      0       unsigned long
        sleeper 4419    volatile int
        mark_object_ary 11539260        unsigned long
+       special_exceptions      0x009e2e34      unsigned long [3]
        top_self        11557220        unsigned long
        load_path       11456220        unsigned long
        loaded_features 11456160        unsigned long
+       loading_table   0x00000000 {type=??? num_bins=??? entries_packed=??? ...}       st_table *
+       signal_buff     0x009e2e50      long [23]
        buffered_signal_size    0       long
+       event_hooks     0x00000000 {flag=??? func=??? data=??? ...}     rb_event_hook_struct *
        src_encoding_index      -1      int
        verbose 4       unsigned long
        debug   0       unsigned long
        progname        11429980        unsigned long
+   stack   0x00a50020      unsigned long *
    stack_size      131072  unsigned long
+   cfp     0x00acfdf0 {pc=0x00000000 sp=0x00a5007c bp=0x00a5007c ...}      rb_control_frame_t *
    safe_level      0       int
    raised_flag     0       int
    state   0       int
+   passed_block    0x00000000 {self=??? lfp=??? dfp=??? ...}       rb_block_struct *
    top_self        11557220        unsigned long
    top_wrapper     0       unsigned long
+   base_block      0x00000000 {self=??? lfp=??? dfp=??? ...}       rb_block_struct *
+   local_lfp       0x00000000      unsigned long *
    local_svar      0       unsigned long
    thread_id       0x000007ac      void *
    status  THREAD_STOPPED_FOREVER  rb_thread_status
    priority        0       int
+   native_thread_data      {interrupt_event=0x000007a8 }   native_thread_data_struct
    thgroup 11438760        unsigned long
    value   0       unsigned long
    errinfo 4       unsigned long
    thrown_errinfo  0       unsigned long
    exec_signal     0       int
    interrupt_flag  2       int
+   interrupt_lock  {DebugInfo=0x00145758 {Type=0 CreatorBackTraceIndex=0 CriticalSection=0x009e4068 {DebugInfo=0x00145758 {Type=0 
CreatorBackTraceIndex=0 CriticalSection=0x009e4068 ...} LockCount=0 RecursionCount=1 ...} ...} LockCount=0 RecursionCount=1 ...} 
_RTL_CRITICAL_SECTION
+   unblock {func=0x00000000 arg=0x00000000 }       rb_unblock_callback
    locking_mutex   0       unsigned long
    keeping_mutexes 0       unsigned long
+   tag     0x0012d32c {buf=0x0012d32c tag=0 retval=1 ...}  rb_vm_tag *
+   trap_tag        0x00000000 {prev=??? }  rb_vm_trap_tag *
    parse_in_eval   0       int
+   local_storage   0x00000000 {type=??? num_bins=??? entries_packed=??? ...}       st_table *
+   join_list_next  0x00000000 {self=??? vm=??? stack=??? ...}      rb_thread_struct *
+   join_list_head  0x00000000 {self=??? vm=??? stack=??? ...}      rb_thread_struct *
    first_proc      0       unsigned long
    first_args      0       unsigned long
    first_func      0x00000000      unsigned long (void)*
+   machine_stack_start     0x0012fffc      unsigned long *
+   machine_stack_end       0x0012d2ac      unsigned long *
    machine_stack_maxsize   838861  unsigned int
+   machine_regs    0x009e40c0      int [16]
    mark_stack_len  0       int
    stat_insn_usage 0       unsigned long
+   event_hooks     0x00000000 {flag=??? func=??? data=??? ...}     rb_event_hook_struct *
    event_flags     0       unsigned int
    tracing 0       int
    fiber   0       unsigned long
    root_fiber      0       unsigned long
+   root_jmpbuf     0x009e411c      int [16]
    method_missing_reason   0       int
    abort_on_exception      0       int


. . . I fixed up the stack, and let the program continue.  It appeared to exit
cleanly, however the "test_thread.rb ...." did not continue, so I hit ^C.

The tests completed with:

#822 test_thread.rb:
FAIL 1/861 tests failed


I ran `nmake test` again, but it did not crash this time.

I will try a few more times to see if it might happen again.

Hope this helps... Please let me know if there's any additional information
I should provide if it happens again.


Regards,

Bill