BLOG main image
분류 전체보기 (17)
Life (2)
Dump Analysis (9)
Reversing (1)
Windows (1)
Book (2)
Reference (2)
31,406 Visitors up to today!
Today 12 hit, Yesterday 11 hit
daisy rss
tistory 티스토리 가입하기!
2018. 7. 29. 23:26

이번 덤프는 윈도우 8과 서버 2012부터 많은 사람들을 괴롭혔던 BugCheck 0x133: DPC_WATCHDOG_VIOLATION 이라는 특이한 오류다.

이 오류는 BugCheck 0x7F_8에 해당하는 커널 스택 오버 플로우와 매우 유사하다. 커널 스택 오버 플로우가 커널 스택에 대한 사용량 문제라면 0x133은 커널 시간에 대한 사용량 문제다. 커널에서는 일반적인 요청보다 좀 더 중요한 일을 처리해야 할 때 DPC(Deferred Procudure Call)/Dispatch라는 인터럽트 레벨에서 동작하게 된다. 문제는 이 DPC/Dispatch 레벨이 스레드 스케쥴링 등의 운영체제 주요 동작보다도 더 높은 레벨이라 DPC/Dispatch 레벨에서 작업이 지연되면 시스템이 느려지거나 행 증상이 발생할 수도 있다. 물론 운영체제만 사용 가능한 인터럽트 레벨이라면 큰 문제가 없겠지만 불행히도 DPC/Dispatch 레벨은 커널 드라이버라면 스핀락(SpinLock) 함수를 통해 쉽게 사용 가능하다. 상황이 이렇다보니 잘못 작성된 커널 드라이버가 스핀락을 획득하고 오랜 시간 반환하지 않으면 시스템이 멈추는 불상사가 발생한다. 이 문제를 해결하기 위해 새로 추가된 오류 코드가 바로 0x133이다. 커널에서는 별도의 감시자(Watchdog)를 통해 DPC/Dispatch 레벨에서의 동작 시간이 정해진 제한 시간(Time Out)을 넘으면 지체없이 이 오류 코드를 발생시킨다. 여러 모듈이 지연시키는 경우도 각각 동작 시간을 누적하여 제한 시간을 넘기면 이 오류 코드가 발생할 수 있다. 따라서 원인 분석을 위해 성능 지연 구간에 대한 별도의 성능 로그를 수집해야 할 수도 있다. 나는 이런 점에서 0x133을 매우 어려운 커널 스택 오버 플로우 이슈 정도로 생각한다.

물론 여기서는 덤프에서 원인 분석이 가능하도록 단일 모듈에서 성능 지연이 발생한 경우를 살펴볼 것이다.

먼저 !analyze -v 명령을 통해 기본 분석부터 시작해보자.

kd> !analyze -v

*******************************************************************************

*                                                                             *

*                        Bugcheck Analysis                                    *

*                                                                             *

*******************************************************************************

DPC_WATCHDOG_VIOLATION (133)

The DPC watchdog detected a prolonged run time at an IRQL of DISPATCH_LEVEL

or above.

Arguments:

Arg1: 00000001, The system cumulatively spent an extended period of time at

       DISPATCH_LEVEL or above. The offending component can usually be

       identified with a stack trace.

Arg2: 00001e00, The watchdog period.

Arg3: 00000000, cast to nt!DPC_WATCHDOG_GLOBAL_TRIAGE_BLOCK, which contains

       additional information regarding the cumulative timeout

Arg4: 00000000

Debugging Details:

------------------

DUMP_CLASS: 1

DUMP_QUALIFIER: 401

BUILD_VERSION_STRING:  14393.693.x86fre.rs1_release.161220-1747

SYSTEM_MANUFACTURER:  SAMSUNG ELECTRONICS CO.,LTD

SYSTEM_PRODUCT_NAME:  Samsung Desktop System

SYSTEM_SKU:  System SKUNumber

SYSTEM_VERSION:  CAAAAAAF

BIOS_VENDOR:  SAMSUNG ELECTRONICS CO.,LTD

BIOS_VERSION:  04NS

BIOS_DATE:  08/16/2011

BASEBOARD_MANUFACTURER:  SAMSUNG ELECTRONICS CO.,LTD

BASEBOARD_PRODUCT:  Samsung DeskTop System

BASEBOARD_VERSION:  CAAAAAAA

DUMP_TYPE:  1

BUGCHECK_P1: 1

BUGCHECK_P2: 1e00

BUGCHECK_P3: 0

BUGCHECK_P4: 0

DPC_TIMEOUT_TYPE:  DPC_QUEUE_EXECUTION_TIMEOUT_EXCEEDED

CPU_COUNT: 4

CPU_MHZ: cdd

CPU_VENDOR:  GenuineIntel

CPU_FAMILY: 6

CPU_MODEL: 2a

CPU_STEPPING: 7

CPU_MICROCODE: 6,2a,7,0 (F,M,S,R)  SIG: 29'00000000 (cache) 29'00000000 (init)

DEFAULT_BUCKET_ID:  WIN8_DRIVER_FAULT

BUGCHECK_STR:  0x133

PROCESS_NAME:  SMSS.exe

CURRENT_IRQL:  1c

ANALYSIS_SESSION_HOST:  PAUL-PC

ANALYSIS_SESSION_TIME:  06-11-2018 22:34:11.0900

ANALYSIS_VERSION: 10.0.16299.91 amd64fre

LAST_CONTROL_TRANSFER:  from 81b48d4e to 81b284a8

STACK_TEXT: 

d461b7d4 81b48d4e 00000133 00000001 00001e00 nt!KeBugCheckEx

d461b804 81a3b08c 85dc5120 00000002 00000000 nt! ?? ::FNODOBFM::`string'+0x9eae

d461b8d0 820336b7 81a3d64d 00000000 d461ba14 nt!KeClockInterruptNotify+0x36c

d461b8e0 82044cdb 00000002 000000d1 00000000 hal!HalpTimerClockInterruptCommon+0x3f

d461b8e0 81a3d64d 00000002 000000d1 00000000 hal!HalpTimerClockInterrupt+0x1f7

d461b9f0 81ba85d0 c786f3b8 8833d980 83000100 nt!KxWaitForSpinLockAndAcquire+0x1d

d461ba14 81a54003 00000000 830001c8 883125c7 nt!KiAcquireSpinLockInstrumented+0x53

d461ba20 883125c7 0032a582 d461bae0 8831f149 nt!KfAcquireSpinLock+0x33

d461ba2c 8831f149 8a352a0a c786f3b8 00000000 SomeDrv+0x25c7

d461bae0 81ca719d c786f3b8 00000001 00000000 SomeDrv+0xf149

d461bbb8 81ca6f6a 00000000 00000000 042ffdc8 nt!IopXxxControlFile+0x21d

d461bbe4 81b36987 00000300 00000000 00000000 nt!NtDeviceIoControlFile+0x2a

d461bbe4 77ce4d50 00000300 00000000 00000000 nt!KiSystemServicePostCall

042ffde8 00000000 00000000 00000000 00000000 0x77ce4d50

THREAD_SHA1_HASH_MOD_FUNC:  2a46f69c6139803d83a04cedcad275f72ac07d42

THREAD_SHA1_HASH_MOD_FUNC_OFFSET:  6f2b762ab8d468cacab44d7f866169a56cdce50c

THREAD_SHA1_HASH_MOD:  bd912fdd2f42d7d45cc2017c378e8c588d451ef1

FOLLOWUP_IP:

SomeDrv+25c7

883125c7 8845fe          mov     byte ptr [ebp-2],al

FAULT_INSTR_CODE:  81fe4588

SYMBOL_STACK_INDEX:  8

SYMBOL_NAME:  SomeDrv+25c7

FOLLOWUP_NAME:  MachineOwner

MODULE_NAME: SomeDrv

IMAGE_NAME:  SomeDrv.sys

DEBUG_FLR_IMAGE_TIMESTAMP:  57fde77c

STACK_COMMAND:  .thread ; .cxr ; kb

BUCKET_ID_FUNC_OFFSET:  25c7

FAILURE_BUCKET_ID:  0x133_ISR_SomeDrv!unknown_function

BUCKET_ID:  0x133_ISR_SomeDrv!unknown_function

PRIMARY_PROBLEM_CLASS:  0x133_ISR_SomeDrv!unknown_function

TARGET_TIME:  2017-02-27T00:48:23.000Z

OSBUILD:  14393

OSSERVICEPACK:  0

SERVICEPACK_NUMBER: 0

OS_REVISION: 0

SUITE_MASK:  272

PRODUCT_TYPE:  1

OSPLATFORM_TYPE:  x86

OSNAME:  Windows 10

OSEDITION:  Windows 10 WinNt TerminalServer SingleUserTS

OS_LOCALE: 

USER_LCID:  0

OSBUILD_TIMESTAMP:  2016-12-21 13:24:07

BUILDDATESTAMP_STR:  161220-1747

BUILDLAB_STR:  rs1_release

BUILDOSVER_STR:  10.0.14393.693.x86fre.rs1_release.161220-1747

ANALYSIS_SESSION_ELAPSED_TIME:  ece

ANALYSIS_SOURCE:  KM

FAILURE_ID_HASH_STRING:  km:0x133_isr_SomeDrv!unknown_function

FAILURE_ID_HASH:  {c26eac98-dd1d-7af7-3055-fbbff800604a}

Followup:     MachineOwner

---------


출력 결과 중 BugCheck 파라미터 부분을 유심히 살펴보면 대략적인 발생 원인을 이해할 수 있다.

Arg1: 00000001, The system cumulatively spent an extended period of time at

       DISPATCH_LEVEL or above. The offending component can usually be

       identified with a stack trace.

Arg2: 00001e00, The watchdog period.


첫 번째 파라미터는 1이며, 시스템이 DISPATCH_LEVEL 이상에서 장시간 동작한 것이 원인이라고 말한다. 스택 추적을 통해 문제를 일으킨 원인을 확인할 수 있다고도 언급한다.

두 번째 파라미터는 감시 중인 제한 시간으로  Tick 단위다. 하나 혹은 복수의 커널 드라이버가 DISPATCH_LEVEL 이상에서 동작한 누적 시간 값이 제한 시간을 넘길 경우 이 오류가 발생한다.

이를 통해 누군가 DISPATCH_LEVEL 이상에서 0x1e00(7,680) Tick 만큼 장시간 동작한 것이 문제의 원인 임을 짐작할 수 있다. 커널에서 성능 지연이 감지되면 시스템을 멈추는 방식이므로 문제 발생 당시 실행 중인 스레드가 범인일 가능성이 높다. 첫 번째 파라미터 설명에서 실행 중인 콜 스택을 살펴보라는 것도 그런 이유에서다.

그렇다면 !thread 명령으로 현재 실행 중인 스레드 정보를 확인해보자.

kd> !thread

THREAD d8e548c0  Cid 2978.2c68  Teb: 0157e000 Win32Thread: 00000000 RUNNING on processor 0

Not impersonating

DeviceMap                 88a03058

Owning Process            d8bc6800       Image:         SMSS.exe

Attached Process          N/A            Image:         N/A

Wait Start TickCount      39290          Ticks: 7680 (0:00:02:00.000)

Context Switch Count      3651           IdealProcessor: 0            

UserTime                  00:00:00.062

KernelTime                00:02:00.046

Win32 Start Address 0x0fb738e0

Stack Init d461bca0 Current d461ba2c Base d461c000 Limit d4619000 Call 00000000

Priority 8 BasePriority 8 PriorityDecrement 0 IoPriority 2 PagePriority 5

ChildEBP RetAddr  Args to Child             

d461b7d4 81b48d4e 00000133 00000001 00001e00 nt!KeBugCheckEx

d461b804 81a3b08c 85dc5120 00000002 00000000 nt! ?? ::FNODOBFM::`string'+0x9eae

d461b8d0 820336b7 81a3d64d 00000000 d461ba14 nt!KeClockInterruptNotify+0x36c (FPO: [Non-Fpo])

d461b8e0 82044cdb 00000002 000000d1 00000000 hal!HalpTimerClockInterruptCommon+0x3f (FPO: [0,0,4])

d461b8e0 81a3d64d 00000002 000000d1 00000000 hal!HalpTimerClockInterrupt+0x1f7 (FPO: [0,2] TrapFrame @ d461b978)

d461b9f0 81ba85d0 c786f3b8 8833d980 83000100 nt!KxWaitForSpinLockAndAcquire+0x1d (FPO: [0,0,0])

d461ba14 81a54003 00000000 830001c8 883125c7 nt!KiAcquireSpinLockInstrumented+0x53 (FPO: [Non-Fpo])

d461ba20 883125c7 0032a582 d461bae0 8831f149 nt!KfAcquireSpinLock+0x33 (FPO: [0,0,0])

d461ba2c 8831f149 8a352a0a c786f3b8 00000000 SomeDrv+0x25c7

d461bae0 81ca719d c786f3b8 00000001 00000000 SomeDrv+0xf149

d461bbb8 81ca6f6a 00000000 00000000 042ffdc8 nt!IopXxxControlFile+0x21d (FPO: [Non-Fpo])

d461bbe4 81b36987 00000300 00000000 00000000 nt!NtDeviceIoControlFile+0x2a (FPO: [Non-Fpo])

d461bbe4 77ce4d50 00000300 00000000 00000000 nt!KiSystemServicePostCall (FPO: [0,3] TrapFrame @ d461bc14)

042ffde8 00000000 00000000 00000000 00000000 0x77ce4d50


스레드 정보의 Ticks 필드를 보면 정확하게 7680(0x1e00) Tick이 경과했음을 알 수 있다. 2분의 시간이 경과한 순간 커널이 제한 시간을 다 사용한 것으로 판단하여 0x133을 발생시킨 것이다.

이번에는 k명령으로 스레드의 콜 스택을 분석하며 문제가 발생한 상황을 좀 더 이해해보자.

kd> k

 # ChildEBP RetAddr 

00 d461b7d4 81b48d4e nt!KeBugCheckEx ç 3) 제한 시간이 경과하여 BSOD 발생

01 d461b804 81a3b08c nt! ?? ::FNODOBFM::`string'+0x9eae

02 d461b8d0 820336b7 nt!KeClockInterruptNotify+0x36c

03 d461b8e0 82044cdb hal!HalpTimerClockInterruptCommon+0x3f

04 d461b8e0 81a3d64d hal!HalpTimerClockInterrupt+0x1f7

05 d461b9f0 81ba85d0 nt!KxWaitForSpinLockAndAcquire+0x1d ç 2) 스핀락 획득 시도

06 d461ba14 81a54003 nt!KiAcquireSpinLockInstrumented+0x53

07 d461ba20 883125c7 nt!KfAcquireSpinLock+0x33

08 d461ba2c 8831f149 SomeDrv+0x25c7     ç 1) SomeDrv 모듈에서 스핀락 획득 함수 호출

09 d461bae0 81ca719d SomeDrv+0xf149

0a d461bbb8 81ca6f6a nt!IopXxxControlFile+0x21d

0b d461bbe4 81b36987 nt!NtDeviceIoControlFile+0x2a

0c d461bbe4 77ce4d50 nt!KiSystemServicePostCall

0d 042ffde8 00000000 0x77ce4d50


콜 스택을 보면 1)번에서 SomeDrv 모듈이 스핀락을 얻으려고 시도하고 있다. 하지만 스핀락을 획득하지 못해 2)번에서 nt! KxWaitForSpinLockAndAcquire 함수를 통해 획득하기를 기다리고 있다. 동작 자체로는 아무 문제가 없지만 락 획득을 빨리 하지 못한 것이 문제의 원인이다. 무려 2분 동안 락을 획득하지 못하고 있는 것은 정상적인 상황이 아니다. 하지만 이 문제를 분석하기에 앞서 확인해야할 부분이 하나 있다.

앞서 0x133이 발생하려면 제한 시간 외에도 인터럽트 레벨이 DISPATCH_LEVEL 이상이라는 조건이 있었다. 제한 시간 조건은 스레드의 Ticks 정보를 통해 만족함을 확인했지만 인터럽트 레벨 조건은 아직 확인하지 못했다.

문제 발생 당시 인터럽트 레벨을 어떻게 알 수 있을까? 문제의 콜 스택에서 스핀락을 얻으려는 부분이 보이는가? 커널에서 락이나 이벤트를 사용할 경우 내부에서는 동기화를 위해 인터럽트 레벨을 변경하는 경우가 많이 있다. 그렇다면 nt!KfAcquireSpinLock 함수를 디스어셈블링해서 인터럽트 레벨을 변경하는 부분이 있는지 살펴보면 답을 알 수 있다.

kd> u nt!KfAcquireSpinLock

nt!KfAcquireSpinLock:

81a53fd0 8bff            mov     edi,edi

81a53fd2 53              push    ebx

81a53fd3 56              push    esi

81a53fd4 8bf1            mov     esi,ecx

81a53fd6 ff153891c381    call    dword ptr [nt!_imp__KeRaiseIrqlToDpcLevel (81c39138)]

81a53fdc f60506b9c48121  test    byte ptr [nt!PerfGlobalGroupMask+0x6 (81c4b906)],21h

81a53fe3 8ad8            mov     bl,al

81a53fe5 7515            jne     nt!KfAcquireSpinLock+0x2c (81a53ffc)


다행히 시작 부분에 KeRaiseIrqlToDpcLevel 함수를 통해 인터럽트 레벨을 Dpc/Dispatch로 상승시키는 코드가 확인된다. 0x133을 발생시키는 인터럽트 레벨과 제한 시간 조건 모두를 만족하는 상황이므로 SomeDrv 모듈에서 스핀락을 획득하는 동작이 문제의 발단이다.

이제 오랜 시간 동안 스핀락을 획득하지 못한 원인을 밝혀내야 한다. 먼저 스핀락을 획득하는 함수인 nt!KfAcquireSpinLock 함수의 원형을 살펴보자.

KIRQL

FASTCALL

KfAcquireSpinLock(

    _Inout_ PKSPIN_LOCK SpinLock

    );

 

<wdm.h>

typedef ULONG_PTR KSPIN_LOCK;

typedef KSPIN_LOCK *PKSPIN_LOCK;


KSPIN_LOCK 구조체의 포인터를 파라미터로 전달받고 있다. 뭔가 특별한 락 구조체인 것처럼 보이지만 wdm.h 헤더 파일을 보면 실은 단순한 unsigned long 변수다. 스핀락은 바로 이 변수를 통해 테스트 앤 셋(Test And Set) 방식으로 동기화를 수행한다. 이 방식을 단순하게 설명하면 락 변수 값이 0이면 스핀락 획득시 변수를 1로 설정하고 락 반환시 0으로 복원한다. 이미 1인 상태에서 스핀락 획득을 시도하면 0이 되길 지속적으로 기다린다(루프를 돌면서 기다리는 이 동작 때문에 스핀락이라고 부른다).

다시 본론으로 돌아와서 이번에는 nt! KfAcquireSpinLock 함수에 전달된 KSPIN_LOCK 변수가 정상인지 확인해야 한다. 콜 스택에서 nt!KfAcquireSpinLock 함수를 호출한 1)번 부분을 디스어셈블링해보자.

kd> ub SomeDrv+0x25c7

SomeDrv+0x25b1:

883125b1 cc              int     3

883125b2 8bff            mov     edi,edi

883125b4 55              push    ebp

883125b5 8bec            mov     ebp,esp

883125b7 51              push    ecx

883125b8 c645ff00        mov     byte ptr [ebp-1],0

883125bc b980d93388      mov     ecx,offset SomeDrv+0x2d980 (8833d980) ç 1) 파라미터

883125c1 ff1508e03288    call    dword ptr [SomeDrv+0x1e008 (8832e008)] ç 2) nt!KfAcquireSpinLock 함수 호출


nt!KfAcquireSpinLock 함수 원형을 보면 호출 규약이 FASTCALL 이므로 첫 번째 파라미터는 ecx에 설정된다. 1)번을 보면 SomeDrv+0x2d980 위치의 값을 ecx에 설정하고 있다. 바로 SomeDrv+0x2d980KSPIN_LOCK 구조체 변수의 주소다. 2)번에서 호출된 함수는 ln 명령을 사용하면 nt!KfAcquireSpinLock 함수 임을 쉽게 알 수 있다.

kd> ln poi(8832e008)

Browse module

Set bu breakpoint

 

(81a53fd0)   nt!KfAcquireSpinLock   |  (81a54010)   nt!KfReleaseSpinLock

Exact matches:

    nt!KfAcquireSpinLock (<no parameter info>)


KSPIN_LOCK 구조체 위치인 SomeDrv+0x2d980 주소도 dd 명령으로 확인해보자.

kd> dd SomeDrv+0x2d980 L1

8833d980  00490057


어라? KSPIN_LOCK 구조체 주소인 8833d980에 저장된 값이 뭔가 이상하다. 스핀락 획득 유무에 따라 0 아니면 1이 있어야 하는데 00490057이라는 비정상적인 값이 들어 있다. 왠지 불길한 예감이 든다. 이럴 때는 db 명령을 통해 8833d980 주소의 메모리를 확인해보면 의외의 단서를 찾을 수 있다.

kd> db 8833d980

8833d980  57 00 49 00 4e 00 44 00-4f 00 57 00 53 00 5c 00  W.I.N.D.O.W.S.\.

8833d990  53 00 59 00 53 00 54 00-45 00 4d 00 33 00 32 00  S.Y.S.T.E.M.3.2.

8833d9a0  5c 00 44 00 4e 00 53 00-41 00 50 00 49 00 2e 00  \.D.N.S.A.P.I...

8833d9b0  44 00 4c 00 4c 00 00 00-59 00 53 00 54 00 45 00  D.L.L...Y.S.T.E.

8833d9c0  4d 00 33 00 32 00 5c 00-44 00 4e 00 53 00 41 00  M.3.2.\.D.N.S.A.

8833d9d0  50 00 49 00 2e 00 44 00-4c 00 4c 00 43 00 3a 00  P.I...D.L.L.C.:.

8833d9e0  5c 00 57 00 49 00 4e 00-44 00 4f 00 57 00 53 00  \.W.I.N.D.O.W.S.

8833d9f0  5c 00 53 00 59 00 53 00-54 00 45 00 4d 00 33 00  \.S.Y.S.T.E.M.3.


역시 00490057KSPIN_LOCK 구조체의 정상적인 값이 아닌 어떤 문자열 값의 일부분이다. du 명령으로 약간 앞 쪽을 살펴보면 왠지 전체 문자열을 알 수 있을 것 같다.

kd> du 8833d980-6

8833d97a  "C:\WINDOWS\SYSTEM32\DNSAPI.DLL"


아하! "C:\WINDOWS\SYSTEM32\DNSAPI.DLL"이라는 파일 경로 문자열이 들어 있다. 아무래도 누군가 KSPIN_LOCK 구조체 위치에 이 문자열을 덮어 써버려 메모리를 손상시킨 것 같다. 정말 메모리 손상이 문제의 원인이 맞는지 알려면 스핀락을 획득하는 부분을 조금 더 분석할 필요가 있다. kv 명령으로 콜 스택을 다시 확인해보자.

kd> kv

 # ChildEBP RetAddr  Args to Child             

00 d461b7d4 81b48d4e 00000133 00000001 00001e00 nt!KeBugCheckEx

01 d461b804 81a3b08c 85dc5120 00000002 00000000 nt! ?? ::FNODOBFM::`string'+0x9eae

02 d461b8d0 820336b7 81a3d64d 00000000 d461ba14 nt!KeClockInterruptNotify+0x36c (FPO: [Non-Fpo])

03 d461b8e0 82044cdb 00000002 000000d1 00000000 hal!HalpTimerClockInterruptCommon+0x3f (FPO: [0,0,4])

04 d461b8e0 81a3d64d 00000002 000000d1 00000000 hal!HalpTimerClockInterrupt+0x1f7 (FPO: [0,2] TrapFrame @ d461b978) ç 2) 트랩 프레임

05 d461b9f0 81ba85d0 c786f3b8 8833d980 83000100 nt!KxWaitForSpinLockAndAcquire+0x1d (FPO: [0,0,0]) ç 1) 대기 함수

06 d461ba14 81a54003 00000000 830001c8 883125c7 nt!KiAcquireSpinLockInstrumented+0x53 (FPO: [Non-Fpo])

07 d461ba20 883125c7 0032a582 d461bae0 8831f149 nt!KfAcquireSpinLock+0x33 (FPO: [0,0,0])

08 d461ba2c 8831f149 8a352a0a c786f3b8 00000000 SomeDrv+0x25c7

09 d461bae0 81ca719d c786f3b8 00000001 00000000 SomeDrv +0xf149

0a d461bbb8 81ca6f6a 00000000 00000000 042ffdc8 nt!IopXxxControlFile+0x21d (FPO: [Non-Fpo])

0b d461bbe4 81b36987 00000300 00000000 00000000 nt!NtDeviceIoControlFile+0x2a (FPO: [Non-Fpo])

0c d461bbe4 77ce4d50 00000300 00000000 00000000 nt!KiSystemServicePostCall (FPO: [0,3] TrapFrame @ d461bc14)

0d 042ffde8 00000000 00000000 00000000 00000000 0x77ce4d50


1)nt!KxWaitForSpinLockAndAcquire함수는 스핀락을 획득하기 위해 시도하는 함수다. 2)번에는 트랩 프레임(TrapFrame)이 확인된다. 트랩 프레임이 있다는 것은 직전 1)번 함수 동작에 문제가 있어 인터럽트가 발생했다는 의미다. .trap 명령을 사용해 문제 발생 당시 상황으로 컨텍스트를 복원해보자.

kd> .trap d461b978

ErrCode = 00000000

eax=00490057 ebx=83000100 ecx=8833d980 edx=00000000 esi=520f94a9 edi=8833d980

eip=81a3d64d esp=d461b9ec ebp=d461ba14 iopl=0         nv up ei pl nz na pe nc

cs=0008  ss=0010  ds=8c3b  es=01c8  fs=6b68  gs=ba20             efl=00000206

nt!KxWaitForSpinLockAndAcquire+0x1d:

81a3d64d f390            pause


edi 레지스터에 설정된 8833d980 값을 기억해두자(앞서 확인한 KSPIN_LOCK 구조체 주소다). esi 레지스터 값도 봐두면 좋다. 문제가 발생했던1)번 시점의 동작을 확인하기 위해 nt!KxWaitForSpinLockAndAcquire 함수를 처음부터 살펴봐야한다. 함수가 짧으니 너무 걱정하지 말자.

kd> u nt!KxWaitForSpinLockAndAcquire L14

nt!KxWaitForSpinLockAndAcquire:

81a3d630 8bff            mov     edi,edi

81a3d632 56              push    esi

81a3d633 57              push    edi

81a3d634 8bf9            mov     edi,ecx

81a3d636 33f6            xor     esi,esi ç 1) esi = 0

81a3d638 eb06            jmp     nt!KxWaitForSpinLockAndAcquire+0x10 (81a3d640)

81a3d63a 8d9b00000000    lea     ebx,[ebx]

81a3d640 46              inc     esi ç 2) esi + 1(루프 시작)

81a3d641 853530e0c381    test    dword ptr [nt!HvlLongSpinCountMask (81c3e030)],esi

81a3d647 0f84a2bc1000    je      nt! ?? ::FNODOBFM::`string'+0xa44f (81b492ef)

81a3d64d f390            pause ç 3) 인터럽트 발생 위치(트랩 프레임)

81a3d64f 8b07            mov     eax,dword ptr [edi] ç 4) edi 값을 eax 설정

81a3d651 85c0            test    eax,eax ç 5) eax 값이 0인지 확인

81a3d653 75eb            jne     nt!KxWaitForSpinLockAndAcquire+0x10 (81a3d640) ç 6) 0 아니면 2) 루프 시작 위치로 이동

81a3d655 f00fba2f00      lock bts dword ptr [edi],0

81a3d65a 72e4            jb      nt!KxWaitForSpinLockAndAcquire+0x10 (81a3d640)

81a3d65c 5f              pop     edi

81a3d65d 8bc6            mov     eax,esi

81a3d65f 5e              pop     esi

81a3d660 c3              ret


중요 위치마다 주석이 있어 함수 동작을 이해하는 데 무리가 없을 것이다. 1)번부터 살펴보자. 우선 esi 레지스터는 단순한 카운터 변수다. 2)번을 보면 루프 진입시마다 1씩 증가한다. 4)번에는 edi 값을 eax에 설정하고 5)번에서 eax0인지 확인한다. 참고로 ediKSPIN_LOCK 구조체 변수의 주소였다.

eax에 설정한 edi 값을 확인해보자.

kd> dd edi L1

8833d980  00490057


edi00490057 값이 있으므로 eax에도 00490057 값이 설정된다(앞서 00490057 값은 문자열의 일부였다). 6)번에서는 eax 값이 0이 아니므로 루프 시작 위치인 2)번으로 다시 이동한다. eax는 이미 문자열로 덮어 써져 0이 될 수 없으므로 계속 이 루틴이 반복된다. 즉 무한 루프 상태다. 과연 이 루프는 얼마나 수행됐을까? 카운터 변수인 esi 레지스터 값을 확인해보자.

kd> r esi

Last set context:

esi=520f94a9


맙소사! 0x520f94a9(1,376,752,809)라는 엄청나게 큰 값이 설정되어 있다. 무려 13억번이나 루프가 돌고 있었던 것이다! 그리고는 결국 제한 시간이 다 되어 3)번 위치의 pause 명령에서 0x133이 발생했다. 이제야 모든 것이 명확해졌다. 누군가 스핀락 변수를 문자열로 손상시켜 스핀락 획득 함수 내부에서 무한 루프에 빠져 버린 것이 원인이다(물론 대부분의 경우 누군가는 스핀락 사용 중인 SomeDrv 자신이다).

스핀락을 획득하려고 인터럽트 레벨을 상승시키고 무한 루프에 빠졌으니 DPC_WATCHDOG_VIOLATION(0x133) 버그체크가 발생하는 것은 어찌보면 당연하다.

여기서는 메모리 손상에 의한 0x133을 소개했지만 훨씬 까다로운 경우도 있다. 바로 스핀락을 획득하고 수행한 작업들 하나하나가 조금씩 성능 지연을 일으켜 누적에 의해 제한 시간을 넘기는 경우다. 단일 모듈이 아닌 다수의 모듈에서 지연이 발생하는 경우라면 더욱 골치아프다. 이 경우 별도의 성능 측정을 통해 모듈별로 매 작업마다 성능 지연이 발생하는 구간을 찾아내야해서 굉장히 어렵다. 이런 이유로 스핀락을 획득하고 시간 걸리는 작업은 아예 하지 않는 것이 정신 건강에 이롭다. 주로 다량의 엔트리가 삽입된 리스트를 검색할 때 성능 지연이 발생하는데 해시 테이블 등으로 자료 구조를 변경하거나 리스트에 삽입되는 최대 개수를 제한하는 등의 수정이 필요할 수 있다. 물론 가장 좋은 것은 개발 초기부터 이런 문제를 예상하며 성능을 고려한 설계를 하는 것이다.

앞으로 이 오류 코드가 발생한다면 이것 하나만 기억하자. 스핀락과 연관된 코드를 살펴보라!”



'Dump Analysis' 카테고리의 다른 글

[Hang] CPU 과점유  (0) 2018.08.13
[0x133] DPC_WATCHDOG_VIOLATION  (0) 2018.07.29
[0xC5] 해제 리스트 손상  (0) 2018.07.19
[0xC5] 풀 헤더 손상  (0) 2018.07.16
[0x1A] 페이지 손상  (0) 2018.07.12
[0x50] 해제된 핸들  (0) 2018.07.09
Name
Password
Homepage
Secret