diff --git a/ts/docs/architecture/telemetry/local-telemetry-debugging.md b/ts/docs/architecture/telemetry/local-telemetry-debugging.md index e322f5f369..5a862dda7d 100644 --- a/ts/docs/architecture/telemetry/local-telemetry-debugging.md +++ b/ts/docs/architecture/telemetry/local-telemetry-debugging.md @@ -36,6 +36,24 @@ In TypeAgent, run: The @trace typeagent\* command enables all debug logs in the typeagent namespace. The @log profile diagnostic command enables all structured + debug logs to be captured locally. +After sending a request, jump straight to its trace in Grafana Explore: + +``` +@log open last +``` + +To open a specific trace by id (for example one copied from a JSONL record or +a colleague's bug report): + +``` +@log open 0123456789abcdef0123456789abcdef +``` + +`@log open` checks the local Grafana endpoint and waits briefly for the exact +trace to become queryable in Tempo before launching the browser. A stopped +stack fails fast with a clear "start with `pnpm run telemetry:grafana`" +message, and a trace that was not captured reports an error instead of opening +an empty Explore view. For setup details, queries, cleanup, and troubleshooting, continue below. @@ -204,6 +222,17 @@ In Grafana: 2. Select the **Tempo** data source. 3. Search for the trace ID. +From TypeAgent, you can skip the manual Explore steps and jump straight to +the trace: + +``` +@log open # opens a specific trace +@log open last # opens the previous completed request's trace +``` + +The natural-language forms `open trace in local Grafana`, `open last +trace`, and `view the last action result in Grafana` map to the same action. + If you do not have the trace ID, search for service `typeagent-local` and narrow the time range to when you sent the request. diff --git a/ts/packages/dispatcher/dispatcher/src/command/command.ts b/ts/packages/dispatcher/dispatcher/src/command/command.ts index c74989d547..4841ec8041 100644 --- a/ts/packages/dispatcher/dispatcher/src/command/command.ts +++ b/ts/packages/dispatcher/dispatcher/src/command/command.ts @@ -505,6 +505,7 @@ export async function processCommand( options?: ProcessCommandOptions, parentContext?: Context, ): Promise { + const isCommand = originalInput.trimStart().startsWith("@"); // Create the AbortController *before* acquiring the lock so that a // cancelCommandByClientId() call that arrives while we are queued can // already abort the controller that will drive this command. @@ -521,8 +522,9 @@ export async function processCommand( // steps in later phases; the root span carries only the values known // at the outermost async boundary. Everything the wrapper receives is // an identifier, not user text - see setTypeAgentSpanAttributes. - const sessionId = context.session.sessionDirPath - ? getSessionName(context.session.sessionDirPath) + const sessionAtStart = context.session; + const sessionId = sessionAtStart.sessionDirPath + ? getSessionName(sessionAtStart.sessionDirPath) : undefined; const rootAttributes: { -readonly [K in keyof otel.TypeAgentSpanAttributes]: otel.TypeAgentSpanAttributes[K]; @@ -550,9 +552,7 @@ export async function processCommand( ...(requestId.connectionId === undefined ? {} : { connectionId: requestId.connectionId }), - kind: originalInput.trimStart().startsWith("@") - ? "command" - : "request", + kind: isCommand ? "command" : "request", attachmentCount: attachments?.length ?? 0, }); try { @@ -602,6 +602,25 @@ export async function processCommand( if (result !== undefined && rootTraceId !== undefined) { result.traceId = rootTraceId; } + if ( + rootTraceId !== undefined && + context.session === sessionAtStart + ) { + context.sessionTraceHistory.push({ + traceId: rootTraceId, + requestId: requestId.requestId, + kind: isCommand ? "command" : "request", + isTraceOpen: + result?.actions?.some( + (action) => + action.schemaName === + "system.log" && + action.actionName === + "openLogTrace", + ) === true, + completedAt: Date.now(), + }); + } logRequestCompleted( context.logger, requestId.requestId, diff --git a/ts/packages/dispatcher/dispatcher/src/context/commandHandlerContext.ts b/ts/packages/dispatcher/dispatcher/src/context/commandHandlerContext.ts index 0d7e272057..1aeadeb876 100644 --- a/ts/packages/dispatcher/dispatcher/src/context/commandHandlerContext.ts +++ b/ts/packages/dispatcher/dispatcher/src/context/commandHandlerContext.ts @@ -302,6 +302,14 @@ export type PendingTopicalRoute = { }; // Command Handler Context definition. +export type SessionTrace = { + traceId: string; + requestId: string; + kind: "command" | "request"; + isTraceOpen: boolean; + completedAt: number; +}; + export type CommandHandlerContext = { readonly agents: AppAgentManager; readonly portRegistrar: IPortRegistrar; @@ -406,6 +414,11 @@ export type CommandHandlerContext = { * `typeagent.trace.id` so existing logs can still be joined. */ readonly traceId: string | undefined; + /** + * Canonical OpenTelemetry root traces completed in the current session. + * Kept in completion order for trace inspection commands. + */ + readonly sessionTraceHistory: SessionTrace[]; readonly telemetryOptions: { readonly joinActiveTrace: boolean; }; @@ -1330,6 +1343,7 @@ export async function initializeCommandHandlerContext( logger, activationId, traceId, + sessionTraceHistory: [], telemetryOptions: { joinActiveTrace: options?.telemetry?.joinActiveTrace ?? false, }, @@ -1983,6 +1997,7 @@ export async function setSessionOnCommandHandlerContext( session: Session, ) { context.session = session; + context.sessionTraceHistory.length = 0; await context.agents.close(); await initializeMemory(context, session.getSessionDirPath()); diff --git a/ts/packages/dispatcher/dispatcher/src/context/system/action/logActionHandler.ts b/ts/packages/dispatcher/dispatcher/src/context/system/action/logActionHandler.ts index 11652f848e..335452bc90 100644 --- a/ts/packages/dispatcher/dispatcher/src/context/system/action/logActionHandler.ts +++ b/ts/packages/dispatcher/dispatcher/src/context/system/action/logActionHandler.ts @@ -3,8 +3,10 @@ import type { ActionContext, TypeAgentAction } from "@typeagent/agent-sdk"; +import type { CommandHandlerContext } from "../../commandHandlerContext.js"; import { clearLogSettings, + openLogTrace, setLogProfile, showLogStatus, } from "../handlers/logCommandHandler.js"; @@ -12,7 +14,7 @@ import type { LogAction } from "../schema/logActionSchema.js"; export async function executeLogAction( action: TypeAgentAction, - context: ActionContext, + context: ActionContext, ) { switch (action.actionName) { case "showLogStatus": @@ -24,6 +26,9 @@ export async function executeLogAction( case "clearLogSettings": clearLogSettings(context); return; + case "openLogTrace": + await openLogTrace(action.parameters.traceId, context); + return; default: throw new Error( `Invalid log action: ${(action as TypeAgentAction).actionName}`, diff --git a/ts/packages/dispatcher/dispatcher/src/context/system/handlers/logCommandHandler.ts b/ts/packages/dispatcher/dispatcher/src/context/system/handlers/logCommandHandler.ts index b105b40ca2..5ab58b4c4a 100644 --- a/ts/packages/dispatcher/dispatcher/src/context/system/handlers/logCommandHandler.ts +++ b/ts/packages/dispatcher/dispatcher/src/context/system/handlers/logCommandHandler.ts @@ -15,8 +15,15 @@ */ import registerDebug from "debug"; +import open from "open"; -import type { ActionContext, ParsedCommandParams } from "@typeagent/agent-sdk"; +import type { + ActionContext, + CompletionGroups, + ParsedCommandParams, + PartialParsedCommandParams, + SessionContext, +} from "@typeagent/agent-sdk"; import type { CommandHandler, CommandHandlerNoParams, @@ -29,6 +36,7 @@ import { } from "@typeagent/agent-sdk/helpers/display"; import { otel } from "@typeagent/telemetry"; import { metrics as otelMetrics, trace as otelTrace } from "@opentelemetry/api"; +import type { CommandHandlerContext } from "../../commandHandlerContext.js"; const KNOWN_PROFILES = otel.LOCAL_TELEMETRY_PROFILES; @@ -194,7 +202,336 @@ function getConstructorName(value: unknown): string { return ctor?.name ?? "unknown"; } -export function getLogCommandHandlers(): CommandHandlerTable { +export const LOCAL_GRAFANA_BASE_URL = "http://127.0.0.1:24319"; + +const LOCAL_GRAFANA_HEALTH_URL = `${LOCAL_GRAFANA_BASE_URL}/api/health`; +const LOCAL_GRAFANA_HEALTH_TIMEOUT_MS = 1500; +const LOCAL_TEMPO_TRACE_WAIT_TIMEOUT_MS = 5000; +const LOCAL_TEMPO_TRACE_WAIT_ATTEMPTS = 10; +const LOCAL_TEMPO_TRACE_WAIT_INTERVAL_MS = 500; +const TRACE_ID_HEX_RE = /^[0-9a-f]{32}$/; + +export type OpenLogTraceDependencies = { + fetch: (input: string | URL, init?: RequestInit) => Promise; + openUrl: (url: string) => Promise; + wait?: (milliseconds: number) => Promise; +}; + +const defaultDependencies: OpenLogTraceDependencies = { + fetch: globalThis.fetch, + openUrl: open, +}; + +/** + * Build a Grafana 13 Explore URL using Tempo's direct trace lookup query. + */ +export function buildLocalGrafanaTraceUrl(traceId: string): string { + const panes = { + tap: { + datasource: "tempo", + queries: [ + { + refId: "A", + datasource: { type: "tempo", uid: "tempo" }, + queryType: "traceql", + query: traceId, + filters: [], + }, + ], + range: { from: "now-1h", to: "now" }, + }, + }; + const url = new URL("/explore", LOCAL_GRAFANA_BASE_URL); + const params = new URLSearchParams(); + params.set("schemaVersion", "1"); + params.set("orgId", "1"); + params.set("panes", JSON.stringify(panes)); + url.search = params.toString(); + return url.toString(); +} + +function resolveTraceId( + rawTraceId: string, + systemContext: CommandHandlerContext, +): { traceId: string } | { error: string } { + const trimmed = rawTraceId.trim(); + if (trimmed.length === 0) { + return { + error: "Trace id is required. Provide a 32 hex character trace id or 'last'.", + }; + } + const lower = trimmed.toLowerCase(); + if (lower === "last") { + let trace: + | (typeof systemContext.sessionTraceHistory)[number] + | undefined; + for ( + let i = systemContext.sessionTraceHistory.length - 1; + i >= 0; + i-- + ) { + const candidate = systemContext.sessionTraceHistory[i]; + if (candidate.kind === "request" && !candidate.isTraceOpen) { + trace = candidate; + break; + } + } + if (trace === undefined) { + const tracing = describeProvider(otelTrace.getTracerProvider()); + if (tracing.startsWith("no-op")) { + return { + error: "Tracing is not active in this TypeAgent process. Start the local stack with 'pnpm run telemetry:grafana', then restart TypeAgent before running a request.", + }; + } + return { + error: "No previous completed request's trace id is available yet. Run a request first, then use '@log open last'.", + }; + } + return { traceId: trace.traceId }; + } + if (!TRACE_ID_HEX_RE.test(lower)) { + return { + error: `Invalid trace id '${rawTraceId}'. Provide a 32 hex character trace id or 'last'.`, + }; + } + return { traceId: lower }; +} + +async function isLocalGrafanaReady( + dependencies: OpenLogTraceDependencies, + abortSignal: AbortSignal | undefined, +): Promise { + try { + abortSignal?.throwIfAborted(); + const response = await dependencies.fetch(LOCAL_GRAFANA_HEALTH_URL, { + signal: combineAbortSignals( + abortSignal, + LOCAL_GRAFANA_HEALTH_TIMEOUT_MS, + ), + }); + return response.ok; + } catch { + abortSignal?.throwIfAborted(); + return false; + } +} + +type TraceAvailability = "ready" | "not-found" | "unavailable"; + +async function waitForLocalTempoTrace( + traceId: string, + dependencies: OpenLogTraceDependencies, + abortSignal: AbortSignal | undefined, +): Promise { + const traceUrl = `${LOCAL_GRAFANA_BASE_URL}/api/datasources/proxy/uid/tempo/api/traces/${traceId}`; + let backendUnavailable = false; + const timeoutSignal = AbortSignal.timeout( + LOCAL_TEMPO_TRACE_WAIT_TIMEOUT_MS, + ); + const pollingSignal = + abortSignal === undefined + ? timeoutSignal + : AbortSignal.any([abortSignal, timeoutSignal]); + for ( + let attempt = 0; + attempt < LOCAL_TEMPO_TRACE_WAIT_ATTEMPTS; + attempt++ + ) { + abortSignal?.throwIfAborted(); + try { + const response = await dependencies.fetch(traceUrl, { + signal: pollingSignal, + }); + if (response.ok) { + if (await containsTypeAgentRootSpan(response)) { + return "ready"; + } + } else if ( + response.status !== 404 && + response.status !== 429 && + response.status < 500 + ) { + return "unavailable"; + } else if (response.status !== 404) { + backendUnavailable = true; + } + } catch { + abortSignal?.throwIfAborted(); + if (timeoutSignal.aborted) { + break; + } + backendUnavailable = true; + } + if (attempt + 1 < LOCAL_TEMPO_TRACE_WAIT_ATTEMPTS) { + try { + await waitForRetry(dependencies, pollingSignal); + } catch { + abortSignal?.throwIfAborted(); + break; + } + } + } + return backendUnavailable ? "unavailable" : "not-found"; +} + +function combineAbortSignals( + abortSignal: AbortSignal | undefined, + timeoutMs: number, +): AbortSignal { + const timeoutSignal = AbortSignal.timeout(timeoutMs); + return abortSignal === undefined + ? timeoutSignal + : AbortSignal.any([abortSignal, timeoutSignal]); +} + +async function waitForRetry( + dependencies: OpenLogTraceDependencies, + abortSignal: AbortSignal | undefined, +): Promise { + abortSignal?.throwIfAborted(); + if (dependencies.wait !== undefined) { + await dependencies.wait(LOCAL_TEMPO_TRACE_WAIT_INTERVAL_MS); + abortSignal?.throwIfAborted(); + return; + } + await new Promise((resolve, reject) => { + const onAbort = () => { + clearTimeout(timeout); + reject(abortSignal?.reason); + }; + const timeout = setTimeout(() => { + abortSignal?.removeEventListener("abort", onAbort); + resolve(); + }, LOCAL_TEMPO_TRACE_WAIT_INTERVAL_MS); + abortSignal?.addEventListener("abort", onAbort, { once: true }); + }); +} + +async function containsTypeAgentRootSpan(response: Response): Promise { + try { + const payload = (await response.json()) as { + batches?: { + scopeSpans?: { + spans?: { name?: string }[]; + }[]; + }[]; + }; + return ( + payload.batches?.some((batch) => + batch.scopeSpans?.some((scope) => + scope.spans?.some( + (span) => span.name === "typeagent.request", + ), + ), + ) === true + ); + } catch { + return false; + } +} + +// The command and natural-language action share validation, health checking, +// URL construction, browser launch, and user-facing errors here. +export async function openLogTrace( + rawTraceId: string, + context: ActionContext, + dependencies: OpenLogTraceDependencies = defaultDependencies, +): Promise { + const systemContext = context.sessionContext.agentContext; + const resolved = resolveTraceId(rawTraceId, systemContext); + if ("error" in resolved) { + displayError(resolved.error, context); + return; + } + const { traceId } = resolved; + + if (!(await isLocalGrafanaReady(dependencies, context.abortSignal))) { + displayError( + `Local Grafana at ${LOCAL_GRAFANA_BASE_URL} is not reachable. Start it with 'pnpm run telemetry:grafana' from the ts directory, then retry.`, + context, + ); + return; + } + + const availability = await waitForLocalTempoTrace( + traceId, + dependencies, + context.abortSignal, + ); + if (availability === "not-found") { + displayError( + `Trace ${traceId} is not available in local Tempo. It may still be exporting or may not have been captured. Confirm local telemetry is enabled and restart TypeAgent if its configuration changed.`, + context, + ); + return; + } + if (availability === "unavailable") { + displayError( + "Local Grafana is running, but its Tempo data source is not responding. Wait for the telemetry stack to finish starting, then retry.", + context, + ); + return; + } + + const url = buildLocalGrafanaTraceUrl(traceId); + try { + context.abortSignal?.throwIfAborted(); + await dependencies.openUrl(url); + } catch (err) { + const message = err instanceof Error ? err.message : String(err); + displayError( + `Failed to open Grafana in your browser: ${message}`, + context, + ); + return; + } + displaySuccess(`Opened trace ${traceId} in local Grafana: ${url}`, context); +} + +class LogOpenCommandHandler implements CommandHandler { + public constructor( + private readonly dependencies: OpenLogTraceDependencies = defaultDependencies, + ) {} + + public readonly description = + "Open a captured trace by id (or 'last') in the local Grafana Explore view"; + public readonly parameters = { + args: { + traceId: { + description: + "32 hex character trace id, or 'last' for the previous completed request's trace", + type: "string", + }, + }, + } as const; + public async run( + context: ActionContext, + params: ParsedCommandParams, + ) { + await openLogTrace(params.args.traceId, context, this.dependencies); + } + public async getCompletion( + _context: SessionContext, + _params: PartialParsedCommandParams, + names: string[], + ): Promise { + if (!names.includes("traceId")) { + return { groups: [] }; + } + return { + groups: [ + { + name: "traceId", + completions: ["last"], + }, + ], + }; + } +} + +export function getLogCommandHandlers( + openTraceDependencies: OpenLogTraceDependencies = defaultDependencies, +): CommandHandlerTable { return { description: "Local OpenTelemetry sink controls (independent of @trace)", @@ -203,6 +540,7 @@ export function getLogCommandHandlers(): CommandHandlerTable { status: new LogStatusCommandHandler(), profile: new LogProfileCommandHandler(), clear: new LogClearCommandHandler(), + open: new LogOpenCommandHandler(openTraceDependencies), }, }; } diff --git a/ts/packages/dispatcher/dispatcher/src/context/system/schema/logActionSchema.agr b/ts/packages/dispatcher/dispatcher/src/context/system/schema/logActionSchema.agr index b2b4d472d5..9b1f0a4d08 100644 --- a/ts/packages/dispatcher/dispatcher/src/context/system/schema/logActionSchema.agr +++ b/ts/packages/dispatcher/dispatcher/src/context/system/schema/logActionSchema.agr @@ -68,9 +68,27 @@ actionName: "clearLogSettings" }; +// Open one request's captured OpenTelemetry trace in local Grafana. Every +// rule anchors on "local Grafana" or an explicit "last trace" so these do not +// swallow generic "open ..." or "view ..." phrases. + = + open (the)? trace $(traceId:wildcard) in (the)? local grafana -> { + actionName: "openLogTrace", + parameters: { traceId } + } + | open (the)? last trace -> { + actionName: "openLogTrace", + parameters: { traceId: "last" } + } + | view (the)? last action result in (local)? grafana -> { + actionName: "openLogTrace", + parameters: { traceId: "last" } + }; + = | | | | - | ; + | + | ; diff --git a/ts/packages/dispatcher/dispatcher/src/context/system/schema/logActionSchema.ts b/ts/packages/dispatcher/dispatcher/src/context/system/schema/logActionSchema.ts index 3dbb5e06b9..b8d9f1b03a 100644 --- a/ts/packages/dispatcher/dispatcher/src/context/system/schema/logActionSchema.ts +++ b/ts/packages/dispatcher/dispatcher/src/context/system/schema/logActionSchema.ts @@ -4,7 +4,8 @@ export type LogAction = | ShowLogStatusAction | SetLogProfileAction - | ClearLogSettingsAction; + | ClearLogSettingsAction + | OpenLogTraceAction; // Show the current local OpenTelemetry logging configuration. // Examples: "show local log status", "check local telemetry settings". @@ -26,3 +27,15 @@ export type SetLogProfileAction = { export type ClearLogSettingsAction = { actionName: "clearLogSettings"; }; + +// Open a captured request's OpenTelemetry trace in the local Grafana Explore +// view. `traceId` is either a 32-character hex trace id or the literal "last", +// which resolves to the trace id of the previously completed request. +// Examples: "open trace in local Grafana", "open last trace", +// "view the last action result in Grafana". +export type OpenLogTraceAction = { + actionName: "openLogTrace"; + parameters: { + traceId: string; + }; +}; diff --git a/ts/packages/dispatcher/dispatcher/test/logActionHandler.spec.ts b/ts/packages/dispatcher/dispatcher/test/logActionHandler.spec.ts index c2b01c2b8f..12c5018114 100644 --- a/ts/packages/dispatcher/dispatcher/test/logActionHandler.spec.ts +++ b/ts/packages/dispatcher/dispatcher/test/logActionHandler.spec.ts @@ -6,12 +6,14 @@ import { jest } from "@jest/globals"; const mockShowLogStatus = jest.fn(); const mockSetLogProfile = jest.fn(); const mockClearLogSettings = jest.fn(); +const mockOpenLogTrace = jest.fn(async () => undefined); jest.unstable_mockModule( "../src/context/system/handlers/logCommandHandler.js", () => ({ showLogStatus: mockShowLogStatus, setLogProfile: mockSetLogProfile, clearLogSettings: mockClearLogSettings, + openLogTrace: mockOpenLogTrace, }), ); @@ -30,19 +32,37 @@ async function run(action: any) { describe("executeLogAction delegates to shared log controls", () => { it.each([ - [{ actionName: "showLogStatus" }, mockShowLogStatus, []], + [{ actionName: "showLogStatus" }, () => mockShowLogStatus, [] as any[]], [ { actionName: "setLogProfile", parameters: { profile: "diagnostic" }, }, - mockSetLogProfile, + () => mockSetLogProfile, ["diagnostic"], ], - [{ actionName: "clearLogSettings" }, mockClearLogSettings, []], - ])("maps %j to the shared control", async (action, handler, args) => { + [{ actionName: "clearLogSettings" }, () => mockClearLogSettings, []], + [ + { + actionName: "openLogTrace", + parameters: { + traceId: "0123456789abcdef0123456789abcdef", + }, + }, + () => mockOpenLogTrace, + ["0123456789abcdef0123456789abcdef"], + ], + [ + { + actionName: "openLogTrace", + parameters: { traceId: "last" }, + }, + () => mockOpenLogTrace, + ["last"], + ], + ])("maps %j to the shared control", async (action, getHandler, args) => { await run(action); - expect(handler).toHaveBeenCalledWith( + expect(getHandler()).toHaveBeenCalledWith( ...args, expect.objectContaining({ sessionContext: { agentContext }, diff --git a/ts/packages/dispatcher/dispatcher/test/logCommandHandler.spec.ts b/ts/packages/dispatcher/dispatcher/test/logCommandHandler.spec.ts index c3ff917053..7470e75499 100644 --- a/ts/packages/dispatcher/dispatcher/test/logCommandHandler.spec.ts +++ b/ts/packages/dispatcher/dispatcher/test/logCommandHandler.spec.ts @@ -1,17 +1,29 @@ // Copyright (c) Microsoft Corporation. // Licensed under the MIT License. +import { jest } from "@jest/globals"; import { otel } from "@typeagent/telemetry"; -import { getLogCommandHandlers } from "../src/context/system/handlers/logCommandHandler.js"; +import { + buildLocalGrafanaTraceUrl, + getLogCommandHandlers, + LOCAL_GRAFANA_BASE_URL, + openLogTrace, + type OpenLogTraceDependencies, +} from "../src/context/system/handlers/logCommandHandler.js"; import { parseParams } from "../src/command/parameters.js"; type Captured = { kind: string | undefined; content: unknown }; -function makeContext(): { +function makeContext(agentContextOverrides?: Record): { context: any; captured: Captured[]; + agentContext: Record; } { const captured: Captured[] = []; + const agentContext: Record = { + sessionTraceHistory: [], + ...agentContextOverrides, + }; const context = { actionIO: { appendDisplay(payload: any) { @@ -30,13 +42,13 @@ function makeContext(): { } }, }, - sessionContext: { agentContext: {} }, + sessionContext: { agentContext }, }; - return { context, captured }; + return { context, captured, agentContext }; } async function runSub( - name: "status" | "profile" | "clear", + name: "status" | "profile" | "clear" | "open", argv: string, ctx: any, ) { @@ -50,6 +62,47 @@ async function runSub( } } +function joinText(captured: Captured[]): string { + return captured + .map((c) => (typeof c.content === "string" ? c.content : "")) + .join("\n"); +} + +function makeTraceResponse(): Response { + return Response.json({ + batches: [ + { + scopeSpans: [ + { + spans: [{ name: "typeagent.request" }], + }, + ], + }, + ], + }); +} + +function makeReadyDeps(overrides?: { + fetch?: OpenLogTraceDependencies["fetch"]; + openUrl?: OpenLogTraceDependencies["openUrl"]; +}) { + const fetchMock = jest.fn(async (input: string | URL) => + String(input).endsWith("/api/health") + ? new Response(null, { status: 200 }) + : makeTraceResponse(), + ); + const openMock = jest.fn( + async (_url) => undefined, + ); + const waitMock = jest.fn(async () => undefined); + const deps: OpenLogTraceDependencies = { + fetch: overrides?.fetch ?? fetchMock, + openUrl: overrides?.openUrl ?? openMock, + wait: waitMock, + }; + return { deps, fetchMock, openMock, waitMock }; +} + describe("@log command handler", () => { beforeEach(() => { // Each test gets a fresh state singleton to avoid cross-test bleed. @@ -69,9 +122,7 @@ describe("@log command handler", () => { const { context, captured } = makeContext(); await runSub("status", "", context); - const text = captured - .map((c) => (typeof c.content === "string" ? c.content : "")) - .join("\n"); + const text = joinText(captured); expect(text).toContain("Local OTel profile: focused"); expect(text).toContain("debug bridge: available"); expect(text).toContain("local JSONL: configured"); @@ -114,9 +165,7 @@ describe("@log command handler", () => { await runSub("profile", profile, setCtx); const { context, captured } = makeContext(); await runSub("status", "", context); - const text = captured - .map((c) => (typeof c.content === "string" ? c.content : "")) - .join("\n"); + const text = joinText(captured); expect(text).toContain(`profile behavior: ${behavior}`); }); @@ -135,8 +184,367 @@ describe("@log command handler", () => { it("registers the expected subcommands and defaults to status", () => { const table = getLogCommandHandlers(); expect(Object.keys(table.commands ?? {}).sort()).toEqual( - ["clear", "profile", "status"].sort(), + ["clear", "open", "profile", "status"].sort(), ); expect(table.defaultSubCommand).toBeDefined(); }); }); + +describe("@log open", () => { + const VALID_ID = "0123456789abcdef0123456789abcdef"; + + it("opens an explicit 32 hex trace id in local Grafana", async () => { + const { context, captured } = makeContext(); + const { deps, fetchMock, openMock } = makeReadyDeps(); + await openLogTrace(VALID_ID, context, deps); + + expect(fetchMock).toHaveBeenCalledTimes(2); + const fetchArgs = fetchMock.mock.calls[0]; + expect(fetchArgs[0]).toBe(`${LOCAL_GRAFANA_BASE_URL}/api/health`); + expect(fetchMock.mock.calls[1][0]).toBe( + `${LOCAL_GRAFANA_BASE_URL}/api/datasources/proxy/uid/tempo/api/traces/${VALID_ID}`, + ); + + expect(openMock).toHaveBeenCalledTimes(1); + expect(openMock.mock.calls[0][0]).toBe( + buildLocalGrafanaTraceUrl(VALID_ID), + ); + + const success = captured.find((c) => c.kind === "success"); + expect(success).toBeDefined(); + expect(String(success!.content)).toContain(VALID_ID); + expect(String(success!.content)).toContain(LOCAL_GRAFANA_BASE_URL); + }); + + it("normalizes uppercase hex trace ids to lowercase", async () => { + const upper = VALID_ID.toUpperCase(); + const { context, captured } = makeContext(); + const { deps, openMock } = makeReadyDeps(); + await openLogTrace(upper, context, deps); + + expect(openMock).toHaveBeenCalledTimes(1); + expect(openMock.mock.calls[0][0]).toBe( + buildLocalGrafanaTraceUrl(VALID_ID), + ); + const success = captured.find((c) => c.kind === "success"); + expect(String(success!.content)).toContain(VALID_ID); + }); + + it("resolves 'last' to the stored previous trace id", async () => { + const { context, captured } = makeContext({ + sessionTraceHistory: [ + { + traceId: VALID_ID, + requestId: "request-1", + kind: "request", + isTraceOpen: false, + completedAt: 1, + }, + ], + }); + const { deps, openMock } = makeReadyDeps(); + await openLogTrace("last", context, deps); + + expect(openMock).toHaveBeenCalledTimes(1); + expect(openMock.mock.calls[0][0]).toBe( + buildLocalGrafanaTraceUrl(VALID_ID), + ); + const success = captured.find((c) => c.kind === "success"); + expect(success).toBeDefined(); + }); + + it("ignores newer command and trace-open entries when resolving the last request", async () => { + const commandTraceId = "fedcba9876543210fedcba9876543210"; + const traceOpenId = "11111111111111111111111111111111"; + const { context } = makeContext({ + sessionTraceHistory: [ + { + traceId: VALID_ID, + requestId: "request-1", + kind: "request", + isTraceOpen: false, + completedAt: 1, + }, + { + traceId: commandTraceId, + requestId: "command-1", + kind: "command", + isTraceOpen: false, + completedAt: 2, + }, + { + traceId: traceOpenId, + requestId: "request-2", + kind: "request", + isTraceOpen: true, + completedAt: 3, + }, + ], + }); + const { deps, openMock } = makeReadyDeps(); + await openLogTrace("last", context, deps); + + expect(openMock).toHaveBeenCalledWith( + buildLocalGrafanaTraceUrl(VALID_ID), + ); + }); + + it("shows a clear error when 'last' has no stored trace id", async () => { + const { context, captured } = makeContext(); + const { deps, fetchMock, openMock } = makeReadyDeps(); + await openLogTrace("last", context, deps); + + expect(fetchMock).not.toHaveBeenCalled(); + expect(openMock).not.toHaveBeenCalled(); + const error = captured.find((c) => c.kind === "error"); + expect(error).toBeDefined(); + expect(String(error!.content)).toMatch( + /Tracing is not active|No previous completed request/, + ); + }); + + it("rejects invalid trace ids without touching Grafana", async () => { + const { context, captured } = makeContext(); + const { deps, fetchMock, openMock } = makeReadyDeps(); + await openLogTrace("not-a-trace-id", context, deps); + + expect(fetchMock).not.toHaveBeenCalled(); + expect(openMock).not.toHaveBeenCalled(); + const error = captured.find((c) => c.kind === "error"); + expect(error).toBeDefined(); + expect(String(error!.content)).toContain("Invalid trace id"); + }); + + it("does not open when local Grafana is unavailable", async () => { + const { context, captured } = makeContext(); + const fetchMock = jest.fn(async () => { + throw new TypeError("fetch failed"); + }); + const openMock = jest.fn(async () => undefined); + await openLogTrace(VALID_ID, context, { + fetch: fetchMock, + openUrl: openMock, + }); + + expect(fetchMock).toHaveBeenCalledTimes(1); + expect(openMock).not.toHaveBeenCalled(); + const error = captured.find((c) => c.kind === "error"); + expect(error).toBeDefined(); + expect(String(error!.content)).toContain("pnpm run telemetry:grafana"); + }); + + it("does not open when health endpoint returns non-ok", async () => { + const { context, captured } = makeContext(); + const fetchMock = jest.fn( + async () => new Response(null, { status: 503 }), + ); + const openMock = jest.fn(async () => undefined); + await openLogTrace(VALID_ID, context, { + fetch: fetchMock, + openUrl: openMock, + }); + + expect(openMock).not.toHaveBeenCalled(); + const error = captured.find((c) => c.kind === "error"); + expect(String(error!.content)).toContain("pnpm run telemetry:grafana"); + }); + + it("waits for a recently exported trace to become available", async () => { + const { context } = makeContext(); + const fetchMock = jest + .fn() + .mockResolvedValueOnce(new Response(null, { status: 200 })) + .mockResolvedValueOnce(new Response(null, { status: 404 })) + .mockResolvedValueOnce(makeTraceResponse()); + const openMock = jest.fn(async () => undefined); + const waitMock = jest.fn(async () => undefined); + await openLogTrace(VALID_ID, context, { + fetch: fetchMock, + openUrl: openMock, + wait: waitMock, + }); + + expect(waitMock).toHaveBeenCalledTimes(1); + expect(openMock).toHaveBeenCalledTimes(1); + }); + + it("waits until the root request span has been exported", async () => { + const { context } = makeContext(); + const partialTrace = Response.json({ + batches: [ + { + scopeSpans: [ + { spans: [{ name: "typeagent.translation" }] }, + ], + }, + ], + }); + const fetchMock = jest + .fn() + .mockResolvedValueOnce(new Response(null, { status: 200 })) + .mockResolvedValueOnce(partialTrace) + .mockResolvedValueOnce(makeTraceResponse()); + const openMock = jest.fn(async () => undefined); + const waitMock = jest.fn(async () => undefined); + await openLogTrace(VALID_ID, context, { + fetch: fetchMock, + openUrl: openMock, + wait: waitMock, + }); + + expect(waitMock).toHaveBeenCalledTimes(1); + expect(openMock).toHaveBeenCalledTimes(1); + }); + + it("does not open when the trace was not captured by Tempo", async () => { + const { context, captured } = makeContext(); + const fetchMock = jest + .fn() + .mockResolvedValueOnce(new Response(null, { status: 200 })) + .mockResolvedValue(new Response(null, { status: 404 })); + const openMock = jest.fn(async () => undefined); + const waitMock = jest.fn(async () => undefined); + await openLogTrace(VALID_ID, context, { + fetch: fetchMock, + openUrl: openMock, + wait: waitMock, + }); + + expect(waitMock).toHaveBeenCalledTimes(9); + expect(openMock).not.toHaveBeenCalled(); + const error = captured.find((c) => c.kind === "error"); + expect(String(error!.content)).toContain( + "is not available in local Tempo", + ); + }); + + it("distinguishes a persistently unavailable Tempo data source", async () => { + const { context, captured } = makeContext(); + const fetchMock = jest + .fn() + .mockResolvedValueOnce(new Response(null, { status: 200 })) + .mockResolvedValue(new Response(null, { status: 503 })); + const openMock = jest.fn(async () => undefined); + const waitMock = jest.fn(async () => undefined); + await openLogTrace(VALID_ID, context, { + fetch: fetchMock, + openUrl: openMock, + wait: waitMock, + }); + + expect(waitMock).toHaveBeenCalledTimes(9); + expect(openMock).not.toHaveBeenCalled(); + const error = captured.find((c) => c.kind === "error"); + expect(String(error!.content)).toContain( + "Tempo data source is not responding", + ); + }); + + it("reports opener errors via displayError", async () => { + const { context, captured } = makeContext(); + const fetchMock = jest.fn(async (input: string | URL) => + String(input).endsWith("/api/health") + ? new Response(null, { status: 200 }) + : makeTraceResponse(), + ); + const openMock = jest.fn(async () => { + throw new Error("browser missing"); + }); + await openLogTrace(VALID_ID, context, { + fetch: fetchMock, + openUrl: openMock, + }); + + expect(openMock).toHaveBeenCalledTimes(1); + const error = captured.find((c) => c.kind === "error"); + expect(error).toBeDefined(); + expect(String(error!.content)).toContain("browser missing"); + const success = captured.find((c) => c.kind === "success"); + expect(success).toBeUndefined(); + }); + + it("stops polling and does not open after cancellation", async () => { + const { context } = makeContext(); + const abortController = new AbortController(); + context.abortSignal = abortController.signal; + const fetchMock = jest + .fn() + .mockResolvedValueOnce(new Response(null, { status: 200 })) + .mockResolvedValueOnce(new Response(null, { status: 404 })); + const openMock = jest.fn(async () => undefined); + const waitMock = jest.fn(async () => { + abortController.abort(); + }); + + await expect( + openLogTrace(VALID_ID, context, { + fetch: fetchMock, + openUrl: openMock, + wait: waitMock, + }), + ).rejects.toMatchObject({ name: "AbortError" }); + expect(openMock).not.toHaveBeenCalled(); + }); + + it("builds the Grafana 13 Explore URL with schemaVersion, orgId, and tempo panes", () => { + const url = buildLocalGrafanaTraceUrl(VALID_ID); + const parsed = new URL(url); + expect(parsed.origin).toBe(LOCAL_GRAFANA_BASE_URL); + expect(parsed.pathname).toBe("/explore"); + expect(parsed.searchParams.get("schemaVersion")).toBe("1"); + expect(parsed.searchParams.get("orgId")).toBe("1"); + const panesRaw = parsed.searchParams.get("panes"); + expect(panesRaw).not.toBeNull(); + const panes = JSON.parse(panesRaw!); + const paneIds = Object.keys(panes); + expect(paneIds).toHaveLength(1); + const pane = panes[paneIds[0]]; + expect(pane.datasource).toBe("tempo"); + expect(pane.queries).toHaveLength(1); + const query = pane.queries[0]; + expect(query.refId).toBe("A"); + expect(query.queryType).toBe("traceql"); + expect(query.query).toBe(VALID_ID); + expect(query.filters).toEqual([]); + expect(query.datasource).toEqual({ type: "tempo", uid: "tempo" }); + expect(pane.range).toEqual({ from: "now-1h", to: "now" }); + }); + + it("open command delegates to the shared openLogTrace via the ActionContext", async () => { + const { deps, fetchMock, openMock } = makeReadyDeps(); + const table = getLogCommandHandlers(deps); + const cmd: any = (table.commands as any).open; + const { context } = makeContext(); + const params = parseParams(VALID_ID, cmd.parameters); + await cmd.run(context, params); + + expect(fetchMock).toHaveBeenCalledTimes(2); + expect(openMock).toHaveBeenCalledWith( + buildLocalGrafanaTraceUrl(VALID_ID), + ); + }); + + it("registers a 'last' parameter completion", async () => { + const table = getLogCommandHandlers(); + const cmd: any = (table.commands as any).open; + const groups = await cmd.getCompletion( + { agentContext: {} } as any, + {}, + ["traceId"], + ); + expect( + groups.groups.some((g: any) => g.completions.includes("last")), + ).toBe(true); + }); + + it("returns no completions when the traceId slot is not being edited", async () => { + const table = getLogCommandHandlers(); + const cmd: any = (table.commands as any).open; + const groups = await cmd.getCompletion( + { agentContext: {} } as any, + {}, + [], + ); + expect(groups.groups).toHaveLength(0); + }); +}); diff --git a/ts/packages/dispatcher/dispatcher/test/logGrammar.spec.ts b/ts/packages/dispatcher/dispatcher/test/logGrammar.spec.ts index fb9bbcc24c..4f474126d8 100644 --- a/ts/packages/dispatcher/dispatcher/test/logGrammar.spec.ts +++ b/ts/packages/dispatcher/dispatcher/test/logGrammar.spec.ts @@ -76,4 +76,47 @@ describe("system.log grammar", () => { expect(match(input)).toBeUndefined(); }, ); + + // Grafana trace open shortcuts. The wildcard-bearing rule anchors on + // "in local grafana" so it does not swallow generic "open X" phrases. + const TRACE_ID = "0123456789abcdef0123456789abcdef"; + + it("maps 'open trace in local grafana' to an openLogTrace action", () => { + expect(match(`open trace ${TRACE_ID} in local grafana`)).toEqual({ + actionName: "openLogTrace", + parameters: { traceId: TRACE_ID }, + }); + }); + + it.each(["open last trace", "open the last trace"])( + "maps '%s' to openLogTrace with traceId=last", + (input) => { + expect(match(input)).toEqual({ + actionName: "openLogTrace", + parameters: { traceId: "last" }, + }); + }, + ); + + it.each([ + "view the last action result in grafana", + "view the last action result in local grafana", + ])("maps '%s' to openLogTrace with traceId=last", (input) => { + expect(match(input)).toEqual({ + actionName: "openLogTrace", + parameters: { traceId: "last" }, + }); + }); + + it.each([ + // Broad open/view phrases must NOT be captured. Those anchors are + // deliberately narrow so unrelated intents fall through to the LLM. + "open the trace file", + "open trace", + "view the last result", + "view the last action", + "open in grafana", + ])("does not capture unscoped phrase %p", (input) => { + expect(match(input)).toBeUndefined(); + }); });