Calls to `tick()` do not cause all setTimeouts to fire in specific scenarios.

[abel-matsec]

• FakeTimers version : via sinon 15.0.4, fake-timers 10.2.0
• Environment : MacOS
• Other libraries you are using: bluebird (but the bug does not pertain to just bluebird)

What did you expect to happen?

In the below unit test, I would expect all of my delayXResolved values to be true. Alternatively, when using tickAsync all things behave as I would have expected.

What actually happens

Only some of them are set to true. Subsequent calls show varying behavior of when the timers actually fire.

How to reproduce

Unit test demonstrating the issue with both sinonjs and fake-timers libs. Run via mocha with:

npx mocha --require ts-node/register ./SinonRepro.mocha.spec.ts

import * as FakeTimers from '@sinonjs/fake-timers';
import * as assert from 'assert';
import * as bluebird from 'bluebird';
import * as sinon from 'sinon';

describe('sinon.SinonFakeTimers.tick() bug repro', () => {
    it('Sinon bug repro', async () => {
        const clock = sinon.useFakeTimers();

        let delay1Resolved = false;
        let delay2Resolved = false;
        let delay3Resolved = false;
        let delay4Resolved = false;
        let delay5Resolved = false;

        // Build a simple version of delay to see if the odd behavior being
        // observed is specifically due to bluebird or something else...
        function delay<T>(ms: number, value?: T): Promise<T | undefined> {
            return new Promise(($resolve, $reject) => {
                setTimeout(() => {
                    $resolve(value);
                }, ms);
            });
        }

        async function asyncDelay1(): Promise<void> {
            bluebird
                .delay(1000)
                .then(() => {
                    delay1Resolved = true;
                })
                .catch(assert.fail);
        }

        // This function will not execute as expected when we advance time synchronously
        async function asyncDelay2(): Promise<void> {
            await bluebird.delay(1000);
            delay2Resolved = true;
        }

        async function asyncDelay4(): Promise<void> {
            await delay(1000);
            delay4Resolved = true;
        }

        async function asyncDelay5(): Promise<void> {
            await delay(1000).then(() => {
                delay5Resolved = true;
            });
        }

        // Start 3 different delay mechanisms running
        asyncDelay1().catch(assert.fail);
        asyncDelay2().catch(assert.fail);
        bluebird
            .delay(1000)
            .then(() => {
                delay3Resolved = true;
            })
            .catch(assert.fail);
        asyncDelay4().catch(assert.fail);
        asyncDelay5().catch(assert.fail);

        assert.equal(delay1Resolved, false);
        assert.equal(delay2Resolved, false);
        assert.equal(delay3Resolved, false);
        assert.equal(delay4Resolved, false);
        assert.equal(delay5Resolved, false);

        // T = 0
        clock.tick(100);
        // T = 100
        assert.equal(delay1Resolved, false);
        assert.equal(delay2Resolved, false);
        assert.equal(delay3Resolved, false);
        assert.equal(delay4Resolved, false);
        assert.equal(delay5Resolved, false);

        clock.tick(100);
        // T = 200
        assert.equal(delay1Resolved, false);
        assert.equal(delay2Resolved, false);
        assert.equal(delay3Resolved, false);
        assert.equal(delay5Resolved, false);

        // TODO: We would normally expect this to trigger the callback to set the value to true
        clock.tick(1000);
        // T = 1200
        assert.equal(delay1Resolved, true);
        assert.equal(delay2Resolved, false);
        assert.equal(delay3Resolved, true);
        assert.equal(delay4Resolved, false);
        assert.equal(delay5Resolved, false);

        // Breaking the event loop via an async call appears to trigger our custom delay impl...
        await clock.tickAsync(1);
        // T = 1201
        assert.equal(delay2Resolved, false);
        assert.equal(delay4Resolved, true);
        assert.equal(delay5Resolved, true);

        // WTF...
        await clock.tickAsync(1);
        // T = 1202
        assert.equal(delay2Resolved, true);

        clock.restore();
    });

    it('fake-timers bug repro', async () => {
        const clock = FakeTimers.install();

        let delay1Resolved = false;
        let delay2Resolved = false;
        let delay3Resolved = false;
        let delay4Resolved = false;
        let delay5Resolved = false;

        // Build a simple version of delay to see if the odd behavior being
        // observed is specifically due to bluebird or something else...
        function delay<T>(ms: number, value?: T): Promise<T | undefined> {
            return new Promise(($resolve, $reject) => {
                setTimeout(() => {
                    $resolve(value);
                }, ms);
            });
        }

        async function asyncDelay1(): Promise<void> {
            bluebird
                .delay(1000)
                .then(() => {
                    delay1Resolved = true;
                })
                .catch(assert.fail);
        }

        // This function will not execute as expected when we advance time synchronously
        async function asyncDelay2(): Promise<void> {
            await bluebird.delay(1000);
            delay2Resolved = true;
        }

        async function asyncDelay4(): Promise<void> {
            await delay(1000);
            delay4Resolved = true;
        }

        async function asyncDelay5(): Promise<void> {
            await delay(1000).then(() => {
                delay5Resolved = true;
            });
        }

        // Start 3 different delay mechanisms running
        asyncDelay1().catch(assert.fail);
        asyncDelay2().catch(assert.fail);
        bluebird
            .delay(1000)
            .then(() => {
                delay3Resolved = true;
            })
            .catch(assert.fail);
        asyncDelay4().catch(assert.fail);
        asyncDelay5().catch(assert.fail);

        assert.equal(delay1Resolved, false);
        assert.equal(delay2Resolved, false);
        assert.equal(delay3Resolved, false);
        assert.equal(delay4Resolved, false);
        assert.equal(delay5Resolved, false);

        // T = 0
        clock.tick(100);
        // T = 100
        assert.equal(delay1Resolved, false);
        assert.equal(delay2Resolved, false);
        assert.equal(delay3Resolved, false);
        assert.equal(delay4Resolved, false);
        assert.equal(delay5Resolved, false);

        clock.tick(100);
        // T = 200
        assert.equal(delay1Resolved, false);
        assert.equal(delay2Resolved, false);
        assert.equal(delay3Resolved, false);
        assert.equal(delay5Resolved, false);

        // TODO: We would normally expect this to trigger the callback to set the value to true
        clock.tick(1000);
        // T = 1200
        assert.equal(delay1Resolved, true);
        assert.equal(delay2Resolved, false);
        assert.equal(delay3Resolved, true);
        assert.equal(delay4Resolved, false);
        assert.equal(delay5Resolved, false);

        // Breaking the event loop via an async call appears to trigger our custom delay impl...
        await clock.tickAsync(1);
        // T = 1201
        assert.equal(delay2Resolved, false);
        assert.equal(delay4Resolved, true);
        assert.equal(delay5Resolved, true);

        // WTF...
        await clock.tickAsync(1);
        // T = 1202
        assert.equal(delay2Resolved, true);

        clock.uninstall();
    });
});

[fatso83]

All good then, I suppose 😸?

[abel-matsec]

Oh weird. Yeah, not all good :P didn't realize that mentioning this PR in our internal repo would close the issue... re-opening

[benjamingr]

These are async functions, when you await anything in them even if that promise is already fulfilled or it's not even a promise it will defer a microtick before continuing to run.

The reason your bluebird example sometimes "works" is that bluebird internally knows some functions are supposed to be async like setTimeout so it skips that microtick which is done here: https://github.com/petkaantonov/bluebird/blob/master/src/timers.js#L32 and subsequently the microtick is skipped here: https://github.com/petkaantonov/bluebird/blob/master/src/promise.js#L714-L717

Basically bluebird is making the assumption setTimeout is async which is fair and the mocks break that assumption which messes with timing. A little like if you do Promise.setScheduler(fn => fn()).

This is not a bug in fake-timers and there is nothing we can do to make the native promises behave like bluebird anyway - you need to await those function calls :)

[abel-matsec]

Thanks for the explanation! It might be beneficial to add some notes to the documentation for the sync methods to warn folks of edge cases like this they might run into. It was very surprising and non-obvious for us, and a helpful doc caveat could have saved a lot of time.

Thanks for the great work on this lib!

[benjamingr]

Thanks for the explanation! It might be beneficial to add some notes to the documentation for the sync methods to warn folks of edge cases like this they might run into. It was very surprising and non-obvious for us, and a helpful doc caveat could have saved a lot of time.

This is more of a bluebird caveat than a fake-timers one, though I agree a note about this potential behavior may be useful. Wanna open a docs PR :)?

[abel-matsec]

@benjamingr I'm not sure it's just a bluebird caveat. I show in my above example me defining my own util (i.e. not using bluebird), and observing similar odd behavior. I can look into maybe starting a docs PR, though I'm not sure I'll be able to explain the subtleties of tick execution as well as you guys can, but I can take a crack at it regardless.

        function delay<T>(ms: number, value?: T): Promise<T | undefined> {
            return new Promise(($resolve, $reject) => {
                setTimeout(() => {
                    $resolve(value);
                }, ms);
            });
        }