diff --git a/apps/portal/src/components/LogViewer.tsx b/apps/portal/src/components/LogViewer.tsx index e784a9b4f..8e4708cb6 100644 --- a/apps/portal/src/components/LogViewer.tsx +++ b/apps/portal/src/components/LogViewer.tsx @@ -119,6 +119,14 @@ export function LogViewer({ [{log.source}] )} {log.message} + {log.data && Object.keys(log.data).filter(k => k !== "iteration" && k !== "final").length > 0 && ( + + {Object.entries(log.data) + .filter(([k]) => k !== "iteration" && k !== "final") + .map(([k, v]) => `${k}=${typeof v === "object" ? JSON.stringify(v) : v}`) + .join(" ")} + + )} ); diff --git a/apps/workers/report-generator/src/report-queue-processor.test.ts b/apps/workers/report-generator/src/report-queue-processor.test.ts new file mode 100644 index 000000000..61d6c92c8 --- /dev/null +++ b/apps/workers/report-generator/src/report-queue-processor.test.ts @@ -0,0 +1,365 @@ +// Copyright (c) Microsoft Corporation. +// Licensed under the MIT License. + +import { describe, it, expect, vi, beforeEach, afterEach } from "vitest"; +import type { SessionEvent } from "@github/copilot-sdk"; + +// --------------------------------------------------------------------------- +// Mocks – must be declared before importing the module under test +// --------------------------------------------------------------------------- + +/** Captured session.on handler so tests can fire synthetic events */ +let capturedEventHandler: ((event: SessionEvent) => void) | undefined; + +const mockSendAndWait = vi.fn().mockResolvedValue(undefined); +const mockSessionOn = vi.fn((handler: (event: SessionEvent) => void) => { + capturedEventHandler = handler; + return () => {}; +}); +const mockCreateSession = vi.fn().mockResolvedValue({ + on: mockSessionOn, + sendAndWait: mockSendAndWait, +}); +const mockClientStop = vi.fn().mockResolvedValue([]); + +vi.mock("@github/copilot-sdk", () => { + class StubCopilotClient { + createSession = mockCreateSession; + stop = mockClientStop; + } + return { CopilotClient: StubCopilotClient }; +}); + +vi.mock("shared", () => { + // Minimal stub of BaseQueueProcessor – only what the constructor needs + class StubBaseQueueProcessor { + protected collection = { updateOne: vi.fn().mockResolvedValue({}) }; + constructor() {} + protected safeDeleteMessage = vi.fn().mockResolvedValue(undefined); + } + class StubTokenManagerClient { + acquireToken = vi.fn().mockResolvedValue("fake-token"); + } + return { + BaseQueueProcessor: StubBaseQueueProcessor, + TokenManagerClient: StubTokenManagerClient, + }; +}); + +vi.mock("./tools.js", () => ({ + createReportTools: vi.fn(() => []), +})); + +vi.mock("./prompt.js", () => ({ + REPORT_SYSTEM_PROMPT: "You are a test prompt.", +})); + +vi.mock("fs", () => ({ + mkdirSync: vi.fn(), + rmSync: vi.fn(), + existsSync: vi.fn(() => false), + readFileSync: vi.fn(() => '{"version":"0.0.0-test"}'), +})); + +vi.mock("os", () => ({ + tmpdir: vi.fn(() => "/tmp"), +})); + +import { ReportQueueProcessor } from "./report-queue-processor.js"; + +// --------------------------------------------------------------------------- +// Helpers +// --------------------------------------------------------------------------- + +function makeConfig() { + return { + reportModel: "gpt-4.1", + apiBaseUrl: "http://localhost:3000", + sessionTimeoutMs: 5000, + // BaseQueueProcessor plumbing – values don't matter for these tests + queueName: "report-queue", + connectionString: "DefaultEndpointsProtocol=https;AccountName=fake", + mongoUri: "mongodb://localhost:27017", + mongoDb: "test", + collectionName: "reports", + } as any; +} + +/** + * Access the private `runCopilotSession` method via type escape. + * This lets us test event-handler behaviour in isolation. + */ +async function callRunCopilotSession( + processor: ReportQueueProcessor, + log: ReturnType, +) { + return (processor as any).runCopilotSession([], "req-123", log); +} + +function makeBaseEvent(type: string, data: Record = {}): SessionEvent { + return { + id: "evt-1", + timestamp: new Date().toISOString(), + parentId: null, + type, + data, + } as unknown as SessionEvent; +} + +// --------------------------------------------------------------------------- +// Tests +// --------------------------------------------------------------------------- + +describe("ReportQueueProcessor – session event logging", () => { + let processor: ReportQueueProcessor; + let log: ReturnType; + + beforeEach(() => { + capturedEventHandler = undefined; + log = vi.fn().mockResolvedValue(undefined); + processor = new ReportQueueProcessor(makeConfig()); + + // Ensure sendAndWait triggers captured handler with a delta so response is non-empty + mockSendAndWait.mockImplementation(async () => { + if (capturedEventHandler) { + capturedEventHandler(makeBaseEvent("assistant.message_delta", { + messageId: "m1", + deltaContent: "Report content goes here.", + })); + } + return undefined; + }); + }); + + afterEach(() => { + vi.restoreAllMocks(); + }); + + it("logs 'Acquired Copilot SDK token' before creating a session", async () => { + await callRunCopilotSession(processor, log); + + expect(log).toHaveBeenCalledWith("info", "Acquired Copilot SDK token"); + }); + + it("logs session.start events with sessionId and model", async () => { + mockSendAndWait.mockImplementation(async () => { + capturedEventHandler!(makeBaseEvent("session.start", { + sessionId: "sess-42", + selectedModel: "gpt-4.1", + version: 1, + producer: "test", + copilotVersion: "1.0", + startTime: new Date().toISOString(), + })); + // Need non-empty response + capturedEventHandler!(makeBaseEvent("assistant.message_delta", { + messageId: "m1", + deltaContent: "ok", + })); + }); + + await callRunCopilotSession(processor, log); + + expect(log).toHaveBeenCalledWith("info", "Copilot session started", { + sessionId: "sess-42", + model: "gpt-4.1", + }); + }); + + it("logs session.error events at error level", async () => { + mockSendAndWait.mockImplementation(async () => { + capturedEventHandler!(makeBaseEvent("session.error", { + errorType: "rate_limit", + message: "Rate limit exceeded", + })); + capturedEventHandler!(makeBaseEvent("assistant.message_delta", { + messageId: "m1", + deltaContent: "partial", + })); + }); + + await callRunCopilotSession(processor, log); + + expect(log).toHaveBeenCalledWith("error", "Session error: Rate limit exceeded", { + errorType: "rate_limit", + }); + }); + + it("logs session.info events", async () => { + mockSendAndWait.mockImplementation(async () => { + capturedEventHandler!(makeBaseEvent("session.info", { + infoType: "general", + message: "Model switched", + })); + capturedEventHandler!(makeBaseEvent("assistant.message_delta", { + messageId: "m1", + deltaContent: "content", + })); + }); + + await callRunCopilotSession(processor, log); + + expect(log).toHaveBeenCalledWith("info", "Session: Model switched"); + }); + + it("logs assistant.turn_start and assistant.turn_end", async () => { + mockSendAndWait.mockImplementation(async () => { + capturedEventHandler!(makeBaseEvent("assistant.turn_start", { turnId: "t1" })); + capturedEventHandler!(makeBaseEvent("assistant.message_delta", { + messageId: "m1", + deltaContent: "text", + })); + capturedEventHandler!(makeBaseEvent("assistant.turn_end", { turnId: "t1" })); + }); + + await callRunCopilotSession(processor, log); + + expect(log).toHaveBeenCalledWith("info", "Assistant turn started", { turnId: "t1" }); + expect(log).toHaveBeenCalledWith("info", "Assistant turn ended", { turnId: "t1" }); + }); + + it("logs tool.execution_start with tool name and arguments", async () => { + mockSendAndWait.mockImplementation(async () => { + capturedEventHandler!(makeBaseEvent("tool.execution_start", { + toolCallId: "tc-1", + toolName: "get_run_summary", + arguments: { foo: "bar" }, + })); + capturedEventHandler!(makeBaseEvent("tool.execution_complete", { + toolCallId: "tc-1", + success: true, + })); + capturedEventHandler!(makeBaseEvent("assistant.message_delta", { + messageId: "m1", + deltaContent: "done", + })); + }); + + await callRunCopilotSession(processor, log); + + expect(log).toHaveBeenCalledWith("info", "Tool call: get_run_summary", { + toolCallId: "tc-1", + arguments: { foo: "bar" }, + }); + }); + + it("logs tool.execution_complete with success status", async () => { + mockSendAndWait.mockImplementation(async () => { + capturedEventHandler!(makeBaseEvent("tool.execution_start", { + toolCallId: "tc-2", + toolName: "list_turns", + })); + capturedEventHandler!(makeBaseEvent("tool.execution_complete", { + toolCallId: "tc-2", + success: true, + })); + capturedEventHandler!(makeBaseEvent("assistant.message_delta", { + messageId: "m1", + deltaContent: "result", + })); + }); + + await callRunCopilotSession(processor, log); + + expect(log).toHaveBeenCalledWith("info", "Tool result: list_turns (success)", { + toolCallId: "tc-2", + }); + }); + + it("logs tool.execution_complete with failure and error message", async () => { + mockSendAndWait.mockImplementation(async () => { + capturedEventHandler!(makeBaseEvent("tool.execution_start", { + toolCallId: "tc-3", + toolName: "extract_snapshot", + })); + capturedEventHandler!(makeBaseEvent("tool.execution_complete", { + toolCallId: "tc-3", + success: false, + error: { message: "Not found", code: "404" }, + })); + capturedEventHandler!(makeBaseEvent("assistant.message_delta", { + messageId: "m1", + deltaContent: "fallback", + })); + }); + + await callRunCopilotSession(processor, log); + + expect(log).toHaveBeenCalledWith("info", "Tool result: extract_snapshot (failed)", { + toolCallId: "tc-3", + error: "Not found", + }); + }); + + it("logs unknown tool name as 'unknown' when no matching start event", async () => { + mockSendAndWait.mockImplementation(async () => { + // Complete event without a preceding start event + capturedEventHandler!(makeBaseEvent("tool.execution_complete", { + toolCallId: "tc-orphan", + success: true, + })); + capturedEventHandler!(makeBaseEvent("assistant.message_delta", { + messageId: "m1", + deltaContent: "ok", + })); + }); + + await callRunCopilotSession(processor, log); + + expect(log).toHaveBeenCalledWith("info", "Tool result: unknown (success)", { + toolCallId: "tc-orphan", + }); + }); + + it("throttles delta progress logs to every ~2000 chars", async () => { + mockSendAndWait.mockImplementation(async () => { + // Send many small deltas totalling ~5000 chars + const chunk = "x".repeat(500); + for (let i = 0; i < 10; i++) { + capturedEventHandler!(makeBaseEvent("assistant.message_delta", { + messageId: "m1", + deltaContent: chunk, + })); + } + }); + + await callRunCopilotSession(processor, log); + + // Should get progress logs at ~2000, ~4000 chars (2 progress logs) + const progressCalls = log.mock.calls.filter( + (call: unknown[]) => + typeof call[1] === "string" && (call[1] as string).includes("chars so far"), + ); + expect(progressCalls.length).toBe(2); + expect(progressCalls[0][1]).toContain("2000"); + expect(progressCalls[1][1]).toContain("4000"); + }); + + it("does not log delta progress for small responses", async () => { + // Default mock sends 25 chars, well under 2000 threshold + await callRunCopilotSession(processor, log); + + const progressCalls = log.mock.calls.filter( + (call: unknown[]) => + typeof call[1] === "string" && (call[1] as string).includes("chars so far"), + ); + expect(progressCalls.length).toBe(0); + }); + + it("throws when Copilot SDK returns empty response", async () => { + mockSendAndWait.mockImplementation(async () => { + // No delta events → empty response + }); + + await expect(callRunCopilotSession(processor, log)).rejects.toThrow( + "Copilot SDK returned an empty response", + ); + }); + + it("calls client.stop() even if session throws", async () => { + mockSendAndWait.mockRejectedValue(new Error("session boom")); + + await expect(callRunCopilotSession(processor, log)).rejects.toThrow("session boom"); + expect(mockClientStop).toHaveBeenCalled(); + }); +}); diff --git a/apps/workers/report-generator/src/report-queue-processor.ts b/apps/workers/report-generator/src/report-queue-processor.ts index 05506aee4..e4dc5490e 100644 --- a/apps/workers/report-generator/src/report-queue-processor.ts +++ b/apps/workers/report-generator/src/report-queue-processor.ts @@ -135,9 +135,14 @@ export class ReportQueueProcessor extends BaseQueueProcessor { await this.safeDeleteMessage(message.messageId, currentPopReceipt); } + /** Char-count interval for emitting delta progress logs */ + private static readonly DELTA_LOG_INTERVAL = 2000; + /** * Run a Copilot SDK session with the report tools and system prompt. - * Streams response deltas and logs progress. + * Streams response deltas and logs progress. Forwards key + * {@link SessionEvent} types to `log()` so the portal can display + * real-time progress on the Logs tab. */ private async runCopilotSession( tools: ReturnType, @@ -145,8 +150,14 @@ export class ReportQueueProcessor extends BaseQueueProcessor { log: (level: LogEvent["level"], msg: string, data?: Record) => Promise ): Promise { const githubToken = await this.tokenClient.acquireToken("copilot-sdk"); + await log("info", "Acquired Copilot SDK token"); + const client = new CopilotClient({ githubToken }); let fullResponse = ""; + let lastLoggedCharCount = 0; + + // Track in-flight tool names so we can pair start/complete events + const toolNames = new Map(); try { const session = await client.createSession({ @@ -156,10 +167,71 @@ export class ReportQueueProcessor extends BaseQueueProcessor { systemMessage: { mode: "replace", content: REPORT_SYSTEM_PROMPT }, }); - // Accumulate streamed response + // Forward session events to structured log session.on((event: SessionEvent) => { - if (event.type === "assistant.message_delta") { - fullResponse += event.data.deltaContent; + switch (event.type) { + // --- Session lifecycle --- + case "session.start": + void log("info", "Copilot session started", { + sessionId: event.data.sessionId, + model: event.data.selectedModel, + }); + break; + + case "session.error": + void log("error", `Session error: ${event.data.message}`, { + errorType: event.data.errorType, + }); + break; + + case "session.info": + void log("info", `Session: ${event.data.message}`); + break; + + // --- Assistant turns --- + case "assistant.turn_start": + void log("info", "Assistant turn started", { + turnId: event.data.turnId, + }); + break; + + case "assistant.turn_end": + void log("info", "Assistant turn ended", { + turnId: event.data.turnId, + }); + break; + + // --- Tool calls --- + case "tool.execution_start": + toolNames.set(event.data.toolCallId, event.data.toolName); + void log("info", `Tool call: ${event.data.toolName}`, { + toolCallId: event.data.toolCallId, + arguments: event.data.arguments as Record | undefined, + }); + break; + + case "tool.execution_complete": { + const name = toolNames.get(event.data.toolCallId) ?? "unknown"; + toolNames.delete(event.data.toolCallId); + const status = event.data.success ? "success" : "failed"; + const extra: Record = { toolCallId: event.data.toolCallId }; + if (event.data.error) { + extra.error = event.data.error.message; + } + void log("info", `Tool result: ${name} (${status})`, extra); + break; + } + + // --- Streamed response --- + case "assistant.message_delta": + fullResponse += event.data.deltaContent; + + // Emit periodic progress logs (throttled by char count) + if (fullResponse.length - lastLoggedCharCount >= ReportQueueProcessor.DELTA_LOG_INTERVAL) { + lastLoggedCharCount = fullResponse.length; + void log("info", `Generating report… (${fullResponse.length} chars so far)`); + } + break; } });