I wanted my PowerShell scripts to log output and errors to separate log files, but with a timestamp on each line. Here's how I've pulled it off!

My PowerShell Logging Strategy

In my new job I've been doing a ton of PowerShell scripting. Mostly because it's a simple, transparent way to move data around between systems.

The approach I've been taking is a script to export data out of one system, and a script to import data (from the pipeline) into another system. So if you consider System A and System B and you want to move orders from one to the other, I'd do something like this:

Export-SystemAOrders.ps1 | Import-SystemBOrders.ps1

So the scripts use Export and Import verbs, and their "nouns" are the system in question and the kind of data being moved.

I have several scheduled jobs running pipeline-based scripts like this at various times, and I wanted each of them to write to two different log files - one for standard output and the other for errors. The log files needed to have the date in their filename and a timestamp for each entry.

Capturing standard output was easy enough, but adding a timestamp to errors proved to be a bit trickier. Thankfully I've struck upon a reliable way to do it:

$errors = '..\Logs\errors-' + (Get-Date -format yyyyMMdd) + '-' + ($MyInvocation.MyCommand.Name -replace '.ps1$', '.log')
$output = '..\Logs\output-' + (Get-Date -format yyyyMMdd) + '-' + ($MyInvocation.MyCommand.Name -replace '.ps1$', '.log')

filter log($Source) {
    if ($_ -is [System.Management.Automation.ErrorRecord]) {
        "$(Get-Date -format HH:mm)`t$Source`t$_" | Out-File $errors -Append
    } 
    else {
        "$(Get-Date -format HH:mm)`t$Source`t$_" | Out-File $output -Append
    }
}

(Export-SystemAOrders.ps1 | Import-SystemBOrders.ps1) 2>&1 | log -Source 'System A'

So what I've got here is a "filter function" (which is a kind of function that gets called for every item on the pipeline) which differentiates between errors and normal output. If it's an error, it appends a line to an error log file. If it's standard output, it appends to the output log file.

My log files have filenames that match the job, so if the job was called "Sync-SystemBOrders.ps1" then the log files would be called:

errors-20200310-Sync-SystemBOrders.log

output-20200310-Sync-SystemBOrders.log

... and the log entries end up looking like this:

13:25 System B Creating new order 12345

Notice that I've enclosed the two scripts in parentheses and doing the redirection on the outside. That's so I can capture output and errors from either side of the pipeline. I'm not 100% sure that's correct, but it seems to be working, so rock on. 🤘

powershell logging
Posted by: Matt Hamilton
Last revised: 24 Nov, 2020 01:14 AM History

Comments

No comments yet. Be the first!

No new comments are allowed on this post.