From aa0a23293f4a521795d4a73b27ef1677fbc0ea57 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?=E5=B0=8F=E6=A9=98?= Date: Sat, 23 May 2026 06:07:45 +0000 Subject: [PATCH] feat: add process-level debug logger (Phase 1) - New ProcessLogger in workflow-util: process-scoped JSONL logger - Entry schema: {ts, pid, tag, msg, thread, workflow} - Storage: ~/.uncaged/workflow/logs/YYYY-MM-DD.jsonl - Auto logs process init info (argv, node version, context) - cli-workflow thread commands fully instrumented: - thread start/step, moderator evaluate, agent spawn/done - thread archived, error paths Refs #411, #412, #410 --- packages/cli-workflow/src/commands/thread.ts | 80 +++++++++++++++--- .../__tests__/process-logger.test.ts | 81 +++++++++++++++++++ packages/workflow-util/src/index.ts | 7 ++ packages/workflow-util/src/logger.ts | 22 +---- .../workflow-util/src/process-logger/index.ts | 7 ++ .../src/process-logger/log-tag.ts | 21 +++++ .../src/process-logger/process-logger.ts | 78 ++++++++++++++++++ .../workflow-util/src/process-logger/types.ts | 20 +++++ 8 files changed, 284 insertions(+), 32 deletions(-) create mode 100644 packages/workflow-util/__tests__/process-logger.test.ts create mode 100644 packages/workflow-util/src/process-logger/index.ts create mode 100644 packages/workflow-util/src/process-logger/log-tag.ts create mode 100644 packages/workflow-util/src/process-logger/process-logger.ts create mode 100644 packages/workflow-util/src/process-logger/types.ts diff --git a/packages/cli-workflow/src/commands/thread.ts b/packages/cli-workflow/src/commands/thread.ts index d3db13c..7d25941 100644 --- a/packages/cli-workflow/src/commands/thread.ts +++ b/packages/cli-workflow/src/commands/thread.ts @@ -23,7 +23,7 @@ import type { WorkflowConfig, WorkflowPayload, } from "@uncaged/workflow-protocol"; -import { generateUlid } from "@uncaged/workflow-util"; +import { createProcessLogger, generateUlid, type ProcessLogger } from "@uncaged/workflow-util"; import { config as loadDotenv } from "dotenv"; import { parse, stringify } from "yaml"; @@ -47,6 +47,18 @@ import { materializeWorkflowPayload } from "./workflow.js"; const END_ROLE = "$END"; export const THREAD_READ_DEFAULT_QUOTA = 4000; +const PL_THREAD_START = "7HNQ4B2X"; +const PL_MODERATOR = "M3K8V9T1"; +const PL_AGENT_SPAWN = "R5J2W8N4"; +const PL_AGENT_DONE = "C6P9L3H7"; +const PL_THREAD_ARCHIVED = "F4D8Q2K5"; +const PL_STEP_ERROR = "B8T5N1V6"; + +function failStep(plog: ProcessLogger, message: string): never { + plog.log(PL_STEP_ERROR, message, null); + fail(message); +} + type ChainState = { startHash: CasRef; start: StartNodePayload; @@ -168,6 +180,10 @@ export async function cmdThreadStart( const workflowHash = await resolveWorkflowCasRef(uwf, storageRoot, workflowId, projectRoot); const threadId = generateUlid(Date.now()) as ThreadId; + const plog = createProcessLogger({ + storageRoot, + context: { thread: threadId, workflow: workflowHash }, + }); const startPayload: StartNodePayload = { workflow: workflowHash, prompt, @@ -183,6 +199,12 @@ export async function cmdThreadStart( index[threadId] = headHash; await saveThreadsIndex(storageRoot, index); + plog.log( + PL_THREAD_START, + `thread created workflow=${workflowHash} thread=${threadId} head=${headHash}`, + null, + ); + return { workflow: workflowHash, thread: threadId }; } @@ -625,6 +647,7 @@ function resolveAgentConfig( } function spawnAgent( + plog: ProcessLogger, agent: AgentConfig, threadId: ThreadId, role: string, @@ -648,12 +671,12 @@ function spawnAgent( ? err.stderr : err.stderr.toString("utf8"); const detail = stderr.trim() !== "" ? `: ${stderr.trim()}` : ""; - fail(`agent command failed (${agent.command})${detail}`); + failStep(plog, `agent command failed (${agent.command})${detail}`); } const line = stdout.trim().split("\n").pop()?.trim() ?? ""; if (!isCasRef(line)) { - fail(`agent stdout is not a valid CAS hash: ${line || "(empty)"}`); + failStep(plog, `agent stdout is not a valid CAS hash: ${line || "(empty)"}`); } return line; } @@ -685,9 +708,15 @@ export async function cmdThreadStep( fail(`--count must be a positive integer, got: ${count}`); } + const workflowHash = await resolveActiveThreadWorkflowHash(storageRoot, threadId); + const plog = createProcessLogger({ + storageRoot, + context: { thread: threadId, workflow: workflowHash }, + }); + const results: StepOutput[] = []; for (let i = 0; i < count; i++) { - const result = await cmdThreadStepOnce(storageRoot, threadId, agentOverride); + const result = await cmdThreadStepOnce(storageRoot, threadId, agentOverride, plog); results.push(result); if (result.done) { break; @@ -696,16 +725,31 @@ export async function cmdThreadStep( return results; } -async function cmdThreadStepOnce( +async function resolveActiveThreadWorkflowHash( storageRoot: string, threadId: ThreadId, - agentOverride: string | null, -): Promise { +): Promise { const index = await loadThreadsIndex(storageRoot); const headHash = index[threadId]; if (headHash === undefined) { fail(`thread not active: ${threadId}`); } + const uwf = await createUwfStore(storageRoot); + const chain = walkChain(uwf, headHash); + return chain.start.workflow; +} + +async function cmdThreadStepOnce( + storageRoot: string, + threadId: ThreadId, + agentOverride: string | null, + plog: ProcessLogger, +): Promise { + const index = await loadThreadsIndex(storageRoot); + const headHash = index[threadId]; + if (headHash === undefined) { + failStep(plog, `thread not active: ${threadId}`); + } const uwf = await createUwfStore(storageRoot); const chain = walkChain(uwf, headHash); @@ -715,10 +759,17 @@ async function cmdThreadStepOnce( const nextResult = await evaluate(workflow, context); if (!nextResult.ok) { - fail(nextResult.error.message); + failStep(plog, `moderator evaluate failed: ${nextResult.error.message}`); } + plog.log( + PL_MODERATOR, + `moderator role=${nextResult.value.role} prompt=${nextResult.value.prompt}`, + null, + ); + if (nextResult.value.role === END_ROLE) { + plog.log(PL_THREAD_ARCHIVED, `thread archived head=${headHash}`, null); await archiveThread(storageRoot, threadId, workflowHash, headHash); return { workflow: workflowHash, @@ -733,14 +784,20 @@ async function cmdThreadStepOnce( const config = await loadWorkflowConfig(storageRoot); const agent = resolveAgentConfig(config, workflow, role, agentOverride); + plog.log(PL_AGENT_SPAWN, `spawning agent command=${agent.command}`, { + args: [...agent.args, threadId, role].join(" "), + }); + loadDotenv({ path: getEnvPath(storageRoot) }); - const newHead = spawnAgent(agent, threadId, role, edgePrompt); + const newHead = spawnAgent(plog, agent, threadId, role, edgePrompt); + + plog.log(PL_AGENT_DONE, `agent returned head=${newHead}`, null); // Re-create store to pick up nodes written by the agent subprocess const uwfAfter = await createUwfStore(storageRoot); const newNode = uwfAfter.store.get(newHead); if (newNode === null || newNode.type !== uwfAfter.schemas.stepNode) { - fail(`agent returned hash that is not a StepNode: ${newHead}`); + failStep(plog, `agent returned hash that is not a StepNode: ${newHead}`); } // Reload threads index to avoid overwriting changes made by the agent subprocess @@ -752,11 +809,12 @@ async function cmdThreadStepOnce( const contextAfter = buildModeratorContext(uwfAfter, chainAfter); const afterResult = await evaluate(workflow, contextAfter); if (!afterResult.ok) { - fail(afterResult.error.message); + failStep(plog, `post-step moderator evaluate failed: ${afterResult.error.message}`); } const done = afterResult.value.role === END_ROLE; if (done) { + plog.log(PL_THREAD_ARCHIVED, `thread archived head=${newHead}`, null); await archiveThread(storageRoot, threadId, workflowHash, newHead); } diff --git a/packages/workflow-util/__tests__/process-logger.test.ts b/packages/workflow-util/__tests__/process-logger.test.ts new file mode 100644 index 0000000..e2786f1 --- /dev/null +++ b/packages/workflow-util/__tests__/process-logger.test.ts @@ -0,0 +1,81 @@ +import { mkdirSync, mkdtempSync, readFileSync, rmSync } from "node:fs"; +import { tmpdir } from "node:os"; +import { join } from "node:path"; +import { afterEach, describe, expect, test } from "bun:test"; + +import { createProcessLogger } from "../src/process-logger/index.js"; + +function logDateKey(date: Date): string { + return date.toISOString().slice(0, 10); +} + +describe("createProcessLogger", () => { + let tmpDir: string; + + afterEach(() => { + if (tmpDir !== undefined) { + rmSync(tmpDir, { recursive: true, force: true }); + } + }); + + test("writes init and log lines to dated JSONL under storage root", () => { + tmpDir = mkdtempSync(join(tmpdir(), "uwf-process-log-")); + const plog = createProcessLogger({ + storageRoot: tmpDir, + context: { thread: "THREAD01", workflow: "WORKFLOW01" }, + }); + + expect(plog.pid).toMatch(/^\d+-\d+$/); + + plog.log("7NQW4HBT", "moderator selected role=planner"); + + const logPath = join(tmpDir, "logs", `${logDateKey(new Date())}.jsonl`); + const lines = readFileSync(logPath, "utf8") + .trim() + .split("\n") + .map((line) => JSON.parse(line) as Record); + + expect(lines).toHaveLength(2); + expect(lines[0]?.tag).toBe("W9F3RK2M"); + expect(lines[0]?.pid).toBe(plog.pid); + expect(lines[0]?.thread).toBe("THREAD01"); + expect(lines[0]?.workflow).toBe("WORKFLOW01"); + expect(lines[0]?.msg).toContain("process start"); + expect(lines[0]?.msg).toContain("node="); + + expect(lines[1]?.tag).toBe("7NQW4HBT"); + expect(lines[1]?.msg).toBe("moderator selected role=planner"); + expect(lines[1]?.thread).toBe("THREAD01"); + expect(lines[1]?.workflow).toBe("WORKFLOW01"); + }); + + test("creates logs directory when missing", () => { + tmpDir = mkdtempSync(join(tmpdir(), "uwf-process-log-")); + createProcessLogger({ + storageRoot: tmpDir, + context: { thread: null, workflow: null }, + }); + mkdirSync(join(tmpDir, "logs"), { recursive: true }); + expect(() => + readFileSync(join(tmpDir, "logs", `${logDateKey(new Date())}.jsonl`), "utf8"), + ).not.toThrow(); + }); + + test("merges per-call context into the JSONL entry", () => { + tmpDir = mkdtempSync(join(tmpdir(), "uwf-process-log-")); + const plog = createProcessLogger({ + storageRoot: tmpDir, + context: { thread: "T1", workflow: null }, + }); + plog.log("M3K8V9T1", "spawn agent", { command: "uwf-hermes", args: "tid role" }); + + const logPath = join(tmpDir, "logs", `${logDateKey(new Date())}.jsonl`); + const lines = readFileSync(logPath, "utf8") + .trim() + .split("\n") + .map((line) => JSON.parse(line) as Record); + const last = lines[lines.length - 1]; + expect(last?.command).toBe("uwf-hermes"); + expect(last?.args).toBe("tid role"); + }); +}); diff --git a/packages/workflow-util/src/index.ts b/packages/workflow-util/src/index.ts index 58c2fcf..362f039 100644 --- a/packages/workflow-util/src/index.ts +++ b/packages/workflow-util/src/index.ts @@ -13,6 +13,13 @@ export { validateFrontmatter, } from "./frontmatter-markdown/index.js"; export { createLogger } from "./logger.js"; +export { createProcessLogger } from "./process-logger/index.js"; +export type { + CreateProcessLoggerOptions, + ProcessLogFn, + ProcessLogger, + ProcessLoggerContext, +} from "./process-logger/index.js"; export { normalizeRefsField } from "./refs-field.js"; export { err, ok } from "./result.js"; export { getDefaultWorkflowStorageRoot, getGlobalCasDir } from "./storage-root.js"; diff --git a/packages/workflow-util/src/logger.ts b/packages/workflow-util/src/logger.ts index 2305def..e2a2e4d 100644 --- a/packages/workflow-util/src/logger.ts +++ b/packages/workflow-util/src/logger.ts @@ -1,28 +1,8 @@ import { appendFileSync } from "node:fs"; -import { CROCKFORD_BASE32_ALPHABET } from "./base32.js"; +import { assertValidLogTag } from "./process-logger/log-tag.js"; import type { CreateLoggerOptions, LogFn } from "./types.js"; -const TAG_LENGTH = 8; - -const TAG_CHAR_SET: ReadonlySet = new Set(CROCKFORD_BASE32_ALPHABET.split("")); - -function assertValidLogTag(tag: string): void { - if (tag.length !== TAG_LENGTH) { - throw new Error(`log tag must be exactly ${TAG_LENGTH} characters`); - } - for (let i = 0; i < tag.length; i++) { - const ch = tag[i]; - if (ch === undefined) { - throw new Error("log tag validation failed"); - } - const upper = ch.toUpperCase(); - if (!TAG_CHAR_SET.has(upper)) { - throw new Error(`invalid Crockford Base32 character in log tag: ${ch}`); - } - } -} - /** Append one JSONL log record: `{ tag, content, timestamp }` per RFC-001. */ export function createLogger(options: CreateLoggerOptions): LogFn { if (options.sink.kind === "stderr") { diff --git a/packages/workflow-util/src/process-logger/index.ts b/packages/workflow-util/src/process-logger/index.ts new file mode 100644 index 0000000..b8c8530 --- /dev/null +++ b/packages/workflow-util/src/process-logger/index.ts @@ -0,0 +1,7 @@ +export { createProcessLogger } from "./process-logger.js"; +export type { + CreateProcessLoggerOptions, + ProcessLogFn, + ProcessLogger, + ProcessLoggerContext, +} from "./types.js"; diff --git a/packages/workflow-util/src/process-logger/log-tag.ts b/packages/workflow-util/src/process-logger/log-tag.ts new file mode 100644 index 0000000..ba85c3f --- /dev/null +++ b/packages/workflow-util/src/process-logger/log-tag.ts @@ -0,0 +1,21 @@ +import { CROCKFORD_BASE32_ALPHABET } from "../base32.js"; + +const TAG_LENGTH = 8; + +const TAG_CHAR_SET: ReadonlySet = new Set(CROCKFORD_BASE32_ALPHABET.split("")); + +export function assertValidLogTag(tag: string): void { + if (tag.length !== TAG_LENGTH) { + throw new Error(`log tag must be exactly ${TAG_LENGTH} characters`); + } + for (let i = 0; i < tag.length; i++) { + const ch = tag[i]; + if (ch === undefined) { + throw new Error("log tag validation failed"); + } + const upper = ch.toUpperCase(); + if (!TAG_CHAR_SET.has(upper)) { + throw new Error(`invalid Crockford Base32 character in log tag: ${ch}`); + } + } +} diff --git a/packages/workflow-util/src/process-logger/process-logger.ts b/packages/workflow-util/src/process-logger/process-logger.ts new file mode 100644 index 0000000..7967929 --- /dev/null +++ b/packages/workflow-util/src/process-logger/process-logger.ts @@ -0,0 +1,78 @@ +import { appendFileSync, mkdirSync } from "node:fs"; +import { join } from "node:path"; + +import { getDefaultWorkflowStorageRoot } from "../storage-root.js"; +import { assertValidLogTag } from "./log-tag.js"; +import type { CreateProcessLoggerOptions, ProcessLogger, ProcessLoggerContext } from "./types.js"; + +const INIT_TAG = "W9F3RK2M"; + +function logDateKey(date: Date): string { + return date.toISOString().slice(0, 10); +} + +function getProcessLogsDir(storageRoot: string): string { + return join(storageRoot, "logs"); +} + +function getProcessLogFilePath(storageRoot: string, date: Date): string { + return join(getProcessLogsDir(storageRoot), `${logDateKey(date)}.jsonl`); +} + +function buildEntry( + processId: string, + tag: string, + msg: string, + baseContext: ProcessLoggerContext, + extra: Record | null, +): Record { + const entry: Record = { + ts: new Date().toISOString(), + pid: processId, + tag: tag.toUpperCase(), + msg, + }; + if (baseContext.thread !== null) { + entry.thread = baseContext.thread; + } + if (baseContext.workflow !== null) { + entry.workflow = baseContext.workflow; + } + if (extra !== null) { + for (const [key, value] of Object.entries(extra)) { + entry[key] = value; + } + } + return entry; +} + +function appendEntry(filePath: string, entry: Record): void { + appendFileSync(filePath, `${JSON.stringify(entry)}\n`, "utf8"); +} + +/** Process-scoped debug logger — append-only JSONL under `/logs/YYYY-MM-DD.jsonl`. */ +export function createProcessLogger(options: CreateProcessLoggerOptions): ProcessLogger { + const storageRoot = options.storageRoot ?? getDefaultWorkflowStorageRoot(); + const processId = `${Date.now()}-${process.pid}`; + const baseContext = options.context; + const logFilePath = getProcessLogFilePath(storageRoot, new Date()); + + mkdirSync(getProcessLogsDir(storageRoot), { recursive: true }); + + const log: ProcessLogger["log"] = (tag, msg, context = null) => { + assertValidLogTag(tag); + appendEntry(logFilePath, buildEntry(processId, tag, msg, baseContext, context)); + }; + + const argvSummary = JSON.stringify(process.argv); + const initParts = [`argv=${argvSummary}`, `node=${process.version}`]; + if (baseContext.thread !== null) { + initParts.push(`thread=${baseContext.thread}`); + } + if (baseContext.workflow !== null) { + initParts.push(`workflow=${baseContext.workflow}`); + } + log(INIT_TAG, `process start ${initParts.join(" ")}`, null); + + return { pid: processId, log }; +} diff --git a/packages/workflow-util/src/process-logger/types.ts b/packages/workflow-util/src/process-logger/types.ts new file mode 100644 index 0000000..9dde2d8 --- /dev/null +++ b/packages/workflow-util/src/process-logger/types.ts @@ -0,0 +1,20 @@ +export type ProcessLoggerContext = { + thread: string | null; + workflow: string | null; +}; + +export type CreateProcessLoggerOptions = { + storageRoot: string | null; + context: ProcessLoggerContext; +}; + +export type ProcessLogFn = ( + tag: string, + msg: string, + context: Record | null, +) => void; + +export type ProcessLogger = { + pid: string; + log: ProcessLogFn; +};