From 4a8805e6064895058898804de6779b7fdf2988e5 Mon Sep 17 00:00:00 2001 From: yaowenc2 Date: Thu, 27 Aug 2026 12:48:31 -0700 Subject: [PATCH 01/19] =?UTF-8?q?feat(compute):=20add=20`compute=20logs=20?= =?UTF-8?q?`=20=E2=80=94=20container=20stdout/stderr=20from=20the=20CL?= =?UTF-8?q?I?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The dashboard has had a compute Logs panel since cloud-backend #662 / oss #1480, but the CLI only exposed `compute events` (machine lifecycle). Agents driving the CLI therefore concluded compute logs were UI-only. This wires the existing GET /api/compute/services/:id/logs endpoint into `compute logs`, with --limit, --follow (2s poll via nextToken), --next-token, and --json (returns { lines, nextToken }). Co-Authored-By: Claude Fable 5 --- README.md | 10 +++ src/commands/compute/events.ts | 6 +- src/commands/compute/logs.test.ts | 73 +++++++++++++++++++++ src/commands/compute/logs.ts | 105 ++++++++++++++++++++++++++++++ src/index.ts | 2 + 5 files changed, 193 insertions(+), 3 deletions(-) create mode 100644 src/commands/compute/logs.test.ts create mode 100644 src/commands/compute/logs.ts diff --git a/README.md b/README.md index c56ed58a..34ca2fcf 100644 --- a/README.md +++ b/README.md @@ -1091,6 +1091,16 @@ Get compute service machine events (start/stop/exit/restart). npx @insforge/cli compute events my-api --limit 50 ``` +#### `npx @insforge/cli compute logs ` + +Get container stdout/stderr (application logs) — the same data as the dashboard's Logs panel. Use `compute events` for machine lifecycle events instead. + +```bash +npx @insforge/cli compute logs my-api --limit 200 +npx @insforge/cli compute logs my-api --follow # poll for new lines every 2s +npx @insforge/cli --json compute logs my-api # { lines, nextToken } — pass nextToken back via --next-token to page forward +``` + #### `npx @insforge/cli compute delete ` Delete a compute service and its Fly.io resources. diff --git a/src/commands/compute/events.ts b/src/commands/compute/events.ts index 73789e39..f979ffc1 100644 --- a/src/commands/compute/events.ts +++ b/src/commands/compute/events.ts @@ -7,9 +7,9 @@ import { reportCliUsage } from '../../lib/skills.js'; import { trackCommandUsage } from '../../lib/command-telemetry.js'; // `compute events ` returns Fly machine lifecycle events (start/stop/exit/ -// restart) — not container stdout/stderr. The previous name `compute logs` -// was misleading; container log streaming is roadmap work and will reuse the -// freshly-vacated `logs` command name when it lands. +// restart) — not container stdout/stderr. For container logs use +// `compute logs `. (This command was originally named `compute logs`, +// which was misleading.) export function registerComputeEventsCommand(computeCmd: Command): void { computeCmd .command('events ') diff --git a/src/commands/compute/logs.test.ts b/src/commands/compute/logs.test.ts new file mode 100644 index 00000000..2403f8a2 --- /dev/null +++ b/src/commands/compute/logs.test.ts @@ -0,0 +1,73 @@ +import { describe, expect, it, vi, beforeEach, afterEach } from 'vitest'; +import type * as ErrorsModule from '../../lib/errors.js'; + +const ossFetchMock = vi.hoisted(() => vi.fn()); +const outputJsonMock = vi.hoisted(() => vi.fn()); +vi.mock('../../lib/api/oss.js', () => ({ ossFetch: ossFetchMock })); +vi.mock('../../lib/credentials.js', () => ({ requireAuth: vi.fn().mockResolvedValue(undefined) })); +vi.mock('../../lib/skills.js', () => ({ reportCliUsage: vi.fn() })); +vi.mock('../../lib/output.js', () => ({ outputJson: outputJsonMock })); +vi.mock('../../lib/errors.js', async (importOriginal) => { + const actual = await importOriginal(); + return { + ...actual, + handleError: (err: unknown) => { throw err; }, + }; +}); + +import { Command } from 'commander'; +import { registerComputeLogsCommand, formatLogLine } from './logs.js'; + +function run(args: string[]) { + const cmd = new Command(); + cmd.exitOverride(); + cmd.option('--json'); + const compute = cmd.command('compute'); + registerComputeLogsCommand(compute); + return cmd.parseAsync(['node', 'insforge', ...args]); +} + +describe('compute logs', () => { + let logSpy: ReturnType; + beforeEach(() => { + ossFetchMock.mockReset(); + outputJsonMock.mockReset(); + logSpy = vi.spyOn(console, 'log').mockImplementation(() => {}); + }); + afterEach(() => logSpy.mockRestore()); + + it('calls the container logs endpoint with a clamped limit', async () => { + ossFetchMock.mockResolvedValueOnce({ json: async () => ({ lines: [], nextToken: null }) }); + await run(['compute', 'logs', 'my api', '--limit', '5000']); + expect(ossFetchMock).toHaveBeenCalledWith('/api/compute/services/my%20api/logs?limit=1000'); + expect(logSpy).toHaveBeenCalledWith('No logs found.'); + }); + + it('forwards --next-token as next_token', async () => { + ossFetchMock.mockResolvedValueOnce({ json: async () => ({ lines: [], nextToken: null }) }); + await run(['compute', 'logs', 'svc', '--next-token', 'abc']); + expect(ossFetchMock.mock.calls[0][0]).toBe('/api/compute/services/svc/logs?limit=100&next_token=abc'); + }); + + it('prints formatted lines', async () => { + ossFetchMock.mockResolvedValueOnce({ + json: async () => ({ + lines: [{ timestamp: 0, message: 'hello', region: 'sjc', instance: 'abc123' }], + nextToken: 'tok', + }), + }); + await run(['compute', 'logs', 'svc']); + expect(logSpy).toHaveBeenCalledWith('1970-01-01T00:00:00.000Z [sjc abc123] hello'); + }); + + it('emits the full result (with cursor) under --json', async () => { + const payload = { lines: [{ timestamp: 1, message: 'x' }], nextToken: 'tok' }; + ossFetchMock.mockResolvedValueOnce({ json: async () => payload }); + await run(['--json', 'compute', 'logs', 'svc']); + expect(outputJsonMock).toHaveBeenCalledWith(payload); + }); + + it('formatLogLine omits the bracket when no region/instance', () => { + expect(formatLogLine({ timestamp: 0, message: 'm' })).toBe('1970-01-01T00:00:00.000Z m'); + }); +}); diff --git a/src/commands/compute/logs.ts b/src/commands/compute/logs.ts new file mode 100644 index 00000000..6cdbf08b --- /dev/null +++ b/src/commands/compute/logs.ts @@ -0,0 +1,105 @@ +import type { Command } from 'commander'; +import { ossFetch } from '../../lib/api/oss.js'; +import { requireAuth } from '../../lib/credentials.js'; +import { handleError, getRootOpts } from '../../lib/errors.js'; +import { outputJson } from '../../lib/output.js'; +import { reportCliUsage } from '../../lib/skills.js'; + +// `compute logs ` returns container stdout/stderr ("application logs") — +// the same data the dashboard Logs panel shows. For machine lifecycle events +// (start/stop/exit/restart) use `compute events ` instead. +// +// Endpoint: GET /api/compute/services/:id/logs?limit=&next_token= +// Response: { lines: { timestamp, message, instance?, region? }[], nextToken: string | null } +// `nextToken` is an opaque forward cursor; `--follow` polls with it. The +// endpoint is rate-limited server-side (dashboard polls every ~2s), so the +// follow interval stays at 2s. + +export interface ComputeLogLine { + timestamp: number; + message: string; + instance?: string; + region?: string; +} + +export interface ComputeLogsResult { + lines: ComputeLogLine[]; + nextToken: string | null; +} + +const FOLLOW_INTERVAL_MS = 2000; + +export function formatLogLine(line: ComputeLogLine): string { + const ts = new Date(line.timestamp).toISOString(); + const where = [line.region, line.instance].filter(Boolean).join(' '); + return where ? `${ts} [${where}] ${line.message}` : `${ts} ${line.message}`; +} + +export async function fetchComputeLogs( + id: string, + opts: { limit: number; nextToken?: string }, +): Promise { + const params = new URLSearchParams({ limit: String(opts.limit) }); + if (opts.nextToken) params.set('next_token', opts.nextToken); + const res = await ossFetch( + `/api/compute/services/${encodeURIComponent(id)}/logs?${params.toString()}`, + ); + const body = await res.json() as Partial | null; + return { + lines: Array.isArray(body?.lines) ? body.lines : [], + nextToken: typeof body?.nextToken === 'string' && body.nextToken.length > 0 ? body.nextToken : null, + }; +} + +export function registerComputeLogsCommand(computeCmd: Command): void { + computeCmd + .command('logs ') + .description('Get compute service container logs (stdout/stderr)') + .option('--limit ', 'Max number of log lines per fetch (1-1000)', '100') + .option('-f, --follow', 'Keep polling for new lines (Ctrl+C to stop)') + .option('--next-token ', 'Resume from a cursor returned by a previous --json call') + .action(async (id: string, opts, cmd) => { + const { json } = getRootOpts(cmd); + try { + await requireAuth(); + + const limit = Math.max(1, Math.min(Number(opts.limit) || 100, 1000)); + let result = await fetchComputeLogs(id, { limit, nextToken: opts.nextToken }); + + if (json && !opts.follow) { + outputJson(result); + await reportCliUsage('cli.compute.logs', true); + return; + } + + const print = (lines: ComputeLogLine[]) => { + for (const line of lines) { + console.log(json ? JSON.stringify(line) : formatLogLine(line)); + } + }; + + if (result.lines.length === 0 && !opts.follow) { + console.log('No logs found.'); + await reportCliUsage('cli.compute.logs', true); + return; + } + print(result.lines); + + if (opts.follow) { + if (!json) console.error('Following logs... (Ctrl+C to stop)'); + let token = result.nextToken; + while (true) { + await new Promise((r) => setTimeout(r, FOLLOW_INTERVAL_MS)); + result = await fetchComputeLogs(id, { limit, nextToken: token ?? undefined }); + print(result.lines); + if (result.nextToken) token = result.nextToken; + } + } + + await reportCliUsage('cli.compute.logs', true); + } catch (err) { + await reportCliUsage('cli.compute.logs', false); + handleError(err, json); + } + }); +} diff --git a/src/index.ts b/src/index.ts index 0a2990d4..5d102da5 100644 --- a/src/index.ts +++ b/src/index.ts @@ -79,6 +79,7 @@ import { registerComputeDeleteCommand } from './commands/compute/delete.js'; import { registerComputeStartCommand } from './commands/compute/start.js'; import { registerComputeStopCommand } from './commands/compute/stop.js'; import { registerComputeEventsCommand } from './commands/compute/events.js'; +import { registerComputeLogsCommand } from './commands/compute/logs.js'; import { registerComputeDeployCommand } from './commands/compute/deploy.js'; import { registerLogsCommand } from './commands/logs.js'; @@ -276,6 +277,7 @@ registerComputeDeleteCommand(computeCmd); registerComputeStartCommand(computeCmd); registerComputeStopCommand(computeCmd); registerComputeEventsCommand(computeCmd); +registerComputeLogsCommand(computeCmd); // PostHog commands const posthogCmd = program.command('posthog').description('Manage PostHog product analytics integration'); From 51e7e36d8ad5d24a2af2a5073837ce6dbc0c3780 Mon Sep 17 00:00:00 2001 From: yaowenc2 Date: Thu, 27 Aug 2026 14:12:45 -0700 Subject: [PATCH 02/19] fix(compute-logs): sanitize terminal escapes in human output; document NDJSON follow mode MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Greptile P1s: container output can carry ANSI/OSC escapes (terminal injection) — strip ESC-led sequences and C0 controls except tab in the human-readable path (JSON.stringify already escapes them in --json). --json --follow now documents its NDJSON shape in help + README. Co-Authored-By: Claude Fable 5 --- README.md | 1 + src/commands/compute/logs.test.ts | 10 ++++++++++ src/commands/compute/logs.ts | 16 ++++++++++++++-- 3 files changed, 25 insertions(+), 2 deletions(-) diff --git a/README.md b/README.md index 34ca2fcf..65baaabc 100644 --- a/README.md +++ b/README.md @@ -1099,6 +1099,7 @@ Get container stdout/stderr (application logs) — the same data as the dashboar npx @insforge/cli compute logs my-api --limit 200 npx @insforge/cli compute logs my-api --follow # poll for new lines every 2s npx @insforge/cli --json compute logs my-api # { lines, nextToken } — pass nextToken back via --next-token to page forward +npx @insforge/cli --json compute logs my-api --follow # NDJSON: one {timestamp, message, ...} object per line ``` #### `npx @insforge/cli compute delete ` diff --git a/src/commands/compute/logs.test.ts b/src/commands/compute/logs.test.ts index 2403f8a2..3f0c7772 100644 --- a/src/commands/compute/logs.test.ts +++ b/src/commands/compute/logs.test.ts @@ -71,3 +71,13 @@ describe('compute logs', () => { expect(formatLogLine({ timestamp: 0, message: 'm' })).toBe('1970-01-01T00:00:00.000Z m'); }); }); + +describe('sanitizeLogMessage', () => { + it('strips ANSI CSI/OSC sequences and control chars, keeps tabs', async () => { + const { sanitizeLogMessage } = await import('./logs.js'); + expect(sanitizeLogMessage('\u001b[31mred\u001b[0m ok')).toBe('red ok'); + expect(sanitizeLogMessage('\u001b]0;evil title\u0007text')).toBe('text'); + expect(sanitizeLogMessage('a\u0008b\rc')).toBe('abc'); + expect(sanitizeLogMessage('keep\ttabs')).toBe('keep\ttabs'); + }); +}); diff --git a/src/commands/compute/logs.ts b/src/commands/compute/logs.ts index 6cdbf08b..b2e32fcf 100644 --- a/src/commands/compute/logs.ts +++ b/src/commands/compute/logs.ts @@ -29,10 +29,22 @@ export interface ComputeLogsResult { const FOLLOW_INTERVAL_MS = 2000; +// Container output is attacker-adjacent data: a compromised (or just chatty) +// app can emit ANSI/OSC escape sequences that reprogram the reader's +// terminal. Strip ESC-led sequences and all C0 controls except tab before +// printing. JSON mode is safe as-is — JSON.stringify escapes controls. +// eslint-disable-next-line no-control-regex +const TERMINAL_CONTROLS = /\u001b\[[0-9;?]*[ -/]*[@-~]|\u001b\][^\u0007\u001b]*(?:\u0007|\u001b\\)|\u001b[@-_]|[\u0000-\u0008\u000a-\u001f\u007f]/g; + +export function sanitizeLogMessage(message: string): string { + return message.replace(TERMINAL_CONTROLS, ''); +} + export function formatLogLine(line: ComputeLogLine): string { const ts = new Date(line.timestamp).toISOString(); const where = [line.region, line.instance].filter(Boolean).join(' '); - return where ? `${ts} [${where}] ${line.message}` : `${ts} ${line.message}`; + const msg = sanitizeLogMessage(line.message); + return where ? `${ts} [${where}] ${msg}` : `${ts} ${msg}`; } export async function fetchComputeLogs( @@ -56,7 +68,7 @@ export function registerComputeLogsCommand(computeCmd: Command): void { .command('logs ') .description('Get compute service container logs (stdout/stderr)') .option('--limit ', 'Max number of log lines per fetch (1-1000)', '100') - .option('-f, --follow', 'Keep polling for new lines (Ctrl+C to stop)') + .option('-f, --follow', 'Keep polling for new lines (Ctrl+C to stop). With --json, emits NDJSON: one log-line object per line') .option('--next-token ', 'Resume from a cursor returned by a previous --json call') .action(async (id: string, opts, cmd) => { const { json } = getRootOpts(cmd); From 7574fca44a238c9ca2614fd2cc40a4e41b0a0a39 Mon Sep 17 00:00:00 2001 From: yaowenc2 Date: Thu, 27 Aug 2026 14:22:30 -0700 Subject: [PATCH 03/19] =?UTF-8?q?fix(compute-logs):=20address=20review=20r?= =?UTF-8?q?ound=202=20=E2=80=94=20telemetry,=20C1=20controls,=20follow=20d?= =?UTF-8?q?edupe,=20exact=20limit?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit - Use PostHog trackCommandUsage like the rest of the compute group (DEVELOPMENT.md says new commands skip the legacy OSS usage path) - Sanitize at the fetch boundary and extend to 8-bit C1 controls, covering --json output where JSON.stringify leaves C1 bytes raw (cubic P2) - Deduplicate --follow output when the provider returns no cursor (coderabbit): filter lines at or before the last printed timestamp - parseLimit: exact 1-1000 contract; --limit 0 clamps to 1, malformed input falls back to the default (john-bot suggestion) - Tests: fake-timer follow loop (cursor forwarding, NDJSON, dedupe), C1 stripping, parseLimit table (cubic P3 / john-bot suggestion) Co-Authored-By: Claude Fable 5 --- src/commands/compute/logs.test.ts | 109 ++++++++++++++++++++++++------ src/commands/compute/logs.ts | 60 +++++++++++----- 2 files changed, 129 insertions(+), 40 deletions(-) diff --git a/src/commands/compute/logs.test.ts b/src/commands/compute/logs.test.ts index 3f0c7772..27dd25ce 100644 --- a/src/commands/compute/logs.test.ts +++ b/src/commands/compute/logs.test.ts @@ -5,7 +5,7 @@ const ossFetchMock = vi.hoisted(() => vi.fn()); const outputJsonMock = vi.hoisted(() => vi.fn()); vi.mock('../../lib/api/oss.js', () => ({ ossFetch: ossFetchMock })); vi.mock('../../lib/credentials.js', () => ({ requireAuth: vi.fn().mockResolvedValue(undefined) })); -vi.mock('../../lib/skills.js', () => ({ reportCliUsage: vi.fn() })); +vi.mock('../../lib/command-telemetry.js', () => ({ trackCommandUsage: vi.fn() })); vi.mock('../../lib/output.js', () => ({ outputJson: outputJsonMock })); vi.mock('../../lib/errors.js', async (importOriginal) => { const actual = await importOriginal(); @@ -16,7 +16,11 @@ vi.mock('../../lib/errors.js', async (importOriginal) => { }); import { Command } from 'commander'; -import { registerComputeLogsCommand, formatLogLine } from './logs.js'; +import { registerComputeLogsCommand, formatLogLine, sanitizeLogMessage, parseLimit } from './logs.js'; + +const ESC = String.fromCharCode(0x1b); +const BEL = String.fromCharCode(0x07); +const CSI_C1 = String.fromCharCode(0x9b); // 8-bit CSI function run(args: string[]) { const cmd = new Command(); @@ -27,57 +31,118 @@ function run(args: string[]) { return cmd.parseAsync(['node', 'insforge', ...args]); } +function page(lines: unknown[], nextToken: string | null = null) { + return { json: async () => ({ lines, nextToken }) }; +} + describe('compute logs', () => { let logSpy: ReturnType; + let errSpy: ReturnType; beforeEach(() => { ossFetchMock.mockReset(); outputJsonMock.mockReset(); logSpy = vi.spyOn(console, 'log').mockImplementation(() => {}); + errSpy = vi.spyOn(console, 'error').mockImplementation(() => {}); + }); + afterEach(() => { + logSpy.mockRestore(); + errSpy.mockRestore(); + vi.useRealTimers(); }); - afterEach(() => logSpy.mockRestore()); it('calls the container logs endpoint with a clamped limit', async () => { - ossFetchMock.mockResolvedValueOnce({ json: async () => ({ lines: [], nextToken: null }) }); + ossFetchMock.mockResolvedValueOnce(page([])); await run(['compute', 'logs', 'my api', '--limit', '5000']); expect(ossFetchMock).toHaveBeenCalledWith('/api/compute/services/my%20api/logs?limit=1000'); expect(logSpy).toHaveBeenCalledWith('No logs found.'); }); it('forwards --next-token as next_token', async () => { - ossFetchMock.mockResolvedValueOnce({ json: async () => ({ lines: [], nextToken: null }) }); + ossFetchMock.mockResolvedValueOnce(page([])); await run(['compute', 'logs', 'svc', '--next-token', 'abc']); expect(ossFetchMock.mock.calls[0][0]).toBe('/api/compute/services/svc/logs?limit=100&next_token=abc'); }); it('prints formatted lines', async () => { - ossFetchMock.mockResolvedValueOnce({ - json: async () => ({ - lines: [{ timestamp: 0, message: 'hello', region: 'sjc', instance: 'abc123' }], - nextToken: 'tok', - }), - }); + ossFetchMock.mockResolvedValueOnce(page( + [{ timestamp: 0, message: 'hello', region: 'sjc', instance: 'abc123' }], 'tok', + )); await run(['compute', 'logs', 'svc']); expect(logSpy).toHaveBeenCalledWith('1970-01-01T00:00:00.000Z [sjc abc123] hello'); }); - it('emits the full result (with cursor) under --json', async () => { - const payload = { lines: [{ timestamp: 1, message: 'x' }], nextToken: 'tok' }; - ossFetchMock.mockResolvedValueOnce({ json: async () => payload }); + it('emits the full result (with cursor) under --json, sanitized', async () => { + ossFetchMock.mockResolvedValueOnce(page([{ timestamp: 1, message: `x${CSI_C1}31my` }], 'tok')); await run(['--json', 'compute', 'logs', 'svc']); - expect(outputJsonMock).toHaveBeenCalledWith(payload); + expect(outputJsonMock).toHaveBeenCalledWith({ + lines: [{ timestamp: 1, message: 'x31my' }], + nextToken: 'tok', + }); + }); + + it('--follow forwards the cursor on the next poll and prints per batch', async () => { + vi.useFakeTimers(); + ossFetchMock.mockResolvedValueOnce(page([{ timestamp: 1, message: 'one' }], 'tokA')); + ossFetchMock.mockResolvedValueOnce(page([{ timestamp: 2, message: 'two' }], 'tokB')); + ossFetchMock.mockResolvedValue(page([])); + void run(['compute', 'logs', 'svc', '--follow']); + await vi.advanceTimersByTimeAsync(0); + expect(logSpy).toHaveBeenCalledWith('1970-01-01T00:00:00.001Z one'); + await vi.advanceTimersByTimeAsync(2000); + expect(ossFetchMock.mock.calls[1][0]).toBe('/api/compute/services/svc/logs?limit=100&next_token=tokA'); + expect(logSpy).toHaveBeenCalledWith('1970-01-01T00:00:00.002Z two'); + await vi.advanceTimersByTimeAsync(2000); + expect(ossFetchMock.mock.calls[2][0]).toBe('/api/compute/services/svc/logs?limit=100&next_token=tokB'); }); - it('formatLogLine omits the bracket when no region/instance', () => { - expect(formatLogLine({ timestamp: 0, message: 'm' })).toBe('1970-01-01T00:00:00.000Z m'); + it('--follow without a cursor drops already-printed lines on refetch', async () => { + vi.useFakeTimers(); + ossFetchMock.mockResolvedValueOnce(page([{ timestamp: 5, message: 'seen' }], null)); + ossFetchMock.mockResolvedValueOnce(page([ + { timestamp: 5, message: 'seen' }, + { timestamp: 9, message: 'fresh' }, + ], null)); + ossFetchMock.mockResolvedValue(page([])); + void run(['compute', 'logs', 'svc', '--follow']); + await vi.advanceTimersByTimeAsync(0); + await vi.advanceTimersByTimeAsync(2000); + expect(ossFetchMock.mock.calls[1][0]).toBe('/api/compute/services/svc/logs?limit=100'); + const printed = logSpy.mock.calls.map((c) => String(c[0])); + expect(printed.filter((l) => l.includes('seen'))).toHaveLength(1); + expect(printed.some((l) => l.includes('fresh'))).toBe(true); + }); + + it('--json --follow emits NDJSON per line', async () => { + vi.useFakeTimers(); + ossFetchMock.mockResolvedValueOnce(page([{ timestamp: 1, message: 'a' }], 'tok')); + ossFetchMock.mockResolvedValue(page([])); + void run(['--json', 'compute', 'logs', 'svc', '--follow']); + await vi.advanceTimersByTimeAsync(0); + expect(logSpy).toHaveBeenCalledWith(JSON.stringify({ timestamp: 1, message: 'a' })); + expect(outputJsonMock).not.toHaveBeenCalled(); }); }); describe('sanitizeLogMessage', () => { - it('strips ANSI CSI/OSC sequences and control chars, keeps tabs', async () => { - const { sanitizeLogMessage } = await import('./logs.js'); - expect(sanitizeLogMessage('\u001b[31mred\u001b[0m ok')).toBe('red ok'); - expect(sanitizeLogMessage('\u001b]0;evil title\u0007text')).toBe('text'); - expect(sanitizeLogMessage('a\u0008b\rc')).toBe('abc'); + it('strips ANSI CSI/OSC sequences and control chars, keeps tabs', () => { + expect(sanitizeLogMessage(`${ESC}[31mred${ESC}[0m ok`)).toBe('red ok'); + expect(sanitizeLogMessage(`${ESC}]0;evil title${BEL}text`)).toBe('text'); + expect(sanitizeLogMessage('a\rb\nc')).toBe('abc'); expect(sanitizeLogMessage('keep\ttabs')).toBe('keep\ttabs'); }); + + it('strips 8-bit C1 controls (CSI/OSC without ESC)', () => { + expect(sanitizeLogMessage(`x${CSI_C1}31my`)).toBe('x31my'); + expect(sanitizeLogMessage(String.fromCharCode(0x90) + 'dcs')).toBe('dcs'); + }); +}); + +describe('parseLimit', () => { + it('clamps into 1-1000 and defaults malformed input', () => { + expect(parseLimit('0')).toBe(1); + expect(parseLimit('5000')).toBe(1000); + expect(parseLimit('abc')).toBe(100); + expect(parseLimit(undefined)).toBe(100); + expect(parseLimit('250')).toBe(250); + }); }); diff --git a/src/commands/compute/logs.ts b/src/commands/compute/logs.ts index b2e32fcf..a76647ff 100644 --- a/src/commands/compute/logs.ts +++ b/src/commands/compute/logs.ts @@ -3,7 +3,7 @@ import { ossFetch } from '../../lib/api/oss.js'; import { requireAuth } from '../../lib/credentials.js'; import { handleError, getRootOpts } from '../../lib/errors.js'; import { outputJson } from '../../lib/output.js'; -import { reportCliUsage } from '../../lib/skills.js'; +import { trackCommandUsage } from '../../lib/command-telemetry.js'; // `compute logs ` returns container stdout/stderr ("application logs") — // the same data the dashboard Logs panel shows. For machine lifecycle events @@ -28,23 +28,33 @@ export interface ComputeLogsResult { } const FOLLOW_INTERVAL_MS = 2000; +const DEFAULT_LIMIT = 100; // Container output is attacker-adjacent data: a compromised (or just chatty) // app can emit ANSI/OSC escape sequences that reprogram the reader's -// terminal. Strip ESC-led sequences and all C0 controls except tab before -// printing. JSON mode is safe as-is — JSON.stringify escapes controls. +// terminal. Strip ESC-led sequences, C0 controls except tab, and 8-bit C1 +// controls (which encode CSI/OSC without ESC). Applied at the fetch boundary +// so every output mode — including --json, where JSON.stringify leaves C1 +// bytes raw — is covered. // eslint-disable-next-line no-control-regex -const TERMINAL_CONTROLS = /\u001b\[[0-9;?]*[ -/]*[@-~]|\u001b\][^\u0007\u001b]*(?:\u0007|\u001b\\)|\u001b[@-_]|[\u0000-\u0008\u000a-\u001f\u007f]/g; +const TERMINAL_CONTROLS = /\u001b\[[0-9;?]*[ -/]*[@-~]|\u001b\][^\u0007\u001b]*(?:\u0007|\u001b\\)|\u001b[@-_]|[\u0000-\u0008\u000a-\u001f\u007f\u0080-\u009f]/g; export function sanitizeLogMessage(message: string): string { return message.replace(TERMINAL_CONTROLS, ''); } +// Exact 1-1000 contract: malformed input falls back to the default (same as +// omitting the flag); finite values clamp into range, so `--limit 0` -> 1. +export function parseLimit(raw: unknown): number { + const n = Number(raw); + if (!Number.isFinite(n)) return DEFAULT_LIMIT; + return Math.max(1, Math.min(Math.trunc(n), 1000)); +} + export function formatLogLine(line: ComputeLogLine): string { const ts = new Date(line.timestamp).toISOString(); const where = [line.region, line.instance].filter(Boolean).join(' '); - const msg = sanitizeLogMessage(line.message); - return where ? `${ts} [${where}] ${msg}` : `${ts} ${msg}`; + return where ? `${ts} [${where}] ${line.message}` : `${ts} ${line.message}`; } export async function fetchComputeLogs( @@ -57,8 +67,12 @@ export async function fetchComputeLogs( `/api/compute/services/${encodeURIComponent(id)}/logs?${params.toString()}`, ); const body = await res.json() as Partial | null; + const lines = (Array.isArray(body?.lines) ? body.lines : []).map((l) => ({ + ...l, + message: sanitizeLogMessage(String(l.message ?? '')), + })); return { - lines: Array.isArray(body?.lines) ? body.lines : [], + lines, nextToken: typeof body?.nextToken === 'string' && body.nextToken.length > 0 ? body.nextToken : null, }; } @@ -67,7 +81,7 @@ export function registerComputeLogsCommand(computeCmd: Command): void { computeCmd .command('logs ') .description('Get compute service container logs (stdout/stderr)') - .option('--limit ', 'Max number of log lines per fetch (1-1000)', '100') + .option('--limit ', 'Max number of log lines per fetch (1-1000)', String(DEFAULT_LIMIT)) .option('-f, --follow', 'Keep polling for new lines (Ctrl+C to stop). With --json, emits NDJSON: one log-line object per line') .option('--next-token ', 'Resume from a cursor returned by a previous --json call') .action(async (id: string, opts, cmd) => { @@ -75,12 +89,16 @@ export function registerComputeLogsCommand(computeCmd: Command): void { try { await requireAuth(); - const limit = Math.max(1, Math.min(Number(opts.limit) || 100, 1000)); + const limit = parseLimit(opts.limit); let result = await fetchComputeLogs(id, { limit, nextToken: opts.nextToken }); + await trackCommandUsage('compute', 'logs', true, { + result_count: result.lines.length, + follow: Boolean(opts.follow), + }); + if (json && !opts.follow) { outputJson(result); - await reportCliUsage('cli.compute.logs', true); return; } @@ -92,7 +110,6 @@ export function registerComputeLogsCommand(computeCmd: Command): void { if (result.lines.length === 0 && !opts.follow) { console.log('No logs found.'); - await reportCliUsage('cli.compute.logs', true); return; } print(result.lines); @@ -100,17 +117,24 @@ export function registerComputeLogsCommand(computeCmd: Command): void { if (opts.follow) { if (!json) console.error('Following logs... (Ctrl+C to stop)'); let token = result.nextToken; - while (true) { + // When the provider stops returning a cursor, each poll re-fetches + // the recent window; drop lines at or before the newest timestamp + // already printed so they don't repeat. Cursor-based pages don't + // overlap, so no filter is applied while a token advances. + let lastTs = result.lines.length > 0 ? result.lines[result.lines.length - 1].timestamp : 0; + for (;;) { await new Promise((r) => setTimeout(r, FOLLOW_INTERVAL_MS)); - result = await fetchComputeLogs(id, { limit, nextToken: token ?? undefined }); - print(result.lines); - if (result.nextToken) token = result.nextToken; + const page = await fetchComputeLogs(id, { limit, nextToken: token ?? undefined }); + const fresh = token ? page.lines : page.lines.filter((l) => l.timestamp > lastTs); + print(fresh); + if (fresh.length > 0) { + lastTs = Math.max(lastTs, fresh[fresh.length - 1].timestamp); + } + if (page.nextToken) token = page.nextToken; } } - - await reportCliUsage('cli.compute.logs', true); } catch (err) { - await reportCliUsage('cli.compute.logs', false); + await trackCommandUsage('compute', 'logs', false, {}, err); handleError(err, json); } }); From ae71eba03cf54c59bd47b06f82e198a0514d2389 Mon Sep 17 00:00:00 2001 From: yaowenc2 Date: Thu, 27 Aug 2026 14:22:53 -0700 Subject: [PATCH 04/19] =?UTF-8?q?chore(compute-logs):=20lint=20=E2=80=94?= =?UTF-8?q?=20const=20result,=20drop=20unused=20test=20import?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Co-Authored-By: Claude Fable 5 --- src/commands/compute/logs.test.ts | 2 +- src/commands/compute/logs.ts | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/src/commands/compute/logs.test.ts b/src/commands/compute/logs.test.ts index 27dd25ce..e4866850 100644 --- a/src/commands/compute/logs.test.ts +++ b/src/commands/compute/logs.test.ts @@ -16,7 +16,7 @@ vi.mock('../../lib/errors.js', async (importOriginal) => { }); import { Command } from 'commander'; -import { registerComputeLogsCommand, formatLogLine, sanitizeLogMessage, parseLimit } from './logs.js'; +import { registerComputeLogsCommand, sanitizeLogMessage, parseLimit } from './logs.js'; const ESC = String.fromCharCode(0x1b); const BEL = String.fromCharCode(0x07); diff --git a/src/commands/compute/logs.ts b/src/commands/compute/logs.ts index a76647ff..84d89850 100644 --- a/src/commands/compute/logs.ts +++ b/src/commands/compute/logs.ts @@ -90,7 +90,7 @@ export function registerComputeLogsCommand(computeCmd: Command): void { await requireAuth(); const limit = parseLimit(opts.limit); - let result = await fetchComputeLogs(id, { limit, nextToken: opts.nextToken }); + const result = await fetchComputeLogs(id, { limit, nextToken: opts.nextToken }); await trackCommandUsage('compute', 'logs', true, { result_count: result.lines.length, From db8695649ec120b334c0bf2a62ef59720f821e34 Mon Sep 17 00:00:00 2001 From: yaowenc2 Date: Thu, 27 Aug 2026 14:23:25 -0700 Subject: [PATCH 05/19] chore(compute-logs): type test callbacks for tsc Co-Authored-By: Claude Fable 5 --- src/commands/compute/logs.test.ts | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/src/commands/compute/logs.test.ts b/src/commands/compute/logs.test.ts index e4866850..5893dc0f 100644 --- a/src/commands/compute/logs.test.ts +++ b/src/commands/compute/logs.test.ts @@ -107,9 +107,9 @@ describe('compute logs', () => { await vi.advanceTimersByTimeAsync(0); await vi.advanceTimersByTimeAsync(2000); expect(ossFetchMock.mock.calls[1][0]).toBe('/api/compute/services/svc/logs?limit=100'); - const printed = logSpy.mock.calls.map((c) => String(c[0])); - expect(printed.filter((l) => l.includes('seen'))).toHaveLength(1); - expect(printed.some((l) => l.includes('fresh'))).toBe(true); + const printed = logSpy.mock.calls.map((c: unknown[]) => String(c[0])); + expect(printed.filter((l: string) => l.includes('seen'))).toHaveLength(1); + expect(printed.some((l: string) => l.includes('fresh'))).toBe(true); }); it('--json --follow emits NDJSON per line', async () => { From 5e2168d2330514830c47ecb06ef8e63eb84d6ebf Mon Sep 17 00:00:00 2001 From: yaowenc2 Date: Thu, 27 Aug 2026 14:27:23 -0700 Subject: [PATCH 06/19] fix(compute-logs): follow-loop retry, readable multi-line messages, integration test r2d2 round (reviewed at 51e7e36; remaining items): - --follow now retries transient poll failures (429/5xx/network via isTransientApiError) with capped exponential backoff, up to 5 consecutive; non-transient errors still fail fast - sanitizer collapses C0 control runs to a single space so stack traces delivered as one entry stay readable; escape sequences and C1 introducers still vanish outright - compute logs --json integration test alongside compute events Co-Authored-By: Claude Fable 5 --- src/commands/compute/logs.test.ts | 17 +++++++++++++- src/commands/compute/logs.ts | 39 ++++++++++++++++++++++++------- src/integration/compute.test.ts | 13 +++++++++++ 3 files changed, 60 insertions(+), 9 deletions(-) diff --git a/src/commands/compute/logs.test.ts b/src/commands/compute/logs.test.ts index 5893dc0f..ae5ac9dd 100644 --- a/src/commands/compute/logs.test.ts +++ b/src/commands/compute/logs.test.ts @@ -1,5 +1,6 @@ import { describe, expect, it, vi, beforeEach, afterEach } from 'vitest'; import type * as ErrorsModule from '../../lib/errors.js'; +import { CLIError } from '../../lib/errors.js'; const ossFetchMock = vi.hoisted(() => vi.fn()); const outputJsonMock = vi.hoisted(() => vi.fn()); @@ -112,6 +113,20 @@ describe('compute logs', () => { expect(printed.some((l: string) => l.includes('fresh'))).toBe(true); }); + it('--follow retries transient poll failures and keeps tailing', async () => { + vi.useFakeTimers(); + ossFetchMock.mockResolvedValueOnce(page([{ timestamp: 1, message: 'one' }], 'tokA')); + ossFetchMock.mockRejectedValueOnce(new CLIError('rate limited', 1, 'RATE_LIMITED', 429)); + ossFetchMock.mockResolvedValueOnce(page([{ timestamp: 2, message: 'two' }], 'tokB')); + ossFetchMock.mockResolvedValue(page([])); + void run(['compute', 'logs', 'svc', '--follow']); + await vi.advanceTimersByTimeAsync(0); + await vi.advanceTimersByTimeAsync(2000); // poll 1 -> 429 + await vi.advanceTimersByTimeAsync(4000); // backoff + await vi.advanceTimersByTimeAsync(2000); // poll 2 -> succeeds + expect(logSpy).toHaveBeenCalledWith('1970-01-01T00:00:00.002Z two'); + }); + it('--json --follow emits NDJSON per line', async () => { vi.useFakeTimers(); ossFetchMock.mockResolvedValueOnce(page([{ timestamp: 1, message: 'a' }], 'tok')); @@ -127,7 +142,7 @@ describe('sanitizeLogMessage', () => { it('strips ANSI CSI/OSC sequences and control chars, keeps tabs', () => { expect(sanitizeLogMessage(`${ESC}[31mred${ESC}[0m ok`)).toBe('red ok'); expect(sanitizeLogMessage(`${ESC}]0;evil title${BEL}text`)).toBe('text'); - expect(sanitizeLogMessage('a\rb\nc')).toBe('abc'); + expect(sanitizeLogMessage('a\rb\nc')).toBe('a b c'); expect(sanitizeLogMessage('keep\ttabs')).toBe('keep\ttabs'); }); diff --git a/src/commands/compute/logs.ts b/src/commands/compute/logs.ts index 84d89850..9be1fdae 100644 --- a/src/commands/compute/logs.ts +++ b/src/commands/compute/logs.ts @@ -1,7 +1,7 @@ import type { Command } from 'commander'; import { ossFetch } from '../../lib/api/oss.js'; import { requireAuth } from '../../lib/credentials.js'; -import { handleError, getRootOpts } from '../../lib/errors.js'; +import { handleError, getRootOpts, isTransientApiError } from '../../lib/errors.js'; import { outputJson } from '../../lib/output.js'; import { trackCommandUsage } from '../../lib/command-telemetry.js'; @@ -29,18 +29,29 @@ export interface ComputeLogsResult { const FOLLOW_INTERVAL_MS = 2000; const DEFAULT_LIMIT = 100; +// A long-running tail will meet a 429 (the logs limiter is shared per-IP) or +// a passing 5xx; retry those with backoff and only give up after a run of +// consecutive failures. Non-transient errors (401/403/404) still fail fast. +const MAX_CONSECUTIVE_POLL_FAILURES = 5; // Container output is attacker-adjacent data: a compromised (or just chatty) // app can emit ANSI/OSC escape sequences that reprogram the reader's -// terminal. Strip ESC-led sequences, C0 controls except tab, and 8-bit C1 -// controls (which encode CSI/OSC without ESC). Applied at the fetch boundary -// so every output mode — including --json, where JSON.stringify leaves C1 -// bytes raw — is covered. +// terminal. Strip ESC-led sequences (a trailing bare-ESC arm defangs any +// form the specific arms miss) and 8-bit C1 controls (which encode CSI/OSC +// without ESC); collapse remaining C0 controls except tab to a space. +// Applied at the fetch boundary so every output mode — including --json, +// where JSON.stringify leaves C1 bytes raw — is covered. // eslint-disable-next-line no-control-regex -const TERMINAL_CONTROLS = /\u001b\[[0-9;?]*[ -/]*[@-~]|\u001b\][^\u0007\u001b]*(?:\u0007|\u001b\\)|\u001b[@-_]|[\u0000-\u0008\u000a-\u001f\u007f\u0080-\u009f]/g; +const TERMINAL_SEQUENCES = /\u001b\[[0-9;?]*[ -/]*[@-~]|\u001b\][^\u0007\u001b]*(?:\u0007|\u001b\\)|\u001b[@-_]|[\u0080-\u009f]|\u001b/g; +// eslint-disable-next-line no-control-regex +const CONTROL_RUNS = /[\u0000-\u0008\u000a-\u001f\u007f]+/g; export function sanitizeLogMessage(message: string): string { - return message.replace(TERMINAL_CONTROLS, ''); + // Sequences (and their C1 single-byte introducers) vanish outright; runs of + // remaining C0 controls become one space so a multi-line message (a stack + // trace delivered as a single entry) stays readable instead of gluing + // "line1line2" together. + return message.replace(TERMINAL_SEQUENCES, '').replace(CONTROL_RUNS, ' '); } // Exact 1-1000 contract: malformed input falls back to the default (same as @@ -122,9 +133,21 @@ export function registerComputeLogsCommand(computeCmd: Command): void { // already printed so they don't repeat. Cursor-based pages don't // overlap, so no filter is applied while a token advances. let lastTs = result.lines.length > 0 ? result.lines[result.lines.length - 1].timestamp : 0; + let pollFailures = 0; for (;;) { await new Promise((r) => setTimeout(r, FOLLOW_INTERVAL_MS)); - const page = await fetchComputeLogs(id, { limit, nextToken: token ?? undefined }); + let page: ComputeLogsResult; + try { + page = await fetchComputeLogs(id, { limit, nextToken: token ?? undefined }); + pollFailures = 0; + } catch (pollErr) { + pollFailures += 1; + if (!isTransientApiError(pollErr) || pollFailures >= MAX_CONSECUTIVE_POLL_FAILURES) { + throw pollErr; + } + await new Promise((r) => setTimeout(r, Math.min(FOLLOW_INTERVAL_MS * 2 ** pollFailures, 30_000))); + continue; + } const fresh = token ? page.lines : page.lines.filter((l) => l.timestamp > lastTs); print(fresh); if (fresh.length > 0) { diff --git a/src/integration/compute.test.ts b/src/integration/compute.test.ts index ad8de59b..291fdd55 100644 --- a/src/integration/compute.test.ts +++ b/src/integration/compute.test.ts @@ -97,6 +97,19 @@ describe.skipIf(!integrationEnabled)('CLI Compute Services Integration', () => { expect(Array.isArray(payload)).toBe(true); }); + it('compute logs --json should return lines and cursor', async () => { + expect(createdServiceId).toBeDefined(); + + const result = await runCli(['--json', 'compute', 'logs', createdServiceId!, '--limit', '5'], { apiUrl }); + expectCliSuccess(result); + + const payload = parseJsonOutput(result.stdout) as Record; + expectNoErrorPayload(payload); + + expect(Array.isArray(payload.lines)).toBe(true); + expect('nextToken' in payload).toBe(true); + }); + it('compute stop --json should stop the service', async () => { expect(createdServiceId).toBeDefined(); From 7d29de0d792f644fd4a5317c1def3991ab1d0927 Mon Sep 17 00:00:00 2001 From: yaowenc2 Date: Thu, 27 Aug 2026 14:28:47 -0700 Subject: [PATCH 07/19] fix(compute-logs): same-timestamp dedupe keys; sanitize region/instance John-bot round-3 suggestions: cursorless-follow dedupe now keys the lines sharing the boundary timestamp instead of dropping same-millisecond arrivals, and fetch normalization sanitizes every printable string field, not just message. Co-Authored-By: Claude Fable 5 --- src/commands/compute/logs.test.ts | 2 ++ src/commands/compute/logs.ts | 36 +++++++++++++++++++++++++------ 2 files changed, 31 insertions(+), 7 deletions(-) diff --git a/src/commands/compute/logs.test.ts b/src/commands/compute/logs.test.ts index ae5ac9dd..646d80ac 100644 --- a/src/commands/compute/logs.test.ts +++ b/src/commands/compute/logs.test.ts @@ -101,6 +101,7 @@ describe('compute logs', () => { ossFetchMock.mockResolvedValueOnce(page([{ timestamp: 5, message: 'seen' }], null)); ossFetchMock.mockResolvedValueOnce(page([ { timestamp: 5, message: 'seen' }, + { timestamp: 5, message: 'sibling' }, { timestamp: 9, message: 'fresh' }, ], null)); ossFetchMock.mockResolvedValue(page([])); @@ -110,6 +111,7 @@ describe('compute logs', () => { expect(ossFetchMock.mock.calls[1][0]).toBe('/api/compute/services/svc/logs?limit=100'); const printed = logSpy.mock.calls.map((c: unknown[]) => String(c[0])); expect(printed.filter((l: string) => l.includes('seen'))).toHaveLength(1); + expect(printed.filter((l: string) => l.includes('sibling'))).toHaveLength(1); expect(printed.some((l: string) => l.includes('fresh'))).toBe(true); }); diff --git a/src/commands/compute/logs.ts b/src/commands/compute/logs.ts index 9be1fdae..8437496b 100644 --- a/src/commands/compute/logs.ts +++ b/src/commands/compute/logs.ts @@ -78,9 +78,14 @@ export async function fetchComputeLogs( `/api/compute/services/${encodeURIComponent(id)}/logs?${params.toString()}`, ); const body = await res.json() as Partial | null; - const lines = (Array.isArray(body?.lines) ? body.lines : []).map((l) => ({ - ...l, + // Normalize to the documented shape and sanitize every printable string + // field — region/instance come from the provider API rather than container + // output, but they end up on the same terminal line. + const lines = (Array.isArray(body?.lines) ? body.lines : []).map((l): ComputeLogLine => ({ + timestamp: l.timestamp, message: sanitizeLogMessage(String(l.message ?? '')), + ...(l.instance !== undefined ? { instance: sanitizeLogMessage(String(l.instance)) } : {}), + ...(l.region !== undefined ? { region: sanitizeLogMessage(String(l.region)) } : {}), })); return { lines, @@ -129,10 +134,16 @@ export function registerComputeLogsCommand(computeCmd: Command): void { if (!json) console.error('Following logs... (Ctrl+C to stop)'); let token = result.nextToken; // When the provider stops returning a cursor, each poll re-fetches - // the recent window; drop lines at or before the newest timestamp - // already printed so they don't repeat. Cursor-based pages don't - // overlap, so no filter is applied while a token advances. + // the recent window; drop lines already printed so they don't + // repeat. Timestamps are the boundary, with a key set for the lines + // sharing the newest timestamp so same-millisecond arrivals aren't + // silently dropped. Cursor-based pages don't overlap, so no filter + // is applied while a token advances. + const lineKey = (l: ComputeLogLine) => `${l.instance ?? ''}|${l.message}`; let lastTs = result.lines.length > 0 ? result.lines[result.lines.length - 1].timestamp : 0; + const lastTsKeys = new Set( + result.lines.filter((l) => l.timestamp === lastTs).map(lineKey), + ); let pollFailures = 0; for (;;) { await new Promise((r) => setTimeout(r, FOLLOW_INTERVAL_MS)); @@ -148,10 +159,21 @@ export function registerComputeLogsCommand(computeCmd: Command): void { await new Promise((r) => setTimeout(r, Math.min(FOLLOW_INTERVAL_MS * 2 ** pollFailures, 30_000))); continue; } - const fresh = token ? page.lines : page.lines.filter((l) => l.timestamp > lastTs); + const fresh = token + ? page.lines + : page.lines.filter( + (l) => l.timestamp > lastTs || (l.timestamp === lastTs && !lastTsKeys.has(lineKey(l))), + ); print(fresh); if (fresh.length > 0) { - lastTs = Math.max(lastTs, fresh[fresh.length - 1].timestamp); + const newTs = fresh[fresh.length - 1].timestamp; + if (newTs !== lastTs) { + lastTs = newTs; + lastTsKeys.clear(); + } + for (const l of fresh) { + if (l.timestamp === lastTs) lastTsKeys.add(lineKey(l)); + } } if (page.nextToken) token = page.nextToken; } From 01f4759b00db3989ee06a7d2fed166d593660ef2 Mon Sep 17 00:00:00 2001 From: yaowenc2 Date: Thu, 27 Aug 2026 14:33:17 -0700 Subject: [PATCH 08/19] fix(compute-logs): clear stale follow cursor when the server stops returning one Review Critical: `if (page.nextToken) token = page.nextToken` kept a stale cursor across a null-cursor response, so the loop kept re-fetching from an abandoned cursor and the no-cursor dedupe never engaged. Assign the cursor as reported, including null; regression test covers the cursor-to-no-cursor transition (stale token not reused, no duplicate lines). Co-Authored-By: Claude Fable 5 --- src/commands/compute/logs.test.ts | 20 ++++++++++++++++++++ src/commands/compute/logs.ts | 6 +++++- 2 files changed, 25 insertions(+), 1 deletion(-) diff --git a/src/commands/compute/logs.test.ts b/src/commands/compute/logs.test.ts index 646d80ac..d115fb3c 100644 --- a/src/commands/compute/logs.test.ts +++ b/src/commands/compute/logs.test.ts @@ -115,6 +115,26 @@ describe('compute logs', () => { expect(printed.some((l: string) => l.includes('fresh'))).toBe(true); }); + it('--follow clears a stale cursor when the server stops returning one', async () => { + vi.useFakeTimers(); + ossFetchMock.mockResolvedValueOnce(page([{ timestamp: 1, message: 'one' }], 'tokA')); + ossFetchMock.mockResolvedValueOnce(page([{ timestamp: 2, message: 'two' }], null)); + ossFetchMock.mockResolvedValueOnce(page([ + { timestamp: 2, message: 'two' }, + { timestamp: 3, message: 'three' }, + ], null)); + ossFetchMock.mockResolvedValue(page([])); + void run(['compute', 'logs', 'svc', '--follow']); + await vi.advanceTimersByTimeAsync(0); + await vi.advanceTimersByTimeAsync(2000); // poll 1: uses tokA, returns null cursor + await vi.advanceTimersByTimeAsync(2000); // poll 2: must NOT reuse tokA + expect(ossFetchMock.mock.calls[1][0]).toBe('/api/compute/services/svc/logs?limit=100&next_token=tokA'); + expect(ossFetchMock.mock.calls[2][0]).toBe('/api/compute/services/svc/logs?limit=100'); + const printed = logSpy.mock.calls.map((c: unknown[]) => String(c[0])); + expect(printed.filter((l: string) => l.includes('two'))).toHaveLength(1); + expect(printed.some((l: string) => l.includes('three'))).toBe(true); + }); + it('--follow retries transient poll failures and keeps tailing', async () => { vi.useFakeTimers(); ossFetchMock.mockResolvedValueOnce(page([{ timestamp: 1, message: 'one' }], 'tokA')); diff --git a/src/commands/compute/logs.ts b/src/commands/compute/logs.ts index 8437496b..b800994c 100644 --- a/src/commands/compute/logs.ts +++ b/src/commands/compute/logs.ts @@ -175,7 +175,11 @@ export function registerComputeLogsCommand(computeCmd: Command): void { if (l.timestamp === lastTs) lastTsKeys.add(lineKey(l)); } } - if (page.nextToken) token = page.nextToken; + // Take the cursor as the server reports it, including null: a + // stale token must not survive the transition, or the loop keeps + // re-fetching from a cursor the provider has abandoned and the + // no-cursor dedupe above never engages. + token = page.nextToken; } } } catch (err) { From 6b0dcea7ae983c4dc99467ff70af44fcffe1f08f Mon Sep 17 00:00:00 2001 From: yaowenc2 Date: Thu, 27 Aug 2026 14:35:07 -0700 Subject: [PATCH 09/19] =?UTF-8?q?fix(compute-logs):=20dedupe=20every=20fol?= =?UTF-8?q?low=20poll=20=E2=80=94=20frozen=20cursor=20can't=20reprint=20it?= =?UTF-8?q?s=20batch?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Closes the other half of r2d2's follow-correctness pair: a server handing back the same cursor with the same lines would reprint them every poll, since cursor-mode pages skipped the dedupe filter. The timestamp+key boundary now applies to every poll; advancing pages carry strictly newer timestamps and pass through untouched. Co-Authored-By: Claude Fable 5 --- src/commands/compute/logs.test.ts | 18 ++++++++++++++++++ src/commands/compute/logs.ts | 22 +++++++++++----------- 2 files changed, 29 insertions(+), 11 deletions(-) diff --git a/src/commands/compute/logs.test.ts b/src/commands/compute/logs.test.ts index d115fb3c..1f789246 100644 --- a/src/commands/compute/logs.test.ts +++ b/src/commands/compute/logs.test.ts @@ -115,6 +115,24 @@ describe('compute logs', () => { expect(printed.some((l: string) => l.includes('fresh'))).toBe(true); }); + it('--follow does not reprint a frozen cursor batch', async () => { + vi.useFakeTimers(); + ossFetchMock.mockResolvedValueOnce(page([{ timestamp: 1, message: 'one' }], 'tokA')); + ossFetchMock.mockResolvedValueOnce(page([{ timestamp: 1, message: 'one' }], 'tokA')); + ossFetchMock.mockResolvedValueOnce(page([ + { timestamp: 1, message: 'one' }, + { timestamp: 2, message: 'two' }, + ], 'tokA')); + ossFetchMock.mockResolvedValue(page([])); + void run(['compute', 'logs', 'svc', '--follow']); + await vi.advanceTimersByTimeAsync(0); + await vi.advanceTimersByTimeAsync(2000); + await vi.advanceTimersByTimeAsync(2000); + const printed = logSpy.mock.calls.map((c: unknown[]) => String(c[0])); + expect(printed.filter((l: string) => l.includes('one'))).toHaveLength(1); + expect(printed.filter((l: string) => l.includes('two'))).toHaveLength(1); + }); + it('--follow clears a stale cursor when the server stops returning one', async () => { vi.useFakeTimers(); ossFetchMock.mockResolvedValueOnce(page([{ timestamp: 1, message: 'one' }], 'tokA')); diff --git a/src/commands/compute/logs.ts b/src/commands/compute/logs.ts index b800994c..f15337fa 100644 --- a/src/commands/compute/logs.ts +++ b/src/commands/compute/logs.ts @@ -133,12 +133,14 @@ export function registerComputeLogsCommand(computeCmd: Command): void { if (opts.follow) { if (!json) console.error('Following logs... (Ctrl+C to stop)'); let token = result.nextToken; - // When the provider stops returning a cursor, each poll re-fetches - // the recent window; drop lines already printed so they don't - // repeat. Timestamps are the boundary, with a key set for the lines - // sharing the newest timestamp so same-millisecond arrivals aren't - // silently dropped. Cursor-based pages don't overlap, so no filter - // is applied while a token advances. + // Dedupe every poll against what was already printed: a cursorless + // poll re-fetches the recent window, and a frozen cursor (the + // server handing back the same token with the same lines) would + // otherwise repeat its batch forever. Timestamps are the boundary, + // with a key set for the lines sharing the newest timestamp so + // same-millisecond arrivals aren't silently dropped; ordinary + // advancing pages carry strictly newer timestamps and pass through + // untouched. const lineKey = (l: ComputeLogLine) => `${l.instance ?? ''}|${l.message}`; let lastTs = result.lines.length > 0 ? result.lines[result.lines.length - 1].timestamp : 0; const lastTsKeys = new Set( @@ -159,11 +161,9 @@ export function registerComputeLogsCommand(computeCmd: Command): void { await new Promise((r) => setTimeout(r, Math.min(FOLLOW_INTERVAL_MS * 2 ** pollFailures, 30_000))); continue; } - const fresh = token - ? page.lines - : page.lines.filter( - (l) => l.timestamp > lastTs || (l.timestamp === lastTs && !lastTsKeys.has(lineKey(l))), - ); + const fresh = page.lines.filter( + (l) => l.timestamp > lastTs || (l.timestamp === lastTs && !lastTsKeys.has(lineKey(l))), + ); print(fresh); if (fresh.length > 0) { const newTs = fresh[fresh.length - 1].timestamp; From 6bbdf43aaf0ddbde04af80006c6afbb440894bd6 Mon Sep 17 00:00:00 2001 From: yaowenc2 Date: Thu, 27 Aug 2026 14:42:04 -0700 Subject: [PATCH 10/19] fix(compute-logs): boundary dedupe by occurrence count, region in key John-bot suggestion: the key-set dedupe swallowed genuinely repeated identical lines at the boundary timestamp. Track per-key occurrence counts (region|instance|message) so only already-printed occurrences are suppressed; extras print. Co-Authored-By: Claude Fable 5 --- src/commands/compute/logs.test.ts | 19 +++++++++++++++ src/commands/compute/logs.ts | 39 ++++++++++++++++++++++++------- 2 files changed, 49 insertions(+), 9 deletions(-) diff --git a/src/commands/compute/logs.test.ts b/src/commands/compute/logs.test.ts index 1f789246..bea13176 100644 --- a/src/commands/compute/logs.test.ts +++ b/src/commands/compute/logs.test.ts @@ -153,6 +153,25 @@ describe('compute logs', () => { expect(printed.some((l: string) => l.includes('three'))).toBe(true); }); + it('--follow keeps genuinely repeated identical lines at the boundary timestamp', async () => { + vi.useFakeTimers(); + ossFetchMock.mockResolvedValueOnce(page([ + { timestamp: 5, message: 'dup' }, + { timestamp: 5, message: 'dup' }, + ], null)); + ossFetchMock.mockResolvedValueOnce(page([ + { timestamp: 5, message: 'dup' }, + { timestamp: 5, message: 'dup' }, + { timestamp: 5, message: 'dup' }, + ], null)); + ossFetchMock.mockResolvedValue(page([])); + void run(['compute', 'logs', 'svc', '--follow']); + await vi.advanceTimersByTimeAsync(0); + await vi.advanceTimersByTimeAsync(2000); + const printed = logSpy.mock.calls.map((c: unknown[]) => String(c[0])); + expect(printed.filter((l: string) => l.includes('dup'))).toHaveLength(3); + }); + it('--follow retries transient poll failures and keeps tailing', async () => { vi.useFakeTimers(); ossFetchMock.mockResolvedValueOnce(page([{ timestamp: 1, message: 'one' }], 'tokA')); diff --git a/src/commands/compute/logs.ts b/src/commands/compute/logs.ts index f15337fa..37a90d1d 100644 --- a/src/commands/compute/logs.ts +++ b/src/commands/compute/logs.ts @@ -141,11 +141,18 @@ export function registerComputeLogsCommand(computeCmd: Command): void { // same-millisecond arrivals aren't silently dropped; ordinary // advancing pages carry strictly newer timestamps and pass through // untouched. - const lineKey = (l: ComputeLogLine) => `${l.instance ?? ''}|${l.message}`; + const lineKey = (l: ComputeLogLine) => `${l.region ?? ''}|${l.instance ?? ''}|${l.message}`; let lastTs = result.lines.length > 0 ? result.lines[result.lines.length - 1].timestamp : 0; - const lastTsKeys = new Set( - result.lines.filter((l) => l.timestamp === lastTs).map(lineKey), - ); + // Occurrence COUNTS, not a set: identical messages repeated at the + // boundary timestamp are real lines — suppress only as many as were + // already printed. + const lastTsCounts = new Map(); + for (const l of result.lines) { + if (l.timestamp === lastTs) { + const k = lineKey(l); + lastTsCounts.set(k, (lastTsCounts.get(k) ?? 0) + 1); + } + } let pollFailures = 0; for (;;) { await new Promise((r) => setTimeout(r, FOLLOW_INTERVAL_MS)); @@ -161,18 +168,32 @@ export function registerComputeLogsCommand(computeCmd: Command): void { await new Promise((r) => setTimeout(r, Math.min(FOLLOW_INTERVAL_MS * 2 ** pollFailures, 30_000))); continue; } - const fresh = page.lines.filter( - (l) => l.timestamp > lastTs || (l.timestamp === lastTs && !lastTsKeys.has(lineKey(l))), - ); + const suppress = new Map(lastTsCounts); + const fresh: ComputeLogLine[] = []; + for (const l of page.lines) { + if (l.timestamp < lastTs) continue; + if (l.timestamp === lastTs) { + const k = lineKey(l); + const remaining = suppress.get(k) ?? 0; + if (remaining > 0) { + suppress.set(k, remaining - 1); + continue; + } + } + fresh.push(l); + } print(fresh); if (fresh.length > 0) { const newTs = fresh[fresh.length - 1].timestamp; if (newTs !== lastTs) { lastTs = newTs; - lastTsKeys.clear(); + lastTsCounts.clear(); } for (const l of fresh) { - if (l.timestamp === lastTs) lastTsKeys.add(lineKey(l)); + if (l.timestamp === lastTs) { + const k = lineKey(l); + lastTsCounts.set(k, (lastTsCounts.get(k) ?? 0) + 1); + } } } // Take the cursor as the server reports it, including null: a From 525a8b785b5983faa79519bb62641005e1af13f0 Mon Sep 17 00:00:00 2001 From: yaowenc2 Date: Thu, 27 Aug 2026 14:48:07 -0700 Subject: [PATCH 11/19] fix(compute-logs): only dedupe when the cursor did not advance My previous commit over-corrected: filtering every poll on a millisecond watermark converted duplicate output into SILENT DROPS whenever provider timestamps share a millisecond (docker cursors are nanosecond precision), arrive out of order, or map to 0. Silent loss in a log tail is worse than the duplicates it replaced. - Gate the dedupe on `cursorAdvanced`: an advancing cursor guarantees a non-overlapping page, so it prints verbatim. Frozen and null cursors still dedupe, preserving the two earlier cursor fixes. - formatLogLine tolerates a missing/NaN timestamp instead of throwing (in --follow that threw outside the poll try/catch, killing the tail) - Watermark is now max(timestamps), not the last element, so an unsorted page can't move it backwards - parseLimit('') falls back to the default rather than clamping to 1 - Tests pin BOTH directions of the predicate (advancing-cursor pass-through, older-line-behind-new-cursor) plus telemetry event stability; negative control verified: reverting the gate turns exactly the two new tests red Co-Authored-By: Claude Fable 5 --- src/commands/compute/logs.test.ts | 48 +++++++++++++++++++++++++++++-- src/commands/compute/logs.ts | 42 ++++++++++++++++++++------- 2 files changed, 77 insertions(+), 13 deletions(-) diff --git a/src/commands/compute/logs.test.ts b/src/commands/compute/logs.test.ts index bea13176..d29a6eaa 100644 --- a/src/commands/compute/logs.test.ts +++ b/src/commands/compute/logs.test.ts @@ -6,7 +6,8 @@ const ossFetchMock = vi.hoisted(() => vi.fn()); const outputJsonMock = vi.hoisted(() => vi.fn()); vi.mock('../../lib/api/oss.js', () => ({ ossFetch: ossFetchMock })); vi.mock('../../lib/credentials.js', () => ({ requireAuth: vi.fn().mockResolvedValue(undefined) })); -vi.mock('../../lib/command-telemetry.js', () => ({ trackCommandUsage: vi.fn() })); +const trackCommandUsageMock = vi.hoisted(() => vi.fn()); +vi.mock('../../lib/command-telemetry.js', () => ({ trackCommandUsage: trackCommandUsageMock })); vi.mock('../../lib/output.js', () => ({ outputJson: outputJsonMock })); vi.mock('../../lib/errors.js', async (importOriginal) => { const actual = await importOriginal(); @@ -17,7 +18,7 @@ vi.mock('../../lib/errors.js', async (importOriginal) => { }); import { Command } from 'commander'; -import { registerComputeLogsCommand, sanitizeLogMessage, parseLimit } from './logs.js'; +import { registerComputeLogsCommand, sanitizeLogMessage, parseLimit, formatLogLine } from './logs.js'; const ESC = String.fromCharCode(0x1b); const BEL = String.fromCharCode(0x07); @@ -42,6 +43,7 @@ describe('compute logs', () => { beforeEach(() => { ossFetchMock.mockReset(); outputJsonMock.mockReset(); + trackCommandUsageMock.mockReset(); logSpy = vi.spyOn(console, 'log').mockImplementation(() => {}); errSpy = vi.spyOn(console, 'error').mockImplementation(() => {}); }); @@ -172,6 +174,40 @@ describe('compute logs', () => { expect(printed.filter((l: string) => l.includes('dup'))).toHaveLength(3); }); + it('--follow prints an advancing-cursor page verbatim, even within one millisecond', async () => { + vi.useFakeTimers(); + // Docker cursors are nanosecond precision; both pages share a millisecond. + ossFetchMock.mockResolvedValueOnce(page([{ timestamp: 1000, message: 'tick' }], 'ns1')); + ossFetchMock.mockResolvedValueOnce(page([{ timestamp: 1000, message: 'tick' }], 'ns2')); + ossFetchMock.mockResolvedValue(page([])); + void run(['compute', 'logs', 'svc', '--follow']); + await vi.advanceTimersByTimeAsync(0); + await vi.advanceTimersByTimeAsync(2000); + const printed = logSpy.mock.calls.map((c: unknown[]) => String(c[0])); + expect(printed.filter((l: string) => l.includes('tick'))).toHaveLength(2); + }); + + it('--follow prints an older-timestamp line arriving behind a new cursor', async () => { + vi.useFakeTimers(); + ossFetchMock.mockResolvedValueOnce(page([{ timestamp: 5000, message: 'newer' }], 'ns1')); + ossFetchMock.mockResolvedValueOnce(page([{ timestamp: 0, message: 'unparseable-ts' }], 'ns2')); + ossFetchMock.mockResolvedValue(page([])); + void run(['compute', 'logs', 'svc', '--follow']); + await vi.advanceTimersByTimeAsync(0); + await vi.advanceTimersByTimeAsync(2000); + const printed = logSpy.mock.calls.map((c: unknown[]) => String(c[0])); + expect(printed.some((l: string) => l.includes('unparseable-ts'))).toBe(true); + }); + + it('emits stable telemetry for the command', async () => { + ossFetchMock.mockResolvedValueOnce(page([{ timestamp: 1, message: 'x' }], null)); + await run(['compute', 'logs', 'svc']); + expect(trackCommandUsageMock).toHaveBeenCalledWith('compute', 'logs', true, { + result_count: 1, + follow: false, + }); + }); + it('--follow retries transient poll failures and keeps tailing', async () => { vi.useFakeTimers(); ossFetchMock.mockResolvedValueOnce(page([{ timestamp: 1, message: 'one' }], 'tokA')); @@ -211,11 +247,19 @@ describe('sanitizeLogMessage', () => { }); }); +describe('formatLogLine', () => { + it('falls back to the raw value instead of throwing on a bad timestamp', () => { + expect(formatLogLine({ timestamp: Number.NaN, message: 'm' })).toContain('m'); + expect(() => formatLogLine({ timestamp: undefined as unknown as number, message: 'm' })).not.toThrow(); + }); +}); + describe('parseLimit', () => { it('clamps into 1-1000 and defaults malformed input', () => { expect(parseLimit('0')).toBe(1); expect(parseLimit('5000')).toBe(1000); expect(parseLimit('abc')).toBe(100); + expect(parseLimit('')).toBe(100); expect(parseLimit(undefined)).toBe(100); expect(parseLimit('250')).toBe(250); }); diff --git a/src/commands/compute/logs.ts b/src/commands/compute/logs.ts index 37a90d1d..441ad318 100644 --- a/src/commands/compute/logs.ts +++ b/src/commands/compute/logs.ts @@ -57,13 +57,18 @@ export function sanitizeLogMessage(message: string): string { // Exact 1-1000 contract: malformed input falls back to the default (same as // omitting the flag); finite values clamp into range, so `--limit 0` -> 1. export function parseLimit(raw: unknown): number { + if (raw === '' || raw === null || raw === undefined) return DEFAULT_LIMIT; const n = Number(raw); if (!Number.isFinite(n)) return DEFAULT_LIMIT; return Math.max(1, Math.min(Math.trunc(n), 1000)); } export function formatLogLine(line: ComputeLogLine): string { - const ts = new Date(line.timestamp).toISOString(); + // A missing/NaN timestamp would make toISOString throw, and in --follow + // that happens outside the poll try/catch, killing the tail. Fall back to + // the raw value the way the dashboard does. + const d = new Date(line.timestamp); + const ts = Number.isNaN(d.getTime()) ? String(line.timestamp) : d.toISOString(); const where = [line.region, line.instance].filter(Boolean).join(' '); return where ? `${ts} [${where}] ${line.message}` : `${ts} ${line.message}`; } @@ -133,16 +138,23 @@ export function registerComputeLogsCommand(computeCmd: Command): void { if (opts.follow) { if (!json) console.error('Following logs... (Ctrl+C to stop)'); let token = result.nextToken; - // Dedupe every poll against what was already printed: a cursorless - // poll re-fetches the recent window, and a frozen cursor (the - // server handing back the same token with the same lines) would - // otherwise repeat its batch forever. Timestamps are the boundary, - // with a key set for the lines sharing the newest timestamp so - // same-millisecond arrivals aren't silently dropped; ordinary - // advancing pages carry strictly newer timestamps and pass through - // untouched. + // Dedupe only when the cursor did NOT advance: a cursorless poll + // re-fetches the recent window, and a frozen cursor (the server + // handing back the token it was given) would otherwise repeat its + // batch forever. When the cursor advances the server guarantees a + // non-overlapping page, so it prints verbatim — filtering it on a + // millisecond watermark would silently drop lines whose provider + // timestamps share a millisecond (docker cursors are nanosecond + // precision) or arrive out of order. + // + // Within a re-sent window the watermark is the newest timestamp + // seen, plus per-key occurrence COUNTS for the lines sharing it, so + // genuinely repeated identical messages still print. const lineKey = (l: ComputeLogLine) => `${l.region ?? ''}|${l.instance ?? ''}|${l.message}`; - let lastTs = result.lines.length > 0 ? result.lines[result.lines.length - 1].timestamp : 0; + // Max, not last: a page arriving unsorted must not move the + // watermark backwards. + const maxTs = (lines: ComputeLogLine[]) => lines.reduce((m, l) => Math.max(m, l.timestamp), 0); + let lastTs = maxTs(result.lines); // Occurrence COUNTS, not a set: identical messages repeated at the // boundary timestamp are real lines — suppress only as many as were // already printed. @@ -168,9 +180,17 @@ export function registerComputeLogsCommand(computeCmd: Command): void { await new Promise((r) => setTimeout(r, Math.min(FOLLOW_INTERVAL_MS * 2 ** pollFailures, 30_000))); continue; } + // `token` still holds the cursor this request was made with, so a + // frozen token (nextToken === token) and a null token both keep + // the dedupe. + const cursorAdvanced = page.nextToken !== null && page.nextToken !== token; const suppress = new Map(lastTsCounts); const fresh: ComputeLogLine[] = []; for (const l of page.lines) { + if (cursorAdvanced) { + fresh.push(l); + continue; + } if (l.timestamp < lastTs) continue; if (l.timestamp === lastTs) { const k = lineKey(l); @@ -184,7 +204,7 @@ export function registerComputeLogsCommand(computeCmd: Command): void { } print(fresh); if (fresh.length > 0) { - const newTs = fresh[fresh.length - 1].timestamp; + const newTs = maxTs(fresh); if (newTs !== lastTs) { lastTs = newTs; lastTsCounts.clear(); From bd25fdea6d2a77d848389121fd4bbdc8572c5567 Mon Sep 17 00:00:00 2001 From: yaowenc2 Date: Thu, 27 Aug 2026 14:58:16 -0700 Subject: [PATCH 12/19] fix(compute-logs): don't block the tail on telemetry flush; handle undated lines MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Found by running the built CLI against a mock of the real endpoint — neither issue was reachable from the fake-timer unit tests: - trackCommandUsage ends by flushing and SHUTTING DOWN the PostHog client over the network. Awaiting it before the follow loop stalled the tail before its first poll: nothing printed, no second request. Emit it up front (a tail never reaches the end of the action) but only await it in the non-follow path. - A line whose timestamp is unusable (the Fly driver maps an unparseable one to 0/NaN) was silently dropped by the watermark filter. It can't be positioned, so a re-sent window now dedupes it against the previous page's occurrences instead — printed once, never repeated. Verified live over 5 polls: ANSI/8-bit-C1 escapes stripped, advancing cursor prints within the same millisecond, frozen cursor doesn't reprint, cursorless overlap deduped, undated line printed exactly once, and --json --follow emits one valid JSON object per line. Co-Authored-By: Claude Fable 5 --- src/commands/compute/logs.test.ts | 15 +++++++++++++ src/commands/compute/logs.ts | 36 ++++++++++++++++++++++++++++++- 2 files changed, 50 insertions(+), 1 deletion(-) diff --git a/src/commands/compute/logs.test.ts b/src/commands/compute/logs.test.ts index d29a6eaa..5e85e9cc 100644 --- a/src/commands/compute/logs.test.ts +++ b/src/commands/compute/logs.test.ts @@ -199,6 +199,21 @@ describe('compute logs', () => { expect(printed.some((l: string) => l.includes('unparseable-ts'))).toBe(true); }); + it('--follow prints a line with an unusable timestamp instead of dropping it', async () => { + vi.useFakeTimers(); + ossFetchMock.mockResolvedValueOnce(page([{ timestamp: 5000, message: 'newer' }], null)); + ossFetchMock.mockResolvedValueOnce(page([{ timestamp: null, message: 'no-ts' }], null)); + // Same window re-sent: the undated line must not repeat. + ossFetchMock.mockResolvedValue(page([{ timestamp: null, message: 'no-ts' }], null)); + void run(['compute', 'logs', 'svc', '--follow']); + await vi.advanceTimersByTimeAsync(0); + await vi.advanceTimersByTimeAsync(2000); + await vi.advanceTimersByTimeAsync(2000); + await vi.advanceTimersByTimeAsync(2000); + const printed = logSpy.mock.calls.map((c: unknown[]) => String(c[0])); + expect(printed.filter((l: string) => l.includes('no-ts'))).toHaveLength(1); + }); + it('emits stable telemetry for the command', async () => { ossFetchMock.mockResolvedValueOnce(page([{ timestamp: 1, message: 'x' }], null)); await run(['compute', 'logs', 'svc']); diff --git a/src/commands/compute/logs.ts b/src/commands/compute/logs.ts index 441ad318..cd2c096c 100644 --- a/src/commands/compute/logs.ts +++ b/src/commands/compute/logs.ts @@ -113,10 +113,17 @@ export function registerComputeLogsCommand(computeCmd: Command): void { const limit = parseLimit(opts.limit); const result = await fetchComputeLogs(id, { limit, nextToken: opts.nextToken }); - await trackCommandUsage('compute', 'logs', true, { + // Emitted before the tail starts, because a --follow run never + // reaches the end of the action. NOT awaited in follow mode: + // trackCommandUsage ends by flushing and shutting down the PostHog + // client over the network, which stalls the tail before its first + // poll (observed live: nothing printed and no second request while + // the flush retried). + const usage = trackCommandUsage('compute', 'logs', true, { result_count: result.lines.length, follow: Boolean(opts.follow), }); + if (!opts.follow) await usage; if (json && !opts.follow) { outputJson(result); @@ -165,6 +172,20 @@ export function registerComputeLogsCommand(computeCmd: Command): void { lastTsCounts.set(k, (lastTsCounts.get(k) ?? 0) + 1); } } + // Lines whose timestamp is unusable (the Fly driver maps an + // unparseable one to 0/NaN) can't be positioned against the + // watermark, so a re-sent window is deduped against the previous + // page's occurrences of the same line instead. + const undatedCounts = (lines: ComputeLogLine[]) => { + const m = new Map(); + for (const l of lines) { + if (Number.isFinite(l.timestamp)) continue; + const k = lineKey(l); + m.set(k, (m.get(k) ?? 0) + 1); + } + return m; + }; + let prevUndated = undatedCounts(result.lines); let pollFailures = 0; for (;;) { await new Promise((r) => setTimeout(r, FOLLOW_INTERVAL_MS)); @@ -185,12 +206,23 @@ export function registerComputeLogsCommand(computeCmd: Command): void { // the dedupe. const cursorAdvanced = page.nextToken !== null && page.nextToken !== token; const suppress = new Map(lastTsCounts); + const undatedSuppress = new Map(prevUndated); const fresh: ComputeLogLine[] = []; for (const l of page.lines) { if (cursorAdvanced) { fresh.push(l); continue; } + if (!Number.isFinite(l.timestamp)) { + const k = lineKey(l); + const seen = undatedSuppress.get(k) ?? 0; + if (seen > 0) { + undatedSuppress.set(k, seen - 1); + continue; + } + fresh.push(l); + continue; + } if (l.timestamp < lastTs) continue; if (l.timestamp === lastTs) { const k = lineKey(l); @@ -203,6 +235,8 @@ export function registerComputeLogsCommand(computeCmd: Command): void { fresh.push(l); } print(fresh); + // An advanced cursor means the next page can't overlap this one. + prevUndated = cursorAdvanced ? new Map() : undatedCounts(page.lines); if (fresh.length > 0) { const newTs = maxTs(fresh); if (newTs !== lastTs) { From cd3bb3298e9e673f024a1e1217760e4ba2669ff6 Mon Sep 17 00:00:00 2001 From: yaowenc2 Date: Thu, 27 Aug 2026 15:07:00 -0700 Subject: [PATCH 13/19] fix(compute-logs): guard the follow watermark against NaN, future, and backward moves MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Review suggestions 1-3 at bd25fde, plus a bug my own new test caught: - maxTs skips non-finite timestamps (one NaN poisoned the max, making every comparison false and reprinting the whole page) and implausibly future ones (a single year-2100 line would pin the watermark and silently drop every real line after it — same failure class as the Critical just fixed) - the watermark is now monotonic: a poll whose fresh lines are all undated yielded maxTs 0 and moved it BACKWARDS, reprinting everything above it on the next poll (caught by the new mixed-page test) - fetch-boundary contract tests: shape normalization, string sanitization, empty cursor -> null, malformed body timestamp is deliberately still not coerced to 0 at the boundary, and the code says why: an unusable timestamp must stay distinguishable from a genuine 0 so the follow loop prints it once instead of dropping it below the watermark. Co-Authored-By: Claude Fable 5 --- src/commands/compute/logs.test.ts | 52 +++++++++++++++++++++++++++++++ src/commands/compute/logs.ts | 26 ++++++++++++++-- 2 files changed, 75 insertions(+), 3 deletions(-) diff --git a/src/commands/compute/logs.test.ts b/src/commands/compute/logs.test.ts index 5e85e9cc..e60a6ec1 100644 --- a/src/commands/compute/logs.test.ts +++ b/src/commands/compute/logs.test.ts @@ -214,6 +214,35 @@ describe('compute logs', () => { expect(printed.filter((l: string) => l.includes('no-ts'))).toHaveLength(1); }); + it('--follow ignores an implausibly future timestamp when advancing the watermark', async () => { + vi.useFakeTimers(); + ossFetchMock.mockResolvedValueOnce(page([ + { timestamp: 1000, message: 'real' }, + { timestamp: 4102444800000, message: 'year-2100' }, + ], null)); + ossFetchMock.mockResolvedValue(page([{ timestamp: 2000, message: 'later-real' }], null)); + void run(['compute', 'logs', 'svc', '--follow']); + await vi.advanceTimersByTimeAsync(0); + await vi.advanceTimersByTimeAsync(2000); + const printed = logSpy.mock.calls.map((c: unknown[]) => String(c[0])); + expect(printed.some((l: string) => l.includes('later-real'))).toBe(true); + }); + + it('--follow does not reprint dated lines when a page also carries an undated one', async () => { + vi.useFakeTimers(); + ossFetchMock.mockResolvedValueOnce(page([{ timestamp: 1000, message: 'dated' }], null)); + ossFetchMock.mockResolvedValue(page([ + { timestamp: 1000, message: 'dated' }, + { timestamp: null, message: 'undated' }, + ], null)); + void run(['compute', 'logs', 'svc', '--follow']); + await vi.advanceTimersByTimeAsync(0); + await vi.advanceTimersByTimeAsync(2000); + await vi.advanceTimersByTimeAsync(2000); + const printed = logSpy.mock.calls.map((c: unknown[]) => String(c[0])); + expect(printed.filter((l: string) => l.includes('dated') && !l.includes('undated'))).toHaveLength(1); + }); + it('emits stable telemetry for the command', async () => { ossFetchMock.mockResolvedValueOnce(page([{ timestamp: 1, message: 'x' }], null)); await run(['compute', 'logs', 'svc']); @@ -248,6 +277,29 @@ describe('compute logs', () => { }); }); +describe('fetchComputeLogs boundary', () => { + it('normalizes the shape, sanitizes strings, and drops an empty cursor to null', async () => { + ossFetchMock.mockResolvedValueOnce({ + json: async () => ({ + lines: [{ timestamp: 7, message: `a${ESC}[31mb`, region: `s${ESC}[0mjc`, instance: 'i1', extra: 'dropped' }], + nextToken: '', + }), + }); + const { fetchComputeLogs } = await import('./logs.js'); + const out = await fetchComputeLogs('svc', { limit: 10 }); + expect(out).toEqual({ + lines: [{ timestamp: 7, message: 'ab', region: 'sjc', instance: 'i1' }], + nextToken: null, + }); + }); + + it('tolerates a malformed body', async () => { + ossFetchMock.mockResolvedValueOnce({ json: async () => null }); + const { fetchComputeLogs } = await import('./logs.js'); + expect(await fetchComputeLogs('svc', { limit: 10 })).toEqual({ lines: [], nextToken: null }); + }); +}); + describe('sanitizeLogMessage', () => { it('strips ANSI CSI/OSC sequences and control chars, keeps tabs', () => { expect(sanitizeLogMessage(`${ESC}[31mred${ESC}[0m ok`)).toBe('red ok'); diff --git a/src/commands/compute/logs.ts b/src/commands/compute/logs.ts index cd2c096c..3bedef2d 100644 --- a/src/commands/compute/logs.ts +++ b/src/commands/compute/logs.ts @@ -33,6 +33,9 @@ const DEFAULT_LIMIT = 100; // a passing 5xx; retry those with backoff and only give up after a run of // consecutive failures. Non-transient errors (401/403/404) still fail fast. const MAX_CONSECUTIVE_POLL_FAILURES = 5; +// Tolerance for provider/client clock disagreement when deciding whether a +// timestamp is plausible enough to advance the follow watermark. +const CLOCK_SKEW_MS = 5 * 60 * 1000; // Container output is attacker-adjacent data: a compromised (or just chatty) // app can emit ANSI/OSC escape sequences that reprogram the reader's @@ -86,6 +89,11 @@ export async function fetchComputeLogs( // Normalize to the documented shape and sanitize every printable string // field — region/instance come from the provider API rather than container // output, but they end up on the same terminal line. + // + // `timestamp` is deliberately NOT coerced to 0 the way the backend does: + // an unusable timestamp has to stay distinguishable from a genuine 0 so + // the follow loop prints it once instead of dropping it below the + // watermark. formatLogLine and maxTs both handle non-finite values. const lines = (Array.isArray(body?.lines) ? body.lines : []).map((l): ComputeLogLine => ({ timestamp: l.timestamp, message: sanitizeLogMessage(String(l.message ?? '')), @@ -159,8 +167,17 @@ export function registerComputeLogsCommand(computeCmd: Command): void { // genuinely repeated identical messages still print. const lineKey = (l: ComputeLogLine) => `${l.region ?? ''}|${l.instance ?? ''}|${l.message}`; // Max, not last: a page arriving unsorted must not move the - // watermark backwards. - const maxTs = (lines: ComputeLogLine[]) => lines.reduce((m, l) => Math.max(m, l.timestamp), 0); + // watermark backwards. Non-finite timestamps are skipped (they'd + // poison the max into NaN, which compares false against everything + // and reprints the whole page), and so are implausibly future ones + // — a single year-2100 line would otherwise pin the watermark and + // silently drop every real line after it. + const maxTs = (lines: ComputeLogLine[]) => lines.reduce( + (m, l) => (Number.isFinite(l.timestamp) && l.timestamp > m && l.timestamp <= Date.now() + CLOCK_SKEW_MS + ? l.timestamp + : m), + 0, + ); let lastTs = maxTs(result.lines); // Occurrence COUNTS, not a set: identical messages repeated at the // boundary timestamp are real lines — suppress only as many as were @@ -238,8 +255,11 @@ export function registerComputeLogsCommand(computeCmd: Command): void { // An advanced cursor means the next page can't overlap this one. prevUndated = cursorAdvanced ? new Map() : undatedCounts(page.lines); if (fresh.length > 0) { + // Monotonic: a page whose fresh lines are all undated yields + // maxTs 0, and letting the watermark retreat would reprint + // everything above it on the next poll. const newTs = maxTs(fresh); - if (newTs !== lastTs) { + if (newTs > lastTs) { lastTs = newTs; lastTsCounts.clear(); } From 2cb375d6b2eaf39733c610050f26494aee3baa03 Mon Sep 17 00:00:00 2001 From: yaowenc2 Date: Thu, 27 Aug 2026 15:15:29 -0700 Subject: [PATCH 14/19] fix(compute-logs): treat implausibly future timestamps as undated everywhere cubic P2 on cd3bb32: maxTs skipped a far-future timestamp but the dedupe still saw it as finite, so it matched neither the < nor the == branch and reprinted on every poll. One 'positionable' predicate now gates the watermark, the undated bookkeeping, and the filter, so such a line is printed once and never pins the watermark. Negative control: relaxing positionable back to Number.isFinite turns the new reprint test red. Co-Authored-By: Claude Fable 5 --- src/commands/compute/logs.test.ts | 17 +++++++++++++++++ src/commands/compute/logs.ts | 14 +++++++++----- 2 files changed, 26 insertions(+), 5 deletions(-) diff --git a/src/commands/compute/logs.test.ts b/src/commands/compute/logs.test.ts index e60a6ec1..4326e9c5 100644 --- a/src/commands/compute/logs.test.ts +++ b/src/commands/compute/logs.test.ts @@ -228,6 +228,23 @@ describe('compute logs', () => { expect(printed.some((l: string) => l.includes('later-real'))).toBe(true); }); + it('--follow does not reprint a future-dated line on every poll', async () => { + vi.useFakeTimers(); + const future = Date.now() + 60 * 60 * 1000; + ossFetchMock.mockResolvedValueOnce(page([{ timestamp: 1000, message: 'real' }], null)); + ossFetchMock.mockResolvedValue(page([ + { timestamp: 1000, message: 'real' }, + { timestamp: future, message: 'from-the-future' }, + ], null)); + void run(['compute', 'logs', 'svc', '--follow']); + await vi.advanceTimersByTimeAsync(0); + await vi.advanceTimersByTimeAsync(2000); + await vi.advanceTimersByTimeAsync(2000); + await vi.advanceTimersByTimeAsync(2000); + const printed = logSpy.mock.calls.map((c: unknown[]) => String(c[0])); + expect(printed.filter((l: string) => l.includes('from-the-future'))).toHaveLength(1); + }); + it('--follow does not reprint dated lines when a page also carries an undated one', async () => { vi.useFakeTimers(); ossFetchMock.mockResolvedValueOnce(page([{ timestamp: 1000, message: 'dated' }], null)); diff --git a/src/commands/compute/logs.ts b/src/commands/compute/logs.ts index 3bedef2d..2c832889 100644 --- a/src/commands/compute/logs.ts +++ b/src/commands/compute/logs.ts @@ -172,10 +172,14 @@ export function registerComputeLogsCommand(computeCmd: Command): void { // and reprints the whole page), and so are implausibly future ones // — a single year-2100 line would otherwise pin the watermark and // silently drop every real line after it. + // A timestamp is "positionable" only if it can be compared against + // the watermark at all. Anything else — non-finite, or implausibly + // far in the future — is treated as undated everywhere, so it can + // neither pin the watermark nor slip past the dedupe and reprint on + // every poll. + const positionable = (ts: number) => Number.isFinite(ts) && ts <= Date.now() + CLOCK_SKEW_MS; const maxTs = (lines: ComputeLogLine[]) => lines.reduce( - (m, l) => (Number.isFinite(l.timestamp) && l.timestamp > m && l.timestamp <= Date.now() + CLOCK_SKEW_MS - ? l.timestamp - : m), + (m, l) => (positionable(l.timestamp) && l.timestamp > m ? l.timestamp : m), 0, ); let lastTs = maxTs(result.lines); @@ -196,7 +200,7 @@ export function registerComputeLogsCommand(computeCmd: Command): void { const undatedCounts = (lines: ComputeLogLine[]) => { const m = new Map(); for (const l of lines) { - if (Number.isFinite(l.timestamp)) continue; + if (positionable(l.timestamp)) continue; const k = lineKey(l); m.set(k, (m.get(k) ?? 0) + 1); } @@ -230,7 +234,7 @@ export function registerComputeLogsCommand(computeCmd: Command): void { fresh.push(l); continue; } - if (!Number.isFinite(l.timestamp)) { + if (!positionable(l.timestamp)) { const k = lineKey(l); const seen = undatedSuppress.get(k) ?? 0; if (seen > 0) { From 1b94f6f4f2cc7b98a64e320e8a08be55e0344f4b Mon Sep 17 00:00:00 2001 From: yaowenc2 Date: Thu, 27 Aug 2026 16:52:23 -0700 Subject: [PATCH 15/19] fix(compute-logs): scope the future-timestamp bound per page, not to the local clock MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Review Critical: positionable() compared the provider's timestamps against Date.now(), the READER's clock. A machine more than CLOCK_SKEW_MS behind (laptop resumed from sleep before NTP re-syncs, paused VM) failed the bound on every legitimate line, dropping the whole tail into content-only dedupe — a silent dead tail on exactly the crash loop you run -f to watch. The bound is now scoped to each page: if nothing the server sent looks plausible, the disagreement is with our clock, so the bound isn't applied. A lone year-2100 line is still treated as undated, because the rest of its page corroborates the clock. Negative control: restoring the global bound turns the new slow-clock test red while the other 24 stay green. Co-Authored-By: Claude Fable 5 --- src/commands/compute/logs.test.ts | 21 +++++++++++++++++++++ src/commands/compute/logs.ts | 18 +++++++++++++++++- 2 files changed, 38 insertions(+), 1 deletion(-) diff --git a/src/commands/compute/logs.test.ts b/src/commands/compute/logs.test.ts index 4326e9c5..3057ff7b 100644 --- a/src/commands/compute/logs.test.ts +++ b/src/commands/compute/logs.test.ts @@ -260,6 +260,27 @@ describe('compute logs', () => { expect(printed.filter((l: string) => l.includes('dated') && !l.includes('undated'))).toHaveLength(1); }); + it('--follow keeps tailing when the local clock is far behind the provider', async () => { + vi.useFakeTimers(); + // Reader's clock 10 minutes behind the timestamps the server sends. + const serverNow = 1_700_000_000_000; + vi.setSystemTime(serverNow - 10 * 60 * 1000); + const win = (n: number) => page([ + { timestamp: serverNow + n, message: 'EADDRINUSE, retrying' }, + ], null); + ossFetchMock.mockResolvedValueOnce(win(0)); + ossFetchMock.mockResolvedValueOnce(win(1)); + ossFetchMock.mockResolvedValueOnce(win(2)); + ossFetchMock.mockResolvedValue(page([])); + void run(['compute', 'logs', 'svc', '--follow']); + await vi.advanceTimersByTimeAsync(0); + await vi.advanceTimersByTimeAsync(2000); + await vi.advanceTimersByTimeAsync(2000); + const printed = logSpy.mock.calls.map((c: unknown[]) => String(c[0])); + // All three distinct lines must appear; a global clock bound printed only the first. + expect(printed.filter((l: string) => l.includes('EADDRINUSE'))).toHaveLength(3); + }); + it('emits stable telemetry for the command', async () => { ossFetchMock.mockResolvedValueOnce(page([{ timestamp: 1, message: 'x' }], null)); await run(['compute', 'logs', 'svc']); diff --git a/src/commands/compute/logs.ts b/src/commands/compute/logs.ts index 2c832889..5ca2782c 100644 --- a/src/commands/compute/logs.ts +++ b/src/commands/compute/logs.ts @@ -177,7 +177,21 @@ export function registerComputeLogsCommand(computeCmd: Command): void { // far in the future — is treated as undated everywhere, so it can // neither pin the watermark nor slip past the dedupe and reprint on // every poll. - const positionable = (ts: number) => Number.isFinite(ts) && ts <= Date.now() + CLOCK_SKEW_MS; + // + // The future bound is scoped PER PAGE, not to the local clock alone: + // Date.now() is the reader's clock while the timestamps are the + // provider's. If a laptop resumed from sleep is minutes behind NTP, + // a global bound would reject every legitimate line and drop the + // whole tail into content-only dedupe — a silent dead tail on + // exactly the crash loop you ran `-f` to watch. So if nothing in + // the page looks plausible, the disagreement is with our clock and + // the bound is not applied. + const positionableFor = (lines: ComputeLogLine[]) => { + const bound = Date.now() + CLOCK_SKEW_MS; + const clockTrusted = lines.some((l) => Number.isFinite(l.timestamp) && l.timestamp <= bound); + return (ts: number) => Number.isFinite(ts) && (!clockTrusted || ts <= bound); + }; + let positionable = positionableFor(result.lines); const maxTs = (lines: ComputeLogLine[]) => lines.reduce( (m, l) => (positionable(l.timestamp) && l.timestamp > m ? l.timestamp : m), 0, @@ -222,6 +236,8 @@ export function registerComputeLogsCommand(computeCmd: Command): void { await new Promise((r) => setTimeout(r, Math.min(FOLLOW_INTERVAL_MS * 2 ** pollFailures, 30_000))); continue; } + // Re-scope the plausibility bound to this page before any use. + positionable = positionableFor(page.lines); // `token` still holds the cursor this request was made with, so a // frozen token (nextToken === token) and a null token both keep // the dedupe. From e514b59a374412dad5374fa1a2ffd2af2e974be7 Mon Sep 17 00:00:00 2001 From: yaowenc2 Date: Thu, 27 Aug 2026 17:04:58 -0700 Subject: [PATCH 16/19] fix(compute-logs): make clock trust sticky, not per-page MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Review suggestion #1: computing clockTrusted per page meant a page whose lines were ALL implausibly future disabled the future bound entirely — letting a bogus timestamp become positionable and re-pin the watermark, killing the tail permanently. That partially regressed cd3bb32; the existing guard test missed it because its page is mixed, so the page carried trust on its own. Trust is now earned once and never given back. Negative control: reverting to per-page trust turns the new uniform-page test red while the other 25 stay green. Co-Authored-By: Claude Fable 5 --- src/commands/compute/logs.test.ts | 19 +++++++++++++++++++ src/commands/compute/logs.ts | 8 +++++++- 2 files changed, 26 insertions(+), 1 deletion(-) diff --git a/src/commands/compute/logs.test.ts b/src/commands/compute/logs.test.ts index 3057ff7b..177154c0 100644 --- a/src/commands/compute/logs.test.ts +++ b/src/commands/compute/logs.test.ts @@ -281,6 +281,25 @@ describe('compute logs', () => { expect(printed.filter((l: string) => l.includes('EADDRINUSE'))).toHaveLength(3); }); + it('--follow survives a page in which every line is implausibly future', async () => { + vi.useFakeTimers(); + const future = Date.now() + 365 * 24 * 60 * 60 * 1000; + ossFetchMock.mockResolvedValueOnce(page([{ timestamp: 1000, message: 'real-1' }], null)); + // A uniform all-future page must not disable the bound for later polls. + ossFetchMock.mockResolvedValueOnce(page([{ timestamp: future, message: 'bogus-future' }], null)); + ossFetchMock.mockResolvedValueOnce(page([{ timestamp: 2000, message: 'real-2' }], null)); + ossFetchMock.mockResolvedValueOnce(page([{ timestamp: 3000, message: 'real-3' }], null)); + ossFetchMock.mockResolvedValue(page([])); + void run(['compute', 'logs', 'svc', '--follow']); + await vi.advanceTimersByTimeAsync(0); + await vi.advanceTimersByTimeAsync(2000); + await vi.advanceTimersByTimeAsync(2000); + await vi.advanceTimersByTimeAsync(2000); + const printed = logSpy.mock.calls.map((c: unknown[]) => String(c[0])); + expect(printed.some((l: string) => l.includes('real-2'))).toBe(true); + expect(printed.some((l: string) => l.includes('real-3'))).toBe(true); + }); + it('emits stable telemetry for the command', async () => { ossFetchMock.mockResolvedValueOnce(page([{ timestamp: 1, message: 'x' }], null)); await run(['compute', 'logs', 'svc']); diff --git a/src/commands/compute/logs.ts b/src/commands/compute/logs.ts index 5ca2782c..86033209 100644 --- a/src/commands/compute/logs.ts +++ b/src/commands/compute/logs.ts @@ -186,9 +186,15 @@ export function registerComputeLogsCommand(computeCmd: Command): void { // exactly the crash loop you ran `-f` to watch. So if nothing in // the page looks plausible, the disagreement is with our clock and // the bound is not applied. + // Trust is STICKY: a page can earn it but never give it back. + // Recomputing per page would let a page in which every line is + // implausibly future disable the bound outright — the very state + // the bound exists to prevent — and re-pin the watermark to a bogus + // timestamp, killing the tail permanently. + let clockTrusted = false; const positionableFor = (lines: ComputeLogLine[]) => { const bound = Date.now() + CLOCK_SKEW_MS; - const clockTrusted = lines.some((l) => Number.isFinite(l.timestamp) && l.timestamp <= bound); + clockTrusted = clockTrusted || lines.some((l) => Number.isFinite(l.timestamp) && l.timestamp <= bound); return (ts: number) => Number.isFinite(ts) && (!clockTrusted || ts <= bound); }; let positionable = positionableFor(result.lines); From e1ca55c1a166e0da07828d8106888d02e7be5bfd Mon Sep 17 00:00:00 2001 From: yaowenc2 Date: Thu, 27 Aug 2026 17:14:37 -0700 Subject: [PATCH 17/19] fix(compute-logs): key the undated dedupe on timestamp too MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Review Critical: a scrolling window almost always contains a line older than CLOCK_SKEW_MS, and on a slow clock that old line satisfies the plausibility bound — earning trust permanently. The bound then rejects every NEW line, routing the live tail into the content-only undated path, where a crash loop's identical messages collapse to one and the tail goes silent. A timestamp that can't be ORDERED against the watermark is still a stable IDENTIFIER, so the undated dedupe now keys on it: identical messages at different timestamps stay distinct, while a genuinely re-sent line (same timestamp, same text) is still suppressed. Also strengthens the slow-clock test, which passed vacuously — its window held only recent lines, the one shape where the trust heuristic happens to hold. It now carries an old line like a real window does; negative control: dropping the timestamp from the undated key turns it red. Co-Authored-By: Claude Fable 5 --- src/commands/compute/logs.test.ts | 5 +++++ src/commands/compute/logs.ts | 11 +++++++++-- 2 files changed, 14 insertions(+), 2 deletions(-) diff --git a/src/commands/compute/logs.test.ts b/src/commands/compute/logs.test.ts index 177154c0..67583205 100644 --- a/src/commands/compute/logs.test.ts +++ b/src/commands/compute/logs.test.ts @@ -265,7 +265,12 @@ describe('compute logs', () => { // Reader's clock 10 minutes behind the timestamps the server sends. const serverNow = 1_700_000_000_000; vi.setSystemTime(serverNow - 10 * 60 * 1000); + // The window also carries an OLD line, the way a real scrolling window + // does — that older line satisfies the plausibility bound even on a slow + // clock, so without a timestamp-keyed undated dedupe the live lines + // collapse into one and the tail goes silent. const win = (n: number) => page([ + { timestamp: serverNow - 10 * 60 * 1000, message: 'listening on :8080' }, { timestamp: serverNow + n, message: 'EADDRINUSE, retrying' }, ], null); ossFetchMock.mockResolvedValueOnce(win(0)); diff --git a/src/commands/compute/logs.ts b/src/commands/compute/logs.ts index 86033209..1f136741 100644 --- a/src/commands/compute/logs.ts +++ b/src/commands/compute/logs.ts @@ -166,6 +166,13 @@ export function registerComputeLogsCommand(computeCmd: Command): void { // seen, plus per-key occurrence COUNTS for the lines sharing it, so // genuinely repeated identical messages still print. const lineKey = (l: ComputeLogLine) => `${l.region ?? ''}|${l.instance ?? ''}|${l.message}`; + // A timestamp that can't be ordered against the watermark is still a + // stable identifier for the line. Keying the undated dedupe on it + // keeps identical messages at DIFFERENT timestamps distinct, so a + // crash loop emitting the same text every second is never collapsed + // into a single printed line; a genuinely re-sent line (same + // timestamp, same text) is still suppressed. + const undatedKey = (l: ComputeLogLine) => `${String(l.timestamp)}|${lineKey(l)}`; // Max, not last: a page arriving unsorted must not move the // watermark backwards. Non-finite timestamps are skipped (they'd // poison the max into NaN, which compares false against everything @@ -221,7 +228,7 @@ export function registerComputeLogsCommand(computeCmd: Command): void { const m = new Map(); for (const l of lines) { if (positionable(l.timestamp)) continue; - const k = lineKey(l); + const k = undatedKey(l); m.set(k, (m.get(k) ?? 0) + 1); } return m; @@ -257,7 +264,7 @@ export function registerComputeLogsCommand(computeCmd: Command): void { continue; } if (!positionable(l.timestamp)) { - const k = lineKey(l); + const k = undatedKey(l); const seen = undatedSuppress.get(k) ?? 0; if (seen > 0) { undatedSuppress.set(k, seen - 1); From e784f82662262a0fea7c1412fb93260b470aa060 Mon Sep 17 00:00:00 2001 From: yaowenc2 Date: Fri, 28 Aug 2026 09:53:47 -0700 Subject: [PATCH 18/19] fix(compute-logs): retry the initial fetch in follow mode too MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Review suggestion: --follow only rode out transient failures AFTER the first successful fetch, so an initial 429 (the logs limiter is shared per-IP with the dashboard), 5xx, or network blip killed the tail before it reached the resilient loop. One fetchPage helper now carries the retry for every fetch in follow mode, which also collapses the loop's bespoke failure bookkeeping. One-shot mode is unchanged and still fails fast — covered by a test. Co-Authored-By: Claude Fable 5 --- src/commands/compute/logs.test.ts | 18 ++++++++++++++++ src/commands/compute/logs.ts | 36 +++++++++++++++++++------------ 2 files changed, 40 insertions(+), 14 deletions(-) diff --git a/src/commands/compute/logs.test.ts b/src/commands/compute/logs.test.ts index 67583205..6c121704 100644 --- a/src/commands/compute/logs.test.ts +++ b/src/commands/compute/logs.test.ts @@ -305,6 +305,24 @@ describe('compute logs', () => { expect(printed.some((l: string) => l.includes('real-3'))).toBe(true); }); + it('--follow retries a transient failure on the INITIAL fetch', async () => { + vi.useFakeTimers(); + ossFetchMock.mockRejectedValueOnce(new CLIError('rate limited', 1, 'RATE_LIMITED', 429)); + ossFetchMock.mockResolvedValueOnce(page([{ timestamp: 1, message: 'after-429' }], null)); + ossFetchMock.mockResolvedValue(page([])); + void run(['compute', 'logs', 'svc', '--follow']); + await vi.advanceTimersByTimeAsync(0); + await vi.advanceTimersByTimeAsync(4000); + const printed = logSpy.mock.calls.map((c: unknown[]) => String(c[0])); + expect(printed.some((l: string) => l.includes('after-429'))).toBe(true); + }); + + it('does NOT retry the initial fetch without --follow', async () => { + ossFetchMock.mockRejectedValueOnce(new CLIError('rate limited', 1, 'RATE_LIMITED', 429)); + await expect(run(['compute', 'logs', 'svc'])).rejects.toThrow('rate limited'); + expect(ossFetchMock).toHaveBeenCalledTimes(1); + }); + it('emits stable telemetry for the command', async () => { ossFetchMock.mockResolvedValueOnce(page([{ timestamp: 1, message: 'x' }], null)); await run(['compute', 'logs', 'svc']); diff --git a/src/commands/compute/logs.ts b/src/commands/compute/logs.ts index 1f136741..99943a77 100644 --- a/src/commands/compute/logs.ts +++ b/src/commands/compute/logs.ts @@ -119,7 +119,27 @@ export function registerComputeLogsCommand(computeCmd: Command): void { await requireAuth(); const limit = parseLimit(opts.limit); - const result = await fetchComputeLogs(id, { limit, nextToken: opts.nextToken }); + + // In follow mode every fetch — including the first — rides out + // transient failures. The logs limiter is shared per-IP with the + // dashboard, so an initial 429 is ordinary; without this the tail + // died before it ever reached the resilient loop. Non-transient + // errors (401/403/404) still fail fast. + const fetchPage = async (nextToken?: string): Promise => { + if (!opts.follow) return fetchComputeLogs(id, { limit, nextToken }); + let failures = 0; + for (;;) { + try { + return await fetchComputeLogs(id, { limit, nextToken }); + } catch (err) { + failures += 1; + if (!isTransientApiError(err) || failures >= MAX_CONSECUTIVE_POLL_FAILURES) throw err; + await new Promise((r) => setTimeout(r, Math.min(FOLLOW_INTERVAL_MS * 2 ** failures, 30_000))); + } + } + }; + + const result = await fetchPage(opts.nextToken); // Emitted before the tail starts, because a --follow run never // reaches the end of the action. NOT awaited in follow mode: @@ -234,21 +254,9 @@ export function registerComputeLogsCommand(computeCmd: Command): void { return m; }; let prevUndated = undatedCounts(result.lines); - let pollFailures = 0; for (;;) { await new Promise((r) => setTimeout(r, FOLLOW_INTERVAL_MS)); - let page: ComputeLogsResult; - try { - page = await fetchComputeLogs(id, { limit, nextToken: token ?? undefined }); - pollFailures = 0; - } catch (pollErr) { - pollFailures += 1; - if (!isTransientApiError(pollErr) || pollFailures >= MAX_CONSECUTIVE_POLL_FAILURES) { - throw pollErr; - } - await new Promise((r) => setTimeout(r, Math.min(FOLLOW_INTERVAL_MS * 2 ** pollFailures, 30_000))); - continue; - } + const page = await fetchPage(token ?? undefined); // Re-scope the plausibility bound to this page before any use. positionable = positionableFor(page.lines); // `token` still holds the cursor this request was made with, so a From 67ba77d385f2905c7427e0957e25630069dfefbe Mon Sep 17 00:00:00 2001 From: yaowenc2 Date: Fri, 28 Aug 2026 09:58:23 -0700 Subject: [PATCH 19/19] fix(compute-logs): announce the tail before the first fetch, and each retry cubic P2: with initial-fetch retry, a --follow hit by a 429 printed nothing for up to a minute and looked hung; --json --follow never printed the banner at all. The 'Following logs...' notice now goes out before the first request (both output modes, on stderr so NDJSON stays clean), and each backoff says what it is waiting for. Co-Authored-By: Claude Fable 5 --- src/commands/compute/logs.ts | 11 +++++++++-- 1 file changed, 9 insertions(+), 2 deletions(-) diff --git a/src/commands/compute/logs.ts b/src/commands/compute/logs.ts index 99943a77..f766c931 100644 --- a/src/commands/compute/logs.ts +++ b/src/commands/compute/logs.ts @@ -134,11 +134,19 @@ export function registerComputeLogsCommand(computeCmd: Command): void { } catch (err) { failures += 1; if (!isTransientApiError(err) || failures >= MAX_CONSECUTIVE_POLL_FAILURES) throw err; - await new Promise((r) => setTimeout(r, Math.min(FOLLOW_INTERVAL_MS * 2 ** failures, 30_000))); + const wait = Math.min(FOLLOW_INTERVAL_MS * 2 ** failures, 30_000); + // Say so, or backoff makes a retrying tail look hung — the + // first page can be up to ~a minute away on a 429. + console.error(`Request failed (attempt ${failures}), retrying in ${Math.round(wait / 1000)}s...`); + await new Promise((r) => setTimeout(r, wait)); } } }; + // Printed before the first fetch so --follow acknowledges it is alive + // even while the initial request is still retrying. + if (opts.follow) console.error('Following logs... (Ctrl+C to stop)'); + const result = await fetchPage(opts.nextToken); // Emitted before the tail starts, because a --follow run never @@ -171,7 +179,6 @@ export function registerComputeLogsCommand(computeCmd: Command): void { print(result.lines); if (opts.follow) { - if (!json) console.error('Following logs... (Ctrl+C to stop)'); let token = result.nextToken; // Dedupe only when the cursor did NOT advance: a cursorless poll // re-fetches the recent window, and a frozen cursor (the server