Practical PowerShell: Output and Logging

Effective Logging for PowerShell Issues

In this installment of the Practical PowerShell series, I want to touch on an essential subject: output and logging. In previous articles, I discussed topics such as managing code flow and error handling. In addition to taking measures to anticipate the success (or failure) of actions, you should also consider if and how you want to make the results known to the person running the code, and if and how you want to keep them informed about how things are progressing.

In addition, when you have a script that manipulates data or performs configuration changes, you might want to record those actions. After all, output to the console is volatile and might not even be seen when running scripts as part of a headless Azure Function or Runbook. And even if you don’t want to see the output, perhaps a customer might be interested in this kind of report.

Here I discuss some of the most common options for output and adding custom logging to your scripts. I briefly mention Start-Transcript and Stop-Transcript, two cmdlets to log session interaction to a file. I occasionally use these cmdlets to keep a record of everything I do in customer environments. While simple, it is an unstructured output that is hard to process further.

The Right Kind of Output

Since the early days of PowerShell, the community encouraged the usage of the Write-Output cmdlet over cmdlets such as Write-Host. Why? The idea is that if the output is PowerShell objects, generated through Write-Output, this output can be further processed using other cmdlets. For example, you can use Where-Object or Export-Csv to process and store output. Using Write-Host just writes output to the “console” of the host, thereby limiting options to further process this data. This difference is what made object-based PowerShell stand out from the text-based shell environments such as those commonly found on Linux systems. Tony discussed object-based PowerShell in an earlier article on Practical 365.

With that out of the way, I think it is often acceptable to use Write-Host instead of Write-Output, especially when working with scripts running complex tasks or if the script requires some form of interaction. It can also be the case that your script generates different sorts of output, which makes sending them as single output make little sense, for example when you return selected properties of mailboxes as well as delegation permissions as well. Writing additional information to the console using Write-Host to give a sense of progress is better than administrators having to stare at no output whatsoever. In fact, the lack of output might make most administrators wonder if the script is functioning at all.

As discussed in the Error Handling article, output types are organized by streams in PowerShell. Think of this as channels in Microsoft Teams. Every stream can be redirected or have its display suppressed. The available output stream cmdlets are:

• Write-Host sends output to the console itself, which is not considered a stream.
• Write-Output is referred to as the success stream, used to send output when things are good, which is the default.
• Write-Warning, Write-Verbose, and Write-Debug send output to the respective stream. The display of these output streams depends on the setting of their respective preference variable, e.g., set $WarningPreference to SilentlyContinue suppress display of messages sent to the warning stream. You can also control this behavior for your own scripts, as mentioned in the earlier article on Functions and Parameters. The debug and verbose streams are not shown by default (Continue).
• Write-Error for sending messages related to non-terminating errors to the error stream. Handling of errors and display is configured using $ErrorActionPreference.
• Write-Information was introduced with PowerShell 5. It is a wrapper for the cmdlet Write-Host that sends output to the information stream.

In addition to these, there is also the nifty cmdlet Write-Progress, which does not deal with output streams, but is used to display a progress bar instead. Its usage is a bit more complex, but it is worth looking at, especially for those long-running operations for console-based tasks. A little word of advice on Write-Progress is that it does not make sense when running headless scripts. Screen output is also relatively intensive, especially when you call it more often than required; the bar shows a percentage, so there is no use in updating it for every iteration when working with larger sets. Updating it every Nth iteration suffices, e.g.

$Mailboxes= Get-Mailbox -ResultSize Unlimited
$UpdateEvery= [int]($Mailboxes.Count / 100)
ForEach( $Mailbox in $Mailboxes) {
    $i++
    # Only show/update the progress bar for every ~1% change
    If($i -ge $UpdateEvery) {
        Write-Progress -Activity 'Processing Users ..'
            -Status ('User: {0}' -f $User.Name)
            -PercentComplete ($Index / $Mailboxes.Count) * 100
        $i= 0
    }

    # Do something
}

Green is Good, Red is Bad

Due to the nature of PowerShell, administrators are used to color-coded output, where green output is good and red is bad news. In PowerShell, every output stream has its color for screen display. By the way, you can change the default colors by modifying the color properties of $host.PrivateData and setting it to one of the colors returned by [enum]::GetNames([System.ConsoleColor]), which enumerates the available console colors. For example, to set the error stream color to gray, use $host.PrivateData.ErrorForegroundColor = ‘Gray’. Now things might be easier on the eyes, but errors will not stand out anymore.

The same color names can be used to override the output color when using Write-Host, e.g. Write-Host ‘All is good’ -ForegroundColor Green. Note that only Write-Host supports colorization; the cmdlets for stream output use their configured colors, e.g. red for Write-Error and yellow for Write-Warning.

Logging What Goes On

We discussed logging output to screen, but what about generating logs and sending them elsewhere for reporting or analysis? Some products are built around this functionality, such as Microsoft’s own Log Analytics, the Windows Eventlog, or the notorious Apache Log4j Service. Using those services requires talking to their respective interfaces, e.g.

Write-EventLog -LogName Application -Source MyScript -EventId 1001 -EntryType Information -Message 'All is well'

But you can also perform fit-for-use logging by sending output to text files. If needed, you can distribute the log files to relevant people via e-mail afterward. It is all up to you and your requirements.

Now, to a more practical example of logging using a function I use in customer scenarios. Using a helper function removes the need to have two statements: one to log something to the console and one to store information in a log file. I looked at leveraging the Tee-Object cmdlet, which outputs objects to the information stream and a file. In my case, I wanted to perform color coding and include timestamps to the log file, so I created the following function:

Function Write-Log {
    param(
        [string]$Message='',
        [ValidateSet('Info','Warning', 'Error', 'Success', 'Verbose', 'Debug')]
        [string]$Severity= 'Info',
        [switch]$LogToFile,
        [string]$LogFileName
    )
    If(!( $LogFileName)) {
        # LogFile parameter not specified (null), so determine one
        $LogFolder= $PSScriptRoot
        $LogName= Split-Path -Path $MyInvocation.ScriptName -LeafBase
        $LogFileName= Join-Path -Path $LogFolder -ChildPath ('{0}-{1}.log' -f [string](Get-Date -format "yyyyMMdd"), $LogName)
    }
    Switch( $Severity) {
        'Warning' {
            $FormattedMessage= '[WARNING] {0}' -f $Message
            Write-Host $FormattedMessage -ForegroundColor $host.PrivateData.WarningForegroundColor -BackgroundColor $host.PrivateData.WarningBackgroundColor
        }
        'Error' {
            $FormattedMessage= '[ERROR] {0}' -f $Message
            Write-Host $FormattedMessage -ForegroundColor $host.PrivateData.ErrorForegroundColor -BackgroundColor $host.PrivateData.ErrorBackgroundColor        
        }
        'Verbose' {
            $FormattedMessage= '[VERBOSE] {0}' -f $Message
            Write-Host $FormattedMessage -ForegroundColor $host.PrivateData.VerboseForegroundColor -BackgroundColor $host.PrivateData.VerboseBackgroundColor
        }
        'Debug' {
            # Only log debug messages if debug stream shown
            If( $DebugPreference -ine 'SilentlyContinue') {
                $FormattedMessage= '[DEBUG] {0}' -f $Message
                Write-Host $FormattedMessage -ForegroundColor $host.PrivateData.DebugForegroundColor -BackgroundColor $host.PrivateData.DebugBackgroundColor
            }
            # Never log debug messages to file
            $LogToFile= $false
        }
        Default {
            $FormattedMessage= '{0}' -f $Message
            Write-Host $FormattedMessage
        }
    }
    If( $LogToFile) {
        [pscustomobject]@{
             Time = [string](Get-Date -format 'yyyyMMddHHmmss')
             Severity = $Severity
             Message = $Message
        } | Export-Csv -Path $LogFileName -Append -NoTypeInformation   
    }
}

This function accomplishes the following goals:

• Only one command is needed to write to the console and file.
• When not provided, the log file is based on the script name and date in ISO 8601 format.
• You can provide severity categories.
• Messages logged to the file contain a timestamp in ISO 8601 format, useful for text-based sorting and filtering.
• Severity is used for color coding messages to console output.
• By using a timestamp in the log filename, we generate a separate log per day, simplifying log rotation and cleaning up older logs.

When embedding the function in an existing script and calling it with for example, the following command in your script:

Write-Log -Severity Info -Message 'Well, hello there'

In addition to the console output, a log file is created with a timestamped entry, e.g.:

"Time","Severity","Message"
"20240820154704","Info"," Well, hello there"

Why does the example export to a CSV file and not a plain text file? In my case, it allows me to add extra fields to the log files, such as the identity of the user object being processed. Also, fields are easier to sort and filter than in log messages, allowing for further filtering or selection. Also, in this case, the people who wanted to use the logs preferred to import the data into Excel for filtering and sorting, so CSV files are a better choice. But if you do not have this requirement, alter the Export-CSV to use Add-Content for text files.

Tip: If you generate output with failures, consider using a structure that can be used as input for the script. For example, when an operation on a user object fails, add the Identity property and the reason for failure. This CSV output can be made into an input file again after remediating the cause of failure. This might save you some time, as you do not have to hand-pick these entries from the original source.

Another benefit of using a function is that if someday you decide to log to another destination, such as SQL Server or Eventlog, you do not need to modify your script but simply add the necessary code to the helper function together perhaps with a little housekeeping for setting up the necessary connections.

To conclude this article, be aware not to log any sensitive information to log files. Log files might be shared with third parties or sent to notification groups via mail. Be sure to sanitize the message where needed.