feat(logging): trace tool calls and write a log per agent

Record complete tool-call arguments in the workflow log and project each agent's events into its own durable log.

Add agent listing and agent-specific log tailing while preserving byte-exact output and draining log handles before
activities return.
This commit is contained in:
ajmallesh
2026-08-26 20:13:03 -07:00
parent 242f85f158
commit f5e7143619
43 changed files with 2694 additions and 1177 deletions
+170 -23
View File
@@ -9,6 +9,7 @@
import fs from 'node:fs';
import path from 'node:path';
import { StringDecoder } from 'node:string_decoder';
import { setTimeout as sleep } from 'node:timers/promises';
import { watch } from 'chokidar';
import { fail } from '../errors.js';
@@ -18,8 +19,69 @@ import { resolveWorkflowId } from '../session.js';
import { waitForWorkflowClose } from '../temporal-client.js';
import { stdoutIsTerminal } from '../tty.js';
/** Read a byte range from a file and return it as a UTF-8 string. */
function readRange(filePath: string, start: number, end: number): string {
const TERMINAL_HEADINGS = new Set(['Scan COMPLETED', 'Scan PARTIAL', 'Scan FAILED', 'Scan CANCELLED']);
// The combined log resets completion on the bare `RESUMED` heading; a per-agent file carries the
// distinct `--- RESUMED (<workflow id>) ---` boundary that WorkflowLogger.logResumeBoundary writes
// (kept distinct per resume so it stays idempotent per file). Both mean a new execution began, so a
// `--agent` tail must clear a stale terminal marker on either, matching the combined tail.
const AGENT_RESUME_BOUNDARY = /^--- RESUMED \(.+\) ---$/u;
function isResumeBoundary(line: string): boolean {
return line === 'RESUMED' || AGENT_RESUME_BOUNDARY.test(line);
}
/** Tracks only complete structural lines while output remains byte-for-byte unchanged. */
export class LogCompletionState {
private pendingLine = '';
private terminalIsLastMarker = false;
private failureIsLastMarker = false;
ingest(chunk: string): void {
const lines = `${this.pendingLine}${chunk}`.split('\n');
this.pendingLine = lines.pop() ?? '';
for (const line of lines) {
if (isResumeBoundary(line)) {
this.terminalIsLastMarker = false;
this.failureIsLastMarker = false;
} else if (TERMINAL_HEADINGS.has(line)) {
this.terminalIsLastMarker = true;
this.failureIsLastMarker = line === 'Scan FAILED';
}
}
}
isComplete(): boolean {
return this.terminalIsLastMarker;
}
hasFailureMarker(): boolean {
return this.failureIsLastMarker;
}
}
/** Append the forced-stop marker after the worker has exited, unless this execution already ended. */
export function appendCancellationFallback(logFile: string): void {
fs.mkdirSync(path.dirname(logFile), { recursive: true });
const state = new LogCompletionState();
try {
state.ingest(fs.readFileSync(logFile, 'utf8'));
} catch {
// A pre-registration stop may not have created the file yet.
}
if (state.isComplete()) return;
const descriptor = fs.openSync(logFile, 'a', 0o600);
try {
fs.writeSync(descriptor, '\nScan CANCELLED\n');
fs.fsyncSync(descriptor);
} finally {
fs.closeSync(descriptor);
}
}
/** Read a byte range without decoding across an arbitrary live-write boundary. */
function readRange(filePath: string, start: number, end: number): Buffer {
const length = end - start;
const buffer = Buffer.alloc(length);
const fd = fs.openSync(filePath, 'r');
@@ -28,7 +90,7 @@ function readRange(filePath: string, start: number, end: number): string {
} finally {
fs.closeSync(fd);
}
return buffer.toString('utf-8');
return buffer;
}
/** Resolve a workspace ID to its workflow.log path, or exit with an error. */
@@ -76,9 +138,6 @@ export interface TailResult {
readonly sawFailure: boolean;
}
// The worker writes this exact line at the head of its terminal failure summary.
const FAILURE_MARKER = /^Scan FAILED$/m;
/**
* Stream a scan's log to the terminal until the workflow closes (completion comes from Temporal,
* or Ctrl-C). A Temporal outage is warned about and, if sustained, ends the tail with a diagnostic.
@@ -88,24 +147,25 @@ const FAILURE_MARKER = /^Scan FAILED$/m;
export function tailUntilComplete(logFile: string, opts: TailOptions = {}): Promise<TailResult> {
return new Promise((resolve) => {
let position = 0;
const completion = new LogCompletionState();
let done = false;
let sawFailure = false;
const controller = new AbortController();
let watcher: ReturnType<typeof watch> | undefined;
const completionDecoder = new StringDecoder('utf8');
/** Output any new content appended since the last read. */
function flush(): void {
function flush(): boolean {
try {
const { size } = fs.statSync(logFile);
if (size <= position) return;
if (size <= position) return completion.isComplete();
const data = readRange(logFile, position, size);
process.stdout.write(data);
position = size;
if (!sawFailure && FAILURE_MARKER.test(data)) {
sawFailure = true;
}
completion.ingest(completionDecoder.write(data));
return completion.isComplete();
} catch {
// File not present yet or transiently unreadable — nothing to flush this round.
return false;
}
}
@@ -113,22 +173,32 @@ export function tailUntilComplete(logFile: string, opts: TailOptions = {}): Prom
if (done) return;
done = true;
controller.abort();
process.off('SIGINT', finish);
const result = { sawFailure: completion.hasFailureMarker() };
if (watcher) {
watcher.close().finally(() => resolve({ sawFailure }));
watcher.close().finally(() => resolve(result));
// Safety net — resolve anyway if watcher.close() stalls.
setTimeout(() => resolve({ sawFailure }), 1000).unref();
setTimeout(() => resolve(result), 1000).unref();
} else {
resolve({ sawFailure });
resolve(result);
}
}
// 1. Output existing content, then stream anything appended.
flush();
// 1. Output existing content, then stream anything appended. A per-agent file can be created
// after the watcher starts, so `add` is handled too and streams it from its first line.
watcher = watch(logFile, { persistent: true });
watcher.on('change', () => flush());
const onFsEvent = (): void => {
if (flush() && !opts.workflowId) finish();
};
watcher.on('change', onFsEvent);
watcher.on('add', onFsEvent);
if (flush() && !opts.workflowId) {
finish();
return;
}
// 2. Ctrl-C stops watching.
process.on('SIGINT', finish);
process.once('SIGINT', finish);
// 3. Temporal decides completion. Without a workflow id, the tail relies on Ctrl-C alone.
if (opts.workflowId) {
@@ -162,11 +232,51 @@ export function tailUntilComplete(logFile: string, opts: TailOptions = {}): Prom
});
}
export function logs(workspaceId: string): void {
const logFile = resolveLogFile(workspaceId);
const workflowId = resolveWorkflowId(workspaceId);
console.error(stdoutIsTerminal() ? `Tailing scan log: ${logFile}` : 'Tailing scan log');
/** The `.shannon/agents/` directory that sits beside a scan's combined workflow.log. */
function agentsDirFor(logFile: string): string {
return path.join(path.dirname(logFile), 'agents');
}
/** List the per-agent log names available for a scan (filename stems, sorted), or an empty list. */
export function listAgentLogNames(logFile: string): string[] {
try {
return fs
.readdirSync(agentsDirFor(logFile))
.filter((entry) => entry.endsWith('.log'))
.map((entry) => entry.slice(0, -'.log'.length))
.sort();
} catch {
return [];
}
}
/**
* Resolve an agent name to its per-agent log path. The name must be a closed-charset basename, and
* the resolved file must stay inside the agents directory: traversal and symlink escapes are
* rejected. Returns undefined when the name is structurally invalid or escapes the directory.
*/
export function resolveAgentLogFile(logFile: string, agentName: string): string | undefined {
if (!/^[a-z0-9][a-z0-9-]{0,63}$/u.test(agentName)) return undefined;
const agentsDir = agentsDirFor(logFile);
const target = path.join(agentsDir, `${agentName}.log`);
try {
const realDir = fs.realpathSync(agentsDir);
const realTarget = fs.realpathSync(target);
if (realTarget !== path.join(realDir, `${agentName}.log`)) return undefined;
} catch {
// The file does not exist yet (scan still starting); the closed-charset check already proved
// the path cannot traverse out of the agents directory, so it is safe to watch for creation.
}
return target;
}
export interface LogsOptions {
readonly agent?: string;
readonly listAgents?: boolean;
}
function tailFileToExit(logFile: string, workflowId: string | undefined, label: string): void {
console.error(stdoutIsTerminal() ? `${label}: ${logFile}` : label);
let unreachable = false;
tailUntilComplete(logFile, {
...(workflowId ? { workflowId } : {}),
@@ -175,3 +285,40 @@ export function logs(workspaceId: string): void {
},
}).finally(() => process.exit(unreachable ? 1 : 0));
}
export function logs(workspaceId: string, options: LogsOptions = {}): void {
const logFile = resolveLogFile(workspaceId);
if (options.listAgents) {
const names = listAgentLogNames(logFile);
if (names.length === 0) {
console.error('No per-agent logs for this scan yet.');
process.exit(0);
}
for (const name of names) console.log(name);
process.exit(0);
}
const workflowId = resolveWorkflowId(workspaceId);
if (options.agent !== undefined) {
const agentFile = resolveAgentLogFile(logFile, options.agent);
if (agentFile === undefined) {
fail(`No agent log named: ${options.agent}`, '', 'Available agents:', ...withBullets(listAgentLogNames(logFile)));
}
const known = listAgentLogNames(logFile);
// If the directory already lists agents, a name not among them is a typo, not a not-yet-created
// file; fail loudly rather than tailing a path that will never appear.
if (known.length > 0 && !known.includes(options.agent)) {
fail(`No agent log named: ${options.agent}`, '', 'Available agents:', ...withBullets(known));
}
tailFileToExit(agentFile, workflowId, `Tailing ${options.agent} log`);
return;
}
tailFileToExit(logFile, workflowId, 'Tailing scan log');
}
function withBullets(names: readonly string[]): string[] {
return names.length === 0 ? [' (none yet)'] : names.map((name) => ` - ${name}`);
}
+87 -12
View File
@@ -3,24 +3,29 @@
* Never touches infra or data; to wipe Temporal state entirely, use `shannon reset`.
*/
import path from 'node:path';
import * as p from '@clack/prompts';
import { confirmOrExit } from '../confirm.js';
import {
anyRunningScanWorkflow,
cancelWorkflow,
ensureDocker,
isTemporalReady,
isWorkflowRunning,
runningContainers,
runningScanWorkspaces,
scanFilter,
stopContainers,
terminateAllWorkflows,
terminateWorkflow,
WORKER_FILTER,
} from '../docker.js';
import { fail, failUsage, warn } from '../errors.js';
import { getWorkspacesDir } from '../home.js';
import { commandPrefix } from '../mode.js';
import { resolveRunFile } from '../paths.js';
import { resolveWorkflowId } from '../session.js';
import { resolveDefaultWorkspace } from '../workspaces.js';
import { appendCancellationFallback } from './logs.js';
export interface StopOptions {
all: boolean;
@@ -28,11 +33,77 @@ export interface StopOptions {
workspace?: string;
}
const CANCELLATION_GRACE_MS = 10_000;
const CANCELLATION_POLL_MS = 250;
export interface StopTarget {
readonly workspace: string;
readonly workflowId?: string;
readonly workflowRunning: boolean;
}
export interface StopLifecycle {
readonly cancel: (workflowId: string) => boolean;
readonly isRunning: (workflowId: string) => boolean;
readonly terminate: (workflowId: string) => boolean;
readonly containers: (workspace: string) => string[];
readonly stopContainers: (ids: string[]) => Promise<void>;
readonly appendFallback: (workspace: string) => void;
readonly wait: (milliseconds: number) => Promise<void>;
}
const stopLifecycle: StopLifecycle = {
cancel: cancelWorkflow,
isRunning: isWorkflowRunning,
terminate: (workflowId) => terminateWorkflow(workflowId, 'Stopped after cancellation grace period'),
containers: (workspace) => runningContainers(scanFilter(workspace)),
stopContainers,
appendFallback: (workspace) => {
const logFile = resolveRunFile(path.join(getWorkspacesDir(), workspace), 'workflow.log');
appendCancellationFallback(logFile);
},
wait: (milliseconds) => new Promise((resolve) => setTimeout(resolve, milliseconds)),
};
/** Cancel first; terminate and write the fallback heading only when graceful closure misses its deadline. */
export async function stopTargetCancelFirst(
target: StopTarget,
lifecycle: StopLifecycle = stopLifecycle,
graceMs: number = CANCELLATION_GRACE_MS,
pollMs: number = CANCELLATION_POLL_MS,
): Promise<'graceful' | 'forced'> {
let forced = !target.workflowRunning || target.workflowId === undefined;
if (!forced && target.workflowId !== undefined) {
lifecycle.cancel(target.workflowId);
const deadline = Date.now() + graceMs;
while (lifecycle.isRunning(target.workflowId) && Date.now() < deadline) {
await lifecycle.wait(pollMs);
}
forced = lifecycle.isRunning(target.workflowId);
if (forced) lifecycle.terminate(target.workflowId);
}
await lifecycle.stopContainers(lifecycle.containers(target.workspace));
if (forced && lifecycle.containers(target.workspace).length === 0) {
lifecycle.appendFallback(target.workspace);
}
return forced ? 'forced' : 'graceful';
}
/** Apply the same captured-target lifecycle concurrently for `stop --all`. */
export function stopTargetsCancelFirst(
targets: readonly StopTarget[],
lifecycle: StopLifecycle = stopLifecycle,
graceMs: number = CANCELLATION_GRACE_MS,
pollMs: number = CANCELLATION_POLL_MS,
): Promise<readonly ('graceful' | 'forced')[]> {
return Promise.all(targets.map((target) => stopTargetCancelFirst(target, lifecycle, graceMs, pollMs)));
}
/**
* Stop a single scan. Terminating the workflow both clears Temporal's record and
* brings the container down (the worker waits on the workflow result), so that runs
* first; `docker stop` is the fallback for the pre-registration window and an
* unreachable Temporal. The stop is then verified rather than assumed.
* Stop a single scan. Cooperative cancellation gets the first ten seconds so the
* workflow can flush its terminal log; termination and a host-written heading are
* the fallback for the pre-registration window or an unavailable finalizer.
*/
async function stopSingleScan(workspace: string, yes: boolean): Promise<void> {
const workflowId = resolveWorkflowId(workspace);
@@ -56,10 +127,7 @@ async function stopSingleScan(workspace: string, yes: boolean): Promise<void> {
const spinner = p.spinner();
spinner.start(`Stopping scan ${workspace}`);
if (workflowId && workflowRunning) {
terminateWorkflow(workflowId, `Stopped via shannon stop ${workspace}`);
}
await stopContainers(runningContainers(filter));
await stopTargetCancelFirst({ workspace, ...(workflowId !== undefined && { workflowId }), workflowRunning });
const stillRunning = runningContainers(filter);
if (stillRunning.length > 0) {
@@ -78,6 +146,14 @@ async function stopSingleScan(workspace: string, yes: boolean): Promise<void> {
async function stopAllScans(yes: boolean): Promise<void> {
const temporalUp = isTemporalReady();
const initial = runningContainers(WORKER_FILTER);
const targets = [...new Set(runningScanWorkspaces())].map((workspace): StopTarget => {
const workflowId = resolveWorkflowId(workspace);
return {
workspace,
...(workflowId !== undefined && { workflowId }),
workflowRunning: Boolean(workflowId && temporalUp && isWorkflowRunning(workflowId)),
};
});
// Resolve what is running before prompting, so we never confirm a no-op.
if (initial.length === 0) {
@@ -90,9 +166,8 @@ async function stopAllScans(yes: boolean): Promise<void> {
const spinner = p.spinner();
spinner.start('Stopping all scans');
if (temporalUp) {
terminateAllWorkflows('Stopped via shannon stop --all');
}
await stopTargetsCancelFirst(targets);
// Keep the legacy safety net for a worker whose workspace label was unavailable.
await stopContainers(runningContainers(WORKER_FILTER));
const stillRunning = runningContainers(WORKER_FILTER);