diff --git a/CHANGELOG.md b/CHANGELOG.md index cedfa92d..9e14e647 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -13,6 +13,9 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 - The grunt task passed config values to bedrock without type coercion, so string values for `Number` or `Boolean` options (e.g. `--webdriverPort=14444` or `--useSelenium=false` via `grunt.option`) were rejected or misread. #TINYMCE-14879 - Extended test start pings to every page load, allowing updates during a chunk or fail-retry reload. This should reduce how often the server's no-updates watchdog is tripped. #TINYMCE-14879 - Safari 26 failed to load the test page through the LambdaTest tunnel on `localhost`. The LT tunnel URL now uses LambdaTest's `localhost.lambdatest.com` DNS alias for all browsers. #TINYMCE-14879 +- The server used a single 55 second budget for both "the browser has stopped responding" and "the browser has not finished a test", so a slow remote browser was killed as if the driver had died. Liveness is now tracked separately from progress: silence from the browser is still caught after 55 seconds, while lack of progress is measured in client pings rather than elapsed time, so a slower connection widens the tolerance by the same factor. #TD-2600 +- The runner only posted to the server when a test finished, so a browser running one slow test looked the same as a browser that had died. It now posts on a fixed heartbeat regardless of test activity, rescheduled after each post completes so a slow connection cannot stack requests. #TD-2600 +- `/tests/init` did not record browser activity, so the bundle re-fetch after a chunk or retry reload counted as silence. #TD-2600 ## 17.0.1 - 2026-08-28 diff --git a/modules/runner/src/main/ts/reporter/Reporter.ts b/modules/runner/src/main/ts/reporter/Reporter.ts index 219020c0..bb854f4b 100644 --- a/modules/runner/src/main/ts/reporter/Reporter.ts +++ b/modules/runner/src/main/ts/reporter/Reporter.ts @@ -17,6 +17,7 @@ export interface TestReporter { export interface Reporter { readonly summary: () => { offset: number; passed: number; failed: number; skipped: number }; readonly test: (file: string, name: string, totalNumTests: number) => TestReporter; + readonly startHeartbeat: (intervalMs?: number) => void; readonly strayFailure: (file: string, name: string, e: LoggedError) => void; readonly waitForResults: () => Promise; readonly retry: () => Promise; @@ -49,9 +50,16 @@ const mapError = (e: LoggedError) => mapStackTrace(e.stack).then((mappedStack) = return e; }); +/* + * How often the runner posts to the server whether or not a test has finished. The server counts + * these to decide whether a run has stalled, so the value is a cadence and not a budget: slowing + * the connection slows the pings and widens the server's tolerance by the same factor. + */ +const HEARTBEAT_INTERVAL = 20 * 1000; + export const Reporter = (params: UrlParams, callbacks: Callbacks, ui: ReporterUi, mouse: MouseWatch): Reporter => { const initial = Date.now(); - let timeOfLastReport = initial; + let heartbeatTimer: ReturnType | null = null; let currentCount = params.offset || 0; let passCount = 0; let skipCount = 0; @@ -66,8 +74,6 @@ export const Reporter = (params: UrlParams, callbacks: Callbacks, ui: ReporterUi const requestsInFlight: Promise[] = []; const takeResults = (): TestReport[] => { - // Assume the results will be posted once they are returned - timeOfLastReport = Date.now(); // splice deletes the values specified and returns them return testResults.splice(0, testResults.length); }; @@ -80,9 +86,33 @@ export const Reporter = (params: UrlParams, callbacks: Callbacks, ui: ReporterUi const reportResult = (result: TestReport): void => { testResults.push(result); - if (Date.now() - timeOfLastReport > 30 * 1000) { - // ping the server with results every 30 seconds or so, as a form of keep-alive - reportResults(); + }; + + // Posts even when the batch is empty. An empty post is how the server tells a browser that is + // slow from one that is gone, so this must not be skipped when nothing has finished. + const reportProgress = (): Promise => { + const sent = callbacks.sendTestResults(params.session, takeResults()); + requestsInFlight.push(sent); + return sent; + }; + + // Rescheduled only once the previous post settles, so a slow connection stretches the gap + // instead of stacking requests on top of one that has not come back. + const scheduleHeartbeat = (intervalMs: number = HEARTBEAT_INTERVAL): void => { + heartbeatTimer = setTimeout(() => { + const again = (): void => { + if (!finished) { + scheduleHeartbeat(intervalMs); + } + }; + reportProgress().then(again, again); + }, intervalMs); + }; + + const stopHeartbeat = (): void => { + if (heartbeatTimer !== null) { + clearTimeout(heartbeatTimer); + heartbeatTimer = null; } }; @@ -266,6 +296,7 @@ export const Reporter = (params: UrlParams, callbacks: Callbacks, ui: ReporterUi const done = (error?: LoggedError): void => { finished = true; + stopHeartbeat(); const setAsDone = (): void => { const totalTime = elapsed(initial); ui.done(totalTime); @@ -282,6 +313,7 @@ export const Reporter = (params: UrlParams, callbacks: Callbacks, ui: ReporterUi return { summary, test, + startHeartbeat: scheduleHeartbeat, strayFailure, retry, waitForResults, diff --git a/modules/runner/src/main/ts/runner/Runner.ts b/modules/runner/src/main/ts/runner/Runner.ts index a8260180..0e7ef327 100644 --- a/modules/runner/src/main/ts/runner/Runner.ts +++ b/modules/runner/src/main/ts/runner/Runner.ts @@ -78,7 +78,6 @@ export const Runner = (rootSuite: Suite, params: UrlParams, callbacks: Callbacks ui.render(params.offset, numTests, actions.restartTests, retryTest, loadNextTest); return Promise.all([callbacks.sendInit(params.session), callbacks.loadHarness()]).then(([_, harness]) => { - // we don't need a keep-alive timer in auto mode, if (harness.mode === 'manual') { // delay this ajax call until after the reporter status elements are in the page const keepAliveTimer = setInterval(() => { @@ -87,6 +86,9 @@ export const Runner = (rootSuite: Suite, params: UrlParams, callbacks: Callbacks clearInterval(keepAliveTimer); }); }, KEEP_ALIVE_INTERVAL); + } else { + // only auto mode has the watchdog that counts these pings; manual keeps its keep-alive + reporter.startHeartbeat(); } return harness; diff --git a/modules/runner/src/test/ts/reporter/ReporterTest.ts b/modules/runner/src/test/ts/reporter/ReporterTest.ts index a9986761..aa3650cb 100644 --- a/modules/runner/src/test/ts/reporter/ReporterTest.ts +++ b/modules/runner/src/test/ts/reporter/ReporterTest.ts @@ -52,6 +52,7 @@ describe('Reporter.test', () => { let doneCalled: boolean, doneError: string | undefined, offset: number; let mouseMoved: boolean, startFails: boolean; let startGate: Promise | null; + let resultsPosts: number; const mouse: MouseWatch = { hasMoved: () => mouseMoved, clear: () => { @@ -71,6 +72,7 @@ describe('Reporter.test', () => { return startGate !== null ? startGate : Promise.resolve(); }, sendTestResults: (session, results) => { + resultsPosts++; results.forEach(r => endTestData.push({session, ...r})); return Promise.resolve(); }, @@ -86,6 +88,7 @@ describe('Reporter.test', () => { mouseMoved = false; startFails = false; startGate = null; + resultsPosts = 0; reporter = Reporter({ ...params, offset }, callbacks, ui, mouse); startTestData = []; endTestData = []; @@ -95,6 +98,18 @@ describe('Reporter.test', () => { beforeEach(() => reset()); + it('TD-2668: the heartbeat posts even when no test has finished', () => { + reset(0); + // The server counts these posts to tell a slow browser from a dead one, so an empty batch + // still has to go out. Without that there is nothing to count while one slow test runs. + reporter.startHeartbeat(10); + return new Promise((resolve) => setTimeout(resolve, 60)).then(() => { + assert.isAtLeast(resultsPosts, 2, 'Checking the heartbeat posted repeatedly with nothing to send'); + assert.lengthOf(endTestData, 0, 'Checking the posts carried no results'); + reporter.done(); + }); + }); + it('should report the session id, number tests, file and name on start', () => { return fc.assert(fc.asyncProperty(fc.string(), fc.string(), fc.integer({ max: offset }), (fileName, testName, testCount) => { reset(0); diff --git a/modules/runner/src/test/ts/runner/RunnerTestUtils.ts b/modules/runner/src/test/ts/runner/RunnerTestUtils.ts index ced1ed9f..b80f7667 100644 --- a/modules/runner/src/test/ts/runner/RunnerTestUtils.ts +++ b/modules/runner/src/test/ts/runner/RunnerTestUtils.ts @@ -53,6 +53,7 @@ export const MockReporter = (): MockReporter => { return { test, + startHeartbeat: noop, strayFailure: (_file, name, e) => { failures.push(e); failedNames.push(name); diff --git a/modules/server/src/main/ts/bedrock/server/Apis.ts b/modules/server/src/main/ts/bedrock/server/Apis.ts index 02ab25d9..765924e6 100644 --- a/modules/server/src/main/ts/bedrock/server/Apis.ts +++ b/modules/server/src/main/ts/bedrock/server/Apis.ts @@ -160,9 +160,14 @@ export const create = (master: DriverMaster | null, pMaybeDriver: Promise { c.recordAlive(data.session); - return keepAliveAction(); + // manual mode pings this every few seconds, so it must be the throttled variant or a + // run would issue a webdriver command on every ping + return maybeSendKeepAlive(); + }), + Routes.effect('POST', '/tests/init', (data: { session: string }) => { + c.recordAlive(data.session); + return resetMousePositionAction(true); }), - Routes.effect('POST', '/tests/init', () => resetMousePositionAction(true)), Routes.effect('POST', '/tests/start', (data: StartData) => { c.recordTestResults(data.session, data.results); c.recordTestStart(data.session, data.name, data.file, data.number, data.totalTests); diff --git a/modules/server/src/main/ts/bedrock/server/Controller.ts b/modules/server/src/main/ts/bedrock/server/Controller.ts index 93faa2e9..6e74f30c 100644 --- a/modules/server/src/main/ts/bedrock/server/Controller.ts +++ b/modules/server/src/main/ts/bedrock/server/Controller.ts @@ -35,6 +35,8 @@ interface TestSession { readonly lookup: Record>; alive: number; updated: number; + pings: number; + pingsAtLastProgress: number; previous: PreviousTest | null; done: boolean; error?: string; @@ -51,6 +53,23 @@ export interface Controller { readonly awaitDone: () => Promise; } +/* + * How long the browser may go without contacting the server at all before we treat the driver + * as dead. Every route bumps `session.alive`, and the runner posts on a fixed heartbeat whether + * or not a test has finished, so silence for this long means nothing is getting through. + */ +const LIVENESS_TIMEOUT = 55 * 1000; + +/* + * How many client pings may arrive without a single test finishing before we treat the run as + * stuck. The runner posts on a fixed interval whether or not a test has completed, so this is + * deliberately a count and not a duration: a link that halves in speed stretches the tolerance + * by the same factor instead of tripping it, which a wall-clock budget cannot do. The count times + * the heartbeat interval must stay above the longest single-test timeout in use, or one + * slow-but-legal test would be mistaken for a stuck run. + */ +const STALE_PINGS = 4; + export const create = (stickyFirstSession: boolean, overallTimeout: number, testfiles: string[], loglevel: 'simple' | 'advanced'): Controller => { const hud = Hud.create(testfiles, loglevel); const sessions: Record = {}; @@ -84,6 +103,8 @@ export const create = (stickyFirstSession: boolean, overallTimeout: number, test id: sessionId, alive: now, updated: now, + pings: 0, + pingsAtLastProgress: 0, results: [], lookup: {}, previous: null, @@ -122,6 +143,7 @@ export const create = (stickyFirstSession: boolean, overallTimeout: number, test const session = getSession(id); const now = Date.now(); session.updated = now; + session.pingsAtLastProgress = session.pings; session.totalTests = totalTests; session.currentTest = currentCount; session.done = false; @@ -154,9 +176,14 @@ export const create = (stickyFirstSession: boolean, overallTimeout: number, test const recordTestResults = (id: string, results: TestResult[]) => { const now = Date.now(); const session = getSession(id); - session.updated = now; - session.done = false; + // Every post counts as a ping, including the empty ones the runner sends on its heartbeat. + // Only a post that actually carries results counts as progress, otherwise the heartbeat + // would keep feeding the very clock it exists to let us read. + session.pings++; if (results.length > 0) { + session.updated = now; + session.done = false; + session.pingsAtLastProgress = session.pings; const {name, file} = results.slice(-1)[0]; session.previous = { name, @@ -179,6 +206,7 @@ export const create = (stickyFirstSession: boolean, overallTimeout: number, test session.currentTest = session.totalTests; } session.updated = Date.now(); + session.pingsAtLastProgress = session.pings; updateHud(session); }; @@ -203,6 +231,11 @@ export const create = (stickyFirstSession: boolean, overallTimeout: number, test return Promise.reject({message, results, start, now}); } return new Promise((resolve, reject) => { + const failRun = (message: string, results: TestResult[], now: number) => { + reject({message, results, start, now}); + clearInterval(poller); + timeoutError = true; + }; const poller = setInterval(() => { const now = Date.now(); const allElapsed = now - start; @@ -218,12 +251,14 @@ export const create = (stickyFirstSession: boolean, overallTimeout: number, test } clearInterval(poller); } else { - if ((now - session.updated) > (55 * 1000)) { - // sticky sessions have longer before they time out, but we still can't sit around if the driver has failed - const message = `No updates from the browser in ${formatTime(now - session.updated)}, assuming driver has failed.`; - reject({message, results, start, now}); - clearInterval(poller); - timeoutError = true; + if ((now - session.alive) > LIVENESS_TIMEOUT) { + // nothing at all is reaching us: the driver really has failed + failRun(`No updates from the browser in ${formatTime(now - session.alive)}, assuming driver has failed.`, results, now); + } else if ((session.pings - session.pingsAtLastProgress) >= STALE_PINGS) { + // the browser is still talking to us, it just isn't finishing tests + failRun(`No test progress for ${session.pings - session.pingsAtLastProgress} client pings ` + + `(${formatTime(now - session.updated)}), but the browser is still responding. ` + + `Assuming the run is stuck. Limit is set to ${STALE_PINGS} pings.`, results, now); } else if (allElapsed > overallTimeout) { // combined tests took too long let lastTest; @@ -240,18 +275,12 @@ export const create = (stickyFirstSession: boolean, overallTimeout: number, test const estimatedTotal = Math.ceil(((allElapsed / session.results.length) * testfiles.length) / 1000) * 1000; const message = 'Tests timed out: ' + formatTime(allElapsed) + '. Limit is set to ' + formatTime(overallTimeout) + '. Estimated required time ' + formatTime(estimatedTotal) + '.\n' + lastTest + '\nTop 10 longest running tests:\n' + longest; - reject({message, results, start, now}); - clearInterval(poller); - timeoutError = true; + failRun(message, results, now); } } } else if (allElapsed > overallTimeout) { // combined tests took too long - const message = 'Tests took too long to start'; - const results: TestResult[] = []; - reject({message, results, start, now}); - clearInterval(poller); - timeoutError = true; + failRun('Tests took too long to start', [], now); } }, 1000); });