One of my perennial peeves is logging the output of a process, script application—or,
more properly, the complete lack of process logs to track problems and verify
that a particular program did what it was supposed to do while you weren't looking!
Many applications have the ability to create a debug file that can sometimes
be useful to non-programmers. Other programs expect the output to be all the
proof you need. And when an application crashes, a program that only displays
an error dialog is more than frustrating for everyone involved. The developer
who wrote the program needs more information (and wants it badly!) in order
to figure out what is wrong. The user wants it just as badly, so that if only
a minor adjustment is needed, she can find out about it, make the change and
get back to work without ever having to cause a programmer to lose a single
precious hair from his head.
The problem becomes even more serious, however, when the application doesn't
expect user interaction. Applications with this kind of operational need can't
get by with a simple Error Dialog because, ideally, no one is there to look
and then press "Okay".
So I'm famous for simply saying, "If it's doing something, log it!"
And I mean that. Your scripts should be fully capable of logging what they are
attempting to do, where they are in the process, if they succeeded, failed or
if there was a problem and the system pushed a message back to the script.
Additionally, I suggest that only some of the events/errors your scripts
and programs should ever make their way to the Windows Event Log. If your program
processes files, for instance, and starts to work in a directory with 800 of
them…and then discovers it can only list the files and not actually copy
them, do you want your system event logs clogged with 800 entries about the
same error? I didn't think so!
Okay then! So you took my advice and decided to keep things as simple as possible.
Your script now uses the Windows Scripting FileSystemObject to create
a text file every time it runs and it logs everything. Wonderful!
Late Friday night, while out on the town, imbibing copious quantities of brain
poison, your leash (pardon me, your pager) starts shaking in your pocket. You
jump off the stool and land flat on your butt. You shouldn't drink so much!
Your fatigued eyes stop jiggling long enough to decipher the message on the
dim screen of the pager. It appears that ServerX, the core database replication
feed has run out of disk space. Tag! You're it!
When the cabbie finally gets you to the office (well, surely you wouldn't drive
in that condition, would you?) you manage to log on to the server and start
looking for huge files that weren't there yesterday. The newest, largest file
is the log file YOU created with your script. Aaaaagh!
Look man, it's simple; you need to log, but you don't always need to log everything.
Sometimes you only need to log while in search of a problem with your process
and you want to know everything. Sometimes you want to log to satisfy an audit
requirement ("Smithers!! I want to know when you succeed AND when you fail!").
Other times you only want to log dates and times when the process starts and
stops. Sometimes, you don't want to log anything at all. There are two problems.
First, you're lazy. You don't want to constantly have to go deleting your log
files every few days to free up disk space. Tough! It's your job! The second
problem is real, though. To change how much information gets logged, you have
to go re-edit a hundred lines or so of your script!
The truth is that you can write your script with two simple subroutines to
help you control the depth of logged information produced by your script. By
using these two routines and simply editing a single variable at the beginning
of your script, you get real control of the depth of your logs and the rate
at which they grow!! A third Function can be used to make sure the log is unique
and written to the same disk location as your script. And, as if that wasn't
enough, this technique is usable with almost no changes in any VBA enabled application,
Visual Basic or VBScript!
Ahh, that's too cool!
Here's how:
- Using a global variable, define a 'DEBUG' level for the depth of information
to log (in VBScript, any variable defined in a script but outside a subroutine
has global scope).
- Determine where to save the log file and what it's called.
- Every time you perform some task in your script, send a message about the
task results to a subroutine along with a 'rating' (priority) describing the
importance of the message.
- That subroutine compares the current value of DEBUG to the priority of the
message and determines whether to forward the message to the logging subroutine.
In the following example we'll demonstrate a deliberate failure to set an Object
Variable and a deliberate success in setting another Object Variable. We'll
control the value of DEBUG by using a For…Next loop that increments
from 1 to 5. For each loop, DEBUG will have the value of (i), the increment
value for the loop.
The output log entries will be time stamped and stored in the same location
as your script and will be named DemoVariableError.Log. Save the script
to a text file (watch for line wrapping!) called DemoVariableErrorLogging.vbs.
Open a command prompt and type:
CSCRIPT <drive>:\<path>\demoerrorlogging.vbs
Where <drive>:\<path> represents the drive and path to the script
on your system. Press enter and use a text editor to open the DemoVariableError.log
and see the results.
Here's the script example (or download
this script file, also listed in the TechTrax Code
Library):
'**********************************************************************
'Constants for log file operations '*
'**********************************************************************
CONST ForReading = 1, ForWriting = 2, ForAppending = 8 '*
'**********************************************************************
Dim DEBUG, objFictional, objFSO,LogFile,strSep, objShell
'Debug values are:
'0=None
'1=Errors Only
'2=Successes Only
'3=Errors and Successes
'4=Complete Debug Information
'All other values treated as 0
DEBUG=1
'strSep is used to mark the beginning and end of a job's ouput
strSep=String(50,"=")
On Error Resume Next
Set objFSO=CreateObject("Scripting.FileSystemObject")
If Err <> 0 Then
LogBuffer Err.Number & ": " & Err.Description & _
" creating log. LogFile name = " & LogFile, Debug
Err.Clear
End If
LogFile=ExecutingFrom & "DemoVariableError.Log"
LogBuffer "Results will be logged to " & LogFile,Debug
LogBuffer "Debug is currently set to " & Debug, Debug
For i=1 to 5
DEBUG=i
LogBuffer strSep,i
LogBuffer "Job Started:" & Now,i
LogBuffer strSep,i
LogFile=ExecutingFrom & "DemoVariableError.Log"
LogBuffer "DEBUG=" & i, i
LogBuffer "Creating Fictional Object",i
'This one should Err
Set objFictional=CreateObject("SomeObject.Class")
If Err <> 0 Then
LogBuffer Err.Number & ": " & Err.Description & " - creating ",1
LogBuffer "SomeObject.Class",1
Err.Clear
Else
LogBuffer "Created SomeObject.Class",2
End If
LogBuffer "Creating Shell Object", i
'This one shouldn't err
Set objShell=CreateObject("wscript.shell")
If Err <> 0 Then
LogBuffer Err.Number & ": " & Err.Description & " - creating ",1
LogBuffer "WScript.Shell",1
Err.Clear
Else
LogBuffer "Created Shell",2
Set objShell=Nothing
End If
LogBuffer strSep,i
LogBuffer "Job Finished:" & Now,i
LogBuffer strSep,i
Next
On Error GoTo 0
'====================================================================
Sub LogAction (strEntry)
Dim strErrMsg, f
On Error Resume Next
wscript.echo strEntry
set f = objFSO.OpenTextFile(LogFile, ForAppending, True, -2)
f.WriteLine "[ " & Now & " ] - " & strEntry
f.close
On Error Goto 0
End Sub
'====================================================================
Sub LogBuffer(strLogEntry,strPriority)
Select Case DEBUG
Case 1
If strPriority=1 Then
LogAction strLogEntry
End If
Case 2
If strPriority=2 Then
LogAction strLogEntry
End If
Case 3
If (strPriority >= 1) AND (strPriority <= 3) Then
LogAction strLogEntry
End If
Case 4
If (strPriority>=1) AND (strPriority<=4) Then
LogAction strLogEntry
End If
Case Else
End Select
End Sub
'====================================================================
Function ExecutingFrom()
Dim strScriptPath
LogBuffer "Entering Function 'ExecutingFrom'", 4
strScriptPath=Left(wscript.scriptfullname, _
Len(wscript.scriptfullname)-Len(wscript.scriptname))
If Right(strScriptPath,1) <> "\" Then
strScriptPath=strScriptPath & "\"
End If
ExecutingFrom=strScriptPath
LogBuffer "ExecutingFrom =" & ExecutingFrom, 4
LogBuffer "Leaving Function 'ExecutingFrom'.", 4
End Function
'====================================================================
|
