使用Jest测试包含setTimeout调用的函数踩坑记录

前两天给一个包含setTimeout调用的函数写单元测试，在使用fake timer的时候遇到了问题，记录一下。

Promise与事件队列

让我们先来看看被测函数（逻辑有简化）：

// job-queue.js
export class JobQueue {
  enqueueJob(job) {
    job.run()
      .then(() => {
        console.log(`Job ${job.id} successfully ran.`);
      })
      .catch((err) => {
        console.error(`Failed to run job ${job.id}`, err);
        setTimeout(() => {
          this.enqueueJob(job);
        }, 3000);
      });
  }
}

可以看出，这个函数的核心逻辑就是任务执行与重试：当任务执行失败的时候，等待3s后重试，如此直到执行成功为止。

为了测试执行失败时有发生重试，我编写了如下的测试用例：

// job-queue.test.js
const MockJob = jest.fn(() => {
  return {
    id: 0,
    run: jest.fn(async () => {
      console.log('Success');
    }),
  };
});

test('enqueueJob should retry 3s after failing to run the job', async () => {
  const queue = new JobQueue();
  const job = new MockJob();
  job.run.mockImplementationOnce(async () => {
    throw new Error('Always fail');
  });
  queue.enqueueJob(job);
  expect(job.run).toHaveBeenCalledTimes(1);
  await delay(3000); // Just a Promise version of setTimeout
  expect(job.run).toHaveBeenCalledTimes(2);
});

然而，在上述代码执行后，后一个expect语句却判定失败了：

image-20210823192022660.png

而如果将await delay(3000)改为await delay(4000)，用例就可以通过。

是不是两次setTimeout调用的顺序不对呢？于是，我在await delay(3000)前一行加上了日志：

image-20210823193310707.png

可以看到，我们enqueueJob里的catch回调居然是在后面打印的。猜测和JS的事件循环有关，于是我去搜索了相关资料：

在JS中有一个“事件循环”，JS运行时在每一轮Tick时，都会检查事件队列中是否有回调，如果有那么就会将它取出并执行。直到队列中需要在当前Tick执行的回调为空之后，才会进入下一轮Tick，如此循环。

而对于Promise的实现，一个Promise对象创建时传入的回调函数F会被立刻执行，但then和catch中传入的回调会被加入到队列中，在下一轮Tick时才执行（即使F中立刻resolve或reject了该Promise）。

回到我们的测试用例，原因也就明确了：调用enqueueJob之后，catch中的回调被加入了队列，而随后的delay则相当于直接调用了setTimeout（前面说到Promise对象构造时的回调函数是立刻执行的），因此我们测试用例中的setTimeout会先于enqueueJob中catch回调中的setTimeout被调用，因此expect(job.run).toHaveBeenCalledTimes(2)也就会在重试的this.enqueueJob(job)之前执行了。

而解决办法也非常简单，只需要在调用enqueueJob调用后先调用一下await delay(0)就行了，这句话意味着我们的测试用例代码在执行后面的代码之前一定要至少等待一轮Tick，于是我们catch中的回调也就有机会被调用了。

Fake timer

这样修改之后测试用例虽然可以通过了，但如果将上面的3s改成6s，我们就会遇到超时错误：

image-20210823195537643.png

这是因为Jest每个测试用例默认只给了5s。虽然从错误信息中我们知道可以通过jest.setTimeout来修改这个默认超时时间，但这个测试用例在实际运行的时候也的确需要等待6s，如果我们有什么测试用例需要等待几分钟甚至几小时，那总不能在CI上卡个几小时等待用例通过吧。

于是，搜索一番之后，我发现Jest提供了假计时器、也即fake timer相关API。

通过jest.useFakeTimers()即可对当前文件启用fake timer。当然你也可以在单个测试用例前后调用useFakeTimers和useRealTimers来在两个模式之间切换。在启用fake timer的时候，setTimeout、setInterval都会使用Jest提供的假实现，他们不会真正阻塞住测试用例。相应地，Jest还提供了advanceTimersByTime函数，可以将Jest运行测试用例时的假时钟向前拨动，并“按时”运行之前通过setTimeout、setInterval传入的回调。

于是，我们将测试用例稍作修改：

jest.useFakeTimers();

test('enqueueJob should retry 6s after failing to run the job', async () => {
  const queue = new JobQueue();
  const job = new MockJob();
  job.run.mockImplementationOnce(async () => {
    throw new Error('Always fail');
  });
  queue.enqueueJob(job);
  jest.runAllTicks();
  expect(job.run).toHaveBeenCalledTimes(1);
  jest.advanceTimersByTime(6000);
  expect(job.run).toHaveBeenCalledTimes(2);
});

我们做了以下改动：

• 使用jest.runAllTicks代替await delay(0)。根据Jest的官方文档，调用这个函数后，所有队列中的“微任务”都会被立刻执行，这里的目的就是保证catch回调能被立刻调用；
• 使用jest.advanceTimersByTime(6000)代替await delay(6000)。

看起来问题不大，然后执行测试用例之后，我们又回到了老错误：

image-20210823200648450.png

这又是怎么一回事呢？

这里首先我们需要了解“微任务（micro-task）”和“宏任务（macro-task）”。前面提到JS运行时中有一个事件队列，实际上有两个队列：微任务队列和宏任务队列。Promise的then和catch回调会将任务放入微任务队列中，我们还可以通过process.nextTick将一个回调放入微任务队列中。相对地，setTimeout和setInterval的回调则是放入宏队列中。在每一轮Tick中，JS运行时会先清空微任务队列，并且如果微任务队列中的回调被调用的过程中又往微任务队列中放入回调时，这些回调随后也会被调用，直到微任务队列被清空为止，才会开始清空宏任务队列。

这样一来，这个测试用例的表现就不符合预期了，我们的runAllTicks应该能够把catch回调执行完毕才对。

在Jest的issue列表中，我搜到了这样一条issue：

Promises use their own micro-queue for resolution, which Jest has no control over.

Also re-generated README.md via cd website && npm start; has some changes unrelated to the docs/API.md change.

咳咳……也就是说，Promise所使用的微任务队列又是另外一个微任务队列，并且不归Jest控制！

因此，问题也明确了：runAllTicks什么作用也没有发挥，我们回到了最初遇到的问题。

注意我们此时使用的是fake timer，因此是无法使用await delay(0)这个方案的，因此这会导致我们的测试用例在等待setTimeout被回调，而fake timer的setTimeout又在等待advanceTimersByTime，死循环了。

问题解决

稍微思考一下，我们会发现原来的测试用例是有问题的：不论是使用真时钟还是假时钟，在调用enqueueJob后将时间向前拨3s，并不能证明任务真的恰好在3s后执行了，只能证明在3s内执行了，enqueueJob中完全有可能错误地调用了setTimeout(/* ... */, 1500)。

因此，最后我选择了另一种断言方案：

const flushPromises = () => new Promise(resolve => setImmediate(resolve));

test('enqueueJob should retry 6s after failing to run the job', async () => {
  const mockSetTimeout = jest.spyOn(window, 'setTimeout');
  mockSetTimeout.mockImplementation(() => {
    // Do nothing
  });
  const queue = new JobQueue();
  const job = new MockJob();
  job.run.mockImplementationOnce(async () => {
    throw new Error('Always fail');
  });
  queue.enqueueJob(job);
  await flushPromises();
  expect(job.run).toHaveBeenCalledTimes(1);
  expect(mockSetTimeout).toHaveBeenCalledTimes(1);
  const [handler, timeout] = mockSetTimeout.mock.calls[0];
  expect(typeof handler).toBe('function');
  expect(timeout).toEqual(6000);
  // Now run the handler
  handler();
  await flushPromises();
  expect(job.run).toHaveBeenCalledTimes(2);
});

如上所示，我们通过Jest提供的spy函数，对setTimeout函数进行了拦截侦听，被调用时不做任何事。在我们调用完enqueueJob之后，我们通过对setTimeout的mock数据进行断言，来检查enqueueJob是否调用了setTimeout并传入了预期的时长。断言通过后，我们再手动调用传入的回调函数来模拟6s已经经过的场景。

注意，这里我们不再使用await delay(0)，而是改用了setImmediate，这是因为我们把setTimeout给mock了，所以不好使了，改用setImmediate的目的和原来是一样的。

结语

之前精力都在业务代码的编写，很少接触到JS事件队列的知识，这次编写测试用例时遇到的问题让我有机会了解了JS事件队列里的基本概念和原理，还是收获很大的。

参考资料

• https://tr.javascript.info/microtask-queue