OSX, intermittent - sequential/test-debug-prompt

[mhdawson]

• Version: master
• Platform: osx 1010
• Subsystem: debug

https://ci.nodejs.org/view/All/job/node-test-commit-osx/19700/nodes=osx1010/console

not ok 2255 sequential/test-debug-prompt
13:06:24   ---
13:06:24   duration_ms: 0.408
13:06:24   severity: fail
13:06:24   exitcode: 1
13:06:24   stack: |-
13:06:24     events.js:167
13:06:24           throw er; // Unhandled 'error' event
13:06:24           ^
13:06:24     
13:06:24     Error: write EPIPE
13:06:24         at WriteWrap.afterWrite [as oncomplete] (net.js:835:14)
13:06:24     Emitted 'error' event at:
13:06:24         at onwriteError (_stream_writable.js:431:12)
13:06:24         at onwrite (_stream_writable.js:456:5)
13:06:24         at _destroy (internal/streams/destroy.js:40:7)
13:06:24         at Socket._destroy (net.js:605:3)
13:06:24         at Socket.destroy (internal/streams/destroy.js:32:8)
13:06:24         at WriteWrap.afterWrite [as oncomplete] (net.js:837:10)
13:06:24   ...

[Trott]

Hmmm...a recent uptick in this one it seems. Here's one from today.

https://ci.nodejs.org/job/node-test-commit-osx/19816/nodes=osx1010/console

03:35:43 not ok 2263 sequential/test-debug-prompt
03:35:43   ---
03:35:43   duration_ms: 0.397
03:35:43   severity: fail
03:35:43   exitcode: 1
03:35:43   stack: |-
03:35:43     events.js:167
03:35:43           throw er; // Unhandled 'error' event
03:35:43           ^
03:35:43     
03:35:43     Error: write EPIPE
03:35:43         at WriteWrap.afterWrite [as oncomplete] (net.js:836:14)
03:35:43     Emitted 'error' event at:
03:35:43         at onwriteError (_stream_writable.js:431:12)
03:35:43         at onwrite (_stream_writable.js:456:5)
03:35:43         at _destroy (internal/streams/destroy.js:40:7)
03:35:43         at Socket._destroy (net.js:606:3)
03:35:43         at Socket.destroy (internal/streams/destroy.js:32:8)
03:35:43         at WriteWrap.afterWrite [as oncomplete] (net.js:838:10)
03:35:43   ...

[Trott]

And a second one today:

https://ci.nodejs.org/job/node-test-commit-osx/nodes=osx1010/19818/console

And a third:

https://ci.nodejs.org/job/node-test-commit-osx/nodes=osx1010/19821/console

And a fourth:

https://ci.nodejs.org/job/node-test-commit-osx/nodes=osx1010/19825/console

[Trott]

Looking at osx1011 too instead of just osx1010, it's happening there as well.

https://ci.nodejs.org/job/node-test-commit-osx/19817/nodes=osx1011/console

03:35:29 not ok 2263 sequential/test-debug-prompt
03:35:29   ---
03:35:29   duration_ms: 0.422
03:35:29   severity: fail
03:35:29   exitcode: 1
03:35:29   stack: |-
03:35:29     events.js:167
03:35:29           throw er; // Unhandled 'error' event
03:35:29           ^
03:35:29     
03:35:29     Error: write EPIPE
03:35:29         at WriteWrap.afterWrite [as oncomplete] (net.js:836:14)
03:35:29     Emitted 'error' event at:
03:35:29         at onwriteError (_stream_writable.js:431:12)
03:35:29         at onwrite (_stream_writable.js:456:5)
03:35:29         at _destroy (internal/streams/destroy.js:40:7)
03:35:29         at Socket._destroy (net.js:606:3)
03:35:29         at Socket.destroy (internal/streams/destroy.js:32:8)
03:35:29         at WriteWrap.afterWrite [as oncomplete] (net.js:838:10)
03:35:29   ...

[Trott]

@nodejs/platform-macos

[Trott]

Stress test to hopefully get an idea of how frequently this fails. https://ci.nodejs.org/job/node-stress-single-test/1961/nodes=osx1010/

[Trott]

This is getting out of hand. Yet another one today: https://ci.nodejs.org/job/node-test-commit-osx/19827/nodes=osx1010/console

[Trott]

FWIW, I've been unable (so far anyway) to replicate the problem on my 10.11.6 machine.

[Trott]

Also worth noting that it's happening on both the macstadium and the requireio hosts. (A lot of times, a particular failure only happens on one of our providers, but in this case, it's on both.)

[maclover7]

https://ci.nodejs.org/job/node-test-commit-osx/19832/nodes=osx1010/console

15:54:06 not ok 2263 sequential/test-debug-prompt
15:54:06   ---
15:54:06   duration_ms: 0.339
15:54:06   severity: fail
15:54:06   exitcode: 1
15:54:06   stack: |-
15:54:06     events.js:167
15:54:06           throw er; // Unhandled 'error' event
15:54:06           ^
15:54:06     
15:54:06     Error: write EPIPE
15:54:06         at WriteWrap.afterWrite [as oncomplete] (net.js:836:14)
15:54:06     Emitted 'error' event at:
15:54:06         at onwriteError (_stream_writable.js:431:12)
15:54:06         at onwrite (_stream_writable.js:456:5)
15:54:06         at _destroy (internal/streams/destroy.js:40:7)
15:54:06         at Socket._destroy (net.js:606:3)
15:54:06         at Socket.destroy (internal/streams/destroy.js:32:8)
15:54:06         at WriteWrap.afterWrite [as oncomplete] (net.js:838:10)
15:54:06   ...

[Trott]

Stress test at https://ci.nodejs.org/job/node-stress-single-test/1961/nodes=osx1010/console had 4 failures in 1000 runs, which is a lower failure rate than I expected but maybe that's host-dependent. Like, all hosts are affected but some are way more affected.

Anyway, that was with commit cee8677 so with this information, I can begin a slow-motion git bisect using the node-stress-single-test. It would be way more efficient if there was some way that I or someone else could replicate this issue locally.

Didn't look at the change, but my immediate suspicion would be 39977db. The pull request for that change is where this was first reported. And it's a change to inspector so it seems potentially relevant. So I'll see if we get a clean stress test on the commit before that and a failing stress test on that commit. If that doesn't pan out, it will at least inform the git bisect...

[Trott]

Stress test for 9374a83.

https://ci.nodejs.org/job/node-stress-single-test/1962/nodes=osx1010/

This is the commit directly before 39977db so if it comes up green, I'll do a stress test on 39977db next and see what happens...

[Trott]

Failed 1 time in 1000 runs on 9374a83. Looks like maybe I need to use something more like 10000 runs just to be sure...

[Trott]

9374a83 again but this time with 10000 runs: https://ci.nodejs.org/job/node-stress-single-test/1963/nodes=osx1010/

[Trott]

Ooof, 1 failure in 10000 runs this last time. Let's see if 10000 runs on 39977db produces substantially more failures...

https://ci.nodejs.org/job/node-stress-single-test/1964/nodes=osx1010/

[Trott]

Quite the difference! We went from 1-in-10000 failures to 2373 failures in 10000 runs.

[Trott]

So, the TL;DR: It seems that 39977db increased the failure of this test on OS X 10.10 (Yosemite) in CI from about 0.01% failure to about a 24% failure. YIkes!

[Trott]

Testing a possible fix right now that seems to be working out: https://ci.nodejs.org/job/node-stress-single-test/1965/nodes=osx1010/console

PR is #21826