October, 2007

  • Never doubt thy debugger

    A Trappable error C0000005 occured in an external object, the script cannot continue running


    This is an Access Violation exception which can have different causes (MDAC bad installation, third party components such as Oracle dlls which Oracle has a fix for etc...), but in the specific case I had some time ago this was due to a corrupted Windows Scripting Host engine. This was a classic ASP application and it was crashing randomly; we captured a dump with adplus (4 dumps, actually) and the stack of the faulting thread was always the same:

    0:020> kpL2000
    ChildEBP RetAddr  
    04f5f5c8 7346520b vbscript!VarStack::SetMasterSp(long cvar = 6, class VAR ** ppvarSp = 0x04f5f6b8)+0xa3
    04f5f5e4 7346492e vbscript!CScriptRuntime::Init(class CSession * psess = 0x00000000, class FncInfo * pfin = 0x04654e28, class VAR * pvarThis = 0x00000000, int cvar = 0, class VAR * prgvar = 0x00000000, unsigned long grfcall = 0)+0x265
    04f5f6f0 73464cd2 vbscript!CScriptEntryPoint::Call(class VAR * pvarRes = 0x00000000, int cvar = 0, class VAR * prgvar = 0x00000000, class VAR * pvarThis = 0x00000000, unsigned long grfCall = 0)+0x4a
    04f5f748 73465522 vbscript!CSession::Execute(class IEntryPoint * pep = 0x04654e20, struct tagVARIANT * pvarRes = 0x00000000, int cvar = 0, struct tagVARIANT * prgvar = 0x00000000, struct tagVARIANT * pvarThis = 0x00000000, unsigned long grfscr = 0)+0xb4
    04f5f798 7346189b vbscript!COleScript::ExecutePendingScripts(struct tagVARIANT * pvarRes = 0x00000000, struct tagEXCEPINFO * pei = 0x00000000)+0x13e
    04f5f7b4 709e2f5a vbscript!COleScript::SetScriptState(tagSCRIPTSTATE ss = SCRIPTSTATE_STARTED (1))+0x150
    04f5f7e0 709e2f1a asp!CActiveScriptEngine::TryCall(unsigned short * strEntryPoint = 0x00000000)+0x19
    04f5f81c 709f412b asp!CActiveScriptEngine::Call(unsigned short * strEntryPoint = 0x00000000)+0x31
    04f5f824 709f40c8 asp!CActiveScriptEngine::MakeEngineRunnable(void)+0x7
    04f5fa80 709f4231 asp!AllocAndLoadEngines(class CHitObj * pHitObj = 0x01db20f0, class CTemplate * pTemplate = 0x022b1fe8, struct ActiveEngineInfo * pEngineInfo = 0x04f5fb0c, class CScriptingNamespace * pScriptingNamespace = 0x020f2580, int fGlobalAsa = 1)+0x449
    04f5fae0 709f4418 asp!ExecuteGlobal(class CHitObj * pHitObj = 0x01db20f0, class CIntrinsicObjects * intrinsics = 0x04f5fb68, struct ActiveEngineInfo * pEngineInfo = 0x04f5fb0c)+0x184
    04f5fb44 709e2a4d asp!Execute(class CTemplate * pTemplate = 0x022b1e90, class CHitObj * pHitObj = 0x01db20f0, class CIntrinsicObjects * intrinsics = 0x04f5fb68, int fChild = 0)+0xb7
    04f5fb98 709e271a asp!CHitObj::ViperAsyncCallback(int * pfRePosted = 0x00000000)+0x3e8
    04f5fbb4 75bd72a5 asp!CViperAsyncRequest::OnCall(void)+0x92
    04f5fbd0 7770f0eb comsvcs!CSTAActivityWork::STAActivityWorkHelper(void * pvoid = 0x05068f38)+0x32
    04f5fc1c 7770fb38 ole32!EnterForCallback+0xc4
    04f5fd7c 77710042 ole32!SwitchForCallback+0x1a3
    04f5fda8 77694098 ole32!PerformCallback+0x54
    04f5fe40 777127fd ole32!CObjectContext::InternalContextCallback+0x159
    04f5fe60 75bd7649 ole32!CObjectContext::DoCallback+0x1c
    04f5fecc 75bd79a5 comsvcs!CSTAActivityWork::DoWork(unsigned long * pdwWorkCount = 0x0012ced0)+0x12d
    04f5fee4 75bd833e comsvcs!CSTAThread::DoWork(class CSTAWork * pWork = 0x05068f38)+0x18
    04f5ff04 75bd878a comsvcs!CSTAThread::ProcessQueueWork(void)+0x37
    04f5ff84 77bcb530 comsvcs!CSTAThread::WorkerLoop(void * pv = 0x0012ceb0)+0x17c
    04f5ffb8 77e6608b msvcrt!_threadstartex(void * ptd = 0x010aebe0)+0x74
    04f5ffec 00000000 kernel32!BaseThreadStart+0x34

    The call stack shows the VBScript engine is called to run the ASP page, and is crashing just after the initialization; I'm not completely sure if this stack is specific to this problem or if we would have something similar also for the other known causes (MDAC and Oracle dlls) because unfortunately I've not had the chance to review those dumps, so just keep in mind this as a possible solution and not the only one...

    Anyway here we fixed the problem reinstalling the Windows Scripting Host engine for Windows 2003 (version 5.7, as I'm writing).




    Quote of the day:
    After I'm dead I'd rather have people ask why I have no monument than why I have one. - Cato the Elder
  • Never doubt thy debugger

    .NET Runtime 2.0 Error, Event id:5000


    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
    EventType clr20r3, P1 w3wp.exe, P2 6.0.3790.1830, P3 42435be1, P4 app_web_7437ep-9, P5, 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:


            <legacyUnhandledExceptionPolicy enabled="true" />

    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! smile_teeth. 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? smile_nerd

    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
    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
        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

    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 clock

    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))
        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 smile_nerd

    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.


    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

  • Never doubt thy debugger

    Take control over Windbg


    If you're like me and most of my colleagues in Customer Service and Support, you'll probably spend a good deal of time in your debugger, which for me is WinDbg. So, since I'm in love with keyboard shortcuts (a colleague of mine likes kidding me stealing my mouse since I hardly use it, and every now and then uses me as his personal "shortcut reference" smile_regular) and always searching for "productivity tips" to optimize my workflow. Windbg has a few of them, here is what I use.

    Automate WinDbg startup

    I first discovered this in this post from Tess and then customized it to match my needs, especially on my Vista x64 machine; basically this is a .reg file set WinDbg as the default application for .dmp files, and adds a few entries to the right click menu to chose different options. I also have to say that on my x64 machine I actually have two separate folders for WinDbg 32bit and 64bit, so that depending on the dump I'm debugging I can use the right tool:

    Windows Registry Editor Version 5.00
    @="c:\\debuggers x86\\cdb.exe"
    @="Debug This Dump for .NET 1.1 x86"
    @="\"C:\\debuggers x86\\windbg\" -z \"%1\" -c \"$<c:\\debuggers x86\\commands_1.txt\""
    @="c:\\debuggers x86\\cdb.exe"
    @="Debug This Dump for .NET 2.0 x86"
    @="\"C:\\debuggers x86\\windbg\" -z \"%1\" -c \"$<c:\\debuggers x86\\commands_2.txt\""
    @="c:\\debuggers x64\\cdb.exe"
    @="Debug This Dump for .NET 2.0 x64"
    @="\"C:\\debuggers x64\\windbg\" -z \"%1\" -c \"$<c:\\debuggers x64\\commands_2.txt\""

    right click menu 

    With every "block" we are associating the .dmp extension to the cdb.exe icon, creating a description to add a new command to the right click menu and linking it to Windbg. Note that we're using some command line switches to tell Windbg which is the file to open (-z) and a script file to execute at startup (-c).

    This script file is actually just a text file with some commands you would normally run at the beginning of your debugging session; for instance I use it to set my symbol path, load some Windbg extensions I use quite often, and open a log file to have the debugger output automatically saved for later reference, just in case I need to quickly find some information without having to reopen Windbg and go through the various commands:

    .sympath SRV*c:\symbols*\\internalshare\symbols*http://msdl.microsoft.com/download/symbols
    .load extension1
    .load extension2
    .load extension3
    .logopen /d /t

    The /d switch causes the log file name to be chosen based on the target process along with its state, while the /t switch appends the process ID with the current date and time (so if I open multiple times the same dump I have a record for all of my debugging sessions). By the way, you can use the .chain command to list all loaded debugger extensions and their search order, i.e. if you type a command which is contained in more that one extension, the one executed is the one contained in the most recently loaded extension.

    Help online

    If you need help about a particular extension, you can type !<extensionname>.help and a list of all available commands for that extension will be printed in the output window, while if you need help on a specific command you can use !<extensionname>.help <commandname>:

    0:000> !sos.help dumpobj
    !DumpObj [-v] [-short] [-r 2] <object address>
    This command allows you to examine the fields of an object, as well as learn 
    important properties of the object such as the EEClass, the MethodTable, and 
    the size.

    Typing commands

    As I said, I really hate when I have to continuously move my hand from the keyboard to the mouse (maybe for just one click) and vice-versa, so I'm always looking for keyboard shortcuts; so within Windbg I like a couple of small details: if you have some text selected within the command output, a simple right-click will copy it into the clipboard and another right-click will paste it to the command textbox. As an alternative, if you have the mouse cursor within the command output (say after you selected a memory address) you can start typing right away without bothering clicking into the command textbox, because the cursor will automatically move there without losing a letter of what you are typing smile_regular. Small thing I know, but that's how it always begin; very small (from "Big trouble in little China" smile_wink).

    Create or connect to a remote debug session

    Sometimes could happen that you need assistance analyzing a dump (or someone asks your help), but what if you're in a team like mine spread across all over Europe and having a colleague walk down to your desk is simply not an option? Luckily Windbg allows to share your debugging session using the .server command: .server tcp:port=<portnumber> for instance if run on your Windbg (the one with the dump you want to share) will create a server session using TCP as the communication protocol, on port <portnumber>; the string highlighted in red below is the connection string you can send to your peer.

    0:000> .server tcp:port=1234
    Server started.  Client can connect with any of these command lines
    0: <debugger> -remote tcp:Port=1234,Server=<computername>

    Now, on the "client" Windbg you can go to File > Connect to remote session (or hit CTRL+R) and either browse the network to find the Windbg server you're looking for, or type tcp:port=<portnumber>,server=<machinename> and your remote colleague and you will see the same command output and will be able to run commands on the shared dump smile_nerd

    connect to remote debugging session

    While connected you can use the .clients command to list of clients connected to the server, and the .echo command to send messages from one Windbg to the other(s).

    Increase output readability

    Going through a long list of commands and outputs in the debugger window may be not that easy, so it's possible to customize the font and text colors through Edit > Options...

    windbg workspace options



    Quote of the day:
    If life is a waste of time, and time is a waste of life, why don't we all get wasted and have the time of our lives?
  • Never doubt thy debugger

    Gacutil not supported on production?


    The other day I got an interesting question from a customer:

    We are documenting how our production assemblies should be deployed on our production servers. At first we wanted to deploy shared assemblies through the gacutil.exe utility.
    By reading
    this article we realized that Microsoft's recommendation is to use gacutil in a development environment but that it should not be used to deploy assemblies in production.

    This raises the following questions: How should we deploy our assemblies in production? Why not gacutil? Any alternative to MSI?

    The customer was referring to this note box:


    The reason is explained in this article:

    In deployment scenarios, use Windows Installer 2.0 to install assemblies into the global assembly cache. Use Windows Explorer or the Global Assembly Cache tool only in development scenarios, because they do not provide assembly reference counting and other features provided when using the Windows Installer.

    The preferred installation method is a MSI package, but using the appropriate command line switches you can still use gacutil as described in http://msdn2.microsoft.com/en-us/library/ex0ss12c(vs.80).aspx:

    Gacutil.exe provides options that support reference counting similar to the reference counting scheme supported by Windows Installer. You can use Gacutil.exe to install two applications that install the same assembly; the tool keeps track of the number of references to the assembly. As a result, the assembly will remain on the computer until both applications are uninstalled. If you are using Gacutil.exe for actual product installations, use the options that support reference counting. Use the /i and /r options together to install an assembly and add a reference to count it. Use the /u and /r options together to remove a reference count for an assembly. Be aware that using the /i and /u options alone does not support reference counting. These options are appropriate for use during product development but not for actual product installations.



    Quote of the Day:
    An adventure is only an inconvenience rightly considered. An inconvenience is only an adventure wrongly considered.
    --G.K. Chesterton
  • Never doubt thy debugger

    Ok, now how do I capture my dump?


    Now we know how it started, some basic information and terminology and why symbols are important, it's now time to capture our first dump. How? When? Using which tool? It depends... smile_nerd

    From the second post of this series we already know the difference between a hang and a crash dump and depending on the problem we are troubleshooting we know which one we need. There are different ways to capture such a dump but the most used tool in CSS is adplus, and specifically in the IIS and Internet Development team (which I belong to, by the way smile_regular) we also use DebugDiag. I personally prefer adplus, I like it to be run at the command line and be highly configurable through its .cfg files, but there are circumstances (especially unmanaged memory leaks and hanging web applications where the customer can't be always monitoring the server to readily capture a manual hang dump with adplus) where I find DebugDiag quite useful. Let's see the differences.


    Adplus is essentially a VBScript (quite large, more than 5.000 lines) file which helps you capture a dump and it accepts some arguments at the command line (or it's also possible to use a .cfg file to fine control its behavior). The basic arguments you must always provide are the dump mode (-hang or -crash) and the target process(es) (-p <process ID> or -pn <process name>):

    adplus -hang -pn w3wp.exe

    Optionally we can pass multiple process names (or process IDs) simply repeating the -p(n) switch; we can also use the special switch -iis to dump all the IIS related processes (inetinfo.exe, dllhost.exe and w3wp.exe/aspnet_wp.exe). We can also chose to not dump the first chance exceptions (-NoDumpOnFirst) or chose to have a full dump also on first chance (-FullOnFirst) etc...

    Create your .cfg

    Adplus supports a xml-based configuration file to avoid retyping lengthy and detailed command lines; you can specify some options in the .cfg and pass others directly from the command line. All options have defaults, so none is mandatory. Here is the .cfg file format:

       1: <ADPlus>
       2:     <!-- Comments -->
       3:     <Settings>
       4:         <!-- defining basic settings (run mode, quiet mode, etc.) -->
       5:     </Settings>
       6:     <PreCommands>
       7:         <!-- defines a set of commands to execute before the sxe and bp commands -->
       8:     </PreCommands>
       9:     <PostCommands>
      10:         <!-- defines a set of commands to execute after the sxe and bp commands -->
      11:     </PostCommands>
      12:     <Exceptions>
      13:         <!-- commands acting on the exception actions -->
      14:     </Exceptions>
      15:     <Breakpoints>
      16:         <!-- defining breakpoints -->
      17:     </Breakpoints>
      18:     <HangActions>
      19:         <!-- defining actions for hang mode -->
      20:     </HangActions>
      21:     <LinkConfig>
      22:         <!-allows to link to another config file -->
      23:     </ LinkConfig >
      24: </ADPlus>

    The Setting section allows you to define the main settings for adplus, and most of them are equivalent to the command line switches; it's possible to include multiple instances of ProcessID, ProcessName, Spawn and Notify tags:

       1: <Settings>
       2:     <RunMode> runmode </RunMode>
       3:     <Option> IIS </Option>
       4:     <Option> Quiet </Option>
       5:     <Option> NoTlist </Option>
       6:     <Option> NoTsCheck </Option>
       7:     <Option> NoFreeSpaceChecking </Option>
       8:     <OutputDir> OutputDirectoryName </OutputDir>
       9:     <ProcessID> PID </ProcessID>
      10:     <ProcessName> ProcessName </ProcessName>
      11:     <GenerateScript> ScriptName </GenerateScript>
      12:     <Spawn> Spawn Command </Spawn>
      13:     <Sympath> Symbol Path </Sympath>
      14:     <SympathPlus> Symbol Path to add </SympathPlus>
      15:     <Notify> { ComputerName | UserName } </Notify>
      16:     <Debugger> Debugger </ Debugger >
      17: </Settings>

    The Exceptions section allows to customize the actions taken when the debugger breaks on the specified exception; it's also possible to define custom exceptions to monitor:

       1: <Exceptions>
       2:         <!-- options act on all currently defined exceptions -->
       3:        <Option>  FullDumpOnFirstChance  </Option>
       4:        <Option>  MiniDumpOnSecondChance  </Option>
       5:        <Option>  NoDumpOnFirstChance  </Option>
       6:        <Option>  NoDumpOnSecondChance  </Option>
       8:         <!-Defining new exceptions -->
       9:        <NewException>
      10:            <Code> ExceptionCode </Code>
      11:            <Name> ExceptionName </Name>
      12:        </NewException>
      14:         <!-Configuring already defined exceptions -->
      15:        <Config>
      16:           <Code> { ExceptionCode | AllExceptions } </Code>
      17:           <Actions1> Actions  </Actions1> 
      18:           <CustomActions1> CustomActions  </CustomActions1> 
      19:           <Actions2> Actions  </Actions2> 
      20:           <CustomActions2> CustomActions  </CustomActions2> 
      21:           <ReturnAction1> { G | GN | GH | Q | QD } </ReturnAction1> 
      22:           <ReturnAction2> { G | GN | GH | Q | QD } </ReturnAction2> 
      23:        </Config>  
      24:     </Exceptions>

    ReturnAction1 and ReturnAction2 tags are used to define additional actions for first and second chance exceptions respectively; they work just like the debugger commands and are supported only in Windows XP and later.

    The HangActions section allows you specify actions to take when running adplus in hang mode:

       1: <HangActions>
       2:      <Option> MiniDump </Option>
       3:      <Option> FullDump </Option>
       4:      <Option> NoDump </Option>
       5:      <Option> Clear </Option>
       6:      <Actions> Actions  </Actions> 
       7:      <CustomActions> CustomActions  </CustomActions>
       8: </HangActions>

    Here is a sample configuration file (taken from WinDbg help):

       1: <ADPlus>
       2:     <Settings>
       3:         <RunMode> CRASH </RunMode>
       4:         <Option> IIS </Option>
       5:         <OutputDir> c:\MyDumps </OutputDir>
       6:     </Settings>
       8:     <PreCommands>
       9:         <Cmd> .load sos\sos.dll  </Cmd>
      10:     </PreCommands>
      12:     <!-- defining and configuring exceptions -->
      13:     <Exceptions>
      14:         <!-- First we redefine all exceptions -->
      15:         <Config>
      16:             <Code>AllExceptions</Code>
      17:             <Actions1>Log</Actions1>
      18:             <Actions2>MiniDump;Log;EventLog</Actions2>
      19:         </Config>
      20:         <!-- Next we define a special behavior for the Access Violation exception -->
      21:         <Config>
      22:             <Code> av </Code>
      23:             <Actions1>Log</Actions1>
      24:             <Actions2>FullDump;Log;EventLog</Actions2>
      25:         </Config>
      26:         <!-- Adding a custom exception -->
      27:         <NewException>
      28:             <Code> 0x80010005 </Code>
      29:             <Name> Custom_Exception_05 </Name>
      30:         </NewException>
      31:         <!-- Configuring the custom exception -->
      32:         <Config>
      33:             <Code> 0x80010005 </Code>
      34:             <Actions1>Log;Stack</Actions1>
      35:             <Actions2>FullDump;Log;EventLog</Actions2>
      36:             <CustomActions2>   !heap;!locks     </CustomActions2>
      37:         </Config>
      38:     </Exceptions>
      40:     <!-- defining breakpoints -->
      41:     <Breakpoints>
      42:         <NewBP>
      43:             <Address> MyModule!MyClass::MyMethod </Address>
      44:             <Actions> Log;Stack;MiniDump  </Actions> 
      45:             <ReturnAction> G  </ReturnAction> 
      46:         </NewBP>  
      47:     </Breakpoints>
      48: </ADPlus>

    For further details see ADPlus Configuration Files section in WinDbg help.


    This tool was originally developed by the IIS Escalation Engineer team (I'm not sure if they are still the ones behind it now) and essentially allows the user to create a set of rules to capture hang and crash dumps of your processes, also allowing you to specify on which exception to capture the dump, how many dumps to capture for each session, on which events etc... Very flexible.

    DebugDiag report There are three circumstances where I find DebugDiag really helpful and can ease my debugging life compared to adplus. First, it makes very easy to debug in a Terminal Session, it's just a matter of adding a flag in the Preferences tab. Second, creating a hang rule it's possible to monitor a specific URL and DebugDiag will automatically "ping" it to check if the site is up and running; if the server does not respond, DebugDiag will capture the dump you told it. This can be very useful in situations where you need to troubleshoot a site which hangs sporadically, maybe at night, and it's not possible to pay someone to patiently sit in front of the server waiting to run adplus at the right moment... smile_regular When you create this kind of rule you have to specify one (or more) URLs to monitor and then you have to tell DebugDiag which process or application pool to monitor; so even if you can configure the rule on your client to monitor www.yoursite.com, of course you can't dump a process which is running on a different machine so you must install and configure DebugDiag on the affected web server.

    For memory leaks and crashes you can quickly have an idea of what's in the dump opening it within DebugDiag and running the appropriate script in the Advanced Analysis tab; you'll have a simple but precise report about which exception caused the crash and in which thread, or a list of the components responsible for the higher allocation rates etc... This is not enough to have a complete analysis on the problem, but it's for sure a good point to start; of course you can still open and analyze those dumps with WinDbg as usual.

    WinDbg while live debugging

    Live debugging will be the subject of a future post, but just in case you attached WinDbg to a process and you're now wondering how to dump it...

    .dump /ma <output file>

    Dumping on a terminal session?

    If you need to dump a process on a Windows NT or Windows 2000 machine, you cannot to so through a Terminal Server session since the debugger cannot attach to a process which runs in a different Window Station, and if you try you'll likely get a message like the following:

    Win32 error 5
    "Access is denied."

    This is by design but there are a couple of solutions if you need, check You cannot debug through a Terminal Server session or "Running in crash mode remotely" topic in Windbg help.

    DebugDiag makes it easier to overcome this limitation, simply configuring it to run in service mode through its property dialog

    options & settings


    We have different tools for different tasks but also to fit specific habits of every developer: a command line script for geeks whom want to be in full control of their machine and a GUI based debugger for speedy people and final customers whom want to start troubleshooting their applications on their own. Which one to chose is mainly a matter of taste and feelings, the environment you're troubleshooting (if you already have one debugger installed on the machine, it does not make much sense to install the other as they are equivalent in most circumstances) etc... Make your choice and go with your preferred debugger, but if I can give you an advice don't forget to give the other one a try, sooner or later it might come to the rescue... smile_wink



    Quote of the Day:
    Men achieve a certain greatness unawares, when working to another aim.
    --Ralph Waldo Emerson
  • Never doubt thy debugger

    Is your UserControl sluggish at loading?


    Here's an interesting story about performance I had the chance to work on over the last couple of weeks. The object of the call was a UserControl embedded in Internet Explorer, which was very slow to load the first time you browsed the page, but then was performing quite well after that long delay (around 60 seconds); unfortunately closing and reopening the browser caused another 60 seconds delay, which was quite bothering if not frustrating for end users... As you can imagine the control needs to be downloaded, JIT compiled and loaded which of course requires some time depending on how big is the control, how fast (or slow) the Internet connection, how powerful the client etc..., but those 60 seconds where definitely too much. Moreover on Vista we were prompted to run csc.exe and under some circumstances (usually if IE was not run as Administrator) we got a FileNotFoundException.

    fiddler probing


    First thing, Fiddler showed that after downloading the first dll (the actual UserControl) we were probing for further localized resources, so we wasting about 15 seconds just for this reason (which is a quarter of the entire time spent waiting on a white IE page...). At the same time Process Monitor showed (as expected) that some time was needed to JIT the control but also to create on the fly the serialization proxy assembly, which the UserControl needed to call a remote Web Service and get the data to show to the user.

    There are different possible approaches to the problem, but in this case we had some constraints imposed by the hosting company the customer was using to test his application, so to work around those limitations we first removed the strong name from the two assemblies because it was not a strict security requirement in this case and because strong named assemblies are prone to probing (as you may know, one of the token in a strong name is the culture information). Then we specified the NeutralResourceLanguageAttribute to tell the ResourceManager to not search for resources that are included in the main assembly; when looking up resources in the same culture as the neutral resources language, the ResourceManager automatically uses the resources located in the main assembly, instead of searching for a satellite assembly with the current user interface culture for the current thread. This will improve lookup performance for the first resource you load, and can reduce your working set. As a final step we added an empty file (zero bytes) in the first places where the runtime was probing; this because the NeutralResourceLanguageAttribute resolved the problem for me (I was testing with an English OS) but not for the customer whom was using a non English OS...

    Serialization assembly

    As you can see from the screenshot here, the runtime was also probing for <assemblyname>.XmlSerializers.dll which is the proxy needed to call the remote Web Service (and which needs to be created on the fly, as Process Monitor shown); so in this case we used sgen.exe to pre-generate the serialization assembly we could put on the server in the same folder of the UserControl. This serialization assembly is downloaded by the browser and therefore there is no need to create it on the client, so we removed both the security prompt (and the exception) and the delay to create the proxy on the client.

    In short, after applying those changes the time taken from the first HTTP request to the UserControl fully loaded and functioning on the client went from about 60 seconds to just 5! smile_omg

    There is a nice article from Chris Sells on the subject, it's 5 years old but still gives some interesting insight on probing and how serve related files (like .config etc...).

    Specify a codeBase

    Doing further researches for this post I found another couple of possible solutions to the problem. First it's possible to specify a codeBase attribute in your web.config as described in http://support.microsoft.com/kb/814668/en-us (this applies also to .NET 1.1).

    Or you can add a section to the web.config file telling the ResourceManager exactly which resources are present on the machine for each assembly.  Here's an example:

       1: <?xml version="1.0"?>
       2: <configuration>
       3:     <satelliteassemblies>
       4:         <assembly name="mscorlib, Version=..., PublicKeyToken=...">
       5:             <culture>fr</culture>
       6:         </assembly>
       7:         <assembly name="UserAssembly, ...">
       8:             <culture>fr-FR</culture>
       9:             <culture>de-CH</culture>
      10:         </assembly>
      11:             <assembly name="UserAssembly2, ...">
      12:         </assembly>
      13:     </satelliteassemblies>
      14: </configuration>

    Note that the assembly references in this example are abbreviated, and they will need to supply full assembly names.



    Quote of the Day:
    For greed, all nature is too little.
    --Seneca, Roman statesman and author
Page 1 of 1 (6 items)