fix(teams-meetings): keep setup probes within deadline (#111455)

* origin/pr/111455:
  fix(meeting-bot): dedupe prerequisite command probes
  fix(meetings): classify profiler timeouts
  fix(meetings): report prerequisite deadline timeouts
  fix(teams-meetings): keep setup probes within deadline

extensions/teams-meetings/src/node-host.test.ts

@@ -0,0 +1,105 @@
+import { afterEach, beforeEach, describe, expect, it, vi } from "vitest";
+
+const spawnSyncMock = vi.hoisted(() => vi.fn());
+
+vi.mock("node:child_process", async (importOriginal) => {
+  const actual = await importOriginal<typeof import("node:child_process")>();
+  return { ...actual, spawnSync: spawnSyncMock };
+});
+
+import { teamsMeetingsConfig } from "./config.js";
+import { handleTeamsMeetingsNodeHostCommand } from "./node-host.js";
+
+const successfulProbe = {
+  pid: 123,
+  output: [null, "BlackHole 2ch", ""],
+  stdout: "BlackHole 2ch",
+  stderr: "",
+  status: 0,
+  signal: null,
+  error: undefined,
+};
+
+function setupParams() {
+  return JSON.stringify({
+    action: "setup",
+    audioInputCommand: ["capture"],
+    audioOutputCommand: ["play"],
+  });
+}
+
+describe("Teams meeting node-host prerequisite deadline", () => {
+  beforeEach(() => {
+    vi.spyOn(process, "platform", "get").mockReturnValue("darwin");
+    spawnSyncMock.mockReset();
+    spawnSyncMock.mockReturnValue(successfulProbe);
+  });
+
+  afterEach(() => {
+    vi.restoreAllMocks();
+  });
+
+  it("shares one timeout budget across every prerequisite probe", async () => {
+    const now = vi.spyOn(Date, "now");
+    for (const value of [1_000, 1_000, 4_000, 4_000, 8_000, 8_000]) {
+      now.mockReturnValueOnce(value);
+    }
+
+    await expect(handleTeamsMeetingsNodeHostCommand(setupParams())).resolves.toBe(
+      JSON.stringify({ ok: true }),
+    );
+
+    expect(
+      spawnSyncMock.mock.calls.map((call) => (call[2] as { timeout?: number }).timeout),
+    ).toEqual([10_000, 7_000, 3_000]);
+  });
+
+  it("probes the default sox executable only once", async () => {
+    await expect(
+      handleTeamsMeetingsNodeHostCommand(
+        JSON.stringify({
+          action: "setup",
+          audioInputCommand: teamsMeetingsConfig.defaultAudioInputCommand,
+          audioOutputCommand: teamsMeetingsConfig.defaultAudioOutputCommand,
+        }),
+      ),
+    ).resolves.toBe(JSON.stringify({ ok: true }));
+
+    expect(spawnSyncMock).toHaveBeenCalledTimes(2);
+    expect(spawnSyncMock.mock.calls[1]?.[1]).toEqual([
+      "-lc",
+      'command -v "$1" >/dev/null 2>&1',
+      "sh",
+      "sox",
+    ]);
+  });
+
+  it("does not start another probe after the shared deadline expires", async () => {
+    const now = vi.spyOn(Date, "now");
+    for (const value of [1_000, 1_000, 11_000]) {
+      now.mockReturnValueOnce(value);
+    }
+
+    await expect(handleTeamsMeetingsNodeHostCommand(setupParams())).rejects.toThrow(
+      "Microsoft Teams meeting audio prerequisite check timed out on the node.",
+    );
+    expect(spawnSyncMock).toHaveBeenCalledTimes(1);
+  });
+
+  it("reports a timed-out profiler separately from a missing audio device", async () => {
+    const timeoutError = Object.assign(new Error("spawnSync system_profiler ETIMEDOUT"), {
+      code: "ETIMEDOUT",
+    });
+    spawnSyncMock.mockReturnValueOnce({
+      ...successfulProbe,
+      status: null,
+      stdout: "",
+      error: timeoutError,
+    });
+
+    await expect(handleTeamsMeetingsNodeHostCommand(setupParams())).rejects.toThrow(
+      "Microsoft Teams meeting audio prerequisite check timed out on the node.",
+    );
+    expect(spawnSyncMock).toHaveBeenCalledTimes(1);
+  });
+});

extensions/teams-meetings/src/node-host.ts

@@ -9,5 +9,5 @@ export const handleTeamsMeetingsNodeHostCommand =
     meetingLabel: "Microsoft Teams meeting",
     defaultAudioInputCommand: teamsMeetingsConfig.defaultAudioInputCommand,
     defaultAudioOutputCommand: teamsMeetingsConfig.defaultAudioOutputCommand,
-    sharePrerequisiteDeadline: false,
+    sharePrerequisiteDeadline: true,
   });

extensions/zoom-meetings/src/node-host.test.ts

@@ -9,6 +9,7 @@ import { handleZoomMeetingsNodeHostCommand } from "./node-host.js";
 afterEach(() => {
   vi.useRealTimers();
   vi.restoreAllMocks();
+  childProcessMocks.spawnSync.mockReset();
 });
 
 describe("Zoom meetings node setup", () => {
@@ -40,4 +41,28 @@ describe("Zoom meetings node setup", () => {
       ),
     ).toEqual([10_000, 4_000, 2_000]);
   });
+
+  it("reports a timed-out command probe separately from a missing command", async () => {
+    vi.useFakeTimers();
+    vi.setSystemTime(0);
+    vi.spyOn(process, "platform", "get").mockReturnValue("darwin");
+    const timeoutError = Object.assign(new Error("spawnSync /bin/sh ETIMEDOUT"), {
+      code: "ETIMEDOUT",
+    });
+    childProcessMocks.spawnSync
+      .mockReturnValueOnce({ status: 0, stderr: "", stdout: "BlackHole 2ch" })
+      .mockReturnValueOnce({ status: null, stderr: "", stdout: "", error: timeoutError });
+
+    await expect(
+      handleZoomMeetingsNodeHostCommand(
+        JSON.stringify({
+          action: "setup",
+          audioInputCommand: ["sox"],
+          audioOutputCommand: ["play"],
+        }),
+      ),
+    ).rejects.toThrow("Zoom meeting audio prerequisite check timed out on the node.");
+
+    expect(childProcessMocks.spawnSync).toHaveBeenCalledTimes(2);
+  });
 });

src/meeting-bot/node-host.ts

@@ -625,13 +625,20 @@ function readSetupCommand(params: Record<string, unknown>, name: string): string
   return value as string[];
 }
 
+function isSpawnSyncTimeout(error: unknown): boolean {
+  return error instanceof Error && "code" in error && error.code === "ETIMEDOUT";
+}
+
 export function createMeetingConfiguredNodeHost(options: MeetingConfiguredNodeHostOptions) {
-  const commandExists = (command: string, timeoutMs: number): boolean => {
+  const probeCommand = (command: string, timeoutMs: number): "found" | "missing" | "timed-out" => {
     const result = spawnSync("/bin/sh", ["-lc", 'command -v "$1" >/dev/null 2>&1', "sh", command], {
       encoding: "utf8",
       timeout: timeoutMs,
     });
-    return result.status === 0;
+    if (isSpawnSyncTimeout(result.error)) {
+      return "timed-out";
+    }
+    return result.status === 0 ? "found" : "missing";
   };
   const assertAudioAvailable = (
     timeoutMs: number,
@@ -650,6 +657,9 @@ export function createMeetingConfiguredNodeHost(options: MeetingConfiguredNodeHo
       encoding: "utf8",
       timeout: commandTimeout(),
     });
+    if (isSpawnSyncTimeout(result.error)) {
+      throw new Error(`${options.meetingLabel} audio prerequisite check timed out on the node.`);
+    }
     const stderr =
       result.stderr ??
       (result.error
@@ -664,15 +674,25 @@ export function createMeetingConfiguredNodeHost(options: MeetingConfiguredNodeHo
     ) {
       throw new Error("BlackHole 2ch audio device not found on the node.");
     }
+    const commandNames = new Set<string>();
     for (const argv of commands) {
       const command = argv[0];
-      if (
-        !command ||
-        (options.sharePrerequisiteDeadline && Date.now() >= deadline) ||
-        !commandExists(command, commandTimeout())
-      ) {
+      if (!command) {
         throw new Error(`Configured audio command not found on the node: ${command || "<empty>"}`);
       }
+      commandNames.add(command);
+    }
+    for (const command of commandNames) {
+      if (options.sharePrerequisiteDeadline && Date.now() >= deadline) {
+        throw new Error(`${options.meetingLabel} audio prerequisite check timed out on the node.`);
+      }
+      const probeResult = probeCommand(command, commandTimeout());
+      if (probeResult === "timed-out") {
+        throw new Error(`${options.meetingLabel} audio prerequisite check timed out on the node.`);
+      }
+      if (probeResult === "missing") {
+        throw new Error(`Configured audio command not found on the node: ${command}`);
+      }
     }
   };
   const host = createMeetingNodeHost({ ...options, assertAudioAvailable });