http://bugs.winehq.org/show_bug.cgi?id=32515
--- Comment #10 from Anastasius Focht focht@gmx.net 2013-12-04 10:43:48 CST --- Hello Gyb,
--- quote --- Does it help reduce the size of a +relay log somewhat if I launch for example an instance of notepad in a different terminal (before launching the actual game/application)? --- quote ---
depends on the case.
In most cases it makes sense to bootstrap the prefix ('warmup') using a Wine builtin from separate terminal. This avoids capturing unwanted log messages from builtins (services), prefix updates (menubuilder) and the like.
There are other examples where this won't work hence a full bootstrap must be done with logging from start. For example if Steam is put in 'autorun' mode, e.g. started during prefix boot you will not see debug output because the (already started) launcher parent process which spawns app processes upon request (client) doesn't inherit environment variables such as WINEDEBUG.
Anyway, the log looks good. There are various exceptions (msvc thread name, softbp, single step traps) which are on purpose because they are part of their DRM protection scheme.
There is one interesting thread tid=0x60 which causes 'bugsplat' trigger (seems to be the equivalent of 'breakpad').
$ cat SpaceMarine_relay.log | grep 0060: > 0060.txt
--- snip --- ... 0060:Call advapi32.RegOpenKeyExW(80000002,01541dc0 L"Software\Valve\Steam",00000000,00020019,060de6b4) ret=00e6b736 0060:Ret advapi32.RegOpenKeyExW() retval=00000000 ret=00e6b736 0060:Call advapi32.RegQueryValueExW(000007f0,01541da8 L"InstallPath",00000000,060de6b0,060de6c0,060de6bc) ret=00e6b765 0060:Ret advapi32.RegQueryValueExW() retval=000000ea ret=00e6b765 0060:Call ntdll.RtlAllocateHeap(00110000,00000008,0000023a) ret=00e6b78c 0060:Ret ntdll.RtlAllocateHeap() retval=0668f228 ret=00e6b78c 0060:Call advapi32.RegQueryValueExW(000007f0,01541da8 L"InstallPath",00000000,060de6b0,0668f228,060de6bc) ret=00e6b7ac 0060:Ret advapi32.RegQueryValueExW() retval=00000000 ret=00e6b7ac 0060:Call advapi32.RegCloseKey(000007f0) ret=00e6b7ea 0060:Ret advapi32.RegCloseKey() retval=00000000 ret=00e6b7ea 0060:Call KERNEL32.GetModuleHandleA(0147c064 "kernel32.dll") ret=00e48eee 0060:Ret KERNEL32.GetModuleHandleA() retval=7b810000 ret=00e48eee 0060:Call KERNEL32.GetProcAddress(7b810000,01541d88 "Wow64DisableWow64FsRedirection") ret=00e48f04 0060:Ret KERNEL32.GetProcAddress() retval=7b82597c ret=00e48f04 0060:Call KERNEL32.GetProcAddress(7b810000,01541d68 "Wow64RevertWow64FsRedirection") ret=00e48f10 0060:Ret KERNEL32.GetProcAddress() retval=7b825994 ret=00e48f10 0060:Call KERNEL32.Wow64DisableWow64FsRedirection(060de970) ret=00e48f23 0060:Ret KERNEL32.Wow64DisableWow64FsRedirection() retval=00000000 ret=00e48f23 0060:Call KERNEL32.CreateFileW(0668f228 L"C:\Program Files\Steam\package",80000000,00000007,00000000,00000003,00000000,ffffffff) ret=00e4d09a 0060:Ret KERNEL32.CreateFileW() retval=ffffffff ret=00e4d09a 0060:Call KERNEL32.CreateFileW(0668f228 L"C:\Program Files\Steam\package",80000000,00000007,00000000,00000003,02000000,ffffffff) ret=00e4d0b9 0060:Ret KERNEL32.CreateFileW() retval=000007f0 ret=00e4d0b9 0060:Call KERNEL32.GetFileInformationByHandle(000007f0,060de930) ret=00e4d0e7 0060:Ret KERNEL32.GetFileInformationByHandle() retval=00000001 ret=00e4d0e7 0060:Call msvcrt.memcpy(060de6b8,060de710,00000008) ret=00e6d14a 0060:Ret msvcrt.memcpy() retval=060de6b8 ret=00e6d14a 0060:Call msvcrt.memset(060de6c1,00000000,0000002f) ret=00e6d1b7 0060:Ret msvcrt.memset() retval=060de6c1 ret=00e6d1b7 0060:Call KERNEL32.CloseHandle(000007f0) ret=00e4d103 0060:Ret KERNEL32.CloseHandle() retval=00000001 ret=00e4d103 ... --- snip ---
Pretty much the standard Steam DRM/integrity scheme where local folder/filesystem/volume info (GetFileInformationByHandle -> inode numbers) is used to generate and validate PE images and locally 'bind' them to a machine.
Unfortunately the 'integrity checker' thread dies with unexpected fault shortly after this sequence:
--- snip --- 0060:Call KERNEL32.InterlockedCompareExchange(01b171ec,00000001,00000001) ret=00e57d38 0060:Ret KERNEL32.InterlockedCompareExchange() retval=00000000 ret=00e57d38 0060:Call KERNEL32.InterlockedExchange(01b171ec,00000001) ret=00e57d5e 0060:Ret KERNEL32.InterlockedExchange() retval=00000000 ret=00e57d5e 0060:trace:seh:raise_exception code=c0000005 flags=0 addr=0x9c0047 ip=009c0047 tid=0060 0060:trace:seh:raise_exception info[0]=00000001 0060:trace:seh:raise_exception info[1]=c1ceb97c 0060:trace:seh:raise_exception eax=10561b70 ebx=10566d30 ecx=0000002a edx=00000900 esi=105667f0 edi=2c5e2783 0060:trace:seh:raise_exception ebp=060dea2c esp=060de9e0 cs=0073 ds=007b es=007b fs=0033 gs=003b flags=00010216 0060:trace:seh:call_vectored_handlers calling handler at 0xe550c0 code=c0000005 flags=0 0060:trace:seh:call_vectored_handlers handler at 0xe550c0 returned 0 0060:trace:seh:call_stack_handlers calling handler at 0x121706e code=c0000005 flags=0 0060:trace:seh:call_stack_handlers handler at 0x121706e returned 1 060:trace:seh:call_stack_handlers calling handler at 0xe6f9f4 code=c0000005 flags=0 0060:Call msvcrt._except_handler3(060de988,060dea48,060de6bc,060de60c) ret=7bc7be8d 0060:trace:seh:_except_handler3 exception c0000005 flags=0 at 0x9c0047 handler=0xe6f9f4 0x60de6bc 0x60de60c semi-stub 0060:trace:seh:_except_handler3 level 0 prev -1 filter 0x9b0d6d 0060:trace:seh:_except_handler3 filter returned CONTINUE_SEARCH 0060:trace:seh:_except_handler3 reached TRYLEVEL_END, returning ExceptionContinueSearch 0060:Ret msvcrt._except_handler3() retval=00000001 ret=7bc7be8d 0060:trace:seh:call_stack_handlers handler at 0xe6f9f4 returned 1 0060:trace:seh:call_stack_handlers calling handler at 0x7bc923c0 code=c0000005 flags=0 0060:Call KERNEL32.UnhandledExceptionFilter(060de548) ret=7bc92405 ... 0060:Call KERNEL32.CreateFileA(060de31c "C:\users\gyebro\Temp\bugsplat.log",c0000000,00000000,060de17c,00000004,00000080,00000000) ret=10027825 0060:Ret KERNEL32.CreateFileA() retval=000007f0 ret=10027825 ... 0060:Call KERNEL32.CreateThread(00000000,00000000,1000e191,0246ac80,00000000,060de470) ret=1000e29b 0060:Ret KERNEL32.CreateThread() retval=000007f4 ret=1000e29b 0060:Call KERNEL32.WaitForSingleObject(000007f4,00007530) ret=10005fad 0060:Ret KERNEL32.WaitForSingleObject() retval=00000000 ret=10005fad 0060:Call KERNEL32.TerminateProcess(ffffffff,fffffffd) ret=10005fd1 0060:Call PE DLL (proc=0xb4d6c080,module=0xb4d60000 L"imm32.dll",reason=PROCESS_DETACH,res=(nil)) 0060:Call KERNEL32.TlsFree(0000000b) ret=b4d69fa2 0060:Ret KERNEL32.TlsFree() retval=00000001 ret=b4d69fa2 0060:Call user32.UnregisterClassW(b4d6d48c L"IME",00000000) ret=b4d69fbb 0060:Call winex11.drv.CreateDesktopWindow(00010020) ret=7ec91cfc 0060:Ret winex11.drv.CreateDesktopWindow() retval=00000001 ret=7ec91cfc 0060:err:ntdll:RtlpWaitForCriticalSection section 0x110060 "heap.c: main process heap section" wait timed out in thread 0060, blocked by 0063, retrying (60 sec) --- snip ---
The critsec timeout/borked shutdown sequence is definitely another issue to be looked at.
The reason for the fault isn't obvious to me. Can you try to validate the local files? It's called "verify integrity of game cache" in game properties/settings.
If anything fails, it will be re-downloaded. Additionally this forces some PE binaries to be re-signed/updated with actual filesystem metadata. Make sure the game install is 100% valid before launching the game (try to validate multiple times) ... this could be one reason for weird behaviour.
Regards