diff --git a/src/lib/llm/__tests__/client.test.ts b/src/lib/llm/__tests__/client.test.ts index 4dd36e3..ca8d6e2 100644 --- a/src/lib/llm/__tests__/client.test.ts +++ b/src/lib/llm/__tests__/client.test.ts @@ -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", () => { diff --git a/src/lib/llm/client.ts b/src/lib/llm/client.ts index 6d71e7b..2e51ec3 100644 --- a/src/lib/llm/client.ts +++ b/src/lib/llm/client.ts @@ -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 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({ 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(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({ `[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; } }