Information.psm1
|
using namespace System.Management.Automation [String[]]$DebugFilterInclude = @() [String[]]$DebugFilterExclude = @() class DateTimeOffsetConverter : System.Management.Automation.PSTypeConverter { [bool] CanConvertFrom([PSObject]$psSourceValue, [Type]$destinationType) { return $psSourceValue.PSTypeNames.Contains("Deserialized.System.DateTimeOffset") } [object] ConvertFrom([PSObject]$psSourceValue, [Type]$destinationType, [IFormatProvider]$formatProvider, [bool]$ignoreCase) { return [DateTimeOffset]::new($psSourceValue.Ticks, $psSourceValue.Offset) } # These methods aren't necessary... [bool] CanConvertFrom([object]$sourceValue, [Type]$destinationType) { return ([PSObject]$sourceValue).PSTypeNames.Contains("Deserialized.System.DateTimeOffset") } [object] ConvertFrom([object]$sourceValue, [Type]$destinationType, [IFormatProvider]$formatProvider, [bool]$ignoreCase) { [PSObject]$psSourceValue = $sourceValue return [DateTimeOffset]::new($psSourceValue.Ticks, $psSourceValue.Offset) } [bool] CanConvertTo([object]$sourceValue, [Type]$destinationType) { return ([PSObject]$sourceValue).PSTypeNames.Contains("Deserialized.System.DateTimeOffset") -and $destinationType -eq "System.DateTimeOffset" } [object] ConvertTo([object]$sourceValue, [Type]$destinationType, [IFormatProvider]$formatProvider, [bool]$ignoreCase) { [PSObject]$psSourceValue = $sourceValue return [DateTimeOffset]::new($psSourceValue.Ticks, $psSourceValue.Offset) } } Update-TypeData -TypeName 'Deserialized.System.DateTimeOffset' -TargetTypeForDeserialization 'System.DateTimeOffset' -Force Update-TypeData -TypeName 'System.DateTimeOffset' -TypeConverter 'DateTimeOffsetConverter' -SerializationDepth 1 -Force Add-Type -Path $PSScriptRoot\InformationMessage.cs class InformationMessageConverter : System.Management.Automation.PSTypeConverter { [bool] CanConvertFrom([PSObject]$psSourceValue, [Type]$destinationType) { # Write-Warning "CanConvertFrom $($psSourceValue.PSTypeNames)" return $psSourceValue.PSTypeNames.Contains("Deserialized.Information.InformationMessage") } [object] ConvertFrom([PSObject]$psSourceValue, [Type]$destinationType, [IFormatProvider]$formatProvider, [bool]$ignoreCase) { # Write-Warning "ConvertFrom $($psSourceValue.PSTypeNames)" $Properties = @{} if($psSourceValue.GeneratedDateTime -as [DateTimeOffset]) { $Properties.GeneratedDateTime = $psSourceValue.GeneratedDateTime -as [DateTimeOffset] } if($psSourceValue.ElapsedTime -as [TimeSpan]) { $Properties.ElapsedTime = $psSourceValue.ElapsedTime -as [TimeSpan] } if($psSourceValue.PSComputerName -as [string]) { $Properties.PSComputerName = $psSourceValue.PSComputerName -as [string] } if($psSourceValue.ShowException -as [bool]) { $Properties.ShowException = $psSourceValue.ShowException -as [bool] } if($psSourceValue.Prefix -as [string]) { $Properties.Prefix = $psSourceValue.Prefix -as [string] } return New-Object Information.InformationMessage ($psSourceValue.MessageData, $psSourceValue.CallStack) -Property $Properties } [bool] CanConvertFrom([object]$sourceValue, [Type]$destinationType) { return $false; } [object] ConvertFrom([object]$sourceValue, [Type]$destinationType, [IFormatProvider]$formatProvider, [bool]$ignoreCase) { throw [NotImplementedException]::new(); } [bool] CanConvertTo([object]$sourceValue, [Type]$destinationType) { throw [NotImplementedException]::new(); } [object] ConvertTo([object]$sourceValue, [Type]$destinationType, [IFormatProvider]$formatProvider, [bool]$ignoreCase) { throw [NotImplementedException]::new(); } } Update-TypeData -TypeName 'Deserialized.Information.InformationMessage' -TargetTypeForDeserialization 'InformationMessageConverter' -Force Update-TypeData -TypeName 'InformationMessageConverter' -TypeConverter 'InformationMessageConverter' -SerializationDepth 3 -Force Update-TypeData -TypeName 'Information.InformationMessage' -SerializationDepth 4 -Force class InformationRecordConverter : System.Management.Automation.PSTypeConverter { $InformationMessageConverter = [InformationMessageConverter]::new() [bool] CanConvertFrom([PSObject]$psSourceValue, [Type]$destinationType) { return $psSourceValue.PSTypeNames.Contains("Deserialized.System.Management.Automation.InformationRecord") -and $psSourceValue.MessageData.PSTypeNames.Contains("Deserialized.Information.InformationMessage") } [object] ConvertFrom([PSObject]$psSourceValue, [Type]$destinationType, [IFormatProvider]$formatProvider, [bool]$ignoreCase) { $MessageData = $this.InformationMessageConverter.ConvertFrom( $psSourceValue.MessageData, $null, $null, $true) return [System.Management.Automation.InformationRecord]::new($MessageData, $MessageData.CallStack) } [bool] CanConvertFrom([object]$sourceValue, [Type]$destinationType) { return ([PSObject]$sourceValue).PSTypeNames.Contains("Deserialized.System.Management.Automation.InformationRecord") -and ([PSObject]$sourceValue).MessageData.PSTypeNames.Contains("Deserialized.Information.InformationMessage")-and $destinationType -eq "System.Management.Automation.InformationRecord" } [object] ConvertFrom([object]$sourceValue, [Type]$destinationType, [IFormatProvider]$formatProvider, [bool]$ignoreCase) { [PSObject]$psSourceValue = $sourceValue $MessageData = $this.InformationMessageConverter.ConvertFrom( $psSourceValue.MessageData, $null, $null, $true) return [System.Management.Automation.InformationRecord]::new($MessageData, $MessageData.CallStack) } [bool] CanConvertTo([object]$sourceValue, [Type]$destinationType) { return ([PSObject]$sourceValue).PSTypeNames.Contains("Deserialized.System.Management.Automation.InformationRecord") -and ([PSObject]$sourceValue).MessageData.PSTypeNames.Contains("Deserialized.Information.InformationMessage") -and $destinationType -eq "System.Management.Automation.InformationRecord" } [object] ConvertTo([object]$sourceValue, [Type]$destinationType, [IFormatProvider]$formatProvider, [bool]$ignoreCase) { [PSObject]$psSourceValue = $sourceValue $MessageData = $this.InformationMessageConverter.ConvertFrom( $psSourceValue.MessageData, $null, $null, $true) return [System.Management.Automation.InformationRecord]::new($MessageData, $MessageData.CallStack) } } Update-TypeData -TypeName 'Deserialized.System.Management.Automation.InformationRecord' -TargetTypeForDeserialization 'System.Management.Automation.InformationRecord' -Force Update-TypeData -TypeName 'System.Management.Automation.InformationRecord' -TypeConverter 'InformationRecordConverter' -SerializationDepth 6 -Force function New-InformationMessage { [CmdletBinding()] param( # Object or message to write to the Information stream $MessageData, # The CallStack [Array]$CallStack, # Tags to categorize and filter by [String[]]$Tags, # The prefix for the string message [AllowNull()][AllowEmptyString()] [string]$Prefix, # Don't expand error data [switch]$Simple ) if($CallStack -isnot [System.Management.Automation.CallStackFrame[]]) { $CallStack = $CallStack.ForEach{ $_ -split "[\r?\n]+" } } ${Trace Message} = [Information.InformationMessage]::new($MessageData, $CallStack, $Prefix, $Simple) ${Trace Message}.Message = ([PSCustomObject]@{Data=$MessageData} | Format-Table -HideTableHeaders -AutoSize | Out-String).Trim() ${Information Record} = [InformationRecord]::new(${Trace Message}, "$(@($CallStack)[0])") foreach($Tag in $Tags) { ${Information Record}.Tags.Add($Tag) } ${Information Record} } function Get-InfoTemplate { <# .Synopsis Gets the template string used for trace messages #> [CmdletBinding()]param() [Information.InformationMessage]::InfoTemplate } function Set-InfoTemplate { <# .Synopsis Sets the template string used for trace messages .Description Allows setting the template string to format the trace messages. You use {placeholders} for properties of the object, and a few of them support formatting. The following placeholders are available: {Message} = A string representation of the $MessageData {GeneratedDateTime} = A full DateTimeOffset for when this record was generated {ClockTime} = The TimeOfDay from the DateTimeOffset (A TimeSpan representing when the record was generated) {ElapsedTime} = The elapsed time since the Information.InformationMessage::StartTime The three time based fields support formatting by placing it after the field, like: {ClockTime:hh:mm} Additionally, there are several variables from the last frame of the call stack: {Indent} = A series of spaces based on the depth of the callstack (for indenting) {Command} = The command that was run to invoke the current code (i.e. the last command in the call stack) {FunctionName} = The name of the function (if any) containing the current code (might just be <ScriptBlock> to indicate no function) {ScriptPath} = The full path for the running script file {ScriptName} = The name of the running script file {LineNumber} = The line number of the script file {Location} = A pre-formatted Location string {PSComputerName} = The computer that generated the original InformationMessage `e = The escape character ([char]27) for ANSI .Example Set-InfoTemplate '{ElapsedTime} {ScriptName}:{LineNumber} {Message}' Sets the Information.InformationMessage template to a simple message showing elapsed time, the source, and the message .Example Set-InfoTemplate '{ElapsedTime}{Indent}{Message} <{Command}> {ScriptName}:{LineNumber}' Sets a template that includes indenting based on the size of the CallStack .Example Set-InfoTemplate '{ElapsedTime:mm:ss.fff}{Indent}{Message} <{Command}> {ScriptName}:{LineNumber}' Sets a template which applies formatting to the elapsed time, to shorten it. .Example Set-InfoTemplate '`e[38;5;1m{ElapsedTime}{Indent}`e[38;5;6m{Message} `e[38;5;5m<{Command}> {ScriptName}:{LineNumber}`e[39m' Sets a template with ANSI escape sequences for color and indenting based on $CallStackDepth .Example Set-InfoTemplate '{PSComputerName} `e[38;5;1m{ClockTime::mm:ss.fff} {Indent}`e[38;5;6m{Message} `e[38;5;5m<{Command}> {ScriptName}:{LineNumber}`e[39m' Sets a template which includes the computer name, as well as using the actual time -- useful for logging across remote jobs. #> [CmdletBinding()]param( # The string template for help $Template ) [Information.InformationMessage]::InfoTemplate = $Template } function Trace-Info { #.Synopsis # Invoke a command and collect the trace (Information) output and store it to file #.Description # Wraps invocation of a command with exception handling and logging. # Guarantees exceptions will be fully captured and logged. #.Example # $Examples = Join-Path (Get-Module Information).ModuleBase Examples # C:\PS> Trace-Info -Command "$Examples\TraceException.ps1" -Log "$Examples\TraceException.log.clixml" # C:\PS> $Log = Import-CliXml "$Examples\TraceException.log.clixml" # C:\PS> # # Shows how to invoke the TraceException example script, log it, and filter the collected log for exceptions [CmdletBinding()] param( # The command or script path to execute [Parameter()] $Command, # The path to log to [Parameter()] [string]$LogPath, # A collection of tags to include in debug output # If set, automatically causes Write-Info output to be copied to the Debug stream [string[]]$DebugFilterInclude, # A collection of tags to exclute from the debug output # If set, automatically causes Write-Info output to be copied to the Debug stream # If DebugFilterInclude is not set, everything except these tags is copied [string[]]$DebugFilterExclude, [switch]$CatchException, [Switch]$Passthru ) begin { Remove-Variable TraceExceptionLog -ErrorAction Ignore if($PSBoundParameters.ContainsKey('DebugFilterInclude')) { $Script:DebugFilterInclude = $DebugFilterInclude } if($PSBoundParameters.ContainsKey('DebugFilterExclude')) { $Script:DebugFilterExclude = $DebugFilterExclude } Set-Alias Write-Host Write-Trace -Scope Global -Option AllScope Set-Alias Write-Trace Write-Info -Scope Global -Option AllScope } end { try { . { [CmdletBinding()]param() . $Command } -InformationVariable +TraceExceptionLog -ErrorVariable +TraceExceptionLog } catch { # Attempt to remove duplicates (seems to always happen for exceptions) $ErrorRecord = $_ if($TraceExceptionLog.Count -ge 3) { if(($null -eq (Compare-Object $TraceExceptionLog[-3] $ErrorRecord -Property $ErrorRecord.GetType().GetProperties().Name)) -and ($null -eq (Compare-Object $TraceExceptionLog[-1] $ErrorRecord -Property $ErrorRecord.GetType().GetProperties().Name))) { $TraceExceptionLog = $TraceExceptionLog[0..$($TraceExceptionLog.Count-4)] } } if($null -eq (Compare-Object $TraceExceptionLog[-1] $ErrorRecord -Property $ErrorRecord.GetType().GetProperties().Name)) { $TraceExceptionLog = $TraceExceptionLog[0..$($TraceExceptionLog.Count-2)] } } # To make logging convenient, we convert Errors into Information.InformationMessages: $Max = $TraceExceptionLog.Count - 1 :convertErrors foreach($e in 0..$Max) { if($TraceExceptionLog[$e] -isnot [System.Management.Automation.InformationRecord]) { ## If it's remote, we don't need to re-log it if it's already logged... if($TraceExceptionLog[$e] -is [System.Management.Automation.Runspaces.RemotingErrorRecord]) { $ErrorRecord = $TraceExceptionLog[$e] foreach($r in 0..($e-1)) { if($TraceExceptionLog[$r].MessageData.MessageData.Exception.Message -eq $ErrorRecord.MessageData.MessageData.Exception.Message -and $TraceExceptionLog[$r].MessageData.MessageData.Exception.ErrorDetails_ScriptStackTrace -eq $ErrorRecord.MessageData.MessageData.Exception.ScriptStackTrace) { # Write-ErrorInfo $TraceExceptionLog[$e] -Simple -InformationVariable +TraceExceptionLog -Prefix "REMOTE ERROR LOG:" continue convertErrors } } } ## Replace the original with an InformationRecord # Write-Warning "Logged Error on (${Env:ComputerName}) $($TraceExceptionLog[$e])" # $TraceExceptionLog[$e] = Write-ErrorInfo $TraceExceptionLog[$e] -Passthru -InformationVariable +TraceExceptionLog $TraceExceptionLog[$e] = Write-ErrorInfo $TraceExceptionLog[$e] -Passthru } } if($LogPath) { $TraceExceptionLog | Export-Clixml -Depth 4 -Path $LogPath } if($Passthru) { $TraceExceptionLog } Remove-Item Alias:Write-Host Remove-Item Alias:Write-Trace if(!$CatchException -and $ErrorRecord) { throw $ErrorRecord } } } function Write-ErrorInfo { [CmdletBinding()] param( [Parameter(ValueFromPipeline)] $ErrorRecord, [AllowNull()][AllowEmptyString()] [string]$Prefix, [switch]$WriteError, [switch]$Simple, [switch]$Passthru ) $level = 0 $Information_Record = @{ Prefix = $Prefix MessageData = $ErrorRecord Tags = @("Error") Simple = $Simple.IsPresent } if($ErrorRecord -is [System.Management.Automation.ErrorRecord]) { $Information_Record.Tags += "ErrorRecord" $Information_Record.CallStack = $ErrorRecord.ScriptStackTrace $Ex = $ErrorRecord.Exception } else { $Information_Record.Tags += "Exception" $Information_Record.CallStack = $ErrorRecord.ErrorRecord.ScriptStackTrace $Ex = $ErrorRecord } # recursively add the exception types as tags do { $Information_Record.Tags += $Ex.GetType().Name $Ex = $Ex.InnerException } while($Ex.InnerException) $Info = New-InformationMessage @Information_Record $PSCmdlet.WriteInformation($Info) if($Passthru) { $Info } # Make sure this error shows up in the error stream (as the last error) if($WriteError) { Write-Error -ErrorRecord $ErrorRecord } } function Write-Info { <# .Synopsis An enhancement to the built-in Write-Information to make it show the calling script line .Description Writes messages to the Information stream with callstack and tags, optionally echoing to the debug stream. Messages echoed to the debug stream are only written when debugging is enabled (so they'll be visible) and can be filtered by tags. .Example Write-Info "Enter Get-MyFunctionName" Writes a message to the information stream .Example function Test-Information { [CmdletBinding()]param($Name, $Age) Write-Info 'Enter Test-Information' -Tag 'Trace','Enter' # do stuff Write-Info 'Exit Test-Information' -Tag 'Trace','Exit' } $InformationTracePreference = "CallStack" Test-Information -InformationVariable Log $Log | Where Tags -match Enter | % { $_.MessageData.CallStack } Writes enter and exit messages to the information stream using the TracePreference variables to add CallStack information, and shows how to filter and show that data .Example $InformationDebugEcho = $true Test-Information -Debug Using the same Test-Information from the Example 2, this exameple doesn't includ CallStack information, but uses the $InformationDebugEcho and the -Debug switch trigger the information stream to be echoed to Debug, and printed with source and timestamp information. #> [CmdletBinding(DefaultParameterSetName="InformationOutput")] param( # Specifies an informational message that you want to display to users as they run a script or command. # Note that this is a rich object, and the -InformationVariable can collect those objects, but the stream will just get the ToString() [Parameter(Mandatory=$true, Position=0, ValueFromPipeline=$true, ValueFromPipelineByPropertyName=$true)] [Alias("Object")] [PSObject]$MessageData, # Specifies a simple string that you can use to sort and filter messages that you have added to the information stream with Write-Information [String[]]$Tags, # Supports passing in an existing Stopwatch so you can correlate logs output across jobs [DateTimeOffset]$StartTime ) begin { if($StartTime) { [Information.InformationMessage]::StartTime = $StartTime } if(!${script:Pre-Trace Timer Prompt}) { # Assume that we should reset the StartTime any time we hit the prompt: ${script:Pre-Trace Timer Prompt} = ${function:prompt} ${function:global:prompt} = { [Information.InformationMessage]::StartTime = [DateTimeOffset]::MinValue ${function:global:prompt} = ${script:Pre-Trace Timer Prompt} Remove-Variable -Scope Script -Name "Pre-Trace Timer Prompt" & ${function:global:prompt} } $MyInvocation.MyCommand.ScriptBlock.Module.OnRemove = { if(${script:Pre-Trace Timer Prompt}) { ${function:global:prompt} = ${script:Pre-Trace Timer Prompt} Remove-Variable -Scope Script -Name "Pre-Trace Timer Prompt" } } } # Magically look up the stack for anyone turning on Information and treat it as present here: if($Specified = (Get-PSCallStack).Where({ $_.GetFrameVariables().ContainsKey("InformationPreference")},1)) { $InformationPreference = $Specified.GetFrameVariables()["InformationPreference"].Value } # Magically look up the stack for anyone turning on Debug, and treat it as "Continue" in here if($Specified = (Get-PSCallStack).Where({ $_.GetFrameVariables().ContainsKey("DebugPreference")},1)) { $DebugPreference = $Specified.GetFrameVariables()["DebugPreference"].Value } # Write-Info always treats Debug as either Silent or Contine -- never inquire or any of that if($DebugPreference -notin "SilentlyContinue","Ignore") { $DebugPreference = "Continue" } } process { # The main point of this wrapper is to put the line number into the Source: ${Your CallStack} = Get-PSCallStack | Select-Object -Skip 1 if($PSCmdlet.MyInvocation.InvocationName -eq "Write-Host") { $Tags = @("PSHOST") + $Tags } ${Trace Message} = New-InformationMessage -MessageData $MessageData -CallStack ${Your CallStack} -Tags $Tags $PSCmdlet.WriteInformation(${Trace Message}) if($DebugPreference -eq "Continue") { if(!$DebugFilterInclude -or $Tags.Where{ $_ -in $DebugFilterInclude}) { if(!$DebugFilterExclude -or -not $Tags.Where{ $_ -in $DebugFilterExclude}) { Write-Debug ${Trace Message}.ToString() } } } } } Export-ModuleMember -Function * -Variable DebugFilterInclude, DebugFilterExclude |