fix(providers): add redacted WS debug logging to copilot-m365-web (#6210) (#6447)

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)

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<ReadableStream<Uint8Array>> {
+    // #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<Uint8Array>(
       {
         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 {

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<Record<string, unknown>>, captured: { url?: string }) {
+  return class FakeWS {
+    private handlers: Record<string, (arg?: unknown) => 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<void> {
+  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}`
+    );
+  }
+});