node icon indicating copy to clipboard operation
node copied to clipboard

`test/pummel/test-timers.js` is flaky

Open avivkeller opened this issue 1 year ago • 3 comments

Test

test/pummel/test-timers.js

Platform

Linux x64

Console output

=== release test-timers ===
Path: pummel/test-timers
--- stderr ---
diff: 999
node:internal/assert/utils:281
    throw err;
    ^

AssertionError [ERR_ASSERTION]: The expression evaluated to a falsy value:

  assert.ok(1000 <= diff && diff < 1000 + WINDOW)

    at Timeout.<anonymous> (/home/runner/work/_temp/node-v23.0.0-nightly2024-09-2371eb7381f9/test/pummel/test-timers.js:39:12)
    at Timeout._onTimeout (/home/runner/work/_temp/node-v23.0.0-nightly2024-09-2371eb7381f9/test/common/index.js:493:15)
    at listOnTimeout (node:internal/timers:614:17)
    at process.processTimers (node:internal/timers:549:7) {
  generatedMessage: true,
  code: 'ERR_ASSERTION',
  actual: false,
  expected: true,
  operator: '=='
}

Node.js v23.0.0-pre
Command: out/Release/node --test-reporter=spec /home/runner/work/_temp/node-v23.0.0-nightly2024-09-2371eb7381f9/test/pummel/test-timers.js

Build links

  • https://github.com/nodejs/node/actions/runs/11001920947/job/30547830943?pr=54987#step:10:5638

Additional information

No response

avivkeller avatar Sep 23 '24 23:09 avivkeller

It is still flaky.

https://ci.nodejs.org/job/node-test-commit-arm/55372/nodes=ubuntu2204-armv7l/testReport/junit/(root)/pummel/test_timers/

---
duration_ms: 1913.169
exitcode: 1
severity: fail
stack: |-
  diff: 1003
  diff: 1682
  node:internal/assert/utils:281
      throw err;
      ^

  AssertionError [ERR_ASSERTION]: The expression evaluated to a falsy value:

    assert.ok(Math.abs(diff - t) < WINDOW * interval_count)

      at Timeout.<anonymous> (/home/iojs/build/workspace/node-test-commit-arm/test/pummel/test-timers.js:64:12)
      at Timeout._onTimeout (/home/iojs/build/workspace/node-test-commit-arm/test/common/index.js:491:15)
      at listOnTimeout (node:internal/timers:614:17)
      at process.processTimers (node:internal/timers:549:7) {
    generatedMessage: true,
    code: 'ERR_ASSERTION',
    actual: false,
    expected: true,
    operator: '=='
  }

  Node.js v23.0.0-pre
...

lpinca avatar Oct 15 '24 16:10 lpinca

Thanks for reporting 🙏 I will take a look soon

jakecastelli avatar Oct 16 '24 00:10 jakecastelli

I took some time to investigate this test failure more thoroughly. Looks like it used to fail prior to fixing the other test, so it seems we've uncovered another flaky test by resolving the previous one 😄

Joke aside. Looks like when the machine is heavily overloaded, it would have a very significant impact on scheduling / firing timers over and over. Especially this failure - here

duration_ms: 3147.927
exitcode: 1
severity: fail
stack: |-
  diff: 1002 <------- first
  diff: 1003 <------- second
  diff: 2426

The actual interval between second interval and the first interval is only 1ms difference which seems pretty wild to me.

I believe the original intent of the test was to check if setInterval allows for a tolerance of 200ms between each timer when under pressure, but the results are proving to be unpredictable.

I would consider to dig into timers a bit more and at the moment I would purpose to mark the test as flaky on the appeared platforms.

Happy for any suggestions! @nodejs/timers

jakecastelli avatar Oct 17 '24 02:10 jakecastelli

I've been monitoring the reliability report for nearly a week, and I've noticed that flakiness frequently occurs on these three platforms, but not on others (so far):

  • ubi81_container-x64-1
  • ubuntu2204_sharedlibs_container-x64-7
  • ubuntu2204_container-armv7l-1

It could be a coincidence, but I believe we can label them as flaky. I'm open to alternative suggestions.

jakecastelli avatar Oct 22 '24 03:10 jakecastelli