Node: Request streams from http2 intermittantly not emitting end event

[DullReferenceException]

• Version: v12.14.0
• Platform: Linux
• Subsystem: http2

In a nutshell, what we and others are seeing is a case where server-side code downloads bytes from a request using streaming mode, but no end event is received. The data events are firing fine, and all bytes are downloaded (a counter confirms that the number of bytes equals content-length). As you can imagine, this impacts things like middlewares which are waiting for the end event before continuing further processing. In our case, this surfaces as intermittent client-side timeouts and eventually the request is aborted.

We believe that others are seeing the same issue based on similar reports. See the following:

• https://github.com/stream-utils/raw-body/issues/57#issuecomment-528873512
• https://github.com/dlau/koa-body/issues/154#issuecomment-570917525
• https://github.com/nodejs/node/issues/29529#issuecomment-531947873

I have a way to reproduce... sort of. Essentially I create a secure http2 server and spam it with JSON post requests.

const { once } = require('events');
const { promises: { readFile } } = require('fs');
const { connect, createSecureServer } = require('http2');
const path = require('path');

const PORT = 8443;
const REQUEST_TIMEOUT = 10000;
const TIME_BETWEEN_REQUESTS = 100;
const REQUEST_PROCESSING_TIME = 100;

async function reproduce() {
  const server = await startServer();

  try {
    await Promise.race([
      requestSessionLoop(),
      requestSessionLoop()
    ]);
  } finally {
    server.close();
  }
}

async function startServer() {
  const [cert, key] = await Promise.all([
    readFile(path.resolve(__dirname, './certs/bugrepro.org.crt')),
    readFile(path.resolve(__dirname, './certs/bugrepro.org.key'))
  ]);

  const server = createSecureServer({ cert, key }, handleRequest);
  server
    .on('session', session => {
      console.log('Started new session', session);
    })
    .on('sessionError', err => {
      console.error('Got session error:', err.stack);
    })
  server.listen(PORT);

  await once(server, 'listening');
}

async function handleRequest(req, res) {
  const contentLength = req.headers['content-length'];
  const buffers = [];
  let bytesRead = 0;

  // Simulate processing delay
  //await delay(REQUEST_PROCESSING_TIME);

  req
    .on('data', chunk => {
      bytesRead += chunk.length;
      buffers.push(chunk);
    })
    .once('end', () => {
      try {
        const concatenated = buffers.join('');
        const body = JSON.parse(concatenated);
        console.log('Got request:', JSON.stringify(body));
        res.statusCode = 204;
        res.end();
      } catch (err) {
        res.statusCode = 500;
        res.end(err.stack);
      }
    })
    .once('aborted', () => {
      console.log(`Server received abort event from client. Bytes received: ${bytesRead} out of ${contentLength}.`);
      console.log('Request state:')
      console.dir(req);
    })
    .once('error', err => {
      console.error('Got error from request stream');
      res.statusCode = 500;
      res.end(err.stack);
    });
}

let sessionCounter = 0;

async function requestSessionLoop() {
  const ca = await readFile(path.resolve(__dirname, './certs/fakeca.crt'));
  const session = connect(`https://bugrepro.org:${PORT}`, { ca });
  const sessionId = ++sessionCounter;
  let requestCounter = 0;

  session
    .on('error', err => {
      console.error(`Received error from H2 session: ${err.stack}`);
    })
    .on('frameError', err => {
      console.error(`Received frame error from H2 session: ${err.stack}`);
    })
    .on('timeout', () => {
      console.log('Session timed out');
    })

  await once(session, 'connect');

  while (true) {
    // console.log(`Sending request #${++requestCounter}`);
    const stream = session.request({ ':method': 'POST', ':path': '/', 'content-type': 'application/json' });
    stream.setTimeout(REQUEST_TIMEOUT);
    stream.end(JSON.stringify({ sessionId, request: ++requestCounter, random: Math.random(), some: { arbitrary: 'content' } }));
    await verifyResponse(stream);
    stream.destroy();

    await delay(TIME_BETWEEN_REQUESTS);
  }
}

async function verifyResponse(req) {
  return new Promise((resolve, reject) => {
    req
      .once('error', err => {
        reject(new Error(`Received error from request stream: ${err.stack}`));
      })
      .once('frameError', err => {
        reject(new Error(`Received frame error from request stream: ${err.stack}`));
      })
      .once('aborted', () => {
        reject(new Error(`Request was aborted`));
      })
      .once('timeout', () => {
        reject(new Error(`Request timed out`));
      })
      .once('response', (headers, flags) => {
        const responseBuffer = [];
        req
          .on('data', chunk => {
            responseBuffer.push(chunk);
          })
          .once('end', () => {
            const body = responseBuffer.join('');
            const status = headers[':status'];
            if (status >= 400) {
              throw new Error(`Received unexpected HTTP error ${status} with body: ${body}`);
            } else {
              resolve();
            }
          })
      });
  });
}

function delay(ms) {
  return new Promise((resolve) => {
    setTimeout(resolve, ms);
  });
}

reproduce().catch(console.error);

Sadly, I couldn't get node-issued requests to reproduce by themselves. However, while this is running, trying a bunch of curl requests in parallel eventually gets the condition to occur:

curl --cacert ./certs/fakeca.crt https://bugrepro.org:8443/ -H 'content-type: application/json' --data '{ "fake": "json", "data": "payload" }' -m 10 --compressed --verbose
*   Trying 127.0.0.1...
* TCP_NODELAY set
* Connected to bugrepro.org (127.0.0.1) port 8443 (#0)
* ALPN, offering h2
* ALPN, offering http/1.1
* successfully set certificate verify locations:
*   CAfile: ./certs/fakeca.crt
  CApath: /etc/ssl/certs
* TLSv1.3 (OUT), TLS handshake, Client hello (1):
* TLSv1.3 (IN), TLS handshake, Server hello (2):
* TLSv1.3 (IN), TLS Unknown, Certificate Status (22):
* TLSv1.3 (IN), TLS handshake, Unknown (8):
* TLSv1.3 (IN), TLS Unknown, Certificate Status (22):
* TLSv1.3 (IN), TLS handshake, Certificate (11):
* TLSv1.3 (IN), TLS Unknown, Certificate Status (22):
* TLSv1.3 (IN), TLS handshake, CERT verify (15):
* TLSv1.3 (IN), TLS Unknown, Certificate Status (22):
* TLSv1.3 (IN), TLS handshake, Finished (20):
* TLSv1.3 (OUT), TLS change cipher, Client hello (1):
* TLSv1.3 (OUT), TLS Unknown, Certificate Status (22):
* TLSv1.3 (OUT), TLS handshake, Finished (20):
* SSL connection using TLSv1.3 / TLS_AES_256_GCM_SHA384
* ALPN, server accepted to use h2
* Server certificate:
*  subject: C=US; ST=Washington; L=Seattle; O=Bug Repro Fake Org; CN=bugrepro.org; [email protected]
*  start date: Jan 10 22:55:45 2020 GMT
*  expire date: Feb  9 22:55:45 2020 GMT
*  common name: bugrepro.org (matched)
*  issuer: C=US; ST=Washington; L=Seattle; O=Fake CA Ltd; CN=Fake CA; [email protected]
*  SSL certificate verify ok.
* Using HTTP2, server supports multi-use
* Connection state changed (HTTP/2 confirmed)
* Copying HTTP/2 data in stream buffer to connection buffer after upgrade: len=0
* TLSv1.3 (OUT), TLS Unknown, Unknown (23):
* TLSv1.3 (OUT), TLS Unknown, Unknown (23):
* TLSv1.3 (OUT), TLS Unknown, Unknown (23):
* Using Stream ID: 1 (easy handle 0x7fffd54d47e0)
* TLSv1.3 (OUT), TLS Unknown, Unknown (23):
> POST / HTTP/2
> Host: bugrepro.org:8443
> User-Agent: curl/7.58.0
> Accept: */*
> Accept-Encoding: deflate, gzip
> content-type: application/json
> Content-Length: 37
> 
* TLSv1.3 (IN), TLS Unknown, Certificate Status (22):
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
* TLSv1.3 (IN), TLS Unknown, Certificate Status (22):
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
* TLSv1.3 (IN), TLS Unknown, Unknown (23):
* Connection state changed (MAX_CONCURRENT_STREAMS updated)!
* TLSv1.3 (OUT), TLS Unknown, Unknown (23):
* TLSv1.3 (OUT), TLS Unknown, Unknown (23):
* We are completely uploaded and fine
* TLSv1.3 (IN), TLS Unknown, Unknown (23):
* Operation timed out after 10000 milliseconds with 0 bytes received
* Connection #0 to host bugrepro.org left intact
curl: (28) Operation timed out after 10000 milliseconds with 0 bytes received

When this timeout abort occurs, I see from the server's logs:

Server received abort event from client. Bytes received: 37 out of 37.

If it helps, here's what the console.dir of the request object shows. Maybe its state lends some clues as to what's going on:

Http2ServerRequest {
  _readableState: ReadableState {
    objectMode: false,
    highWaterMark: 16384,
    buffer: BufferList { head: null, tail: null, length: 0 },
    length: 0,
    pipes: null,
    pipesCount: 0,
    flowing: true,
    ended: false,
    endEmitted: false,
    reading: true,
    sync: false,
    needReadable: true,
    emittedReadable: false,
    readableListening: false,
    resumeScheduled: false,
    paused: false,
    emitClose: true,
    autoDestroy: false,
    destroyed: false,
    defaultEncoding: 'utf8',
    awaitDrain: 0,
    readingMore: false,
    decoder: null,
    encoding: null
  },
  readable: true,
  _events: [Object: null prototype] {
    pause: [Function: onRequestPause],
    resume: [Function: onRequestResume],
    data: [Function],
    end: [Function: bound onceWrapper] { listener: [Function] },
    error: [Function: bound onceWrapper] { listener: [Function] }
  },
  _eventsCount: 5,
  _maxListeners: undefined,
  [Symbol(state)]: { closed: false, didRead: true },
  [Symbol(headers)]: [Object: null prototype] {
    ':method': 'POST',
    ':path': '/',
    ':scheme': 'https',
    ':authority': 'bugrepro.org:8443',
    'user-agent': 'curl/7.58.0',
    accept: '*/*',
    'accept-encoding': 'deflate, gzip',
    'content-type': 'application/json',
    'content-length': '37'
  },
  [Symbol(rawHeaders)]: [
    ':method',         'POST',
    ':path',           '/',
    ':scheme',         'https',
    ':authority',      'bugrepro.org:8443',
    'user-agent',      'curl/7.58.0',
    'accept',          '*/*',
    'accept-encoding', 'deflate, gzip',
    'content-type',    'application/json',
    'content-length',  '37'
  ],
  [Symbol(trailers)]: {},
  [Symbol(rawTrailers)]: [],
  [Symbol(stream)]: ServerHttp2Stream {
    _readableState: ReadableState {
      objectMode: false,
      highWaterMark: 16384,
      buffer: [BufferList],
      length: 0,
      pipes: null,
      pipesCount: 0,
      flowing: true,
      ended: false,
      endEmitted: false,
      reading: true,
      sync: false,
      needReadable: true,
      emittedReadable: false,
      readableListening: false,
      resumeScheduled: false,
      paused: false,
      emitClose: true,
      autoDestroy: false,
      destroyed: false,
      defaultEncoding: 'utf8',
      awaitDrain: 0,
      readingMore: false,
      decoder: null,
      encoding: null
    },
    readable: true,
    _events: [Object: null prototype] {
      pause: [Function: streamOnPause],
      newListener: [Function: streamListenerAdded],
      removeListener: [Function: streamListenerRemoved],
      trailers: [Function: onStreamTrailers],
      end: [Function: onStreamEnd],
      error: [Function: onStreamError],
      aborted: [Array],
      close: [Array],
      drain: [Function: onStreamDrain],
      wantTrailers: [Function: onStreamTrailersReady],
      data: [Function: onStreamData]
    },
    _eventsCount: 11,
    _maxListeners: undefined,
    _writableState: WritableState {
      objectMode: false,
      highWaterMark: 16384,
      finalCalled: false,
      needDrain: false,
      ending: false,
      ended: false,
      finished: false,
      destroyed: false,
      decodeStrings: false,
      defaultEncoding: 'utf8',
      length: 0,
      writing: false,
      corked: 0,
      sync: true,
      bufferProcessing: false,
      onwrite: [Function: bound onwrite],
      writecb: null,
      writelen: 0,
      bufferedRequest: null,
      lastBufferedRequest: null,
      pendingcb: 0,
      prefinished: false,
      errorEmitted: false,
      emitClose: true,
      autoDestroy: false,
      bufferedRequestCount: 0,
      corkedRequestsFree: [Object]
    },
    writable: true,
    allowHalfOpen: true,
    timeout: 0,
    [Symbol(asyncId)]: 52824,
    [Symbol(kSession)]: ServerHttp2Session {
      _events: [Object: null prototype],
      _eventsCount: 6,
      _maxListeners: undefined,
      timeout: 120000,
      [Symbol(state)]: [Object],
      [Symbol(encrypted)]: true,
      [Symbol(alpnProtocol)]: 'h2',
      [Symbol(type)]: 0,
      [Symbol(proxySocket)]: null,
      [Symbol(socket)]: [TLSSocket],
      [Symbol(timeout)]: [Timeout],
      [Symbol(kHandle)]: [Http2Session],
      [Symbol(kNativeFields)]: [Uint8Array],
      [Symbol(server)]: [Http2SecureServer],
      [Symbol(local-settings)]: [Object],
      [Symbol(remote-settings)]: [Object]
    },
    [Symbol(timeout)]: null,
    [Symbol(state)]: {
      didRead: true,
      flags: 19,
      rstCode: 8,
      writeQueueSize: 0,
      trailersReady: false,
      endAfterHeaders: false
    },
    [Symbol(request)]: [Circular],
    [Symbol(proxySocket)]: null,
    [Symbol(id)]: 1,
    [Symbol(kHandle)]: Http2Stream { owner: [Circular], [Symbol(owner)]: [Circular] },
    [Symbol(protocol)]: 'https',
    [Symbol(authority)]: 'bugrepro.org:8443',
    [Symbol(response)]: Http2ServerResponse {
      _events: [Object: null prototype] {},
      _eventsCount: 0,
      _maxListeners: undefined,
      writable: true,
      [Symbol(state)]: [Object],
      [Symbol(headers)]: [Object: null prototype] {},
      [Symbol(trailers)]: [Object: null prototype] {},
      [Symbol(stream)]: [Circular]
    }
  },
  [Symbol(aborted)]: true
}

I know it's not ideal that I don't have a quick and easy way to reproduce. There's probably something key to reproducing, since we're actually able to reproduce _in our application_ more easily, but still intermittantly. It occurs for us in Chrome, but only when a given session ID is reused, when sending a post request. We can tell from Chrome logs that indeed the request is sent fully, and it times out/aborts while waiting for server headers.

Please let me know of any more details I can provide or things I can try to capture. We are highly motivated to squash this bug, since our alternative is to re-engineer our live application back to http1, which is obviously not ideal.

[DullReferenceException]

Archive to reproduce (contains the certs). You also have to point your host file such that bugrepro.org is resolved as 127.0.0.1.

http2-bug-repro.zip

[DullReferenceException]

http2-bug-repro.zip

(Created prior zip incorrectly)

[DullReferenceException]

Updates on debugging. I was able to make this a bit easier to reproduce by adding more activity to the server:
repro.js.txt

Still, none of the node client code initiates the failure; it only seems to be Chrome and curl (using http2) that triggers the issue, so maybe there's something extra that the node clients are doing that some other H2 clients are not. Sadly, turning on NODE_DEBUG=http2 makes me unable to reproduce, so maybe the extra console I/O eliminates a race condition or something like that.

I've also captured an additional util.inspect for the Http2ServerRequest object.

This is the state of the request during the handling of the final data event:
before.txt

...and this is the state at the time of the request having been aborted:
after.txt

Doing a diff on the two, here's two takeaways I got:

• The before readable state has reading: false; at the time of abort it's reading: true
• The stream symbol property differs between the two snapshots. The before state has it as an Http2Stream. The after state is a ServerHttp2Stream.

[DullReferenceException]

Found a good lead when turning on tracing for curl requests. There's a definite difference in client-side behaviors when comparing a successful curl request versus an unsuccessful request. Here's the output of a success versus a failure:

curl-success-trace.txt
curl-failure-trace.txt

In all cases for successes, curl sends the request body immediately after sending the request headers. In the case of failures, there is additional activity between the sending of the headers and the body. I'm not sure exactly what this activity is, but it looks like a back-and-forth that's present in both cases, just occurring at a different point in time (I'd recommend you use a diff tool to see what I mean).

Seems like it relates to a new TLS session being issued between the sending of the header and body; some state must be getting lost in the process.

[ronag]

Can you reproduce it when not using the compat API? Just to see if we can remove one layer of complexity.

[DullReferenceException]

@ronag: I think it's just the compat API. Here's why. I have created a version of the repro that does not use the compat API:

repro-non-compat.js.txt

I struggled to get the same TLS sequence that got the failures to occur using this repro script. After switching back to the compat API, I could get it to reproduce. Notably, after reproducing with the compat API, I ran the non-compat API, immediately after and got the same trace pattern as with the failing pattern, and the non-compat API did not get the timeout/failure. Here's the same two same mismatching session traces when running against the non-compat API that did not have the failure:

pattern-1-success.txt
pattern-2-success.txt

[DullReferenceException]

Strike that... while seeing if using the stream property of the request to read the body instead would work as a workaround, I was able to reproduce. So then I plugged in the repro code above that doesn't use the compat layer and ran the curl command in a zsh while loop, and I was able to get it to reproduce as well.

So this appears to be a problem with raw http2 streams, not just the compatibility API.

[ronag]

@nodejs/http2 seems related to http2 core

[ronag]

@DullReferenceException: Can you see what other events you get? Does it emit e.g. 'error' or 'close'?

[DullReferenceException]

It does not emit any error event. It does emit close, but only after the client aborts the request, not before.

[DullReferenceException]

Since the compat wrapper isn't to blame, here's a dump of the stream's state at the point of receiving the last data chunk and after the abort event:

Request state after reading last chunk:
Http2Stream {
  id: 1,
  closed: false,
  destroyed: false,
  state: {
    state: 2,
    weight: 16,
    sumDependencyWeight: 0,
    localClose: 0,
    remoteClose: 0,
    localWindowSize: 65498
  },
  readableState: ReadableState {
    objectMode: false,
    highWaterMark: 16384,
    buffer: BufferList { head: null, tail: null, length: 0 },
    length: 0,
    pipes: null,
    pipesCount: 0,
    flowing: true,
    ended: false,
    endEmitted: false,
    reading: true,
    sync: false,
    needReadable: true,
    emittedReadable: false,
    readableListening: false,
    resumeScheduled: false,
    paused: false,
    emitClose: true,
    autoDestroy: false,
    destroyed: false,
    defaultEncoding: 'utf8',
    awaitDrain: 0,
    readingMore: false,
    decoder: null,
    encoding: null
  },
  writableState: WritableState {
    objectMode: false,
    highWaterMark: 16384,
    finalCalled: false,
    needDrain: false,
    ending: false,
    ended: false,
    finished: false,
    destroyed: false,
    decodeStrings: false,
    defaultEncoding: 'utf8',
    length: 0,
    writing: false,
    corked: 0,
    sync: true,
    bufferProcessing: false,
    onwrite: [Function: bound onwrite],
    writecb: null,
    writelen: 0,
    bufferedRequest: null,
    lastBufferedRequest: null,
    pendingcb: 0,
    prefinished: false,
    errorEmitted: false,
    emitClose: true,
    autoDestroy: false,
    bufferedRequestCount: 0,
    corkedRequestsFree: {
      next: null,
      entry: null,
      finish: [Function: bound onCorkedFinish]
    }
  }
}

Stream state after abort:
ServerHttp2Stream {
  _readableState: ReadableState {
    objectMode: false,
    highWaterMark: 16384,
    buffer: BufferList { head: null, tail: null, length: 0 },
    length: 0,
    pipes: null,
    pipesCount: 0,
    flowing: true,
    ended: false,
    endEmitted: false,
    reading: true,
    sync: false,
    needReadable: true,
    emittedReadable: false,
    readableListening: false,
    resumeScheduled: false,
    paused: false,
    emitClose: true,
    autoDestroy: false,
    destroyed: false,
    defaultEncoding: 'utf8',
    awaitDrain: 0,
    readingMore: false,
    decoder: null,
    encoding: null
  },
  readable: true,
  _events: [Object: null prototype] {
    pause: [Function: streamOnPause],
    newListener: [Function: streamListenerAdded],
    removeListener: [Function: streamListenerRemoved],
    data: [Function],
    end: [Function: bound onceWrapper] { listener: [Function] },
    error: [Function: bound onceWrapper] { listener: [Function] }
  },
  _eventsCount: 6,
  _maxListeners: undefined,
  _writableState: WritableState {
    objectMode: false,
    highWaterMark: 16384,
    finalCalled: false,
    needDrain: false,
    ending: false,
    ended: false,
    finished: false,
    destroyed: false,
    decodeStrings: false,
    defaultEncoding: 'utf8',
    length: 0,
    writing: false,
    corked: 0,
    sync: true,
    bufferProcessing: false,
    onwrite: [Function: bound onwrite],
    writecb: null,
    writelen: 0,
    bufferedRequest: null,
    lastBufferedRequest: null,
    pendingcb: 0,
    prefinished: false,
    errorEmitted: false,
    emitClose: true,
    autoDestroy: false,
    bufferedRequestCount: 0,
    corkedRequestsFree: {
      next: null,
      entry: null,
      finish: [Function: bound onCorkedFinish]
    }
  },
  writable: true,
  allowHalfOpen: true,
  timeout: 0,
  [Symbol(asyncId)]: 54782,
  [Symbol(kSession)]: ServerHttp2Session {
    _events: [Object: null prototype] {
      newListener: [Function: sessionListenerAdded],
      removeListener: [Function: sessionListenerRemoved],
      stream: [Function: sessionOnStream],
      error: [Function: sessionOnError],
      priority: [Function: sessionOnPriority],
      timeout: [Function]
    },
    _eventsCount: 6,
    _maxListeners: undefined,
    timeout: 120000,
    [Symbol(state)]: {
      destroyCode: 0,
      flags: 1,
      goawayCode: null,
      goawayLastStreamID: null,
      streams: [Map],
      pendingStreams: Set {},
      pendingAck: 0,
      writeQueueSize: 0,
      originSet: undefined
    },
    [Symbol(encrypted)]: true,
    [Symbol(alpnProtocol)]: 'h2',
    [Symbol(type)]: 0,
    [Symbol(proxySocket)]: null,
    [Symbol(socket)]: TLSSocket {
      _tlsOptions: [Object],
      _secureEstablished: true,
      _securePending: false,
      _newSessionPending: false,
      _controlReleased: true,
      _SNICallback: null,
      servername: 'bugrepro.org',
      alpnProtocol: 'h2',
      authorized: false,
      authorizationError: null,
      encrypted: true,
      _events: [Object: null prototype],
      _eventsCount: 6,
      connecting: false,
      _hadError: false,
      _parent: [Socket],
      _host: null,
      _readableState: [ReadableState],
      readable: false,
      _maxListeners: undefined,
      _writableState: [WritableState],
      writable: false,
      allowHalfOpen: false,
      _sockname: null,
      _pendingData: null,
      _pendingEncoding: '',
      server: [Http2SecureServer],
      _server: null,
      ssl: null,
      _requestCert: false,
      _rejectUnauthorized: true,
      timeout: 0,
      write: [Function: writeAfterFIN],
      [Symbol(res)]: null,
      [Symbol(asyncId)]: 54706,
      [Symbol(kHandle)]: null,
      [Symbol(lastWriteQueueSize)]: 0,
      [Symbol(timeout)]: [Timeout],
      [Symbol(kBuffer)]: null,
      [Symbol(kBufferCb)]: null,
      [Symbol(kBufferGen)]: null,
      [Symbol(kBytesRead)]: 179,
      [Symbol(kBytesWritten)]: 18,
      [Symbol(error-emitted)]: false,
      [Symbol(kSession)]: [Circular],
      [Symbol(disable-renegotiation)]: true,
      [Symbol(server)]: [Http2SecureServer]
    },
    [Symbol(timeout)]: Timeout {
      _idleTimeout: 120000,
      _idlePrev: [Timeout],
      _idleNext: [Timeout],
      _idleStart: 5189,
      _onTimeout: [Function: bound _onTimeout],
      _timerArgs: undefined,
      _repeat: null,
      _destroyed: false,
      [Symbol(refed)]: false,
      [Symbol(asyncId)]: 54764,
      [Symbol(triggerId)]: 54706
    },
    [Symbol(kHandle)]: Http2Session { fields: [Uint8Array], [Symbol(owner)]: [Circular] },
    [Symbol(kNativeFields)]: Uint8Array [ 0, 0, 0 ],
    [Symbol(server)]: Http2SecureServer {
      _contexts: [],
      requestCert: false,
      rejectUnauthorized: true,
      ALPNProtocols: [Buffer [Uint8Array]],
      pfx: undefined,
      key: [Buffer [Uint8Array]],
      passphrase: undefined,
      cert: [Buffer [Uint8Array]],
      clientCertEngine: undefined,
      ca: undefined,
      minVersion: undefined,
      maxVersion: undefined,
      secureProtocol: undefined,
      crl: undefined,
      sigalgs: undefined,
      ciphers: undefined,
      ecdhCurve: undefined,
      dhparam: undefined,
      honorCipherOrder: true,
      secureOptions: undefined,
      sessionIdContext: '81681a7a1b4c3ea5ccc041bb81bb43b3',
      _sharedCreds: [SecureContext],
      _events: [Object: null prototype],
      _eventsCount: 7,
      _maxListeners: undefined,
      _connections: 600,
      _handle: [TCP],
      _usingWorkers: false,
      _workers: [],
      _unref: false,
      allowHalfOpen: false,
      pauseOnConnect: false,
      timeout: 120000,
      _connectionKey: '6::::8443',
      [Symbol(handshake-timeout)]: 120000,
      [Symbol(snicallback)]: undefined,
      [Symbol(asyncId)]: 14,
      [Symbol(enableTrace)]: undefined,
      [Symbol(options)]: [Object]
    },
    [Symbol(local-settings)]: {
      headerTableSize: 4096,
      enablePush: true,
      initialWindowSize: 65535,
      maxFrameSize: 16384,
      maxConcurrentStreams: 4294967295,
      maxHeaderListSize: 4294967295,
      enableConnectProtocol: 0
    }
  },
  [Symbol(timeout)]: null,
  [Symbol(state)]: {
    didRead: true,
    flags: 19,
    rstCode: 8,
    writeQueueSize: 0,
    trailersReady: false,
    endAfterHeaders: false
  },
  [Symbol(request)]: null,
  [Symbol(proxySocket)]: null,
  [Symbol(id)]: 1,
  [Symbol(kHandle)]: Http2Stream { owner: [Circular], [Symbol(owner)]: [Circular] },
  [Symbol(protocol)]: 'https',
  [Symbol(authority)]: 'bugrepro.org:8443'
}

[DullReferenceException]

Simplified repro script. Did away with the node client requests loop. Just running a curl command in a loop is sufficient, like:

while curl --cacert ./certs/fakeca.crt https://bugrepro.org:8443/ -H 'content-type: application/json' --data '{ "fake": "json", "data": "payload" }' -m 10; do :; done

Here's the simplified JS:

const { once } = require('events');
const { promises: { readFile } } = require('fs');
const { createSecureServer, constants: { HTTP2_HEADER_STATUS } } = require('http2');
const path = require('path');
const { inspect } = require('util');

const PORT = 8443;
const REQUEST_PROCESSING_TIME = { min: 10, max: 100 };

async function reproduce() {
  await startServer();

  console.log(`
Server has started. To reproduce, you must:

1. Have a version of curl that supports http2
2. Add a hosts file entry (typically at /etc/hosts) containing a line with: 127.0.0.1 bugrepro.org

Next, run this command, or if you don't have a shell like bash or zsh, you may have to translate to something else:

while curl --cacert ./certs/fakeca.crt https://bugrepro.org:8443/ -H 'content-type: application/json' --data '{ "fake": "json", "data": "payload" }' -m 10; do :; done

This should repeatedly send POST requests to the server until the error situation occurs, at which point the server will terminate.`);
}

async function startServer() {
  const [cert, key] = await Promise.all([
    readFile(path.resolve(__dirname, './certs/bugrepro.org.crt')),
    readFile(path.resolve(__dirname, './certs/bugrepro.org.key'))
  ]);

  const server = createSecureServer({ cert, key });
  server
    .on('sessionError', err => {
      console.error('Got session error:', err.stack);
    })
    .on('stream', handleStream)
  server.listen(PORT);

  await once(server, 'listening');

  return server;
}

let hasOutputSuccessEvents = false;

async function handleStream(stream, headers, flags) {
  await delay(randomRange(REQUEST_PROCESSING_TIME));

  const streamEvents = captureAllEvents(stream);

  const contentLength = parseInt(headers['content-length'], 10);
  const buffers = [];
  let bytesRead = 0;
  let lastChunkState;

  stream
    .on('data', chunk => {
      bytesRead += chunk.length;
      buffers.push(chunk);
      if (bytesRead === contentLength) {
        lastChunkState = inspect(stream);
      }
    })
    .once('end', () => {
      try {
        const concatenated = buffers.join('');
        JSON.parse(concatenated);
        stream.respond({
          [HTTP2_HEADER_STATUS]: 204
        });
        stream.end();
        if (!hasOutputSuccessEvents) {
          console.log('Stream event sequence on success:');
          console.dir(streamEvents);
          hasOutputSuccessEvents = true;
        }
      } catch (err) {
        stream.respond({
          [HTTP2_HEADER_STATUS]: 500
        });
        stream.end(err.stack);
      }
    })
    .once('aborted', () => {
      console.log(`Server received abort event from client. Bytes received: ${bytesRead} out of ${contentLength}.`);
      console.log('\nRequest state after reading last chunk:');
      console.log(lastChunkState);
      console.log('\nStream state after abort:')
      console.dir(stream);
      console.log('\n\nStream event sequence on success:');
      console.dir(streamEvents);
    })
    .once('error', err => {
      console.error('Got error from stream');
      stream.respond({ [HTTP2_HEADER_STATUS]: 500 });
      stream.end(err.stack);
    });
}

function captureAllEvents(emitter) {
  const events = [];
  const origEmit = emitter.emit.bind(emitter);
  let firstTimestamp = null;
  emitter.emit = (event, ...args) => {
    if (!firstTimestamp) {
      firstTimestamp = Date.now();
    }
    const timestamp = Date.now() - firstTimestamp;
    events.push({
      timestamp,
      event,
      args
    });
    origEmit(event, ...args);
  };
  return events;
}

function delay(ms) {
  return new Promise((resolve) => {
    setTimeout(resolve, ms);
  });
}

function randomRange({ min, max }) {
  const magnitude = max - min;
  return Math.random() * magnitude + min;
}

reproduce().catch(console.error);

I added some event capturing to the stream, but nothing interesting/unusual shows up.

[rahbari]

I used node 12.4 without any problem, after updating to 12.14.1 after 4 or 5 successful uploads, request stream halts till client or server timeout (no end event) after receiving all data.

[DullReferenceException]

I just tried my repro on 12.4.0, and it does reproduce. So does 12.0.0.

[rahbari]

I used 12.4 for so long and didn't have any problem, this is how I read the request:

new Promise((res, rej) => {
  const a = [];
  req.on('error', e => rej(e)).on('data', c => a.push(c)).on('end', () => res(Buffer.concat(a)));
});

req is a Http2ServerRequest object from Compatibility API.
after updating to 12.14.1 it halts randomly (end is not emitted) after request is readed completely, I removed 12.14.1 and installed 12.4 again and there is no problem as of now.

[rahbari]

This issue still exists in 12.16.0 and 13.8.0. Also I tested different version of node.js 12, my problem starts to occurs from node 12.8.1. Now I'm using 12.8.0 and it has no problem.

[akc42]

I was just about to leave a similar report. I find it occurs much more frequently on slower hardware. I am running my server on a raspberry pi 3. I am using the npm 'router' module as my middleware router, but instead of using 'bodyParser' I wrote my own with a timeout on getting the 'end' event. Here is that code

    readBody(req,next) {
      const buffer = [];
      let t = 0;
      function cleanup() {
        req.off('data', gotData);
        req.off('error', anError);
        let body;
        try {
          body = JSON.parse(Buffer.concat(buffer).toString());
        } catch(e) {
          //normally after a restart
          body = {};
        }
        req.body = body;
        next();
      }
      function gotData(chunk) {
        if (t === 0) t = setTimeout(() => {
          logger('error', `Reading request body timed out for url ${req.url}`);
          t = 0;
          req.off('end', anEnd);
          anEnd();
        }, 1000); //allow a second for an end to fire
        buffer.push(chunk);
      }
      function anEnd() {
        if (t !== 0) {
          clearTimeout(t);
          t = 0;
        }
        debugapi('got a end in reading request body');
        req.off('close', aClose);
        cleanup();
      }
      function aClose() {
        debugapi('got a close in reading request body');
        req.off('end', anEnd);
        cleanup();
      }
      function anError(err) {
        debugapi('error whilst reading body o ', err);
        req.off('data', gotData);
        req.off('end', anEnd);
        req.off('close', aClose);
        next(err);
      }

      debugapi('setting up to read request body');
      req.once('end', anEnd);
      req.once('close', aClose);
      req.once('error', anError);
      req.on('data', gotData);
    }

On the PI it occurs frequently. On my desktop less so. I have only just got this far in tracing the issue so I don't really have the data.

Before I put the timeout in - what would happen is the request would timeout (from the client? it took two minutes) and then repeat and more often than not it would then work.

[asilvas]

@akc42 what version(s) of node were you able to confirm this issue?

[akc42]

I was on 12.15.0, I just downgraded to 12.8.0 and the problem went away. I then upgraded to 12.8.1 and the problem returned. Looks like @rahbari is correct - the problem is between those two versions. The changelog shows lots of http2 changes between those two versions.

[akc42]

I've upgraded to v13.9.0 and changed by code so that the readBody routine above does a const reqStream = req.stream; at the head of it, and then all the req.{on,once,off} calls are replaced with the reqStream equivalents

This is still failing in the same way - maybe a fraction less often (it seems to be 100% of the time when this is the first time through the routine when the client has reloaded - about 50% if the time after that) on the raspberry pi with node --inspect myapp in operation. (No breakpoints at the moment, as I am getting stream fails if I try to put something on and I just wanted to prove my new code still worked the same)

[rahbari]

@asilvas @akc42 i tested all version from 12.4 to 12.16 to find out where the problem starts. It's okay in 12.8 and it's interesting that it happens in 12.8.1 (maybe 1 of 2) so much more than 12.16. I tested on latest windows 10, new core i7 machine so I don't think it has anything to do with slow hardware.
I'm stuck with 12.8 and I don't know how others are using newer versions because it's very fundamental bug that make 12.8.1+ unusable. Some suggested to check received data against content-length but it's not good if this header is not available.

[jasnell]

Hey all. Interesting issue for sure. I'll try to dig in on it later today but will need some time to review the discussion here.

[akc42]

@jasnell any progress on this?

[mrfx]

Hi, thanks for your thoughts. Since stream.on('end') is not reliable yet, my workoraund is:

const http2handler (req, res) {

  let buffer = [];
  let counter = 0;
  req.stream.on('data', ( chunk ) => {
    counter += chunk.length;
    buffer.push( chunk );
    if ( counter === Number( req.headers['content-length'] ) ) {
      const body = Buffer.concat(buffer).toString();
      const response = sampleBodyHandleFunc( body );
      res.stream.respond(headers);
      res.stream.end(response);
      return;
    }
  } );

}

const server = http2
  .createSecureServer(serverOptions, http2handler)
  .listen(8888, () => {
    console.log("http2 server started on port", 8888);
});

[FallingSnow]

Any luck on this? This is affecting code in production for me.

[jasnell]

Been spending some time digging in on the http2 code again this week and will be continuing next week. This issue is on my list of ones to get to but I haven't yet been able to get to it.

[cucar]

Spent 2 days on this problem. I see it in production as well. Tracked it down to http2stream not emitting end event. Please solve as soon as possible.

[rahbari]

I just tested node 14.2, I don't know if this problem is fixed or not, but it didn't halt after several uploads.
UPDATE
After several days of testing, it still hangs sometimes.

[clshortfuse]

Experiencing this on v14.3.0 on Mac OS X with Chrome v81.0.4044.138.

I can reproduce this by restarting my NodeJS instance, and while it's starting refresh the Chrome Window. When I compare JSON.stringify(serverHttp2Stream), on the last chunk in a stream, a correct response will have _readableState.reading: false. I set a timer for 5000 ms on hung streams and inspect again and it has _readableState.reading: true. Everything else is the same.

Right now I'm using Content-Length to see if I got the expected amount of data and then manually ending the read stream. It'll help, but not every request will send a Content-Length.

Edit: Also hangs on Safari v13.1 (15609.1.20.111.8).

Edit2: Disabling all stream.pushStream() commands makes the issue go away. Only been able to reproduce when using stream.pushStream(). Will continue to investigate.

Edit3: FIXED IT. Basically, the data stream can stall and NodeJS doesn't recover. Push exacerbates the issue, but not the true cause. I've messed around by simulating very low bandwidth on Chrome and listening for 'readable' events with a small buffer size (1KB). Sometimes it'll stall, but sending a ping (stream.session.ping(() => {});) will cause the session to wake up and the stream to continue.

Now all that remains is to figure how often to send a .ping(). My current logic is the following:

const STREAM_WAIT_MS = 0; let pingTimeout = null; stream.on('readable', () => { // Consume data clearTimeout(pingTimeout); pingTimeout = setTimeout(() => stream.session.ping(() => {}), STREAM_WAIT_MS); }); stream.on('end', () => { clearTimeout(pingTimeout); });

Because of the way events are sequenced and how setTimeout works, it'll only get called on an event loop where no data is received from the stream. On streams where data comes in without issue, ping is never called.

[bathos]

We’ve been using the content-length “hack” for this for a while too. This occurs for us without the compat API. I thought I was just screwing something up for the longest time so it’s at least a relief to see it confirmed that the 'end' event should be getting emitted and other folks are encountering this too.

@clshortfuse re: pushStream, I have seen this occur when there are no push streams being spawned. In our case it seems to be _nearly_ reliably reproducible for things like image uploads.

[zandaqo]

I have first encountered this problem in August 2019, but I thought it was cause by a different issue and reported it in Semptember: https://github.com/nodejs/node/issues/29529#issuecomment-531947873
And now, almost one year and two major versions later we are still having it...

[asilvas]

I have first encountered this problem in August 2019, but I thought it was cause by a different issue and reported it in Semptember: #29529 (comment)
And now, almost one year and two major versions later we are still having it...

While that is unfortunate, this is open source, and we're all free to contribute a fix.

[clshortfuse]

I seem to have discovered a somewhat high chance of failure with HTML Form requests using POST from Chrome while using .on('readable'). I might a have a reproducible soon. I just want to know if somebody else is experiencing this as well with Form POST requests.

fetch() POST requests seem to have no issue. It might be that the Http2 session for my JavaScript requests are initiated by a request with no content (GET or OPTIONS). Then the JS POST is using a new stream on the same session. But the HTML Form POST might be using a new connection.

[clshortfuse]

Got it. I can 100% reproduce it on my Mac OS X system with Node v14.3.0 with either Chrome or Safari.

It seems the HTTP2 frames in the session are stalled by one. If a POST request is sent with data to the server, that stream won't emit the last 'readable' event (where .read() is null). For some reason, the session is stalled here. If I send a PING frame on the session, it'll continue working. But what I also figured out is that if the client sends any other frame, the stalled stream will get it's missing event ('readable' and then 'end'). So, the issue doesn't appear to be in the stream code, but the session code.

I confirmed this by having my client-side JS code fetch('404') right after a POST. Once the fetch is done, that previous POST completes immediately.

This does not happen on Ubuntu in Windows WSL, which explains why I felt like I was going crazy when I thought I fixed a bug, and then when going back to Macbook, starting having issues. And it probably doesn't happen on my Amazon Linux servers which explains why my clients haven't been complaining when I pushed code without the PING frame being added to every POST read.

Here's the reproducible code. You'll have to add certificate with:

openssl req -x509 -newkey rsa:2048 -nodes -sha256 -subj '/CN=localhost' -keyout localhost-privkey.pem -out localhost-cert.pem

````js
import { performance } from 'perf_hooks';
import http2 from 'http2';
import { existsSync, readFileSync } from 'fs';

// DEBUG OPTIONS
const SEND_PING = false;
const REQUEST_404 = false;
/** @type {'readable'|'data'} */
const EVENT = 'readable';
const READ_BEFORE_RESPOND = false;

/**

• @param {import('http2').SecureServerOptions} options
• @return {Promise}
  /
  async function setupHTTP2(options) {
  return new Promise((resolve, reject) => {
  const http2Server = http2.createSecureServer(options);
  http2Server.listen(8443, '0.0.0.0', () => resolve(http2Server));
  http2Server.addListener('error', reject);
  });
  }
  /*
• @param {import('http2').ServerHttp2Stream} stream
• @param {import('http2').IncomingHttpHeaders} headers
• @return {Promise}
  /
  async function handleHttp2Stream(stream, headers) {
  const pathName = headers[':path'];
  if (pathName === '/') {
  stream.respond({ ':status': 200 });
  stream.end(/ html */ <html> <head> <script type="text/javascript"> fetch('input.json', { headers: [['Content-Type', 'application/json']], method: 'POST', body: JSON.stringify({test: 'content'}), }) .then((response) => response.text()) .then(console.log) .catch(console.error); </script> ${REQUEST_404 ? "<script>setTimeout(() => fetch('404'),100)</script>" : ''} </head> </body> ${new Date()} <form action="form" method="POST"><input name="field"><input type="submit" value="POST"></form> </body> </html> );
  return pathName;
  }
  if (headers[':method'] === 'POST') {
  return new Promise((resolve, reject) => {
  let received = '';
  if (!READ_BEFORE_RESPOND) {
  stream.respond({ ':status': 200 });
  }
  stream.on(EVENT, (chunk) => {
  console.log(----BEGIN '${EVENT}'----);
  console.log(' ----BEGIN CHUNK-----');
  if (EVENT === 'readable') {
  chunk = stream.read();
  }
  if (chunk != null) {
  console.log(' ', chunk);
  received += chunk.toString();
  }
  console.log(' ----END CHUNK-----');
  // analyzeStates();
  console.log(----END '${EVENT}'----);
  if (!SEND_PING) return;
  setTimeout(() => {
  console.log(' ----BEGIN PING----');
  if (stream) {
  if (stream.session) {
  stream.session.ping(() => { console.log('!!!!PONG!!!!'); });
  console.log(' ----SENT PING----');
  } else {
  console.warn(' ----NO SESSION----');
  }
  } else {
  console.warn(' ----NO STREAM----');
  }
  console.log(' ----END PING----');
  }, 0);
  });
  stream.on('end', () => {
  console.log('!!!!!END!!!!!');
  if (READ_BEFORE_RESPOND) {
  stream.respond({ ':status': 200 });
  }
  stream.end(received);
  resolve(pathName);
  });
  stream.on('error', (err) => {
  console.error(err);
  reject(err);
  });
  });
  }
  stream.respond({ ':status': 404 }, { endStream: true });
  return pathName;
  }

const sessionIds = new WeakMap();

/**

• @param {import('http2').Http2Session} session
• @return {string}
  */
  function getSessionId(session) {
  if (sessionIds.has(session)) {
  return sessionIds.get(session);
  }
  const id = Math.random().toString(36).substr(2, 16);
  sessionIds.set(session, id);
  return id;
  }

async function runServer() {
const server = await setupHTTP2({
key: existsSync('localhost-privkey.pem') && readFileSync('localhost-privkey.pem'),
cert: existsSync('localhost-privkey.pem') && readFileSync('localhost-cert.pem'),
});
console.log('HTTP2 Server listening on', server.address());
server.addListener('session', async (session) => {
const sessionId = getSessionId(session);
console.log('New session', sessionId);
session.on('close', () => {
console.log('Closed session', sessionId);
});
});
server.addListener('stream', async (stream, headers) => {
const { session } = stream;
console.log('Started stream', stream.id || 'NO_ID', 'on', getSessionId(session));
const start = performance.now();
const response = await handleHttp2Stream(stream, headers);
const duration = performance.now() - start;
console.log('Completed stream', stream.id || 'NO_ID', 'for', response, 'in', ${duration.toFixed(2)}ms, 'on', getSessionId(session));
});
}
runServer();
````

Run it and open https://localhost:8443/ in Mac OS X.

Edit: It appears this can happen if you respond before reading the stream. I updated the code to add a debug options for that. So, in a gist, if you try to read from a stream after having already responded, you won't get the 'end' event.

Edit2: I think it can be explained as, if the last frame is the frame with data, you won't have an issue. If you push another frame (like with .respond()), you have to wait for another client frame (like a PONG or a new stream) before the Readable in question will emit 'end'.

[mcollina]

@clshortfuse can you create a client with node.js that reproduce the problem? This would be highly instrumental in writing a test

[clshortfuse]

@mcollina I'm struggling a bit reproducing it with the built-in http/2 client. It just works fine. It completely fails with Chrome. I also discovered it also fails with curl, but only sometimes. The times it does fail on curl, it may be a race condition somewhere.

Something about remoteSettings, session state, and localSettings may not be occurring in a specific order. I'd guess the nodeJS client always does things in a certain order. Regardless, I don't think I'm going to nip this in the bud until I do a packet sniffer, which I'll try tomorrow.

Interesting sidenote: READ_BEFORE_RESPOND won't fix curl. Only SEND_PING will. Chrome works with either.

Edit: Before I forget. Both Chrome and curl have larger remoteWindowSize values than the server's 64kib. Might be related.

[mcollina]

Thanks for spending time in debugging this. http/2 is a really complex protocol with a lot of moving parts.. and it’s hard to test.

Let us know how you progress on this!

[clshortfuse]

It's a combination of what I figured. I checked it out in Wireshark. Chrome will succeed if any packet appears in after the DATA packet in question (the one with the data in the Readable). It doesn't matter if the packet is inbound or outbound, it just has to exist. But if the last packet is a DATA packet, it'll hang there.

I tried nghttp's command-line binary and it always works, no surprise. But why it works is because a SETTINGS packet is sent to the client after receiving the content DATA.

Chrome works differently. Chrome appears to rarely (but not always) finish the SETTINGS phase before sending the DATA. That's why it stalls so often. This also explains the curl fluctuation I saw with it working and it then not, based on different timings for SETTINGS.

It has nothing to do with window size. The DATA packet itself has the flag that says to end the stream. I went though node_http2.cc and the OnFrameReceive isn't being fired. It's not stalling on NodeJS, it's stalling on nghttp2!

https://github.com/nodejs/node/blob/f1ae7ea343020f608fdc1ca77d9cdfe2c093ac72/src/node_http2.cc#L414

We get partial data because OnDataChunkReceived is firing fine from nghttp2. Now, we can be a bit proactive here, maybe. In the OnDataChunkReceived, the flag is included and actually tells us the stream has ended. It also includes the length of the chunk. That means, once we get the final chunk, we can emit UV_EOF.

https://github.com/nodejs/node/blob/f1ae7ea343020f608fdc1ca77d9cdfe2c093ac72/src/node_http2.cc#L1020

I've confirmed that the flag is only set on the final chunk. I'm not sure WHY nghttp2 isn't sending OnFrameReceive. It might be a Mac OS X thing, but at least we can fix it on our side by handling OnDataChunkReceived better.

---

Edit: I haven't written C code in over a decade, but something like this:

c if (flags & NGHTTP2_FLAG_END_STREAM) { stream->EmitRead(UV_EOF); return 0; // Don't pause }

at https://github.com/nodejs/node/blob/f1ae7ea343020f608fdc1ca77d9cdfe2c093ac72/src/node_http2.cc#L1086 should do the trick.

---

Edit2: It might actually be in NodeJS's forcing nghttp2 to pause https://github.com/nodejs/node/blob/f1ae7ea343020f608fdc1ca77d9cdfe2c093ac72/src/node_http2.cc#L1092

It doesn't look like it's returning after sending out whatever data it wants to. And when it finally does try to read (on the next nghttp2 callback), it gets a bad length:

Http2Session server (62) receiving -4095 bytes, offset 0

Still, there's no point in pausing if we reached EOF.

[clshortfuse]

For devs that don't want to wait for fix in a new NodeJS release, the application-level fix is to send a packet out when the read stalls. That will resumed the paused internal read stream. Quick simply, you can send a PING.

Instead of reading from the ServerHttp2Stream directly, you setup a PassThrough that will auto-ping on stall:

js // Workaround for https://github.com/nodejs/node/issues/31309 const STREAM_WAIT_MS = 0; /** @type {NodeJS.Timeout} */ let pingTimeout = null; function sendPing() { if (stream.session) stream.session.ping(() => {}); } const autoPingStream = new PassThrough({ read(...args) { clearTimeout(pingTimeout); pingTimeout = setTimeout(sendPing, STREAM_WAIT_MS); return PassThrough.prototype._read.call(this, ...args); }, }); stream.pipe(autoPingStream);

Then access autoPingStream as you would stream with the exact same read events ('data', 'readable').

[niftylettuce]

Just chiming in here - is this related to the bug I discovered here? https://github.com/nodejs/node/issues/33687

[clshortfuse]

@niftylettuce 99% sure, yes. I did a Wireshark specifically with Chrome and narrowed it down to lack of END_STREAM flag support. It also can happen with Safari and curl on Mac. Unfortunately, the test file I built to properly show the issue is gone because my Macbook Pro decides it no longer wants to boot. But the good news is I no longer really need it since a PR is in place.

I suggest you use the workaround in the comment above which will "wake up" the stalled state.

[niftylettuce]

Thanks @clshortfuse - this seems Chrome/Chromium specific. Is there a patch they can do on their side too to alleviate this? I imagine people update their Chrome/Chromium version faster than Node.

[niftylettuce]

@clshortfuse Is there an example fix I could add to my Koa setup? And is there one we can add for people using Express, Fastify, etc?

[clshortfuse]

I don't know exactly how things work on Koa or Express. I recently gave up trying to get full functionality HTTP2 out of Express and wound up writing my own framework. That's actually how I came across this issue.

You need to be able to interface with the session and send something, anything to wake it up. I'm assuming Koa and Express don't interface with the stream event and are using the the downconverted HTTP1-compatible request. With a stream, you can get the .session object and send a ping.

If the documentation here is how I assume it to be, you might be able to do .request.stream.session.ping(() => {}). But that's assuming the request or stream property hasn't been mutated (which I know Express likes to do). And I'm pretty sure, at least on Express, if you try reading from the stream directly, yourself, you're going to have to problems because the framework expects complete access. So you'll have to figure out how and when to slip the ping in,.

[niftylettuce]

@clshortfuse Hey! As a workaround in the interim, couldn't we just change this?

server.timeout = 5000; // 5s timeout vs. 120s timeout for HTTP/2 to reset

Ref: https://nodejs.org/api/http.html#http_server_timeout

[clshortfuse]

@niftylettuce You're still going to drop a perfectly good connection. You'll send something like an error with status code 500 when they try to load a page or submit something. I'm assuming you're using koa/bodyparser, so based on the dependency tree of:

koa/bodyparser => co-body => raw-body

You'll have to modify https://github.com/stream-utils/raw-body/blob/0e1291f1d6cbc9ee8e16f893d091e417841c95e5/index.js#L240 in your node_modules and inject sending the ping.

To be honest, it might be easier to switch to spdy which I know doesn't have the issue. Or skip koa/bodyparser and read from the stream yourself, sending a ping on stall. Or, maybe, you can try your luck by blindly calling ctx.req.stream.session.ping(() => {}) if you feel it's stalled after a while.

[niftylettuce]

A bit confused on where to inject it, @clshortfuse any chance you could send me an example? Also, can you toss me an email at [email protected] with your PayPal or preferred means of receiving the bug bounty award for this?

[niftylettuce]

As I mentioned over email, the examples you had shared by email @clshortfuse did not work unfortunately.