diff --git a/GDJS/Runtime/gameplay-tests/gameplay-test-runner.ts b/GDJS/Runtime/gameplay-tests/gameplay-test-runner.ts index 78d28c4360..86eca2e21e 100644 --- a/GDJS/Runtime/gameplay-tests/gameplay-test-runner.ts +++ b/GDJS/Runtime/gameplay-tests/gameplay-test-runner.ts @@ -56,8 +56,13 @@ namespace gdjs { source: string; /** Readable state to evaluate on object/behavior snapshots. */ stateInspectors?: GameplayTestStateInspectors; - /** Wall-clock timeout for the whole run. Default: 30000. */ + /** Wall-clock timeout for the RUNNING part of the test: the time + * spent waiting for the game to boot or for scene assets to load is + * excluded (bounded separately by `loadingTimeoutMs`). Default: 30000. */ timeoutMs?: number; + /** Wall-clock bound on each loading wait (game boot, scene assets), + * which is excluded from `timeoutMs`. Default: 300000. */ + loadingTimeoutMs?: number; /** Maximum number of frames stepped. Default: 20000. */ maxFrames?: number; /** @@ -299,8 +304,13 @@ namespace gdjs { status: 'passed' | 'failed' | 'error' | 'stopped' | 'timeout'; framesExecuted: integer; durationMs: number; - /** The wall-clock budget the run had (`durationMs` close to it means - * the test is at risk of timing out on a slower machine). */ + /** Time spent waiting for the game to boot and for scene assets to + * load, excluded from the `timeoutMs` budget. `durationMs` includes + * it: `durationMs - loadingMs` is what counted against the budget. */ + loadingMs: number; + /** The wall-clock budget the run had, loading excluded + * (`durationMs - loadingMs` close to it means the test is at risk of + * timing out on a slower machine). */ timeoutMs: number; gameTimeMs: number; assertions: Array; @@ -325,6 +335,10 @@ namespace gdjs { }; const DEFAULT_TIMEOUT_MS = 30000; + /** Loading (game boot, scene assets) is excluded from `timeoutMs` - + * on the web, a first preview can download assets for minutes - but + * still bounded, so a dead network cannot hang a run forever. */ + const DEFAULT_LOADING_TIMEOUT_MS = 300000; const DEFAULT_MAX_FRAMES = 20000; /** How long frames are stepped before yielding once to the browser: * the game visibly plays (a rendered frame per refresh), stop/progress @@ -523,6 +537,10 @@ namespace gdjs { * result as `profiles`). */ _profiles: Array = []; _timeoutMs: number; + _loadingTimeoutMs: number; + /** Time spent waiting for loading (game boot, scene assets) so far: + * excluded from the `_timeoutMs` budget, reported as `loadingMs`. */ + _loadingTimeMs: number = 0; _maxFrames: integer; /** Last time the stepping loop yielded to the browser (see * `_maybeYield`). */ @@ -572,6 +590,8 @@ namespace gdjs { this._runtimeGame = runtimeGame; this._payload = payload; this._timeoutMs = payload.timeoutMs || DEFAULT_TIMEOUT_MS; + this._loadingTimeoutMs = + payload.loadingTimeoutMs || DEFAULT_LOADING_TIMEOUT_MS; this._maxFrames = payload.maxFrames || DEFAULT_MAX_FRAMES; this._lastYieldTimeMs = Date.now(); this._paceSpeedFactor = payload.speedFactor @@ -623,13 +643,58 @@ namespace gdjs { `The test reached the maximum number of frames (${this._maxFrames}).` ); } - if (Date.now() - this._startTimeMs > this._timeoutMs) { + if ( + Date.now() - this._startTimeMs - this._loadingTimeMs > + this._timeoutMs + ) { throw new GameplayTestTimeoutError( - `The test timed out after ${this._timeoutMs}ms (wall-clock).` + `The test timed out after ${this._timeoutMs}ms ` + + '(wall-clock, loading time excluded).' ); } } + /** + * Await a loading promise (game boot, scene assets...) WITHOUT + * counting the wait against the `timeoutMs` budget: the timeout is + * about the running game, not about how long a web preview takes to + * download its resources. The wait is still bounded (by + * `loadingTimeoutMs`) so a dead network cannot hang the run, and + * progress heartbeats keep flowing so the editor knows the run is + * alive. + */ + async _awaitLoading( + loadingPromise: Promise, + description: string + ): Promise { + const loadingStartTimeMs = Date.now(); + const heartbeatIntervalId = setInterval(() => { + if (this._onProgress) this._onProgress(this._framesExecuted); + }, 1000); + let loadingTimeoutId: any = null; + try { + await Promise.race([ + loadingPromise, + new Promise((_, reject) => { + loadingTimeoutId = setTimeout( + () => + reject( + new Error( + `${description} did not finish loading within ` + + `${this._loadingTimeoutMs}ms.` + ) + ), + this._loadingTimeoutMs + ); + }), + ]); + } finally { + clearInterval(heartbeatIntervalId); + if (loadingTimeoutId) clearTimeout(loadingTimeoutId); + this._loadingTimeMs += Date.now() - loadingStartTimeMs; + } + } + private _recordEvent(event: GameplayTestEvent): void { if (this._eventLog.length >= MAX_EVENT_LOG_ENTRIES) return; this._eventLog.push(event); @@ -835,7 +900,13 @@ namespace gdjs { ); } if (!this._runtimeGame.areSceneAssetsReady(sceneName)) { - await this._runtimeGame.loadSceneAssets(sceneName); + // On the web, this can download assets for a long time (notably + // the first run of a preview): waited for as loading, outside of + // the `timeoutMs` budget. + await this._awaitLoading( + this._runtimeGame.loadSceneAssets(sceneName), + `The assets of the scene "${sceneName}"` + ); } this._checkGuards(); this._runtimeGame @@ -2721,6 +2792,7 @@ namespace gdjs { status, framesExecuted: this._framesExecuted, durationMs: this._startTimeMs ? Date.now() - this._startTimeMs : 0, + loadingMs: Math.round(this._loadingTimeMs), timeoutMs: this._timeoutMs, gameTimeMs: Math.round(this._gameTimeMs), assertions: this._assertions, @@ -2833,7 +2905,13 @@ namespace gdjs { // create scenes before asynchronously loaded libraries (Jolt // physics...) are ready, or the startup could push the game's first // scene in the middle of the test. - const bootDeadlineMs = Date.now() + harness._timeoutMs; + // This wait is loading: excluded from the `timeoutMs` budget (counted + // in `loadingMs` instead), bounded by `loadingTimeoutMs`, with + // progress heartbeats so the editor knows the run is alive. + harness._startTimeMs = Date.now(); + const bootWaitStartTimeMs = Date.now(); + const bootDeadlineMs = bootWaitStartTimeMs + harness._loadingTimeoutMs; + let lastBootHeartbeatTimeMs = 0; while (runtimeGame.isStartingUp()) { if (harness._stopped) { currentlyRunningHarness = null; @@ -2841,13 +2919,23 @@ namespace gdjs { } if (Date.now() > bootDeadlineMs) { currentlyRunningHarness = null; + harness._loadingTimeMs += Date.now() - bootWaitStartTimeMs; return harness._makeResult('error', [ - `The game did not finish starting within ${harness._timeoutMs}ms ` + - '(the first scene was never created).', + `The game did not finish starting within ` + + `${harness._loadingTimeoutMs}ms (the first scene was never ` + + 'created).', ]); } + if ( + harness._onProgress && + Date.now() - lastBootHeartbeatTimeMs > 1000 + ) { + lastBootHeartbeatTimeMs = Date.now(); + harness._onProgress(0); + } await new Promise((resolve) => setTimeout(resolve, 20)); } + harness._loadingTimeMs += Date.now() - bootWaitStartTimeMs; const inputManager = runtimeGame.getInputManager(); const wasPaused = runtimeGame.isPaused(); @@ -2911,23 +2999,29 @@ namespace gdjs { }, }; - harness._startTimeMs = Date.now(); let result: GameplayTestResult; try { // A wall-clock watchdog, in case the script awaits something that - // never resolves. A synchronous infinite loop can NOT be interrupted - // (this is a limit of running in the same thread as the game). - let watchdogTimeoutId: any = null; + // never resolves. Checked periodically (not a one-shot timer) so + // the time spent loading - which grows `_loadingTimeMs` - stays + // excluded from the budget. A synchronous infinite loop can NOT be + // interrupted (this is a limit of running in the same thread as + // the game). + let watchdogIntervalId: any = null; const watchdog = new Promise((_, reject) => { - watchdogTimeoutId = setTimeout( - () => + watchdogIntervalId = setInterval(() => { + if ( + Date.now() - harness._startTimeMs - harness._loadingTimeMs > + harness._timeoutMs + 1000 + ) { reject( new GameplayTestTimeoutError( - `The test timed out after ${harness._timeoutMs}ms (wall-clock).` + `The test timed out after ${harness._timeoutMs}ms ` + + '(wall-clock, loading time excluded).' ) - ), - harness._timeoutMs + 1000 - ); + ); + } + }, 250); }); // A stop rejects this promise, interrupting the script even when // it awaits something else than the harness (a timer, a fetch...). @@ -2944,7 +3038,7 @@ namespace gdjs { stopSignal, ]); } finally { - if (watchdogTimeoutId) clearTimeout(watchdogTimeoutId); + if (watchdogIntervalId) clearInterval(watchdogIntervalId); harness._rejectOnStop = null; } diff --git a/GDJS/tests/tests/gameplaytestharness.js b/GDJS/tests/tests/gameplaytestharness.js index 5c0ebf634a..ad0fc4ea26 100644 --- a/GDJS/tests/tests/gameplaytestharness.js +++ b/GDJS/tests/tests/gameplaytestharness.js @@ -138,6 +138,7 @@ describe('gdjs.gameplayTests', () => { expect(result.status).to.be('passed'); expect(result.timeoutMs).to.be(5000); + expect(typeof result.loadingMs).to.be('number'); expect(result.framesExecuted).to.be(6); // 1 (goToScene) + 5. expect(result.assertions.length).to.be(1); expect(result.assertions[0].passed).to.be(true); @@ -421,10 +422,15 @@ describe('gdjs.gameplayTests', () => { harness.getSceneName() === 'Scene 2', 'The first scene of the game is running' ); - ` + `, + // A budget smaller than the startup delay: the wait for the game to + // finish starting is loading, excluded from the timeout budget. + { timeoutMs: 50 } ); expect(result.status).to.be('passed'); + // The startup wait is measured and reported as loading time. + expect(result.loadingMs >= 90).to.be(true); }); it('fails with a clear error when a started game never finishes starting', async () => { @@ -433,13 +439,56 @@ describe('gdjs.gameplayTests', () => { const result = await runTestScript( runtimeGame, 'await harness.stepFrames(1);', - { timeoutMs: 300 } + // The bound on this wait is the LOADING timeout, not the test budget. + { timeoutMs: 5000, loadingTimeoutMs: 300 } ); expect(result.status).to.be('error'); expect(result.errors[0]).to.contain('did not finish starting'); }).timeout(10000); + it('excludes slow scene-asset loading from the timeout budget', async () => { + const runtimeGame = makeRuntimeGame(); + // Simulate scene assets that take longer to load than the whole test + // budget (like the first run of a web preview downloading resources). + const anyRuntimeGame = /** @type {any} */ (runtimeGame); + let slowLoadDone = false; + anyRuntimeGame.areSceneAssetsReady = () => slowLoadDone; + anyRuntimeGame.loadSceneAssets = async () => { + await new Promise((resolve) => setTimeout(resolve, 300)); + slowLoadDone = true; + }; + const result = await runTestScript( + runtimeGame, + ` + await harness.goToScene('Scene 1'); + await harness.stepFrames(2); + harness.assert(harness.getSceneName() === 'Scene 1', 'Scene is running'); + `, + { timeoutMs: 200 } + ); + + expect(result.status).to.be('passed'); + expect(result.loadingMs >= 280).to.be(true); + // The wall-clock duration includes the loading time. + expect(result.durationMs >= result.loadingMs).to.be(true); + }).timeout(10000); + + it('fails with a clear error when scene assets never finish loading', async () => { + const runtimeGame = makeRuntimeGame(); + const anyRuntimeGame = /** @type {any} */ (runtimeGame); + anyRuntimeGame.areSceneAssetsReady = () => false; + anyRuntimeGame.loadSceneAssets = () => new Promise(() => {}); + const result = await runTestScript( + runtimeGame, + `await harness.goToScene('Scene 1');`, + { timeoutMs: 5000, loadingTimeoutMs: 200 } + ); + + expect(result.status).to.be('error'); + expect(result.errors[0]).to.contain('did not finish loading'); + }).timeout(10000); + it('gives the camera state and camera/heading-relative positions', async () => { const runtimeGame = makeRuntimeGame(); const result = await runTestScript( diff --git a/newIDE/app/src/GameplayTests/GameplayTestRunner.js b/newIDE/app/src/GameplayTests/GameplayTestRunner.js index e49ad5e58e..2e0c4592dd 100644 --- a/newIDE/app/src/GameplayTests/GameplayTestRunner.js +++ b/newIDE/app/src/GameplayTests/GameplayTestRunner.js @@ -40,8 +40,12 @@ export type GameplayTestResult = { status: 'passed' | 'failed' | 'error' | 'stopped' | 'timeout', framesExecuted: number, durationMs: number, - // The wall-clock budget the run had (a duration close to it means the - // test is at risk of timing out on a slower machine). + // Time spent waiting for the game to boot and for scene assets to load, + // excluded from the `timeoutMs` budget (`durationMs` includes it). + loadingMs: number, + // The wall-clock budget the run had, loading excluded + // (`durationMs - loadingMs` close to it means the test is at risk of + // timing out on a slower machine). timeoutMs: number, gameTimeMs: number, assertions: Array, @@ -154,6 +158,7 @@ const makeResultWithoutRun = ( status, framesExecuted: 0, durationMs: 0, + loadingMs: 0, timeoutMs: 0, gameTimeMs: 0, assertions: [], @@ -182,6 +187,7 @@ export const makeGameplayTestResultReadableOutput = ( testName: result.testName, framesExecuted: result.framesExecuted, durationMs: result.durationMs, + loadingMs: result.loadingMs, timeoutMs: result.timeoutMs, gameTimeMs: result.gameTimeMs, assertions: result.assertions, @@ -345,6 +351,10 @@ const runSingleTest = async ({ if (parsedMessage.messageId !== messageId) return; if (parsedMessage.command === 'gameplayTest.progress') { + // The game is alive (stepping frames, or heartbeating while it + // loads assets - loading is not counted against the test + // timeout): give it a full budget again. + armWatchdog(); if (onProgress && parsedMessage.payload) { onProgress(test, parsedMessage.payload.frame || 0); } @@ -365,17 +375,24 @@ const runSingleTest = async ({ resolve(result); }; - // An editor-side watchdog, in case the game dies without sending - // its result. - watchdogTimeoutId = setTimeout(() => { - finish( - makeErrorResult( - test.testName, - `No result received from the game after ${timeoutMs + - RESULT_EXTRA_TIMEOUT_MS}ms - the game may have crashed or been closed.` - ) - ); - }, timeoutMs + RESULT_EXTRA_TIMEOUT_MS); + // An editor-side watchdog, in case the game dies without sending its + // result. Re-armed by every progress message: a game legitimately + // spends long over its own timeout while loading assets (loading is + // excluded from the test budget), but it heartbeats while doing so - a + // full silence is what means it crashed. + const armWatchdog = () => { + if (watchdogTimeoutId !== null) clearTimeout(watchdogTimeoutId); + watchdogTimeoutId = setTimeout(() => { + finish( + makeErrorResult( + test.testName, + `No result nor progress received from the game after ${timeoutMs + + RESULT_EXTRA_TIMEOUT_MS}ms - the game may have crashed or been closed.` + ) + ); + }, timeoutMs + RESULT_EXTRA_TIMEOUT_MS); + }; + armWatchdog(); const payload: Object = { testName: test.testName, diff --git a/newIDE/app/src/MainFrame/LocalCliCommandRunner.js b/newIDE/app/src/MainFrame/LocalCliCommandRunner.js index 1155c93aa1..7a7e61e73c 100644 --- a/newIDE/app/src/MainFrame/LocalCliCommandRunner.js +++ b/newIDE/app/src/MainFrame/LocalCliCommandRunner.js @@ -239,9 +239,16 @@ const runners: { [commandName: string]: CliCommandRunner } = { for (const result of results) { const passed = result.status === 'passed'; if (!passed) failedCount++; + // Loading (game boot, scene assets) is excluded from the timeout + // budget: only the running time counts against it. + const loadingMs = result.loadingMs || 0; + const runningMs = Math.max(0, result.durationMs - loadingMs); + const loadingText = loadingMs + ? ` + ${(loadingMs / 1000).toFixed(1)}s loading` + : ''; const budgetText = result.timeoutMs - ? `, ${(result.durationMs / 1000).toFixed(1)}s / ${result.timeoutMs / - 1000}s budget` + ? `, ${(runningMs / 1000).toFixed(1)}s / ${result.timeoutMs / + 1000}s budget${loadingText}` : ''; console.info( `[CLI] ${passed ? 'PASSED' : 'FAILED'} (${result.status}): ${ @@ -250,14 +257,10 @@ const runners: { [commandName: string]: CliCommandRunner } = { result.errors.length ? ' - ' + result.errors.join(' | ') : '' }` ); - if ( - passed && - result.timeoutMs && - result.durationMs >= 0.8 * result.timeoutMs - ) { + if (passed && result.timeoutMs && runningMs >= 0.8 * result.timeoutMs) { console.warn( `[CLI] WARNING: "${result.testName}" used ${Math.round( - (100 * result.durationMs) / result.timeoutMs + (100 * runningMs) / result.timeoutMs )}% of its wall-clock budget - it is at risk of timing out on a slower machine. Shorten it or raise its timeout.` ); } diff --git a/newIDE/app/src/stories/componentStories/GameplayTests/GameplayTestProperties.stories.js b/newIDE/app/src/stories/componentStories/GameplayTests/GameplayTestProperties.stories.js index 4a44007766..699c92a04d 100644 --- a/newIDE/app/src/stories/componentStories/GameplayTests/GameplayTestProperties.stories.js +++ b/newIDE/app/src/stories/componentStories/GameplayTests/GameplayTestProperties.stories.js @@ -73,6 +73,7 @@ const makeResult = ( status: 'passed', framesExecuted: 0, durationMs: 0, + loadingMs: 0, timeoutMs: 0, gameTimeMs: 0, assertions: [],