diff --git a/.gitea/workflows/macos-native-diagnostic.yaml b/.gitea/workflows/macos-native-diagnostic.yaml index bab3682..1f02a73 100644 --- a/.gitea/workflows/macos-native-diagnostic.yaml +++ b/.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" diff --git a/docs/macos-native-diagnostic.md b/docs/macos-native-diagnostic.md index 8b8dce3..de15173 100644 --- a/docs/macos-native-diagnostic.md +++ b/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 diff --git a/tools/ci/MacOsNativeDiagnostic.cs b/tools/ci/MacOsNativeDiagnostic.cs index 27c21b9..97d5705 100644 --- a/tools/ci/MacOsNativeDiagnostic.cs +++ b/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);