[Bug 33125] Tomb Raider (2013) freezes (bug in game engine, semaphore object handle value must be zero on all error paths)
wine-bugs at winehq.org
wine-bugs at winehq.org
Mon Jul 7 19:00:50 CDT 2014
http://bugs.winehq.org/show_bug.cgi?id=33125
Anastasius Focht <focht at 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 at 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/0e1b381503751294c6e6925b9ba1eeb0aa770179:/dlls/kernel32/sync.c#l777
--- 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
--
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