test-http2-large-file is flaky

[MoLow]

Test

test-http2-large-file

Platform

AIX

Console output

22:30:07 not ok 3904 sequential/test-http2-large-file
22:30:07 ---
22:30:07 duration_ms: 120107.72300
22:30:07 severity: fail
22:30:07 exitcode: -15
22:30:07 stack: |-
22:30:07 timeout
22:30:07 ...

Build links

• https://ci.nodejs.org/job/node-test-commit-aix/45967/nodes=aix72-ppc64/console

Additional information

No response

[MoLow]

I took https://ci.nodejs.org/computer/test-osuosl-aix72-ppc64_be-2/ offline to investigate

[MoLow]

on AIX tools/test.py sequential/test-http2-large-file --timeout 30 --repeat 50 reproduces easily
however, this change causes the test to be very stable and I have no idea why:

diff --git a/test/sequential/test-http2-large-file.js b/test/sequential/test-http2-large-file.js
index 2f2cc2c80d..3afcec73f4 100644
--- a/test/sequential/test-http2-large-file.js
+++ b/test/sequential/test-http2-large-file.js
@@ -24,6 +24,7 @@ server.listen(0, common.mustCall(() =>{
{settings:{initialWindowSize: 6553500 } });
 const request = client.request({':method': 'POST' });
 function writeChunk(){
+ console.log({remaining });
 if (remaining > 0){
 remaining -= chunkLength;
 request.write(chunk, writeChunk);

[Trott]

on AIX tools/test.py sequential/test-http2-large-file --timeout 30 --repeat 50 reproduces easily however, this change causes the test to be very stable and I have no idea why:

diff --git a/test/sequential/test-http2-large-file.js b/test/sequential/test-http2-large-file.js
index 2f2cc2c80d..3afcec73f4 100644
--- a/test/sequential/test-http2-large-file.js
+++ b/test/sequential/test-http2-large-file.js
@@ -24,6 +24,7 @@ server.listen(0, common.mustCall(() =>{
{settings:{initialWindowSize: 6553500 } });
 const request = client.request({':method': 'POST' });
 function writeChunk(){
+ console.log({remaining });
 if (remaining > 0){
 remaining -= chunkLength;
 request.write(chunk, writeChunk);

There's a long history of console.log() statements causing tests to succeed that otherwise fail because they are blocking or otherwise causes an I/O delay that "fixes" a race condition. I can probably find an issue from 2015 about this!

[MoLow]

it does not seem to be a race condition, this did not fix the issue:

diff --git a/test/sequential/test-http2-large-file.js b/test/sequential/test-http2-large-file.js
index 2f2cc2c80d..300e0642ab 100644
--- a/test/sequential/test-http2-large-file.js
+++ b/test/sequential/test-http2-large-file.js
@@ -24,12 +24,14 @@ server.listen(0, common.mustCall(() =>{
{settings:{initialWindowSize: 6553500 } });
 const request = client.request({':method': 'POST' });
 function writeChunk(){
- if (remaining > 0){
+ setTimeout(() =>{
+ if (remaining > 0){
 remaining -= chunkLength;
 request.write(chunk, writeChunk);
 } else{
 request.end();
 }
+ }, 10);

[Trott]

I forget (or maybe never knew!) the details, but console.log() has weird side effects that cause I/O flushing or other things and the side effects vary from platform to platform. Maybe someone on @nodejs/console or @nodejs/libuv would know more. If I recall correctly, it blocks on some platforms but not on others.

[MoLow]

process.stdout.write(''); does not make the issue go await either so it is definitely very specific to console.log

[richardlau]

@miladfarca has been investigating this as an upstream V8 issue: https://bugs.chromium.org/p/v8/issues/detail?id=13902

[MoLow]

https://ci.nodejs.org/computer/test-osuosl-aix72-ppc64_be-2/ is back online

[targos]

Happened on Windows and Linux with https://ci.nodejs.org/job/node-test-pull-request/56726/

[targos]

The V8 issue talks about disabling concurrent sparkplug to fix it temporarily but we already do it: 7071c1d

Related:

• PR trying to fix the issue: Do not drain worker tasks on main thread #47452
• PR with additional V8 fixes (now they are on main) and unskipping problematic tests: Fix concurrent sparkplug #47461