Wednesday, June 29, 2005

VBScript Production Debugging

An error typically occurs in an ASP application running VB Script when either

  1. An On Error Resume Next statement is called prior to executing some script. A number of method calls are then made which can potentially raise errors. After each statement is completed the Err.Number property is usually checked and action taken such as logging the error and providing user friendly messages.
  2. No On Error Resume Next statement is called prior to executing some script . In this case any statements that follow will halt the processing of the script and return a runtime application error to the user.

Whilst the first case is the preferred approach to handle errors gracefully most developers typically do not check most statements for errors. If Err.Number is not checked errors can be silently ignored by the server side script, and then consequently cause other errors which are logged. It is therefore essential to be able to log information on the original error, namely the source, description and number.

Unlike languages such as C++ / VB or .NET exceptions aren’t raised to the debugger from scripting engines such as VBScript. Consequently we can’t use adplus to capture a dump file when a specific type of exception occurs. However when an error is raised a number of functions are called within the scripting runtime.

  • vbscript!COleScript::OnScriptError. This is called when a script occurs in the 2nd case above
  • vbscript!CScriptRuntime::RecordErrorContext. This is called to record an error in the scripting runtime when On Error Resume Next has been called.

Although we can’t use adplus to create a dump file on an exception (because none is raised) we can use it to create a dump when a specific break point is reached. Opening the dump file shows the following call stack

0:023> kvn
# ChildEBP RetAddr Args to Child
00 0148f4a8 733183bf 0003aa70 000b5f48 00000000 vbscript!CScriptRuntime::RecordErrorContext
01 0148f4c4 73318320 0003aa70 0148f5cc 00000010 vbscript!CSession::RecordExcepInfoAndClear
02 0148f5b8 73304b01 0003a9c0 000b5f48 60030001 vbscript!InvokeDispatch

If we dump the first argument plus 8 we can see the EXCEPINFO structure which is passed to this method. EXCEPINFO is the automation structure which defines an error i.e.

struct EXCEPINFOA, 9 elements, 0x20 bytes
+0x000 wCode : Uint2B
+0x002 EXC_unused1 : UChar
+0x004 bstrSource : Ptr32 to Void
+0x008 bstrDescription : Ptr32 to Void
+0x00c bstrHelpFile : Ptr32 to Void
+0x010 dwHelpContext : Uint4B
+0x014 EXC_unused2 : UChar
+0x018 pfnDeferredFillIn : Ptr32 to Void
+0x01c scode : Uint4B

Reviewing the dump we see

0:023> dd 0003aa70 + 8
0003aa78 00000000 000b85bc 00121254 00000000
0003aa88 000f43e8 00000000 00000000 800a0063
0003aa98 00000000 00000000 00000000 00000000
0003aaa8 00000000 00000000 000a0004 0008012a

To find the source and description we can use the du command i.e.

0:023> du 000b85bc
000b85bc "MyVBClass"
0:023> du 00121254
00121254 "Failed to get supplier invoice, "
00121294 "Reason=Failed to open connection"
001212d4 ", reason=Object required"

However to get this information a full dump needs to be created. If many script errors occur this maybe unworkable in a production environment. A more elegant approach involves using a custom action in an adplus config file to extract the source, description and number and add to the log file adplus produces. i.e.



<ADPlus>
<Settings>
<RunMode>CRASH</RunMode>
<ProcessID><Put process id in here></ProcessID>
</Settings>
<Breakpoints>
<NewBP>
<Address>vbscript!CScriptRuntime::RecordErrorContext</Address>
<CustomActions>.echo -----;.echo VB Script On Error Resume Next error occurred.;.echo;.echo Source:;du poi(poi(esp+4)+c);.echo Description:;du
poi(poi(esp+4)+10);.echo Code:;?poi(poi(esp+4)+24);g</CustomActions>
<Actions>Log;Stack;</Actions>
<ReturnAction>G</ReturnAction>
</NewBP>
<NewBP>
<Address>vbscript!COleScript::OnScriptError </Address>
<CustomActions>.echo -----;.echo VB Script On Error Resume Next error occurred.;.echo;.echo Source:;du poi(poi(esp+4)+c);.echo Description:;du
poi(poi(esp+4)+10);.echo Code:;?poi(poi(esp+4)+24);g</CustomActions>
<Actions>Log;Stack;</Actions>
<ReturnAction>G</ReturnAction>
</NewBP>
</Breakpoints>
</ADPlus>

The most interesting line in the config file is

.echo Source:;du poi(poi(esp+4)+c);.echo Description:;du poi(poi(esp+4)+10);.echo Code:;?poi(poi(esp+4)+24);

The source and description are output as strings using the du command. From the parameter poi(poi(esp+4)+c), esp+4 is the stack pointer + 1 DWORD which equals the first parameter to the function were breaking on ( RecordErrorContext or OnScriptError ). This is dereferenced using the poi operator from which we then add 0xC to get to the offset of the Source member in the EXCEPINFO structure. The Source member is just a pointer to a string so poi is used again to dereference it. Description is handled the same and the error code is simply output using the ? evaluate expression command.

When a VB Script exception occurs you get all the relevant information provided in the log file along with any other exceptions which are raised i.e.

VB Script On Error Resume Next error occurred.

Source:
0017edf4 "MyVBClass"
Description:
0017eeac "Failed to get supplier invoice, "
0017eeec "Reason=Failed to open connection"
0017ef2c ", reason=Object required"
Code:
Evaluate expression: -2146828189 = 800a0063

No comments: