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;
}
});