flaky test-http-server-keepalive-req-gc.js

[Trott]

• Version: 13.0.0-pre (master branch)
• Platform: SmartOS
• Subsystem: http

https://ci.nodejs.org/job/node-test-commit-smartos/nodes=smartos18-64/27655/console

04:56:09 not ok 965 parallel/test-http-server-keepalive-req-gc
04:56:09   ---
04:56:09   duration_ms: 0.345
04:56:09   severity: fail
04:56:09   exitcode: 1
04:56:09   stack: |-
04:56:09     Mismatched <anonymous> function calls. Expected exactly 1, actual 0.
04:56:09         at Object.mustCall (/home/iojs/build/workspace/node-test-commit-smartos/nodes/smartos18-64/test/common/index.js:337:10)
04:56:09         at Object.<anonymous> (/home/iojs/build/workspace/node-test-commit-smartos/nodes/smartos18-64/test/parallel/test-http-server-keepalive-req-gc.js:18:36)
04:56:09         at Module._compile (internal/modules/cjs/loader.js:936:30)
04:56:09         at Object.Module._extensions..js (internal/modules/cjs/loader.js:947:10)
04:56:09         at Module.load (internal/modules/cjs/loader.js:789:32)
04:56:09         at Function.Module._load (internal/modules/cjs/loader.js:702:12)
04:56:09         at Function.Module.runMain (internal/modules/cjs/loader.js:999:10)
04:56:09         at internal/main/run_main_module.js:17:11
04:56:09   ...

Others:

https://ci.nodejs.org/job/node-test-commit-smartos/nodes=smartos18-64/27653/console

https://ci.nodejs.org/job/node-test-commit-smartos/nodes=smartos18-64/27651/console

https://ci.nodejs.org/job/node-test-commit-smartos/nodes=smartos18-64/27649/console

https://ci.nodejs.org/job/node-test-commit-smartos/nodes=smartos18-64/27648/console

https://ci.nodejs.org/job/node-test-commit-smartos/nodes=smartos18-64/27647/console

[Trott]

@nodejs/platform-smartos @nodejs/build

[cjihrig]

FWIW, this failure is definitely not specific to SmartOS. I just observed the same failures on macOS while developing a test for #29288.

[Trott]

FWIW, this failure is definitely not specific to SmartOS. I just observed the same failures on macOS while developing a test for #29288.

I think @mcollina mentioned seeing it on macOS too. It's definitely occurring more often on SmartOS in CI, but that could very easily be more about (for example) resources that the hosts are provisioned with than OS....

[addaleax]

For those who can reproduce locally (I am unable on Linux): Could you maybe add this and share the resulting snapshot?

process.on('exit', (code) => code !== 0 && require('v8').writeHeapSnapshot());

[Trott]

For those who can reproduce locally (I am unable on Linux): Could you maybe add this and share the resulting snapshot?

process.on('exit', (code) => code !== 0 && require('v8').writeHeapSnapshot());

I'm able to reproduce reliably on macOS with this:

tools/test.py --repeat 192 parallel/test-http-server-keepalive-req-gc

For other people trying to get a heap snapshot: Adding the above exit handler didn't work, I think because common.mustCall() is failing in an exit handler itself. So I added this exit handler to mustCall() in the common module:

diff --git a/test/common/index.js b/test/common/index.js
index 98a2687222..b861ceb291 100644
--- a/test/common/index.js
+++ b/test/common/index.js
@@ -330,7 +330,10 @@ function runCallChecks(exitCode) {
     console.log(context.stack.split('\n').slice(2).join('\n'));
   });
 
-  if (failed.length) process.exit(1);
+  if (failed.length) {
+    require('v8').writeHeapSnapshot();
+    process.exit(1);
+  }
 }
 
 function mustCall(fn, exact) {

[addaleax]

@Trott Could you share the heap snapshot? And thanks for fixing that :)

[Trott]

@Trott Could you share the heap snapshot? And thanks for fixing that :)

Yeah, trying to figure out where to upload them.

[Trott]

@Trott Could you share the heap snapshot? And thanks for fixing that :)

Yeah, trying to figure out where to upload them.

@addaleax I've emailed you a link to one of the snapshot files. Let me know if you need more.

[addaleax]

@Trott Okay, it looks like the req object is not part of the heap snapshot, meaning it has likely been gc’ed, but we didn’t get the notification – Does adding a dummy setTimeout(() => {}, 100); after the global.gc() call help?

[addaleax]

Alternatively, what would be a good platform to debug this on in CI?

[Trott]

@Trott Okay, it looks like the req object is not part of the heap snapshot, meaning it has likely been gc’ed, but we didn’t get the notification – Does adding a dummy setTimeout(() => {}, 100); after the global.gc() call help?

No. Nor does changing 100 to 1000 or even 10000 (although obviously that slows the test down a lot--but it still fails frequently).

[Trott]

I think I have a solution. PR coming momentarily.

[Trott]

Proposed fix in #29347. Works for me locally.