Standardize PowerShell logging with my Write-LogEntry function

• Author
• Recent Posts

Josh Rickard

Josh's primary focus is in Windows security and PowerShell automation. He is a GIAC Certified Windows Security Administrator (GCWN) and GIAC Certified Forensic Analyst (GCFA). You can reach Josh at MSAdministrator.com or on Twitter at @MS_dministrator.

Latest posts by Josh Rickard (see all)

• Search Event Logs and error codes with Netikus.net System32 - Thu, Jan 10 2019
• Netikus.net IPMon+ – GUI for ipmon.exe - Tue, Nov 20 2018
• Understanding PowerShell Begin, Process, and End blocks - Mon, Oct 15 2018

Using Write-LogEntry

The function offers a few parameters that allow you to log different outputs types, such as informational, debug, and error information. Each one of these parameter options belongs to a parameter set.

Write-LogEntry -Info 'This is an informational log event'
Write-LogEntry -Debugging 'This is a debugging log event'
Write-LogEntry -Error 'This is an error log event'

In addition to being able to write errors out, we can also pass any $error[0] variables that may hit a catch block in your script. The Error and ErrorRecord parameters belong to the same parameter set. This means that you can only use the ErrorRecord parameter in combination with the Error parameter.

Write-LogEntry -Error 'This is an error log event' -ErrorRecord $Error[0]

Here are some examples of the output that Write-LogEntry provides:

A log file created with Write LogEntry

Explaining the Write-LogEntry function

Have a look at the function below first. I will explain the crucial parts in detail below.

function Write-LogEntry
{
    [CmdletBinding(DefaultParameterSetName = 'Info', 
                  SupportsShouldProcess=$true, 
                  PositionalBinding=$false,
                  HelpUri = 'https://github.com/MSAdministrator/WriteLogEntry',
                  ConfirmImpact='Medium')]
    [OutputType()]
    Param
    (
        # Information type of log entry
        [Parameter(Mandatory=$true, 
                   ValueFromPipelineByPropertyName=$true,
                   Position=0,
                   ParameterSetName = 'Info')]
        [ValidateNotNull()]
        [ValidateNotNullOrEmpty()]
        [Alias("information")]
        [System.String]$Info,

        # Debug type of log entry
        [Parameter(Mandatory=$true, 
                   ValueFromPipelineByPropertyName=$true, 
                   Position=0,
                   ParameterSetName = 'Debug')]
        [ValidateNotNull()]
        [ValidateNotNullOrEmpty()]
        [System.String]$Debugging,

        # Error type of log entry
        [Parameter(Mandatory=$true, 
                   ValueFromPipeline=$true,
                   Position=0,
                   ParameterSetName = 'Error')]
        [ValidateNotNull()]
        [ValidateNotNullOrEmpty()]
        [System.String]$Error,


        # The error record containing an exception to log
        [Parameter(Mandatory=$false, 
                   ValueFromPipeline=$true,
                   ValueFromPipelineByPropertyName=$true, 
                   ValueFromRemainingArguments=$false, 
                   Position=1,
                   ParameterSetName = 'Error')]
        [ValidateNotNull()]
        [ValidateNotNullOrEmpty()]
        [Alias("record")]
        [System.Management.Automation.ErrorRecord]$ErrorRecord,

        # Logfile location
        [Parameter(Mandatory=$false, 
                   ValueFromPipelineByPropertyName=$true, 
                   Position=2)]
        [Alias("file", "location")]
        [System.String]$LogFile = "$($ExecutionContext.SessionState.Path.GetUnresolvedProviderPathFromPSPath(‘.\’))" + "\log.log"
    )

    if (!(Test-Path -Path $LogFile))
    {
         try
         {
            New-Item -Path $LogFile -ItemType File -Force | Out-Null
         }
         catch
         {
            Write-Error -Message 'Error creating log file'
            break
         }
    }

    $mutex = New-Object -TypeName 'Threading.Mutex' -ArgumentList $false, 'MyInterprocMutex'
   
    
    switch ($PSBoundParameters.Keys)
    {
         'Error' 
         {
            $mutex.waitone() | Out-Null

            Add-Content -Path $LogFile -Value "$((Get-Date).ToString('yyyyMMddThhmmss')) [ERROR]: $Error"

            if ($PSBoundParameters.ContainsKey('ErrorRecord'))
            {
                $Message = '{0} ({1}: {2}:{3} char:{4})' -f $ErrorRecord.Exception.Message,
                                                            $ErrorRecord.FullyQualifiedErrorId,
                                                            $ErrorRecord.InvocationInfo.ScriptName,
                                                            $ErrorRecord.InvocationInfo.ScriptLineNumber,
                                                            $ErrorRecord.InvocationInfo.OffsetInLine

                Add-Content -Path $LogFile -Value "$((Get-Date).ToString('yyyyMMddThhmmss')) [ERROR]: $Message"
            }

            $mutex.ReleaseMutex() | Out-Null
         }
         'Info' 
         {
            $mutex.waitone() | Out-Null

            Add-Content -Path $LogFile -Value "$((Get-Date).ToString('yyyyMMddThhmmss')) [INFO]: $Info"
                
            $mutex.ReleaseMutex() | Out-Null
         }
         'Debugging' 
         {
            Write-Debug -Message "$Debugging"

            $mutex.waitone() | Out-Null
                
            Add-Content -Path $LogFile -Value "$((Get-Date).ToString('yyyyMMddThhmmss')) [DEBUG]: $Debugging"
                
            $mutex.ReleaseMutex() | Out-Null
         }
    }#End of switch statement
} # end of Write-LogEntry function

In addition to the three parameters discussed above, we have an additional parameter you can use to specify where to create the log file (if not already created). The default value for this parameter uses the automatic variable $ExecutionContext. By traversing the available properties on $ExecutionContext, we can find the calling scopes path and create a log.log file in the folder where your script is located.

"$($ExecutionContext.SessionState.Path.GetUnresolvedProviderPathFromPSPath(‘.\’))" + "\log.log"

Based on the parameter set you have chosen, we have a series of output formatting defined. The decision on which format to use depends on your selection. Write-LogEntry verifies your selection and applies that formatting based on a switch statement. This switch statement uses the Keys property of the $PSBoundParameters automatic variable to identify the parameter(s) used. The $PSBoundParameters variable stores a hashtable that contains the parameters passed to the function.

switch ($PSBoundParameters.Keys)
	{
	            'Error'
	            {}
	            'Info'
	            {}
	            ‘Debugging’
	            {}
	}

Depending on which parameter you used when calling the function, a separate Add-Content call formats a prefix with the current time format (yyyyMMddThhmmss), which equates to 20170416T184532. We also add the log type called and the string passed to that parameter.

At the top of the function, we create a new System.Threading.Mutex object. The Mutex object ensures we will not receive a warning or error if we attempt to write to the log file while another thread is using the file. A Mutex object (System.Threading.Mutex) essentially ensures that only one thread at a time uses the resource, the log file in our case.

$mutex = New-Object -TypeName 'Threading.Mutex' -ArgumentList $false, 'MyInterprocMutex'

##### SNIPPET #####
$mutex.waitone() | Out-Null

Add-Content -Path $LogFile -Value "$((Get-Date).ToString('yyyyMMddThhmmss')) [INFO]: $Info"

$mutex.ReleaseMutex() | Out-Null

Before we open the log file to write the desired content, we block the current thread until the process signals that it's ready to write the content. After we have written to our log file using the Add-Content cmdlet, we close that Mutex thread by calling the ReleaseMutex() method.

You may have noticed the Error switch statement has a few more lines of code than the other statements (Debugging and Info). The "error" ParameterSet has two parameters available: Error and ErrorRecord.

# Error type of log entry
[Parameter(Mandatory=$true,
                   ValueFromPipeline=$true,
                   Position=0,
                   ParameterSetName = 'Error')]
        [ValidateNotNull()]
        [ValidateNotNullOrEmpty()]
        [System.String]$Error,


        # The error record containing an exception to log
        [Parameter(Mandatory=$false,
                   ValueFromPipeline=$true,
                   ValueFromPipelineByPropertyName=$true,
                   Position=1,
                   ParameterSetName = 'Error')]
        [ValidateNotNull()]
        [ValidateNotNullOrEmpty()]
        [Alias("record")]
        [System.Management.Automation.ErrorRecord]$ErrorRecord,

If you choose to use the "error" ParameterSet then the Error parameter is mandatory. You can use this function by just passing a string to the Error parameter, but we also can pass an $error variable to an optional parameter called ErrorRecord.

If you have passed an $error variable to the ErrorRecord parameter, you can identify it with the following if statement. This statement uses the $PSBoundParameters ContainsKeys() method to determine whether the ErrorRecord variable has been passed into the function. If the ErrorRecord parameter was used, then this statement parses the $error variable to a more readable format. By using string formatting, we can modify the output so that it's easy to read.

if ($PSBoundParameters.ContainsKey('ErrorRecord'))
       {
        $Message = '{0} ({1}: {2}:{3} char:{4})' -f $ErrorRecord.Exception.Message,
                                                    $ErrorRecord.FullyQualifiedErrorId,
                                                    $ErrorRecord.InvocationInfo.ScriptName,
                                                    $ErrorRecord.InvocationInfo.ScriptLineNumber,
                                                    $ErrorRecord.InvocationInfo.OffsetInLine

Instead of having a traditional error output like the following:

PS: C:\ try { do-something }catch{ $Error[0] }

do-something : The term 'do-something' is not recognized as the name of a cmdlet, function, script file, or operable program. Check the spelling of the name, or if a path was included, verify that the path is correct and try again.
At line:1 char:8
+  try { do-something }catch{ $Error[0] }
+        ~~~~~~~~~~~~
    + CategoryInfo          : ObjectNotFound: (do-something:String) [], CommandNotFoundException
    + FullyQualifiedErrorId : CommandNotFoundException

We have the ability to parse out the necessary properties on the $error[0] record to a more readable format:

20170415T125920 [ERROR]: The term 'do-Something' is not recognized as the name of a cmdlet, function, script file, or operable program. Check the spelling of the name, or if a path was included, verify that the path is correct and try again. (CommandNotFoundException: :1 char:8)

Conclusion

Like writing help text or documenting scripts, logging is not a glorious task. The Write-LogEntry function simplifies this task for you and standardizes logging in your scripts. This helps with troubleshooting and helps users of your scripts to understand the output. You can find the latest version of my Write-LogEntry tool on GitHub.