꿈과 희망이 함께하는 Inside Windows

간혹 ( 정말 간혹 ) 무한 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로 빠지는 경우가 있다는것을 알 수 있습니다.

1. eax 와 edi+30h가 동일한 값을 경우 루프를 빠져 나오고 edi+30h에 ecx를 넣어 준다.
2. eax 와 edi+30h가 동일한 값이 아닐 경우 eax에 edi+30h의 값을 넣어주고 루프를 반복하여 돌게 된다. ( eax는 edi+30h의 값을 대입하지만 바로 위에서 다시 0으로 세팅함 )

그럼 각 Register및 메모리의 주소를 확인해 보면 진짜 무한 loop으로 빠져 있는지를 확인 할 수 있습니다.

lock cmpxchg를 수행 후의 Register와 메모리값을 확인하면 아래와 같이 정리가 되죠 .

1. eax : 0×00000001
2. edi+30h : 0×00000001
3. EFlags : 0×00000297 ( Zero Flag : 0 )

여기서 몇가지 가능성을 추정해 볼 수 있습니다.

1. Lock cmpxchg를 수행후 Register의 값을 통해( eax가 최초 0에서 edi+30h과 값이 다르기 때문에 eax에 edi+30h의 값이 들어가고 zero flag가 0으로 세팅된것임 ) CPU를 선점한 Thread는 특정 Flag가 0으로 세팅될 때 까지 지속적으로 루프를 수행하고 있음을 확인 할 수 있다.
2. 만약 Flag가 최초 0이었다고 가정하면 최초에 위의 코드에 진입한 Thread가 Flag를 1로 변경하게 되므로 Flag를 1로 변경 후 그 이후 동작을 수행하고 있는 Thread가 존재 한다는 것을 알 수 있다.
3. 위의 코드는 IofCallDriver를 후킹한 코드에서 수행 되므로 많은 수의 Thread가 위와 같은 형태의 대기 상태일 것이라는 것을 알 수 있다. ( 실재로 존재 하는데 너무 많아서 올리지 않음 )
4. 위의 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 현상이 발생하는 것으로 보입니다.

그럼 시나리오 정리를 하면 .

1. Priority가 낮은 Thread가 동기화 Flag를 1로 변경 후 원복하지 않은 상태에서 테스크 스위칭이 발생
2. 추후 CPU를 선점한 Thread가 같은 Flag를 통해서 동기화를 이루고 있는 Hooking 로직이면 Lock 현상이 발생
3. 이 후 다시 Flag를 1로 변경한 Thread가 CPU를 선점하여 Flag를 0으로 변경하면 Lcok 현상이 사라짐 

그럼 이제 그 동기화 부분을 찾아서 수정할 방법을 고민해 보면 될꺼 같습니다. 머 Kernel Level에서 사용되는 동기화 Object를 사용하는 방법을 쓰면 좋을꺼 같내요.

Enjoy Debugging