[Bug 14697] OllyDbg 2.x freezes sometimes during processing of debug events (debug events can block completion of queued user APCs)

Sun Feb 22 15:56:25 CST 2015

https://bugs.winehq.org/show_bug.cgi?id=14697

--- Comment #8 from Anastasius Focht <focht at gmx.net> ---
Hello folks,

still present.

I found another manifestation of the design problem with some native API
implemented using APC, now with only a main thread present in debuggee.

Debugger = 32-bit variant of x64_dbg

tid 0x09 = debugger main thread (gui) 
tid 0x25 = debugger thread (script thread)
tid 0x28 = debugger thread (debugger event loop, partially blocking, partially
live looping with Sleep)

tid 0x27 = debuggee main thread

Single stepping in debuggee:

--- snip ---
0027: queue_exception_event( first=1, code=80000004, flags=00000000,
record=00000000, address=7bc80526, len=0, params={},
context={cpu=x86,eip=7bc80526,esp=0033dca0,ebp=0033dda8,eflags=00200246,cs=0023,ss=002b,ds=002b,es=002b,fs=0063,gs=006b,eax=000000c0,ebx=7bcd3000,ecx=0033dc78,edx=00000000,esi=0033e674,edi=00000000,dr0=00000000,dr1=00000000,dr2=00000000,dr3=00000000,dr6=00004000,dr7=00000000,...}}
)
...
0027: queue_exception_event() = 0 { handle=0070 }
...
0027: select( flags=2, cookie=0033d07c, timeout=infinite, prev_apc=0000,
result={}, data={WAIT,handles={0070}} )
0027: select() = PENDING { timeout=infinite, call={APC_NONE}, apc_handle=0000 }
0028:Ret  KERNEL32.ContinueDebugEvent() retval=00000001 ret=0093ed78
0028:Call KERNEL32.WaitForDebugEvent(0099c6d0,ffffffff) ret=0093cb5f
0028: wait_debug_event( get_handle=1 )
0028: wait_debug_event() = 0 { pid=0026, tid=0027, wait=0000,
event={exception,first=1,exc_code=80000004,flags=00000000,record=00000000,address=7bc80526,params={}}
}
0028:Ret  KERNEL32.WaitForDebugEvent() retval=00000001 ret=0093cb5f
...
--- snip ---

Setting softbp in debuggee using GUI (internally using scripting engine).

PAGE_EXECUTE_READWRITE to prepare for patching opcodes which causes execution
of APC.

--- snip ---
...
0025:Call
KERNEL32.VirtualProtectEx(00000354,7bc8053a,00000001,00000040,09f0d9a4)
ret=00952892
0025: queue_apc( handle=0354,
call={APC_VIRTUAL_PROTECT,addr=7bc8053a,size=00000001,prot=40} )
0027: *wakeup* signaled=192
0025: queue_apc() = 0 { handle=039c, self=0 }
0025: select( flags=2, cookie=09f0d55c, timeout=infinite, prev_apc=0000,
result={}, data={WAIT_ALL,handles={039c}} )
0025: select() = PENDING { timeout=infinite, call={APC_NONE}, apc_handle=0000 }
0027: select( flags=2, cookie=0033d07c, timeout=infinite, prev_apc=0000,
result={}, data={WAIT,handles={0070}} )
0027: select() = USER_APC { timeout=infinite,
call={APC_VIRTUAL_PROTECT,addr=7bc8053a,size=00000001,prot=40}, apc_handle=0074
}
0027: select( flags=2, cookie=0033d07c, timeout=infinite, prev_apc=0074,
result={APC_VIRTUAL_PROTECT,status=0,addr=7bc80000,size=00001000,prot=20},
data={WAIT,handles={0070}} )
0028:Ret  KERNEL32.Sleep() retval=00000000 ret=007c236c
0025: *wakeup* signaled=0
0028:Call KERNEL32.Sleep(00000001) ret=007c236c
0027: select() = PENDING { timeout=infinite, call={APC_NONE}, apc_handle=0000 }
0025: get_apc_result( handle=039c )
0025: get_apc_result() = 0 {
result={APC_VIRTUAL_PROTECT,status=0,addr=7bc80000,size=00001000,prot=20} }
0025:Ret  KERNEL32.VirtualProtectEx() retval=00000001 ret=00952892 
--- snip ---

Save opcode and write softbp (int 3):

--- snip ---
0025:Call
KERNEL32.ReadProcessMemory(00000354,7bc8053a,09f0d9c1,00000001,09f0d9b0)
ret=009528b3
0025: read_process_memory( handle=0354, addr=7bc8053a )
0027: *signal* signal=19
0025: read_process_memory() = 0 { data={74} }
0025:Ret  KERNEL32.ReadProcessMemory() retval=00000001 ret=009528b3
0025:Call
KERNEL32.WriteProcessMemory(00000354,7bc8053a,009897ea,00000001,09f0d9b0)
ret=009528d8
0025: write_process_memory( handle=0354, addr=7bc8053a, data={cc} )
0027: *signal* signal=19
0025: write_process_memory() = 0
0025:Ret  KERNEL32.WriteProcessMemory() retval=00000001 ret=009528d8 
--- snip ---

Make code PAGE_EXECUTE_READ again (causes queuing of APC):

--- snip ---
0025:Call
KERNEL32.VirtualProtectEx(00000354,7bc8053a,00000001,00000020,09f0d9a4)
ret=00952922
0025: queue_apc( handle=0354,
call={APC_VIRTUAL_PROTECT,addr=7bc8053a,size=00000001,prot=20} )
0027: *wakeup* signaled=192
0025: queue_apc() = 0 { handle=039c, self=0 }
0025: select( flags=2, cookie=09f0d55c, timeout=infinite, prev_apc=0000,
result={}, data={WAIT_ALL,handles={039c}} )
0025: select() = PENDING { timeout=infinite, call={APC_NONE}, apc_handle=0000 }
0027: queue_exception_event( first=1, code=80000003, flags=00000000,
record=00000000, address=7bc8053a, len=0, params={},
context={cpu=x86,eip=7bc8053b,esp=0033cfa0,ebp=0033d0a8,eflags=00200246,cs=0023,ss=002b,ds=002b,es=002b,fs=0063,gs=006b,eax=00000000,ebx=7bcd3000,ecx=00000024,edx=0033d054,esi=0033d974,edi=00000000,dr0=00000000,dr1=00000000,dr2=00000000,dr3=00000000,dr6=00004000,dr7=00000000,...}}
)
0027: queue_exception_event() = 0 { handle=0074 }
0027: select( flags=2, cookie=0033c37c, timeout=infinite, prev_apc=0000,
result={}, data={WAIT,handles={0074}} )
0027: select() = USER_APC { timeout=infinite,
call={APC_VIRTUAL_PROTECT,addr=7bc8053a,size=00000001,prot=20}, apc_handle=0078
}
0027: queue_exception_event( first=1, code=80000003, flags=00000000,
record=00000000, address=7bc8053a, len=0, params={},
context={cpu=x86,eip=7bc8053b,esp=0033c2a0,ebp=0033c3a8,eflags=00200246,cs=0023,ss=002b,ds=002b,es=002b,fs=0063,gs=006b,eax=00000000,ebx=7bcd3000,ecx=0033c32c,edx=00000000,esi=0033cc74,edi=00000000,dr0=00000000,dr1=00000000,dr2=00000000,dr3=00000000,dr6=00004000,dr7=00000000,...
...
0028:Ret  KERNEL32.Sleep() retval=00000000 ret=007c236c
0027: queue_exception_event() = 0 { handle=007c }
0028:Call KERNEL32.Sleep(00000001) ret=007c236c
0027: select( flags=2, cookie=0033b67c, timeout=infinite, prev_apc=0000,
result={}, data={WAIT,handles={007c}} )
0027: select() = PENDING { timeout=infinite, call={APC_NONE}, apc_handle=0000 }
0028:Ret  KERNEL32.Sleep() retval=00000000 ret=007c236c 
...
0009:err:ntdll:RtlpWaitForCriticalSection section 0x99d3f0 "?" wait timed out
in thread 0009, blocked by 0025, retrying (60 sec) 
--- snip ---

At this point the debugger and debuggee are stuck.

The problem can be partially attributed to the rather unusual handling of debug
events on the debugger side. Instead of having thread 0x28 doing debug event
loop continuously using blocking waits, the state machine also has a state
where it basically live loops with 'Sleep(1)', polling for variable state
changes from other debugger threads until entering the blocking wait again
using 'WaitForDebugEvent'.

During execution of APC_VIRTUAL_PROTECT on the debuggee side, the breakpoint is
hit (most likely in area/caller of 'server_select') which causes
EXCEPTION_DEBUG_EVENT being sent to debugger.
The debugger event thread 0x28 is in a state where it live loops using
Sleep(1), unable to handle debug events until the opcode patching sequence
finishes in script engine thread 0x25 (return from 'VirtualProtectEx') which
blocks debug event delivery/completion.
This in turn prevents APC_VIRTUAL_PROTECT from being completed on debuggee
side.

$ wine --version
wine-1.7.37

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.