Visual Basic

Tip 6: Write meaningful error logs (to a central location if possible).

By way of an example, Listing 1-3 is a typical log file entry produced by our internal application template code. No explanation is provided because most of the entry is pretty obvious.

Listing 1-3 Typical log file entry

  The Application:
  ----------------
  C:\TMS\TEMPLATE\TEST.EXE  Version 1.0.15
  OS App Name C:\TMS\TEMPLATE\TEST.EXE
  The Error:
  ----------
  An error has occurred in C:\TMS\TEMPLATE\TEST.EXE - the TMS error code associated
  with this error is 000053. If the problem persists, please report the error to TMS
  support. The error occurred at line 100.
  The error probably occurred in frmMainForm.cmd1_Click.
  The standard VB error text for this error is 'File not found'.
  Active Environment Variables:
  -----------------------------
  TMP=C:\WINDOWS\TEMP
  winbootdir=C:\WINDOWS
  COMSPEC=C:\COMMAND.COM
  PATH=C:\WINDOWS;C:\WINDOWS\COMMAND;C:\;C:\DOS
  TEMP=C:\TEMP
  DIRCMD=/OGN/L
  PROMPT=$e[0m[$e[1;33m$p$e[0m]$_$g
  CMDLINE=WIN
  windir=C:\WINDOWS
  Relevant Directories:           Attr:
  ---------------------
  Windows DIR C:\WINDOWS        - 16
  System  DIR C:\WINDOWS\SYSTEM - 16
  Current DIR C:\TMS\TEMPLATE   - 16
  Versions:
  ----------
  Windows    - 3.95
  DOS        - 7.0
  Mode       - Enhanced
  CPU        - 486 or Better
  COPRO      - True
  Windows 95 _ True (4.03.1214)B
  Resources:
  ----------
  Free Mem (Rough) 15,752 MB
  Free GDI  (%) 79
  Free USER (%) 69
  Free Handles 103
  Other:
  ------
  Threads           - 64
  VMs              - 4
  Registered Owner _ Peter J. Morris
  ******************************************************************************
  * Error Entry End. TEST
  ******************************************************************************
  ******************************************************************************
  * Stack Dump Start. TEST. Created 21 March 1998 19:01
  ******************************************************************************
  Stack Frame: 001 of 003 AppObject   - Run         Called @ line 70 CheckStack
  Stack Frame: 002 of 003 AppObject   - CheckStack  Called @ line 10 cmd1_Click
  Stack Frame: 003 of 003 frmMainForm - cmd1_Click
  ******************************************************************************
  * Stack Dump End. TEST
  ******************************************************************************
  ******************************************************************************
  * DAO Errors Start. TEST. Created 21 March 1998 19:01
  ******************************************************************************
  No Errors
  ******************************************************************************
  * DAO Errors End. TEST
  ******************************************************************************

Also, see the note on stack frames later in this chapter for a fuller explanation of the Stack log entries.

The log files you write can be centralized; that is, all your applications can write to a single file or perhaps to many different files held in a central location. That "file" could be a Microsoft Jet database. Now if you log meaningful information of the same kind from different sources to a database, what have you got? Useful data, that's what! At TMS, we created a system like this once for a client. All the data gathered was analyzed in real time by another Visual Basic application and displayed on a machine in the company's support department. The application had some standard queries it could throw at the data (How's application xyz performing today?), as well as a query editor that the company could use to build its own queries on the data. (Show me all the Automation errors that occurred for user abc this year, and sort them by error code.) All the results could be graphed, too-an ability that, as is usual, allows the true nature of the data statistics to become apparent.

After a little while, it wasn't just Support that accessed this database. User education used it to spot users who were experiencing errors because of a lack of training, and developers used it to check on how their beta release was running. Remember, users are generally bad at reporting errors. Most prefer to Ctrl+Alt+Delete and try again before contacting support. By logging errors automatically, you don't need the user to report the error (sometimes incorrectly or with missing information: "Let's see, it said something about…"); it's always done by the application, and all the necessary information is logged automatically.

Figure 1-4 shows an example of the kind of output that's easy to produce from the log:

Figure 1-4 Graphing error log data

This chart shows how many users have produced trappable errors in various interesting applications.

Whenever we hit an error, we determine whether we're running in Visual Basic's IDE and then log or output different error text and do some other stuff differently depending on the result of that test. The reason we do this is that programmers are not end users, meaning that a programmer doesn't mind seeing "Input past end of file," but users almost always mind! If you know which context you're running in, you can easily switch messages.

The test we do internally at TMS to determine whether we're running in the IDE involves a routine called InDesign. Here's the code (the explanation follows):

Public Function InDesign() As Boolean
      ' ****************************************
      ' The only thing Debug.Assert is good for!
      ' ****************************************
      Static nCallCount   As Integer
      Static bRet         As Boolean  ' By default this is set to False.
      nCallCount = nCallCount + 1
      Select Case nCallCount
          Case 1: ' First time in
              Debug.Assert InDesign()
          Case 2: ' Second time in so we must have executed Debug.Assert...
              bRet = True
      End Select
      ' If Debug.Assert called, we need to return True to prevent the trap.
      InDesign = bRet
      ' Reset for future calls.
      nCallCount = 0
  End Function

In the earlier versions of Visual Basic (previous to Visual Basic 6), InDesign used API calls to determine whether the Visual Basic IDE was kicking around. The version of InDesign (not shown here) evolved from some Visual Basic 4 code and therefore needed to cater to both the 16-bit and 32-bit worlds. We modified this code for the pure 32-bit world and replaced it with what amounts to a call to GetModuleHandle:

Private Function InDesign() As Boolean
      InDesign = 0 < GetModuleHandle("VBA5.DLL")
  End Function

The only problem with this code was that you needed to know the name of the DLL that implements the IDE, which in this case was VBA5.DLL. Who knew that this would be VBA6.DLL for version 6 and who knows what it will be for version 7 and so on? By the way, this code works because if the application is running under the IDE in Win32, the IDE (and its DLLs and so on) must be loaded into the same process space as the application. The DLLs of other processes cannot be seen (easily, anyway); ergo, if you can see it you must have it loaded, and if you have it loaded you must be running in the IDE.

Anyway, back to the InDesign code shown earlier. This "new" cut of the code should work for all future versions of Visual Basic (as well as for version 6). This code essentially uses the fact that Debug.Assert is coded in such a way as to make it suboptimal (an explanation of this statement follows shortly). Because the Debug object effectively goes away when you make an EXE, it follows that methods applied to it, like Print, also have no effect-in fact, they don't even run. Because the Assert method is such a method, we can make use of this disappearing act to determine whether the code is running in design mode.

The first time we call the function, which requires only a simple If InDesign Then statement, nCallCount is zero and bRet is False (initialized by default). Notice that both variables are declared as static, meaning they are accessed locally but stored globally. In other words, they are shared, persistent objects that can be accessed only within the scope of the subroutine in which they're declared. We increment nCallCount and then execute the Select Case statement. Obviously nCallCount is now 1, so the Case 1 code executes. At this point, if we're running in design mode, the Debug.Assert line causes us to reenter the routine. This time, nCallCount = nCallCount + 1 increments the static nCallCount to 2, and the Case 2 code sets bRet to True. Note that True is returned to the call made to Debug.Assert from the first entry into InDesign. Because we've asserted something that's True, we don't execute a Stop here. Instead, we return to the line of code to be executed after the call to Debug.Assert, which is the InDesign = bRet code (again). Once more we return True (because bRet is still set to True from the previous call to InDesign). This final value of True is now returned to the original caller to indicate, "Yes, we are running in design mode."

Now consider what happens if we're running as an EXE. Basically this means that the line Debug.Assert InDesign is missing from the routine. In this case, the only call made to our routine returns the state of bRet-False by default. If you're worried about the clock cycles taken here (that as an EXE we increment an integer and then set it to zero again), don't be-it's fast! If you insist, however, you can wrap the routine so that it's called just once, perhaps upon application start-up.

OK, why did I say that Debug.Assert was suboptimal? Normally assertions are used to implement what is known in the trade as a "soft if." Consider this code:

nFile = FreeFile

If FreeFile fails, what does nFile equal? Actually, like Open, FreeFile raises an exception to indicate failure (maybe it knows that return values can, and will, be ignored), but for the sake of argument let's say FreeFile returns 0. To detect this, as you should if you're building really critical applications that must cope with and recover from every possibility, expand the code to this:

nFile = FreeFile
  If nFile <> 0 Then
      .
      .
      .
  End If

Adding the conditional test and the indentation complicates the code. The execution time increases due to the branch, the evaluation of both the expressions on either side of the angle brackets, and of course the comparison itself. For all we know, we may never need this code-after all, what is the probability that FreeFile will fail in real life? To test this, sanitize the code, and make it more efficient, we would use a "soft if" conditional instead of a "hard if" conditional:

nFile = FreeFile
  Assert nFile <> 0
  .
  .
  .

Here we're asserting our belief that FreeFile will never return 0. (Note that we've lost the indentation.) Now we build the application and send it out to test. If the assertion fails, the probability that we've run out of file handles surely approaches 1, whereas if it doesn't fail, the probability approaches 0. In this case, we can decide that the likelihood of failure is so remote that we can effectively ignore it. If the assertion never fails, we use conditional compilation to remove it and build the final EXE. In fact, we'd normally remove all assertions either by turning them into "hard ifs" or by removing them altogether. Never ship with assertions in your code. By the way, all of the previous was C-speak (for example, I'd do it this way in C or C++), and therein lies the rub. In Visual Basic you can't do otherwise because Debug.Assert is removed for you whenever you build an EXE. "Great," you say. "So now I must never ship with assertions in my code?" (I just said this practice was a good one, but only when you ship the final EXE.) "How do I determine if an assertion failed during a test if it's not even there?" Aha-the plot thickens. Assertions in Visual Basic seem to be there solely for the developer and not the tester, meaning they work only in the IDE environment. In other words, suboptimal. That is, of course, unless you ship the source and IDE when you go out to beta!

Back to the story. By using InDesign we can, as mentioned earlier, do things a little differently at run time depending upon whether we're running in the IDE. We at TMS usually store the result of a single call to InDesign in a property of the App object called InDesign. (We replace the real App object with our own-also called App-and set this property at application start-up.)

Another use of App.InDesign is to turn off your own error handling altogether. Now I know that Visual Basic allows you to Break On All Errors, but that's rarely useful, especially if you implement delayed error handling. Instead, use App.InDesign to conditionally turn error handling on or off:

If Not App.InDesign Then On Error GoTo ...

The reason for this is that one of the last things you want within the IDE is active error handlers. Imagine you're hitting F8 and tracing through your code. I'm sure you know what happens next-you suddenly find yourself in an error handler. What you really want is for Visual Basic to issue a Stop for you on the erroring line (which it will do by default if you're using the IDE and hit an error and don't have an error handler active). The code above causes that to happen even when your error handling code has been added. Only if you're running as an EXE will the error trap become enabled.