windbg - 분석 예: 시작하자마자 비정상 종료하는 프로세스 - NullReferenceException
콘솔 응용 프로그램이었는데, 시작하자마자 비정상 종료하는 프로세스였습니다. 개발자 PC에서 이런 현상이 발생하면 소스 코드 올려놓은 상태에서 'F5' 키를 눌러 바로 디버깅 모드로 넘어가 쉽게 문제 해결을 할 수 있지만, 원격 컴퓨터에서만 재현되는 상황이라면 답답한 심정이 됩니다.
이런 경우에도 역시, "덤프"를 뜨는 것이 적절한 해결책이 될 수 있는데요. 우선, 지난번에 알려드린 "풀 덤프" 방법들 중에서,
풀 덤프 파일을 남기는 방법
; https://www.sysnet.pe.kr/2/0/991
procdump.exe를 이용하여 덤프를 남겨보겠습니다. 예를 들어 실행 파일이 test.exe라고 가정할 때 아래와 같은 옵션으로 프로세스를 시작하면 예외가 발생했을 때 덤프를 남길 수 있습니다.
D:\temp>procdump -e -ma -x d:\temp\test.exe d:\temp\test.dmp
ProcDump v3.01 - Writes process dump files
Copyright (C) 2009-2010 Mark Russinovich
Sysinternals - www.sysinternals.com
Process: test.exe (3464)
CPU threshold: n/a
Performance counter: n/a
Commit threshold: n/a
Threshold seconds: n/a
Number of dumps: 1
Hung window check: Disabled
Exception monitor: Unhandled
Terminate monitor: Disabled
Dump file: d:\temp\test.dmp
[13:49.54] Unhandled exception.
Writing dump file d:\temp\test_110212_134954.dmp...
Dump written.
The process has exited.
(참고로, "Working Directory"가 procdump.exe 실행 폴더로 바뀌기 때문에 procdump.exe를 이용하여 덤프를 남길 때는 procdump.exe 실행 파일 자체를 대상 EXE 폴더에 복사하고 덤프를 뜨는 것이 좋습니다.)
이 덤프 파일을 windbg에 열면 다음과 같은 화면으로 시작합니다
Microsoft (R) Windows Debugger Version 6.11.0001.404 AMD64
Copyright (c) Microsoft Corporation. All rights reserved.
Loading Dump File [D:\...[생략]...\test_110212_134954.dmp]
User Mini Dump File with Full Memory: Only application data is available
Comment: '
*** procdump -e -ma -x d:\temp\test.exe d:\temp\test.dmp
*** Unhandled exception'
Symbol search path is: SRV*\\localhost\e$\Symbols*http://msdl.microsoft.com/download/symbols;
Executable search path is:
Windows 7 Version 7600 MP (4 procs) Free x64
Product: Server, suite: TerminalServer SingleUserTS
Machine Name:
Debug session time: Sat Feb 12 13:49:54.000 2011 (GMT+9)
System Uptime: 1 days 10:22:04.203
Process Uptime: 0 days 0:00:01.000
................................
KERNELBASE!RaiseException+0x39:
000007fe`fd4caa7d 4881c4c8000000 add rsp,0C8h
...[생략: SOS 로드 단계 설명]...
자, 이제 예외를 검사해 보면, 아래와 같이 Test!Test.MainForm..ctor()에서 NULL 참조 오류가 발생했음을 알 수 있습니다.
0:000> !pe
Exception object: 00000000026e7cc8
Exception type: System.NullReferenceException
Message: Object reference not set to an instance of an object.
InnerException: <none>
StackTrace (generated):
SP IP Function
00000000001FEC40 000007FF001605B4 Test!Test.MainForm..ctor()+0x434
00000000001FECC0 000007FF0016014B Test!Test.Program.Main()+0x2b
StackTraceString: <none>
HResult: 80004003
애석하게도 위의 상황에서 sos 수준으로는 더 이상의 오류 추적은 불가능합니다. 왜냐하면 PDB 파일이 없기 때문입니다.
여전히 PDB 파일이 없는 상황에서 SOSEX.dll 확장을 이용하면 조금 더 자세한 정보를 얻을 수 있습니다. 이에 대해서는 다음의 글에서 소개해 주고 있습니다.
Case of NullReferenceException not handled by sos / windbg
; http://naveensrinivasan.com/2010/05/27/case-of-nullreferenceexception-not-handled-by-sos-windbg/
바로, !mk 확장 명령이 그것입니다. 곧바로 ^^ SOSEX.dll 파일을 다운로드해서,
SOSEX v4.0 Now Available
; http://www.stevestechspot.com/SOSEXV40NowAvailable.aspx
(저는, 64비트 버전을 다운로드 받았습니다.)
DLL 파일을 "C:\Program Files\Debugging Tools for Windows (x64)" 폴더에 복사해줍니다. 그다음 sos.dll을 로드하는 것과 같은 명령어로 다음과 같이 실행하고,
0:000> .load sosex
이전까지 추적했던 덤프 파일에 대해 !mk 명령을 내려주면 다음과 같은 출력을 확인할 수 있습니다.
0:000> !mk
Thread 0:
ESP EIP
00:U 00000000001fe5c0 000007fefdbcaa7d KERNELBASE!RaiseException+0x39
01:U 00000000001fe690 000007fef70fdbdc mscorwks!NakedThrowHelper2+0xc
02:U 00000000001fe6c0 000007fef70fdc2a mscorwks!NakedThrowHelper_RspAligned+0x3d
03:U 00000000001fec38 000007fef70fdc35 mscorwks!NakedThrowHelper_FixRsp+0x5
04:M 00000000001fec40 000007ff001605b4 *** ERROR: Module load completed but symbols could not be loaded for test.exe
Test.MainForm..ctor()(+0x1c0 IL)(+0x434 Native)
05:M 00000000001fecc0 000007ff0016014b Test.Program.Main()(+0x10 IL)(+0x2b Native)
06:U 00000000001fecf0 000007fef70fd502 mscorwks!CallDescrWorker+0x82
07:U 00000000001fed30 000007fef6fb9fd3 mscorwks!CallDescrWorkerWithHandler+0xd3
08:U 00000000001fedd0 000007fef6fca3af mscorwks!MethodDesc::CallDescr+0x24f
09:U 00000000001ff020 000007fef6f3dc7f mscorwks!ClassLoader::RunMain+0x22b
0a:U 00000000001ff280 000007fef6f21c74 mscorwks!Assembly::ExecuteMainMethod+0xbc
0b:U 00000000001ff570 000007fef6f59955 mscorwks!SystemDomain::ExecuteMainMethod+0x491
0c:U 00000000001ffb40 000007fef706db07 mscorwks!ExecuteEXE+0x47
0d:U 00000000001ffb90 000007fef6f2855c mscorwks!CorExeMain+0xac
0e:U 00000000001ffbf0 000007fefa2d3309 mscoreei!CorExeMain+0x41
0f:U 00000000001ffc20 000007fefa365b21 mscoree!CorExeMain_Exported+0x57
10:U 00000000001ffc50 00000000777ff56d kernel32!BaseThreadInitThunk+0xd
11:U 00000000001ffc80 0000000077932cc1 ntdll!RtlUserThreadStart+0x1d
즉 IL 코드의 offset 값(== 0x1c0)이 출력되는데요. 이 값을 기반으로 추적하는 방법은 이전에 설명한 Watson Bucket 정보를 추적하는 것과 같습니다.
Watson Bucket 정보를 이용한 CLR 응용 프로그램 예외 분석
; https://www.sysnet.pe.kr/2/0/595
단지, 위의 글에 설명된 것처럼 ildasm.exe를 별도로 구동할 필요는 없습니다. 왜냐하면 windbg 내에서 모두 해결할 수 있기 때문인데요. 우선, Test.Program.Main의 Method Desc를 알아내야 합니다. 이는 !pe 출력에서 나타난 IP 값을 통해서 알 수 있습니다.
0:000> !pe
Exception object: 00000000026e7cc8
Exception type: System.NullReferenceException
Message: Object reference not set to an instance of an object.
InnerException: <none>
StackTrace (generated):
SP IP Function
00000000001FEC40 000007FF001605B4 Test!Test.MainForm..ctor()+0x434
00000000001FECC0 000007FF0016014B Test!Test.Program.Main()+0x2b
StackTraceString: <none>
HResult: 80004003
이어서 "!ip2md" 명령을 내리고,
0:000> !ip2md 000007FF001605B4
MethodDesc: 000007ff00016c58
Method Name: Test.MainForm..ctor()
Class: 000007ff00152578
MethodTable: 000007ff00016e88
mdToken: 0600002f
Module: 000007ff000133d0
IsJitted: yes
CodeAddr: 000007ff00160180
이어서 "!dumpil" 명령을 내리면, ILDASM에서 봤던 출력과 유사한 덤프를 얻을 수 있습니다.
0:000> !dumpil 000007ff00016c58
ilAddr = 0000000000c42d64
...[생략]...
IL_0199: ldarg.0
IL_019a: call System.Environment::get_MachineName
IL_019f: stfld Test.MainForm::computerName
IL_01a4: ldstr "CLSID\{{{0}}}\InprocServer32"
IL_01a9: ldstr "FF8C2B6C-DBB5-4AED-9876-2CED6FFAF4C9"
IL_01ae: call System.String::Format
IL_01b3: stloc.1
IL_01b4: ldsfld Microsoft.Win32.Registry::ClassesRoot
IL_01b9: ldloc.1
IL_01ba: callvirt Microsoft.Win32.RegistryKey::OpenSubKey
IL_01bf: stloc.2
IL_01c0: ldloc.2
IL_01c1: ldsfld System.String::Empty
IL_01c6: ldsfld System.String::Empty
IL_01cb: callvirt Microsoft.Win32.RegistryKey::GetValue
...[생략]...
IL_03d1: ret
정황을 보아하니, 이렇게 해석이 될 수 있을 것 같습니다.
RegistryKey regKey = RegistryKey.OpenSubKey(...[경로]...);
regKey.GetValue(...); // regKey == NULL 이므로 예외 발생
굳이 위와 같은 정황 분석을 하지 않아도, 개발자 자신이 가지고 있는 .NET 코드와 비교해 보면 충분히 정확한 오류 라인을 찾아낼 수 있습니다.
물론, PDB 파일이 있었다면 이렇게 "!dumpil" 명령을 내리는 수고 없이 곧바로 소스 코드 라인 번호를 얻었을 것입니다.
처음으로 돌아가서, 물론 덤프 파일을 뜨는 것이 도움이 되긴 합니다. 하지만,
Watson Bucket 내용을 설명하면서 이벤트 로그에 남는 내용의 의미를 해석해 보았는데요. 어렵게 덤프 분석을 하지 않아도, 이렇게 이벤트 로그를 구하게 되면 좀 더 손쉽게 디버깅이 됩니다. 아래는 위에서 분석한 덤프를 뜬 응용 프로그램이 종료했을 때 이벤트 로그에 남은 내용입니다.
Fault bucket , type 0
Event Name: CLR20r3
Response: Not available
Cab Id: 0
Problem signature:
P1: test.exe
P2: 1.0.0.0
P3: 4d465cd0
P4: test
P5: 1.0.0.0
P6: 4d465cd0
P7: 2f
P8: 1c0
P9: System.NullReferenceException
P10:
...[생략]...
[이 글에 대해서 여러분들과 의견을 공유하고 싶습니다. 틀리거나 미흡한 부분 또는 의문 사항이 있으시면 언제든 댓글 남겨주십시오.]