http2: onSessionRead after stream:end

[sebdeckers]

• Version: latest on master as well as PR http2: additional refinement of stream/session #138
• Platform: MacOS
• Subsystem: http2

There is a problem with the client. When the server terminates the socket, the client emits an end event before it has finished emitting all data events. This causes onread to throw an error.

Apologies for vague explanation. Here is the code to reproduce the error. pushserver.js is a long running process that does not show errors. The actual test case is pushclient.js. I separated them for easier debugging; it gets too confusing with debug messages from server and client in the same process.stdout.

Logs included below from master and pr #138. Also logs of nghttp for reference that confirm pushserver.js operates fine (AFAICT).

Note that the client error can be worked around by delaying the closing of the socket on the server side. That's what I did in test/parallel/test-http2-compat-serverresponse-createpushresponse.js previously, as that was only meant to test server implementation.

Test Source Code

test/parallel/test-http2-pushserver.js

'use strict';

const common = require('../common');
const assert = require('assert');
const h2 = require('http2');

const server = h2.createServer();
server.listen(55555, common.mustCall(function() {
  const port = server.address().port;
  console.log(`http://localhost:${port}`)
  server.on('request', function(request, response) {
    assert.strictEqual(response.stream.id % 2, 1);

    response.createPushResponse(
      {
        ':path': '/pushed',
        ':method': 'GET',
        ':scheme': 'http',
        ':authority': `localhost:${port}`
      },
      common.mustCall(function(error, pushResponse) {
        assert.strictEqual(error, null);
        assert.strictEqual(pushResponse.stream.id % 2, 0);

        // let count = 2;
        // function cleanupServer() { if (--count === 0) server.close(); }
        // response.stream.on('finish', common.mustCall(cleanupServer));
        // pushResponse.stream.on('finish', common.mustCall(cleanupServer));

        pushResponse.write('This is a server-initiated response');
        response.write('This is a client-initiated response');

        // setTimeout(() => pushResponse.end(), 1000);
        // setTimeout(() => response.end(), 1000);
        pushResponse.end();
        response.end();
      })
    );
  });
}));

test/parallel/test-http2-pushclient.js

'use strict';

const common = require('../common');
const assert = require('assert');
const h2 = require('http2');

const port = 55555

const url = `http://localhost:${port}`;
const session = h2.connect(url, common.mustCall(function() {
  let count = 2;
  function cleanupClient() {
    if (--count === 0) {
      // session.destroy();
      session.shutdown({
        graceful: true,
        immediate: false
      });
    }
  }

  function onStream(pushStream, headers, flags) {
    assert.strictEqual(headers[':path'], '/pushed');
    assert.strictEqual(headers[':method'], 'GET');
    assert.strictEqual(headers[':scheme'], 'http');
    assert.strictEqual(headers[':authority'], `localhost:${port}`);
    assert.strictEqual(flags, h2.constants.NGHTTP2_FLAG_END_HEADERS);

    let data = '';
    pushStream.setEncoding('utf8');
    pushStream.on('data', (chunk) => { data += chunk; });
    pushStream.on('end', common.mustCall(() => {
      console.trace({end: data})
      // assert.strictEqual(data, 'This is a server-initiated response');
    }));
    pushStream.on('end', common.mustCall(cleanupClient));
  }

  session.on('stream', common.mustCall(onStream));

  const requestStream = session.request({
    ':path': '/',
    ':method': 'GET',
    ':scheme': 'http',
    ':authority': `localhost:${port}`
  });

  requestStream.on('response', common.mustCall(function(headers, flags) {
    assert.strictEqual(headers[':status'], 200);
    assert.ok(headers['date']);
    assert.strictEqual(flags, h2.constants.NGHTTP2_FLAG_END_HEADERS);
  }));

  let data = '';
  requestStream.setEncoding('utf8');
  requestStream.on('data', (chunk) => { data += chunk; });
  requestStream.on('end', common.mustCall(() => {
    console.trace({end: data})
    assert.strictEqual(data, 'This is a client-initiated response');
  }));

  requestStream.on('end', common.mustCall(cleanupClient));
  requestStream.end();
}));

Output (master)

Commit 5f17ac4

pushserver.js

http2 👉  NODE_DEBUG=http2 ./node test/parallel/test-http2-pushserver.js 
(node:54981) ExperimentalWarning: The http2 module is an experimental API.
http://localhost:55555
HTTP2 54981: socket destroy called
HTTP2 54981: socket destroy called
HTTP2 54981: nghttp2session handle destroyed
HTTP2 54981: nghttp2session destroyed

pushclient.js ❌

http2 👉  NODE_DEBUG=http2 ./node test/parallel/test-http2-pushclient.js 
HTTP2 54982: creating client http2 session
(node:54982) ExperimentalWarning: The http2 module is an experimental API.
Trace: { end: 'This is a client-initiated response' }
    at ClientHttp2Stream.requestStream.on.common.mustCall (/Users/seb/Code/nodejs/http2/test/parallel/test-http2-pushclient.js:58:13)
    at ClientHttp2Stream.<anonymous> (/Users/seb/Code/nodejs/http2/test/common/index.js:504:15)
    at emitNone (events.js:110:20)
    at ClientHttp2Stream.emit (events.js:207:7)
    at endReadableNT (_stream_readable.js:996:12)
    at _combinedTickCallback (internal/process/next_tick.js:102:11)
    at process._tickCallback (internal/process/next_tick.js:161:9)
Trace: { end: '' }
    at ClientHttp2Stream.pushStream.on.common.mustCall (/Users/seb/Code/nodejs/http2/test/parallel/test-http2-pushclient.js:33:15)
    at ClientHttp2Stream.<anonymous> (/Users/seb/Code/nodejs/http2/test/common/index.js:504:15)
    at emitNone (events.js:110:20)
    at ClientHttp2Stream.emit (events.js:207:7)
    at endReadableNT (_stream_readable.js:996:12)
    at _combinedTickCallback (internal/process/next_tick.js:102:11)
    at process._tickCallback (internal/process/next_tick.js:161:9)
assert.js:92
  throw new AssertionError({
  ^

AssertionError [ERR_ASSERTION]: Internal HTTP/2 Failure. Stream does not exist. Please report this as a bug in Node.js
    at Http2Session.onSessionRead [as onread] (internal/http2/core.js:217:3)

nghttp ✅

http2server 👉  nghttp -v http://localhost:55555
[  0.006] Connected
[  0.008] send SETTINGS frame <length=12, flags=0x00, stream_id=0>
          (niv=2)
          [SETTINGS_MAX_CONCURRENT_STREAMS(0x03):100]
          [SETTINGS_INITIAL_WINDOW_SIZE(0x04):65535]
[  0.008] send PRIORITY frame <length=5, flags=0x00, stream_id=3>
          (dep_stream_id=0, weight=201, exclusive=0)
[  0.008] send PRIORITY frame <length=5, flags=0x00, stream_id=5>
          (dep_stream_id=0, weight=101, exclusive=0)
[  0.008] send PRIORITY frame <length=5, flags=0x00, stream_id=7>
          (dep_stream_id=0, weight=1, exclusive=0)
[  0.008] send PRIORITY frame <length=5, flags=0x00, stream_id=9>
          (dep_stream_id=7, weight=1, exclusive=0)
[  0.008] send PRIORITY frame <length=5, flags=0x00, stream_id=11>
          (dep_stream_id=3, weight=1, exclusive=0)
[  0.008] send HEADERS frame <length=39, flags=0x25, stream_id=13>
          ; END_STREAM | END_HEADERS | PRIORITY
          (padlen=0, dep_stream_id=11, weight=16, exclusive=0)
          ; Open new stream
          :method: GET
          :path: /
          :scheme: http
          :authority: localhost:55555
          accept: */*
          accept-encoding: gzip, deflate
          user-agent: nghttp2/1.20.0
[  0.012] recv SETTINGS frame <length=0, flags=0x00, stream_id=0>
          (niv=0)
[  0.012] recv SETTINGS frame <length=0, flags=0x01, stream_id=0>
          ; ACK
          (niv=0)
[  0.012] send SETTINGS frame <length=0, flags=0x01, stream_id=0>
          ; ACK
          (niv=0)
[  0.021] recv (stream_id=13) :authority: localhost:55555
[  0.021] recv (stream_id=13) :scheme: http
[  0.021] recv (stream_id=13) :method: GET
[  0.021] recv (stream_id=13) :path: /pushed
[  0.021] recv PUSH_PROMISE frame <length=26, flags=0x04, stream_id=13>
          ; END_HEADERS
          (padlen=0, promised_stream_id=2)
[  0.021] recv (stream_id=13) :status: 200
[  0.021] recv (stream_id=13) date: Sat, 20 May 2017 05:11:13 GMT
[  0.021] recv HEADERS frame <length=25, flags=0x04, stream_id=13>
          ; END_HEADERS
          (padlen=0)
          ; First response header
[  0.021] recv (stream_id=2) :status: 200
[  0.021] recv (stream_id=2) date: Sat, 20 May 2017 05:11:13 GMT
[  0.021] recv HEADERS frame <length=2, flags=0x04, stream_id=2>
          ; END_HEADERS
          (padlen=0)
          ; First push response header
This is a client-initiated response[  0.021] recv DATA frame <length=35, flags=0x01, stream_id=13>
          ; END_STREAM
This is a server-initiated response[  0.021] recv DATA frame <length=35, flags=0x01, stream_id=2>
          ; END_STREAM
[  0.021] send GOAWAY frame <length=8, flags=0x00, stream_id=0>
          (last_stream_id=2, error_code=NO_ERROR(0x00), opaque_data(0)=[])

Output: PR #138

Commit 97fa4c7

pushserver.js

http2 👉  NODE_DEBUG=http2 ./node test/parallel/test-http2-pushserver.js 
HTTP2 57651: creating htt2pserver
HTTP2 57651: http2server created
(node:57651) ExperimentalWarning: The http2 module is an experimental API.
http://localhost:55555
HTTP2 57651: setting up compatibility handler
HTTP2 57651: server received a connection
HTTP2 57651: setting up session handle
HTTP2 57651: sending settings
HTTP2 57651: submitting actual settings
HTTP2 57651: settings complete
HTTP2 57651: http2session created
HTTP2 57651: new settings received
HTTP2 57651: headers were received on stream 1: 0
HTTP2 57651: http2stream created
HTTP2 57651: stream 1 is ready
HTTP2 57651: created serverhttp2stream
HTTP2 57651: emit server stream event
HTTP2 57651: initiating push stream for stream 1
HTTP2 57651: push stream 2 created
HTTP2 57651: http2stream created
HTTP2 57651: stream 2 is ready
HTTP2 57651: created serverhttp2stream
HTTP2 57651: initiating response for stream 2
HTTP2 57651: initiating response for stream 1
HTTP2 57651: checking for trailers
HTTP2 57651: checking for trailers
HTTP2 57651: session is closing the stream 1: 0
HTTP2 57651: destroying stream 1
HTTP2 57651: stream 1 destroyed
HTTP2 57651: stream 1 is closed
HTTP2 57651: session is closing the stream 2: 0
HTTP2 57651: destroying stream 2
HTTP2 57651: stream 2 destroyed
HTTP2 57651: stream 2 is closed
HTTP2 57651: socket destroy called
HTTP2 57651: destroying nghttp2session
HTTP2 57651: nghttp2session handle destroyed
HTTP2 57651: nghttp2session destroyed

pushclient.js ❌

http2 👉  NODE_DEBUG=http2 ./node test/parallel/test-http2-pushclient.js 
HTTP2 57654: connecting to http://localhost:55555/
HTTP2 57654: http2session created
HTTP2 57654: clienthttp2session created
(node:57654) ExperimentalWarning: The http2 module is an experimental API.
HTTP2 57654: setting up session handle
HTTP2 57654: sending settings
HTTP2 57654: submitting actual settings
HTTP2 57654: settings complete
HTTP2 57654: initiating request
HTTP2 57654: http2stream created
HTTP2 57654: clienthttp2stream created
HTTP2 57654: session connected, immediate stream init
HTTP2 57654: connected.. initializing request
HTTP2 57654: stream 1 initialized
HTTP2 57654: stream 1 is ready
HTTP2 57654: checking for trailers
HTTP2 57654: new settings received
HTTP2 57654: headers were received on stream 2: 0
HTTP2 57654: http2stream created
HTTP2 57654: stream 2 is ready
HTTP2 57654: clienthttp2stream created
HTTP2 57654: headers were received on stream 1: 1
HTTP2 57654: emitting stream 'response' event
HTTP2 57654: headers were received on stream 2: 2
HTTP2 57654: emitting stream 'push' event
HTTP2 57654: session is closing the stream 1: 0
HTTP2 57654: destroying stream 1
HTTP2 57654: stream 1 destroyed
HTTP2 57654: stream 1 is closed
Trace: { end: 'This is a client-initiated response' }
    at ClientHttp2Stream.requestStream.on.common.mustCall (/Users/seb/Code/nodejs/http2/test/parallel/test-http2-pushclient.js:58:13)
    at ClientHttp2Stream.<anonymous> (/Users/seb/Code/nodejs/http2/test/common/index.js:504:15)
    at emitNone (events.js:110:20)
    at ClientHttp2Stream.emit (events.js:207:7)
    at endReadableNT (_stream_readable.js:1032:12)
    at _combinedTickCallback (internal/process/next_tick.js:102:11)
    at process._tickCallback (internal/process/next_tick.js:161:9)
HTTP2 57654: session is closing the stream 2: 0
HTTP2 57654: destroying stream 2
HTTP2 57654: stream 2 destroyed
HTTP2 57654: stream 2 is closed
Trace: { end: '' }
    at ClientHttp2Stream.pushStream.on.common.mustCall (/Users/seb/Code/nodejs/http2/test/parallel/test-http2-pushclient.js:33:15)
    at ClientHttp2Stream.<anonymous> (/Users/seb/Code/nodejs/http2/test/common/index.js:504:15)
    at emitNone (events.js:110:20)
    at ClientHttp2Stream.emit (events.js:207:7)
    at endReadableNT (_stream_readable.js:1032:12)
    at _combinedTickCallback (internal/process/next_tick.js:102:11)
    at process._tickCallback (internal/process/next_tick.js:161:9)
HTTP2 57654: initiating shutdown
HTTP2 57654: sending shutdown
HTTP2 57654: submitting actual shutdown request
HTTP2 57654: shutdown is complete
assert.js:92
  throw new AssertionError({
  ^

AssertionError [ERR_ASSERTION]: Internal HTTP/2 Failure. Stream does not exist. Please report this as a bug in Node.js
    at Http2Session.onSessionRead [as onread] (internal/http2/core.js:233:3)

nghttp ✅

http2server 👉  nghttp -v http://localhost:55555
[  0.003] Connected
[  0.004] send SETTINGS frame <length=12, flags=0x00, stream_id=0>
          (niv=2)
          [SETTINGS_MAX_CONCURRENT_STREAMS(0x03):100]
          [SETTINGS_INITIAL_WINDOW_SIZE(0x04):65535]
[  0.004] send PRIORITY frame <length=5, flags=0x00, stream_id=3>
          (dep_stream_id=0, weight=201, exclusive=0)
[  0.004] send PRIORITY frame <length=5, flags=0x00, stream_id=5>
          (dep_stream_id=0, weight=101, exclusive=0)
[  0.004] send PRIORITY frame <length=5, flags=0x00, stream_id=7>
          (dep_stream_id=0, weight=1, exclusive=0)
[  0.004] send PRIORITY frame <length=5, flags=0x00, stream_id=9>
          (dep_stream_id=7, weight=1, exclusive=0)
[  0.004] send PRIORITY frame <length=5, flags=0x00, stream_id=11>
          (dep_stream_id=3, weight=1, exclusive=0)
[  0.004] send HEADERS frame <length=39, flags=0x25, stream_id=13>
          ; END_STREAM | END_HEADERS | PRIORITY
          (padlen=0, dep_stream_id=11, weight=16, exclusive=0)
          ; Open new stream
          :method: GET
          :path: /
          :scheme: http
          :authority: localhost:55555
          accept: */*
          accept-encoding: gzip, deflate
          user-agent: nghttp2/1.20.0
[  0.004] recv SETTINGS frame <length=0, flags=0x00, stream_id=0>
          (niv=0)
[  0.004] recv SETTINGS frame <length=0, flags=0x01, stream_id=0>
          ; ACK
          (niv=0)
[  0.004] send SETTINGS frame <length=0, flags=0x01, stream_id=0>
          ; ACK
          (niv=0)
[  0.012] recv (stream_id=13) :authority: localhost:55555
[  0.012] recv (stream_id=13) :scheme: http
[  0.012] recv (stream_id=13) :method: GET
[  0.012] recv (stream_id=13) :path: /pushed
[  0.012] recv PUSH_PROMISE frame <length=26, flags=0x04, stream_id=13>
          ; END_HEADERS
          (padlen=0, promised_stream_id=2)
[  0.012] recv (stream_id=13) :status: 200
[  0.012] recv (stream_id=13) date: Sat, 20 May 2017 05:32:49 GMT
[  0.012] recv HEADERS frame <length=25, flags=0x04, stream_id=13>
          ; END_HEADERS
          (padlen=0)
          ; First response header
[  0.012] recv (stream_id=2) :status: 200
[  0.012] recv (stream_id=2) date: Sat, 20 May 2017 05:32:49 GMT
[  0.012] recv HEADERS frame <length=2, flags=0x04, stream_id=2>
          ; END_HEADERS
          (padlen=0)
          ; First push response header
This is a client-initiated response[  0.012] recv DATA frame <length=35, flags=0x01, stream_id=13>
          ; END_STREAM
This is a server-initiated response[  0.012] recv DATA frame <length=35, flags=0x01, stream_id=2>
          ; END_STREAM
[  0.012] send GOAWAY frame <length=8, flags=0x00, stream_id=0>
          (last_stream_id=2, error_code=NO_ERROR(0x00), opaque_data(0)=[])

[sebdeckers]

I've rarely felt this clueless, but regardless I'm trying to figure out this problem.

Some findings so far:

Callbacks from nghttp2 are executed in the correct sequence:

1. Data on stream 1: Nghttp2Session::OnFrameReceive (NGHTTP2_DATA)
2. Closing stream 1: Nghttp2Session::OnStreamClose
3. Data on stream 2: Nghttp2Session::OnFrameReceive (NGHTTP2_DATA)
4. Closing stream 2: Nghttp2Session::OnStreamClose

But the sequence in Nghttp2Session::DrainCallbacks is incorrect:

1. Data on stream 1: NGHTTP2_CB_DATA_CHUNKS
2. Closing stream 1: NGHTTP2_CB_STREAM_CLOSE
3. Closing stream 2: NGHTTP2_CB_STREAM_CLOSE
4. Data on stream 2: NGHTTP2_CB_DATA_CHUNKS

Any help appreciated 😅

[sebdeckers]

Did some more digging... It seems like the second NGHTTP2_DATA frame was not being queued due to Nghttp2Stream::IsReading returning false on the pushed stream. The reading_ property for the second stream is -1 because Nghttp2Stream::ReadStart is only triggered later by core.js at this.session._handle.streamReadStart(stream.id).

Is it correct to fix this as follows?

src/node_http2_core-inl.h

bool Nghttp2Stream::IsReading() const {
  return reading_ != 0;
}

Seems to work but not sure if it's as intended.

Otherwise, do we need to invoke Nghttp2Stream::ReadStart at an earlier stage on the pushed stream?

[sebdeckers]

Alternative solution:

src/node_http2_core.cc

int Nghttp2Session::OnBeginHeadersCallback(nghttp2_session* session,
                                           const nghttp2_frame* frame,
                                           void* user_data) {
  std::shared_ptr<Nghttp2Stream> stream_handle;
  Nghttp2Session* handle = static_cast<Nghttp2Session*>(user_data);
  int32_t stream_id = (frame->hd.type == NGHTTP2_PUSH_PROMISE) ?
    frame->push_promise.promised_stream_id :
    frame->hd.stream_id;
  if (!handle->HasStream(stream_id)) {
    stream_handle = handle->StreamInit(stream_id, frame->headers.cat);
    stream_handle->ReadStart();
  } else {
    stream_handle = handle->FindStream(stream_id);
    assert(stream_handle);
    stream_handle->current_headers_category_ = frame->headers.cat;
  }
  return 0;
}

[jasnell]

I think the first solution is the preferred. We intentionally do not call ReadStart() until the js layer calls for it. This is to ensure that the machinery necessary on the js side is all ready to go to receive the data.

[jasnell]

Ok, looking at it further we have a few issues here. The most significant is that while the final DATA frame is being received and queued internally on the client in the native layer, the subsequent RST_FRAME that is received causes the internal data storage for the stream to be cleared before it can be read. This will happen when the DATA frame and RST_FRAME are received on the same tick (which is what is happening here). I'll need to refactor it a bit such that the JS layer can be notified that the RST_FRAME has been received but the memory is not cleared until we're certain that all of the received DATA frames have been pushed.

[sebdeckers]

Fixed in #138

Test case updated: https://github.com/jasnell/http2-1/blame/no-rest-for-the-weary/test/parallel/test-http2-compat-serverresponse-createpushresponse.js#L35-L36