test: test-cluster-send-handle-large-payload intermittent failures

[matthewloring]

• Version: master
• Platform: OS X
• Subsystem: Test

This test seems to be timing out sometimes. Introduced by #14588.

\cc @addaleax

[addaleax]

Hm, I ran a stress test on the original PR because it had been flaky before, but that came back green, and a local stress test worked fine for me too, so I assume this is something platform-specific. So, uh, here are two stress tests to narrow that down a bit:

OS X: https://ci.nodejs.org/job/node-stress-single-test/1367/
Linux: https://ci.nodejs.org/job/node-stress-single-test/1368/

[matthewloring]

I think @bnoordhuis has experienced this too (#14730 (review)). He may have suggestions on reproducing it. For me it happens fairly infrequently (~1 in 20 runs).

[addaleax]

@nodejs/platform-macos … I don’t have access to OS X myself, but I am available to anybody who wants me do help debug my mistakes ;)

[Trott]

I can replicate this locally. This might work on whatever your local OS is as well to replicate it:

$ tools/test.py -j 96 --repeat 192 test/parallel/test-cluster-send-handle-large-payload.js 
=== release test-cluster-send-handle-large-payload ===                    
Path: parallel/test-cluster-send-handle-large-payload
Command: out/Release/node /Users/trott/io.js/test/parallel/test-cluster-send-handle-large-payload.js
--- TIMEOUT ---
=== release test-cluster-send-handle-large-payload ===                   
Path: parallel/test-cluster-send-handle-large-payload
Command: out/Release/node /Users/trott/io.js/test/parallel/test-cluster-send-handle-large-payload.js
--- TIMEOUT ---
=== release test-cluster-send-handle-large-payload ===                   
Path: parallel/test-cluster-send-handle-large-payload
Command: out/Release/node /Users/trott/io.js/test/parallel/test-cluster-send-handle-large-payload.js
--- TIMEOUT ---
=== release test-cluster-send-handle-large-payload ===                   
Path: parallel/test-cluster-send-handle-large-payload
Command: out/Release/node /Users/trott/io.js/test/parallel/test-cluster-send-handle-large-payload.js
--- TIMEOUT ---
=== release test-cluster-send-handle-large-payload ===                   
Path: parallel/test-cluster-send-handle-large-payload
Command: out/Release/node /Users/trott/io.js/test/parallel/test-cluster-send-handle-large-payload.js
--- TIMEOUT ---
=== release test-cluster-send-handle-large-payload ===                   
Path: parallel/test-cluster-send-handle-large-payload
Command: out/Release/node /Users/trott/io.js/test/parallel/test-cluster-send-handle-large-payload.js
--- TIMEOUT ---
=== release test-cluster-send-handle-large-payload ===                   
Path: parallel/test-cluster-send-handle-large-payload
Command: out/Release/node /Users/trott/io.js/test/parallel/test-cluster-send-handle-large-payload.js
--- TIMEOUT ---
=== release test-cluster-send-handle-large-payload ===                   
Path: parallel/test-cluster-send-handle-large-payload
Command: out/Release/node /Users/trott/io.js/test/parallel/test-cluster-send-handle-large-payload.js
--- TIMEOUT ---
=== release test-cluster-send-handle-large-payload ===                   
Path: parallel/test-cluster-send-handle-large-payload
Command: out/Release/node /Users/trott/io.js/test/parallel/test-cluster-send-handle-large-payload.js
--- TIMEOUT ---
=== release test-cluster-send-handle-large-payload ===                   
Path: parallel/test-cluster-send-handle-large-payload
Command: out/Release/node /Users/trott/io.js/test/parallel/test-cluster-send-handle-large-payload.js
--- TIMEOUT ---
=== release test-cluster-send-handle-large-payload ===                   
Path: parallel/test-cluster-send-handle-large-payload
Command: out/Release/node /Users/trott/io.js/test/parallel/test-cluster-send-handle-large-payload.js
--- TIMEOUT ---
=== release test-cluster-send-handle-large-payload ===                   
Path: parallel/test-cluster-send-handle-large-payload
Command: out/Release/node /Users/trott/io.js/test/parallel/test-cluster-send-handle-large-payload.js
--- TIMEOUT ---
=== release test-cluster-send-handle-large-payload ===                   
Path: parallel/test-cluster-send-handle-large-payload
Command: out/Release/node /Users/trott/io.js/test/parallel/test-cluster-send-handle-large-payload.js
--- TIMEOUT ---
[02:11|% 100|+ 179|-  13]: Done 
$

First 96 tests pass in about 11 seconds, and then it pauses for two minutes as some of the tests (13 above) time out.

Easiest/fastest solution would be to move the test to sequential, but of course that might not be the best solution.
¯\(ツ)/¯

[addaleax]

Easiest/fastest solution would be to move the test to sequential, but of course that might not be the best solution.

Every time somebody proposes that, I think either the test is broken or Node is broken. ;) I don’t think there’s a reason to assume this test should be flaky under load.

[addaleax]

Also, no, no luck reproducing under Linux, no matter how many parallel jobs.

[Trott]

Also, no, no luck reproducing under Linux, no matter how many parallel jobs.

Looks like -j doesn't even have that much to do with it other than making it happen more reliably. I'm seeing it with just tools/test.py -j 1 --repeat 192 test/parallel/test-cluster-send-handle-large-payload.js

[addaleax]

@Trott Any chance you could do some digging and figure out whether it’s the parent or the child process that’s hanging? And which handles are keeping it open (assuming it’s stuck with 0 % CPU, not 100 % CPU)?

[Trott]

@addaleax Yes, looking right now...might have to stop for a few meetings, but will pick up again later if so...

[Trott]

When this times out, the process.send() in the subprocess is getting called, but the message event on worker is not being emitted (or at least the listener is not being invoked).

If I add a callback to process.send(), it never indicates an error in this test, whether the test succeeds or times out.

Judging from #6767, process.send() may be fire-and-forget. Maybe the message gets received and maybe not.

I don't know why macOS would be more susceptible to missing the message than anything else. If this is not-a-bug behavior, I guess we can add a retry. If this is a bug... ¯\(ツ)/¯

The .send() from the parent process to the subprocess never seems to fail.

[addaleax]

Okay, so this might be fix-able by adding an extra round-trip. I can try that on the weekend if nobody beats me to it.

[Trott]

If the process.send() message getting dropped from time to time is a case of working-as-expected, I have a fix for the test ready to go. If, on the other hand, that's a bug in process.send() that might even be specific to macOS, then uh, yeah, that's gonna take some deeper looking.

[addaleax]

@Trott I think the discussion in the issue you linked means that, if the problem actually is “the process exits before process.send() can finish”, then yes, that may be things working as expected.

(I’m not convinced that issue shouldn’t be re-opened, but that’s another story.)

[Trott]

I think the discussion in the issue you linked means that, if the problem actually is “the process exits before process.send() can finish”,

@addaleax Unfortunately, that doesn't appear to be what's going on here. :-( If I keep the event loop open in the child process, the message is still sometimes never received and the test times out.

(Interestingly, if I add a useless console.log() in the right place, I can get the test to be reliable. I've seen this troubling behavior manifest before. Someone once gave me an explanation for it, but I can't remember what it was right now. But maybe that hints in the right direction?)

EDIT: (Yeah, the "I have a fix ready to go" above...not so much.)

[addaleax]

Interestingly, if I add a useless console.log() in the right place, I can get the test to be reliable.

That sounds weird, I don’t think I have heard of that and I’m not sure what that means.

dtruss -f output for the test might be nice, but I’d be too tired to really dig into it right now anyway. Have fun playing around with the test if you like :)

[Trott]

Just so I don't forget what it was: Put a console.log() statement as the last line of the process.on('message',...) handler and the test is no longer flaky.
(╯°□°)╯︵ ┻━┻

[Trott]

OK, good news is I have a simple fix.

Bad news is that I suspect it covers up a legitimate bug. Not sure, though.

Basically, if the child process waits a bit before sending the payload back, the message is always received, and the test passes reliably.

That seems like a code smell to me. I thought I was pretty thorough in checking for events I might listen to that might seem like less a less code-smelly approach, but I'm going to go look again.

[Trott]

Fix (if it is indeed an OS quirk and not a bug) in #14780.