간혹 ( 정말 간혹 ) 무한 Loop 코드가 CPU를 모두 선점하여 시스템이 먹통이 되는 경우가 종종 발생합니다. 예를 들면 일정 시간동안 시스템이 멈췄다가 다시 원래대로 돌아오는 것과 같은 현상이 대표적인 경우가 아닐까 생각됩니다.
일단 키보드를 이용해서 Hang 발생시점에 Dump를 발생 시킵니다. 그 덤프를 통해서 분석을 해보도록 하죠.
1: kd> !running -i -t
System Processors 3 (affinity mask)
Idle Processors 0
Prcbs Current Next
0 ffdff120 88afcda8 …………….
ChildEBP RetAddr
WARNING: Stack unwind information not available. Following frames may be wrong.
a2eba5a4 a2fb05a9 lockDrv+0×12154
a2eba5c0 a2fb0731 lockDrv+0×15a9
a2eba5f4 a2fb3aab lockDrv+0×1731
a2eba628 a2fb3bcc lockDrv+0×4aab
a2eba680 a467e18f lockDrv+0×4bcc
a2eba6a4 a467e80e mfehidk+0×718f
a2eba73c a468c367 mfehidk+0×780e
a2eba74c a468c3b7 mfehidk+0×15367
a2eba774 804e33eb mfehidk!DEVICEDISPATCH::DispatchPassThrough+0×48
a2eba784 a4623ace nt!IopfCallDriver+0×31
a2eba7e8 a4623f70 UDSecDrvXP+0×1ace
a2eba804 804e33eb UDSecDrvXP+0×1f70
a2eba814 8057dbed nt!IopfCallDriver+0×31
a2eba8f4 8056f03b nt!IopParseDevice+0xa12
a2eba96c 80572358 nt!ObpLookupObjectName+0×53c
a2eba9c0 8057e246 nt!ObOpenObjectByName+0xea
a2ebaa3c 8057e315 nt!IopCreateFile+0×407
a2ebaa98 8057e358 nt!IoCreateFile+0×8e
a2ebaad8 f79e7564 nt!NtCreateFile+0×30
a2ebad30 804df99f fhdrv+0×564
1 f7717120 88b06498 …………….
ChildEBP RetAddr
a2ef6460 f75897fb nt!KeBugCheckEx+0×1b
a2ef647c f7589033 i8042prt!I8xProcessCrashDump+0×237
a2ef64c4 804dd90f i8042prt!I8042KeyboardInterruptService+0×21c
a2ef64c4 a2fc1154 nt!KiInterruptDispatch+0×45
WARNING: Stack unwind information not available. Following frames may be wrong.
a2ef65a4 a2fb05a9 lockDrv+0×12154
a2ef65c0 a2fb0731 lockDrv+0×15a9
a2ef65f4 a2fb3aab lockDrv+0×1731
a2ef6628 a2fb3bcc lockDrv+0×4aab
a2ef6680 a467e18f lockDrv+0×4bcc
a2ef66a4 a467e80e mfehidk+0×718f
a2ef673c a468c367 mfehidk+0×780e
a2ef674c a468c3b7 mfehidk+0×15367
a2ef6774 804e33eb mfehidk!DEVICEDISPATCH::DispatchPassThrough+0×48
a2ef6784 a4623ace nt!IopfCallDriver+0×31
a2ef67e8 a4623f70 UDSecDrvXP+0×1ace
a2ef6804 804e33eb UDSecDrvXP+0×1f70
a2ef6814 8057dbed nt!IopfCallDriver+0×31
a2ef68f4 8056f03b nt!IopParseDevice+0xa12
a2ef696c 80572358 nt!ObpLookupObjectName+0×53c
a2ef69c0 8057e246 nt!ObOpenObjectByName+0xea
1: kd> u IofCallDriver
nt!IofCallDriver:
804e33b9 ff2580d75580 jmp dword ptr [nt!pIofCallDriver (8055d780)]
804e33bf 90 nop
804e33c0 90 nop
804e33c1 90 nop
804e33c2 90 nop
804e33c3 90 nop
nt!IopfCallDriver:
804e33c4 fe4a23 dec byte ptr [edx+23h]
804e33c7 8a4223 mov al,byte ptr [edx+23h]
1: kd> dd 8055d780
8055d780 a2fb3bc0 804e37da 804ecd58 804eceb1
8055d790 00000000 00000000 00000000 00000000
8055d7a0 00000000 00000000 00000000 00000000
8055d7b0 00000000 00000000 00000000 00000000
8055d7c0 00000000 00000000 00000000 00000000
8055d7d0 00000000 00000000 00000000 00000000
8055d7e0 00000000 00000000 00000000 00000000
8055d7f0 00000000 00000000 00000000 00000000
1: kd> u a2fb3bc0
lockDrv+0×4bc0:
a2fb3bc0 8bc4 mov eax,esp
a2fb3bc2 60 pushad
a2fb3bc3 52 push edx
a2fb3bc4 51 push ecx
a2fb3bc5 ff30 push dword ptr [eax]
a2fb3bc7 e80efeffff call lockDrv+0×49da (a2fb39da)
a2fb3bcc 83f800 cmp eax,0
a2fb3bcf 7407 je lockDrv+0×4bd8 (a2fb3bd8)
일단 2개의 비슷한 모양의 Stack이 CPU를 선점하고 있는것을 확인 할 수 있습니다. 일단 마지막 동작을 확인 하기 위해서 Trap Frame을 이용합니다. Register 값과 디스어셈코드를 보고 마지막 동작을 추정할 수 있습니다.
1: kd> kvn
# ChildEBP RetAddr Args to Child
00 a2ef6460 f75897fb 000000e2 00000000 00000000 nt!KeBugCheckEx+0×1b (FPO: [5,0,0])
01 a2ef647c f7589033 00f29d40 016498c6 00000000 i8042prt!I8xProcessCrashDump+0×237 (FPO: [3,0,0])
02 a2ef64c4 804dd90f 8a1496d0 89f29c88 01010009 i8042prt!I8042KeyboardInterruptService+0×21c (FPO: [Non-Fpo])
03 a2ef64c4 a2fc1154 8a1496d0 89f29c88 01010009 nt!KiInterruptDispatch+0×45 (FPO: [0,2] TrapFrame @ a2ef64e8)
WARNING: Stack unwind information not available. Following frames may be wrong.
04 a2ef65a4 a2fb05a9 8a12c720 89fbe4f8 8a12c720 lockDrv+0×12154
05 a2ef65c0 a2fb0731 8a12c238 00000001 88b62204 lockDrv+0×15a9
06 a2ef65f4 a2fb3aab 8a12c238 a468d12b 88b62204 lockDrv+0×1731
07 a2ef6628 a2fb3bcc a468d12b 8a12c238 88b62008 lockDrv+0×4aab
08 a2ef6680 a467e18f 88b62008 a2ef6734 88b62008 lockDrv+0×4bcc
09 a2ef66a4 a467e80e 88b62008 01b62204 88f2eb40 mfehidk+0×718f
0a a2ef673c a468c367 88f2eb40 88b62008 a2ef6774 mfehidk+0×780e
0b a2ef674c a468c3b7 a2ef675c 89f89220 893fe020 mfehidk+0×15367
0c a2ef6774 804e33eb 893fe020 88b62008 8a0b6470 mfehidk!DEVICEDISPATCH::DispatchPassThrough+0×48
0d a2ef6784 a4623ace 88b62018 8a0b6470 00000000 nt!IopfCallDriver+0×31 (FPO: [0,0,0])
0e a2ef67e8 a4623f70 893b6020 88b62008 00000001 UDSecDrvXP+0×1ace
0f a2ef6804 804e33eb 893b6020 88b62008 88b62008 UDSecDrvXP+0×1f70
10 a2ef6814 8057dbed 8a30f8e8 8901958c a2ef69ac nt!IopfCallDriver+0×31 (FPO: [0,0,0])
11 a2ef68f4 8056f03b 8a30f900 00000000 890194e8 nt!IopParseDevice+0xa12 (FPO: [Non-Fpo])
12 a2ef696c 80572358 00000000 a2ef69ac 00000042 nt!ObpLookupObjectName+0×53c (FPO: [11,15,4])
13 a2ef69c0 8057e246 00000000 00000000 08a67001 nt!ObOpenObjectByName+0xea (FPO: [7,5,4])
1: kd> .trap a2ef64e8
ErrCode = 00000000
eax=00000001 ebx=1001829b ecx=00000001 edx=8a12c720 esi=a2fc729b edi=a2fc0e00
eip=a2fc1154 esp=a2ef655c ebp=a2ef65a4 iopl=0 nv up ei ng nz ac pe cy
cs=0008 ss=0010 ds=55f8 es=0000 fs=71f0 gs=32fa efl=00000297
lockDrv+0×12154:
a2fc1154 75f7 jne lockDrv+0×1214d (a2fc114d) [br=1]
1: kd> ub lockDrv+0×12154
lockDrv+0×1213b:
a2fc113b 833e00 cmp dword ptr [esi],0
a2fc113e 75f2 jne lockDrv+0×12132 (a2fc1132)
a2fc1140 8b742424 mov esi,dword ptr [esp+24h]
a2fc1144 8bde mov ebx,esi
a2fc1146 03f0 add esi,eax
a2fc1148 b901000000 mov ecx,1
a2fc114d 33c0 xor eax,eax
a2fc114f f00fb14f30 lock cmpxchg dword ptr [edi+30h],ecx
1: kd> u lockDrv+0×12154
lockDrv+0×12154:
a2fc1154 75f7 jne lockDrv+0×1214d (a2fc114d)
a2fc1156 ac lods byte ptr [esi]
a2fc1157 6652 push dx
a2fc1159 b2e9 mov dl,0E9h
a2fc115b e9c90a0000 jmp lockDrv+0×12c29 (a2fc1c29)
a2fc1160 81e67b4fd45d and esi,5DD44F7Bh
a2fc1166 e9ad100000 jmp lockDrv+0×13218 (a2fc2218)
a2fc116b 660fb6c8 movzx cx,al
CPU를 선점함 코드를 보면 특정 조건이 맞지 않으면 무한 Loop로 빠지는 경우가 있다는것을 알 수 있습니다.
- eax 와 edi+30h가 동일한 값을 경우 루프를 빠져 나오고 edi+30h에 ecx를 넣어 준다.
- eax 와 edi+30h가 동일한 값이 아닐 경우 eax에 edi+30h의 값을 넣어주고 루프를 반복하여 돌게 된다. ( eax는 edi+30h의 값을 대입하지만 바로 위에서 다시 0으로 세팅함 )
그럼 각 Register및 메모리의 주소를 확인해 보면 진짜 무한 loop으로 빠져 있는지를 확인 할 수 있습니다.
lock cmpxchg를 수행 후의 Register와 메모리값을 확인하면 아래와 같이 정리가 되죠 .
- eax : 0×00000001
- edi+30h : 0×00000001
- EFlags : 0×00000297 ( Zero Flag : 0 )
여기서 몇가지 가능성을 추정해 볼 수 있습니다.
- Lock cmpxchg를 수행후 Register의 값을 통해( eax가 최초 0에서 edi+30h과 값이 다르기 때문에 eax에 edi+30h의 값이 들어가고 zero flag가 0으로 세팅된것임 ) CPU를 선점한 Thread는 특정 Flag가 0으로 세팅될 때 까지 지속적으로 루프를 수행하고 있음을 확인 할 수 있다.
- 만약 Flag가 최초 0이었다고 가정하면 최초에 위의 코드에 진입한 Thread가 Flag를 1로 변경하게 되므로 Flag를 1로 변경 후 그 이후 동작을 수행하고 있는 Thread가 존재 한다는 것을 알 수 있다.
- 위의 코드는 IofCallDriver를 후킹한 코드에서 수행 되므로 많은 수의 Thread가 위와 같은 형태의 대기 상태일 것이라는 것을 알 수 있다. ( 실재로 존재 하는데 너무 많아서 올리지 않음 )
- 위의 Flag ( edi+20h 값 )은 후킹 코드 상의 동기화를 위해서 사용된 동기화 Flag로 추정해 볼 수 있다.
그럼 이제 문제의 원인이라 할 수 있는 lockDrv+0×12154 이후 코드를 수행하는 Thread를 찾아 보면 될꺼 같습니다. 왜냐하면 이 녀석이 CPU를 다시 선점하여 완전히 로직을 수행해야 다른 녀석들도 무한 Loop에서 벗어 날 수 있기 때문입니다.
1: kd> !thread 88f09b98
THREAD 88f09b98 Cid 1200.1270 Teb: 7ff94000 Win32Thread: e31d5a48 READY
IRP List:
88b00008: (0006,0220) Flags: 00000884 Mdl: 00000000
Not impersonating
DeviceMap e10f0448
Owning Process 88fca020 Image: iexplore.exe
Attached Process N/A Image: N/A
Wait Start TickCount 50449 Ticks: 187 (0:00:00:02.921)
Context Switch Count 109392 LargeStack
UserTime 00:00:00.625
KernelTime 00:00:00.781
Win32 Start Address iertutil!CIsoScope::RegisterThread (0×3fa3407f)
Start Address kernel32!BaseThreadStartThunk (0×7c7e06f9)
Stack Init a343e000 Current a343d3e0 Base a343e000 Limit a3439000 Call 0
Priority 7 BasePriority 7 PriorityDecrement 0 DecrementCount 16
ChildEBP RetAddr Args to Child
a343d3f4 80703f63 00000000 a343d4b8 80703106 nt!KiDispatchInterrupt+0xa7 (FPO: [Uses EBP] [0,0,3])
a343d400 80703106 00000000 000000e1 a343d4b8 hal!HalEndSystemInterrupt+0×57 (FPO: [2,2,0])
a343d400 a2fc59fc 00000000 000000e1 a343d4b8 hal!HalpIpiHandler+0xbe (FPO: [0,2] TrapFrame @ a343d410)
WARNING: Stack unwind information not available. Following frames may be wrong.
a343d4b8 a2fb05a9 8a12c720 89fbe4f8 8a12c720 lockDrv+0×169fc
a343d4d4 a2fb0731 8a12c238 00000001 00000000 lockDrv+0×15a9
a343d508 a2fb3aab 8a12c238 a467bdda 00000000 lockDrv+0×1731
a343d53c a2fb3bcc a467bdda 8a12c238 88fbb008 lockDrv+0×4aab
a343d618 a467c401 8a238a08 889da5a0 889da580 lockDrv+0×4bcc
a343d630 a463f444 a343d658 00000000 a343d6cc mfehidk+0×5401
.. 생략
lockDrv+0×12154 이후 실행 코드를 아래와 같이 살펴보면 88f09b98 Thread의 마지막 Stack에 위치한 코드는 lockDrv+0×12154 이후에 수행되는 코드임을 알 수 있습니다.. ( 코드가 가상화되어 수동으로 순서를 조합한 것임 )
lockDrv+0×12156:
a2fc1156 ac lods byte ptr [esi]
a2fc1157 6652 push dx
a2fc1159 b2e9 mov dl,0E9h
a2fc115b e9c90a0000 jmp lockDrv+0×12c29 (a2fc1c29)
lockDrv+0×12c29:
a2fc1c29 28d0 sub al,dl
a2fc1c2b 665a pop dx
a2fc1c2d 00d8 add al,bl
a2fc1c2f 52 push edx
a2fc1c30 b6e1 mov dh,0E1h
a2fc1c32 f6de neg dh
a2fc1c34 80f653 xor dh,53h
a2fc1c37 c0ee07 shr dh,7
a2fc1c3a 6800000000 push 0
a2fc1c3f 283424 sub byte ptr [esp],dh
a2fc1c42 e90d310000 jmp lockDrv+0×15d54 (a2fc4d54)
lockDrv+0×15d54:
a2fc4d54 8a3424 mov dh,byte ptr [esp]
a2fc4d57 83c404 add esp,4
a2fc4d5a 80f6e9 xor dh,0E9h
a2fc4d5d 00f0 add al,dh
a2fc4d5f 5a pop edx
a2fc4d60 51 push ecx
a2fc4d61 52 push edx
a2fc4d62 b6f6 mov dh,0F6h
a2fc4d64 80f65a xor dh,5Ah
a2fc4d67 0f897a010000 jns lockDrv+0×15ee7 (a2fc4ee7))
lockDrv+0×15d6d:
a2fc4d6d fec6 inc dh
a2fc4d6f e94fd6ffff jmp lockDrv+0×133c3 (a2fc23c3)
lockDrv+0×133c3:
a2fc23c3 80e68e and dh,8Eh
a2fc23c6 0f82033f0000 jb lockDrv+0×172cf (a2fc62cf)
lockDrv+0×133cc:
a2fc23cc 80c6f6 add dh,0F6h
a2fc23cf 53 push ebx
a2fc23d0 e917360000 jmp lockDrv+0×169ec (a2fc59ec)
lockDrv+0×169ec:
a2fc59ec b7d7 mov bh,0D7h
a2fc59ee fecf dec bh
a2fc59f0 e9f3c0ffff jmp lockDrv+0×12ae8 (a2fc1ae8)
lockDrv+0×12ae8:
a2fc1ae8 fecf dec bh
a2fc1aea f6df neg bh
a2fc1aec 80efdb sub bh,0DBh
a2fc1aef e9063f0000 jmp lockDrv+0×169fa (a2fc59fa)
lockDrv+0×169fa:
a2fc59fa 00fe add dh,bh
a2fc59fc 5b pop ebx
a2fc59fd 88f5 mov ch,dh
a2fc59ff 5a pop edx
a2fc5a00 30e8 xor al,ch
a2fc5a02 e9d5000000 jmp lockDrv+0×16adc (a2fc5adc)
lockDrv+0×16adc: <== 현재 실행 중이 었던 블록
a2fc5adc 8b0c24 mov ecx,dword ptr [esp]
a2fc5adf 81c404000000 add esp,4
a2fc5ae5 52 push edx
a2fc5ae6 89e2 mov edx,esp
a2fc5ae8 81c204000000 add edx,4
a2fc5aee e962cdffff jmp lockDrv+0×13855 (a2fc2855)
이제 이 문제의 결론이 어느 정도 보이죠 .
즉 Thread 88f09b98 가 동기화 Flag를 1로 바꾼 상태이며 Flag를 원복 하지 않은 상태에서 CPU상의 테스크가 변경되어 다른 Thread는 무한 Loop를 돌게 된 것으로 볼 수 있다. 실제 Flag를 선점한 Thread는 Priority가 낮기 때문에 다음 CPU 선점까지의 시간이 지연되어 PC의 Lock 현상이 발생하는 것으로 보입니다.
그럼 시나리오 정리를 하면 .
- Priority가 낮은 Thread가 동기화 Flag를 1로 변경 후 원복하지 않은 상태에서 테스크 스위칭이 발생
- 추후 CPU를 선점한 Thread가 같은 Flag를 통해서 동기화를 이루고 있는 Hooking 로직이면 Lock 현상이 발생
- 이 후 다시 Flag를 1로 변경한 Thread가 CPU를 선점하여 Flag를 0으로 변경하면 Lcok 현상이 사라짐
그럼 이제 그 동기화 부분을 찾아서 수정할 방법을 고민해 보면 될꺼 같습니다. 머 Kernel Level에서 사용되는 동기화 Object를 사용하는 방법을 쓰면 좋을꺼 같내요.
Enjoy Debugging
최근 답글