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

http2: [8.x] server stream emits error after close #24559

Closed
Flarna opened this issue Nov 21, 2018 · 22 comments
Closed

http2: [8.x] server stream emits error after close #24559

Flarna opened this issue Nov 21, 2018 · 22 comments
Assignees

Comments

@Flarna
Copy link
Member

Flarna commented Nov 21, 2018

  • Version: 8.13.0
  • Platform: Tested on Windows I expect it's platform independent
  • Subsystem: http2

With 8.13.0 http2 server stream emits error after close whereas 10.13.0 and 11.2.0 emit error before close.

I was expecting that 8.13.0 acts like 10.13.0 as http2 is out of experimental now and quite a lot was backported to reach parity.
The sequence is not documented to my understanding but I have the feeling that error should come first.

In my use case (APM) the consequence is that I can't attach the error event to the server transaction as this one is already closed.

Reproducer:

const { createServer, connect } = require('http2');

createServer()
  .on('stream', (stream) => {
    console.log('ServerStream created');
    stream
      .on('close', () => console.log('ServerStream close'))
      .on('error', (err) => console.log('ServerStream error'))
      .respondWithFile('dont exist');;
  })
  .listen(8000);

connect('http://localhost:8000').request()
  .on('response', () => console.log('response'))
  .on('error', () => console.log('ClientRequest error'));

prints:

for 8.13.0:
ServerStream created
ServerStream close
ServerStream error
ClientRequest error

for 10.13.0/11.2.0:
ServerStream created
ServerStream error
ServerStream close
ClientRequest error

Refs: #22850

@ofrobots
Copy link
Contributor

/cc @nodejs/http2

@MylesBorins MylesBorins self-assigned this Nov 22, 2018
@MylesBorins
Copy link
Contributor

I've opened a PR with a test for this... gonna start digging

#24685

@MylesBorins
Copy link
Contributor

So it would appear that the change that introduced this behavior difference landed in 10.x... as the order is consistent all the way through 9.x.

I believe it is this Semver-Major change to net

net: emit 'close' after 'end'

As such I think that this behavior difference is expected, and unfortunately not something that can be fixed. I'll let someone else chime in to confirm. Perhaps it makes sense to document this?

@MylesBorins
Copy link
Contributor

/cc @lpinca

@mcollina
Copy link
Member

mcollina commented Nov 27, 2018

Emitting error after close is a bug. In a lot of cases, an hard-to-solve one. I’m inclined to consider this just a bug.

(bugs could be semver-major)

@MylesBorins
Copy link
Contributor

@mcollina are you suggesting we change the behavior in net in 8.x LTS?

@mcollina
Copy link
Member

No, we should fix http2 everywhere.

@lpinca
Copy link
Member

lpinca commented Nov 28, 2018

I don't think backporting #19241 is an option. It's definitely semver-major.

@MylesBorins
Copy link
Contributor

to add to what @lpinca said... the issue here is not http2 it is net, which I don't think we can change

@mcollina
Copy link
Member

@MylesBorins I'm proposing we fix http2 to handle this new event ordering correctly. Worst case, we swallow the error. IMHO after 'close' no error should be emitted. This change might be semver-major, but that's a different decision.

I agree we should not revert the change in net.

@lpinca
Copy link
Member

lpinca commented Nov 28, 2018

@mcollina I like you proposal. I'm not sure what it means in practice though, wouldn't it make future backports harder or is the plan to apply the changes on master first?

@mcollina
Copy link
Member

I would apply the changes on master first, and backport as usual.

@Flarna
Copy link
Member Author

Flarna commented Nov 28, 2018

I haven't digged into this yet but I wonder why a net change should impact the ordering of events on a single http2 stream. The TCP connection (net) is not closed in the use case above.

@lpinca
Copy link
Member

lpinca commented Nov 28, 2018

If there is no issue on master how would you fix something that isn't broken? I mean how do you justify the change?

@mcollina
Copy link
Member

Oh I misunderstood the issue. Then we should probably work on a fix on Node 8 to address the situation. This is probably going to be very hard.

IMHO it's better than we just swallow the error on Node 8. Unfortunately this is going to make the backports harder.

@Flarna
Copy link
Member Author

Flarna commented Nov 29, 2018

I did some debugging and I think #19836 is the change which fixed this in Node >= 10.

@MylesBorins
Copy link
Contributor

#19836 is built on top of #18438 which landed on v10.0.0

As the behavior for the test we wrote passes on 10.x I'm not 100% sure that #19836 is the PR that fixed it... but we can dig in a bit and see if we can get something working

@Flarna
Copy link
Member Author

Flarna commented Nov 29, 2018

Yes, it seems it's a combination of these. Also #19451 seems to be involved.
I got following call chain:

respondWithFile => fs.open() ==>
afterOpen() => this.destroy(err) => this._destroy()

NodeJS 8:
ServerHttp2Stream._destroy() calls process.nextTick(emit, this, 'close', code) => close comes first
Callback passed to _destroy() does a process.nextTick(emitErrorNT, this, err)

NodeJS 10:
Callback passed to _destroy() does a process.nextTick(emitErrorAndCloseNT, this, err) ==> emits first error then close
==> the process.nextTick(emit, this, 'close', code); in ServerHttp2Stream._destroy() has been removed in #19451

@MylesBorins
Copy link
Contributor

#19451 has already landed on 8.x in e4c10e1 fwiw

@Flarna
Copy link
Member Author

Flarna commented Nov 29, 2018

But not the complete change - the line process.nextTick(emit, this, 'close', code) in _destroy() is still there. Most likely because #19836 and/or #18438 have not been backported.

@Flarna
Copy link
Member Author

Flarna commented Dec 2, 2018

I have a fix in http2 to correct the sequence but I found that v8.x has a test which verifies that error comes after close.... This test was adapted in #17406 to verify close is after error.

Edit: PR: #24789

Should I submit a PR to correct the sequence or is this anyway something which can't be done in a patch/minor release?

BethGriggs pushed a commit that referenced this issue Dec 11, 2018
Correct sequence of emitting `error` and `close` events for a
`Http2Stream`.

PR-URL: #24789
Refs: #22850
Refs: #24685
Fixes: #24559
Reviewed-By: Luigi Pinca <luigipinca@gmail.com>
Reviewed-By: Matteo Collina <matteo.collina@gmail.com>
Reviewed-By: Trivikram Kamat <trivikr.dev@gmail.com>
@Flarna
Copy link
Member Author

Flarna commented Dec 11, 2018

fixed via #24789

@Flarna Flarna closed this as completed Dec 11, 2018
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

5 participants