apc 异步过程调用无法抛到主线程的问题跟踪

引发:

使用项目的ipc时发现不能向主线程抛apc消息,后编写测试代码经反复测试发现测试代码也无法发送:

主线程:

子线程:

下面的内核调试记录对本次问题查找本无益处,但还是花费了大量时间,需要记录:
因为apc为内核支持的功能,所以有幸可以从wrk代码找到原因,在找到问题前隐约的怀疑是向上抛出消息的时候出了问题,所以首先想到的是确认内核态的apc分发到底是不是在子线程:
记录:反复实验后发现,子线程的apc抛给了自己!(这个时候本应该怀疑线程句柄有问题,以后切记!)

1,windbg刚开始链接不上server2003,后发现内核调试过程需要爱2003线启动至等待状态,在开启windbg
2,最好先设置好符号路径和源代码路径,两者都在host机器上
3,不要反复的点击继续按钮,这玩意坑爹的缓存会发送多条命令
4,开始调试:
0: kd> ?0n3008
Evaluate expression: 3008 = 00000bc0
0: kd> !process bc0
Searching for Process with Cid == bc0
Cid handle table at e1003c98 with 413 entries in use

PROCESS 89ea74e0 SessionId: 0 Cid: 0bc0 Peb: 7ffdc000 ParentCid: 07e4

THREAD 89ea79e0 Cid 0bc0.0bc4 Teb: 7ffdf000 Win32Thread: e1ad31b8 WAIT: (DelayExecution) UserMode Alertable
89ea7a58 NotificationTimer
Not impersonating
DeviceMap e1b2c778
Owning Process 89ea74e0 Image: exitprocess.exe
Attached Process N/A Image: N/A
Wait Start TickCount 21061 Ticks: 98 (0:00:00:01.531)
Context Switch Count 107 IdealProcessor: 0

THREAD 89f33a88 Cid 0bc0.05a0 Teb: 7ffde000 Win32Thread: e1efca28 WAIT: (WrUserRequest) UserMode Non-Alertable
8a1842f8 SynchronizationEvent
Not impersonating
DeviceMap e1b2c778
Owning Process 89ea74e0 Image: exitprocess.exe
…
0: kd> .process /i /p 89ea74e0
You need to continue execution (press ‘g’ ) for the context
to be switched. When the debugger breaks in again, you will be in
the new process context.
0: kd> g
Break instruction exception - code 80000003 (first chance)
nt!RtlpBreakWithStatusInstruction:
80861cb8 cc int 3
0: kd> !apc
* Enumerating APCs in all processes
Process 8a77c648 System
Process 89d78020 smss.exe
Process 89fcc698 csrss.exe
Process 89d519e0 winlogon.exe
Process 89f90020 services.exe
Process 89eae4a8 lsass.exe
Process 8a4996c0 vmacthlp.exe
Process 8a4d56d0 svchost.exe
Process 8a166d60 svchost.exe
Process 8a4e1b18 svchost.exe
Process 8a374d88 svchost.exe
Process 8a25e020 svchost.exe
Process 8a46a9b8 spoolsv.exe
Process 8a48eb88 msdtc.exe
Process 89f87430 svchost.exe
Process 8a1838e0 svchost.exe
Process 8a027d88 vmtoolsd.exe
Process 8a343d88 explorer.exe
Process 89fb1720 svchost.exe
Process 899bdd88 wmiprvse.exe
Process 89ff6d88 TPAutoConnSvc.e
Process 89ff2790 vmtoolsd.exe
Process 8a4cfd88 dllhost.exe
Process 8a569348 ctfmon.exe
Process 89ff8b18 TPAutoConnect.e
Process 8a665bf8 wmiprvse.exe
Process 89d57220 conime.exe
Process 89ea74e0 exitprocess.exe
Process 8a20da10 procexp.exe

0: kd> .thread
Implicit thread is now 8a7788d0
0: kd> !apc 89ea74e0 89ea79e0
KAPC @ 89ea74e0
Type 3
KernelRoutine 89ea74f0 +ffffffff89ea74f0
RundownRoutine 78897000 [phone]

0: kd> .reload /user
Loading User Symbols
……………
0: kd> lm
start end module name
00400000 0040d000 exitprocess (deferred)
4b210000 4b261000 MSCTF (deferred)
4c510000 4c53e000 msctfime (deferred)
63090000 63099000 LPK (deferred)
74ae0000 74b41000 USP10 (deferred)
75d60000 75d87000 apphelp (deferred)
76180000 7619d000 IMM32 (deferred)
774b0000 775e4000 ole32 (deferred)
77b70000 77bca000 msvcrt (deferred)
…

0: kd> kb
ChildEBP RetAddr Args to Child
f78f6d2c 809bc0b2 00000007 8a7788d0 8089dd7c nt!RtlpBreakWithStatusInstruction [C:\test\wrk\wrk\base\ntos\rtl\i386\debug2.asm @ 47]
f78f6d80 80818953 00000000 00000000 8a7788d0 nt!ExpDebuggerWorker+0xac [c:\test\wrk\wrk\base\ntos\ex\worker.c @ 1680]
f78f6dac 80930c70 00000000 00000000 00000000 nt!ExpWorkerThread+0xe9 [c:\test\wrk\wrk\base\ntos\ex\worker.c @ 1183]
f78f6ddc 8088731e 8081886a 00000001 00000000 nt!PspSystemThreadStartup+0x2e [c:\test\wrk\wrk\base\ntos\ps\create.c @ 2214]
00000000 00000000 00000000 00000000 00000000 nt!KiThreadStartup+0x16 [C:\test\wrk\wrk\base\ntos\ke\i386\threadbg.asm @ 78]
0: kd> ~0s
0: kd> kb
用户态下这两个命令都无用
ChildEBP RetAddr Args to Child
f78f6d2c 809bc0b2 00000007 8a7788d0 8089dd7c nt!RtlpBreakWithStatusInstruction [C:\test\wrk\wrk\base\ntos\rtl\i386\debug2.asm @ 47]
f78f6d80 80818953 00000000 00000000 8a7788d0 nt!ExpDebuggerWorker+0xac [c:\test\wrk\wrk\base\ntos\ex\worker.c @ 1680]
f78f6dac 80930c70 00000000 00000000 00000000 nt!ExpWorkerThread+0xe9 [c:\test\wrk\wrk\base\ntos\ex\worker.c @ 1183]
f78f6ddc 8088731e 8081886a 00000001 00000000 nt!PspSystemThreadStartup+0x2e [c:\test\wrk\wrk\base\ntos\ps\create.c @ 2214]
00000000 00000000 00000000 00000000 00000000 nt!KiThreadStartup+0x16 [C:\test\wrk\wrk\base\ntos\ke\i386\threadbg.asm @ 78]
0: kd> x nt!KiDeliverApc –该函数为apc的分发入口
8082b736 nt!KiDeliverApc (char, struct _KTRAP_FRAME , struct _KTRAP_FRAME )
0: kd> bp 8082b736
0: kd> g –实际上这个断点因为在内核态,所以会对所有进程生效,故这个时候着实迷茫了一阵
Breakpoint 0 hit
nt!KiDeliverApc:
8082b736 55 push ebp
1: kd> ~0kb
^ Extra character error in ‘~0kb’
* WARNING: symbols timestamp is wrong 0x52fd7cf2 0x5091bef3 for exitprocess.exe
* ERROR: Module load completed but symbols could not be loaded for exitprocess.exe

本想看一下用户栈,结果发现忘了加载符号了,而此时加载怎么也找不到进程的模块,只好去客户机上重启进程重新来一遍

0: kd> ?0n3464
Evaluate expression: 3464 = 00000d88
0: kd> !process d88
Searching for Process with Cid == d88
Cid handle table at e1003c98 with 371 entries in use

PROCESS 8a679d88 SessionId: 0 Cid: 0d88 Peb: 7ffdc000 ParentCid: 07e4
DirBase: 7a2e7000 ObjectTable: e1b0f588 HandleCount: 42.
Image: exitprocess.exe
VadRoot 8a4c2cf0 Vads 47 Clone 0 Private 131. Modified 7. Locked 0.
DeviceMap e1b2c778
Token e1999888
ElapsedTime 00:00:24.000
UserTime 00:00:00.000
KernelTime 00:00:00.000
QuotaPoolUsage[PagedPool] 20064
QuotaPoolUsage[NonPagedPool] 1880
Working Set Sizes (now,min,max) (728, 50, 345) (2912KB, 200KB, 1380KB)
PeakWorkingSetSize 728
VirtualSize 19 Mb
PeakVirtualSize 19 Mb
PageFaultCount 770
MemoryPriority BACKGROUND
BasePriority 8
CommitCharge 245

    THREAD 8a4d23b8  Cid 0d88.0ea0  Teb: 7ffdf000 Win32Thread: e1c15c38 WAIT: (DelayExecution) UserMode Alertable        8a4d2430  NotificationTimer    Not impersonating    DeviceMap                 e1b2c778    Owning Process            8a679d88       Image:         exitprocess.exe    Attached Process          N/A            Image:         N/A    Wait Start TickCount      83989          Ticks: 127 (0:00:00:01.984)    Context Switch Count      32             IdealProcessor: 0                 LargeStack    UserTime                  00:00:00.000    KernelTime                00:00:00.000    Win32 Start Address 0x0040143b    Start Address kernel32!BaseProcessStartThunk (0x7c82b5c7)    Stack Init b9e4b000 Current b9e4ac80 Base b9e4b000 Limit b9e47000 Call 0    Priority 11 BasePriority 8 PriorityDecrement 2    ChildEBP RetAddr      b9e4ac98 8082e704 nt!KiSwapContext+0x26 (FPO: [Uses EBP] [0,0,4]) [C:\test\wrk\wrk\base\ntos\ke\i386\ctxswap.asm @ 128]    b9e4acc4 80826791 nt!KiSwapThread+0x282 (FPO: [Non-Fpo]) (CONV: fastcall) [c:\test\wrk\wrk\base\ntos\ke\thredsup.c @ 2013]    b9e4ad0c 809918f2 nt!KeDelayExecutionThread+0x2a9 (FPO: [Non-Fpo]) (CONV: stdcall) [c:\test\wrk\wrk\base\ntos\ke\wait.c @ 415]    b9e4ad54 8088284c nt!NtDelayExecution+0x84 (FPO: [Non-Fpo]) (CONV: stdcall) [c:\test\wrk\wrk\base\ntos\ex\delay.c @ 79]    b9e4ad54 7c95ed54 nt!KiFastCallEntry+0xfc (FPO: [0,0] TrapFrame @ b9e4ad64) [C:\test\wrk\wrk\base\ntos\ke\i386\trap.asm @ 1369]    0012ff5c 00000000 ntdll!KiFastSystemCallRet (FPO: [0,0,0])    THREAD 8a29d688  Cid 0d88.0e6c  Teb: 7ffde000 Win32Thread: e1dd1d28 WAIT: (WrUserRequest) UserMode Non-Alertable        89df0c60  SynchronizationEvent    Not impersonating    DeviceMap                 e1b2c778    Owning Process            8a679d88       Image:         exitprocess.exe    Attached Process          N/A            Image:         N/A    Wait Start TickCount      83311          Ticks: 805 (0:00:00:12.578)    Context Switch Count      164            IdealProcessor: 0                 LargeStack    UserTime                  00:00:00.000    KernelTime                00:00:00.015    Win32 Start Address 0x004010a0    Start Address kernel32!BaseThreadStartThunk (0x7c82b5bb)    Stack Init b9dcb000 Current b9dcac50 Base b9dcb000 Limit b9dc6000 Call 0    Priority 12 BasePriority 8 PriorityDecrement 2    ChildEBP RetAddr      b9dcac68 8082e704 nt!KiSwapContext+0x26 (FPO: [Uses EBP] [0,0,4]) [C:\test\wrk\wrk\base\ntos\ke\i386\ctxswap.asm @ 128]    b9dcac94 808272e4 nt!KiSwapThread+0x282 (FPO: [Non-Fpo]) (CONV: fastcall) [c:\test\wrk\wrk\base\ntos\ke\thredsup.c @ 2013]    b9dcacdc bf875ecb nt!KeWaitForSingleObject+0x344 (FPO: [Non-Fpo]) (CONV: stdcall) [c:\test\wrk\wrk\base\ntos\ke\wait.c @ 1242]    b9dcad38 bf87605f win32k!xxxSleepThread+0x1be (FPO: [Non-Fpo])    b9dcad4c bf87607c win32k!xxxRealWaitMessageEx+0x12 (FPO: [Non-Fpo])    b9dcad5c 8088284c win32k!NtUserWaitMessage+0x14 (FPO: [0,0,0])    b9dcad5c 7c95ed54 nt!KiFastCallEntry+0xfc (FPO: [0,0] TrapFrame @ b9dcad64) [C:\test\wrk\wrk\base\ntos\ke\i386\trap.asm @ 1369]    009ef71c 00000000 ntdll!KiFastSystemCallRet (FPO: [0,0,0])

0: kd> .process /i /p 8a679d88
You need to continue execution (press ‘g’ ) for the context
to be switched. When the debugger breaks in again, you will be in
the new process context.
0: kd> g
Break instruction exception - code 80000003 (first chance)
nt!RtlpBreakWithStatusInstruction:
80861cb8 cc int 3
0: kd> .reload /user
Loading User Symbols
……………
0: kd> lm
start end module name
00400000 0040d000 exitprocess (deferred)
4b210000 4b261000 MSCTF (deferred)
4c510000 4c53e000 msctfime (deferred)
63090000 63099000 LPK (deferred)
74ae0000 74b41000 USP10 (deferred)
这是空过x来检验符号是否加载上:
0: kd> x exitprocess!*
00407c58 exitprocess!__newclmap = unsigned char [] “— memory read error at address 0x00407c58 —”
00407c58 exitprocess!__newclmap = unsigned char [384] “— memory read error at address 0x00407c58 —”
0040a908 exitprocess!_debugger_hook_dummy = 0n0
打断点
0: kd> bp exitprocess!ExecMessageCallbackToMainAPCFunc
0: kd> bl
0 e 00401080 [e:\workspace\open source\code\trunk\exitprocess\exitprocess.cpp @ 19] 0001 (0001) exitprocess!ExecMessageCallbackToMainAPCFunc

0: kd> g
Breakpoint 0 hit
exitprocess!ExecMessageCallbackToMainAPCFunc:
001b:00401080 55 push ebp
1: kd> kb
ChildEBP RetAddr Args to Child
009efc00 7c802bf5 00000000 009efc6c 00000000 exitprocess!ExecMessageCallbackToMainAPCFunc [e:\workspace\open source\code\trunk\exitprocess\exitprocess.cpp @ 19]
009efc58 7c95ec2d 00401080 00000000 00000000 kernel32!BaseDispatchAPC+0x50
009effa8 004010be 00000064 00000001 009effec ntdll!KiUserApcDispatcher+0x25
009effb8 7c826063 fffffffe 00000000 00000000 exitprocess!worker_proc+0x1e [e:\workspace\open source\code\trunk\exitprocess\exitprocess.cpp @ 28]
009effec 00000000 004010a0 fffffffe 00000000 kernel32!BaseThreadStart+0x34
1: kd> !thread
THREAD 8a29d688 Cid 0d88.0e6c Teb: 7ffde000 Win32Thread: e1dd1d28 RUNNING on processor 1
Not impersonating
DeviceMap e1b2c778
Owning Process 8a679d88 Image: exitprocess.exe
Attached Process N/A Image: N/A
Wait Start TickCount 85708 Ticks: 0
Context Switch Count 302 IdealProcessor: 0 LargeStack
UserTime 00:00:00.000
KernelTime 00:00:00.015
Win32 Start Address exitprocess!worker_proc (0x004010a0)
Start Address kernel32!BaseThreadStartThunk (0x7c82b5bb)
Stack Init b9dcb000 Current b9dcac50 Base b9dcb000 Limit b9dc6000 Call 0
Priority 10 BasePriority 8 PriorityDecrement 0
ChildEBP RetAddr Args to Child
009efc00 7c802bf5 00000000 009efc6c 00000000 exitprocess!ExecMessageCallbackToMainAPCFunc (FPO: [Non-Fpo]) (CONV: stdcall) [e:\workspace\open source\code\trunk\exitprocess\exitprocess.cpp @ 19]
009efc58 7c95ec2d 00401080 00000000 00000000 kernel32!BaseDispatchAPC+0x50 (FPO: [Non-Fpo])
009effa8 004010be 00000064 00000001 009effec ntdll!KiUserApcDispatcher+0x25
009effb8 7c826063 fffffffe 00000000 00000000 exitprocess!worker_proc+0x1e (FPO: [Non-Fpo]) (CONV: stdcall) [e:\workspace\open source\code\trunk\exitprocess\exitprocess.cpp @ 28]
009effec 00000000 004010a0 fffffffe 00000000 kernel32!BaseThreadStart+0x34 (FPO: [Non-Fpo])
这时候发现确实是子线程,在看内核态的分发是否是子线程:

0: kd> bp /p 8a679d88 nt!KiInitializeUserApc –/p参数可以在内核态指定断点触发的进程
0: kd> bl
0 e 00401080 [e:\workspace\open source\code\trunk\exitprocess\exitprocess.cpp @ 19] 0001 (0001) exitprocess!ExecMessageCallbackToMainAPCFunc
1 e 8083222a [c:\test\wrk\wrk\base\ntos\ke\i386\apcuser.c @ 65] 0001 (0001) nt!KiInitializeUserApc
2 e 8083222a [c:\test\wrk\wrk\base\ntos\ke\i386\apcuser.c @ 65] 0001 (0001) nt!KiInitializeUserApc
Match process data 8a679d88

0: kd> g
Breakpoint 2 hit
nt!KiInitializeUserApc:
8083222a 6840030000 push 340h
1: kd> !thread
THREAD 8a29d688 Cid 0d88.0e6c Teb: 7ffde000 Win32Thread: e1dd1d28 RUNNING on processor 1
Not impersonating
DeviceMap e1b2c778
Owning Process 8a679d88 Image: exitprocess.exe
Attached Process N/A Image: N/A
Wait Start TickCount 86104 Ticks: 0
Context Switch Count 525 IdealProcessor: 0 LargeStack
UserTime 00:00:00.015
KernelTime 00:00:00.062
Win32 Start Address exitprocess!worker_proc (0x004010a0)
Start Address kernel32!BaseThreadStartThunk (0x7c82b5bb)
Stack Init b9dcb000 Current b9dcac50 Base b9dcb000 Limit b9dc6000 Call 0
Priority 10 BasePriority 8 PriorityDecrement 0
ChildEBP RetAddr Args to Child
b9dcacf8 8082b919 00000000 b9dcad64 7c802baf nt!KiInitializeUserApc (FPO: [Non-Fpo]) (CONV: stdcall) [c:\test\wrk\wrk\base\ntos\ke\i386\apcuser.c @ 65]
b9dcad4c 808828b4 00000001 00000000 b9dcad64 nt!KiDeliverApc+0x1e3 (FPO: [Non-Fpo]) (CONV: stdcall) [c:\test\wrk\wrk\base\ntos\ke\apcsup.c @ 354]
b9dcad4c 7c95ed54 00000001 00000000 b9dcad64 nt!KiServiceExit+0x56 (FPO: [0,0] TrapFrame @ b9dcad64) [C:\test\wrk\wrk\base\ntos\ke\i386\trap.asm @ 1390]
009eff3c 7c951364 7c802439 00000001 009eff80 ntdll!KiFastSystemCallRet (FPO: [0,0,0])
009eff40 7c802439 00000001 009eff80 00000000 ntdll!ZwDelayExecution+0xc (FPO: [2,0,0])
009effa8 004010be 00000064 00000001 009effec kernel32!SleepEx+0x68 (FPO: [Non-Fpo])
009effb8 7c826063 fffffffe 00000000 00000000 exitprocess!worker_proc+0x1e (FPO: [Non-Fpo]) (CONV: stdcall) [e:\workspace\open source\code\trunk\exitprocess\exitprocess.cpp @ 28]
009effec 00000000 004010a0 fffffffe 00000000 kernel32!BaseThreadStart+0x34 (FPO: [Non-Fpo])

发现内核态也在子线程