windbg 디버깅 사례: AppDomain 간의 static 변수 사용으로 인한 crash
이번 글은 가로채기 관련한 상황에서 crash가 발생한 거라서 일반적인 닷넷 응용 프로그램 개발에서 이런 문제를 겪을 일은 거의 없을 것입니다. 단지 windbg를 사용하면서 어떻게 문제를 풀어나갔는지 기록해 둘 필요가 있어서 남깁니다. ^^
우선, 이 문제는 Local SYSTEM 계정에서 실행된 SSRS(SQL Server Reporting Services)에서만 재현되어 추적하기가 매우 어려웠습니다. 사실, 지난 글들이 이 문제 하나 때문에 씌여진 것들입니다. ^^;
윈도우 8에서 "Interactive Services Detection" 서비스 시작하는 방법
; https://www.sysnet.pe.kr/2/0/1583
윈도우 8 - UI가 있는 프로그램을 Local SYSTEM 권한의 세션 0 데스크탑에서 실행하는 방법
; https://www.sysnet.pe.kr/2/0/1584
NT 서비스가 시작하자마자 디버거를 연결시키는 방법 (1)
; https://www.sysnet.pe.kr/2/0/1586
NT 서비스가 시작하자마자 디버거를 연결시키는 방법 (2)
; https://www.sysnet.pe.kr/2/0/1587
Local SYSTEM 계정으로 실행된 IE에서 다운로드가 안되는 문제
; https://www.sysnet.pe.kr/2/0/1596
NT 서비스 시작 단계에서 닷넷 메서드에 BP를 걸어 디버깅하는 방법
; https://www.sysnet.pe.kr/2/0/1598
windbg - Symbol file could not be found. Defaulted to export symbols
; https://www.sysnet.pe.kr/2/0/1601
windbg - 사용자 모드 원격 디버깅
; https://www.sysnet.pe.kr/2/0/1602
휴... 그리고 이제야 드디어 (제 수준에서) 결론이 났습니다. ^^
어디 따라가 볼까요?
문제는 제가 만든 가로채기 모듈이 대상 메서드에 들어간 경우 다음과 같은 식의 오류가 발생한다는 것이었습니다. 문제가 발생한 시점에 windbg로 analyze를 해보면 다음과 같이 나옵니다. (아래의 결과는 PDB 연결이 안된 상태입니다.)
0:010> !analyze -v
...[생략]...
FAULTING_IP:
mscorwks!IEE+cfd6
00007ffc`641aa12e 48f7440a2801000000 test qword ptr [rdx+rcx+28h],1
EXCEPTION_RECORD: ffffffffffffffff -- (.exr 0xffffffffffffffff)
ExceptionAddress: 00007ffc641aa12e (mscorwks!IEE+0x000000000000cfd6)
ExceptionCode: c0000005 (Access violation)
ExceptionFlags: 00000000
NumberParameters: 2
Parameter[0]: 0000000000000000
Parameter[1]: 000000000000002a
Attempt to read from address 000000000000002a
FAULTING_THREAD: 0000000000001ac8
...[생략]...
MANAGED_STACK:
(TransitionMU)
000000000390A9A0 00007FFC051FC66B MyInterceptModule_Clr20!MyInterceptModule.Profiler.Intercept.StackBuilderSinkSyncProcessMessage2000_Intercept(System.Object, Boolean ByRef, System.Runtime.Remoting.Messaging.IMessage)+0x9b
000000000390ABA0 00007FFC051FABAD mscorlib!System.Runtime.Remoting.Messaging.StackBuilderSink.SyncProcessMessage(System.Runtime.Remoting.Messaging.IMessage)+0x3d
000000000390AC10 00007FFC051FAADD mscorlib!System.Runtime.Remoting.Messaging.ServerObjectTerminatorSink.SyncProcessMessage(System.Runtime.Remoting.Messaging.IMessage)+0x9d
...[생략]...
(TransitionUM)
(TransitionMU)
000000000390E1E0 00007FFC04FF5187 ReportingServicesLibrary!Microsoft.ReportingServices.Library.ServiceAppDomainController.StartServiceInNewAppDomain(Boolean)+0x207
000000000390E290 00007FFC04C45E60 ReportingServicesLibrary!Microsoft.ReportingServices.Library.ServiceAppDomainController.StartInternal(System.Object)+0x220
000000000390E370 00007FFC04C32AAF mscorlib!System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object)+0x7f
000000000390E3C0 00007FFC04C44550 mscorlib!System.Threading.ThreadHelper.ThreadStart(System.Object)+0x60
(TransitionUM)
MANAGED_STACK_COMMAND: _EFN_StackTrace
LAST_CONTROL_TRANSFER: from 00007ffc051fc66b to 00007ffc641aa12e
...[생략]...
SYMBOL_NAME: MyInterceptModule_clr20!MyInterceptModule.Profiler.Intercept.StackBuilderSinkSyncProcessMessage2000_Intercept
FOLLOWUP_NAME: MachineOwner
MODULE_NAME: MyInterceptModule_clr20
IMAGE_NAME: MyInterceptModule.Clr20.dll
STACK_COMMAND: _EFN_StackTrace ; ** Pseudo Context ** ; kb
BUCKET_ID: WRONG_SYMBOLS
FAILURE_BUCKET_ID: NULL_CLASS_PTR_DEREFERENCE_CALL_c0000005_MyInterceptModule.Clr20.dll!MyInterceptModule.Profiler.Intercept.StackBuilderSinkSyncProcessMessage2000_Intercept
...[생략]...
분명히 callstack 상에 제 모듈이 있기 때문에 잘못된 것은 알겠지만 아쉽게도 오류 위치가 mscorwks라서 뭐가 문제인지 도대체 알 수가 없었습니다.
mscorwks!IEE+cfd6
00007ffc`641aa12e 48f7440a2801000000 test qword ptr [rdx+rcx+28h],1
이 단서에서 어떤 것을 찾아낼 수 있을지 PDB 연결을 한 후 디버깅을 해볼까요? ^^
0:010> sxe ld MyInterceptModule.Clr20; g
ModLoad: 00000000`09e30000 00000000`09ebc000 MyInterceptModule.Clr20.dll
ntdll!ZwMapViewOfSection+0xa:
00007ffc`74b167fa c3 ret
재미있는 건 이후로 2번 더 sxe ld로 인한 BP가 걸리게 됩니다.
0:010> g
ModLoad: 00000000`09f10000 00000000`09f9c000 MyInterceptModule.Clr20.dll
ntdll!ZwMapViewOfSection+0xa:
00007ffc`74b167fa c3 ret
0:010> g
ModLoad: 00000000`09e50000 00000000`09edc000 C:\Windows\assembly\GAC_MSIL\MyInterceptModule.Clr20\1.0.1.0__cc862a9be44088eb\MyInterceptModule.Clr20.dll
ntdll!ZwMapViewOfSection+0xa:
00007ffc`74b167fa c3 ret
여기까지 진행해도 MyInterceptModule.Clr20 어셈블리에 구현된 코드에 bpmd를 이용해 BP를 걸 수는 없습니다. 왜냐하면 메타데이터에 대한 처리가 된 것은 아니기 때문에 SOS에서 처리할 수 없습니다.
그래서 일단 제가 테스트한 코드가 가로채기할 대상 메서드가 실행되는 시점으로 BP를 잡고,
0:010> !bpmd mscorlib System.Runtime.Remoting.Messaging.StackBuilderSink.SyncProcessMessage
Found 2 methods...
MethodDesc = 00007ffc049b9fa8
MethodDesc = 00007ffc049b9fb0
Adding pending breakpoints...
(SyncProcessMessage 메서드의 경우 오버로드된 메서드가 2개가 있어 저렇게 2개가 걸립니다.)
진행하면 이제 SyncProcessMessage가 실행되는 시점에 멈춥니다.
0:010> g
(184c.11cc): CLR notification exception - code e0444143 (first chance)
JITTED mscorlib!System.Runtime.Remoting.Messaging.StackBuilderSink.SyncProcessMessage(System.Runtime.Remoting.Messaging.IMessage)
Setting breakpoint: bp 00007FFC051FAB70 [System.Runtime.Remoting.Messaging.StackBuilderSink.SyncProcessMessage(System.Runtime.Remoting.Messaging.IMessage)]
Breakpoint 0 hit
00007ffc`051fab70 53 push rbx
여기까지 왔으니 name2ee로 원래의 제 메서드를 풀이하고,
0:010> !name2ee MyInterceptModule.Clr20.dll!MyInterceptModule.Intercept.StackBuilderSinkSyncProcessMessage2000_Intercept
Module: 00007ffc05261e00 (MyInterceptModule.Clr20.dll)
Token: 0x000000000600008a
MethodDesc: 00007ffc05263ca8
Name: MyInterceptModule.Intercept.StackBuilderSinkSyncProcessMessage2000_Intercept(System.Object, Boolean ByRef, System.Runtime.Remoting.Messaging.IMessage)
Not JITTED yet. Use !bpmd -md 00007ffc05263ca8 to break on run.
아직 JIT 컴파일되진 않았지만 MethodDesc값을 구했으므로 sos를 이용해 BP를 걸 수는 있습니다.
0:010> !bpmd -md 00007ffc05253ca8
MethodDesc = 00007ffc05253ca8
Adding pending breakpoints...
여기서 SyncProcessMessage 메서드를 역어셈블해서 제가 만든 가로채기 메서드가 어떻게 심어져 있는지 볼까요?
0:010> !U 00007ffc049b9fa8
Normal JIT generated code
System.Runtime.Remoting.Messaging.StackBuilderSink.SyncProcessMessage(System.Runtime.Remoting.Messaging.IMessage)
Begin 00007ffc051fab70, size ca
00007ffc`051fab70 53 push rbx
00007ffc`051fab71 55 push rbp
00007ffc`051fab72 57 push rdi
00007ffc`051fab73 4883ec50 sub rsp,50h
00007ffc`051fab77 488d6c2420 lea rbp,[rsp+20h]
00007ffc`051fab7c 488bfa mov rdi,rdx
00007ffc`051fab7f 488bd9 mov rbx,rcx
00007ffc`051fab82 48895d50 mov qword ptr [rbp+50h],rbx
00007ffc`051fab86 48896500 mov qword ptr [rbp],rsp
00007ffc`051fab8a 48c7451000000000 mov qword ptr [rbp+10h],0
00007ffc`051fab92 c6450800 mov byte ptr [rbp+8],0
00007ffc`051fab96 48c7451800000000 mov qword ptr [rbp+18h],0
00007ffc`051fab9e 4c8bc7 mov r8,rdi
00007ffc`051faba1 488d5508 lea rdx,[rbp+8]
00007ffc`051faba5 488bcb mov rcx,rbx
00007ffc`051faba8 e80b630400 call 00007ffc`05240eb8 (MyInterceptModule.Intercept.StackBuilderSinkSyncProcessMessage2000_Intercept(System.Object, Boolean ByRef, System.Runtime.Remoting.Messaging.IMessage), mdToken: 0600008a)
00007ffc`051fabad 48894520 mov qword ptr [rbp+20h],rax
00007ffc`051fabb1 0fb64508 movzx eax,byte ptr [rbp+8]
00007ffc`051fabb5 85c0 test eax,eax
00007ffc`051fabb7 7517 jne 00007ffc`051fabd0
00007ffc`051fabb9 488b03 mov rax,qword ptr [rbx]
00007ffc`051fabbc 4533c9 xor r9d,r9d
00007ffc`051fabbf 4533c0 xor r8d,r8d
00007ffc`051fabc2 488bd7 mov rdx,rdi
00007ffc`051fabc5 488bcb mov rcx,rbx
00007ffc`051fabc8 ff5068 call qword ptr [rax+68h]
00007ffc`051fabcb 48894518 mov qword ptr [rbp+18h],rax
00007ffc`051fabcf 90 nop
...[생략]...
00007ffc`051fac38 f3c3 rep ret
"call 00007ffc`05240eb8" 호출이 한번 된 다음 JIT 된 시점에 보면 역어셈블 결과가 다음과 같이 나옵니다.
0:010> !U 00007ffc05253ca8
Normal JIT generated code
MyInterceptModule.Intercept.StackBuilderSinkSyncProcessMessage2000_Intercept(System.Object, Boolean ByRef, System.Runtime.Remoting.Messaging.IMessage)
Begin 00007ffc051fdd00, size 59
00007ffc`051fdd00 4c89442418 mov qword ptr [rsp+18h],r8
00007ffc`051fdd05 4889542410 mov qword ptr [rsp+10h],rdx
00007ffc`051fdd0a 48894c2408 mov qword ptr [rsp+8],rcx
00007ffc`051fdd0f 4883ec38 sub rsp,38h
00007ffc`051fdd13 48c744242000000000 mov qword ptr [rsp+20h],0
00007ffc`051fdd1c 48b800212505fc7f0000 mov rax,7FFC05252100h
00007ffc`051fdd26 8b00 mov eax,dword ptr [rax]
00007ffc`051fdd28 85c0 test eax,eax
00007ffc`051fdd2a 7405 je 00007ffc`051fdd31
00007ffc`051fdd2c e8afbb205f call mscorwks!JIT_DbgIsJustMyCode (00007ffc`644098e0)
00007ffc`051fdd31 ba02000000 mov edx,2
00007ffc`051fdd36 b90b000000 mov ecx,0Bh
00007ffc`051fdd3b e8e0cffa5e call mscorwks!JIT_GetSharedNonGCStaticBase_InlineGetAppDomain (00007ffc`641aad20)
00007ffc`051fdd40 90 nop
00007ffc`051fdd41 48c744242000000000 mov qword ptr [rsp+20h],0
00007ffc`051fdd4a eb00 jmp 00007ffc`051fdd4c
00007ffc`051fdd4c 488b442420 mov rax,qword ptr [rsp+20h]
00007ffc`051fdd51 eb00 jmp 00007ffc`051fdd53
00007ffc`051fdd53 4883c438 add rsp,38h
00007ffc`051fdd57 f3c3 rep ret
문제가 발생한 라인은 mscorwks!JIT_GetSharedNonGCStaticBase_InlineGetAppDomain 메서드 호출이었습니다. 그 바로 위에 보면 ecx와 edx에 2와 0x0b 값을 전달하는 것으로 봐서 JIT_GetSharedNonGCStaticBase_InlineGetAppDomain 함수는 fastcall 방식으로 보입니다.
계속해서 JIT_GetSharedNonGCStaticBase_InlineGetAppDomain을 역어셈블해서 실행을 추적해 보면,
0:010> !U 00007ffc`641aad20
Unmanaged code
00007ffc`641aad20 e9ebf3ffff jmp mscorwks!JIT_GetSharedNonGCStaticBase_Slow (00007ffc`641aa110)
00007ffc`641aad25 0100 add dword ptr [rax],eax
00007ffc`641aad27 0000 add byte ptr [rax],al
00007ffc`641aad29 7415 je mscorwks!JIT_GetSharedNonGCStaticBase__PatchTLSLabel+0x15 (00007ffc`641aad40)
00007ffc`641aad2b 65488b042580140000 mov rax,qword ptr gs:[1480h]
00007ffc`641aad34 488b80a8070000 mov rax,qword ptr [rax+7A8h]
00007ffc`641aad3b 488b4488fc mov rax,qword ptr [rax+rcx*4-4]
00007ffc`641aad40 f644022801 test byte ptr [rdx+rax+28h],1
00007ffc`641aad45 7409 je mscorwks!JIT_GetSharedNonGCStaticBase__PatchTLSLabel+0x25 (00007ffc`641aad50)
00007ffc`641aad47 f3c3 rep ret
다시 내부에서는 mscorwks!JIT_GetSharedNonGCStaticBase_Slow 메서드로 곧장 jmp 합니다.
0:010> !U 00007ffc`641aa110
Unmanaged code
00007ffc`641aa110 4883ec28 sub rsp,28h
00007ffc`641aa114 48f7c101000000 test rcx,1
00007ffc`641aa11b 7411 je mscorwks!JIT_GetSharedNonGCStaticBase_Slow+0x1e (00007ffc`641aa12e)
00007ffc`641aa11d e8bedbffff call mscorwks!GetAppDomain (00007ffc`641a7ce0)
00007ffc`641aa122 488b80a8070000 mov rax,qword ptr [rax+7A8h]
00007ffc`641aa129 488b4c88fc mov rcx,qword ptr [rax+rcx*4-4]
00007ffc`641aa12e 48f7440a2801000000 test qword ptr [rdx+rcx+28h],1
자... crash가 발생한 곳까지 드디어 왔습니다. 아래의 "test qword ptr [rdx+rcx+28h],1" 코드를 수행하면서 "Access violation" 예외가 발생한 것인데요. rcx가 바로 위 라인에서 덮어써졌기 때문에 GetAppDomain의 결과로 rax, rcx의 값에 도대체 어떤 값이 넘어오는지 궁금했습니다.
일단 추적으로 계속해 보면 현재 rcx 레지스터의 값은 이전에 JIT_GetSharedNonGCStaticBase_InlineGetAppDomain 인자로 전달했던 값이어서 1이 아니므로 "call mscorwks!GetAppDomain" 호출로 연결됩니다.
0:010> !U 00007ffc`641a7ce0
Unmanaged code
00007ffc`641a7ce0 eb11 jmp mscorwks!GetAppDomain_PrologStart (00007ffc`641a7cf3)
00007ffc`641a7ce2 c3 ret
휴~~~ 길군요. ^^ 계속 들어갑니다.
0:010> u 00007ffc`641a7cf3
mscorwks!GetAppDomain_PrologStart:
00007ffc`641a7cf3 4152 push r10
00007ffc`641a7cf5 4153 push r11
00007ffc`641a7cf7 4883ec28 sub rsp,28h
00007ffc`641a7cfb 48894c2440 mov qword ptr [rsp+40h],rcx
00007ffc`641a7d00 4889542448 mov qword ptr [rsp+48h],rdx
00007ffc`641a7d05 4c89442450 mov qword ptr [rsp+50h],r8
00007ffc`641a7d0a 4c894c2458 mov qword ptr [rsp+58h],r9
00007ffc`641a7d0f 65488b042568000000 mov rax,qword ptr gs:[68h]
rcx, rdx는 최초의 JIT_GetSharedNonGCStaticBase_InlineGetAppDomain 메서드 호출에서 전달되었던 값이고 r8, r9는 잘 모르겠습니다. 이후 gs:[68h]가 나오는데, x64에서 GS는 TEB를 가리키는 데 사용되므로 [68h] 위치의 값은 다음과 같이 확인할 수 있습니다.
0:010> dt ntdll!_TEB @$teb
+0x000 NtTib : _NT_TIB
+0x038 EnvironmentPointer : (null)
+0x040 ClientId : _CLIENT_ID
+0x050 ActiveRpcHandle : (null)
+0x058 ThreadLocalStoragePointer : 0x00000000`010ebb30 Void
+0x060 ProcessEnvironmentBlock : 0x00007ff5`ff9cc000 _PEB
+0x068 LastErrorValue : 0
+0x06c CountOfOwnedCriticalSections : 0
+0x070 CsrClientThread : (null)
...[생략]...
그냥 GetLastError API를 호출한 효과겠군요. ^^ 계속해서 값을 역어셈블하고,
00007ffc`641a7d05 4c89442450 mov qword ptr [rsp+50h],r8 ss:00000000`0404add0=00000002c7ff0098
00007ffc`641a7d0a 4c894c2458 mov qword ptr [rsp+58h],r9 ss:00000000`0404add8=000000024814efc0
00007ffc`641a7d0f 65488b042568000000 mov rax,qword ptr gs:[68h] gs:00000000`00000068=????????????????
00007ffc`641a7d18 4889442420 mov qword ptr [rsp+20h],rax ss:00000000`0404ada0=0000000000000001
00007ffc`641a7d1d 8b0d65866100 mov ecx,dword ptr [mscorwks!gAppDomainTLSIndex (00007ffc`647c0388)] ds:00007ffc`647c0388=0000004a
00007ffc`641a7d23 ff151797d4ff call qword ptr [mscorwks!_imp_TlsGetValue (00007ffc`63ef1440)] ds:00007ffc`63ef1440={KERNEL32!TlsGetValueStub (00007ffc`72ef1370)}
00007ffc`641a7d29 488b4c2420 mov rcx,qword ptr [rsp+20h] ss:00000000`0404ada0=0000000000000000
00007ffc`641a7d2e 6548890c2568000000 mov qword ptr gs:[68h],rcx gs:00000000`00000068=????????????????
00007ffc`641a7d37 488b4c2440 mov rcx,qword ptr [rsp+40h] ss:00000000`0404adc0=000000000000000b
00007ffc`641a7d3c 488b542448 mov rdx,qword ptr [rsp+48h] ss:00000000`0404adc8=0000000000000002
00007ffc`641a7d41 4c8b442450 mov r8,qword ptr [rsp+50h] ss:00000000`0404add0=000000024814efc0
00007ffc`641a7d46 4c8b4c2458 mov r9,qword ptr [rsp+58h] ss:00000000`0404add8=0000000000000001
00007ffc`641a7d4b 4883c428 add rsp,28h
00007ffc`641a7d4f 415b pop r11
00007ffc`641a7d51 415a pop r10
00007ffc`641a7d53 c3 ret
끝나는 시점 즈음에 레지스터 값을 확인해 보면 이제 crash가 발생한 시점의 rax, rcx 값을 구할 수 있습니다.
0:010> r
rax=00000001f82be040 rbx=000000024814d4c8 rcx=000000000000000b
rdx=0000000000000002 rsi=000000024814d4b0 rdi=000000024814efc0
rip=00007ffc641a7d4f rsp=000000000404ad80 rbp=000000000404ae50
r8=000000024814efc0 r9=0000000000000001 r10=00007ffc049248c8
r11=00007ffc04840000 r12=00007ffc04acddc0 r13=0000000000000000
r14=0000000000000000 r15=0000000000000002
iopl=0 nv up ei pl nz na pe nc
cs=0033 ss=002b ds=002b es=002b fs=0053 gs=002b efl=00000202
리턴을 해서 mscorwks!GetAppDomain 코드를 호출한 다음부터 추적을 계속하면,
00007ffc`641aa11d e8bedbffff call mscorwks!GetAppDomain (00007ffc`641a7ce0)
00007ffc`641aa122 488b80a8070000 mov rax,qword ptr [rax+7A8h]
00007ffc`641aa129 488b4c88fc mov rcx,qword ptr [rax+rcx*4-4]
00007ffc`641aa12e 48f7440a2801000000 test qword ptr [rdx+rcx+28h],1
이제 [00000001f82be040 + 7a8h] 주소의 값을 덤프하고, 거기서 [rax+rcx*4 - 4]를 대입하니 0이 나옵니다. rdx의 경우 최초 JIT_GetSharedNonGCStaticBase_InlineGetAppDomain에 전달했던 2가 그대로 보존되어 있어서 결국 [2 + 0 + 28h]가 되어 [2ah] 주소 값을 구하게 되는데 바로 그 지점의 메모리를 접근하는 것이 "!analyze -v" 결과에 나왔던 것처럼 "Access violation - Attempt to read from address 000000000000002a"로 crash된 것입니다.
그래서 뭘 얻었냐고요? ^^; mscorwks!GetAppDomain 메서드 내부를 어셈블리 수준에서 추적한 것으로는 직접적으로 알 수 있는 결과는 없었습니다. 단지, 거기까지 추적해 본 것은 제 디버깅 능력을 향상시키기 위해서 가본 것일 뿐 그 이상의 의미는 없습니다.
오히려 좌절을 느낄 수밖에 없었는데요. 저는 이 문제를 최대한 간단하게 만들기 위해 가로채기 들어가는 제 메서드의 코드를 전부 삭제했는데도 그와 같은 문제가 발생한 것입니다.
static void MyInterceptModule.Intercept.StackBuilderSinkSyncProcessMessage2000_Intercept(...)
{
return null;
}
그런데도 JIT 컴파일 된 어셈블리에는 crash를 발생시키게 되는 JIT_GetSharedNonGCStaticBase_InlineGetAppDomain 호출이 무조건 포함되어 있었습니다.
00007ffc`051fdd00 4c89442418 mov qword ptr [rsp+18h],r8
00007ffc`051fdd05 4889542410 mov qword ptr [rsp+10h],rdx
00007ffc`051fdd0a 48894c2408 mov qword ptr [rsp+8],rcx
00007ffc`051fdd0f 4883ec38 sub rsp,38h
00007ffc`051fdd13 48c744242000000000 mov qword ptr [rsp+20h],0
00007ffc`051fdd1c 48b800212505fc7f0000 mov rax,7FFC05252100h
00007ffc`051fdd26 8b00 mov eax,dword ptr [rax]
00007ffc`051fdd28 85c0 test eax,eax
00007ffc`051fdd2a 7405 je 00007ffc`051fdd31
00007ffc`051fdd2c e8afbb205f call mscorwks!JIT_DbgIsJustMyCode (00007ffc`644098e0)
00007ffc`051fdd31 ba02000000 mov edx,2
00007ffc`051fdd36 b90b000000 mov ecx,0Bh
00007ffc`051fdd3b e8e0cffa5e call mscorwks!JIT_GetSharedNonGCStaticBase_InlineGetAppDomain (00007ffc`641aad20)
00007ffc`051fdd40 90 nop
00007ffc`051fdd41 48c744242000000000 mov qword ptr [rsp+20h],0
00007ffc`051fdd4a eb00 jmp 00007ffc`051fdd4c
00007ffc`051fdd4c 488b442420 mov rax,qword ptr [rsp+20h]
00007ffc`051fdd51 eb00 jmp 00007ffc`051fdd53
00007ffc`051fdd53 4883c438 add rsp,38h
00007ffc`051fdd57 f3c3 rep ret
다행인 점은 그래도 문제를 해결할 수 있는 힌트를 중간에 호출되었던 메서드의 이름에서 찾을 수 있었다는 것입니다.
JIT_GetSharedNonGCStaticBase_InlineGetAppDomain
JIT_GetSharedNonGCStaticBase_Slow
JIT_GetSharedNonGCStaticBase__PatchTLSLabel
mscorwks!GetAppDomain
여기서 제가 그동안 공부해왔던 것들로부터 지식이 종합이 되어 순간적으로 해결 단서가 보였습니다. 닷넷 응용 프로그램은 static 변수를 AppDomain별로 관리한다는 사실과 제가 가로채기를 한 메서드가 구현되는 클래스에는 static 변수 및 static 생성자가 있었다는 점입니다.
그래서 혹시나 싶어 static 생성자가 발생할 수 있는 모든 경우를 삭제하고 static 생성자마저 지우고 나서 테스트를 하니 위의 crash 문제가 사라졌습니다. 그리고 이 때의 StackBuilderSinkSyncProcessMessage2000_Intercept 메서드를 역어셈블 해보면 다음과 같이 JIT_GetSharedNonGCStaticBase_InlineGetAppDomain API 호출이 사라진 것을 볼 수 있습니다.
0:055> !U 00007ffc05262dd8
Normal JIT generated code
MyInterceptModule.Intercept.StackBuilderSinkSyncProcessMessage2000_Intercept(System.Object, Boolean ByRef, System.Runtime.Remoting.Messaging.IMessage)
Begin 00007ffc05209ff0, size 4a
00007ffc`05209ff0 4c89442418 mov qword ptr [rsp+18h],r8
00007ffc`05209ff5 4889542410 mov qword ptr [rsp+10h],rdx
00007ffc`05209ffa 48894c2408 mov qword ptr [rsp+8],rcx
00007ffc`05209fff 4883ec38 sub rsp,38h
00007ffc`0520a003 48c744242000000000 mov qword ptr [rsp+20h],0
00007ffc`0520a00c 48b800212605fc7f0000 mov rax,7FFC05262100h
00007ffc`0520a016 8b00 mov eax,dword ptr [rax]
00007ffc`0520a018 85c0 test eax,eax
00007ffc`0520a01a 7405 je 00007ffc`0520a021
00007ffc`0520a01c e8bff81f5f call mscorwks!JIT_DbgIsJustMyCode (00007ffc`644098e0)
00007ffc`0520a021 90 nop
00007ffc`0520a022 48c744242000000000 mov qword ptr [rsp+20h],0
00007ffc`0520a02b eb00 jmp 00007ffc`0520a02d
00007ffc`0520a02d 488b442420 mov rax,qword ptr [rsp+20h]
00007ffc`0520a032 eb00 jmp 00007ffc`0520a034
00007ffc`0520a034 4883c438 add rsp,38h
00007ffc`0520a038 f3c3 rep ret
결국, AppDomain 초기화 시점에 내부적으로 static 관련 클래스 초기화를 하면서 crash가 된 것입니다.
처음 crash가 발생했을 때는 정말 막막했습니다. mscorwks라니... ^^; 저더러 어떡하라는 겁니까? 그래도 제가 windbg를 구성해서 PDB를 연결해 기어이 내부까지 한번 들어가 본 것은 그만한 이유가 있습니다. 예를 들어, PDB가 연결되지 않은 경우에는 mscorwks!JIT_GetSharedNonGCStaticBase_InlineGetAppDomain 호출이 이름 풀이가 되지 않아 다음과 같이 나와 버립니다.
00007ffc`051fc65c ba02000000 mov edx,2
00007ffc`051fc661 b90b000000 mov ecx,0Bh
00007ffc`051fc666 e8b5e6fa5e call mscorwks!IEE+0xdbc8 (00007ffc`641aad20) (mscorwks!IEE)
PDB가 연결되지 않아 "mscorwks!IEE+0xdbc8" 이런 식으로 메서드 호출이 보여지는 경우, 아마 저는 AppDomain과 static 저장소에 관한 힌트를 생각해내지 못했을 수 있습니다.
사실, 정리해 놓고 보니 금방 여기까지 결론이 온 것 같은데 실은 NT 서비스 디버깅하는 환경을 구성하는 적절한 방법과 PDB 파일 문제로 인해 시간이 제법 걸렸었습니다. 자잘하게 너무 시간이 걸리다 보니 중간 즈음에는 그냥 (언제가 될진 모르지만 그냥 안전하게) 일정 시점 뒤로 StackBuilderSinkSyncProcessMessage2000_Intercept 메서드를 호출하지 않도록 미룰까... 하는 꼼수 처리 방법까지 생각해 봤는데요. 그래도 그건 아니겠다 싶어서 시간을 갖고 기어이 추적을 해본 것입니다.
다행히 이렇게 결론이 났고 닷넷의 버그인지, 원래 그렇게 쓰면 안되는 것인지 까지는 모르겠으나 직접적인 문제를 우회할 수 있는 방법을 알게 되었습니다. 이제 좀 마음 편히 한숨 잘 수 있겠군요. ^^
[이 글에 대해서 여러분들과 의견을 공유하고 싶습니다. 틀리거나 미흡한 부분 또는 의문 사항이 있으시면 언제든 댓글 남겨주십시오.]