Why Logging Matters

Nobody likes dealing with log files.  Nerds like to invoke a shock of disbelief by claiming they do, but let's face it, if they saw a naked attractive person or a glass of cold beer, they'd rather tackle one of those before tackling a big log file.

But if you are writing software, or making anything that uses software technology to "do" something, you really need to take some time to at least make it possible to generate a log output.  A log file is like the black box on an aircraft. It's your chance to create a trail of crumbs to lead you back to where things go wrong at the worst possible times.  Whether you save your status output to a "file", a database, a cardboard box or whatever, doesn't really matter.  Well, it does matter, but the most important aspect is that you bother to make some output to be captured somewhere while your bundle of technological joy is doing something.

What to do?

So, how do you know what to log?  In simplest terms: EVERYTHING.  Log as much as you possibly can.  You can get fancy and split your verbosity into "normal" and "heavy-duty" if you want.  It really depends on your assessment of how complex the processing you're performing really is.  Regardless of verbosity, the most simple and direct advice I can offer you is to do your logging output as follows:

A) Before you execute the next task
B) During the task execution (redirected log output)
C) After the task completes (result or exit code)

I've seen people who only use option (A), which isn't bad really, except that the output you'd see at (C) might impact the very next task to be executed (or another later in the sequence).  Option (C) alone makes it tough to track a complicated (lengthy) sequence, since you won't be able to find where it crashed.  At the very least, use options (A) and (C) together.  Even without (B) that will help enormously.  One project I worked with would include a routine in (C) that essentially captured the output from (B) which happened to be an out-of-band process, and merge it back into the same log as (A), and then continued piping into the same log with (C) and onward.  That's really not as complicated as it wounds.

Time-stamping is very important as well.  I prefer to prefix each and every line of status output with a (short-format) DATE and (long-format) TIME, followed by a category tag (e.g. "info", "fail", "warn", etc.) and then the detailed verbage.  As an example from a CMD script:

echo %DATE% %TIME% info: adjusting target folder permissions... >>%LOG%
cacls %TARGETPATH% /e /t /c /g users:C
echo %DATE% %TIME% info: exit code is %errorlevel% >>%LOG%

From VBscript, you could do it something like this as well:

wscript.echo Now & " info: getting ready to copy files to " & targetPath
retval = objShell.Run("cmd /c robocopy " & sourcePath & " " & targetPath & options, 7, True)
wscript.echo Now & " info: exit code is " & retval

The language doesn't really matter.  You can do this with PowerShell, KiXtart, Perl, or anything that is still often used in 2012.  The above examples are just for demonstration.  There are many ways, some better than others, to create status output for logging.  Just do it.


Conclusion

Logging really is your friend.  It's your black box recorder, waiting to shine a crucial light on exactly which little bolt failed and caused the entire jumbo jet to crash into a mountain side on a clear day.  Best of all, it's ENTIRELY under your control (if you're the one enabling status output from your program code or software package, or script). You can make it do whatever you want.  But be careful to use it wisely and be consistent.