diff --git a/src/lib/llm/__tests__/client.test.ts b/src/lib/llm/__tests__/client.test.ts index 9b4e326..b24f5d9 100644 --- a/src/lib/llm/__tests__/client.test.ts +++ b/src/lib/llm/__tests__/client.test.ts @@ -2,6 +2,7 @@ import { afterEach, describe, expect, it, vi } from "vitest"; import { z } from "zod"; import * as client from "../client"; +import type { LlmClientTraceEvent } from "../trace-types"; describe("generateValidatedJson", () => { const originalProvider = process.env.LLM_PROVIDER; @@ -13,9 +14,133 @@ describe("generateValidatedJson", () => { delete process.env.LLM_LOG_RAW_LIMIT; delete process.env.DEEPSEEK_MODEL; client.setGenerateJsonForValidation(client.generateJson); + client.setChatCompletionForTesting(null); vi.restoreAllMocks(); }); + it("traces the exact SDK request and full SDK response", async () => { + process.env.LLM_PROVIDER = "deepseek"; + process.env.DEEPSEEK_API_KEY = "test-key"; + const traced: LlmClientTraceEvent[] = []; + let sdkRequest: unknown; + const sdkResponse = { + id: "chatcmpl_1", + object: "chat.completion", + created: 1784188800, + model: "deepseek-v4-pro", + choices: [{ + index: 0, + message: { role: "assistant", content: '{"value":"ok"}' }, + finish_reason: "stop", + }], + usage: { prompt_tokens: 10, completion_tokens: 4, total_tokens: 14 }, + }; + client.setChatCompletionForTesting(async (request) => { + sdkRequest = request; + return sdkResponse; + }); + + await client.generateValidatedJson({ + schema: z.object({ value: z.string() }), + schemaName: "valueSchema", + prompt: "Return JSON.", + task: "article_optimizer", + traceStage: "draft", + onTraceEvent: (event) => { + traced.push(event); + }, + }); + + expect(traced.find((event) => event.type === "started")).toMatchObject({ + type: "started", + request: sdkRequest, + }); + expect(traced.find((event) => event.type === "responded")).toMatchObject({ + type: "responded", + response: sdkResponse, + }); + expect(traced.map((event) => event.type)).toEqual([ + "started", + "responded", + "validated", + ]); + expect(JSON.stringify(traced)).not.toContain("test-key"); + }); + + it("traces JSON parse and schema failures in their actual order", async () => { + process.env.LLM_PROVIDER = "deepseek"; + process.env.DEEPSEEK_API_KEY = "test-key"; + const jsonParseEvents: LlmClientTraceEvent[] = []; + client.setChatCompletionForTesting(async () => ({ + choices: [{ message: { content: "not json" } }], + })); + + await expect(client.generateValidatedJson({ + schema: z.object({ value: z.string() }), + schemaName: "valueSchema", + prompt: "Return JSON.", + onTraceEvent: (event) => { + jsonParseEvents.push(event); + }, + })).rejects.toThrow("not valid JSON"); + expect(jsonParseEvents.map((event) => event.type)).toEqual([ + "started", + "responded", + "failed", + ]); + expect(jsonParseEvents.at(-1)).toMatchObject({ + type: "failed", + error_type: "json_parse", + }); + + const schemaEvents: LlmClientTraceEvent[] = []; + client.setChatCompletionForTesting(async () => ({ + choices: [{ message: { content: '{"value":42}' } }], + })); + await expect(client.generateValidatedJson({ + schema: z.object({ value: z.string() }), + schemaName: "valueSchema", + prompt: "Return JSON.", + onTraceEvent: (event) => { + schemaEvents.push(event); + }, + })).rejects.toThrow("schema validation"); + expect(schemaEvents.map((event) => event.type)).toEqual([ + "started", + "responded", + "validated", + "failed", + ]); + expect(schemaEvents.at(-1)).toMatchObject({ + type: "failed", + error_type: "schema_validation", + }); + }); + + it("redacts configured secrets from traced provider errors", async () => { + process.env.LLM_PROVIDER = "deepseek"; + process.env.DEEPSEEK_API_KEY = "super-secret-key"; + const traced: LlmClientTraceEvent[] = []; + client.setChatCompletionForTesting(async () => { + throw new Error("request failed for super-secret-key"); + }); + + await expect(client.generateValidatedJson({ + schema: z.object({ value: z.string() }), + prompt: "Return JSON.", + onTraceEvent: (event) => { + traced.push(event); + }, + })).rejects.toThrow("request failed"); + + expect(traced.map((event) => event.type)).toEqual(["started", "failed"]); + expect(JSON.stringify(traced)).not.toContain("super-secret-key"); + expect(traced.at(-1)).toMatchObject({ + type: "failed", + error_type: "provider", + }); + }); + it("throws clearly when no provider key is configured", async () => { process.env.LLM_PROVIDER = "deepseek"; delete process.env.DEEPSEEK_API_KEY; diff --git a/src/lib/llm/client.ts b/src/lib/llm/client.ts index 54a8499..4035ae2 100644 --- a/src/lib/llm/client.ts +++ b/src/lib/llm/client.ts @@ -1,8 +1,15 @@ import OpenAI from "openai"; +import { nanoid } from "nanoid"; import type { z } from "zod"; import { createLlmAuditSummary, type LlmAuditSummary } from "./audit"; -import type { LlmTaskName } from "./trace-types"; +import type { + LlmClientTraceEvent, + LlmClientTraceHandler, + LlmTaskName, + LlmTraceErrorType, + LlmTraceWorkflowStage, +} from "./trace-types"; export type { LlmTaskName } from "./trace-types"; @@ -12,7 +19,12 @@ export interface GenerateInput { model?: string; temperature?: number; task?: LlmTaskName; + schemaName?: string; + traceStage?: LlmTraceWorkflowStage; + rewriteRound?: number; + onTraceEvent?: LlmClientTraceHandler; onAuditSummary?: (summary: LlmAuditSummary) => void | Promise; + traceCallId?: string; } export interface GenerateValidatedJsonInput extends GenerateInput { @@ -93,6 +105,64 @@ function getTask(input: GenerateInput): LlmTaskName { return input.task || "unknown"; } +function callIdFor(input: GenerateInput) { + return input.traceCallId ?? `llmcall_${nanoid(12)}`; +} + +function redactConfiguredSecrets(value: string) { + return [process.env.DEEPSEEK_API_KEY, process.env.OPENAI_API_KEY] + .filter((secret): secret is string => Boolean(secret)) + .reduce( + (redacted, secret) => redacted.split(secret).join("[redacted]"), + value, + ); +} + +function safeErrorSummary(error: unknown) { + if (error instanceof Error) { + return `${error.name}: ${redactConfiguredSecrets(error.message)}`; + } + return `Error: ${redactConfiguredSecrets(String(error))}`; +} + +async function emitTrace(input: GenerateInput, event: LlmClientTraceEvent) { + try { + await input.onTraceEvent?.(event); + } catch (error) { + console.warn(`[llm:trace-warning] ${safeErrorSummary(error)}`); + } +} + +function failedEvent( + callId: string, + errorType: LlmTraceErrorType, + error: unknown, + startedAt: number, +): Extract { + return { + type: "failed", + call_id: callId, + error_type: errorType, + error_summary: safeErrorSummary(error), + duration_ms: Date.now() - startedAt, + failed_at: new Date().toISOString(), + }; +} + +function buildChatCompletionRequest(input: GenerateInput, model: string) { + return { + model, + temperature: input.temperature ?? 0.1, + response_format: { type: "json_object" as const }, + messages: [ + ...(input.system + ? [{ role: "system" as const, content: input.system }] + : []), + { role: "user" as const, content: input.prompt }, + ], + } satisfies ChatCompletionRequest; +} + function getRawLogLimit() { const parsed = Number(process.env.LLM_LOG_RAW_LIMIT ?? "4000"); return Number.isFinite(parsed) && parsed >= 0 ? parsed : 4000; @@ -166,39 +236,75 @@ export async function generateText(input: GenerateInput) { export async function generateJson(input: GenerateInput): Promise { const task = getTask(input); const startedAt = Date.now(); - try { - const status = getLlmProviderStatus(); - if (!status.configured) { - throw new Error(status.reason ?? "LLM provider is not configured"); - } - const effectiveModel = input.model ?? status.model; - console.info( - `[llm:start] provider=${status.provider} model=${effectiveModel} task=${task}`, - ); - const request = { - model: effectiveModel, - temperature: input.temperature ?? 0.1, - response_format: { type: "json_object" }, - messages: [ - ...(input.system ? [{ role: "system" as const, content: input.system }] : []), - { role: "user" as const, content: input.prompt }, - ], - } satisfies ChatCompletionRequest; - const response = chatCompletionForTesting - ? await chatCompletionForTesting(request) - : await createClient().client.chat.completions.create(request); - const content = response.choices[0]?.message.content ?? "{}"; - console.info( - `[llm:response] task=${task} duration_ms=${Date.now() - startedAt} raw=${truncateRaw(content)}`, - ); - return JSON.parse(content) as T; - } catch (error) { + const callId = callIdFor(input); + const status = getLlmProviderStatus(); + if (!status.configured) { + const error = new Error(status.reason ?? "LLM provider is not configured"); const normalized = normalizeLlmError(error); console.error( `[llm:error] task=${task} duration_ms=${Date.now() - startedAt} message=${quoteLogValue(normalized.message)}`, ); throw normalized; } + + const effectiveModel = input.model ?? status.model; + console.info( + `[llm:start] provider=${status.provider} model=${effectiveModel} task=${task}`, + ); + const request = buildChatCompletionRequest(input, effectiveModel); + await emitTrace(input, { + type: "started", + call_id: callId, + task, + context: { + workflow_stage: input.traceStage ?? "unknown", + rewrite_round: input.rewriteRound, + schema_name: input.schemaName, + }, + provider: status.provider, + model: effectiveModel, + request, + started_at: new Date(startedAt).toISOString(), + }); + + let response: ChatCompletionResult; + try { + response = chatCompletionForTesting + ? await chatCompletionForTesting(request) + : await createClient().client.chat.completions.create(request); + } catch (error) { + await emitTrace(input, failedEvent(callId, "provider", error, startedAt)); + const normalized = normalizeLlmError(error); + console.error( + `[llm:error] task=${task} duration_ms=${Date.now() - startedAt} message=${quoteLogValue(normalized.message)}`, + ); + throw normalized; + } + + await emitTrace(input, { + type: "responded", + call_id: callId, + response, + duration_ms: Date.now() - startedAt, + responded_at: new Date().toISOString(), + }); + + const content = response.choices[0]?.message.content ?? "{}"; + console.info( + `[llm:response] task=${task} duration_ms=${Date.now() - startedAt} raw=${truncateRaw(content)}`, + ); + try { + return JSON.parse(content) as T; + } catch (error) { + await emitTrace(input, failedEvent(callId, "json_parse", error, startedAt)); + const message = `LLM response is not valid JSON: ${redactConfiguredSecrets( + error instanceof Error ? error.message : String(error), + )}`; + console.error( + `[llm:error] task=${task} duration_ms=${Date.now() - startedAt} message=${quoteLogValue(message)}`, + ); + throw new Error(message); + } } export let generateJsonForValidation: (input: GenerateInput) => Promise = @@ -227,6 +333,9 @@ export async function generateValidatedJson({ const status = getLlmProviderStatus(); const startedAt = Date.now(); const effectiveModel = input.model ?? status.model; + const traceCallId = callIdFor(input); + const tracedInput: GenerateInput = { ...input, traceCallId }; + const schemaName = input.schemaName ?? "anonymousSchema"; const emitAudit = async ({ schemaValid, output, @@ -257,7 +366,7 @@ export async function generateValidatedJson({ } try { - const generated = await generateJsonForValidation(input); + const generated = await generateJsonForValidation(tracedInput); if (!usesDefaultGenerator) { console.info( `[llm:response] task=${task} duration_ms=${Date.now() - startedAt} raw=${truncateRaw(stringifyForLog(generated))}`, @@ -265,6 +374,14 @@ export async function generateValidatedJson({ } const parsed = schema.safeParse(generated); if (parsed.success) { + await emitTrace(tracedInput, { + type: "validated", + call_id: traceCallId, + schema_name: schemaName, + schema_valid: true, + validation_issues: [], + validated_at: new Date().toISOString(), + }); await emitAudit({ schemaValid: true, output: parsed.data, @@ -274,6 +391,18 @@ export async function generateValidatedJson({ return parsed.data; } const zodSummary = summarizeZodError(parsed.error); + const validationIssues = parsed.error.issues.map((issue) => { + const path = issue.path.length > 0 ? issue.path.join(".") : ""; + return `${path}: ${issue.message}`; + }); + await emitTrace(tracedInput, { + type: "validated", + call_id: traceCallId, + schema_name: schemaName, + schema_valid: false, + validation_issues: validationIssues, + validated_at: new Date().toISOString(), + }); console.warn( `[llm:validated] task=${task} ok=false zod_error=${quoteLogValue(zodSummary)}`, ); @@ -282,16 +411,29 @@ export async function generateValidatedJson({ output: generated, errorSummary: zodSummary, }); - throw new LlmValidationError( + const validationError = new LlmValidationError( `LLM response failed schema validation: ${zodSummary}`, task, ); + await emitTrace( + tracedInput, + failedEvent(traceCallId, "schema_validation", validationError, startedAt), + ); + throw validationError; } catch (error) { if (error instanceof LlmValidationError) { throw error; } console.info(`[llm:validated] task=${task} ok=false reason=provider_error`); - const message = error instanceof Error ? error.message : String(error); + const message = redactConfiguredSecrets( + error instanceof Error ? error.message : String(error), + ); + if (!usesDefaultGenerator) { + await emitTrace( + tracedInput, + failedEvent(traceCallId, "provider", error, startedAt), + ); + } await emitAudit({ schemaValid: false, output: null, @@ -307,6 +449,8 @@ export async function generateValidatedJson({ } function normalizeLlmError(error: unknown) { - const message = error instanceof Error ? error.message : "Unknown LLM error"; + const message = redactConfiguredSecrets( + error instanceof Error ? error.message : "Unknown LLM error", + ); return new Error(`LLM provider error: ${message}`); }