From 6b0c01b74be2af93c32fab34a563684d9502f487 Mon Sep 17 00:00:00 2001 From: Andrew Moore Date: Fri, 7 Aug 2026 05:11:01 -0700 Subject: [PATCH] Merge nucleic/upbeat-opal-viper-cc8l into main --- Sources/RunnerCore/Config.swift | 15 ++- Sources/RunnerCore/SSHExec.swift | 106 ++++++++++++++++--- Sources/RunnerHost/Doctor.swift | 131 +++++++++++++++++++++++- Sources/RunnerHost/Orchestrator.swift | 95 +++++++++++++++-- Tests/RunnerCoreTests/ConfigTests.swift | 2 +- docs/DESIGN.md | 14 ++- docs/setup.md | 2 +- docs/troubleshooting.md | 58 +++++++++++ 8 files changed, 395 insertions(+), 28 deletions(-) diff --git a/Sources/RunnerCore/Config.swift b/Sources/RunnerCore/Config.swift index 7b308cd..5e3267a 100644 --- a/Sources/RunnerCore/Config.swift +++ b/Sources/RunnerCore/Config.swift @@ -140,6 +140,19 @@ public struct RunnerConfig: Codable, Sendable, Equatable { /// Ceiling on boot + DHCP lease + SSH readiness before a slot is /// declared dead and recycled. + /// + /// - Important: This must exceed the guest's *worst-case* time to become + /// SSH-ready, not its typical one. A clone that is still booting when + /// this expires is destroyed and replaced by another clone that starts + /// from zero — and because the replacement adds load to an already + /// contended host, the next boot is slower still. Set too tight, this + /// is not a timeout but a livelock: the daemon boots forever and no + /// runner ever registers. + /// + /// A guest sharing an Apple Silicon host with other Virtualization + /// guests can take several minutes to reach `sshd`, so the default is + /// deliberately generous. A genuinely wedged guest still gets caught; + /// it just takes longer to notice, which is the cheaper mistake. public var bootTimeoutSeconds: Int public init( @@ -147,7 +160,7 @@ public struct RunnerConfig: Codable, Sendable, Equatable { pollIntervalSeconds: Int = 5, reconcileIntervalSeconds: Int = 300, jobTimeoutMinutes: Int = 120, - bootTimeoutSeconds: Int = 300 + bootTimeoutSeconds: Int = 900 ) { self.maxConcurrentVMs = maxConcurrentVMs self.pollIntervalSeconds = pollIntervalSeconds diff --git a/Sources/RunnerCore/SSHExec.swift b/Sources/RunnerCore/SSHExec.swift index 0ddde45..88ea030 100644 --- a/Sources/RunnerCore/SSHExec.swift +++ b/Sources/RunnerCore/SSHExec.swift @@ -179,7 +179,7 @@ public final class SSHExecutor: GuestExecutor, @unchecked Sendable { /// otherwise read from the terminal exits instead of hanging. /// - timeout: Wall-clock ceiling on the whole exchange. /// - Throws: ``SSHTransportError`` for connect/auth problems (which - /// ``waitForSSH(host:port:username:password:timeout:pollInterval:)`` needs + /// ``waitForSSH(host:port:username:password:timeout:pollInterval:reportInterval:onAttemptFailure:)`` needs /// to tell apart), or ``CoreError/timeout(_:)`` when the ceiling elapses. func execute(_ command: String, stdin: Data?, timeout: Duration) async throws -> SSHCommandResult { let group = MultiThreadedEventLoopGroup.singleton @@ -189,7 +189,18 @@ public final class SSHExecutor: GuestExecutor, @unchecked Sendable { let host = self.host let port = self.port + // The `timeout` argument below cannot bound the connect: its watchdog is + // scheduled on the channel's event loop, which does not exist until the + // connect has already succeeded. A booting guest answers ARP long before + // it answers SYNs, so without an explicit ceiling here each probe hangs + // for the platform default — around 75 s — and `waitForSSH` gets a + // handful of attempts inside its budget instead of one every couple of + // seconds. Bounded by `timeout` so a caller asking for less than the + // default gets what it asked for. + let connectTimeout = min(timeout, Self.defaultConnectTimeout) + let bootstrap = ClientBootstrap(group: group) + .connectTimeout(.nanoseconds(Self.nanoseconds(connectTimeout))) .channelOption(ChannelOptions.socketOption(.tcp_nodelay), value: 1) .channelInitializer { channel in channel.eventLoop.makeCompletedFuture { @@ -288,7 +299,14 @@ public final class SSHExecutor: GuestExecutor, @unchecked Sendable { "'" + value.replacingOccurrences(of: "'", with: "'\\''") + "'" } - private static func nanoseconds(_ duration: Duration) -> Int64 { + /// Ceiling on the TCP connect alone. + /// + /// Long enough that a loaded host's slow-but-working connect is not cut + /// short, short enough that a silently dropped SYN costs one poll interval + /// rather than the platform's ~75 s. + static let defaultConnectTimeout = Duration.seconds(10) + + static func nanoseconds(_ duration: Duration) -> Int64 { let components = duration.components let seconds = components.seconds.multipliedReportingOverflow(by: 1_000_000_000) guard !seconds.overflow else { return .max } @@ -302,7 +320,7 @@ public final class SSHExecutor: GuestExecutor, @unchecked Sendable { // MARK: - Transport failures /// Connection-level failures, kept distinct from ``CoreError`` so that -/// ``waitForSSH(host:port:username:password:timeout:pollInterval:)`` can tell +/// ``waitForSSH(host:port:username:password:timeout:pollInterval:reportInterval:onAttemptFailure:)`` can tell /// "sshd is not up yet" (retry) from "the password is wrong" (give up now). enum SSHTransportError: Error { /// No TCP connection could be established. @@ -568,12 +586,42 @@ final class ExecChannelHandler: ChannelInboundHandler { } } +/// One failed probe, handed to ``waitForSSH(host:port:username:password:timeout:pollInterval:reportInterval:onAttemptFailure:)``'s +/// reporting callback. +/// +/// Carries a rendered `error` rather than the `Error` itself so the whole value +/// is `Sendable` and can cross into a logger on another isolation domain. +public struct SSHWaitAttempt: Sendable { + /// 1-based probe count. + public let attempt: Int + /// Time since the wait began. + public let elapsed: Duration + /// The failure, rendered through `asCoreError` where applicable so the + /// Local Network privacy hint survives. + public let error: String + + public init(attempt: Int, elapsed: Duration, error: String) { + self.attempt = attempt + self.elapsed = elapsed + self.error = error + } +} + /// Blocks until a guest accepts an authenticated SSH session, or the deadline /// passes. /// /// Called after a DHCP lease appears but before any provisioning: a fresh guest /// answers on port 22 only once `launchd` has started `sshd`, which lags the -/// lease by tens of seconds. +/// lease by tens of seconds — and by minutes on a host running several guests +/// at once. +/// +/// - Important: A caller whose own supervisor also enforces a deadline must pass +/// a `timeout` strictly smaller than the supervisor's *remaining* budget. +/// Otherwise the supervisor always fires first, this function is cancelled +/// mid-`Task.sleep`, and the `CoreError.timeout` below — the only place the +/// last error is ever rendered — is never thrown. That is why failures are +/// also reported as they happen via `onAttemptFailure` rather than solely at +/// the end. /// /// - Parameters: /// - host: Guest IP. @@ -582,6 +630,11 @@ final class ExecChannelHandler: ChannelInboundHandler { /// - password: Guest password. /// - timeout: Overall ceiling. /// - pollInterval: Delay between attempts. Defaults to 2 s. +/// - reportInterval: Floor on the gap between `onAttemptFailure` calls. +/// Defaults to 30 s. The first failure is always reported. +/// - onAttemptFailure: Called for the first failure and then no more often +/// than `reportInterval`, so a boot that is merely slow is visible while it +/// is happening instead of only in the post-mortem. /// - Throws: ``CoreError/timeout(_:)`` if the guest never answers. public func waitForSSH( host: String, @@ -589,13 +642,18 @@ public func waitForSSH( username: String, password: String, timeout: Duration, - pollInterval: Duration = .seconds(2) + pollInterval: Duration = .seconds(2), + reportInterval: Duration = .seconds(30), + onAttemptFailure: (@Sendable (SSHWaitAttempt) -> Void)? = nil ) async throws { let executor = SSHExecutor(host: host, port: port, username: username, password: password) let started = ContinuousClock.now var lastError: Error? + var attempt = 0 + var lastReport: ContinuousClock.Instant? while true { + attempt += 1 do { // A real authenticated session running a trivial command, not a bare // TCP probe: sshd binds the port before it is ready to authenticate, @@ -616,20 +674,36 @@ public func waitForSSH( lastError = error } + if let onAttemptFailure, let lastError { + let now = ContinuousClock.now + // Every probe of a guest that is still booting fails, so reporting + // each one would bury the log. First one, then a heartbeat. + if lastReport.map({ now - $0 >= reportInterval }) ?? true { + lastReport = now + onAttemptFailure( + SSHWaitAttempt( + attempt: attempt, + elapsed: now - started, + error: renderSSHWaitError(lastError) + ) + ) + } + } + guard ContinuousClock.now - started < timeout else { break } try await Task.sleep(for: pollInterval) guard ContinuousClock.now - started < timeout else { break } } - // Rendered through `asCoreError` rather than interpolated raw: a connect - // failure is where the Local Network privacy hint lives, and the timeout - // message is the *only* place most operators will ever see the last error. - let detail: String - if let lastError { - let rendered = (lastError as? SSHTransportError).map { "\($0.asCoreError)" } ?? "\(lastError)" - detail = "; last error: \(rendered)" - } else { - detail = "" - } - throw CoreError.timeout("ssh on \(host):\(port)\(detail)") + let detail = lastError.map { "; last error: \(renderSSHWaitError($0))" } ?? "" + throw CoreError.timeout("ssh on \(host):\(port) after \(attempt) attempts\(detail)") +} + +/// Renders a probe failure for humans. +/// +/// Goes through `asCoreError` rather than interpolating raw: a connect failure +/// is where the Local Network privacy hint lives, and these strings are the only +/// place most operators will ever see why a boot stalled. +private func renderSSHWaitError(_ error: Error) -> String { + (error as? SSHTransportError).map { "\($0.asCoreError)" } ?? "\(error)" } diff --git a/Sources/RunnerHost/Doctor.swift b/Sources/RunnerHost/Doctor.swift index ae2137c..fd844a6 100644 --- a/Sources/RunnerHost/Doctor.swift +++ b/Sources/RunnerHost/Doctor.swift @@ -92,7 +92,11 @@ public enum Doctor { /// same verb the real download uses, because the presigned redirect /// target is signed per method. Catches a version bump that no longer /// has a darwin-arm64 asset. - /// 10. **Local Network privacy**. Passes when a subnet allowlist is set in + /// 10. **Guest SSH**, against whichever slot currently holds a DHCP lease — + /// the one check that exercises host → vmnet → guest `sshd` → password + /// auth end to end. Informational when no guest is up, since `doctor` + /// will not boot one. + /// 11. **Local Network privacy**. Passes when a subnet allowlist is set in /// `com.apple.network.local-network`; otherwise informational. On /// macOS 15+ the first attempt to reach a guest over the NAT link can /// be blocked by the Local Network permission prompt, which a @@ -107,6 +111,7 @@ public enum Doctor { checks.append(checkLoginKeychain()) checks.append(contentsOf: await checkGitea(config: config)) checks.append(await checkRunnerDownloadURL(config: config)) + checks.append(await checkGuestSSH(config: config)) checks.append(localNetworkNote()) return checks } @@ -148,6 +153,7 @@ public enum Doctor { checks.append(checkLoginKeychain()) checks.append(contentsOf: await checkGitea(config: loaded)) checks.append(await checkRunnerDownloadURL(config: loaded)) + checks.append(await checkGuestSSH(config: loaded)) checks.append(contentsOf: checkTokenFilePermissions(config: loaded)) checks.append(localNetworkNote()) return checks @@ -523,6 +529,129 @@ public enum Doctor { ] } + /// Whether a guest that is up right now actually accepts an SSH session. + /// + /// Every other check in this file inspects the host. This one exercises the + /// exact path the boot sequence depends on and that nothing else proves: + /// host → vmnet → guest `sshd` → password auth with `guest.username` / + /// `guest.password`. It is the difference between "the daemon never got a + /// runner online" and a named cause — wrong credentials, Local Network + /// privacy blocking the link, or a guest image whose Remote Login is off. + /// + /// Read-only with respect to host state: it uses the MACs already persisted + /// in `state.json` and never generates them, so running `doctor` on a fresh + /// host does not quietly create the slot address table. + /// + /// - Note: Informational when no guest is currently leased. `doctor` must not + /// boot a VM — that costs minutes and a slot out of the host's hard cap of + /// two — so with nothing running there is simply nothing to probe. To make + /// this check meaningful, leave a guest up (`gitea-macos-runner vm boot`) + /// and run `doctor` again. + public static func checkGuestSSH(config: RunnerConfig) async -> DoctorCheck { + let name = "guest ssh" + + let macs: [String] + do { + macs = try VMStore(config: config).loadState().slotMACAddresses + } catch { + return DoctorCheck( + name: name, + result: .warn, + detail: "could not read host state: \(error)", + remediation: "check that \(config.storeDirectoryURL.path) is readable" + ) + } + + guard !macs.isEmpty else { + return DoctorCheck( + name: name, + result: .info, + detail: "no slot MAC addresses assigned yet; skipped", + remediation: nil + ) + } + + // Newest lease wins if a slot somehow holds more than one: that is the + // guest currently on the link. + let leases = DHCPLeaseParser.parseFile() + guard let (mac, lease) = macs.lazy + .compactMap({ mac in DHCPLeaseParser.lease(forMAC: mac, in: leases).map { (mac, $0) } }) + .first + else { + return DoctorCheck( + name: name, + result: .info, + detail: "no guest currently holds a DHCP lease; skipped", + remediation: """ + this check only runs against a guest that is already up. To exercise the \ + host→guest SSH path, run `gitea-macos-runner vm boot --image default` and \ + then `doctor` again. + """ + ) + } + + // Short and fixed rather than derived from `scheduler.bootTimeoutSeconds`: + // this probes a guest that is already booted, so a slow answer is a + // finding, not something to wait fifteen minutes for. + do { + try await waitForSSH( + host: lease.ipAddress, + username: config.guest.username, + password: config.guest.password, + timeout: .seconds(20), + pollInterval: .seconds(2) + ) + return DoctorCheck( + name: name, + result: .pass, + detail: "authenticated to \(config.guest.username)@\(lease.ipAddress) (\(mac))" + ) + } catch let error as CoreError { + let detail = "\(config.guest.username)@\(lease.ipAddress) (\(mac)): \(error)" + switch error { + case .timeout: + // Nothing answered. bootpd leases last 24 hours and the slot MACs + // are persistent, so on any host that has ever run the daemon the + // most likely explanation is a lease outliving the guest that held + // it — not a broken host. Calling that `.fail` would make `doctor` + // cry wolf on a perfectly healthy idle machine. + return DoctorCheck( + name: name, + result: .warn, + detail: detail, + remediation: """ + most likely a stale lease: bootpd keeps leases for 24 hours, so this \ + address may belong to a guest that has already been torn down. If a \ + guest really is up at this address, the daemon cannot reach it either — \ + check that the host's Local Network permission is not dropping the \ + connection (see the "local network access" check). + """ + ) + default: + // Authentication reached the guest and was refused: the guest is up + // and the credentials are wrong. Nothing about that improves on its + // own, and every boot will fail the same way. + return DoctorCheck( + name: name, + result: .fail, + detail: detail, + remediation: """ + the daemon authenticates over this exact path, so no boot can succeed \ + while it fails. Check that guest.username and guest.password match an \ + account in the guest image, and that Remote Login is enabled there. + """ + ) + } + } catch { + return DoctorCheck( + name: name, + result: .warn, + detail: "\(config.guest.username)@\(lease.ipAddress) (\(mac)): \(error)", + remediation: nil + ) + } + } + /// The macOS 15+ Local Network permission note. /// /// Reports `.pass` when the host carries a subnet allowlist that actually diff --git a/Sources/RunnerHost/Orchestrator.swift b/Sources/RunnerHost/Orchestrator.swift index f4f964d..c7aa148 100644 --- a/Sources/RunnerHost/Orchestrator.swift +++ b/Sources/RunnerHost/Orchestrator.swift @@ -50,7 +50,7 @@ public struct LiveVM: Sendable { /// /// `ensureFreeSpace` → `cloneImage(named:slotMAC:)` → ``VMInstance/start(options:)`` /// → poll `/var/db/dhcpd_leases` for the slot MAC until `bootTimeout` → -/// ``waitForSSH(host:port:username:password:timeout:pollInterval:)`` → write the +/// ``waitForSSH(host:port:username:password:timeout:pollInterval:reportInterval:onAttemptFailure:)`` → write the /// registration token into a guest file with mode `0600` → over SSH: /// /// ```sh @@ -105,6 +105,15 @@ public actor Orchestrator { /// The supervising task per slot: clone → boot → register → run → teardown. private var slotTasks: [Int: Task] = [:] + /// Why a slot's supervising task was cancelled, left for that task to find. + /// + /// `Task.cancel()` carries no payload and `CancellationError` no detail, so + /// a lifecycle that catches one knows only *that* it was stopped. Everything + /// worth reading — "boot timeout: provisioning for 312s (limit 300s)" — is + /// known only to the canceller. Without this hand-off the operator sees + /// `reason=cancelled`, which names the mechanism and hides the cause. + private var slotCancelReasons: [Int: String] = [:] + /// The "the guest stopped on its own" watcher per slot. private var deathWatchTasks: [Int: Task] = [:] @@ -252,6 +261,7 @@ public actor Orchestrator { // let them run their own teardown; whatever they miss we clean up below. let tasks = slotTasks slotTasks.removeAll() + for (slot, _) in tasks { slotCancelReasons[slot] = "shutting down" } for (_, task) in tasks { task.cancel() } for (_, task) in tasks { await task.value } @@ -307,6 +317,9 @@ public actor Orchestrator { // are about to kill, so it would otherwise clear that entry only // after the boot had already been refused. if let task = slotTasks.removeValue(forKey: slot) { + // Before the cancel, not after: the task may reach its + // `catch` the instant it is cancelled. + slotCancelReasons[slot] = reason task.cancel() // Its own teardown runs to completion here, which also means // it cannot race a successor booted later in this pass. @@ -404,6 +417,9 @@ public actor Orchestrator { let generation = (slotGeneration[slot] ?? 0) + 1 slotGeneration[slot] = generation + // Taken alongside the `Date()` handed to the planner, so the lifecycle + // can measure against the same deadline the planner will enforce. + let provisioningStarted = ContinuousClock.now state = SchedulerCore.markProvisioning(state: state, slot: slot, jobHint: jobHint, now: Date()) logger.info( @@ -417,7 +433,13 @@ public actor Orchestrator { slotTasks[slot] = Task { [weak self] in guard let self else { return } - await self.runSlotLifecycle(slot: slot, jobHint: jobHint, runnerName: runnerName, generation: generation) + await self.runSlotLifecycle( + slot: slot, + jobHint: jobHint, + runnerName: runnerName, + generation: generation, + provisioningStarted: provisioningStarted + ) } } @@ -425,11 +447,40 @@ public actor Orchestrator { /// /// Every failure path funnels into the same teardown, because a slot that is /// neither live nor idle is a slot leaked for the process's lifetime. - private func runSlotLifecycle(slot: Int, jobHint: Int64, runnerName: String, generation: Int) async { + /// + /// - Parameter provisioningStarted: When the *planner's* boot deadline began + /// ticking — earlier than this function's own first instruction. Used to + /// budget the readiness waits against the deadline that will actually be + /// enforced rather than against a fresh copy of it. + private func runSlotLifecycle( + slot: Int, + jobHint: Int64, + runnerName: String, + generation: Int, + provisioningStarted: ContinuousClock.Instant + ) async { let bootTimeout = Duration.seconds(max(30, config.scheduler.bootTimeoutSeconds)) let jobTimeout = Duration.seconds(max(60, config.scheduler.jobTimeoutMinutes * 60)) var teardownReason = "job finished" + // Both readiness waits below are already supervised by the planner's + // boot deadline, which started ticking at `provisioningStarted` — before + // the clone, the boot and the DHCP lease had spent any of it. Handing + // either wait the full `bootTimeout` puts its deadline strictly *after* + // the planner's, so the planner always wins the race: this task is + // cancelled mid-wait and the specific error the wait was about to throw + // ("ssh on 192.168.65.233:22 after 41 attempts; last error: …") is + // discarded in favour of a bare cancellation. Budget from what is left + // and the wait gets to speak first. + func remainingBootBudget() -> Duration { + let spent = ContinuousClock.now - provisioningStarted + // Landing a little before the planner, so its next tick finds the + // slot already failing for a stated reason. The floor keeps an + // already-overrun budget from collapsing to zero attempts, which + // would trade one useless message for another. + return max(.seconds(15), bootTimeout - spent - .seconds(5)) + } + do { let mac = try store.macAddress(forSlot: slot, slotCount: slotCount) // Whatever lease this MAC already holds belongs to the *previous* @@ -454,15 +505,40 @@ public actor Orchestrator { await self?.vmStoppedUnexpectedly(slot: slot, generation: generation, reason: reason) } - let ip = try await waitForLease(mac: mac, timeout: bootTimeout, replacing: priorLease) + let ip = try await waitForLease( + mac: mac, + timeout: remainingBootBudget(), + replacing: priorLease + ) live[slot]?.ipAddress = ip logger.info("guest leased address", metadata: ["slot": .stringConvertible(slot), "ip": .string(ip)]) + // A `Logger` is a value type, so the callback below gets its own + // copy and never touches the actor — which is what lets it be a + // plain synchronous closure called from inside the poll loop. + let log = logger try await waitForSSH( host: ip, username: config.guest.username, password: config.guest.password, - timeout: bootTimeout + timeout: remainingBootBudget(), + onAttemptFailure: { attempt in + // A guest sharing a host with other Virtualization guests + // can take minutes to start `sshd`. Without this the wait is + // indistinguishable from a hang: the log goes quiet between + // "guest leased address" and teardown, which is exactly the + // window an operator most wants to see into. + log.info( + "waiting for guest ssh", + metadata: [ + "slot": .stringConvertible(slot), + "host": .string(ip), + "attempt": .stringConvertible(attempt.attempt), + "elapsed": .string("\(attempt.elapsed.components.seconds)s"), + "error": .string(attempt.error), + ] + ) + } ) let token = try await registrationToken() @@ -511,7 +587,9 @@ public actor Orchestrator { ) } } catch is CancellationError { - teardownReason = "cancelled" + // Whoever cancelled us knows why; `CancellationError` does not. + // Falling back to "cancelled" only when nobody left a note. + teardownReason = slotCancelReasons[slot] ?? "cancelled" } catch { teardownReason = "\(error)" logger.error( @@ -539,6 +617,10 @@ public actor Orchestrator { state = SchedulerCore.releaseJob(state: state, jobID: jobHint) } + // A note left for a cancel that arrived after the lifecycle had already + // finished on its own would otherwise be read by the *next* occupant of + // this slot, mislabelling its teardown. + slotCancelReasons[slot] = nil slotTasks[slot] = nil } @@ -551,6 +633,7 @@ public actor Orchestrator { "guest stopped unexpectedly", metadata: ["slot": .stringConvertible(slot), "reason": .string("\(reason)")] ) + slotCancelReasons[slot] = "guest stopped: \(reason)" slotTasks[slot]?.cancel() await teardownSlot(slot, reason: "guest stopped: \(reason)") } diff --git a/Tests/RunnerCoreTests/ConfigTests.swift b/Tests/RunnerCoreTests/ConfigTests.swift index d9c5608..3ea6f10 100644 --- a/Tests/RunnerCoreTests/ConfigTests.swift +++ b/Tests/RunnerCoreTests/ConfigTests.swift @@ -64,7 +64,7 @@ struct ConfigTests { #expect(c.scheduler.pollIntervalSeconds == 5) #expect(c.scheduler.reconcileIntervalSeconds == 300) #expect(c.scheduler.jobTimeoutMinutes == 120) - #expect(c.scheduler.bootTimeoutSeconds == 300) + #expect(c.scheduler.bootTimeoutSeconds == 900) #expect(c.guest.username == "admin") #expect(c.guest.cpuCount == 4) #expect(c.guest.memoryGB == 8) diff --git a/docs/DESIGN.md b/docs/DESIGN.md index 957db27..dc24884 100644 --- a/docs/DESIGN.md +++ b/docs/DESIGN.md @@ -284,8 +284,18 @@ scheduler treats as transient back-pressure rather than a failure. ### Timeouts * A slot in `.provisioning(since:)` longer than `bootTimeoutSeconds` (default - 300) is torn down. Covers a guest that never gets a lease, never starts `sshd`, - or hangs in Setup Assistant. + 900) is torn down. Covers a guest that never gets a lease, never starts `sshd`, + or hangs in Setup Assistant. The default is deliberately generous: several + Virtualization guests sharing one host push a boot from tens of seconds into + minutes, and a limit below the worst case does not time out a bad boot, it + livelocks — each replacement clone starts from zero and adds load, so the next + boot is slower still and no runner ever registers. +* The lifecycle's own `waitForLease` and `waitForSSH` budgets are derived from + what is *left* of that deadline, not from a fresh copy of it. Given the full + `bootTimeoutSeconds` their deadlines would fall after the planner's, so the + planner would always cancel first and the specific error — which host, how + many attempts, what the last one said — would be discarded in favour of a bare + cancellation. * A slot in `.running(jobHint:since:)` longer than `jobTimeoutMinutes` (default 120) is torn down. Covers a job that hangs. This is comfortably below Gitea's own `ABANDONED_JOB_TIMEOUT` (24 h), so our teardown always happens first and diff --git a/docs/setup.md b/docs/setup.md index ef240ca..ff9c268 100644 --- a/docs/setup.md +++ b/docs/setup.md @@ -277,7 +277,7 @@ is required; the file form wins over the inline form when both are present. | `pollIntervalSeconds` | `5` | How often to poll the queued-jobs API. | | `reconcileIntervalSeconds` | `300` | How often to sweep Gitea for orphaned runner registrations from uncleanly-killed VMs. | | `jobTimeoutMinutes` | `120` | Wall-clock limit for one job; the VM is destroyed when exceeded. | -| `bootTimeoutSeconds` | `300` | Time allowed from VM start to a usable SSH connection. | +| `bootTimeoutSeconds` | `900` | Time allowed from VM start to a usable SSH connection. | **`guest`** diff --git a/docs/troubleshooting.md b/docs/troubleshooting.md index 10d9504..0ca286d 100644 --- a/docs/troubleshooting.md +++ b/docs/troubleshooting.md @@ -26,6 +26,7 @@ gitea-macos-runner service status | VM boots but never gets an IP | DHCP lease not yet written, or Local Network privacy denial (macOS 15+) | Check `/var/db/dhcpd_leases`; grant Local Network permission or pre-authorize the subnet | | Runner not listed under Privacy & Security → Local Network | Expected — the list is populated only after the app first attempts a local connection; it cannot be pre-approved | Boot one VM by hand from a GUI Terminal to create the entry, or (better on CI) allowlist the subnet with `defaults write com.apple.network.local-network` | | SSH times out on a freshly built image | Guest macOS < 27, so provisioning options were ignored and Setup Assistant is waiting | Rebuild the image from a macOS **27+** IPSW | +| VMs boot in a loop; every teardown says `reason=cancelled` and nothing is logged between the lease and the teardown | `scheduler.bootTimeoutSeconds` is below the guest's *worst-case* boot on a contended host, so each clone is killed while still starting — and each replacement makes the next one slower | Raise `scheduler.bootTimeoutSeconds` (default 900) and reduce the number of concurrent guests; see [The daemon boots VMs forever](#the-daemon-boots-vms-forever-and-every-teardown-says-reasoncancelled) | | `ssh failed: cannot connect … No route to host) (errno: 65)` part-way through provisioning | macOS 15+ Local Network privacy blocking the app — the grant is keyed on the executable's UUID, so `make install` withdraws it | Allowlist the subnet (`192.168.64.0/18`) and **reboot**; see [SSH fails with "No route to host" mid-run](#ssh-fails-with-no-route-to-host-errno-65-mid-run) | | Allowlist is set but guests are still unreachable | It names `192.168.64.0/24` while the NAT has moved to `192.168.65.x` | Widen it to `192.168.64.0/18` and reboot; `doctor` now warns about too-narrow allowlists | | `SecKeyCreateRandomKey` / "Interaction is not allowed" | `login.keychain` is locked — no GUI session | Run as a LaunchAgent in an unlocked GUI session; enable auto-login | @@ -195,6 +196,63 @@ with this builder. --- +## The daemon boots VMs forever and every teardown says `reason=cancelled` + +**Symptom.** A job is queued, the daemon is running, and the log repeats the same three lines with a +new runner name each time — but no runner ever appears in Gitea: + +``` +info orchestrator: job=1 runner=macos-vm-1cd8e83f… slot=0 booting VM +info orchestrator: ip=192.168.65.233 slot=0 guest leased address +info orchestrator: reason=cancelled slot=0 tearing down slot +``` + +Note what is missing: nothing between the lease and the teardown, and a teardown reason that names +no cause. + +**Cause.** The guest takes longer to reach `sshd` than `scheduler.bootTimeoutSeconds` allows, so the +scheduler tears the slot down while it is still coming up — usually seconds before it would have +succeeded. This is not a timeout that fires once; it is a **livelock**. The replacement clone starts +from zero *and* adds load to an already contended host, so the next boot is slower still and the +loop never converges. + +Several Virtualization guests on one Mac is enough to cause it: a guest that reaches SSH in 40 +seconds on an idle host can take four or five minutes when it is sharing the machine, and each slot +holds 4 vCPU and 8 GB for the whole attempt. Check with `uptime` inside a guest — a load average in +the tens means the guest is starved, not broken. + +**Fix.** + +1. Raise `scheduler.bootTimeoutSeconds`. The default is 900; treat it as a ceiling on the guest's + *worst* case, not its typical one. Timing out too early costs far more than noticing a genuinely + wedged guest late. + +2. Reduce contention. Count what is actually running: + + ```sh + ps -Ao pid,rss,etime,comm | grep -i -e virtual -e vmnet + ``` + + Virtualization guests belonging to *other* tools compete for the same cores and the same two-VM + macOS limit. Shut down what you are not using, or lower `scheduler.maxConcurrentVMs`. + +3. Confirm the guest itself is fine, independently of the daemon, with `doctor` — its `guest ssh` + check authenticates against whichever slot currently holds a lease: + + ```sh + gitea-macos-runner doctor + ``` + +**If you are on an older build**, upgrade: the empty gap in that log was three bugs, all now fixed. +`waitForSSH` was handed the full `bootTimeoutSeconds` even though the scheduler's clock had started +before the clone — so the scheduler always fired first and `waitForSSH`'s own error was unreachable; +its per-attempt failures were only ever reported in that unreachable error; and the teardown +overwrote the planner's reason with `cancelled`. Current builds log `waiting for guest ssh` with the +attempt count and the last error while it is happening, and report +`reason="boot timeout: provisioning for 312s (limit 300s)"`. + +--- + ## `SecKeyCreateRandomKey` / "Interaction is not allowed" **Symptom.** The daemon starts but fails during VM setup with a Security-framework error mentioning