test(windows): prove one residual cleanup window from supervisor evidence

docs/phase1-conformance.md

@@ -2047,7 +2047,7 @@ revision authorities can therefore have different workflow hashes:
 
 | File | Bytes | SHA-256 |
 | --- | ---: | --- |
-| `.github/workflows/client-v1-conformance.yml` | 182,280 | `3b0d2ba8173a479f2d64d8e018f6fd8093711c87d179c5a37b78403921a81709` |
+| `.github/workflows/client-v1-conformance.yml` | 183,220 | `d71071d3a3d99472021e6b90e2299cc1b87b720a65356086ff205874e202b7fa` |
 | `scripts/contract-canary.mjs` | 40,618 | `a4c2fe0a5eb6a5ff4653de5374c34c0fb46907c6806a5d23b86d8b37206ef958` |
 | `scripts/executable-resolution.mjs` | 9,154 | `31e3c412ff8c835f14522f36a59e91f4a4ba82913210ae8e3b4455217503f430` |
 | `scripts/owned-temp-directory.mjs` | 9,205 | `1ba30d2d5f0312143e2837956899a4f3f116f3619937d5d9756ff197ecb2a325` |
@@ -2072,7 +2072,7 @@ revision authorities can therefore have different workflow hashes:
 | `scripts/unix-producer-supervisor.test.sh` | 13,348 | `a8c6f48915b0c86a704a7ddc28eaa7f808ae0a3ddfcdb38c0c23ac0d83738f6d` |
 | `scripts/phase1-windows-supervisor-build.sh` | 4,646 | `713a9e0282887ade3e243b5ba175794d74cdb02c28c38dcd41491c9505812770` |
 | `scripts/phase1-windows-supervisor-install.ps1` | 1,743 | `2baab275f0bb6789884cded5f6185d00bfa5348b9e7c3ad1e5575353639101d5` |
-| `scripts/windows-job-supervisor.cs` | 399,778 | `b175670ed6eb74ecf4916f43fdb14f15281836f9d74746e5008a6af9c72f15e5` |
+| `scripts/windows-job-supervisor.cs` | 402,329 | `1f6a6d210b3551688dcb530bc4513f9f18578b35e681720139afec26b372c823` |
 | `scripts/windows-job-supervisor.test.ps1` | 206,688 | `de658abd2f567623889a0d6a585508311a6045b938d075ee1e02125db28561e9` |
 | `scripts/windows-quota-diagnostics.test.ps1` | 45,628 | `2a2f59c95e14d7687cc258d52ed233062a793ba516a2b0d18d9a473a3ed79d96` |
 | `scripts/windows-owner-directory-quota.test.ps1` | 14,789 | `a6fccce4e1e41b06c655bc1a70bf870ba115f0848ee647777d2606294483cd1f` |
@@ -2082,7 +2082,7 @@ revision authorities can therefore have different workflow hashes:
 | `scripts/windows-cleanup-delete-diagnostics.test.ps1` | 7,433 | `e9d30285a1fe0ad035637621c6a3840eb8a6194b2f23e1a4aa188c5884cd0c64` |
 | `scripts/windows-profile-cleanup-characterization.test.ps1` | 11,549 | `00052aab05d01785d225999536002fe17585fd80ff71b537b6ebed088b4549d7` |
 | `scripts/windows-profile-residual-policy.test.ps1` | 14,847 | `2a8517338ffc84d38967d11d3ade3f58d4d7004f5437da890da30a1cb0dda417` |
-| `scripts/windows-profile-residual-native.test.ps1` | 50,117 | `1526a99951752b3173d37ad9815f76d9300452e39277b0c8903cd8f0f1ebea90` |
+| `scripts/windows-profile-residual-native.test.ps1` | 55,009 | `e1e4063c67951fd97e31b461aa38a83ee97f085722cca4eb5c441ed4b6b550f9` |
 | `scripts/windows-process-sid-diagnostics.cs` | 4,054 | `cd4b1c16a759ce4e63b87c82c4be0dbee9c0b48e9bfd3851eb966c303918e1a2` |
 | `scripts/windows-process-sid-diagnostics.test.ps1` | 7,316 | `c83e2d63355fb95c8220045115a3b8106b7507b7132d235ad74eb0283f6c481f` |
 | `scripts/windows-staging-binding.test.ps1` | 885 | `56514e709e34b68e0692bd5c3bd91c8bea0a01fd281ded33920f83c2ab653182` |

scripts/windows-job-supervisor.cs

@@ -3376,6 +3376,13 @@ internal static void DeleteOperatingSystemProfileCore(
                 lastDeleteError = error;
                 Thread.Sleep(100);
             }
+            // The residual window opens exactly once, here, once the delete loop has returned.
+            // Its start is recorded so a cleanup failure carries how many windows ran and when.
+            // The native regression reads that evidence instead of bounding wall-clock time,
+            // which cannot tell a slow runner from a window that was reopened part-way through.
+            TimeSpan deletePhase = deleteTimer.Elapsed;
+            List<long> residualWindowStarts = new List<long>();
+            residualWindowStarts.Add(Stopwatch.GetTimestamp());
             Stopwatch timer = Stopwatch.StartNew();
             int residualEntries = 0;
             try
@@ -3405,6 +3412,39 @@ internal static void DeleteOperatingSystemProfileCore(
                     lastDeleteError,
                     "Ephemeral Windows profile deletion remained blocked.");
             }
+            catch (ProfileCleanupException failure)
+            {
+                failure.Data[ProfileResidualWindowKey] =
+                    DescribeProfileResidualWindow(deletePhase, residualWindowStarts, timer);
+                throw;
+            }
+        }
+
+        internal const string ProfileResidualWindowKey = "OpenCoven.ProfileResidualWindow";
+
+        // Evidence attached to one profile cleanup failure: how long the delete loop ran, every
+        // residual window start and the moment the window expired as Stopwatch.GetTimestamp
+        // ticks, and the elapsed time the window's own clock reports. A window that was reopened
+        // shows a second start; a clock that was reset disagrees with the timestamps. Neither
+        // needs a wall-clock ceiling to detect.
+        internal static string DescribeProfileResidualWindow(
+            TimeSpan deletePhase, IList<long> starts, Stopwatch window)
+        {
+            if (deletePhase < TimeSpan.Zero || starts == null || starts.Count < 1 || window == null)
+                throw new ArgumentException("Invalid profile residual window evidence.");
+            StringBuilder evidence = new StringBuilder();
+            evidence.Append("delete-ms=").Append(
+                ((long)deletePhase.TotalMilliseconds).ToString(CultureInfo.InvariantCulture));
+            evidence.Append(";starts=");
+            for (int index = 0; index < starts.Count; index++)
+            {
+                if (index > 0) evidence.Append(',');
+                evidence.Append(starts[index].ToString(CultureInfo.InvariantCulture));
+            }
+            evidence.Append(";expired=").Append(Stopwatch.GetTimestamp().ToString(CultureInfo.InvariantCulture));
+            evidence.Append(";elapsed-ms=").Append(window.ElapsedMilliseconds.ToString(CultureInfo.InvariantCulture));
+            evidence.Append(";frequency=").Append(Stopwatch.Frequency.ToString(CultureInfo.InvariantCulture));
+            return evidence.ToString();
         }
 
         internal sealed class ProfileCleanupIdentity

scripts/windows-profile-residual-native.test.ps1

@@ -341,7 +341,8 @@ namespace OpenCoven.Tests {
         }
         // Records when userenv unregistration is first observed on the cleanup stopwatch.
         // The residual deadline starts only after DeleteProfileW returns, so the time from
-        // here to return bounds that one window without the phases before it.
+        // here to return covers that one window without the phases before it. It is printed
+        // for the log; the window itself is proven by the supervisor's own evidence.
         public sealed class UnregistrationClock : IDisposable {
             private readonly ManualResetEventSlim stop = new ManualResetEventSlim();
             private readonly Task poll;
@@ -438,6 +439,41 @@ function Assert-ResidualFailure([Exception]$Failure, [string]$Expected) {
   }
 }
 
+$windowKey = [string][OpenCoven.WindowsJobSupervisor].GetField(
+  'ProfileResidualWindowKey', [Reflection.BindingFlags]'NonPublic,Static').GetValue($null)
+if ($windowKey -cne 'OpenCoven.ProfileResidualWindow') { throw 'Residual window evidence key changed its contract.' }
+# The supervisor stamps one profile cleanup failure with the delete loop's duration, every
+# residual window start, the moment the window expired and the window clock's own reading.
+function Get-ResidualWindow([Exception]$Failure) {
+  if ($null -eq $Failure) { return $null }
+  $queue = [Collections.Generic.Queue[Exception]]::new()
+  $queue.Enqueue($Failure)
+  $visited = 0
+  while ($queue.Count -gt 0) {
+    if ($visited -ge 32) { throw 'Native residual exception graph exceeded its bound.' }
+    $visited++
+    $item = $queue.Dequeue()
+    $evidence = $item.Data[$windowKey]
+    if ($evidence -is [string]) {
+      $match = [regex]::Match($evidence,
+        '^delete-ms=(?<delete>\d+);starts=(?<starts>\d+(?:,\d+)*);expired=(?<expired>\d+);elapsed-ms=(?<elapsed>\d+);frequency=(?<frequency>\d+)$')
+      if (-not $match.Success) { throw "Residual window evidence changed its contract: $evidence." }
+      $starts = [long[]]($match.Groups['starts'].Value.Split(',') | ForEach-Object { [long]$_ })
+      return @{
+        DeleteMs = [long]$match.Groups['delete'].Value
+        Starts = $starts
+        Expired = [long]$match.Groups['expired'].Value
+        ElapsedMs = [long]$match.Groups['elapsed'].Value
+        Frequency = [long]$match.Groups['frequency'].Value
+      }
+    }
+    if ($item -is [AggregateException]) {
+      foreach ($inner in $item.InnerExceptions) { $queue.Enqueue($inner) }
+    } elseif ($null -ne $item.InnerException) { $queue.Enqueue($item.InnerException) }
+  }
+  return $null
+}
+
 $profileFailureType = [OpenCoven.WindowsJobSupervisor].GetNestedType(
   'ProfileCleanupException', [Reflection.BindingFlags]::NonPublic)
 $profileFailureConstructor = $profileFailureType.GetConstructor(
@@ -539,6 +575,38 @@ if ($invalidSharing -isnot [InvalidOperationException] -or
     $invalidSharing.Message -cne 'Residual deletion handles must deny delete sharing.') {
   throw 'Residual deletion admitted delete sharing or reached native code before rejecting it.'
 }
+$describeWindow = [OpenCoven.WindowsJobSupervisor].GetMethod(
+  'DescribeProfileResidualWindow', [Reflection.BindingFlags]'NonPublic,Static')
+if ($null -eq $describeWindow) { throw 'Residual window evidence describer is absent.' }
+$windowClock = [Diagnostics.Stopwatch]::StartNew()
+$windowStarts = [Collections.Generic.List[long]]::new()
+$windowStarts.Add([Diagnostics.Stopwatch]::GetTimestamp())
+$windowStarts.Add([Diagnostics.Stopwatch]::GetTimestamp())
+$windowProbe = [InvalidOperationException]::new('probe')
+$windowProbe.Data[$windowKey] = [string]$describeWindow.Invoke($null,
+  [object[]]@([TimeSpan]::FromMilliseconds(1234.9), $windowStarts, $windowClock))
+$windowEvidence = Get-ResidualWindow ([AggregateException]::new([Exception[]]@([InvalidOperationException]::new('outer', $windowProbe))))
+if ($null -eq $windowEvidence -or $windowEvidence.DeleteMs -ne 1234 -or $windowEvidence.Starts.Count -ne 2 -or
+    $windowEvidence.Starts[0] -ne $windowStarts[0] -or $windowEvidence.Starts[1] -ne $windowStarts[1] -or
+    $windowEvidence.Expired -lt $windowStarts[1] -or $windowEvidence.ElapsedMs -lt 0 -or
+    $windowEvidence.Frequency -ne [Diagnostics.Stopwatch]::Frequency) {
+  throw 'Residual window evidence did not round-trip through the failure graph.'
+}
+if ($null -ne (Get-ResidualWindow ([InvalidOperationException]::new('bare')))) {
+  throw 'Residual window evidence was found on a failure that carries none.'
+}
+foreach ($invalid in @(
+    @([TimeSpan]::FromSeconds(-1), $windowStarts, $windowClock),
+    @([TimeSpan]::Zero, [Collections.Generic.List[long]]::new(), $windowClock),
+    @([TimeSpan]::Zero, $null, $windowClock),
+    @([TimeSpan]::Zero, $windowStarts, $null))) {
+  $rejected = $null
+  try { $describeWindow.Invoke($null, [object[]]$invalid) | Out-Null } catch { $rejected = $_.Exception.GetBaseException() }
+  if ($rejected -isnot [ArgumentException] -or $rejected.Message -cne 'Invalid profile residual window evidence.') {
+    throw 'Residual window evidence accepted invalid inputs.'
+  }
+}
+Write-Host 'Portable residual window evidence passed.'
 Write-Host 'Portable residual failure classification passed.'
 if ($PortableOnly) { return }
 
@@ -771,14 +839,26 @@ foreach ($case in @('delayed', 'persistent', 'denied', 'readonly', 'junction', '
       }
     }
     $timing = 'total=' + (Format-Seconds $total)
+    $evidence = Get-ResidualWindow $failure
+    if ($null -ne $evidence) {
+      $timing += ';delete=' + (Format-Seconds ([TimeSpan]::FromMilliseconds($evidence.DeleteMs))) +
+        ';window=' + (Format-Seconds ([TimeSpan]::FromMilliseconds($evidence.ElapsedMs))) +
+        ';windows=' + $evidence.Starts.Count
+    }
     if ($fullWindow) {
       $window = $unregistration.Since($total)
       $timing += ';after-unregistration=' + (Format-Seconds $window)
       Write-Host "Native residual timing: case=$case;$timing."
-      # The window cannot end before its 10 s deadline. Windows runners measured 10.7-13.1 s,
-      # and one restart would take it to 20 s or more.
-      if ($window -lt [TimeSpan]::FromSeconds(9.5) -or $window -gt [TimeSpan]::FromSeconds(18)) {
-        throw "Residual cleanup window was outside its 10 s deadline: $timing."
+      # Wall-clock time cannot tell a slow runner from a window that was reopened part-way
+      # through: a restart at 8.8 s and one slow window both end near 18.8 s (#453). The
+      # supervisor's own evidence can. Exactly one window opened, it ran to its 10 s deadline,
+      # and its clock agrees with its recorded start, so it was never reset.
+      if ($null -eq $evidence) { throw "Residual cleanup failure carried no window evidence: $timing." }
+      if ($evidence.Starts.Count -ne 1) { throw "Residual cleanup opened its window more than once: $timing." }
+      if ($evidence.ElapsedMs -lt 10000) { throw "Residual cleanup window ended before its 10 s deadline: $timing." }
+      $windowWall = ($evidence.Expired - $evidence.Starts[0]) / [double]$evidence.Frequency
+      if ([Math]::Abs($windowWall - ($evidence.ElapsedMs / 1000.0)) -gt 0.5) {
+        throw "Residual cleanup window clock disagrees with its recorded start: $timing."
       }
     }
     $budget = if ($fullWindow) { 30 } else { 20 }