investigate flaky test-timers-promisified

[Trott]

• Test: test/parallel/test-timers-promisified.js
• Platform: LinuxONE
• Console Output:

00:05:37 not ok 2126 parallel/test-timers-promisified
00:05:37   ---
00:05:37   duration_ms: 0.111
00:05:37   severity: fail
00:05:37   exitcode: 1
00:05:37   stack: |-
00:05:37     node:internal/process/promises:245
00:05:37               triggerUncaughtException(err, true /* fromPromise */);
00:05:37               ^
00:05:37     
00:05:37     AssertionError [ERR_ASSERTION]: second interval ran too early
00:05:37         at /home/iojs/build/workspace/node-test-commit-linuxone/nodes/rhel7-s390x/test/parallel/test-timers-promisified.js:404:12
00:05:37         at /home/iojs/build/workspace/node-test-commit-linuxone/nodes/rhel7-s390x/test/common/index.js:376:15 {
00:05:37       generatedMessage: false,
00:05:37       code: 'ERR_ASSERTION',
00:05:37       actual: false,
00:05:37       expected: true,
00:05:37       operator: '=='
00:05:37     }
00:05:37   ...

• Build Links:
  https://ci.nodejs.org/job/node-test-commit-linuxone/25660/nodes=rhel7-s390x/console

[Trott]

Refs: #37226 but this looks different

[Trott]

@benjamingr @Linkgoron

[Trott]

Here's the code that's failing. In this code, setInterval() is require('timers/promises).setInterval().

{
  // Check that the timing is correct
  let pre = false;
  let post = false;
  setPromiseTimeout(1).then(() => pre = true);
  const iterable = setInterval(() => {}, 2);
  const iterator = iterable[Symbol.asyncIterator]();

  iterator.next().then(common.mustCall(() => {
    assert.ok(pre, 'interval ran too early');
    assert.ok(!post, 'interval ran too late');
    return iterator.next();
  })).then(common.mustCall(() => {
    assert.ok(post, 'second interval ran too early');
    return iterator.return();
  }));

  setPromiseTimeout(3).then(() => post = true);
}

[benjamingr]

I think we established already that Node makes no timing guarantees (at the moment) other than:

The only guarantee is that the timeout will not execute sooner than the declared timeout interval.

(I think this behaviour is very counterintuitive, but I also acknowledge I was just not aware of it for a pretty long time - and fixing this is hard)

Since the order of timers is not guaranteed - I would write these tests using mocks (mock out Timeout or something a-la @sinon/fake-timers).

I think any fix we will make to these sort of tests is inherently flakey if it relies on a guarantee timers don't make.

[Linkgoron]

I'm not sure if this is the other bug, I think that there's timer "drift" happening here. Maybe relying on 1-2-3 ms timers wasn't such a great idea.

I agree with @benjamingr that it's difficult to fix this correctly, although with the current timer implementation I think that without the second check ('second interval ran too early') this test shouldn't fail.

[richardlau]

FWIW I’ve had a bad run of consecutive failures so I ran a stress test to check this is still flaky and hasn’t become consistently failing. It is still flaky, failing 436 times out of 1000: https://ci.nodejs.org/job/node-stress-single-test/nodes=rhel7-s390x/217/

[Trott]

FWIW I’ve had a bad run of consecutive failures so I ran a stress test to check this is still flaky and hasn’t become consistently failing. It is still flaky, failing 436 times out of 1000: https://ci.nodejs.org/job/node-stress-single-test/nodes=rhel7-s390x/217/

@richardlau #37425 is an attempt to fix this if you want to give that a review.