From 90c02f8942216c0afaacac2180165e4d25651f81 Mon Sep 17 00:00:00 2001 From: Michael FIG Date: Mon, 7 Oct 2024 13:14:00 -0600 Subject: [PATCH] test(multichain-testing): stir for no AVA timeout in long awaits --- multichain-testing/package.json | 3 +- multichain-testing/test/stake-ica.test.ts | 5 +- multichain-testing/test/stir.test.ts | 26 +++++++++ multichain-testing/test/support.ts | 4 ++ multichain-testing/tools/sleep.ts | 71 +++++++++++++++++++++-- 5 files changed, 102 insertions(+), 7 deletions(-) create mode 100644 multichain-testing/test/stir.test.ts diff --git a/multichain-testing/package.json b/multichain-testing/package.json index 4da3c7459343..8e862ce27461 100644 --- a/multichain-testing/package.json +++ b/multichain-testing/package.json @@ -58,8 +58,7 @@ "**/*.test.ts" ], "concurrency": 1, - "serial": true, - "timeout": "125s" + "serial": true }, "eslintConfig": { "root": true, diff --git a/multichain-testing/test/stake-ica.test.ts b/multichain-testing/test/stake-ica.test.ts index f5fd41fd0203..eaef0e7f2e7b 100644 --- a/multichain-testing/test/stake-ica.test.ts +++ b/multichain-testing/test/stake-ica.test.ts @@ -243,7 +243,10 @@ const stakeScenario = test.macro(async (t, scenario: StakeIcaScenario) => { console.log('waiting for unbonding period'); // XXX reference `120000` from chain state + `maxClockSkew` - await sleep(120000); + await sleep(120000, { + stir: description => + t.pass(`stirring while waiting for unbonding period: ${description}`), + }); const { balances: rewardsWithUndelegations } = await retryUntilCondition( () => queryClient.queryBalances(address), ({ balances }) => { diff --git a/multichain-testing/test/stir.test.ts b/multichain-testing/test/stir.test.ts new file mode 100644 index 000000000000..88540bb7b64a --- /dev/null +++ b/multichain-testing/test/stir.test.ts @@ -0,0 +1,26 @@ +import test from '@endo/ses-ava/prepare-endo.js'; +import { sleep } from '../tools/sleep.js'; + +test('sleep without tripping AVA timeout', async t => { + const stirred: string[] = []; + t.timeout(500); + const sleepTime = 4_000; + await sleep(sleepTime, { + log: t.log, + stirEveryMs: 300, + stir: description => { + stirred.push(description); + t.pass(description); + }, + }); + t.like(stirred, { + length: 15, + 0: `sleeping for ${sleepTime}ms...`, + 1: `while sleeping (1/14)`, + 2: `while sleeping (2/14)`, + // ... + 13: `while sleeping (13/14)`, + 14: `while sleeping (14/14)`, + 15: undefined, + }); +}); diff --git a/multichain-testing/test/support.ts b/multichain-testing/test/support.ts index 2267b8134367..de27633687c7 100644 --- a/multichain-testing/test/support.ts +++ b/multichain-testing/test/support.ts @@ -61,6 +61,10 @@ export const commonSetup = async (t: ExecutionContext) => { const retryUntilCondition = makeRetryUntilCondition({ log: t.log, setTimeout: globalThis.setTimeout, + setInterval: globalThis.setInterval, + clearInterval: globalThis.clearInterval, + stir: description => + t.pass(`stirring in retryUntilCondition ${description}`), }); const hermes = makeHermes(childProcess); diff --git a/multichain-testing/tools/sleep.ts b/multichain-testing/tools/sleep.ts index 66251a87dcaa..8c7ee0ffc1ad 100644 --- a/multichain-testing/tools/sleep.ts +++ b/multichain-testing/tools/sleep.ts @@ -1,21 +1,68 @@ +const ambientSetInterval = globalThis.setInterval; +const ambientClearInterval = globalThis.clearInterval; const ambientSetTimeout = globalThis.setTimeout; +// Derived from the fact that AVA's "default timeout is 10 seconds." +// https://github.com/avajs/ava/blob/main/docs/07-test-timeouts.md#test-timeouts +const DEFAULT_STIR_EVERY_MS = 8_000; + type Log = (...values: unknown[]) => void; type SleepOptions = { log?: Log; + clearInterval?: typeof ambientClearInterval; + setInterval?: typeof ambientSetInterval; setTimeout?: typeof ambientSetTimeout; + stirEveryMs?: number; + /** + * Call every `stirEveryMs` during sleeping so that the sleeper isn't timed + * out by, e.g. a test runner. + * @param description - A bit of context as to why we're stirring. + */ + stir?: (description: string) => void; }; -export const sleep = ( +/** + * + * @param {number} ms Sleep duration in milliseconds + * @param {SleepOptions} opts + * @returns {Promise} + */ +export const deepSleep = ( ms: number, - { log = () => {}, setTimeout = ambientSetTimeout }: SleepOptions = {}, + { setTimeout = ambientSetTimeout }: SleepOptions = {}, ) => new Promise(resolve => { - log(`Sleeping for ${ms}ms...`); setTimeout(resolve, ms); }); +export const sleep = async ( + ms: number, + { + log = () => {}, + stir, + stirEveryMs = DEFAULT_STIR_EVERY_MS, + setTimeout = ambientSetTimeout, + }: SleepOptions = {}, +) => { + log(`Sleeping for ${ms}ms...`); + await (stir && stir(`sleeping for ${ms}ms...`)); + let remaining = ms; + let nStirs = 0; + const totalStirs = Math.ceil(ms / stirEveryMs); + const doStir = async () => { + nStirs += 1; + await (stir && stir(`while sleeping (${nStirs}/${totalStirs})`)); + }; + while (stir && remaining >= stirEveryMs) { + remaining -= stirEveryMs; + await deepSleep(stirEveryMs, { setTimeout }); + await doStir(); + } + await deepSleep(remaining, { setTimeout }); + await doStir(); +}; + export type RetryOptions = { maxRetries?: number; retryIntervalMs?: number; @@ -29,13 +76,27 @@ const retryUntilCondition = async ( maxRetries = 6, retryIntervalMs = 3500, log = () => {}, + stirEveryMs, + stir, setTimeout = ambientSetTimeout, + setInterval = ambientSetInterval, + clearInterval = ambientClearInterval, }: RetryOptions = {}, ): Promise => { console.log({ maxRetries, retryIntervalMs, message }); let retries = 0; while (retries < maxRetries) { + let conditionStirring; + if (stir) { + let nStirs = 0; + conditionStirring = setInterval(() => { + nStirs += 1; + stir( + `during ${message} condition (${retries + 1}/${maxRetries})#${nStirs}`, + ); + }, stirEveryMs); + } try { const result = await operation(); if (condition(result)) { @@ -47,13 +108,15 @@ const retryUntilCondition = async ( } else { log(`Unknown error: ${String(error)}`); } + } finally { + conditionStirring === undefined || clearInterval(conditionStirring); } retries++; console.log( `Retry ${retries}/${maxRetries} - Waiting for ${retryIntervalMs}ms for ${message}...`, ); - await sleep(retryIntervalMs, { log, setTimeout }); + await sleep(retryIntervalMs, { log, setTimeout, stirEveryMs, stir }); } throw Error(`${message} condition failed after ${maxRetries} retries.`);