diff --git a/README.md b/README.md index c56ed58a..65baaabc 100644 --- a/README.md +++ b/README.md @@ -1091,6 +1091,17 @@ 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 --json compute logs my-api --follow # NDJSON: one {timestamp, message, ...} object per line +``` + #### `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..6c121704 --- /dev/null +++ b/src/commands/compute/logs.test.ts @@ -0,0 +1,413 @@ +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()); +vi.mock('../../lib/api/oss.js', () => ({ ossFetch: ossFetchMock })); +vi.mock('../../lib/credentials.js', () => ({ requireAuth: vi.fn().mockResolvedValue(undefined) })); +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(); + return { + ...actual, + handleError: (err: unknown) => { throw err; }, + }; +}); + +import { Command } from 'commander'; +import { registerComputeLogsCommand, sanitizeLogMessage, parseLimit, formatLogLine } 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(); + cmd.exitOverride(); + cmd.option('--json'); + const compute = cmd.command('compute'); + registerComputeLogsCommand(compute); + 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(); + trackCommandUsageMock.mockReset(); + logSpy = vi.spyOn(console, 'log').mockImplementation(() => {}); + errSpy = vi.spyOn(console, 'error').mockImplementation(() => {}); + }); + afterEach(() => { + logSpy.mockRestore(); + errSpy.mockRestore(); + vi.useRealTimers(); + }); + + it('calls the container logs endpoint with a clamped limit', async () => { + 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(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(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, sanitized', async () => { + ossFetchMock.mockResolvedValueOnce(page([{ timestamp: 1, message: `x${CSI_C1}31my` }], 'tok')); + await run(['--json', 'compute', 'logs', 'svc']); + 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('--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: 5, message: 'sibling' }, + { 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: 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); + }); + + 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')); + 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 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 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('--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('--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 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)); + 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('--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); + // 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)); + 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('--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('--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']); + 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')); + 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')); + 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('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'); + expect(sanitizeLogMessage(`${ESC}]0;evil title${BEL}text`)).toBe('text'); + expect(sanitizeLogMessage('a\rb\nc')).toBe('a b c'); + 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('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 new file mode 100644 index 00000000..f766c931 --- /dev/null +++ b/src/commands/compute/logs.ts @@ -0,0 +1,333 @@ +import type { Command } from 'commander'; +import { ossFetch } from '../../lib/api/oss.js'; +import { requireAuth } from '../../lib/credentials.js'; +import { handleError, getRootOpts, isTransientApiError } from '../../lib/errors.js'; +import { outputJson } from '../../lib/output.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 +// (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; +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; +// 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 +// 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_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 { + // 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 +// 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 { + // 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}`; +} + +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; + // 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 ?? '')), + ...(l.instance !== undefined ? { instance: sanitizeLogMessage(String(l.instance)) } : {}), + ...(l.region !== undefined ? { region: sanitizeLogMessage(String(l.region)) } : {}), + })); + return { + 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)', 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) => { + const { json } = getRootOpts(cmd); + try { + await requireAuth(); + + const limit = parseLimit(opts.limit); + + // 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; + 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 + // 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); + 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.'); + return; + } + print(result.lines); + + if (opts.follow) { + 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 + // 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}`; + // 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 + // 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. + // + // 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. + // 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; + 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); + const maxTs = (lines: ComputeLogLine[]) => lines.reduce( + (m, l) => (positionable(l.timestamp) && l.timestamp > m ? 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 + // 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); + } + } + // 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 (positionable(l.timestamp)) continue; + const k = undatedKey(l); + m.set(k, (m.get(k) ?? 0) + 1); + } + return m; + }; + let prevUndated = undatedCounts(result.lines); + for (;;) { + await new Promise((r) => setTimeout(r, FOLLOW_INTERVAL_MS)); + 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 + // 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 undatedSuppress = new Map(prevUndated); + const fresh: ComputeLogLine[] = []; + for (const l of page.lines) { + if (cursorAdvanced) { + fresh.push(l); + continue; + } + if (!positionable(l.timestamp)) { + const k = undatedKey(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); + const remaining = suppress.get(k) ?? 0; + if (remaining > 0) { + suppress.set(k, remaining - 1); + continue; + } + } + 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) { + // 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) { + lastTs = newTs; + lastTsCounts.clear(); + } + for (const l of fresh) { + 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 + // 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) { + await trackCommandUsage('compute', 'logs', false, {}, err); + 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'); 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();