ci: stop Recovery boot loops and capture first reset evidence

.gitea/workflows/macos-native-diagnostic.yaml

@@ -6,7 +6,7 @@ on:
 jobs:
   macos-native-diagnostic:
     runs-on: ubuntu-latest
-    timeout-minutes: 95
+    timeout-minutes: 25
     env:
       DOTNET_SKIP_FIRST_TIME_EXPERIENCE: "1"
       DOTNET_NOLOGO: "1"

docs/macos-native-diagnostic.md

@@ -8,7 +8,11 @@ The existing Intel Celeron 1037U has neither AVX nor AVX2. KVM run 4187 at `720a
 
 [CryptexFixup 1.0.5](https://github.com/acidanthera/CryptexFixup/blob/1.0.5/kern_start.cpp) selects the installed/updated Rosetta Cryptex and patches APFS hash checking; it does not replace the running Recovery cache or emulate instructions. macOS 13 is outside the [.NET 10 supported-OS policy](https://github.com/dotnet/core/blob/main/release-notes/10.0/supported-os.md). This candidate therefore uses macOS 14 and software CPU emulation without Cryptex. It changes the compatibility profile, not one isolated causal variable; actual success must be measured.
 
-Earlier TCG run 4159 observed guest AVX2. Runs 4161/4163 measured slow native startup and reached the 40-minute host limit before readiness. They predated the UDIF CRC repair at `94a70b2`, reuse of successful sw_vers output and capturing the large Recovery hash only once. They do not qualify this candidate. Host/workflow limits are 90/95 minutes; a readiness pass does not establish that full installation/build/tests fit the pipeline.
+Earlier TCG run 4159 observed guest AVX2 with the upstream-selected Skylake model. Runs 4161/4163 measured slow native startup and reached the 40-minute host limit before readiness. They predated the UDIF CRC repair at `94a70b2`, reuse of successful sw_vers output and capturing the large Recovery hash only once. They do not qualify this candidate.
+
+Run 4188 at `c01ae13` passed the actual AVX/AVX2 ROM test (positive exit 33, negative exit 0), then recorded 93 UEFI starts and 87 XNU handoffs before its 90-minute deadline. Container restart count, CPU throttling and OOM events were zero; no guest hook proof appeared. This establishes a guest boot loop, without identifying its cause. The next diagnostic preserves the same CPU/OS profile and has host/workflow limits of 20/25 minutes. Its purpose is to capture the first failure, not qualify full-run performance.
+
+Kernel arguments add `-v debug=0x108 serial=5 msgbuf=1048576` while preserving the other pinned arguments, following [OpenCore 1.0.7](https://raw.githubusercontent.com/acidanthera/OpenCorePkg/1.0.7/Docs/Configuration.tex). Actual VM arguments add `-no-reboot -no-shutdown` and `-d int,cpu_reset,guest_errors,unimp`. The [QEMU reset policy](https://github.com/qemu/qemu/blob/v11.1.1/system/runstate.c) pauses the VM after a requested reset so monitor/framebuffer evidence survives. Exception output uses the existing 8-MiB Docker log ring. CPU/staging markers and sparse kernel-handoff lines are retained separately; repeated handoff or halted VM status fails immediately. These diagnostics do not prove a particular panic, CPU deficiency, or completed native test.
 
 ## Entry points and dependencies
 

tools/ci/MacOsNativeDiagnostic.cs

@@ -16,6 +16,8 @@ static class NativeDiagnostic
     const string DockurCommit = "16a5b470cdd601bae8b05b02d748d7edfb36c12e";
     const string Profile = "tcg-haswell-sonoma";
     const string CpuModel = "Haswell-noTSX";
+    const int DiagnosticMinutes = 20;
+    const string DiagnosticArguments = "-object iothread,id=io2 -no-reboot -no-shutdown -d int,cpu_reset,guest_errors,unimp";
     const string CpuFlags = "Haswell-noTSX,l3-cache=on,+hypervisor,vendor=GenuineIntel,vmx=off,vmware-cpuid-freq=on,-pdpe1gb,-pcid,-invpcid,-tsc-deadline,-xsavec,-xsaves,+ssse3,+sse4.2,+popcnt,+avx,+avx2,+aes,+fma,+bmi1,+bmi2,+smep,+xsave,+xsaveopt,+xgetbv1,+movbe,+rdrand,enforce=on";
     const string OpenCoreTemplateHash = "287328995d4198f1b05166f087d85bf7ef66bedafe150d17ad112ac8de60051d";
     const string UdifChecksumBindingHash = "6109d04619e800c483fdac363d593cd1cd69f34131d2521417334e11d41c8bfa";
@@ -100,7 +102,7 @@ static class NativeDiagnostic
         Save(statePath, state);
         Directory.CreateDirectory(work);
         File.WriteAllText(Path.Combine(work, "run.owner"), token);
-        using var deadline = new CancellationTokenSource(TimeSpan.FromMinutes(90));
+        using var deadline = new CancellationTokenSource(TimeSpan.FromMinutes(DiagnosticMinutes));
         using var signal = OperatingSystem.IsLinux() ? PosixSignalRegistration.Create(PosixSignal.SIGTERM, context => { context.Cancel = true; deadline.Cancel(); }) : null;
         ConsoleCancelEventHandler cancelHandler = (_, context) => { context.Cancel = true; deadline.Cancel(); };
         Console.CancelKeyPress += cancelHandler;
@@ -112,7 +114,7 @@ static class NativeDiagnostic
                 throw new InvalidOperationException("This diagnostic runs on the existing Linux/x64 runner only.");
             ValidateContracts();
             var sourceCommit = (await Command("git", ["rev-parse", "HEAD"], output, "candidate-commit", deadline.Token)).Output.Trim();
-            Save(Path.Combine(output, "run-metadata.json"), new { token, startedUtc = DateTimeOffset.UtcNow, sourceCommit, dockurCommit = DockurCommit, profile = Profile, causalSingleVariableTest = false, kvm = false, cpuModel = CpuModel, recoveryMajor = 14, cpuFlags = CpuFlags, runId = Environment.GetEnvironmentVariable("GITHUB_RUN_ID"), server = Environment.GetEnvironmentVariable("GITHUB_SERVER_URL"), architecture = RuntimeInformation.ProcessArchitecture.ToString(), deadlineMinutes = 90 });
+            Save(Path.Combine(output, "run-metadata.json"), new { token, startedUtc = DateTimeOffset.UtcNow, sourceCommit, dockurCommit = DockurCommit, profile = Profile, causalSingleVariableTest = false, kvm = false, cpuModel = CpuModel, recoveryMajor = 14, cpuFlags = CpuFlags, runId = Environment.GetEnvironmentVariable("GITHUB_RUN_ID"), server = Environment.GetEnvironmentVariable("GITHUB_SERVER_URL"), architecture = RuntimeInformation.ProcessArchitecture.ToString(), deadlineMinutes = DiagnosticMinutes });
             var info = await Command("docker", ["info", "--format", "{{json .}}"], output, "docker-info", deadline.Token);
             using (var document = JsonDocument.Parse(info.Output))
             {
@@ -137,7 +139,7 @@ static class NativeDiagnostic
             using (var image = JsonDocument.Parse(imageInspect.Output))
                 state = state with { ImageId = image.RootElement[0].GetProperty("Id").GetString() };
             Save(statePath, state);
-            var create = await Command("docker", ["create", "--name", state.ContainerName, "--label", OwnerLabel + "=" + token, "--memory", "6g", "--memory-swap", "6g", "--cpus", "2", "--shm-size", "512m", "--log-opt", "max-size=8m", "--log-opt", "max-file=1", "--env", "KVM=N", "--env", "CPU_MODEL=" + CpuModel, "--env", "NETWORK=slirp", "--env", "DISPLAY=web", "--env", "MANUAL=N", "--env", "VERSION=14", "--env", "RAM_SIZE=4G", "--env", "CPU_CORES=2", "--env", "DISK_SIZE=64G", "--env", "DISK_TYPE=sata", "--env", "ARGUMENTS=-object iothread,id=io2", state.ImageTag], output, "docker-create", deadline.Token);
+            var create = await Command("docker", ["create", "--name", state.ContainerName, "--label", OwnerLabel + "=" + token, "--memory", "6g", "--memory-swap", "6g", "--cpus", "2", "--shm-size", "512m", "--log-opt", "max-size=8m", "--log-opt", "max-file=1", "--env", "KVM=N", "--env", "CPU_MODEL=" + CpuModel, "--env", "NETWORK=slirp", "--env", "DISPLAY=web", "--env", "MANUAL=N", "--env", "VERSION=14", "--env", "RAM_SIZE=4G", "--env", "CPU_CORES=2", "--env", "DISK_SIZE=64G", "--env", "DISK_TYPE=sata", "--env", "ARGUMENTS=" + DiagnosticArguments, state.ImageTag], output, "docker-create", deadline.Token);
             var id = create.Output.Trim();
             if (!System.Text.RegularExpressions.Regex.IsMatch(id, "^[0-9a-f]{64}$")) throw new InvalidOperationException("Docker did not return a container identity.");
             state = state with { ContainerId = id };
@@ -154,6 +156,7 @@ static class NativeDiagnostic
             {
                 deadline.Token.ThrowIfCancellationRequested();
                 await CaptureGuest(id, output, deadline.Token);
+                await CheckRecoveryBootProgress(id, output, deadline.Token);
                 var proofPath = Path.Combine(output, "guest-proof.log");
                 if (!diskPressureCaptured && File.Exists(proofPath) && File.ReadAllText(proofPath).Contains("[proof-start] disks", StringComparison.Ordinal))
                 {
@@ -181,7 +184,7 @@ static class NativeDiagnostic
         }
         catch (Exception exception)
         {
-            error = exception is OperationCanceledException ? "The explicit 90-minute diagnostic deadline or cancellation was reached." : exception.Message;
+            error = exception is OperationCanceledException ? $"The explicit {DiagnosticMinutes}-minute diagnostic deadline or cancellation was reached." : exception.Message;
             Console.Error.WriteLine(error);
         }
         finally
@@ -222,6 +225,7 @@ static class NativeDiagnostic
         }
         var good = JsonSerializer.Serialize(new { token = "validation", success = true, osVersion = "14.6.1", architecture = "x86_64", uid = 0, disk = "/dev/disk1", diskBytes = GuestDiskBytes, readOnly = false, systemExit = 0, diskArbitrationExit = 0, recoveryExit = 0, diskListExit = 0 });
         ValidateResult(good, "validation");
+        ValidateBootProgress();
         foreach (var invalid in new[] { good.Replace("14.6.1", "13.6.1"), good.Replace("x86_64", "arm64"), good.Replace("\"readOnly\":false", "\"readOnly\":true"), good.Replace("\"success\":true", "\"success\":false"), good.Replace("68719476736", "17179869184"), good.Replace("validation", "stale") })
         {
             try { ValidateResult(invalid, "validation"); } catch (InvalidOperationException) { continue; }
@@ -302,6 +306,9 @@ static class NativeDiagnostic
         entry = ReplaceOnce(entry, ". proc.sh       # Initialize processor\n", "");
         entry = ReplaceOnce(entry, ". init.sh       # Initialize system\n", ". init.sh       # Initialize system\n. cpu.sh        # Compose the exact guest CPU before any Apple download\n. proc.sh       # Compose the actual accelerator/CPU_FLAGS once\n" + TcgPreflight + "\n");
         entry = ReplaceOnce(entry, "trap - ERR\n", "[[ \"$KVM_OPTS\" == ' -accel tcg,thread=multi' && \"$CPU_FLAGS\" == '" + CpuFlags + "' && \"$CPU_OPTS\" == \"-cpu $CPU_FLAGS -smp $SMP\" ]] || { error 'Supported profile refuses a CPU/accelerator fallback.'; exit 1; }\ninfo '[supported-profile] accelerator=tcg cpu=Haswell-noTSX recovery=14; AVX/AVX2 preflight passed; native guest gates still pending'\n\ntrap - ERR\n");
+        entry = ReplaceOnce(entry, "\ntrap - ERR\n", "\nprintf '%s\\n' '[supported-profile] accelerator=tcg cpu=Haswell-noTSX recovery=14; AVX/AVX2 preflight passed; native guest gates still pending' >> \"$QEMU_DIR/native-stage.log\"\ntrap - ERR\n");
+        // Preserve sparse boot markers independently of the bounded, verbose Docker trace.
+        entry = ReplaceOnce(entry, "  -e 's/failed to load Boot/skipped Boot/g' \\\n", "  -e 's/failed to load Boot/skipped Boot/g' \\\n  -e '/^#\\[EB|LOG:HANDOFF TO XNU\\] /w /run/shm/kernel-handoffs.log' \\\n");
         var hookPath = Path.Combine("tools", "ci", "macos-native-readiness.sh");
         var hook = ReplaceOnce(File.ReadAllText(hookPath), "@@PROOF_TOKEN@@", token);
         var wrapper = File.ReadAllText(Path.Combine("tools", "ci", "macos-native-bootstrap.sh"));
@@ -386,6 +393,16 @@ static class NativeDiagnostic
         var add = PlistValue(PlistValue(document.Root!.Element("dict")!, "Kernel"), "Add");
         var expected = new[] { "Lilu.kext", "VMHide.kext", "VirtualSMC.kext", "WhateverGreen.kext", "VoodooPS2Controller.kext", "VoodooPS2Controller.kext/Contents/PlugIns/VoodooPS2Keyboard.kext", "AppleMCEReporterDisabler.kext" };
         if (!add.Elements("dict").Select(dict => PlistValue(dict, "BundlePath").Value).SequenceEqual(expected) || add.Elements("dict").Any(dict => PlistValue(dict, "Enabled").Name != "true")) throw new InvalidOperationException("Pinned Kernel.Add order/enabled contract mismatch.");
+        var nvram = PlistValue(PlistValue(PlistValue(document.Root!.Element("dict")!, "NVRAM"), "Add"), "7C436110-AB2A-4BBB-A880-FE41995C9F82");
+        if (PlistValue(nvram, "boot-args").Value != "keepsyms=1 debug=0x100 -lilubeta -wegbeta vmhState=enabled") throw new InvalidOperationException("Pinned kernel diagnostic arguments differ.");
+        const string diagnosticBoot = """
+              local diagnostic_boot='-v keepsyms=1 debug=0x108 serial=5 msgbuf=1048576 -lilubeta -wegbeta vmhState=enabled'
+              local boot_args="/plist/dict/key[.='NVRAM']/following-sibling::dict[1]/key[.='Add']/following-sibling::dict[1]/key[.='7C436110-AB2A-4BBB-A880-FE41995C9F82']/following-sibling::dict[1]/key[.='boot-args']/following-sibling::string[1]"
+              xmlstarlet ed -P -L -u "$boot_args" -v "$diagnostic_boot" "$CFG" || exit 12
+              [ "$(xmlstarlet sel -t -v "$boot_args" "$CFG")" = "$diagnostic_boot" ] || { error 'Kernel diagnostic arguments were not installed.'; exit 12; }
+
+            """;
+        boot = ReplaceOnce(boot, "  # DEBUG logging goes only to the OpenCore log file on the EFI partition.\n", diagnosticBoot + "  # DEBUG logging goes only to the OpenCore log file on the EFI partition.\n");
         boot = ReplaceOnce(boot, "  PLIST=\"/assets/config.plist\"\n", "  [ ! -e /custom.plist ] || { error 'Supported profile refuses an unverified custom OpenCore config!'; exit 12; }\n  PLIST=\"/assets/config.plist\"\n");
         boot = ReplaceOnce(boot, "  if [ -s \"$target\" ] && [ \"$previous\" = \"$current\" ]; then\n    IMG=\"$target\"\n    return 0\n  fi\n", "  # This owned compatibility probe always rebuilds; never trust a cached boot.img.\n");
         boot = ReplaceOnce(boot, "    echo \"VMHIDE=$vmhide\"\n", "    echo \"VMHIDE=$vmhide\"\n    echo \"PROFILE=tcg-haswell-sonoma\"\n");
@@ -417,6 +434,7 @@ static class NativeDiagnostic
         cat "$QEMU_DIR/cpu-preflight-negative.log"
         (( negative != 33 )) || { error 'AVX2-disabled negative control unexpectedly passed.'; exit 1; }
         info "[cpu-preflight] positive=$positive negative=$negative cpu=$CPU_FLAGS; actual AVX/AVX2 executed before Apple download"
+        printf '[cpu-preflight] positive=%s negative=%s cpu=%s; actual AVX/AVX2 executed before Apple download\n' "$positive" "$negative" "$CPU_FLAGS" > "$QEMU_DIR/native-stage.log"
         """.Replace("@@CPU_FLAGS@@", CpuFlags, StringComparison.Ordinal);
 
     static async Task ValidateTcgPreflight(string output, CancellationToken cancellation)
@@ -523,6 +541,9 @@ static class NativeDiagnostic
     {
         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);
+        var stage = await Command("docker", ["exec", id, "cat", "/run/shm/native-stage.log"], output, "capture-native-stage", cancellation, requireSuccess: false);
+        ReportCpuPreflight(output, stage.ExitCode == 0 ? stage.Output : logs.Output);
+        await Command("docker", ["exec", id, "head", "-c", "4096", "/run/shm/kernel-handoffs.log"], output, "capture-kernel-handoffs", cancellation, requireSuccess: false, retainSuccessful: true);
         foreach (var file in new[] { ("proof.log", "guest-proof.log"), ("result.json", "guest-result.json") })
         {
             var result = await Command("docker", ["exec", id, "cat", "/dev/shm/installstate/" + file.Item1], output, "capture-" + file.Item1, cancellation, requireSuccess: false);
@@ -530,11 +551,51 @@ static class NativeDiagnostic
         }
         // The immutable Recovery image is complete only after this staging marker.
         // Hash it once instead of rereading the image on every twenty-second poll.
-        if (logs.Output.Contains("[supported-profile] accelerator=tcg", StringComparison.Ordinal)
+        if ((logs.Output + stage.Output).Contains("[supported-profile] accelerator=tcg", StringComparison.Ordinal)
             && !File.Exists(Path.Combine(output, "guest-container-resources.last-success.json")))
             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 || exit 1; 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, retainSuccessful: true);
     }
 
+    static void ReportCpuPreflight(string output, string logs)
+    {
+        var receipt = Path.Combine(output, "cpu-preflight-runtime.json");
+        if (File.Exists(receipt)) return;
+        var expectedSuffix = " cpu=" + CpuFlags + "; actual AVX/AVX2 executed before Apple download";
+        foreach (var line in logs.Split('\n'))
+        {
+            var match = System.Text.RegularExpressions.Regex.Match(line, @"\[cpu-preflight\] positive=33 negative=([0-9]{1,3})");
+            if (!match.Success || match.Groups[1].Value == "33" || !line[(match.Index + match.Length)..].StartsWith(expectedSuffix, StringComparison.Ordinal)) continue;
+            var sourceMarker = match.Value + expectedSuffix;
+            var marker = "[cpu-preflight] positive=33 negative=" + match.Groups[1].Value + " accelerator=tcg cpu=" + CpuModel + " instructions=AVX/AVX2";
+            Console.WriteLine(marker);
+            Save(receipt, new { marker, markerSha256 = Hash(Encoding.UTF8.GetBytes(sourceMarker)), capturedUtc = DateTimeOffset.UtcNow, readinessGateSatisfied = false });
+            return;
+        }
+    }
+
+    static int KernelHandoffs(string logs) => logs.Split('\n').Count(line => line.Trim().StartsWith("#[EB|LOG:HANDOFF TO XNU] ", StringComparison.Ordinal));
+
+    static void ValidateBootProgress()
+    {
+        const string handoff = "#[EB|LOG:HANDOFF TO XNU] _\r\n";
+        foreach (var (logs, count) in new[] { ("", 0), ("BdsDxe: starting Boot0002\n", 0), (handoff, 1), (handoff + handoff, 2), ("source says \"" + handoff, 0), ("#[EB|LOG:HANDOFF TO XNU-ish] _\n", 0) })
+            if (KernelHandoffs(logs) != count) throw new InvalidOperationException("Recovery boot-progress parser accepted missing, quoted or malformed markers.");
+    }
+
+    static async Task CheckRecoveryBootProgress(string id, string output, CancellationToken cancellation)
+    {
+        var retained = Path.Combine(output, "capture-kernel-handoffs.last-success.stdout.log");
+        var count = KernelHandoffs(File.ReadAllText(File.Exists(retained) ? retained : Path.Combine(output, "container.stdout.log")));
+        Save(Path.Combine(output, "recovery-boot-progress.json"), new { kernelHandoffs = count, unexpectedRepeat = count >= 2, capturedUtc = DateTimeOffset.UtcNow });
+        if (count >= 2) throw new InvalidOperationException("Recovery returned to kernel boot before readiness; repeated handoff detected. See serial/exception logs; this does not identify the reset cause.");
+        if (!File.ReadAllText(Path.Combine(output, "capture-native-stage.stdout.log")).Contains("[supported-profile] accelerator=tcg", StringComparison.Ordinal)) return;
+        using var deadline = CancellationTokenSource.CreateLinkedTokenSource(cancellation);
+        deadline.CancelAfter(TimeSpan.FromSeconds(8));
+        var monitor = await Command("docker", ["exec", id, "sh", "-c", "test -S /run/shm/monitor.sock || exit 1; printf 'info status\\n' | /usr/bin/timeout -s KILL 5 /usr/bin/nc.openbsd -q 1 -w 2 -U /run/shm/monitor.sock"], output, "recovery-vm-status", deadline.Token, requireSuccess: false);
+        if (monitor.ExitCode == 0 && System.Text.RegularExpressions.Regex.IsMatch(monitor.Output, @"(?m)^VM status: (shutdown|paused|internal-error|guest-panicked)(?:\s+\([^\r\n]*\))?\r?$"))
+            throw new InvalidOperationException("Recovery VM halted before readiness. The first reset was retained for exception/monitor evidence.");
+    }
+
     static async Task CapturePressure(string id, string output, string phase, CancellationToken cancellation)
     {
         using var snapshotDeadline = CancellationTokenSource.CreateLinkedTokenSource(cancellation);