test(client-azure-end-to-end-tests): debug support (microsoft#25773)

- Add additional child logging prefix for distinction under CI where
output appears jumbled
- Exclude non-interactive connection telemetry from logs
- On unexpect ClientJoin send additional details

Author: jason-ha

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

@@ -41,9 +41,10 @@ import type {
 } from "./messageTypes.js";
 
 const connectTimeoutMs = 10_000;
+const testLabel = process.argv[2];
 // Identifier given to child process
-const process_id = process.argv[2];
-const verbosity = process.argv[3] ?? "";
+const process_id = process.argv[3];
+const verbosity = process.argv[4] ?? "";
 
 const useAzure = process.env.FLUID_CLIENT === "azure";
 const tenantId = useAzure
@@ -82,7 +83,7 @@ function selectiveVerboseLog(event: ITelemetryBaseEvent, logLevel?: LogLevel): v
 	if (interest === "details") {
 		content.details = event.details;
 	}
-	console.log(`[${process_id}] [${logLevel ?? LogLevel.default}]`, content);
+	console.log(`[${testLabel}] [${process_id}] [${logLevel ?? LogLevel.default}]`, content);
 }
 
 /**
@@ -163,7 +164,7 @@ function createSendFunction(): (msg: MessageToParent) => void {
 		const sendFn = process.send.bind(process);
 		if (verbosity.includes("msgs")) {
 			return (msg: MessageToParent) => {
-				console.log(`[${process_id}] Sending`, msg);
+				console.log(`[${testLabel}] [${process_id}] Sending`, msg);
 				sendFn(msg);
 			};
 		}
@@ -248,11 +249,17 @@ class MessageHandler {
 
 	private readonly logger: ITelemetryBaseLogger = {
 		send: (event: ITelemetryBaseEvent, logLevel?: LogLevel) => {
+			// Filter out non-interactive client telemetry
+			const clientType = event.clientType;
+			if (typeof clientType === "string" && clientType.startsWith("noninteractive")) {
+				return;
+			}
+
 			// Special case unexpected telemetry event
 			if (event.eventName.endsWith(":JoinResponseWhenAlone")) {
 				this.send({
 					event: "error",
-					error: `Unexpected ClientJoin response. Details: ${JSON.stringify(event.details)}`,
+					error: `Unexpected ClientJoin response. Details: ${JSON.stringify(event.details)}\nLog: ${JSON.stringify(this.log)}`,
 				});
 				// Keep going
 			}
@@ -374,7 +381,7 @@ class MessageHandler {
 				eventCategory: "messageReceived",
 				eventName: msg.command,
 			});
-			console.log(`[${process_id}] Received`, msg);
+			console.log(`[${testLabel}] [${process_id}] Received`, msg);
 		}
 
 		if (msg.command === "ping") {
@@ -513,7 +520,7 @@ class MessageHandler {
 					}
 				}
 				console.log(
-					`[${process_id}] Report: ${attendees.size} attendees, ${connectedCount} connected`,
+					`[${testLabel}] [${process_id}] Report: ${attendees.size} attendees, ${connectedCount} connected`,
 				);
 			} else {
 				this.send({ event: "error", error: `${process_id} is not connected to presence` });
@@ -712,7 +719,7 @@ function setupMessageHandler(): void {
 	const messageHandler = new MessageHandler();
 	process.on("message", (msg: MessageFromParent) => {
 		messageHandler.onMessage(msg).catch((error: Error) => {
-			console.error(`Error in client ${process_id}`, error);
+			console.error(`[${testLabel}] Error in client ${process_id}`, error);
 			send({ event: "error", error: `${process_id}: ${error.message}` });
 		});
 	});

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

@@ -58,6 +58,7 @@ interface ChildProcess extends AnyChildProcess {
  * @returns A collection of child processes and a promise that rejects on the first child error.
  */
 export async function forkChildProcesses(
+	testLabel: string,
 	numProcesses: number,
 	cleanUpAccumulator: (() => void)[],
 ): Promise<{
@@ -72,6 +73,7 @@ export async function forkChildProcesses(
 	const childErrorPromises: Promise<never>[] = [];
 	for (let i = 0; i < numProcesses; i++) {
 		const child = fork("./lib/test/multiprocess/childClient.tool.js", [
+			testLabel,
 			`child ${i}` /* identifier passed to child process */,
 			childLoggingVerbosity /* console logging verbosity */,
 		]);
@@ -348,6 +350,10 @@ export async function connectAndListenForAttendees(
 		readyTimeoutMs: childConnectTimeoutMs,
 	});
 
+	// These actions are not awaited. They are here to provide additional logging.
+	// It is up to the caller to await attendeeIdPromises if desired. This can mean
+	// An "error" message is output, but the caller does not care about attendee
+	// ids and proceeds.
 	Promise.all(connectResult.attendeeIdPromises)
 		.then(() => console.log("All attendees connected."))
 		.catch((error) => {

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

@@ -131,11 +131,12 @@ describe(`Presence with AzureClient`, () => {
 			const allAttendeesFullyJoinedTimeoutMs = (2000 + 300 * numClients) * timeoutMultiplier;
 
 			for (const writeClients of [numClients, 1]) {
-				it(`announces 'attendeeConnected' when remote client joins session [${numClients} clients, ${writeClients} writers]`, async function () {
+				it(`announces 'attendeeConnected' when remote client joins session [${numClients} clients, ${writeClients} writers]`, async function testAnnouncesAttendeeConnected() {
 					setTestTimeout(this, childConnectTimeoutMs + allAttendeesJoinedTimeoutMs + 1000);
 
 					// Setup
 					const { children, childErrorPromise } = await forkChildProcesses(
+						this.test?.title ?? "",
 						numClients,
 						afterCleanUp,
 					);
@@ -153,7 +154,7 @@ describe(`Presence with AzureClient`, () => {
 					);
 				});
 
-				it(`announces 'attendeeDisconnected' when remote client disconnects [${numClients} clients, ${writeClients} writers]`, async function () {
+				it(`announces 'attendeeDisconnected' when remote client disconnects [${numClients} clients, ${writeClients} writers]`, async function testAnnouncesAttendeeDisconnected() {
 					if (useAzure && numClients > 50) {
 						// Even with increased timeouts, more than 50 clients can be too large for AFR.
 						// This may be due to slow responses/inactivity from the clients that are
@@ -173,6 +174,7 @@ describe(`Presence with AzureClient`, () => {
 
 					// Setup
 					const { children, childErrorPromise } = await forkChildProcesses(
+						this.test?.title ?? "",
 						numClients,
 						afterCleanUp,
 					);
@@ -345,8 +347,9 @@ describe(`Presence with AzureClient`, () => {
 				const testValue = "testValue";
 				const workspaceId = "presenceTestWorkspace";
 
-				beforeEach(async () => {
+				beforeEach(async function usingLatestStateObject_beforeEach(): Promise<void> {
 					({ children, childErrorPromise } = await forkChildProcesses(
+						this.currentTest?.title ?? "",
 						numClients,
 						afterCleanUp,
 					));
@@ -432,8 +435,9 @@ describe(`Presence with AzureClient`, () => {
 				const value1 = { name: "Alice", score: 100 };
 				const value2 = { name: "Bob", score: 200 };
 
-				beforeEach(async () => {
+				beforeEach(async function usingLatestMapStateObject_beforeEach(): Promise<void> {
 					({ children, childErrorPromise } = await forkChildProcesses(
+						this.currentTest?.title ?? "",
 						numClients,
 						afterCleanUp,
 					));