[Bug 21562] New: Multiple init/deinit of msvcrt (std fd's) causes pluto app installer to hang

wine-bugs at winehq.org wine-bugs at winehq.org
Sun Jan 31 10:58:04 CST 2010 

http://bugs.winehq.org/show_bug.cgi?id=21562

           Summary: Multiple init/deinit of msvcrt (std fd's) causes pluto
                    app installer to hang
           Product: Wine
           Version: 1.1.37
          Platform: x86
               URL: http://pluto.brain-killer.org/download/pluto_FE_w32_en
                    _0036.exe
        OS/Version: Linux
            Status: UNCONFIRMED
          Severity: normal
          Priority: P2
         Component: msvcrt
        AssignedTo: wine-bugs at winehq.org
        ReportedBy: focht at gmx.net


Hello,

an interesting one...

WINEDEBUG=+tid,+seh,+loaddll,+msvcrt,+server,+relay wine
./pluto_FE_w32_en_0036.exe >>log.txt 2>&1

The app installer creates an additional worker (unpack) thread from its main
thread:

--- snip ---
0009:Call
KERNEL32.CreateThread(00000000,00000000,0042b674,00000000,00000000,00436718)
ret=0042c3e8
0009: *fd* 6 <- 22
0009: new_thread( access=001f03ff, attributes=00000000, suspend=1, request_fd=6
)
0009: new_thread() = 0 { tid=001b, handle=0004 } 
...
001b:Starting thread proc 0x42b674 (arg=(nil)) 
...
0009:Ret  KERNEL32.CreateThread() retval=00000004 ret=0042c3e8
--- snip ---

The app installer main thread contains a loop to check if the (unpack) worker
thread (handle = 0x4) is still alive.
While doing so, it pumps messages and delays the next check, illustrated by
following code snippet:

--- snip ---
0009:Ret  KERNEL32.Sleep() retval=00000000 ret=004167e4
0009:Call KERNEL32.GetExitCodeThread(00000004,0032fd9c) ret=0042c40f
0009: get_thread_info( handle=0004, tid_in=0000 )
0009: get_thread_info() = 0 { pid=0008, tid=001b, teb=7ffd4000,
affinity=ffffffffffffffff, creation_time=1caa28d3911cf76 (-0.0285120),
exit_time=0, exit_code=259, priority=0, last=0 }
0009:Ret  KERNEL32.GetExitCodeThread() retval=00000001 ret=0042c40f
0009:Call user32.PeekMessageA(0032fd0c,00000000,00000000,00000000,00000001)
ret=004167d9
...
0009:Ret  user32.PeekMessageA() retval=00000000 ret=004167d9
0009:Call KERNEL32.Sleep(00000001) ret=004167e4 
--- snip ---

Unfortunately something goes wrong and the app installer refuses to terminate -
because the worker checking loop suddenly became a forever loop:

--- snip ---
...
0009:Call KERNEL32.Sleep(00000001) ret=004167e4
0009:Ret  KERNEL32.Sleep() retval=00000000 ret=004167e4
0009:Call KERNEL32.GetExitCodeThread(00000004,0032fd9c) ret=0042c40f
0009: get_thread_info( handle=0004, tid_in=0000 )
0009: get_thread_info() = INVALID_HANDLE { pid=0000, tid=0000, teb=00000000,
affinity=00000000, creation_time=0, exit_time=0, exit_code=0, priority=0,
last=0 }
0009:Ret  KERNEL32.GetExitCodeThread() retval=00000000 ret=0042c40f
0009:Call user32.PeekMessageA(0032fd0c,00000000,00000000,00000000,00000001)
ret=004167d9
0009: get_message( flags=00000001, get_win=00000000, get_first=00000000,
get_last=ffffffff, hw_id=00000000, wake_mask=00000000, changed_mask=00000000 )
0009: get_message() = PENDING { win=00000000, msg=00000000, wparam=00000000,
lparam=00000000, type=0, time=00000000, active_hooks=80000000, total=0, data={}
}
...
0009:Ret  user32.PeekMessageA() retval=00000000 ret=004167d9 
--- snip ---

The installer code doesn't evaluate the return code of GetExitCodeThread() but
instead accesses the exit code variable directly, comparing it to 0x103 ->
STILL_ACTIVE.
Because the thread once lived in this state, this variable is never touched by
Wine in case the thread handle becomes invalid.
GetExitCodeThread() fails but the variable still contains the last known "good"
value -> STILL_ACTIVE (the app doesn't reinit it).

The app still thinks the worker is alive and goes into forever loop.

Now the culprit: the thread handle, delivered to caller upon returning from
CreateThread() is _never_ closed by app explicitly -> CloseHandle() so
GetExitCodeThread() should be successful in any case.

We have to go back in time to unearth the problem ... lets look what happens to
this thread handle (0x4).

--- snip ---
...
001b:Call KERNEL32.FreeLibrary(10000000) ret=004242bb
001b:Call PE DLL (proc=0x10001148,module=0x10000000
L"unpack.dll",reason=PROCESS_DETACH,res=(nil))
001b:Ret  PE DLL (proc=0x10001148,module=0x10000000
L"unpack.dll",reason=PROCESS_DETACH,res=(nil)) retval=1
001b:Call PE DLL (proc=0x5de0cc9c,module=0x5de00000
L"crtdll.dll",reason=PROCESS_DETACH,res=(nil))
001b:Ret  PE DLL (proc=0x5de0cc9c,module=0x5de00000
L"crtdll.dll",reason=PROCESS_DETACH,res=(nil)) retval=1
001b:Call PE DLL (proc=0x5c7cd8b4,module=0x5c790000
L"msvcrt.dll",reason=PROCESS_DETACH,res=(nil))
...
001b:trace:msvcrt:DllMain (0x5c790000, DLL_PROCESS_DETACH, (nil)) pid(8),
tid(1b), tls(4)
001b:trace:msvcrt:msvcrt_free_mt_locks : uninitializing all mtlocks 
...
001b:trace:msvcrt:MSVCRT__close :fd (3) handle (0xfffffff6)
001b:Call KERNEL32.CloseHandle(fffffff6) ret=5c7ad9fc
001b: close_handle( handle=0004 )
001b: close_handle() = 0
001b:Ret  KERNEL32.CloseHandle() retval=00000001 ret=5c7ad9fc
001b:trace:msvcrt:msvcrt_free_fd :fd (3) freed
001b:trace:msvcrt:MSVCRT__close :ok
...
001b:trace:msvcrt:MSVCRT__close :fd (4) handle (0xfffffff5)
001b:Call KERNEL32.CloseHandle(fffffff5) ret=5c7ad9fc
001b: close_handle( handle=0008 )
001b: close_handle() = 0
001b:Ret  KERNEL32.CloseHandle() retval=00000001 ret=5c7ad9fc
001b:trace:msvcrt:msvcrt_free_fd :fd (4) freed
001b:trace:msvcrt:MSVCRT__close :ok
...
001b:trace:msvcrt:MSVCRT__close :fd (5) handle (0xfffffff4)
001b:Call KERNEL32.CloseHandle(fffffff4) ret=5c7ad9fc
001b: close_handle( handle=000c )
001b: close_handle() = 0
001b:Ret  KERNEL32.CloseHandle() retval=00000001 ret=5c7ad9fc
001b:trace:msvcrt:msvcrt_free_fd :fd (5) freed
001b:trace:msvcrt:MSVCRT__close :ok
001b:trace:msvcrt:MSVCRT__fcloseall :closed (3) handles
...
001b:trace:msvcrt:MSVCRT__close :fd (0) handle (0x8)
001b:Call KERNEL32.CloseHandle(00000008) ret=5c7ad9fc
001b: close_handle( handle=0008 )
001b: close_handle() = INVALID_HANDLE
001b:Ret  KERNEL32.CloseHandle() retval=00000000 ret=5c7ad9fc
...
001b:warn:msvcrt:MSVCRT__close :failed-last error (6)
...
001b:trace:msvcrt:MSVCRT__close :ok
...
001b:trace:msvcrt:MSVCRT__close :fd (1) handle (0xc)
001b:Call KERNEL32.CloseHandle(0000000c) ret=5c7ad9fc
001b: close_handle( handle=000c )
001b: close_handle() = INVALID_HANDLE
001b:Ret  KERNEL32.CloseHandle() retval=00000000 ret=5c7ad9fc
...
001b:warn:msvcrt:MSVCRT__close :failed-last error (6)
...
001b:trace:msvcrt:MSVCRT__close :ok
...
001b:trace:msvcrt:MSVCRT__close :fd (2) handle (0x50)
001b:Call KERNEL32.CloseHandle(00000050) ret=5c7ad9fc
001b: close_handle( handle=0050 )
001b: close_handle() = 0
001b:Ret  KERNEL32.CloseHandle() retval=00000001 ret=5c7ad9fc
001b:trace:msvcrt:msvcrt_free_fd :fd (2) freed
001b:Call KERNEL32.GetStdHandle(fffffff4) ret=5c7ac729
001b:Ret  KERNEL32.GetStdHandle() retval=0000000c ret=5c7ac729
001b:trace:msvcrt:MSVCRT__close :ok
...
001b:trace:msvcrt:msvcrt_free_console :Closing console handles 
--- snip ---

*eek* ... the thread handle gets closed as part of msvcrt cleanup!

PROCESS_DETACH -> msvcrt_free_io() -> MSVCRT__fcloseall()

This will close fd(3), fd(4), fd(5) -> stdin,stdout,stderr

Corresponding msvcrt init:

--- snip ---
...
001b:Call PE DLL (proc=0x5c7cd8b4,module=0x5c790000
L"msvcrt.dll",reason=PROCESS_ATTACH,res=(nil))
...
001b:trace:msvcrt:DllMain (0x5c790000, DLL_PROCESS_ATTACH, (nil)) pid(8),
tid(1b), tls(0)
...
001b:Call KERNEL32.GetStartupInfoA(0096e4b8) ret=5c7acdd6
001b:Ret  KERNEL32.GetStartupInfoA() retval=00000011 ret=5c7acdd6
001b:Call KERNEL32.GetStdHandle(fffffff6) ret=5c7acf77
001b:Ret  KERNEL32.GetStdHandle() retval=00000004 ret=5c7acf77
001b:Call
KERNEL32.DuplicateHandle(ffffffff,00000004,ffffffff,5c7db2e0,00000000,00000001,00000002)
ret=5c7acfc0
001b: dup_handle( src_process=ffffffff, src_handle=0004, dst_process=ffffffff,
access=00000000, attributes=00000002, options=00000002 )
001b: dup_handle() = 0 { handle=0008, self=1, closed=0 }
001b:Ret  KERNEL32.DuplicateHandle() retval=00000001 ret=5c7acfc0
001b:Call KERNEL32.GetStdHandle(fffffff5) ret=5c7acff6
001b:Ret  KERNEL32.GetStdHandle() retval=00000008 ret=5c7acff6
001b:Call
KERNEL32.DuplicateHandle(ffffffff,00000008,ffffffff,5c7db304,00000000,00000001,00000002)
ret=5c7ad03f
001b: dup_handle( src_process=ffffffff, src_handle=0008, dst_process=ffffffff,
access=00000000, attributes=00000002, options=00000002 )
001b: dup_handle() = 0 { handle=000c, self=1, closed=0 }
001b:Ret  KERNEL32.DuplicateHandle() retval=00000001 ret=5c7ad03f
001b:Call KERNEL32.GetStdHandle(fffffff4) ret=5c7ad075
001b:Ret  KERNEL32.GetStdHandle() retval=0000000c ret=5c7ad075
001b:Call
KERNEL32.DuplicateHandle(ffffffff,0000000c,ffffffff,5c7db328,00000000,00000001,00000002)
ret=5c7ad0be
001b: dup_handle( src_process=ffffffff, src_handle=000c, dst_process=ffffffff,
access=00000000, attributes=00000002, options=00000002 )
001b: dup_handle() = 0 { handle=0050, self=1, closed=0 }
001b:Ret  KERNEL32.DuplicateHandle() retval=00000001 ret=5c7ad0be
001b:trace:msvcrt:msvcrt_init_io :handles (0x8)(0xc)(0x50)
--- snip ---

The culprit: msvcrt is actually loaded and unloaded _two_ times!

Upon the first unload sequence all std/fd handles are teared down (including
handle 0x4) - this makes the handle values available in server again.

When the worker thread is created it gets the unused handle 0x4 assigned from
wineserver.
This is the handle which is then polled by installers GetExitCodeThread() loop.

When msvcrt is loaded a second time, GetStdHandle( STD_XXX) will still deliver
its original value from PEB (0x4, 0x8, 0xC).
Upon second msvcrt unload, fd(3), fd(4), fd(5) are closed again but this time
they close something completely different (indication are also fd close errors
following), leaving the app installer in forever loop.

Regards

-- 
Configure bugmail: http://bugs.winehq.org/userprefs.cgi?tab=email
Do not reply to this email, post in Bugzilla using the
above URL to reply.
------- You are receiving this mail because: -------
You are watching all bug changes.

More information about the wine-bugs mailing list