From 53aa6d9716ccc5e19ead6067f0097b32e947ebe7 Mon Sep 17 00:00:00 2001 From: Diego Rodrigues de Sa e Souza <8016841+diegosouzapw@users.noreply.github.com> Date: Mon, 6 Jul 2026 18:16:22 -0300 Subject: [PATCH] fix(providers): add redacted WS debug logging to copilot-m365-web (#6210) (#6447) --- CHANGELOG.md | 2 + open-sse/executors/copilot-m365-web.ts | 27 +++- .../copilot-m365-web-logging-6210.test.ts | 140 ++++++++++++++++++ 3 files changed, 167 insertions(+), 2 deletions(-) create mode 100644 tests/unit/copilot-m365-web-logging-6210.test.ts diff --git a/CHANGELOG.md b/CHANGELOG.md index c558d4ee90..9f4eb4cf1f 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -21,6 +21,8 @@ ### 🐛 Bug Fixes +- **fix(providers):** the `copilot-m365-web` streaming executor now emits `debug`-level WebSocket diagnostics ([#6210](https://github.com/diegosouzapw/OmniRoute/issues/6210)) — the outbound WS URL (with the `access_token` **redacted** via `redactWsUrl()`), handshake success/failure, and each received SignalR frame's `type`/`target`. Previously the streaming path logged nothing, so an empty `content:null` response (the M365 Education / Starter tier symptom fixed in #6234) was undiagnosable even at `APP_LOG_LEVEL=debug`. The change is debug-level and side-effect-free — it does not alter streaming behavior or the frame parser, and the token never reaches the logs. Regression guard: `tests/unit/copilot-m365-web-logging-6210.test.ts` (thanks @qpeyba) + - **fix(resilience):** a round-robin combo no longer returns `503 all upstream accounts are unavailable` when a compatibility-rejected target is actually healthy ([#6238](https://github.com/diegosouzapw/OmniRoute/issues/6238)). `filterTargetsByRequestCompatibility` drops request-incompatible targets (tool/vision/structured-output unsupported, or below the required context window) **before** any availability check runs, and its `compatible.length === 0` safety net only fired when *all* targets were filtered — not when the kept targets later all turned out runtime-unavailable (circuit-open / cooldown / no credentials). So a combo could 503 while a compat-rejected-but-healthy provider sat unused. `handleRoundRobinCombo` now keeps the compat-rejected set and, when every compat-kept target was skipped without a single real attempt, probes those rejected targets as a **last-resort fallback tier** (via the new pure `open-sse/services/combo/comboCompatFallback.ts`) before crystallizing the 503. Regression guard: `tests/unit/combo-roundrobin-compat-fallback-6238.test.ts`. (thanks @ThongAccount) - **fix(startup):** best-effort self-heal for a corrupted Turbopack dev cache on Windows ([#6289](https://github.com/diegosouzapw/OmniRoute/issues/6289)). On Windows, `pnpm dev` can fail at startup when Turbopack `mmap`s a persistent-cache SST file and the OS refuses the mapping (`os error 1455` — "paging file too small"), which Turbopack surfaces as a misleading `Module not found: Can't resolve '@/shared/utils/machine'`. This is a **known upstream Turbopack cache-corruption bug — not our code**. The dev launcher (`scripts/dev/run-next.mjs`) now wraps `nextApp.prepare()` and, when it rejects with that signature (`isTurbopackCacheCorruption` in the new `scripts/dev/turbopackCacheHeal.mjs`), purges `.build/next/**/cache/turbopack` and retries **once** with a clear log. **Caveat — best-effort only:** the corruption often surfaces as a runtime overlay rather than a `prepare()` rejection, so this cannot always intercept it; the reliable remedy remains manually deleting the Turbopack cache dir. Regression guard: `tests/unit/turbopack-cache-heal-6289.test.ts`. (thanks @chirag127) diff --git a/open-sse/executors/copilot-m365-web.ts b/open-sse/executors/copilot-m365-web.ts index 890e3bf9f0..4a850a9804 100644 --- a/open-sse/executors/copilot-m365-web.ts +++ b/open-sse/executors/copilot-m365-web.ts @@ -1,7 +1,7 @@ import WebSocket from "ws"; import { FETCH_TIMEOUT_MS } from "../config/constants.ts"; import { sanitizeErrorMessage } from "../utils/error.ts"; -import { BaseExecutor, type ExecuteInput } from "./base.ts"; +import { BaseExecutor, type ExecuteInput, type ExecutorLog } from "./base.ts"; import { buildPrompt, buildWsUrl, @@ -59,7 +59,11 @@ export class CopilotM365WebExecutor extends BaseExecutor { prompt: string; model: string; signal?: AbortSignal; + log?: ExecutorLog | null; }): Promise> { + // #6210 — observability for the empty-response class. The access_token rides + // in the WS query string, so every URL logged here goes through redactWsUrl(). + const log = input.log ?? null; return new ReadableStream( { start: async (controller) => { @@ -119,6 +123,8 @@ export class CopilotM365WebExecutor extends BaseExecutor { const traceId = wsUrlParts.searchParams.get("clientrequestid") ?? crypto.randomUUID().replace(/-/g, ""); const sessionId = wsUrlParts.searchParams.get("X-SessionId") ?? crypto.randomUUID(); + log?.debug?.("M365_WS", `connecting → ${redactWsUrl(input.wsUrl)}`); + ws = new WebSocketCtor(input.wsUrl, { headers: { Origin: "https://m365.cloud.microsoft", @@ -142,6 +148,7 @@ export class CopilotM365WebExecutor extends BaseExecutor { }; ws.on("open", () => { + log?.debug?.("M365_WS", "socket open — sending handshake"); ws?.send(handshakeFrame()); }); @@ -153,14 +160,20 @@ export class CopilotM365WebExecutor extends BaseExecutor { for (const rawFrame of split.frames) { const frame = parseFrame(rawFrame); + log?.debug?.( + "M365_WS", + `frame type=${String(frame?.type)} target=${String(frame?.target)}` + ); if (!handshakeComplete) { const err = handshakeError(frame); if (err) { clearTimeout(timeout); + log?.debug?.("M365_WS", `handshake failed: ${err}`); abort(`Microsoft 365 Copilot handshake failed: ${err}`); return; } handshakeComplete = true; + log?.debug?.("M365_WS", "handshake complete — sending chat invocation"); sendChat(); continue; } @@ -186,6 +199,10 @@ export class CopilotM365WebExecutor extends BaseExecutor { ws.on("error", (err) => { clearTimeout(timeout); + log?.debug?.( + "M365_WS", + `socket error: ${err instanceof Error ? err.message : String(err)}` + ); abort( sanitizeErrorMessage( err instanceof Error ? err.message : "Microsoft 365 Copilot WebSocket error" @@ -244,7 +261,13 @@ export class CopilotM365WebExecutor extends BaseExecutor { const wsUrl = buildWsUrl(connectionParams); try { - const wsStream = await this.wsChat({ wsUrl, prompt, model, signal: input.signal ?? undefined }); + const wsStream = await this.wsChat({ + wsUrl, + prompt, + model, + signal: input.signal ?? undefined, + log: input.log, + }); if (stream) { return { diff --git a/tests/unit/copilot-m365-web-logging-6210.test.ts b/tests/unit/copilot-m365-web-logging-6210.test.ts new file mode 100644 index 0000000000..aa98106db6 --- /dev/null +++ b/tests/unit/copilot-m365-web-logging-6210.test.ts @@ -0,0 +1,140 @@ +/** + * Regression test for #6210 (observability follow-up) — copilot-m365-web streaming + * path emitted NO logs, so an empty `content:null` response was undiagnosable even at + * `APP_LOG_LEVEL=debug`. The tier parser itself was fixed in #6234; this guards the + * remaining defect: the WS path must emit debug diagnostics (connect / handshake / + * per-frame) AND must never leak the access_token that rides in the WS query string. + * + * The stub drives the executor with a scripted SignalR frame sequence (handshake ack → + * bot update → completion) and a captured `log`, asserting (a) a debug log fires for the + * handshake / first frame and (b) the logged connect URL is redacted — the raw URL handed + * to the WebSocket constructor still carries the secret, proving redaction is real. + */ +import test from "node:test"; +import assert from "node:assert/strict"; +import { + CopilotM365WebExecutor, + __setCopilotM365WebSocketForTesting, +} from "../../open-sse/executors/copilot-m365-web.ts"; +import { encodeFrame } from "../../open-sse/executors/copilot-m365-frames.ts"; +import type { ExecutorLog } from "../../open-sse/executors/base.ts"; + +const SECRET = "SUPERSECRETTOKEN-do-not-log-123"; + +type LogEntry = { level: string; tag: string; message: string }; + +function makeCapturingLog(sink: LogEntry[]): ExecutorLog { + const push = (level: string) => (tag: string, message: string) => + sink.push({ level, tag, message }); + return { debug: push("debug"), info: push("info"), warn: push("warn"), error: push("error") }; +} + +/** + * Minimal `ws`-shaped stub: emits `open` on next tick, answers the handshake request + * frame with `{}` (ack), and once the chat invocation is sent replays `frames`. + */ +function makeFakeWsCtor(frames: Array>, captured: { url?: string }) { + return class FakeWS { + private handlers: Record void> = {}; + constructor(url: string) { + captured.url = url; + setImmediate(() => this.handlers.open?.()); + } + on(event: string, cb: (arg?: unknown) => void) { + this.handlers[event] = cb; + return this; + } + send(data: unknown) { + const str = typeof data === "string" ? data : String(data); + if (str.includes('"protocol":"json"')) { + setImmediate(() => this.handlers.message?.(Buffer.from(encodeFrame({})))); + } else if (str.includes('"target":"chat"')) { + setImmediate(() => { + for (const frame of frames) this.handlers.message?.(Buffer.from(encodeFrame(frame))); + }); + } + } + close() { + /* no-op */ + } + }; +} + +async function drainStream(executor: CopilotM365WebExecutor, log: ExecutorLog): Promise { + const { response } = await executor.execute({ + model: "copilot-m365", + body: { messages: [{ role: "user", content: "hi" }] }, + stream: true, + credentials: { + apiKey: `access_token=${SECRET}`, + providerSpecificData: { chathubPath: "user-oid@tenant-id" }, + }, + log, + }); + await response.text(); +} + +test("copilot-m365-web: WS path emits debug logs for handshake + first frame [#6210]", async () => { + const captured: { url?: string } = {}; + const frames = [ + { type: 1, target: "update", arguments: [{ messages: [{ text: "Hi there", author: "bot" }] }] }, + { type: 3 }, + ]; + const restore = __setCopilotM365WebSocketForTesting( + makeFakeWsCtor(frames, captured) as never + ); + const sink: LogEntry[] = []; + try { + await drainStream(new CopilotM365WebExecutor(), makeCapturingLog(sink)); + } finally { + restore(); + } + + const wsLogs = sink.filter((e) => e.level === "debug" && e.tag === "M365_WS"); + assert.ok(wsLogs.length > 0, "expected at least one M365_WS debug log"); + // (a) handshake is logged. + assert.ok( + wsLogs.some((e) => /handshake complete/i.test(e.message)), + "expected a handshake-complete debug log" + ); + // (a) the first received frame's type/target is logged. + assert.ok( + wsLogs.some((e) => e.message.includes("frame type=1 target=update")), + "expected a per-frame type/target debug log for the first update frame" + ); +}); + +test("copilot-m365-web: logged WS URL is redacted — access_token never leaks [#6210]", async () => { + const captured: { url?: string } = {}; + const frames = [{ type: 3 }]; + const restore = __setCopilotM365WebSocketForTesting( + makeFakeWsCtor(frames, captured) as never + ); + const sink: LogEntry[] = []; + try { + await drainStream(new CopilotM365WebExecutor(), makeCapturingLog(sink)); + } finally { + restore(); + } + + // The raw URL handed to the WebSocket constructor DOES carry the secret — proving the + // redaction assertion below would fail on an un-redacted URL and passes only because + // the executor redacts before logging. + assert.ok(captured.url?.includes(SECRET), "sanity: raw WS URL should contain the token"); + + const connectLog = sink.find( + (e) => e.tag === "M365_WS" && e.message.startsWith("connecting") + ); + assert.ok(connectLog, "expected a 'connecting' debug log"); + assert.ok( + connectLog.message.includes("access_token=REDACTED"), + "connect log should show the token as REDACTED" + ); + // (b) NO logged message anywhere may contain the raw secret. + for (const entry of sink) { + assert.ok( + !entry.message.includes(SECRET), + `log leaked the access_token: ${entry.tag} ${entry.message}` + ); + } +});