diff --git a/src/cli.test.ts b/src/cli.test.ts index 0886893..04eb309 100644 --- a/src/cli.test.ts +++ b/src/cli.test.ts @@ -2,7 +2,11 @@ import { afterEach, describe, expect, test } from "bun:test"; import { mkdtempSync, mkdirSync, readFileSync, rmSync, statSync, writeFileSync } from "fs"; import { tmpdir } from "os"; import { join } from "path"; -import { initializeWallet } from "./cli"; +import { + collectRecentRequestsFromLines, + initializeWallet, + parseStructuredLogLine, +} from "./cli"; const tempDirs: string[] = []; @@ -22,6 +26,139 @@ afterEach(() => { } }); +describe("parseStructuredLogLine", () => { + test("extracts timestamp, level, request id, model, and routing flag", () => { + const line = + "[2026-08-27T13:00:00.000Z] [INFO] [req:a1b2c3d4] [model:gpt-5] Routing request with path: /v1/chat/completions"; + + expect(parseStructuredLogLine(line)).toEqual({ + timestamp: "2026-08-27T13:00:00.000Z", + level: "INFO", + requestId: "a1b2c3d4", + modelId: "gpt-5", + isRouting: true, + }); + }); + + test("parses SDK child lines without marking them as routing lines", () => { + const line = + "[2026-08-27T13:00:01.000Z] [DEBUG] [req:a1b2c3d4] [model:gpt-5] [BalanceManager] token stuff"; + + expect(parseStructuredLogLine(line)).toEqual({ + timestamp: "2026-08-27T13:00:01.000Z", + level: "DEBUG", + requestId: "a1b2c3d4", + modelId: "gpt-5", + isRouting: false, + }); + }); + + test("handles legacy lines that have a request id but no model tag", () => { + const line = + "[2026-08-27T13:00:02.000Z] [INFO] [req:deadbeef] Routing request with path: /v1/responses"; + + expect(parseStructuredLogLine(line)).toEqual({ + timestamp: "2026-08-27T13:00:02.000Z", + level: "INFO", + requestId: "deadbeef", + modelId: undefined, + isRouting: true, + }); + }); + + test("extracts the bare request id from colon-joined legacy child tags", () => { + const line = + "[2026-08-27T13:00:04.000Z] [INFO] [req:deadbeef:RoutstrClient] [RoutstrClient] generic request pricing input {\"modelId\":\"deepseek-v4-flash-0731\"}"; + + const parsed = parseStructuredLogLine(line); + expect(parsed.requestId).toBe("deadbeef"); + expect(parsed.modelId).toBe("deepseek-v4-flash-0731"); + expect(parsed.isRouting).toBe(false); + }); + + test("falls back to the JSON modelId when no model tag is present", () => { + const line = + "[2026-08-27T13:00:05.000Z] [INFO] [req:deadbeef:RoutstrClient] [RoutstrClient] generic request pricing input {\"modelId\":\"deepseek-v4-pro-0813\",\"messageCount\":121}"; + + expect(parseStructuredLogLine(line).modelId).toBe("deepseek-v4-pro-0813"); + }); + + test("returns an empty record for plain non-request lines", () => { + const line = "[2026-08-27T13:00:03.000Z] [WARN] Some startup message"; + + expect(parseStructuredLogLine(line)).toEqual({ + timestamp: "2026-08-27T13:00:03.000Z", + level: "WARN", + requestId: undefined, + modelId: undefined, + isRouting: false, + }); + }); +}); + +describe("collectRecentRequestsFromLines", () => { + const lines = [ + "[2026-08-27T13:00:00.000Z] [INFO] [req:11111111] [model:gpt-5] Routing request with path: /a", + "[2026-08-27T13:00:01.000Z] [DEBUG] [req:11111111] [model:gpt-5] [BalanceManager] token", + "[2026-08-27T13:00:02.000Z] [INFO] [req:22222222] [model:claude-sonnet-4.5] Routing request with path: /b", + "[2026-08-27T13:00:03.000Z] [DEBUG] [req:22222222] [model:claude-sonnet-4.5] [ModelManager] refresh", + ]; + + test("returns one record per request, newest first", () => { + expect(collectRecentRequestsFromLines(lines, 10)).toEqual([ + { + requestId: "22222222", + modelId: "claude-sonnet-4.5", + timestamp: "2026-08-27T13:00:02.000Z", + }, + { + requestId: "11111111", + modelId: "gpt-5", + timestamp: "2026-08-27T13:00:00.000Z", + }, + ]); + }); + + test("respects the limit", () => { + expect(collectRecentRequestsFromLines(lines, 1)).toEqual([ + { + requestId: "22222222", + modelId: "claude-sonnet-4.5", + timestamp: "2026-08-27T13:00:02.000Z", + }, + ]); + }); + + test("defaults the model to unknown for legacy routing lines", () => { + const legacy = [ + "[2026-08-27T13:00:00.000Z] [INFO] [req:deadbeef] Routing request with path: /a", + ]; + + expect(collectRecentRequestsFromLines(legacy, 10)).toEqual([ + { + requestId: "deadbeef", + modelId: "unknown", + timestamp: "2026-08-27T13:00:00.000Z", + }, + ]); + }); + + test("enriches the model from a sibling pricing line in legacy logs", () => { + const legacy = [ + "[2026-08-27T13:00:00.000Z] [INFO] [req:deadbeef] Routing request with path: /a", + "[2026-08-27T13:00:01.000Z] [INFO] [req:deadbeef:RoutstrClient] [RoutstrClient] generic request pricing input {\"modelId\":\"deepseek-v4-flash-0731\"}", + ]; + + expect(collectRecentRequestsFromLines(legacy, 10)).toEqual([ + { + requestId: "deadbeef", + modelId: "deepseek-v4-flash-0731", + timestamp: "2026-08-27T13:00:00.000Z", + }, + ]); + }); +}); + describe("initializeWallet", () => { test("creates the wallet directory and config with restrictive permissions", () => { const walletDir = join(makeTempDir(), "wallet"); diff --git a/src/cli.ts b/src/cli.ts index c8c373d..9b9d9fd 100644 --- a/src/cli.ts +++ b/src/cli.ts @@ -2268,11 +2268,15 @@ function getLogFileForDate(logsDir: string, date: Date = new Date()): string { return `${logsDir}/${year}-${month}-${day}.log`; } -function readLastLines(file: string, lines: number): string { +function readAllLines(file: string): string[] { const content = readFileSync(file, "utf8"); const allLines = content.replace(/\r\n/g, "\n").split("\n"); if (allLines.at(-1) === "") allLines.pop(); - return allLines.slice(-lines).join("\n"); + return allLines; +} + +function readLastLines(file: string, lines: number): string { + return readAllLines(file).slice(-lines).join("\n"); } async function followLogFile(file: string, lines: number): Promise { @@ -2302,51 +2306,239 @@ async function followLogFile(file: string, lines: number): Promise { } } +type StructuredLogLine = { + timestamp?: string; + level?: string; + requestId?: string; + modelId?: string; + isRouting: boolean; +}; + +export function parseStructuredLogLine(line: string): StructuredLogLine { + const out: StructuredLogLine = { isRouting: false }; + + const head = line.match(/^\[([^\]]+)\]\s+\[([^\]]+)\]/); + if (head) { + out.timestamp = head[1]; + out.level = head[2]; + } + + // Request ids are hex (no colons). Stop at the first ':' so legacy + // colon-joined child tags like `[req:2c30d5ed:RoutstrClient]` still yield + // the bare request id. + const req = line.match(/\[req:([^\]\:]+)/); + if (req) { + out.requestId = req[1]!.trim(); + } + + // Prefer an explicit `[model:...]` tag; fall back to the modelId embedded + // in the SDK's `generic request pricing input {"modelId":"..."}` line. + const model = line.match(/\[model:([^\]\:]+)\]/); + if (model) { + out.modelId = model[1]!.trim(); + } else { + const jsonModel = line.match(/"modelId"\s*:\s*"([^"]+)"/); + if (jsonModel) { + out.modelId = jsonModel[1]; + } + } + + out.isRouting = !!out.requestId && line.includes("Routing request with path"); + return out; +} + +type RequestSummary = { + requestId: string; + modelId: string; + timestamp?: string; +}; + +/** + * Scan log lines newest-first and collect one record per request, keyed off + * the "Routing request with path" line (the canonical per-request entry). + * The model is enriched in a second pass from any line belonging to the + * request (the SDK pricing line embeds modelId even in legacy logs). + */ +export function collectRecentRequestsFromLines( + lines: string[], + limit: number, +): RequestSummary[] { + const result: RequestSummary[] = []; + const seen = new Set(); + + for (let i = lines.length - 1; i >= 0; i--) { + const parsed = parseStructuredLogLine(lines[i]!); + if (!parsed.isRouting || !parsed.requestId) continue; + if (seen.has(parsed.requestId)) continue; + seen.add(parsed.requestId); + + result.push({ + requestId: parsed.requestId, + modelId: parsed.modelId ?? "unknown", + timestamp: parsed.timestamp, + }); + + if (result.length >= limit) break; + } + + // Second pass: fill in the model for requests whose routing line predates + // the `[model:...]` tag but which logged `{"modelId":"..."}` later on. + const byRequestId = new Map(result.map((r) => [r.requestId, r])); + for (const line of lines) { + const parsed = parseStructuredLogLine(line); + if (!parsed.requestId || !parsed.modelId) continue; + const record = byRequestId.get(parsed.requestId); + if (record && record.modelId === "unknown") { + record.modelId = parsed.modelId; + } + } + + return result; +} + +function collectRecentRequests( + files: string[], + limit: number, +): RequestSummary[] { + const result: RequestSummary[] = []; + const seen = new Set(); + + // Files are passed oldest-first (yesterday, today); scan newest-first. + for (const file of [...files].reverse()) { + if (!existsSync(file)) continue; + const remaining = limit - result.length; + if (remaining <= 0) break; + + for (const request of collectRecentRequestsFromLines( + readAllLines(file), + remaining, + )) { + if (seen.has(request.requestId)) continue; + seen.add(request.requestId); + result.push(request); + if (result.length >= limit) return result; + } + } + + return result; +} + +function filterLinesByRequestId( + files: string[], + requestId: string, +): string[] { + const matches: string[] = []; + for (const file of files) { + if (!existsSync(file)) continue; + for (const line of readAllLines(file)) { + if (parseStructuredLogLine(line).requestId === requestId) { + matches.push(line); + } + } + } + return matches; +} + +function parseLinesOption(value: string): number { + const parsed = Number.parseInt(value, 10); + return Number.isFinite(parsed) && parsed > 0 ? parsed : 50; +} + + program .command("logs") .description("View daemon logs") .option("-f, --follow", "Follow log output", false) .option("-c, --coco", "Show Cashu wallet-engine (coco) logs instead of daemon logs", false) .option("-n, --lines ", "Number of lines to show", "50") - .action(async (options: { follow: boolean; lines: string; coco: boolean }) => { - await requireLocalDaemon(); - const logsDir = options.coco ? COCO_LOGS_DIR : LOGS_DIR; - const todayFile = getLogFileForDate(logsDir); - const yesterday = new Date(); - yesterday.setDate(yesterday.getDate() - 1); - const yesterdayFile = getLogFileForDate(logsDir, yesterday); + .option("-r, --recent", "List recent request ids with their model", false) + .option("-i, --request-id ", "Only show log lines for a specific request id") + .action( + async (options: { + follow: boolean; + lines: string; + coco: boolean; + recent: boolean; + requestId?: string; + }) => { + await requireLocalDaemon(); - if (!existsSync(todayFile) && !existsSync(yesterdayFile)) { - console.log("No log files found. Daemon may not have started yet."); - console.log(`Logs directory: ${logsDir}`); - process.exit(1); - } - - const lines = parseInt(options.lines, 10); - - const logFiles = [yesterdayFile, todayFile].filter((file, index, files) => { - return existsSync(file) && files.indexOf(file) === index; - }); - - if (options.follow) { - if (existsSync(todayFile)) { - await followLogFile(todayFile, lines); - } else { - console.log("No log file for today to follow."); + if (options.recent && options.requestId) { + console.error( + "Cannot combine --recent (-r) with --request-id (-i).", + ); + process.exit(1); } - return; - } - for (const file of logFiles) { - if (logFiles.length > 1) { - console.log(`==> ${file} <==`); + const logsDir = options.coco ? COCO_LOGS_DIR : LOGS_DIR; + const todayFile = getLogFileForDate(logsDir); + const yesterday = new Date(); + yesterday.setDate(yesterday.getDate() - 1); + const yesterdayFile = getLogFileForDate(logsDir, yesterday); + + if (!existsSync(todayFile) && !existsSync(yesterdayFile)) { + console.log("No log files found. Daemon may not have started yet."); + console.log(`Logs directory: ${logsDir}`); + process.exit(1); } - const output = readLastLines(file, lines); - if (output) { - console.log(output); + + const lines = parseLinesOption(options.lines); + + const logFiles = [yesterdayFile, todayFile].filter( + (file, index, files) => + existsSync(file) && files.indexOf(file) === index, + ); + + if (options.recent) { + const requests = collectRecentRequests(logFiles, lines); + if (requests.length === 0) { + console.log("No requests found in recent logs."); + return; + } + + console.log("Recent requests (newest first):"); + for (const request of requests) { + const when = request.timestamp ? ` ${request.timestamp}` : ""; + console.log(` ${request.requestId} ${request.modelId}${when}`); + } + return; } - } - }); + + if (options.requestId) { + const matches = filterLinesByRequestId(logFiles, options.requestId); + if (matches.length === 0) { + console.log( + `No log lines found for request '${options.requestId}'.`, + ); + return; + } + + for (const line of matches) { + console.log(line); + } + return; + } + + if (options.follow) { + if (existsSync(todayFile)) { + await followLogFile(todayFile, lines); + } else { + console.log("No log file for today to follow."); + } + return; + } + + for (const file of logFiles) { + if (logFiles.length > 1) { + console.log(`==> ${file} <==`); + } + const output = readLastLines(file, lines); + if (output) { + console.log(output); + } + } + }, + ); export function cli(args: string[]) { program.parse(args); diff --git a/src/daemon/http/index.ts b/src/daemon/http/index.ts index 17e694a..505b6c8 100644 --- a/src/daemon/http/index.ts +++ b/src/daemon/http/index.ts @@ -358,18 +358,17 @@ async function buildWalletDetails(deps: DaemonDeps): Promise<{ }; } -function makeSdkLogger(prefix?: string): SdkLogger { - const tag = prefix ? `[${prefix}]` : undefined; +function makeSdkLogger(...parts: string[]): SdkLogger { + const tag = parts.length ? parts.map((p) => `[${p}]`).join(" ") : undefined; const fmt = (...args: unknown[]) => (tag ? [tag, ...args] : args); return { log: (...args: unknown[]) => logger.log(...fmt(...args)), warn: (...args: unknown[]) => logger.warn(...fmt(...args)), error: (...args: unknown[]) => logger.error(...fmt(...args)), debug: (...args: unknown[]) => logger.debug(...fmt(...args)), - child: (p: string) => makeSdkLogger(prefix ? `${prefix}:${p}` : p), + child: (p: string) => makeSdkLogger(...parts, p), }; } -const sdkLogger: SdkLogger = makeSdkLogger(); export function createDaemonRequestHandler(deps: { provider: string | null; @@ -1744,8 +1743,8 @@ export function createDaemonRequestHandler(deps: { try { await deps.ensureProvidersBootstrapped(); const reqId = randomBytes(4).toString("hex"); - const reqLogger = sdkLogger.child(`req:${reqId}`); - logger.log(`[req:${reqId}] Routing request with path: `, url.pathname); + const reqLogger = makeSdkLogger(`req:${reqId}`, `model:${modelId}`); + reqLogger.log(`Routing request with path: ${url.pathname}`); const response = await routeRequests({ modelId,