test(client): debuggability with console logging

- log extra error from test process to console without mocha redirection
- use FLUID_TEST_VERBOSE to control child logging that now optional outputs messaging and select telemetry

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.
+ */
+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();
@@ -189,12 +211,14 @@ export async function connectAndWaitForAttendees(
 		});
 	});
 	const connectResult = await connectChildProcesses(children, 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;
 }