diff --git a/Resources/provision.sh b/Resources/provision.sh index 7604e30..f0824b8 100755 --- a/Resources/provision.sh +++ b/Resources/provision.sh @@ -124,8 +124,16 @@ fi # -------------------------------------------------------------------------- log "ensuring /usr/local/bin exists and is on PATH for non-login shells" mkdir -p /usr/local/bin -chown root:wheel /usr/local /usr/local/bin -chmod 755 /usr/local /usr/local/bin +# Best-effort, deliberately: on a stock macOS 27 install /usr/local already +# exists, already is root:wheel 755, and is SIP-protected — so chown and chmod +# on it fail with "Operation not permitted" even as root. The directory is +# already exactly as we want it, so treating that refusal as a build failure +# would abort provisioning over a no-op. When /usr/local really was ours to +# create, these succeed. +chown root:wheel /usr/local /usr/local/bin 2>/dev/null \ + || warn "could not chown /usr/local (system-owned and SIP-protected; already correct)" +chmod 755 /usr/local /usr/local/bin 2>/dev/null \ + || warn "could not chmod /usr/local (system-owned and SIP-protected; already correct)" ZSHENV_MARKER="# gitea-macos-runner: ensure /usr/local/bin on PATH" if [ ! -f /etc/zshenv ] || ! grep -qF "$ZSHENV_MARKER" /etc/zshenv 2>/dev/null; then diff --git a/Sources/RunnerHost/ImageBuilder.swift b/Sources/RunnerHost/ImageBuilder.swift index 8d5f521..3b09e1d 100644 --- a/Sources/RunnerHost/ImageBuilder.swift +++ b/Sources/RunnerHost/ImageBuilder.swift @@ -79,9 +79,29 @@ public struct ImageBuilder: Sendable { // Checked against the filesystem rather than `store.image(named:)`: a // half-built bundle from a previous failed run is exactly the thing this - // needs to catch, and it would not read back as a valid image. + // needs to look at, and it would not read back as a valid image. let bundleURL = store.imagesDir.appendingPathComponent(name, isDirectory: true) if FileManager.default.fileExists(atPath: bundleURL.path) { + let existing = VMBundle(rootURL: bundleURL) + let existingConfig = try? existing.loadConfig() + + // Installed but never provisioned: resume rather than throw away an + // hour of installing. This is safe precisely because provisioning is + // what got skipped — the guest has never been booted, so its *true* + // first boot is still ahead of it and `VZMacGuestProvisioningOptions` + // will still be evaluated. (macOS only honours those options on the + // first boot after a restore; a guest that already booted once has + // consumed that chance, which is the ambiguous case handled by the + // SSH probe in `bootProvisionAndSeal`.) + if existing.isComplete(), let existingConfig, !existingConfig.provisioned { + progress?( + .note("image '\(name)' already installed — resuming first boot + provisioning")) + try await firstBootAndProvision( + bundle: existing, config: config, isResume: true, progress: progress) + progress?(.done) + return + } + throw CoreError.configInvalid( "image '\(name)' already exists at \(bundleURL.path). " + "Delete it first (`image delete \(name)`), or build under a different --name." @@ -370,19 +390,47 @@ public struct ImageBuilder: Sendable { } installer.install { result in + // `VZVirtualMachine` holds an exclusive lock on the bundle's + // auxiliary storage (nvram.bin) for its whole lifetime, and + // releases it in `dealloc`. The next thing the caller does is + // build a *second* VM over the same bundle for first boot, so + // if this one is still alive at that moment the new one fails + // validation with "Failed to lock auxiliary storage" — which + // is exactly what operators hit. + // + // Hence: drop every strong reference here, on the queue that + // owns these objects... + session.observation?.invalidate() session.observation = nil session.installer = nil session.virtualMachine = nil - switch result { - case .success: - progress?(1.0) - continuation.resume() - case .failure(let error): - continuation.resume(throwing: VMInstance.mapVZError(error)) + + // ...and resume the caller only from a *later* block on that + // same serial queue. Returning from this handler is what lets + // the framework's own frame unwind and release its references, + // and a serial queue guarantees that has happened before the + // block below runs. Resuming inline instead would race the + // deallocation against the first-boot VM. + let boxedResult = UncheckedBox(result) + queue.async { + switch boxedResult.value { + case .success: + progress?(1.0) + continuation.resume() + case .failure(let error): + continuation.resume(throwing: VMInstance.mapVZError(error)) + } } } } } + + // One more hop to the back of the same queue: by the time an empty block + // gets to run, everything enqueued above it — including the release of + // the last reference to the VM — has finished. + await withCheckedContinuation { (continuation: CheckedContinuation) in + queue.async { continuation.resume() } + } } /// Boots the freshly installed guest, gets it onto the network, and hands it @@ -416,10 +464,14 @@ public struct ImageBuilder: Sendable { /// - Parameters: /// - bundle: The installed bundle. /// - config: Guest credentials and timeouts. + /// - isResume: `true` when this is picking up a bundle that was installed + /// by an earlier run. Only affects the advice given if the guest never + /// answers on SSH — see ``bootProvisionAndSeal(bundle:config:startOptions:isFirstBoot:isResume:xcodeXIPPath:progress:)``. /// - progress: Stage callback. public func firstBootAndProvision( bundle: VMBundle, config: RunnerConfig, + isResume: Bool = false, progress: (@Sendable (ImageBuildStage) -> Void)? = nil ) async throws { guard #available(macOS 27.0, *) else { @@ -460,6 +512,7 @@ public struct ImageBuilder: Sendable { config: config, startOptions: startOptions, isFirstBoot: true, + isResume: isResume, xcodeXIPPath: nil, progress: progress ) @@ -504,6 +557,7 @@ public struct ImageBuilder: Sendable { config: config, startOptions: nil, isFirstBoot: false, + isResume: false, xcodeXIPPath: xcodeXIPPath, progress: progress ) @@ -519,6 +573,7 @@ public struct ImageBuilder: Sendable { config: RunnerConfig, startOptions: VZMacOSVirtualMachineStartOptions?, isFirstBoot: Bool, + isResume: Bool, xcodeXIPPath: String?, progress: (@Sendable (ImageBuildStage) -> Void)? ) async throws { @@ -527,15 +582,11 @@ public struct ImageBuilder: Sendable { let bootTimeout = Duration.seconds(max(60, config.scheduler.bootTimeoutSeconds)) progress?(.firstBoot) - let instance = try VMInstance(bundle: bundle, label: "image:\(bundle.name)", headless: true) - - do { - try await instance.start(options: startOptions) - } catch { - throw CoreError.provisioningFailed( - "could not boot image '\(bundle.name)': \(error)" - ) - } + let instance = try await Self.bootRetryingAuxStorageLock( + bundle: bundle, + startOptions: startOptions, + progress: progress + ) let address: String do { @@ -552,6 +603,37 @@ public struct ImageBuilder: Sendable { } catch { _ = await instance.requestStopThenForce() if isFirstBoot { + // A resumed build has a second candidate cause, and it is + // unrecoverable rather than merely slow: macOS evaluates + // `VZMacGuestProvisioningOptions` only on the first boot after a + // restore. If the earlier run got far enough to boot the guest — + // which the bundle on disk cannot tell us — that chance is spent, + // and no amount of retrying will produce an account or sshd. + // Reaching SSH is the only way to distinguish the two, so this is + // said here, after the probe has failed, rather than refusing to + // resume in the first place. + if isResume { + throw CoreError.provisioningFailed( + """ + the resumed guest never became reachable over SSH within \ + \(config.scheduler.bootTimeoutSeconds)s. + + Either the guest is older than macOS 27 (see below), or an earlier run \ + already consumed its first boot — macOS applies automated Setup Assistant \ + provisioning only once, on the first boot after a restore, so a guest that \ + has booted before can no longer be provisioned unattended. + + There is no way to re-arm it: delete the image and build again with a \ + macOS 27 or newer restore image. + + gitea-macos-runner image delete \(bundle.name) + gitea-macos-runner image build --ipsw + + Underlying error: \(error) + """ + ) + } + // The most likely cause by far, and the one with no diagnostic of // its own: a pre-27 guest accepts the provisioning options and // ignores them, so it sits at Setup Assistant with no account and @@ -624,6 +706,64 @@ public struct ImageBuilder: Sendable { /// Full name for the account Setup Assistant automation creates. static let guestAccountFullName = "Gitea Runner" + /// Creates and starts the VM, tolerating a still-held auxiliary-storage lock. + /// + /// `VZVirtualMachine` takes an exclusive lock on the bundle's `nvram.bin` + /// and gives it up only when the object deallocates. `install(bundle:…)` + /// now drains its queue before returning, so its installer VM is gone by + /// the time we get here — but "gone" is an ARC and Objective-C runtime + /// property, and a stray autorelease pool or a framework thread that has + /// not yet unwound can still be holding the last reference for a moment. + /// The failure that produces is not ambiguous and not persistent: + /// + /// Invalid virtual machine configuration. Failed to lock auxiliary storage. + /// + /// So it is retried, briefly and only for that message. Anything else fails + /// on the first attempt, because a genuinely invalid configuration does not + /// become valid by waiting. + static func bootRetryingAuxStorageLock( + bundle: VMBundle, + startOptions: VZMacOSVirtualMachineStartOptions?, + progress: (@Sendable (ImageBuildStage) -> Void)?, + timeout: Duration = .seconds(30), + pollInterval: Duration = .seconds(2) + ) async throws -> VMInstance { + let started = ContinuousClock.now + var announced = false + + while true { + do { + let instance = try VMInstance( + bundle: bundle, label: "image:\(bundle.name)", headless: true) + try await instance.start(options: startOptions) + return instance + } catch { + guard isAuxiliaryStorageLockFailure(error), + ContinuousClock.now - started < timeout + else { + throw CoreError.provisioningFailed( + "could not boot image '\(bundle.name)': \(error)" + ) + } + if !announced { + announced = true + progress?(.note("waiting for installer to release the VM bundle…")) + } + try await Task.sleep(for: pollInterval) + } + } + } + + /// Whether an error is the transient "someone else still has nvram.bin". + /// + /// Matched on the message because the framework reports it as a generic + /// `VZError.invalidVirtualMachineConfiguration` with the detail only in the + /// description — there is no distinct code to switch on. + static func isAuxiliaryStorageLockFailure(_ error: any Error) -> Bool { + let text = "\(error)".lowercased() + return text.contains("auxiliary storage") && text.contains("lock") + } + /// Polls `/var/db/dhcpd_leases` until the guest's MAC appears. /// /// - Parameters: diff --git a/Sources/gitea-macos-runner/CommandImage.swift b/Sources/gitea-macos-runner/CommandImage.swift index a87538b..96811d0 100644 --- a/Sources/gitea-macos-runner/CommandImage.swift +++ b/Sources/gitea-macos-runner/CommandImage.swift @@ -64,7 +64,12 @@ struct ImageCommand: AsyncParsableCommand { let store = VMStore(config: config) try store.ensureLayout() - if try store.image(named: name) != nil { + // Only a *finished* image blocks a rebuild. An installed but + // unprovisioned bundle is an hour of work that `ImageBuilder.build` + // knows how to resume, so it must get the chance to say so. + if let existing = try store.image(named: name), + (try? existing.loadConfig())?.provisioned == true + { throw ValidationError( "image '\(name)' already exists — delete it first with `image delete \(name)`" ) @@ -101,7 +106,10 @@ struct ImageCommand: AsyncParsableCommand { // it to exit is its own deadlock. See `VZAppRuntime.run`. VZAppRuntime.flushAndExit(1) } - printer.finish("done") + // Just seals the line: the builder's own `.done` stage has + // already printed it, and saying it twice down a pipe reads + // like something ran twice. + printer.finish() print("built image '\(imageName)'") print("next: gitea-macos-runner vm boot --image \(imageName)") @@ -281,7 +289,30 @@ struct ImageCommand: AsyncParsableCommand { if case .note(let text) = stage { printer.line(text) } else { - printer.update(describe(stage)) + printer.update(describe(stage), group: group(of: stage)) + } + } + + /// The stage a status line belongs to, ignoring its varying payload. + /// + /// Two lines share a group exactly when one is meant to overwrite the + /// other. Crossing a group boundary seals the previous line instead, which + /// is why `installing macOS … 100%` survives into scrollback rather than + /// being replaced by `first boot + guest provisioning…`. + static func group(of stage: ImageBuildStage) -> String { + switch stage { + case .downloadingIPSW: return "download" + case .preparing: return "preparing" + case .loadingRestoreImage: return "loading" + case .creatingBundle: return "bundle" + case .note: return "note" + case .installing: return "install" + case .firstBoot: return "firstBoot" + // Each provisioning step is its own headline — "installing Node.js" + // should not erase "downloading gitea-runner". + case .provisioning(let step): return "provisioning:\(step)" + case .finalizing: return "finalizing" + case .done: return "done" } } diff --git a/Sources/gitea-macos-runner/Main.swift b/Sources/gitea-macos-runner/Main.swift index 3c853a9..de5d3ea 100644 --- a/Sources/gitea-macos-runner/Main.swift +++ b/Sources/gitea-macos-runner/Main.swift @@ -136,6 +136,7 @@ final class OnceFlag: @unchecked Sendable { final class ProgressPrinter: @unchecked Sendable { private let lock = NSLock() private var lastLine = "" + private var lastGroup: String? /// Whether carriage-return rewriting means anything here. /// @@ -147,17 +148,31 @@ final class ProgressPrinter: @unchecked Sendable { private let isInteractive = isatty(fileno(stderr)) == 1 /// Rewrites the current line. - func update(_ line: String) { + /// + /// - Parameters: + /// - line: The text to show. + /// - group: Names the stage this line belongs to. When it changes, the + /// outgoing stage's final line is sealed with a newline rather than + /// overwritten — so `installing macOS [####] 100%` is still on screen + /// when the operator scrolls back to work out where the last hour went, + /// instead of being replaced by whatever came next. + func update(_ line: String, group: String? = nil) { lock.lock() defer { lock.unlock() } + + if let group, let lastGroup, group != lastGroup, !lastLine.isEmpty, isInteractive { + emit("\n") + lastLine = "" + } + if let group { lastGroup = group } + guard line != lastLine else { return } lastLine = line guard isInteractive else { - FileHandle.standardError.write(Data((line + "\n").utf8)) + emit(line + "\n") return } - let padding = String(repeating: " ", count: max(0, 78 - line.count)) - FileHandle.standardError.write(Data(("\r" + line + padding).utf8)) + emit("\r" + line + pad(line)) } /// Emits a standalone line without losing the status line under it. @@ -177,12 +192,20 @@ final class ProgressPrinter: @unchecked Sendable { lock.lock() defer { lock.unlock() } if let line { - let padding = isInteractive ? String(repeating: " ", count: max(0, 78 - line.count)) : "" - let prefix = isInteractive ? "\r" : "" - FileHandle.standardError.write(Data((prefix + line + padding + "\n").utf8)) + emit((isInteractive ? "\r" : "") + line + (isInteractive ? pad(line) : "") + "\n") } else if !lastLine.isEmpty, isInteractive { - FileHandle.standardError.write(Data("\n".utf8)) + emit("\n") } lastLine = "" } + + /// Trailing blanks that erase whatever the previous, longer line left behind. + private func pad(_ line: String) -> String { + String(repeating: " ", count: max(0, 78 - line.count)) + } + + /// Writes straight to the descriptor. Call with ``lock`` held. + private func emit(_ text: String) { + FileHandle.standardError.write(Data(text.utf8)) + } } diff --git a/docs/troubleshooting.md b/docs/troubleshooting.md index 696e968..3a97675 100644 --- a/docs/troubleshooting.md +++ b/docs/troubleshooting.md @@ -35,6 +35,8 @@ gitea-macos-runner service status | `image build` appears to hang during install | Normal — macOS install is slow | Wait. **Do not stop the VM mid-install**; if you did, delete the image and rebuild | | `image build` prints its banner and then nothing, at 0% CPU | Old build: the build task was queued behind the `NSApplication` run loop and never started | Upgrade — the task is now detached. Stage lines should appear within seconds | | `image build` stuck at `loading restore image metadata…` | A truncated or partial `.ipsw` — the framework blocks rather than failing | Upgrade (the file is now size- and magic-checked first); re-download the IPSW | +| `provisioning failed: … Failed to lock auxiliary storage` after install | The installer's VM had not yet released `nvram.bin` when first boot started | Upgrade — the install now drains its queue and first boot retries for 30 s. Re-run `image build`; it resumes | +| `image build` says `image 'default' already exists` after a failed first boot | Old build: an installed-but-unprovisioned bundle was treated as a finished image | Upgrade — `image build` now resumes it instead of refusing | --- @@ -441,7 +443,7 @@ minutes, longer on slower storage). The install phase is largely silent. **Fix.** **Wait, and do not stop the VM mid-install.** Interrupting the installer leaves the disk image in an undefined state; the resulting image may boot and then fail in confusing ways later. -There is no resume. +There is no resume from a *partial* install — only from a complete one (see the next section). If you did interrupt it, or the build genuinely failed: @@ -453,3 +455,61 @@ gitea-macos-runner image build --ipsw --name Before rebuilding, verify the IPSW is complete and matches your host architecture (Apple Silicon) and version requirement (macOS 27+ for unattended provisioning), and that you have enough free disk for the IPSW plus the target disk size. + +--- + +## `Failed to lock auxiliary storage` right after the install finishes + +**Symptom.** The macOS install runs to 100%, then: + +``` +first boot + guest provisioning… +error: provisioning failed: could not boot image 'default': provisioning failed: Invalid +virtual machine configuration. Failed to lock auxiliary storage. +``` + +**Cause.** A `VZVirtualMachine` holds an exclusive lock on its bundle's `nvram.bin` for its entire +lifetime and releases it in `dealloc`. `VZMacOSInstaller` owns a VM of its own, and older builds +resumed the caller from inside the installer's completion handler — before the framework's frame +had unwound and dropped the last reference. First boot then constructed a *second* VM over the same +bundle and lost the race. + +**Fix.** Upgrade. Two changes address it: + +- The install now tears down its VM on its own serial queue and resumes the caller only from a + later block on that queue, so the installer's VM is deallocated before `install()` returns. +- First boot retries specifically on this failure for up to 30 s (2 s apart), printing + `waiting for installer to release the VM bundle…`. Any other configuration error still fails + immediately — an invalid configuration does not become valid by waiting. + +Nothing is lost when it does happen: the install is complete, so re-running `image build` resumes. + +--- + +## `image build` resumes an installed-but-unprovisioned image + +**Symptom.** A previous `image build` finished installing macOS and then failed at first boot or +provisioning. Re-running it prints: + +``` +image default already installed — resuming first boot + provisioning +``` + +**This is intended.** An `image build` that fails after the install has left an hour of work on +disk, and throwing it away to redo an identical install is not a reasonable default. When the +bundle exists, is complete, and is not yet marked provisioned, the install phase is skipped and the +build goes straight to first boot. + +It is safe because provisioning is exactly what did *not* happen: the guest has never been booted, +so its first boot is still ahead of it and `VZMacGuestProvisioningOptions` — which macOS evaluates +only on the first boot after a restore — still applies. + +**The one ambiguous case.** The bundle on disk cannot say whether an earlier run got far enough to +*boot* the guest. If it did, that single chance at automated Setup Assistant is spent. Rather than +guess, the resume boots and waits for SSH: if the guest answers, provisioning was never applied and +the build continues normally. Only if SSH times out does it stop, and it then tells you so +explicitly — that state is unrecoverable, and the fix is `image delete` followed by a fresh build. + +An image that is already `provisioned` is untouched; `image build` still refuses with +`image '' already exists`. To re-run provisioning on a finished image, use +`gitea-macos-runner image provision ` instead.