windbg 분석 사례 - ODP.NET 사용 시 Finalizer에서 System.AccessViolationException 예외 발생으로 인한 비정상 종료
미리 말하면 이번 글은 정답이 없습니다. 게다가 굳이 windbg까지 갈 필요 없이 그냥 이벤트 로그의 정보만으로도,
アプリケ?ション:w3wp.exe
フレ?ムワ?クのバ?ジョン: v4.0.30319
?明: ハンドルされない例外のため、プロセスが中止されました。
例外情報: System.AccessViolationException
スタック:
場所 Oracle.DataAccess.Client.OpsMet.FreeValCtx(Oracle.DataAccess.Client.OpoMetValCtx*)
場所 Oracle.DataAccess.Client.OpsMet.FreeValCtx(Oracle.DataAccess.Client.OpoMetValCtx*)
場所 Oracle.DataAccess.Client.MetaData.Finalize()
문제를 인지할 수 있습니다. 호출 스택에서 볼 수 있는 바와 같이, Finalize 메서드가 CLR의 Finalizer 스레드에 의해 실행 중 System.AccessViolationException 예외가 발생하고 있습니다. Finalizer에서 예외가 발생하는 경우,
windbg 분석 사례 - 종료자(Finalizer)에서 예외가 발생한 경우 비정상 종료(Crash) 발생
; https://www.sysnet.pe.kr/2/0/11732
비정상 종료(crash)가 발생하긴 하지만, 이번 사례에서는 Finalizer가 아니더라도 System.AccessViolationException 예외가 발생한 이상 무조건 비정상 종료하게 되어 있습니다. 위의 오류가 발생할 때 덤프를 떠서 windbg로 열어 보면,
This dump file has an exception of interest stored in it.
The stored exception information can be accessed via .ecxr.
(14a4.19e4): Access violation - code c0000005 (first/second chance not available)
ntdll!RtlFreeHeap+0x2a9:
000007f9`db9a5558 4c8b6f08 mov r13,qword ptr [rdi+8] ds:0000094a`5b84e748=????????????????
0:024> !clrstack
OS Thread Id: 0x19e4 (24)
Child SP IP Call Site
000000182419ec18 000007f9db9a5558 [InlinedCallFrame: 000000182419ec18] Oracle.DataAccess.Client.OpsMet.FreeValCtx(Oracle.DataAccess.Client.OpoMetValCtx*)
000000182419ec18 000007f974bc7248 [InlinedCallFrame: 000000182419ec18] Oracle.DataAccess.Client.OpsMet.FreeValCtx(Oracle.DataAccess.Client.OpoMetValCtx*)
000000182419ebf0 000007f974bc7248 DomainNeutralILStubClass.IL_STUB_PInvoke(Oracle.DataAccess.Client.OpoMetValCtx*)
000000182419ecc0 000007f974de081e Oracle.DataAccess.Client.MetaData.Finalize()
000000182419f0c8 000007f9d36fc446 [DebuggerU2MCatchHandlerFrame: 000000182419f0c8]
000000182419f268 000007f9d36fc446 [ContextTransitionFrame: 000000182419f268]
000000182419f360 000007f9d36fc446 [GCFrame: 000000182419f360]
000000182419f5d8 000007f9d36fc446 [DebuggerU2MCatchHandlerFrame: 000000182419f5d8]
이벤트 로그와 동일합니다. 처음엔, 위의 상황을 보고 할당과 해제의 균형이 맞지 않는 것이므로 ODP.NET 모듈들의 버전이 뭔가 섞인 것이 아닌가 생각되어 버전 확인을 먼저 해봤습니다.
0:024> lmvm Oracle_DataAccess
Browse full module list
start end module name
00000018`29d90000 00000018`29f00000 Oracle_DataAccess (no symbols)
Loaded symbol image file: Oracle.DataAccess.dll
Image path: C:\Windows\Microsoft.Net\assembly\GAC_64\Oracle.DataAccess\v4.0_4.112.4.0__89b483f429c47342\Oracle.DataAccess.dll
Image name: Oracle.DataAccess.dll
Browse all global symbols functions data
Has CLR image header, track-debug-data flag not set
Timestamp: Tue Sep 17 06:13:07 2013 (52385563)
CheckSum: 0017715C
ImageSize: 00170000
File version: 4.112.4.0
Product version: 4.112.4.0
File flags: 0 (Mask 3F)
File OS: 4 Unknown Win32
File type: 2.0 Dll
File date: 00000000.00000000
Translations: 0000.04b0
Information from resource tables:
CompanyName: Oracle Corporation
ProductName: Oracle Data Provider for .NET
InternalName: Oracle.DataAccess.dll
OriginalFilename: Oracle.DataAccess.dll
ProductVersion: 4.112.4.0
FileVersion: 4.112.4.0
FileDescription: Oracle.DataAccess.dll
LegalCopyright: Copyright (C) Oracle Corporation 1998-2013. All Rights Reserved.
Comments: Oracle.DataAccess.dll
0:024> lmvm oci
Browse full module list
start end module name
00000018`2a310000 00000018`2a3c4000 oci (deferred)
Image path: c:\product\11.2.0\client_1\BIN\oci.dll
Image name: oci.dll
Browse all global symbols functions data
Timestamp: Wed Oct 9 13:06:56 2013 (5255B760)
CheckSum: 000B42C3
ImageSize: 000B4000
File version: 11.2.0.1
Product version: 0.0.0.0
File flags: 0 (Mask 0)
File OS: 0 Unknown Base
File type: 0.0 Unknown
File date: 00000000.00000000
Translations: 0409.04b0
Information from resource tables:
CompanyName: Oracle Corporation
OriginalFilename: Oci.dll
FileVersion: 11.2.0.1.0 Production
FileDescription: Oracle Call Interface
0:024> lmvm oraops11w
Browse full module list
start end module name
00000001`80000000 00000001`80068000 OraOps11w (export symbols) OraOps11w.dll
Loaded symbol image file: OraOps11w.dll
Image path: c:\product\11.2.0\client_1\BIN\OraOps11w.dll
Image name: OraOps11w.dll
Browse all global symbols functions data
Timestamp: Tue Sep 17 06:12:13 2013 (5238552D)
CheckSum: 0006AF0C
ImageSize: 00068000
File version: 2.112.4.0
Product version: 2.112.4.0
File flags: 0 (Mask 3F)
File OS: 4 Unknown Win32
File type: 2.0 Dll
File date: 00000000.00000000
Translations: 0409.04b0
Information from resource tables:
CompanyName: Oracle Corporation
ProductName: Oracle Data Provider for .NET
InternalName: OraOps
OriginalFilename: OraOps11w.dll
ProductVersion: 2.112.4.0
FileVersion: 2.112.4.0
FileDescription: Oracle Provider Services
LegalCopyright: Copyright ⓒ 2013
대충 찾아보면 112 버전과 oci의 11.2가 한 쌍으로 명명하는 듯한데,
Oracle.DataAccess.dll - 4.112.4.0
oci.dll - 11.2.0.1
OraOps11w.dll - 2.112.4.0
그런 의미에서 버전 문제는 아닌 것 같습니다. 재미 삼아 ^^ 좀 더 아래로 내려가보면,
0:024> kv
# Child-SP RetAddr : Args to Child : Call Site
00 00000018`2419eac0 000007f9`db791172 : 000007f9`d36ca7bd 00000018`39a18e10 000007f9`74de0960 000007f9`d36a4859 : ntdll!RtlFreeHeap+0x2a9
*** ERROR: Symbol file could not be found. Defaulted to export symbols for OraOps11w.dll -
01 00000018`2419eb60 00000001`80011c6f : 00000014`00000000 00000000`00000001 00000018`2419ef10 000007f9`74bb89ed : combase!CoTaskMemFree+0x36
02 00000018`2419eb90 00000001`80020aa4 : 00000018`39a18e10 00000018`39a18ef0 00000014`5feda898 000007f9`d3d454b0 : OraOps11w!ssmem_free+0xf
03 00000018`2419ebc0 000007f9`74bc7248 : 000007f9`74cb1110 00000018`2419ebb0 00000000`00000000 00000018`2419ebd0 : OraOps11w!OpsMetFreeValCtx+0x54
04 00000018`2419ebf0 000007f9`74de081e : 00000018`396f0fa0 00000000`00000000 00000018`2419ed00 000007f9`74de098a : 0x000007f9`74bc7248
05 00000018`2419ecc0 000007f9`d36fc446 : 00000014`5feda3e8 00000000`00000000 00000000`00000000 00000000`0000000d : 0x000007f9`74de081e
06 00000018`2419ed20 000007f9`d37be6ae : 00000000`000000c0 000007f9`d36ff1c9 00000013`d73e0120 000007f9`db9abac2 : clr!CreateAssemblyNameObject+0x38386
07 00000018`2419ed50 000007f9`d37be623 : 000007f9`74de07e0 00000000`00000000 000007f9`74c4a978 00000018`2419f0c8 : clr!CreateApplicationContext+0x15d7e
08 00000018`2419ed90 000007f9`d37be56f : 00000014`5feda3e8 000007f9`d37be73c 00000014`5feda3e8 000007f9`74c4a978 : clr!CreateApplicationContext+0x15cf3
09 00000018`2419edd0 000007f9`d37d0d66 : 00000000`00000000 00000018`2419ee69 00000014`5ff70e98 00000000`00000000 : clr!CreateApplicationContext+0x15c3f
0a 00000018`2419ee10 000007f9`d37d072b : 00000014`5feda3e8 00000013`00000411 00000000`00000000 00000000`000003d0 : clr!CopyPDBs+0x5176
0b 00000018`2419eed0 000007f9`d37cc7a7 : 00000001`27d78e00 00000018`2419f348 00000000`00000000 000007f9`c6fc1927 : clr!CopyPDBs+0x4b3b
0c 00000018`2419ef10 000007f9`d3732a2c : 00000018`273ba480 000007f9`dba8b4d9 ffffffff`fffffffe 00000018`276c76f0 : clr!CopyPDBs+0xbb7
0d 00000018`2419ef40 000007f9`d37329ba : 00000018`2419f640 00000018`2419f390 00000000`00000008 00000000`00000000 : clr!GetMetaDataInternalInterface+0x86d0
0e 00000018`2419ef80 000007f9`d3732931 : 00000000`00000001 00000018`27c55f60 00000013`d8cfabf0 000007f9`d36a315c : clr!GetMetaDataInternalInterface+0x865e
0f 00000018`2419f080 000007f9`d36db9fc : 00000018`2419f268 00000013`d8cfabf0 00000018`2419f640 00000013`dde1be01 : clr!GetMetaDataInternalInterface+0x85d5
10 00000018`2419f110 000007f9`d37afc8a : 00000000`00000000 00000018`24d9f720 00000018`2419f369 000007f9`d37bd9a7 : clr!CreateAssemblyNameObject+0x1793c
11 00000018`2419f140 000007f9`d37cc834 : 00000013`d8cfabf0 000007f9`d36a48e2 00000018`2419f640 00000013`dde1bef0 : clr!CreateApplicationContext+0x735a
12 00000018`2419f2d0 000007f9`d37cc8a4 : 00000000`00000000 00000018`2419f369 00000013`dde1bef0 00000018`24d9f720 : clr!CopyPDBs+0xc44
13 00000018`2419f310 000007f9`d37d072b : 00000013`dde1bef0 00000018`00000411 00000000`00000000 00000000`00000001 : clr!CopyPDBs+0xcb4
14 00000018`2419f3d0 000007f9`d37d0930 : 00000000`00000000 00000000`00000001 00000000`00000000 00000000`00000000 : clr!CopyPDBs+0x4b3b
15 00000018`2419f410 000007f9`d3732a2c : 00000000`00000000 00000018`2419f640 00000000`00000001 00000000`00001000 : clr!CopyPDBs+0x4d40
16 00000018`2419f450 000007f9`d37329ba : 00000018`2419f640 00000000`00000000 0000d111`daedd9c0 000007f9`d38b630a : clr!GetMetaDataInternalInterface+0x86d0
17 00000018`2419f490 000007f9`d3732931 : 00000000`00000000 000007f9`00000000 ffffffff`fffffffe 00000000`00000000 : clr!GetMetaDataInternalInterface+0x865e
18 00000018`2419f590 000007f9`d37d66fe : ffffffff`ffffffff 00000013`d8cfabf0 000007f9`d37d0890 00000000`00000001 : clr!GetMetaDataInternalInterface+0x85d5
19 00000018`2419f620 000007f9`d387e360 : 00000000`00000000 00000000`00000000 00000000`00000001 00000000`00000012 : clr!SetRuntimeInfo+0xaf2
1a 00000018`2419f680 000007f9`d36fadde : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : clr!NGenCreateNGenWorker+0x3164
1b 00000018`2419f6c0 000007f9`da551832 : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : clr!CreateAssemblyNameObject+0x36d1e
1c 00000018`2419f780 000007f9`db9fd609 : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : kernel32!BaseThreadInitThunk+0x1a
1d 00000018`2419f7b0 00000000`00000000 : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : ntdll!RtlUserThreadStart+0x1d
OraOps11w!OpsMetFreeValCtx 함수를 역어셈블 해,
0:024> u OraOps11w!OpsMetFreeValCtx
OraOps11w!OpsMetFreeValCtx:
00000001`80020a50 4883ec28 sub rsp,28h
00000001`80020a54 833d350f040000 cmp dword ptr [OraOps11w!OpsTSAAllocValCtxForToUTC+0x1bef0 (00000001`80061990)],0
00000001`80020a5b 48895c2430 mov qword ptr [rsp+30h],rbx
00000001`80020a60 488bd9 mov rbx,rcx
00000001`80020a63 7411 je OraOps11w!OpsMetFreeValCtx+0x26 (00000001`80020a76)
00000001`80020a65 488d15d4b30200 lea rdx,[OraOps11w!OpsTSAAllocValCtxForToUTC+0x63a0 (00000001`8004be40)]
00000001`80020a6c b901000000 mov ecx,1
00000001`80020a71 e87a640000 call OraOps11w!OpsCallTrace (00000001`80026ef0)
OraOps11w!OpsMetFreeValCtx+0x26:
00000001`80020a76 4885db test rbx,rbx
00000001`80020a79 0f84ad000000 je OraOps11w!OpsMetFreeValCtx+0xdc (00000001`80020b2c)
00000001`80020a7f 488bcb mov rcx,rbx
00000001`80020a82 e829ffffff call OraOps11w!OpsMetRelRef (00000001`800209b0)
00000001`80020a87 85c0 test eax,eax
00000001`80020a89 0f859d000000 jne OraOps11w!OpsMetFreeValCtx+0xdc (00000001`80020b2c)
00000001`80020a8f 48897c2420 mov qword ptr [rsp+20h],rdi
00000001`80020a94 33ff xor edi,edi
OraOps11w!OpsMetFreeValCtx+0x46:
00000001`80020a96 66393b cmp word ptr [rbx],di
00000001`80020a99 740d je OraOps11w!OpsMetFreeValCtx+0x58 (00000001`80020aa8)
00000001`80020a9b 488b4b20 mov rcx,qword ptr [rbx+20h]
00000001`80020a9f e8bc11ffff call OraOps11w!ssmem_free (00000001`80011c60)
00000001`80020aa4 48897b20 mov qword ptr [rbx+20h],rdi
00000001`80020aa8 48397b28 cmp qword ptr [rbx+28h],rdi
00000001`80020aac 7471 je OraOps11w!OpsMetFreeValCtx+0xcf (00000001`80020b1f)
00000001`80020aae 66393b cmp word ptr [rbx],di
...[생략]...
0:023> u OraOps11w!ssmem_free
OraOps11w!ssmem_free:
00000001`80011c60 4883ec28 sub rsp,28h
00000001`80011c64 4885c9 test rcx,rcx
00000001`80011c67 7406 je OraOps11w!ssmem_free+0xf (00000001`80011c6f)
00000001`80011c69 ff15d95e0300 call qword ptr [OraOps11w!OpsTSAAllocValCtxForToUTC+0x20a8 (00000001`80047b48)]
00000001`80011c6f b801000000 mov eax,1
00000001`80011c74 4883c428 add rsp,28h
00000001`80011c78 c3 ret
/*
라이브 상태에서 BreakPoint를 걸고 싶다면.
bp OraOps11w!OpsMetFreeValCtx
bp OraOps11w!ssmem_free
*/
오류가 발생한 곳은 저 지점입니다. 어떤 메모리를 해제하려다가 저런 예외가 발생했는지는 ODP.NET을 파일로 저장한 다음,
windbg - 풀 덤프에 포함된 모든 닷넷 모듈을 파일로 저장하는 방법
; https://www.sysnet.pe.kr/2/0/11297
OpoMetValCtx 구조체를 살펴보면 됩니다.
[StructLayout(LayoutKind.Sequential)]
public struct OpoMetValCtx
{
public short NoOfMetaAlloc;
public short NoOfCols;
public short NoOfHiddenCols;
public byte bHasLongCol;
public byte bHasLongLobBFileCol;
public byte bHasXmlType;
public byte bHasUdtType;
public byte bUdtInfoFetched;
public byte bHasDescCol;
public byte bPkFetched;
public byte bPkPresent;
public byte bPooled;
public int InitialLongFS;
public int InitialLobFS;
public byte bStmtParsed;
public unsafe ColMetaVal* pColMetaVal;
public IntPtr pOpoMetRefCtx;
public int CommandType;
public byte bRowidPresent;
public IntPtr pCommandText;
public IntPtr pNewCommandText;
public ushort NoOfBlobCols;
public ushort NoOfClobCols;
public ushort NoOfNClobCols;
public int RefCount;
public int NoOfDescCols;
public byte bChgNtfnRowidPresent;
}
구조체가 8바이트 정렬될 때, "mov rcx, qword ptr [rbx+20h]" 코드를 통해 [rbx + 20h]의 위치에 해당하는 것이 바로 저 ColMetaVal 멤버입니다. 이 멤버를 해제하는 방식은 COM의 CoTaskMemFree를 이용한다는 것을 Callstack을 통해 알 수 있으므로,
combase!CoTaskMemFree+0x36
OraOps11w!ssmem_free+0xf
OraOps11w!OpsMetFreeValCtx+0x54
이 멤버에 대한 할당 및 해제를 다음과 같은 닷넷 코드로 재현할 수 있습니다.
namespace WebSiteTest
{
public class OracleHelper
{
[DllImport("OraOps11w.dll", EntryPoint = "OpsMetFreeValCtx", CallingConvention = CallingConvention.Cdecl, CharSet = CharSet.Unicode)]
public static extern unsafe int FreeValCtx(MyOpoMetValCtx* pOpoMetValCtx);
[DllImport("OraOps11w.dll", EntryPoint = "ssmem_free", CallingConvention = CallingConvention.Cdecl, CharSet = CharSet.Unicode)]
public static extern unsafe int ssmem_free(MyColMetaVal* pOpoMetValCtx);
}
[StructLayout(LayoutKind.Sequential)]
public struct MyDacDef
{
public int Type;
public uint Length;
}
[StructLayout(LayoutKind.Sequential)]
public struct MyColMetaVal
{
public ushort Ordinal;
public ushort OraType;
public int Size;
public byte Precision;
public sbyte Scale;
public byte NullOK;
public byte Updatable;
public byte bIsUnique;
public byte bIsKeyColumn;
public byte bIsHiddenCol;
public byte bIsExpression;
public int bIsByteSemantic;
public uint Offset;
public MyDacDef Define;
public ushort CharSetForm;
public ushort UCS2Character;
public ushort ROWIDOrd;
public int bIsXmlType;
public IntPtr pOpsDscCtx;
public int ociTypeCode;
public int bIsFinalType;
}
[StructLayout(LayoutKind.Sequential)]
public struct MyOpoMetValCtx
{
public short NoOfMetaAlloc;
public short NoOfCols;
public short NoOfHiddenCols;
public byte bHasLongCol;
public byte bHasLongLobBFileCol;
public byte bHasXmlType;
public byte bHasUdtType;
public byte bUdtInfoFetched;
public byte bHasDescCol;
public byte bPkFetched;
public byte bPkPresent;
public byte bPooled;
public int InitialLongFS;
public int InitialLobFS;
public byte bStmtParsed;
public unsafe MyColMetaVal* pColMetaVal;
public IntPtr pOpoMetRefCtx;
public int CommandType;
public byte bRowidPresent;
public IntPtr pCommandText;
public IntPtr pNewCommandText;
public ushort NoOfBlobCols;
public ushort NoOfClobCols;
public ushort NoOfNClobCols;
public int RefCount;
public int NoOfDescCols;
public byte bChgNtfnRowidPresent;
}
}
MyOpoMetValCtx _ctx = new MyOpoMetValCtx();
private unsafe void TestOracle()
{
_ctx.bHasUdtType = 1;
_ctx.InitialLongFS = 0x01010101;
_ctx.InitialLobFS = 0x02020202;
int size = sizeof(MyColMetaVal);
IntPtr ptr = Marshal.AllocCoTaskMem(size);
_ctx.pColMetaVal = (MyColMetaVal *)ptr.ToPointer();
GC.Collect(2, GCCollectionMode.Forced);
GC.Collect(2, GCCollectionMode.Forced);
}
unsafe ~OracleDefault()
{
fixed(MyOpoMetValCtx* pctx = &_ctx)
{
OracleHelper.ssmem_free(pctx->pColMetaVal);
pctx->pColMetaVal = null;
// 또는, OracleHelper.FreeValCtx(pctx);
}
}
물론, 아무런 문제 없는 제 시스템에서는 저 코드가 오류 없이 잘 실행이 됩니다.
그런데, 사실 좀 의문이 남는 부분이 있는데요. COM의 AllocCoTaskMem과 CoTaskMemFree는 시스템에 공통으로 적용되는 할당 및 해제 방식이기 때문에 DLL의 new/delete와 같은 문제가 발생하지는 않습니다.
Visual Studio에서 C++ DLL을 대상으로 단위 테스트할 때 비정상 종료한다면?
; https://www.sysnet.pe.kr/2/0/11173
DebugDiag를 이용해 덤프 분석을 해보면 다음과 같은 오류 분석이 나오는데,
[Description]
In dump.dmp the assembly instruction at ntdll!RtlFreeHeap+2a9 in C:\Windows\System32\ntdll.dll has caused an access violation exception (0xC0000005) when trying to read from memory location 0x5b84e748 on thread 24
Heap corruption was detected in dump.dmp
However pageheap was not enabled in this dump. Please follow the instructions in the recommendation section for troubleshooting heap corruption issues.
Current NTGlobalFlags value: 0x0
[Recommendation]
An exception thrown by a heap memory manager function indicates heap corruption. Please click the 'PageHeap Flags...' button in the DebugDiag crash rule configuration dialog to enable PageHeap for the target process and collect another dump. For more information, review the following documents:
How to Use the Debug Diagnostic Tool v1.1 (DebugDiag) to Debug User Mode Processes
Debugging Heap corruption with Application Verifier and Debugdiag
어떤 식으로든 다른 구성 요소에 의해 힙이 손상된 듯합니다. 저 멀리 일본의 경우이고, 딱히 제 임의로 테스트할 수 없는 환경이라 일단 ODP.NET Managed 버전을 사용해 보라는 가이드와,
ODP.NET의 완전한 닷넷 버전 Oracle ODP.NET, Managed Driver
; https://www.sysnet.pe.kr/2/0/10928
다음의 글에 따라 Heap 손상의 원인을 밝힐 수 있는 테스트를 해보라는 가이드를 함께 했습니다.
Debugging Heap corruption with Application Verifier and Debugdiag
; https://docs.microsoft.com/en-us/archive/blogs/lagdas/debugging-heap-corruption-with-application-verifier-and-debugdiag
이후 어떻게 조치가 되었는지 소식이 들려오면 업데이트하겠습니다. ^^
(2019-12-20 업데이트: 이 문제의 원인은
windbg - Marshal.FreeHGlobal에서 발생한 덤프 분석 사례 글에서 설명합니다.)
[이 글에 대해서 여러분들과 의견을 공유하고 싶습니다. 틀리거나 미흡한 부분 또는 의문 사항이 있으시면 언제든 댓글 남겨주십시오.]