test(client): debuggability via console or debugger (#25351)

Console logging updates:
- Log extra error from test process to console without mocha redirection
- Use FLUID_TEST_VERBOSE to control child logging to optionally output
messaging and select telemetry

Under debugger updates:
- For longer test cases, modify that case's timeout without impacting
general timeouts.
- Detect when debugger is attached and alter timeouts to increase by
x1000

Author: jason-ha

packages/service-clients/end-to-end-tests/azure-client/package.json

@@ -35,7 +35,8 @@
 		"test:realsvc:tinylicious": "start-server-and-test start:tinylicious:test 7071 test:realsvc:tinylicious:run",
 		"test:realsvc:tinylicious:report": "npm run test:realsvc:tinylicious",
 		"test:realsvc:tinylicious:run": "npm run test:realsvc:azure:run -- --driver=t9s",
-		"test:realsvc:verbose": "cross-env FLUID_TEST_VERBOSE=1 npm run test:realsvc"
+		"test:realsvc:verbose": "cross-env FLUID_TEST_VERBOSE=msgs npm run test:realsvc",
+		"test:realsvc:veryverbose": "cross-env FLUID_TEST_VERBOSE=msgs+telem npm run test:realsvc"
 	},
 	"c8": {
 		"all": true,

packages/service-clients/end-to-end-tests/azure-client/src/test/multiprocess/childClient.ts

@@ -10,9 +10,11 @@ import {
 	type AzureContainerServices,
 	type AzureLocalConnectionConfig,
 	type AzureRemoteConnectionConfig,
+	type ITelemetryBaseEvent,
 } from "@fluidframework/azure-client";
 import { AttachState } from "@fluidframework/container-definitions";
 import { ConnectionState } from "@fluidframework/container-loader";
+import { LogLevel } from "@fluidframework/core-interfaces";
 import type { ScopeType } from "@fluidframework/driver-definitions/legacy";
 import type { ContainerSchema, IFluidContainer } from "@fluidframework/fluid-static";
 import {
@@ -37,6 +39,7 @@ type MessageToParent = Required<MessageFromChild>;
 const connectTimeoutMs = 10_000;
 // Identifier given to child process
 const process_id = process.argv[2];
+const verbosity = process.argv[3] ?? "";
 
 const useAzure = process.env.FLUID_CLIENT === "azure";
 const tenantId = useAzure
@@ -47,6 +50,24 @@ if (useAzure && endPoint === undefined) {
 	throw new Error("Azure Fluid Relay service endpoint is missing");
 }
 
+function selectiveVerboseLog(event: ITelemetryBaseEvent, logLevel?: LogLevel): void {
+	if (event.eventName.includes(":Signal") || event.eventName.includes(":Join")) {
+		console.log(`[${process_id}] [${logLevel ?? LogLevel.default}]`, {
+			eventName: event.eventName,
+			details: event.details,
+			containerConnectionState: event.containerConnectionState,
+		});
+	} else if (
+		event.eventName.includes(":Container:") ||
+		event.eventName.includes(":Presence:")
+	) {
+		console.log(`[${process_id}] [${logLevel ?? LogLevel.default}]`, {
+			eventName: event.eventName,
+			containerConnectionState: event.containerConnectionState,
+		});
+	}
+}
+
 /**
  * Get or create a Fluid container with Presence in initialObjects.
  */
@@ -81,7 +102,12 @@ const getOrCreatePresenceContainer = async (
 				endpoint: "http://localhost:7071",
 				type: "local",
 			};
-	const client = new AzureClient({ connection: connectionProps });
+	const client = new AzureClient({
+		connection: connectionProps,
+		logger: {
+			send: verbosity.includes("telem") ? selectiveVerboseLog : () => {},
+		},
+	});
 	const schema: ContainerSchema = {
 		initialObjects: {
 			// A DataObject is added as otherwise fluid-static complains "Container cannot be initialized without any DataTypes"
@@ -120,7 +146,14 @@ const getOrCreatePresenceContainer = async (
 };
 function createSendFunction(): (msg: MessageToParent) => void {
 	if (process.send) {
-		return process.send.bind(process);
+		const sendFn = process.send.bind(process);
+		if (verbosity.includes("msgs")) {
+			return (msg: MessageToParent) => {
+				console.log(`[${process_id}] Sending`, msg);
+				sendFn(msg);
+			};
+		}
+		return sendFn;
 	}
 	throw new Error("process.send is not defined");
 }
@@ -262,6 +295,9 @@ class MessageHandler {
 	}
 
 	public async onMessage(msg: MessageFromParent): Promise<void> {
+		if (verbosity.includes("msgs")) {
+			console.log(`[${process_id}] Received`, msg);
+		}
 		switch (msg.command) {
 			case "ping": {
 				this.handlePing();

packages/service-clients/end-to-end-tests/azure-client/src/test/multiprocess/orchestratorUtils.ts

@@ -18,6 +18,27 @@ import type {
 	LatestMapValueGetResponseEvent,
 } from "./messageTypes.js";
 
+/**
+ * Child process to console logging verbosity
+ *
+ * @remarks
+ * Meaningful substrings:
+ * - "msgs"
+ * - "telem"
+ *
+ * @example "msgs+telem"
+ */
+const childLoggingVerbosity = process.env.FLUID_TEST_VERBOSE ?? "none";
+
+/**
+ * Capture console./warn/error before test infrastructure alters it.
+ */
+export const testConsole = {
+	log: console.log,
+	warn: console.warn,
+	error: console.error,
+};
+
 /**
  * Fork child processes to simulate multiple Fluid clients.
  *
@@ -44,7 +65,8 @@ export async function forkChildProcesses(
 	const childErrorPromises: Promise<never>[] = [];
 	for (let i = 0; i < numProcesses; i++) {
 		const child = fork("./lib/test/multiprocess/childClient.js", [
-			`child${i}` /* identifier passed to child process */,
+			`child ${i}` /* identifier passed to child process */,
+			childLoggingVerbosity /* console logging verbosity */,
 		]);
 		cleanUpAccumulator.push(() => {
 			child.kill();
@@ -204,12 +226,14 @@ export async function connectAndWaitForAttendees(
 		writeClients,
 		readyTimeoutMs: childConnectTimeoutMs,
 	});
-	Promise.all(connectResult.attendeeIdPromises).catch((error) => {
-		console.error("Error connecting children:", error);
-	});
+	Promise.all(connectResult.attendeeIdPromises)
+		.then(() => console.log("All attendees connected."))
+		.catch((error) => {
+			testConsole.error("Error connecting children:", error);
+		});
 	await timeoutAwait(Promise.race([attendeeConnectedPromise, earlyExitPromise]), {
 		durationMs: attendeesJoinedTimeoutMs,
-		errorMsg: "did not receive all 'attendeeConnected' events",
+		errorMsg: "child 0 did not receive all 'attendeeConnected' events",
 	});
 	return connectResult;
 }

packages/service-clients/end-to-end-tests/azure-client/src/test/multiprocess/presenceTest.spec.ts

@@ -5,6 +5,7 @@
 
 import { strict as assert } from "node:assert";
 import type { ChildProcess } from "node:child_process";
+import inspector from "node:inspector";
 
 import type { AttendeeId } from "@fluidframework/presence/beta";
 import { timeoutPromise } from "@fluidframework/test-utils/internal";
@@ -14,13 +15,45 @@ import {
 	forkChildProcesses,
 	connectChildProcesses,
 	connectAndWaitForAttendees,
+	getLatestMapValueResponses,
+	getLatestValueResponses,
 	registerWorkspaceOnChildren,
-	waitForLatestValueUpdates,
+	testConsole,
 	waitForLatestMapValueUpdates,
-	getLatestValueResponses,
-	getLatestMapValueResponses,
+	waitForLatestValueUpdates,
 } from "./orchestratorUtils.js";
 
+const debuggerAttached = inspector.url() !== undefined;
+
+/**
+ * Set this to a high number when debugging to avoid timeouts from debugging time.
+ */
+const timeoutMultiplier = debuggerAttached ? 1000 : 1;
+
+/**
+ * Sets the timeout for the given test context.
+ *
+ * @remarks
+ * If a debugger is attached, the timeout is set to 0 to prevent timeouts during debugging.
+ * Otherwise, it sets the timeout to the maximum of the current timeout and the specified duration.
+ *
+ * @param context - The Mocha test context.
+ * @param duration - The duration in milliseconds to set the timeout to. Zero disables the timeout.
+ */
+function setTimeout(context: Mocha.Context, duration: number): void {
+	const currentTimeout = context.timeout();
+	const newTimeout =
+		debuggerAttached || currentTimeout === 0 || duration === 0
+			? 0
+			: Math.max(currentTimeout, duration);
+	if (newTimeout !== currentTimeout) {
+		testConsole.log(
+			`${context.test?.title}: setting timeout to ${newTimeout}ms (was ${currentTimeout}ms)`,
+		);
+		context.timeout(newTimeout);
+	}
+}
+
 /**
  * This test suite is a prototype for a multi-process end to end test for Fluid using the new Presence API on AzureClient.
  * In the future we hope to expand and generalize this pattern to broadly test more Fluid features.
@@ -71,11 +104,11 @@ describe(`Presence with AzureClient`, () => {
 		/**
 		 * Timeout for child processes to connect to container ({@link ConnectedEvent})
 		 */
-		const childConnectTimeoutMs = 1000 * numClients;
+		const childConnectTimeoutMs = 1000 * numClients * timeoutMultiplier;
 		/**
 		 * Timeout for presence attendees to connect {@link AttendeeConnectedEvent}
 		 */
-		const attendeesJoinedTimeoutMs = 2000;
+		const attendeesJoinedTimeoutMs = (1000 + 200 * numClients) * timeoutMultiplier;
 		/**
 		 * Timeout for workspace registration {@link WorkspaceRegisteredEvent}
 		 */
@@ -90,7 +123,9 @@ describe(`Presence with AzureClient`, () => {
 		const getStateTimeoutMs = 5000;
 
 		for (const writeClients of [numClients, 1]) {
-			it(`announces 'attendeeConnected' when remote client joins session [${numClients} clients, ${writeClients} writers]`, async () => {
+			it(`announces 'attendeeConnected' when remote client joins session [${numClients} clients, ${writeClients} writers]`, async function () {
+				setTimeout(this, childConnectTimeoutMs + attendeesJoinedTimeoutMs + 1000);
+
 				// Setup
 				const { children, childErrorPromise } = await forkChildProcesses(
 					numClients,
@@ -118,6 +153,13 @@ describe(`Presence with AzureClient`, () => {
 					this.skip();
 				}
 
+				const childDisconnectTimeoutMs = 10_000 * timeoutMultiplier;
+
+				setTimeout(
+					this,
+					childConnectTimeoutMs + attendeesJoinedTimeoutMs + childDisconnectTimeoutMs + 1000,
+				);
+
 				// Setup
 				const { children, childErrorPromise } = await forkChildProcesses(
 					numClients,
@@ -135,8 +177,6 @@ describe(`Presence with AzureClient`, () => {
 					childErrorPromise,
 				);
 
-				const childDisconnectTimeoutMs = 10_000;
-
 				const waitForDisconnected = children.map(async (child, index) =>
 					index === 0
 						? Promise.resolve()