Skip to content

test_runner: mock timer promisified setTimeout cleanup goes wrong losing some timers #50365

Closed
@mika-fischer

Description

@mika-fischer

Version

v20.5.1

Platform

Linux s7 5.15.0-69-generic #76-Ubuntu SMP Fri Mar 17 17:19:29 UTC 2023 x86_64 x86_64 x86_64 GNU/Linux

Subsystem

test

What steps will reproduce the bug?

The promisified mocked setTimeout sometimes cleans up the wrong timers. This always happens if the id of the timer diverges from the position in the priority queue.

The main reason is that the id of the timer is passed to PriorityQueue.removeAt instead of the position in the priority queue. Additionally, if the signal passed to setTimeout is aborted after the timer already fired, removeAt will be called, even though the timer is no longer in the priority queue.

I can prepare a PR for this. Should I base this on #50331 or on main?

import assert from "node:assert";
import { test } from "node:test";
import timers from "node:timers/promises";

test("aborting setTimeout clears wrong timer", async (t) => {
  const f1 = t.mock.fn();
  const f2 = t.mock.fn();
  t.mock.timers.enable();
  const ac = new AbortController();

  // id 1 & pos 1 in priority queue
  timers.setTimeout(100, undefined, { signal: ac.signal }).then(f1, f1);
  // id 2 & pos 1 in priority queue (id 1 is moved to pos 2)
  timers.setTimeout(50).then(f2, f2);

  ac.abort(); // BUG: will remove timer at pos 1 not timer with id 1!

  t.mock.timers.runAll();
  await Promise.resolve(); // let promises settle

  // First setTimeout is aborted
  assert.strictEqual(f1.mock.callCount(), 1);
  assert.strictEqual(f1.mock.calls[0].arguments[0].code, "ABORT_ERR");

  // Second setTimeout should resolve, but never settles, because it was eronously removed by ac.abort()
  assert.strictEqual(f2.mock.callCount(), 1);
});

test("aborting setTimeout after timer is already triggered clear wrong timer", async (t) => {
  const f1 = t.mock.fn();
  const f2 = t.mock.fn();
  t.mock.timers.enable();
  const ac = new AbortController();

  // id 1 & pos 1 in priority queue
  timers.setTimeout(50, true, { signal: ac.signal }).then(f1, f1);
  // id 2 & pos 2 in priority queue
  timers.setTimeout(100).then(f2, f2);

  // First setTimeout resolves
  t.mock.timers.tick(50);
  await Promise.resolve(); // let promises settle
  assert.strictEqual(f1.mock.callCount(), 1);
  assert.strictEqual(f1.mock.calls[0].arguments.length, 1);
  assert.strictEqual(f1.mock.calls[0].arguments[0], true);

  // Now timer with id 2 will be at pos 1 in priority queue
  ac.abort(); // BUG: will remove timer at pos 1 not timer with id 1!

  // Second setTimeout should resolve, but never settles, because it was eronously removed by ac.abort()
  t.mock.timers.runAll();
  await Promise.resolve(); // let promises settle
  assert.strictEqual(f2.mock.callCount(), 1);
});

fails with

❯ ~/src/libs/node/node index.mjs
✖ aborting setTimeout clears wrong timer (3.909688ms)
  AssertionError [ERR_ASSERTION]: Expected values to be strictly equal:
  
  0 !== 1
  
      at TestContext.<anonymous> (file:///home/mfischer/src/tests/node-mock-timers/index.mjs:21:10)
      at async Test.run (node:internal/test_runner/test:581:9)
      at async startSubtest (node:internal/test_runner/harness:204:3) {
    generatedMessage: true,
    code: 'ERR_ASSERTION',
    actual: 0,
    expected: 1,
    operator: 'strictEqual'
  }

✖ aborting setTimeout after timer is already triggered clear wrong timer (0.395849ms)
  AssertionError [ERR_ASSERTION]: Expected values to be strictly equal:
  
  0 !== 1
  
      at TestContext.<anonymous> (file:///home/mfischer/src/tests/node-mock-timers/index.mjs:45:10)
      at async Test.run (node:internal/test_runner/test:581:9)
      at async Test.processPendingSubtests (node:internal/test_runner/test:325:7) {
    generatedMessage: true,
    code: 'ERR_ASSERTION',
    actual: 0,
    expected: 1,
    operator: 'strictEqual'
  }
[...]

How often does it reproduce? Is there a required condition?

Always

What is the expected behavior? Why is that the expected behavior?

All timers should fire and be cleaned up as expected

What do you see instead?

Some timers never fire because they are cleaned up eronseously

Additional information

No response

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions