http://bugs.winehq.org/show_bug.cgi?id=33125
Anastasius Focht focht@gmx.net changed:
What |Removed |Added ---------------------------------------------------------------------------- URL| |http://store.steampowered.c | |om/app/203160/ Summary|Tomb Raider (2013) game |Tomb Raider (2013) freezes |freezes |(bug in game engine, | |semaphore object handle | |value must be zero on all | |error paths)
--- Comment #110 from Anastasius Focht focht@gmx.net --- Hello folks,
I could reproduce the problem.
It's actually buggy code in the game engine that just works by chance.
I looked at the disassembly from different gcc optimization levels and could not really spot a problem. There is some questionable (redundant) code in the function prolog at O1+ but still no overly optimized code that breaks something.
Running with +relay avoided the freeze so stack layout/values certainly had an impact.
A +server trace along with +msvcrt (msvcrt = good search patterns to correlate with working a +relay trace):
--- snip --- ... 0063: create_semaphore( access=001f0003, attributes=00000080, initial=00000000, max=7fffffff, objattr={rootdir=0000,sd={},name=L""} ) 0063: create_semaphore() = 0 { handle=011c } ... 0063: create_semaphore( access=001f0003, attributes=00000080, initial=00000000, max=7fffffff, objattr={rootdir=0000,sd={},name=L""} ) 0063: create_semaphore() = 0 { handle=0120 } ... 0063: create_event( access=001f0003, attributes=00000000, manual_reset=0, initial_state=0, objattr={rootdir=0000,sd={},name=L""} ) 0063: create_event() = 0 { handle=0208 } 0063: create_event( access=001f0003, attributes=00000000, manual_reset=0, initial_state=0, objattr={rootdir=0000,sd={},name=L""} ) 0063: create_event() = 0 { handle=020c } 0063:trace:msvcrt:pf_printf_a Format is: "%s%s.drm" ... 0063:trace:msvcrt:MSVCRT_strncpy_s (0x33ece4 2000 "InitializePanel: 0" 18) 0063:trace:msvcrt:MSVCRT_strncpy_s (0x33eae4 2000 "ShowPanel(0)" 12) 0063:trace:msvcrt:MSVCRT_strncpy_s (0x33eae4 2000 "Prev ID 0" 9) 0063:trace:msvcrt:MSVCRT_strncpy_s (0x33ece4 2000 "this[nav_list_item_8_mc].GetState() 2" 37) ... 0063: release_semaphore() = 0 { prev_count=00000000 } 0063: release_semaphore( handle=011c, count=00000001 ) 0063: release_semaphore() = 0 { prev_count=00000000 } 0066: release_semaphore( handle=0208, count=00000001 ) 0066: release_semaphore() = OBJECT_TYPE_MISMATCH { prev_count=00000000 } 0063: release_semaphore( handle=011c, count=00000001 ) 0063: release_semaphore() = 0 { prev_count=00000001 } 0066: select( flags=2, cookie=053fe4dc, timeout=infinite, prev_apc=0000, result={}, data={WAIT,handles={011c,0120}} ) 0066: select() = 0 { timeout=infinite, call={APC_NONE}, apc_handle=0000 } 0063: select( flags=2, cookie=0033f09c, timeout=infinite, prev_apc=0000, result={}, data={WAIT,handles={0208}} ) 0063: select() = PENDING { timeout=infinite, call={APC_NONE}, apc_handle=0000 } 0066: release_semaphore( handle=0208, count=00000001 ) 0066: release_semaphore() = OBJECT_TYPE_MISMATCH { prev_count=00000000 } 0066: select( flags=2, cookie=053fe4dc, timeout=infinite, prev_apc=0000, result={}, data={WAIT,handles={011c,0120}} ) 0066: select() = 0 { timeout=infinite, call={APC_NONE}, apc_handle=0000 } 0066: release_semaphore( handle=0208, count=00000001 ) 0066: release_semaphore() = OBJECT_TYPE_MISMATCH { prev_count=00000000 } 0066: event_op( handle=0208, op=1 ) 0063: *wakeup* signaled=0 0066: event_op() = 0 0063: select( flags=2, cookie=0033f09c, timeout=infinite, prev_apc=0000, result={}, data={WAIT,handles={0208}} ) 0063: select() = PENDING { timeout=infinite, call={APC_NONE}, apc_handle=0000 } 0066: select( flags=2, cookie=053fe4dc, timeout=infinite, prev_apc=0000, result={}, data={WAIT,handles={011c,0120}} ) 0066: select() = PENDING { timeout=infinite, call={APC_NONE}, apc_handle=0000 } ... <threads 00063 and 0066 wait blocked> --- snip ---
The 'OBJECT_TYPE_MISMATCH' error catched my attention. Object/handle 0x208 was certainly valid but not a semaphore.
That value was leaked through earlier call(s) which incidentally mapped to a valid handle (event object). Because the event was waitable but not signaled, the thread assumed it waited on a counted semaphore got blocked forever.
An unoptimized build of Wine gave this trace:
--- snip --- ... 0062: create_semaphore( access=001f0003, attributes=00000080, initial=00000000, max=7fffffff, objattr={rootdir=0000,sd={},name=L""} ) 0062: create_semaphore() = 0 { handle=011c } 0062: create_semaphore( access=001f0003, attributes=00000080, initial=00000000, max=7fffffff, objattr={rootdir=0000,sd={},name=L""} ) 0062: create_semaphore() = 0 { handle=0120 } ... 0062: create_event( access=001f0003, attributes=00000080, manual_reset=0, initial_state=0, objattr={rootdir=0000,sd={},name=L""} ) 0062: create_event() = 0 { handle=0208 } 0062: create_event( access=001f0003, attributes=00000080, manual_reset=0, initial_state=0, objattr={rootdir=0000,sd={},name=L""} ) 0062: create_event() = 0 { handle=020c } 0062:trace:msvcrt:pf_printf_a Format is: "%s%s.drm" ... 0062:trace:msvcrt:MSVCRT_strncpy_s (0x33eca4 2000 "InitializePanel: 0" 18) 0062:trace:msvcrt:MSVCRT_strncpy_s (0x33eaa4 2000 "ShowPanel(0)" 12) 0062:trace:msvcrt:MSVCRT_strncpy_s (0x33eaa4 2000 "Prev ID 0" 9) 0062:trace:msvcrt:MSVCRT_strncpy_s (0x33eca4 2000 "this[nav_list_item_8_mc].GetState() 2" 37) ... 0062: release_semaphore( handle=011c, count=00000001 ) 0065: *wakeup* signaled=0 0062: release_semaphore() = 0 { prev_count=00000000 } ... 0062: release_semaphore( handle=011c, count=00000001 ) 0065: *wakeup* signaled=0 0062: release_semaphore() = 0 { prev_count=00000000 } 0062: release_semaphore( handle=011c, count=00000001 ) 0062: release_semaphore() = 0 { prev_count=00000000 } 0065: release_semaphore( handle=7b8bc000, count=00000001 ) 0065: release_semaphore() = INVALID_HANDLE { prev_count=00000000 } 0062: release_semaphore( handle=011c, count=00000001 ) 0062: release_semaphore() = 0 { prev_count=00000001 } 0065: select( flags=2, cookie=053fe5ec, timeout=infinite, prev_apc=0000, result={}, data={WAIT,handles={011c,0120}} ) 0065: select() = 0 { timeout=infinite, call={APC_NONE}, apc_handle=0000 } 0062: select( flags=2, cookie=0033f15c, timeout=infinite, prev_apc=0000, result={}, data={WAIT,handles={7b8bc000}} ) 0062: select() = INVALID_HANDLE { timeout=infinite, call={APC_NONE}, apc_handle=0000 } 0065: release_semaphore( handle=7b8bc000, count=00000001 ) 0065: release_semaphore() = INVALID_HANDLE { prev_count=00000000 } 0062: select( flags=2, cookie=0033f15c, timeout=infinite, prev_apc=0000, result={}, data={WAIT,handles={7b8bc000}} ) 0062: select() = INVALID_HANDLE { timeout=infinite, call={APC_NONE}, apc_handle=0000 } 0065: select( flags=2, cookie=053fe5ec, timeout=infinite, prev_apc=0000, result={}, data={WAIT,handles={011c,0120}} ) 0065: select() = 0 { timeout=infinite, call={APC_NONE}, apc_handle=0000 } 0062: select( flags=2, cookie=0033f15c, timeout=infinite, prev_apc=0000, result={}, data={WAIT,handles={7b8bc000}} ) 0062: select() = INVALID_HANDLE { timeout=infinite, call={APC_NONE}, apc_handle=0000 } 0065: release_semaphore( handle=7b8bc000, count=00000001 ) 0065: release_semaphore() = INVALID_HANDLE { prev_count=00000000 } 0062: select( flags=2, cookie=0033f15c, timeout=infinite, prev_apc=0000, result={}, data={WAIT,handles={0208}} ) 0062: select() = PENDING { timeout=infinite, call={APC_NONE}, apc_handle=0000 } 0065: event_op( handle=0208, op=1 ) 0062: *wakeup* signaled=0 0065: event_op() = 0 0065: select( flags=2, cookie=053fe5ec, timeout=infinite, prev_apc=0000, result={}, data={WAIT,handles={011c,0120}} ) 0065: select() = PENDING { timeout=infinite, call={APC_NONE}, apc_handle=0000 } 0062: release_semaphore( handle=011c, count=00000001 ) 0065: *wakeup* signaled=0 ... --- snip ---
The handle value now changed to 0x7b8bc000, which works "better" on sync APIs because it immediately fails them, giving 'INVALID_HANDLE'. Mapped base address of kernel32, leaked through local stack area.
With +relay,+server together it become more obvious:
--- snip --- ... 0063:Call KERNEL32.CreateSemaphoreW(00000000,00000000,7fffffff,00000000) ret=005283d1 0063: create_semaphore( access=001f0003, attributes=00000080, initial=00000000, max=7fffffff, objattr={rootdir=0000,sd={},name=L""} ) 0063: create_semaphore() = 0 { handle=011c } 0063:Ret KERNEL32.CreateSemaphoreW() retval=0000011c ret=005283d1 ... 0063:Call KERNEL32.CreateSemaphoreW(00000000,00000000,7fffffff,00000000) ret=005283e0 0063: create_semaphore( access=001f0003, attributes=00000080, initial=00000000, max=7fffffff, objattr={rootdir=0000,sd={},name=L""} ) 0063: create_semaphore() = 0 { handle=0120 } 0063:Ret KERNEL32.CreateSemaphoreW() retval=00000120 ret=005283e0 0063:Call msvcr90._beginthreadex(00000000,00020000,00527fd0,00000000,00000000,00000000) ret=00528406 ... 0063:Call KERNEL32.CreateEventW(00000000,00000000,00000000,00000000) ret=00527298 0063: create_event( access=001f0003, attributes=00000000, manual_reset=0, initial_state=0, objattr={rootdir=0000,sd={},name=L""} ) 0063: create_event() = 0 { handle=0208 } 0063:Ret KERNEL32.CreateEventW() retval=00000208 ret=00527298 ... 0063:Call KERNEL32.CreateSemaphoreW(00000000,00000000,ffffffff,00000000) ret=0064381d 0063:Ret KERNEL32.CreateSemaphoreW() retval=7bcde220 ret=0064381d ... 0063:trace:msvcrt:pf_printf_a Format is: "%s%s.drm" 0063:Call msvcr90._stricmp(00dd3b48 "generalbank",129ee9f9 "ac_bendy_01_medium_shrub") ret=0055b09c 0063:Ret msvcr90._stricmp() retval=00000001 ret=0055b09c ... 0063:trace:msvcrt:MSVCRT_strncpy_s (0x33ece4 2000 "InitializePanel: 0" 18) ... 0063:trace:msvcrt:MSVCRT_strncpy_s (0x33eae4 2000 "ShowPanel(0)" 12) ... 0063:trace:msvcrt:MSVCRT_strncpy_s (0x33eae4 2000 "Prev ID 0" 9) ... 0063:trace:msvcrt:MSVCRT_strncpy_s (0x33ece4 2000 "this[nav_list_item_8_mc].GetState() 2" 37) ... --- snip ---
'TombRaider.exe' disassembly, the culprit:
--- snip --- 00643804 33C0 XOR EAX,EAX 00643806 53 PUSH EBX ; lpName = NULL 00643807 6A FF PUSH -1 ; lMaximumCount = 0xffffffff (!) 00643809 53 PUSH EBX ; lInitialCount = 0 0064380A 53 PUSH EBX ; lpSemaphoreAttributes = NULL 0064380B 8946 08 MOV DWORD PTR DS:[ESI+8],EAX 0064380E 895E 0C MOV DWORD PTR DS:[ESI+C],EBX 00643811 895E 10 MOV DWORD PTR DS:[ESI+10],EBX 00643814 895E 14 MOV DWORD PTR DS:[ESI+14],EBX 00643817 FF15 FC70D800 CALL DWORD PTR DS:[<&KERNEL32.CreateSemaphoreW>] 0064381D 8906 MOV DWORD PTR DS:[ESI],EAX 0064381F 8BC6 MOV EAX,ESI 00643821 5E POP ESI 00643822 5B POP EBX 00643823 C2 0400 RETN 4 --- snip ---
'lMaximumCount' < 0 (LONG) can't obviously work.
The code here (including caller) doesn't check the returned handle value and stores it right away for later use.
Wine doesn't initialize the local variable that ought to carry the return value, which is passed as 'out' parameter to NtXXX API. Depending on the stack layout/optimizations, different stack values get leaked as handle values.
Source: http://source.winehq.org/git/wine.git/blob/0e1b381503751294c6e6925b9ba1eeb0a...
--- snip --- 777 HANDLE WINAPI DECLSPEC_HOTPATCH CreateSemaphoreExW( SECURITY_ATTRIBUTES *sa, LONG initial, LONG max, 778 LPCWSTR name, DWORD flags, DWORD access ) 779 { 780 HANDLE ret; 781 UNICODE_STRING nameW; 782 OBJECT_ATTRIBUTES attr; 783 NTSTATUS status; ... 798 status = NtCreateSemaphore( &ret, access, &attr, initial, max ); 799 if (status == STATUS_OBJECT_NAME_EXISTS) 800 SetLastError( ERROR_ALREADY_EXISTS ); 801 else 802 SetLastError( RtlNtStatusToDosError(status) ); 803 return ret; 804 } --- snip ---
You need to explicitly zero-init 'ret' here or have 'NtCreateSemaphore' zero-init the 'out' handle parameter. With that part fixed, the freeze is gone.
Despite the failure of 'CreateSemaphoreExW' to create a sync object the game works (profile -> main screen cut scene threading synchronization).
Regards