Tuesday, January 30, 2007

ASP.NET debugging using memory crash analysis

I was given a task to find out why ASP.NET process was crashing several times an hour on production machines. The only information I had was couple of entries in Event Log.

Event Type: Error
Event Source: ASP.NET 2.0.50727.0
Event Category: None
Event ID: 1000
Date: 10/13/2006
Time: 1:02:32 PM
User: N/A
aspnet_wp.exe (PID: 16620) stopped unexpectedly.

Event Type: Error
Event Source: .NET Runtime 2.0 Error Reporting
Event Category: None
Event ID: 5000
Date: 10/13/2006
Time: 1:02:28 PM
User: N/A
EventType clr20r3, P1 aspnet_wp.exe, P2 2.0.50727.42, P3 4333aece, P4 system.data, P5, P6 4333aea2, P7 1946, P8 25, P9 system.invalidoperationexception, P10 NIL.

Here is the steps I took based on this article

  1. Install Debugging tools for Windows
  2. Locate you crash dumps in following location
  3. Start Windbg program and modify symbol path to point to Microsoft servers
  4. Open crash dump file
  5. Results of operation with crash dump are below, stuff in red are commands and stuff in blue are relevant pieces

Extracted C:DOCUME~1A-GREG~1.SUVLOCALS~1Temp1700003cac0_mdmpmem.hdmp from

Loading Dump File [C:DOCUME~1A-GREG~1.SUVLOCALS~1Temp1700003cac0_mdmpmem.hdmp]
User Mini Dump File: Only registers, stack and portions of memory are available

Windows 2000 Version 2195 (Service Pack 4) UP Free x86 compatible
Product: Server, suite: TerminalServer SingleUserTS
Debug session time: Wed Sep 27 15:46:57.000 2006 (GMT-5)
System Uptime: not available
Process Uptime: 0 days 0:03:06.000
Symbol search path is: srv*c:symbols*http://msdl.microsoft.com/download/symbols
Executable search path is:
sos.dll needs a full memory dump for complete functionality.
You can create one with .dump /ma <filename>
This dump file has an exception of interest stored in it.
The stored exception information can be accessed via .ecxr.
(1d84.3eec): CLR exception - code e0434f4d (first/second chance not available)
eax=06030000 ebx=02dee60c ecx=00001000 edx=00000000 esi=77f88f08 edi=000007ac
eip=77f88f13 esp=02dee5f0 ebp=02dee614 iopl=0 nv up ei ng nz ac pe cy
cs=001b ss=0023 ds=0023 es=0023 fs=003b gs=0000 efl=00000297
77f88f13 c20c00 ret 0Ch

  • Dumping list of threads including thread where exception occurred (in our case thread no 6)

0:006> !threads
ThreadCount: 9
UnstartedThread: 0
BackgroundThread: 9
PendingThread: 0
DeadThread: 0
Hosted Runtime: no
PreEmptive GC Alloc Lock
ID OSID ThreadOBJ State GC Context Domain Count APT Exception
1 1 3ad8 00164c48 8808220 Enabled 00000000:00000000 0015c550 0 Ukn (Threadpool Completion Port)
6 2 3eec 00170710 b220 Enabled 00000000:00000000 05227d48 1 MTA (Finalizer) System.InvalidOperationException (01003f2c)
7 3 3294 001866e8 80a220 Enabled 00000000:00000000 0015c550 0 MTA (Threadpool Completion Port)
10 4 3d48 00198c68 1220 Enabled 00000000:00000000 0015c550 0 Ukn
11 5 246c 001e27d8 880b220 Enabled 00000000:00000000 0015c550 0 MTA (Threadpool Completion Port)
13 6 37c 00200c08 180b220 Enabled 00000000:00000000 0015c550 0 MTA (Threadpool Worker)
9 8 8fc 0023a8e0 220 Enabled 00000000:00000000 0015c550 0 STA
15 9 7dc 002330b8 200b220 Enabled 00000000:00000000 002124c0 1 MTA
16 7 ae0 00233478 880b220 Enabled 00000000:00000000 0015c550 0 MTA (Threadpool Completion Port)

  • Find information about exception based on address above

0:006> !printexception 01003f2c
Exception object: 01003f2c
Exception type: System.InvalidOperationException
Message: Internal .Net Framework Data Provider error 1.
InnerException: <none>
StackTrace (generated):
SP IP Function
02DEF8D4 653976BF System.Data.ProviderBase.DbConnectionInternal.PrePush(System.Object)
02DEF8E0 652B29CD System.Data.ProviderBase.DbConnectionPool.PutObject(System.Data.ProviderBase.DbConnectionInternal, System.Object)
02DEF920 65277FC6 System.Data.ProviderBase.DbConnectionInternal.CloseConnection(System.Data.Common.DbConnection, System.Data.ProviderBase.DbConnectionFactory)
02DEF950 652CD4BA System.Data.SqlClient.SqlConnection.Close()
02DEF988 05E5299E RNTransactionLogWS.RNTransactionLog.Finalize()

StackTraceString: <none>
HResult: 80131509

  • Our InvalidOperationException happened in Finalize() method of RNTransacationLog. We need to dump contents of that assembly, first we using IP to MD command to find method descriptor

0:006> !ip2md 0x05E5299E
MethodDesc: 05c78bb8
Method Name: RNTransactionLogWS.RNTransactionLog.Finalize()
Class: 05e3544c
MethodTable: 05c78c5c
mdToken: 06000035
Module: 05c75534
IsJitted: yes
m_CodeOrIL: 05e52960

  • Dump method table to find which DLL code compiled to

0:006> !dumpmt 05c78c5c
EEClass: 05e3544c
Module: 05c75534
Name: RNTransactionLogWS.RNTransactionLog
mdToken: 02000008 (C:WINNTMicrosoft.NETFrameworkv2.0.50727Temporary ASP.NET Filesiis_rnlogging8f383ed1f56b55d8assemblydl36231f022a01f4daa_e7a8c501RNTransactionLogWS.DLL)
BaseSize: 0x18
ComponentSize: 0x0
Number of IFaces in IFaceMap: 0
Slots in VTable: 23

  • Find loading address by using command lmv<assemblyname>

0:006> lmv mRNTransactionLogWS
start end module name
05e40000 05e50000 RNTransactionLogWS (deferred)
Image path: C:WINNTMicrosoft.NETFrameworkv2.0.50727Temporary ASP.NET Filesiis_rnlogging8f383ed1f56b55d8assemblydl36231f022a01f4daa_e7a8c501RNTransactionLogWS.DLL
Image name: RNTransactionLogWS.DLL
Has CLR image header, track-debug-data flag not set
Timestamp: Mon Dec 05 12:24:57 2005 (439485F9)
CheckSum: 00000000
ImageSize: 00010000
File version: 1.0.2165.22349
Product version: 1.0.2165.22349
File flags: 0 (Mask 3F)
File OS: 4 Unknown Win32
File type: 2.0 Dll
File date: 00000000.00000000
Translations: 0000.04b0
InternalName: RNTransactionLogWS.dll
OriginalFilename: RNTransactionLogWS.dll
&nbsp; ProductVersion: 1.0.2165.22349
FileVersion: 1.0.2165.22349

  • Now we can extract assembly from memory dump

0:006> !savemodule 05e40000 c:a.dll
3 sections in file
section 0 - VA=2000, VASize=8af4, FileAddr=1000, FileSize=9000
section 1 - VA=c000, VASize=390, FileAddr=a000, FileSize=1000
section 2 - VA=e000, VASize=c, FileAddr=b000, FileSize=1000

The last is finding offending code in assembly. Ildasm.exe can be used or Lutz Roeder's reflector from http://www.aisto.com/roeder/dotnet/. Output of reflector shown below highlighting offending method where exception happened (Finalize())

We can see that developer tried to close Connection object within Finalize() method which is explicitly stated in MSDN as prohibited. Here is part of documentation

Caution noteCaution

Do not call Close or Dispose on a Connection, a DataReader, or any other managed object in the Finalize method of your class. In a finalizer, you should only release unmanaged resources that your class owns directly. If your class does not own any unmanaged resources, do not include a Finalize method in your class definition. For more information, see Garbage Collection.

Bingo! We know how, when and why application was crashing.