From 8e659d30490226c3cee8662cc545b3b3f50e5cde Mon Sep 17 00:00:00 2001 From: lang <39692836+mindfn@users.noreply.github.com> Date: Sat, 26 Sep 2026 10:08:52 +0800 Subject: [PATCH] fix(f247): back off the personal Chrome reply poll while the Host Adapter is unavailable (#1531) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit * fix(f247): back off the personal Chrome reply poll while the Host Adapter is unavailable Why: the Host always starts PersonalChromeAssistantReturnPoller at boot (index.ts), and it polls every second. On a Host where ChatGPT Pro is not installed there is no pairing record, so every tick fails with HOST_UNAVAILABLE ("personal Chrome Host Adapter is not installed") and writes "[F247] personal Chrome assistant return poll deferred". That is one wasted check and one log line per second, forever, for everyone who does not use this optional feature (reported by the maintainer from a running instance). What: while the adapter answers HOST_UNAVAILABLE, the poller backs off exponentially from twice the poll interval up to 60s (2s, 4s, 8s, 16s, 32s, then 60s). The first successful answer resets it to the normal cadence. Only changes of state are logged: one line when it starts backing off and one when it resumes. HOST_UNAVAILABLE also covers "installed but the helper is not running", which is why a capped backoff is used rather than a fixed idle period: a reply is picked up at most 60s after the helper comes back. Other errors keep today's per-attempt debug line. The durable fix is F202 C1 W2-3 h3: reply polling becomes generic and runs only for an enabled package that declares it, so a Host without ChatGPT Pro does not poll at all. This change keeps the current wiring and only makes it quiet until then. Tests: personal-chrome-assistant-return-poller.test.ts, with an injected clock. - Over 3 minutes of 1s ticks with the adapter absent, the adapter is asked only at 0/2/6/14/30/62/122s, and exactly one line is logged. - After 3 failures the adapter answers at 14s; polling returns to every second, with one "resumed" line. - RED before the change. Poller and adapter suites: 19/19. tsc clean. Co-Authored-By: Claude Opus 5.5 * fix(f247): time the reply-poll backoff on a monotonic clock; test the reply that waited Review of #1531 at db8d07f958 (5324077784): - P1: the backoff deadline came from Date.now(), so a backward wall-clock step (NTP, sleep and wake, a manual change) could suspend recovery for as long as the step, far past the 60 s cap. It now uses performance.now(). The injectable clock is renamed monotonicNow so the contract is explicit. Regression: after the first failure Date.now() steps back an hour, and the retry still happens once 100 ms of real time has passed (red before the fix). - P2: the first log line now says polling backs off exponentially, up to one check per 60s. Both state-change lines are asserted exactly. - P2: a reply waiting when the adapter comes back is ingested once and acknowledged at its exact source on the first poll that gets an answer (14 s), then polling continues every second, with exactly two log lines. Also: the backoff tests move to their own file, so the original poller test is back to its upstream 331 lines (under the 350-line cap). The backoff steps in drainOnce move into small private methods (Biome cognitive complexity 19, over the 15 limit, now within it). The new test file joins the test:f247-chrome-host-spike lane. [宪宪/claude-opus-5-5🐾] Co-Authored-By: Claude Opus 5.5 --------- Co-authored-by: Claude Opus 5.5 (cherry picked from commit 1789afb026eb93056a7a07b3670c83fd3c6f84ca) --- packages/api/package.json | 2 +- ...personal-chrome-assistant-return-poller.ts | 66 +++++++- ...me-assistant-return-poller-backoff.test.ts | 145 ++++++++++++++++++ 3 files changed, 207 insertions(+), 6 deletions(-) create mode 100644 packages/api/test/personal-chrome-assistant-return-poller-backoff.test.ts diff --git a/packages/api/package.json b/packages/api/package.json index b5dd734605..b41468608d 100644 --- a/packages/api/package.json +++ b/packages/api/package.json @@ -24,7 +24,7 @@ "smoke:f254-codex-freshness": "pnpm run build && node dist/scripts/f254-codex-native-freshness-live-fixture.js", "smoke:f306-native-effect-guard": "pnpm run build && node dist/scripts/f306-native-effect-guard/live-fixture.js", "smoke:f254-claude-capability": "pnpm run build && node dist/scripts/f254-claude-stream-json-capability-fixture.js", - "test:f247-chrome-host-spike": "pnpm run build && node --import tsx --test test/personal-chrome-host-adapter.test.ts test/personal-chrome-assistant-return-poller.test.ts && node --test test/f247-browser-assistant-return-ingest.test.js test/personal-chrome-assistant-forwarding.test.js test/personal-chrome-assistant-return-inbox.test.js test/personal-chrome-assistant-return-terminal.test.js test/personal-chrome-conversation-binding.test.js test/personal-chrome-install-cli.test.js test/personal-chrome-installation.test.js test/personal-chrome-installation-race.test.js test/personal-chrome-native-host.test.js test/personal-chrome-native-messaging-integration.test.js test/personal-chrome-native-messaging-watchdog.test.js test/personal-chrome-page-adapter.test.js test/personal-chrome-page-adapter-multiline.test.js test/personal-chrome-extension-contract.test.js test/personal-chrome-live-gate.test.js test/personal-chrome-in-place-live-gate.test.js test/personal-chrome-normal-dispatch-live-gate.test.js test/personal-chrome-plugin-routes.test.js test/personal-chrome-plugin-state-route-exact.test.js test/personal-chrome-plugin-state.test.js test/f247-owner-chrome-product-chain.test.js test/f247-fingerprint-bounds-product-chain.test.js && node scripts/f247-personal-chrome-host-spike.mjs", + "test:f247-chrome-host-spike": "pnpm run build && node --import tsx --test test/personal-chrome-host-adapter.test.ts test/personal-chrome-assistant-return-poller.test.ts test/personal-chrome-assistant-return-poller-backoff.test.ts && node --test test/f247-browser-assistant-return-ingest.test.js test/personal-chrome-assistant-forwarding.test.js test/personal-chrome-assistant-return-inbox.test.js test/personal-chrome-assistant-return-terminal.test.js test/personal-chrome-conversation-binding.test.js test/personal-chrome-install-cli.test.js test/personal-chrome-installation.test.js test/personal-chrome-installation-race.test.js test/personal-chrome-native-host.test.js test/personal-chrome-native-messaging-integration.test.js test/personal-chrome-native-messaging-watchdog.test.js test/personal-chrome-page-adapter.test.js test/personal-chrome-page-adapter-multiline.test.js test/personal-chrome-extension-contract.test.js test/personal-chrome-live-gate.test.js test/personal-chrome-in-place-live-gate.test.js test/personal-chrome-normal-dispatch-live-gate.test.js test/personal-chrome-plugin-routes.test.js test/personal-chrome-plugin-state-route-exact.test.js test/personal-chrome-plugin-state.test.js test/f247-owner-chrome-product-chain.test.js test/f247-fingerprint-bounds-product-chain.test.js && node scripts/f247-personal-chrome-host-spike.mjs", "install:f247-personal-chrome": "pnpm run build && node scripts/f247-personal-chrome-install.mjs install", "inspect:f247-personal-chrome": "node scripts/f247-personal-chrome-install.mjs inspect", "uninstall:f247-personal-chrome": "node scripts/f247-personal-chrome-install.mjs uninstall", diff --git a/packages/api/src/domains/cats/services/cloud-bridge/personal-chrome-host/personal-chrome-assistant-return-poller.ts b/packages/api/src/domains/cats/services/cloud-bridge/personal-chrome-host/personal-chrome-assistant-return-poller.ts index 27af5a4581..38d90b5ceb 100644 --- a/packages/api/src/domains/cats/services/cloud-bridge/personal-chrome-host/personal-chrome-assistant-return-poller.ts +++ b/packages/api/src/domains/cats/services/cloud-bridge/personal-chrome-host/personal-chrome-assistant-return-poller.ts @@ -1,3 +1,4 @@ +import { performance } from 'node:perf_hooks'; import type { CloudAssistantReturnIngestInput, CloudAssistantReturnIngestOutcome, @@ -6,6 +7,16 @@ import type { PersonalChromeAssistantReturnCursor } from './assistant-return-cur import type { IPersonalChromeAssistantReturnAdapter } from './personal-chrome-host-transport.js'; const DEFAULT_POLL_INTERVAL_MS = 1_000; +/** + * While the Host Adapter is unavailable (not installed, or its helper is not running) the poller + * backs off exponentially from twice the poll interval up to this cap, instead of retrying — and + * logging — every second on every Host where ChatGPT Pro is not installed. The first answer resets it. + */ +const MAX_UNAVAILABLE_BACKOFF_MS = 60_000; + +function isHostUnavailable(error: unknown): boolean { + return typeof error === 'object' && error !== null && (error as { code?: unknown }).code === 'HOST_UNAVAILABLE'; +} interface AssistantReturnIngestPort { ingest(input: CloudAssistantReturnIngestInput): Promise; @@ -20,6 +31,9 @@ export class PersonalChromeAssistantReturnPoller { private timer: NodeJS.Timeout | undefined; private draining = false; private resumeAfter: PersonalChromeAssistantReturnCursor | undefined; + /** Consecutive HOST_UNAVAILABLE answers; zero while the adapter is reachable. */ + private unavailableStreak = 0; + private nextAttemptAt = 0; constructor( private readonly deps: { @@ -28,6 +42,12 @@ export class PersonalChromeAssistantReturnPoller { readonly logger: AssistantReturnPollerLogger; readonly grantPersistence: 'durable' | 'ephemeral'; readonly pollIntervalMs?: number; + /** + * Milliseconds on a monotonic clock, used only to time the backoff. Defaults to + * `performance.now()`. Never wall-clock time: a backward clock step would stretch the + * backoff far past its cap (PR #1531 review). + */ + readonly monotonicNow?: () => number; }, ) { const interval = deps.pollIntervalMs ?? DEFAULT_POLL_INTERVAL_MS; @@ -49,11 +69,16 @@ export class PersonalChromeAssistantReturnPoller { this.timer = undefined; } + private now(): number { + return this.deps.monotonicNow?.() ?? performance.now(); + } + async drainOnce(): Promise { - if (this.draining) return; + if (this.draining || this.backingOff()) return; this.draining = true; try { const pending = await this.deps.adapter.list_assistant_returns(this.resumeAfter); + this.noteAnswered(); const item = pending[0]; if (!item) { this.resumeAfter = undefined; @@ -92,12 +117,43 @@ export class PersonalChromeAssistantReturnPoller { await this.deps.adapter.ack_assistant_return(item.conversationId, item.sourceMessageId, item.assistantMessageId); this.resumeAfter = undefined; } catch (error) { - this.deps.logger.debug?.( - { error: error instanceof Error ? { name: error.name, message: error.message } : String(error) }, - '[F247] personal Chrome assistant return poll deferred', - ); + if (isHostUnavailable(error)) { + this.backOff(error); + return; + } + this.deps.logger.debug?.(errorDetail(error), '[F247] personal Chrome assistant return poll deferred'); } finally { this.draining = false; } } + + /** While the adapter is unavailable, ticks are skipped until the current backoff has elapsed. */ + private backingOff(): boolean { + return this.unavailableStreak > 0 && this.now() < this.nextAttemptAt; + } + + /** The adapter answered: back to the normal cadence, with one line if it had been unavailable. */ + private noteAnswered(): void { + if (this.unavailableStreak === 0) return; + this.unavailableStreak = 0; + this.deps.logger.debug?.({}, '[F247] personal Chrome Host Adapter answered; assistant return polling resumed'); + } + + /** Doubles the wait from twice the poll interval up to the cap; only the first failure is logged. */ + private backOff(error: unknown): void { + this.unavailableStreak += 1; + const interval = this.deps.pollIntervalMs ?? DEFAULT_POLL_INTERVAL_MS; + this.nextAttemptAt = this.now() + Math.min(MAX_UNAVAILABLE_BACKOFF_MS, interval * 2 ** this.unavailableStreak); + // Only the change of state is worth a line; the repeats are the expected steady state. + if (this.unavailableStreak === 1) { + this.deps.logger.debug?.( + errorDetail(error), + `[F247] personal Chrome Host Adapter unavailable; assistant return polling backs off exponentially, up to one check per ${MAX_UNAVAILABLE_BACKOFF_MS / 1_000}s, until it answers`, + ); + } + } +} + +function errorDetail(error: unknown): object { + return { error: error instanceof Error ? { name: error.name, message: error.message } : String(error) }; } diff --git a/packages/api/test/personal-chrome-assistant-return-poller-backoff.test.ts b/packages/api/test/personal-chrome-assistant-return-poller-backoff.test.ts new file mode 100644 index 0000000000..a3bcef5cd8 --- /dev/null +++ b/packages/api/test/personal-chrome-assistant-return-poller-backoff.test.ts @@ -0,0 +1,145 @@ +/** + * #1532: while the Host Adapter answers HOST_UNAVAILABLE (ChatGPT Pro not installed, or its helper not + * running), the reply poll backs off exponentially up to one check a minute and logs only changes of + * state, instead of checking and logging every second. The first answer restores the normal cadence. + */ +import assert from 'node:assert/strict'; +import { describe, it } from 'node:test'; + +import { PersonalChromeAssistantReturnPoller } from '../src/domains/cats/services/cloud-bridge/personal-chrome-host/personal-chrome-assistant-return-poller.js'; + +const BACKING_OFF = + '[F247] personal Chrome Host Adapter unavailable; assistant return polling backs off exponentially, up to one check per 60s, until it answers'; +const RESUMED = '[F247] personal Chrome Host Adapter answered; assistant return polling resumed'; + +const reply = { + conversationId: 'conversation-7', + sourceMessageId: 'source-message-9', + assistantMessageId: 'conversation-turn-43', + content: 'bounded assistant final', +}; + +function unavailable() { + return Object.assign(new Error('personal Chrome Host Adapter is not installed'), { code: 'HOST_UNAVAILABLE' }); +} + +/** + * A poller on a stepped monotonic clock. The adapter fails `failures` times, then answers with the + * waiting replies; like the native inbox, a reply is listed until it is acknowledged. + */ +function harness(options: { failures: number; replies?: Array }) { + let clock = 0; + let remainingFailures = options.failures; + const inbox = [...(options.replies ?? [])]; + const calls: number[] = []; + const logs: string[] = []; + const ingested: unknown[] = []; + const acknowledgements: Array<[string, string, string]> = []; + const acknowledgedAt: number[] = []; + const poller = new PersonalChromeAssistantReturnPoller({ + adapter: { + list_assistant_returns: async () => { + calls.push(clock); + if (remainingFailures > 0) { + remainingFailures -= 1; + throw unavailable(); + } + return inbox.slice(0, 1); + }, + ack_assistant_return: async (conversationId, sourceMessageId, assistantMessageId) => { + acknowledgements.push([conversationId, sourceMessageId, assistantMessageId]); + acknowledgedAt.push(clock); + inbox.shift(); + }, + }, + ingestService: { + ingest: async (input) => { + ingested.push(input); + return { status: 'persisted', messageId: 'callback-message-1' }; + }, + }, + logger: { + debug: (_context, message) => logs.push(message), + warn: (_context, message) => logs.push(message), + }, + grantPersistence: 'durable', + monotonicNow: () => clock, + }); + return { + calls, + logs, + ingested, + acknowledgements, + acknowledgedAt, + async tickUntil(untilMs: number) { + for (; clock <= untilMs; clock += 1_000) await poller.drainOnce(); + clock -= 1_000; + }, + }; +} + +/** A tick every second from 14 s to 20 s: the normal cadence after the adapter answers at 14 s. */ +const RECOVERED_CADENCE = [14_000, 15_000, 16_000, 17_000, 18_000, 19_000, 20_000]; + +describe('PersonalChromeAssistantReturnPoller when the Host Adapter is unavailable', () => { + it('backs off exponentially to one check a minute and logs the change of state once', async () => { + const h = harness({ failures: Number.POSITIVE_INFINITY }); + + await h.tickUntil(180_000); + + // 2 s, 4 s, 8 s, 16 s, 32 s, then capped at 60 s: a handful of checks, not one per second. + assert.deepEqual(h.calls, [0, 2_000, 6_000, 14_000, 30_000, 62_000, 122_000]); + assert.deepEqual(h.logs, [BACKING_OFF]); + }); + + it('resumes the normal cadence as soon as the adapter answers, with one line', async () => { + const h = harness({ failures: 3 }); + + await h.tickUntil(20_000); + + // Fails at 0, 2 s and 6 s; answers at 14 s, then polls every second again. + assert.deepEqual(h.calls, [0, 2_000, 6_000, ...RECOVERED_CADENCE]); + assert.deepEqual(h.logs, [BACKING_OFF, RESUMED]); + }); + + it('delivers a reply that waited through the backoff: ingested once, acknowledged at its exact source', async () => { + const h = harness({ failures: 3, replies: [reply] }); + + await h.tickUntil(20_000); + + assert.deepEqual(h.ingested, [{ sourceMessageId: reply.sourceMessageId, content: reply.content }]); + assert.deepEqual(h.acknowledgements, [[reply.conversationId, reply.sourceMessageId, reply.assistantMessageId]]); + assert.deepEqual(h.acknowledgedAt, [14_000], 'handled by the first poll that gets an answer, not a later one'); + assert.deepEqual(h.calls, [0, 2_000, 6_000, ...RECOVERED_CADENCE]); + assert.deepEqual(h.logs, [BACKING_OFF, RESUMED]); + }); + + it('keeps its backoff on a monotonic clock: a backward wall-clock step does not stretch it', async (t) => { + let wallClock = 3_600_000; + t.mock.method(Date, 'now', () => wallClock); + let calls = 0; + const poller = new PersonalChromeAssistantReturnPoller({ + adapter: { + list_assistant_returns: async () => { + calls += 1; + throw unavailable(); + }, + ack_assistant_return: async () => {}, + }, + ingestService: { ingest: async () => ({ status: 'duplicate', messageId: 'unused' }) }, + logger: { warn() {} }, + grantPersistence: 'durable', + pollIntervalMs: 50, + }); + + await poller.drainOnce(); // unavailable: the first retry is due 100 ms later + await poller.drainOnce(); + assert.equal(calls, 1, 'the backoff still holds before it has elapsed'); + + wallClock = 0; // the wall clock steps back an hour + await new Promise((resolve) => setTimeout(resolve, 150)); + await poller.drainOnce(); + + assert.equal(calls, 2, 'the retry follows elapsed time, not the wall clock'); + }); +});