feat(cli): mcpctl trace <code>, and bound the table it reads
The trace codes are now emitted in every deadline message and degradation notice, so they need somewhere to go. `mcpctl trace <code>` queries the audit events mcpd already stores and renders the request as a waterfall: each step with its offset, duration, byte delta, and any ⚠ degradation or ✗ error, then a summary naming the slowest step. No new endpoint was needed -- GET /api/v1/audit/events?correlationId= already existed and correlationId is already an indexed column; it just had nothing writing meaningful values into it until this branch, and nothing reading it. --strict exits non-zero when the trace contains an error or a degraded step, so it composes into scripts. An empty result explains itself rather than printing nothing: batches flush up to 5s late, old requests predate trace codes, and the codes exclude I/L/O/U so a mistyped one is worth calling out. Retention: AuditEvent had no prune at all. That was defensible while the table was write-only; it is not now that a command reads it. Mirrors the AuditLog convention exactly -- POST /api/v1/audit/events/purge, triggered rather than scheduled, guarded by the existing audit-purge RBAC operation so it cannot be granted by accident separately from the log purge. 30 days by default rather than AuditLog's 90: these are several rows per MCP call, not a record of administrative mutations. Note for the plan's sake: I had assumed AuditLog retention was a scheduled job registered in main.ts. It is not -- it is a manual endpoint. Mirroring what the codebase actually does beat inventing a scheduler that exists for neither table. completions are generated, so `trace` is registered in PROJECT_SCOPED_COMMANDS and both shells regenerated; the freshness test passes. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01GqMidYEGUJG5fxeoTELBu2
This commit is contained in:
171
src/cli/src/commands/trace.ts
Normal file
171
src/cli/src/commands/trace.ts
Normal file
@@ -0,0 +1,171 @@
|
||||
import { Command } from 'commander';
|
||||
import type { ApiClient } from '../api-client.js';
|
||||
|
||||
export interface TraceCommandDeps {
|
||||
client: ApiClient;
|
||||
log: (...args: string[]) => void;
|
||||
}
|
||||
|
||||
/** Mirrors mcplocal's AuditEvent rows as stored by mcpd. */
|
||||
interface AuditEvent {
|
||||
timestamp: string;
|
||||
sessionId: string;
|
||||
projectName: string;
|
||||
eventKind: string;
|
||||
source: string;
|
||||
serverName?: string | null;
|
||||
correlationId?: string | null;
|
||||
userName?: string | null;
|
||||
payload: Record<string, unknown>;
|
||||
}
|
||||
|
||||
function num(v: unknown): number | null {
|
||||
return typeof v === 'number' && Number.isFinite(v) ? v : null;
|
||||
}
|
||||
|
||||
function str(v: unknown): string | null {
|
||||
return typeof v === 'string' && v.length > 0 ? v : null;
|
||||
}
|
||||
|
||||
function clock(iso: string): string {
|
||||
const d = new Date(iso);
|
||||
if (Number.isNaN(d.getTime())) return '--:--:--';
|
||||
const p = (n: number): string => String(n).padStart(2, '0');
|
||||
return `${p(d.getHours())}:${p(d.getMinutes())}:${p(d.getSeconds())}`;
|
||||
}
|
||||
|
||||
function bytes(n: number): string {
|
||||
if (n < 1024) return `${String(n)}B`;
|
||||
if (n < 1024 * 1024) return `${(n / 1024).toFixed(1)}kB`;
|
||||
return `${(n / (1024 * 1024)).toFixed(1)}MB`;
|
||||
}
|
||||
|
||||
/** One line of detail per event kind — what you actually want to see. */
|
||||
function detailOf(e: AuditEvent): string {
|
||||
const p = e.payload;
|
||||
switch (e.eventKind) {
|
||||
case 'stage_execution': {
|
||||
const parts = [str(p['stage']) ?? 'stage'];
|
||||
const ms = num(p['durationMs']);
|
||||
if (ms !== null) parts.push(`${String(ms)}ms`);
|
||||
const inSize = num(p['inputSize']);
|
||||
const outSize = num(p['outputSize']);
|
||||
if (inSize !== null && outSize !== null) parts.push(`${bytes(inSize)} → ${bytes(outSize)}`);
|
||||
const sections = num(p['sectionCount']);
|
||||
if (sections !== null && sections > 0) parts.push(`${String(sections)} sections`);
|
||||
return parts.join(' ');
|
||||
}
|
||||
case 'pipeline_execution': {
|
||||
const ms = num(p['totalDurationMs']);
|
||||
const stages = num(p['stageCount']);
|
||||
return `${String(stages ?? 0)} stages${ms === null ? '' : `, ${String(ms)}ms total`}`;
|
||||
}
|
||||
case 'tool_call_trace': {
|
||||
const parts = [str(p['toolName']) ?? '(tool)'];
|
||||
const ms = num(p['durationMs']);
|
||||
if (ms !== null) parts.push(`${String(ms)}ms`);
|
||||
const size = num(p['resultSizeBytes']);
|
||||
if (size !== null) parts.push(bytes(size));
|
||||
return parts.join(' ');
|
||||
}
|
||||
case 'gate_decision': {
|
||||
const trigger = str(p['trigger']) ?? 'gate';
|
||||
const matched = Array.isArray(p['matchedPrompts']) ? (p['matchedPrompts']).length : 0;
|
||||
return `${trigger} · ${String(matched)} prompts`;
|
||||
}
|
||||
default:
|
||||
return e.eventKind;
|
||||
}
|
||||
}
|
||||
|
||||
function degradationOf(e: AuditEvent): string | null {
|
||||
if (e.payload['degraded'] !== true) return null;
|
||||
return str(e.payload['degradedReason']) ?? 'degraded';
|
||||
}
|
||||
|
||||
function errorOf(e: AuditEvent): string | null {
|
||||
return str(e.payload['error']);
|
||||
}
|
||||
|
||||
export function createTraceCommand(deps?: Partial<TraceCommandDeps>): Command {
|
||||
const log = deps?.log ?? ((...args: string[]): void => { console.log(...args); });
|
||||
|
||||
return new Command('trace')
|
||||
.argument('<code>', 'trace code from an error message or degradation notice')
|
||||
.description('Show the stage-by-stage timeline for one MCP request')
|
||||
.option('-o, --output <format>', 'table (default) or json')
|
||||
.option('--strict', 'exit non-zero if the trace contains an error or a degraded step')
|
||||
.action(async (code: string, opts: { output?: string; strict?: boolean }) => {
|
||||
const client = deps?.client;
|
||||
if (!client) throw new Error('trace: no API client configured');
|
||||
|
||||
const res = await client.get<{ events?: AuditEvent[]; total?: number }>(
|
||||
`/api/v1/audit/events?correlationId=${encodeURIComponent(code)}&limit=500`,
|
||||
);
|
||||
const events = (res.events ?? [])
|
||||
.slice()
|
||||
.sort((a, b) => new Date(a.timestamp).getTime() - new Date(b.timestamp).getTime());
|
||||
|
||||
if (events.length === 0) {
|
||||
log(`No trace found for '${code}'.`);
|
||||
log('');
|
||||
log('Traces are written by mcplocal and stored by mcpd. If the request is very');
|
||||
log('recent the batch may not have flushed yet (up to 5s); if it is very old it');
|
||||
log('may predate trace codes. Check the code was copied exactly — they are 8');
|
||||
log('characters, no I/L/O/U.');
|
||||
if (opts.strict === true) process.exitCode = 1;
|
||||
return;
|
||||
}
|
||||
|
||||
if (opts.output === 'json') {
|
||||
log(JSON.stringify(events, null, 2));
|
||||
return;
|
||||
}
|
||||
|
||||
const first = events[0]!;
|
||||
const start = new Date(first.timestamp).getTime();
|
||||
const call = events.find((e) => e.eventKind === 'tool_call_trace');
|
||||
const headline = call ? detailOf(call) : first.eventKind;
|
||||
|
||||
log(`Trace ${code} project ${first.projectName} session ${first.sessionId.slice(0, 8)}…`);
|
||||
if (first.userName) log(`user ${first.userName}`);
|
||||
log(`${headline}`);
|
||||
log('');
|
||||
log(' TIME Δms EVENT DETAIL');
|
||||
|
||||
let degradedCount = 0;
|
||||
let errorCount = 0;
|
||||
let slowest: { name: string; ms: number } | null = null;
|
||||
|
||||
for (const e of events) {
|
||||
const delta = new Date(e.timestamp).getTime() - start;
|
||||
const degraded = degradationOf(e);
|
||||
const err = errorOf(e);
|
||||
if (degraded !== null) degradedCount++;
|
||||
if (err !== null) errorCount++;
|
||||
|
||||
const ms = num(e.payload['durationMs']) ?? num(e.payload['totalDurationMs']);
|
||||
const label = str(e.payload['stage']) ?? e.eventKind;
|
||||
if (ms !== null && (slowest === null || ms > slowest.ms)) slowest = { name: label, ms };
|
||||
|
||||
const marks = [
|
||||
degraded !== null ? `⚠ ${degraded}` : null,
|
||||
err !== null ? `✗ ${err}` : null,
|
||||
].filter((x): x is string => x !== null).join(' ');
|
||||
|
||||
log(
|
||||
` ${clock(e.timestamp)} ${String(delta).padStart(6)} `
|
||||
+ `${e.eventKind.padEnd(19)} ${detailOf(e)}${marks ? ` ${marks}` : ''}`,
|
||||
);
|
||||
}
|
||||
|
||||
log('');
|
||||
const summary: string[] = [`${String(events.length)} events`];
|
||||
if (degradedCount > 0) summary.push(`⚠ ${String(degradedCount)} degraded`);
|
||||
if (errorCount > 0) summary.push(`✗ ${String(errorCount)} error${errorCount === 1 ? '' : 's'}`);
|
||||
if (slowest !== null) summary.push(`slowest: ${slowest.name} (${String(slowest.ms)}ms)`);
|
||||
log(summary.join(' · '));
|
||||
|
||||
if (opts.strict === true && (degradedCount > 0 || errorCount > 0)) process.exitCode = 1;
|
||||
});
|
||||
}
|
||||
@@ -29,6 +29,7 @@ import { createSkillsCommand } from './commands/skills.js';
|
||||
import { createStatuslineCommand } from './commands/statusline.js';
|
||||
import { createPasswdCommand } from './commands/passwd.js';
|
||||
import { createErrorsCommand } from './commands/errors.js';
|
||||
import { createTraceCommand } from './commands/trace.js';
|
||||
import { ApiClient, ApiError } from './api-client.js';
|
||||
import { loadConfig } from './config/index.js';
|
||||
import { loadCredentials } from './auth/index.js';
|
||||
@@ -280,6 +281,11 @@ export function createProgram(): Command {
|
||||
log: (...args) => console.log(...args),
|
||||
}));
|
||||
|
||||
program.addCommand(createTraceCommand({
|
||||
client,
|
||||
log: (...args) => console.log(...args),
|
||||
}));
|
||||
|
||||
program.addCommand(createBackupCommand({
|
||||
client,
|
||||
log: (...args) => console.log(...args),
|
||||
|
||||
75
src/cli/tests/trace.test.ts
Normal file
75
src/cli/tests/trace.test.ts
Normal file
@@ -0,0 +1,75 @@
|
||||
import { describe, it, expect, vi } from 'vitest';
|
||||
import { createTraceCommand } from '../src/commands/trace.js';
|
||||
import type { ApiClient } from '../src/api-client.js';
|
||||
|
||||
function clientReturning(events: unknown[]): ApiClient {
|
||||
return { get: vi.fn(async () => ({ events, total: events.length })) } as unknown as ApiClient;
|
||||
}
|
||||
|
||||
function run(client: ApiClient, args: string[]): Promise<string[]> {
|
||||
const lines: string[] = [];
|
||||
const cmd = createTraceCommand({ client, log: (...a: string[]) => { lines.push(a.join(' ')); } });
|
||||
return cmd.parseAsync(['node', 'trace', ...args]).then(() => lines);
|
||||
}
|
||||
|
||||
const base = {
|
||||
sessionId: 'abcdef1234567890', projectName: 'sre', source: 'mcplocal',
|
||||
correlationId: 'K3P7QW2M', userName: 'michal@itaz.eu',
|
||||
};
|
||||
|
||||
describe('mcpctl trace', () => {
|
||||
it('renders a waterfall ordered by time', async () => {
|
||||
const lines = await run(clientReturning([
|
||||
{ ...base, timestamp: '2026-08-25T22:00:02.000Z', eventKind: 'tool_call_trace',
|
||||
payload: { toolName: 'docmost/search', durationMs: 461, resultSizeBytes: 14091, error: null } },
|
||||
{ ...base, timestamp: '2026-08-25T22:00:00.000Z', eventKind: 'stage_execution',
|
||||
payload: { stage: 'paginate', durationMs: 12, inputSize: 14091, outputSize: 5632, sectionCount: 2 } },
|
||||
]), ['K3P7QW2M']);
|
||||
|
||||
const out = lines.join('\n');
|
||||
expect(out).toContain('Trace K3P7QW2M');
|
||||
expect(out).toContain('project sre');
|
||||
expect(out).toContain('docmost/search');
|
||||
// Sorted: the stage at :00 must precede the tool_call at :02 even though
|
||||
// the API returned them newest-first.
|
||||
expect(out.indexOf('paginate')).toBeLessThan(out.indexOf('tool_call_trace'));
|
||||
});
|
||||
|
||||
it('flags degraded steps and names the slowest', async () => {
|
||||
const lines = await run(clientReturning([
|
||||
{ ...base, timestamp: '2026-08-25T22:00:00.000Z', eventKind: 'stage_execution',
|
||||
payload: { stage: 'summarize-tree', durationMs: 30001, inputSize: 100, outputSize: 50,
|
||||
degraded: true, degradedReason: 'stage LLM budget of 30000ms exhausted' } },
|
||||
]), ['K3P7QW2M']);
|
||||
|
||||
const out = lines.join('\n');
|
||||
expect(out).toContain('⚠ stage LLM budget of 30000ms exhausted');
|
||||
expect(out).toContain('1 degraded');
|
||||
expect(out).toContain('slowest: summarize-tree (30001ms)');
|
||||
});
|
||||
|
||||
it('explains an empty result instead of printing nothing', async () => {
|
||||
const lines = await run(clientReturning([]), ['ZZZZZZZZ']);
|
||||
const out = lines.join('\n');
|
||||
expect(out).toContain("No trace found for 'ZZZZZZZZ'");
|
||||
expect(out).toContain('no I/L/O/U');
|
||||
});
|
||||
|
||||
it('--strict exits non-zero on a degraded trace', async () => {
|
||||
process.exitCode = 0;
|
||||
await run(clientReturning([
|
||||
{ ...base, timestamp: '2026-08-25T22:00:00.000Z', eventKind: 'stage_execution',
|
||||
payload: { stage: 'paginate', durationMs: 1, degraded: true, degradedReason: 'timed out' } },
|
||||
]), ['K3P7QW2M', '--strict']);
|
||||
expect(process.exitCode).toBe(1);
|
||||
process.exitCode = 0;
|
||||
});
|
||||
|
||||
it('queries mcpd by correlationId', async () => {
|
||||
const client = clientReturning([]);
|
||||
await run(client, ['K3P7QW2M']);
|
||||
expect(client.get).toHaveBeenCalledWith(
|
||||
expect.stringContaining('/api/v1/audit/events?correlationId=K3P7QW2M'),
|
||||
);
|
||||
});
|
||||
});
|
||||
@@ -155,6 +155,9 @@ function mapUrlToPermission(method: string, url: string): PermissionCheck {
|
||||
if (segment === 'backup') return { kind: 'operation', operation: 'backup' };
|
||||
if (segment === 'restore') return { kind: 'operation', operation: 'restore' };
|
||||
if (segment === 'audit-logs' && method === 'DELETE') return { kind: 'operation', operation: 'audit-purge' };
|
||||
// Same operation guards the trace-event purge — both are bulk deletes of
|
||||
// audit history and should not be separately grantable by accident.
|
||||
if (url.startsWith('/api/v1/audit/events/purge')) return { kind: 'operation', operation: 'audit-purge' };
|
||||
// /api/v1/secrets/migrate is a bulk cross-backend operation — treat as op, not a plain secret write.
|
||||
if (url.startsWith('/api/v1/secrets/migrate')) return { kind: 'operation', operation: 'migrate-secrets' };
|
||||
// /api/v1/secretbackends/:id/rotate — manual rotation trigger. Operation so
|
||||
|
||||
@@ -170,6 +170,17 @@ export class AuditEventRepository implements IAuditEventRepository {
|
||||
});
|
||||
return groups.length;
|
||||
}
|
||||
|
||||
/**
|
||||
* Prune old events. AuditEvent had no retention at all while the table was
|
||||
* write-only; now that `mcpctl trace` reads it, it is worth bounding.
|
||||
*/
|
||||
async deleteOlderThan(cutoff: Date): Promise<number> {
|
||||
const result = await this.prisma.auditEvent.deleteMany({
|
||||
where: { timestamp: { lt: cutoff } },
|
||||
});
|
||||
return result.count;
|
||||
}
|
||||
}
|
||||
|
||||
function buildWhere(filter?: AuditEventFilter): Prisma.AuditEventWhereInput {
|
||||
|
||||
@@ -108,6 +108,8 @@ export interface IAuditEventRepository {
|
||||
countSessions(filter?: { projectName?: string; userName?: string; from?: Date; to?: Date }): Promise<number>;
|
||||
/** Rank tools by invocation count for a project (from tool_call_trace events). */
|
||||
toolUsage(projectName: string, from: Date, sampleLimit?: number): Promise<ToolUsageEntry[]>;
|
||||
/** Delete events older than `cutoff`; returns the number removed. */
|
||||
deleteOlderThan(cutoff: Date): Promise<number>;
|
||||
}
|
||||
|
||||
// ── MCP Tokens ──
|
||||
|
||||
@@ -58,6 +58,15 @@ export function registerAuditEventRoutes(app: FastifyInstance, service: AuditEve
|
||||
return service.getById(request.params.id);
|
||||
});
|
||||
|
||||
// POST /api/v1/audit/events/purge — drop events past the retention window.
|
||||
// Mirrors /api/v1/audit-logs/purge: triggered, not scheduled, so an operator
|
||||
// (or a cron) decides when a potentially large delete runs.
|
||||
app.post('/api/v1/audit/events/purge', async (_request, reply) => {
|
||||
const deleted = await service.purgeExpired();
|
||||
reply.code(200);
|
||||
return { deleted };
|
||||
});
|
||||
|
||||
// GET /api/v1/audit/tool-usage — rank tools by invocation count (for favourites)
|
||||
app.get<{ Querystring: { projectName?: string; window?: string; limit?: string } }>('/api/v1/audit/tool-usage', async (request, reply) => {
|
||||
const q = request.query;
|
||||
|
||||
@@ -17,8 +17,31 @@ export interface AuditEventQueryParams {
|
||||
offset?: number;
|
||||
}
|
||||
|
||||
/**
|
||||
* Default retention for trace/audit events.
|
||||
*
|
||||
* Shorter than AuditLog's 90 days: these are high-volume per-request telemetry
|
||||
* (several rows per MCP call), not a record of administrative mutations.
|
||||
*/
|
||||
const DEFAULT_RETENTION_DAYS = 30;
|
||||
|
||||
export class AuditEventService {
|
||||
constructor(private readonly repo: IAuditEventRepository) {}
|
||||
constructor(
|
||||
private readonly repo: IAuditEventRepository,
|
||||
private readonly retentionDays: number =
|
||||
Number(process.env['MCPD_AUDIT_EVENT_RETENTION_DAYS']) || DEFAULT_RETENTION_DAYS,
|
||||
) {}
|
||||
|
||||
/**
|
||||
* Drop events past the retention window. The table previously had no prune
|
||||
* at all and grew unbounded; `mcpctl trace` now reads it, so bounding it
|
||||
* matters more than it did when nothing consumed it.
|
||||
*/
|
||||
async purgeExpired(): Promise<number> {
|
||||
const cutoff = new Date();
|
||||
cutoff.setDate(cutoff.getDate() - this.retentionDays);
|
||||
return this.repo.deleteOlderThan(cutoff);
|
||||
}
|
||||
|
||||
async list(params?: AuditEventQueryParams): Promise<{ events: AuditEvent[]; total: number }> {
|
||||
const filter = this.buildFilter(params);
|
||||
|
||||
Reference in New Issue
Block a user