From ce69ddb88e54f4eb912ec5f16e3ba824db303550 Mon Sep 17 00:00:00 2001 From: "opencode-agent[bot]" Date: Fri, 5 Jun 2026 14:07:45 +0000 Subject: [PATCH] feat(core): write logs as state jsonl --- packages/core/src/global.ts | 2 +- packages/core/src/util/log.ts | 173 +++++++++++++-------- packages/opencode/src/cli/cmd/run/trace.ts | 2 +- packages/opencode/src/index.ts | 14 +- packages/opencode/src/temporary.ts | 24 ++- packages/opencode/test/util/log.test.ts | 120 +++++++++----- 6 files changed, 228 insertions(+), 107 deletions(-) diff --git a/packages/core/src/global.ts b/packages/core/src/global.ts index 5f9799c252..24dea6199b 100644 --- a/packages/core/src/global.ts +++ b/packages/core/src/global.ts @@ -19,7 +19,7 @@ const paths = { }, data, bin: path.join(cache, "bin"), - log: path.join(data, "log"), + log: state, repos: path.join(data, "repos"), cache, config, diff --git a/packages/core/src/util/log.ts b/packages/core/src/util/log.ts index 3b5249cdc3..08dfdcaeac 100644 --- a/packages/core/src/util/log.ts +++ b/packages/core/src/util/log.ts @@ -2,10 +2,10 @@ export * as Log from "./log" import path from "path" import fs from "fs/promises" -import { createWriteStream } from "fs" +import { appendFileSync } from "fs" import * as Global from "../global" import { Schema } from "effect" -import { Glob } from "./glob" +import { ensureProcessMetadata } from "./opencode-process" export const Level = Schema.Literals(["DEBUG", "INFO", "WARN", "ERROR"]).annotate({ identifier: "LogLevel", @@ -19,9 +19,6 @@ const levelPriority: Record = { WARN: 2, ERROR: 3, } -const keep = 10 -const initializedRunID = "OPENCODE_LOG_INITIALIZED_RUN_ID" - let level: Level = "INFO" function shouldLog(input: Level): boolean { @@ -49,59 +46,42 @@ const loggers = new Map() export const Default = create({ service: "default" }) export interface Options { - print: boolean + print?: boolean dev?: boolean level?: Level + file?: string | false } let logpath = "" export function file() { return logpath } -let write = (msg: any) => { - process.stderr.write(msg) - return msg.length +type LogEntry = { + json: string + pretty: string +} +let write = (entry: LogEntry) => { + process.stderr.write(entry.pretty) } export async function init(options: Options) { - if (options.level) level = options.level - void cleanup(Global.Path.log) - if (options.print) return - logpath = path.join( - Global.Path.log, - options.dev ? "dev.log" : new Date().toISOString().split(".")[0].replace(/:/g, "") + ".log", - ) - const runID = process.env.OPENCODE_RUN_ID - const shouldTruncate = !options.dev || !runID || process.env[initializedRunID] !== runID - if (shouldTruncate) await fs.truncate(logpath).catch(() => {}) - if (options.dev && runID) process.env[initializedRunID] = runID - const stream = createWriteStream(logpath, { flags: "a" }) - write = async (msg: any) => { - return new Promise((resolve, reject) => { - stream.write(msg, (err) => { - if (err) reject(err) - else resolve(msg.length) - }) - }) + level = options.level ?? parseLevel(process.env.OPENCODE_LOG_LEVEL) ?? level + const print = options.print ?? truthy(process.env.OPENCODE_PRINT_LOGS) + const configured = options.file ?? process.env.OPENCODE_LOG_FILE + logpath = configured === false || disabled(configured) ? "" : configured || path.join(Global.Path.log, "log.jsonl") + + if (logpath) await fs.mkdir(path.dirname(logpath), { recursive: true }) + + write = (entry) => { + if (logpath) { + try { + appendFileSync(logpath, entry.json) + } catch {} + } + if (print) process.stderr.write(entry.pretty) } } -async function cleanup(dir: string) { - const files = ( - await Glob.scan("????-??-??T??????.log", { - cwd: dir, - absolute: false, - include: "file", - }).catch(() => []) - ) - .filter((file) => path.basename(file) === file) - .sort() - if (files.length <= keep) return - - const doomed = files.slice(0, -keep) - await Promise.all(doomed.map((file) => fs.unlink(path.join(dir, file)).catch(() => {}))) -} - function formatError(error: Error, depth = 0): string { const result = error.message return error.cause instanceof Error && depth < 10 @@ -121,43 +101,63 @@ export function create(tags?: Record) { } } - function build(message: any, extra?: Record) { - const prefix = Object.entries({ - ...tags, - ...extra, - }) - .filter(([_, value]) => value !== undefined && value !== null) - .map(([key, value]) => { - const prefix = `${key}=` - if (value instanceof Error) return prefix + formatError(value) - if (typeof value === "object") return prefix + JSON.stringify(value) - return prefix + value + function build(inputLevel: Level, message: any, extra?: Record): LogEntry { + const ts = new Date() + const metadata = ensureProcessMetadata("main") + const fields = Object.fromEntries( + Object.entries({ + ...tags, + ...extra, }) + .filter((entry) => entry[1] !== undefined && entry[1] !== null) + .map(([key, value]) => [key, normalize(value)]), + ) + const service = typeof fields.service === "string" ? fields.service : undefined + if (service) delete fields.service + const text = stringifyMessage(message) + const record = { + ts: ts.toISOString(), + level: inputLevel, + message: text, + run_id: metadata.runID, + process_role: metadata.processRole, + pid: process.pid, + service, + fields, + } + const diff = ts.getTime() - last + last = ts.getTime() + const prefix = Object.entries({ service, ...fields }) + .filter((entry) => entry[1] !== undefined && entry[1] !== null) + .map(([key, value]) => `${key}=${typeof value === "object" ? safeStringify(value) : value}`) .join(" ") - const next = new Date() - const diff = next.getTime() - last - last = next.getTime() - return [next.toISOString().split(".")[0], "+" + diff + "ms", prefix, message].filter(Boolean).join(" ") + "\n" + return { + json: safeStringify(record) + "\n", + pretty: + [inputLevel.padEnd(5), ts.toISOString().split(".")[0], "+" + diff + "ms", prefix, text] + .filter(Boolean) + .join(" ") + "\n", + } } const result: Logger = { debug(message?: any, extra?: Record) { if (shouldLog("DEBUG")) { - write("DEBUG " + build(message, extra)) + write(build("DEBUG", message, extra)) } }, info(message?: any, extra?: Record) { if (shouldLog("INFO")) { - write("INFO " + build(message, extra)) + write(build("INFO", message, extra)) } }, error(message?: any, extra?: Record) { if (shouldLog("ERROR")) { - write("ERROR " + build(message, extra)) + write(build("ERROR", message, extra)) } }, warn(message?: any, extra?: Record) { if (shouldLog("WARN")) { - write("WARN " + build(message, extra)) + write(build("WARN", message, extra)) } }, tag(key: string, value: string) { @@ -192,3 +192,50 @@ export function create(tags?: Record) { return result } + +function truthy(value: string | undefined) { + return value?.toLowerCase() === "1" || value?.toLowerCase() === "true" +} + +function disabled(value: string | undefined) { + const lower = value?.toLowerCase() + return lower === "0" || lower === "false" || lower === "off" +} + +function parseLevel(value: string | undefined): Level | undefined { + if (value === "DEBUG" || value === "INFO" || value === "WARN" || value === "ERROR") return value + return undefined +} + +function stringifyMessage(message: any): string { + if (message instanceof Error) return formatError(message) + if (message === undefined) return "" + if (typeof message === "string") return message + if (typeof message === "object") return safeStringify(message) + return String(message) +} + +function normalize(value: any): any { + if (value instanceof Error) { + return { + name: value.name, + message: formatError(value), + stack: value.stack, + } + } + if (typeof value === "bigint") return value.toString() + return value +} + +function safeStringify(value: any) { + const seen = new WeakSet() + return JSON.stringify(value, (_, item) => { + if (typeof item === "bigint") return item.toString() + if (item instanceof Error) return normalize(item) + if (typeof item === "object" && item !== null) { + if (seen.has(item)) return "[Circular]" + seen.add(item) + } + return item + }) +} diff --git a/packages/opencode/src/cli/cmd/run/trace.ts b/packages/opencode/src/cli/cmd/run/trace.ts index 5ed220393b..95a936c168 100644 --- a/packages/opencode/src/cli/cmd/run/trace.ts +++ b/packages/opencode/src/cli/cmd/run/trace.ts @@ -1,7 +1,7 @@ // Dev-only JSONL event trace for direct interactive mode. // // Enable with OPENCODE_DIRECT_TRACE=1. Writes one JSON line per event to -// ~/.local/share/opencode/log/direct/-.jsonl. Also writes +// ~/.local/state/opencode/direct/-.jsonl. Also writes // a latest.json pointer so you can quickly find the most recent trace. // // The trace captures the full closed loop: outbound prompts, inbound SDK diff --git a/packages/opencode/src/index.ts b/packages/opencode/src/index.ts index d20f29dd4d..ed40ca26c8 100644 --- a/packages/opencode/src/index.ts +++ b/packages/opencode/src/index.ts @@ -67,6 +67,11 @@ function show(out: string) { process.stderr.write(out) } +function parseLogLevel(value: string | undefined): Log.Level | undefined { + if (value === "DEBUG" || value === "INFO" || value === "WARN" || value === "ERROR") return value + return undefined +} + const cli = yargs(args) .parserConfiguration({ "populate--": true }) .scriptName("opencode") @@ -79,6 +84,10 @@ const cli = yargs(args) describe: "print logs to stderr", type: "boolean", }) + .option("log-file", { + describe: "path to JSONL log file", + type: "string", + }) .option("log-level", { describe: "log level", type: "string", @@ -94,10 +103,13 @@ const cli = yargs(args) } await Log.init({ - print: process.argv.includes("--print-logs"), + print: opts.printLogs, + file: opts.logFile, dev: Installation.isLocal(), level: (() => { if (opts.logLevel) return opts.logLevel as Log.Level + const envLevel = parseLogLevel(process.env.OPENCODE_LOG_LEVEL) + if (envLevel) return envLevel if (Installation.isLocal()) return "DEBUG" return "INFO" })(), diff --git a/packages/opencode/src/temporary.ts b/packages/opencode/src/temporary.ts index 7747eb1e9f..f0325f0cc9 100644 --- a/packages/opencode/src/temporary.ts +++ b/packages/opencode/src/temporary.ts @@ -4,11 +4,27 @@ import { InstallationVersion } from "@opencode-ai/core/installation/version" import { hideBin } from "yargs/helpers" import { Log } from "./node" +const args = hideBin(process.argv) + +function flag(name: string) { + const index = args.indexOf(name) + if (index >= 0) return args[index + 1] + const value = args.find((arg) => arg.startsWith(name + "=")) + return value?.slice(name.length + 1) +} + +function parseLogLevel(value: string | undefined): Log.Level | undefined { + if (value === "DEBUG" || value === "INFO" || value === "WARN" || value === "ERROR") return value + return undefined +} + Log.init({ - print: false, + print: args.includes("--print-logs"), + file: flag("--log-file"), + level: parseLogLevel(flag("--log-level")), }) -const cli = yargs(hideBin(process.argv)) +const cli = yargs(args) .parserConfiguration({ "populate--": true }) .scriptName("opencode") .wrap(100) @@ -20,6 +36,10 @@ const cli = yargs(hideBin(process.argv)) describe: "print logs to stderr", type: "boolean", }) + .option("log-file", { + describe: "path to JSONL log file", + type: "string", + }) .option("log-level", { describe: "log level", type: "string", diff --git a/packages/opencode/test/util/log.test.ts b/packages/opencode/test/util/log.test.ts index 62dc1d61c2..16fbabf16c 100644 --- a/packages/opencode/test/util/log.test.ts +++ b/packages/opencode/test/util/log.test.ts @@ -3,6 +3,7 @@ import { Effect } from "effect" import fs from "fs/promises" import path from "path" import { CrossSpawnSpawner } from "@opencode-ai/core/cross-spawn-spawner" +import * as EffectLogger from "@opencode-ai/core/effect/logger" import { Global } from "@opencode-ai/core/global" import * as Log from "@opencode-ai/core/util/log" import { tmpdirScoped } from "../fixture/fixture" @@ -10,68 +11,109 @@ import { testEffect } from "../lib/effect" const it = testEffect(CrossSpawnSpawner.defaultLayer) -function files(dir: string) { - return Effect.gen(function* () { - let last = "" - let same = 0 - - for (let i = 0; i < 50; i++) { - const list = yield* Effect.promise(() => fs.readdir(dir).then((files) => files.sort())) - const next = JSON.stringify(list) - same = next === last ? same + 1 : 0 - if (same >= 2 && list.length === 11) return list - last = next - yield* Effect.sleep("10 millis") - } - - return yield* Effect.promise(() => fs.readdir(dir).then((files) => files.sort())) - }) +function restoreEnv(key: string, value: string | undefined) { + if (value === undefined) delete process.env[key] + else process.env[key] = value } -it.live("init cleanup keeps the newest timestamped logs", () => +it.live("init writes JSONL to the default state log file", () => Effect.gen(function* () { const log = Global.Path.log + const file = process.env.OPENCODE_LOG_FILE + const level = process.env.OPENCODE_LOG_LEVEL + const print = process.env.OPENCODE_PRINT_LOGS yield* Effect.addFinalizer(() => Effect.sync(() => (Global.Path.log = log))) const dir = yield* tmpdirScoped() Global.Path.log = dir + restoreEnv("OPENCODE_LOG_FILE", undefined) + restoreEnv("OPENCODE_LOG_LEVEL", undefined) + restoreEnv("OPENCODE_PRINT_LOGS", undefined) + yield* Effect.addFinalizer(() => + Effect.promise(async () => { + Global.Path.log = log + restoreEnv("OPENCODE_LOG_FILE", file) + restoreEnv("OPENCODE_LOG_LEVEL", level) + restoreEnv("OPENCODE_PRINT_LOGS", print) + await Log.init({ print: false, level: "DEBUG" }) + }), + ) - const list = Array.from({ length: 12 }, (_, i) => `2000-01-${String(i + 1).padStart(2, "0")}T000000.log`) + yield* Effect.promise(() => Log.init({ print: false, level: "DEBUG" })) + Log.create({ service: "log.test.default" }).info("hello", { answer: 42 }) - yield* Effect.all(list.map((file) => Effect.promise(() => fs.writeFile(path.join(dir, file), file)))) + const record = JSON.parse(yield* Effect.promise(() => fs.readFile(path.join(dir, "log.jsonl"), "utf8"))) - yield* Effect.promise(() => Log.init({ print: false, dev: false })) - - const next = yield* files(dir) - - expect(next).not.toContain(list[0]!) - expect(next).toContain(list.at(-1)!) + expect(Log.file()).toBe(path.join(dir, "log.jsonl")) + expect(record.level).toBe("INFO") + expect(record.message).toBe("hello") + expect(record.service).toBe("log.test.default") + expect(record.pid).toBe(process.pid) + expect(record.fields.answer).toBe(42) + expect(typeof record.run_id).toBe("string") + expect(typeof record.process_role).toBe("string") }), ) -it.live("local dev log is not truncated twice for the same run", () => +it.live("env can override file path and log level", () => Effect.gen(function* () { const log = Global.Path.log - const runID = process.env.OPENCODE_RUN_ID - const initialized = process.env.OPENCODE_LOG_INITIALIZED_RUN_ID + const file = process.env.OPENCODE_LOG_FILE + const level = process.env.OPENCODE_LOG_LEVEL yield* Effect.addFinalizer(() => - Effect.sync(() => { + Effect.promise(async () => { Global.Path.log = log - if (runID === undefined) delete process.env.OPENCODE_RUN_ID - else process.env.OPENCODE_RUN_ID = runID - if (initialized === undefined) delete process.env.OPENCODE_LOG_INITIALIZED_RUN_ID - else process.env.OPENCODE_LOG_INITIALIZED_RUN_ID = initialized + restoreEnv("OPENCODE_LOG_FILE", file) + restoreEnv("OPENCODE_LOG_LEVEL", level) + await Log.init({ print: false, level: "DEBUG" }) }), ) const dir = yield* tmpdirScoped() Global.Path.log = dir - process.env.OPENCODE_RUN_ID = "run-1" - delete process.env.OPENCODE_LOG_INITIALIZED_RUN_ID + process.env.OPENCODE_LOG_FILE = path.join(dir, "custom.jsonl") + process.env.OPENCODE_LOG_LEVEL = "WARN" - yield* Effect.promise(() => Log.init({ print: false, dev: true })) - yield* Effect.promise(() => fs.writeFile(path.join(dir, "dev.log"), "main startup\n")) - yield* Effect.promise(() => Log.init({ print: false, dev: true })) + yield* Effect.promise(() => Log.init({ print: false })) + const logger = Log.create({ service: "log.test.env" }) + logger.info("hidden") + logger.warn("visible") - expect(yield* Effect.promise(() => fs.readFile(path.join(dir, "dev.log"), "utf8"))).toContain("main startup") + const records = (yield* Effect.promise(() => fs.readFile(path.join(dir, "custom.jsonl"), "utf8"))) + .trim() + .split("\n") + .map((line) => JSON.parse(line)) + + expect(Log.file()).toBe(path.join(dir, "custom.jsonl")) + expect(records).toHaveLength(1) + expect(records[0].level).toBe("WARN") + expect(records[0].message).toBe("visible") + }), +) + +it.live("Effect logger writes annotations into JSONL fields", () => + Effect.gen(function* () { + const log = Global.Path.log + yield* Effect.addFinalizer(() => + Effect.promise(async () => { + Global.Path.log = log + await Log.init({ print: false, level: "DEBUG" }) + }), + ) + + const dir = yield* tmpdirScoped() + Global.Path.log = dir + yield* Effect.promise(() => Log.init({ print: false, level: "DEBUG" })) + + yield* Effect.logInfo("effect hello").pipe( + Effect.annotateLogs({ service: "log.test.effect", "session.id": "session-1" }), + Effect.provide(EffectLogger.layer), + ) + + const record = JSON.parse(yield* Effect.promise(() => fs.readFile(path.join(dir, "log.jsonl"), "utf8"))) + + expect(record.level).toBe("INFO") + expect(record.message).toBe("effect hello") + expect(record.service).toBe("log.test.effect") + expect(record.fields["session.id"]).toBe("session-1") }), )