Cleanly switch to real time and back again to fake time while testing

[weshouman]

Scenario

Having promises that are produced in the stubs and resolved in the test, each promise of the promises list is resolved in the fake time, then the clock is ticked at the end of the for loop.

What did you expect to happen?

When the promise is resolved we should have the fake time effective again, and thus the test should continue in the fake time.

What actually happens

When test is executed it executes in the real time, and not the fake time.

After executing the scenario, the code pointer does not jump back from the stub to the next line in the UUT, in which Invoked ... log message is shown in the attached code, unless either of the following happens:

• An await of a stub promise that times out in at least 1 ms (which happens at the beginning of the for loop, allowing each resolver to move on based on the previous one), in which case the date in the UUT is set to the real time again.
• An await of a UUT promise (which happens in the n-th subfunction call which continues when we finish the loop and await the mainFunction's promise), in which case the date in the UUT is set to the fake time.

Questions

• Is there a better way to change to and back from real time?
• How to ensure that the Test is always set back to the fake time, while using the timerUtils?
• Bonus, how to get enableFurtherWait to run without blocking the promise?

How to reproduce

Here's a demo code with the output logs.

UUT.js

```javascript // UUT.js const enableFurtherWait = false; const callCount = 3; async function subFunction(index) { await new Promise((resolve) => setTimeout(resolve, 1000)); // to be stubbed anyway } async function mainFunction() { for (let i = 1; i <= callCount; i++) { // await subFunction(i); // this won't work! console.log(`UUT: Invoking subfunction ${i} at ${new Date().toISOString()}`); await UUT.subFunction(i); console.log(`UUT: Invoked subfunction ${i} at ${new Date().toISOString()}`); } if (enableFurtherWait) { console.log(`UUT: Waiting a couple of seconds after subfunctions at ${new Date().toISOString()}`); await new Promise((resolve) => { console.log("Promise started"); setTimeout(resolve, 2000);}); // Wait for 2 seconds } console.log(`UUT: mainFunction completed at ${new Date().toISOString()}`); } export const UUT = { mainFunction, subFunction }; ```

UUT.test.js

```javascript // UUT.test.js import { timerUtils } from './timerUtils.js'; import { UUT } from './UUT.js'; import sinon from 'sinon'; import { expect } from 'chai'; const promiseResolvers = []; const useGlobalClock = true; let clock; // should always match with UUT.js, always the last call would show the Invoked log in real time const callCount = 3; describe('Main Function Test', function() { beforeEach(function() { if (useGlobalClock) { clock = sinon.useFakeTimers(); } else { timerUtils.useFakeTimer(); } sinon.stub(UUT, 'subFunction').callsFake((index) => { console.log(`Stub: subFunction ${index} called, ${new Date().toISOString()}`); return new Promise((resolve) => { promiseResolvers.push(resolve); }); }); }); afterEach(function() { if (useGlobalClock) { clock.restore(); } else { timerUtils.restoreRealTimer(); } promiseResolvers.length = 0; UUT.subFunction.restore(); }); it('should complete mainFunction with controlled promise resolution', async function() { const mainFunctionPromise = UUT.mainFunction(); for (let i = 1; i <= callCount; i++) { if (useGlobalClock) { clock.restore() } else { timerUtils.pauseFakeTimer(); } console.log(`Test: Restored the real time clock`); await new Promise(resolve => setTimeout(resolve, 50)); console.log(`Test: Use fake timers again`) if (useGlobalClock) { clock = sinon.useFakeTimers(); } else { timerUtils.resumeFakeTimer(); } let rCount = promiseResolvers.length; expect(rCount, `Expected ${i} resolvers but received ${rCount}`).to.equal(i); console.log(`Test: Resolving subfunction ${i}`); if (typeof promiseResolvers[i - 1] === 'function') { // Resolve the i-th subfunction's promise promiseResolvers[i - 1](); console.log(`Test: Resolved subfunction ${i}`) } else { throw new Error(`Test: Resolver for subfunction ${i} is not a function`); } console.log(`Test: Advancing fake timer for subfunction ${i}`); if (useGlobalClock) { clock.tick(1000) } else { timerUtils.currentClock.tick(1000); } } console.log(`Test: rCount is ${promiseResolvers.length}`) console.log('Test: All subfunctions resolved, advancing time for the final wait'); if (useGlobalClock) { clock.tick(2100) } else { timerUtils.currentClock.tick(2100); } console.log('Test: awaiting mainFunction promise'); await mainFunctionPromise; console.log('Test: mainFunction should be completed now'); expect(UUT.subFunction.callCount).to.equal(callCount); }); }); ```

timerUtils.js

```javascript // timerUtils.js import sinon from 'sinon'; export const timerUtils = { currentClock: null, elapsedFakeTime: 0, useFakeTimer: function() { console.log('Starting fake timer'); this.currentClock = sinon.useFakeTimers(); this.elapsedFakeTime = 0; }, pauseFakeTimer: function() { if (this.currentClock) { this.elapsedFakeTime = this.currentClock.now; console.log('Pausing fake timer at:', this.elapsedFakeTime); this.currentClock.restore(); } }, resumeFakeTimer: function() { console.log('Resuming fake timer from:', this.elapsedFakeTime); this.currentClock = sinon.useFakeTimers({ now: this.elapsedFakeTime }); }, restoreRealTimer: function() { if (this.currentClock) { console.log('Restoring real timer'); this.currentClock.restore(); this.currentClock = null; } } }; ```

Output Logs

```log // output Main Function Test UUT: Invoking subfunction 1 at 1970-01-01T00:00:00.000Z Stub: subFunction 1 called, 1970-01-01T00:00:00.000Z Test: Restored the real time clock Test: Use fake timers again Test: Resolving subfunction 1 Test: Resolved subfunction 1 Test: Advancing fake timer for subfunction 1 Test: Restored the real time clock UUT: Invoked subfunction 1 at 2023-12-31T15:36:44.323Z UUT: Invoking subfunction 2 at 2023-12-31T15:36:44.323Z Stub: subFunction 2 called, 2023-12-31T15:36:44.323Z Test: Use fake timers again Test: Resolving subfunction 2 Test: Resolved subfunction 2 Test: Advancing fake timer for subfunction 2 Test: Restored the real time clock UUT: Invoked subfunction 2 at 2023-12-31T15:36:44.376Z UUT: Invoking subfunction 3 at 2023-12-31T15:36:44.376Z Stub: subFunction 3 called, 2023-12-31T15:36:44.377Z Test: Use fake timers again Test: Resolving subfunction 3 Test: Resolved subfunction 3 Test: Advancing fake timer for subfunction 3 Test: rCount is 3 Test: All subfunctions resolved, advancing time for the final wait Test: awaiting mainFunction promise UUT: Invoked subfunction 3 at 1970-01-01T00:00:05.000Z UUT: mainFunction completed at 1970-01-01T00:00:05.000Z Test: mainFunction should be completed now ✔ should complete mainFunction with controlled promise resolution (162ms) ```

Notes

• Sometimes I noticed that there was a difference when using the global clock directly (resulted in the test using the fake time) versus using the normal timerUtils clock (resulted in the test using the real time). But the results were not always consistent. And thus the flag for useGlobalClock
• The code is a demo that showcases the issue, the original codebase is much larger.

Workaround

Avoid switching to the real time and use await Promise.resolve() which would allow resolving promises in fake time.

References

• StackOverflow Question

[fatso83]

I have a real hard understanding why you need this complicated setup. fake-timers allows you to resolve async timers and promises without resorting to all these hacks. Switching back and forth between fake timers and real timers is a big smell that something is off in the design. Try see if using the *Async versions of tick, runAll and runToLast fixes your issues (I would think so, as that's what is normally used when mixing timers and promises, i.e. micro and macro ticks).

[weshouman]

Thanks, using clock.tickAsync() was actually the solution for it.

And as for the setup complexity, this demo was a minimal snippet that only captures the issue of a larger scenario of HIL (Hardware in the loop) Simulation testing, in which real time can not be overlooked and still there's a desire of ticking the clock in the HIL test itself.

This gist shows the demo with the *Async you mentioned as part of a HIL test demo.