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.

Sign up for GitHub

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

Jump to bottom

http2: fix premature destroy #21051

Closed
wants to merge 1 commit into from
Closed

http2: fix premature destroy #21051

wants to merge 1 commit into from

Conversation

apapirovski
Copy link
Member

@apapirovski apapirovski commented May 31, 2018 •
edited
Loading

Check stream._writableState.finished instead of stream.writable as the latter can lead to premature calls to destroy and dropped writes on busy processes.

Fixes: #20750

Checklist
  • make -j4 test (UNIX), or vcbuild test (Windows) passes
  • commit message follows commit guidelines

@apapirovski
http2: fix premature destroy
e06612c 
Check stream._writableState.finished instead of stream.writable
as the latter can lead to premature calls to destroy and dropped
writes on busy processes.
@apapirovski apapirovski added the http2 Issues or PRs related to the http2 subsystem. label May 31, 2018
@nodejs-github-bot nodejs-github-bot added dont-land-on-v4.x http2 Issues or PRs related to the http2 subsystem. labels May 31, 2018
@apapirovski
Copy link
Member Author

/cc @nodejs/http2

@bzoz Could you check if this fixes the failures you were seeing on Windows? If not, please let me know what the new debugging output is as it would likely be a different / new bug. Thanks in advance!!

@apapirovski
Copy link
Member Author

CI: https://ci.nodejs.org/job/node-test-pull-request/15183/

addaleax
addaleax approved these changes May 31, 2018
View reviewed changes
Copy link
Member

@addaleax addaleax left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM if CI is good

(Maybe also /cc @ryzokuken)

@ryzokuken
Copy link
Contributor

Umm, this should fix the bug, but it uses the hidden property?

@apapirovski I understand that literally everyone in the userland uses _writeableState, but we have been trying to move away from it as much as possible in core, possibly even refactoring parts of code to remove any instances. Would you rather like to leverage this into an opportunity to change the stream class in such a way that we don't need to access _writableState anymore?

/cc @mcollina

@apapirovski
Copy link
Member Author

Landed in 7b6c428

@apapirovski apapirovski closed this Jun 3, 2018
@apapirovski apapirovski deleted the fix-http2-pipe branch June 3, 2018 14:25
apapirovski added a commit that referenced this pull request Jun 3, 2018
@apapirovski
http2: fix premature destroy
7b6c428 
Check stream._writableState.finished instead of stream.writable
as the latter can lead to premature calls to destroy and dropped
writes on busy processes.

PR-URL: #21051
Fixes: #20750
Reviewed-By: Anna Henningsen <anna@addaleax.net>
Reviewed-By: James M Snell <jasnell@gmail.com>
@bzoz
Copy link
Contributor

bzoz commented Jun 4, 2018

Sorry, this does not fix the issue:

Path: parallel/test-http2-pipe
(node:2416) ExperimentalWarning: The http2 module is an experimental API.
events.js:167
      throw er; // Unhandled 'error' event
      ^

Error: read ECONNRESET
    at TCP.onread (net.js:656:25)
Emitted 'error' event at:
    at emitErrorNT (internal/streams/destroy.js:82:8)
    at emitErrorAndCloseNT (internal/streams/destroy.js:50:3)
    at process._tickCallback (internal/process/next_tick.js:63:19)
Command: C:\Users\Administrator\Desktop\node\Release\node.exe C:\Users\Administrator\Desktop\node\test\parallel\test-http2-pipe.js

I'll try to produce the --debug-http2 --debug-nghttp2 log

@apapirovski
Copy link
Member Author

@bzoz thanks. I'm guessing there's another race condition elsewhere in the code. This would've fixed the last one I saw based on the debug logs.

@bzoz
Copy link
Contributor

bzoz commented Jun 4, 2018

Got it:

=== release test-http2-pipe ===
Path: parallel/test-http2-pipe
(node:1060) ExperimentalWarning: The http2 module is an experimental API.
Http2Session server (19) session created
Http2Session server (19) i/o stream consumed
Http2Session server (19) scheduling write
Http2Session client (24) session created
Http2Session client (24) i/o stream consumed
Http2Session client (24) scheduling write
Http2Priority: parent: 0, weight: 16, exclusive: 0
Http2Session client (24) request submitted
Http2Session client (24) submitting request
Http2Session client (24) request submitted, new stream id 1
HttpStream 1 (27) [Http2Session client (24)] queuing 1 buffers to send
HttpStream 1 (27) [Http2Session client (24)] reading starting
Http2Session server (19) sending pending data
Http2Session server (19) nghttp2 has 9 bytes to send
Http2Session server (19) wants read? 1
Http2Session client (24) sending pending data
Http2Session client (24) nghttp2 has 24 bytes to send
Http2Session client (24) nghttp2 has 9 bytes to send
Http2Session client (24) nghttp2 has 25 bytes to send
Http2Session client (24) reading outbound data for stream 1
Http2Session client (24) stream 1 has pending outbound data
Http2Session client (24) sending 16384 bytes for data frame on stream 1
Http2Session client (24) nghttp2 has 16384 bytes to send directly
Http2Session client (24) reading outbound data for stream 1
Http2Session client (24) stream 1 has pending outbound data
Http2Session client (24) sending 16384 bytes for data frame on stream 1
Http2Session client (24) nghttp2 has 16384 bytes to send directly
Http2Session client (24) reading outbound data for stream 1
Http2Session client (24) stream 1 has pending outbound data
Http2Session client (24) sending 16384 bytes for data frame on stream 1
Http2Session client (24) nghttp2 has 16384 bytes to send directly
Http2Session client (24) reading outbound data for stream 1
Http2Session client (24) stream 1 has pending outbound data
Http2Session client (24) sending 16383 bytes for data frame on stream 1
Http2Session client (24) nghttp2 has 16383 bytes to send directly
Http2Session client (24) wants read? 1
Http2Session client (24) receiving 9 bytes
Http2Session client (24) receiving 9 bytes [wants data? 1]
Http2Session client (24) complete frame received: type: 4
Http2Session client (24) settings refreshed for session
Http2Session client (24) sending pending data
Http2Session client (24) nghttp2 has 9 bytes to send
Http2Session client (24) wants read? 1
Http2Session client (24) wants read? 1
Http2Session server (19) receiving 23360 bytes
Http2Session server (19) receiving 23360 bytes [wants data? 1]
Http2Session server (19) complete frame received: type: 4
Http2Session server (19) settings refreshed for session
Http2Session server (19) beginning headers for stream 1
Http2Session server (19) complete frame received: type: 1
Http2Session server (19) handle headers frame for stream 1
HttpStream 1 (29) [Http2Session server (19)] submitting response
HttpStream 1 (29) [Http2Session server (19)] response submitted
HttpStream 1 (29) [Http2Session server (19)] reading starting
HttpStream 1 (29) [Http2Session server (19)] writable side shutdown
Http2Session server (19) buffering data chunk for stream 1, size: 16384, flags: 0
HttpStream 1 (29) [Http2Session server (19)] reading stopped
HttpStream 1 (29) [Http2Session server (19)] reading starting
Http2Session server (19) complete frame received: type: 0
Http2Session server (19) handling data frame for stream 1
Http2Session server (19) buffering data chunk for stream 1, size: 6900, flags: 0
HttpStream 1 (29) [Http2Session server (19)] reading starting
Http2Session server (19) sending pending data
Http2Session server (19) nghttp2 has 9 bytes to send
Http2Session server (19) nghttp2 has 34 bytes to send
Http2Session server (19) reading outbound data for stream 1
Http2Session server (19) no more data for stream 1
Http2Session server (19) nghttp2 has 9 bytes to send
Http2Session server (19) wants read? 1
Http2Session server (19) wants read? 1
Http2Session client (24) receiving 52 bytes
Http2Session client (24) receiving 52 bytes [wants data? 1]
Http2Session client (24) complete frame received: type: 4
Http2Session client (24) settings refreshed for session
Http2Session client (24) beginning headers for stream 1
HttpStream 1 (27) [Http2Session client (24)] starting headers, category: 1
Http2Session client (24) complete frame received: type: 1
Http2Session client (24) handle headers frame for stream 1
Http2Session client (24) complete frame received: type: 0
Http2Session client (24) handling data frame for stream 1
Http2Session client (24) sending pending data
Http2Session client (24) wants read? 1
Http2Session server (19) receiving 23360 bytes
Http2Session server (19) receiving 23360 bytes [wants data? 1]
Http2Session server (19) buffering data chunk for stream 1, size: 9484, flags: 0
HttpStream 1 (29) [Http2Session server (19)] reading stopped
Http2Session server (19) complete frame received: type: 0
Http2Session server (19) handling data frame for stream 1
Http2Session server (19) buffering data chunk for stream 1, size: 13867, flags: 0
Http2Session server (19) sending pending data
Http2Session server (19) nghttp2 has 13 bytes to send
Http2Session server (19) wants read? 1
Http2Session server (19) wants read? 1
Http2Session client (24) receiving 13 bytes
Http2Session client (24) receiving 13 bytes [wants data? 1]
Http2Session client (24) complete frame received: type: 8
Http2Session client (24) sending pending data
Http2Session client (24) wants read? 1
Http2Session server (19) receiving 7300 bytes
Http2Session server (19) receiving 7300 bytes [wants data? 1]
Http2Session server (19) buffering data chunk for stream 1, size: 2517, flags: 0
Http2Session server (19) complete frame received: type: 0
Http2Session server (19) handling data frame for stream 1
Http2Session server (19) buffering data chunk for stream 1, size: 4774, flags: 0
Http2Session server (19) sending pending data
Http2Session server (19) wants read? 1
Http2Session server (19) receiving 7300 bytes
Http2Session server (19) receiving 7300 bytes [wants data? 1]
Http2Session server (19) buffering data chunk for stream 1, size: 7300, flags: 0
Http2Session server (19) sending pending data
Http2Session server (19) wants read? 1
Http2Session server (19) receiving 4318 bytes
Http2Session server (19) receiving 4318 bytes [wants data? 1]
Http2Session server (19) buffering data chunk for stream 1, size: 4309, flags: 0
Http2Session server (19) complete frame received: type: 0
Http2Session server (19) handling data frame for stream 1
Http2Session server (19) complete frame received: type: 4
Http2Session server (19) settings refreshed for session
Http2Session server (19) sending pending data
Http2Session server (19) nghttp2 has 13 bytes to send
Http2Session server (19) wants read? 1
Http2Session server (19) wants read? 1
Http2Session client (24) receiving 13 bytes
Http2Session client (24) receiving 13 bytes [wants data? 1]
Http2Session client (24) complete frame received: type: 8
Http2Session client (24) sending pending data
Http2Session client (24) wants read? 1
HttpStream 1 (29) [Http2Session server (19)] reading starting
Http2Session server (19) scheduling write
HttpStream 1 (29) [Http2Session server (19)] reading stopped
Http2Session server (19) sending pending data
Http2Session server (19) nghttp2 has 13 bytes to send
Http2Session server (19) wants read? 1
Http2Session client (24) receiving 13 bytes
Http2Session client (24) receiving 13 bytes [wants data? 1]
Http2Session client (24) complete frame received: type: 8
Http2Session client (24) sending pending data
Http2Session client (24) reading outbound data for stream 1
Http2Session client (24) stream 1 has pending outbound data
Http2Session client (24) sending 1 bytes for data frame on stream 1
Http2Session client (24) nghttp2 has 1 bytes to send directly
Http2Session client (24) reading outbound data for stream 1
Http2Session client (24) deferring stream 1
HttpStream 1 (27) [Http2Session client (24)] queuing 1 buffers to send
Http2Session client (24) wants read? 1
Http2Session client (24) wants read? 1
Http2Session client (24) scheduling write
Http2Session client (24) sending pending data
Http2Session client (24) reading outbound data for stream 1
Http2Session client (24) stream 1 has pending outbound data
Http2Session client (24) sending 16384 bytes for data frame on stream 1
Http2Session client (24) nghttp2 has 16384 bytes to send directly
Http2Session client (24) reading outbound data for stream 1
Http2Session client (24) stream 1 has pending outbound data
Http2Session client (24) sending 16384 bytes for data frame on stream 1
Http2Session client (24) nghttp2 has 16384 bytes to send directly
Http2Session client (24) reading outbound data for stream 1
Http2Session client (24) stream 1 has pending outbound data
Http2Session client (24) sending 16384 bytes for data frame on stream 1
Http2Session client (24) nghttp2 has 16384 bytes to send directly
Http2Session client (24) reading outbound data for stream 1
Http2Session client (24) stream 1 has pending outbound data
Http2Session client (24) sending 16382 bytes for data frame on stream 1
Http2Session client (24) nghttp2 has 16382 bytes to send directly
Http2Session client (24) wants read? 1
Http2Session server (19) receiving 7310 bytes
Http2Session server (19) receiving 7310 bytes [wants data? 1]
Http2Session server (19) buffering data chunk for stream 1, size: 1, flags: 0
Http2Session server (19) complete frame received: type: 0
Http2Session server (19) handling data frame for stream 1
Http2Session server (19) buffering data chunk for stream 1, size: 7291, flags: 0
Http2Session server (19) sending pending data
Http2Session server (19) wants read? 1
Http2Session server (19) receiving 7300 bytes
Http2Session server (19) receiving 7300 bytes [wants data? 1]
Http2Session server (19) buffering data chunk for stream 1, size: 7300, flags: 0
Http2Session server (19) sending pending data
Http2Session server (19) wants read? 1
Http2Session server (19) receiving 7300 bytes
Http2Session server (19) receiving 7300 bytes [wants data? 1]
Http2Session server (19) buffering data chunk for stream 1, size: 1793, flags: 0
Http2Session server (19) complete frame received: type: 0
Http2Session server (19) handling data frame for stream 1
Http2Session server (19) buffering data chunk for stream 1, size: 5498, flags: 0
Http2Session server (19) sending pending data
Http2Session server (19) wants read? 1
Http2Session server (19) receiving 7300 bytes
Http2Session server (19) receiving 7300 bytes [wants data? 1]
Http2Session server (19) buffering data chunk for stream 1, size: 7300, flags: 0
Http2Session server (19) sending pending data
Http2Session server (19) wants read? 1
Http2Session server (19) receiving 7300 bytes
Http2Session server (19) receiving 7300 bytes [wants data? 1]
Http2Session server (19) buffering data chunk for stream 1, size: 3586, flags: 0
Http2Session server (19) complete frame received: type: 0
Http2Session server (19) handling data frame for stream 1
Http2Session server (19) buffering data chunk for stream 1, size: 3705, flags: 0
Http2Session server (19) sending pending data
Http2Session server (19) nghttp2 has 13 bytes to send
Http2Session server (19) wants read? 1
Http2Session server (19) wants read? 1
HttpStream 1 (29) [Http2Session server (19)] reading starting
Http2Session server (19) scheduling write
HttpStream 1 (29) [Http2Session server (19)] reading stopped
Http2Session server (19) sending pending data
Http2Session server (19) nghttp2 has 13 bytes to send
Http2Session server (19) wants read? 1
Http2Session client (24) receiving 13 bytes
Http2Session client (24) receiving 13 bytes [wants data? 1]
Http2Session client (24) complete frame received: type: 8
Http2Session client (24) sending pending data
Http2Session client (24) wants read? 1
Http2Session server (19) receiving 7300 bytes
Http2Session server (19) receiving 7300 bytes [wants data? 1]
Http2Session server (19) buffering data chunk for stream 1, size: 7300, flags: 0
HttpStream 1 (29) [Http2Session server (19)] reading starting
Http2Session server (19) sending pending data
Http2Session server (19) wants read? 1
Http2Session client (24) receiving 13 bytes
Http2Session client (24) receiving 13 bytes [wants data? 1]
Http2Session client (24) complete frame received: type: 8
Http2Session client (24) sending pending data
Http2Session client (24) reading outbound data for stream 1
Http2Session client (24) stream 1 has pending outbound data
Http2Session client (24) sending 2 bytes for data frame on stream 1
Http2Session client (24) nghttp2 has 2 bytes to send directly
Http2Session client (24) reading outbound data for stream 1
Http2Session client (24) deferring stream 1
HttpStream 1 (27) [Http2Session client (24)] queuing 1 buffers to send
Http2Session client (24) wants read? 1
Http2Session client (24) wants read? 1
Http2Session client (24) scheduling write
Http2Session client (24) sending pending data
Http2Session client (24) reading outbound data for stream 1
Http2Session client (24) stream 1 has pending outbound data
Http2Session client (24) sending 16312 bytes for data frame on stream 1
Http2Session client (24) nghttp2 has 16312 bytes to send directly
Http2Session client (24) reading outbound data for stream 1
Http2Session client (24) deferring stream 1
Http2Session client (24) wants read? 1
Http2Session server (19) receiving 7300 bytes
Http2Session server (19) receiving 7300 bytes [wants data? 1]
Http2Session server (19) buffering data chunk for stream 1, size: 5379, flags: 0
HttpStream 1 (29) [Http2Session server (19)] reading starting
Http2Session server (19) complete frame received: type: 0
Http2Session server (19) handling data frame for stream 1
Http2Session server (19) buffering data chunk for stream 1, size: 1912, flags: 0
HttpStream 1 (29) [Http2Session server (19)] reading starting
Http2Session server (19) sending pending data
Http2Session server (19) wants read? 1
Http2Session server (19) receiving 7300 bytes
Http2Session server (19) receiving 7300 bytes [wants data? 1]
Http2Session server (19) buffering data chunk for stream 1, size: 7300, flags: 0
HttpStream 1 (29) [Http2Session server (19)] reading starting
Http2Session server (19) sending pending data
Http2Session server (19) wants read? 1
Http2Session server (19) receiving 7300 bytes
Http2Session server (19) receiving 7300 bytes [wants data? 1]
Http2Session server (19) buffering data chunk for stream 1, size: 7170, flags: 0
HttpStream 1 (29) [Http2Session server (19)] reading starting
Http2Session server (19) complete frame received: type: 0
Http2Session server (19) handling data frame for stream 1
Http2Session server (19) buffering data chunk for stream 1, size: 2, flags: 0
HttpStream 1 (29) [Http2Session server (19)] reading starting
Http2Session server (19) complete frame received: type: 0
Http2Session server (19) handling data frame for stream 1
Http2Session server (19) buffering data chunk for stream 1, size: 110, flags: 0
HttpStream 1 (29) [Http2Session server (19)] reading starting
Http2Session server (19) sending pending data
Http2Session server (19) nghttp2 has 13 bytes to send
Http2Session server (19) wants read? 1
Http2Session server (19) wants read? 1
Http2Session client (24) receiving 13 bytes
Http2Session client (24) receiving 13 bytes [wants data? 1]
Http2Session client (24) complete frame received: type: 8
Http2Session client (24) sending pending data
Http2Session client (24) wants read? 1
Http2Session client (24) write finished with status 0
HttpStream 1 (27) [Http2Session client (24)] writable side shutdown
Http2Session client (24) scheduling write
Http2Session client (24) sending pending data
Http2Session client (24) reading outbound data for stream 1
Http2Session client (24) no more data for stream 1
Http2Session client (24) stream 1 closed with code: 0
HttpStream 1 (27) [Http2Session client (24)] closed with code 0
HttpStream 1 (27) [Http2Session client (24)] destroying stream
HttpStream 1 (27) [Http2Session client (24)] destroying stream
Http2Session client (24) nghttp2 has 9 bytes to send
Http2Session client (24) wants read? 1
Http2Session client (24) submitting goaway
Http2Session client (24) scheduling write
Http2Session client (24) destroying session
Http2Session client (24) closing session
Http2Session client (24) terminating session with code 0
Http2Session client (24) sending pending data
Http2Session client (24) nghttp2 has 17 bytes to send
Http2Session client (24) nghttp2 has 17 bytes to send
Http2Session client (24) wants read? 0
HttpStream 1 (27) [Http2Session client (24)] tearing down stream
Http2Session client (24) write finished with status -4081
Http2Session server (19) receiving 7300 bytes
Http2Session server (19) receiving 7300 bytes [wants data? 1]
Http2Session server (19) buffering data chunk for stream 1, size: 7300, flags: 0
HttpStream 1 (29) [Http2Session server (19)] reading starting
Http2Session server (19) sending pending data
Http2Session server (19) nghttp2 has 13 bytes to send
Http2Session server (19) wants read? 1
Http2Session server (19) wants read? 1
Http2Session server (19) receiving -4077 bytes
HttpStream 1 (29) [Http2Session server (19)] sending rst_stream with code 2
Http2Session server (19) sending pending data
HttpStream 1 (29) [Http2Session server (19)] destroying stream
HttpStream 1 (29) [Http2Session server (19)] destroying stream
Http2Session server (19) destroying session
Http2Session server (19) closing session
events.js:167
      throw er; // Unhandled 'error' event
      ^

Error: read ECONNRESET
    at TCP.onread (net.js:656:25)
Emitted 'error' event at:
    at emitErrorNT (internal/streams/destroy.js:82:8)
    at emitErrorAndCloseNT (internal/streams/destroy.js:50:3)
    at process._tickCallback (internal/process/next_tick.js:63:19)
Command: C:\Users\Administrator\Desktop\node\Release\node.exe C:\Users\Administrator\Desktop\node\test\parallel\test-http2-pipe.js

@bzoz bzoz mentioned this pull request Jun 5, 2018
Closed
MylesBorins pushed a commit that referenced this pull request Jun 6, 2018
@apapirovski @MylesBorins
http2: fix premature destroy
341b2c2 
Check stream._writableState.finished instead of stream.writable
as the latter can lead to premature calls to destroy and dropped
writes on busy processes.

PR-URL: #21051
Fixes: #20750
Reviewed-By: Anna Henningsen <anna@addaleax.net>
Reviewed-By: James M Snell <jasnell@gmail.com>
@MylesBorins MylesBorins mentioned this pull request Jun 6, 2018
Merged
kjin pushed a commit to kjin/node that referenced this pull request Aug 23, 2018
@apapirovski @kjin
http2: fix premature destroy
a0e58bf 
Check stream._writableState.finished instead of stream.writable
as the latter can lead to premature calls to destroy and dropped
writes on busy processes.

PR-URL: nodejs#21051
Fixes: nodejs#20750
Reviewed-By: Anna Henningsen <anna@addaleax.net>
Reviewed-By: James M Snell <jasnell@gmail.com>
kjin pushed a commit to kjin/node that referenced this pull request Sep 25, 2018
@apapirovski @kjin
http2: fix premature destroy
e4069e3 
Check stream._writableState.finished instead of stream.writable
as the latter can lead to premature calls to destroy and dropped
writes on busy processes.

PR-URL: nodejs#21051
Fixes: nodejs#20750
Reviewed-By: Anna Henningsen <anna@addaleax.net>
Reviewed-By: James M Snell <jasnell@gmail.com>
kjin pushed a commit to kjin/node that referenced this pull request Oct 16, 2018
@apapirovski @kjin
http2: fix premature destroy
3a34ebd 
Check stream._writableState.finished instead of stream.writable
as the latter can lead to premature calls to destroy and dropped
writes on busy processes.

PR-URL: nodejs#21051
Fixes: nodejs#20750
Reviewed-By: Anna Henningsen <anna@addaleax.net>
Reviewed-By: James M Snell <jasnell@gmail.com>
BethGriggs pushed a commit that referenced this pull request Oct 17, 2018
@apapirovski @BethGriggs
http2: fix premature destroy
3c8c53f 
Check stream._writableState.finished instead of stream.writable
as the latter can lead to premature calls to destroy and dropped
writes on busy processes.

Backport-PR-URL: #22850
PR-URL: #21051
Fixes: #20750
Reviewed-By: Anna Henningsen <anna@addaleax.net>
Reviewed-By: James M Snell <jasnell@gmail.com>
@BethGriggs BethGriggs mentioned this pull request Oct 30, 2018
Merged
@beevelop beevelop mentioned this pull request Nov 20, 2018
Closed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers

@jasnell jasnell jasnell approved these changes

@addaleax addaleax addaleax approved these changes

Assignees
No one assigned
Labels
http2 Issues or PRs related to the http2 subsystem.
Projects
None yet
Milestone
No milestone
Development

Successfully merging this pull request may close these issues.

flaky: parallel/test-http2-* on Windows
6 participants
@apapirovski @ryzokuken @bzoz @jasnell @addaleax @nodejs-github-bot