diff --git a/apps/ade-cli/src/bootstrap.ts b/apps/ade-cli/src/bootstrap.ts index f6215bbc9..a5ad42951 100644 --- a/apps/ade-cli/src/bootstrap.ts +++ b/apps/ade-cli/src/bootstrap.ts @@ -1547,11 +1547,6 @@ export async function createAdeRuntime(args: { const service = createSyncTunnelClientService({ logger, configStore: cloudRelayStore, - getSyncPort: () => resolvedArgs.syncRuntime?.sharedSyncListener?.getPort() ?? null, - getExpectedLoopbackNonce: () => - resolvedArgs.syncRuntime?.sharedSyncListener?.getExpectedLoopbackNonce() ?? null, - getRelayBridgeProof: () => - resolvedArgs.syncRuntime?.sharedSyncListener?.getRelayBridgeProof() ?? null, isAccountSignedIn: () => { const status = accountAuthService.getStatus(); return status.signedIn && Boolean(status.userId?.trim()); @@ -1568,15 +1563,19 @@ export async function createAdeRuntime(args: { }, onPublicationStateChanged: () => resolvedArgs.syncRuntime?.requestAccountMachinePublish?.(), }); - resolvedArgs.syncRuntime?.sharedSyncListener?.onLoopbackValidated(() => { - void service.validateCurrentBridge().catch((error) => { - logger.warn("sync.tunnel_bridge_validation_failed", { - error: error instanceof Error ? error.message : String(error), - }); - }); - }); return service; }); + // Bind the listener OUTSIDE the factory. The client is cached one-per-machine + // and built by whichever runtime bootstrapped first, which is regularly a + // scope with no listener (headless one-shot, embedded fallback). Everything + // captured in that factory — the port accessor and the loopback retry hook — + // then pointed at null for the life of the process, so the bridge could never + // validate and Relay stayed fail-closed even though the listener was up. + // Attaching here means the runtime that actually owns the listener wins, + // whether or not it was the one that created the instance. + if (resolvedArgs.syncRuntime?.sharedSyncListener) { + syncTunnelClientService.attachHostListener(resolvedArgs.syncRuntime.sharedSyncListener); + } // Only the runtime that actually hosts phone sync (owns the brain-level // shared listener) may register the relay tunnel. The relay DO keeps ONE // host socket per machineKey (last wins), so a headless one-shot CLI diff --git a/apps/ade-cli/src/cli.test.ts b/apps/ade-cli/src/cli.test.ts index 75cef138d..9cbc7be02 100644 --- a/apps/ade-cli/src/cli.test.ts +++ b/apps/ade-cli/src/cli.test.ts @@ -1328,6 +1328,68 @@ describe("ADE CLI", () => { expect(output).not.toContain("no PIN set"); }); + it("surfaces a prior install that did not land in update status --text", () => { + const plan = expectExecutePlan(buildCliPlan(["update", "status"])); + expect(inferFormatter(plan)).toBe("update-status"); + + const output = formatOutput( + { + status: "ready", + currentVersion: "1.2.37", + latestKnownVersion: "1.2.38", + version: "1.2.38", + progressPercent: null, + bytesPerSecond: null, + transferredBytes: null, + totalBytes: null, + releaseNotesUrl: null, + error: null, + errorDetails: null, + recentlyInstalled: null, + parked: null, + lastInstallFailed: { targetVersion: "1.2.38", attempt: 2 }, + autoApplyPending: null, + autoApplySuppressedUntil: null, + }, + { text: true } as any, + inferFormatter(plan), + ); + + expect(output).toContain("status"); + expect(output).toContain("1.2.38 did not land"); + expect(output).toContain("attempt 2"); + expect(output).toContain("ade update install"); + }); + + it("renders progress and omits the install-failure row for a clean update snapshot", () => { + const plan = expectExecutePlan(buildCliPlan(["update", "status"])); + const output = formatOutput( + { + status: "downloading", + currentVersion: "1.2.37", + latestKnownVersion: "1.2.38", + version: "1.2.38", + progressPercent: 42.4, + bytesPerSecond: 1_048_576, + transferredBytes: 1_048_576, + totalBytes: 4_194_304, + releaseNotesUrl: null, + error: null, + errorDetails: null, + recentlyInstalled: null, + parked: null, + lastInstallFailed: null, + autoApplyPending: null, + autoApplySuppressedUntil: null, + }, + { text: true } as any, + inferFormatter(plan), + ); + + expect(output).toContain("42% · 1 MB of 4 MB · 1 MB/s"); + expect(output).not.toContain("last install failed"); + }); + it("applies sync web clipboard and open flags only when a link exists", () => { const options = { ...baseResolveOpts(), diff --git a/apps/ade-cli/src/cli.ts b/apps/ade-cli/src/cli.ts index a2d86f39d..46dc15486 100644 --- a/apps/ade-cli/src/cli.ts +++ b/apps/ade-cli/src/cli.ts @@ -256,7 +256,8 @@ type FormatterId = | "storage-compress" | "storage-maintenance" | "sync-status" - | "sync-web"; + | "sync-web" + | "update-status"; type ChatWaitTarget = | "idle" @@ -2304,16 +2305,27 @@ ${CURSOR_CLOUD_HELP.cloud}`, the post-install notice. quitAndInstall relaunches the desktop app and only succeeds when status is "ready". - $ ade --socket update status --text Read AutoUpdateSnapshot (status, version, progress) + $ ade --socket update status --text Read AutoUpdateSnapshot (status, version, progress, last failed install) $ ade --socket update check --text Trigger a background update check $ ade --socket update install --text Refresh latest, then quit and install when ready $ ade --socket update dismiss --text Clear the recently-installed banner $ ade --socket update actions --text List callable update actions Snapshot status values: idle, checking, downloading, ready, installing, error. - "installing" appears between quitAndInstall and the desktop relaunch; if the - install fails, status falls back to error and the pending-install record is - cleared automatically. + "installing" appears between quitAndInstall and the desktop relaunch. That + window is deliberately long — the OS installer stages the new bundle in + process on macOS, so the app is only force-quit after a hard bound of several + minutes (about a minute on Windows/Linux, where staging is external). Do NOT + read a few slow minutes in "installing" as a hang, and do not kill the desktop + app to "unstick" it: that is exactly what makes an install fail to land. + + If quitAndInstall fails before the native handoff, status falls back to error + and the pending-install record is cleared. If the app quits but relaunches on + the OLD version, the install did not land: the next snapshot carries + "lastInstallFailed": { targetVersion, attempt }, which survives the restart. + Check that field before re-offering the same update — the first failure keeps + the downloaded archive so a retry is just another install, and only a second + failure discards the download and forces a fresh one. `, }; @@ -16834,6 +16846,91 @@ function formatStorageMaintenance(value: unknown): string { return `${header}\n\n${table}`; } +function formatEpochTimestamp(value: unknown): string | null { + if (typeof value !== "number" || !Number.isFinite(value) || value <= 0) return null; + // Finite and positive still admits epochs past 8.64e15, where toISOString + // throws RangeError. Every other field here degrades to a missing row rather + // than taking down `ade update status --text`; this one must too. + const date = new Date(value); + if (Number.isNaN(date.getTime())) return null; + const iso = date.toISOString(); + return `${iso} (${relativeTime(iso)})`; +} + +function formatUpdateStatus(value: unknown): string { + if (!isRecord(value)) return JSON.stringify(value, null, 2); + const errorDetails = isRecord(value.errorDetails) ? value.errorDetails : null; + const recentlyInstalled = isRecord(value.recentlyInstalled) ? value.recentlyInstalled : null; + const parked = isRecord(value.parked) ? value.parked : null; + // A previous install quit and the app came back on the old version. The + // snapshot deliberately keeps this across the restart, so an agent reading + // status must see it — otherwise the same update is silently offered again + // and the failure reads as "the update did nothing". + const lastInstallFailed = isRecord(value.lastInstallFailed) ? value.lastInstallFailed : null; + const autoApplyPending = isRecord(value.autoApplyPending) ? value.autoApplyPending : null; + + const progressParts: string[] = []; + if (typeof value.progressPercent === "number" && Number.isFinite(value.progressPercent)) { + progressParts.push(`${Math.round(value.progressPercent)}%`); + } + if (typeof value.transferredBytes === "number" && typeof value.totalBytes === "number") { + progressParts.push( + `${formatBytes(value.transferredBytes)} of ${formatBytes(value.totalBytes)}`, + ); + } + if (typeof value.bytesPerSecond === "number" && value.bytesPerSecond > 0) { + progressParts.push(`${formatBytes(value.bytesPerSecond)}/s`); + } + + const failedAttempt = typeof lastInstallFailed?.attempt === "number" + ? lastInstallFailed.attempt + : null; + const lastInstallFailedLine = lastInstallFailed + // renderKeyValues truncates each value at 96 columns, so this has to stay + // short enough that the retry hint survives a long version string. + ? `${asString(lastInstallFailed.targetVersion) ?? "unknown"} did not land` + + `${failedAttempt != null ? ` · attempt ${failedAttempt}` : ""}` + + " · relaunched on old version — retry: ade update install" + : null; + + const parkedLine = parked + ? `${asString(parked.reason) ?? "unknown reason"}${ + formatEpochTimestamp(parked.at) ? ` at ${formatEpochTimestamp(parked.at)}` : "" + }` + : null; + + const recentlyInstalledLine = recentlyInstalled + ? `${asString(recentlyInstalled.version) ?? "unknown version"}${ + asString(recentlyInstalled.installedAt) + ? ` · ${relativeTime(asString(recentlyInstalled.installedAt)!)}` + : "" + }` + : null; + + const errorLine = asString(value.error); + const errorDetailLine = errorDetails + ? `${asString(errorDetails.kind) ?? "error"} during ${ + asString(errorDetails.phase) ?? "unknown phase" + }${errorDetails.preservesDownload === true ? " · download preserved" : ""}` + : null; + + return renderKeyValues("ADE update", [ + ["status", value.status], + ["current version", value.currentVersion], + ["latest known", value.latestKnownVersion], + ["update version", value.version], + ["progress", progressParts.length ? progressParts.join(" · ") : null], + ["release notes", value.releaseNotesUrl], + ["last install failed", lastInstallFailedLine], + ["parked", parkedLine], + ["recently installed", recentlyInstalledLine], + ["auto-apply at", formatEpochTimestamp(autoApplyPending?.deadlineAt)], + ["auto-apply suppressed until", formatEpochTimestamp(value.autoApplySuppressedUntil)], + ["error", errorLine], + ["error detail", errorDetailLine], + ]); +} + function formatLastFailureLine(report: AdeLastFailureReport): string { const repeat = report.count > 1 ? ` x${report.count}` : ""; const scope = report.projectRoot ? ` [${report.projectRoot}]` : ""; @@ -18440,6 +18537,8 @@ function formatTextOutput( return formatStorageCompression(value); case "storage-maintenance": return formatStorageMaintenance(value); + case "update-status": + return formatUpdateStatus(value); case "action-result": default: if (isRecord(value)) @@ -18558,6 +18657,7 @@ function inferFormatter( if (label === "history commits") return "history-commits"; if (label === "history show") return "history-show"; if (label === "actions list") return "actions-list"; + if (label === "update status") return "update-status"; if (label.endsWith("actions")) return "actions-list"; const firstStep = plan.steps[0]; const params = typeof firstStep?.params === "object" && firstStep.params != null diff --git a/apps/ade-cli/src/commands/doctor.ts b/apps/ade-cli/src/commands/doctor.ts index a27a26f80..252b0a4bd 100644 --- a/apps/ade-cli/src/commands/doctor.ts +++ b/apps/ade-cli/src/commands/doctor.ts @@ -555,7 +555,20 @@ function syncPortRow(input: DoctorInput): DoctorRow { label: "Sync port", status: "warn", detail: `bound on ${input.syncPort} instead of 8787${ - holders.length ? ` · base holders: ${holders.join("; ")}` : " · first three base ports have no visible holders" + holders.length + ? ` · base holders: ${holders.join("; ")}` + // "No visible holders" reads as "the ports are free", which is exactly + // the wrong conclusion: the holder is usually tailscaled, and it runs + // as root so this probe cannot see it. Point at the check that can. + : " · no holders visible to this user (a root-owned holder such as" + + " tailscaled is invisible here — check `tailscale serve status`" + + " and `netstat -an -p tcp`)" + }${ + // The usual cause is ADE's own stranded `tailscale serve` entries from + // earlier runs. The host now reclaims those on its next publish, so the + // fix is a brain restart, not 60-odd manual `serve --tcp=N off` calls. + holders.length ? "" : " · ADE reclaims its own stale serve entries on the" + + " next publish; `ade brain restart` should return it to 8787" }`, }; } diff --git a/apps/ade-cli/src/services/sync/syncHostService.test.ts b/apps/ade-cli/src/services/sync/syncHostService.test.ts index f17f68295..3f39dff92 100644 --- a/apps/ade-cli/src/services/sync/syncHostService.test.ts +++ b/apps/ade-cli/src/services/sync/syncHostService.test.ts @@ -58,6 +58,7 @@ import { recordChatEventInReplayBuffer, resolveSyncHostInboundProjectScope, selectChangesetBatchChunk, + staleAdeTailnetServePorts, syncConnectionTransportForOrigin, } from "./syncHostService"; import { createBrainProjectActionsSyncHandler } from "./brainProjectActionsSyncHandler"; @@ -130,6 +131,51 @@ type BonjourPublishArgs = { disableIPv6: boolean; }; +// Regression: `tailscale serve --bg` outlives the process that registered it, +// but ADE tracked the served port in memory only. Every restart -- and every +// force-kill that skipped teardown -- orphaned the previous entry, which stayed +// bound on the tailnet address and made ADE's own next wildcard bind fail +// EADDRINUSE against its own leftovers. It walked one port higher and leaked +// another, ratcheting forever: 66 stranded ports and ~70 failed binds per start +// on one machine. +describe("staleAdeTailnetServePorts", () => { + const serveStatus = (ports: Record) => + JSON.stringify({ + TCP: Object.fromEntries( + Object.entries(ports).map(([port, forward]) => [port, { TCPForward: forward }]), + ), + }); + + it("reclaims ADE's own stranded ports and keeps the live one", () => { + const json = serveStatus({ + "8787": "127.0.0.1:8787", + "8788": "127.0.0.1:8788", + "8852": "127.0.0.1:8852", + }); + expect(staleAdeTailnetServePorts(json, 8852)).toEqual([8787, 8788]); + }); + + it("leaves a hand-rolled serve in the same range alone", () => { + const json = serveStatus({ + // Same port range, but forwarding somewhere ADE never would. + "8790": "127.0.0.1:3000", + "8791": "192.168.1.5:8791", + "8792": "127.0.0.1:8792", + }); + expect(staleAdeTailnetServePorts(json, 8852)).toEqual([8792]); + }); + + it("ignores ports outside ADE's sync range", () => { + const json = serveStatus({ "443": "127.0.0.1:443", "9100": "127.0.0.1:9100" }); + expect(staleAdeTailnetServePorts(json, 8852)).toEqual([]); + }); + + it("returns nothing for unparseable or empty status", () => { + expect(staleAdeTailnetServePorts("not json", 8852)).toEqual([]); + expect(staleAdeTailnetServePorts(JSON.stringify({}), 8852)).toEqual([]); + }); +}); + describe("resolveSyncHostInboundProjectScope", () => { it("keeps runtime-scoped envelopes projectless", () => { expect(resolveSyncHostInboundProjectScope("hello", "project-1", "project-1")).toEqual({ @@ -7133,6 +7179,40 @@ describe("sync host reliability guards", () => { } as unknown as Parameters[0]); } + // The relay readiness self-probe bridges into the sync host and disconnects + // without ever speaking the protocol, on every poll. Logging that at info + // made routine probe traffic indistinguishable at a glance from a peer that + // tried to authenticate and was rejected. + it("logs a peer that closed without sending a frame at debug", async () => { + const { projectRoot, cleanup } = createTempProjectRoot(); + const logger = createDiscoveryLogger(); + const host = createReliabilityHost(projectRoot, { logger }); + try { + const port = await host.waitUntilListening(); + const ws = new WebSocket(`ws://127.0.0.1:${port}`); + await new Promise((resolve, reject) => { + ws.once("open", () => resolve()); + ws.once("error", reject); + }); + ws.close(4000, "self probe complete"); + + await vi.waitFor(() => expect(logger.debug).toHaveBeenCalledWith( + "sync_host.peer_closed_without_frames", + expect.objectContaining({ + authenticated: false, + reason: "self probe complete", + }), + )); + expect(logger.info).not.toHaveBeenCalledWith( + "sync_host.peer_closed", + expect.anything(), + ); + } finally { + await host.dispose(); + cleanup(); + } + }); + it("serializes project switch handling without deadlocking later peer messages", async () => { const { projectRoot, cleanup } = createTempProjectRoot(); const project = createDiscoveryProject({ diff --git a/apps/ade-cli/src/services/sync/syncHostService.ts b/apps/ade-cli/src/services/sync/syncHostService.ts index dd305f375..3b0454555 100644 --- a/apps/ade-cli/src/services/sync/syncHostService.ts +++ b/apps/ade-cli/src/services/sync/syncHostService.ts @@ -1,6 +1,7 @@ import fs from "node:fs"; import http from "node:http"; import { execFile, spawn, type ChildProcess } from "node:child_process"; +import net from "node:net"; import os from "node:os"; import path from "node:path"; import { runWithAbortSignal } from "./abortSignal"; @@ -172,7 +173,7 @@ import { createMachineIdentitySigningStore, type MachineIdentitySigningStore, } from "./machineIdentitySigningStore"; -import { DEFAULT_SYNC_COMPRESSION_THRESHOLD_BYTES, DEFAULT_SYNC_HOST_PORT, DEFAULT_SYNC_MAX_FRAME_BYTES, encodeSyncEnvelope, encodeSyncEnvelopeFrames, mapPlatform, parseSyncEnvelope, SYNC_CHUNKED_ENVELOPES_CAPABILITY, SYNC_RUNTIME_ONLY_CAPABILITY, wsDataToText, type ParsedSyncEnvelope } from "./syncProtocol"; +import { DEFAULT_SYNC_COMPRESSION_THRESHOLD_BYTES, DEFAULT_SYNC_HOST_PORT, DEFAULT_SYNC_MAX_FRAME_BYTES, SYNC_HOST_MAX_PORT, encodeSyncEnvelope, encodeSyncEnvelopeFrames, mapPlatform, parseSyncEnvelope, SYNC_CHUNKED_ENVELOPES_CAPABILITY, SYNC_RUNTIME_ONLY_CAPABILITY, wsDataToText, type ParsedSyncEnvelope } from "./syncProtocol"; import { resolveTailscaleCliPath } from "./resolveTailscaleCliPath"; import { createSyncRemoteCommandService, type SyncRemoteCommandService } from "./syncRemoteCommandService"; import { prepareProductAnalyticsRemoteCommand } from "./productAnalyticsRemoteCommand"; @@ -265,6 +266,40 @@ function isMobileChangesetPeer(peer: { metadata: SyncPeerMetadata | null }): boo return peer.metadata?.deviceType === "phone" || peer.metadata?.platform === "iOS"; } +/** + * Ports still advertised through `tailscale serve` that ADE published on an + * earlier run and never tore down. + * + * Only ADE's exact signature is reclaimed: a port inside ADE's own sync range + * forwarding to 127.0.0.1 on the SAME port. A hand-rolled `tailscale serve` + * that happens to sit in that range — anything forwarding elsewhere — is left + * strictly alone. + */ +export function staleAdeTailnetServePorts( + serveStatusJson: string, + currentPort: number, +): number[] { + let parsed: unknown; + try { + parsed = JSON.parse(serveStatusJson); + } catch { + return []; + } + const tcp = (parsed as { TCP?: unknown } | null)?.TCP; + if (!tcp || typeof tcp !== "object") return []; + const stale: number[] = []; + for (const [key, value] of Object.entries(tcp as Record)) { + const port = Number.parseInt(key, 10); + if (!Number.isInteger(port)) continue; + if (port < DEFAULT_SYNC_HOST_PORT || port > SYNC_HOST_MAX_PORT) continue; + if (port === currentPort) continue; + const forward = (value as { TCPForward?: unknown } | null)?.TCPForward; + if (forward !== `127.0.0.1:${port}`) continue; + stale.push(port); + } + return stale.sort((left, right) => left - right); +} + export function isRuntimeHostPairingRecord( record: SyncPairingRecord | null | undefined, ): boolean { @@ -531,6 +566,13 @@ type PeerState = { changesetRecoveryNotBeforeMs: number; remoteAddress: string | null; remotePort: number | null; + /** + * Frames received from this peer. A peer that closes having sent none never + * attempted the sync protocol at all — the relay readiness self-probe bridges + * in and disconnects like this on every poll — so it must not be logged with + * the same weight as a peer that tried to authenticate and was rejected. + */ + framesReceived: number; transportOrigin: SyncTransportOrigin; relayAuthorization: RelayAuthorizationLifecycle | null; adoptChallenge: { @@ -3178,6 +3220,7 @@ export function createSyncHostService(args: SyncHostServiceArgs) { pairingRecord: null, connectedAt: nowIso(), lastSeenAt: nowIso(), + framesReceived: 0, lastAppliedAt: null, lastKnownServerDbVersion: 0, latencyMs: null, @@ -3232,6 +3275,7 @@ export function createSyncHostService(args: SyncHostServiceArgs) { }, authTimeoutMs); peer.authTimeout.unref?.(); ws.on("message", (raw) => { + peer.framesReceived += 1; let envelope: ParsedSyncEnvelope; try { envelope = parseSyncEnvelope(wsDataToText(raw)); @@ -3281,7 +3325,7 @@ export function createSyncHostService(args: SyncHostServiceArgs) { // changed.", "The machine took too long to respond.", …) while 1006 // means the transport died with no close frame at all. Keep this log — // it is the primary tool for diagnosing mobile disconnect loops. - args.logger.info("sync_host.peer_closed", { + const closeDetail = { code, reason: reason.toString("utf8") || null, peerDeviceId: peer.metadata?.deviceId ?? peer.pairedDeviceId ?? null, @@ -3289,7 +3333,17 @@ export function createSyncHostService(args: SyncHostServiceArgs) { remoteAddress: peer.remoteAddress ?? null, connectedAt: peer.connectedAt ?? null, authenticated: peer.authenticated, - }); + }; + // A peer that never sent a frame never attempted the protocol: the relay + // readiness self-probe bridges in and drops on every poll, and so does a + // port scan. Logging those at info buried the real signal — a rejected + // peer looks identical at a glance — so keep them at debug. Anything that + // actually spoke, including every authentication failure, stays at info. + if (!peer.authenticated && peer.framesReceived === 0) { + args.logger.debug("sync_host.peer_closed_without_frames", closeDetail); + } else { + args.logger.info("sync_host.peer_closed", closeDetail); + } if (removeAllPresenceForDevice(peer.metadata?.deviceId, "remote")) { broadcastBrainStatus(); } @@ -3833,6 +3887,11 @@ export function createSyncHostService(args: SyncHostServiceArgs) { stdout: stdoutText || null, stderr: stderrText || null, }); + // Best-effort and deliberately after publish: reclaiming old entries + // must never delay or endanger advertising the live port. + if (tailnetServeActivePublishToken === publishToken) { + void reclaimStaleTailnetServes(port).catch(() => {}); + } }) .catch((error: unknown) => { if (tailnetServeActivePublishToken !== publishToken) return; @@ -3875,6 +3934,72 @@ export function createSyncHostService(args: SyncHostServiceArgs) { }); }; + // A stranded `tailscale serve` entry forwards to a port nothing listens on. + // A live one — this host or a sibling ADE — has a real listener behind it. + const isLocalPortServing = (port: number): Promise => new Promise((resolve) => { + const socket = net.connect({ port, host: "127.0.0.1" }); + const settle = (serving: boolean) => { + socket.removeAllListeners(); + socket.destroy(); + resolve(serving); + }; + socket.setTimeout(750, () => settle(false)); + socket.once("connect", () => settle(true)); + socket.once("error", () => settle(false)); + }); + + // `serve --bg` outlives the process that registered it, but the port ADE + // tracks is in-memory only, so every restart — and every force-kill that + // skips the teardown below — orphans the previous entry. Tailscale keeps it + // bound on the tailnet address, which makes ADE's own next wildcard bind fail + // EADDRINUSE against its own leftovers and walk one port higher, leaking + // another entry. It ratchets forever; one machine had 66 stranded ports and + // burned ~70 failed binds on every start. Reclaim them whenever we publish. + const reclaimStaleTailnetServes = async (currentPort: number): Promise => { + const cli = resolveTailscaleCliPath(); + let stale: number[]; + try { + const { stdout } = await execFileAsync(cli, ["serve", "status", "--json"], { timeout: 10_000 }); + stale = staleAdeTailnetServePorts(stdout, currentPort); + } catch { + // No Tailscale, no permission, unparseable output: publishing the current + // port matters more than tidying old ones. + return; + } + if (stale.length === 0) return; + let reclaimed = 0; + for (const port of stale) { + // The snapshot is stale the moment reclaiming starts: turning off a low + // port frees it, and a host restarting mid-loop prefers exactly those low + // ports. Without re-checking, this loop can turn off the serve entry a + // newer host just published and leave the machine with no tailnet route + // at all, while status still reports "published". + if (disposed) return; + if (tailnetServePort != null && port === tailnetServePort) continue; + // `tailscale serve` is machine-global while the sync-host singleton is + // uid- and channel-scoped, so a sibling ADE (another channel, another + // user) can legitimately own one of these ports. Its serve entry is + // byte-identical to a stale one — same port forwarding to 127.0.0.1 on + // the same port — so the status output cannot tell them apart. What does + // is whether anything is actually listening: a stranded entry forwards + // into nothing. Probe immediately before each teardown, so the window + // between the snapshot and this `off` is closed too. + if (await isLocalPortServing(port)) continue; + try { + await execFileAsync(cli, ["serve", `--tcp=${port}`, "off"], { timeout: 10_000 }); + reclaimed += 1; + } catch { + // A single stubborn entry must not stop the rest. + } + } + args.logger.info("sync_host.tailnet_serve_reclaimed", { + currentPort, + staleCount: stale.length, + reclaimed, + ports: stale.slice(0, 20), + }); + }; + const unpublishTailnetDiscovery = async (): Promise => { if (!tailnetServeSignature) return; tailnetServeActivePublishToken = ++tailnetServePublishSequence; @@ -6759,14 +6884,40 @@ export function createSyncHostService(args: SyncHostServiceArgs) { return true; } } - if (!pairingStore.authenticate(pairedAuth.deviceId, pairedAuth.secret)) return true; + // This rejection used to be silent on both ends: the host logged + // nothing and the client showed a bare "authentication". Name it, + // and tell the client the one thing that actually resolves it. + const knownRecord = pairingStore.getPairingRecord(pairedAuth.deviceId); + if (!pairingStore.authenticate(pairedAuth.deviceId, pairedAuth.secret)) { + // Deliberately identical for both cases. The host knows which it + // is and logs it below, but telling an UNAUTHENTICATED caller + // whether a device id exists here turns this into an existence + // oracle, and the user's next step is the same either way. + authFailureMessage = "This device is not paired with this machine, or its saved" + + " pairing is no longer valid. Pair it again."; + args.logger.warn("sync_host.paired_device_rejected", { + deviceId: pairedAuth.deviceId, + reason: knownRecord ? "secret_mismatch" : "unknown_device", + }); + return true; + } authenticatedPairingRecord = pairingStore.getPairingRecord(pairedAuth.deviceId); if (!authenticatedPairingRecord) return true; const pairingAccountOwner = toOptionalString(authenticatedPairingRecord.accountOwnerUserId); if (pairingAccountOwner) { const currentOwner = await refreshAccountLease(); if (!isPeerLifecycleCurrent(peer, lifecycleGeneration)) return true; - if (currentOwner !== pairingAccountOwner) return true; + if (currentOwner !== pairingAccountOwner) { + // A LAN client rejected here sees only "authentication"; the + // account mismatch is the actionable part. + authFailureMessage = "This machine is signed in to a different ADE account than the one that paired this device."; + args.logger.warn("sync_host.paired_account_owner_mismatch", { + deviceId: pairedAuth.deviceId, + hasCurrentOwner: Boolean(currentOwner), + ownerMatches: false, + }); + return true; + } } const dpopFailure = evaluatePairedHelloDpop({ storedPublicKey: authenticatedPairingRecord.dpopPublicKey, diff --git a/apps/ade-cli/src/services/sync/syncTunnelClientService.test.ts b/apps/ade-cli/src/services/sync/syncTunnelClientService.test.ts index 19a7eb7e1..52b8b0c86 100644 --- a/apps/ade-cli/src/services/sync/syncTunnelClientService.test.ts +++ b/apps/ade-cli/src/services/sync/syncTunnelClientService.test.ts @@ -390,6 +390,93 @@ describe("createSyncTunnelClientService", () => { } }); + // Regression: the tunnel client is cached one-per-machine and built by + // whichever runtime bootstrapped first — regularly a scope that owns no + // listener (headless one-shot, embedded fallback). The accessors and the + // loopback retry hook captured in that closure then read null for the life + // of the process, so the bridge never validated and Relay stayed + // fail-closed even though the real listener was bound and healthy. + it("validates the bridge when the host attaches a listener the constructor never saw", async () => { + const listener = createSharedSyncListener({ bindHost: "127.0.0.1" }); + const relay = new WebSocketServer({ host: "127.0.0.1", port: 0 }); + await new Promise((resolve, reject) => { + relay.once("listening", resolve); + relay.once("error", reject); + }); + const address = relay.address(); + const relayPort = typeof address === "object" && address ? address.port : 0; + relay.on("connection", (socket, request) => { + if ((request.url ?? "").startsWith("/connect/")) { + socket.send(JSON.stringify({ t: "accepted", v: 2 })); + socket.send(JSON.stringify({ t: "ready", v: 2 })); + } + }); + const originalFetch = globalThis.fetch; + globalThis.fetch = async () => new Response(null, { status: 204 }); + // Built by a runtime with no listener: every accessor is null, and no + // loopback subscription is possible. + const service = createSyncTunnelClientService({ + getSyncPort: () => null, + getExpectedLoopbackNonce: () => null, + getRelayBridgeProof: () => null, + configStore: fakeStore(`http://127.0.0.1:${relayPort}`), + }); + + try { + await service.start(); + await vi.waitFor(() => { + expect(service.getStatus().connected).toBe(true); + }); + expect(service.getStatus().relayBridgeValidated).toBe(false); + + const syncPort = await listener.ensureListening([0]); + // The host runtime hands over the listener it owns. Before the fix this + // had no way in, and the client stayed pinned to the null accessors. + service.attachHostListener(listener); + + await vi.waitFor(() => { + expect(service.getStatus()).toMatchObject({ + connected: true, + relayBridgeValidated: true, + validatedPort: syncPort, + }); + }); + } finally { + await service.dispose(); + globalThis.fetch = originalFetch; + await listener.close(); + await new Promise((resolve) => relay.close(() => resolve())); + } + }); + + // Regression: stop() left the loopback subscription installed, so the + // listener retained a callback into a disposed client for the process + // lifetime. + it("releases the host listener subscription on stop", async () => { + const unsubscribe = vi.fn(); + const onLoopbackValidated = vi.fn(() => unsubscribe); + const fakeListener = { + getPort: () => 8787, + getExpectedLoopbackNonce: () => "n".repeat(43), + getRelayBridgeProof: () => "e".repeat(43), + onLoopbackValidated, + }; + const service = createSyncTunnelClientService({ + configStore: fakeStore("https://relay.example.com"), + }); + try { + service.attachHostListener(fakeListener); + expect(onLoopbackValidated).toHaveBeenCalledTimes(1); + expect(unsubscribe).not.toHaveBeenCalled(); + + await service.stop(); + + expect(unsubscribe).toHaveBeenCalledTimes(1); + } finally { + await service.dispose(); + } + }); + it("keeps Relay offline signed out, resumes on sign-in, and closes when token refresh fails", async () => { const relay = new WebSocketServer({ host: "127.0.0.1", port: 0 }); await new Promise((resolve, reject) => { diff --git a/apps/ade-cli/src/services/sync/syncTunnelClientService.ts b/apps/ade-cli/src/services/sync/syncTunnelClientService.ts index e57239446..55fd3ee88 100644 --- a/apps/ade-cli/src/services/sync/syncTunnelClientService.ts +++ b/apps/ade-cli/src/services/sync/syncTunnelClientService.ts @@ -50,6 +50,17 @@ export type SyncTunnelClientStatus = { export type SyncTunnelClientService = { start(): Promise; stop(): Promise; + /** + * Hand this client the shared listener it must bridge into. + * + * The client is cached one-per-machine and built by whichever runtime + * bootstrapped first — which is frequently NOT the runtime that owns the + * listener. Accessors captured at construction therefore read a listener + * that stays null forever, so the bridge can never validate and Relay dies + * fail-closed. The runtime that actually owns the listener calls this, and + * it wins regardless of who created the instance. + */ + attachHostListener(listener: TunnelHostListener | null): void; /** Re-probe the active shared listener without opening a Relay pipe. */ validateCurrentBridge(): Promise; /** Dial Relay exactly like a ready-v2 controller and verify bridge readiness. */ @@ -60,18 +71,29 @@ export type SyncTunnelClientService = { type MachineIdentity = { machineKey: string; secret: string }; +/** The slice of the shared sync listener the relay bridge needs. */ +export type TunnelHostListener = { + getPort(): number | null; + getExpectedLoopbackNonce(): string; + getRelayBridgeProof(): string; + onLoopbackValidated(handler: () => void): () => void; +}; + type SyncTunnelClientArgs = { logger?: Logger; - /** Local ADE sync WebSocket server port, or null when the host isn't up. */ - getSyncPort: () => number | null; - /** Expected identity of the active in-process sync listener. */ - getExpectedLoopbackNonce?: () => string | null; - /** Private proof accepted only by the active in-process sync listener. */ - getRelayBridgeProof: () => string | null; /** Relay is usable only while the host has a current ADE account session. */ isAccountSignedIn?: () => boolean; /** Refresh-aware lease; the account token is validated upstream and never retained here. */ getAccountLease?: () => Promise<{ userId: string; expiresAt?: string | null } | null>; + /** + * Test seam only. Production passes none of these — bootstrap hands the + * listener to attachHostListener instead, so the attached listener is the + * single source of truth there. Wiring them from a per-runtime closure is + * what caused the cached-client bug this replaced. + */ + getSyncPort?: () => number | null; + getExpectedLoopbackNonce?: () => string | null; + getRelayBridgeProof?: () => string | null; configStore: SyncCloudRelayStore; /** Overrides the identity from configStore (e.g. a shared machine store). */ machineIdentity?: () => MachineIdentity | null; @@ -273,6 +295,8 @@ export function createSyncTunnelClientService(args: SyncTunnelClientArgs): SyncT let started = false; let stopped = false; let connected = false; + let hostListener: TunnelHostListener | null = null; + let detachHostListener: (() => void) | null = null; let lastError: string | null = null; let lastControlError: string | null = null; let bridgeOpenFailure: { @@ -458,10 +482,23 @@ export function createSyncTunnelClientService(args: SyncTunnelClientArgs): SyncT } }; + // An attached listener wins. Production never supplies the arg accessors, so + // there the listener is the only source — which is the point: the client is + // cached one-per-machine, and a closure captured by the first runtime to + // bootstrap outlived it and silently answered null forever. + const syncPort = (): number | null => + hostListener ? hostListener.getPort() : args.getSyncPort?.() ?? null; + const expectedLoopbackNonce = (): string | null => + hostListener + ? hostListener.getExpectedLoopbackNonce() + : args.getExpectedLoopbackNonce?.() ?? null; + const relayBridgeProofValue = (): string | null => + hostListener ? hostListener.getRelayBridgeProof() : args.getRelayBridgeProof?.() ?? null; + const bridgeValidationIdentity = (): BridgeValidationIdentity => { const eligible = accountSignedIn(); - const port = args.getSyncPort(); - const nonce = args.getExpectedLoopbackNonce?.() ?? null; + const port = syncPort(); + const nonce = expectedLoopbackNonce(); return { key: JSON.stringify([ port, @@ -1312,10 +1349,10 @@ export function createSyncTunnelClientService(args: SyncTunnelClientArgs): SyncT if (!await validateCurrentBridge()) { rejectOpen( - args.getSyncPort() == null || !accountSignedIn() + syncPort() == null || !accountSignedIn() ? RELAY_CLOSE_HOST_UNAVAILABLE : RELAY_CLOSE_BRIDGE_REJECTED, - args.getSyncPort() == null ? "host sync listener unavailable" : "bridge validation failed", + syncPort() == null ? "host sync listener unavailable" : "bridge validation failed", ); return; } @@ -1337,7 +1374,7 @@ export function createSyncTunnelClientService(args: SyncTunnelClientArgs): SyncT rejectOpen(RELAY_CLOSE_BRIDGE_REJECTED, "bridge identity changed"); return; } - const relayBridgeProof = args.getRelayBridgeProof(); + const relayBridgeProof = relayBridgeProofValue(); if (!relayBridgeProof) { clearBridgeValidation(); recordFailure("Relay bridge refused because the local bridge credential is unavailable."); @@ -1626,9 +1663,52 @@ export function createSyncTunnelClientService(args: SyncTunnelClientArgs): SyncT await refreshAccountLease(); }, + attachHostListener(listener: TunnelHostListener | null): void { + if (hostListener === listener) return; + const hadListener = hostListener != null; + detachHostListener?.(); + detachHostListener = null; + hostListener = listener; + // Swapping owners has to invalidate what the previous owner proved. + // Ready tunnels keep forwarding into the OLD listener's local socket, so + // leaving them up means "new owner wins" is only true for validation + // inputs while live traffic still reaches the machine that no longer + // owns the bridge. Drop the validation and the pipes together; the next + // tunnel re-opens against the new listener. + if (hadListener) { + clearBridgeValidation(); + closeRelayConnections("host listener replaced"); + } + if (!listener) return; + // Re-run validation whenever the listener re-validates loopback. This + // subscription used to be registered in the construction closure, so + // when the creating runtime had no listener it silently bound to + // nothing and the one retry path that could repair a startup-ordering + // failure never fired. + detachHostListener = listener.onLoopbackValidated(() => { + void validateCurrentBridge().catch((error) => { + log.warn?.("sync_tunnel.bridge_validation_failed", { + error: error instanceof Error ? error.message : String(error), + }); + }); + }); + // The listener may already be bound and validated by the time the host + // attaches, in which case no future event is coming. Skip while it is + // still unbound: attach happens during runtime construction, before + // ensureListening, and validating there only records a "listener is not + // bound" failure that doctor and Settings surface until the subscription + // above clears it. + if (!stopped && listener.getPort() != null) { + void validateCurrentBridge().catch(() => {}); + } + }, + async stop(): Promise { stopped = true; started = false; + detachHostListener?.(); + detachHostListener = null; + hostListener = null; clearReconnect(); if (accountStatusTimer) { clearInterval(accountStatusTimer); diff --git a/apps/desktop/src/main/services/account/accountBridge.trust.test.ts b/apps/desktop/src/main/services/account/accountBridge.trust.test.ts index d3f6eec75..0fbaee13c 100644 --- a/apps/desktop/src/main/services/account/accountBridge.trust.test.ts +++ b/apps/desktop/src/main/services/account/accountBridge.trust.test.ts @@ -458,6 +458,8 @@ describe("desktop account machine lifecycle", () => { const reconcileAccountOwnership = vi.fn(() => ({ removedTargetIds: [], removedCredentialHostIds: [], + removedCredentials: [], + currentOwnerUserId: null, })); const { createAccountBridge } = await import("./accountBridge"); const bridge = createAccountBridge({ @@ -600,6 +602,8 @@ describe("desktop account machine lifecycle", () => { const reconcileAccountOwnership = vi.fn(() => ({ removedTargetIds: [], removedCredentialHostIds: [], + removedCredentials: [], + currentOwnerUserId: null, })); const { createAccountBridge } = await import("./accountBridge"); const bridge = createAccountBridge({ diff --git a/apps/desktop/src/main/services/account/accountBridge.ts b/apps/desktop/src/main/services/account/accountBridge.ts index e4b4ad3cb..92258c509 100644 --- a/apps/desktop/src/main/services/account/accountBridge.ts +++ b/apps/desktop/src/main/services/account/accountBridge.ts @@ -16,7 +16,9 @@ import { } from "../../../../../ade-cli/src/services/account/sharedAccountAuthService"; import { AccountMachineDirectoryService } from "../../../../../ade-cli/src/services/account/accountMachineDirectoryService"; import { resolveMachineAdeLayout } from "../../../../../ade-cli/src/services/projects/machineLayout"; +import { createFileLogger, type Logger } from "../logging/logger"; import os from "node:os"; +import path from "node:path"; import type { AccountAuthStatus, AccountLoginStartResult, @@ -167,6 +169,26 @@ export function createAccountBridge(options: AccountBridgeOptions): AccountBridg directoryBaseUrl: () => resolveDirectoryBaseUrl(options.getProjectRoot()), deviceName: () => `ADE Desktop on ${os.hostname()}`, }); + // Machine-scoped, deliberately not the project logger. Dropping a paired + // secret is a machine-level credential mutation, and the project logger + // follows the active project — which, on a remote-bound project, ships these + // records to the other machine and leaves nothing behind on the machine that + // actually lost its trust. Resolved lazily and defensively: a log sink is + // never worth failing account auth over. + let machineLogger: Logger | null | undefined; + const getMachineLogger = (): Logger | null => { + if (machineLogger !== undefined) return machineLogger; + try { + const { runtimeDir } = resolveMachineAdeLayout(); + machineLogger = runtimeDir + ? createFileLogger(path.join(runtimeDir, "account-trust.jsonl")) + : null; + } catch { + machineLogger = null; + } + return machineLogger; + }; + const reconcileLocalMachines = (currentOwnerUserId: string | null): void => { const result = options.reconcileAccountOwnership?.(currentOwnerUserId); if ( @@ -174,10 +196,32 @@ export function createAccountBridge(options: AccountBridgeOptions): AccountBridg && (result.removedTargetIds.length > 0 || result.removedCredentialHostIds.length > 0) ) { - options.logger?.info("account.local_machines_removed", { + const counts = { targetCount: result.removedTargetIds.length, credentialCount: result.removedCredentialHostIds.length, + }; + // Warn, not info: each removed credential costs the user a manual + // re-pair of that machine, so this is never routine. + // + // Account and host identifiers go ONLY to the machine-local sink. The + // project logger is the reason this split exists — on a remote-bound + // project it ships records to the other machine, so putting owner ids in + // it would re-introduce exactly the cross-machine identifier exposure the + // split was added to prevent. It gets counts, nothing more. + getMachineLogger()?.warn("account.local_machines_removed", { + ...counts, + currentOwnerUserId: result.currentOwnerUserId, + removed: result.removedCredentials.map((credentials) => ({ + hostDeviceId: credentials.hostDeviceId, + hostName: credentials.hostName, + previousOwnerUserId: credentials.previousOwnerUserId, + })), }); + // Dropping a paired secret is the forensic record for "why did my + // pairing vanish". The file logger batches on a 500 ms timer, so a quit + // that follows the prune closely would lose exactly that line. + getMachineLogger()?.flushSync?.(); + options.logger?.info("account.local_machines_removed", counts); } }; diff --git a/apps/desktop/src/main/services/analytics/productAnalyticsPolicy.ts b/apps/desktop/src/main/services/analytics/productAnalyticsPolicy.ts index 44f33440d..8815950f6 100644 --- a/apps/desktop/src/main/services/analytics/productAnalyticsPolicy.ts +++ b/apps/desktop/src/main/services/analytics/productAnalyticsPolicy.ts @@ -15,7 +15,8 @@ export const MAX_LOCAL_IDENTIFIER_LENGTH = 512; export const INTERNAL_ONLY_EVENTS = new Set([ "ade_work_session_started", "ade_work_session_completed", "ade_daily_usage_summary", "ade_analytics_budget", - "ade_update_install_aborted", "ade_update_quit_escalated", "ade_update_auto_applied", + "ade_update_install_aborted", "ade_update_quit_escalated", "ade_update_install_did_not_land", + "ade_update_auto_applied", "ade_update_auto_apply_cancelled", "ade_brain_recovered", "ade_publish_failing", ]); @@ -32,6 +33,7 @@ export const EVENT_DAILY_BUDGETS: Record = { ade_analytics_budget: 2, ade_update_install_aborted: 20, ade_update_quit_escalated: 10, + ade_update_install_did_not_land: 10, ade_update_auto_applied: 10, ade_update_auto_apply_cancelled: 10, ade_brain_recovered: 10, @@ -50,6 +52,7 @@ export const EVENT_MINUTE_BUDGETS: Record = { ade_analytics_budget: 2, ade_update_install_aborted: 6, ade_update_quit_escalated: 3, + ade_update_install_did_not_land: 3, ade_update_auto_applied: 3, ade_update_auto_apply_cancelled: 3, ade_brain_recovered: 3, @@ -60,6 +63,7 @@ const STRING_PROPERTIES = new Set([ "screen", "feature", "action", "outcome", "app_version", "runtime_mode", "provider", "model_family", "duration_bucket", "error_kind", "route_kind", "connection_state", "drop_reason", "source", "mode", "entry_point", "release_channel", "summary_kind", "reason", "last_command", "leg", "code", + "escalation_reason", ]); const NUMBER_PROPERTIES = new Set([ "sent_count", "dropped_count", "interaction_count", "session_count", "chat_session_count", @@ -67,9 +71,11 @@ const NUMBER_PROPERTIES = new Set([ "push_operations", "pr_landings", "files_changed", "artifacts_captured", "automation_runs", "worker_runs", "active_days", "current_streak_days", "token_count", "input_token_count", "output_token_count", "call_count", "duration_ms", "provider_count", "model_count", "error_count", "bytes_freed", "files_compressed", "blocked_ms", - "failing_minutes", + "failing_minutes", "attempt", +]); +const BOOLEAN_PROPERTIES = new Set([ + "recoverable", "paired", "cached_data", "is_packaged", "native_staging_completed", ]); -const BOOLEAN_PROPERTIES = new Set(["recoverable", "paired", "cached_data", "is_packaged"]); // Actions emitted only by daemon services (not user-mutation ledger rows) that // are still meaningful product facts. Kept here rather than in the usage-stats @@ -100,7 +106,8 @@ const EVENT_PROPERTY_KEYS: Record ]), ade_analytics_budget: new Set(["sent_count", "dropped_count", "drop_reason"]), ade_update_install_aborted: new Set(["reason"]), - ade_update_quit_escalated: new Set(["blocked_ms"]), + ade_update_quit_escalated: new Set(["blocked_ms", "escalation_reason", "native_staging_completed"]), + ade_update_install_did_not_land: new Set(["attempt"]), ade_update_auto_applied: new Set(), ade_update_auto_apply_cancelled: new Set(), ade_brain_recovered: new Set(["blocked_ms", "last_command"]), @@ -146,6 +153,7 @@ const SAFE_STRING_VALUES: Partial>> = { release_channel: new Set(["stable", "beta", "development", "unknown"]), summary_kind: new Set(["overall", "client", "provider", "model"]), reason: new Set(AUTO_UPDATE_INSTALL_ABORT_REASONS), + escalation_reason: new Set(["hard_deadline", "post_staging"]), }; export function safeProductAnalyticsString(value: ProductAnalyticsPropertyValue): string | null { diff --git a/apps/desktop/src/main/services/logging/logger.test.ts b/apps/desktop/src/main/services/logging/logger.test.ts index df0ad2af6..b5c8f6ba6 100644 --- a/apps/desktop/src/main/services/logging/logger.test.ts +++ b/apps/desktop/src/main/services/logging/logger.test.ts @@ -64,4 +64,52 @@ describe("createFileLogger", () => { expect(consoleSpy).not.toHaveBeenCalled(); }); + + // Callers on their way to app.exit() rely on this: the normal batched write + // never lands, so without a synchronous drain the records that explain the + // exit are lost. + it("writes queued lines to disk synchronously on flushSync", () => { + const logPath = path.join(fs.mkdtempSync(path.join(os.tmpdir(), "ade-logger-")), "test.log"); + const logger = createFileLogger(logPath); + + logger.error("autoUpdate.quit_escalated", { blockedMs: 300_000 }); + logger.flushSync?.(); + + const written = fs.readFileSync(logPath, "utf8").trim().split("\n"); + expect(written).toHaveLength(1); + expect(JSON.parse(written[0])).toMatchObject({ + level: "error", + event: "autoUpdate.quit_escalated", + meta: { blockedMs: 300_000 }, + }); + }); + + // Regression: a line landing exactly on the batch limit makes scheduleFlush + // call flush() synchronously, which splices the batch out before its first + // await. Draining only the queue would then write nothing and the app.exit() + // that follows would lose the record flushSync exists to preserve. + it("drains a batch already handed to an in-flight flush", () => { + const logPath = path.join(fs.mkdtempSync(path.join(os.tmpdir(), "ade-logger-")), "test.log"); + const logger = createFileLogger(logPath, { flushBatchSize: 2 }); + + logger.info("first.event"); + // Hits flushBatchSize, so flush() runs synchronously up to its first await + // and the batch is no longer in queuedLines. + logger.error("autoUpdate.quit_escalated", { blockedMs: 300_000 }); + logger.flushSync?.(); + + const written = fs.readFileSync(logPath, "utf8"); + expect(written).toContain("autoUpdate.quit_escalated"); + expect(written).toContain("first.event"); + }); + + it("is a no-op on flushSync with nothing queued", () => { + const logPath = path.join(fs.mkdtempSync(path.join(os.tmpdir(), "ade-logger-")), "test.log"); + const logger = createFileLogger(logPath); + + logger.flushSync?.(); + logger.flushSync?.(); + + expect(fs.existsSync(logPath)).toBe(false); + }); }); diff --git a/apps/desktop/src/main/services/logging/logger.ts b/apps/desktop/src/main/services/logging/logger.ts index ca2b58cd4..8db039d03 100644 --- a/apps/desktop/src/main/services/logging/logger.ts +++ b/apps/desktop/src/main/services/logging/logger.ts @@ -29,6 +29,13 @@ export type Logger = { info: (event: string, meta?: Record) => void; warn: (event: string, meta?: Record) => void; error: (event: string, meta?: Record) => void; + // Writes still-queued lines straight to disk. Normal logging batches through + // an async stream, so a caller about to end the process (app.exit, force + // quit) must call this or its last records are lost — exactly the records + // that explain why the process died. Note it cannot recover a batch already + // handed to an in-flight async flush, so call it immediately after the write + // that matters, while that line is still queued. + flushSync?: () => void; }; function resolveMinLevel(): number { @@ -79,6 +86,9 @@ export function createFileLogger( let queuedLines: string[] = []; let flushTimer: NodeJS.Timeout | null = null; let flushInProgress = false; + // The batch a running flush() spliced out of queuedLines but has not yet + // written. flushSync must be able to reach it. + let inFlightPayload: string | null = null; let flushRequested = false; let logDirReady = false; let logStream: fs.WriteStream | null = null; @@ -194,6 +204,7 @@ export function createFileLogger( const payload = lines.join(""); const bytes = Buffer.byteLength(payload, "utf8"); flushInProgress = true; + inFlightPayload = payload; try { if (!ensureLogDir()) return; @@ -203,6 +214,7 @@ export function createFileLogger( } catch { // Last ditch: avoid crashing the app on log write failures. } finally { + inFlightPayload = null; flushInProgress = false; if (flushRequested || queuedLines.length > 0) { flushRequested = false; @@ -224,6 +236,31 @@ export function createFileLogger( flushTimer.unref?.(); }; + // Drains the in-flight batch as well as the queue. A line that lands exactly + // on the batch limit triggers flush() synchronously, which splices it out + // before its first await — so draining only queuedLines would return having + // written nothing, and the app.exit() that follows would kill the pending + // write and lose precisely the record this API exists to preserve. Rotation + // is skipped deliberately: on the way out, a slightly oversized log beats a + // lost one, and a duplicated line beats a missing one if the async write also + // lands. + const flushSync = () => { + if (flushTimer) { + clearTimeout(flushTimer); + flushTimer = null; + } + const pending = inFlightPayload ?? ""; + if (pending.length === 0 && queuedLines.length === 0) return; + const payload = pending + queuedLines.splice(0, queuedLines.length).join(""); + try { + if (!ensureLogDir()) return; + fs.appendFileSync(logFilePath, payload); + estimatedFileSize = (estimatedFileSize ?? 0) + Buffer.byteLength(payload, "utf8"); + } catch { + // Same contract as flush(): never crash the app over a log write. + } + }; + const writeLine = (level: LogLevel, event: string, meta?: Record) => { if (LOG_LEVELS[level] < minLevel) return; @@ -245,6 +282,7 @@ export function createFileLogger( debug: (event, meta) => writeLine("debug", event, meta), info: (event, meta) => writeLine("info", event, meta), warn: (event, meta) => writeLine("warn", event, meta), - error: (event, meta) => writeLine("error", event, meta) + error: (event, meta) => writeLine("error", event, meta), + flushSync }; } diff --git a/apps/desktop/src/main/services/remoteRuntime/remoteConnectionService.test.ts b/apps/desktop/src/main/services/remoteRuntime/remoteConnectionService.test.ts index 4648c88a1..37d7587c9 100644 --- a/apps/desktop/src/main/services/remoteRuntime/remoteConnectionService.test.ts +++ b/apps/desktop/src/main/services/remoteRuntime/remoteConnectionService.test.ts @@ -563,8 +563,9 @@ describe("RemoteConnectionService", () => { } as unknown as RemoteConnectionPool; const pairedStore = { pruneAccountOwned: vi.fn(() => [{ - hostIdentity: { deviceId: "owned-host" }, + hostIdentity: { deviceId: "owned-host", name: "Owned Host" }, machineKey: "owned-key", + accountOwnerUserId: "account-a", }]), }; const service = new RemoteConnectionService(registry, pool, {}, pairedStore as any); @@ -574,6 +575,13 @@ describe("RemoteConnectionService", () => { expect(service.reconcileAccountOwnership("account-b")).toEqual({ removedTargetIds: [accountOwned.id], removedCredentialHostIds: ["owned-host"], + // Detail the prune log needs to name what trust it destroyed. + removedCredentials: [{ + hostDeviceId: "owned-host", + hostName: "Owned Host", + previousOwnerUserId: "account-a", + }], + currentOwnerUserId: "account-b", }); expect(pool.disconnect).toHaveBeenCalledWith(accountOwned.id); expect(pool.disconnect).not.toHaveBeenCalledWith(localOwned.id); @@ -605,6 +613,8 @@ describe("RemoteConnectionService", () => { expect(service.reconcileAccountOwnership(null)).toEqual({ removedTargetIds: [], removedCredentialHostIds: [], + removedCredentials: [], + currentOwnerUserId: null, }); expect(pool.reconcileAccountRelayOwner).toHaveBeenCalledWith(null); expect(registry.pruneAccountOwned).not.toHaveBeenCalled(); diff --git a/apps/desktop/src/main/services/remoteRuntime/remoteConnectionService.ts b/apps/desktop/src/main/services/remoteRuntime/remoteConnectionService.ts index 0b2bbde3c..4abb628c8 100644 --- a/apps/desktop/src/main/services/remoteRuntime/remoteConnectionService.ts +++ b/apps/desktop/src/main/services/remoteRuntime/remoteConnectionService.ts @@ -86,6 +86,18 @@ type RemoteConnectionServiceOptions = { export type AccountMachineReconciliationResult = { removedTargetIds: string[]; removedCredentialHostIds: string[]; + /** + * Detail for the removed pairings. Dropping a paired secret forces the user + * to re-pair that machine by hand, so the reason has to be reconstructable + * afterwards from a log — counts alone are not enough to tell an intended + * account switch from an identity glitch that silently cost trust. + */ + removedCredentials: Array<{ + hostDeviceId: string; + hostName: string | null; + previousOwnerUserId: string | null; + }>; + currentOwnerUserId: string | null; }; type RemoteConnectionDisconnectOptions = { @@ -321,12 +333,23 @@ export class RemoteConnectionService { removedCredentialHostIds: removedCredentials.map( (credentials) => credentials.hostIdentity.deviceId, ), + removedCredentials: removedCredentials.map((credentials) => ({ + hostDeviceId: credentials.hostIdentity.deviceId, + hostName: credentials.hostIdentity.name ?? null, + previousOwnerUserId: credentials.accountOwnerUserId ?? null, + })), + currentOwnerUserId, }; } async reconcileAuthorizedAccountOwnership(): Promise { if (!this.options.getAuthorizedAccountOwnerId) { - return { removedTargetIds: [], removedCredentialHostIds: [] }; + return { + removedTargetIds: [], + removedCredentialHostIds: [], + removedCredentials: [], + currentOwnerUserId: null, + }; } const currentOwnerUserId = await this.options.getAuthorizedAccountOwnerId() .catch(() => null); @@ -433,6 +456,10 @@ export class RemoteConnectionService { appVersion: this.options.appVersion, relayAccountToken, runtimeHostGrant: parsed.runtimeHostGrant ?? null, + // Known from the pairing payload; lets the store reuse this + // desktop's existing identity for the host instead of orphaning + // a record there on every re-pair. + hostDeviceId: parsed.hostIdentity.deviceId, }, ); if (paired.hostIdentity.deviceId !== parsed.hostIdentity.deviceId) { diff --git a/apps/desktop/src/main/services/remoteRuntime/syncPairedMachineStore.test.ts b/apps/desktop/src/main/services/remoteRuntime/syncPairedMachineStore.test.ts index d485f5b7a..070646241 100644 --- a/apps/desktop/src/main/services/remoteRuntime/syncPairedMachineStore.test.ts +++ b/apps/desktop/src/main/services/remoteRuntime/syncPairedMachineStore.test.ts @@ -329,6 +329,142 @@ describe("DesktopPairedMachineStore", () => { }); }); + // Regression: re-pairing used to mint a fresh local device id every time. + // The host keys pairing records by that id, so each re-pair left it holding + // another record it could never match again — an unbounded pile of orphaned, + // still-valid secrets, and one observed machine had accumulated six. + it("reuses this desktop's pairing identity when re-pairing the same machine", async () => { + const adeHome = fs.mkdtempSync(path.join(os.tmpdir(), "ade-desktop-repair-")); + process.env.ADE_HOME = adeHome; + const presentedDeviceIds: string[] = []; + + const createWebSocket = () => new FakeWebSocket((text, ws) => { + const envelope = parseSyncEnvelope(wsDataToText(text)); + if (envelope.type === "pairing_request") { + const payload = envelope.payload as { peer: { deviceId: string } }; + presentedDeviceIds.push(payload.peer.deviceId); + ws.receive(encodeSyncEnvelope({ + type: "pairing_result", + requestId: envelope.requestId, + payload: { + ok: true, + deviceId: payload.peer.deviceId, + secret: "host-issued-secret", + }, + })); + return; + } + if (envelope.type !== "hello") return; + const payload = envelope.payload as { peer: unknown }; + ws.receive(encodeSyncEnvelope({ + type: "hello_ok", + requestId: envelope.requestId, + payload: { + peer: payload.peer, + brain: { + deviceId: "mac-studio-host", + deviceName: "Studio", + platform: "macOS", + deviceType: "desktop", + siteId: "mac-studio-site", + dbVersion: 0, + }, + serverDbVersion: 0, + heartbeatIntervalMs: 5_000, + pollIntervalMs: 1_500, + // Deliberately no relay URL: a LAN endpoint yields no machine key, + // which is the exact case the first fix attempt would have missed. + features: { rpcChannel: true, portForward: true }, + }, + })); + }) as unknown as WebSocket; + + const store = new DesktopPairedMachineStore(); + const first = await store.pairWithMachine( + "ws://192.168.1.240:8806", + "123456", + "Desktop client", + { pairingTimeoutMs: 2_000, createWebSocket, hostDeviceId: "mac-studio-host" }, + ); + const second = await store.pairWithMachine( + "ws://192.168.1.240:8806", + "123456", + "Desktop client", + { pairingTimeoutMs: 2_000, createWebSocket, hostDeviceId: "mac-studio-host" }, + ); + + expect(presentedDeviceIds).toHaveLength(2); + expect(presentedDeviceIds[1]).toBe(presentedDeviceIds[0]); + expect(second.deviceId).toBe(first.deviceId); + expect(second.siteId).toBe(first.siteId); + expect(new DesktopPairedMachineStore().list()).toHaveLength(1); + }); + + // Regression: identity recovery once fell back to matching any saved record + // holding this endpoint. A bare LAN address is not a host identity — DHCP + // handing 192.168.1.240 to a different Mac would have handed that Mac the + // identity this desktop uses with the first one. + it("does not reuse an identity from a different host that once used this endpoint", async () => { + const adeHome = fs.mkdtempSync(path.join(os.tmpdir(), "ade-desktop-endpoint-")); + process.env.ADE_HOME = adeHome; + const presentedDeviceIds: string[] = []; + const sharedEndpoint = "ws://192.168.1.240:8806"; + + const makeSocket = (hostDeviceId: string) => () => new FakeWebSocket((text, ws) => { + const envelope = parseSyncEnvelope(wsDataToText(text)); + if (envelope.type === "pairing_request") { + const payload = envelope.payload as { peer: { deviceId: string } }; + presentedDeviceIds.push(payload.peer.deviceId); + ws.receive(encodeSyncEnvelope({ + type: "pairing_result", + requestId: envelope.requestId, + payload: { ok: true, deviceId: payload.peer.deviceId, secret: "host-issued-secret" }, + })); + return; + } + if (envelope.type !== "hello") return; + const payload = envelope.payload as { peer: unknown }; + ws.receive(encodeSyncEnvelope({ + type: "hello_ok", + requestId: envelope.requestId, + payload: { + peer: payload.peer, + brain: { + deviceId: hostDeviceId, + deviceName: hostDeviceId, + platform: "macOS", + deviceType: "desktop", + siteId: `${hostDeviceId}-site`, + dbVersion: 0, + }, + serverDbVersion: 0, + heartbeatIntervalMs: 5_000, + pollIntervalMs: 1_500, + features: { rpcChannel: true, portForward: true }, + }, + })); + }) as unknown as WebSocket; + + const store = new DesktopPairedMachineStore(); + const first = await store.pairWithMachine(sharedEndpoint, "123456", "Desktop client", { + pairingTimeoutMs: 2_000, + createWebSocket: makeSocket("mac-a"), + hostDeviceId: "mac-a", + }); + // Same address, different machine answering — the record for mac-a still + // lists this endpoint. + const second = await store.pairWithMachine(sharedEndpoint, "123456", "Desktop client", { + pairingTimeoutMs: 2_000, + createWebSocket: makeSocket("mac-b"), + hostDeviceId: "mac-b", + }); + + expect(presentedDeviceIds).toHaveLength(2); + expect(second.deviceId).not.toBe(first.deviceId); + expect(second.siteId).not.toBe(first.siteId); + expect(new DesktopPairedMachineStore().list()).toHaveLength(2); + }); + it("replaces stale relay connection metadata only when explicitly requested", () => { const filePath = path.join( fs.mkdtempSync(path.join(os.tmpdir(), "ade-desktop-pairing-store-")), diff --git a/apps/desktop/src/main/services/remoteRuntime/syncPairedMachineStore.ts b/apps/desktop/src/main/services/remoteRuntime/syncPairedMachineStore.ts index 7566b7f68..660d2e6f5 100644 --- a/apps/desktop/src/main/services/remoteRuntime/syncPairedMachineStore.ts +++ b/apps/desktop/src/main/services/remoteRuntime/syncPairedMachineStore.ts @@ -63,6 +63,13 @@ export type PairWithMachineOptions = Omit< pairingTimeoutMs?: number; relayAccountToken?: string | null; runtimeHostGrant?: string | null; + /** + * Host this pairing is aimed at, when the caller already knows it (a QR or + * link payload carries it). Lets re-pairing reuse this desktop's existing + * pairing identity for that host instead of minting a new one, which the + * host would store as a second, permanently unmatchable record. + */ + hostDeviceId?: string | null; }; export type PairWithAccountMachineOptions = Omit< @@ -578,8 +585,37 @@ export class DesktopPairedMachineStore { if (!deviceName) throw new Error("Desktop device name is required."); const keys = generateDesktopDpopKeyPair(); - const localDeviceId = randomUUID(); - const siteId = randomUUID(); + // Re-pairing the same machine must reuse this desktop's existing pairing + // identity. The host keys its pairing records by this device id and upserts + // on re-pair, so minting a fresh one instead leaves behind a record the host + // can never match again — one orphaned, still-valid secret per re-pair, + // forever. + // + // Known tradeoff: because the host upserts on this id, `pairPeer` rotates + // the secret and DPoP binding for an EXISTING record before it answers, and + // this client only persists the replacement after `hello_ok`. A drop in + // between leaves the host holding credentials the desktop never saved, so a + // previously working pairing needs one more manual re-pair. Minting a fresh + // id instead would avoid that window at the cost of the unbounded orphaned- + // record leak this reuse exists to stop — strictly worse. Closing it + // properly needs an atomic commit/ack in the pairing protocol, which is a + // host-side change and not something to land in a merge loop. + // + // The hello that reports the host identity arrives after the pairing request + // that carries this id, so the prior record has to be recovered up front: + // by the host the caller is aiming at, else the relay machine key. Both + // identify a HOST. Matching on a saved endpoint deliberately is not an + // option — a bare LAN address is not a host identity, so DHCP handing + // 192.168.1.240 to a different Mac would hand that Mac the identity this + // desktop uses with the first one. + const endpointMachineKey = machineKeyFromEndpoint(endpoint); + const existing = (options.hostDeviceId?.trim() + ? this.get(options.hostDeviceId.trim()) + : null) + ?? (endpointMachineKey ? this.get(endpointMachineKey) : null) + ?? null; + const localDeviceId = existing?.deviceId ?? randomUUID(); + const siteId = existing?.siteId ?? randomUUID(); const createdAt = nowIso(); const connection = await openSyncEnvelopeConnection({ endpoint, diff --git a/apps/desktop/src/main/services/state/globalState.ts b/apps/desktop/src/main/services/state/globalState.ts index e416d44e9..dbdb77360 100644 --- a/apps/desktop/src/main/services/state/globalState.ts +++ b/apps/desktop/src/main/services/state/globalState.ts @@ -35,6 +35,16 @@ export type PendingInstallUpdate = { requestedAt: string; }; +// Consecutive installs of the same version that quit without landing. The +// archive was already checksum-verified before it went "ready", so the first +// failure keeps it and a retry skips re-downloading; a repeat says the archive +// itself is suspect and earns a clean slate. +export type FailedInstallAttempts = { + targetVersion: string; + count: number; + lastFailedAt: string; +}; + export type GlobalState = { lastProjectRoot?: string; lastRemoteProjectBinding?: Extract & { @@ -43,6 +53,7 @@ export type GlobalState = { recentProjects?: RecentProject[]; pendingInstallUpdate?: PendingInstallUpdate; recentlyInstalledUpdate?: RecentlyInstalledUpdate; + failedInstallAttempts?: FailedInstallAttempts; welcomeVideo?: AppWelcomeVideoState; }; diff --git a/apps/desktop/src/main/services/updates/autoUpdateService.test.ts b/apps/desktop/src/main/services/updates/autoUpdateService.test.ts index 63d5f36b4..007223c61 100644 --- a/apps/desktop/src/main/services/updates/autoUpdateService.test.ts +++ b/apps/desktop/src/main/services/updates/autoUpdateService.test.ts @@ -30,6 +30,7 @@ function makeLogger(): Logger { info: vi.fn(), warn: vi.fn(), error: vi.fn(), + flushSync: vi.fn(), }; } @@ -251,7 +252,10 @@ describe("createAutoUpdateService", () => { service.dispose(); }); - it("cleans cached downloads when a requested install relaunches on the old version", () => { + // The archive is checksum-verified before the update is offered, so one + // failed handoff does not make it suspect. Re-downloading the whole release + // on every retry is what made a flaky install cost gigabytes. + it("keeps the verified download when a requested install relaunches on the old version", () => { const globalStatePath = makeStatePath(); const updaterCacheDir = makeUpdaterCacheDir(); const logger = makeLogger(); @@ -275,12 +279,64 @@ describe("createAutoUpdateService", () => { updater: new FakeAutoUpdater(), }); - expect(readState(globalStatePath)).toEqual({}); + expect(readState(globalStatePath)).toEqual({ + failedInstallAttempts: { + targetVersion: "1.2.3", + count: 1, + lastFailedAt: "2026-04-06T15:21:00.000Z", + }, + }); + expect(fs.readdirSync(updaterCacheDir).sort()).toEqual(["pending", "update.zip"]); + expect(logger.error).toHaveBeenCalledWith( + "autoUpdate.install_did_not_land", + expect.objectContaining({ + targetVersion: "1.2.3", + attempt: 1, + downloadPreserved: true, + }), + ); + + service.dispose(); + }); + + it("clears the cached download after a second failed install of the same version", () => { + const globalStatePath = makeStatePath(); + const updaterCacheDir = makeUpdaterCacheDir(); + const logger = makeLogger(); + fs.writeFileSync(globalStatePath, JSON.stringify({ + pendingInstallUpdate: { + fromVersion: "1.2.2", + targetVersion: "1.2.3", + releaseNotesUrl: "https://www.ade-app.dev/docs/changelog/v1.2.3", + requestedAt: "2026-04-06T15:20:00.000Z", + }, + failedInstallAttempts: { + targetVersion: "1.2.3", + count: 1, + lastFailedAt: "2026-04-06T15:10:00.000Z", + }, + }), "utf8"); + + const service = createAutoUpdateService({ + logger, + currentVersion: "1.2.2", + globalStatePath, + updaterCacheDir, + startupDelayMs: 60_000, + periodicCheckMs: 60_000, + now: () => "2026-04-06T15:21:00.000Z", + updater: new FakeAutoUpdater(), + }); + expectCacheEmpty(updaterCacheDir); expect(logger.info).toHaveBeenCalledWith( "autoUpdate.cache_cleaned", expect.objectContaining({ reason: "failed_install", entriesRemoved: 2 }), ); + expect(logger.error).toHaveBeenCalledWith( + "autoUpdate.install_did_not_land", + expect.objectContaining({ attempt: 2, downloadPreserved: false }), + ); service.dispose(); }); @@ -1323,11 +1379,15 @@ describe("createAutoUpdateService", () => { service.dispose(); }); - it("force-quits when the native handoff does not reach will-quit by the hard deadline", async () => { + // Regression: the soft deadline used to force-quit, which killed the process + // mid-staging. Squirrel needs ~10s to expand and code-sign verify a ~750 MB + // bundle, so that raced — and usually beat — a healthy install. + it("does not force-quit while the native installer is still staging", async () => { vi.useFakeTimers(); const globalStatePath = makeStatePath(); const updaterCacheDir = makeUpdaterCacheDir(); const updater = new FakeAutoUpdater(); + const nativeUpdater = new EventEmitter(); const logger = makeLogger(); const forceQuit = vi.fn(); const service = createAutoUpdateService({ @@ -1336,7 +1396,9 @@ describe("createAutoUpdateService", () => { globalStatePath, updaterCacheDir, installWatchdogMs: 1_000, - quitDeadlineMs: 5_000, + quitStagingSlowWarnMs: 5_000, + quitHardDeadlineMs: 300_000, + nativeUpdater, forceQuit, getDiskSpace: () => ({ availableBytes: 20 * 1024 * 1024 * 1024, @@ -1350,28 +1412,162 @@ describe("createAutoUpdateService", () => { await expect(service.quitAndInstall()).resolves.toBe(true); expect(service.getSnapshot().status).toBe("installing"); - await vi.advanceTimersByTimeAsync(1_000); + // Well past the soft deadline: noted, never fatal. + await vi.advanceTimersByTimeAsync(60_000); + expect(forceQuit).not.toHaveBeenCalled(); + expect(logger.warn).toHaveBeenCalledWith("autoUpdate.quit_staging_slow", { + blockedMs: 5_000, + }); expect(service.getSnapshot().status).toBe("installing"); expect(readState(globalStatePath)).toMatchObject({ pendingInstallUpdate: { targetVersion: "1.2.3" }, }); + expect(fs.readdirSync(updaterCacheDir).sort()).toEqual(["pending", "update.zip"]); + + service.dispose(); + }); + + it("force-quits once staging finished but the process never exited", async () => { + vi.useFakeTimers(); + const globalStatePath = makeStatePath(); + const updaterCacheDir = makeUpdaterCacheDir(); + const updater = new FakeAutoUpdater(); + const nativeUpdater = new EventEmitter(); + const logger = makeLogger(); + const forceQuit = vi.fn(); + const service = createAutoUpdateService({ + logger, + currentVersion: "1.2.2", + globalStatePath, + updaterCacheDir, + installWatchdogMs: 1_000, + quitStagingSlowWarnMs: 5_000, + quitHardDeadlineMs: 300_000, + quitPostStagingDeadlineMs: 15_000, + nativeUpdater, + forceQuit, + getDiskSpace: () => ({ + availableBytes: 20 * 1024 * 1024 * 1024, + volumePath: "/System/Volumes/Data", + }), + autoCheckEnabled: false, + updater, + }); + updater.emit("update-downloaded", { version: "1.2.3" }); + + await expect(service.quitAndInstall()).resolves.toBe(true); - await vi.advanceTimersByTimeAsync(4_000); + await vi.advanceTimersByTimeAsync(20_000); + nativeUpdater.emit("update-downloaded"); + expect(forceQuit).not.toHaveBeenCalled(); + + await vi.advanceTimersByTimeAsync(15_000); expect(forceQuit).toHaveBeenCalledWith({ blockedPhase: "app_quit", - blockedMs: 5_000, + blockedMs: 35_000, }); expect(logger.error).toHaveBeenCalledWith("autoUpdate.quit_escalated", { blockedPhase: "app_quit", - blockedMs: 5_000, + blockedMs: 35_000, + reason: "post_staging", + nativeStagingCompleted: true, + }); + // The escalation record has to survive the app.exit() that follows. + expect(logger.flushSync).toHaveBeenCalled(); + + service.dispose(); + }); + + // Regression: the staged deadline is Squirrel.Mac-specific. Only MacUpdater + // drives the native updater, so on Windows/Linux the staging signal can never + // arrive — the long bound would strand the app in "installing" for five + // minutes where the previous code force-quit in ten seconds. + it("falls back to the short hard bound when no staging signal can arrive", async () => { + vi.useFakeTimers(); + const globalStatePath = makeStatePath(); + const updaterCacheDir = makeUpdaterCacheDir(); + const updater = new FakeAutoUpdater(); + const logger = makeLogger(); + const forceQuit = vi.fn(); + const service = createAutoUpdateService({ + logger, + currentVersion: "1.2.2", + globalStatePath, + updaterCacheDir, + installWatchdogMs: 1_000, + // No hard bound supplied: the default must come from whether a staging + // signal is possible at all, not from the macOS-only five-minute value. + nativeUpdater: null, + forceQuit, + getDiskSpace: () => ({ + availableBytes: 20 * 1024 * 1024 * 1024, + volumePath: "/System/Volumes/Data", + }), + autoCheckEnabled: false, + updater, + }); + updater.emit("update-downloaded", { version: "1.2.3" }); + + await expect(service.quitAndInstall()).resolves.toBe(true); + + await vi.advanceTimersByTimeAsync(59_000); + expect(forceQuit).not.toHaveBeenCalled(); + + await vi.advanceTimersByTimeAsync(1_500); + expect(forceQuit).toHaveBeenCalledWith({ + blockedPhase: "app_quit", + blockedMs: 60_000, + }); + + service.dispose(); + }); + + it("force-quits a handoff that never stages at all, at the hard deadline", async () => { + vi.useFakeTimers(); + const globalStatePath = makeStatePath(); + const updaterCacheDir = makeUpdaterCacheDir(); + const updater = new FakeAutoUpdater(); + const logger = makeLogger(); + const forceQuit = vi.fn(); + const service = createAutoUpdateService({ + logger, + currentVersion: "1.2.2", + globalStatePath, + updaterCacheDir, + installWatchdogMs: 1_000, + quitStagingSlowWarnMs: 5_000, + quitHardDeadlineMs: 300_000, + nativeUpdater: null, + forceQuit, + getDiskSpace: () => ({ + availableBytes: 20 * 1024 * 1024 * 1024, + volumePath: "/System/Volumes/Data", + }), + autoCheckEnabled: false, + updater, + }); + updater.emit("update-downloaded", { version: "1.2.3" }); + + await expect(service.quitAndInstall()).resolves.toBe(true); + + await vi.advanceTimersByTimeAsync(300_000); + + expect(forceQuit).toHaveBeenCalledWith({ + blockedPhase: "app_quit", + blockedMs: 300_000, + }); + expect(logger.error).toHaveBeenCalledWith("autoUpdate.quit_escalated", { + blockedPhase: "app_quit", + blockedMs: 300_000, + reason: "hard_deadline", + nativeStagingCompleted: false, }); expect(service.getSnapshot().status).toBe("installing"); expect(readState(globalStatePath)).toMatchObject({ pendingInstallUpdate: { targetVersion: "1.2.3" }, }); - expect(fs.readdirSync(updaterCacheDir).sort()).toEqual(["pending", "update.zip"]); service.dispose(); }); diff --git a/apps/desktop/src/main/services/updates/autoUpdateService.ts b/apps/desktop/src/main/services/updates/autoUpdateService.ts index ac2e61160..a1ab9920c 100644 --- a/apps/desktop/src/main/services/updates/autoUpdateService.ts +++ b/apps/desktop/src/main/services/updates/autoUpdateService.ts @@ -29,7 +29,24 @@ import { } from "./autoUpdateVersions"; const DEFAULT_INSTALL_WATCHDOG_MS = 30_000; -const DEFAULT_QUIT_DEADLINE_MS = 10_000; +// Warn only, never fatal. Squirrel.Mac needs roughly this long just to expand +// and code-sign verify the archive, so killing here loses a coin flip against a +// healthy install — which is exactly the bug this replaced. +const DEFAULT_QUIT_STAGING_SLOW_WARN_MS = 10_000; +// Hard bound while the OS installer may still be staging. Only a genuinely +// wedged handoff should reach this. macOS only: it is long because Squirrel.Mac +// stages in-process and signals when it is done. +const DEFAULT_QUIT_HARD_DEADLINE_MS = 5 * 60_000; +// Everywhere else the installer is an external process (NSIS, AppImage) that +// never emits the staging signal, so the long bound would just hang the app in +// "installing" for five minutes. Nothing stages in-process there, so a short +// bound is correct — and still far more generous than the 10s that broke macOS. +const DEFAULT_QUIT_HARD_DEADLINE_NO_STAGING_MS = 60_000; +// Once staging is done the installer is already running and about to replace +// the bundle, so a process that still has not exited is a real wedge and a +// short bound is safe again. +const DEFAULT_QUIT_POST_STAGING_DEADLINE_MS = 15_000; +const FAILED_INSTALL_CACHE_RESET_ATTEMPTS = 2; const DEFAULT_AUTO_APPLY_IDLE_MS = 2 * 60_000; const DEFAULT_AUTO_APPLY_COUNTDOWN_MS = 10_000; const DEFAULT_AUTO_APPLY_SUPPRESSION_MS = 4 * 60 * 60_000; @@ -51,6 +68,31 @@ type AutoUpdaterLike = { removeListener: (event: string, listener: (...args: any[]) => void) => unknown; }; +// Electron's own `autoUpdater`, i.e. the Squirrel.Mac binding that +// electron-updater's MacUpdater drives underneath. Its `update-downloaded` +// fires when the OS installer has finished staging the new bundle — the only +// in-process signal that the native handoff actually got somewhere. +type NativeUpdaterLike = { + on: (event: string, listener: (...args: any[]) => void) => unknown; + removeListener: (event: string, listener: (...args: any[]) => void) => unknown; +}; + +function resolveNativeUpdater(): NativeUpdaterLike | null { + // Resolved through require, NOT a static import, and this is load-bearing: + // tests mock "electron" as `{ app }`, and a static `import { autoUpdater }` + // makes vitest throw "No 'autoUpdater' export is defined on the electron + // mock" before any test body runs. A missing native updater must degrade to + // "no staging signal", never to a crash. + try { + if (typeof require !== "function") return null; + const electron = require("electron") as { autoUpdater?: NativeUpdaterLike }; + const candidate = electron?.autoUpdater; + return typeof candidate?.on === "function" ? candidate : null; + } catch { + return null; + } +} + type CreateAutoUpdateServiceArgs = { logger: Logger; currentVersion: string; @@ -70,7 +112,10 @@ type CreateAutoUpdateServiceArgs = { installTargetPath?: string; getDiskSpace?: (targetPath: string) => DiskSpaceInfo; installWatchdogMs?: number; - quitDeadlineMs?: number; + quitStagingSlowWarnMs?: number; + quitHardDeadlineMs?: number; + quitPostStagingDeadlineMs?: number; + nativeUpdater?: NativeUpdaterLike | null; autoApplyIdleMs?: number; autoApplyCountdownMs?: number; autoApplySuppressionMs?: number; @@ -111,6 +156,7 @@ export function createEmptyAutoUpdateSnapshot(currentVersion = ""): AutoUpdateSn errorDetails: null, recentlyInstalled: null, parked: null, + lastInstallFailed: null, autoApplyPending: null, autoApplySuppressedUntil: null, }; @@ -153,6 +199,7 @@ function cloneSnapshot(snapshot: AutoUpdateSnapshot): AutoUpdateSnapshot { ...snapshot, recentlyInstalled: cloneRecentlyInstalledUpdate(snapshot.recentlyInstalled), parked: snapshot.parked ? { ...snapshot.parked } : null, + lastInstallFailed: snapshot.lastInstallFailed ? { ...snapshot.lastInstallFailed } : null, autoApplyPending: snapshot.autoApplyPending ? { ...snapshot.autoApplyPending } : null, }; } @@ -208,10 +255,12 @@ function reconcilePersistedUpdateState(args: { changed: boolean; recentlyInstalled: RecentlyInstalledUpdate | null; cacheCleanupReason: string | null; + failedInstall: { targetVersion: string; attempt: number } | null; } { const nextState: GlobalState = { ...args.state }; let changed = false; let cacheCleanupReason: string | null = null; + let failedInstall: { targetVersion: string; attempt: number } | null = null; if ( nextState.recentlyInstalledUpdate @@ -221,6 +270,20 @@ function reconcilePersistedUpdateState(args: { changed = true; } + // The counter outlives the launch that recorded it, so the notice has to as + // well. Without this, one ordinary quit-and-reopen drops lastInstallFailed + // from the snapshot while the persisted counter still makes the next failure + // attempt 2 and evicts the cache — the UI would claim a clean slate the + // policy does not agree with. The renderer only shows it when it matches the + // version actually being offered, so surfacing it here is safe. + const persistedFailure = nextState.failedInstallAttempts; + if (persistedFailure) { + failedInstall = { + targetVersion: persistedFailure.targetVersion, + attempt: persistedFailure.count, + }; + } + const pendingInstall = nextState.pendingInstallUpdate; if (pendingInstall) { const installedTargetOrNewer = compareUpdateVersions(args.currentVersion, pendingInstall.targetVersion) >= 0; @@ -233,8 +296,26 @@ function reconcilePersistedUpdateState(args: { githubReleaseUrl: buildGithubReleaseUrl(args.currentVersion), }; cacheCleanupReason = "installed"; + nextState.failedInstallAttempts = undefined; + failedInstall = null; } else { - cacheCleanupReason = "failed_install"; + const previous = nextState.failedInstallAttempts; + const attempt = previous?.targetVersion === pendingInstall.targetVersion + ? previous.count + 1 + : 1; + nextState.failedInstallAttempts = { + targetVersion: pendingInstall.targetVersion, + count: attempt, + lastFailedAt: args.now, + }; + failedInstall = { targetVersion: pendingInstall.targetVersion, attempt }; + // First failure: the archive passed its checksum before it ever went + // "ready", so the quit lost a race rather than the bytes being bad. + // Keeping it turns a retry into a click instead of a fresh download of + // the whole release. A second failure stops trusting it. + cacheCleanupReason = attempt >= FAILED_INSTALL_CACHE_RESET_ATTEMPTS + ? "failed_install" + : null; } nextState.pendingInstallUpdate = undefined; changed = true; @@ -247,6 +328,7 @@ function reconcilePersistedUpdateState(args: { cloneRecentlyInstalledUpdate(nextState.recentlyInstalledUpdate ?? null), ), cacheCleanupReason, + failedInstall, }; } @@ -282,7 +364,15 @@ export function createAutoUpdateService({ installTargetPath = process.execPath, getDiskSpace = readDiskSpace, installWatchdogMs = DEFAULT_INSTALL_WATCHDOG_MS, - quitDeadlineMs = DEFAULT_QUIT_DEADLINE_MS, + quitStagingSlowWarnMs = DEFAULT_QUIT_STAGING_SLOW_WARN_MS, + // Only Squirrel.Mac reports staging progress; electron-updater's other + // backends never touch the native updater, so arming the long bound off a + // signal that cannot arrive would strand the app in "installing". + nativeUpdater = process.platform === "darwin" ? resolveNativeUpdater() : null, + quitHardDeadlineMs = nativeUpdater + ? DEFAULT_QUIT_HARD_DEADLINE_MS + : DEFAULT_QUIT_HARD_DEADLINE_NO_STAGING_MS, + quitPostStagingDeadlineMs = DEFAULT_QUIT_POST_STAGING_DEADLINE_MS, autoApplyIdleMs = DEFAULT_AUTO_APPLY_IDLE_MS, autoApplyCountdownMs = DEFAULT_AUTO_APPLY_COUNTDOWN_MS, autoApplySuppressionMs = DEFAULT_AUTO_APPLY_SUPPRESSION_MS, @@ -334,10 +424,27 @@ export function createAutoUpdateService({ reason: initialState.cacheCleanupReason, }); } + if (initialState.failedInstall) { + // Relaunching on the old version after an install was requested means the + // handoff never landed. Say so plainly: silently re-offering the same + // update is what made this look like the update "did nothing". + logger.error("autoUpdate.install_did_not_land", { + targetVersion: initialState.failedInstall.targetVersion, + currentVersion, + attempt: initialState.failedInstall.attempt, + downloadPreserved: initialState.cacheCleanupReason == null, + }); + productAnalyticsService?.captureInternal({ + event: "ade_update_install_did_not_land", + surface: "desktop", + properties: { attempt: initialState.failedInstall.attempt }, + }); + } let snapshot: AutoUpdateSnapshot = { ...createEmptyAutoUpdateSnapshot(currentVersion), recentlyInstalled: initialState.recentlyInstalled, + lastInstallFailed: initialState.failedInstall, }; let checkPromise: Promise | null = null; // In-flight guard for quitAndInstall. Two IPC callers (e.g. AutoUpdateControl @@ -357,7 +464,11 @@ export function createAutoUpdateService({ let compressedUpdateBytes: number | null = null; let compressedUpdateVersion: string | null = null; let preservedDownloadRetry: PreservedDownloadRetry | null = null; - let quitDeadlineTimer: ReturnType | null = null; + let escalationTimer: ReturnType | null = null; + let stagingSlowWarnTimer: ReturnType | null = null; + let quitArmedAtMs: number | null = null; + let nativeStagingCompleted = false; + let detachNativeStagingListener: (() => void) | null = null; let activityCheckTimer: ReturnType | null = null; let autoApplyDeadlineTimer: ReturnType | null = null; let idleSinceMs: number | null = null; @@ -397,9 +508,18 @@ export function createAutoUpdateService({ } function clearQuitDeadline(): void { - if (!quitDeadlineTimer) return; - clearTimeout(quitDeadlineTimer); - quitDeadlineTimer = null; + if (escalationTimer) { + clearTimeout(escalationTimer); + escalationTimer = null; + } + if (stagingSlowWarnTimer) { + clearTimeout(stagingSlowWarnTimer); + stagingSlowWarnTimer = null; + } + detachNativeStagingListener?.(); + detachNativeStagingListener = null; + quitArmedAtMs = null; + nativeStagingCompleted = false; } function clearAutoApplyDeadline(): void { @@ -1079,27 +1199,83 @@ export function createAutoUpdateService({ return false; } + function escalateQuit(reason: "hard_deadline" | "post_staging"): void { + if (!installQuitArmed) return; + const blockedMs = quitBlockedMs(); + const blockedPhase = "app_quit"; + logger.error("autoUpdate.quit_escalated", { + blockedPhase, + blockedMs, + reason, + nativeStagingCompleted, + }); + productAnalyticsService?.captureInternal({ + event: "ade_update_quit_escalated", + surface: "desktop", + properties: { + blocked_ms: blockedMs, + escalation_reason: reason, + native_staging_completed: nativeStagingCompleted, + }, + }); + // forceQuit ends the process outright, and log writes are batched onto an + // async stream — without this the record above dies with the process and + // the escalation leaves no trace at all. + logger.flushSync?.(); + forceQuit?.({ blockedPhase, blockedMs }); + } + + const quitBlockedMs = (): number => Math.max(0, nowMs() - (quitArmedAtMs ?? nowMs())); + + // One escalation timer, re-armed. Before staging completes it carries the + // long bound; after, the short one. Two variables would imply two ways to get + // force-quit, and there is only ever one armed at a time. + function armEscalation(delayMs: number, reason: "hard_deadline" | "post_staging"): void { + if (escalationTimer) clearTimeout(escalationTimer); + escalationTimer = setTimeout(() => { + escalationTimer = null; + escalateQuit(reason); + }, delayMs); + escalationTimer.unref?.(); + } + + // Squirrel finished expanding and verifying the new bundle and is handing off + // to its installer, so the remaining window is short and bounded. + function onNativeStagingComplete(): void { + if (!installQuitArmed || nativeStagingCompleted) return; + nativeStagingCompleted = true; + logger.info("autoUpdate.native_staging_complete", { elapsedMs: quitBlockedMs() }); + armEscalation(quitPostStagingDeadlineMs, "post_staging"); + } + function armQuitDeadline(): void { clearQuitDeadline(); installQuitArmed = true; - const startedAt = nowMs(); - quitDeadlineTimer = setTimeout(() => { - quitDeadlineTimer = null; - if (!installQuitArmed) return; - const blockedMs = Math.max(0, nowMs() - startedAt); - const blockedPhase = "app_quit"; - logger.error("autoUpdate.quit_escalated", { - blockedPhase, - blockedMs, - }); - productAnalyticsService?.captureInternal({ - event: "ade_update_quit_escalated", - surface: "desktop", - properties: { blocked_ms: blockedMs }, - }); - forceQuit?.({ blockedPhase, blockedMs }); - }, quitDeadlineMs); - quitDeadlineTimer.unref?.(); + nativeStagingCompleted = false; + quitArmedAtMs = nowMs(); + + if (nativeUpdater) { + const listener = () => onNativeStagingComplete(); + nativeUpdater.on("update-downloaded", listener); + detachNativeStagingListener = () => { + try { + nativeUpdater.removeListener("update-downloaded", listener); + } catch { + // A detached native updater is not worth failing the install over. + } + }; + } + + // Observation, not enforcement: staging legitimately runs past this on a + // large bundle or a busy disk. Killing here is what broke installs before. + stagingSlowWarnTimer = setTimeout(() => { + stagingSlowWarnTimer = null; + if (!installQuitArmed || nativeStagingCompleted) return; + logger.warn("autoUpdate.quit_staging_slow", { blockedMs: quitBlockedMs() }); + }, quitStagingSlowWarnMs); + stagingSlowWarnTimer.unref?.(); + + armEscalation(quitHardDeadlineMs, "hard_deadline"); } function dismissInstalledNotice(): void { @@ -1170,6 +1346,8 @@ export function createAutoUpdateService({ error: null, errorDetails: null, parked: null, + // This attempt supersedes the notice about the previous one. + lastInstallFailed: null, autoApplyPending: null, }); try { diff --git a/apps/desktop/src/renderer/components/app/AutoUpdateControl.test.tsx b/apps/desktop/src/renderer/components/app/AutoUpdateControl.test.tsx index 8bd259f83..4fe1ca4ca 100644 --- a/apps/desktop/src/renderer/components/app/AutoUpdateControl.test.tsx +++ b/apps/desktop/src/renderer/components/app/AutoUpdateControl.test.tsx @@ -21,6 +21,7 @@ const idleSnapshot: AutoUpdateSnapshot = { errorDetails: null, recentlyInstalled: null, parked: null, + lastInstallFailed: null, autoApplyPending: null, autoApplySuppressedUntil: null, }; diff --git a/apps/desktop/src/renderer/components/app/AutoUpdateControl.tsx b/apps/desktop/src/renderer/components/app/AutoUpdateControl.tsx index 2be1ddf9b..12733a0c0 100644 --- a/apps/desktop/src/renderer/components/app/AutoUpdateControl.tsx +++ b/apps/desktop/src/renderer/components/app/AutoUpdateControl.tsx @@ -201,6 +201,17 @@ export function AutoUpdateControl() { const runtimeRequiresDesktopUpdate = runtimeSkew?.state === "runtime_newer"; const showRuntimeSkewIndicator = runtimeRequiresDesktopUpdate && !shouldShowIndicator && !showUpdateError; + // A previous attempt quit but came back on the old version. Saying so beats + // re-offering the identical button as if nothing had happened. + const retryAfterFailedInstall = Boolean( + snapshot.lastInstallFailed + && snapshot.version + && snapshot.lastInstallFailed.targetVersion === snapshot.version, + ); + // A second consecutive failure stops trusting the archive and clears the + // cache, so only the first retry can promise the bytes are still local. + const downloadStillLocal = (snapshot.lastInstallFailed?.attempt ?? 0) < 2; + function indicatorTitle(): string { switch (effectiveStatus) { case "checking": @@ -210,7 +221,12 @@ export function AutoUpdateControl() { case "installing": return "ADE is preparing to quit and reopen automatically"; default: - return `Install ${versionLabel(snapshot.version)}. ADE will quit and reopen automatically.`; + return retryAfterFailedInstall + ? `The last attempt to install ${versionLabel(snapshot.version)} quit without finishing. ` + + (downloadStillLocal + ? "Try again — the download is already on this machine." + : "Try again — ADE will download it again first.") + : `Install ${versionLabel(snapshot.version)}. ADE will quit and reopen automatically.`; } } @@ -284,7 +300,10 @@ export function AutoUpdateControl() { ) : null} {effectiveStatus === "ready" ? ( - Install update {snapshot.version ? `v${snapshot.version}` : ""} + + {retryAfterFailedInstall ? "Retry install" : "Install update"} + {snapshot.version ? ` v${snapshot.version}` : ""} + ) : null} {effectiveStatus === "installing" ? ( ADE will quit and reopen diff --git a/apps/desktop/src/renderer/components/app/useAutoUpdateSnapshot.ts b/apps/desktop/src/renderer/components/app/useAutoUpdateSnapshot.ts index 048687f47..0f2374cd0 100644 --- a/apps/desktop/src/renderer/components/app/useAutoUpdateSnapshot.ts +++ b/apps/desktop/src/renderer/components/app/useAutoUpdateSnapshot.ts @@ -16,6 +16,7 @@ export const EMPTY_AUTO_UPDATE_SNAPSHOT: AutoUpdateSnapshot = { errorDetails: null, recentlyInstalled: null, parked: null, + lastInstallFailed: null, autoApplyPending: null, autoApplySuppressedUntil: null, }; diff --git a/apps/desktop/src/shared/types/core.ts b/apps/desktop/src/shared/types/core.ts index 030003859..b95a382bc 100644 --- a/apps/desktop/src/shared/types/core.ts +++ b/apps/desktop/src/shared/types/core.ts @@ -222,6 +222,12 @@ export type AutoUpdateSnapshot = { recentlyInstalled: RecentlyInstalledUpdate | null; /** A consented install that aborted before the native updater could take over. */ parked: { reason: AutoUpdateInstallAbortReason; at: number } | null; + /** + * A previous install quit but came back on the old version. Survives the + * restart so the UI can say the update did not land instead of silently + * offering the same version again. + */ + lastInstallFailed: { targetVersion: string; attempt: number } | null; /** Renderer-visible countdown before an idle update is applied. */ autoApplyPending: { deadlineAt: number } | null; /** Explicit user cancellation suppresses another idle countdown until this epoch. */ diff --git a/apps/desktop/src/shared/types/productAnalytics.ts b/apps/desktop/src/shared/types/productAnalytics.ts index 8a374f816..f434908c2 100644 --- a/apps/desktop/src/shared/types/productAnalytics.ts +++ b/apps/desktop/src/shared/types/productAnalytics.ts @@ -12,6 +12,7 @@ export const PRODUCT_ANALYTICS_EVENTS = [ "ade_analytics_budget", "ade_update_install_aborted", "ade_update_quit_escalated", + "ade_update_install_did_not_land", "ade_update_auto_applied", "ade_update_auto_apply_cancelled", "ade_brain_recovered", diff --git a/apps/ios/ADETests/ADETests.swift b/apps/ios/ADETests/ADETests.swift index 1e4c75d44..9f6a1a1d5 100644 --- a/apps/ios/ADETests/ADETests.swift +++ b/apps/ios/ADETests/ADETests.swift @@ -3617,6 +3617,54 @@ final class ADETests: XCTestCase { XCTAssertEqual(SyncUserFacingError.message(for: compressedPayloadError), "The machine sent unreadable sync data. Reconnect and try again.") } + /// The host owns the wording of `hello_error.message` and reworded it — a + /// paired-device rejection and an account-owner mismatch now carry their own + /// prose instead of a generic "authentication failed". iOS must key on + /// `ADEErrorCode`, never on that prose, so a host reword can never silently + /// drop these back to the raw server string. + func testSyncUserFacingAuthFailureIgnoresHostSuppliedWording() { + let rewordedPairingRejection = NSError( + domain: "ADE", + code: 5, + userInfo: [ + NSLocalizedDescriptionKey: "This device is not paired with this machine, or its saved pairing is no longer valid. Pair it again.", + "ADEErrorCode": "auth_failed", + ] + ) + XCTAssertEqual( + SyncUserFacingError.message(for: rewordedPairingRejection), + "This phone is no longer paired with this machine. Pair again from Settings." + ) + + let accountOwnerMismatch = NSError( + domain: "ADE", + code: 5, + userInfo: [ + NSLocalizedDescriptionKey: "This machine is signed in to a different ADE account than the one that paired this device.", + "ADEErrorCode": "auth_failed", + ] + ) + XCTAssertEqual( + SyncUserFacingError.message(for: accountOwnerMismatch), + "This phone is no longer paired with this machine. Pair again from Settings." + ) + + // Attribution still wins over the code, whatever the host wrote. + let unattributedReword = NSError( + domain: "ADE", + code: 5, + userInfo: [ + NSLocalizedDescriptionKey: "This device is not paired with this machine, or its saved pairing is no longer valid. Pair it again.", + "ADEErrorCode": "auth_failed", + "ADEAmbiguousRouteAuthFailure": true, + ] + ) + XCTAssertEqual( + SyncUserFacingError.message(for: unattributedReword), + "A machine on this route rejected the saved pairing — possibly a different ADE machine. ADE kept the pairing and will keep trying other routes. If you unpaired this phone on purpose, pair again from Settings." + ) + } + @MainActor func testSyncServiceMigratesLegacyConnectionDraftProfile() throws { let legacyDraftKey = "ade.sync.connectionDraft" diff --git a/docs/ARCHITECTURE.md b/docs/ARCHITECTURE.md index 8c7b4d8c7..155eaa5dd 100644 --- a/docs/ARCHITECTURE.md +++ b/docs/ARCHITECTURE.md @@ -184,7 +184,7 @@ ade brain update status --text Use `ADE_VERSION=vX.Y.Z` for a pinned release or `ADE_INSTALL_DIR` to choose the destination directory. The installer defaults to `$ADE_HOME/bin/ade`; both install and `ade brain update` verify downloaded runtime assets against `SHA256SUMS`. `ade brain update` stages the next release under `$ADE_HOME/runtime/updates/`, verifies the staged binary against the staged native deps, promotes the binary/deps into place, and restarts the per-user brain service. -**Health check (`ade doctor [--online] [--text]`).** `apps/ade-cli/src/commands/doctor.ts` connects to the machine brain over the local socket (bounded ~2 s) and prints one status row (`ok` / `warn` / `fail`) per subsystem: **App** (installed desktop version from the `.app` `Info.plist` vs the latest known version — read from disk, or from GitHub with `--online`), **Brain** (running version/pid/uptime plus any build-hash or role mismatch), **Wedge history** (the most recent recovered event-loop wedge, if any), **Sync port** (whether the shared listener bound the default `8787`, and the holders of the base ports when it drifted), **Publish health** (the account-directory publisher's last-leg durations and slowest leg), **Relay** (end-to-end verified vs a classified failure), and **Account** (signed-in state and source). The command exits non-zero when any row is `fail`. The row-evaluation logic (`evaluateDoctorRows`) is pure and dependency-injected so the desktop connection-doctor card and the CLI share one verdict. +**Health check (`ade doctor [--online] [--text]`).** `apps/ade-cli/src/commands/doctor.ts` connects to the machine brain over the local socket (bounded ~2 s) and prints one status row (`ok` / `warn` / `fail`) per subsystem: **App** (installed desktop version from the `.app` `Info.plist` vs the latest known version — read from disk, or from GitHub with `--online`), **Brain** (running version/pid/uptime plus any build-hash or role mismatch), **Wedge history** (the most recent recovered event-loop wedge, if any), **Sync port** (whether the shared listener bound the default `8787`, and the holders of the base ports when it drifted — with no visible holder reported as exactly that, since a root-owned holder such as `tailscaled` is invisible to a user-level probe and must be checked with `tailscale serve status` / `netstat -an -p tcp`), **Publish health** (the account-directory publisher's last-leg durations and slowest leg), **Relay** (end-to-end verified vs a classified failure), and **Account** (signed-in state and source). The command exits non-zero when any row is `fail`. The row-evaluation logic (`evaluateDoctorRows`) is pure and dependency-injected so the desktop connection-doctor card and the CLI share one verdict. **Install + PATH wiring (when the desktop ships `ade`).** On macOS / Linux the desktop installer drops the launcher at `$HOME/.local/bin/ade`; on Windows it lands at `%LOCALAPPDATA%\ADE\bin\ade.cmd`. After a successful install on Windows, the packaged `.cmd` installer adds the target directory to HKCU `Environment\Path` when needed and broadcasts an environment-change notification. After a successful install on POSIX, `ensureUserBinOnShellPath` appends a marked `export PATH="$HOME/.local/bin:$PATH"` block to the user's shell rc (`.zshrc` for zsh, `.bashrc` for bash, `.profile` otherwise) iff (a) the install dir isn't already on the inherited `PATH` and (b) the file doesn't already contain the marker / line / target dir. The install IPC reply tells the renderer which profile was edited so the Settings/Onboarding UI can prompt the user to open a new terminal or `source` it. @@ -297,7 +297,7 @@ The `/open` route is the HTTPS half of the ADE deeplink scheme (`https://ade-app Four independent Cloudflare Workers, each its own npm package / lockfile / `wrangler.jsonc` with its own trust model. None is a runtime dependency of the desktop app; the brain talks to them over HTTPS/WebSocket. - **`apps/push-relay/`** — fans ADE agent-state transitions out to iPhones as APNs alert pushes and Live Activity updates (Worker + a single D1 database; free-plan compatible, no Durable Objects). The brain is the only publisher: it claims an unguessable 32–64-hex `machineKey` with a relay secret (`POST /machines/:key/claim`, first-writer-wins) and HMAC-signs every later call (`x-ade-push-signature: sha256=HMAC(secret, "...")`). It stores only device tokens and in-flight notification payloads — no chat/PR content. APNs auth is an ES256 provider JWT from the `.p8` (wrangler secrets `APNS_KEY` / `APNS_KEY_ID` / `APNS_TEAM_ID`). Brain-side publisher lives at `apps/ade-cli/src/services/push/`. See [features/sync-and-multi-device/push-notifications.md](./features/sync-and-multi-device/push-notifications.md). -- **`apps/tunnel-relay/`** — pipes ADE **sync** WebSocket frames between a controller and a brain when there is no direct LAN/Tailscale path (Worker + Durable Object with SQLite storage, one instance per `machineKey`, WebSocket Hibernation API). The brain holds a persistent HMAC-signed outbound control socket while the machine has a valid ADE account session; a controller dials `/connect/:machineKey`; the DO pairs it with a dedicated brain-side pipe socket and passes bytes through 1:1 with no frame wrapping, so the normal ADE hello / pairing / DPoP handshake is unchanged. Native 30-second ping / 10-second pong transport liveness is the primary keepalive; because a hibernated or wedged DO can leave the edge answering those transport pings after the machine's control registration is dead, the brain adds a low-frequency application-level `{t:"ping"}`/`{t:"pong"}` keepalive (180 s interval, 30 s deadline) to catch such "zombie" controls, and verifies the path end-to-end with a self-probe (`syncRelaySelfProbe`) that dials `/connect/:machineKey?ready=2` like a real controller. The account directory advertises a `relay` endpoint only after that self-probe round-trips (honest relay publication); an at-capacity `4503` close is treated as liveness proof, not failure. Failed bridge opens are rejected explicitly; application close codes and bounded sanitized reasons survive the phone/pipe/local boundaries. Early controller frames are bounded by both 64 frames and 256 KiB, and idle-sweep alarms run only while a client or pipe exists. Brain-side client is `apps/ade-cli/src/services/sync/syncTunnelClientService.ts`. There is no user relay toggle: sign-in starts and advertises Relay, while sign-out closes it. It remains the lowest-priority `relay` address candidate after LAN and Tailscale. TLS terminates at the Worker, so this is a trusted-operator plaintext path rather than end-to-end encryption; relay payload E2E encryption is planned security work. +- **`apps/tunnel-relay/`** — pipes ADE **sync** WebSocket frames between a controller and a brain when there is no direct LAN/Tailscale path (Worker + Durable Object with SQLite storage, one instance per `machineKey`, WebSocket Hibernation API). The brain holds a persistent HMAC-signed outbound control socket while the machine has a valid ADE account session; a controller dials `/connect/:machineKey`; the DO pairs it with a dedicated brain-side pipe socket and passes bytes through 1:1 with no frame wrapping, so the normal ADE hello / pairing / DPoP handshake is unchanged. Native 30-second ping / 10-second pong transport liveness is the primary keepalive; because a hibernated or wedged DO can leave the edge answering those transport pings after the machine's control registration is dead, the brain adds a low-frequency application-level `{t:"ping"}`/`{t:"pong"}` keepalive (180 s interval, 30 s deadline) to catch such "zombie" controls, and verifies the path end-to-end with a self-probe (`syncRelaySelfProbe`) that dials `/connect/:machineKey?ready=2` like a real controller. The account directory advertises a `relay` endpoint only after that self-probe round-trips (honest relay publication); an at-capacity `4503` close is treated as liveness proof, not failure. Failed bridge opens are rejected explicitly; application close codes and bounded sanitized reasons survive the phone/pipe/local boundaries. Early controller frames are bounded by both 64 frames and 256 KiB, and idle-sweep alarms run only while a client or pipe exists. Brain-side client is `apps/ade-cli/src/services/sync/syncTunnelClientService.ts`, shared one-per-machine and handed the shared sync listener by `attachHostListener()` from whichever runtime actually owns that listener (which is often not the runtime that constructed the client). There is no user relay toggle: sign-in starts and advertises Relay, while sign-out closes it. It remains the lowest-priority `relay` address candidate after LAN and Tailscale. TLS terminates at the Worker, so this is a trusted-operator plaintext path rather than end-to-end encryption; relay payload E2E encryption is planned security work. - **`apps/account-directory/`** — Clerk-authenticated machine directory and OAuth device-authorization bridge (Worker + D1). The machine brain publishes a health-filtered registration through `accountMachinePublisherService.ts`: a 30-second heartbeat keeps the row inside the Worker's 90-second online window, while sign-in and publish-relevant relay-route changes trigger coalesced immediate writes and reset the heartbeat deadline. The Worker scopes rows by Clerk `sub`, selects at most the 500 most recently seen machines, then returns online-first order. Machine-list responses expose separate auth and D1 durations through `Server-Timing`, including auth failures. Authentication failures return only fixed classifications such as `token expired`, `invalid issuer`, and `invalid audience`; directory clients consume at most 512 response bytes before exposing the short reason in machine-list results and publisher health. Clients attach `X-ADE-Correlation-ID`; the Worker reflects and CORS-exposes it and logs it with route, method, status, and duration so a connection attempt can be followed without recording account tokens or full endpoint URLs. Desktop, ADE Code, hosted web, and iOS use the compiled HTTPS Worker origin by default. Headless login binds each short-lived device code to a daemon secret, uses Clerk OAuth + PKCE in any browser, and atomically burns the approved token pair on redemption. Each published row also carries the machine's long-lived Ed25519 identity as `pubkey`; a same-account desktop/iOS client verifies that key during the sealed `ade-adopt-v1` handshake to adopt a machine over a direct LAN/Tailscale route (LAN → Tailscale → Relay fallback) without exposing the account bearer in plaintext — see [features/sync-and-multi-device/README.md](./features/sync-and-multi-device/README.md). - **`apps/webhook-relay/`** — the pre-existing GitHub webhook relay (different trust model and lifecycle again). See its own docs. @@ -1114,7 +1114,7 @@ The sync subsystem is **owned by the ADE runtime** (`apps/ade-cli/src/services/s - **Bounded, snapshot-isolated exports**: `exportChangesSince` scans bounded `db_version` windows (the sync pump walks 250k-version windows per poll) inside a read transaction that pins the WAL snapshot — the `crsql_changes` vtab aborts on concurrent commits and a bare `LIMIT` cannot bound a vtab scan. Callers can exclude tables in SQL before limiting and reject a single oversized version group with `crsql_export_version_group_too_large` rather than materializing it. Startup self-heals orphaned `__crsql_clock`/`__crsql_pks` shadow tables (base table dropped, shadows left behind), which otherwise abort every `crsql_changes` scan. - **Fair, acknowledged delivery**: host/desktop-peer batches normally target 250 rows / 256 KB; active chat peers get a 64 KB target and at most 2 seconds of background deferral above the 512 KB socket watermark. The sender advances only after `changeset_ack`. Six failed sends abandon the encoded batch but keep its `fromDbVersion`, then re-export progressively smaller windows (down to 16 rows / 16 KB) after bounded backoff. An iOS replica with ACK + chunk support and a gap strictly over 5,000 versions receives one ACK-gated compact current-state reseed, built at most 1,000 rows per poll and capped at 10,000 rows / 4 MiB; oversized state falls back to incremental replay. iOS persists its last-acked cursor/pending batch and performs the same no-skip recovery from 64 rows / 64 KB down to one row / 4 KB. - **Suppression**: `discardUnpublishedChangesForTables` writes a per-table, per-site high-water mark into the local-only `local_crr_change_suppressions` table. Subsequent `exportChangesSince` calls drop local-site rows for those tables at or below that mark, so a local wipe (e.g. clearing `devices` and `sync_cluster_state` when joining another host as a viewer) cannot leak back as DELETE rows. The viewer-join path follows the wipe with `syncPeerService.acknowledgeLocalDbVersion()` to advance the outbound cursor past the suppressed range. -- **Transport**: one brain-level WebSocket listener on port 8787 by default (preferred-port retry for ~3 s before falling back to a port scan, so restarts do not drift the port phones saved); JSON-framed changesets + zlib compression for large batches; encoded envelopes >720 KB are sliced into `envelope_chunk` frames for peers declaring the `chunkedEnvelopes` capability; 60s ping/pong. Controllers adopt the host-advertised interval and postpone their fallback heartbeat whenever any inbound envelope proves the socket is alive, avoiding redundant application frames on relay-backed connections. Relay controllers use ready-v2 (`accepted` then `ready`) and send no ADE hello before the machine pipe/local listener exists; a non-v2 Worker is retried on a fresh legacy socket, never downgraded in place. iOS races up to three authenticated candidates and shares monotonic `connectionAttempt` metadata so the host rejects late losing routes; `hello_ok.connectionTransport` is the host-observed direct/relay truth. The same envelope channel carries project catalog, project-switch, and runtime-scoped project-action messages (browse/open/create/clone/list GitHub repos/default parent directory); on a hosted-project switch the new host service adopts the open sockets, so connected phones survive the swap. A machine-wide fallback handler serves catalog/project actions when no project host owns the listener, while handoff-time reconnects still park for adoption by the next host. Phones keep per-host-DB sync cursors keyed by the `serverDbSiteId` from `hello_ok`, and the host filters high-churn tables the phone never reads (transcripts, operations, usage logs, automation runs) from phone changesets. +- **Transport**: one brain-level WebSocket listener on port 8787 by default (preferred-port retry for ~3 s before falling back to a port scan, so restarts do not drift the port phones saved; each tailnet publish also retires ADE's own leftover `tailscale serve` entries, which otherwise hold the low ports through `tailscaled` and ratchet the listener upward on every restart); JSON-framed changesets + zlib compression for large batches; encoded envelopes >720 KB are sliced into `envelope_chunk` frames for peers declaring the `chunkedEnvelopes` capability; 60s ping/pong. Controllers adopt the host-advertised interval and postpone their fallback heartbeat whenever any inbound envelope proves the socket is alive, avoiding redundant application frames on relay-backed connections. Relay controllers use ready-v2 (`accepted` then `ready`) and send no ADE hello before the machine pipe/local listener exists; a non-v2 Worker is retried on a fresh legacy socket, never downgraded in place. iOS races up to three authenticated candidates and shares monotonic `connectionAttempt` metadata so the host rejects late losing routes; `hello_ok.connectionTransport` is the host-observed direct/relay truth. The same envelope channel carries project catalog, project-switch, and runtime-scoped project-action messages (browse/open/create/clone/list GitHub repos/default parent directory); on a hosted-project switch the new host service adopts the open sockets, so connected phones survive the swap. A machine-wide fallback handler serves catalog/project actions when no project host owns the listener, while handoff-time reconnects still park for adoption by the next host. Phones keep per-host-DB sync cursors keyed by the `serverDbSiteId` from `hello_ok`, and the host filters high-churn tables the phone never reads (transcripts, operations, usage logs, automation runs) from phone changesets. ### 13.2 Device model diff --git a/docs/features/onboarding-and-settings/README.md b/docs/features/onboarding-and-settings/README.md index c73800e13..8b066436d 100644 --- a/docs/features/onboarding-and-settings/README.md +++ b/docs/features/onboarding-and-settings/README.md @@ -519,8 +519,8 @@ Auto-update (top-bar control, not a settings tab): electron-updater wrapper that owns the renderer-visible `AutoUpdateSnapshot` (`status: "idle" | "checking" | "downloading" | "ready" | "installing" | "error"`, version, progress, recently - installed notice, plus the `parked` / `autoApplyPending` / - `autoApplySuppressedUntil` fields and `currentVersion` / + installed notice, plus the `parked` / `lastInstallFailed` / + `autoApplyPending` / `autoApplySuppressedUntil` fields and `currentVersion` / `latestKnownVersion` for the truthful-version surfaces). Tracks superseded downloads against the current ready version via `compareUpdateVersions` (the SemVer-aware comparator in `autoUpdateVersions.ts` that handles @@ -543,6 +543,13 @@ Auto-update (top-bar control, not a settings tab): `snapshot.parked` with a typed `AutoUpdateInstallAbortReason` (`refresh_failed`, `install_preflight_failed`, `prepare_failed`, `prepare_timeout`, `handoff_failed`) so the shell banner can offer a retry. + Once the native handoff starts, a staged quit deadline bounds it: a + never-fatal slow mark, then either the post-staging bound (armed when + Electron's own `autoUpdater` reports the OS installer finished staging) or the + hard bound. Escalation logs `autoUpdate.quit_escalated` with its + `hard_deadline` / `post_staging` reason, drains the log with + `logger.flushSync()`, and force-quits. See + [desktop-auto-update.md](./desktop-auto-update.md) for the numbers. When the runtime reports `RuntimeActivitySummary.idle` (no active agent turns or work sessions), a staged update is auto-applied after an idle grace period plus a renderer-visible countdown (`autoApplyPending`); an explicit cancel @@ -553,14 +560,23 @@ Auto-update (top-bar control, not a settings tab): the same SemVer comparator (so `>=` target counts as installed, even if the running build is one ahead), populates `recentlyInstalledUpdate` with the actual running version, and - cleans up the updater cache directory. On packaged launches with a + cleans up the updater cache directory. A launch that comes back on the *old* + version instead records `failedInstallAttempts` (target version + consecutive + count), logs `autoUpdate.install_did_not_land`, captures + `ade_update_install_did_not_land`, and surfaces `lastInstallFailed`. The + first such failure keeps the verified download so the retry is a click, not + another full release download; a second consecutive failure on the same + version clears the cache. On packaged launches with a recently installed update, the desktop refreshes the per-user runtime service so `ade serve` re-execs the updated bundled CLI and clients do not fall back to an isolated build-mismatch runtime. - `apps/desktop/src/renderer/components/app/AutoUpdateControl.tsx` — the small badge in the app shell top bar. Shows "Checking for updates" / "Downloading vX.Y.Z (NN%)" / "Install update vX.Y.Z" / - "ADE will quit and reopen" depending on the snapshot. Clicking the + "ADE will quit and reopen" depending on the snapshot. When + `lastInstallFailed` names the staged version, the ready label reads "Retry + install vX.Y.Z" and the tooltip says whether the download is still on the + machine. Clicking the install affordance prompts the user, sets a local `installRequested` flag, and calls `window.ade.updateQuitAndInstall()`; if the IPC returns `false` diff --git a/docs/features/onboarding-and-settings/desktop-auto-update.md b/docs/features/onboarding-and-settings/desktop-auto-update.md index 6baa9f5af..9a42e044b 100644 --- a/docs/features/onboarding-and-settings/desktop-auto-update.md +++ b/docs/features/onboarding-and-settings/desktop-auto-update.md @@ -61,6 +61,63 @@ so loopback transfer and staging are not mistaken for a stalled quit. Handoff timeouts retain the pending-install marker because Squirrel may still complete; an explicit updater error clears it. +## Quit deadline during the native handoff + +`quitAndInstall` arms a deadline before entering `electron-updater` so a quit +that never happens cannot strand the app in `installing` forever. The window has +to respect what Squirrel.Mac actually does after that call: pull the archive +from the loopback server, expand it, code-sign verify the expanded bundle, then +spawn ShipIt. On a ~750 MB archive that is roughly ten seconds, and it scales +with bundle size and disk contention. + +So the deadline is staged rather than a single hard bound: + +| Stage | Default | Behavior | +| --- | --- | --- | +| Soft mark | 10s | Logs `autoUpdate.quit_staging_slow`. Never fatal. | +| Native staging complete | — | Electron's own `autoUpdater` emits `update-downloaded`; logs `autoUpdate.native_staging_complete` and re-arms the short bound below. | +| Post-staging bound | 15s | ShipIt is already running, so a process still alive here is genuinely wedged: escalate. | +| Hard bound | 5min (macOS) / 60s elsewhere | Staging never signalled at all: escalate. | + +The staging signal comes from Electron's own `autoUpdater` — the Squirrel.Mac +binding `electron-updater`'s `MacUpdater` drives underneath — resolved through +`require("electron")` at construction and only on darwin, degrading to "no +staging signal" if it is absent rather than throwing. Everywhere else the +installer is an external process (NSIS, AppImage) that never emits that event, +so nothing stages in-process, the long bound could only hang the app in +`installing` for five minutes, and the shorter 60-second bound applies from the +start. + +Escalation logs `autoUpdate.quit_escalated` with its `hard_deadline` / +`post_staging` reason and whether staging had completed, captures the matching +`ade_update_quit_escalated` analytics event, and calls `logger.flushSync()` +before `forceQuit`, because `forceQuit` ends the process and ordinary log writes +are batched onto an async stream — without the sync drain the escalation record +dies with the process and the failure leaves no trace. + +A single hard bound around ten seconds cannot work: it force-quits the process +mid-staging and loses that race most of the time, so the app quits, nothing +installs, and it relaunches on the old version. + +## When an install does not land + +Relaunching on the old version while a `pendingInstallUpdate` marker exists +means the handoff never completed. `reconcilePersistedUpdateState` records this +in the `failedInstallAttempts` global-state row (target version + consecutive +count + timestamp), logs `autoUpdate.install_did_not_land`, captures the +internal-only `ade_update_install_did_not_land` event with just the bounded +`attempt` counter, and exposes `lastInstallFailed` on the snapshot so the +top-bar pill reads "Retry install vX" instead of silently offering the same +update again. Requesting another install clears `lastInstallFailed` (the new +attempt supersedes the notice); a launch that does land on the target version +clears `failedInstallAttempts` entirely. + +The first such failure **keeps** the cached archive. It was checksum-verified +before the update was ever offered, so a lost quit race says nothing about the +bytes, and re-downloading the whole release on every retry is pure cost. A +second consecutive failure on the same version stops trusting the archive and +clears the updater cache. + ## Truthful version surfaces Every version surface reads from one shared snapshot so they can never disagree diff --git a/docs/features/remote-runtime/README.md b/docs/features/remote-runtime/README.md index b077b8c79..8a0bde8ea 100644 --- a/docs/features/remote-runtime/README.md +++ b/docs/features/remote-runtime/README.md @@ -68,6 +68,24 @@ relay payload E2E encryption is planned security work. See the trust boundary in security model). The published machine name is channel-suffixed (` · Beta` / ` · Alpha`, stable left bare) so two channels on one Mac are distinguishable rows. +- `apps/ade-cli/src/services/sync/syncTunnelClientService.ts` and + `apps/ade-cli/src/bootstrap.ts` — the relay side of a paired route. The tunnel + client is shared one-per-machine (`getSharedSyncTunnelClientService`, keyed by + `sync-cloud-relay.json`); bootstrap hands the shared listener to + `attachHostListener()` outside the construction factory so the runtime that + owns the listener supplies the port, loopback nonce, and bridge proof + regardless of which runtime created the instance. See *Relay tunnel and the + sync port* below. +- `apps/ade-cli/src/services/sync/syncHostService.ts` — the host end: paired + hello authentication (with the `sync_host.paired_device_rejected` / + `sync_host.paired_account_owner_mismatch` rejection logs and the + frame-count-aware peer-close logs) and tailnet publication, including + `staleAdeTailnetServePorts` / `reclaimStaleTailnetServes`, which retire + ADE's own leftover `tailscale serve` entries after each successful publish. +- `apps/ade-cli/src/commands/doctor.ts` — the `Sync port` row names a drifted + port and its base-port holders, and says explicitly that a root-owned holder + such as `tailscaled` is invisible to this probe rather than reporting the + ports as free. - `apps/ade-cli/src/tuiClient/remoteLauncher.ts`, `pairedRemoteConnector.ts`, `remoteLaunchBudget.ts`, and `remoteBridge.ts` — `ade code remote` target resolution, legacy account-target migration, @@ -477,6 +495,86 @@ diagnostics with `ADE_ENABLE_DESKTOP_SYNC_HOST=1`. destination lane/chat rather than automatically replaying the mutation. - "Tailscale CLI was not found / timed out / failed" warning under the discovered-machines list — surfaced from `discoverLanRuntimes` diagnostics. LAN (Bonjour) discovery still ran; install or unblock `tailscale` to add tailnet peers. - Agent provider missing or unauthenticated — use the inline `AgentCliAuthCard` to install or authenticate that provider on the active runtime machine. +- `lan :: authentication` in the route list — the host was reached and it *rejected* this desktop, so the other routes' `timeout`/`unreachable` entries are noise. The host's `hello_error` message names which of three causes it was: the pairing was removed on that machine, the saved secret no longer matches, or the two machines are signed in to different ADE accounts. The first two are reported identically (an unauthenticated caller must not be told whether a device id exists on that host) and both need a re-pair; only the account mismatch is fixed by signing in. + +## Pairing identity and paired-secret lifetime + +A desktop's pairing identity is per-host, not per-machine: `sync-device-id` is +the machine's stable id, but each entry in `desktop-paired-machines.json` +carries its own `deviceId` that the host uses as the key for its pairing +record. Re-pairing the same machine therefore **must** present the same +`deviceId` — the host upserts on that key. `pairWithMachine` recovers the prior +identity (and its `siteId`) before it sends the pairing request, because the +`hello` that reports the host identity only arrives afterwards. It looks the +saved record up by two things that both identify a *host*: the caller-supplied +`hostDeviceId` (a QR/link payload and account-directory adoption both carry it), +then the relay machine key parsed out of a `/connect/` endpoint. A bare LAN +address is not a host identity — DHCP handing `192.168.1.240` to a different Mac +would hand that Mac the identity this desktop uses with the first one — so +matching on a saved endpoint is deliberately not an option, and a LAN pairing +with no `hostDeviceId` mints a fresh identity. + +Minting a fresh id when one already exists is not merely untidy: the host keeps +the old record forever, secret still valid, with no way to ever match it again, +accumulating one orphaned credential per re-pair. + +Three logs make a lost pairing diagnosable: + +- Host: `sync_host.paired_device_rejected` (`unknown_device` vs + `secret_mismatch`) and `sync_host.paired_account_owner_mismatch`, both at + warn. The host distinguishes those two rejection causes for itself but tells + the unauthenticated caller the same thing either way, so the close reason is + not an existence oracle for device ids. +- Host, for peers that never spoke: `sync_host.peer_closed_without_frames` at + **debug**. The relay readiness self-probe bridges in over loopback and + disconnects without sending a frame on every poll, and so does a port scan. + Keeping that routine traffic out of `sync_host.peer_closed` is what makes a + rejected peer visible at a glance. Anything that sent at least one frame — + including every authentication failure — logs `sync_host.peer_closed` at + info. +- Desktop: `account.local_machines_removed`, written at **warn** to the + machine-scoped `/runtime/account-trust.jsonl` (and mirrored + at info to the project logger). The machine-scoped sink is the load-bearing + one: dropping a paired secret is a machine-level credential mutation, and the + project logger follows the active project, which on a remote-bound project + ships the record to the other machine and leaves nothing on the machine that + actually lost its trust. Each removed credential records its host device id, + host name, previous owner, and whether the owner actually changed, so an + intended account switch is distinguishable from an identity glitch that + silently cost trust. The sink is resolved lazily and never fails account auth. + +## Relay tunnel and the sync port + +The relay tunnel client is cached **one per machine**, keyed by the cloud-relay +config file, and is built by whichever runtime bootstraps first — regularly a +scope that owns no shared listener (a headless one-shot, an embedded fallback). +So it must not capture per-runtime state at construction. The runtime that owns +the listener calls `attachHostListener()`, which supplies the port, loopback +nonce, and bridge proof, registers the `onLoopbackValidated` retry hook, and +validates once the listener is bound. Symptom when this is wrong: +`routeHealth.listener` reports bound and loopback-validated on a real port while +`relayBridgeValidated` is false and `lastBridgeValidationAt` has never been set — +relay silently never works, and a LAN auth failure becomes a total outage +because no fallback route exists. + +ADE advertises its sync port with `tailscale serve --bg --tcp=`. That +outlives the process that registered it, so the served port is reclaimed after +each successful publish (`staleAdeTailnetServePorts` + +`reclaimStaleTailnetServes`). Without it every restart — and every force-kill +that skips teardown — orphans an entry that Tailscale keeps bound on the tailnet +address; ADE's own next wildcard bind then fails `EADDRINUSE` against its own +leftover and walks one port higher, leaking another. It ratchets forever: one +machine reached 66 stranded ports and ~70 failed binds per start, drifting from +8787 to 8852. + +Only ADE's exact signature is reclaimed — a port inside ADE's sync range +forwarding to `127.0.0.1` on the **same** port — so a hand-rolled +`tailscale serve` is left alone, and the live port is re-checked inside the loop +because reclaiming frees exactly the low ports a restarting host prefers. + +Diagnosing this needs `netstat -an -p tcp` or `tailscale serve status`, **not** +`lsof`: tailscaled runs as root, so a user-level probe reports the ports as +having no holder, which reads as "free" and is the opposite of the truth. ## Related docs diff --git a/docs/features/sync-and-multi-device/README.md b/docs/features/sync-and-multi-device/README.md index 63983ee53..5da81a022 100644 --- a/docs/features/sync-and-multi-device/README.md +++ b/docs/features/sync-and-multi-device/README.md @@ -610,7 +610,11 @@ Canonical files (`apps/ade-cli/src/services/sync/`): that holder, logs `sync_listener.zombie_reaped`, and retries the freed port once — so a dead-but-port-holding sibling brain cannot force the new brain onto a drifted port that phones never saved. The same diagnosis feeds the - `ade doctor` Sync-port row. The listener is + `ade doctor` Sync-port row, which is explicit that it cannot see a root-owned + holder: a stranded `tailscale serve` entry from an earlier run holds the port + through `tailscaled`, so a user-level probe reports no holders even though the + port is taken (`tailscale serve status` and `netstat -an -p tcp` show it). + Those leftovers are reclaimed on the next tailnet publish. The listener is handed between hosts on project switch: the new host adopts the open sockets — peer metadata carried over, pairing auth re-validated against the pairing store, changeset cursors recomputed @@ -840,9 +844,18 @@ Canonical files (`apps/ade-cli/src/services/sync/`): validation is **proactive**: `validateCurrentBridge()` re-probes the loopback sync listener (matching port + identity nonce) whenever the control socket opens and whenever the shared listener reports a fresh loopback - validation (`sharedSyncListener.onLoopbackValidated`, wired in - `bootstrap.ts`), serializing probes through the same validation queue used by - inbound opens. This flips `relayBridgeValidated` — and therefore directory relay + validation, serializing probes through the same validation queue used by + inbound opens. The listener itself arrives through `attachHostListener()`, + which `bootstrap.ts` calls from the runtime that owns the shared listener — + not from the construction factory. The client is shared one-per-machine + (`getSharedSyncTunnelClientService`, keyed by `sync-cloud-relay.json`) and is + built by whichever runtime bootstraps first, which is regularly a scope with + no listener at all (a headless one-shot, an embedded fallback), so anything + captured at construction would answer `null` for the life of the process and + the bridge could never validate. Attaching supplies the port, loopback nonce, + and relay bridge proof, subscribes the `onLoopbackValidated` retry hook + (whose failures log `sync_tunnel.bridge_validation_failed`), and validates + immediately if the listener is already bound; `stop()` detaches it. This flips `relayBridgeValidated` — and therefore directory relay publication — true as soon as the listener is confirmed, so the earlier "bridge not validated against the sync port" state self-heals instead of waiting for an inbound client to open the first tunnel. `openTunnel` still @@ -1277,7 +1290,19 @@ grace. Older peers close exactly when their initial token expires. (`SyncTailnetDiscoveryStatus`: `disabled | publishing | published | pending_approval | unavailable | failed`) plus `error` / `stderr` tails. The runtime tracks a `tailnetServeSignature` (`serve:`) - so re-publishing is a no-op while the port hasn't changed. + so re-publishing is a no-op while the port hasn't changed. Because + `serve --bg` outlives the process that registered it, each successful publish + is followed by a best-effort reclaim (`staleAdeTailnetServePorts` + + `reclaimStaleTailnetServes`, logged as `sync_host.tailnet_serve_reclaimed`): + `tailscale serve status --json` is scanned for ADE's exact signature — a port + in the sync range forwarding to `127.0.0.1` on the **same** port — and every + match other than the live one is turned off. Without it, a restart or + force-kill strands an entry that Tailscale keeps bound on the tailnet address, + ADE's next wildcard bind fails `EADDRINUSE` against its own leftover and walks + one port higher, and the port ratchets upward on every start. A hand-rolled + `tailscale serve` forwarding anywhere else is never touched, and the live port + is re-checked inside the loop because reclaiming frees exactly the low ports a + concurrently restarting host prefers. ## Sync protocol (summary) diff --git a/docs/logging.md b/docs/logging.md index 8442ee8fc..99482b483 100644 --- a/docs/logging.md +++ b/docs/logging.md @@ -22,7 +22,11 @@ Only closed event names, closed property keys, and coarse allowlisted values may Operational logs use ADE's local logging services and may include bounded diagnostic context appropriate for the local machine. They are for debugging a specific installation and must not be forwarded to PostHog. -The machine brain writes the same `{ts, level, event, meta}` JSONL format as the desktop logger to `~/.ade/runtime/brain.jsonl`, honoring `ADE_LOG_LEVEL` (default `info`). The file rotates at 10 MiB to `brain.1.jsonl`; warnings and errors are also mirrored to stderr with an ISO-8601 timestamp and uppercase level for launchd diagnostics. Account-directory publish outcomes record only bounded per-leg durations, the failing leg, and coarse failure codes such as `token_timeout` or `http_timeout`; they never include bearer tokens or response bodies. These high-frequency health events remain local operational logs and are not product analytics. +The machine brain writes the same `{ts, level, event, meta}` JSONL format as the desktop logger to `~/.ade/runtime/brain.jsonl`, honoring `ADE_LOG_LEVEL` (default `info`). The file rotates at 10 MiB to `brain.1.jsonl`; warnings and errors are also mirrored to stderr with an ISO-8601 timestamp and uppercase level for launchd diagnostics. + +Writes are batched onto an async stream, so a caller that is about to end the process (`app.exit`, a force quit, an install handoff escalation) must call `logger.flushSync()` immediately after the line that matters — while it is still queued — or the records explaining the exit die with the process. `flushSync` drains only what is still queued (a batch already handed to an in-flight async flush is not duplicated), skips rotation deliberately, and, like every other log write, never throws. + +Not every operational log belongs to the active project. `createFileLogger` also backs machine-scoped sinks for facts that outlive or fall outside a project: `accountBridge` writes `account.local_machines_removed` to `/runtime/account-trust.jsonl`, because dropping a paired machine credential is a machine-level mutation and the project logger follows the active project — on a remote-bound project it would ship the record to the other machine and leave nothing on the machine that actually lost its trust. Account-directory publish outcomes record only bounded per-leg durations, the failing leg, and coarse failure codes such as `token_timeout` or `http_timeout`; they never include bearer tokens or response bodies. These high-frequency health events remain local operational logs and are not product analytics. Claude compaction observations use the local structured line `agent_chat.claude_context_compaction_observed` with `sessionId`, `trigger` @@ -80,12 +84,13 @@ The public contract is `apps/desktop/src/shared/types/productAnalytics.ts`. The - `ade_analytics_budget` - `ade_update_install_aborted` - `ade_update_quit_escalated` +- `ade_update_install_did_not_land` - `ade_update_auto_applied` - `ade_update_auto_apply_cancelled` - `ade_brain_recovered` - `ade_publish_failing` -The update and reliability events are low-frequency by construction: the four `ade_update_*` events fire at most once per install attempt or idle-apply cycle (daily caps 10–20, minute caps 3–6); `ade_brain_recovered` fires once per wedge recovery at brain startup; `ade_publish_failing` is edge-triggered once per sustained failure episode (first crossing of two minutes), never per attempt. Properties are closed enums and bounded numbers — `reason` is allowlisted to the abort-reason constant, `last_command` is a closed sync-action slug, and `leg`/`code` are the coarse publish classifications. Worst-case combined volume is a handful of events on a very bad day, inside the shared ceiling. +The update and reliability events are low-frequency by construction: the five `ade_update_*` events fire at most once per install attempt or idle-apply cycle (daily caps 10–20, minute caps 3–6). `ade_update_install_did_not_land` is emitted once at startup when a requested install relaunched on the old version, so it is bounded by app launches that follow a failed handoff, and carries only a bounded `attempt` counter; `ade_brain_recovered` fires once per wedge recovery at brain startup; `ade_publish_failing` is edge-triggered once per sustained failure episode (first crossing of two minutes), never per attempt. Properties are closed enums and bounded numbers — `reason` is allowlisted to the abort-reason constant, `escalation_reason` to `hard_deadline` / `post_staging`, `last_command` is a closed sync-action slug, and `leg`/`code` are the coarse publish classifications. Worst-case combined volume is a handful of events on a very bad day, inside the shared ceiling. The default machine-wide ceiling is 200 accepted events per UTC day, shared across desktop, runtime, TUI, hosted web, and API-originated aggregates. Each event also has a tighter per-day and per-minute ceiling. Capture ingress is capped, noisy events use persisted deduplication windows, the in-memory transport queue is bounded, and the previous day's accepted/drop totals are summarized in at most two budget events per day. @@ -145,7 +150,7 @@ The full-access personal key belongs only in encrypted ADE secrets. When running - ADE · Marketing acquisition - ADE · Reliability and analytics budget -When an event or property contract changes, update the dashboard spec and its tests in the same change. Run the provisioner in `--validate` mode locally. A live provisioning run requires the personal management key and should be idempotent: an immediate second run must report no changes. +The 30-day volume insight sums the whole ingested catalog through a formula that addresses each series by its PostHog letter (`A`…`Z`), so the catalog cannot exceed 26 events; the spec throws at load time rather than emitting a formula PostHog would reject. When an event or property contract changes, update the dashboard spec and its tests in the same change. Run the provisioner in `--validate` mode locally. A live provisioning run requires the personal management key and should be idempotent: an immediate second run must report no changes. ## How to instrument new code diff --git a/scripts/posthog/dashboard-spec.mjs b/scripts/posthog/dashboard-spec.mjs index 23b427184..e54557029 100644 --- a/scripts/posthog/dashboard-spec.mjs +++ b/scripts/posthog/dashboard-spec.mjs @@ -13,6 +13,7 @@ export const EVENTS = Object.freeze({ ANALYTICS_BUDGET: "ade_analytics_budget", UPDATE_INSTALL_ABORTED: "ade_update_install_aborted", UPDATE_QUIT_ESCALATED: "ade_update_quit_escalated", + UPDATE_INSTALL_DID_NOT_LAND: "ade_update_install_did_not_land", UPDATE_AUTO_APPLIED: "ade_update_auto_applied", UPDATE_AUTO_APPLY_CANCELLED: "ade_update_auto_apply_cancelled", BRAIN_RECOVERED: "ade_brain_recovered", @@ -30,6 +31,14 @@ export const EVENTS = Object.freeze({ }); const ALL_INGESTED_EVENTS = Object.freeze(Object.values(EVENTS)); +// PostHog series letters are A..Z, so the catalog cannot exceed 26 events +// without a different addressing scheme. Fail loudly here rather than emitting +// a formula containing "[" that PostHog would silently reject. +if (ALL_INGESTED_EVENTS.length > 26) { + throw new Error( + `Event catalog has ${ALL_INGESTED_EVENTS.length} events; the volume insight formula only addresses 26 (A..Z).`, + ); +} const ALL_INGESTED_EVENTS_FORMULA = ALL_INGESTED_EVENTS .map((_, index) => String.fromCharCode("A".charCodeAt(0) + index)) .join("+"); @@ -517,6 +526,7 @@ export const dashboardSpec = Object.freeze({ eventNode(EVENTS.PUBLISH_FAILING, "Route publish failing"), eventNode(EVENTS.UPDATE_INSTALL_ABORTED, "Update install aborted"), eventNode(EVENTS.UPDATE_QUIT_ESCALATED, "Update quit escalated"), + eventNode(EVENTS.UPDATE_INSTALL_DID_NOT_LAND, "Update did not land"), eventNode(EVENTS.UPDATE_AUTO_APPLIED, "Update auto-applied"), ], interval: "day", @@ -562,7 +572,7 @@ export const dashboardSpec = Object.freeze({ insight( "monthly-analytics-volume", "30-day ingested analytics volume", - "PostHog's actual ingested count across ADE's closed 25-event catalog. The goal line marks the current 1,000,000-event monthly Product Analytics free allowance. This is an instrumentation health view, not the account billing meter: stray or abusive events sent with the public project token are outside this chart.", + "PostHog's actual ingested count across ADE's closed 26-event catalog. The goal line marks the current 1,000,000-event monthly Product Analytics free allowance. This is an instrumentation health view, not the account billing meter: stray or abusive events sent with the public project token are outside this chart.", trends({ series: ALL_INGESTED_EVENTS.map((event) => eventNode(event, event)), formula: ALL_INGESTED_EVENTS_FORMULA, diff --git a/scripts/posthog/provision.test.mjs b/scripts/posthog/provision.test.mjs index 4feee4228..f50bdb29c 100644 --- a/scripts/posthog/provision.test.mjs +++ b/scripts/posthog/provision.test.mjs @@ -76,8 +76,8 @@ test("dashboard queries match the bounded instrumentation semantics", () => { const ingestedVolume = findInsight("monthly-analytics-volume"); assert.equal(ingestedVolume.name, "30-day ingested analytics volume"); - assert.equal(ingestedVolume.query.source.series.length, 25); - assert.equal(ingestedVolume.query.source.trendsFilter.formula, "A+B+C+D+E+F+G+H+I+J+K+L+M+N+O+P+Q+R+S+T+U+V+W+X+Y"); + assert.equal(ingestedVolume.query.source.series.length, 26); + assert.equal(ingestedVolume.query.source.trendsFilter.formula, "A+B+C+D+E+F+G+H+I+J+K+L+M+N+O+P+Q+R+S+T+U+V+W+X+Y+Z"); }); test("config requires HTTPS and a numeric project ID", () => {