When running a command in powershell how can I prepend a date/time for all output on stdout/stderr?

Viewed 146

Is it possible in powershell when running a script to add a date prefix to all log output?

I know that it would be possible to do something like: Write-Host "$(Get-Date -format 'u') my log output"

But I dont want to have to call some function for each time we output a line. Instead I want to modify all output when running any script or command and have the time prefix for every line.

2 Answers

The objects generated by Write-Host already come with a timestamp, you can use Update-TypeData to override the .ToString() Method from the InformationRecord Class and then redirect the output from the Information Stream to the Success Stream.

Update-TypeData -TypeName System.Management.Automation.InformationRecord -Value {
    return $this.TimeGenerated.ToString('u') + $this.MessageData.Message.PadLeft(10)
} -MemberType ScriptMethod -MemberName ToString -Force

'Hello', 'World', 123 | Write-Host 6>&1 

To insert a date in front of all output, that is stdout, stderr and the PowerShell-specific streams, you can use the redirection operator *>&1 to redirect (merge) all streams of a command or scriptblock, pipe to Out-String -Stream to format the stream objects into lines of text and then use ForEach-Object to process each line and prepend the date.

Let me start with a simple example, a more complete solution can be found below.

# Run a scriptblock
&{
    # Test output to all possible streams, using various formatting methods.
    # Added a few delays to test if the final output is still streaming.

    "Write $($PSStyle.Foreground.BrightGreen)colored`ntext$($PSStyle.Reset) to stdout"
    Start-Sleep -Millis 250
    [PSCustomObject]@{ Answer = 42; Question = 'What?' } | Format-Table
    Start-Sleep -Millis 250
    Get-Content -Path not-exists -EA Continue  # produce a non-terminating error
    Start-Sleep -Millis 250
    Write-Host 'Write to information stream'
    Start-Sleep -Millis 250
    Write-Warning 'Write to warning stream'
    Start-Sleep -Millis 250
    Write-Verbose 'Write to verbose stream' -Verbose
    Start-Sleep -Millis 250
    $DebugPreference = 'Continue'  # To avoid prompt, needed for Windows Powershell
    Write-Debug 'Write to debug stream'
        
} *>&1 | Out-String -Stream | ForEach-Object {
    # Add date in front of each output line

    $date = Get-Date -Format "yy\/MM\/dd H:mm:ss"

    foreach( $line in $_ -split '\r?\n' ) {
        "$($PSStyle.Reset)[$date] $line"
    }
}

Output in PS 7.2 console:

Console Output

  • Using Out-String we use the standard PowerShell formatting system to have the output look normally, as it would appear without redirection (e. g. things like tables stay intact). The -Stream parameter is crucial to keep the streaming output behaviour of PowerShell. Without this parameter, output would only be received once the whole scriptblock has completed.
  • While the output already looks quite nice, there are some minor issues:
    • The verbose, warning and debug messages are not colored as usual.
    • The word "text" in the 2nd line should be colored in green. This isn't working due to the use of $PSStyle.Reset. When removed, the colors of the error message leak into the date column, which looks far worse. It can be fixed, but it is not trivial.
    • The line wrapping isn't right (it wraps into the date column in the middle of the output).

As a more general, reusable solution I've created a function Invoke-WithDateLog that runs a scriptblock, captures all of its output, inserts a date in front of each line and outputs it again:

Function Invoke-WithDateLog {
    [CmdletBinding()]
    param(
        [Parameter(Mandatory)] 
        [scriptblock] $ScriptBlock,
        
        [Parameter()]          
        [string] $DateFormat = '[yy\/MM\/dd H:mm:ss] ',
        
        [Parameter()]          
        [string] $DateStyle = $PSStyle.Foreground.BrightBlack,
        
        [Parameter()]          
        [switch] $CatchExceptions,
        
        [Parameter()]          
        [switch] $ExceptionStackTrace,
        
        [Parameter()]          
        [Collections.ICollection] $ErrorCollection
    )

    # Variables are private so they are not visible from within the ScriptBlock. 
    $private:ansiEscapePattern = "`e\[[0-9;]*m"
    $private:lastFmt = ''

    & {
        if( $CatchExceptions ) { 
            try   { & $scriptBlock }
            catch {
                # The common parameter -ErrorVariable doesn't work in scripted cmdlets, so use our own error variable parameter.
                if( $null -ne $ErrorCollection ) {
                    $null = $ErrorCollection.Add( $_ )
                }

                # Write as regular output, colored like an error message.
                "`n" + $PSStyle.Formatting.Error + "EXCEPTION ($($_.Exception.GetType().FullName)):`n  $_" + $PSStyle.Reset

                # Optionally write stacktrace. Using the -replace operator we indent each line.
                Write-Debug ($_.ScriptStackTrace -replace '^|\r?\n', "`n  ") -Debug:$ExceptionStackTrace
            }
        }
        else { 
            & $scriptBlock 
        }

    } *>&1 | ForEach-Object -PipelineVariable record {

        # Here the $_ variable is either:
        # - a string in case of simple output
        # - an instance of one of the System.Management.Automation.*Record classes (output of Write-Error, Write-Debug, ...)
        # - an instance of one of the Microsoft.PowerShell.Commands.Internal.Format.* classes (output of a Format-* cmdlet) 
        
        if( $_ -is [System.Management.Automation.ErrorRecord] ) {
            # The common parameter -ErrorVariable doesn't work in scripted cmdlets, so use our own error variable parameter.
            if( $null -ne $ErrorCollection ) {
                $null = $ErrorCollection.Add( $_ )
            }
        }

        $_ # Forward current record

    } | Out-String -Stream | ForEach-Object {

        # Here the $_ variable is always a (possibly multiline) string of formatted output.

        # Out-String doesn't add any ANSI escape codes to colorize Verbose, Warning and Debug messages, 
        # so we have to do it by ourselfs.
        $overrideFmt = switch( $record ) {
            { $_ -is [System.Management.Automation.VerboseRecord] } { $PSStyle.Formatting.Verbose; break }
            { $_ -is [System.Management.Automation.WarningRecord] } { $PSStyle.Formatting.Warning; break }
            { $_ -is [System.Management.Automation.DebugRecord]   } { $PSStyle.Formatting.Debug;   break }
        }

        # Prefix for each line. It resets the ANSI escape formatting before the date.
        $prefix = $DateStyle + (Get-Date -Format $DateFormat) + $PSStyle.Reset

        foreach( $line in $_ -split '\r?\n' ) {

            # Produce the final, formatted output.
            $prefix + ($overrideFmt ?? $lastFmt) + $line + ($overrideFmt ? $PSStyle.Reset : '')

            # Remember last ANSI escape sequence (if any) of current line, for cases where formatting spans multiple lines.
            $lastFmt = [regex]::Match( $line, $ansiEscapePattern, 'RightToLeft' ).Value
        }
    }
}

Usage example:

# To differentiate debug and verbose output from warnings 
$PSStyle.Formatting.Debug = $PSStyle.Foreground.Yellow
$PSStyle.Formatting.Verbose = $PSStyle.Foreground.BrightCyan

Invoke-WithDateLog -CatchExceptions -ExceptionStackTrace {
    "Write $($PSStyle.Foreground.Green)colored`ntext$($PSStyle.Reset) to stdout"
    [PSCustomObject]@{ Answer = 42; Question = 'What?' } | Format-Table
    Get-Content -Path not-exists -EA Continue  # produce a non-terminating error
    Write-Host    'Write to information stream'
    Write-Warning 'Write to warning stream'
    Write-Verbose 'Write to verbose stream' -Verbose
    Write-Debug   'Write to debug stream' -Debug
    throw 'Critical error'
}

Output in PS 7.2 console:

Console Output

Notes:

  • The code requires PowerShell 7+.

  • The date formatting can be changed through parameters -DateFormat (see formatting specifiers) and -DateStyle (ANSI escape sequence for coloring).

  • Script-terminating errors such as created by throwing an exception or using Write-Error -EA Stop, are not logged by default. Instead they bubble up from the scriptblock as usual. You can pass parameter -CatchExceptions to catch exceptions and log them like regular non-terminating errors. Pass -ExceptionStackTrace to also log the script stacktrace, which is very useful for debugging.

  • Scripted cmdlets such as this one don't set the automatic variable $? and also don't add errors to the automatic $Error variable when an error is written via Write-Error. Neither the common parameter -ErrorVariable works. To still be able to collect error information I've added parameter -ErrorCollection which can be used like this:

    $scriptErrors = [Collections.ArrayList]::new() 
    
    Invoke-WithDateLog -CatchExceptions -ExceptionStackTrace -ErrorCollection $scriptErrors {
        Write-Error 'Write to stderr' -EA Continue
        throw 'Critical error'
    }
    
    if( $scriptErrors ) {
        # Outputs "Number of errors: 2"
        "`nNumber of errors: $($scriptErrors.Count)"
    }
    
Related