Skip to content

Commit 998bf2a

Browse files
claudiospizziclaudiospizzi
committed
feat: add caller context information (script name and line number) to the log messages
1 parent 1cbfe18 commit 998bf2a

8 files changed

Lines changed: 70 additions & 29 deletions

‎CHANGELOG.md‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -8,6 +8,7 @@ and this project adheres to [Semantic Versioning](http://semver.org/).
88
## Unreleased
99

1010
* Added: Option to include the script stack trace in the error log message (Write-ErrorLog)
11+
* Added: Add caller context information (script name and line number) to the log messages (Start-ScriptLogger)
1112

1213
## 3.3.0 - 2019-11-05
1314

‎ScriptLogger/Functions/Start-ScriptLogger.ps1‎

Lines changed: 5 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -14,7 +14,8 @@
1414
- {1} NetBIOS computer name.
1515
- {2} Current session username.
1616
- {3} Log entry level.
17-
- {4} Message.
17+
- {4} Log message (or error description).
18+
- {5} Context information (script name and line number).
1819
1920
.INPUTS
2021
None.
@@ -57,9 +58,9 @@ function Start-ScriptLogger
5758

5859
# This parameter defines, how the log output will be formatted.
5960
[Parameter(Mandatory = $false)]
60-
[ValidateScript({$_ -f (Get-Date), $Env:ComputerName, $Env:Username, 'Verbose', 'Message'})]
61+
[ValidateScript({ $_ -f (Get-Date), $Env:ComputerName, $Env:Username, 'Verbose', 'Message', 'Context' })]
6162
[System.String]
62-
$Format = '{0:yyyy-MM-dd} {0:HH:mm:ss} {1} {2} {3,-11} {4}',
63+
$Format = '{0:yyyy-MM-dd} {0:HH:mm:ss} {1} {2} {3,-11} [{5}] {4}',
6364

6465
# The event log level. All log messages equal to or higher to the level
6566
# will be logged. This is the level order: Verbose, Information, Warning
@@ -175,7 +176,7 @@ function Start-ScriptLogger
175176

176177
if ($PSCmdlet.ShouldProcess('ScriptLogger', 'Start'))
177178
{
178-
Write-Verbose "Start script logger '$Name'"
179+
Microsoft.PowerShell.Utility\Write-Verbose "Start script logger '$Name'"
179180

180181
$Script:Loggers[$Name] = [PSCustomObject] @{
181182
PSTypeName = 'ScriptLogger.Configuration'

‎ScriptLogger/Functions/Stop-ScriptLogger.ps1‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -38,7 +38,7 @@ function Stop-ScriptLogger
3838
{
3939
if ($PSCmdlet.ShouldProcess('ScriptLogger', 'Stop'))
4040
{
41-
Write-Verbose "Stop script logger '$Name'"
41+
Microsoft.PowerShell.Utility\Write-Verbose "Stop script logger '$Name'"
4242

4343
$Script:Loggers.Remove($Name)
4444
}

‎ScriptLogger/Tests/Unit/Start-ScriptLogger.Tests.ps1‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -19,7 +19,7 @@ Describe 'Start-ScriptLogger' {
1919

2020
$defaultEnabled = $true
2121
$defaultPath = "$PSScriptRoot\Start-ScriptLogger.Tests.ps1.log"
22-
$defaultFormat = '{0:yyyy-MM-dd} {0:HH:mm:ss} {1} {2} {3,-11} {4}'
22+
$defaultFormat = '{0:yyyy-MM-dd} {0:HH:mm:ss} {1} {2} {3,-11} [{5}] {4}'
2323
$defaultLevel = 'Verbose'
2424
$defaultEncoding = 'UTF8'
2525
$defaultRotation = 'None'

‎ScriptLogger/Tests/Unit/Write-ErrorLog.Tests.ps1‎

Lines changed: 50 additions & 17 deletions
Original file line numberDiff line numberDiff line change
@@ -36,11 +36,15 @@ Describe 'Write-ErrorLog' {
3636

3737
InModuleScope $moduleName {
3838

39-
# Arrange
40-
$errorRecord = $(try { 0 / 0 } catch { $_ })
41-
4239
# Act
43-
Write-ErrorLog -ErrorRecord $errorRecord
40+
try
41+
{
42+
0/0
43+
}
44+
catch
45+
{
46+
Write-ErrorLog -ErrorRecord $_
47+
}
4448

4549
# Assert
4650
Assert-MockCalled -Scope It -CommandName 'Write-ScriptLoggerLog' -Times 1 -Exactly
@@ -114,41 +118,56 @@ Describe 'Write-ErrorLog' {
114118

115119
# Arrange
116120
Start-ScriptLogger -Path 'TestDrive:\test.log' -NoEventLog -NoConsoleOutput
121+
$callerLine = 124
117122

118123
# Act
119124
Write-ErrorLog -Message 'My Error'
120125

121126
# Assert
122127
$logFile = Get-Content -Path 'TestDrive:\test.log'
123-
$logFile | Should -Be "2000-12-31 01:02:03 $Env:ComputerName $Env:Username Error My Error"
128+
$logFile | Should -Be "2000-12-31 01:02:03 $Env:ComputerName $Env:Username Error [Write-ErrorLog.Tests.ps1:$callerLine] My Error"
124129
}
125130

126131
It 'should write a valid error record to the log file' {
127132

128133
# Arrange
129134
Start-ScriptLogger -Path 'TestDrive:\test.log' -NoEventLog -NoConsoleOutput
135+
$callerLine = 144
130136

131137
# Act
132-
$errorRecord = $(try { 0 / 0 } catch { $_ })
133-
Write-ErrorLog -ErrorRecord $errorRecord
138+
try
139+
{
140+
0 / 0
141+
}
142+
catch
143+
{
144+
Write-ErrorLog -ErrorRecord $_
145+
}
134146

135147
# Assert
136148
$logFile = Get-Content -Path 'TestDrive:\test.log'
137-
$logFile | Should -BeLike "2000-12-31 01:02:03 $Env:ComputerName $Env:Username Error Attempted to divide by zero. (RuntimeException: *\Unit\Write-ErrorLog.Tests.ps1:* char:*)"
149+
$logFile | Should -BeLike "2000-12-31 01:02:03 $Env:ComputerName $Env:Username Error ``[Write-ErrorLog.Tests.ps1:$callerLine``] Attempted to divide by zero. (RuntimeException: *\Unit\Write-ErrorLog.Tests.ps1:* char:*)"
138150
}
139151

140152
It 'should write a valid message with stack trace to the log' {
141153

142154
# Arrange
143155
Start-ScriptLogger -Path 'TestDrive:\test.log' -NoEventLog -NoConsoleOutput
156+
$callerLine = 165
144157

145158
# Act
146-
$errorRecord = $(try { 0 / 0 } catch { $_ })
147-
Write-ErrorLog -ErrorRecord $errorRecord -IncludeStackTrace
159+
try
160+
{
161+
0 / 0
162+
}
163+
catch
164+
{
165+
Write-ErrorLog -ErrorRecord $_ -IncludeStackTrace
166+
}
148167

149168
# Assert
150169
$logFile = Get-Content -Path 'TestDrive:\test.log'
151-
$logFile[0] | Should -BeLike "2000-12-31 01:02:03 $Env:ComputerName $Env:Username Error Attempted to divide by zero. (RuntimeException: *\Unit\Write-ErrorLog.Tests.ps1:* char:*)"
170+
$logFile[0] | Should -BeLike "2000-12-31 01:02:03 $Env:ComputerName $Env:Username Error ``[Write-ErrorLog.Tests.ps1:$callerLine``] Attempted to divide by zero. (RuntimeException: *\Unit\Write-ErrorLog.Tests.ps1:* char:*)"
152171
$logFile[1] | Should -BeLike "at <ScriptBlock>, *\ScriptLogger\Tests\Unit\Write-ErrorLog.Tests.ps1:*"
153172
}
154173
}
@@ -160,6 +179,7 @@ Describe 'Write-ErrorLog' {
160179
# Arrange
161180
Start-ScriptLogger -Path 'TestDrive:\test.log' -NoLogFile -NoConsoleOutput
162181
$filterTimestamp = [System.DateTime]::Now.AddSeconds(-1)
182+
$callerLine = 185
163183

164184
# Act
165185
Write-ErrorLog -Message 'My Error'
@@ -169,7 +189,7 @@ Describe 'Write-ErrorLog' {
169189
$eventLog.EventID | Should -Be 0
170190
$eventLog.CategoryNumber | Should -Be 0
171191
$eventLog.EntryType | Should -Be 'Error'
172-
$eventLog.Message | Should -Be "The description for Event ID '0' in Source 'PowerShell' cannot be found. The local computer may not have the necessary registry information or message DLL files to display the message, or you may not have permission to access them. The following information is part of the event:'My Error'"
192+
$eventLog.Message | Should -Be "The description for Event ID '0' in Source 'PowerShell' cannot be found. The local computer may not have the necessary registry information or message DLL files to display the message, or you may not have permission to access them. The following information is part of the event:'[Write-ErrorLog.Tests.ps1:$callerLine] My Error'"
173193
$eventLog.Source | Should -Be 'PowerShell'
174194
$eventLog.InstanceId | Should -Be 0
175195
}
@@ -179,17 +199,24 @@ Describe 'Write-ErrorLog' {
179199
# Arrange
180200
Start-ScriptLogger -Path 'TestDrive:\test.log' -NoLogFile -NoConsoleOutput
181201
$filterTimestamp = [System.DateTime]::Now.AddSeconds(-1)
202+
$callerLine = 211
182203

183204
# Act
184-
$errorRecord = $(try { 0 / 0 } catch { $_ })
185-
Write-ErrorLog -ErrorRecord $errorRecord
205+
try
206+
{
207+
0 / 0
208+
}
209+
catch
210+
{
211+
Write-ErrorLog -ErrorRecord $_
212+
}
186213

187214
# Assert
188215
$eventLog = Get-EventLog -LogName 'Windows PowerShell' -Source 'PowerShell' -InstanceId 0 -EntryType Error -After $filterTimestamp -Newest 1
189216
$eventLog.EventID | Should -Be 0
190217
$eventLog.CategoryNumber | Should -Be 0
191218
$eventLog.EntryType | Should -Be 'Error'
192-
$eventLog.Message | Should -BeLike "The description for Event ID '0' in Source 'PowerShell' cannot be found. The local computer may not have the necessary registry information or message DLL files to display the message, or you may not have permission to access them. The following information is part of the event:'Attempted to divide by zero. (RuntimeException: *\Unit\Write-ErrorLog.Tests.ps1:* char:*)'"
219+
$eventLog.Message | Should -BeLike "The description for Event ID '0' in Source 'PowerShell' cannot be found. The local computer may not have the necessary registry information or message DLL files to display the message, or you may not have permission to access them. The following information is part of the event:'``[Write-ErrorLog.Tests.ps1:$callerLine``] Attempted to divide by zero. (RuntimeException: *\Unit\Write-ErrorLog.Tests.ps1:* char:*)'"
193220
$eventLog.Source | Should -Be 'PowerShell'
194221
$eventLog.InstanceId | Should -Be 0
195222
}
@@ -228,8 +255,14 @@ Describe 'Write-ErrorLog' {
228255
Start-ScriptLogger -Path 'TestDrive:\test.log' -NoLogFile -NoEventLog
229256

230257
# Act
231-
$errorRecord = $(try { 0 / 0 } catch { $_ })
232-
Write-ErrorLog -ErrorRecord $errorRecord
258+
try
259+
{
260+
0 / 0
261+
}
262+
catch
263+
{
264+
Write-ErrorLog -ErrorRecord $_
265+
}
233266

234267
# Assert
235268
Assert-MockCalled -Scope It -CommandName 'Show-ScriptLoggerErrorMessage' -Times 1 -Exactly

‎ScriptLogger/Tests/Unit/Write-InformationLog.Tests.ps1‎

Lines changed: 4 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -70,13 +70,14 @@ Describe 'Write-InformationLog' {
7070

7171
# Arrange
7272
Start-ScriptLogger -Path 'TestDrive:\test.log' -NoEventLog -NoConsoleOutput
73+
$callerLine = 76
7374

7475
# Act
7576
Write-InformationLog -Message 'My Information'
7677

7778
# Assert
7879
$logFile = Get-Content -Path 'TestDrive:\test.log'
79-
$logFile | Should -Be "2000-12-31 01:02:03 $Env:ComputerName $Env:Username Information My Information"
80+
$logFile | Should -Be "2000-12-31 01:02:03 $Env:ComputerName $Env:Username Information [Write-InformationLog.Tests.ps1:$callerLine] My Information"
8081
}
8182
}
8283

@@ -87,6 +88,7 @@ Describe 'Write-InformationLog' {
8788
# Arrange
8889
Start-ScriptLogger -Path 'TestDrive:\test.log' -NoLogFile -NoConsoleOutput
8990
$filterTimestamp = [System.DateTime]::Now.AddSeconds(-1)
91+
$callerLine = 94
9092

9193
# Act
9294
Write-InformationLog -Message 'My Information'
@@ -97,7 +99,7 @@ Describe 'Write-InformationLog' {
9799
$eventLog.EventID | Should -Be 0
98100
$eventLog.CategoryNumber | Should -Be 0
99101
$eventLog.EntryType | Should -Be 'Information'
100-
$eventLog.Message | Should -Be "The description for Event ID '0' in Source 'PowerShell' cannot be found. The local computer may not have the necessary registry information or message DLL files to display the message, or you may not have permission to access them. The following information is part of the event:'My Information'"
102+
$eventLog.Message | Should -Be "The description for Event ID '0' in Source 'PowerShell' cannot be found. The local computer may not have the necessary registry information or message DLL files to display the message, or you may not have permission to access them. The following information is part of the event:'[Write-InformationLog.Tests.ps1:$callerLine] My Information'"
101103
$eventLog.Source | Should -Be 'PowerShell'
102104
$eventLog.InstanceId | Should -Be 0
103105
}

‎ScriptLogger/Tests/Unit/Write-VerboseLog.Tests.ps1‎

Lines changed: 4 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -70,13 +70,14 @@ Describe 'Write-VerboseLog' {
7070

7171
# Arrange
7272
Start-ScriptLogger -Path 'TestDrive:\test.log' -NoEventLog -NoConsoleOutput
73+
$callerLine = 76
7374

7475
# Act
7576
Write-VerboseLog -Message 'My Verbose'
7677

7778
# Assert
7879
$logFile = Get-Content -Path 'TestDrive:\test.log'
79-
$logFile | Should -Be "2000-12-31 01:02:03 $Env:ComputerName $Env:Username Verbose My Verbose"
80+
$logFile | Should -Be "2000-12-31 01:02:03 $Env:ComputerName $Env:Username Verbose [Write-VerboseLog.Tests.ps1:$callerLine] My Verbose"
8081
}
8182
}
8283

@@ -87,6 +88,7 @@ Describe 'Write-VerboseLog' {
8788
# Arrange
8889
Start-ScriptLogger -Path 'TestDrive:\test.log' -NoLogFile -NoConsoleOutput
8990
$filterTimestamp = [System.DateTime]::Now.AddSeconds(-1)
91+
$callerLine = 94
9092

9193
# Act
9294
Write-VerboseLog -Message 'My Verbose'
@@ -97,7 +99,7 @@ Describe 'Write-VerboseLog' {
9799
$eventLog.EventID | Should -Be 0
98100
$eventLog.CategoryNumber | Should -Be 0
99101
$eventLog.EntryType | Should -Be 'Information'
100-
$eventLog.Message | Should -Be "The description for Event ID '0' in Source 'PowerShell' cannot be found. The local computer may not have the necessary registry information or message DLL files to display the message, or you may not have permission to access them. The following information is part of the event:'My Verbose'"
102+
$eventLog.Message | Should -Be "The description for Event ID '0' in Source 'PowerShell' cannot be found. The local computer may not have the necessary registry information or message DLL files to display the message, or you may not have permission to access them. The following information is part of the event:'[Write-VerboseLog.Tests.ps1:$callerLine] My Verbose'"
101103
$eventLog.Source | Should -Be 'PowerShell'
102104
$eventLog.InstanceId | Should -Be 0
103105
}

‎ScriptLogger/Tests/Unit/Write-WarningLog.Tests.ps1‎

Lines changed: 4 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -70,13 +70,14 @@ Describe 'Write-WarningLog' {
7070

7171
# Arrange
7272
Start-ScriptLogger -Path 'TestDrive:\test.log' -NoEventLog -NoConsoleOutput
73+
$callerLine = 76
7374

7475
# Act
7576
Write-WarningLog -Message 'My Warning'
7677

7778
# Assert
7879
$logFile = Get-Content -Path 'TestDrive:\test.log'
79-
$logFile | Should -Be "2000-12-31 01:02:03 $Env:ComputerName $Env:Username Warning My Warning"
80+
$logFile | Should -Be "2000-12-31 01:02:03 $Env:ComputerName $Env:Username Warning [Write-WarningLog.Tests.ps1:$callerLine] My Warning"
8081
}
8182
}
8283

@@ -87,6 +88,7 @@ Describe 'Write-WarningLog' {
8788
# Arrange
8889
Start-ScriptLogger -Path 'TestDrive:\test.log' -NoLogFile -NoConsoleOutput
8990
$filterTimestamp = [System.DateTime]::Now.AddSeconds(-1)
91+
$callerLine = 94
9092

9193
# Act
9294
Write-WarningLog -Message 'My Warning'
@@ -97,7 +99,7 @@ Describe 'Write-WarningLog' {
9799
$eventLog.EventID | Should -Be 0
98100
$eventLog.CategoryNumber | Should -Be 0
99101
$eventLog.EntryType | Should -Be 'Warning'
100-
$eventLog.Message | Should -Be "The description for Event ID '0' in Source 'PowerShell' cannot be found. The local computer may not have the necessary registry information or message DLL files to display the message, or you may not have permission to access them. The following information is part of the event:'My Warning'"
102+
$eventLog.Message | Should -Be "The description for Event ID '0' in Source 'PowerShell' cannot be found. The local computer may not have the necessary registry information or message DLL files to display the message, or you may not have permission to access them. The following information is part of the event:'[Write-WarningLog.Tests.ps1:$callerLine] My Warning'"
101103
$eventLog.Source | Should -Be 'PowerShell'
102104
$eventLog.InstanceId | Should -Be 0
103105
}

0 commit comments

Comments
 (0)