investigate flaky test-timers-promisified

[Trott]

Unfortunately, this test is unreliable and is failing in CI on Raspberry Pi devices. I also can make it fail trivially on my macOS laptop by running tools/test.py -j96 --repeat=192 test/parallel/test-timers-promisified.js. I haven't looked closely (yet) but in my experience, having a magic number delay variable like this in a timers test indicates an assumption that the host isn't so slow that (say) a 10ms second timer won't fire 50ms later. This assumption is, of course, incorrect if the machine has low CPU/memory (like a Raspberry Pi device) or if there are a lot of other things competing for the machine's resources (-j96 --repeat=192).

Originally posted by @Trott in #37153 (comment)

[Trott]

https://ci.nodejs.org/job/node-test-binary-arm-12+/9172/RUN_SUBSET=0,label=pi2-docker/console

00:21:00 not ok 570 parallel/test-timers-promisified
00:21:00   ---
00:21:00   duration_ms: 2.154
00:21:00   severity: fail
00:21:00   exitcode: 1
00:21:00   stack: |-
00:21:00     node:internal/process/promises:227
00:21:00               triggerUncaughtException(err, true /* fromPromise */);
00:21:00               ^
00:21:00     
00:21:00     AssertionError [ERR_ASSERTION]: iterations was 2 < 3
00:21:00         at /home/iojs/build/workspace/node-test-binary-arm/test/parallel/test-timers-promisified.js:370:14
00:21:00         at /home/iojs/build/workspace/node-test-binary-arm/test/common/index.js:376:15
00:21:00         at runNextTicks (node:internal/process/task_queues:59:5)
00:21:00         at processTimers (node:internal/timers:496:9) {
00:21:00       generatedMessage: false,
00:21:00       code: 'ERR_ASSERTION',
00:21:00       actual: false,
00:21:00       expected: true,
00:21:00       operator: '=='
00:21:00     }
00:21:00   ...

[Trott]

@nodejs/timers

[Trott]

Relevant failing test case:

node/test/parallel/test-timers-promisified.js

Lines 352 to 373 in fe43bd8

	{
	// Check that if we abort when we have some callbacks left,
	// we actually call them.
	const controller = new AbortController();
	const { signal } = controller;
	const delay = 10;
	let totalIterations = 0;
	const timeoutLoop = runInterval(async (iterationNumber) => {
	if (iterationNumber === 2) {
	await setTimeout(delay * 2);
	controller.abort();
	}
	if (iterationNumber > totalIterations) {
	totalIterations = iterationNumber;
	}
	}, delay, signal);
	timeoutLoop.catch(common.mustCall(() => {
	assert.ok(totalIterations >= 3, `iterations was ${totalIterations} < 3`);
	}));
	}
	}

[benjamingr]

cc @Linkgoron

[Trott]

It's also trivial to make it fail also by changing delay to 1 on line 357. That would suggest that we should avoid the temptation to make the test more reliable by increasing that value because that masks the problem but doesn't solve it.

[benjamingr]

@Trott I went on a quick call with @Linkgoron (we know each other in real life) and we agreed he'll open a PR removing this test for now in the meantime.

Then we should investigate why the error happens - I thought that eventhough timers didn't have a guarantee regarding running exactly after N milliseconds they were at least ordered. Apparently I was wrong.

[Trott]

Then we should investigate why the error happens - I thought that eventhough timers didn't have a guarantee regarding running exactly after N milliseconds they were at least ordered. Apparently I was wrong.

I think the problem might be that timers and intervals are in separate queues and ordering there is not guaranteed? I think? Or something close enough to that such that the solution may be to replace the timer on line 361 with an interval. Still investigating....

[Linkgoron]

@Trott There is another test that is also dependant on such ordering (the last one in the test-timers-promisifed.js) is it also introducing flakiness? The one on lines 375-393 (I couldn't make it fail using tools/test.py -j96 --repeat=192 test/parallel/test-timers-promisified.js).

[Trott]

Then we should investigate why the error happens - I thought that eventhough timers didn't have a guarantee regarding running exactly after N milliseconds they were at least ordered. Apparently I was wrong.

I think the problem might be that timers and intervals are in separate queues and ordering there is not guaranteed? I think? Or something close enough to that such that the solution may be to replace the timer on line 361 with an interval. Still investigating....

Hmm, the intervals are firing out of order, and I do think that's a bug?

Here's my modified version of the test with some really crude debugging going on. Using console.log() will introduce delays/synchronicit/something that makes it harder to cause the test to fail. So I use a foo variable to collect information instead and then print it out when everything is done.

{
    // Check that if we abort when we have some callbacks left,
    // we actually call them.
    const controller = new AbortController();
    const { signal } = controller;
    const delay = 1;
    let totalIterations = 0;
    let foo = '';
    const timeoutLoop = runInterval(async (iterationNumber) => {
      foo += `start ${iterationNumber}\n`;
      if (iterationNumber === 2) {
        foo += 'awaiting\n';
        await setTimeout(delay * 2);
        foo += 'aborting\n';
        controller.abort();
        foo += 'aborted\n';
      }
      if (iterationNumber > totalIterations) {
        totalIterations = iterationNumber;
      }
    }, delay, signal);

    timeoutLoop.catch(common.mustCall(() => {
      assert.ok(totalIterations >= 3, `iterations was ${totalIterations} < 3, ${foo}`);
      console.log(foo);
    }));
  }
}

Most of the time, the test succeeds and the output looks like this:

$ ./node --no-warnings --expose-internals test/parallel/test-timers-promisified.js
start 1
start 2
awaiting
aborting
aborted
start 3

$ 

But fairly often, the test fails and the output instead looks like this:

$ ./node --no-warnings --expose-internals test/parallel/test-timers-promisified.js
node:internal/process/promises:227
          triggerUncaughtException(err, true /* fromPromise */);
          ^

AssertionError [ERR_ASSERTION]: iterations was 2 < 3, start 1
start 2
awaiting
aborting
aborted

    at /Users/trott/io.js/test/parallel/test-timers-promisified.js:375:14
    at /Users/trott/io.js/test/common/index.js:376:15
    at runNextTicks (node:internal/process/task_queues:59:5)
    at processTimers (node:internal/timers:496:9) {
  generatedMessage: false,
  code: 'ERR_ASSERTION',
  actual: false,
  expected: true,
  operator: '=='
}
$ 

Note there is no start 1!

So, if that should be impossible, if the functions should be executing in order, then that's a legit bug to fix. On the other hand, if that should be possible, then the test needs to be changed to accommodate it.

[Trott]

Maybe the ordering problem is caused by this bit in the test?

    for await (const value of interval) {
      assert.strictEqual(value, input);
      iteration++;
      await fn(iteration);
    }

The first await "pauses" execution for iteration 1 and then iteration 2 comes along and manages to get to the second await? Something like that?

[Trott]

@Trott There is another test that is also dependant on such ordering (the last one in the test-timers-promisifed.js) is it also introducing flakiness? The one on lines 375-393 (I couldn't make it fail using tools/test.py -j96 --repeat=192 test/parallel/test-timers-promisified.js).

@Linkgoron Yeah, I can't make the other one fail either. If it is also not 100% reliable, it is much closer to 100% than the one we're talking about.

[benjamingr]

Hmm, the intervals are firing out of order, and I do think that's a bug?

Yes, I tend to agree this is a bug in our timers.

I don't actually think the queues are different (I checked the code and that's my understanding). @Linkgoron also mentioned the test fails even if you use setInterval in all cases (without mixing setInterval/setTimeout)

[Trott]

Note there is no start 1!

Whoops, there is a start 1 and I just missed it because of line-wrapping. 🤦‍♂️