If you are working with PowerShell frequently, you will often run into the question of logging. How do I want to write logs, where to write them and which format should they have. We wont go into these questions here, however, we will take a look at how to implement PowerShell logging in a non-blocking (async) way.

Table of Contents

  1. Introduction
  2. Logging logic
  3. Logging runspace
  4. Logging class
    1. Example

Introduction

PowerShell is generally single threaded. If we want to write some logs into a file, we would probably use something like this:

1
2
3
...
Write-Output "$([Datetime]::UtcNow) (Error): This output is blocking my shell" | Out-File C:\temp\test.log -Append
...

Maybe we would write a log function like this:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
function global:WriteLog
{
    param(
        [Parameter(Mandatory=$true)]
        [ValidateSet('Information', 'Warning', 'Error')]
        [String[]]
        $type,
        [Parameter(Mandatory=$true)]
        [string]$message
    )
    
    $logMessage = "$([Datetime]::UtcNow) ($type): $message"
    Write-Output $logMessage
    Add-content -Path "C:\temp\test.log" -Value $logMessage
}

And there are a lot of reference implementations and variations of varying complexity out there. The problem is that it is still blocking the main PowerShell thread.
To overcome these limitation, there are a few ways in PowerShell:

  • PowerShell Jobs
  • Timer objects
  • Runspace factory

As PowerShell jobs are much too clunky and don’t have a intuitive way of exchanging data between the job scope and the current scope, we will focus on timer objects and runspaces.

There are lots of good articles out there about PowerShell runspaces:

Beginning use of PowerShell runspaces: Part 1
Beginning use of PowerShell runspaces: Part 2
Beginning use of PowerShell runspaces: Part 3
RunspaceFactory Class

So we will create a separate runspace - aka. a thread - to handle all the logging logic for us.

Logging logic

So first we write a scriptblock that will provide the logging functionality we need. As I said before, we will also use timers on this. What the following script does, is checking for a new message in the logging queue and handling it.

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
loggingScript =
{
    function Start-Logging
    {
        $loggingTimer = new-object Timers.Timer
        $action = {logging}
        $loggingTimer.Interval = 1000
        $null = Register-ObjectEvent -InputObject $loggingTimer -EventName elapsed -Sourceidentifier loggingTimer -Action $action
        $loggingTimer.start()
    }

    function logging
    {
        $sw = $logFile.AppendText()
        while (-not $logEntries.IsEmpty)
        {
            $entry = ''
            $null = $logEntries.TryDequeue([ref]$entry)
            $sw.WriteLine($entry)
        }
        $sw.Flush()
        $sw.Close()
    }

    $logFile = New-Item -ItemType File -Name "$($env:COMPUTERNAME)_$([DateTime]::UtcNow.ToString(`"yyyyMMddTHHmmssZ`")).log" -Path $logLocation

    Start-Logging
}

First we create a timer object to check the log queue for new log messages frequently. What logging queue you ask? This one:

1
$logEntries = [System.Collections.Concurrent.ConcurrentQueue[string]]::new()

We use a concurrent queue, because all objects inside of the System.Collections.Concurrent namespace already handles threat locks by themselves. That means that we don’t have to care about both threads (main and logging thread) accessing the object at the same time and causing race conditions. Thats also the reason why we don’t use Synchronized objects, because they are not completely thread safe and could lead to performance degradation.

If you want to learn more about thread safety in .NET, I recommend this article: Thread-Safe Collections

The time calls the function logging every 1 second. By calling AppendText() on the earlier created $logFile object, we get a Stream Writer back and save it into the $sw variable.
Then we try to dequeue all messages from our queue until it’s empty, appending every single entry to our log file.

This is very basic and should only show the concept, feel free to add all the logic you need.

Logging runspace

To be able to launch the above code in a separate runspace, we first need a runspace. We create it by using the RunspaceFactory class.

1
2
3
4
5
6
7
8
$loggingRunspace = [runspacefactory]::CreateRunspace()
$loggingRunspace.ThreadOptions = "ReuseThread"
$loggingRunspace.Open()
$loggingRunspace.SessionStateProxy.SetVariable("logEntries", $logEntries)
$loggingRunspace.SessionStateProxy.SetVariable("logLocation", $logLocation)
$cmd = [PowerShell]::Create().AddScript($loggingScript)
$cmd.Runspace = $loggingRunspace
$null = $cmd.BeginInvoke()

We set the ThreadOptions on the runspace object to ReuseThread.
According to the PSThreadOptions Enum, ReuseThread defines that the runspace *”Creates a new thread for the first invocation and then re-uses that thread in subsequent invocations.”*.
Then we open the runspace synchronously by calling Open() to be able to interact with it.
Now we can use a neat property called SessionStateProxy to add objects that we want to use for communication.
It basically declares and initializes variables in the remote runspace, in our case we want the logEntries and the logLocation variables to be accessible from the runspace scope.

The $logLocation variable is not thread safe. As long as you set it initially and only read it in the logging runspace there should be no problem. If you want to do more with it, considering using a thread safe type or at least implement some locks with e.g. [System.Threading.Monitor]::Enter/Exit

Logging class

As I love PowerShell classes for their extensibility and reusability, I obviously also created a class to reuse the logging construct.

PsLogger.ps1link
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
enum SyslogSeverity
{
    Emergency = 0
    Alert = 1
    Critical = 2
    Error = 3
    Warning = 4
    Notice = 5
    Informational = 6
    Debug = 7
}

enum SyslogFacility
{
kern = 0
user = 1
mail = 2
daemon = 3
auth = 4
syslog = 5
lpr = 6
news = 7
uucp = 8
cron = 9
authpriv = 10
ftp = 11
ntp = 12
audit = 13
alert = 14
clockdaemon = 15
local0 = 16
local1 = 17
local2 = 18
local3 = 19
local4 = 20
local5 = 21
local6 = 22
local7 = 23
}

Class PsLogger
{
    hidden $loggingScript =
    {
        function Start-Logging
        {
            $loggingTimer = new-object Timers.Timer
            $action = {logging}
            $loggingTimer.Interval = 1000
            $null = Register-ObjectEvent -InputObject $loggingTimer -EventName elapsed -Sourceidentifier loggingTimer -Action $action
            $loggingTimer.start()
        }
    
        function logging
        {
            $sw = $logFile.AppendText()
            while (-not $logEntries.IsEmpty)
            {
                $entry = ''
                $null = $logEntries.TryDequeue([ref]$entry)
                $sw.WriteLine($entry)
            }
            $sw.Flush()
            $sw.Close()
        }
    
        $logFile = New-Item -ItemType File -Name "$($env:COMPUTERNAME)_$([DateTime]::UtcNow.ToString(`"yyyyMMddTHHmmssZ`")).log" -Path $logLocation
    
        Start-Logging
    }
    hidden $_loggingRunspace = [runspacefactory]::CreateRunspace()
    hidden $_logEntries = [System.Collections.Concurrent.ConcurrentQueue[string]]::new()
    hidden $_processId = $pid
    hidden $_processName
    hidden $_logLocation = $env:temp
    hidden $_fqdn
    hidden [SyslogFacility]$_facility = [SyslogFacility]::local7
    
    PsLogger([string]$logLocation)
	{
        $this._logLocation = $logLocation
        $this._processName = (Get-process -Id $this._processId).processname
        $comp = Get-CimInstance -ClassName win32_computersystem
        $this._fqdn = "$($comp.DNSHostName).$($comp.Domain)"

        # Add Script Properties for all severity levels
        foreach ($enum in [SyslogSeverity].GetEnumNames()) 
        {
            $this._AddSeverities($enum)
        }

        # Start Logging runspace
        $this._StartLogging()
    }
    
    hidden _LogMessage([string]$message, [string]$severity)
    {
        $addResult = $false
        while ($addResult -eq $false)
        {
            $msg = '<{0}>1 {1} {2} {3} {4} - - {5}' -f ($this._facility*8+[SyslogSeverity]::$severity), [DateTime]::UtcNow.tostring('yyyy-MM-ddTHH:mm:ss.fffK'), $this._fqdn, $this._processName, $this._processId, $message
            $addResult = $this._logEntries.TryAdd($msg)
        }
    }

    hidden _StartLogging()
    {
        $this._LoggingRunspace.ThreadOptions = "ReuseThread"
        $this._LoggingRunspace.Open()
        $this._LoggingRunspace.SessionStateProxy.SetVariable("logEntries", $this._logEntries)
        $this._LoggingRunspace.SessionStateProxy.SetVariable("logLocation", $this._logLocation)
        $cmd = [PowerShell]::Create().AddScript($this.loggingScript)
      
        $cmd.Runspace = $this._LoggingRunspace
        $null = $cmd.BeginInvoke()
    }

    hidden _AddSeverities([string]$propName)
    {
        $property = new-object management.automation.PsScriptMethod $propName, {param($value) $propname = $propname; $this._LogMessage($value, $propname)}.GetNewClosure()
        $this.psobject.methods.add($property)
    }
}

The only things I added here were the two enums for syslog severity and facilities and a little bit of logic to achieve a syslog like log output. If you would like to combine this method with a full featured syslog implementation, I recommend you take a look at the Posh-SYSLOG module by Kieran Jacobsen.

For better accessability and a log framework like usability, I also added a method called _AddSeverities. It is called with every enum name returned by the GetEnumNames() method to add as PSScriptMethod for each.
That enables us to use syntax like this to log something:

1
$psLogger.Alert("Test Alert")

Example

Here, we create an instance of the PsLogger class and write some logs to the “C:\temp” folder. 

1
2
3
4
5
. 'c:\temp\PSLogger.ps1'
$logger = [PSLogger]::new("C:\temp")
$logger.Alert("Async logging is awesome")
$logger.Informational("It really is")
$logger.Error("Critical error")

Now lets take a look at the output file.

1
2
3
<185>1 2019-07-04T18:38:27.687Z DESKTOP-XXXXXXX.WORKGROUP pwsh 10168 - - Async logging is awesome
<190>1 2019-07-04T18:38:27.711Z DESKTOP-XXXXXXX.WORKGROUP pwsh 10168 - - It really is
<187>1 2019-07-04T18:38:28.346Z DESKTOP-XXXXXXX.WORKGROUP pwsh 10168 - - Critical error

And thats it! You can now extend and rewrite the logging class for your needs and don’t forget to check in frequently for my next post about logging into Azure append blobs 😃