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'); + }); +});