From deb35d9b696a6466095feb416ed4077864be3d35 Mon Sep 17 00:00:00 2001 From: Colin Neilens Date: Mon, 26 Oct 2026 22:35:47 -0700 Subject: [PATCH] Fix numbered journal validation deadline Keep the one-second Open/Copy/retry budget separate from the caller cleanup deadline after immutable bytes are copied. Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com> Signed-off-by: Colin Neilens --- Tools/windows/Tests/UiCaptureDriver.Tests.ps1 | 157 ++++++++++++++++-- Tools/windows/UI-CAPTURE-SCENARIOS.md | 17 ++ Tools/windows/UiCaptureDriver.psm1 | 67 +++++--- 3 files changed, 211 insertions(+), 30 deletions(-) diff --git a/Tools/windows/Tests/UiCaptureDriver.Tests.ps1 b/Tools/windows/Tests/UiCaptureDriver.Tests.ps1 index 26fa8aa4..021dec00 100644 --- a/Tools/windows/Tests/UiCaptureDriver.Tests.ps1 +++ b/Tools/windows/Tests/UiCaptureDriver.Tests.ps1 @@ -5019,13 +5019,13 @@ function Invoke-CapJournalTimingContract { $verified[0].copyElapsedMilliseconds -eq $transaction.CopyElapsedMilliseconds -and $verified[0].totalElapsedMilliseconds -ge 0) ` 'Existing post-verification observation lacks the actual Open/Copy accumulator values.' + $ioElapsed = $transaction.IoClock.Elapsed.TotalMilliseconds Start-Sleep -Milliseconds 1050 - $failure = Assert-CapRejects { - & $module { param($Transaction) Assert-CapJournalTime $Transaction 1 } $transaction - } 'JournalUnavailable' - Assert-CapTest ($failure -match 'openMs=[0-9]' -and $failure -match 'copyMs=[0-9]' -and - $failure -match 'totalMs=[0-9]' -and $transaction.BudgetMilliseconds -eq 1000 -and $transaction.Retries -eq 0) ` - 'Deadline message lost actual phases or changed the original timing/retry contract.' + & $module { param($Transaction) Assert-CapJournalTime $Transaction 1 -Io } $transaction + Assert-CapTest (-not $transaction.IoClock.IsRunning -and + $transaction.IoClock.Elapsed.TotalMilliseconds -eq $ioElapsed -and + $transaction.BudgetMilliseconds -eq 1000 -and $transaction.Retries -eq 0) ` + 'Post-copy CPU time was still charged to the completed I/O phase.' $missing = & $module { param($State) New-CapJournalTransaction $State } $state $null = Assert-CapRejects { & $module { param($State,$Transaction) Read-CapJournalObject $State 2 $Transaction } $state $missing @@ -5488,8 +5488,15 @@ function Invoke-CapFirstOpenGroups { [pscustomobject]@{ Transaction = $transaction; Read = $read } } $state Assert-CapTest ($proof.Read.Reference.length -gt 0 -and $proof.Transaction.BudgetMilliseconds -gt 0 -and - $proof.Transaction.BudgetMilliseconds -lt 750 -and $proof.Transaction.DeadlineUtc -le $state.DeadlineUtc) ` - 'First Open did not clip its I/O budget to the absolute deadline.' + $proof.Transaction.BudgetMilliseconds -lt 750 -and + $proof.Transaction.DeadlineUtc -eq $state.DeadlineUtc -and + $proof.Transaction.IoDeadlineUtc -le $proof.Transaction.DeadlineUtc) ` + 'First Open did not separate its clipped I/O budget from the absolute deadline.' @{ + budgetMilliseconds = $proof.Transaction.BudgetMilliseconds + transactionDeadlineUtc = $proof.Transaction.DeadlineUtc + stateDeadlineUtc = $state.DeadlineUtc + ioDeadlineUtc = $proof.Transaction.IoDeadlineUtc + } Start-Sleep -Milliseconds 800 $null = Assert-CapRejects { & (Get-Module UiCaptureDriver) { param($State,$Transaction) Read-CapJournalObject $State 1 $Transaction } $state $proof.Transaction @@ -5513,16 +5520,144 @@ function Invoke-CapFirstOpenGroups { 'Final manifest lost its creation-started 1000ms budget or attempted a late Open.' $manifestState.ObservationPath = $manifestState.Directory try { - & (Get-Module UiCaptureDriver) { param($Transaction) Assert-CapJournalTime $Transaction 1 } $manifestTransaction + & (Get-Module UiCaptureDriver) { + param($Transaction) Assert-CapJournalTime $Transaction 1 -Io + } $manifestTransaction throw 'Expired manifest unexpectedly passed with an unavailable observation sink.' } catch { Assert-CapTest ($_.Exception.Data['CapJournalFailure'] -ceq 'JournalUnavailable' -and $_.Exception.Data.Contains('CapJournalObservationFailure')) ` 'Failure observation masked the primary JournalUnavailable instead of retaining a secondary diagnostic.' } - return @{ subcases = 4; delayMilliseconds = $delay.Elapsed.TotalMilliseconds + + $large = New-JournalContractContext 'terminal-post-copy-cpu' + $processes = @( + foreach ($index in 1..679) { + [pscustomobject]@{ + pid = [long](10000 + $index); creationFileTimeUtc = [long](20000 + $index) + expectedImagePath = 'C:\fixture\' + ('x' * 1150) + "\process-$index.exe" + role = "terminal-process-$index"; parentPid = 1L; sessionId = 1L + kernelExited = $true; stdoutEof = $true; stderrEof = $true + streamOwnerPid = [long](10000 + $index) + streamOwnerCreationFileTimeUtc = [long](20000 + $index) + } + } + ) + $entries = @( + foreach ($process in $processes) { + [pscustomobject]@{ + pid = $process.pid; creationFileTimeUtc = $process.creationFileTimeUtc + role = $process.role; expectedImagePath = $process.expectedImagePath + expectedParentPid = $process.parentPid; expectedSessionId = $process.sessionId + } + } + ) + $bootstrap = [pscustomobject]@{ entries = @(); ownedProcesses = @(); outcome = 'COMPLETE' + ownedProcessSurvivors = @(); pendingLaunchesRemaining = @(); cleanupFailures = @() } + $terminalData = [pscustomobject]@{ entries = $entries; ownedProcesses = $processes; outcome = 'COMPLETE' + ownedProcessSurvivors = @(); pendingLaunchesRemaining = @(); cleanupFailures = @() } + $null = Publish-CapJournalSnapshot $large.State Bootstrap $bootstrap + $largeTerminal = Publish-CapJournalSnapshot $large.State Terminal $terminalData + Assert-CapTest ($largeTerminal.length -gt 1480000 -and $entries.Count -eq 679 -and + $processes.Count -eq 679) 'Large terminal fixture did not reproduce the official journal scale.' @{ + terminalBytes = $largeTerminal.length; entries = $entries.Count; processes = $processes.Count + } + $largeOutput = Join-Path $large.Root 'output' + $null = New-Item -ItemType Directory -Path $largeOutput + $largeManifest = [pscustomobject]@{ + status = 'COMPLETE'; ownedProcesses = $processes; ownedProcessSurvivors = @() + pendingLaunchesRemaining = @(); cleanupFailures = @() + journal = [pscustomobject]@{ + protocolVersion = 2L; binding = $large.Binding; directory = $large.State.Directory + terminal = $largeTerminal; published = @($large.State.Published.ToArray()) + } + } + $largeManifestReference = Write-CapImmutableJson -Root $large.Root ` + -Path (Join-Path $largeOutput 'manifest.json') -Value $largeManifest + $largeRecord = Read-CapJournalFinalRecord ` + (Format-CapJournalFinalRecord $large.Binding $largeManifestReference $largeTerminal) $large.Binding + $module = Get-Module UiCaptureDriver + $originalDecoder = & $module { (Get-Item Function:ConvertFrom-CapJournalBytes).ScriptBlock } + try { + & $module { + param($Original,$TargetLength) + $script:CapPostCopyOriginalDecoder = $Original + $script:CapPostCopyTargetLength = $TargetLength + Set-Item Function:ConvertFrom-CapJournalBytes -Value { + param([byte[]]$Bytes) + if ($Bytes.Length -eq $script:CapPostCopyTargetLength) { + Start-Sleep -Milliseconds 1200 + } + & $script:CapPostCopyOriginalDecoder -Bytes $Bytes + } + } $originalDecoder $largeTerminal.length + $cpuClock = [Diagnostics.Stopwatch]::StartNew() + $largeProof = Read-CapJournalFinalProof -State $large.State -OutputDirectory $largeOutput -Record $largeRecord + $cpuClock.Stop() + Assert-CapTest ($largeProof.HashChainVerified -and + $largeProof.Manifest.ownedProcesses.Count -eq 679 -and + $cpuClock.Elapsed.TotalMilliseconds -gt 1000) ` + 'Copied immutable terminal bytes did not retain the hard deadline through post-copy validation.' @{ + terminalBytes = $largeTerminal.length; processEntries = $processes.Count + elapsedMilliseconds = $cpuClock.Elapsed.TotalMilliseconds + } + + $hardReader = New-CapJournalState -Root $large.Root -Directory $large.State.Directory ` + -Binding $large.Binding -DeadlineUtc ([DateTime]::UtcNow.AddMilliseconds(800)) + & $module { + $script:CapPostCopyDelayMilliseconds = 1200 + Set-Item Function:ConvertFrom-CapJournalBytes -Value { + param([byte[]]$Bytes) + if ($Bytes.Length -eq $script:CapPostCopyTargetLength) { + Start-Sleep -Milliseconds $script:CapPostCopyDelayMilliseconds + } + & $script:CapPostCopyOriginalDecoder -Bytes $Bytes + } + } + $hardFailure = Assert-CapRejects { + Read-CapJournalFinalProof -State $hardReader -OutputDirectory $largeOutput -Record $largeRecord + } 'JournalUnavailable' + Assert-CapTest ($hardFailure.Contains('hard deadline/exhaustion')) ` + 'Post-copy validation did not retain the absolute caller deadline refusal.' $hardFailure + } finally { + & $module { + param($Original) + Set-Item Function:ConvertFrom-CapJournalBytes -Value $Original + Remove-Variable CapPostCopyOriginalDecoder,CapPostCopyTargetLength,CapPostCopyDelayMilliseconds ` + -Scope Script -ErrorAction SilentlyContinue + } $originalDecoder + } + + $ioState = New-CapFirstOpenContext 'copy-over-io-budget' + $originalReader = & $module { (Get-Item Function:Read-CapJournalObject).ScriptBlock } + $copyNeedle = '$stream.CopyTo($buffer); $bytes = $buffer.ToArray()' + Assert-CapTest ([regex]::Matches($originalReader.ToString(), [regex]::Escape($copyNeedle)).Count -eq 1) ` + 'Copy deadline seam requires exactly one production CopyTo expression.' + $slowCopyReader = [scriptblock]::Create($originalReader.ToString().Replace( + $copyNeedle, 'Start-Sleep -Milliseconds 1100; $stream.CopyTo($buffer); $bytes = $buffer.ToArray()')) + try { + & $module { param($Body) Set-Item Function:Read-CapJournalObject -Value $Body } $slowCopyReader + $ioTransaction = & $module { param($State) New-CapJournalTransaction $State } $ioState + $ioFailure = Assert-CapRejects { + & $module { + param($State,$Transaction) Read-CapJournalObject $State 1 $Transaction + } $ioState $ioTransaction + } 'JournalUnavailable' + Assert-CapTest ($ioFailure.Contains('I/O deadline/exhaustion') -and + $ioTransaction.CopyElapsedMilliseconds -ge 1000) ` + 'An over-one-second copy did not retain the fixed I/O refusal.' @{ + failure = $ioFailure; copyMilliseconds = $ioTransaction.CopyElapsedMilliseconds + } + } finally { + & $module { param($Body) Set-Item Function:Read-CapJournalObject -Value $Body } $originalReader + } + + return @{ subcases = 7; delayMilliseconds = $delay.Elapsed.TotalMilliseconds preOpenRefusal = $failure; manifestRefusal = $manifestFailure - clippedBudgetMilliseconds = $proof.Transaction.BudgetMilliseconds } + clippedBudgetMilliseconds = $proof.Transaction.BudgetMilliseconds + terminalBytes = $largeTerminal.length; terminalProcesses = $processes.Count + postCopyValidationMilliseconds = $cpuClock.Elapsed.TotalMilliseconds + hardDeadlineRefusal = $hardFailure; ioDeadlineRefusal = $ioFailure } } } diff --git a/Tools/windows/UI-CAPTURE-SCENARIOS.md b/Tools/windows/UI-CAPTURE-SCENARIOS.md index 6d8f99f8..4e40f81d 100644 --- a/Tools/windows/UI-CAPTURE-SCENARIOS.md +++ b/Tools/windows/UI-CAPTURE-SCENARIOS.md @@ -95,6 +95,23 @@ cleanup evidence. The correction adds no capture scenes or top-level preflight group, so the registered totals remain **182 default / 185 with `-RequireRealSeed`**. +The numbered reader keeps that one-second budget specifically around Open, +Copy and retry waits. After immutable bytes have copied within the I/O budget, +the I/O clock stops; UTF-8/JSON decode, payload hash and schema checks, complete +terminal inventory validation, and final manifest binding remain bounded by the +unchanged absolute caller or cleanup deadline. A later numbered Open resumes the +same accumulated I/O clock with only its remaining budget, so post-copy CPU time +cannot create a false `JournalUnavailable` and cannot grant another second of +I/O. + +The focused contract reproduces the C8R terminal scale with exactly 679 process +entries and a numbered terminal larger than 1.48 MB, then injects more than one +second of post-copy validation. It also retains explicit refusals for a copy +that exceeds the one-second I/O budget and for post-copy validation that exceeds +the hard caller deadline. This tooling repair does not alter the frozen failed +lease or promote its result: that run remains `CLEANUP_UNPROVEN` / `UNPROVEN`, +and another official capture still requires separate renewed authorization. + An owned journal actor can exit after the worker publishes its generation but before the supervisor opens a retained handle. The supervisor defers only the exact typed initial-handle race when the recorded PID is unchanged and current diff --git a/Tools/windows/UiCaptureDriver.psm1 b/Tools/windows/UiCaptureDriver.psm1 index 3cd06da3..ddbe685e 100644 --- a/Tools/windows/UiCaptureDriver.psm1 +++ b/Tools/windows/UiCaptureDriver.psm1 @@ -5143,9 +5143,12 @@ function New-CapJournalTransaction { $createdUtc = [DateTime]::UtcNow $clock = [Diagnostics.Stopwatch]::StartNew() $remaining = [Math]::Max(0, [Math]::Min(1000.0, ($State.DeadlineUtc - $createdUtc).TotalMilliseconds)) + $ioDeadlineUtc = $createdUtc.AddMilliseconds($remaining) + if ($ioDeadlineUtc -gt $State.DeadlineUtc) { $ioDeadlineUtc = $State.DeadlineUtc } return [pscustomobject]@{ CreatedUtc = $createdUtc - DeadlineUtc = if ($ManifestBudget) { $createdUtc.AddMilliseconds($remaining) } else { $State.DeadlineUtc } + DeadlineUtc = $State.DeadlineUtc + IoDeadlineUtc = if ($ManifestBudget) { $ioDeadlineUtc } else { $null } Clock = $clock IoClock = if ($ManifestBudget) { $clock } else { $null } BudgetMilliseconds = if ($ManifestBudget) { $remaining } else { 1000.0 } @@ -5177,12 +5180,15 @@ function Format-CapJournalPhaseTiming { } function Assert-CapJournalTime { - param($Transaction, [long]$Sequence, [AllowNull()][string]$NativeError = $null) - if ([DateTime]::UtcNow -ge $Transaction.DeadlineUtc -or - ($null -ne $Transaction.IoClock -and - $Transaction.IoClock.Elapsed.TotalMilliseconds -ge $Transaction.BudgetMilliseconds)) { + param($Transaction, [long]$Sequence, [AllowNull()][string]$NativeError = $null, [switch]$Io) + $hardExhausted = [DateTime]::UtcNow -ge $Transaction.DeadlineUtc + $ioExhausted = $Io -and $null -ne $Transaction.IoClock -and ( + ($Transaction.IoClock.IsRunning -and [DateTime]::UtcNow -ge $Transaction.IoDeadlineUtc) -or + $Transaction.IoClock.Elapsed.TotalMilliseconds -ge $Transaction.BudgetMilliseconds) + if ($hardExhausted -or $ioExhausted) { + $deadlineClass = if ($hardExhausted) { 'hard deadline/exhaustion' } else { 'I/O deadline/exhaustion' } $failure = New-CapJournalFailure 'JournalUnavailable' ( - "sequence=$Sequence HRESULT=$NativeError retries=$($Transaction.Retries); deadline/exhaustion, no late success. $(Format-CapJournalPhaseTiming $Transaction)") + "sequence=$Sequence HRESULT=$NativeError retries=$($Transaction.Retries); $deadlineClass, no late success. $(Format-CapJournalPhaseTiming $Transaction)") try { $attempt = if ($Transaction.Attempts.ContainsKey($Sequence)) { $Transaction.Attempts[$Sequence] } else { 0 } Write-CapJournalObservation $Transaction.ObservationState $Sequence $attempt 'DeadlineExhausted' $NativeError $Transaction @@ -5198,7 +5204,7 @@ function Read-CapJournalObject { param($State, [long]$Sequence, $Transaction, [switch]$Advance, [switch]$RetainStream) $native = $null while ($true) { - Assert-CapJournalTime $Transaction $Sequence $native + Assert-CapJournalTime $Transaction $Sequence $native -Io if (-not $Transaction.Attempts.ContainsKey($Sequence)) { $Transaction.Attempts[$Sequence] = 0 } if ($Transaction.Attempts[$Sequence] -ge 8) { throw (New-CapJournalFailure 'JournalUnavailable' "sequence=$Sequence HRESULT=$native; eight Open attempts. $(Format-CapJournalPhaseTiming $Transaction)") @@ -5211,11 +5217,23 @@ function Read-CapJournalObject { $now = [DateTime]::UtcNow $Transaction.BudgetMilliseconds = [Math]::Max(0, [Math]::Min(1000.0, ($Transaction.DeadlineUtc - $now).TotalMilliseconds)) - $ioDeadline = $now.AddMilliseconds($Transaction.BudgetMilliseconds) - if ($ioDeadline -lt $Transaction.DeadlineUtc) { $Transaction.DeadlineUtc = $ioDeadline } + $Transaction.IoDeadlineUtc = $now.AddMilliseconds($Transaction.BudgetMilliseconds) + if ($Transaction.IoDeadlineUtc -gt $Transaction.DeadlineUtc) { + $Transaction.IoDeadlineUtc = $Transaction.DeadlineUtc + } $Transaction.IoClock = [Diagnostics.Stopwatch]::StartNew() + } elseif (-not $Transaction.IoClock.IsRunning) { + $now = [DateTime]::UtcNow + $remaining = [Math]::Max(0, [Math]::Min( + $Transaction.BudgetMilliseconds - $Transaction.IoClock.Elapsed.TotalMilliseconds, + ($Transaction.DeadlineUtc - $now).TotalMilliseconds)) + $Transaction.IoDeadlineUtc = $now.AddMilliseconds($remaining) + if ($Transaction.IoDeadlineUtc -gt $Transaction.DeadlineUtc) { + $Transaction.IoDeadlineUtc = $Transaction.DeadlineUtc + } + $Transaction.IoClock.Start() } - Assert-CapJournalTime $Transaction $Sequence $native + Assert-CapJournalTime $Transaction $Sequence $native -Io if ($null -eq $Transaction.PreOpenElapsedMilliseconds) { $Transaction.PreOpenElapsedMilliseconds = $Transaction.Clock.Elapsed.TotalMilliseconds } @@ -5245,11 +5263,11 @@ function Read-CapJournalObject { throw (New-CapJournalFailure 'JournalUnavailable' "sequence=$Sequence HRESULT=$native; global retry limit. $(Format-CapJournalPhaseTiming $Transaction)") } $Transaction.Retries++ - Assert-CapJournalTime $Transaction $Sequence $native - $remaining = [Math]::Min(($Transaction.DeadlineUtc - [DateTime]::UtcNow).TotalMilliseconds, + Assert-CapJournalTime $Transaction $Sequence $native -Io + $remaining = [Math]::Min(($Transaction.IoDeadlineUtc - [DateTime]::UtcNow).TotalMilliseconds, $Transaction.BudgetMilliseconds - $Transaction.IoClock.Elapsed.TotalMilliseconds) if ($remaining -gt 0) { Start-Sleep -Milliseconds ([int][Math]::Min(100, [Math]::Floor($remaining))) } - Assert-CapJournalTime $Transaction $Sequence $native + Assert-CapJournalTime $Transaction $Sequence $native -Io if ($Advance) { $names = Get-CapJournalNames $State foreach ($number in $names.Keys) { $State.HighestObserved = [Math]::Max($State.HighestObserved, $number) } @@ -5272,7 +5290,8 @@ function Read-CapJournalObject { throw } finally { $buffer.Dispose() } - Assert-CapJournalTime $Transaction $Sequence + $Transaction.IoClock.Stop() + Assert-CapJournalTime $Transaction $Sequence -Io $envelope = ConvertFrom-CapJournalBytes $bytes try { Assert-CapDataRecord $envelope @{ schemaVersion = [long]; sequence = [long] @@ -5429,7 +5448,7 @@ function Read-CapJournalFinalProof { throw (New-CapJournalFailure 'PostTerminalPublication' 'Observed floor exceeds final binding.') } $transaction = New-CapJournalTransaction $State -ManifestBudget - Assert-CapJournalTime $transaction $Record.terminal.sequence + Assert-CapJournalTime $transaction $Record.terminal.sequence -Io $manifestPath = Assert-CapArtifactPath -Root $State.Root -Path (Join-Path $OutputDirectory $Record.manifest.name) $stream = $null $held = [Collections.Generic.List[IO.Stream]]::new() @@ -5438,7 +5457,17 @@ function Read-CapJournalFinalProof { $stream = Open-CapJournalManifestStream $State $manifestPath $transaction $Record.terminal.sequence $held.Add($stream) $memory = [IO.MemoryStream]::new() - try { $stream.CopyTo($memory); $bytes = $memory.ToArray() } finally { $memory.Dispose() } + try { + $copyClock = [Diagnostics.Stopwatch]::StartNew() + try { $stream.CopyTo($memory); $bytes = $memory.ToArray() } + finally { + $elapsed = $copyClock.Elapsed.TotalMilliseconds + $transaction.CopyElapsedMilliseconds = if ($null -eq $transaction.CopyElapsedMilliseconds) { $elapsed } + else { $transaction.CopyElapsedMilliseconds + $elapsed } + } + } finally { $memory.Dispose() } + $transaction.IoClock.Stop() + Assert-CapJournalTime $transaction $Record.terminal.sequence -Io if ($bytes.Length -ne $Record.manifest.length -or [Convert]::ToHexString([Security.Cryptography.SHA256]::HashData($bytes)) -cne $Record.manifest.sha256) { throw (New-CapJournalFailure 'JournalHash' 'Final manifest bytes differ.') @@ -5627,7 +5656,7 @@ function Open-CapJournalManifestStream { param($State, [string]$Path, $Transaction, [long]$Sequence) $native = $null for ($attempt = 1; $attempt -le 8; $attempt++) { - Assert-CapJournalTime $Transaction $Sequence $native + Assert-CapJournalTime $Transaction $Sequence $native -Io if ($null -eq $Transaction.PreOpenElapsedMilliseconds) { $Transaction.PreOpenElapsedMilliseconds = $Transaction.Clock.Elapsed.TotalMilliseconds } @@ -5644,8 +5673,8 @@ function Open-CapJournalManifestStream { } if ($Transaction.Retries -ge 7) { break } $Transaction.Retries++ - Assert-CapJournalTime $Transaction $Sequence $native - $remaining = [Math]::Min(($Transaction.DeadlineUtc - [DateTime]::UtcNow).TotalMilliseconds, + Assert-CapJournalTime $Transaction $Sequence $native -Io + $remaining = [Math]::Min(($Transaction.IoDeadlineUtc - [DateTime]::UtcNow).TotalMilliseconds, $Transaction.BudgetMilliseconds - $Transaction.IoClock.Elapsed.TotalMilliseconds) if ($remaining -gt 0) { Start-Sleep -Milliseconds ([int][Math]::Min(100, [Math]::Floor($remaining))) } }