diff --git a/docs/linking-sessions-to-request-logs.md b/docs/linking-sessions-to-request-logs.md new file mode 100644 index 0000000..af480ab --- /dev/null +++ b/docs/linking-sessions-to-request-logs.md @@ -0,0 +1,177 @@ +# Linking pi sessions to request/response logs + +When `requestResponseLogging` is enabled, the daemon records every proxied +upstream call as two files that share one id: + +- `requests/.json` — method, url, baseUrl, redacted headers, request body +- `responses/.jsonl` — one JSON event per line: `response_start`, `chunk`, + `end` / `error` + +The `id` is minted in `src/daemon/request-response-log-sink.ts` (`makeId()`): +the request's arrival time with `:`/`.` swapped for `-`, plus 8 hex chars, e.g. +`2026-09-30T09-22-35-288Z-60c8e8cf`. The request's `id` and the response's +`requestLogId` are the same string, so **the request and response logs are +paired by filename stem** and never need matching against each other. + +Separately, pi records its own transcript per working directory. The two are +written by different processes, so the session has no log id and the logs have +no session id. This document explains the two keys that recover the link +exactly, and how to run the mapper on redtop. + +## TL;DR + +```bash +# on redtop +bun scripts/link-session-logs.ts /home/user/.routstrd/reqRes +``` + +Every assistant turn prints the response log it produced. The request log is +the same stem under `requests/`. + +## Where the data lives + +| | redtop (`ssh redtop`) | default | +| --- | --- | --- | +| request/response logs | `/home/user/.routstrd/reqRes` | `~/.routstrd/request-response-logs` | +| log root on disk | `requestResponseLogging.dir` in `~/.routstrd/config.json` | `REQUEST_RESPONSE_LOGS_DIR` (`src/utils/config.ts`) | +| pi sessions | `/home/user/.pi/agent/sessions/----/*.jsonl` | `~/.pi/agent/sessions/…` | +| pi provider config | `/home/user/.pi/agent/models.json` (`providers.routstr`) | `~/.pi/agent/models.json` | + +On redtop the log root is set explicitly: + +```jsonc +// ~/.routstrd/config.json +"requestResponseLogging": { "enabled": true, "dir": "/home/user/.routstrd/reqRes" } +``` + +pi reaches the daemon through the `routstr` provider that +`routstrd clients add pi-agent` writes into `models.json` +(`src/integrations/pi.ts`, `configPath: ~/.pi/agent/models.json`). So the +sessions and the logs on redtop are two views of the *same* traffic. + +Logs are stored uncompressed on redtop (`requests/*.json`, +`responses/*.jsonl`). Elsewhere they may be brotli-compressed (`.jsonl.br`); +the mapper handles both. + +## The join keys + +### 1. `responseId` ⇄ response stream id (primary, exact) + +Each assistant message in a pi session stores the upstream response id: + +```jsonc +// session .jsonl +{ "type": "message", + "timestamp": "2026-09-30T09:22:36.852Z", + "message": { "role": "assistant", "provider": "routstr", + "responseId": "chatcmpl-b5e868d7b747dd8be5a2fbc0b1313507", … } } +``` + +The response log replays the raw upstream SSE stream inside its `chunk` events, +so the same id appears verbatim: + +```jsonc +// responses/.jsonl +{ "requestLogId": "2026-09-30T09-22-35-288Z-60c8e8cf", "type": "chunk", + "text": "data: {\"id\":\"chatcmpl-b5e868d7b747dd8be5a2fbc0b1313507\", …}\n\n" } +``` + +The id prefix depends on which upstream provider answered — `chatcmpl-…` for +Venice, `gen-…` for OpenRouter — but it is always present and always identical +to `responseId`. Match on `chunk.text`, never on the raw file: the SSE text is +JSON-escaped in the log, so `grep '"id":"'` misses it. + +### 2. request ⇄ response (exact, by id) + +`requests/.json` and `responses/.jsonl` share the filename stem +(`id` == `requestLogId`). A response hit therefore yields its request for free. + +### 3. trigger timestamp ≈ request timestamp (secondary) + +The request log's `timestamp` is when the daemon received the call, which is +the instant pi fired it — within ~10–30 ms of the *triggering* session message +(the user turn or tool result), and within a few ms of the assistant record's +epoch-ms `message.timestamp`. Useful as a sanity check or fallback, but not +needed once key 1 works. + +## Running the mapper + +The mapper is `scripts/link-session-logs.ts` (bun, no extra deps): + +```bash +bun run link-logs -- [logsDir] [--all] [--json] +``` + +- `logsDir` defaults to `$ROUTSTRD_LOG_DIR`, else `~/.routstrd/request-response-logs`. +- `--all` scans every response log instead of only the session's UTC day (use + when a session spans midnight or logs were rotated). +- `--json` prints a machine-readable table with both the `requests/` and + `responses/` paths per turn. + +On redtop the script must exist in the redtop checkout. Copy it over now (or +`git pull` once the change is pushed): + +```bash +scp scripts/link-session-logs.ts \ + redtop:~/projects/routstr_main/routstrd/scripts/ +``` + +`bun` is on `PATH` in an interactive fish session on redtop (`~/.bun/bin`); +from a non-interactive shell, add it explicitly: + +```bash +ssh redtop 'export PATH=$HOME/.bun/bin:$PATH; \ + bun ~/projects/routstr_main/routstrd/scripts/link-session-logs.ts \ + ~/.pi/agent/sessions/--home-user-projects-routstr_main-routstr-core--/.jsonl \ + ~/.routstrd/reqRes' +``` + +To work from the Mac against redtop's logs, either run it there over SSH (as +above) or pull the logs first: + +```bash +rsync -a redtop:/home/user/.routstrd/reqRes/ ~/.routstrd/reqRes-redtop/ +bun scripts/link-session-logs.ts ~/.routstrd/reqRes-redtop +``` + +### Finding the session for a given directory + +pi slugs the message's `cwd` into the session directory name by dropping the +leading `/` and replacing the rest with `-`, wrapped in `--`: + +``` +/home/user/projects/routstr_main/routstr-core + -> ~/.pi/agent/sessions/--home-user-projects-routstr_main-routstr-core--/ +``` + +Pick the file you want inside that directory (or `ls -t … | head -1` for the +latest). + +## Verified + +Against this repo's own history the link is 1:1 and exact: + +- `2026-09-30T09-21-41-962Z_01a0f19e…jsonl` → **12/12** assistant turns matched + (provider: Venice, `chatcmpl-…`). +- `2026-09-15T19-49-27-933Z_01a0a69e…jsonl` → **8/8** (OpenRouter, `gen-…`). +- `2026-08-16T10-51-25-080Z_01a00a32…jsonl` → 51 of 55 turns carry a + `responseId`; all 51 matched (compressed `.br` logs). +- On redtop, `2026-10-01T07-55-38-825Z_01a0f676…jsonl` → **2/2**. + +## Caveats + +- **Retries and aborted calls leave orphan logs.** A single assistant turn can + produce more than one request/response pair (transient `scp`-style failures, + provider retries), and some logs belong to sessions outside the one you are + looking at. Drive the join from the session, never assume the counts match. +- **No `responseId` = no exact link.** The key exists in modern pi session + files (see the `2026-06-*` / `2026-08-*` sessions above). If a session omits + it, fall back to the trigger-timestamp window. +- **Don't match on the system/developer prompt.** The session stores it as + `sections` (preamble + project context); the request log stores it as one + flattened `developer` message. They are not byte-identical. +- **Content can quote an id.** Tool output that happens to contain an id string + can make a stem look like it matches an unrelated turn. The mapper only reads + `chunk.text`, which is model output, keeping this rare. +- **Logging may start mid-history.** If `requestResponseLogging` was enabled + after a session began, earlier turns simply have no logs. diff --git a/package.json b/package.json index 0a7948b..40af913 100644 --- a/package.json +++ b/package.json @@ -24,6 +24,7 @@ "lint": "tsc --noEmit", "test": "bun test", "smoke": "scripts/smoke/chat-completions.sh", + "link-logs": "bun scripts/link-session-logs.ts", "build": "bun build src/index.ts --target=bun --outfile=dist/index.js --external better-sqlite3 && bun build src/daemon/index.ts --target=bun --outfile=dist/daemon/index.js --external better-sqlite3", "build:binary": "bun build --compile --no-compile-autoload-dotenv --no-compile-autoload-bunfig src/index.ts --outfile=dist/routstrd", "prepublishOnly": "bun run build" diff --git a/scripts/link-session-logs.ts b/scripts/link-session-logs.ts new file mode 100644 index 0000000..db7be22 --- /dev/null +++ b/scripts/link-session-logs.ts @@ -0,0 +1,176 @@ +#!/usr/bin/env bun +/** + * link-session-logs.ts — map a pi session transcript to the routstrd + * request/response logs it produced. + * + * When `requestResponseLogging` is enabled the daemon writes one + * `requests/.json` and one `responses/.jsonl` per proxied upstream + * call. A pi session (see `routstrd clients add pi-agent`) records the same + * calls in its own transcript, under `~/.pi/agent/sessions//*.jsonl`. + * + * The two are written by different processes, so there is no session id on the + * log side and no log id on the session side — but each assistant message in + * the session stores the upstream response id (`message.responseId`), and that + * same id appears verbatim inside the response log's SSE chunks. The request + * and response logs then share one id (`requests/.json` ↔ + * `responses/.jsonl`, `id` == `requestLogId`), so a response hit yields the + * request too. + * + * Usage: + * bun scripts/link-session-logs.ts [logsDir] [--all] [--json] + * + * logsDir Request/response log root. Defaults to $ROUTSTRD_LOG_DIR, else + * ~/.routstrd/request-response-logs. On redtop it is + * /home/user/.routstrd/reqRes (see requestResponseLogging.dir). + * --all Scan every response log instead of only the session's UTC day + * (slower; use when a session spans midnight or logs were rotated). + * --json Emit machine-readable JSON instead of a table. + */ +import { readFileSync, readdirSync, existsSync } from "node:fs"; +import { homedir } from "node:os"; +import { basename, join } from "node:path"; +import { brotliDecompressSync } from "node:zlib"; + +const ID_RE = /"id"\s*:\s*"([^"]+)"/g; + +interface Turn { + /** ISO timestamp of the assistant message (also when the request fired). */ + timestamp: string; + responseId?: string; + model?: string; +} + +function readMaybeCompressed(path: string): string { + const buf = readFileSync(path); + if (!path.endsWith(".br")) return buf.toString("utf8"); + try { + return brotliDecompressSync(buf).toString("utf8"); + } catch { + return buf.toString("utf8"); + } +} + +/** Upstream generation ids emitted inside a response log's SSE chunks. */ +function responseIds(path: string): Set { + const ids = new Set(); + for (const line of readMaybeCompressed(path).split("\n")) { + if (!line.trim()) continue; + let event: { type?: string; text?: string }; + try { + event = JSON.parse(line); + } catch { + continue; + } + if (event.type !== "chunk" || typeof event.text !== "string") continue; + for (const match of event.text.matchAll(ID_RE)) ids.add(match[1]!); + } + return ids; +} + +function assistantTurns(sessionPath: string): Turn[] { + const turns: Turn[] = []; + for (const line of readFileSync(sessionPath, "utf8").split("\n")) { + if (!line.trim()) continue; + let record: { type?: string; timestamp?: string; message?: { role?: string; responseId?: string; responseModel?: string } }; + try { + record = JSON.parse(line); + } catch { + continue; + } + if (record.type !== "message" || record.message?.role !== "assistant") continue; + turns.push({ + timestamp: record.timestamp ?? "", + responseId: record.message.responseId, + model: record.message.responseModel, + }); + } + return turns; +} + +/** Strip the `.jsonl` / `.jsonl.br` suffix to recover the log id (stem). */ +function stemOf(file: string): string { + return file.replace(/\.jsonl(\.br)?$/, ""); +} + +function main(): void { + const args = process.argv.slice(2); + const flags = new Set(args.filter((a) => a.startsWith("--"))); + const positional = args.filter((a) => !a.startsWith("--")); + const [sessionPath, logsArg] = positional; + + if (!sessionPath) { + console.error("usage: bun scripts/link-session-logs.ts [logsDir] [--all] [--json]"); + process.exit(2); + } + + const logsDir = + logsArg || process.env.ROUTSTRD_LOG_DIR || join(homedir(), ".routstrd", "request-response-logs"); + const responsesDir = join(logsDir, "responses"); + const requestsDir = join(logsDir, "requests"); + if (!existsSync(responsesDir)) { + console.error(`no responses directory at ${responsesDir}`); + process.exit(2); + } + + const day = basename(sessionPath).slice(0, 10); // YYYY-MM-DD + const candidates = readdirSync(responsesDir).filter( + (file) => file.endsWith(".jsonl") || file.endsWith(".jsonl.br"), + ); + const scanned = flags.has("--all") ? candidates : candidates.filter((file) => file.startsWith(day)); + + // responseId -> response log stem(s). Usually one; retries or quoted ids can + // make a stem appear more than once, so keep every hit. + const byResponseId = new Map(); + for (const file of scanned) { + const stem = stemOf(file); + for (const id of responseIds(join(responsesDir, file))) { + const hits = byResponseId.get(id) ?? []; + if (!hits.includes(stem)) hits.push(stem); + byResponseId.set(id, hits); + } + } + + const turns = assistantTurns(sessionPath); + const rows = turns.map((turn) => { + const stems = turn.responseId ? (byResponseId.get(turn.responseId) ?? []) : []; + return { + timestamp: turn.timestamp, + responseId: turn.responseId ?? null, + model: turn.model ?? null, + responseLogs: stems.map((stem) => join(responsesDir, `${stem}.jsonl`)), + requestLogs: stems.map((stem) => { + const plain = join(requestsDir, `${stem}.json`); + return existsSync(plain) ? plain : join(requestsDir, `${stem}.json.br`); + }), + matched: stems.length > 0, + }; + }); + + if (flags.has("--json")) { + console.log(JSON.stringify(rows, null, 2)); + return; + } + + const matched = rows.filter((r) => r.matched).length; + console.log(`session : ${sessionPath}`); + console.log(`logs : ${logsDir}`); + console.log(`scanned : ${scanned.length} response log(s)${flags.has("--all") ? " (all)" : ` for ${day}`}`); + console.log(`turns : ${rows.length} assistant message(s), ${matched} matched\n`); + + const width = Math.max(...rows.map((r) => (r.responseId ?? "—").length), 10); + for (const row of rows) { + const id = (row.responseId ?? "—").padEnd(width); + const hit = row.matched ? row.responseLogs[0]!.replace(`${logsDir}/`, "") : "NO MATCH"; + console.log(` ${row.timestamp} ${id} ${hit}`); + } + + const unmatched = rows.filter((r) => !r.matched); + if (unmatched.length > 0) { + console.log( + `\n${unmatched.length} unmatched turn(s). If the session spans midnight or the logs were` + + ` rotated, re-run with --all. Pre-responseId pi versions cannot be matched this way.`, + ); + } +} + +main();