Thread-safe PowerShell Logging with PSFramework

In my previous post, I mentioned that I wasn’t checking the status of my RSJobs because I had logging built into my function. I originally tried to log out to plain text files with Out-File, but quickly hit a wall. In a multi-threaded script, attempting to write to the same text file from multiple threads results in collisions and waits at best, and outright failure at worse. Perplexed, I turned to the PowerShellHelp channel in the SQL Community Slack and asked for suggestions for thread-safe logging to text files.

Here Comes PSFramework

Fred Weinmann (blog|twitter) popped up quickly and suggested his PSFramework PowerShell module. It’s being used in dbatools as well and has a variety of very useful functions, but of primary interest to me for this project are the logging functions. Fred provides a thread-safe logging function which is easy to both set up and use. How easy?

• Setup is one function, called a single time (outside your multi-threaded process)
• Writing to the log is one function (called from anywhere)

That’s…pretty easy. And even better, it’s non-blocking. That is, once you throw a message “over the wall” to the logging function, you don’t have to wait for it to complete before your script moves on. That wait could be a few milliseconds, or a few minutes, depending on what else is going on. But that’s OK because PSFramework is just putting the message into a queue to be written later, while you move on to doing other things.

Setup and Usage

PSFramework is available from the PSGallery, so installation is just Install-Module PSFramework. To set up PSFramework’s logging, use Set-PSFLoggingProvider. At the time of this writing PSFramework supports three providers:

• gelf (Greylog Extended Log Format, which also requires a server to log to)
• filesystem
• logfile

In my case, I wanted to use logfile – just writing my log messages out to a plain text file. Just provide the function with the full path to the logfile and tell it to enable the provider. filesystem will also produce a file (name determined by the module itself) with slightly less data and no header row.

$LogFile = Join-Path -path "e:\tmp\poshrsjob" -ChildPath "Demo-$(Get-date -f 'yyyyMMddHHmmss').txt";
Set-PSFLoggingProvider -Name logfile -FilePath $LogFile -Enabled $true;

Now we’re ready to start writing to the log.

Writing messages out to your log is really easy – just call Write-PSFMessage. It supports various “levels” for your messages and other parameters.

Write-PSFMessage -Message "$(Get-Date -format 'o')|I'm writing a blog post!";

Inside my try/catch blocks, I used it to log exceptions a bit differently.

Write-PSFMessage -Message "$(Get-Date -format 'o')|Exception when doing something important. $($Error[0])" -Level Important;

A full sample script:

You may notice an extra line in the Scriptblock for the downloads as compared to my previous post. That’s because I ran this demo on PowerShell 5.1, where TLS 1.2 isn’t the default like it apparently is on PowerShell Core.

Output

What’s the log look like? About what you’d expect.

In this case, several of the fields are empty or anonymous because I was logging from outside a module or even a file (it’s all Scriptblocks). This log also demonstrates that my download jobs completed out of order due to the random delays I included.

Conclusion

I’ve only demonstrated a basic use case here, but hopefully you can see where this is going. There are a number of other great options for managing your logging with this module and I’m sure it’ll expand even more in the future. Check out Get-Help about_psf_message for all the details about how it works and what you can do with it – there’s extensive documentation here. This functionality is only the top of the iceberg that is PSFramework, too.

Whether you’re multi-threading or not, this is a great way to add lightweight, non-blocking logging to your PowerShell scripts.