javascriptasynchronoustestingpromisesinon

Switching between fake and real time using sinon.js


Summary

How to cleanly switch to real time and back again to fake time while testing with Sinon?


Details

Given the following UUT.js, UUT.test.js and timerUtils.js, I want to shift from fake time to real time, for example to advance the promise resolution, and then continue test execution in the fake time.

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, but the code pointer does not jump back from the stub to the next line in the UUT, in which Invoked ... log message is shown, unless either of the following happens:

Questions:

Code

// 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
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
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
  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


Solution

  • As mentioned in this comment, the tickAsync would allow promise resolution before executing the timers.

    With awaiting the tickAsync we could now switch to the real time in the stub and run any blocking code there before switching back to the fake time

    For further insights, This gist includes an updated implementation