From bbe353236775820a35b1c555f618347578bb8b5a Mon Sep 17 00:00:00 2001 From: Jason Hartman Date: Tue, 26 Aug 2025 13:06:46 -0700 Subject: [PATCH 1/2] 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 --- .../azure-client/package.json | 3 +- .../src/test/multiprocess/childClient.ts | 40 ++++++++++++++++++- .../test/multiprocess/orchestratorUtils.ts | 34 +++++++++++++--- 3 files changed, 69 insertions(+), 8 deletions(-) diff --git a/packages/service-clients/end-to-end-tests/azure-client/package.json b/packages/service-clients/end-to-end-tests/azure-client/package.json index 02c85da1faa9..f531255f8966 100644 --- a/packages/service-clients/end-to-end-tests/azure-client/package.json +++ b/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, diff --git a/packages/service-clients/end-to-end-tests/azure-client/src/test/multiprocess/childClient.ts b/packages/service-clients/end-to-end-tests/azure-client/src/test/multiprocess/childClient.ts index 45acccc1fcfe..a99f3f6af2a9 100644 --- a/packages/service-clients/end-to-end-tests/azure-client/src/test/multiprocess/childClient.ts +++ b/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; 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 { + if (verbosity.includes("msgs")) { + console.log(`[${process_id}] Received`, msg); + } switch (msg.command) { case "ping": { this.handlePing(); diff --git a/packages/service-clients/end-to-end-tests/azure-client/src/test/multiprocess/orchestratorUtils.ts b/packages/service-clients/end-to-end-tests/azure-client/src/test/multiprocess/orchestratorUtils.ts index 486325a3fdc2..d23a24c08e3f 100644 --- a/packages/service-clients/end-to-end-tests/azure-client/src/test/multiprocess/orchestratorUtils.ts +++ b/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[] = []; 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; } From e1008e42c3caf666e63c7a89a93b455e5381c99a Mon Sep 17 00:00:00 2001 From: Jason Hartman Date: Tue, 2 Sep 2025 09:29:33 -0700 Subject: [PATCH 2/2] test(client): per test case timeouts with debug support - 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 --- .../test/multiprocess/orchestratorUtils.ts | 2 +- .../test/multiprocess/presenceTest.spec.ts | 56 ++++++++++++++++--- 2 files changed, 49 insertions(+), 9 deletions(-) diff --git a/packages/service-clients/end-to-end-tests/azure-client/src/test/multiprocess/orchestratorUtils.ts b/packages/service-clients/end-to-end-tests/azure-client/src/test/multiprocess/orchestratorUtils.ts index d23a24c08e3f..594762a31f56 100644 --- a/packages/service-clients/end-to-end-tests/azure-client/src/test/multiprocess/orchestratorUtils.ts +++ b/packages/service-clients/end-to-end-tests/azure-client/src/test/multiprocess/orchestratorUtils.ts @@ -33,7 +33,7 @@ const childLoggingVerbosity = process.env.FLUID_TEST_VERBOSE ?? "none"; /** * Capture console./warn/error before test infrastructure alters it. */ -const testConsole = { +export const testConsole = { log: console.log, warn: console.warn, error: console.error, diff --git a/packages/service-clients/end-to-end-tests/azure-client/src/test/multiprocess/presenceTest.spec.ts b/packages/service-clients/end-to-end-tests/azure-client/src/test/multiprocess/presenceTest.spec.ts index ca52a035458b..6e5eabf4a4cd 100644 --- a/packages/service-clients/end-to-end-tests/azure-client/src/test/multiprocess/presenceTest.spec.ts +++ b/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()