From 706a2f8e9fd56d3397eafec23e740c7d4b641fcd Mon Sep 17 00:00:00 2001 From: Jeremy McSpadden Date: Tue, 31 Mar 2026 12:49:19 -0500 Subject: [PATCH] refactor(state): centralize pipeline logging through workflow logger (#3282) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit * refactor(state): centralize pipeline logging through workflow logger Route 15 raw process.stderr.write calls through the structured workflow logger (logWarning/logError). Adds "db" and "dispatch" as new LogComponent values. Enables auto-loop drain/summarize, audit-log persistence, and doctor integration for reconciliation and DB events that previously bypassed structured logging. Files changed: - workflow-logger.ts: add "db" and "dispatch" components - state.ts: 3 reconciliation calls → logWarning/logError - gsd-db.ts: 4 DB operation calls → logError - workflow-reconcile.ts: 3 event merge calls → logWarning/logError - auto-dispatch.ts: 1 reactive dispatch call → logError - auto-post-unit.ts: 3 triage/rogue calls → logWarning/logError * test(workflow-logger): add tests for db and dispatch log components Cover the new LogComponent values added in this refactor to satisfy the CI require-tests gate. --- src/resources/extensions/gsd/auto-dispatch.ts | 3 +- .../extensions/gsd/auto-post-unit.ts | 7 +-- src/resources/extensions/gsd/gsd-db.ts | 9 ++-- src/resources/extensions/gsd/state.ts | 13 ++--- .../gsd/tests/workflow-logger.test.ts | 48 +++++++++++++++++++ .../extensions/gsd/workflow-logger.ts | 4 +- .../extensions/gsd/workflow-reconcile.ts | 13 ++--- 7 files changed, 70 insertions(+), 27 deletions(-) diff --git a/src/resources/extensions/gsd/auto-dispatch.ts b/src/resources/extensions/gsd/auto-dispatch.ts index b537d8916..839ba5fb1 100644 --- a/src/resources/extensions/gsd/auto-dispatch.ts +++ b/src/resources/extensions/gsd/auto-dispatch.ts @@ -28,6 +28,7 @@ import { buildSliceFileName, } from "./paths.js"; import { existsSync, mkdirSync, readFileSync, writeFileSync } from "node:fs"; +import { logError } from "./workflow-logger.js"; import { join } from "node:path"; import { hasImplementationArtifacts } from "./auto-recovery.js"; import { @@ -526,7 +527,7 @@ export const DISPATCH_RULES: DispatchRule[] = [ }; } catch (err) { // Non-fatal — fall through to sequential execution - process.stderr.write(`gsd-reactive: graph derivation failed: ${(err as Error).message}\n`); + logError("dispatch", "reactive graph derivation failed", { error: (err as Error).message }); return null; } }, diff --git a/src/resources/extensions/gsd/auto-post-unit.ts b/src/resources/extensions/gsd/auto-post-unit.ts index 51201b6d9..860e71bd1 100644 --- a/src/resources/extensions/gsd/auto-post-unit.ts +++ b/src/resources/extensions/gsd/auto-post-unit.ts @@ -13,6 +13,7 @@ import type { ExtensionContext, ExtensionAPI } from "@gsd/pi-coding-agent"; import { deriveState } from "./state.js"; +import { logWarning, logError } from "./workflow-logger.js"; import { loadFile, parseSummary, resolveAllOverrides } from "./files.js"; import { loadPrompt } from "./prompt-loader.js"; import { @@ -412,10 +413,10 @@ export async function postUnitPreVerification(pctx: PostUnitContext, opts?: PreV ); } for (const action of triageResult.actions) { - process.stderr.write(`gsd-triage: ${action}\n`); + logWarning("engine", `triage resolution: ${action}`); } } catch (err) { - process.stderr.write(`gsd-triage: resolution execution failed: ${(err as Error).message}\n`); + logError("engine", "triage resolution failed", { error: (err as Error).message }); } } @@ -423,7 +424,7 @@ export async function postUnitPreVerification(pctx: PostUnitContext, opts?: PreV try { const rogueFiles = detectRogueFileWrites(s.currentUnit.type, s.currentUnit.id, s.basePath); for (const rogue of rogueFiles) { - process.stderr.write(`gsd-rogue: detected rogue file write: ${rogue.path} (unit: ${rogue.unitId})\n`); + logWarning("engine", "rogue file write detected", { path: rogue.path, unitId: rogue.unitId }); ctx.ui.notify(`Rogue file write detected: ${rogue.path}`, "warning"); } } catch (e) { diff --git a/src/resources/extensions/gsd/gsd-db.ts b/src/resources/extensions/gsd/gsd-db.ts index e6cb15dd3..4c22b41dc 100644 --- a/src/resources/extensions/gsd/gsd-db.ts +++ b/src/resources/extensions/gsd/gsd-db.ts @@ -10,6 +10,7 @@ import { existsSync, copyFileSync, mkdirSync, realpathSync } from "node:fs"; import { dirname } from "node:path"; import type { Decision, Requirement, GateRow, GateId, GateScope, GateStatus, GateVerdict } from "./types.js"; import { GSDError, GSD_STALE_STATE } from "./errors.js"; +import { logError } from "./workflow-logger.js"; const _require = createRequire(import.meta.url); @@ -1773,7 +1774,7 @@ export function copyWorktreeDb(srcDbPath: string, destDbPath: string): boolean { copyFileSync(srcDbPath, destDbPath); return true; } catch (err) { - process.stderr.write(`gsd-db: failed to copy DB to worktree: ${(err as Error).message}\n`); + logError("db", "failed to copy DB to worktree", { error: (err as Error).message }); return false; } } @@ -1805,13 +1806,13 @@ export function reconcileWorktreeDb( // ATTACH DATABASE doesn't support parameterized paths in all providers, // so we use strict allowlist validation instead. if (/['";\x00]/.test(worktreeDbPath)) { - process.stderr.write("gsd-db: worktree DB reconciliation failed: path contains unsafe characters\n"); + logError("db", "worktree DB reconciliation failed: path contains unsafe characters"); return zero; } if (!currentDb) { const opened = openDatabase(mainDbPath); if (!opened) { - process.stderr.write("gsd-db: worktree DB reconciliation failed: cannot open main DB\n"); + logError("db", "worktree DB reconciliation failed: cannot open main DB"); return zero; } } @@ -1945,7 +1946,7 @@ export function reconcileWorktreeDb( try { adapter.exec("DETACH DATABASE wt"); } catch { /* best effort */ } } } catch (err) { - process.stderr.write(`gsd-db: worktree DB reconciliation failed: ${(err as Error).message}\n`); + logError("db", "worktree DB reconciliation failed", { error: (err as Error).message }); return { ...zero, conflicts }; } } diff --git a/src/resources/extensions/gsd/state.ts b/src/resources/extensions/gsd/state.ts index 77e36c001..9e1b3f311 100644 --- a/src/resources/extensions/gsd/state.ts +++ b/src/resources/extensions/gsd/state.ts @@ -42,6 +42,7 @@ import { join, resolve } from 'path'; import { existsSync, readdirSync, readFileSync } from 'node:fs'; import { debugCount, debugTime } from './debug-logger.js'; import { extractVerdict } from './verdict-parser.js'; +import { logWarning, logError } from './workflow-logger.js'; import { isDbAvailable, @@ -704,15 +705,11 @@ export async function deriveStateFromDb(basePath: string): Promise { if (summaryPath && existsSync(summaryPath)) { try { updateTaskStatus(activeMilestone.id, activeSlice.id, t.id, "complete"); - process.stderr.write( - `gsd-reconcile: task ${activeMilestone.id}/${activeSlice.id}/${t.id} had SUMMARY on disk but DB status was "${t.status}" — updated to "complete" (#2514)\n`, - ); + logWarning("reconcile", `task ${activeMilestone.id}/${activeSlice.id}/${t.id} status reconciled from "${t.status}" to "complete" (#2514)`, { mid: activeMilestone.id, sid: activeSlice.id, tid: t.id }); reconciled = true; } catch (e) { // DB write failed — continue with stale status rather than crash - process.stderr.write( - `gsd-reconcile: failed to update task ${t.id}: ${(e as Error).message}\n`, - ); + logError("reconcile", `failed to update task ${t.id}`, { tid: t.id, error: (e as Error).message }); } } } @@ -1367,9 +1364,7 @@ export async function _deriveStateImpl(basePath: string): Promise { const summaryPath = resolveTaskFile(basePath, activeMilestone.id, activeSlice.id, t.id, "SUMMARY"); if (summaryPath && existsSync(summaryPath)) { t.done = true; - process.stderr.write( - `gsd-reconcile: task ${activeMilestone.id}/${activeSlice.id}/${t.id} has SUMMARY on disk but plan shows incomplete — marking done (#2514)\n`, - ); + logWarning("reconcile", `task ${activeMilestone.id}/${activeSlice.id}/${t.id} reconciled via SUMMARY on disk (#2514)`, { mid: activeMilestone.id, sid: activeSlice.id, tid: t.id }); } } diff --git a/src/resources/extensions/gsd/tests/workflow-logger.test.ts b/src/resources/extensions/gsd/tests/workflow-logger.test.ts index 015e4ff85..69fd2dcd4 100644 --- a/src/resources/extensions/gsd/tests/workflow-logger.test.ts +++ b/src/resources/extensions/gsd/tests/workflow-logger.test.ts @@ -317,6 +317,54 @@ describe("workflow-logger", () => { }); }); + describe("new log components (db, dispatch)", () => { + test("logError with 'db' component stores correct component", () => { + logError("db", "failed to copy DB to worktree", { error: "ENOENT" }); + const entries = peekLogs(); + assert.equal(entries.length, 1); + assert.equal(entries[0].severity, "error"); + assert.equal(entries[0].component, "db"); + assert.equal(entries[0].message, "failed to copy DB to worktree"); + assert.deepEqual(entries[0].context, { error: "ENOENT" }); + }); + + test("logError with 'dispatch' component stores correct component", () => { + logError("dispatch", "reactive graph derivation failed", { error: "timeout" }); + const entries = peekLogs(); + assert.equal(entries.length, 1); + assert.equal(entries[0].severity, "error"); + assert.equal(entries[0].component, "dispatch"); + assert.deepEqual(entries[0].context, { error: "timeout" }); + }); + + test("logWarning with 'reconcile' component for centralized logging path", () => { + logWarning("reconcile", "could not acquire sync lock — another reconciliation may be in progress"); + const entries = peekLogs(); + assert.equal(entries.length, 1); + assert.equal(entries[0].severity, "warn"); + assert.equal(entries[0].component, "reconcile"); + }); + + test("summarizeLogs includes db and dispatch entries", () => { + logError("db", "worktree DB reconciliation failed: path contains unsafe characters"); + logWarning("dispatch", "graph derivation timeout"); + const summary = summarizeLogs()!; + assert.ok(summary.includes("1 error(s)")); + assert.ok(summary.includes("1 warning(s)")); + assert.ok(summary.includes("unsafe characters")); + assert.ok(summary.includes("graph derivation timeout")); + }); + + test("formatForNotification renders db and dispatch components", () => { + logError("db", "copy failed"); + logWarning("dispatch", "slow derivation"); + const entries = drainLogs(); + const formatted = formatForNotification(entries); + assert.ok(formatted.includes("[db] copy failed")); + assert.ok(formatted.includes("[dispatch] slow derivation")); + }); + }); + describe("stderr output", () => { test("writes WARN prefix to stderr for warnings", (t) => { const written: string[] = []; diff --git a/src/resources/extensions/gsd/workflow-logger.ts b/src/resources/extensions/gsd/workflow-logger.ts index 0770408d0..882059302 100644 --- a/src/resources/extensions/gsd/workflow-logger.ts +++ b/src/resources/extensions/gsd/workflow-logger.ts @@ -31,7 +31,9 @@ export type LogComponent = | "state" // deriveState fallback/degradation | "tool" // Tool handler errors | "compaction" // Event compaction - | "reconcile"; // Worktree reconciliation + | "reconcile" // Worktree reconciliation + | "db" // Database operations (gsd-db) + | "dispatch"; // Auto-dispatch rule evaluation export interface LogEntry { ts: string; diff --git a/src/resources/extensions/gsd/workflow-reconcile.ts b/src/resources/extensions/gsd/workflow-reconcile.ts index 763f93037..216f1019a 100644 --- a/src/resources/extensions/gsd/workflow-reconcile.ts +++ b/src/resources/extensions/gsd/workflow-reconcile.ts @@ -1,5 +1,6 @@ import { join } from "node:path"; import { mkdirSync, existsSync, readFileSync, unlinkSync } from "node:fs"; +import { logWarning, logError } from "./workflow-logger.js"; import { readEvents, findForkPoint, appendEvent, getSessionId } from "./workflow-events.js"; import type { WorkflowEvent } from "./workflow-events.js"; import { @@ -308,9 +309,7 @@ export function reconcileWorktreeLogs( // Acquire advisory lock to prevent concurrent reconcile + append races const lock = acquireSyncLock(mainBasePath); if (!lock.acquired) { - process.stderr.write( - `[gsd] reconcile: could not acquire sync lock — another reconciliation may be in progress\n`, - ); + logWarning("reconcile", "could not acquire sync lock — another reconciliation may be in progress"); return { autoMerged: 0, conflicts: [] }; } @@ -349,9 +348,7 @@ function _reconcileWorktreeLogsInner( if (conflicts.length > 0) { // D-04: atomic all-or-nothing — block entire merge writeConflictsFile(mainBasePath, conflicts, worktreeBasePath); - process.stderr.write( - `[gsd] reconcile: ${conflicts.length} conflict(s) detected — see ${join(mainBasePath, ".gsd", "CONFLICTS.md")}\n`, - ); + logError("reconcile", `${conflicts.length} conflict(s) detected`, { count: String(conflicts.length), path: join(mainBasePath, ".gsd", "CONFLICTS.md") }); return { autoMerged: 0, conflicts }; } @@ -375,9 +372,7 @@ function _reconcileWorktreeLogsInner( try { writeManifest(mainBasePath); } catch (err) { - process.stderr.write( - `[gsd] reconcile: manifest write failed (non-fatal): ${(err as Error).message}\n`, - ); + logWarning("reconcile", "manifest write failed (non-fatal)", { error: (err as Error).message }); } return { autoMerged: merged.length, conflicts: [] };