From f18046a325ff03b512ed2d8accfc63c0a075fff5 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Jakub=20Jare=C5=A1?= Date: Thu, 9 Jul 2026 23:46:27 +0200 Subject: [PATCH] Replay parallel worker debug output interleaved with tests Debug output (Debug.WriteDebugMessages, enabled e.g. by Output.Verbosity = 'Diagnostic') was written straight to the host by each parallel worker as it ran, so it appeared up front, detached from the test that produced it. Capture host/debug output into the same event tape the recorder already uses and replay it in tape order from the parent. Each worker runs one file synchronously, so append order is the correct order and the debug lines land interleaved with the per-test output they belong to. - Output.ps1: Write-PesterHostMessage appends to the worker's tape (script-scoped parallelOutputTape) instead of writing live. - Pester.Parallel.ps1: point the tape at the recorder's list and split the tape positionally at ContainerDiscoveryEnd so host entries stay in the phase they were produced in. - Main.ps1: replay host entries (Step = $null) to the real host and drop the warning this branch previously added. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> --- src/Main.ps1 | 8 ++++ src/functions/Output.ps1 | 17 +++++++ src/functions/Pester.Parallel.ps1 | 26 +++++++--- tst/Pester.RSpec.Parallel.ts.ps1 | 79 +++++++++++++++++++++++++++++++ 4 files changed, 123 insertions(+), 7 deletions(-) diff --git a/src/Main.ps1 b/src/Main.ps1 index 5827ab61e..a1c7dfdd0 100644 --- a/src/Main.ps1 +++ b/src/Main.ps1 @@ -686,6 +686,14 @@ function Invoke-Pester { $replaySegment = { param($entries) foreach ($entry in $entries) { + # Host/debug output captured in the worker carries no Step - replay it to the + # real host now, in tape order, so it lands interleaved with the per-test output + # it belongs to instead of appearing up front, detached from its test (#2825). + if ($null -eq $entry.Step) { + $hostArgs = $entry.Host + Write-PesterHostMessage @hostArgs + continue + } if ($entry.Context -is [System.Collections.IDictionary] -and $entry.Context.Contains('Configuration')) { $entry.Context['Configuration'] = $pluginConfiguration } diff --git a/src/functions/Output.ps1 b/src/functions/Output.ps1 index d9a9272cd..3bfc045f4 100644 --- a/src/functions/Output.ps1 +++ b/src/functions/Output.ps1 @@ -125,6 +125,23 @@ function Write-PesterHostMessage { } process { + # In a parallel worker the whole run is silenced (Output.Verbosity = 'None') and its output is + # captured into the shared event tape (see Invoke-TestInParallel) so the parent can replay it in + # order. Instead of writing to the host right away - which in a ForEach-Object -Parallel runspace + # surfaces live and detached from the test that produced it (#2825) - append the message to the + # tape. The worker runs one file synchronously, so append order already is the correct order, and + # host/debug entries land interleaved with the per-test steps the recorder captured around them. + # Read the tape via GetValue (not the 'defined' helper): 'defined' returns the value through a + # function output, which enumerates a collection and would hand back its first element instead of + # the list itself. GetValue returns the list object and tolerates the variable being unset ($null). + $parallelOutputTape = $ExecutionContext.SessionState.PSVariable.GetValue('parallelOutputTape') + if ($null -ne $parallelOutputTape) { + $captured = @{} + foreach ($k in $PSBoundParameters.Keys) { $captured[$k] = $PSBoundParameters[$k] } + $null = $parallelOutputTape.Add([PSCustomObject]@{ Step = $null; Host = $captured }) + return + } + if (-not $HostSupportsOutput) { return } if ($RenderMode -eq 'Ansi') { diff --git a/src/functions/Pester.Parallel.ps1 b/src/functions/Pester.Parallel.ps1 index f55bcd5c8..d4509c56b 100644 --- a/src/functions/Pester.Parallel.ps1 +++ b/src/functions/Pester.Parallel.ps1 @@ -94,22 +94,29 @@ function Split-PesterEventTape { DiscoveryEnd/RunStart steps at the right moment, the parent needs the per-container steps grouped by phase: everything up to and including ContainerDiscoveryEnd is discovery, the rest (ContainerRunStart onward) is the run. + + The tape may also carry host/debug output entries (Step = $null) captured while the file ran. + Splitting positionally at ContainerDiscoveryEnd - rather than by step name - keeps each of those + entries in the phase it was produced in, so debug written during discovery replays with discovery + and debug written during the run replays interleaved with the tests. #> [CmdletBinding()] param( [object[]] $Tape ) - $discoverySteps = @('ContainerDiscoveryStart', 'BlockDiscoveryStart', 'TestDiscoveryStart', 'TestDiscoveryEnd', 'BlockDiscoveryEnd', 'ContainerDiscoveryEnd') $discovery = [System.Collections.Generic.List[object]]@() $run = [System.Collections.Generic.List[object]]@() + $inRun = $false foreach ($entry in $Tape) { - if ($discoverySteps -contains $entry.Step) { - $discovery.Add($entry) - } - else { + if ($inRun) { $run.Add($entry) + continue + } + $discovery.Add($entry) + if ('ContainerDiscoveryEnd' -eq $entry.Step) { + $inRun = $true } } @@ -292,13 +299,18 @@ function Invoke-TestInParallel { New-PluginObject @h } $tape $recordedSteps - # Inject the recorder via the supported additional-plugins channel, run, then clear it. + # Inject the recorder via the supported additional-plugins channel and point the module's + # parallel output tape at the same list, so both the recorded plugin steps and any host/debug + # output the run writes are appended to one ordered tape. Run, then clear both. The tape is + # wrapped in a hashtable when handed across the module boundary: passing the (still empty) list + # positionally coerces it to a fixed-size array, which then throws on .Add during the run. & $pesterModule { param($p) $script:additionalPlugins = $p } $recorder + & $pesterModule { param($box) $script:parallelOutputTape = $box.Tape } @{ Tape = $tape } try { $out = Invoke-Pester -Configuration $workerConfig } finally { - & $pesterModule { $script:additionalPlugins = $null } + & $pesterModule { $script:additionalPlugins = $null; $script:parallelOutputTape = $null } } $runObject = $null diff --git a/tst/Pester.RSpec.Parallel.ts.ps1 b/tst/Pester.RSpec.Parallel.ts.ps1 index cba4a81bf..5e39f906b 100644 --- a/tst/Pester.RSpec.Parallel.ts.ps1 +++ b/tst/Pester.RSpec.Parallel.ts.ps1 @@ -568,4 +568,83 @@ Describe 'OuterTwo' { finally { Remove-Item -Path $folder -Recurse -Force } } } + + b "Run.Parallel debug output" { + t "captures debug output and replays it interleaved with each file's tests" { + # Each worker runs silently and records its screen and debug output into the shared tape; + # the parent replays that tape in order. So debug output must come back interleaved with the + # per-test output of the file that produced it, not dumped up front detached from it (#2825). + $folder = Join-Path ([IO.Path]::GetTempPath()) ([Guid]::NewGuid().Guid) + $null = New-Item -ItemType Directory -Path $folder -Force + try { + Set-Content -Path (Join-Path $folder 'A.Tests.ps1') -Value @' +Describe 'A' { It 'a1 passes' { 1 | Should -Be 1 } } +'@ + Set-Content -Path (Join-Path $folder 'B.Tests.ps1') -Value @' +Describe 'B' { It 'b1 passes' { 1 | Should -Be 1 } } +'@ + $c = [PesterConfiguration]::Default + $c.Run.Path = $folder + $c.Run.Parallel = $true + $c.Run.PassThru = $true + $c.Output.Verbosity = 'Diagnostic' + $c.Output.RenderMode = 'Plaintext' + + # 6>&1 folds the host output (written as information records) into the pipeline so we can + # replay it exactly as it was rendered; the Pester.Run object comes out alongside it. + $out = Invoke-Pester -Configuration $c 3>$null 6>&1 + $r = @($out).Where({ $_ -is [Pester.Run] })[0] + + # The run still executes in parallel and produces correct results. + $r.PassedCount | Verify-Equal 2 + + # PowerShell 5.1 has no ForEach-Object -Parallel and falls back to a sequential run whose + # output differs, so only assert the exact parallel rendering on 7+. + if ($PSVersionTable.PSVersion.Major -ge 7) { + # Rebuild the console text from the captured Write-Host records (honouring -NoNewline), + # then blank out the volatile version, temp paths and timings so the snapshot is stable. + $sb = [System.Text.StringBuilder]::new() + foreach ($rec in @($out)) { + if ($rec -isnot [System.Management.Automation.InformationRecord]) { continue } + $md = $rec.MessageData + if ($md -is [System.Management.Automation.HostInformationMessage]) { + $null = $sb.Append($md.Message) + if (-not $md.NoNewLine) { $null = $sb.Append("`n") } + } + } + $normalized = $sb.ToString() ` + -replace 'Pester v\S+', 'Pester v' ` + -replace ([regex]::Escape($folder + [IO.Path]::DirectorySeparatorChar)), '' ` + -replace '\d+ ms', '