Wednesday, December 9, 2015

Logging PowerShell Error Message Output

When designing a PowerShell script that will be executed as a scheduled task, I prefer copious amounts of logging, for obvious reasons. I recently had some fun with getting error messages logged with sufficient detail. Consider the following simple script:
$A = Get-ChildItem C:\temp
try {
 $B = Get-ChildItem2 C:\temp
} catch {
 $Error[0] | Out-File -filepath c:\temp\test.log
}

I have forced an error to occur on line 3 by including an invalid command. When run interactively no output is produced on the screen, which is fine because when run as a scheduled task, no one will be there to see it anyways. The log file contains the following content:
Get-ChildItem2 : The term 'Get-ChildItem2' 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 C:\Temp\test.ps1:3 char:7
+     $B = Get-ChildItem2 C:\temp
+          ~~~~~~~~~~~~~~
    + CategoryInfo          : ObjectNotFound: (Get-ChildItem2:String) [], CommandNotFoundException
    + FullyQualifiedErrorId : CommandNotFoundException
The output log contains the normal error detail you'd see if running the command interactively.


Let's enhance the log with something normal like a timestamp.
(get-date -UFormat "%Y%m%d%H%M%S") + ": " + $Error[0] | Out-File -filepath c:\temp\test.log

The output log now contains the content:
20151209123349: The term 'Get-ChildItem2' 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.
We successfully added the timestamp, but lost many details such as the line that incurred the error. Let's see if we can restore the missing data to the log file. When we look at the error object, we can see the following information:

PS C:\Temp> $Error[0] | gm

   TypeName: System.Management.Automation.ErrorRecord
Name                  MemberType     Definition
----                  ----------     ----------
Equals                Method         bool Equals(System.Object obj)
GetHashCode           Method         int GetHashCode()
GetObjectData         Method         void GetObjectData(System.Runtime.Serialization.SerializationInfo info, System....
GetType               Method         type GetType()
ToString              Method         string ToString()
CategoryInfo          Property       System.Management.Automation.ErrorCategoryInfo CategoryInfo {get;}
ErrorDetails          Property       System.Management.Automation.ErrorDetails ErrorDetails {get;set;}
Exception             Property       System.Exception Exception {get;}
FullyQualifiedErrorId Property       string FullyQualifiedErrorId {get;}
InvocationInfo        Property       System.Management.Automation.InvocationInfo InvocationInfo {get;}
PipelineIterationInfo Property       System.Collections.ObjectModel.ReadOnlyCollection[int] PipelineIterationInfo {g...
ScriptStackTrace      Property       string ScriptStackTrace {get;}
TargetObject          Property       System.Object TargetObject {get;}
PSMessageDetails      ScriptProperty System.Object PSMessageDetails {get=& { Set-StrictMode -Version 1; $this.Except...

We have a default to ToString() method.  Let's see what that gets us:
PS C:\Temp> $Error[0].ToString()
The term 'Get-ChildItem2' 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.


That matches the text that ended up in the second log file. Let's see if we can find where the missing data lives in the ErrorRecord object. The initial output contains the keywords CategoryInfo and FullyQualifiedErrorId.  Those are both properties, so let's look at those:

PS C:\Temp> $Error[0].CategoryInfo

Category   : ObjectNotFound
Activity   :
Reason     : CommandNotFoundException
TargetName : Get-ChildItem2
TargetType : String

PS C:\Temp> $Error[0].FullyQualifiedErrorId
CommandNotFoundException


That's a start as that data is included in the initial output, but is unformatted.  We're still missing the pointer to the faulting line in the script. Looking through the other properties, we see that the InvocationInfo property contains the data we were looking for in the PositionMessage property.


PS C:\Temp> $Error[0].InvocationInfo

MyCommand             :
BoundParameters       : {}
UnboundArguments      : {}
ScriptLineNumber      : 3
OffsetInLine          : 7
HistoryId             : 36
ScriptName            : C:\Temp\test.ps1
Line                  :     $B = Get-ChildItem2 C:\temp

PositionMessage       : At C:\Temp\test.ps1:3 char:7
                        +     $B = Get-ChildItem2 C:\temp
                        +          ~~~~~~~~~~~~~~
PSScriptRoot          : C:\Temp
PSCommandPath         : C:\Temp\test.ps1
InvocationName        : Get-ChildItem2
PipelineLength        : 0
PipelinePosition      : 0
ExpectingInput        : False
CommandOrigin         : Internal
DisplayScriptPosition :


At this point, we could come up with a mildly complex function to recreate the initial output by referencing the appropriate properties. However, there's an easier way to get the error output.


Out-String


In all my years of PowerShell-ing, I've never had a reason to use Out-String, as most items will normally render as a string to the console or a file (as was evidenced above). Out-String does exactly what we want in this instance.
PS C:\Temp> $Error[0] | Out-String
Get-ChildItem2 : The term 'Get-ChildItem2' 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 C:\Temp\test.ps1:3 char:7
+     $B = Get-ChildItem2 C:\temp
+          ~~~~~~~~~~~~~~
    + CategoryInfo          : ObjectNotFound: (Get-ChildItem2:String) [], CommandNotFoundException
    + FullyQualifiedErrorId : CommandNotFoundException


From the console, this output is unsurprisingly identical to the statement $Error[0] issued all by itself.


We can add this into our script as follows:
(get-date -UFormat "%Y%m%d%H%M%S") + ": " + ($Error[0] | Out-String) | Out-File -filepath c:\temp\test.log
And finally our log file contains the full content we want:
20151209132608: Get-ChildItem2 : The term 'Get-ChildItem2' 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 C:\Temp\test.ps1:3 char:7
+     $B = Get-ChildItem2 C:\temp
+          ~~~~~~~~~~~~~~
    + CategoryInfo          : ObjectNotFound: (Get-ChildItem2:String) [], CommandNotFoundException
    + FullyQualifiedErrorId : CommandNotFoundException