test(client-azure-end-to-end): fix Azure connect timeouts (microsoft#25781)

allow more time for connecting to real AFR service in Presence tests.

Change from a fixed 10s to dynamic time based on number of clients.

Additionally changes:
- fix `beforeEach` cross contamination from different client counts by
injected a `describe` block within loop body
- output `beforeEach` completion time (otherwise untracked from mocha
output)
- output timestamp under verbose logging
- send along or request and show log if connect times out

Author: jason-ha

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

@@ -40,7 +40,6 @@ import type {
 	EventEntry,
 } from "./messageTypes.js";
 
-const connectTimeoutMs = 10_000;
 const testLabel = process.argv[2];
 // Identifier given to child process
 const process_id = process.argv[3];
@@ -62,6 +61,10 @@ const containerSchema = {
 	},
 } as const satisfies ContainerSchema;
 
+function log(...data: unknown[]): void {
+	console.log(`[${testLabel}] [${new Date().toISOString()}] [${process_id}]`, ...data);
+}
+
 function telemetryEventInterestLevel(eventName: string): "none" | "basic" | "details" {
 	if (eventName.includes(":Signal") || eventName.includes(":Join")) {
 		return "details";
@@ -83,7 +86,7 @@ function selectiveVerboseLog(event: ITelemetryBaseEvent, logLevel?: LogLevel): v
 	if (interest === "details") {
 		content.details = event.details;
 	}
-	console.log(`[${testLabel}] [${process_id}] [${logLevel ?? LogLevel.default}]`, content);
+	log(`[${logLevel ?? LogLevel.default}]`, content);
 }
 
 /**
@@ -96,6 +99,7 @@ const getOrCreateContainer = async (params: {
 	user: UserIdAndName;
 	scopes?: ScopeType[];
 	createScopes?: ScopeType[];
+	connectTimeoutMs: number;
 }): Promise<{
 	container: IFluidContainer<typeof containerSchema>;
 	services: AzureContainerServices;
@@ -105,7 +109,7 @@ const getOrCreateContainer = async (params: {
 }> => {
 	let container: IFluidContainer<typeof containerSchema>;
 	let { containerId } = params;
-	const { logger, onDisconnected, user, scopes, createScopes } = params;
+	const { logger, onDisconnected, user, scopes, createScopes, connectTimeoutMs } = params;
 	const connectionProps: AzureRemoteConnectionConfig | AzureLocalConnectionConfig = useAzure
 		? {
 				tenantId,
@@ -164,7 +168,7 @@ function createSendFunction(): (msg: MessageToParent) => void {
 		const sendFn = process.send.bind(process);
 		if (verbosity.includes("msgs")) {
 			return (msg: MessageToParent) => {
-				console.log(`[${testLabel}] [${process_id}] Sending`, msg);
+				log(`Sending`, msg);
 				sendFn(msg);
 			};
 		}
@@ -381,7 +385,7 @@ class MessageHandler {
 				eventCategory: "messageReceived",
 				eventName: msg.command,
 			});
-			console.log(`[${testLabel}] [${process_id}] Received`, msg);
+			log(`Received`, msg);
 		}
 
 		if (msg.command === "ping") {
@@ -478,7 +482,10 @@ class MessageHandler {
 			this.presence = presence;
 
 			// wait for 'ConnectionState.Connected'
-			await connected;
+			await connected.catch((error) => {
+				(error as Error).message += `\nLog: ${JSON.stringify(this.log)}`;
+				throw error;
+			});
 
 			// Acknowledge connection before sending current attendee information
 			this.send({
@@ -519,9 +526,7 @@ class MessageHandler {
 						connectedCount++;
 					}
 				}
-				console.log(
-					`[${testLabel}] [${process_id}] Report: ${attendees.size} attendees, ${connectedCount} connected`,
-				);
+				log(`Report: ${attendees.size} attendees, ${connectedCount} connected`);
 			} else {
 				this.send({ event: "error", error: `${process_id} is not connected to presence` });
 			}

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

@@ -57,6 +57,7 @@ export interface ConnectCommand {
 	 * If not provided, a new Fluid container will be created.
 	 */
 	containerId?: string;
+	connectTimeoutMs: number;
 }
 
 /**

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

@@ -154,6 +154,7 @@ export async function executeDebugReports(
 function composeConnectMessage(
 	id: string | number,
 	scopes: ScopeType[] = [ScopeType.DocRead],
+	connectTimeoutMs: number,
 ): ConnectCommand {
 	return {
 		command: "connect",
@@ -163,6 +164,7 @@ function composeConnectMessage(
 		},
 		scopes,
 		createScopes: [ScopeType.DocWrite, ScopeType.DocRead],
+		connectTimeoutMs,
 	};
 }
 
@@ -257,6 +259,7 @@ export async function connectChildProcesses(
 		const connectContainerCreator = composeConnectMessage(
 			0,
 			writeClients > 0 ? [ScopeType.DocWrite, ScopeType.DocRead] : [ScopeType.DocRead],
+			/* connectTimeoutMs */ readyTimeoutMs,
 		);
 		firstChild.send(connectContainerCreator);
 	}
@@ -266,7 +269,10 @@ export async function connectChildProcesses(
 			durationMs: readyTimeoutMs,
 			errorMsg: "did not receive 'connected' from child process",
 		},
-	);
+	).catch(async (error) => {
+		await executeDebugReports([firstChild]);
+		throw error;
+	});
 
 	const attendeeIdPromises: Promise<AttendeeId>[] = [];
 	for (const [index, child] of childProcesses.entries()) {
@@ -277,6 +283,7 @@ export async function connectChildProcesses(
 		const message = composeConnectMessage(
 			index,
 			index < writeClients ? [ScopeType.DocWrite, ScopeType.DocRead] : [ScopeType.DocRead],
+			/* connectTimeoutMs */ readyTimeoutMs,
 		);
 		message.containerId = containerId;
 		attendeeIdPromises.push(