This error message was reported by a customer last week; every day, randomly, his application pools (on two servers in NLB) were restarted during business hours without an apparent reason, and of course users were complaining because of lost sessions etc…; the following entry was added to the Application event log:
Event Type: Error
Event Source: .NET Runtime 2.0 Error Reporting
Event Category: None
Event ID: 5000
Date: 9/28/2005
Time: 3:18:02 PM
User: N/A
Computer: IIS-SERVER
Description:
EventType clr20r3, P1 w3wp.exe, P2 6.0.3790.1830, P3 42435be1, P4 app_web_7437ep-9, P5 0.0.0.0, P6 433b1670, P7 9, P8 a, P9 system.exception, P10 NIL
The first thing to do when we have a specific error message is to search the Knowledge Base for known issues/hotfixes etc…, and was quite easy to find the article Unhandled exceptions cause ASP.NET-based applications to unexpectedly quit in the .NET Framework 2.0 which I already used more than once in the past to resolve similar issues; I usually suggest the customer to first apply the solution described in “Method 2”:
Method 2
Change the unhandled exception policy back to the default behavior that occurs in the .NET Framework 1.1 and in the .NET Framework 1.0.
Note We do not recommend that you change the default behavior. If you ignore exceptions, the application may leak resources and abandon locks.
To enable this default behavior, add the following code to the Aspnet.config file that is located in the following folder:
%WINDIR%\Microsoft.NET\Framework\v2.0.50727<configuration> <runtime> <legacyUnhandledExceptionPolicy enabled="true" /> </runtime> </configuration>
That is to resolve the problem immediately and have the application running smoothly (at least smoother than before), while the second important step I always suggest is review application’s code to spot places where an exception might throw exceptions outside of a try…catch block and correct it; the bottom line is that is not safe ignoring exceptions and continue execution “hoping” that everything goes right because good old Mr. Murphy and his law are always there, watching carefully on you! ?. Anyway this time the customer had already available a couple of crash dumps captured with adplus, so I just needed some analysis to have a better understanding or what exactly was causing the error… Easy, right? ?
Ok, so the first thing I usually do when I’m in Windbg (and the environment is ready to go) is running some standard commands to get a general idea about the state of the process (threads, stack, heap status, exceptions and so on), but in this case I was interested in finding the root cause of a specific exception, and opening the dump I already had this interesting message:
This dump file has an exception of interest stored in it. The stored exception information can be accessed via .ecxr. (eb4.e40): CLR exception - code e0434f4d (first/second chance not available) CLR exception type: System.FormatException "Input string was not in a correct format."
Let’s have a look at the exception objects still on the heap:
[...] Number of exceptions of this type: 2 Exception object: 1c10f964 Exception type: System.FormatException Message: Input string was not in a correct format. InnerException: <none> StackTrace (generated): SP IP Function 09E0ECA4 793A84DB System.Text.StringBuilder.FormatError() 09E0ECAC 79604D81 System.Text.StringBuilder.AppendFormat(System.IFormatProvider, System.String, System.Object[]) 09E0ECF0 79350B9E System.String.Format(System.IFormatProvider, System.String, System.Object[]) 09E0ED0C 793A6704 System.String.Format(System.String, System.Object) 09E0ED1C 01ABE4A5 MyApp.Class.Identity.Pi2.Sp.Frmx.CSessionLogin.CleanupTicket(System.DateTime, Int32, Boolean, System.Collections.ArrayList) 09E0ED90 01ABE306 MyApp.Class.Identity.Pi2.Sp.Frmx.CAuthentication.Cleanup(System.Object) 09E0EDEC 793D9C1A System.Threading._TimerCallback.TimerCallback_Context(System.Object) 09E0EDF0 793683DD System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object) 09E0EE08 793D9C7F System.Threading._TimerCallback.PerformTimerCallback(System.Object) [...]
The exception stack shows three calls involving a TimerCallback, then a couple of custom methods and finally a few string manipulations (by the way, just in case you don’t know, the stack must be read from bottom to top); the exception is coding from a StringBuilder object, while the runtime was trying to format a string but for some reason failed. This string manipulation is happening “behind the scenes”, the runtime uses those objects as a consequence of what we’re doing in our custom methods, so if the StringBuilder is failing is likely because we passed it some wrong arguments, or asked him to do something not allowed.
Ok, so let’s have a look at those two custom methods; we can extract the IL code by means of the !u command and the IP (Instruction Pointer) address:
0:020> !u 01ABE4A5 Normal JIT generated code MyApp.Class.Identity.Pi2.Sp.Frmx.CSessionLogin.CleanupTicket(System.DateTime, Int32, Boolean, System.Collections.ArrayList) Begin 01abe3f0, size 31d 01abe3f0 55 push ebp 01abe3f1 8bec mov ebp,esp 01abe3f3 57 push edi 01abe3f4 56 push esi 01abe3f5 53 push ebx 01abe3f6 83ec50 sub esp,50h 01abe3f9 33c0 xor eax,eax [...] 01abe45b f30f7e00 movq xmm0,mmword ptr [eax] 01abe45f 660fd60424 movq mmword ptr [esp],xmm0 01abe464 e8e7b88e77 call mscorlib_ni!System.DateTime.Compare(System.DateTime, System.DateTime) (793a9d50) 01abe469 8bf0 mov esi,eax 01abe46b 85f6 test esi,esi 01abe46d 7e41 jle MyApp_Class_Identity_Pi2_Sp_Frmx!MyApp.Class.Identity.Pi2.Sp.Frmx.CSessionLogin.CleanupTicket(System.DateTime, Int32, Boolean, System.Collections.ArrayList)+0xc0 (01abe4b0) 01abe46f 8b05e031b507 mov eax,dword ptr ds:[7B531E0h] 01abe475 8945a8 mov dword ptr [ebp-58h],eax 01abe478 b9f05e1079 mov ecx,offset mscorlib_ni+0x45ef0 (79105ef0) 01abe47d e89a3bf2ff call 019e201c (JitHelp: CORINFO_HELP_NEWSFAST) 01abe482 8bd8 mov ebx,eax 01abe484 8d7b04 lea edi,[ebx+4] 01abe487 3b0f cmp ecx,dword ptr [edi] 01abe489 8b75bc mov esi,dword ptr [ebp-44h] 01abe48c 83c654 add esi,54h 01abe48f 3b0e cmp ecx,dword ptr [esi] 01abe491 f30f7e06 movq xmm0,mmword ptr [esi] 01abe495 660fd607 movq mmword ptr [edi],xmm0 01abe499 8bf3 mov esi,ebx 01abe49b 8bd6 mov edx,esi 01abe49d 8b4da8 mov ecx,dword ptr [ebp-58h] 01abe4a0 e833828e77 call mscorlib_ni!System.String.Format(System.String, System.Object) (793a66d8) >>> 01abe4a5 8bf0 mov esi,eax 01abe4a7 8975b8 mov dword ptr [ebp-48h],esi 01abe4aa 90 nop 01abe4ab e99f000000 jmp MyApp_Class_Identity_Pi2_Sp_Frmx!MyApp.Class.Identity.Pi2.Sp.Frmx.CSessionLogin.CleanupTicket(System.DateTime, Int32, Boolean, System.Collections.ArrayList)+0x15f (01abe54f) 01abe4b0 8d7dc8 lea edi,[ebp-38h] 01abe4b3 8d7510 lea esi,[ebp+10h] [...]
We can continue disassemble the subsequent calls, here is an excerpt of StringBuilder.AppendFormat:
[...] 79350daa 83fe7b cmp esi,7Bh 79350dad 0f84d33f2b00 je mscorlib_ni!System.Text.StringBuilder.AppendFormat(System.IFormatProvider, System.String, System.Object[])+0x2b41ce (79604d86) 79350db3 83fe7d cmp esi,7Dh 79350db6 751f jne mscorlib_ni!System.Text.StringBuilder.AppendFormat(System.IFormatProvider, System.String, System.Object[])+0x21f (79350dd7) 79350db8 3b3c24 cmp edi,dword ptr [esp] 79350dbb 7d15 jge mscorlib_ni!System.Text.StringBuilder.AppendFormat(System.IFormatProvider, System.String, System.Object[])+0x21a (79350dd2) 79350dbd 3b7b04 cmp edi,dword ptr [ebx+4] 79350dc0 0f8326402b00 jae mscorlib_ni!System.Text.StringBuilder.AppendFormat(System.IFormatProvider, System.String, System.Object[])+0x2b4234 (79604dec) 79350dc6 66837c7b087d cmp word ptr [ebx+edi*2+8],7Dh 79350dcc 0f84d63f2b00 je mscorlib_ni!System.Text.StringBuilder.AppendFormat(System.IFormatProvider, System.String, System.Object[])+0x2b41f0 (79604da8) 79350dd2 83c7ff add edi,0FFFFFFFFh 79350dd5 eb15 jmp mscorlib_ni!System.Text.StringBuilder.AppendFormat(System.IFormatProvider, System.String, System.Object[])+0x234 (79350dec) 79350dd7 8bc5 mov eax,ebp [...] 79350e74 8d4ade lea ecx,[edx-22h] 79350e77 e84c2cb200 call mscorwks!JIT_Writeable_Thunks_Buf+0x198 (79e73ac8) (JitHelp: CORINFO_HELP_GETSHARED_GCSTATIC_BASE) 79350e7c 8b6810 mov ebp,dword ptr [eax+10h] 79350e7f 8b44240c mov eax,dword ptr [esp+0Ch] 79350e83 2b4508 sub eax,dword ptr [ebp+8] 79350e86 89442410 mov dword ptr [esp+10h],eax 79350e8a 837c240800 cmp dword ptr [esp+8],0 79350e8f 7508 jne mscorlib_ni!System.Text.StringBuilder.AppendFormat(System.IFormatProvider, System.String, System.Object[])+0x2e1 (79350e99) 79350e91 85c0 test eax,eax 79350e93 0f8f3c3f2b00 jg mscorlib_ni!System.Text.StringBuilder.AppendFormat(System.IFormatProvider, System.String, System.Object[])+0x2b421d (79604dd5) 79350e99 8bd5 mov edx,ebp 79350e9b 8b4c2414 mov ecx,dword ptr [esp+14h] 79350e9f e85ca3ffff call mscorlib_ni!System.Text.StringBuilder.Append(System.String) (7934b200) 79350ea4 837c240800 cmp dword ptr [esp+8],0 79350ea9 0f847afdffff je mscorlib_ni!System.Text.StringBuilder.AppendFormat(System.IFormatProvider, System.String, System.Object[])+0x71 (79350c29) 79350eaf 837c241000 cmp dword ptr [esp+10h],0 79350eb4 0f8e6ffdffff jle mscorlib_ni!System.Text.StringBuilder.AppendFormat(System.IFormatProvider, System.String, System.Object[])+0x71 (79350c29) 79350eba ff742410 push dword ptr [esp+10h] 79350ebe 8b4c2418 mov ecx,dword ptr [esp+18h] 79350ec2 ba20000000 mov edx,20h 79350ec7 e898670500 call mscorlib_ni!System.Text.StringBuilder.Append(Char, Int32) (793a7664) 79350ecc e958fdffff jmp mscorlib_ni!System.Text.StringBuilder.AppendFormat(System.IFormatProvider, System.String, System.Object[])+0x71 (79350c29) 79350ed1 8b442414 mov eax,dword ptr [esp+14h] 79350ed5 83c428 add esp,28h [...] 79350f92 8bf9 mov edi,ecx 79350f94 8bf2 mov esi,edx 79350f96 b96cfe0f79 mov ecx,offset mscorlib_ni+0x3fe6c (790ffe6c) 79350f9b e8cb75b300 call mscorwks!RuntimeTypeHandle::GetRuntimeType (79e8856b) 79350fa0 3bc6 cmp eax,esi 79350fa2 750a jne mscorlib_ni!System.Globalization.CultureInfo.GetFormat(System.Type)+0x1e (79350fae) 79350fa4 8bcf mov ecx,edi 79350fa6 8b01 mov eax,dword ptr [ecx] 79350fa8 ff5070 call dword ptr [eax+70h] 79350fab 5e pop esi 79350fac 5f pop edi 79350fad c3 ret 79350fae b9f0ff0f79 mov ecx,offset mscorlib_ni+0x3fff0 (790ffff0) 79350fb3 e8b375b300 call mscorwks!RuntimeTypeHandle::GetRuntimeType (79e8856b) 79350fb8 3bc6 cmp eax,esi 79350fba 0f84e43e2b00 je mscorlib_ni!System.Globalization.CultureInfo.GetFormat(System.Type)+0x2b3f14 (79604ea4) 79350fc0 33c0 xor eax,eax 79350fc2 5e pop esi [...] 79350fe4 85ed test ebp,ebp 79350fe6 0f84cc3e2b00 je mscorlib_ni!System.Text.StringBuilder.Append(Char[], Int32, Int32)+0x2b3ee8 (79604eb8) 79350fec 85f6 test esi,esi 79350fee 750c jne mscorlib_ni!System.Text.StringBuilder.Append(Char[], Int32, Int32)+0x2c (79350ffc) 79350ff0 8bc3 mov eax,ebx [...]
From this latest chunk of IL we can see that we’re inside a loop (note the recurrent StringBuilder.AppendFormat calls) and we’re very likely dealing with dates (note the System.Globalization.CultureInfo.GetFormat calls); the next call is where the runtime is throwing the exception:
0:020> !u 793A84DB preJIT generated code System.Text.StringBuilder.FormatError() Begin 793a84a4, size 38 793a84a4 50 push eax 793a84a5 b9b8201279 mov ecx,offset mscorlib_ni+0x620b8 (791220b8) 793a84aa e8e1b5ac00 call mscorwks!JIT_Writeable_Thunks_Buf+0x160 (79e73a90) (JitHelp: CORINFO_HELP_NEWSFAST) 793a84af 890424 mov dword ptr [esp],eax 793a84b2 8b1500e06879 mov edx,dword ptr [mscorlib_ni+0x5ce000 (7968e000)] 793a84b8 b9791b0070 mov ecx,70001B79h 793a84bd e82ab8ce00 call mscorwks!JIT_StrCns (7a093cec) 793a84c2 8bc8 mov ecx,eax 793a84c4 e81229b800 call mscorwks!GetResourceFromDefault (79f2addb) 793a84c9 8bd0 mov edx,eax 793a84cb 8b0c24 mov ecx,dword ptr [esp] 793a84ce e81dc10100 call mscorlib_ni!System.FormatException..ctor(System.String) (793c45f0) 793a84d3 8b0c24 mov ecx,dword ptr [esp] 793a84d6 e8f1bfce00 call mscorwks!JIT_Throw (7a0944cc) >>> 793a84db cc int 3
The next step would be to have a look at the source code of the component, but I’m not the developer and I don’t have it at hand… of course I could have called the customer to ask for the project, but why bother him when we can extract the modules directly from the dump? But first, we need to know where the method we’re investigating is contained. The !ip2md (Instrutction Pointer to Method Definition) comes at hand; let’s dump the CleanupTicket IP:
0:020> !ip2md 01ABE4A5 MethodDesc: 05ecfb20 Method Name: MyApp.Class.Identity.Pi2.Sp.Frmx.CSessionLogin.CleanupTicket(System.DateTime, Int32, Boolean, System.Collections.ArrayList) Class: 0668e38c MethodTable: 05ecfbac mdToken: 06000017 Module: 05ec6508 IsJitted: yes m_CodeOrIL: 01abe3f0
Now we can dump the method table with !dumpmt to find out the name of the dll:
0:020> !dumpmt 05ecfbac EEClass: 0668e38c Module: 05ec6508 Name: MyApp.Class.Identity.Pi2.Sp.Frmx.CSessionLogin mdToken: 02000006 (C:\WINDOWS\Microsoft.NET\Framework\v2.0.50727\Temporary ASP.NET Files\test\8b453812\8f89c492\assembly\dl3\4a6a6dc7\0076b989_27f1c701\MyApp.Class.Identity.Pi2.Sp.Frmx.DLL) BaseSize: 0x60 ComponentSize: 0x0 Number of IFaces in IFaceMap: 0 Slots in VTable: 25
Finally with the lm command we can get the complete details about this module, included the chunk of memory (initial and final addresses) where it is loaded. Note that if the file name contains dots (“.”) you must replace them with underscores (“_”), and you don’t have to use the extension; for example System.Web.dll will be translated as System_Web:
0:020> lmv mMyApp_Class_Identity_Pi2_Sp_Frmx start end module name 068b0000 068be000 MyApp_Class_Identity_Pi2_Sp_Frmx (deferred) Image path: C:\WINDOWS\Microsoft.NET\Framework\v2.0.50727\Temporary ASP.NET Files\test\8b453812\8f89c492\assembly\dl3\4a6a6dc7\0076b989_27f1c701\MyApp.Class.Identity.Pi2.Sp.Frmx.DLL Image name: MyApp.Class.Identity.Pi2.Sp.Frmx.DLL Using CLR debugging support for all symbols Has CLR image header, track-debug-data flag not set Timestamp: Fri Aug 24 18:40:06 2007 (46CF09E6) CheckSum: 00000000 ImageSize: 0000E000 File version: 0.12.2792.0 Product version: 0.12.2792.0 File flags: 0 (Mask 3F) File OS: 4 Unknown Win32 File type: 2.0 Dll File date: 00000000.00000000 Translations: 0000.04b0 CompanyName: ProductName: InternalName: MyApp.Class.Identity.Pi2.Sp.Frmx.dll OriginalFilename: MyApp.Class.Identity.Pi2.Sp.Frmx.dll ProductVersion: 0.12.2792.0 FileVersion: 0.12.2792.0 FileDescription: LegalCopyright: LegalTrademarks: Comments:
Finally… let’s use !savemodule <starting address> <output name> to extract the module from the dump:
0:020> !savemodule 068b0000 C:\temp\MyApp.Class.Identity.Pi2.Sp.Frmx.DLL
4 sections in file
section 0 - VA=2000, VASize=4d54, FileAddr=1000, FileSize=5000
section 1 - VA=8000, VASize=a3, FileAddr=6000, FileSize=1000
section 2 - VA=a000, VASize=8a8, FileAddr=7000, FileSize=1000
section 3 - VA=c000, VASize=c, FileAddr=8000, FileSize=1000
Wow, that sounds long and complicated, but once you get used to it it’s just a matter of 20 seconds ⏱
Ok, now that we have our module we can use Reflector to finally have a look at the source code of our CleanupTicket method, here it is:
internal void CleanupTicket(DateTime dt, int iToMin, bool bNoCheck, ArrayList vArrayList) { string str; if (!bNoCheck) { if (DateTime.Compare(dt, this.m_dtE) > 0) { str = string.Format("LEASE to expired at {0:yyy/MM/dd-HH:mm:ss:fff", this.m_dtE); } else if (DateTime.Compare(dt, this.m_dtLastAccess.AddMinutes((double) iToMin)) > 0) { str = string.Format("IDLE to timout expired at {0:yyy/MM/dd-HH:mm:ss:fff} + {1} min", this.m_dtLastAccess, 60); } } if (StringType.StrCmp(str, "", false) != 0) { bfLogging.WriteFmt("CSessionLogin::CleanupTicket", "", "Ticket {0} is added to the logout bag. {1}", new object[] { this.m_strGuid, str }); } if (bNoCheck | (StringType.StrCmp(str, "", false) != 0)) { vArrayList.Add(this); } if (this.m_vHashtableCSessionLoginPseudoSp != null) { foreach (CSessionLogin login in this.m_vHashtableCSessionLoginPseudoSp.Values) { login.CleanupTicket(dt, iToMin, bNoCheck | (StringType.StrCmp(str, "", false) != 0), vArrayList); } } }
As you can see we are formatting some strings and we have a loop as we saw in the IL code, and here (and in the previous method, Cleanup, which I’ve not reported here just to save some space) we don’t have any try…catch blocks; this means that if for any reason an exception is thrown in this code (or if we pass some wrong argument which can’t be successfully converted to the underlying runtime objects like the StringBuilder) the exception will not be trapped, and as explained in the KB article this will eventually recycle the worker process ?
In this case the developer reviewed the code to add exception handling on the sensitive lines, and they finally got rid of those unwanted worker process recycles. By the way, my colleague Tess ha a very similar post on her blog here.
Carlo
Quote of the day:
A good novel tells us the truth about its hero; but a bad novel tells us the truth about its author. – G. K. Chesterton