feat: add central llm runtime logging

2026-06-21 23:43:02 +08:00
parent f017ce1bba
commit 9416d81e80
2 changed files with 202 additions and 26 deletions
@@ -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");
+  });
 });
@@ -6,6 +6,7 @@ export interface GenerateInput {
  prompt: string;
  model?: string;
  temperature?: number;
+  task?: string;
 }

 export interface GenerateValidatedJsonInput<T> 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<ChatCompletionResult>)
+  | null = null;
+
+export function setChatCompletionForTesting(
+  handler: ((request: ChatCompletionRequest) => Promise<ChatCompletionResult>) | 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(".") : "<root>";
+      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<T>(input: GenerateInput): Promise<T> {
+  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<T>({
  schema,
  ...input
 }: GenerateValidatedJsonInput<T>): Promise<T | null> {
+  const task = getTask(input);
  if (!isLlmConfigured()) {
+    console.info(`[llm:validated] task=${task} ok=false reason=not_configured`);
    return null;
  }

  try {
    const generated = await generateJsonForValidation<unknown>(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;
  }
 }