From 9416d81e80f921f7aef7297bafd4f6eb1399a555 Mon Sep 17 00:00:00 2001 From: Codex Date: Tue, 16 Jun 2026 23:34:14 +0800 Subject: [PATCH] feat: add central llm runtime logging --- src/lib/llm/__tests__/client.test.ts | 140 +++++++++++++++++++++++---- src/lib/llm/client.ts | 88 +++++++++++++++-- 2 files changed, 202 insertions(+), 26 deletions(-) diff --git a/src/lib/llm/__tests__/client.test.ts b/src/lib/llm/__tests__/client.test.ts index f540435..4dd36e3 100644 --- a/src/lib/llm/__tests__/client.test.ts +++ b/src/lib/llm/__tests__/client.test.ts @@ -7,12 +7,12 @@ describe("generateValidatedJson", () => { const originalProvider = process.env.LLM_PROVIDER; const originalDeepSeekKey = process.env.DEEPSEEK_API_KEY; - afterEach(() => { - process.env.LLM_PROVIDER = originalProvider; - process.env.DEEPSEEK_API_KEY = originalDeepSeekKey; - client.setGenerateJsonForValidation(client.generateJson); - vi.restoreAllMocks(); - }); + afterEach(() => { + process.env.LLM_PROVIDER = originalProvider; + process.env.DEEPSEEK_API_KEY = originalDeepSeekKey; + client.setGenerateJsonForValidation(client.generateJson); + vi.restoreAllMocks(); + }); it("returns null when no provider key is configured", async () => { process.env.LLM_PROVIDER = "deepseek"; @@ -26,10 +26,10 @@ describe("generateValidatedJson", () => { expect(result).toBeNull(); }); - it("returns parsed data when the model response matches the schema", async () => { - process.env.LLM_PROVIDER = "deepseek"; - process.env.DEEPSEEK_API_KEY = "test-key"; - client.setGenerateJsonForValidation(async () => ({ value: "from-llm" })); + it("returns parsed data when the model response matches the schema", async () => { + process.env.LLM_PROVIDER = "deepseek"; + process.env.DEEPSEEK_API_KEY = "test-key"; + client.setGenerateJsonForValidation(async () => ({ value: "from-llm" })); const result = await client.generateValidatedJson({ schema: z.object({ value: z.string() }), @@ -39,10 +39,10 @@ describe("generateValidatedJson", () => { expect(result).toEqual({ value: "from-llm" }); }); - it("returns null when the model response fails schema validation", async () => { - process.env.LLM_PROVIDER = "deepseek"; - process.env.DEEPSEEK_API_KEY = "test-key"; - client.setGenerateJsonForValidation(async () => ({ value: 42 })); + it("returns null when the model response fails schema validation", async () => { + process.env.LLM_PROVIDER = "deepseek"; + process.env.DEEPSEEK_API_KEY = "test-key"; + client.setGenerateJsonForValidation(async () => ({ value: 42 })); const result = await client.generateValidatedJson({ schema: z.object({ value: z.string() }), @@ -52,12 +52,12 @@ describe("generateValidatedJson", () => { expect(result).toBeNull(); }); - it("returns null when the provider call rejects", async () => { - process.env.LLM_PROVIDER = "deepseek"; - process.env.DEEPSEEK_API_KEY = "test-key"; - client.setGenerateJsonForValidation(async () => { - throw new Error("provider down"); - }); + it("returns null when the provider call rejects", async () => { + process.env.LLM_PROVIDER = "deepseek"; + process.env.DEEPSEEK_API_KEY = "test-key"; + client.setGenerateJsonForValidation(async () => { + throw new Error("provider down"); + }); const result = await client.generateValidatedJson({ schema: z.object({ value: z.string() }), @@ -66,4 +66,104 @@ describe("generateValidatedJson", () => { expect(result).toBeNull(); }); + + it("logs validation success with the supplied task label", async () => { + const infoSpy = vi.spyOn(console, "info").mockImplementation(() => {}); + process.env.LLM_PROVIDER = "deepseek"; + process.env.DEEPSEEK_API_KEY = "test-key"; + client.setGenerateJsonForValidation(async () => ({ value: "from-llm" })); + + const result = await client.generateValidatedJson({ + schema: z.object({ value: z.string() }), + prompt: "Return JSON.", + task: "article_optimizer", + }); + + expect(result).toEqual({ value: "from-llm" }); + expect(infoSpy).toHaveBeenCalledWith( + "[llm:validated] task=article_optimizer ok=true", + ); + }); + + it("logs validation failure with a compact Zod summary", async () => { + const warnSpy = vi.spyOn(console, "warn").mockImplementation(() => {}); + process.env.LLM_PROVIDER = "deepseek"; + process.env.DEEPSEEK_API_KEY = "test-key"; + client.setGenerateJsonForValidation(async () => ({ value: 42 })); + + const result = await client.generateValidatedJson({ + schema: z.object({ value: z.string() }), + prompt: "Return JSON.", + task: "fact_extractor", + }); + + expect(result).toBeNull(); + expect(warnSpy).toHaveBeenCalledWith( + expect.stringContaining("[llm:validated] task=fact_extractor ok=false"), + ); + expect(warnSpy).toHaveBeenCalledWith(expect.stringContaining("value")); + }); +}); + +describe("generateJson logging", () => { + const originalProvider = process.env.LLM_PROVIDER; + const originalDeepSeekKey = process.env.DEEPSEEK_API_KEY; + + afterEach(() => { + process.env.LLM_PROVIDER = originalProvider; + process.env.DEEPSEEK_API_KEY = originalDeepSeekKey; + client.setChatCompletionForTesting(null); + vi.restoreAllMocks(); + }); + + it("logs provider, model, task, duration, and truncated raw response", async () => { + const infoSpy = vi.spyOn(console, "info").mockImplementation(() => {}); + process.env.LLM_PROVIDER = "deepseek"; + process.env.DEEPSEEK_API_KEY = "test-key"; + const longContent = `{"value":"${"x".repeat(4100)}"}`; + client.setChatCompletionForTesting(async () => ({ + choices: [{ message: { content: longContent } }], + })); + + const result = await client.generateJson<{ value: string }>({ + prompt: "Return JSON.", + task: "article_optimizer", + }); + + expect(result.value).toHaveLength(4100); + expect(infoSpy).toHaveBeenCalledWith( + "[llm:start] provider=deepseek model=deepseek-v4-pro task=article_optimizer", + ); + const responseLog = infoSpy.mock.calls + .map((call) => call[0]) + .find((line) => line.startsWith("[llm:response]")); + expect(responseLog).toContain("task=article_optimizer"); + expect(responseLog).toContain("duration_ms="); + expect(responseLog).toContain("raw="); + expect(responseLog?.length).toBeLessThan(4200); + }); + + it("logs provider errors without leaking API keys", async () => { + const infoSpy = vi.spyOn(console, "info").mockImplementation(() => {}); + const errorSpy = vi.spyOn(console, "error").mockImplementation(() => {}); + process.env.LLM_PROVIDER = "deepseek"; + process.env.DEEPSEEK_API_KEY = "super-secret-key"; + client.setChatCompletionForTesting(async () => { + throw new Error("upstream unavailable"); + }); + + await expect( + client.generateJson({ + prompt: "Return JSON.", + task: "quality_inspector", + }), + ).rejects.toThrow("LLM provider error: upstream unavailable"); + + expect(infoSpy).toHaveBeenCalledWith( + "[llm:start] provider=deepseek model=deepseek-v4-pro task=quality_inspector", + ); + const errorLog = errorSpy.mock.calls.map((call) => call[0]).join("\n"); + expect(errorLog).toContain("[llm:error] task=quality_inspector"); + expect(errorLog).not.toContain("super-secret-key"); + }); }); diff --git a/src/lib/llm/client.ts b/src/lib/llm/client.ts index a3e7bea..6d71e7b 100644 --- a/src/lib/llm/client.ts +++ b/src/lib/llm/client.ts @@ -6,6 +6,7 @@ export interface GenerateInput { prompt: string; model?: string; temperature?: number; + task?: string; } export interface GenerateValidatedJsonInput extends GenerateInput { @@ -51,6 +52,51 @@ export function isLlmConfigured() { return getLlmProviderStatus().configured; } +interface ChatCompletionResult { + choices: Array<{ message: { content?: string | null } }>; +} + +type ChatCompletionRequest = { + model: string; + temperature: number; + response_format?: { type: "json_object" }; + messages: Array<{ role: "system" | "user"; content: string }>; +}; + +let chatCompletionForTesting: + | ((request: ChatCompletionRequest) => Promise) + | null = null; + +export function setChatCompletionForTesting( + handler: ((request: ChatCompletionRequest) => Promise) | null, +) { + chatCompletionForTesting = handler; +} + +function getTask(input: GenerateInput) { + return input.task?.trim() || "unknown"; +} + +function truncateRaw(value: string, maxLength = 4000) { + return value.length > maxLength + ? `${value.slice(0, maxLength)}...[truncated ${value.length - maxLength} chars]` + : value; +} + +function summarizeZodError(error: z.ZodError) { + return error.issues + .slice(0, 5) + .map((issue) => { + const path = issue.path.length > 0 ? issue.path.join(".") : ""; + return `${path}: ${issue.message}`; + }) + .join("; "); +} + +function quoteLogValue(value: string) { + return JSON.stringify(value); +} + function createClient() { const status = getLlmProviderStatus(); @@ -93,21 +139,40 @@ export async function generateText(input: GenerateInput) { } export async function generateJson(input: GenerateInput): Promise { + const task = getTask(input); + const startedAt = Date.now(); try { - const { client, model } = createClient(); - const response = await client.chat.completions.create({ - model: input.model ?? model, + 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) { - throw normalizeLlmError(error); + const normalized = normalizeLlmError(error); + console.error( + `[llm:error] task=${task} duration_ms=${Date.now() - startedAt} message=${quoteLogValue(normalized.message)}`, + ); + throw normalized; } } @@ -124,14 +189,25 @@ export async function generateValidatedJson({ schema, ...input }: GenerateValidatedJsonInput): Promise { + const task = getTask(input); if (!isLlmConfigured()) { + console.info(`[llm:validated] task=${task} ok=false reason=not_configured`); return null; } try { const generated = await generateJsonForValidation(input); - return schema.parse(generated); + const parsed = schema.safeParse(generated); + if (parsed.success) { + console.info(`[llm:validated] task=${task} ok=true`); + return parsed.data; + } + console.warn( + `[llm:validated] task=${task} ok=false zod_error=${quoteLogValue(summarizeZodError(parsed.error))}`, + ); + return null; } catch { + console.info(`[llm:validated] task=${task} ok=false reason=provider_error`); return null; } }