Using console.log in test when useFakeTimers results in unexpected timer added from birpc package

[justrhysism]

Describe the bug

If a test contains a call to console, a setTimeout is invoked by the birpc package, which when combined with useFakeTimers can lead to unexpected results.

This does appear to only occur on first usage of console. Subsequent usages the behaviour is not exhibited. As such I've found a workaround by doing the following:

function timerBugWorkaround() {
    console.log();
    vi.clearAllTimers();
  }

beforeEach(() => {
    vi.useFakeTimers();
    timerBugWorkaround(); // Uncomment to invoke workaround
});

Unfortunately for me, I have spent many hours trying to figure out what was going on here when extra timers were being added from seemingly nowhere. Whilst this bug may not be a major issue, it does result in unexpected changes for something as common as using console.log (which is default go-to debugging tool before reaching for the inspector).

I believe this did also result in some issues from timers which are added later being automatically run without explicitly being advanced, however I can't seem to get a solid repro of that issue at this time—I haven't investigated further as I do believe it was ultimately caused by this issue.

Reproduction

https://stackblitz.com/edit/vitest-dev-vitest-qmkkke?file=test/basic.test.ts

System Info

Not relevant, repro in StackBlitz

Used Package Manager

npm

Validations

• Follow our Code of Conduct
• Read the Contributing Guidelines.
• Read the docs.
• Check that there isn't already an issue that reports the same bug to avoid creating a duplicate.
• Check that this is a concrete bug. For Q&A open a GitHub Discussion or join our Discord Chat Server.
• The provided reproduction is a minimal reproducible example of the bug.

[sheremet-va]

Cannot reproduce with the latest version. Can you confirm the issue is fixed?

[gkubisa]

TL;DR To me it looks like the RPC timeouts are managed using fake timers instead of real timers, when a test file sets up fake timers. More details below...

I randomly get Error: [birpc] timeout on calling "onTaskUpdate" using vitest@0.12.9. I see vi.advanceTimersByTime(60 * 1000); in the stack trace, which is called from one of my tests.

I set up the fake timers as follows.

beforeAll(() => {
  vi.useFakeTimers();
});
afterAll(() => {
  vi.useRealTimers();
});
beforeEach(() => {
  vi.clearAllTimers();
  vi.setSystemTime(0);
});

I use advanceTimersByTime quite a lot in the test file in which I get the error. The error happens in the "watch" mode after re-running the tests a few times by pressing "a".

Additionally, in some cases I seem to get some unexpected timers which are not scheduled by my code. I confirmed the existence of those timers using vi.getTimerCount(). I noticed this problem in the first place after migrating some tests from jest + @sinon/fake-timers to vitest - some tests started failing because vi.advanceTimersToNextTimer(); did not advance the timer as much as I expected. I worked around this issue by calling vi.advanceTimersToNextTimer(); more times. :-/

[sheremet-va]

@gkubisa would be grate if you could provide a small reproduction. i have a solution in stash, but I cannot test it :)

[gkubisa]

I'll try... I also noticed that birpc makes no effort to use real timers rather than fake timers set up by vitest.

[sheremet-va]

birpc is environment-agnostic. it shouldn’t know about such things. this issue should be handled by vitest.

[gkubisa]

birpc is environment-agnostic. it shouldn’t now about such things. this issue should be handled by vitest.

Sure, that makes sense. I was just pointing out the source of the issue. I managed to reproduce it consistently using the following snippet.

import { afterAll, beforeAll, describe, test, vi } from 'vitest';

const { setTimeout } = window;

function delay(timeout) {
  return new Promise((resolve) => {
    setTimeout(resolve, timeout);
  });
}

function checkExtraTimers(location) {
  const count = vi.getTimerCount();
  if (count > 0) {
    console.log(`got extra timers (${location}): ${count}`);
  }
}

beforeAll(() => {
  vi.useFakeTimers();
});

afterAll(() => {
  vi.useRealTimers();
});

describe.each([1, 2])('group %d', (group) => {
  test('test', async () => {
    checkExtraTimers(`group ${group}a`);
    vi.advanceTimersByTime(60000 + 1);

    await delay(10);

    checkExtraTimers(`group ${group}b`);
    vi.advanceTimersByTime(60000 + 1);
  });
});