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', '