Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

flaky: test-stream-pipeline-http2 #24456

Closed
refack opened this issue Nov 17, 2018 · 18 comments
Closed

flaky: test-stream-pipeline-http2 #24456

refack opened this issue Nov 17, 2018 · 18 comments
Labels
flaky-test Issues and PRs related to the tests with unstable failures on the CI. stream Issues and PRs related to the stream subsystem. windows Issues and PRs related to the Windows platform.

Comments

@refack
Copy link
Contributor

refack commented Nov 17, 2018

  • Version: master
  • Platform: Windows 2008R2
  • Subsystem: cli
@refack refack added flaky-test Issues and PRs related to the tests with unstable failures on the CI. stream Issues and PRs related to the stream subsystem. windows Issues and PRs related to the Windows platform. labels Nov 17, 2018
@Trott
Copy link
Member

Trott commented Nov 18, 2018

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
Copy link
Contributor Author

refack commented Nov 18, 2018

Does running with -j1 pass?

@Trott
Copy link
Member

Trott commented Nov 18, 2018

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
Copy link
Contributor Author

refack commented Nov 18, 2018

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

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

@refack
Copy link
Contributor Author

refack commented Nov 19, 2018

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
Copy link
Member

Trott commented Nov 24, 2018

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 added a commit to Trott/io.js that referenced this issue Nov 24, 2018
Splitting out the http2 portion of the test has a few benfits:

* We don't skip the rest of the tests if `node` is compiled without
  crypto.
* We can find out if the http2 portion of the test is responsible for
  the timeouts reported in issue 24456.

Refs: nodejs#24456
@Trott
Copy link
Member

Trott commented Nov 24, 2018

#24631 is an attempt to diagnose this a bit by splitting the http2 stuff into a separate test.

Trott added a commit to Trott/io.js that referenced this issue Nov 25, 2018
Splitting out the http2 portion of the test has a few benfits:

* We don't skip the rest of the tests if `node` is compiled without
  crypto.
* We can find out if the http2 portion of the test is responsible for
  the timeouts reported in issue 24456.

Refs: nodejs#24456

PR-URL: nodejs#24631
Reviewed-By: Refael Ackermann <refack@gmail.com>
Reviewed-By: Anna Henningsen <anna@addaleax.net>
Reviewed-By: Colin Ihrig <cjihrig@gmail.com>
@Trott Trott changed the title flaky: test-stream-pipeline flaky: test-stream-pipeline-http2 Nov 25, 2018
@Trott
Copy link
Member

Trott commented Nov 25, 2018

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

targos pushed a commit that referenced this issue Nov 25, 2018
Splitting out the http2 portion of the test has a few benfits:

* We don't skip the rest of the tests if `node` is compiled without
  crypto.
* We can find out if the http2 portion of the test is responsible for
  the timeouts reported in issue 24456.

Refs: #24456

PR-URL: #24631
Reviewed-By: Refael Ackermann <refack@gmail.com>
Reviewed-By: Anna Henningsen <anna@addaleax.net>
Reviewed-By: Colin Ihrig <cjihrig@gmail.com>
rvagg pushed a commit that referenced this issue Nov 28, 2018
Splitting out the http2 portion of the test has a few benfits:

* We don't skip the rest of the tests if `node` is compiled without
  crypto.
* We can find out if the http2 portion of the test is responsible for
  the timeouts reported in issue 24456.

Refs: #24456

PR-URL: #24631
Reviewed-By: Refael Ackermann <refack@gmail.com>
Reviewed-By: Anna Henningsen <anna@addaleax.net>
Reviewed-By: Colin Ihrig <cjihrig@gmail.com>
@joyeecheung
Copy link
Member

I am also seeing this on macOS

@joyeecheung
Copy link
Member

joyeecheung commented Dec 5, 2018

 '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
Copy link
Member

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
Copy link
Member

joyeecheung commented Dec 5, 2018

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
Copy link
Member

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

@mcollina
Copy link
Member

mcollina commented Dec 8, 2018

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

@Trott
Copy link
Member

Trott commented Dec 8, 2018

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

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
Copy link
Member

Trott commented Dec 8, 2018

@addaleax ^^^^^

Trott added a commit to Trott/io.js that referenced this issue Dec 8, 2018
addaleax added a commit to addaleax/node that referenced this issue Dec 9, 2018
HTTP/2 streams call `.end()` on themselves from their
`.destroy()` method, which might be queued (e.g. due to network
congestion) and not processed before the stream itself is destroyed.

In that case, the `_writableState.ended` property could be set before
the stream emits its `'close'` event, and never actually emits the
`'finished'` event, confusing the end-of-stream implementation so
that it wouldn’t call its callback.

This can be fixed by watching for the end events themselves using the
existing `'finish'` and `'end'` listeners rather than relying on the
`.ended` properties of the `_...State` objects.

These properties still need to be checked to know whether stream
closure was premature – My understanding is that ideally, streams
should not emit `'close'` before `'end'` and/or `'finished'`, so this
might be another bug, but changing this would require modifying tests
and almost certainly be a breaking change.

Fixes: nodejs#24456
@addaleax
Copy link
Member

addaleax commented Dec 9, 2018

This should be addressed by #24926 :)

Trott pushed a commit to Trott/io.js that referenced this issue Dec 11, 2018
HTTP/2 streams call `.end()` on themselves from their
`.destroy()` method, which might be queued (e.g. due to network
congestion) and not processed before the stream itself is destroyed.

In that case, the `_writableState.ended` property could be set before
the stream emits its `'close'` event, and never actually emits the
`'finished'` event, confusing the end-of-stream implementation so
that it wouldn’t call its callback.

This can be fixed by watching for the end events themselves using the
existing `'finish'` and `'end'` listeners rather than relying on the
`.ended` properties of the `_...State` objects.

These properties still need to be checked to know whether stream
closure was premature – My understanding is that ideally, streams
should not emit `'close'` before `'end'` and/or `'finished'`, so this
might be another bug, but changing this would require modifying tests
and almost certainly be a breaking change.

Fixes: nodejs#24456

PR-URL: nodejs#24926
Reviewed-By: Rich Trott <rtrott@gmail.com>
Reviewed-By: Luigi Pinca <luigipinca@gmail.com>
Reviewed-By: Matteo Collina <matteo.collina@gmail.com>
Reviewed-By: Franziska Hinkelmann <franziska.hinkelmann@gmail.com>
@Trott
Copy link
Member

Trott commented Dec 11, 2018

Fixed in 83ec33b

@Trott Trott closed this as completed Dec 11, 2018
BethGriggs pushed a commit that referenced this issue Dec 17, 2018
HTTP/2 streams call `.end()` on themselves from their
`.destroy()` method, which might be queued (e.g. due to network
congestion) and not processed before the stream itself is destroyed.

In that case, the `_writableState.ended` property could be set before
the stream emits its `'close'` event, and never actually emits the
`'finished'` event, confusing the end-of-stream implementation so
that it wouldn’t call its callback.

This can be fixed by watching for the end events themselves using the
existing `'finish'` and `'end'` listeners rather than relying on the
`.ended` properties of the `_...State` objects.

These properties still need to be checked to know whether stream
closure was premature – My understanding is that ideally, streams
should not emit `'close'` before `'end'` and/or `'finished'`, so this
might be another bug, but changing this would require modifying tests
and almost certainly be a breaking change.

Fixes: #24456

PR-URL: #24926
Reviewed-By: Rich Trott <rtrott@gmail.com>
Reviewed-By: Luigi Pinca <luigipinca@gmail.com>
Reviewed-By: Matteo Collina <matteo.collina@gmail.com>
Reviewed-By: Franziska Hinkelmann <franziska.hinkelmann@gmail.com>
refack pushed a commit to refack/node that referenced this issue Jan 14, 2019
Splitting out the http2 portion of the test has a few benfits:

* We don't skip the rest of the tests if `node` is compiled without
  crypto.
* We can find out if the http2 portion of the test is responsible for
  the timeouts reported in issue 24456.

Refs: nodejs#24456

PR-URL: nodejs#24631
Reviewed-By: Refael Ackermann <refack@gmail.com>
Reviewed-By: Anna Henningsen <anna@addaleax.net>
Reviewed-By: Colin Ihrig <cjihrig@gmail.com>
refack pushed a commit to refack/node that referenced this issue Jan 14, 2019
HTTP/2 streams call `.end()` on themselves from their
`.destroy()` method, which might be queued (e.g. due to network
congestion) and not processed before the stream itself is destroyed.

In that case, the `_writableState.ended` property could be set before
the stream emits its `'close'` event, and never actually emits the
`'finished'` event, confusing the end-of-stream implementation so
that it wouldn’t call its callback.

This can be fixed by watching for the end events themselves using the
existing `'finish'` and `'end'` listeners rather than relying on the
`.ended` properties of the `_...State` objects.

These properties still need to be checked to know whether stream
closure was premature – My understanding is that ideally, streams
should not emit `'close'` before `'end'` and/or `'finished'`, so this
might be another bug, but changing this would require modifying tests
and almost certainly be a breaking change.

Fixes: nodejs#24456

PR-URL: nodejs#24926
Reviewed-By: Rich Trott <rtrott@gmail.com>
Reviewed-By: Luigi Pinca <luigipinca@gmail.com>
Reviewed-By: Matteo Collina <matteo.collina@gmail.com>
Reviewed-By: Franziska Hinkelmann <franziska.hinkelmann@gmail.com>
BethGriggs pushed a commit that referenced this issue Feb 11, 2019
Splitting out the http2 portion of the test has a few benfits:

* We don't skip the rest of the tests if `node` is compiled without
  crypto.
* We can find out if the http2 portion of the test is responsible for
  the timeouts reported in issue 24456.

Refs: #24456

PR-URL: #24631
Reviewed-By: Refael Ackermann <refack@gmail.com>
Reviewed-By: Anna Henningsen <anna@addaleax.net>
Reviewed-By: Colin Ihrig <cjihrig@gmail.com>
BethGriggs pushed a commit that referenced this issue Feb 12, 2019
HTTP/2 streams call `.end()` on themselves from their
`.destroy()` method, which might be queued (e.g. due to network
congestion) and not processed before the stream itself is destroyed.

In that case, the `_writableState.ended` property could be set before
the stream emits its `'close'` event, and never actually emits the
`'finished'` event, confusing the end-of-stream implementation so
that it wouldn’t call its callback.

This can be fixed by watching for the end events themselves using the
existing `'finish'` and `'end'` listeners rather than relying on the
`.ended` properties of the `_...State` objects.

These properties still need to be checked to know whether stream
closure was premature – My understanding is that ideally, streams
should not emit `'close'` before `'end'` and/or `'finished'`, so this
might be another bug, but changing this would require modifying tests
and almost certainly be a breaking change.

Fixes: #24456

PR-URL: #24926
Reviewed-By: Rich Trott <rtrott@gmail.com>
Reviewed-By: Luigi Pinca <luigipinca@gmail.com>
Reviewed-By: Matteo Collina <matteo.collina@gmail.com>
Reviewed-By: Franziska Hinkelmann <franziska.hinkelmann@gmail.com>
BethGriggs pushed a commit that referenced this issue Feb 20, 2019
HTTP/2 streams call `.end()` on themselves from their
`.destroy()` method, which might be queued (e.g. due to network
congestion) and not processed before the stream itself is destroyed.

In that case, the `_writableState.ended` property could be set before
the stream emits its `'close'` event, and never actually emits the
`'finished'` event, confusing the end-of-stream implementation so
that it wouldn’t call its callback.

This can be fixed by watching for the end events themselves using the
existing `'finish'` and `'end'` listeners rather than relying on the
`.ended` properties of the `_...State` objects.

These properties still need to be checked to know whether stream
closure was premature – My understanding is that ideally, streams
should not emit `'close'` before `'end'` and/or `'finished'`, so this
might be another bug, but changing this would require modifying tests
and almost certainly be a breaking change.

Fixes: #24456

PR-URL: #24926
Reviewed-By: Rich Trott <rtrott@gmail.com>
Reviewed-By: Luigi Pinca <luigipinca@gmail.com>
Reviewed-By: Matteo Collina <matteo.collina@gmail.com>
Reviewed-By: Franziska Hinkelmann <franziska.hinkelmann@gmail.com>
rvagg pushed a commit that referenced this issue Feb 28, 2019
Splitting out the http2 portion of the test has a few benfits:

* We don't skip the rest of the tests if `node` is compiled without
  crypto.
* We can find out if the http2 portion of the test is responsible for
  the timeouts reported in issue 24456.

Refs: #24456

PR-URL: #24631
Reviewed-By: Refael Ackermann <refack@gmail.com>
Reviewed-By: Anna Henningsen <anna@addaleax.net>
Reviewed-By: Colin Ihrig <cjihrig@gmail.com>
rvagg pushed a commit that referenced this issue Feb 28, 2019
HTTP/2 streams call `.end()` on themselves from their
`.destroy()` method, which might be queued (e.g. due to network
congestion) and not processed before the stream itself is destroyed.

In that case, the `_writableState.ended` property could be set before
the stream emits its `'close'` event, and never actually emits the
`'finished'` event, confusing the end-of-stream implementation so
that it wouldn’t call its callback.

This can be fixed by watching for the end events themselves using the
existing `'finish'` and `'end'` listeners rather than relying on the
`.ended` properties of the `_...State` objects.

These properties still need to be checked to know whether stream
closure was premature – My understanding is that ideally, streams
should not emit `'close'` before `'end'` and/or `'finished'`, so this
might be another bug, but changing this would require modifying tests
and almost certainly be a breaking change.

Fixes: #24456

PR-URL: #24926
Reviewed-By: Rich Trott <rtrott@gmail.com>
Reviewed-By: Luigi Pinca <luigipinca@gmail.com>
Reviewed-By: Matteo Collina <matteo.collina@gmail.com>
Reviewed-By: Franziska Hinkelmann <franziska.hinkelmann@gmail.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
flaky-test Issues and PRs related to the tests with unstable failures on the CI. stream Issues and PRs related to the stream subsystem. windows Issues and PRs related to the Windows platform.
Projects
None yet
6 participants
@mcollina @refack @Trott @addaleax @joyeecheung and others