de6976b06e68

every terminating sync path reports a named SyncOutcome with device inventory, persisted last attempt, and [Peach sync] service-worker logs

time
2026-07-26 18:49 UTC · 3 months ago
machine
koh2
agent
claude-opus-5
session
sync visibility
parent
7e3d43b00009
5 files src/background/paired-devices.ts+13 −0src/background/sync-runner.ts+15 −0src/background/sync-trigger.test.ts+113 −1src/background/sync-trigger.ts+154 −24src/shared/sync-outcome.ts+114 −0
src/background/paired-devices.ts+13 −0
@@ -23,6 +23,7 @@2323 import type { DeviceRevocation, PairedDevice } from "../shared/sync-types";2424 import { constantTimeEqualHex } from "../shared/constant-time";2525 import { clampSyncTimestamp } from "../shared/sync-limits";26+import type { SyncOutcome } from "../shared/sync-outcome";2627 2728 const REGISTRY_KEY = "peach_paired_devices_v3";2829 const REVOCATIONS_KEY = "peach_device_revocations_v1";@@ -292,7 +293,17 @@292293   await chrome.storage.local.set({ [LAST_SYNC_AT_KEY]: when });293294 }294295 296+/**297+ * The last sync ATTEMPT, not just the last success. A 3-second flash in the298+ * popup is useless for debugging a real phone, so every terminating path299+ * writes this and Settings reads it back after the fact — including across an300+ * MV3 service-worker restart.301+ */295302 export interface SyncResult {303+  outcome: SyncOutcome;304+  detail?: string;305+  /** When the attempt finished, success or not. */306+  at: number;296307   entriesReceived: number;297308   entriesSent: number;298309 }@@ -304,6 +315,8 @@304315     if (305316       value &&306317       typeof value === "object" &&318+      typeof (value as Record<string, unknown>).outcome === "string" &&319+      typeof (value as Record<string, unknown>).at === "number" &&307320       typeof (value as Record<string, unknown>).entriesReceived === "number" &&308321       typeof (value as Record<string, unknown>).entriesSent === "number"309322     ) {

view file

src/background/sync-runner.ts+15 −0
@@ -122,6 +122,13 @@122122 123123   try {124124     const outcome = await runSyncInitiator(session, adapter);125+    if (outcome.status !== "completed") {126+      console.info(127+        `[Peach sync] protocol ended ${outcome.status} with ${device.deviceName ?? device.deviceId}${128+          outcome.error ? `: ${outcome.error}` : ""129+        }`,130+      );131+    }125132     if (outcome.status === "completed") {126133       return {127134         ok: true,@@ -161,6 +168,14 @@161168       );162169     } catch (error) {163170       lastError = error;171+      // Each clock-skew window fails separately and only the last one survives172+      // into the thrown message; on a real device the earlier ones are often173+      // the informative ones.174+      console.info(175+        `[Peach sync] relay dial failed — relay=${relayUrl} rendezvous=${rendezvousId}: ${176+          error instanceof Error ? error.message : String(error)177+        }`,178+      );164179     }165180   }166181   const detail = lastError instanceof Error ? lastError.message : "unreachable";

view file

src/background/sync-trigger.test.ts+113 −1
@@ -201,7 +201,119 @@201201     // Read the raw storage value to confirm persistence.202202     const raw = await (globalThis as unknown as { chrome: { storage: { local: { get(k: string): Promise<Record<string, unknown>> } } } })203203       .chrome.storage.local.get("peach_last_sync_result");204-    expect(raw.peach_last_sync_result).toEqual({ entriesReceived: 3, entriesSent: 1 });204+    expect(raw.peach_last_sync_result).toMatchObject({205+      outcome: "completed_changes",206+      entriesReceived: 3,207+      entriesSent: 1,208+    });209+    expect(typeof (raw.peach_last_sync_result as { at: unknown }).at).toBe("number");210+  });211+212+  // Every terminating path must be distinguishable. Before this, "nobody to213+  // sync with", "runner not wired" and "synced, nothing to do" were all a bare214+  // `return` — the user and the logs saw the same nothing in all three cases.215+  describe("reported outcomes", () => {216+    it("reports no_paired_devices when the registry is empty", async () => {217+      setSyncRunner(async () => ({ ok: true, entriesReceived: 0, entriesSent: 0 }));218+      await triggerSyncIfReachable({ reason: "manual" });219+      const s = getSyncState();220+      expect(s.outcome).toBe("no_paired_devices");221+      expect(s.status).toBe("idle");222+      expect(typeof s.finishedAt).toBe("number");223+    });224+225+    it("reports no_eligible_host naming the deviceType and trustSource found", async () => {226+      // This is the diagnostic that matters on real hardware: a device that227+      // paired fine but whose type/trust puts it outside the host filter.228+      await upsertPairedDevice({ ...EXT, deviceName: "Other Chrome" });229+      await upsertPairedDevice({230+        ...ANDROID,231+        deviceId: "untrusted-android",232+        deviceName: "Pixel",233+        trustSource: undefined,234+      });235+      setSyncRunner(async () => ({ ok: true, entriesReceived: 0, entriesSent: 0 }));236+      await triggerSyncIfReachable({ reason: "manual" });237+      const s = getSyncState();238+      expect(s.outcome).toBe("no_eligible_host");239+      expect(s.status).toBe("error");240+      expect(s.detail).toContain("Other Chrome [type=extension, trust=unset]");241+      expect(s.detail).toContain("Pixel [type=android, trust=unset]");242+    });243+244+    it("reports runner_unavailable when the runner slot is never wired", async () => {245+      await upsertPairedDevice(ANDROID);246+      setSyncRunner(null);247+      await triggerSyncIfReachable({ reason: "manual" });248+      const s = getSyncState();249+      expect(s.outcome).toBe("runner_unavailable");250+      expect(s.status).toBe("error");251+    });252+253+    it("distinguishes completed_no_changes from a failure", async () => {254+      await upsertPairedDevice(ANDROID);255+      setSyncRunner(async () => ({ ok: true, entriesReceived: 0, entriesSent: 0 }));256+      await triggerSyncIfReachable({ reason: "manual" });257+      const s = getSyncState();258+      expect(s.outcome).toBe("completed_no_changes");259+      expect(s.status).toBe("idle");260+      expect(s.error).toBeUndefined();261+    });262+263+    it("surfaces a runner throw as its own message rather than swallowing it", async () => {264+      await upsertPairedDevice(ANDROID);265+      setSyncRunner(async () => {266+        throw new Error("relay_sync_failed:WebSocket connect timed out");267+      });268+      await triggerSyncIfReachable({ reason: "manual" });269+      const s = getSyncState();270+      expect(s.outcome).toBe("relay_unreachable");271+      expect(s.detail).toBe("relay_sync_failed:WebSocket connect timed out");272+      expect(s.error).toBe("relay_sync_failed:WebSocket connect timed out");273+    });274+275+    it.each([276+      ["sync_disabled", "sync_disabled"],277+      ["private_relay_unset", "private_relay_unset"],278+      ["vault_id_mismatch", "vault_id_mismatch"],279+      ["sync_timeout", "sync_timeout"],280+      ["VAULT_LOCKED", "vault_locked"],281+      ["relay_sync_failed:sync_handshake_timeout", "handshake_failed"],282+      ["something nobody predicted", "run_failed"],283+    ])("classifies runner error %s as %s", async (error, outcome) => {284+      await upsertPairedDevice(ANDROID);285+      setSyncRunner(async () => ({ ok: false, error }));286+      await triggerSyncIfReachable({ reason: "manual", force: true });287+      expect(getSyncState().outcome).toBe(outcome);288+    });289+290+    it("keeps the in-flight run's state when a concurrent trigger is dropped", async () => {291+      await upsertPairedDevice(ANDROID);292+      setSyncRunner(async () => {293+        await new Promise<void>((r) => setTimeout(r, 30));294+        return { ok: true as const, entriesReceived: 0, entriesSent: 0 };295+      });296+      const first = triggerSyncIfReachable({ reason: "manual" });297+      while (getSyncState().status !== "syncing") await Promise.resolve();298+      await triggerSyncIfReachable({ reason: "vault_change" });299+      // The dropped trigger must not stamp a terminal outcome over a live run.300+      expect(getSyncState().status).toBe("syncing");301+      await first;302+      expect(getSyncState().outcome).toBe("completed_no_changes");303+    });304+305+    it("restores the last outcome across a SW restart so a failure stays inspectable", async () => {306+      await upsertPairedDevice(ANDROID);307+      setSyncRunner(async () => ({ ok: false, error: "vault_id_mismatch" }));308+      await triggerSyncIfReachable({ reason: "manual" });309+      _resetSyncTriggerForTest();310+      expect(getSyncState().outcome).toBeUndefined();311+      await hydratePersistedSyncState();312+      const s = getSyncState();313+      expect(s.outcome).toBe("vault_id_mismatch");314+      expect(s.detail).toBe("vault_id_mismatch");315+      expect(typeof s.finishedAt).toBe("number");316+    });205317   });206318 207319   it("hydratePersistedSyncState restores lastSyncAt across SW restart simulation", async () => {

view file

src/background/sync-trigger.ts+154 −24
@@ -12,12 +12,14 @@1212 1313 import {1414   getLastSyncAt,15+  getLastSyncResult,1516   listPairedDevices,1617   markLastSyncedAt,1718   setLastSyncAt,1819   setLastSyncResult,1920 } from "./paired-devices";2021 import type { PairedDevice } from "../shared/sync-types";22+import { isSyncFailure, type SyncOutcome } from "../shared/sync-outcome";2123 2224 export type SyncTriggerReason = "vault_change" | "foreground" | "manual";2325 @@ -26,10 +28,15 @@2628 export interface SyncState {2729   status: SyncRunStatus;2830   reason?: SyncTriggerReason;31+  /** Last SUCCESSFUL sync. `finishedAt` is the last attempt of any kind. */2932   lastSyncAt?: number;3033   entriesReceived?: number;3134   entriesSent?: number;3235   error?: string;36+  outcome?: SyncOutcome;37+  /** Raw internal code, or the device inventory behind `no_eligible_host`. */38+  detail?: string;39+  finishedAt?: number;3340 }3441 3542 export type SyncRunResult =@@ -81,11 +88,28 @@8188  */8289 export async function hydratePersistedSyncState(): Promise<void> {8390   const state = getSyncTriggerState();84-  if (state.lastState.lastSyncAt !== undefined) return;85-  const persisted = await getLastSyncAt();86-  if (typeof persisted === "number") {87-    state.lastState = { ...state.lastState, lastSyncAt: persisted };91+  if (state.lastState.lastSyncAt === undefined) {92+    const persisted = await getLastSyncAt();93+    if (typeof persisted === "number") {94+      state.lastState = { ...state.lastState, lastSyncAt: persisted };95+    }8896   }97+  // The outcome of the last attempt survives too, otherwise a failure that98+  // happened before the SW died is unreportable — which is the case a real99+  // device most needs explained.100+  if (state.lastState.outcome === undefined) {101+    const last = await getLastSyncResult();102+    if (last) {103+      state.lastState = {104+        ...state.lastState,105+        outcome: last.outcome,106+        detail: last.detail,107+        finishedAt: last.at,108+        entriesReceived: last.entriesReceived,109+        entriesSent: last.entriesSent,110+      };111+    }112+  }89113 }90114 91115 export async function triggerSyncIfReachable(opts: {@@ -96,7 +120,11 @@96120   // Claim the guard synchronously before any await, otherwise two97121   // concurrent triggers could both pass the gate before either reached98122   // the registry lookup.99-  if (state.syncInFlight && !opts.force) return;123+  if (state.syncInFlight && !opts.force) {124+    // Deliberately does NOT overwrite lastState — the in-flight run owns it.125+    log(`trigger (${opts.reason}) ignored, a sync is already in flight`);126+    return;127+  }100128   state.syncInFlight = true;101129 102130   try {@@ -114,10 +142,31 @@114142         (d.deviceType === "android" || d.deviceType === "ios") &&115143         (d.trustSource === "direct" || d.trustSource === "vouched"),116144     );117-    if (hosts.length === 0) return;118-    if (!state.runner) return;145+    if (devices.length === 0) {146+      finish({ outcome: "no_paired_devices" });147+      return;148+    }149+    if (hosts.length === 0) {150+      // The device inventory is the diagnostic: it says exactly which151+      // deviceType/trustSource combination the eligibility filter rejected.152+      finish({ outcome: "no_eligible_host", detail: inventory(devices) });153+      return;154+    }155+    if (!state.runner) {156+      finish({ outcome: "runner_unavailable" });157+      return;158+    }119159 120-    setState({ status: "syncing", reason: opts.reason, error: undefined });160+    setState({161+      status: "syncing",162+      reason: opts.reason,163+      error: undefined,164+      outcome: undefined,165+      detail: undefined,166+    });167+    log(168+      `starting (${opts.reason}) against ${hosts.length} host(s): ${inventory(hosts)}`,169+    );121170     await runSyncRounds(hosts);122171   } finally {123172     state.syncInFlight = false;@@ -126,7 +175,10 @@126175 127176 async function runSyncRounds(hosts: PairedDevice[]): Promise<void> {128177   const state = getSyncTriggerState();129-  if (!state.runner) return;178+  if (!state.runner) {179+    finish({ outcome: "runner_unavailable" });180+    return;181+  }130182 131183   let entriesReceived = 0;132184   let entriesSent = 0;@@ -137,6 +189,7 @@137189     try {138190       const result = await state.runner(host);139191       if (!result.ok) {192+        log(`host ${describeHost(host)} refused: ${result.error}`);140193         if (firstError === undefined) firstError = result.error;141194         continue;142195       }@@ -145,32 +198,109 @@145198       await markLastSyncedAt(host.deviceId, Date.now());146199       anySucceeded = true;147200     } catch (err) {148-      if (firstError === undefined) {149-        firstError = (err as Error)?.message ?? String(err);150-      }201+      const message = (err as Error)?.message ?? String(err);202+      log(`host ${describeHost(host)} threw: ${message}`);203+      if (firstError === undefined) firstError = message;151204     }152205   }153206 154207   if (anySucceeded) {155208     const now = Date.now();156-    setState({157-      status: "idle",158-      lastSyncAt: now,209+    finish({210+      outcome: entriesReceived + entriesSent > 0 ? "completed_changes" : "completed_no_changes",211+      // A partial success still names the host that failed — otherwise "synced"212+      // hides the peer that never got the change.213+      detail: firstError,159214       entriesReceived,160215       entriesSent,161-      error: undefined,162216     });163-    // Persist so the popup's "last synced" indicator and entry counts164-    // survive a SW restart. Best-effort — storage failures must not165-    // surface as sync failures.217+    // Persist so the popup's "last synced" indicator survives a SW restart.218+    // Best-effort — storage failures must not surface as sync failures.166219     void setLastSyncAt(now).catch(() => undefined);167-    void setLastSyncResult({ entriesReceived, entriesSent }).catch(() => undefined);168220   } else {169-    setState({170-      status: "error",171-      error: firstError ?? "no_host_reachable",172-    });221+    const error = firstError ?? "no_host_reachable";222+    finish({ outcome: classifySyncError(error), detail: error });173223   }224+}225+226+/**227+ * Runner errors are opaque strings by contract (`SyncRunResult.error` and any228+ * throw). Mapping them here is the only place the popup's plain-English copy229+ * can key off something stable.230+ */231+function classifySyncError(error: string): SyncOutcome {232+  if (error.includes("VAULT_LOCKED")) return "vault_locked";233+  if (error.includes("sync_disabled")) return "sync_disabled";234+  if (error.includes("private_relay_unset")) return "private_relay_unset";235+  if (error.includes("vault_id_mismatch")) return "vault_id_mismatch";236+  if (error.includes("sync_timeout")) return "sync_timeout";237+  if (error.startsWith("relay_sync_failed")) {238+    return /handshake|PAIR_IDENTITY|identity does not match/i.test(error)239+      ? "handshake_failed"240+      : "relay_unreachable";241+  }242+  return "run_failed";243+}244+245+interface SyncFinish {246+  outcome: SyncOutcome;247+  detail?: string;248+  entriesReceived?: number;249+  entriesSent?: number;250+}251+252+/**253+ * The single exit for every terminating path. Nothing may `return` out of a254+ * sync run without going through here — that silence is the bug this whole255+ * module was reworked to remove.256+ */257+function finish(result: SyncFinish): void {258+  const now = Date.now();259+  const failed = isSyncFailure(result.outcome);260+  const entriesReceived = result.entriesReceived ?? 0;261+  const entriesSent = result.entriesSent ?? 0;262+  setState({263+    status: failed ? "error" : "idle",264+    outcome: result.outcome,265+    detail: result.detail,266+    error: failed ? result.detail ?? result.outcome : undefined,267+    finishedAt: now,268+    entriesReceived,269+    entriesSent,270+    ...(result.outcome === "completed_changes" || result.outcome === "completed_no_changes"271+      ? { lastSyncAt: now }272+      : {}),273+  });274+  log(275+    `${result.outcome}${result.detail ? ` — ${result.detail}` : ""}` +276+      (entriesReceived + entriesSent > 0277+        ? ` (sent ${entriesSent}, received ${entriesReceived})`278+        : ""),279+  );280+  void setLastSyncResult({281+    outcome: result.outcome,282+    detail: result.detail,283+    at: now,284+    entriesReceived,285+    entriesSent,286+  }).catch(() => undefined);287+}288+289+/** What the eligibility filter actually saw. Names, not just counts. */290+function inventory(devices: PairedDevice[]): string {291+  return devices.map(describeHost).join("; ");292+}293+294+function describeHost(d: PairedDevice): string {295+  return `${d.deviceName ?? d.deviceId} [type=${d.deviceType ?? "unset"}, trust=${d.trustSource ?? "unset"}]`;296+}297+298+/**299+ * MV3 kills the service worker constantly, so devtools on the SW is the only300+ * post-hoc record of a sync attempt. Prefixed so it can be filtered.301+ */302+function log(message: string): void {303+  console.info(`[Peach sync] ${message}`);174304 }175305 176306 function setState(patch: Partial<SyncState>): void {

view file

src/shared/sync-outcome.ts+114 −0
@@ -0,0 +1,114 @@1+// Why a sync run ended, in a form both the service worker and the popup can2+// name. Before this existed, "no eligible host", "runner not wired" and3+// "synced fine, nothing to do" were all a bare `return` — indistinguishable4+// to the user and to us. A failed sync and a successful no-op must never5+// look the same again.6+7+export type SyncOutcome =8+  | "completed_changes"9+  | "completed_no_changes"10+  | "no_paired_devices"11+  | "no_eligible_host"12+  | "runner_unavailable"13+  | "sync_disabled"14+  | "private_relay_unset"15+  | "vault_locked"16+  | "relay_unreachable"17+  | "handshake_failed"18+  | "vault_id_mismatch"19+  | "sync_timeout"20+  | "run_failed";21+22+/** Outcomes where sync did not do what the user asked, so the UI shows red. */23+const FAILURES: ReadonlySet<SyncOutcome> = new Set<SyncOutcome>([24+  "no_eligible_host",25+  "runner_unavailable",26+  "private_relay_unset",27+  "vault_locked",28+  "relay_unreachable",29+  "handshake_failed",30+  "vault_id_mismatch",31+  "sync_timeout",32+  "run_failed",33+]);34+35+export function isSyncFailure(outcome: SyncOutcome): boolean {36+  return FAILURES.has(outcome);37+}38+39+export interface SyncOutcomeSummary {40+  status?: "idle" | "syncing" | "error";41+  outcome?: SyncOutcome;42+  entriesSent?: number;43+  entriesReceived?: number;44+  detail?: string;45+}46+47+/**48+ * The one indicator light. `busy` pulses green, `ok` is solid green, `error`49+ * is red, `idle` is unlit. Nothing that is actually broken may resolve to50+ * `ok` — a paired-but-unsyncable device is red, not green.51+ */52+export type SyncIndicator = "busy" | "ok" | "error" | "idle";53+54+export function syncIndicator(s: SyncOutcomeSummary, pairedCount: number): SyncIndicator {55+  if (s.status === "syncing") return "busy";56+  if (s.outcome && isSyncFailure(s.outcome)) return "error";57+  if (s.outcome === "completed_changes" || s.outcome === "completed_no_changes") {58+    return "ok";59+  }60+  // Paired with a healthy history but no attempt since this SW woke: still a61+  // successful pair, which is what the light is claiming.62+  if (pairedCount > 0 && s.outcome === undefined) return "ok";63+  return "idle";64+}65+66+const INDICATOR_LABEL: Record<SyncIndicator, string> = {67+  busy: "Syncing",68+  ok: "Sync healthy",69+  error: "Sync problem",70+  idle: "Not syncing",71+};72+73+/** Colour alone is never the signal — this is the same claim in words. */74+export function syncIndicatorLabel(75+  indicator: SyncIndicator,76+  s: SyncOutcomeSummary,77+): string {78+  return `${INDICATOR_LABEL[indicator]} — ${describeSyncOutcome(s)}`;79+}80+81+const COPY: Record<SyncOutcome, string> = {82+  completed_changes: "Synced",83+  completed_no_changes: "Up to date — nothing to send or receive",84+  no_paired_devices: "No devices paired yet",85+  no_eligible_host: "Paired, but no device here can accept a sync",86+  runner_unavailable: "Sync isn't running in the background — reload Peach",87+  sync_disabled: "Sync is switched off",88+  private_relay_unset: "Private relay chosen but no address set",89+  vault_locked: "Vault was locked — unlock and sync again",90+  relay_unreachable: "Couldn't reach the relay",91+  handshake_failed: "Reached the relay, but the device didn't answer",92+  vault_id_mismatch: "That device holds a different vault",93+  sync_timeout: "The device stopped responding mid-sync",94+  run_failed: "Sync failed",95+};96+97+/**98+ * One plain-English line for a sync outcome. `detail` — the raw internal code99+ * or the device inventory behind `no_eligible_host` — is appended rather than100+ * hidden: it is the whole diagnostic on a real device, where devtools is not101+ * an option.102+ */103+export function describeSyncOutcome(s: SyncOutcomeSummary): string {104+  if (!s.outcome) return "Not synced yet";105+  const base = COPY[s.outcome] ?? "Sync failed";106+  if (s.outcome === "completed_changes") {107+    const moved = [108+      (s.entriesSent ?? 0) > 0 ? `${s.entriesSent} sent` : null,109+      (s.entriesReceived ?? 0) > 0 ? `${s.entriesReceived} received` : null,110+    ].filter(Boolean);111+    return moved.length > 0 ? `${base} — ${moved.join(", ")}` : base;112+  }113+  return s.detail ? `${base} (${s.detail})` : base;114+}

view file