Node: Investigate flaky test-http-destroyed-socket-write2

[Trott]

• win2012r2

[Trott]

Stress test to see if flakiness is detectable via stress test: https://ci.nodejs.org/job/node-stress-single-test/89/nodes=win2012r2/

[Trott]

Closing #4064, #4065, and #4066. All three tests were flaky in the same CI build/run on just win2012r2, but have never been flaky before. Stress test runs on all three tests did not produce any test failures. Chalking this up to something weird that probably happened inside CI itself just this one time.

/cc @nodejs/build in case it's something they want to investigate (but totally get it if no one really wants to go down that rabbit hole right now or ever).

[BridgeAR]

I am reopening this one, since it started to fail a couple of times recently.

@ronag could you have a look?

https://ci.nodejs.org/job/node-test-commit-osx/34333/nodes=osx1014/testReport/junit/(root)/test/parallel_test_http_destroyed_socket_write2/

[BridgeAR]

Stress test: https://ci.nodejs.org/job/node-stress-single-test/74/

[ronag]

EDIT: This was an incorrect analysis

This test looks invalid. The failure is hitting a valid path as far as I can see. ERR_STREAM_DESTROYED should probably be added to the list of possible errors...

There is no guarantee that Socket will detect an ungraceful disconnect and emit 'error'. _http_server is not doing anything as far as I can see to detect a premature close on the OutgoingMessage, i.e. onServerResponseClose just waits for socket 'close' and doesn't check whether is has been ended or not.

i.e. the OutgoingMessage is not guaranteed to emit 'error' which is what the test seems to assume... though it probably should... but that's a separate issue?

[BridgeAR]

@ronag would you be so kind and open a PR to fix that? That would be great!

[ronag]

@BridgeAR Sure. I'll put it on my list.

[ronag]

@BridgeAR How do I see in CI what Node version run is against? I can see the commit https://github.com/nodejs/node/commit/77e6691d442aa5d2b1a454b1cec4e7d61b8a336f but not what version that was based on.

I don't think this flakiness should be able to occur on Node 14+. Just wanted to make sure whether that's the case or whether this is for older LTS versions.

[BridgeAR]

@ronag click on "Parameters". It's v15.0.0-pre.

[ronag]

@BridgeAR Did

Stress test: ci.nodejs.org/job/node-stress-single-test/74

reproduce it? Is it reproducible with these stress test single tests?

[ronag]

Made a PR to make the test stricter. If the error occurs again after landing that PR please ping me.

[BridgeAR]

reproduce it? Is it reproducible with these stress test single tests?

It did not fail. Seems like it's difficult to reproduce that way.

[ronag]

I've landed a PR which might make this easier to debug. Please ping me if you encounter this again.

[Trott]

@ronag Just came across it now again in https://pipelines.actions.githubusercontent.com/A76h8lUgAkJrcbixwhN7BUAsUydYrQl8Ux3JbU2S9vu9HqtlrL/_apis/pipelines/1/runs/30920/signedlogcontent/17?urlExpires=2020-06-04T19%3A01%3A31.8124169Z&urlSigningMethod=HMACV1&urlSignature=mTQIwRpEDtvfZ5PIYD%2FC%2F%2F7Ky1nk17UdFua%2BYdvppzw%3D.

2020-06-04T14:33:18.1314890Z not ok 848 parallel/test-http-destroyed-socket-write2
2020-06-04T14:33:18.1316040Z   ---
2020-06-04T14:33:18.1316740Z   duration_ms: 0.213
2020-06-04T14:33:18.1316980Z   severity: fail
2020-06-04T14:33:18.1317130Z   exitcode: 1
2020-06-04T14:33:18.1317880Z   stack: |-
2020-06-04T14:33:18.1318430Z     assert.js:103
2020-06-04T14:33:18.1319340Z       throw new AssertionError(obj);
2020-06-04T14:33:18.1322280Z       ^
2020-06-04T14:33:18.1322970Z     
2020-06-04T14:33:18.1325630Z     AssertionError [ERR_ASSERTION]: Expected values to be strictly equal:
2020-06-04T14:33:18.1326820Z     + actual - expected
2020-06-04T14:33:18.1326950Z     
2020-06-04T14:33:18.1327900Z     + 'ERR_STREAM_DESTROYED'
2020-06-04T14:33:18.1328590Z     - 'ECONNRESET'
2020-06-04T14:33:18.1329810Z         at ClientRequest.<anonymous> (/Users/runner/runners/2.263.0/work/node/node/node-v15.0.0-nightly2020-06-04xxxx/test/parallel/test-http-destroyed-socket-write2.js:67:16)
2020-06-04T14:33:18.1330580Z         at ClientRequest.<anonymous> (/Users/runner/runners/2.263.0/work/node/node/node-v15.0.0-nightly2020-06-04xxxx/test/common/index.js:363:15)
2020-06-04T14:33:18.1331190Z         at ClientRequest.emit (events.js:315:20)
2020-06-04T14:33:18.1331340Z         at emitErrorNt (_http_outgoing.js:666:43)
2020-06-04T14:33:18.1331870Z         at processTicksAndRejections (internal/process/task_queues.js:85:21) {
2020-06-04T14:33:18.1333790Z       generatedMessage: true,
2020-06-04T14:33:18.1335490Z       code: 'ERR_ASSERTION',
2020-06-04T14:33:18.1335950Z       actual: 'ERR_STREAM_DESTROYED',
2020-06-04T14:33:18.1336390Z       expected: 'ECONNRESET',
2020-06-04T14:33:18.1336810Z       operator: 'strictEqual'
2020-06-04T14:33:18.1337280Z     }
2020-06-04T14:33:18.1337590Z   ...

[ronag]

@Trott: there is a revert PR pending for v14 and follow up PR's pending for master.

[Trott]

@Trott: there is a revert PR pending for v14 and follow up PR's pending for master.

Ah! OK, I was pasting that in there because the last comment said to ping if it was seen again. Awesome. Thanks.

[Trott]

Showed up in node-daily-master last night as a timeout.

https://ci.nodejs.org/job/node-test-commit-osx/35784/nodes=osx1014/consoleText

not ok 1756 parallel/test-http-destroyed-socket-write2
  ---
  duration_ms: 120.117
  severity: fail
  exitcode: -15
  stack: |-
    timeout

I am able to replicate locally on macOS:

$ tools/test.py -j96 --repeat 192 test/parallel/test-http-destroyed-socket-write2.js
=== release test-http-destroyed-socket-write2 ===                   
Path: parallel/test-http-destroyed-socket-write2
Command: out/Release/node /Users/trott/io.js/test/parallel/test-http-destroyed-socket-write2.js
--- TIMEOUT ---
[02:00|% 100|+ 191|-   1]: Done    
$

Pinging @ronag again since they may already have ideas.

[Trott]

Showed up again last night as a timeout on macOS:

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

00:46:42 not ok 1805 parallel/test-http-destroyed-socket-write2
00:46:42   ---
00:46:42   duration_ms: 120.112
00:46:42   severity: fail
00:46:42   exitcode: -15
00:46:42   stack: |-
00:46:42     timeout
00:46:42   ...

[Trott]

Able to replicate locally:

$ tools/test.py -j8 --repeat=1024  test/parallel/test-http-destroyed-socket-write2.js
=== release test-http-destroyed-socket-write2 ===                    
Path: parallel/test-http-destroyed-socket-write2
Command: out/Release/node /Users/trott/io.js/test/parallel/test-http-destroyed-socket-write2.js
--- TIMEOUT ---
=== release test-http-destroyed-socket-write2 ===                    
Path: parallel/test-http-destroyed-socket-write2
Command: out/Release/node /Users/trott/io.js/test/parallel/test-http-destroyed-socket-write2.js
--- TIMEOUT ---
[02:42|% 100|+ 1022|-   2]: Done                                     
$