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:

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:

import-module poshrsjob, PSFramework;
$DownloadDir = "e:\tmp\poshrsjob";
$MaxJobs = 3;
$LogFile = Join-Path -path $DownloadDir -ChildPath "Demo-$(Get-date -f 'yyyyMMddHHmmss').txt";
#Set-PSFLoggingProvider -name logfile -Enabled $true -filepath $LogFile;
Set-PSFLoggingProvider -name filesystem -Enabled $true -logpath $DownloadDir;
foreach ($i in 1..6) {
Start-RSJob -Throttle $MaxJobs -Batch "Demo" -argumentlist $i, $DownloadDir -ModulesToImport PSFramework -ScriptBlock {
param($JobNum, $OutputDir)
[Net.ServicePointManager]::SecurityProtocol = [Net.SecurityProtocolType]::Tls12;
$OutputFile = Join-Path -Path $OutputDir -ChildPath "RSJob$JobNum.zip";
Write-PSFMessage -Message "Preparing to download with job $JobNum";
Start-Sleep -Seconds (get-random -Minimum 1 -Maximum 5);
Invoke-WebRequest -uri "https://github.com/proxb/PoshRSJob/archive/master.zip" -OutFile $OutputFile;
Write-PSFMessage -Message "Download $JobNum complete";
}
}
view raw Demo-PSFLogging.ps1 hosted with ❤ by GitHub

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.

"ComputerName","File","FunctionName","Level","Line","Message","ModuleName","Runspace","Tags","TargetObject","Timestamp","Type","Username"
"MyComputer",,"<ScriptBlock>","Verbose","5","Preparing to download with job 1","<Unknown>","54eeec57-30e4-419b-834c-58507418d950","",,"2018-12-21 10:15:56","Verbose, Debug","MyAccount"
"MyComputer",,"<ScriptBlock>","Verbose","5","Preparing to download with job 2","<Unknown>","cdd0f64c-a486-403d-be93-5d45811f416a","",,"2018-12-21 10:15:56","Verbose, Debug","MyAccount"
"MyComputer",,"<ScriptBlock>","Verbose","5","Preparing to download with job 3","<Unknown>","a0d592b6-3372-49e6-864f-c48e1e4d9804","",,"2018-12-21 10:15:56","Verbose, Debug","MyAccount"
"MyComputer",,"<ScriptBlock>","Verbose","8","Download 1 complete","<Unknown>","54eeec57-30e4-419b-834c-58507418d950","",,"2018-12-21 10:15:57","Verbose, Debug","MyAccount"
"MyComputer",,"<ScriptBlock>","Verbose","5","Preparing to download with job 4","<Unknown>","54eeec57-30e4-419b-834c-58507418d950","",,"2018-12-21 10:15:57","Verbose, Debug","MyAccount"
"MyComputer",,"<ScriptBlock>","Verbose","8","Download 3 complete","<Unknown>","a0d592b6-3372-49e6-864f-c48e1e4d9804","",,"2018-12-21 10:15:58","Verbose, Debug","MyAccount"
"MyComputer",,"<ScriptBlock>","Verbose","5","Preparing to download with job 5","<Unknown>","a0d592b6-3372-49e6-864f-c48e1e4d9804","",,"2018-12-21 10:15:58","Verbose, Debug","MyAccount"
"MyComputer",,"<ScriptBlock>","Verbose","8","Download 4 complete","<Unknown>","54eeec57-30e4-419b-834c-58507418d950","",,"2018-12-21 10:15:59","Verbose, Debug","MyAccount"
"MyComputer",,"<ScriptBlock>","Verbose","5","Preparing to download with job 6","<Unknown>","54eeec57-30e4-419b-834c-58507418d950","",,"2018-12-21 10:15:59","Verbose, Debug","MyAccount"
"MyComputer",,"<ScriptBlock>","Verbose","8","Download 2 complete","<Unknown>","cdd0f64c-a486-403d-be93-5d45811f416a","",,"2018-12-21 10:16:00","Verbose, Debug","MyAccount"
"MyComputer",,"<ScriptBlock>","Verbose","8","Download 5 complete","<Unknown>","a0d592b6-3372-49e6-864f-c48e1e4d9804","",,"2018-12-21 10:16:00","Verbose, Debug","MyAccount"
"MyComputer",,"<ScriptBlock>","Verbose","8","Download 6 complete","<Unknown>","54eeec57-30e4-419b-834c-58507418d950","",,"2018-12-21 10:16:02","Verbose, Debug","MyAccount"
view raw PSFLogging.log hosted with ❤ by GitHub

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.

Leave a Reply

Your email address will not be published. Required fields are marked *

This site uses Akismet to reduce spam. Learn how your comment data is processed.

%d bloggers like this: