Node: flaky: test-stream-pipeline-http2

[refack]

• Version: master
• Platform: Windows 2008R2
• Subsystem: cli

• test file - parallel/test-stream-pipeline
• CI job windows/21650/COMPILED_BY=vs2017,RUNNER=win2008r2
• CI worker test-rackspace-win2008r2-x64-5
• output:
  17:39:25 not ok 409 parallel/test-stream-pipeline 17:39:25 --- 17:39:25 duration_ms: 120.169 17:39:25 severity: fail 17:39:25 exitcode: 1 17:39:25 stack: |- 17:39:25 timeout 17:39:25 ...

[Trott]

Replicable locally. Move to sequential?

$ tools/test.py --repeat 192 -j 96 test/parallel/test-stream-pipeline.js 
=== release test-stream-pipeline ===                    
Path: parallel/test-stream-pipeline
Command: out/Release/node /Users/trott/io.js/test/parallel/test-stream-pipeline.js
--- TIMEOUT ---
=== release test-stream-pipeline ===                   
Path: parallel/test-stream-pipeline
Command: out/Release/node /Users/trott/io.js/test/parallel/test-stream-pipeline.js
--- TIMEOUT ---
=== release test-stream-pipeline ===                   
Path: parallel/test-stream-pipeline
Command: out/Release/node /Users/trott/io.js/test/parallel/test-stream-pipeline.js
--- TIMEOUT ---
=== release test-stream-pipeline ===                   
Path: parallel/test-stream-pipeline
Command: out/Release/node /Users/trott/io.js/test/parallel/test-stream-pipeline.js
--- TIMEOUT ---
=== release test-stream-pipeline ===                   
Path: parallel/test-stream-pipeline
Command: out/Release/node /Users/trott/io.js/test/parallel/test-stream-pipeline.js
--- TIMEOUT ---
=== release test-stream-pipeline ===                   
Path: parallel/test-stream-pipeline
Command: out/Release/node /Users/trott/io.js/test/parallel/test-stream-pipeline.js
--- TIMEOUT ---
=== release test-stream-pipeline ===                   
Path: parallel/test-stream-pipeline
Command: out/Release/node /Users/trott/io.js/test/parallel/test-stream-pipeline.js
--- TIMEOUT ---
=== release test-stream-pipeline ===                   
Path: parallel/test-stream-pipeline
Command: out/Release/node /Users/trott/io.js/test/parallel/test-stream-pipeline.js
--- TIMEOUT ---
=== release test-stream-pipeline ===                   
Path: parallel/test-stream-pipeline
Command: out/Release/node /Users/trott/io.js/test/parallel/test-stream-pipeline.js
--- TIMEOUT ---
=== release test-stream-pipeline ===                   
Path: parallel/test-stream-pipeline
Command: out/Release/node /Users/trott/io.js/test/parallel/test-stream-pipeline.js
--- TIMEOUT ---
=== release test-stream-pipeline ===                   
Path: parallel/test-stream-pipeline
Command: out/Release/node /Users/trott/io.js/test/parallel/test-stream-pipeline.js
--- TIMEOUT ---
=== release test-stream-pipeline ===                   
Path: parallel/test-stream-pipeline
Command: out/Release/node /Users/trott/io.js/test/parallel/test-stream-pipeline.js
--- TIMEOUT ---
=== release test-stream-pipeline ===                   
Path: parallel/test-stream-pipeline
Command: out/Release/node /Users/trott/io.js/test/parallel/test-stream-pipeline.js
--- TIMEOUT ---
=== release test-stream-pipeline ===                   
Path: parallel/test-stream-pipeline
Command: out/Release/node /Users/trott/io.js/test/parallel/test-stream-pipeline.js
--- TIMEOUT ---
=== release test-stream-pipeline ===                   
Path: parallel/test-stream-pipeline
Command: out/Release/node /Users/trott/io.js/test/parallel/test-stream-pipeline.js
--- TIMEOUT ---
=== release test-stream-pipeline ===                   
Path: parallel/test-stream-pipeline
Command: out/Release/node /Users/trott/io.js/test/parallel/test-stream-pipeline.js
--- TIMEOUT ---
=== release test-stream-pipeline ===                   
Path: parallel/test-stream-pipeline
Command: out/Release/node /Users/trott/io.js/test/parallel/test-stream-pipeline.js
--- TIMEOUT ---
=== release test-stream-pipeline ===                   
Path: parallel/test-stream-pipeline
Command: out/Release/node /Users/trott/io.js/test/parallel/test-stream-pipeline.js
--- TIMEOUT ---
=== release test-stream-pipeline ===                   
Path: parallel/test-stream-pipeline
Command: out/Release/node /Users/trott/io.js/test/parallel/test-stream-pipeline.js
--- TIMEOUT ---
=== release test-stream-pipeline ===                   
Path: parallel/test-stream-pipeline
Command: out/Release/node /Users/trott/io.js/test/parallel/test-stream-pipeline.js
--- TIMEOUT ---
=== release test-stream-pipeline ===                   
Path: parallel/test-stream-pipeline
Command: out/Release/node /Users/trott/io.js/test/parallel/test-stream-pipeline.js
--- TIMEOUT ---
=== release test-stream-pipeline ===                   
Path: parallel/test-stream-pipeline
Command: out/Release/node /Users/trott/io.js/test/parallel/test-stream-pipeline.js
--- TIMEOUT ---
=== release test-stream-pipeline ===                   
Path: parallel/test-stream-pipeline
Command: out/Release/node /Users/trott/io.js/test/parallel/test-stream-pipeline.js
--- TIMEOUT ---
=== release test-stream-pipeline ===                   
Path: parallel/test-stream-pipeline
Command: out/Release/node /Users/trott/io.js/test/parallel/test-stream-pipeline.js
--- TIMEOUT ---
[02:19|% 100|+ 168|-  24]: Done  
$ 

[refack]

Does running with -j1 pass?

[Trott]

Does running with -j1 pass?

Yes.

$ tools/test.py --repeat 192 -j 1 test/parallel/test-stream-pipeline.js 
[00:58|% 100|+ 192|-   0]: Done  
$ 

[refack]

Since this was obsered on Windows2008R2
-j8 - https://ci.nodejs.org/job/node-stress-single-test/2084/ :x:
-j1 - https://ci.nodejs.org/job/node-stress-single-test/2085/ :x:

Seems like "sequential"izing won't solve this.

[refack]

Job: https://ci.nodejs.org/job/node-test-binary-windows/21717/COMPILED_BY=vs2017,RUNNER=win2008r2-vs2017,RUN_SUBSET=1
Worker: https://ci.nodejs.org/computer/test-rackspace-win2008r2-x64-6/

15:42:10 not ok 409 parallel/test-stream-pipeline
15:42:10   ---
15:42:10   duration_ms: 120.88
15:42:10   severity: fail
15:42:10   exitcode: 1
15:42:10   stack: |-
15:42:10     timeout
15:42:10   ...

[Trott]

Some more context from the -j1 job:

11:04:29 not ok 1 parallel/test-stream-pipeline
11:04:29   ---
11:04:29   duration_ms: 120.160
11:04:29   severity: fail
11:04:29   exitcode: 1
11:04:29   stack: |-
11:04:29     timeout
11:04:29   ...
11:04:29 2   OK: 0   NOT OK: 2   TOTAL: 200
11:04:30 TAP version 13
11:04:30 1..1
11:04:30 ok 1 parallel/test-stream-pipeline
11:04:30   ---
11:04:30   duration_ms: 0.492
11:04:30   ...

Seems like a race condition?

[Trott]

https://github.com/nodejs/node/pull/24631 is an attempt to diagnose this a bit by splitting the http2 stuff into a separate test.

[Trott]

Now that #24631 has landed, the problematic part of the test is in its own test file (test-stream-pipeline-http2.js) and marked as flaky. Leaving this issue open until the flakiness is resolved. /ping @nodejs/http2

[joyeecheung]

I am also seeing this on macOS

[joyeecheung]

 'use strict';

 const common = require('../common');
+const assert = require('assert');
+
 if (!common.hasCrypto)
   common.skip('missing crypto');
 const { Readable, pipeline } = require('stream');
@@ -14,8 +16,14 @@ const http2 = require('http2');
   server.listen(0, () => {
     const url = `http://localhost:${server.address().port}`;
     const client = http2.connect(url);
+    client.on('error', (err) => {
+      console.log(`'error':`, err);
+      assert.ifError(err);
+    });
+
     const req = client.request({ ':method': 'POST' });

+    let cnt = 10;
     const rs = new Readable({
       read() {
         rs.push('hello');
@@ -23,14 +31,21 @@ const http2 = require('http2');
     });

     pipeline(rs, req, common.mustCall((err) => {
+      common.expectsError({
+        code: 'ERR_STREAM_PREMATURE_CLOSE'
+      })(err);
+      console.log('tearing down server and client');
       server.close();
       client.close();
     }));

-    let cnt = 10;
     req.on('data', (data) => {
+      console.log(`'data' event: ${cnt}, ${data.length}`);
       cnt--;
-      if (cnt === 0) rs.destroy();
+      if (cnt === 0) {
+        console.log('destroying rs');
+        rs.destroy();
+      }
     });
   });
 }

=== release test-stream-pipeline-http2 ===
Path: parallel/test-stream-pipeline-http2
'data' event: 10, 16384
'data' event: 9, 1
'data' event: 8, 5
'data' event: 7, 16380
'data' event: 6, 5
'data' event: 5, 16380
'data' event: 4, 5
'data' event: 3, 16380
'data' event: 2, 5
'data' event: 1, 16380
destroying rs
Command: out/Release/node /Users/joyee/projects/node/test/parallel/test-stream-pipeline-http2.js

I am able to produce this locally. Looks like somehow the callback of pipeline doesn't get called when the readable string is destroyed

[joyeecheung]

HTTP2 91536: Http2Session client: created
HTTP2 91536: Http2Session client: initiating request
HTTP2 91536: Http2Session client: setting up session handle
HTTP2 91536: Http2Session client: sending settings
HTTP2 91536: Http2Session client: submitting settings
HTTP2 91536: Http2Session client: connected, initializing request
HTTP2 91536: Http2Session server: received a connection
HTTP2 91536: Http2Session server: setting up session handle
HTTP2 91536: Http2Session server: sending settings
HTTP2 91536: Http2Session server: submitting settings
HTTP2 91536: Http2Session server: created
HTTP2 91536: Http2Session client: new settings received
HTTP2 91536: Http2Session server: new settings received
HTTP2 91536: Http2Stream 1 [Http2Session server]: headers received
HTTP2 91536: Http2Stream 1 [Http2Session server]: initiating response
HTTP2 91536: Http2Session server: settings received
HTTP2 91536: Http2Session client: settings received
HTTP2 91536: Http2Stream 1 [Http2Session client]: headers received
HTTP2 91536: Http2Stream 1 [Http2Session client]: emitting stream 'response' event
HTTP2 91536: Http2Stream 1 [Http2Session client]: destroying stream
HTTP2 91536: Http2Stream 1 [Http2Session server]: closed with code 0
HTTP2 91536: Http2Stream 1 [Http2Session server]: _final shutting down
HTTP2 91536: Http2Stream 1 [Http2Session server]: destroying stream
Command: out/Release/node /Users/joyee/projects/node/test/parallel/test-stream-pipeline-http2.js

with NODE_DEBUG=http2 enabled

[joyeecheung]

With NODE_DEBUG=* enabled, this should be what happens after rs.destroy is called.

see log

HTTP2 92218: Http2Stream 1 [Http2Session client]: destroying stream
STREAM 92218: readableAddChunk null
STREAM 92218: emitReadable_ true 0 true
STREAM 92218: flow true
STREAM 92218: read undefined
STREAM 92218: endReadable false
STREAM 92218: endReadableNT false 0
STREAM 92218: unpipe
STREAM 92218: onunpipe
STREAM 92218: cleanup
STREAM 92218: pipeOnDrain 1
STREAM 92218: readableAddChunk <Buffer 68 65 6c 6c 6f 68 65 6c 6c 6f 68 65 6c 6c 6f 68 65 6c 6c 6f 68 65 6c 6c 6f 68 65 6c 6c 6f 68 65 6c 6c 6f 68 65 6c 6c 6f 68 65 6c 6c 6f 68 65 6c 6c 6f ... 985 more bytes>
STREAM 92218: readableAddChunk <Buffer 68 65 6c 6c 6f 68 65 6c 6c 6f 68 65 6c 6c 6f 68 65 6c 6c 6f 68 65 6c 6c 6f 68 65 6c 6c 6f 68 65 6c 6c 6f 68 65 6c 6c 6f 68 65 6c 6c 6f 68 65 6c 6c 6f ... 985 more bytes>
STREAM 92218: ondata
STREAM 92218: dest.write true
STREAM 92218: maybeReadMore read 0
STREAM 92218: read 0
STREAM 92218: need readable true
STREAM 92218: length less than watermark true
STREAM 92218: do read
STREAM 92218: maybeReadMore read 0
STREAM 92218: read 0
STREAM 92218: need readable true
STREAM 92218: length less than watermark true
STREAM 92218: do read
STREAM 92218: readableAddChunk <Buffer 68 65 6c 6c 6f>
STREAM 92218: readableAddChunk <Buffer 68 65 6c 6c 6f>
STREAM 92218: ondata
STREAM 92218: dest.write true
STREAM 92218: maybeReadMore read 0
STREAM 92218: read 0
STREAM 92218: need readable true
STREAM 92218: length less than watermark true
STREAM 92218: do read
STREAM 92218: maybeReadMore read 0
STREAM 92218: read 0
STREAM 92218: need readable true
STREAM 92218: length less than watermark true
STREAM 92218: do read
HTTP2 92218: Http2Stream 1 [Http2Session server]: closed with code 0
STREAM 92218: readableAddChunk null
STREAM 92218: emitReadable_ false 0 true
STREAM 92218: flow true
STREAM 92218: read undefined
STREAM 92218: endReadable false
STREAM 92218: read 0
STREAM 92218: endReadable false
HTTP2 92218: Http2Stream 1 [Http2Session server]: _final shutting down
STREAM 92218: endReadableNT false 0
STREAM 92218: readableAddChunk null
STREAM 92218: emitReadable_ false 0 true
STREAM 92218: flow true
STREAM 92218: read undefined
STREAM 92218: endReadable false
HTTP2 92218: Http2Stream 1 [Http2Session server]: destroying stream
STREAM 92218: readableAddChunk null
STREAM 92218: endReadableNT true 0
STREAM 92218: endReadableNT false 0
STREAM 92218: onend
STREAM 92218: onfinish
STREAM 92218: unpipe
STREAM 92218: onunpipe
STREAM 92218: cleanup
STREAM 92218: readableAddChunk null

For comparison this is what happens when the test does not time out

see log

HTTP2 92851: Http2Stream 1 [Http2Session client]: destroying stream
STREAM 92851: readableAddChunk null
STREAM 92851: emitReadable_ true 0 true
STREAM 92851: flow true
STREAM 92851: read undefined
STREAM 92851: endReadable false
STREAM 92851: endReadableNT false 0
STREAM 92851: unpipe
STREAM 92851: onunpipe
STREAM 92851: cleanup
STREAM 92851: pipeOnDrain 1
STREAM 92851: readableAddChunk <Buffer 68 65 6c 6c 6f 68 65 6c 6c 6f 68 65 6c 6c 6f 68 65 6c 6c 6f 68 65 6c 6c 6f 68 65 6c 6c 6f 68 65 6c 6c 6f 68 65 6c 6c 6f 68 65 6c 6c 6f 68 65 6c 6c 6f ... 10180 more bytes>
STREAM 92851: readableAddChunk <Buffer 68 65 6c 6c 6f 68 65 6c 6c 6f 68 65 6c 6c 6f 68 65 6c 6c 6f 68 65 6c 6c 6f 68 65 6c 6c 6f 68 65 6c 6c 6f 68 65 6c 6c 6f 68 65 6c 6c 6f 68 65 6c 6c 6f ... 10180 more bytes>
STREAM 92851: ondata
STREAM 92851: dest.write true
STREAM 92851: maybeReadMore read 0
STREAM 92851: read 0
STREAM 92851: need readable true
STREAM 92851: length less than watermark true
STREAM 92851: do read
STREAM 92851: maybeReadMore read 0
STREAM 92851: read 0
STREAM 92851: need readable true
STREAM 92851: length less than watermark true
STREAM 92851: do read
STREAM 92851: readableAddChunk <Buffer 68 65 6c 6c 6f 68 65 6c 6c 6f 68 65 6c 6c 6f 68 65 6c 6c 6f 68 65 6c 6c 6f 68 65 6c 6c 6f 68 65 6c 6c 6f 68 65 6c 6c 6f 68 65 6c 6c 6f 68 65 6c 6c 6f ... 5070 more bytes>
STREAM 92851: readableAddChunk <Buffer 68 65 6c 6c 6f 68 65 6c 6c 6f 68 65 6c 6c 6f 68 65 6c 6c 6f 68 65 6c 6c 6f 68 65 6c 6c 6f 68 65 6c 6c 6f 68 65 6c 6c 6f 68 65 6c 6c 6f 68 65 6c 6c 6f ... 5070 more bytes>
STREAM 92851: ondata
STREAM 92851: dest.write true
STREAM 92851: maybeReadMore read 0
STREAM 92851: read 0
STREAM 92851: need readable true
STREAM 92851: length less than watermark true
STREAM 92851: do read
STREAM 92851: maybeReadMore read 0
STREAM 92851: read 0
STREAM 92851: need readable true
STREAM 92851: length less than watermark true
STREAM 92851: do read
NET 92851: SERVER _emitCloseIfDrained
NET 92851: SERVER handle? false   connections? 1
HTTP2 92851: Http2Session client: marking session closed
HTTP2 92851: Http2Session client: submitting goaway
HTTP2 92851: Http2Session client: destroying
NET 92851: destroy
NET 92851: close
NET 92851: close handle
NET 92851: emit close
STREAM 92851: readableAddChunk <Buffer 68 65 6c 6c 6f 68 65 6c 6c 6f 68 65 6c 6c 6f 68 65 6c 6c 6f 68 65 6c 6c 6f 68 65 6c 6c 6f 68 65 6c 6c 6f 68 65 6c 6c 6f 68 65 6c 6c 6f 68 65 6c 6c 6f ... 980 more bytes>
STREAM 92851: readableAddChunk <Buffer 68 65 6c 6c 6f 68 65 6c 6c 6f 68 65 6c 6c 6f 68 65 6c 6c 6f 68 65 6c 6c 6f 68 65 6c 6c 6f 68 65 6c 6c 6f 68 65 6c 6c 6f 68 65 6c 6c 6f 68 65 6c 6c 6f ... 980 more bytes>
STREAM 92851: ondata
STREAM 92851: dest.write true
STREAM 92851: maybeReadMore read 0
STREAM 92851: read 0
STREAM 92851: need readable true
STREAM 92851: length less than watermark true
STREAM 92851: do read
STREAM 92851: maybeReadMore read 0
STREAM 92851: read 0
STREAM 92851: need readable true
STREAM 92851: length less than watermark true
STREAM 92851: do read
HTTP2 92851: Http2Session server: goaway 0 received [last stream id: 0]
HTTP2 92851: Http2Session server: marking session closed
HTTP2 92851: Http2Session server: submitting goaway
HTTP2 92851: Http2Session server: goaway 0 received [last stream id: 0]
NET 92851: destroy
NET 92851: close
NET 92851: close handle
NET 92851: has server
NET 92851: SERVER _emitCloseIfDrained
HTTP2 92851: Http2Session server: destroying
HTTP2 92851: Http2Stream 1 [Http2Session server]: destroying stream
STREAM 92851: readableAddChunk null
STREAM 92851: emitReadable_ true 0 true
STREAM 92851: flow true
STREAM 92851: read undefined
STREAM 92851: endReadable false
NET 92851: SERVER: emit close
STREAM 92851: endReadableNT false 0
STREAM 92851: readableAddChunk null
STREAM 92851: emitReadable_ false 0 true
STREAM 92851: flow true
STREAM 92851: read undefined
STREAM 92851: endReadable false
STREAM 92851: readableAddChunk null
STREAM 92851: onfinish
STREAM 92851: unpipe
STREAM 92851: onunpipe
STREAM 92851: cleanup
STREAM 92851: endReadableNT false 0
NET 92851: emit close

[joyeecheung]

cc @nodejs/streams any ideas what may cause the callback of pipeline not being called?

[mcollina]

I do not see any net activity whatsoever when it times out. This is weird and probably the source of the issue.

[Trott]

I did a git bisect and determined that the first bad commit is d3f02d0da3d574b91a15d3ace10e76014b7574fc.

When that commit was introduced, this test file did not exist. This test was pulled out of test-stream-pipeline.js when it was noticed that it was a bit flaky. So I had to copy it in to run it as part of the bisect.

Pulling this test out of that file and into its own test-stream-pipeline-http2.js file made it very flaky, at least for me locally. Maybe something changed in the test, but it's also possible that having more CPU/memory/network/whatever available makes it easier to trip the race condition.

[Trott]

@addaleax ^^^^^

[addaleax]

This should be addressed by https://github.com/nodejs/node/pull/24926 :)

[Trott]

Fixed in 83ec33b