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:
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"; | |
} | |
} |
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" |
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.