In a perfect world, computer applications would be syntactically and semantically correct and complete, thus exhibiting no errors nor flaws. Ours is not a perfect world, though, and even worse is that a significant part of those computer applications are still being coded in Visual Basic 6.0. Great!! This way, we are being given a huge opportunity to contribute towards that perfect world.

 

  This post is exactly about one such opportunity: getting rid of these annoying errors which you did not find while testing the code in your development environment, but once it gets under massive exercise by the end-users, they start popping like crazy. My inspiration for this post is an Active Server Pages application which calls into some Visual Basic 6.0 DLLs which, in turn, are accountable for pretty much everything going on in the application from its business layer to page rendering. That is how the VB code is getting such huge exercise and the event logs are getting filled with these VBRuntime errors.

 

  Here it is, the tongue-twister…

 

  So, what can we do about this? The error, by itself, says little about what is going on and you’re live, meaning you can’t pop in with a breakpoint from Visual Studio 6.0… Well, not from Visual Studio, but from any production debugger, you actually can. You can also instruct it to create a full memory dump every time one such error occurs, even if your application is not crashing.

 

  What do we need for that? Well, the list is short, but not necessarily easy to fulfill:

  • A production debugger, as stated above. I personally recommend the acclaimed Debugging Tools for Windows, but of course, I’m biased… By the way, the rest of the post assumes you can live with such bias…
  • Private symbols for the VB6 components. This usually means a PDB file for each module (EXE or DLL) being called when the problem occurs. Getting a perfectly matching private symbol set can be a harsh task, but if the application is still under development or maintenance, be sure to check the Create Symbolic Debug Info in the project properties before recompiling and deploying, and if possible avoid optimizations, at least temporarily.



    If the application is not under maintenance and/or the source code is not available anymore, you’re in trouble. But then again, what would you do if you found out the cause of the problem?
  • Keep the users warned that for some time, they will perceive a non-negligible lack of performance.

  Your users are warned, you have private symbols and you have chosen the Debugging Tools for Windows (wise choice!!). What next? Ok, you can use WinDbg, attach to the process, type sxe C0000005, hit F5, wait for the exception to occur, and when it does, use the .dump /ma DumpFile.dmp to dump it to a file. Let me recommend another way, which is less disruptive of user experience and will enable you to get multiple occurrences of these errors, if they happen while the debugger is attached.

 

  This error is nothing more than the VBRuntime counterpart for an Access Violation, meaning that your code is trying to access a member property or method from a non-existing object (from Nothing, in VB6 notation). So, this is what you can do:

  • Create and edit a file with the cfg extension (I’ll assume the name config.cfg).
  • Copy and paste the following contents (remove the Option tag if not under IIS and be sure to attach to a particular process later):
    <ADPlus>
      <Settings>
        <RunMode> CRASH </RunMode>
        <Option> IIS </Option>
      </Settings>
      <Exceptions>
         <Config>
           <Code> av </Code>
           <Actions1> Log;FullDump </Actions1>
         </Config>
      </Exceptions>
    </ADPlus>
  • Save the file in the same folder where the debugging tools have been installed.
  • Open a command prompt, go to that folder and run the following command cscript adplus.vbs –c config.cfg. You can also specify an output directory by using the –o option, if you feel you’ll be lacking space in your current volume.

 

 

  This will create as many full dumps as access violation occurrences and each one will have a synchronous picture of what was being called by the time it occurred. You can then open each one in WinDbg, for instance, ensuring you have your private symbols in place (the source code will also help) and with a few commands, you’ll be able to pinpoint the cause.

 

  By the way, another option would be to run a parametrized command, such as cscript adplus.vbs -crash -ce C0000005 -FullOnFirst -p <PID> (or -iis). Thanks Bruno, for the valuable input! Still, however, a configuration file will allow you to easily adapt to the circumstances along the way. For a broader discussion on how to capture the adequate set of dumps, check this great post:

    http://blogs.msdn.com/carloc/archive/2007/10/08/ok-now-how-do-i-capture-my-dump.aspx

 

  Back to the discussion at hands, let’s take a look at an example.

 

  When opening one of the dump files, this is what WinDbg is showing:

 

Windows Server 2003 Version 3790 (Service Pack 2) MP (4 procs) Free x86 compatible

Product: Server, suite: TerminalServer SingleUserTS

Machine Name:

Debug session time: Mon May 11 11:56:53.000 2009 (GMT+1)

System Uptime: 0 days 11:54:17.328

Process Uptime: 0 days 0:01:35.000

................................................................

................................................................

................................................................

........................................

Loading unloaded module list

....

This dump file has an exception of interest stored in it.

The stored exception information can be accessed via .ecxr.

(170c.153c): Access violation - code c0000005 (first/second chance not available)

eax=00000000 ebx=72e5e380 ecx=72e67cdb edx=00000001 esi=736560f4 edi=00000000

eip=0bfd304f esp=02dedb7c ebp=02dedc1c iopl=0         nv up ei pl nz na po nc

cs=001b  ss=0023  ds=0023  es=0023  fs=003b  gs=0000             efl=00010202

FailingModule!failingClass::failingFunction+0x14f:

0bfd304f 8b10            mov     edx,dword ptr [eax]  ds:0023:00000000=????????

 

  We can run kbn200 and check the call stack:

 

0:024> kbn200

 # ChildEBP RetAddr  Args to Child             

00 02dedc1c 0bfd07db 0d747678 02dedc78 02dedd44 FailingModule!failingClass::failingFunction+0x14f

01 02dedd98 110136ca 0d747678 087c2fac 02dedf90 FailingModule!failingClass::FailingFunctionCaller+0x9bb

02 02dee000 77d05186 05b9bd68 05ba7aa4 08794c7c FormRender!Constructor::RenderPageFraction+0x3ea

03 02dee028 73646a6f 05b9bd68 00000024 00000004 oleaut32!tPushValJmpTab+0x102

04 02dee984 7363a0d4 05b9bd68 11011734 60030002 msvbvm60!VBStrToLong+0xcf

05 02dee9e0 7773fecb 05b9bd68 60030002 734614f4 msvbvm60!rtFindFirstFile+0x185

06 02deea18 77720fc4 086779dc 05b9bd68 02deeb50 ole32!DISPATCH_CLIENT_FRAME::Invoke+0x3b

07 02deea60 7772134a 0869b8b0 02deeba0 02deeb2c ole32!CCtxChnl::SyncInvoke2+0x70

08 02deeb18 77722ee6 0009c3b0 00104d30 02deec24 ole32!CCtxChnl::SendReceive2+0x201

09 02deec78 77741804 0869b8b4 086776dc 0d8a71cc ole32!CCtxChnl::OnCall+0x225

0a 02deec98 77740027 086776d8 02deecc0 00000006 ole32!LEGACY_INTERCEPTOR::CallIndirect+0x91

0b 02deecb8 7347d36b 8004d091 60030002 734614f4 ole32!LEGACY_INTERCEPTOR::Invoke+0x23

0c 02deed0c 73468ad1 019e4b68 0d8a71cc 60030002 vbscript!CatchIDispatchInvoke+0x46

0d 02deed4c 73468a40 0194b218 0d8a71cc 60030002 vbscript!IDispatchInvoke2+0xaf

0e 02deed88 734689f2 0194b218 0d8a71cc 60030002 vbscript!IDispatchInvoke+0x59

0f 02deee9c 7346613b 0194b218 0d8a71cc 60030002 vbscript!InvokeDispatch+0x13a

10 02deeec0 73468b57 0194b218 0d8a71cc 60030002 vbscript!InvokeByName+0x42

11 02def19c 734633e0 00000000 00000000 0194b218 vbscript!CScriptRuntime::Run+0x2587

12 02def294 734637d1 00000000 00000000 01934530 vbscript!CScriptEntryPoint::Call+0x5c

13 02def2ec 7347e882 0194d190 00000000 00000000 vbscript!CSession::Execute+0xb4

14 02def374 7347d17c 00000000 00000000 01cc27f4 vbscript!NameTbl::InvokeEx+0x526

15 02def3c4 73467353 019e4b68 0194ff80 0b76294c vbscript!CatchIDispatchExInvokeEx+0x43

16 02def400 734672c5 0194b218 0194ff80 0b76294c vbscript!IDispatchExInvokeEx2+0xa6

17 02def438 73466209 0194b218 0194ff80 0b76294c vbscript!IDispatchExInvokeEx+0x56

18 02def548 7346613b 0194b218 0f76dbf0 0b76294c vbscript!InvokeDispatch+0x101

19 02def56c 73466f6c 0194b218 0194ff80 0b76294c vbscript!InvokeByName+0x42

1a 02def848 734633e0 00000000 00000000 0194b218 vbscript!CScriptRuntime::Run+0x262b

1b 02def940 734637d1 00000000 00000000 00000000 vbscript!CScriptEntryPoint::Call+0x5c

1c 02def998 73463b9c 0f5da808 00000000 00000000 vbscript!CSession::Execute+0xb4

1d 02def9e8 73461849 00000000 00000000 709e19c0 vbscript!COleScript::ExecutePendingScripts+0x13e

1e 02defa04 709e2bfa 023c2708 023c2708 01cc27f0 vbscript!COleScript::SetScriptState+0x150

1f 02defa30 709e2bbc 00000000 709e19c0 02defb38 asp!CActiveScriptEngine::TryCall+0x19

20 02defa6c 709e2af2 00000000 6472474e 01fc22b8 asp!CActiveScriptEngine::Call+0x31

21 02defa88 709e29f6 02defb0c 00000000 00000000 asp!CallScriptFunctionOfEngine+0x5b

22 02defadc 709e2921 024c2950 00000000 02defb68 asp!ExecuteRequest+0x17e

23 02defb44 709e24e0 024c2950 01fc22b8 02defb68 asp!Execute+0x24c

24 02defb98 709e244a 00000000 00000000 0b078ba0 asp!CHitObj::ViperAsyncCallback+0x3f0

25 02defbb4 4a77b5ea 02042cc8 0009c240 02defd74 asp!CViperAsyncRequest::OnCall+0x92

26 02defbd0 77720d30 0b078ba0 00104c04 00000000 comsvcs!CSTAActivityWork::STAActivityWorkHelper+0x32

27 02defc1c 777217dc 00000000 00104c04 4a77b5b8 ole32!EnterForCallback+0xc4

28 02defd7c 776f03b4 02defc54 4a77b5b8 0b078ba0 ole32!SwitchForCallback+0x1a3

29 02defda8 7769c194 00104c04 4a77b5b8 0b078ba0 ole32!PerformCallback+0x54

2a 02defe40 7772433a 0009c240 4a77b5b8 0b078ba0 ole32!CObjectContext::InternalContextCallback+0x159

2b 02defe60 4a77b78c 0009c240 4a77b5b8 0b078ba0 ole32!CObjectContext::DoCallback+0x1c

2c 02defecc 4a77bcf2 001014b0 00101490 086d6444 comsvcs!CSTAActivityWork::DoWork+0x12d

2d 02defee4 4a77c7de 0b078ba0 00000001 00101490 comsvcs!CSTAThread::DoWork+0x18

2e 02deff04 4a77cabf 00000000 0190ca48 0190c880 comsvcs!CSTAThread::ProcessQueueWork+0x37

2f 02deff84 77bcb530 00101490 00000000 00000000 comsvcs!CSTAThread::WorkerLoop+0x190

30 02deffb8 77e64829 0190c880 00000000 00000000 msvcrt!_endthreadex+0xa3

31 02deffec 00000000 77bcb4bc 0190c880 00000000 kernel32!BaseThreadStart+0x34

 

  Since we’re sure we have private symbols, we can have the variables displayed with dv /t.

 

0:024> dv /t

void * Me = 0x0d747678

long * intArg = 0x02dedc78

wchar_t ** failingFunction = 0x02dedd44

Boolean unnamed_var1 = False (0)

long unnamed_var1 = 0

long unnamed_var1 = 48159737

long unnamed_var1 = 0

struct Variant unnamed_var1 = struct Variant

struct Variant unnamed_var1 = struct Variant

void * unnamed_var1 = 0x00000000

wchar_t * unnamed_var1 = 0x00000000 ""

wchar_t * unnamed_var1 = 0x00000000 ""

wchar_t * unnamed_var1 = 0x00000000 ""

wchar_t * unnamed_var1 = 0x00000000 ""

wchar_t * unnamed_var1 = 0x000dc434 "//NodeToBeFound[@blnCheck='TRUE'][@id='60']/@Attibute"

wchar_t * unnamed_var1 = 0x0b3e9d3c "//NodeToBeFound[@blnCheck='TRUE'][@id='60"

wchar_t * unnamed_var1 = 0x05b44844 "60"

void * objXMLTipos = 0x036381c0

wchar_t * xslt = 0x00000000 ""

wchar_t * failingFunction = 0x00000000 ""

 

  Here’s the (sanitized) code excerpt, matching the output above:

 

Private Function failingFunction (intArg As Long) As String

        Const cstrMethodName As String = "failingFunction"

        Const cstrTypesPath As String = "../config/EntityTypes.xml"

 

        On Error GoTo ErrorHandler

       

        Dim objXMLTypes As MSXML2.DOMDocument

        Dim xslt        As String

       

        Set objXMLTypes = mobjOpenXMLFile(mobjASPContext.Server.MapPath(cstrTypesPath))

        xslt = objXMLTypes.selectSingleNode("//NodeToBeFound[@blnCheck='TRUE'][@id='" & intArg & "']/@Attribute").Text

        failingFunction = xslt

       

ErrorHandler:

        Set objXMLTypes = Nothing

       

        If Err.Number <> 0 Then

          LogError vbLogEventTypeError, cstrModuleName, cstrMethodName, Err.Description

          RaiseError cstrModuleName, cstrMethodName, Err.Description

        End If

End Function

 

  Having the source code copied to my Source File Path in WinDbg, it promptly points us out that the instruction pointer was at the highlighted line when the access violation occurred. Reaching there without any source code is possible, you'd need to unassemble the function (using the uf command) and manually walk the assembly code back from the instruction pointer (0bfd304f) and checking the context - registers and memory - along the way. Though that can be fun, we'd be deep diving into MSXML code and the post would probably lose its main focus.

 

  Anyway, as you can see from the variables above, there is a string matching the concatenation of the tokens which form the XML query, meaning that the argument was 60. You could also get that from the long * intArg = 0x02dedc78 pointer, by issuing the command

 

0:024> dt long 0x02dedc78

60

 

  After having opened the EntityTypes.xml configuration file, I quickly realized there was no such content matching the query (no node named NodeToBeFound having the blnCheck set to true and an id of 60). By trying to access the Text property of Nothing, the access violation occurs and so the root cause has been found.

 

  As you can see, the cause was a very simple and straightforward one, but you’d probably spend a lot of time trying to figure it out with printf-like techniques, whereas using a production debugger such as this one, you’d find it in almost no time at all.

 

  Till next time,

 

    Manuel Oliveira