The PowerShell function Write-LogEntry described in this post allows you to integrate logging in your scripts in a standardized way. This will help you and your script users to troubleshoot and understand the output.

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

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:

Subscribe to 4sysops newsletter!

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.

6 Comments
  1. Fox 5 years ago

    Excellent function! Great timing too, as I was just starting to add some logging functionality to my script.

  2. Brandon 5 years ago

    Fantastic logging function. I just finished writing my first one to start properly tracking errors in my scripts. Yours is much more polished and useful and I’m definitely not going to re-invent the wheel! Thanks!

  3. LostAtC 5 years ago

    I believe for the date-time stamp you really want the 24 hour format (“HH”):
    (Get-Date).ToString(‘yyyyMMddTHHmmss’)

    Personally I prefer the built in formatting which is a bit easier to read:
    Get-Date -Format ‘s’

  4. Cédric 5 years ago

    Hello,

    It seems you are creating a new mutex everytime you call the function, instead of using the same one. As a result, I don’t think you’re handling concurrent accesses at all since you are locking a different mutex each time you call the function.

    • Cédric 5 years ago

      I’ll reply to my own question ! Apparently, when you call New-Object with the same mutex name, you’re not creating a new mutex, but a new handle to the same mutex.

  5. Peter Kriegel 3 years ago

    I Think If you convert this Function into a Pipline able Function you do not need the Mutex.

    There for you can use the [CmdletBinding()] plus the "Begin {} Process {} End {}" blocks inside your Function.

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

    Points to the Current Path  not the Path of the executing script.
    If a command in the current Process is doing a CD the  the log is written in to the new path!!
    So your Logs can get spreaded over the filesystem.

    Is this intendet?

    For Datetime Format I suggest a UTC time Format.

    if you have servers spread across multiple timezones,
    all your event timestamps MUST be transported in UTC time (as String)
    this UTC MUST be calculated by the sender system and
    cannot be calculated by the receiver system.
    Because only the sender knows his locale timezone setting and dailight savings.

     # create UTC time string HH:mm:ss.mmm-+<UtcOffset.TotalMinutes>
    
    $Now = Get-Date
     "$($Now.ToString('HH:mm:ss.fff'))$([System.TimeZoneInfo]::Local.GetUtcOffset($Now).TotalMinutes.ToString('+0;-#'))"
    
    

    Why do you not use the DebugRecord Object

    and what about the WarningRecord (Write-Warning) and VerboseRecord (Write-Verbose) Objects?

    Here I suggest you use an InputObject Parameter and Examin What Object Type do you process.

    With a Redirection Operator of  *>&1 you can Handle ALL PowerShell Streams in one Function.

    See: about_Redirection

    # will create access denied errors! AND
    
    # Redirect all Streams to success streams
    Get-ChildItem 'C:Windows' -recurse *>&1

    Then a Handler Function can look like this:

    Function Tee-StreamRecords {
    
        [CmdletBinding()]
        param(
    
            <#
                InputObjects which are NOT type of ErrorRecord or WarningRecord or DebugRecord or VerboseRecord or InformationRecord
                are allways passed thru without any further processing
    
                If InputObject is type of ErrorRecord or WarningRecord or DebugRecord or VerboseRecord or InformationRecord
                and if you wish to PassThru the InputObject, the handler has to return the Object !
            #>
            [parameter(Position=0,
    		    Mandatory=$true,
        	    ValueFromPipeline=$true
            )]
            [Object]$InputObject,
            
             # is invoked if InputObject is type of WarningRecord
            [Scriptblock]$WarningHandler,
             # is invoked if InputObject is type of VerboseRecord 
            [Scriptblock]$VerboseHandler,
             # is invoked if InputObject is type of ErrorRecord 
            [Scriptblock]$ErrorHandler,
             # is invoked if InputObject is type of DebugRecord 
            [Scriptblock]$DebugHandler,
             # is invoked if InputObject is type of InformationRecord 
            [Scriptblock]$InformationHandler,
            # is invoked if InputObject is type of ErrorRecord or WarningRecord or DebugRecord or VerboseRecord or InformationRecord 
            [Scriptblock]$AllHandler
        )
    
        Begin{}
        Process{
    
            switch ($InputObject)
             {
                {$InputObject -is [System.Management.Automation.WarningRecord]} {
                   If($WarningHandler) { Invoke-Command $WarningHandler -ArgumentList $InputObject }
                   If($AllHandler) { Invoke-Command $AllHandler -ArgumentList $InputObject }
                }
                {$InputObject -is [System.Management.Automation.VerboseRecord]} {
                    If($VerboseHandler) { Invoke-Command $VerboseHandler -ArgumentList $InputObject }
                    If($AllHandler) { Invoke-Command $AllHandler -ArgumentList $InputObject }
                }
                {$InputObject -is [System.Management.Automation.ErrorRecord]} {
                    If($ErrorHandler) { Invoke-Command $ErrorHandler -ArgumentList $InputObject }
                    If($AllHandler) { Invoke-Command $AllHandler -ArgumentList $InputObject }
                }
                {$InputObject -is [System.Management.Automation.DebugRecord]} {
                    If($DebugHandler) { Invoke-Command $DebugHandler -ArgumentList $InputObject }
                    If($AllHandler) { Invoke-Command $AllHandler -ArgumentList $InputObject }
                }
                {$InputObject -is [System.Management.Automation.InformationRecord]} {
                    If($InformationHandler) { Invoke-Command $InformationHandler -ArgumentList $InputObject }
                    If($AllHandler) { Invoke-Command $AllHandler -ArgumentList $InputObject }
                }
                default {
                   # InputObject seems to be an Object for the succes stream so allways pass it thru
                    $PSCmdlet.WriteObject($InputObject)
                }
             }
        }
        End{}
    }

    Then you can use the redirection like so:

    # log all ErrorRecord Objects to "$env:tempmy.log"
    Get-ChildItem 'C:Windows' -recurse *>&1 | Tee-StreamRecords -ErrorHandler { $Args[0] | Out-File "$env:tempmy.log" }

    For an uptodate version see Github:
    https://github.com/Kriegel/PowerLogging

Leave a reply

Your email address will not be published.

*

© 4sysops 2006 - 2022

CONTACT US

Please ask IT administration questions in the forums. Any other messages are welcome.

Sending

Log in with your credentials

or    

Forgot your details?

Create Account