Ironman Software Forums
Continue the conversion on the Ironman Software forums. Chat with over 1000 users about PowerShell, PowerShell Universal, and PowerShell Pro Tools.
This blog post was provided by one of our users, Victor Maso. For more information about the logging function defined in this post, you can visit GitHub. If you want to contribute to our blog, please email us.
PowerShell Universal has several methods to debug dashboards, jobs and endpoints. However logging within your code is up to you. As part of your custom log function, automatically capturing metadata enables you to audit user actions and debug your code more effectively especially within complex dashboards.
When creating any new application log we want to have some sort of a structure and standards so we can easily parse the logs later. Lets start by adding a timestamp and severity to our log message in a [PSCustomObject].
function Write-PSULog {
param(
[ValidateSet('Info', 'Warn', 'Error', 'Start', 'End', IgnoreCase = $false)]
[string]$Severity = "Info",
[Parameter(Mandatory = $true)]
[string]$Message
)
$LogObject = [PSCustomObject]@{
Timestamp = Get-Date
Severity = $Severity
Message = $Message
}
$LogObject
}
Write-PSULog -Severity Info -Message "Hello World!"
Timestamp Severity Message
--------- -------- -------
11/14/2022 3:31:56 PM Info Hello World!
While this does show us the output and will display in PSU Job log, it will also output the object to the pipeline.
Lets update it to write the output to the host and write a file as JSON. Writing to JSON preserves the PSObject
structure in a text format.
function Write-PSULog {
param(
[ValidateSet('Info', 'Warn', 'Error', 'Start', 'End', IgnoreCase = $false)]
[string]$Severity = "Info",
[Parameter(Mandatory = $true)]
[string]$Message,
[string]$logDirectory="C:\PSULogDir"
)
$LogObject = [PSCustomObject]@{
Timestamp = Get-Date
Severity = $Severity
Message = $Message
}
$logFilePath = Join-Path "$logDirectory" "PSULogFile.json"
$LogObject | ConvertTo-Json -Compress | Out-File -FilePath $logFilePath -Append
Write-Host "$($LogObject.Timestamp) Severity=$($LogObject.Severity) Message=$($LogObject.Message)"
}
Powershell
Write-PSULog -Severity Info -Message "Hello World!"
Write-PSULog -Severity Info -Message "Another Message"
Host Output
11/14/2022 15:25:58 Severity=Info Message=Hello World!
11/14/2022 15:27:25 Severity=Info Message=Another Message
PSULogFile.json
{"Timestamp":"2022-11-14T15:25:58.8605891-05:00","Severity":"Info","Message":"Hello World!"}
{"Timestamp":"2022-11-14T15:27:25.5325547-05:00","Severity":"Info","Message":"Another Message"}
Many SIEM products like Splunk, Sumo and others support automatic parsing of JSON without any sort of log definition being defined. Having a centralized log solution that can parse and categorize your logs can be very beneficial for searching, but not required. Using JSON also allows for the flexibility of having your logs not all contain the same fields but still be structured.
By compressing the JSON (removing whitespace/formatting) and separating each JSON log/document into its own line this usually makes it more compatible, faster to write and smaller in file size to be parsed by a log solution supporting JSON.
Powershell Universal creates some standard variables when running as a Dashboard, Job or API. https://docs.powershelluniversal.com/platform/variables#built-in-variables
By looking for these variables we can determine if this is a job, API or Dashboard and include relevant metadata with each log. We can then populate a new PSCustomObject
with metadata relevant to each type including what user is invoking the process.
if ($DashboardName) {
#Dashboard
$Metadata = [PSCustomObject]@{
Invoking_User = $user
Name = $DashboardName
PSU_Type = "Dashboard"
EndPointID = $endpoint.Name
}
} elseif (($Method) -and ($Url)) {
#Rest API Endpoint
$Metadata = [PSCustomObject]@{
Invoking_User = $Identity
Method = $Method
EndpointUrl = $Url
Body = $Body
}
} elseif ($UAJob.id) {
#UA Job
$UAJobParamObjects = $UAJob.Parameters | ForEach-Object {
[PSCustomObject]@{
Name = $_.name
Type = $_.type
DisplayValue = $_.DisplayValue
}
}
$Metadata = [PSCustomObject]@{
Invoking_User = $UAJob.Identity.name
UAJobParam = $UAJobParamObjects
UAJobScript = $UAJob.ScriptFullPath
UAJobId = $UAJob.Id
}
} else {
#Not running in UA. Identify User run as account by Home directory
$user = $HOME | Split-Path -Leaf
$Metadata = [PSCustomObject]@{
Invoking_User = $user
}
}
To our parameter block we want to add a way for our function to accept an exception object. We can specify $_
as the default for the -LastException
parameter which will automatically retrieve the last exception when used in a catch handler.
function Write-PSULog {
param(
[ValidateSet('Info', 'Warn', 'Error', 'Start', 'End', IgnoreCase = $false)]
[string]$Severity = "Info",
[Parameter(Mandatory = $true)]
[string]$Message,
[string]$logDirectory = "C:\PSULogDir",
[System.Management.Automation.ErrorRecord]$LastException = $_
)
...
...
To ensure a function throws a terminating error (an error that stops the pipeline and does not continue) you usually can specify -ErrorAction
Stop. Using this in a Try
catch
block will allow our log function to access the exception object.
try {
Write-PSULog -Severity Info -Message "Running Get-Service on [$ServiceName]"
Get-Service -Name "Spooler" -BadParam "value" -ErrorAction Stop
} catch {
Write-PSULog -Severity Error -Message "There was an error getting [$ServiceName]"
}
In our code we add a section that expands out some useful information about the exception into a psobject.
if ($Severity -eq "Error") {
if ($LastException.ErrorRecord) {
#PSCore Error
$LastError = $LastException.ErrorRecord
} else {
#PS 5.1 Error
$LastError = $LastException
}
if ($LastException.InvocationInfo.MyCommand.Version) {
$version = $LastError.InvocationInfo.MyCommand.Version.ToString()
}
$LastErrorObject = @{
'ExceptionMessage' = $LastError.Exception.Message
'ExceptionSource' = $LastError.Exception.Source
'ExceptionStackTrace' = $LastError.Exception.StackTrace
'PositionMessage' = $LastError.InvocationInfo.PositionMessage
'InvocationName' = $LastError.InvocationInfo.InvocationName
'MyCommandVersion' = $version
'ScriptName' = $LastError.InvocationInfo.ScriptName
}
}
The very last line of our Write-PSULog
function can throw the very same exception it received at the beginning of the script. This allows you to retain the the same functionality of stopping the pipeline and outputting the same error after your logging is complete. If this were running in a PSU Dashboard the same error will be shown in a red UDToast just like the original terminating error would have.
if ($Severity -eq "Error") {throw $LastException}
Best practice when designing dashboards is to leverage Powershell functions stored in modules and/or PSU Jobs whenever possible. This is fantastic for keeping the code for the layout of a dashboard separate from the code executed by user button press for example. If the function or a nested function within the dashboard or Job has an error the output of the exception or log might not be clear on what file/script line the error ocurred. Dashboards typically create many runspaces and when looking at an exception it will show “scriptblock” as the calling function and the line number where the error occurred will likely not align with the line number in your Dashboard script file.
https://docs.powershelluniversal.com/config/best-practices#use-functions-in-dashboards
https://docs.powershelluniversal.com/config/best-practices#consider-leveraging-jobs
$CallStackDepth = 0
$fullCallStack = Get-PSCallStack
$LogObject | Add-Member -MemberType NoteProperty -Name LastError -Value $LastErrorObject
$FullCallStackWithoutLogFunction = $fullCallStack | ForEach-Object {
#loop through all the objects in the callstack result.
#excluding the 0 position of the call stack which would represent this write-psulog function.
if ($CallStackDepth -gt 0) {
[PSCustomObject]@{
CallStackDepth = $CallStackDepth
ScriptLineNumber = $_.ScriptLineNumber
FunctionName = $_.FunctionName
ScriptName = $_.ScriptName
Location = $_.Location
Command = $_.Command
Arguments = $_.Arguments
}
}
$CallStackDepth++
}
$LogObject | Add-Member -MemberType NoteProperty -Name fullCallStackDump -Value $FullCallStackWithoutLogFunction
function Write-PSULog {
param(
[ValidateSet('Info', 'Warn', 'Error', 'Start', 'End', IgnoreCase = $false)]
[string]$Severity = "Info",
[Parameter(Mandatory = $true)]
[string]$Message,
[string]$logDirectory = "C:\PSULogDir",
[System.Management.Automation.ErrorRecord]$LastException = $_
)
if ($DashboardName) {
#Dashboard
$Metadata = [PSCustomObject]@{
Invoking_User = $user
Name = $DashboardName
PSU_Type = "Dashboard"
EndPointID = $endpoint.Name
}
} elseif (($Method) -and ($Url)) {
#Rest API Endpoint
$Metadata = [PSCustomObject]@{
Invoking_User = $Identity
Method = $Method
EndpointUrl = $Url
Body = $Body
}
} elseif ($UAJob.id) {
#UA Job
$UAJobParamObjects = $UAJob.Parameters | ForEach-Object {
[PSCustomObject]@{
Name = $_.name
Type = $_.type
DisplayValue = $_.DisplayValue
}
}
$Metadata = [PSCustomObject]@{
Invoking_User = $UAJob.Identity.name
UAJobParam = $UAJobParamObjects
UAJobScript = $UAJob.ScriptFullPath
UAJobId = $UAJob.Id
}
} else {
#Identify User run as account by Home directory
$user = $HOME | Split-Path -Leaf
$Metadata = [PSCustomObject]@{
Invoking_User = $user
}
}
$CallStackDepth = 0
$fullCallStack = Get-PSCallStack
$CallingFunction = $fullCallStack[1].FunctionName
$LogObject = [PSCustomObject]@{
Timestamp = (Get-Date).ToString()
Severity = $Severity
CallingFunction = $CallingFunction
Message = $Message
Metadata = $Metadata
}
if ($Severity -eq "Error") {
if ($LastException.ErrorRecord) {
#PSCore Error
$LastError = $LastException.ErrorRecord
} else {
#PS 5.1 Error
$LastError = $LastException
}
if ($LastException.InvocationInfo.MyCommand.Version) {
$version = $LastError.InvocationInfo.MyCommand.Version.ToString()
}
$LastErrorObject = @{
'ExceptionMessage' = $LastError.Exception.Message
'ExceptionSource' = $LastError.Exception.Source
'ExceptionStackTrace' = $LastError.Exception.StackTrace
'PositionMessage' = $LastError.InvocationInfo.PositionMessage
'InvocationName' = $LastError.InvocationInfo.InvocationName
'MyCommandVersion' = $version
'ScriptName' = $LastError.InvocationInfo.ScriptName
}
$LogObject | Add-Member -MemberType NoteProperty -Name LastError -Value $LastErrorObject
$FullCallStackWithoutLogFunction = $fullCallStack | ForEach-Object {
#loop through all the objects in the callstack result.
#excluding the 0 position of the call stack which would represent this write-psulog function.
if ($CallStackDepth -gt 0) {
[PSCustomObject]@{
CallStackDepth = $CallStackDepth
ScriptLineNumber = $_.ScriptLineNumber
FunctionName = $_.FunctionName
ScriptName = $_.ScriptName
Location = $_.Location
Command = $_.Command
Arguments = $_.Arguments
}
}
$CallStackDepth++
}
$LogObject | Add-Member -MemberType NoteProperty -Name fullCallStackDump -Value $FullCallStackWithoutLogFunction
$WriteHostColor = @{foregroundColor = "Red"}
}
$logFilePath = Join-Path "$logDirectory" "PSULogFile.json"
$LogObject | ConvertTo-Json -Depth 2 | Out-File -FilePath $logFilePath -Append -Encoding utf8
Write-Host "$($LogObject.Timestamp) Sev=$($LogObject.Severity) CallingFunction=$($LogObject.CallingFunction) `n $($LogObject.Message)" @WriteHostColor
if ($Severity -eq "Error") {throw $LastException}
}
Measure-Command
and only do more verbose logging when needed like for Errors or the end of scripts. Avoid dependencies that could cause you log function to fail if they are missing. Avoid unnecessary logging where performance matters.Out-null
or assign output to $null
as necessary to avoid hard to diagnose issues due to unexpected output to the pipeline.{
"Timestamp": "11/14/2022 10:20:13 PM",
"Severity": "Info",
"CallingFunction": "Invoke-FailFunction_GetService",
"Message": "Running Get-Service on [FakeService]",
"Metadata": {
"Invoking_User": "Domain\\Victor",
"Name": "WPSU_Dashboard51",
"PSU_Type": "Dashboard",
"EndPointID": "LookupFakeServiceButtonID"
}
}
{
"Timestamp": "11/14/2022 10:20:13 PM",
"Severity": "Error",
"CallingFunction": "Invoke-FailFunction_GetService",
"Message": "There was an error getting [FakeService]",
"Metadata": {
"Invoking_User": "Domain\\Victor",
"Name": "WPSU_Dashboard51",
"PSU_Type": "Dashboard",
"EndPointID": "LookupFakeServiceButtonID"
},
"LastError": {
"ScriptName": "C:\\ProgramData\\UniversalAutomation\\Repository\\PSULogModule\\TestFunctions\\Invoke-FailFunction_GetService.ps1",
"ExceptionSource": "System.Management.Automation",
"ExceptionStackTrace": " at System.Management.Automation.ExceptionHandlingOps.CheckActionPreference(FunctionContext funcContext, Exception exception)\r\n at System.Management.Automation.Interpreter.ActionCallInstruction`2.Run(InterpretedFrame frame)\r\n at System.Management.Automation.Interpreter.EnterTryCatchFinallyInstruction.Run(InterpretedFrame frame)\r\n at System.Management.Automation.Interpreter.EnterTryCatchFinallyInstruction.Run(InterpretedFrame frame)",
"InvocationName": "",
"ExceptionMessage": "A parameter cannot be found that matches parameter name \u0027ExtraVariable\u0027.",
"MyCommandVersion": "3.0.0.0",
"PositionMessage": "At C:\\ProgramData\\UniversalAutomation\\Repository\\PSULogModule\\TestFunctions\\Invoke-FailFunction_GetService.ps1:9 char:40\r\n+ Get-Service -Name $ServiceName -ExtraVariable $ExtraVariable ...\r\n+ ~~~~~~~~~~~~~~"
},
"fullCallStackDump": [
{
"CallStackDepth": 1,
"ScriptLineNumber": 11,
"FunctionName": "Invoke-FailFunction_GetService",
"ScriptName": "C:\\ProgramData\\UniversalAutomation\\Repository\\PSULogModule\\TestFunctions\\Invoke-FailFunction_GetService.ps1",
"Location": "Invoke-FailFunction_GetService.ps1: line 11",
"Command": "Invoke-FailFunction_GetService",
"Arguments": "{ServiceName=FakeService, ExtraVariable=ExtraVariableValue}"
},
{
"CallStackDepth": 2,
"ScriptLineNumber": 9,
"FunctionName": "Invoke-MainScript",
"ScriptName": "C:\\ProgramData\\UniversalAutomation\\Repository\\PSULogModule\\TestFunctions\\Invoke-MainScript.ps1",
"Location": "Invoke-MainScript.ps1: line 9",
"Command": "Invoke-MainScript",
"Arguments": "{ServiceNameToLookup=FakeService}"
},
{
"CallStackDepth": 3,
"ScriptLineNumber": 3,
"FunctionName": "\u003cScriptBlock\u003e",
"ScriptName": null,
"Location": "\u003cNo file\u003e",
"Command": "\u003cScriptBlock\u003e",
"Arguments": "{}"
}
]
}
{
"Timestamp": "11/14/2022 10:26:51 PM",
"Severity": "Info",
"CallingFunction": "Invoke-FailFunction_GetService",
"Message": "Running Get-Service on [FakeService]",
"Metadata": {
"Invoking_User": "Domain\\Victor",
"Method": "GET",
"EndpointUrl": "/WPSU_EndpointPS7/test",
"Body": ""
}
}
{
"Timestamp": "11/14/2022 10:26:51 PM",
"Severity": "Error",
"CallingFunction": "Invoke-FailFunction_GetService",
"Message": "There was an error getting [FakeService]",
"Metadata": {
"Invoking_User": "Domain\\Victor",
"Method": "GET",
"EndpointUrl": "/WPSU_EndpointPS7/test",
"Body": ""
},
"LastError": {
"MyCommandVersion": "7.3.0.500",
"ExceptionMessage": "A parameter cannot be found that matches parameter name 'ExtraVariable'.",
"ScriptName": "C:\\ProgramData\\UniversalAutomation\\Repository\\PSULogModule\\TestFunctions\\Invoke-FailFunction_GetService.ps1",
"PositionMessage": "At C:\\ProgramData\\UniversalAutomation\\Repository\\PSULogModule\\TestFunctions\\Invoke-FailFunction_GetService.ps1:9 char:40\r\n+ Get-Service -Name $ServiceName -ExtraVariable $ExtraVariable …\r\n+ ~~~~~~~~~~~~~~",
"ExceptionStackTrace": " at System.Management.Automation.ExceptionHandlingOps.CheckActionPreference(FunctionContext funcContext, Exception exception)\r\n at System.Management.Automation.Interpreter.ActionCallInstruction`2.Run(InterpretedFrame frame)\r\n at System.Management.Automation.Interpreter.EnterTryCatchFinallyInstruction.Run(InterpretedFrame frame)\r\n at System.Management.Automation.Interpreter.EnterTryCatchFinallyInstruction.Run(InterpretedFrame frame)",
"ExceptionSource": "System.Management.Automation",
"InvocationName": ""
},
"fullCallStackDump": [
{
"CallStackDepth": 1,
"ScriptLineNumber": 11,
"FunctionName": "Invoke-FailFunction_GetService",
"ScriptName": "C:\\ProgramData\\UniversalAutomation\\Repository\\PSULogModule\\TestFunctions\\Invoke-FailFunction_GetService.ps1",
"Location": "Invoke-FailFunction_GetService.ps1: line 11",
"Command": "Invoke-FailFunction_GetService",
"Arguments": "{ServiceName=FakeService, ExtraVariable=ExtraVariableValue}"
},
{
"CallStackDepth": 2,
"ScriptLineNumber": 9,
"FunctionName": "Invoke-MainScript",
"ScriptName": "C:\\ProgramData\\UniversalAutomation\\Repository\\PSULogModule\\TestFunctions\\Invoke-MainScript.ps1",
"Location": "Invoke-MainScript.ps1: line 9",
"Command": "Invoke-MainScript",
"Arguments": "{ServiceNameToLookup=FakeService}"
},
{
"CallStackDepth": 3,
"ScriptLineNumber": 7,
"FunctionName": "<ScriptBlock>",
"ScriptName": null,
"Location": "<No file>",
"Command": "<ScriptBlock>",
"Arguments": "{-TestVar, test}"
},
{
"CallStackDepth": 4,
"ScriptLineNumber": 1,
"FunctionName": "<ScriptBlock>",
"ScriptName": null,
"Location": "<No file>",
"Command": "<ScriptBlock>",
"Arguments": "{}"
}
]
}
{
"Timestamp": "11/14/2022 10:34:45 PM",
"Severity": "Info",
"CallingFunction": "Invoke-FailFunction_GetService",
"Message": "Running Get-Service on [FakeService]",
"Metadata": {
"Invoking_User": "Domain\\Victor",
"UAJobParam": {
"Name": "testJobParam",
"Type": "System.Object",
"DisplayValue": "FakeService"
},
"UAJobScript": "Jobs\\WPSU_Script.ps1",
"UAJobId": 4870
}
}
{
"Timestamp": "11/14/2022 10:34:45 PM",
"Severity": "Error",
"CallingFunction": "Invoke-FailFunction_GetService",
"Message": "There was an error getting [FakeService]",
"Metadata": {
"Invoking_User": "Domain\\Victor",
"UAJobParam": {
"Name": "testJobParam",
"Type": "System.Object",
"DisplayValue": "FakeService"
},
"UAJobScript": "Jobs\\WPSU_Script.ps1",
"UAJobId": 4870
},
"LastError": {
"ScriptName": "C:\\ProgramData\\UniversalAutomation\\Repository\\PSULogModule\\TestFunctions\\Invoke-FailFunction_GetService.ps1",
"ExceptionSource": "System.Management.Automation",
"ExceptionStackTrace": " at System.Management.Automation.ExceptionHandlingOps.CheckActionPreference(FunctionContext funcContext, Exception exception)\r\n at System.Management.Automation.Interpreter.ActionCallInstruction`2.Run(InterpretedFrame frame)\r\n at System.Management.Automation.Interpreter.EnterTryCatchFinallyInstruction.Run(InterpretedFrame frame)\r\n at System.Management.Automation.Interpreter.EnterTryCatchFinallyInstruction.Run(InterpretedFrame frame)",
"InvocationName": "",
"ExceptionMessage": "A parameter cannot be found that matches parameter name \u0027ExtraVariable\u0027.",
"MyCommandVersion": "3.0.0.0",
"PositionMessage": "At C:\\ProgramData\\UniversalAutomation\\Repository\\PSULogModule\\TestFunctions\\Invoke-FailFunction_GetService.ps1:9 char:40\r\n+ Get-Service -Name $ServiceName -ExtraVariable $ExtraVariable ...\r\n+ ~~~~~~~~~~~~~~"
},
"fullCallStackDump": [
{
"CallStackDepth": 1,
"ScriptLineNumber": 11,
"FunctionName": "Invoke-FailFunction_GetService",
"ScriptName": "C:\\ProgramData\\UniversalAutomation\\Repository\\PSULogModule\\TestFunctions\\Invoke-FailFunction_GetService.ps1",
"Location": "Invoke-FailFunction_GetService.ps1: line 11",
"Command": "Invoke-FailFunction_GetService",
"Arguments": "{ServiceName=FakeService, ExtraVariable=ExtraVariableValue}"
},
{
"CallStackDepth": 2,
"ScriptLineNumber": 9,
"FunctionName": "Invoke-MainScript",
"ScriptName": "C:\\ProgramData\\UniversalAutomation\\Repository\\PSULogModule\\TestFunctions\\Invoke-MainScript.ps1",
"Location": "Invoke-MainScript.ps1: line 9",
"Command": "Invoke-MainScript",
"Arguments": "{ServiceNameToLookup=FakeService}"
},
{
"CallStackDepth": 3,
"ScriptLineNumber": 7,
"FunctionName": "\u003cScriptBlock\u003e",
"ScriptName": "C:\\ProgramData\\UniversalAutomation\\Repository\\Jobs\\WPSU_Script.ps1",
"Location": "WPSU_Script.ps1: line 7",
"Command": "WPSU_Script.ps1",
"Arguments": "{testJobParam=FakeService}"
},
{
"CallStackDepth": 4,
"ScriptLineNumber": 1,
"FunctionName": "\u003cScriptBlock\u003e",
"ScriptName": null,
"Location": "\u003cNo file\u003e",
"Command": "\u003cScriptBlock\u003e",
"Arguments": "{}"
}
]
}
Continue the conversion on the Ironman Software forums. Chat with over 1000 users about PowerShell, PowerShell Universal, and PowerShell Pro Tools.
Receive once-a-month updates about Ironman Software. You'll learn about our product updates and blogs related to PowerShell.