记录真实LLM请求与响应
This commit is contained in:
@@ -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;
|
||||
|
||||
+176
-32
@@ -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<void>;
|
||||
traceCallId?: string;
|
||||
}
|
||||
|
||||
export interface GenerateValidatedJsonInput<T> 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<LlmClientTraceEvent, { type: "failed" }> {
|
||||
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<T>(input: GenerateInput): Promise<T> {
|
||||
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: <T>(input: GenerateInput) => Promise<T> =
|
||||
@@ -227,6 +333,9 @@ export async function generateValidatedJson<T>({
|
||||
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<T>({
|
||||
}
|
||||
|
||||
try {
|
||||
const generated = await generateJsonForValidation<unknown>(input);
|
||||
const generated = await generateJsonForValidation<unknown>(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<T>({
|
||||
}
|
||||
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<T>({
|
||||
return parsed.data;
|
||||
}
|
||||
const zodSummary = summarizeZodError(parsed.error);
|
||||
const validationIssues = parsed.error.issues.map((issue) => {
|
||||
const path = issue.path.length > 0 ? issue.path.join(".") : "<root>";
|
||||
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<T>({
|
||||
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<T>({
|
||||
}
|
||||
|
||||
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}`);
|
||||
}
|
||||
|
||||
Reference in New Issue
Block a user