ci: capture native recovery startup context before platform probe

docs/macos-native-diagnostic.md

@@ -20,14 +20,18 @@ Dependencies are the existing Linux/x64 runner, .NET 10 SDK, Git, Bash and Docke
 
 The helper clones Dockur commit `16a5b470cdd601bae8b05b02d748d7edfb36c12e`, verifies its exact Recovery patcher hash, and makes three narrowly verified source edits. The early `rc.cdrom.sh` hook only mounts the existing state share and returns. A same-length XML replacement makes the existing `com.apple.recoveryosd` LaunchDaemon execute `/bin/bash /Volumes/installstate/launch.sh` after boot tasks. The staged `launch.sh` is replaced entirely by the checked-in read-only readiness probe. All replacement counts are exact; an upstream mismatch fails. The two imported QEMU image digests are pinned and the final image/source/Recovery hashes are retained. Other upstream Dockerfile downloads are observed through the resulting image identity rather than asserted to be immutable.
 
-The VM uses TCG (`KVM=N`), slirp networking, a 4-GiB guest, two virtual CPUs and a sparse 64-GiB data disk. Its container has a 6-GiB memory/swap ceiling and a two-CPU limit. The existing Docker daemon must report at least two CPUs and 6 GiB total memory, the runner must have at least 5 GiB available memory, and the Docker filesystem must have at least 8 GiB free before Recovery downloads or boot. Its own native commands have per-command watchdogs and a ten-minute readiness phase; the host orchestrator has a 40-minute deadline and the workflow a 45-minute limit.
+The VM uses TCG (`KVM=N`), slirp networking, a 4-GiB guest, two virtual CPUs and a sparse 64-GiB data disk. Its container has a 6-GiB memory/swap ceiling and a two-CPU limit. The existing Docker daemon must report at least two CPUs and 6 GiB total memory, the runner must have at least 5 GiB available memory, and the Docker filesystem must have at least 8 GiB free before Recovery downloads or boot. Its own native commands retain 45-second watchdogs and a ten-minute readiness phase; the host orchestrator has a 40-minute deadline and the workflow a 45-minute limit.
+
+Actual remote run 4155 stopped at the first `sw_vers` with exit 143 before kernel, process or service probes ran. The updated hook collects native `uname`, root identity, bootargs, guest CPU features and process context first. It logs each child PID and builtin elapsed time, explicitly tags watchdog TERM, and takes two independently five-second-bounded CPU/state/command snapshots during each `sw_vers` attempt. After an initial platform failure it still collects native launchd context and repeats the identical `sw_vers` command once, with the same 45-second limit. A successful native `sw_vers`, native product version and all original identity/service/disk gates remain required. Process state or a retry alone does not establish whether initialization was slow or a service blocked. The upstream AVX2 warning reads host flags; the pinned TCG CPU path configures an Intel guest with AVX/AVX2, so the hook observes actual guest CPU flags without changing host or guest CPU settings.
 
 ## Evidence and cleanup
 
 Evidence is written under the requested output directory: run identity and candidate commit, Docker/runner resources, exact source patch artifacts and hashes, image/container inspection, Recovery hash, native platform/process/launchctl/diskutil logs, machine-readable guest result, outcome and cleanup receipt. The workflow retains these as a seven-day artifact. Phase names and up to 512 KiB of the final native proof also appear in CI stdout, on success or failure, with the run token replaced; no environment or credential dump is printed. A Docker start/build exit zero is not a successful native result. A missing, stale, unsupported-platform, read-only or wrong-size guest receipt fails.
 
+While Recovery readiness is pending, a minute heartbeat reports elapsed guest time and the container's running state. Before final cleanup, an optional ten-second capture rechecks the saved container ID/ownership label and uses the pinned image's existing Unix HMP socket, `nc.openbsd` and a five-second `timeout` to collect only [`info status` and `screendump`](https://www.qemu.org/docs/master/system/monitor.html), retaining the command transcript, exit codes and fresh bounded PPM screenshot. Capture failure is visible and never changes native readiness success.
+
 Every container/image has a random run token in its ownership label. `finally` cleanup and the workflow's `always()` step inspect that exact label before removing the matching container and its anonymous storage volume, then the matching image. They never remove an unrelated name or volume, prune Docker, modify host settings or restart Meeting Assistant. Temporary source files are deleted only when their local marker matches the same token. Evidence remains available after cleanup.
 
 The earlier background-only local bootstrap never obtained DiskManagement readiness. This separate LaunchDaemon probe is still an experiment until the actual remote run produces the required native evidence. Full macOS CI support remains unverified until an installed guest subsequently compiles/signs the native helpers and passes all application tests, including all five native tests without skips.
 
-Remote run 4152 passed Docker access and resource checks but failed before VM startup: the runner's BuildKit could not checksum a dangling `/etc/alternatives/awk.1.gz` link while copying the entire QEMU filesystem. The candidate now derives directly from the same pinned QEMU filesystem image and overwrites its QEMU executable as before. Inspection of that exact digest reports an empty image `Config`, so it adds no inherited environment, user, command or healthcheck. The next actual remote build must verify this compatibility change; it does not claim native readiness.
+Remote run 4152 passed Docker access and resource checks but failed before VM startup: the runner's BuildKit could not checksum a dangling `/etc/alternatives/awk.1.gz` link while copying the entire QEMU filesystem. The candidate now derives directly from the same pinned QEMU filesystem image and overwrites its QEMU executable as before. Inspection of that exact digest reports an empty image `Config`, so it adds no inherited environment, user, command or healthcheck. Actual run 4155 built that image and started QEMU/XNU successfully, then failed the first native `sw_vers` after its 45-second watchdog. It did not prove native readiness.

tools/ci/MacOsNativeDiagnostic.cs

@@ -117,6 +117,8 @@ static class NativeDiagnostic
             AssertContainer(File.ReadAllText(Path.Combine(output, "container-created.stdout.log")), token);
             await Command("docker", ["start", id], output, "docker-start", deadline.Token);
             Console.WriteLine("The owned unprivileged TCG guest is starting. Success requires native macOS 14+/x86_64 and a writable 64-GiB disk; no installer will run.");
+            var recoveryStarted = Stopwatch.StartNew();
+            var heartbeat = Stopwatch.StartNew();
             while (true)
             {
                 deadline.Token.ThrowIfCancellationRequested();
@@ -132,6 +134,11 @@ static class NativeDiagnostic
                 }
                 var running = await Command("docker", ["inspect", "--format", "{{.State.Running}}", id], output, "container-running", deadline.Token);
                 if (running.Output.Trim() != "true") throw new InvalidOperationException("Guest container exited before a native readiness result.");
+                if (heartbeat.Elapsed >= TimeSpan.FromSeconds(60))
+                {
+                    Console.WriteLine($"[native-diagnostic] phase=recovery; elapsed={recoveryStarted.Elapsed.TotalMinutes:F1} minutes; container=running; readiness=pending");
+                    heartbeat.Restart();
+                }
                 await Task.Delay(TimeSpan.FromSeconds(20), deadline.Token);
             }
         }
@@ -144,7 +151,7 @@ static class NativeDiagnostic
         {
             Console.CancelKeyPress -= cancelHandler;
             using var captureDeadline = new CancellationTokenSource(TimeSpan.FromSeconds(45));
-            try { await CaptureGuest(state.ContainerName, output, captureDeadline.Token); } catch (Exception exception) { Console.Error.WriteLine("Final evidence capture: " + exception.Message); }
+            try { await CaptureGuest(state.ContainerId ?? state.ContainerName, output, captureDeadline.Token, true, state.Token); } catch (Exception exception) { Console.Error.WriteLine("Final evidence capture: " + exception.Message); }
             try { PrintGuestProof(output, state.Token); } catch (Exception exception) { Console.Error.WriteLine("Native proof output: " + exception.Message); }
             var clean = await Cleanup(output);
             if (!clean) { outcome = "failed"; error = (error ?? "") + " Owned-resource cleanup failed; inspect cleanup evidence."; }
@@ -229,8 +236,9 @@ static class NativeDiagnostic
             throw new InvalidOperationException("Created container exceeds the owned/unprivileged diagnostic boundary.");
     }
 
-    static async Task CaptureGuest(string id, string output, CancellationToken cancellation)
+    static async Task CaptureGuest(string id, string output, CancellationToken cancellation, bool final = false, string? token = null)
     {
+        if (final && token is not null) await CaptureMonitor(id, output, token, cancellation);
         var logs = await Command("docker", ["logs", "--tail", "3000", id], output, "container", cancellation, requireSuccess: false);
         foreach (var file in new[] { ("proof.log", "guest-proof.log"), ("result.json", "guest-result.json") })
         {
@@ -240,6 +248,41 @@ static class NativeDiagnostic
         await Command("docker", ["exec", id, "sh", "-c", "printf '[qemu]\n'; qemu-system-x86_64 --version | head -n 1; printf '[Recovery hash]\n'; test ! -f /storage/14/setup.dmg || sha256sum /storage/14/setup.dmg; printf '[resources]\n'; df -Pk /storage; cat /sys/fs/cgroup/memory.max /sys/fs/cgroup/cpu.max 2>/dev/null || true"], output, "guest-container-resources", cancellation, requireSuccess: false);
     }
 
+    static async Task CaptureMonitor(string id, string output, string token, CancellationToken cancellation)
+    {
+        using var deadline = CancellationTokenSource.CreateLinkedTokenSource(cancellation);
+        deadline.CancelAfter(TimeSpan.FromSeconds(10));
+        int? monitorExit = null, copyExit = null;
+        string? error = null;
+        try
+        {
+            if (!System.Text.RegularExpressions.Regex.IsMatch(id, "^[0-9a-f]{64}$") || !System.Text.RegularExpressions.Regex.IsMatch(token, "^[0-9a-f]{32}$")) throw new InvalidOperationException("No saved owned container identity for the optional monitor capture.");
+            var inspection = await Command("docker", ["inspect", id], output, "capture-monitor-container", deadline.Token);
+            AssertContainer(inspection.Output, token);
+            using (var document = JsonDocument.Parse(inspection.Output))
+                if (document.RootElement[0].GetProperty("Id").GetString() != id || !document.RootElement[0].GetProperty("State").GetProperty("Running").GetBoolean()) throw new InvalidOperationException("Owned guest container is no longer running for the optional monitor capture.");
+            var screen = "/dev/shm/native-diagnostic-screen-" + token + ".ppm";
+            var monitor = await Command("docker", ["exec", id, "sh", "-c", """
+                test -S /run/shm/monitor.sock || exit 1
+                rm -f -- "$1" || exit 1
+                printf 'info status\nscreendump %s\n' "$1" | /usr/bin/timeout -s KILL 5 /usr/bin/nc.openbsd -q 1 -w 2 -U /run/shm/monitor.sock
+                monitor_exit=$?
+                printf '\n[monitor-exit] %s\n' "$monitor_exit"
+                [ "$monitor_exit" -eq 0 ] || exit "$monitor_exit"
+                bytes=$(stat -c%s "$1") || exit 1
+                [ "$bytes" -gt 0 ] && [ "$bytes" -le 8388608 ] || exit 1
+                printf '[screen-bytes] %s\n' "$bytes"
+                """, "native-monitor", screen], output, "capture-monitor", deadline.Token, requireSuccess: false);
+            monitorExit = monitor.ExitCode;
+            if (monitorExit != 0) throw new InvalidOperationException("Optional monitor status/screenshot command exited " + monitorExit + ".");
+            var copy = await Command("docker", ["cp", id + ":" + screen, Path.Combine(output, "guest-screen-" + token + ".ppm")], output, "capture-monitor-screen", deadline.Token, requireSuccess: false);
+            copyExit = copy.ExitCode;
+            if (copyExit != 0) throw new InvalidOperationException("Optional monitor screenshot copy exited " + copyExit + ".");
+        }
+        catch (Exception exception) { error = exception.Message; Console.Error.WriteLine("Optional final monitor capture: " + error); }
+        finally { Save(Path.Combine(output, "monitor-capture.json"), new { token, monitorExit, copyExit, success = error is null, error, capturedUtc = DateTimeOffset.UtcNow }); }
+    }
+
     static async Task<bool> Cleanup(string output)
     {
         var path = Path.Combine(output, "owned-resources.json");

tools/ci/macos-native-readiness.sh

@@ -45,28 +45,59 @@ finish() {
 run_command() {
   local name="$1"
   shift
-  local process timer sleeper exit_code
+  local process timer sleeper exit_code started observer=""
   LAST_OUTPUT="/tmp/native-diagnostic-$name.out"
   printf '\n[proof-command] %s:' "$name" >> "$PROOF_LOG"
   printf ' %s' "$@" >> "$PROOF_LOG"
   printf '\n' >> "$PROOF_LOG"
+  started=$SECONDS
   "$@" > "$LAST_OUTPUT" 2>&1 &
   process=$!
+  printf '[proof-start] %s child=%s shell=%s parent=%s seconds=%s\n' "$name" "$process" "$$" "$PPID" "$started" >> "$PROOF_LOG"
   (
     trap 'kill "$sleeper" 2>/dev/null || :; exit 0' TERM INT
     sleep 45 &
     sleeper=$!
     wait "$sleeper"
+    printf '[proof-timeout] %s child=%s elapsed=%ss signal=TERM\n' "$name" "$process" "$((SECONDS - started))" >> "$PROOF_LOG"
     kill -TERM "$process" 2>/dev/null || :
-    sleep 2
+    sleep 2 & sleeper=$!; wait "$sleeper"
     kill -KILL "$process" 2>/dev/null || :
   ) &
   timer=$!
+  if [[ "$name" = platform || "$name" = platform-warm ]]; then
+    # Observers never extend the independent 45-second command deadline.
+    (
+      local sample_pid="" sample_timer="" pause_pid="" pause sample_exit
+      trap 'kill -KILL "$sample_pid" 2>/dev/null || :; kill -TERM "$sample_timer" "$pause_pid" 2>/dev/null || :; exit 0' TERM INT
+      for pause in 10 15; do
+        sleep "$pause" & pause_pid=$!; wait "$pause_pid"
+        printf '[proof-process] %s child=%s elapsed=%ss fields=pid,ppid,stat,cpu-time,elapsed,cpu-percent,wchan,comm\n' "$name" "$process" "$((SECONDS - started))" >> "$PROOF_LOG"
+        /bin/ps -p "$process" -o pid=,ppid=,stat=,time=,etime=,pcpu=,wchan=,comm= >> "$PROOF_LOG" 2>&1 &
+        sample_pid=$!
+        (
+          local sample_sleeper=""
+          trap 'kill "$sample_sleeper" 2>/dev/null || :; exit 0' TERM INT
+          sleep 5 & sample_sleeper=$!; wait "$sample_sleeper"
+          kill -KILL "$sample_pid" 2>/dev/null || :
+        ) & sample_timer=$!
+        wait "$sample_pid"; sample_exit=$?
+        kill -TERM "$sample_timer" 2>/dev/null || :; wait "$sample_timer" 2>/dev/null || :
+        printf '[proof-process-exit] %s %s\n' "$name" "$sample_exit" >> "$PROOF_LOG"
+        sample_pid=""; sample_timer=""; pause_pid=""
+      done
+    ) & observer=$!
+  fi
   wait "$process"
   exit_code=$?
   kill -TERM "$timer" 2>/dev/null || :
   wait "$timer" 2>/dev/null || :
+  if [ -n "$observer" ]; then
+    kill -TERM "$observer" 2>/dev/null || :
+    wait "$observer" 2>/dev/null || :
+  fi
   /usr/bin/tail -c 524288 "$LAST_OUTPUT" >> "$PROOF_LOG"
+  printf '\n[proof-duration] %s child=%s elapsed=%ss\n' "$name" "$process" "$((SECONDS - started))" >> "$PROOF_LOG"
   printf '\n[proof-exit] %s\n' "$exit_code" >> "$PROOF_LOG"
   LAST_EXIT="$exit_code"
   local size
@@ -75,13 +106,7 @@ run_command() {
   return 0
 }
 
-run_command platform /usr/bin/sw_vers
+# Collect cheap native identity/context before the first framework-dependent probe.
-(( LAST_EXIT == 0 )) || finish false sw_vers_failed
-run_command version /usr/bin/sw_vers -productVersion
-(( LAST_EXIT == 0 )) || finish false product_version_failed
-os_version=$(cat "$LAST_OUTPUT")
-[[ "$os_version" =~ ^[0-9]+\.[0-9]+(\.[0-9]+)?$ ]] || finish false product_version_invalid
-(( ${os_version%%.*} >= 14 )) || finish false unsupported_macos_version
 run_command kernel /usr/bin/uname -a
 (( LAST_EXIT == 0 )) || finish false uname_failed
 run_command architecture /usr/bin/uname -m
@@ -94,14 +119,28 @@ run_command uid /usr/bin/id -u
 uid=$(cat "$LAST_OUTPUT")
 [ "$uid" = 0 ] || finish false recovery_account_not_root
 run_command bootargs /usr/sbin/sysctl kern.bootargs
+run_command cpu /usr/sbin/sysctl machdep.cpu.brand_string machdep.cpu.features machdep.cpu.leaf7_features
 run_command parent /bin/ps -p "$$" -p "$PPID" -o pid=,ppid=,comm=
 run_command processes /bin/ps -axo pid,ppid,comm
+run_command platform /usr/bin/sw_vers
+platform_exit="$LAST_EXIT"
 run_command system /bin/launchctl print system
 system_exit="$LAST_EXIT"
 run_command arbitration /bin/launchctl print system/com.apple.diskarbitrationd
 arbitration_exit="$LAST_EXIT"
 run_command recovery /bin/launchctl print system/com.apple.recoveryosd
 recovery_exit="$LAST_EXIT"
+if (( platform_exit != 0 )); then
+  printf '[proof-retry] sw_vers once after native service context; same 45-second deadline\n' >> "$PROOF_LOG"
+  run_command platform-warm /usr/bin/sw_vers
+  platform_exit="$LAST_EXIT"
+fi
+(( platform_exit == 0 )) || finish false sw_vers_failed
+run_command version /usr/bin/sw_vers -productVersion
+(( LAST_EXIT == 0 )) || finish false product_version_failed
+os_version=$(cat "$LAST_OUTPUT")
+[[ "$os_version" =~ ^[0-9]+\.[0-9]+(\.[0-9]+)?$ ]] || finish false product_version_invalid
+(( ${os_version%%.*} >= 14 )) || finish false unsupported_macos_version
 
 # Bound readiness independently of the host's 40-minute overall deadline.
 readiness_start=$SECONDS