Skip to content

Commit 8e3f256

Browse files
alexandairalexandair
authored
Merge pull request #989 from alexandair/alex-logging
Add logging functionality
2 parents 0e88be8 + fa29877 commit 8e3f256

6 files changed

Lines changed: 263 additions & 10 deletions

File tree

‎src/powershell/private/tests/Invoke-ZtTest.ps1‎

Lines changed: 32 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -16,18 +16,25 @@
1616
.PARAMETER Database
1717
The Database used for accessing cached tenant data.
1818
19+
.PARAMETER LogsPath
20+
Path to the logs folder where per-test log files are written.
21+
If not specified, no log files are written.
22+
1923
.EXAMPLE
20-
PS C:\> Invoke-ZtTest -Test $_ -Database $global:database
24+
PS C:\> Invoke-ZtTest -Test $_ -Database $global:database -LogsPath $logsPath
2125
22-
Executes the current test with the globally cached database connection.
26+
Executes the current test with the globally cached database connection and writes a log file.
2327
#>
2428
[CmdletBinding()]
2529
param (
2630
[Parameter(Mandatory = $true)]
2731
$Test,
2832

2933
[DuckDB.NET.Data.DuckDBConnection]
30-
$Database
34+
$Database,
35+
36+
[string]
37+
$LogsPath
3138
)
3239
begin {
3340
$previousMessages = Get-PSFMessage -Runspace ([runspace]::DefaultRunspace.InstanceId)
@@ -60,10 +67,22 @@
6067
}
6168

6269
$dbParam = @{}
63-
if ($command.Parameters.ContainsKey("Database") -and $Database) {
70+
if (($null -ne $command) -and $command.Parameters.ContainsKey("Database") -and $Database) {
6471
$dbParam.Database = $Database
6572
}
6673

74+
# Write stub log file and progress entry so hanging tests are visible
75+
if ($LogsPath) {
76+
Write-ZtTestProgress -TestID $Test.TestID -LogsPath $LogsPath -Action Started
77+
try {
78+
$stubPath = Join-Path $LogsPath "$($Test.TestID).md"
79+
[System.IO.File]::WriteAllText($stubPath, "# Test: $($Test.TestID) - Started at $((Get-Date).ToString('yyyy-MM-dd HH:mm:ss.fff'))$([System.Environment]::NewLine)")
80+
}
81+
catch {
82+
Write-PSFMessage -Level Warning -Message "Failed to write stub test log for test '{0}': {1}" -StringValues $Test.TestID, $_ -Tag log
83+
}
84+
}
85+
6786
try {
6887
# Set Current Test for "Add-ZtTestResultDetail to pick up"
6988
$script:__ztCurrentTest = $Test
@@ -88,6 +107,15 @@
88107
end {
89108
$result.Messages = Get-PSFMessage -Runspace ([runspace]::DefaultRunspace.InstanceId) | Where-Object { $_ -notin $previousMessages }
90109
Write-ZtTestStatistics -Result $result
110+
111+
# Write per-test log file (overwrites stub) and progress entry
112+
if ($LogsPath) {
113+
Write-ZtTestLog -Result $result -LogsPath $LogsPath
114+
$progressAction = if ($result.Success) { 'Completed' } else { 'Failed' }
115+
$progressError = if (-not $result.Success -and $result.Error) { "$($result.Error)" } else { $null }
116+
Write-ZtTestProgress -TestID $result.TestID -LogsPath $LogsPath -Action $progressAction -Duration $result.Duration -ErrorMessage $progressError
117+
}
118+
91119
$result
92120
}
93121
}

‎src/powershell/private/tests/Invoke-ZtTests.ps1‎

Lines changed: 6 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -38,7 +38,10 @@
3838
$Pillar = 'All',
3939

4040
[int]
41-
$ThrottleLimit = 5
41+
$ThrottleLimit = 5,
42+
43+
[string]
44+
$LogsPath
4245
)
4346

4447
# Get Tenant Type (AAD = Workforce, CIAM = EEID)
@@ -70,12 +73,12 @@
7073
try {
7174
# Run Sync Tests in the main thread
7275
foreach ($test in $syncTests) {
73-
Invoke-ZtTest -Test $test -Database $Database
76+
Invoke-ZtTest -Test $test -Database $Database -LogsPath $LogsPath
7477
}
7578

7679
# Run Parallel Tests
7780
if ($parallelTests) {
78-
$workflow = Start-ZtTestExecution -Tests $parallelTests -DbPath $Database.Database -ThrottleLimit $ThrottleLimit
81+
$workflow = Start-ZtTestExecution -Tests $parallelTests -DbPath $Database.Database -ThrottleLimit $ThrottleLimit -LogsPath $LogsPath
7982
Wait-ZtTest -Workflow $workflow
8083
}
8184
}

‎src/powershell/private/tests/Start-ZtTestExecution.ps1‎

Lines changed: 6 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -35,13 +35,17 @@
3535
$DbPath,
3636

3737
[int]
38-
$ThrottleLimit = 5
38+
$ThrottleLimit = 5,
39+
40+
[string]
41+
$LogsPath
3942
)
4043
begin {
4144
#region Calculate Resources to Import
4245
$variables = @{
4346
databasePath = $DbPath
4447
moduleRoot = $script:ModuleRoot
48+
logsPath = $LogsPath
4549
}
4650
# Explicitly including all modules required, as we later import the psm1, not the psd1 file
4751
$modulePsd1Path = Join-Path $script:ModuleRoot "$($PSCmdlet.MyInvocation.MyCommand.Module.Name).psd1"
@@ -83,7 +87,7 @@
8387
$script:ModuleRoot = $moduleRoot
8488
$global:database = Connect-Database -Path $databasePath -PassThru
8589
} -ScriptBlock {
86-
Invoke-ZtTest -Test $_ -Database $global:database
90+
Invoke-ZtTest -Test $_ -Database $global:database -LogsPath $logsPath
8791
} -End {
8892
Disconnect-Database -Database $global:database
8993
}

‎src/powershell/private/tests/Write-ZtTestLog.ps1‎

Lines changed: 84 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,84 @@
1+
function Write-ZtTestLog {
2+
<#
3+
.SYNOPSIS
4+
Writes a per-test log file with execution summary and PSFramework messages.
5+
6+
.DESCRIPTION
7+
Writes a per-test log file with execution summary and PSFramework messages.
8+
Each test gets its own <TestID>.md file under the logs folder, making it
9+
easy to debug individual test executions in parallel runs.
10+
11+
The log file contains a header block with test metadata (ID, title, status,
12+
duration, timing, errors) followed by timestamped message lines.
13+
14+
.PARAMETER Result
15+
The test execution statistics object (ZeroTrustAssessment.TestStatistics).
16+
17+
.PARAMETER LogsPath
18+
Path to the logs folder. If empty or null, the function is a no-op.
19+
20+
.EXAMPLE
21+
PS C:\> Write-ZtTestLog -Result $result -LogsPath $logsPath
22+
23+
Writes the full test log for the completed test to <LogsPath>/<TestID>.md.
24+
#>
25+
[CmdletBinding()]
26+
param (
27+
[Parameter(Mandatory = $true)]
28+
$Result,
29+
30+
[string]
31+
$LogsPath
32+
)
33+
process {
34+
if (-not $LogsPath) { return }
35+
36+
try {
37+
[void][System.IO.Directory]::CreateDirectory($LogsPath)
38+
39+
$testId = $Result.TestID
40+
$title = $Result.Test.Title
41+
$status = if ($Result.Success) { 'Pass' } else { 'Fail' }
42+
$duration = if ($null -ne $Result.Duration) { $Result.Duration.ToString('hh\:mm\:ss\.fff') } else { 'N/A' }
43+
$startTime = if ($Result.Start) { $Result.Start.ToString('yyyy-MM-dd HH:mm:ss.fff') } else { 'N/A' }
44+
$endTime = if ($Result.End) { $Result.End.ToString('yyyy-MM-dd HH:mm:ss.fff') } else { 'N/A' }
45+
46+
$lines = [System.Collections.Generic.List[string]]::new()
47+
$lines.Add("# Test: $testId - $title")
48+
$lines.Add("# Status: $status")
49+
$lines.Add("# Duration: $duration")
50+
$lines.Add("# Start: $startTime")
51+
$lines.Add("# End: $endTime")
52+
if (-not $Result.Success -and $Result.Error) {
53+
$errorText = "$($Result.Error)"
54+
$lines.Add("# Error: $errorText")
55+
}
56+
$lines.Add('# ---')
57+
58+
if ($Result.Messages) {
59+
foreach ($msg in $Result.Messages) {
60+
$timestamp = 'N/A'
61+
if ($null -ne $msg.Timestamp) {
62+
try {
63+
$timestamp = ([datetime]$msg.Timestamp).ToString('yyyy-MM-dd HH:mm:ss.fff')
64+
}
65+
catch {
66+
$timestamp = "$($msg.Timestamp)"
67+
}
68+
}
69+
70+
$level = if ($null -ne $msg.Level) { "$($msg.Level)" } else { 'Info' }
71+
$text = if ($null -ne $msg.LogMessage) { "$($msg.LogMessage)" } else { '' }
72+
$lines.Add("$timestamp [$level] $text")
73+
}
74+
}
75+
76+
$logMarkdownPath = Join-Path $LogsPath "$testId.md"
77+
[System.IO.File]::WriteAllLines($logMarkdownPath, $lines)
78+
}
79+
catch {
80+
$errorMessage = if ($null -ne $_.Exception -and $null -ne $_.Exception.Message) { $_.Exception.Message } else { 'Unknown error while writing test log.' }
81+
Write-PSFMessage -Level Warning -Message "Failed to write test log for test '{0}': {1}" -StringValues $Result.TestID, $errorMessage -Tag log
82+
}
83+
}
84+
}

‎src/powershell/private/tests/Write-ZtTestProgress.ps1‎

Lines changed: 128 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,128 @@
1+
function Write-ZtTestProgress {
2+
<#
3+
.SYNOPSIS
4+
Appends a progress entry to the overall test execution progress log.
5+
6+
.DESCRIPTION
7+
Appends a single line to _progress.log in the logs folder, recording when
8+
each test starts, completes, or fails. This append-only log provides an
9+
at-a-glance timeline of all test executions and makes it easy to identify
10+
hanging tests (STARTED without a matching COMPLETED/FAILED line).
11+
12+
Uses a per-file named mutex plus [System.IO.File]::AppendAllText to
13+
serialize writes from parallel runspaces/processes and keep each entry
14+
on a single line.
15+
16+
.PARAMETER TestID
17+
The test ID to log progress for.
18+
19+
.PARAMETER LogsPath
20+
Path to the logs folder. If empty or null, the function is a no-op.
21+
22+
.PARAMETER Action
23+
The progress action: Started, Completed, or Failed.
24+
25+
.PARAMETER Duration
26+
The test duration (for Completed/Failed actions).
27+
28+
.PARAMETER ErrorMessage
29+
The error message (for Failed actions).
30+
31+
.EXAMPLE
32+
PS C:\> Write-ZtTestProgress -TestID 25384 -LogsPath $logsPath -Action Started
33+
34+
Appends a STARTED line for test 25384 to the progress log.
35+
36+
.EXAMPLE
37+
PS C:\> Write-ZtTestProgress -TestID 25384 -LogsPath $logsPath -Action Completed -Duration $result.Duration
38+
39+
Appends a COMPLETED line for test 25384 to the progress log.
40+
#>
41+
[CmdletBinding()]
42+
param (
43+
[Parameter(Mandatory = $true)]
44+
$TestID,
45+
46+
[string]
47+
$LogsPath,
48+
49+
[Parameter(Mandatory = $true)]
50+
[ValidateSet('Started', 'Completed', 'Failed')]
51+
[string]
52+
$Action,
53+
54+
[timespan]
55+
$Duration,
56+
57+
$ErrorMessage
58+
)
59+
process {
60+
if (-not $LogsPath) { return }
61+
62+
try {
63+
[void][System.IO.Directory]::CreateDirectory($LogsPath)
64+
65+
$timestamp = (Get-Date).ToString('yyyy-MM-dd HH:mm:ss.fff')
66+
$actionPadded = $Action.ToUpper().PadRight(10)
67+
68+
$line = "$timestamp $actionPadded $TestID"
69+
if ($null -ne $Duration) {
70+
$line += " $($Duration.ToString('hh\:mm\:ss\.fff'))"
71+
}
72+
if ($Action -eq 'Completed') {
73+
$line += ' Pass'
74+
}
75+
if ($Action -eq 'Failed' -and $ErrorMessage) {
76+
$errorText = "$ErrorMessage"
77+
$errorText = $errorText -replace '[\r\n\t]+', ' '
78+
if ($errorText.Length -gt 1000) {
79+
$errorText = $errorText.Substring(0, 1000) + '...'
80+
}
81+
$line += " $errorText"
82+
}
83+
$line += [System.Environment]::NewLine
84+
85+
$progressFilePath = Join-Path $LogsPath '_progress.log'
86+
$fullPath = [System.IO.Path]::GetFullPath($progressFilePath)
87+
$normalizedPath = if ($IsWindows) { $fullPath.ToLowerInvariant() } else { $fullPath }
88+
89+
# Cache the mutex name per resolved path to avoid repeated SHA256 hashing
90+
if (-not $script:ZtProgressMutexCache) {
91+
$script:ZtProgressMutexCache = @{}
92+
}
93+
if ($script:ZtProgressMutexCache.ContainsKey($normalizedPath)) {
94+
$mutexName = $script:ZtProgressMutexCache[$normalizedPath]
95+
}
96+
else {
97+
$pathBytes = [System.Text.Encoding]::UTF8.GetBytes($normalizedPath)
98+
$pathHashBytes = [System.Security.Cryptography.SHA256]::HashData($pathBytes)
99+
$pathHash = [System.BitConverter]::ToString($pathHashBytes).Replace('-', '')
100+
$mutexName = "Local\ZtProgress_$pathHash"
101+
$script:ZtProgressMutexCache[$normalizedPath] = $mutexName
102+
}
103+
104+
$mutex = $null
105+
$lockAcquired = $false
106+
try {
107+
$mutex = [System.Threading.Mutex]::new($false, $mutexName)
108+
$lockAcquired = $mutex.WaitOne([TimeSpan]::FromSeconds(5))
109+
if (-not $lockAcquired) {
110+
throw "Timed out waiting for progress log mutex '$mutexName'."
111+
}
112+
113+
[System.IO.File]::AppendAllText($fullPath, $line)
114+
}
115+
finally {
116+
if ($lockAcquired -and $null -ne $mutex) {
117+
$null = $mutex.ReleaseMutex()
118+
}
119+
if ($null -ne $mutex) {
120+
$mutex.Dispose()
121+
}
122+
}
123+
}
124+
catch {
125+
Write-PSFMessage -Level Warning -Message "Failed to write progress log for test '{0}': {1}" -StringValues $TestID, $_.Exception.Message -Tag log
126+
}
127+
}
128+
}

‎src/powershell/public/Invoke-ZtAssessment.ps1‎

Lines changed: 7 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -351,6 +351,12 @@ function Invoke-ZtAssessment {
351351
New-Item -ItemType Directory -Path $exportPath -Force -ErrorAction Stop | Out-Null
352352
}
353353

354+
# Create the logs folder for per-test log files
355+
# Use .FullName to get the absolute path because .NET file APIs ([System.IO.File]::WriteAllText etc.)
356+
# resolve relative paths against [Environment]::CurrentDirectory (process CWD), which
357+
# differs from PowerShell's Get-Location after Set-Location / cd.
358+
$logsPath = (New-Item -ItemType Directory -Path (Join-Path $exportPath 'logs') -Force -ErrorAction Stop).FullName
359+
354360

355361
# Send telemetry if not disabled
356362
if (-not $DisableTelemetry) {
@@ -392,7 +398,7 @@ function Invoke-ZtAssessment {
392398

393399
# Run the tests
394400
Write-PSFMessage -Message "Stage 2: Running Tests" -Tag stage
395-
Invoke-ZtTests -Database $database -Tests $Tests -Pillar $Pillar -ThrottleLimit $TestThrottleLimit
401+
Invoke-ZtTests -Database $database -Tests $Tests -Pillar $Pillar -ThrottleLimit $TestThrottleLimit -LogsPath $logsPath
396402
Write-PSFMessage -Message "Stage 3: Adding Tenant Information" -Tag stage
397403
Invoke-ZtTenantInfo -Database $database -Pillar $Pillar
398404

0 commit comments

Comments
 (0)