Tuesday, December 30, 2008

Script Code: Debug or Log Printing

It's often helpful to echo or print information during the execution of a script, so that you can "see" what is happening as it does its processing.  Most people use Wscript.Echo if they're using VBScript, which is fine, but sometimes you may want to produce a more rigidly formatted output.  This can be useful when you want to parse the output from this into something like a log reader or another script as well.

A very common scenario is to have a script that does something and produces some sort of process log as it runs, and then another script or process comes along and collects or scans those logs to produce some sort of additional output.

One way to do this is to replace Wscript.Echo with a custom Sub that you can apply global control over and thereby have additional flexibility and capability with less work.  Consider this piece of code below...

    Const DebugEnabled = True

    Sub MyEcho(strVal)
        If DebugEnabled = True Then
            Wscript.Echo Now & vbTab & strVal
        End If
    End Sub

This is usually more helpful if your script takes a long time to complete.  A script that runs and finishes within a second or two won't really benefit from bothering to include the full date-and-time stamp on each line it produces.  But if you have an iterative loop which takes a few seconds or minutes to process each loop, it might be helpful to see the exact date-and-time on each loop iteration when reviewing the results later.

A classic example would be running a lengthy file backup task.  You may have a script that copies a significant number of files, or very large files, and runs unattended overnight.  The next day you might want to see which steps in the script required the most time to complete.  Consider this chunk of code...

    MyEcho "beginning file copy process..."
    For each objFile in objFolder.Files
        sourcePath = sourceFolder & "\" & objFile.Name
        targetPath = targetFolder & "\" & objFile.Name
        MyEcho "copying: " & sourcePath & " --> " & targetPath
        objFSO.CopyFile sourcePath, targetPath, True
        MyEcho "copy completed"
    MyEcho "file copy process completed"

The output might look like this...

    12/30/2008 5:47:09 PM beginning file copy process...
    12/30/2008 5:47:10 PM copying: c:\folder1\file1.txt --> c:\folder2\file1.txt
    12/30/2008 5:48:02 PM copying: c:\folder1\file2.txt --> c:\folder2\file2.txt
    12/30/2008 5:49:15 PM file copy process completed

You can see that copying file2.txt took more than a minute to copy, while file1.txt took slightly less than a minute to copy.  The entire process took just over two minutes.

This isn't specific to any one scripting language.  You can use this technique in any language.  For example, with KixTart:

    $DebugEnabled = 1

    Function MyEcho($strVal)
        If $DebugEnabled = 1
            ? @DATE+' '+@TIME+Chr(9)+$strVal

Keep in mind that different languages incur some minor differences you need to adjust for.  In the case of KixTart 4.6, it defaults to rendering @DATE as "YYYY/MM/DD", so you may need to pipe that through another function to reformat if needed.  Again, minor.
Post a Comment