feat: log llm runtime responses

This commit is contained in:
Codex
2026-06-21 23:43:03 +08:00
parent d0a7e8e2fe
commit 91709cd6b5
2 changed files with 116 additions and 3 deletions
+84
View File
@@ -10,6 +10,8 @@ describe("generateValidatedJson", () => {
afterEach(() => {
process.env.LLM_PROVIDER = originalProvider;
process.env.DEEPSEEK_API_KEY = originalDeepSeekKey;
delete process.env.LLM_LOG_RAW_LIMIT;
delete process.env.DEEPSEEK_MODEL;
client.setGenerateJsonForValidation(client.generateJson);
vi.restoreAllMocks();
});
@@ -103,6 +105,88 @@ describe("generateValidatedJson", () => {
);
expect(warnSpy).toHaveBeenCalledWith(expect.stringContaining("value"));
});
it("logs provider, model, task, raw response snippet, and validation success", async () => {
process.env.LLM_PROVIDER = "deepseek";
process.env.DEEPSEEK_API_KEY = "test-key";
process.env.DEEPSEEK_MODEL = "deepseek-test";
process.env.LLM_LOG_RAW_LIMIT = "80";
const infoSpy = vi.spyOn(console, "info").mockImplementation(() => {});
const warnSpy = vi.spyOn(console, "warn").mockImplementation(() => {});
client.setGenerateJsonForValidation(async () => ({
value: "from-llm",
longField: "x".repeat(200),
}));
const result = await client.generateValidatedJson({
schema: z.object({ value: z.string(), longField: z.string() }),
task: "article_optimizer",
prompt: "Return JSON.",
});
expect(result?.value).toBe("from-llm");
expect(infoSpy).toHaveBeenCalledWith(
expect.stringContaining(
"[llm:start] provider=deepseek model=deepseek-test task=article_optimizer",
),
);
expect(infoSpy).toHaveBeenCalledWith(
expect.stringContaining("[llm:response] task=article_optimizer"),
);
expect(infoSpy).toHaveBeenCalledWith(
expect.stringContaining('"value":"from-llm"'),
);
expect(infoSpy).toHaveBeenCalledWith(
expect.stringContaining("[llm:validated] task=article_optimizer ok=true"),
);
expect(warnSpy).not.toHaveBeenCalled();
});
it("logs validation failure without leaking provider secrets", async () => {
process.env.LLM_PROVIDER = "deepseek";
process.env.DEEPSEEK_API_KEY = "super-secret-key";
process.env.DEEPSEEK_MODEL = "deepseek-test";
const infoSpy = vi.spyOn(console, "info").mockImplementation(() => {});
const warnSpy = vi.spyOn(console, "warn").mockImplementation(() => {});
client.setGenerateJsonForValidation(async () => ({ value: 42 }));
const result = await client.generateValidatedJson({
schema: z.object({ value: z.string() }),
task: "fact_extractor",
prompt: "Return JSON.",
});
const allLogs = [...infoSpy.mock.calls, ...warnSpy.mock.calls]
.flat()
.join("\n");
expect(result).toBeNull();
expect(allLogs).toContain("[llm:validated] task=fact_extractor ok=false");
expect(allLogs).toContain("zod_error=");
expect(allLogs).not.toContain("super-secret-key");
});
it("logs provider call failure for validated JSON calls", async () => {
process.env.LLM_PROVIDER = "deepseek";
process.env.DEEPSEEK_API_KEY = "test-key";
const warnSpy = vi.spyOn(console, "warn").mockImplementation(() => {});
client.setGenerateJsonForValidation(async () => {
throw new Error("provider unavailable");
});
const result = await client.generateValidatedJson({
schema: z.object({ value: z.string() }),
task: "quality_inspector",
prompt: "Return JSON.",
});
expect(result).toBeNull();
expect(warnSpy).toHaveBeenCalledWith(
expect.stringContaining("[llm:error] task=quality_inspector"),
);
expect(warnSpy).toHaveBeenCalledWith(
expect.stringContaining("provider unavailable"),
);
});
});
describe("generateJson logging", () => {
+32 -3
View File
@@ -1,12 +1,19 @@
import OpenAI from "openai";
import type { z } from "zod";
export type LlmTaskName =
| "unknown"
| "fact_extractor"
| "article_optimizer"
| "quality_inspector"
| "targeted_rewriter";
export interface GenerateInput {
system?: string;
prompt: string;
model?: string;
temperature?: number;
task?: string;
task?: LlmTaskName;
}
export interface GenerateValidatedJsonInput<T> extends GenerateInput {
@@ -77,7 +84,16 @@ function getTask(input: GenerateInput) {
return input.task?.trim() || "unknown";
}
function truncateRaw(value: string, maxLength = 4000) {
function getRawLogLimit() {
const parsed = Number(process.env.LLM_LOG_RAW_LIMIT ?? "4000");
return Number.isFinite(parsed) && parsed >= 0 ? parsed : 4000;
}
function stringifyForLog(value: unknown) {
return typeof value === "string" ? value : JSON.stringify(value);
}
function truncateRaw(value: string, maxLength = getRawLogLimit()) {
return value.length > maxLength
? `${value.slice(0, maxLength)}...[truncated ${value.length - maxLength} chars]`
: value;
@@ -195,8 +211,17 @@ export async function generateValidatedJson<T>({
return null;
}
const status = getLlmProviderStatus();
const startedAt = Date.now();
console.info(
`[llm:start] provider=${status.provider} model=${input.model ?? status.model} task=${task}`,
);
try {
const generated = await generateJsonForValidation<unknown>(input);
console.info(
`[llm:response] task=${task} duration_ms=${Date.now() - startedAt} raw=${truncateRaw(stringifyForLog(generated))}`,
);
const parsed = schema.safeParse(generated);
if (parsed.success) {
console.info(`[llm:validated] task=${task} ok=true`);
@@ -206,8 +231,12 @@ export async function generateValidatedJson<T>({
`[llm:validated] task=${task} ok=false zod_error=${quoteLogValue(summarizeZodError(parsed.error))}`,
);
return null;
} catch {
} catch (error) {
console.info(`[llm:validated] task=${task} ok=false reason=provider_error`);
const message = error instanceof Error ? error.message : String(error);
console.warn(
`[llm:error] task=${task} duration_ms=${Date.now() - startedAt} message=${quoteLogValue(message)}`,
);
return null;
}
}