feat: add gsd --debug mode with structured JSONL diagnostic logging (#468)

Add `gsd auto --debug` and `gsd next --debug` flags (also GSD_DEBUG=1
env var) that write structured JSONL debug logs to `.gsd/debug/`.

Instrumentation points:
- deriveState() timing and result phase
- parseRoadmap/parsePlan timing with native flag
- TTSR checkDelta timing, buffer size, and peak tracking
- Unit dispatch cycle/lifetime counts
- Context injection sizing
- Debug summary with aggregated stats on stop

The logger is zero-overhead when disabled — all functions check a
boolean and return immediately. Auto-prunes to 5 most recent logs.
This commit is contained in:
Flux Labs 2026-03-15 12:51:16 -05:00
parent 5cc99ac77e
commit afd4a514e0
8 changed files with 451 additions and 5 deletions

View file

@ -103,6 +103,7 @@ import type { GitPreferences } from "./git-service.js";
import { truncateToWidth, visibleWidth } from "@gsd/pi-tui";
import { makeUI, GLYPH, INDENT } from "../shared/ui.js";
import { showNextAction } from "../shared/next-action-ui.js";
import { debugLog, debugTime, debugCount, debugPeak, enableDebug, isDebugEnabled, writeDebugSummary, getDebugLogPath } from "./debug-logger.js";
// ─── Disk-backed completed-unit helpers ───────────────────────────────────────
@ -400,6 +401,14 @@ export async function stopAuto(ctx?: ExtensionContext, pi?: ExtensionAPI): Promi
try { await rebuildState(basePath); } catch { /* non-fatal */ }
}
// Write debug summary before resetting state
if (isDebugEnabled()) {
const logPath = writeDebugSummary();
if (logPath) {
ctx?.ui.notify(`Debug log written → ${logPath}`, "info");
}
}
resetMetrics();
resetHookState();
if (basePath) clearPersistedHookState(basePath);
@ -732,6 +741,24 @@ export async function startAuto(
clearLock(base);
}
// ── Debug mode: env-var activation ──────────────────────────────────────
if (!isDebugEnabled() && process.env.GSD_DEBUG === "1") {
enableDebug(base);
}
if (isDebugEnabled()) {
const { isNativeParserAvailable } = await import("./native-parser-bridge.js");
debugLog("debug-start", {
platform: process.platform,
arch: process.arch,
node: process.version,
model: ctx.model?.id ?? "unknown",
provider: ctx.model?.provider ?? "unknown",
nativeParser: isNativeParserAvailable(),
cwd: base,
});
ctx.ui.notify(`Debug logging enabled → ${getDebugLogPath()}`, "info");
}
const state = await deriveState(base);
// No active work at all — start a new milestone via the discuss flow.
@ -1560,7 +1587,14 @@ async function dispatchNextUnit(
// stale data between handleAgentEnd and this dispatch call (Path B fix).
clearParseCache();
const stopDeriveTimer = debugTime("derive-state");
let state = await deriveState(basePath);
stopDeriveTimer({
phase: state.phase,
milestone: state.activeMilestone?.id,
slice: state.activeSlice?.id,
task: state.activeTask?.id,
});
let mid = state.activeMilestone?.id;
let midTitle = state.activeMilestone?.title;
@ -2095,6 +2129,14 @@ async function dispatchNextUnit(
const dispatchKey = `${unitType}/${unitId}`;
const prevCount = unitDispatchCount.get(dispatchKey) ?? 0;
debugLog("dispatch-unit", {
type: unitType,
id: unitId,
cycle: prevCount + 1,
lifetime: (unitLifetimeDispatches.get(dispatchKey) ?? 0) + 1,
});
debugCount("dispatches");
// Hard lifetime cap — survives counter resets from loop-recovery/self-repair.
// Catches the case where reconciliation "succeeds" (artifacts exist) but
// deriveState keeps returning the same unit, creating an infinite cycle.

View file

@ -8,6 +8,7 @@ import type { ExtensionAPI, ExtensionCommandContext } from "@gsd/pi-coding-agent
import { AuthStorage } from "@gsd/pi-coding-agent";
import { existsSync, readFileSync, mkdirSync } from "node:fs";
import { join, dirname } from "node:path";
import { enableDebug, isDebugEnabled } from "./debug-logger.js";
import { fileURLToPath } from "node:url";
import { deriveState } from "./state.js";
import { GSDDashboardOverlay } from "./dashboard-overlay.js";
@ -68,7 +69,7 @@ export function registerGSDCommand(pi: ExtensionAPI): void {
if (parts[0] === "auto" && parts.length <= 2) {
const flagPrefix = parts[1] ?? "";
return ["--verbose"]
return ["--verbose", "--debug"]
.filter((f) => f.startsWith(flagPrefix))
.map((f) => ({ value: `auto ${f}`, label: f }));
}
@ -123,12 +124,16 @@ export function registerGSDCommand(pi: ExtensionAPI): void {
if (trimmed === "next" || trimmed.startsWith("next ")) {
const verboseMode = trimmed.includes("--verbose");
const debugMode = trimmed.includes("--debug");
if (debugMode) enableDebug(process.cwd());
await startAuto(ctx, pi, process.cwd(), verboseMode, { step: true });
return;
}
if (trimmed === "auto" || trimmed.startsWith("auto ")) {
const verboseMode = trimmed.includes("--verbose");
const debugMode = trimmed.includes("--debug");
if (debugMode) enableDebug(process.cwd());
await startAuto(ctx, pi, process.cwd(), verboseMode);
return;
}

View file

@ -0,0 +1,179 @@
// GSD Extension — Debug Logger
// Structured JSONL debug logging for diagnosing stuck/slow GSD sessions.
// Zero overhead when disabled — all public functions are no-ops.
// Copyright (c) 2026 Jeremy McSpadden <jeremy@fluxlabs.net>
import { appendFileSync, mkdirSync, readdirSync, unlinkSync } from 'node:fs';
import { join } from 'node:path';
import { gsdRoot } from './paths.js';
// ─── State ────────────────────────────────────────────────────────────────────
let _enabled = false;
let _logPath: string | null = null;
let _startTime = 0;
/** Rolling counters for the debug summary written on stop. */
const _counters = {
deriveStateCalls: 0,
deriveStateTotalMs: 0,
ttsrChecks: 0,
ttsrTotalMs: 0,
ttsrPeakBuffer: 0,
parseRoadmapCalls: 0,
parseRoadmapTotalMs: 0,
parsePlanCalls: 0,
parsePlanTotalMs: 0,
dispatches: 0,
renders: 0,
};
/** Max debug log files to keep. Older ones are pruned on enable. */
const MAX_DEBUG_LOGS = 5;
// ─── Public API ───────────────────────────────────────────────────────────────
/**
* Enable debug logging. Creates the log file and prunes old logs.
* Can be activated via `--debug` flag or `GSD_DEBUG=1` env var.
*/
export function enableDebug(basePath: string): void {
const debugDir = join(gsdRoot(basePath), 'debug');
mkdirSync(debugDir, { recursive: true });
// Prune old debug logs
try {
const files = readdirSync(debugDir)
.filter(f => f.startsWith('debug-') && f.endsWith('.log'))
.sort();
while (files.length >= MAX_DEBUG_LOGS) {
const oldest = files.shift()!;
try { unlinkSync(join(debugDir, oldest)); } catch { /* ignore */ }
}
} catch { /* non-fatal */ }
const timestamp = new Date().toISOString().replace(/[:.]/g, '-');
_logPath = join(debugDir, `debug-${timestamp}.log`);
_startTime = Date.now();
_enabled = true;
// Reset counters
for (const key of Object.keys(_counters) as (keyof typeof _counters)[]) {
_counters[key] = 0;
}
}
/** Disable debug logging and return the log file path (if any). */
export function disableDebug(): string | null {
const path = _logPath;
_enabled = false;
_logPath = null;
_startTime = 0;
return path;
}
/** Check if debug mode is active. */
export function isDebugEnabled(): boolean {
return _enabled;
}
/** Return the current log file path (or null). */
export function getDebugLogPath(): string | null {
return _logPath;
}
/**
* Log a structured debug event. No-op when debug is disabled.
*
* Each event is one JSON line: `{ ts, event, ...data }`
*/
export function debugLog(event: string, data?: Record<string, unknown>): void {
if (!_enabled || !_logPath) return;
const entry = {
ts: new Date().toISOString(),
event,
...data,
};
try {
appendFileSync(_logPath, JSON.stringify(entry) + '\n');
} catch {
// Silently ignore write failures — debug logging must never break GSD
}
}
/**
* Start a timer for a named operation. Returns a stop function that logs
* the elapsed time and optional result data.
*
* Usage:
* ```ts
* const stop = debugTime('derive-state');
* const result = await deriveState(base);
* stop({ phase: result.phase });
* ```
*/
export function debugTime(event: string): (data?: Record<string, unknown>) => void {
if (!_enabled) return _noop;
const start = performance.now();
return (data?: Record<string, unknown>) => {
const elapsed_ms = Math.round((performance.now() - start) * 100) / 100;
debugLog(event, { elapsed_ms, ...data });
};
}
// ─── Counter Helpers ──────────────────────────────────────────────────────────
/** Increment a debug counter (used by instrumentation points). */
export function debugCount(counter: keyof typeof _counters, value = 1): void {
if (!_enabled) return;
_counters[counter] += value;
}
/** Record a peak value (only updates if new value is higher). */
export function debugPeak(counter: keyof typeof _counters, value: number): void {
if (!_enabled) return;
if (value > _counters[counter]) {
_counters[counter] = value;
}
}
/**
* Write the debug summary and disable logging. Call this when auto-mode stops.
* Returns the log file path for user notification.
*/
export function writeDebugSummary(): string | null {
if (!_enabled || !_logPath) return null;
const totalElapsed_ms = Date.now() - _startTime;
const avgDeriveState_ms = _counters.deriveStateCalls > 0
? Math.round((_counters.deriveStateTotalMs / _counters.deriveStateCalls) * 100) / 100
: 0;
const avgTtsrCheck_ms = _counters.ttsrChecks > 0
? Math.round((_counters.ttsrTotalMs / _counters.ttsrChecks) * 100) / 100
: 0;
debugLog('debug-summary', {
totalElapsed_ms,
dispatches: _counters.dispatches,
deriveStateCalls: _counters.deriveStateCalls,
avgDeriveState_ms,
parseRoadmapCalls: _counters.parseRoadmapCalls,
avgParseRoadmap_ms: _counters.parseRoadmapCalls > 0
? Math.round((_counters.parseRoadmapTotalMs / _counters.parseRoadmapCalls) * 100) / 100
: 0,
parsePlanCalls: _counters.parsePlanCalls,
ttsrChecks: _counters.ttsrChecks,
avgTtsrCheck_ms,
ttsrPeakBuffer: _counters.ttsrPeakBuffer,
renders: _counters.renders,
});
return disableDebug();
}
// ─── Internal ─────────────────────────────────────────────────────────────────
function _noop(_data?: Record<string, unknown>): void { /* no-op */ }

View file

@ -21,6 +21,7 @@ import type {
import { checkExistingEnvKeys } from '../get-secrets-from-user.js';
import { parseRoadmapSlices } from './roadmap-slices.js';
import { nativeParseRoadmap, nativeExtractSection, NATIVE_UNAVAILABLE } from './native-parser-bridge.js';
import { debugTime, debugCount } from './debug-logger.js';
// ─── Parse Cache ──────────────────────────────────────────────────────────
@ -220,9 +221,14 @@ export function parseRoadmap(content: string): Roadmap {
}
function _parseRoadmapImpl(content: string): Roadmap {
const stopTimer = debugTime("parse-roadmap");
// Try native parser first for better performance
const nativeResult = nativeParseRoadmap(content);
if (nativeResult) return nativeResult;
if (nativeResult) {
stopTimer({ native: true, slices: nativeResult.slices.length, boundaryEntries: nativeResult.boundaryMap.length });
debugCount("parseRoadmapCalls");
return nativeResult;
}
const lines = content.split('\n');
@ -291,7 +297,10 @@ function _parseRoadmapImpl(content: string): Roadmap {
}
}
return { title, vision, successCriteria, slices, boundaryMap };
const result = { title, vision, successCriteria, slices, boundaryMap };
stopTimer({ native: false, slices: slices.length, boundaryEntries: boundaryMap.length });
debugCount("parseRoadmapCalls");
return result;
}
// ─── Secrets Manifest Parser ───────────────────────────────────────────────
@ -370,6 +379,7 @@ export function parsePlan(content: string): SlicePlan {
}
function _parsePlanImpl(content: string): SlicePlan {
const stopTimer = debugTime("parse-plan");
const lines = content.split('\n');
const h1 = lines.find(l => l.startsWith('# '));
@ -442,7 +452,10 @@ function _parsePlanImpl(content: string): SlicePlan {
const filesSection = extractSection(content, 'Files Likely Touched');
const filesLikelyTouched = filesSection ? parseBullets(filesSection) : [];
return { id, title, goal, demo, mustHaves, tasks, filesLikelyTouched };
const result = { id, title, goal, demo, mustHaves, tasks, filesLikelyTouched };
stopTimer({ tasks: tasks.length });
debugCount("parsePlanCalls");
return result;
}
// ─── Summary Parser ────────────────────────────────────────────────────────

View file

@ -25,6 +25,7 @@ import type {
} from "@gsd/pi-coding-agent";
import { createBashTool, createWriteTool, createReadTool, createEditTool, isToolCallEventType } from "@gsd/pi-coding-agent";
import { debugLog, debugTime } from "./debug-logger.js";
import { registerGSDCommand } from "./commands.js";
import { registerExitCommand } from "./exit-command.js";
import { registerWorktreeCommand, getWorktreeOriginalCwd, getActiveWorktreeName } from "./worktree-command.js";
@ -251,6 +252,7 @@ export default function (pi: ExtensionAPI) {
pi.on("before_agent_start", async (event, ctx: ExtensionContext) => {
if (!existsSync(join(process.cwd(), ".gsd"))) return;
const stopContextTimer = debugTime("context-inject");
const systemContent = loadPrompt("system");
const loadedPreferences = loadEffectiveGSDPreferences();
let preferenceBlock = "";
@ -302,8 +304,16 @@ export default function (pi: ExtensionAPI) {
].join("\n");
}
const fullSystem = `${event.systemPrompt}\n\n[SYSTEM CONTEXT — GSD]\n\n${systemContent}${preferenceBlock}${newSkillsBlock}${worktreeBlock}`;
stopContextTimer({
systemPromptSize: fullSystem.length,
injectionSize: injection?.length ?? 0,
hasPreferences: preferenceBlock.length > 0,
hasNewSkills: newSkillsBlock.length > 0,
});
return {
systemPrompt: `${event.systemPrompt}\n\n[SYSTEM CONTEXT — GSD]\n\n${systemContent}${preferenceBlock}${newSkillsBlock}${worktreeBlock}`,
systemPrompt: fullSystem,
...(injection
? {
message: {

View file

@ -1,6 +1,7 @@
// GSD Extension — State Derivation
// Reads roadmap + plan files to determine current position.
// Pure TypeScript, zero Pi dependencies.
// Copyright (c) 2026 Jeremy McSpadden <jeremy@fluxlabs.net>
import type {
GSDState,
@ -34,6 +35,7 @@ import { milestoneIdSort, findMilestoneIds } from './guided-flow.js';
import { nativeBatchParseGsdFiles, type BatchParsedFile } from './native-parser-bridge.js';
import { join, resolve } from 'path';
import { debugCount, debugTime } from './debug-logger.js';
// ─── Query Functions ───────────────────────────────────────────────────────
@ -116,7 +118,10 @@ export async function deriveState(basePath: string): Promise<GSDState> {
return _stateCache.result;
}
const stopTimer = debugTime("derive-state-impl");
const result = await _deriveStateImpl(basePath);
stopTimer({ phase: result.phase, milestone: result.activeMilestone?.id });
debugCount("deriveStateCalls");
_stateCache = { basePath, result, timestamp: Date.now() };
return result;
}

View file

@ -0,0 +1,184 @@
// Debug Logger Tests
// Copyright (c) 2026 Jeremy McSpadden <jeremy@fluxlabs.net>
import { test } from 'node:test';
import assert from 'node:assert';
import { mkdtempSync, mkdirSync, readFileSync, existsSync, writeFileSync, readdirSync } from 'node:fs';
import { join } from 'node:path';
import { tmpdir } from 'node:os';
import {
enableDebug,
disableDebug,
isDebugEnabled,
getDebugLogPath,
debugLog,
debugTime,
debugCount,
debugPeak,
writeDebugSummary,
} from '../debug-logger.ts';
function createTempGsdDir(): string {
const tmp = mkdtempSync(join(tmpdir(), 'gsd-debug-test-'));
mkdirSync(join(tmp, '.gsd'), { recursive: true });
return tmp;
}
function readLogLines(logPath: string): Record<string, unknown>[] {
const content = readFileSync(logPath, 'utf-8').trim();
if (!content) return [];
return content.split('\n').map(line => JSON.parse(line));
}
test('enableDebug creates log file and sets enabled', () => {
const tmp = createTempGsdDir();
enableDebug(tmp);
assert.strictEqual(isDebugEnabled(), true);
const logPath = getDebugLogPath();
assert.ok(logPath, 'log path should be set');
assert.ok(logPath!.includes('.gsd/debug/debug-'), 'log path should be in .gsd/debug/');
assert.ok(logPath!.endsWith('.log'), 'log path should end with .log');
disableDebug();
assert.strictEqual(isDebugEnabled(), false);
});
test('debugLog writes JSONL events', () => {
const tmp = createTempGsdDir();
enableDebug(tmp);
debugLog('test-event', { foo: 'bar', num: 42 });
debugLog('another-event');
const logPath = getDebugLogPath()!;
const lines = readLogLines(logPath);
assert.strictEqual(lines.length, 2);
assert.strictEqual(lines[0].event, 'test-event');
assert.strictEqual((lines[0] as any).foo, 'bar');
assert.strictEqual((lines[0] as any).num, 42);
assert.ok(lines[0].ts, 'should have timestamp');
assert.strictEqual(lines[1].event, 'another-event');
disableDebug();
});
test('debugLog is no-op when disabled', () => {
assert.strictEqual(isDebugEnabled(), false);
// Should not throw
debugLog('should-not-appear', { data: 'test' });
});
test('debugTime measures elapsed time', async () => {
const tmp = createTempGsdDir();
enableDebug(tmp);
const stop = debugTime('timed-op');
// Small delay to ensure measurable time
await new Promise(r => setTimeout(r, 10));
stop({ extra: 'data' });
const logPath = getDebugLogPath()!;
const lines = readLogLines(logPath);
assert.strictEqual(lines.length, 1);
assert.strictEqual(lines[0].event, 'timed-op');
assert.ok((lines[0] as any).elapsed_ms >= 0, 'elapsed_ms should be non-negative');
assert.strictEqual((lines[0] as any).extra, 'data');
disableDebug();
});
test('debugTime returns no-op when disabled', () => {
assert.strictEqual(isDebugEnabled(), false);
const stop = debugTime('should-not-appear');
stop({ data: 'test' }); // Should not throw
});
test('debugCount increments counters', () => {
const tmp = createTempGsdDir();
enableDebug(tmp);
debugCount('dispatches');
debugCount('dispatches');
debugCount('dispatches', 3);
// Counters are tested via writeDebugSummary
const logPath = writeDebugSummary()!;
const lines = readLogLines(logPath);
const summary = lines.find(l => l.event === 'debug-summary') as any;
assert.ok(summary, 'should have debug-summary event');
assert.strictEqual(summary.dispatches, 5);
});
test('debugPeak tracks max values', () => {
const tmp = createTempGsdDir();
enableDebug(tmp);
debugPeak('ttsrPeakBuffer', 100);
debugPeak('ttsrPeakBuffer', 500);
debugPeak('ttsrPeakBuffer', 200); // Should not overwrite 500
const logPath = writeDebugSummary()!;
const lines = readLogLines(logPath);
const summary = lines.find(l => l.event === 'debug-summary') as any;
assert.strictEqual(summary.ttsrPeakBuffer, 500);
});
test('writeDebugSummary includes all counters and disables debug', () => {
const tmp = createTempGsdDir();
enableDebug(tmp);
debugCount('deriveStateCalls', 10);
debugCount('deriveStateTotalMs', 80);
debugCount('ttsrChecks', 50);
debugCount('parseRoadmapCalls', 3);
debugCount('dispatches', 2);
const logPath = writeDebugSummary()!;
assert.ok(logPath, 'should return log path');
assert.strictEqual(isDebugEnabled(), false, 'should be disabled after summary');
const lines = readLogLines(logPath);
const summary = lines.find(l => l.event === 'debug-summary') as any;
assert.ok(summary);
assert.strictEqual(summary.deriveStateCalls, 10);
assert.strictEqual(summary.avgDeriveState_ms, 8);
assert.strictEqual(summary.ttsrChecks, 50);
assert.strictEqual(summary.dispatches, 2);
assert.ok(summary.totalElapsed_ms >= 0);
});
test('auto-prunes old debug logs', () => {
const tmp = createTempGsdDir();
const debugDir = join(tmp, '.gsd', 'debug');
mkdirSync(debugDir, { recursive: true });
// Create 6 old log files
for (let i = 0; i < 6; i++) {
writeFileSync(join(debugDir, `debug-2026-01-0${i + 1}.log`), 'old');
}
enableDebug(tmp);
const files = readdirSync(debugDir).filter(f => f.startsWith('debug-') && f.endsWith('.log'));
// Should have at most MAX_DEBUG_LOGS (5) = 5 old + 1 new, but pruned to 5 total
// Actually: prunes to < 5 old, then creates 1 new = at most 5
assert.ok(files.length <= 6, `should have pruned old logs, got ${files.length}`);
disableDebug();
});
test('disableDebug returns log path', () => {
const tmp = createTempGsdDir();
enableDebug(tmp);
const logPath = getDebugLogPath();
const returned = disableDebug();
assert.strictEqual(returned, logPath);
assert.strictEqual(getDebugLogPath(), null);
});

View file

@ -10,6 +10,7 @@
* per-rule JS RegExp iteration when the native module is not loaded.
*/
import picomatch from "picomatch";
import { debugTime, debugCount, debugPeak } from "../gsd/debug-logger.js";
// ── Native TTSR engine (optional) ─────────────────────────────────────
let nativeTtsr: {
@ -341,6 +342,7 @@ export class TtsrManager {
* remain in JS as they are lightweight and context-dependent.
*/
checkDelta(delta: string, context: TtsrMatchContext): Rule[] {
const stopTimer = debugTime("ttsr-check");
const bufferKey = this.#bufferKey(context);
let nextBuffer = `${this.#buffers.get(bufferKey) ?? ""}${delta}`;
// Cap buffer size — keep the tail so patterns still match recent output
@ -348,6 +350,7 @@ export class TtsrManager {
nextBuffer = nextBuffer.slice(-MAX_BUFFER_BYTES);
}
this.#buffers.set(bufferKey, nextBuffer);
debugPeak("ttsrPeakBuffer", nextBuffer.length);
// Lazily compile native engine if rules changed.
if (this.#nativeDirty) this.#compileNative();
@ -365,6 +368,8 @@ export class TtsrManager {
if (!this.#matchesGlobalPaths(entry, context)) continue;
matches.push(entry.rule);
}
debugCount("ttsrChecks");
stopTimer({ bufferSize: nextBuffer.length, native: true, rulesChecked: this.#rules.size, matched: matches.map(m => m.name) });
return matches;
}
@ -374,6 +379,7 @@ export class TtsrManager {
const now = Date.now();
const lastCheck = this.#lastJsCheckAt.get(bufferKey) ?? 0;
if (now - lastCheck < JS_FALLBACK_CHECK_INTERVAL_MS) {
stopTimer({ bufferSize: nextBuffer.length, throttled: true });
return [];
}
this.#lastJsCheckAt.set(bufferKey, now);
@ -386,6 +392,8 @@ export class TtsrManager {
if (!this.#matchesCondition(entry, nextBuffer)) continue;
matches.push(entry.rule);
}
debugCount("ttsrChecks");
stopTimer({ bufferSize: nextBuffer.length, native: false, rulesChecked: this.#rules.size, matched: matches.map(m => m.name) });
return matches;
}