http://bugs.winehq.org/show_bug.cgi?id=12948
--- Comment #8 from Martym martym.de.lagos@gmail.com 2008-07-27 23:41:12 --- Odd since I have been using it for quite some time in Wine without any issues. I am using the same exact install file I downloaded when zMud 7.21 came out and yet today it does not work.
It did work in v9.6 of Wine and once, around v 1.0 for a couple minutes, that is, I updated and launched the app and it worked, once I realised that all my settings were not in place I exited out, moved the folder over, restarted and got the same old message again.
The things that have changed are my kernel and Wine. Zmud has not so how can it be the application when it is the only constant in the equation?
M
(In reply to comment #7)
Hello,
I found the problem ... prepare for journey into debuggers and race conditions ;-) In short: it's a bug in the software protection code which the application is bundled with - not fixable in Wine.
Prerequisite:
- enable wineserver tracing which slows it down sufficiently to observe and log
the behaviour
- "pre-start" wineserver with a console program (cmd.exe) just to let it sit
and wait
Following are relevant process/thread ids to follow snippets:
--- snip --- process tid prio (all id:s are in hex) .. 00000017 0000001b 2 'Zmud.exe' (father, acting as debugger) 00000018 1 'Zmud.exe' (father, acting as debugger) 00000019 0000001a 1 'Zmud.exe' (child, debuggee) .. --- snip ---
The father - which will act as debugger later - creates the child process. The child is created as "suspended" (hence the CREATE_SUSPENDED flags):
--- snip --- 0018: new_process( inherit_all=1, create_flags=00000004, socket_fd=16, exe_file=0x44, hstdin=0x4, hstdout=0x8, hstderr=0xc, process_access=001f0fff, process_attr=00000000, thread_access=001f03ff, thread_attr=00000000, info={AllocationSize=1000,Size=5e4,Flags=0,DebugFlags=0,ConsoleHandle=(nil),ConsoleFlags=0,hStdInput=0x4,hStdOutput=0x8,hStdError=0xc,CurrentDirectory.Handle=(nil),dwX=0,dwY=0,dwXSize=0,dwYSize=0,dwXCountChars=0,dwYCountChars=0,dwFillAttribute=0,dwFlags=0,wShowWindow=1,CurrentDirectory.DosPath=L"C:\Program Files\zMUD\",DllPath=L"C:\Program Files\zMUD;.;C:\windows\system32;C:\windows\system;C:\windows;C:\windows\system32;C:\windows",ImagePathName=L"C:\Program Files\zMUD\Zmud.exe",CommandLine=L"./Zmud.exe",WindowTitle=L"",Desktop=L"",ShellInfo=L"",RuntimeInfo=L""}, ... 0018: new_process() = 0 { info=0x48, pid=0019, phandle=0x4c, tid=001a, thandle=0x50 } --- snip ---
The main thread of the child gets created and process init is done:
--- snip --- 001a: init_thread( unix_pid=17405, unix_tid=17405, debug_level=0, teb=0x7ffd8000, peb=0x7ffdf000, entry=(nil), ldt_copy=0x601239e0, reply_fd=5, wait_fd=7 ) 001a: init_thread() = 0 { pid=0019, tid=001a, info_size=7598, server_start=1c8efe01f98c966 (-3.6957770), version=341 } ... 001a: init_process_done( module=0x400000, entry=0x94ef73, gui=1 ) 0018: *wakeup* signaled=0 cookie=0x16dd154 001a: *sent signal* signal=10 001a: init_process_done() = 0 --- snip ---
After the create process call returns, the father rewrites entry point in the child with an 0xEB, 0xFE opcode sequence which is basically a jump to itself. Remember: PE entry point is not executed yet due to suspended creation. This opcode sequence will let the child enter an endless loop when the main thread of the child process is resumed and the location is hit.
--- snip --- 0018: get_new_process_info( info=0x48 ) 0018: get_new_process_info() = 0 { success=1, exit_code=259 } .. 0018: read_process_memory( handle=0x4c, addr=0x94ef73 ) .. 0018: write_process_memory( handle=0x4c, addr=0x94ef73, data={eb,fe} ) .. 0018: resume_thread( handle=0x50 ) 0018: resume_thread() = 0 { count=1 } --- snip ---
The father continuously suspends child's main thread, fetching thread context and resumes it again until the EIP of rewritten code is reached:
--- snip --- 0018: suspend_thread( handle=0x50 ) 001a: *sent signal* signal=10 0018: suspend_thread() = 0 { count=0 } 0018: get_thread_context( handle=0x50, flags=00010001, suspend=0 ) 0018: get_thread_context() = PENDING { self=0, context={} } 001a: set_thread_context( .. 001a: set_thread_context() = 0 { self=1 } 0018: suspend_thread( handle=0x50 ) 0018: suspend_thread() = 0 { count=1 } 0018: get_thread_context( handle=0x50, flags=00010001, suspend=0 ) 0018: get_thread_context() = 0 { ... } 001a: select( flags=4, cookie=0x7ffdb7b4, signal=(nil), prev_apc=(nil), timeout=0, result={}, handles={} ) 001a: select() = PENDING { apc_handle=(nil), timeout=1c8efe0224574ac (+0.0000000), call={APC_NONE} } 0018: resume_thread( handle=0x50 ) 0018: resume_thread() = 0 { count=2 } 0018: resume_thread( handle=0x50 ) 001a: *wakeup* signaled=258 cookie=0x7ffdb7b4 0018: resume_thread() = 0 { count=1 } .. --- snip ---
When the child entered the endless loop, the father will attach to the child process to receive debug events. From now on, the father acts as debugger.
--- snip --- 0018: debug_process( pid=0019, attach=1 ) 001a: *signal* signal=19 0018: debug_process() = 0 --- snip ---
Next, the father restores the overwritten sequence with original code and resumes the child:
--- snip --- 001a: get_thread_context( handle=0xfffffffe, flags=00010007, suspend=1 ) 001a: get_thread_context() = 0 { self=1, context= .. 0018: suspend_thread( handle=0x50 ) 0018: suspend_thread() = 0 { count=0 } 0018: write_process_memory( handle=0x4c, addr=0x94ef73, data={55,8b} ) 001a: *signal* signal=19 0018: write_process_memory() = 0 0018: new_thread( access=001f03ff, attributes=00000000, suspend=1, request_fd=14 ) 0018: *fd* 14 <- 71 0018: new_thread() = 0 { tid=001b, handle=0x5c } ... 0018: resume_thread( handle=0x5c ) 001b: *wakeup* signaled=258 cookie=0x7ffd77b4 0018: resume_thread() = 0 { count=1 } --- snip ---
The child begins to execute entry code, this is the problematic section (explanation later):
--- snip --- 001a: open_mutex( access=001f0001, attributes=00000000, rootdir=0x24, name=L"19::DA0D2092E0" ) 001a: open_mutex() = OBJECT_NAME_NOT_FOUND { handle=(nil) } 001a: open_mutex( access=001f0001, attributes=00000000, rootdir=0x24, name=L"19::DA0D2092E0" ) 001a: open_mutex() = OBJECT_NAME_NOT_FOUND { handle=(nil) } 001a: set_thread_info( handle=0xfffffffe, mask=1, priority=1, affinity=00000000, token=(nil) ) 001a: set_thread_info() = 0 001a: create_mutex( access=001f0001, attributes=00000080, owned=0, objattr={rootdir=0x24,sd={},name=L"19:DAF"} ) 001a: create_mutex() = 0 { handle=0x40 } --- snip ---
The father enters its debugger loop and receives first debug events:
--- snip --- 0018: get_process_info( handle=0x4c ) 0018: get_process_info() = 0 { pid=0019, ppid=0017, exit_code=259, priority=2, affinity=ffffffff, peb=0x7ffdf000, start_time=1c8efe021cc4f50 (-0.8118270), end_time=0 } 0018: wait_debug_event( get_handle=1 ) 0018: wait_debug_event() = 0 { pid=0019, tid=001a, wait=(nil), event={create_process,file=0x54,process=0x44,thread=0x48,base=0x400000,offset=0,size=0,teb=0x7ffd8000,start=(nil),name=0x110618,unicode=1} } --- snip ---
After receiving the "create process" event, the father creates some mutexes (the child will look for it):
--- snip --- 0018: create_mutex( access=001f0001, attributes=00000080, owned=0, objattr={rootdir=0x14,sd={},name=L"19::DA0D2092E0"} ) 0018: create_mutex() = 0 { handle=0x64 } 0018: resume_thread( handle=0x50 ) 0018: resume_thread() = 0 { count=1 } 0018: create_mutex( access=001f0001, attributes=00000080, owned=0, objattr={rootdir=0x14,sd={},name=L"DILLOCREATE"} ) 0018: create_mutex() = 0 { handle=0x68 } 0018: close_handle( handle=0x68 ) 0018: close_handle() = 0 0018: create_mutex( access=001f0001, attributes=00000080, owned=0, objattr={rootdir=0x14,sd={},name=L"DILLOOEP"} ) 0018: create_mutex() = 0 { handle=0x68 } --- snip ---
Some time later in child process code:
--- snip --- 001a: open_mutex( access=001f0001, attributes=00000000, rootdir=0x24, name=L"19:DAF" ) 001a: open_mutex() = 0 { handle=0x74 } .. 001a: set_window_text( handle=0x10028, text=L"Error!" ) 001a: set_window_text() = 0 --- snip ---
Well, what happens? The mutexes are the critical point, they serve to synchronize father and child startup phases.
Unfortunately there is a race condition which allows the child to create a mutex which it is not allowed to (due to absence of certain father-created mutexes) which leads to this error.
Remember the point when the father attached to the child and restores the original entry point code? As soon as the father resumes the execution of the child's main thread, the child begins to execute further. At the same time the father enters it's main debugging loop, waiting to receive first debug events. This is actually the race: the "process creation" event might be a bit too late when the child already executed some chunk of code.
The problem can be prevented by not resuming child's main thread before entering debugger event loop/creating mutexes. Another solution whould be to guard the page at restored opcode location to let any execution immediately cause page guard exception which would ideally suspend the child thread again (like the protector does for the rest of code to decrypt/encrypt code pages on the fly). When the debugger loop is entered it would receive process creation and page guard exception event serialized and coulde handle it appropriately.
Regards