Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Closed
mika-fischer opened this issue Oct 24, 2023 · 0 comments · Fixed by #50384
Closed

Comments

@mika-fischer
Copy link
Contributor

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

mika-fischer added a commit to mika-fischer/node that referenced this issue Oct 25, 2023
Removal of mocket timers from the priority queue was broken. It used the
timerId instead of the position in the queue as index. This lead to
removal of incorrect timers from the queue causing timers not to be
scheduled at all.

Also, aborts caused removal from the queue even when the timer was
already triggered, and thus no longer present in the queue.

Fixes: nodejs#50365
mika-fischer added a commit to mika-fischer/node that referenced this issue Oct 25, 2023
Removal of mocket timers from the priority queue was broken. It used the
timerId instead of the position in the queue as index. This lead to
removal of incorrect timers from the queue causing timers not to be
scheduled at all.

Also, aborts caused removal from the queue even when the timer was
already triggered, and thus no longer present in the queue.

Fixes: nodejs#50365
nodejs-github-bot pushed a commit that referenced this issue Nov 12, 2023
PR-URL: #50384
Fixes: #50365
Fixes: #50381
Fixes: #50382
Reviewed-By: Benjamin Gruenbaum <benjamingr@gmail.com>
Reviewed-By: Chemi Atlow <chemi@atlow.co.il>
Reviewed-By: James M Snell <jasnell@gmail.com>
targos pushed a commit that referenced this issue Nov 23, 2023
PR-URL: #50384
Fixes: #50365
Fixes: #50381
Fixes: #50382
Reviewed-By: Benjamin Gruenbaum <benjamingr@gmail.com>
Reviewed-By: Chemi Atlow <chemi@atlow.co.il>
Reviewed-By: James M Snell <jasnell@gmail.com>
UlisesGascon pushed a commit that referenced this issue Dec 11, 2023
PR-URL: #50384
Fixes: #50365
Fixes: #50381
Fixes: #50382
Reviewed-By: Benjamin Gruenbaum <benjamingr@gmail.com>
Reviewed-By: Chemi Atlow <chemi@atlow.co.il>
Reviewed-By: James M Snell <jasnell@gmail.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging a pull request may close this issue.

1 participant