diff --git a/.changeset/cli-logs.md b/.changeset/cli-logs.md new file mode 100644 index 000000000..1afa331be --- /dev/null +++ b/.changeset/cli-logs.md @@ -0,0 +1,5 @@ +--- +"@evlog/cli": minor +--- + +`evlog logs` reads the wide events the fs drain wrote to `.evlog/logs`: the last 50 (`evlog logs`), the failures (`evlog logs errors`), the slowest (`evlog logs slow --over 1s`), one request in full by id (`evlog logs `, a UUID prefix is enough), or the shape of the traffic (`evlog logs stats`: per route, status class and level). Filters compose with every view: `--since 15m`, `--until`, `--level error,fatal`, `--path`, `--status 5xx`, `--where payment.amount>5000` on any field of the event (`=`, `!=`, `>`, `>=`, `<`, `<=`, `~regex`, present, `!absent`, repeatable), `--limit`, `--dir`. `-f` follows new events like `tail -f`; `--json` returns the events as JSON. It finds the project's log directory the way `doctor` does, reads every app of a workspace when the root has none, reads the memory drain's dev endpoint with `--url` (a follow there survives the app restarting, and says so when the endpoint stays quiet), handles both the compact and the pretty layout, and never writes. diff --git a/.changeset/fs-reader-pretty.md b/.changeset/fs-reader-pretty.md new file mode 100644 index 000000000..1136cc666 --- /dev/null +++ b/.changeset/fs-reader-pretty.md @@ -0,0 +1,5 @@ +--- +"evlog": patch +--- + +`readFsLogs()` and `tailFsLogs()` from `evlog/fs` now read files the drain wrote with `pretty: true`, assembling each indented event, where they used to skip every line of them as malformed. diff --git a/.gitignore b/.gitignore index 2c326881a..d4d81086a 100644 --- a/.gitignore +++ b/.gitignore @@ -17,6 +17,8 @@ node_modules logs !examples/eve/app/api/demo/logs/ !examples/eve/app/api/demo/logs/** +!packages/cli/src/lib/logs/ +!packages/cli/src/lib/logs/** *.log # Misc diff --git a/apps/docs/content/3.cli/0.overview.md b/apps/docs/content/3.cli/0.overview.md index 8744c70dc..89326a400 100644 --- a/apps/docs/content/3.cli/0.overview.md +++ b/apps/docs/content/3.cli/0.overview.md @@ -21,7 +21,7 @@ The `evlog` executable ships with the `evlog` package. It runs separately from y Start with [`evlog map`](/cli/map) to check supported entry points for evlog logging patterns and get a static observability score with suggested fixes. It writes `evlog.map.json` unless you pass `--no-write`. The score describes recognized source patterns, not the logs your handlers produce in production. -[`evlog init`](/cli/init) adds evlog configuration to the app. [`evlog agents`](/cli/agents) writes logging conventions for the AI agents working in the repository. +[`evlog init`](/cli/init) adds evlog configuration to the app. [`evlog logs`](/cli/logs) reads the events the fs drain wrote: the latest requests, the failures, the slowest, or one request in full. [`evlog agents`](/cli/agents) writes logging conventions for the AI agents working in the repository. ::warning{icon="i-lucide-flask-conical"} **Early days.** `evlog map` has adapters for Nuxt, Nitro, Next.js App Router, TanStack Start, Hono, Express, and Fastify. Each adapter recognizes specific entry-point shapes. Check the detected framework and entry-point count before interpreting the score. Rules can change between releases, so [pin the version](/cli/ci#pin-the-version) when you gate CI on the number. diff --git a/apps/docs/content/3.cli/10.logs.md b/apps/docs/content/3.cli/10.logs.md new file mode 100644 index 000000000..6b0bf7bf0 --- /dev/null +++ b/apps/docs/content/3.cli/10.logs.md @@ -0,0 +1,135 @@ +--- +title: evlog logs +description: Read the wide events your app wrote to .evlog/logs from the terminal — the latest requests, the failures, the slowest, or one request in full. +navigation: + title: logs + icon: i-lucide-scroll-text +links: + - label: File system adapter + icon: i-lucide-folder-open + to: /integrate/adapters/self-hosted/fs + color: neutral + variant: subtle +--- + +`evlog logs` reads the events the [file system drain](/integrate/adapters/self-hosted/fs) wrote and shows them the way you would want to read them: one line per request, the thing that mattered at the end of it, and one request in full when you have its id. It reads files; it never touches the app. + +```bash [Terminal] +evlog logs +``` + +```text [Output] +6 events · .evlog/logs + +08:00:00 GET /api/health 200 2ms +10:00:00 POST /api/checkout 402 412ms ✗ Error: Payment processing failed · Card declined by issuer +10:30:00 GET /api/reports 200 1.2s report.id=r-1 +11:00:00 POST /api/refund 200 80ms audit billing.refund user:usr_42 → invoice:inv_1 success +11:30:00 GET /api/items 500 30ms +11:45:00 GET /api/items warn 700ms user.id=usr_7 + +evlog logs errors — the 2 that failed · evlog logs — one request in full · evlog logs slow — worst first +``` + +The newest event is at the bottom, like `tail`. Nothing is written: the fs drain writes on every request and this reads what it wrote, both the compact and the `pretty: true` layout, across the dated files. + +## Five views + +| Command | Shows | +| --- | --- | +| `evlog logs` | The last 50 events, oldest first | +| `evlog logs errors` | Events that failed: a `5xx` status, an `error` or `fatal` level, or an `error` block | +| `evlog logs slow` | Events over 500ms, worst first (`--over 1s` to move the bar) | +| `evlog logs ` | Every event carrying that id, in full: request, error with `why` and `fix`, audit record, then the business fields. The first block of a UUID is enough | +| `evlog logs stats` | The shape of the traffic: per route, count, errors, p50 and p95, routes with the most errors first; then counts by status class and by level | + +## Filters + +Filters compose with any view. + +| Flag | What it does | +| --- | --- | +| `--since ` | Only events after: a duration back from now (`15m`, `2h`, `3d`) or a date (`2026-10-01`, `2026-10-01T09:00`) | +| `--until ` | Only events before, same spellings | +| `--level ` | Only these levels: `trace`, `debug`, `info`, `warn`, `error`, `fatal` | +| `--path ` | Only requests on this exact path | +| `--status ` | Only this status (`404`) or class (`4xx`) | +| `--where ` | Only events where a field matches, see below; repeat the flag for several clauses, all must hold | +| `--over ` | For `slow`: what a request has to exceed (default `500ms`) | +| `--limit ` | Most events to show (default 50) | +| `--dir ` | Read another directory (default: the project's `.evlog/logs`; in a workspace with no logs at the root, every `apps/*/.evlog/logs` and the like, merged by time with the app in a column) | +| `--url ` | Read the [memory drain](/integrate/adapters/self-hosted/memory)'s dev endpoint instead of files: a JSON array of events, or `{ "events": [...] }` | +| `-f`, `--follow` | Keep reading as the app writes, like `tail -f`; `Ctrl-C` stops | +| `--json` | The events as JSON on stdout | +| `--cwd ` | Another project in the workspace | + +A time, level, status or limit that cannot be read stops the command (exit 2) rather than silently widening the query. + +```bash [Terminal] +evlog logs errors --since 1h +evlog logs slow --over 2s --path /api/reports +evlog logs --status 5xx --level error,fatal --limit 20 +evlog logs -f --path /api/checkout +``` + +### `--where`: any field on the event + +A clause is a dotted field, an operator, and a value. Numbers compare as numbers, everything else as text, and the field can sit anywhere in the event, which is the point of a wide event: the business fields are there to be queried. + +| Clause | Matches when | +| --- | --- | +| `user.id=usr_42` | the field equals the value (`true`/`false` and numbers are read as such) | +| `audit.outcome!=success` | the field differs | +| `payment.amount>5000` | greater; also `>=`, `<`, `<=` | +| `error.message~declined` | the field matches the regular expression, case-insensitive; an object is matched as JSON | +| `audit` | the field is present | +| `!error` | the field is absent | + +```bash [Terminal] +evlog logs --where 'payment.amount>5000' --where audit.outcome=failure +evlog logs errors --where 'error.data.why~card declined' +evlog logs stats --where user.plan=pro +evlog logs -f --where '!error' --where 'durationMs>1000' +``` + +Quote the whole clause whenever it carries `>`, `<` or `!`, which the shell reads as redirection or history before `evlog` ever sees them, and whenever the value has a space: `'payment.amount>5000'`, `'!error'`, `'error.data.why~card declined'`. + +## For agents + +`--json` returns one envelope: the directory, the view, how many events matched, and the events shown. + +```bash [Terminal] +evlog logs errors --since 30m --json +``` + +```json +{ + "schemaVersion": 2, + "dir": "/app/.evlog/logs", + "view": "errors", + "count": 2, + "matched": 2, + "events": [ { "timestamp": "…", "path": "/api/checkout", "status": 402, "error": { "data": { "why": "…", "fix": "…" } } } ] +} +``` + +`stats --json` carries `stats` (`total`, `errors`, `byRoute`, `byStatus`, `byLevel`) in place of `events`. With `--follow --json`, each new event is one JSON line on stdout, since a stream has no end. The [`analyze-logs` skill](/reference/agent-skills) calls `evlog logs` first and falls back to reading the files only when the CLI is not available. + +## A workspace, and a running app + +Run from a monorepo root with no `.evlog/logs` of its own, it reads every app that has one (`apps/*`, `packages/*`, `examples/*`, `services/*`), merges the events by time, and shows the app in a column. `--cwd apps/web` reads one app; `--dir` reads one directory. + +An app on the [memory drain](/integrate/adapters/self-hosted/memory) (Cloudflare Workers, where there is no file system) has no files to read, but it can expose `readMemoryLogs()` on a dev route. Point `--url` at it; every view and filter works the same, and `-f` polls it once a second. A failed poll is a gap rather than the end, since the app restarting under a follower is normal; if the endpoint stays quiet the run says so once and keeps trying. + +```bash [Terminal] +evlog logs errors --url http://localhost:8787/_evlog/logs +``` + +## What it will not do + +- **It reads local files and a dev endpoint.** A remote drain (Axiom, Datadog, …) has its own query language and UI; this command does not wrap them. + +## Next + +- [File system drain](/integrate/adapters/self-hosted/fs): what writes the files, rotation, `pretty` +- [`evlog map`](/cli/map): which handlers emit a wide event at all diff --git a/packages/cli/README.md b/packages/cli/README.md index 329696036..cf4fea074 100644 --- a/packages/cli/README.md +++ b/packages/cli/README.md @@ -64,9 +64,18 @@ pnpm evlog map | `evlog map --baseline [ref]` | Exit 1 on a regression against the committed `evlog.map.json` (path, or `git:`) | | `evlog map --no-write` | Skip writing `evlog.map.json` to the project root | | `evlog map --format github` | GitHub Actions annotations on stdout; or use [`evloghq/action`](https://github.com/evloghq/action), which adds the base comparison, the job summary and a pull request comment | -| `evlog map --format sarif` | SARIF 2.1.0 on stdout, for code scanning | | `evlog map --verbose` | Show per-file parse warnings | | `evlog map --cwd ` | Scan another app in the workspace | +| `evlog logs` | The last 50 wide events the fs drain wrote, oldest first | +| `evlog logs errors` | The ones that failed: a `5xx`, an `error` or `fatal` level, or an `error` block | +| `evlog logs slow [--over 1s]` | Over the bar (default 500ms), worst first | +| `evlog logs ` | One request in full: error with `why`/`fix`, audit record, business fields | +| `evlog logs stats` | Per route: count, errors, p50, p95; then by status class and level | +| `evlog logs --where 'payment.amount>5000' --where audit.outcome=failure` | Any field on the event: `=`, `!=`, `>`, `>=`, `<`, `<=`, `~regex`, present, `!absent` | +| `evlog logs --url http://localhost:8787/_evlog/logs` | Read the memory drain's dev endpoint instead of files | +| `evlog logs -f` | Follow new events as the app writes them | +| `evlog logs --since 15m --path /api/x --status 5xx --level error` | Filters, composable with every view | +| `evlog logs --json` | The events as JSON on stdout (one line per event with `-f`) | | `evlog doctor` | Monorepo-aware diagnosis: Node, project/workspace, stack, evlog install, `.evlog/logs` | | `evlog doctor --cwd ` | Run against another directory | | `evlog doctor --debug` | Same, plus a debug wide event (see Debug) | diff --git a/packages/cli/src/commands/index.ts b/packages/cli/src/commands/index.ts index 76bd2ea3c..e36e99b6b 100644 --- a/packages/cli/src/commands/index.ts +++ b/packages/cli/src/commands/index.ts @@ -24,6 +24,10 @@ export const subCommands = { { name: 'doctor', description: 'Diagnose your evlog setup' }, () => import('./doctor'), ), + logs: lazyCommand( + { name: 'logs', description: 'Read the wide events your app wrote to .evlog/logs' }, + () => import('./logs'), + ), map: lazyCommand( { name: 'map', description: 'Static observability map — Lighthouse for wide events' }, () => import('./map'), diff --git a/packages/cli/src/commands/logs.ts b/packages/cli/src/commands/logs.ts new file mode 100644 index 000000000..71dc15c45 --- /dev/null +++ b/packages/cli/src/commands/logs.ts @@ -0,0 +1,300 @@ +import { existsSync, readdirSync } from 'node:fs' +import { basename, join, resolve } from 'node:path' +import { telemetry } from '@evlog/telemetry' +import { EvlogError } from 'evlog' +import type { WideEvent } from 'evlog' +import { readFsLogs, tailFsLogs } from 'evlog/fs' +import type { CliContext } from '../core/context' +import { createStyle, EXIT_FAIL, EXIT_USAGE } from '../core/output' +import { defineEvlogCommand } from '../lib/command' +import { cliErrors } from '../lib/errors' +import { buildQuery, computeStats, select } from '../lib/logs/query' +import type { LogsArgs, LogsQuery } from '../lib/logs/query' +import { formatLine, formatLogsReport, SOURCE } from '../lib/logs/render' +import type { LogsResult, Sourced } from '../lib/logs/render' +import { findConfiguredFsDrain, findLogsSink, prettyPath, resolveProject } from '../lib/project' +import type { ProjectInfo } from '../lib/project' + +export type { LogsResult } from '../lib/logs/render' + +/** One place events are read from: a directory on disk, labelled when there are several. */ +export interface LogsSource { + dir: string + /** The app the directory belongs to, when a workspace is read as a whole. */ + name?: string +} + +const WORKSPACE_PARENTS = ['apps', 'packages', 'examples', 'services'] + +/** + * The log directories of every app in the workspace: `apps//.evlog/logs` + * and the like, one level down from the root. Only directories that exist count, + * so a workspace with one app that writes reads as that app. + */ +function workspaceSources(root: string): LogsSource[] { + const sources: LogsSource[] = [] + for (const parent of WORKSPACE_PARENTS) { + const base = join(root, parent) + if (!existsSync(base)) continue + for (const entry of readdirSync(base, { withFileTypes: true })) { + if (!entry.isDirectory()) continue + const dir = join(base, entry.name, '.evlog', 'logs') + if (existsSync(dir)) sources.push({ dir, name: entry.name }) + } + } + return sources +} + +/** + * Where the events are. `--dir` wins; otherwise the directory the project + * already writes to, else every app of the workspace that writes, else the + * directory the fs drain is configured for, which may not exist yet. + */ +export async function resolveLogsSources(ctx: CliContext, dir: string | undefined): Promise { + if (dir) return [{ dir: resolve(ctx.cwd, dir) }] + const project: ProjectInfo = await resolveProject(ctx.cwd) + const sink = await findLogsSink(project) + if (sink) return [{ dir: sink.dir }] + const apps = workspaceSources(project.root) + if (apps.length > 0) return apps + const configured = await findConfiguredFsDrain(project, ctx.env) + if (configured) return [{ dir: resolve(project.packageDir, configured.dir) }] + throw cliErrors.LOGS_NO_SINK({ cwd: ctx.cwd }) +} + +export interface RunLogsOptions { + dir?: string + /** Read a JSON array of events from this URL (the memory drain's dev endpoint) instead of files. */ + url?: string + /** Keep reading as the app writes; resolves when `signal` aborts. */ + follow?: boolean + signal?: AbortSignal + /** Called for each event that arrives while following. */ + onEvent?: (event: Sourced) => void + /** Called when following has something to say that is not an event: the endpoint went quiet, or came back. */ + onNotice?: (message: string) => void + now?: Date + fetchFn?: typeof fetch + /** How often a followed `--url` is re-read. The endpoint is a snapshot, so there is nothing to wait on. */ + pollIntervalMs?: number +} + +function tag(event: WideEvent, name: string | undefined): Sourced { + if (!name) return event + return Object.defineProperty(event, SOURCE, { value: name, enumerable: false }) as Sourced +} + +async function fetchEvents(url: string, fetchFn: typeof fetch, signal?: AbortSignal): Promise { + let response: Response + try { + response = await fetchFn(url, { headers: { accept: 'application/json' }, signal }) + } catch (error) { + throw cliErrors.LOGS_URL_UNREACHABLE({ url, reason: error instanceof Error ? error.message : String(error) }) + } + if (!response.ok) throw cliErrors.LOGS_URL_UNREACHABLE({ url, reason: `HTTP ${response.status}` }) + const body = await response.json() as unknown + const events = Array.isArray(body) ? body : typeof body === 'object' && body !== null && Array.isArray((body as { events?: unknown }).events) ? (body as { events: unknown[] }).events : undefined + if (!events) throw cliErrors.LOGS_URL_UNREACHABLE({ url, reason: 'the response is not a JSON array of events' }) + return events as WideEvent[] +} + +const timeOf = (event: WideEvent): number => Date.parse(event.timestamp) || 0 + +/** Read the events the query asks for. Pure with respect to the context: nothing is written. */ +export async function runLogs(ctx: CliContext, args: LogsArgs, options: RunLogsOptions = {}): Promise { + const query = buildQuery(args, options.now) + const fetchFn = options.fetchFn ?? fetch + const inRange = (event: WideEvent): boolean => { + const at = timeOf(event) + if (query.since && at < query.since.getTime()) return false + if (query.until && at > query.until.getTime()) return false + if (query.level && !query.level.includes(event.level)) return false + return query.filter(event) + } + + let all: Sourced[] + let sources: string[] + if (options.url) { + all = (await fetchEvents(options.url, fetchFn, options.signal)).filter(inRange) + sources = [options.url] + } else { + const found = await resolveLogsSources(ctx, options.dir) + if (!options.follow && !found.some(source => existsSync(source.dir))) throw cliErrors.LOGS_NO_SINK({ cwd: ctx.cwd }) + all = [] + for (const source of found) { + for await (const event of readFsLogs({ dir: source.dir, since: query.since, until: query.until, level: query.level, filter: query.filter })) { + all.push(tag(event, found.length > 1 ? source.name : undefined)) + } + } + if (found.length > 1) all.sort((a, b) => timeOf(a) - timeOf(b)) + sources = found.map(source => prettyPath(ctx.cwd, source.dir)) + } + const result: LogsResult = { sources, query, matched: all.length, events: select(all, query), all } + + if (options.follow) { + /* `tail -f` shows the end of the file before it waits, and the caller only + renders what it is handed, so the events already found go through the + same path as the ones still to come. */ + for (const event of result.events) options.onEvent?.(event) + if (options.url) await followUrl(options.url, all, inRange, options) + else await followDirs(await resolveLogsSources(ctx, options.dir), query, options) + } + return result +} + +async function followDirs(sources: LogsSource[], query: LogsQuery, options: RunLogsOptions): Promise { + const label = sources.length > 1 + await Promise.all(sources.map(async (source) => { + for await (const event of tailFsLogs({ dir: source.dir, fromEnd: true, level: query.level, filter: query.filter, pollIntervalMs: 250, signal: options.signal })) { + options.onEvent?.(tag(event, label ? source.name : undefined)) + } + })) +} + +/** What a poll of the endpoint has already shown: the newest instant, and every event at it. */ +interface Seen { + newest: number + atNewest: Set +} + +function seenOf(events: WideEvent[], newest: number): Seen { + return { newest, atNewest: new Set(events.filter(event => timeOf(event) === newest).map(event => JSON.stringify(event))) } +} + +function isFresh(event: WideEvent, seen: Seen): boolean { + const at = timeOf(event) + return at > seen.newest || (at === seen.newest && !seen.atNewest.has(JSON.stringify(event))) +} + +function pause(ms: number, signal: AbortSignal | undefined): Promise { + return new Promise((done) => { + const timer = setTimeout(done, ms) + signal?.addEventListener('abort', () => { + clearTimeout(timer) + done() + }, { once: true }) + }) +} + +/** + * Consecutive failed polls before the silence is reported. A restart takes a + * few seconds, so warning on the first one would cry wolf; never warning + * leaves a follower that looks alive and delivers nothing. + */ +const QUIET_POLLS = 5 + +/** + * The endpoint is a snapshot, so following it means polling and keeping what + * was already shown apart from what is new: an event later than the newest + * shown, or one at the same instant that was not in the last snapshot. + */ +async function followUrl(url: string, shown: WideEvent[], inRange: (event: WideEvent) => boolean, options: RunLogsOptions): Promise { + const fetchFn = options.fetchFn ?? fetch + let seen = seenOf(shown, shown.reduce((max, event) => Math.max(max, timeOf(event)), 0)) + let failures = 0 + while (!options.signal?.aborted) { + await pause(options.pollIntervalMs ?? 1000, options.signal) + if (options.signal?.aborted) return + let events: WideEvent[] + try { + events = (await fetchEvents(url, fetchFn, options.signal)).filter(inRange) + if (failures >= QUIET_POLLS) options.onNotice?.(`${url} is answering again`) + failures = 0 + } catch (error) { + /* A follower outlives the app it watches: a dev server restarting is a + gap in the stream, not a reason to stop. */ + failures += 1 + if (failures === QUIET_POLLS) { + options.onNotice?.(`no answer from ${url} for ${failures} polls (${error instanceof Error ? error.message : String(error)}) — still trying`) + } + continue + } + const fresh: WideEvent[] = [] + for (const event of events) { + if (isFresh(event, seen)) fresh.push(event) + } + for (const event of fresh) options.onEvent?.(event) + if (fresh.length > 0) seen = seenOf(events, fresh.reduce((max, event) => Math.max(max, timeOf(event)), seen.newest)) + } +} + +/** + * `evlog logs` — the wide events the app wrote, from the terminal. + * Logic lives in {@link runLogs}; this file owns the citty surface. + */ +export default defineEvlogCommand('logs', { + meta: { name: 'logs' }, + args: { + what: { type: 'positional', required: false, description: '`errors`, `slow`, `stats`, or a request id to show in full' }, + follow: { type: 'boolean', alias: 'f', description: 'Keep reading as the app writes, like tail -f' }, + since: { type: 'string', description: 'Only events after this: a duration back (15m, 2h, 3d) or a date' }, + until: { type: 'string', description: 'Only events before this: a duration back or a date' }, + level: { type: 'string', description: 'Only these levels, comma-separated (error,fatal)' }, + path: { type: 'string', description: 'Only requests on this exact path' }, + status: { type: 'string', description: 'Only this status (500) or class (5xx)' }, + where: { type: 'string', description: 'Only events where a field matches: user.id=42, payment.amount>5000, error.message~declined, audit, !error (repeatable)' }, + over: { type: 'string', description: 'For `slow`: the duration a request has to exceed (default 500ms)' }, + limit: { type: 'string', description: 'Most events to show (default 50)' }, + dir: { type: 'string', description: 'Log directory (default: the project\'s .evlog/logs, or every app\'s in a workspace)' }, + url: { type: 'string', description: 'Read the memory drain\'s dev endpoint instead of files (a JSON array of events)' }, + }, + async run({ args, cli, ui }) { + const style = createStyle(cli) + const controller = new AbortController() + const stop = (): void => controller.abort() + if (args.follow) process.once('SIGINT', stop) + + let result: LogsResult + try { + result = await runLogs(cli, args as LogsArgs, { + dir: args.dir, + url: args.url, + follow: args.follow, + signal: controller.signal, + onEvent: (event) => { + if (args.json) ui.stdout(JSON.stringify(event)) + else ui.human(formatLine(style, event)) + }, + onNotice: message => ui.human(style.paint('dim', message)), + }) + } catch (error) { + if (error instanceof EvlogError) { + ui.done({ + jsonMode: args.json, + json: { error: { code: error.code, message: error.message, why: error.why, fix: error.fix } }, + human: error.fix ? `${error.message}\n→ ${error.fix}` : error.message, + }) + const failed = error.code === cliErrors.LOGS_NO_SINK.code || error.code === cliErrors.LOGS_URL_UNREACHABLE.code + ui.exit(failed ? EXIT_FAIL : EXIT_USAGE) + return + } + throw error + } finally { + process.off('SIGINT', stop) + } + + telemetry.set({ + logsView: result.query.view, + logsFollow: args.follow === true, + logsEvents: result.matched, + logsWhere: result.query.where.length, + logsSources: result.sources.length, + logsUrl: args.url !== undefined, + } as unknown as Record) + + /* While following, the one-shot part was already streamed line by line + before the tail started, so the report is only for the one-shot run. */ + if (args.follow) return + ui.done({ + jsonMode: args.json, + json: { + sources: result.sources, + view: result.query.view, + count: result.events.length, + matched: result.matched, + ...(result.query.view === 'stats' ? { stats: computeStats(result.all) } : { events: result.events }), + }, + human: formatLogsReport(cli, result), + }) + }, +}) diff --git a/packages/cli/src/index.ts b/packages/cli/src/index.ts index 0655be2f9..eae79fcec 100644 --- a/packages/cli/src/index.ts +++ b/packages/cli/src/index.ts @@ -5,6 +5,7 @@ import { COMMON_ARGS } from './lib/command' import { TELEMETRY_ENDPOINT, TOOL_NAME, VERSION } from './lib/constants' import { resolveCliEnvironment } from './lib/environment' import { INIT_TELEMETRY_FIELDS } from './lib/init/telemetry' +import { LOGS_TELEMETRY_FIELDS } from './lib/logs/query' import { MAP_TELEMETRY_FIELDS } from './lib/map/telemetry-fields' /** @@ -34,7 +35,7 @@ export const main = withTelemetry( can be calibrated against reality. Values are ids from this CLI's own catalog — the allowlist is what keeps a free-text answer from ever being sent. */ - collect: { fields: { ...INIT_TELEMETRY_FIELDS, ...MAP_TELEMETRY_FIELDS } }, + collect: { fields: { ...INIT_TELEMETRY_FIELDS, ...LOGS_TELEMETRY_FIELDS, ...MAP_TELEMETRY_FIELDS } }, }, ) diff --git a/packages/cli/src/lib/errors.ts b/packages/cli/src/lib/errors.ts index fa31ff609..6f9e36ac3 100644 --- a/packages/cli/src/lib/errors.ts +++ b/packages/cli/src/lib/errors.ts @@ -246,6 +246,72 @@ export const cliErrors = defineErrorCatalog('cli', { fix: 'Drop --json, or pass --format json', tags: ['map'], }, + LOGS_NO_SINK: { + status: 404, + message: ({ cwd }: { cwd: string }) => + `No local logs under ${cwd}`, + why: 'There is no .evlog/logs directory here and no fs drain is configured, so nothing has been written to read', + fix: 'Run evlog init --drain fs, start the app and make a request, or pass --dir ', + link: 'https://evlog.dev/cli/logs', + tags: ['logs'], + }, + LOGS_INVALID_TIME: { + status: 400, + message: ({ flag, value }: { flag: string, value: string }) => + `Invalid --${flag} "${value}"`, + why: 'A time bound that cannot be read would silently become no bound, and the run would show everything', + fix: 'Pass a duration back from now (15m, 2h, 3d) or a date (2026-10-01, 2026-10-01T09:00)', + tags: ['logs'], + }, + LOGS_INVALID_LEVEL: { + status: 400, + message: ({ value }: { value: string }) => + `Unknown level "${value}"`, + why: 'Levels are the six evlog writes', + fix: 'Pass one or more of: trace, debug, info, warn, error, fatal', + tags: ['logs'], + }, + LOGS_INVALID_STATUS: { + status: 400, + message: ({ value }: { value: string }) => + `Invalid --status "${value}"`, + why: 'A status filter that cannot be read would silently match nothing', + fix: 'Pass a status (404) or a class (4xx)', + tags: ['logs'], + }, + LOGS_INVALID_DURATION: { + status: 400, + message: ({ flag, value }: { flag: string, value: string }) => + `Invalid --${flag} "${value}"`, + why: 'A duration that cannot be read would silently fall back to the default', + fix: 'Pass milliseconds (500) or a unit (500ms, 1.5s)', + tags: ['logs'], + }, + LOGS_INVALID_WHERE: { + status: 400, + message: ({ value }: { value: string }) => + `Invalid --where "${value}"`, + why: 'A clause that cannot be read would silently match everything', + fix: 'Write field=value, field!=value, field>n, field>=n, field + `Could not read events from ${url}: ${reason}`, + why: 'The memory drain only exists while the app runs, and only where the app exposes readMemoryLogs() over HTTP', + fix: 'Start the app, check the endpoint returns a JSON array of events, and pass its URL to --url', + link: 'https://evlog.dev/cli/logs', + tags: ['logs'], + }, + LOGS_INVALID_LIMIT: { + status: 400, + message: ({ value }: { value: string }) => + `Invalid --limit "${value}"`, + why: 'A limit that cannot be read would silently become the default', + fix: 'Pass a whole number of 1 or more, e.g. --limit 20', + tags: ['logs'], + }, }) declare module 'evlog' { diff --git a/packages/cli/src/lib/logs/query.ts b/packages/cli/src/lib/logs/query.ts new file mode 100644 index 000000000..ec261b2eb --- /dev/null +++ b/packages/cli/src/lib/logs/query.ts @@ -0,0 +1,332 @@ +import type { LogLevel, WideEvent } from 'evlog' +import { cliErrors } from '../errors' + +/** What the run shows: the latest events, the failures, the slowest, or one request. */ +const VIEWS = ['recent', 'errors', 'slow', 'trace', 'stats'] as const +export type LogsView = typeof VIEWS[number] + +/** + * String fields of the `evlog logs` telemetry, with the exact set of values each may take. + * Registered on the root command without loading the reader. + */ +export const LOGS_TELEMETRY_FIELDS = { + logsView: VIEWS, +} as const satisfies Record + +const LEVELS: readonly LogLevel[] = ['trace', 'debug', 'info', 'warn', 'error', 'fatal'] + +const DURATION_UNITS: Record = { ms: 1, s: 1_000, m: 60_000, h: 3_600_000, d: 86_400_000 } + +/** `500ms`, `1.5s`, `15m`, `2h`, `3d`; a bare number is milliseconds. */ +export function parseDuration(value: string): number | undefined { + const match = /^(\d+(?:\.\d+)?)(ms|s|m|h|d)?$/.exec(value.trim()) + if (!match) return undefined + return Number(match[1]) * DURATION_UNITS[match[2] ?? 'ms']! +} + +/** + * `--since` and `--until` take a duration back from now (`15m`) or a date + * (`2026-10-01`, `2026-10-01T09:00`). `now` is a parameter so a test does not + * depend on the clock. + */ +export function parseTime(flag: 'since' | 'until', value: unknown, now: Date): Date | undefined { + if (typeof value !== 'string' || value.length === 0) return undefined + const ago = parseDuration(value) + if (ago !== undefined) return new Date(now.getTime() - ago) + const at = Date.parse(value) + if (Number.isNaN(at)) throw cliErrors.LOGS_INVALID_TIME({ flag, value }) + return new Date(at) +} + +export function parseLevels(value: unknown): LogLevel[] | undefined { + if (typeof value !== 'string' || value.length === 0) return undefined + const levels = value.split(',').map(level => level.trim()) + for (const level of levels) { + if (!(LEVELS as readonly string[]).includes(level)) throw cliErrors.LOGS_INVALID_LEVEL({ value: level }) + } + return levels as LogLevel[] +} + +/** `500` matches that status; `5xx` the whole class. */ +export function parseStatus(value: unknown): ((status: number) => boolean) | undefined { + if (typeof value !== 'string' || value.length === 0) return undefined + const clazz = /^([1-5])xx$/i.exec(value) + if (clazz) { + const hundreds = Number(clazz[1]) + return status => Math.floor(status / 100) === hundreds + } + const exact = Number(value) + if (!Number.isInteger(exact) || exact < 100 || exact > 599) throw cliErrors.LOGS_INVALID_STATUS({ value }) + return status => status === exact +} + +export function parseOver(value: unknown): number | undefined { + if (typeof value !== 'string' || value.length === 0) return undefined + const ms = parseDuration(value) + if (ms === undefined) throw cliErrors.LOGS_INVALID_DURATION({ flag: 'over', value }) + return ms +} + +const DEFAULT_LIMIT = 50 + +export function parseLimit(value: unknown): number { + if (typeof value !== 'string' || value.length === 0) return DEFAULT_LIMIT + const limit = Number(value) + if (!Number.isInteger(limit) || limit < 1) throw cliErrors.LOGS_INVALID_LIMIT({ value }) + return limit +} + +/** One `--where` clause: a dotted field, an operator, and the value it is held against. */ +export interface Where { + path: string[] + op: '=' | '!=' | '>' | '>=' | '<' | '<=' | '~' | 'exists' | 'absent' + value: string | number | boolean | RegExp | undefined +} + +const WHERE = /^(!?)([\w.$-]+)(?:(>=|<=|!=|=|>|<|~)(.*))?$/s + +function coerce(raw: string): string | number | boolean { + if (raw === 'true') return true + if (raw === 'false') return false + const number = Number(raw) + return raw.trim() !== '' && !Number.isNaN(number) ? number : raw +} + +/** + * `payment.amount>5000`, `audit.outcome=failure`, `error.message~declined`, + * `user.id`, `!error`. A quoted value keeps its quotes off: `path="/a b"`. + */ +export function parseWhere(raw: string): Where { + const match = WHERE.exec(raw.trim()) + if (!match) throw cliErrors.LOGS_INVALID_WHERE({ value: raw }) + const [, negated, key, op, value] = match + const path = key!.split('.') + if (op === undefined) return { path, op: negated ? 'absent' : 'exists', value: undefined } + if (negated) throw cliErrors.LOGS_INVALID_WHERE({ value: raw }) + if (/^[=<>~!]/.test(value!)) throw cliErrors.LOGS_INVALID_WHERE({ value: raw }) + const text = value!.replace(/^(["'])(.*)\1$/s, '$2') + if (op === '~') { + try { + return { path, op, value: new RegExp(text, 'i') } + } catch { + throw cliErrors.LOGS_INVALID_WHERE({ value: raw }) + } + } + return { path, op: op as Where['op'], value: coerce(text) } +} + +export function parseWheres(value: unknown): Where[] { + const raws = Array.isArray(value) ? value : typeof value === 'string' && value.length > 0 ? [value] : [] + return raws.map(raw => parseWhere(String(raw))) +} + +function read(event: WideEvent, path: string[]): unknown { + let current: unknown = event + for (const key of path) { + if (typeof current !== 'object' || current === null) return undefined + current = (current as Record)[key] + } + return current +} + +export function matchesWhere(event: WideEvent, where: Where): boolean { + const actual = read(event, where.path) + if (where.op === 'exists') return actual !== undefined && actual !== null + if (where.op === 'absent') return actual === undefined || actual === null + if (actual === undefined || actual === null) return false + if (where.op === '~') return where.value instanceof RegExp && where.value.test(typeof actual === 'string' ? actual : JSON.stringify(actual)) + const expected = where.value + /* A numeric field does not always arrive as a number — a header, an env var + or a hand-written payload carries it as text, and `"10000" > "5000"` is + false lexicographically. Against a numeric clause, read it as the number + it is rather than silently answering the wrong question. */ + const number = typeof actual === 'number' + ? actual + : typeof actual === 'string' && actual.trim() !== '' ? Number(actual) : Number.NaN + if (typeof expected === 'number' && !Number.isNaN(number)) { + switch (where.op) { + case '=': return number === expected + case '!=': return number !== expected + case '>': return number > expected + case '>=': return number >= expected + case '<': return number < expected + case '<=': return number <= expected + } + } + const left = typeof actual === 'object' ? JSON.stringify(actual) : String(actual) + const right = String(expected) + switch (where.op) { + case '=': return left === right + case '!=': return left !== right + case '>': return left > right + case '>=': return left >= right + case '<': return left < right + case '<=': return left <= right + } + return false +} + +export interface LogsQuery { + view: LogsView + where: Where[] + /** The request or trace id a `trace` view looks for. */ + id?: string + since?: Date + until?: Date + level?: LogLevel[] + limit: number + /** Lower bound on `durationMs` for the `slow` view. */ + over: number + /** Every filter the flags asked for, as one predicate for the reader. */ + filter: (event: WideEvent) => boolean +} + +export interface LogsArgs { + what?: string + since?: string + until?: string + level?: string + path?: string + status?: string + over?: string + limit?: string + where?: string | string[] +} + +const DEFAULT_OVER = 500 + +export function field(event: WideEvent, key: string): unknown { + return (event as Record)[key] +} + +function text(event: WideEvent, key: string): string | undefined { + const value = field(event, key) + return typeof value === 'string' ? value : undefined +} + +function number(event: WideEvent, key: string): number | undefined { + const value = field(event, key) + return typeof value === 'number' ? value : undefined +} + +/** A failure by any of the three signals an event can carry: level, status, an error block. */ +export function isError(event: WideEvent): boolean { + if (event.level === 'error' || event.level === 'fatal') return true + const status = number(event, 'status') + if (status !== undefined && status >= 500) return true + const error = field(event, 'error') + return typeof error === 'object' && error !== null +} + +const ID_FIELDS = ['requestId', 'traceId', 'spanId', '_parentRequestId'] as const + +/** + * Whether the event belongs to the request: an exact id, or a prefix of at + * least eight characters, so the first block of a UUID is enough to type. + */ +export function matchesId(event: WideEvent, id: string): boolean { + return ID_FIELDS.some((key) => { + const value = text(event, key) + if (!value) return false + return value === id || (id.length >= 8 && value.startsWith(id)) + }) +} + +/** Turn the flags into a query. Validation happens here, before any file is read. */ +export function buildQuery(args: LogsArgs, now = new Date()): LogsQuery { + const since = parseTime('since', args.since, now) + const until = parseTime('until', args.until, now) + const level = parseLevels(args.level) + const status = parseStatus(args.status) + const over = parseOver(args.over) ?? DEFAULT_OVER + const limit = parseLimit(args.limit) + const path = typeof args.path === 'string' && args.path.length > 0 ? args.path : undefined + const where = parseWheres(args.where) + + const what = args.what?.trim() + const view: LogsView = what === 'errors' ? 'errors' : what === 'slow' ? 'slow' : what === 'stats' ? 'stats' : what ? 'trace' : 'recent' + const id = view === 'trace' ? what : undefined + + const filter = (event: WideEvent): boolean => { + if (path !== undefined && text(event, 'path') !== path) return false + if (status !== undefined) { + const value = number(event, 'status') + if (value === undefined || !status(value)) return false + } + if (view === 'errors' && !isError(event)) return false + if (view === 'slow' && (number(event, 'durationMs') ?? -1) < over) return false + if (id !== undefined && !matchesId(event, id)) return false + return where.every(clause => matchesWhere(event, clause)) + } + + return { view, id, where, since, until, level, limit, over, filter } +} + +/** + * The events a one-shot run shows, from everything the reader yielded in + * file order: the last `limit` of them, oldest first, so the newest is at the + * bottom like `tail`. The `slow` view is the exception: worst first. + */ +export function select(events: WideEvent[], query: LogsQuery): WideEvent[] { + if (query.view === 'stats') return [] + if (query.view === 'slow') { + return [...events] + .sort((a, b) => (number(b, 'durationMs') ?? 0) - (number(a, 'durationMs') ?? 0)) + .slice(0, query.limit) + } + return events.slice(-query.limit) +} + +export interface RouteStats { + route: string + count: number + errors: number + p50: number | undefined + p95: number | undefined +} + +export interface LogsStats { + total: number + errors: number + byRoute: RouteStats[] + byStatus: Record + byLevel: Record +} + +function percentile(sorted: number[], p: number): number | undefined { + if (sorted.length === 0) return undefined + return sorted[Math.min(sorted.length - 1, Math.ceil(sorted.length * p) - 1)] +} + +/** The shape of the traffic: per route, per status class, per level. Routes with the most errors first, then the busiest. */ +export function computeStats(events: WideEvent[]): LogsStats { + const routes = new Map() + const byStatus: Record = {} + const byLevel: Record = {} + let errors = 0 + for (const event of events) { + const method = text(event, 'method') + const route = `${method ? `${method} ` : ''}${text(event, 'path') ?? text(event, 'operation') ?? event.service}` + const entry = routes.get(route) ?? { count: 0, errors: 0, durations: [] } + entry.count += 1 + const failed = isError(event) + if (failed) { + entry.errors += 1 + errors += 1 + } + const duration = number(event, 'durationMs') + if (duration !== undefined) entry.durations.push(duration) + routes.set(route, entry) + const status = number(event, 'status') + const statusKey = status === undefined ? 'none' : `${Math.floor(status / 100)}xx` + byStatus[statusKey] = (byStatus[statusKey] ?? 0) + 1 + byLevel[event.level] = (byLevel[event.level] ?? 0) + 1 + } + const byRoute = [...routes.entries()] + .map(([route, entry]) => { + const sorted = [...entry.durations].sort((a, b) => a - b) + return { route, count: entry.count, errors: entry.errors, p50: percentile(sorted, 0.5), p95: percentile(sorted, 0.95) } + }) + .sort((a, b) => b.errors - a.errors || b.count - a.count || a.route.localeCompare(b.route)) + return { total: events.length, errors, byRoute, byStatus, byLevel } +} diff --git a/packages/cli/src/lib/logs/render.ts b/packages/cli/src/lib/logs/render.ts new file mode 100644 index 000000000..68e957a75 --- /dev/null +++ b/packages/cli/src/lib/logs/render.ts @@ -0,0 +1,221 @@ +import type { WideEvent } from 'evlog' +import type { CliContext } from '../../core/context' +import { createStyle } from '../../core/output' +import type { Style, StyleCode } from '../../core/output' +import { computeStats, field, isError } from './query' +import type { LogsQuery, LogsStats } from './query' + +/** Fields every request event carries, shown in the fixed columns rather than the summary. */ +const STANDARD = new Set([ + 'timestamp', 'level', 'service', 'environment', 'version', 'commitHash', 'region', + 'duration', 'durationMs', 'method', 'path', 'status', 'requestId', 'traceId', 'spanId', + '_parentRequestId', 'operation', 'requestLogs', 'userAgent', 'source', 'error', 'audit', +]) + +function str(value: unknown): string | undefined { + return typeof value === 'string' ? value : undefined +} + +function obj(value: unknown): Record | undefined { + return typeof value === 'object' && value !== null && !Array.isArray(value) ? value as Record : undefined +} + +function clock(timestamp: string): string { + const at = new Date(timestamp) + if (Number.isNaN(at.getTime())) return '--:--:--' + return at.toTimeString().slice(0, 8) +} + +function statusColor(status: number | undefined, level: string): StyleCode { + if (level === 'error' || level === 'fatal' || (status !== undefined && status >= 500)) return 'red' + if (level === 'warn' || (status !== undefined && status >= 400)) return 'yellow' + return 'green' +} + +/** `{ a: 1, b: { c: 2 } }` → `a=1 b{…}`; the business fields, as much as fits in a line. */ +function fields(event: WideEvent, max = 3): string { + const out: string[] = [] + for (const [key, value] of Object.entries(event)) { + if (STANDARD.has(key) || value === undefined || value === null) continue + if (typeof value === 'object') { + const inner = obj(value) + const scalar = inner && Object.entries(inner).find(([, v]) => typeof v !== 'object') + out.push(scalar ? `${key}.${scalar[0]}=${String(scalar[1])}` : `${key}{…}`) + } else { + out.push(`${key}=${String(value)}`) + } + if (out.length === max) break + } + return out.join(' ') +} + +/** The one thing to know about the event: the error, the audit record, or the business fields. */ +function summary(event: WideEvent): { text: string, color?: StyleCode } { + const error = obj(field(event, 'error')) + if (error) { + const data = obj(error.data) + const name = str(error.code) ?? str(data?.code) ?? str(error.name) ?? 'error' + const why = str(data?.why) ?? str(error.why) + return { text: `✗ ${name}: ${str(error.message) ?? ''}${why ? ` · ${why}` : ''}`, color: 'red' } + } + const audit = obj(event.audit) + if (audit) { + const actor = obj(audit.actor) + const target = obj(audit.target) + const who = actor ? `${str(actor.type) ?? ''}:${str(actor.id) ?? ''}` : '' + const what = target ? ` → ${str(target.type) ?? ''}:${str(target.id) ?? ''}` : '' + return { text: `audit ${str(audit.action) ?? ''} ${who}${what} ${str(audit.outcome) ?? ''}`.trim(), color: 'magenta' } + } + return { text: fields(event) } +} + +/** The app an event came from when several directories are read, kept off the event itself. */ +export const SOURCE = Symbol('evlog.source') +export type Sourced = WideEvent & { [SOURCE]?: string } + +/** One event on one line: time, request, status, duration, and what mattered. */ +export function formatLine(style: Style, event: Sourced): string { + const status = typeof field(event, 'status') === 'number' ? field(event, 'status') as number : undefined + const method = str(field(event, 'method')) + const path = str(field(event, 'path')) ?? str(field(event, 'operation')) ?? event.service + const where = method ? `${method.padEnd(6)} ${path}` : ` ${path}` + const { text, color } = summary(event) + const source = event[SOURCE] + const columns = [ + style.paint('dim', clock(event.timestamp)), + ...(source ? [style.paint('cyan', source.padEnd(12))] : []), + where.padEnd(44), + style.paint(statusColor(status, event.level), status !== undefined ? String(status) : event.level.padEnd(3)), + style.paint('dim', (event.duration ?? '').padStart(7)), + color ? style.paint(color, text) : text, + ] + return columns.join(' ').trimEnd() +} + +function section(style: Style, title: string, rows: Array<[string, string | undefined]>): string[] { + const kept = rows.filter((row): row is [string, string] => row[1] !== undefined && row[1] !== '') + if (kept.length === 0) return [] + const width = Math.max(...kept.map(([key]) => key.length)) + return [style.paint('dim', title.toUpperCase()), ...kept.map(([key, value]) => ` ${key.padEnd(width)} ${value}`), ''] +} + +/** The whole event, grouped by what a reader looks for first, then the rest as JSON. */ +export function formatEvent(style: Style, event: WideEvent): string { + const lines: string[] = [formatLine(style, event), ''] + const error = obj(field(event, 'error')) + const data = error ? obj(error.data) : undefined + const audit = obj(event.audit) + const actor = audit ? obj(audit.actor) : undefined + const target = audit ? obj(audit.target) : undefined + + lines.push(...section(style, 'request', [ + ['requestId', str(field(event, 'requestId'))], + ['traceId', str(field(event, 'traceId'))], + ['parent', str(field(event, '_parentRequestId'))], + ['service', `${event.service} · ${event.environment}${event.version ? ` · ${event.version}` : ''}`], + ['at', event.timestamp], + ])) + if (error) { + const stack = str(error.stack)?.split('\n').slice(1, 4).map(line => line.trim()).join('\n' + ' '.repeat(9)) + lines.push(...section(style, 'error', [ + ['name', str(error.name)], + ['message', str(error.message)], + ['status', error.statusCode !== undefined ? String(error.statusCode) : undefined], + ['code', str(error.code) ?? str(data?.code)], + ['why', str(data?.why) ?? str(error.why)], + ['fix', str(data?.fix) ?? str(error.fix)], + ['link', str(data?.link) ?? str(error.link)], + ['stack', stack], + ])) + } + if (audit) { + lines.push(...section(style, 'audit', [ + ['action', str(audit.action)], + ['actor', actor ? `${str(actor.type) ?? ''}:${str(actor.id) ?? ''}` : undefined], + ['target', target ? `${str(target.type) ?? ''}:${str(target.id) ?? ''}` : undefined], + ['outcome', str(audit.outcome)], + ['reason', str(audit.reason)], + ])) + } + const rest = Object.fromEntries(Object.entries(event).filter(([key]) => !STANDARD.has(key))) + if (Object.keys(rest).length > 0) { + lines.push(style.paint('dim', 'FIELDS'), ...JSON.stringify(rest, null, 2).split('\n').map(line => ` ${line}`)) + } + return lines.join('\n').trimEnd() +} + +export interface LogsResult { + /** Where the events came from: a directory per line, or the URL. */ + sources: string[] + query: LogsQuery + /** Every event that matched, in the reader's order. */ + matched: number + /** The events shown: `select()` applied to `matched`. */ + events: Sourced[] + /** Every matched event, for `stats`. */ + all: Sourced[] +} + +function describe(query: LogsQuery): string { + const parts: string[] = [] + if (query.view === 'errors') parts.push('errors') + if (query.view === 'slow') parts.push(`slower than ${query.over}ms`) + if (query.view === 'trace') parts.push(`request ${query.id}`) + for (const clause of query.where) parts.push(`${clause.path.join('.')}${clause.op === 'exists' ? '' : clause.op === 'absent' ? ' absent' : `${clause.op}${String(clause.value)}`}`) + if (query.since) parts.push(`since ${query.since.toISOString()}`) + if (query.until) parts.push(`until ${query.until.toISOString()}`) + if (query.level) parts.push(`level ${query.level.join(',')}`) + return parts.join(' · ') +} + +function formatStats(style: Style, stats: LogsStats): string[] { + const lines: string[] = [] + const ms = (value: number | undefined): string => (value === undefined ? '–' : `${value}ms`) + const width = Math.max(5, ...stats.byRoute.map(row => row.route.length)) + lines.push(style.paint('dim', `${'ROUTE'.padEnd(width)} ${'COUNT'.padStart(5)} ${'ERRORS'.padStart(6)} ${'P50'.padStart(7)} ${'P95'.padStart(7)}`)) + for (const row of stats.byRoute) { + const errors = row.errors > 0 ? style.paint('red', String(row.errors).padStart(6)) : String(row.errors).padStart(6) + lines.push(`${row.route.padEnd(width)} ${String(row.count).padStart(5)} ${errors} ${ms(row.p50).padStart(7)} ${ms(row.p95).padStart(7)}`) + } + const classes = Object.entries(stats.byStatus).sort().map(([key, count]) => `${key} ${count}`).join(' · ') + const levels = Object.entries(stats.byLevel).sort((a, b) => b[1] - a[1]).map(([key, count]) => `${key} ${count}`).join(' · ') + lines.push('', `${style.paint('dim', 'status')} ${classes}`, `${style.paint('dim', 'level ')} ${levels}`) + return lines +} + +/** The one-shot report: a header, one line per event (or the full event for a trace), and what to try next. */ +export function formatLogsReport(ctx: CliContext, result: LogsResult): string { + const style = createStyle(ctx) + const { query, events, matched } = result + const lines: string[] = [] + const filters = describe(query) + const where = result.sources.length === 1 ? result.sources[0] : `${result.sources.length} apps` + if (query.view === 'stats') { + lines.push(style.paint('dim', `${matched} event${matched === 1 ? '' : 's'} · ${where}${filters ? ` · ${filters}` : ''}`), '') + if (matched === 0) return [...lines, 'no event matches'].join('\n') + return [...lines, ...formatStats(style, computeStats(result.all))].join('\n') + } + const shown = events.length === matched ? `${matched} event${matched === 1 ? '' : 's'}` : `${events.length} of ${matched} events` + lines.push(style.paint('dim', `${shown} · ${where}${filters ? ` · ${filters}` : ''}`), '') + + if (events.length === 0) { + lines.push(query.view === 'trace' ? `no event carries the id ${query.id}` : 'no event matches') + lines.push('', style.paint('dim', 'the fs drain writes on every request · evlog logs -f follows new events')) + return lines.join('\n') + } + + if (query.view === 'trace') { + for (const event of events) lines.push(formatEvent(style, event), '') + return lines.join('\n').trimEnd() + } + + for (const event of events) lines.push(formatLine(style, event)) + const failures = events.filter(isError).length + const hints: string[] = [] + if (query.view === 'recent' && failures > 0) hints.push(`evlog logs errors — the ${failures} that failed`) + hints.push('evlog logs — one request in full') + if (query.view !== 'slow') hints.push('evlog logs slow — worst first') + if (query.view === 'recent') hints.push('evlog logs stats — by route') + lines.push('', style.paint('dim', hints.join(' · '))) + return lines.join('\n') +} diff --git a/packages/cli/test/logs.command.test.ts b/packages/cli/test/logs.command.test.ts new file mode 100644 index 000000000..18c0cf728 --- /dev/null +++ b/packages/cli/test/logs.command.test.ts @@ -0,0 +1,460 @@ +import { appendFile, mkdir, mkdtemp, rm, writeFile } from 'node:fs/promises' +import { tmpdir } from 'node:os' +import { join } from 'node:path' +import { runCommand } from 'citty' +import type { WideEvent } from 'evlog' +import { afterEach, describe, expect, it, vi } from 'vitest' +import logs, { runLogs } from '../src/commands/logs' +import { createContext } from '../src/core/context' +import type { CliContext } from '../src/core/context' +import { buildQuery, computeStats, matchesId, matchesWhere, parseDuration, parseTime, parseWhere } from '../src/lib/logs/query' +import { formatEvent, formatLine } from '../src/lib/logs/render' +import { createStyle } from '../src/core/output' + +const NOW = new Date('2026-10-01T12:00:00.000Z') +const tempDirs: string[] = [] + +function event(overrides: Record): WideEvent { + return { + timestamp: '2026-10-01T11:00:00.000Z', + level: 'info', + service: 'shop', + environment: 'development', + method: 'GET', + path: '/api/items', + status: 200, + durationMs: 12, + duration: '12ms', + requestId: 'aaaaaaaa-0000-4000-8000-000000000001', + ...overrides, + } as WideEvent +} + +/** Six requests over two days, one of them pretty-printed, in the fs drain's layout. */ +const EVENTS: WideEvent[] = [ + event({ timestamp: '2026-09-30T08:00:00.000Z', requestId: 'bbbbbbbb-0000-4000-8000-000000000002', path: '/api/health', durationMs: 2, duration: '2ms' }), + event({ timestamp: '2026-10-01T10:00:00.000Z', requestId: 'cccccccc-0000-4000-8000-000000000003', method: 'POST', path: '/api/checkout', status: 402, level: 'error', durationMs: 412, duration: '412ms', + error: { name: 'Error', message: 'Payment processing failed', statusCode: 402, data: { why: 'Card declined by issuer', fix: 'Use another card', link: 'https://docs.example.com/declined' }, stack: 'Error: Payment processing failed\n at handler (checkout.ts:12:3)\n at run (h3.mjs:2017:19)' }, + cart: { items: 3, total: 9999 } }), + event({ timestamp: '2026-10-01T10:30:00.000Z', requestId: 'dddddddd-0000-4000-8000-000000000004', _parentRequestId: 'aaaaaaaa-0000-4000-8000-000000000001', path: '/api/reports', durationMs: 1200, duration: '1.2s', report: { id: 'r-1' } }), + event({ timestamp: '2026-10-01T11:00:00.000Z', requestId: 'eeeeeeee-0000-4000-8000-000000000005', method: 'POST', path: '/api/refund', status: 200, durationMs: 80, duration: '80ms', + audit: { action: 'billing.refund', actor: { type: 'user', id: 'usr_42' }, target: { type: 'invoice', id: 'inv_1' }, outcome: 'success' } }), + event({ timestamp: '2026-10-01T11:30:00.000Z', requestId: 'ffffffff-0000-4000-8000-000000000006', path: '/api/items', status: 500, durationMs: 30, duration: '30ms' }), + event({ timestamp: '2026-10-01T11:45:00.000Z', requestId: 'aaaaaaaa-0000-4000-8000-000000000001', path: '/api/items', level: 'warn', durationMs: 700, duration: '700ms', user: { id: 'usr_7', plan: 'pro' } }), +] + +async function makeSink(): Promise { + const cwd = await mkdtemp(join(tmpdir(), 'evlog-cli-logs-')) + tempDirs.push(cwd) + await writeFile(join(cwd, 'package.json'), JSON.stringify({ name: 'shop' })) + const dir = join(cwd, '.evlog', 'logs') + await mkdir(dir, { recursive: true }) + /* The first day is pretty-printed, the way `pretty: true` writes it. */ + await writeFile(join(dir, '2026-09-30.jsonl'), `${JSON.stringify(EVENTS[0], null, 2)}\n`) + await writeFile(join(dir, '2026-10-01.jsonl'), `${EVENTS.slice(1).map(e => JSON.stringify(e)).join('\n') }\n`) + return cwd +} + +function fakeContext(cwd: string, overrides: Partial = {}): CliContext { + return createContext({ cwd, env: {}, nodeVersion: 'v22.0.0', tty: false, color: false, columns: 120, ...overrides }) +} + +function captureStdout(): string[] { + const out: string[] = [] + vi.spyOn(process.stdout, 'write').mockImplementation(((chunk: string | Uint8Array) => { + out.push(typeof chunk === 'string' ? chunk : Buffer.from(chunk).toString()) + return true + }) as typeof process.stdout.write) + vi.spyOn(process.stderr, 'write').mockImplementation(() => true) + return out +} + +afterEach(async () => { + vi.restoreAllMocks() + process.exitCode = undefined + await Promise.all(tempDirs.splice(0).map(dir => rm(dir, { recursive: true, force: true }))) +}) + +describe('parsing', () => { + it('reads durations with and without a unit', () => { + expect(parseDuration('500')).toBe(500) + expect(parseDuration('1.5s')).toBe(1500) + expect(parseDuration('15m')).toBe(900_000) + expect(parseDuration('2h')).toBe(7_200_000) + expect(parseDuration('3d')).toBe(259_200_000) + expect(parseDuration('soon')).toBeUndefined() + }) + + it('reads --since as a duration back or a date, and refuses the rest', () => { + expect(parseTime('since', '15m', NOW)?.toISOString()).toBe('2026-10-01T11:45:00.000Z') + expect(parseTime('since', '2026-09-30', NOW)?.toISOString()).toBe('2026-09-30T00:00:00.000Z') + expect(parseTime('since', undefined, NOW)).toBeUndefined() + expect(() => parseTime('since', 'yesterday-ish', NOW)).toThrow(/Invalid --since/) + }) + + it('picks the view from the positional', () => { + expect(buildQuery({}).view).toBe('recent') + expect(buildQuery({ what: 'errors' }).view).toBe('errors') + expect(buildQuery({ what: 'slow' }).view).toBe('slow') + expect(buildQuery({ what: 'cccccccc' })).toMatchObject({ view: 'trace', id: 'cccccccc' }) + }) + + it.each([ + [{ level: 'loud' }, /Unknown level/], + [{ status: '42' }, /Invalid --status/], + [{ status: '6xx' }, /Invalid --status/], + [{ over: 'fast' }, /Invalid --over/], + [{ limit: '0' }, /Invalid --limit/], + ])('rejects %o', (args, message) => { + expect(() => buildQuery(args)).toThrow(message) + }) + + it('reads every --where shape', () => { + expect(parseWhere('user.id=42')).toEqual({ path: ['user', 'id'], op: '=', value: 42 }) + expect(parseWhere('payment.amount>5000')).toMatchObject({ op: '>', value: 5000 }) + expect(parseWhere('status<=299')).toMatchObject({ op: '<=', value: 299 }) + expect(parseWhere('audit.outcome!=success')).toMatchObject({ op: '!=', value: 'success' }) + expect(parseWhere('error.message~declined')).toMatchObject({ op: '~' }) + expect(parseWhere('path="/a b"')).toMatchObject({ op: '=', value: '/a b' }) + expect(parseWhere('audit')).toEqual({ path: ['audit'], op: 'exists', value: undefined }) + expect(parseWhere('!error')).toEqual({ path: ['error'], op: 'absent', value: undefined }) + expect(parseWhere('cart.items=true')).toMatchObject({ value: true }) + }) + + it.each(['', '=1', '!user=1', 'a~[', 'a>>1'])('rejects --where %j', (raw) => { + expect(() => parseWhere(raw)).toThrow(/Invalid --where/) + }) + + it('compares numbers as numbers, strings as strings, and reaches into objects', () => { + const e = event({ user: { id: 'usr_7', plan: 'pro' }, cart: { total: 9999 } }) + expect(matchesWhere(e, parseWhere('cart.total>5000'))).toBe(true) + expect(matchesWhere(e, parseWhere('cart.total>10000'))).toBe(false) + expect(matchesWhere(e, parseWhere('user.plan=pro'))).toBe(true) + expect(matchesWhere(e, parseWhere('user.plan!=pro'))).toBe(false) + expect(matchesWhere(e, parseWhere('user.id~^usr_'))).toBe(true) + expect(matchesWhere(e, parseWhere('user'))).toBe(true) + expect(matchesWhere(e, parseWhere('!error'))).toBe(true) + expect(matchesWhere(e, parseWhere('error'))).toBe(false) + expect(matchesWhere(e, parseWhere('missing.deep=1'))).toBe(false) + }) + + it('reads a numeric field that arrived as text as the number it is', () => { + const e = event({ headers: { 'content-length': '10000' }, label: '5kg' }) + expect(matchesWhere(e, parseWhere('headers.content-length>5000'))).toBe(true) + expect(matchesWhere(e, parseWhere('headers.content-length<5000'))).toBe(false) + expect(matchesWhere(e, parseWhere('headers.content-length=10000'))).toBe(true) + /* Text that is not a number is still compared as text, not coerced. */ + expect(matchesWhere(e, parseWhere('label=5kg'))).toBe(true) + expect(matchesWhere(e, parseWhere('label=5'))).toBe(false) + }) + + it('takes several --where clauses and requires all of them', () => { + const query = buildQuery({ where: ['status=200', 'durationMs>50'] }) + expect(query.where).toHaveLength(2) + expect(query.filter(event({ status: 200, durationMs: 80 }))).toBe(true) + expect(query.filter(event({ status: 200, durationMs: 10 }))).toBe(false) + expect(buildQuery({ where: 'status=200' }).where).toHaveLength(1) + }) + + it('matches an id exactly, or by a prefix of at least eight characters', () => { + const e = event({ requestId: 'cccccccc-0000-4000-8000-000000000003', traceId: 'trace-1' }) + expect(matchesId(e, 'cccccccc-0000-4000-8000-000000000003')).toBe(true) + expect(matchesId(e, 'cccccccc')).toBe(true) + expect(matchesId(e, 'ccc')).toBe(false) + expect(matchesId(e, 'trace-1')).toBe(true) + }) +}) + +describe('runLogs', () => { + it('shows the last events oldest first, across both file formats', async () => { + const cwd = await makeSink() + const result = await runLogs(fakeContext(cwd), {}, { now: NOW }) + expect(result.sources).toEqual(['.evlog/logs']) + expect(result.matched).toBe(6) + expect(result.events.map(e => e.path)).toEqual(['/api/health', '/api/checkout', '/api/reports', '/api/refund', '/api/items', '/api/items']) + }) + + it('keeps the newest when --limit cuts the list', async () => { + const cwd = await makeSink() + const result = await runLogs(fakeContext(cwd), { limit: '2' }, { now: NOW }) + expect(result.events.map(e => e.status)).toEqual([500, 200]) + expect(result.matched).toBe(6) + }) + + it('errors: a failing status, an error level, or an error block', async () => { + const cwd = await makeSink() + const result = await runLogs(fakeContext(cwd), { what: 'errors' }, { now: NOW }) + expect(result.events.map(e => [e.path, e.status])).toEqual([['/api/checkout', 402], ['/api/items', 500]]) + }) + + it('slow: worst first, above --over', async () => { + const cwd = await makeSink() + const slow = await runLogs(fakeContext(cwd), { what: 'slow' }, { now: NOW }) + expect(slow.events.map(e => e.durationMs)).toEqual([1200, 700]) + const slower = await runLogs(fakeContext(cwd), { what: 'slow', over: '1s' }, { now: NOW }) + expect(slower.events.map(e => e.durationMs)).toEqual([1200]) + }) + + it('trace: every event carrying the id, by prefix', async () => { + const cwd = await makeSink() + const result = await runLogs(fakeContext(cwd), { what: 'aaaaaaaa' }, { now: NOW }) + /* The forked report event links back through `_parentRequestId`. */ + expect(result.events.map(e => e.path)).toEqual(['/api/reports', '/api/items']) + }) + + it('filters on time, level, path and status class together', async () => { + const cwd = await makeSink() + const ctx = fakeContext(cwd) + /* `since` is inclusive: the checkout at exactly 10:00 is two hours before noon. */ + expect((await runLogs(ctx, { since: '2h' }, { now: NOW })).events.map(e => e.timestamp)).toEqual(['2026-10-01T10:00:00.000Z', '2026-10-01T10:30:00.000Z', '2026-10-01T11:00:00.000Z', '2026-10-01T11:30:00.000Z', '2026-10-01T11:45:00.000Z']) + expect((await runLogs(ctx, { until: '2026-10-01T10:00:00.000Z' }, { now: NOW })).events).toHaveLength(2) + expect((await runLogs(ctx, { level: 'warn,error' }, { now: NOW })).events.map(e => e.level)).toEqual(['error', 'warn']) + expect((await runLogs(ctx, { path: '/api/items', status: '5xx' }, { now: NOW })).events).toHaveLength(1) + expect((await runLogs(ctx, { status: '402' }, { now: NOW })).events.map(e => e.path)).toEqual(['/api/checkout']) + }) + + it('--where composes with a view', async () => { + const cwd = await makeSink() + const ctx = fakeContext(cwd) + expect((await runLogs(ctx, { where: 'audit.actor.id=usr_42' }, { now: NOW })).events.map(e => e.path)).toEqual(['/api/refund']) + expect((await runLogs(ctx, { what: 'errors', where: 'error.data.why~declined' }, { now: NOW })).events.map(e => e.status)).toEqual([402]) + expect((await runLogs(ctx, { where: ['!error', 'durationMs>=700'] }, { now: NOW })).events.map(e => e.path)).toEqual(['/api/reports', '/api/items']) + }) + + it('stats: per route with errors first, then by status class and level', async () => { + const cwd = await makeSink() + const result = await runLogs(fakeContext(cwd), { what: 'stats' }, { now: NOW }) + expect(result.events).toEqual([]) + expect(result.matched).toBe(6) + const stats = computeStats(result.all) + expect(stats.total).toBe(6) + expect(stats.errors).toBe(2) + expect(stats.byRoute[0]).toEqual({ route: 'GET /api/items', count: 2, errors: 1, p50: 30, p95: 700 }) + expect(stats.byRoute[1]).toMatchObject({ route: 'POST /api/checkout', count: 1, errors: 1, p50: 412 }) + expect(stats.byStatus).toEqual({ '2xx': 4, '4xx': 1, '5xx': 1 }) + expect(stats.byLevel).toEqual({ info: 4, error: 1, warn: 1 }) + }) + + it('reads every app of a workspace when the root has no logs, labelling each event', async () => { + const root = await mkdtemp(join(tmpdir(), 'evlog-cli-logs-mono-')) + tempDirs.push(root) + await writeFile(join(root, 'package.json'), JSON.stringify({ name: 'mono', workspaces: ['apps/*'] })) + for (const [app, path, at] of [['web', '/home', '2026-10-01T10:00:00.000Z'], ['api', '/users', '2026-10-01T09:00:00.000Z']] as const) { + await mkdir(join(root, 'apps', app, '.evlog', 'logs'), { recursive: true }) + await writeFile(join(root, 'apps', app, 'package.json'), JSON.stringify({ name: app })) + await writeFile(join(root, 'apps', app, '.evlog', 'logs', '2026-10-01.jsonl'), `${JSON.stringify(event({ path, timestamp: at }))}\n`) + } + await mkdir(join(root, 'apps', 'docs')) + const result = await runLogs(fakeContext(root), {}, { now: NOW }) + expect(result.sources).toEqual(['apps/api/.evlog/logs', 'apps/web/.evlog/logs']) + expect(result.events.map(e => e.path)).toEqual(['/users', '/home']) + expect(formatLine(createStyle({ color: false }), result.events[0]!)).toMatch(/^\S+ api\s+GET \/users/) + }) + + it('reads a memory drain endpoint with --url, and follows it by polling', async () => { + const cwd = await mkdtemp(join(tmpdir(), 'evlog-cli-logs-url-')) + tempDirs.push(cwd) + const snapshot: WideEvent[] = [EVENTS[1]!, EVENTS[4]!] + const fetchFn = (() => Promise.resolve({ ok: true, status: 200, json: () => Promise.resolve(snapshot) })) as unknown as typeof fetch + const result = await runLogs(fakeContext(cwd), { what: 'errors' }, { url: 'http://localhost:3000/_evlog/logs', fetchFn, now: NOW }) + expect(result.sources).toEqual(['http://localhost:3000/_evlog/logs']) + expect(result.events.map(e => e.status)).toEqual([402, 500]) + + const wrapped = (() => Promise.resolve({ ok: true, status: 200, json: () => Promise.resolve({ events: snapshot }) })) as unknown as typeof fetch + expect((await runLogs(fakeContext(cwd), {}, { url: 'http://x', fetchFn: wrapped, now: NOW })).matched).toBe(2) + + const controller = new AbortController() + const seen: WideEvent[] = [] + const run = runLogs(fakeContext(cwd), {}, { + url: 'http://x', fetchFn, follow: true, signal: controller.signal, now: NOW, + onEvent: (e) => { + seen.push(e) + if (seen.length === 3) controller.abort() + }, + }) + await new Promise(resolve => setTimeout(resolve, 50)) + snapshot.push(event({ timestamp: '2026-10-01T11:59:00.000Z', path: '/api/new' })) + await run + expect(seen.map(e => e.path)).toEqual(['/api/checkout', '/api/items', '/api/new']) + }) + + it('a failed poll is a gap in the follow, not the end of it', async () => { + const cwd = await mkdtemp(join(tmpdir(), 'evlog-cli-logs-url-flaky-')) + tempDirs.push(cwd) + const snapshot: WideEvent[] = [EVENTS[0]!] + let polls = 0 + const flaky = (() => { + polls += 1 + /* The second call is the first poll: the app is restarting. */ + if (polls === 2) return Promise.reject(new Error('ECONNREFUSED')) + return Promise.resolve({ ok: true, status: 200, json: () => Promise.resolve(snapshot) }) + }) as unknown as typeof fetch + + const controller = new AbortController() + const seen: WideEvent[] = [] + const run = runLogs(fakeContext(cwd), {}, { + url: 'http://x', fetchFn: flaky, follow: true, signal: controller.signal, now: NOW, + onEvent: (e) => { + seen.push(e) + if (seen.length === 2) controller.abort() + }, + }) + await new Promise(resolve => setTimeout(resolve, 50)) + snapshot.push(event({ timestamp: '2026-10-01T11:59:00.000Z', path: '/api/back-up' })) + await run + expect(polls).toBeGreaterThanOrEqual(3) + expect(seen.map(e => e.path)).toEqual(['/api/health', '/api/back-up']) + }) + + it('hands the abort signal to the fetch, so a stalled poll can be interrupted', async () => { + const cwd = await mkdtemp(join(tmpdir(), 'evlog-cli-logs-url-signal-')) + tempDirs.push(cwd) + const signals: Array = [] + const controller = new AbortController() + const fetchFn = ((_url: string, init?: { signal?: AbortSignal }) => { + signals.push(init?.signal) + if (signals.length === 2) controller.abort() + return Promise.resolve({ ok: true, status: 200, json: () => Promise.resolve([EVENTS[1]!]) }) + }) as unknown as typeof fetch + + await runLogs(fakeContext(cwd), {}, { url: 'http://x', fetchFn, follow: true, signal: controller.signal, pollIntervalMs: 5, now: NOW }) + + expect(signals).toHaveLength(2) + expect(signals.every(signal => signal === controller.signal)).toBe(true) + }) + + it('says when a followed endpoint goes quiet, and when it answers again', async () => { + const cwd = await mkdtemp(join(tmpdir(), 'evlog-cli-logs-url-quiet-')) + tempDirs.push(cwd) + let calls = 0 + const fetchFn = (() => { + calls += 1 + /* The first call is the one-shot read; then six dead polls, then it is back. */ + if (calls > 1 && calls <= 7) return Promise.reject(new Error('ECONNREFUSED')) + return Promise.resolve({ ok: true, status: 200, json: () => Promise.resolve([EVENTS[1]!]) }) + }) as unknown as typeof fetch + + const controller = new AbortController() + const notices: string[] = [] + await runLogs(fakeContext(cwd), {}, { + url: 'http://x', + fetchFn, + follow: true, + signal: controller.signal, + pollIntervalMs: 5, + now: NOW, + onNotice: (message) => { + notices.push(message) + if (notices.length === 2) controller.abort() + }, + }) + + /* One line per outage, not one per poll: the sixth failure is silent. */ + expect(notices).toEqual([ + 'no answer from http://x for 5 polls (Could not read events from http://x: ECONNREFUSED) — still trying', + 'http://x is answering again', + ]) + }) + + it('an unreachable --url is a failure with the fix', async () => { + const cwd = await mkdtemp(join(tmpdir(), 'evlog-cli-logs-url-down-')) + tempDirs.push(cwd) + const down = (() => Promise.reject(new Error('ECONNREFUSED'))) as unknown as typeof fetch + await expect(runLogs(fakeContext(cwd), {}, { url: 'http://localhost:1', fetchFn: down })).rejects.toThrow(/Could not read events from http:\/\/localhost:1: ECONNREFUSED/) + const notJson = (() => Promise.resolve({ ok: true, status: 200, json: () => Promise.resolve({ hello: 1 }) })) as unknown as typeof fetch + await expect(runLogs(fakeContext(cwd), {}, { url: 'http://x', fetchFn: notJson })).rejects.toThrow(/not a JSON array/) + }) + + it('reads --dir as given and refuses a project with no sink', async () => { + const cwd = await makeSink() + const elsewhere = await mkdtemp(join(tmpdir(), 'evlog-cli-logs-other-')) + tempDirs.push(elsewhere) + await writeFile(join(elsewhere, 'package.json'), '{"name":"other"}') + const result = await runLogs(fakeContext(elsewhere), {}, { dir: join(cwd, '.evlog', 'logs'), now: NOW }) + expect(result.matched).toBe(6) + await expect(runLogs(fakeContext(elsewhere), {}, { now: NOW })).rejects.toThrow(/No local logs/) + }) + + it('follows: what it already found streams first, then what arrives, until the signal aborts', async () => { + const cwd = await makeSink() + const controller = new AbortController() + const seen: WideEvent[] = [] + const run = runLogs(fakeContext(cwd), { path: '/api/items' }, { + follow: true, + signal: controller.signal, + now: NOW, + onEvent: (event) => { + seen.push(event) + if (seen.length === 3) controller.abort() + }, + }) + await new Promise(resolve => setTimeout(resolve, 300)) + await appendFile(join(cwd, '.evlog', 'logs', '2026-10-01.jsonl'), `${JSON.stringify(event({ timestamp: '2026-10-01T11:50:00.000Z', path: '/api/other' }))}\n${JSON.stringify(event({ timestamp: '2026-10-01T11:51:00.000Z', path: '/api/items', status: 201 }))}\n`) + const result = await run + expect(result.matched).toBe(2) + /* The two already on disk, oldest first, then the one appended. */ + expect(seen.map(e => e.status)).toEqual([500, 200, 201]) + }) +}) + +describe('rendering', () => { + const style = createStyle({ color: false }) + + it('puts the error, the audit record, or the business fields at the end of the line', () => { + expect(formatLine(style, EVENTS[1]!)).toMatch(/POST {3}\/api\/checkout\s+402\s+412ms\s+✗ Error: Payment processing failed · Card declined by issuer$/) + expect(formatLine(style, EVENTS[3]!)).toMatch(/audit billing\.refund user:usr_42 → invoice:inv_1 success$/) + expect(formatLine(style, EVENTS[5]!)).toMatch(/user\.id=usr_7$/) + }) + + it('shows why, fix and the first frames of the stack for one event', () => { + const text = formatEvent(style, EVENTS[1]!) + expect(text).toContain('why Card declined by issuer') + expect(text).toContain('fix Use another card') + expect(text).toContain('at handler (checkout.ts:12:3)') + expect(text).toContain('"cart"') + expect(text).not.toContain('"error"') + }) +}) + +describe('logs command', () => { + it('--json is an envelope with the events and the counts', async () => { + const cwd = await makeSink() + const out = captureStdout() + await runCommand(logs, { rawArgs: ['--cwd', cwd, '--json', '--no-header', 'errors'] }) + const payload = JSON.parse(out.join('')) as { view: string, count: number, matched: number, events: Array<{ path: string }> } + expect(payload.view).toBe('errors') + expect(payload.count).toBe(2) + expect(payload.matched).toBe(2) + expect(payload.events.map(e => e.path)).toEqual(['/api/checkout', '/api/items']) + expect(process.exitCode).toBeUndefined() + }) + + it('a bad flag is a usage error, before any file is read', async () => { + const cwd = await makeSink() + const out = captureStdout() + await runCommand(logs, { rawArgs: ['--cwd', cwd, '--json', '--no-header', '--since', 'nope'] }) + expect(JSON.parse(out.join('')).error.code).toBe('cli.LOGS_INVALID_TIME') + expect(process.exitCode).toBe(2) + }) + + it('stats --json carries the table instead of events', async () => { + const cwd = await makeSink() + const out = captureStdout() + await runCommand(logs, { rawArgs: ['--cwd', cwd, '--json', '--no-header', 'stats', '--where', 'status<500'] }) + const payload = JSON.parse(out.join('')) as { view: string, matched: number, events?: unknown, stats: { total: number, byStatus: Record } } + expect(payload.view).toBe('stats') + expect(payload.events).toBeUndefined() + expect(payload.stats.total).toBe(5) + expect(payload.stats.byStatus).toEqual({ '2xx': 4, '4xx': 1 }) + }) + + it('no sink is a failure with the fix', async () => { + const cwd = await mkdtemp(join(tmpdir(), 'evlog-cli-logs-empty-')) + tempDirs.push(cwd) + await writeFile(join(cwd, 'package.json'), '{"name":"empty"}') + const out = captureStdout() + await runCommand(logs, { rawArgs: ['--cwd', cwd, '--json', '--no-header'] }) + expect(JSON.parse(out.join('')).error.code).toBe('cli.LOGS_NO_SINK') + expect(process.exitCode).toBe(1) + }) +}) diff --git a/packages/evlog/src/adapters/fs.ts b/packages/evlog/src/adapters/fs.ts index cab80673c..254f7b4bb 100644 --- a/packages/evlog/src/adapters/fs.ts +++ b/packages/evlog/src/adapters/fs.ts @@ -302,18 +302,48 @@ function fileWithinRange(filename: string, since?: number, until?: number): bool return true } +/** + * Turn lines into events, one object per line or one object across lines. + * + * `pretty: true` writes each event indented, so its closing brace sits alone + * at the start of a line while every nested one is indented: that is how an + * object's end is found without parsing on every line. Anything that does not + * parse once assembled (a partial write, a manual edit) is dropped silently, + * the same as a malformed single line. + */ +function createEventAssembler(): (line: string) => WideEvent | undefined { + let pending: string[] = [] + return (line) => { + if (pending.length === 0) { + const trimmed = line.trim() + if (!trimmed) return undefined + try { + return JSON.parse(trimmed) as WideEvent + } catch { + if (trimmed === '{') pending.push(trimmed) + return undefined + } + } + pending.push(line) + if (line !== '}') return undefined + const text = pending.join('\n') + pending = [] + try { + return JSON.parse(text) as WideEvent + } catch { + return undefined + } + } +} + async function* iterateFile(filePath: string): AsyncGenerator { const stream = createReadStream(filePath, { encoding: 'utf-8' }) const rl = createInterface({ input: stream, crlfDelay: Infinity }) + const assemble = createEventAssembler() try { for await (const line of rl) { - const trimmed = line.trim() - if (!trimmed) continue - try { - yield JSON.parse(trimmed) as WideEvent - } catch { - // Skip malformed lines (partial writes, manual edits) silently. - } + const event = assemble(line) + if (event) yield event } } finally { rl.close() @@ -379,7 +409,7 @@ async function readAppendedLines( } const complete = chunk.slice(0, newlineIdx) const remainder = chunk.slice(newlineIdx + 1) - const lines = complete.split('\n').map(l => l.trim()).filter(Boolean) + const lines = complete.split('\n').filter(l => l.trim()) return { events: lines, offset: size, carry: remainder } } finally { await handle.close() @@ -432,6 +462,15 @@ export async function* tailFsLogs(options: TailFsLogsOptions = {}): AsyncGenerat const offsets = new Map() const carries = new Map() + const assemblers = new Map>() + function assemblerFor(filename: string): ReturnType { + let assemble = assemblers.get(filename) + if (!assemble) { + assemble = createEventAssembler() + assemblers.set(filename, assemble) + } + return assemble + } if (options.fromEnd) { const files = await listLogFiles(dir) @@ -472,14 +511,11 @@ export async function* tailFsLogs(options: TailFsLogsOptions = {}): AsyncGenerat offsets.set(filename, offset) carries.set(filename, newCarry) + const assemble = assemblerFor(filename) for (const line of events) { if (signal?.aborted) return - try { - const event = JSON.parse(line) as WideEvent - if (predicate(event)) yield event - } catch { - // Skip malformed lines. - } + const event = assemble(line) + if (event && predicate(event)) yield event } } } diff --git a/packages/evlog/test/adapters/fs-reader.test.ts b/packages/evlog/test/adapters/fs-reader.test.ts index 85250a932..23173ac87 100644 --- a/packages/evlog/test/adapters/fs-reader.test.ts +++ b/packages/evlog/test/adapters/fs-reader.test.ts @@ -75,6 +75,18 @@ describe('readFsLogs', () => { expect(events).toEqual([1, 2, 3]) }) + it('reads events written with pretty: true, mixed with compact ones', async () => { + const pretty = (event: WideEvent): string => JSON.stringify(event, null, 2) + await writeFile( + join(dir, '2026-03-14.jsonl'), + `${pretty(makeEvent(1, { nested: { deep: { x: 1 } } }))}\n${JSON.stringify(makeEvent(2))}\n${pretty(makeEvent(3))}\n`, + ) + + const ids: number[] = [] + for await (const event of readFsLogs({ dir })) ids.push(event.id as number) + expect(ids).toEqual([1, 2, 3]) + }) + it('skips malformed lines without throwing', async () => { await writeFile( join(dir, '2026-03-14.jsonl'), @@ -307,6 +319,33 @@ describe('tailFsLogs', () => { expect(collected).toEqual([42]) }) + it('assembles a pretty-printed event appended across polls', async () => { + const file = join(dir, '2026-03-14.jsonl') + await writeFile(file, '') + + const ac = new AbortController() + const collected: number[] = [] + + const consumer = (async () => { + for await (const event of tailFsLogs({ dir, pollIntervalMs: 50, signal: ac.signal, fromEnd: true })) { + collected.push(event.id as number) + if (collected.length === 2) { + ac.abort() + break + } + } + })() + + await new Promise(r => setTimeout(r, 100)) + const lines = JSON.stringify(makeEvent(7, { nested: { a: 1 } }), null, 2).split('\n') + await appendFile(file, `${lines.slice(0, 4).join('\n')}\n`) + await new Promise(r => setTimeout(r, 100)) + await appendFile(file, `${lines.slice(4).join('\n')}\n${JSON.stringify(makeEvent(8))}\n`) + + await consumer + expect(collected).toEqual([7, 8]) + }) + it('aborts cleanly via AbortSignal', async () => { const ac = new AbortController() const start = Date.now() diff --git a/skills/analyze-logs/SKILL.md b/skills/analyze-logs/SKILL.md index a00d517e9..caf87604d 100644 --- a/skills/analyze-logs/SKILL.md +++ b/skills/analyze-logs/SKILL.md @@ -21,6 +21,19 @@ Read and analyze structured wide-event logs from the local `.evlog/logs/` direct ## Finding the logs +Try the CLI first; it reads both file layouts, every dated file, and knows where the project's drain writes. Prefer the copy the project installed (`pnpm evlog`, or the equivalent for its package manager). The wrappers that fetch on demand (`npx`, `bunx`, `npm exec`) install `@evlog/cli` when the project has none, which runs a release the lockfile never pinned. Ask before that happens. + +```bash +pnpm evlog logs --json # the last 50 events +pnpm evlog logs errors --since 1h --json # what failed +pnpm evlog logs slow --over 1s --json # what was slow, worst first +pnpm evlog logs "$REQUEST_ID" --json # one request, every event with that id +pnpm evlog logs stats --json # per route: count, errors, p50, p95; by status and level +pnpm evlog logs --where 'payment.amount>5000' --where audit.outcome=failure --json +``` + +`--json` is an envelope (`sources`, `view`, `matched`, `events`; `stats` carries `stats` instead); filters are `--since`, `--until`, `--level`, `--path`, `--status` (`500` or `5xx`), `--where field=value|field>n|field~regex|field|!field` on any dotted field (repeatable), `--limit`, `--dir` for a non-default directory, and `--url` for an app on the memory drain that exposes `readMemoryLogs()` over HTTP. From a monorepo root it reads every app's `.evlog/logs` and labels each event. Docs: https://www.evlog.dev/cli/logs. If the CLI is unavailable or the user declines it, read the files directly as below. + Logs are written by evlog's file system drain as `.jsonl` files, organized by date. **Format detection**: The drain supports two modes: @@ -118,7 +131,7 @@ Read the latest `.jsonl` file. Each line is one JSON event. Parse each line inde Filter based on the user's question: -- **Errors**: look for `"level":"error"` or `status >= 400` +- **Errors**: `"level"` of `"error"` or `"fatal"`, `status >= 500`, or an `error` object on the event, which is what `evlog logs errors` matches. A 4xx status on its own is the client's and does not count, though a 4xx event still matches when it carries one of the other two signals; read `status` or pass `--status 4xx` to see them all - **Specific endpoint**: match on `path` - **Slow requests**: filter on `durationMs` (e.g. `durationMs > 500`) - **Specific user/action**: match on application-specific fields