Koa: http2 throws ERR_HTTP2_INVALID_STREAM with minor amount of concurrency

[buu700]

Moving from https://github.com/nodejs/node/issues/22135; as per the comments, it was confirmed to be koa-specific.

---

• Version: v10.8.0
• Platform: Linux 86f664ae731c 4.9.93-linuxkit-aufs #1 SMP Wed Jun 6 16:55:56 UTC 2018 x86_64 x86_64 x86_64 GNU/Linux (ubuntu:18.04 Docker image)
• Subsystem: http2

After a small handful of concurrent requests, http2 fails with the following error:

internal/http2/core.js:1791
      throw new ERR_HTTP2_INVALID_STREAM();
      ^

Error [ERR_HTTP2_INVALID_STREAM]: The stream has been destroyed
    at ServerHttp2Stream.sendTrailers (internal/http2/core.js:1791:13)
    at ServerHttp2Stream.onStreamTrailersReady (internal/http2/compat.js:377:8)
    at ServerHttp2Stream.emit (events.js:182:13)
    at Http2Stream.onStreamTrailers [as ontrailers] (internal/http2/core.js:318:15)
    at ServerHttp2Stream.submitRstStream (internal/http2/core.js:328:19)
    at ServerHttp2Stream.finishCloseStream (internal/http2/core.js:1533:3)
    at closeStream (internal/http2/core.js:1517:7)
    at ServerHttp2Stream.close (internal/http2/core.js:1846:5)
    at state.streams.forEach (internal/http2/core.js:2691:46)
    at Map.forEach (<anonymous>)

Test case:

cat > server.js << EOM
    const app = new (require('koa'))();
    const crypto = require('crypto');
    const fs = require('fs');
    const http2 = require('http2');


    app.use(async ctx => {
        await new Promise(resolve => setTimeout(resolve, 1000));

        ctx.body = 'balls';
        ctx.status = 200;
    });

    http2.createSecureServer(
        {
            allowHTTP1: true,
            cert: fs.readFileSync('cert.pem'),
            key: fs.readFileSync('key.pem'),
            dhparam: fs.readFileSync('dhparams.pem'),
            secureOptions:
                crypto.constants.SSL_OP_NO_SSLv3 |
                crypto.constants.SSL_OP_NO_TLSv1
        },
        app.callback()
    ).listen(
        31337
    );
EOM

killall node
node server.js &
echo -n > count
while ps ux | grep server.js | grep -v grep 2> /dev/null ; do
    echo -e '1\n2\n3\n4\n5\n6\n7\n8\n9\n10'
done | xargs -P10 bash -c '
    echo >> count
    curl -sk https://localhost:31337 > /dev/null
'

When the error occurs, you can manually kill the command with ctrl+C and wc -l count to view how many requests were initiated before the failure. For me it's been anywhere between 10 and 70.

This doesn't seem to be reproducible when using either https or spdy instead of http2.

[dougwilson]

One thing that may be different from the Node.js issue is that your non Koa test did not use the http/2 compat mode while Koa will use the compat mode. It just makes me wonder if the issue is in Node.hs core in the compat mode code perhaps.

[buu700]

Hm, do you know how I would test that? All I see about a compatibility API here is that there's a non-TLS http2.createServer method, which doesn't seem relevant since my koa example already uses http2.createSecureServer and which curl doesn't seem to like (curl: (8) Weird server reply).

Edit: Nevermind, the (req, res) callback is clearly what the compatibility API is. I'll test that out now.

[dougwilson]

This would be an example server.js file:

const crypto = require('crypto');
const fs = require('fs');
const http2 = require('http2');

http2.createSecureServer(
  {
    allowHTTP1: true,
    cert: fs.readFileSync('cert.pem'),
    key: fs.readFileSync('key.pem'),
    secureOptions:
      crypto.constants.SSL_OP_NO_SSLv3 |
      crypto.constants.SSL_OP_NO_TLSv1
  },
  (req, res) => {
    setTimeout(() => {
      res.statusCode = 200;
      res.setHeader('Content-Length', '5');
      res.setHeader('Content-Type', 'text/plain');
      res.end('balls');
    }, 5000);
  }
).listen(
  31337
);

I am trying on my end, but I didn't get any error with any of your examples (or mime above) with Node.js 10.8.0, though I am on the Windows platform, which may play a role in the difference.

[buu700]

Got it, thanks! I pasted more or less the same thing in the other thread for reference, but I wasn't able to reproduce the issue using the compatibility API without koa. Switching back to the original test with koa still reliably produces the error for me.

[dougwilson]

Darn, it was worth a shot. Perhaps a member with a similar platform to yours will be able to take a look 👍

[buu700]

It might be reproducible in Docker on Windows (I'm using Docker on OS X right now with the ubuntu:18.04 image).

Edit: Relevant command: docker run -it ubuntu:18.04 bash.

And within Docker:

export DEBIAN_FRONTEND=noninteractive
apt-get -y --allow-downgrades update
apt-get -y --allow-downgrades upgrade
apt-get -y --allow-downgrades install curl gnupg openssl
echo 'deb https://deb.nodesource.com/node_10.x bionic main' >> /etc/apt/sources.list
curl https://deb.nodesource.com/gpgkey/nodesource.gpg.key | apt-key add -
apt-get -y --allow-downgrades update
apt-get -y --allow-downgrades install nodejs
npm install koa

openssl req -nodes -new -x509 -keyout key.pem -out cert.pem -subj '/CN=localhost'

cat > server.js << EOM
    const app = new (require('koa'))();
    const crypto = require('crypto');
    const fs = require('fs');
    const http2 = require('http2');


    app.use(async ctx => {
        await new Promise(resolve => setTimeout(resolve, 1000));

        ctx.body = 'balls';
        ctx.status = 200;
    });

    http2.createSecureServer(
        {
            allowHTTP1: true,
            cert: fs.readFileSync('cert.pem'),
            key: fs.readFileSync('key.pem'),
            secureOptions:
                crypto.constants.SSL_OP_NO_SSLv3 |
                crypto.constants.SSL_OP_NO_TLSv1
        },
        app.callback()
    ).listen(
        31337
    );
EOM

killall node
node server.js &
echo -n > count
while ps ux | grep server.js | grep -v grep 2> /dev/null ; do
    echo -e '1\n2\n3\n4\n5\n6\n7\n8\n9\n10'
done | xargs -P10 bash -c '
    echo >> count
    curl -sk https://localhost:31337 > /dev/null
'

[dougwilson]

Yea, I noticed you had Docker listed. I don't have it installed and about to head to sleep for the night. If no one else stops by I'll take another stab with Docker.

[damianobarbati]

@buu700 did you manage to solve this issue?

Here a small repro:

import pkg from './package.json';

import fs from 'fs';
import http2 from 'http2';
import koa from 'koa';
import axios from 'axios';

const app = new koa();

app.use(async ctx => {
    try {
        let { data: result } = await axios.get('xxx');
        ctx.body = result;
    }
    catch (error) {
        ctx.status = 500;
        console.error('Internal Server Error', error.message || error);
    }
});

const cert = fs.readFileSync(pkg.ssl.cert);
const key = fs.readFileSync(pkg.ssl.key);

/** KOA + HTTP2 **/
const server1 = http2.createSecureServer({ cert, key }, app.callback()).listen(8443, error => error ? console.error(error) : console.info(`koa+http2s serving on port ${8443}`));
server1.on('error', console.error);
/** KOA + HTTP2 end **/

/** HTTP2 plain **/
http2.createSecureServer({ cert, key }, async (req, res) => {
    try {
        let { data: result } = await axios.get('xxx');
        res.end(JSON.stringify(result, null, 4));
    }
    catch (error) {
        res.end('Internal Server Error');
    }
}).listen(8444, error => error ? console.error(error) : console.info(`http2s serving on port ${8444}`));
/** HTTP2 plain end **/

process.on('SIGINT', process.exit);

The plain http2 server works fine, but the koa+http2 server kills the process because of a SIGINT: it's like koa is trying to send content over a closed stream because the process dies after koa processed the request (the "curl" actually receives data but in the meanwhile node dies!).

Error [ERR_HTTP2_INVALID_STREAM]: The stream has been destroyed
    at ServerHttp2Stream.sendTrailers (internal/http2/core.js:1786:13)
    at ServerHttp2Stream.onStreamTrailersReady (internal/http2/compat.js:382:8)
    at ServerHttp2Stream.emit (events.js:182:13)
    at ServerHttp2Stream.EventEmitter.emit (domain.js:442:20)
    at Http2Stream.onStreamTrailers [as ontrailers] (internal/http2/core.js:325:15)
    at ServerHttp2Stream.submitRstStream (internal/http2/core.js:335:19)
    at ServerHttp2Stream.finishCloseStream (internal/http2/core.js:1523:3)
    at closeStream (internal/http2/core.js:1507:7)
    at ServerHttp2Stream.close (internal/http2/core.js:1840:5)
    at state.streams.forEach (internal/http2/core.js:2687:46)

[buu700]

Nope, as far as I'm aware there's no way around this. I'm just temporarily using the older spdy package instead of the native http2 module for now.

[edevil]

Is this a Koa problem or a problem of the http2 module? Is express affected?

[buu700]

It seems to be Koa-specific based on the issue linked at the top.

[damianobarbati]

I was trying to do the same but express does not seem to support http2 if not with hacks.

const appe = express();

appe.get('/', async (req, res) => {
    try {
        let { data: result } = await axios.get('xxx');
        res.send(1);
    }
    catch (error) {
        res.send(1);
    }
});
http2.createSecureServer({ cert, key }, appe).listen(8444, error => error ? console.error(error) : console.info(`express+http2s serving on port ${8444}`));

Throws:

TypeError: Cannot read property 'readable' of undefined
    at IncomingMessage._read (_http_incoming.js:95:19)
    at IncomingMessage.Readable.read (_stream_readable.js:452:10)
    at resume_ (_stream_readable.js:899:12)
    at process._tickCallback (internal/process/next_tick.js:63:19)

Not sure though this is the proper way to use express + http2

[damianobarbati]

FYI: adding a 50ms delay await sleep(50) after the axios call prevent the ERR_HTTP2_INVALID_STREAM error and process SIGINT.

Is anyone actively investigating on this...?

[edevil]

@damianobarbati what node version are you using and how do you launch your repro code? Naively running it like this does not work:

$ /usr/local/Cellar/node/10.11.0/bin/node server.js
/Users/andre/work/koa-http2/server.js:1
(function (exports, require, module, __filename, __dirname) { import pkg from './package.json';
                                                                     ^^^

SyntaxError: Unexpected identifier
    at new Script (vm.js:79:7)
    at createScript (vm.js:251:10)
    at Object.runInThisContext (vm.js:303:10)
    at Module._compile (internal/modules/cjs/loader.js:657:28)
    at Object.Module._extensions..js (internal/modules/cjs/loader.js:700:10)
    at Module.load (internal/modules/cjs/loader.js:599:32)
    at tryModuleLoad (internal/modules/cjs/loader.js:538:12)
    at Function.Module._load (internal/modules/cjs/loader.js:530:3)
    at Function.Module.runMain (internal/modules/cjs/loader.js:742:12)
    at startup (internal/bootstrap/node.js:279:19)

[damianobarbati]

@edevil NODE_ENV=development HTTPS=8443 node -r esm index.js

Node version:

$ node -v
v10.11.0

Deps:

    "dependencies": {
        "axios": "^0.18.0",
        "better-console": "^1.0.1",
        "esm": "^3.0.84",
        "jsonwebtoken": "^8.3.0",
        "kcors": "^2.2.1",
        "koa": "^2.5.3",
        "koa-basic-auth": "^3.0.0",
        "koa-body": "^4.0.3",
        "koa-compress": "^3.0.0",
        "koa-json": "^2.0.2",
        "koa-mount": "^3.0.0",
        "koa-no-trailing-slash": "^2.1.0",
        "koa-router": "^7.4.0",
        "koa-send": "^5.0.0",
        "koa-sslify": "^2.1.2",
        "koa-useragent": "^1.0.1",
        "lodash-es": "^4.17.11",
        "luxon": "^1.3.3",
        "mysql2": "^1.6.1",
        "pm2": "^3.1.2",
        "sleep-promise": "^8.0.1"
    },

[edevil]

FWIW I also managed to reproduce this issue after sending a bunch of requests:

$ /usr/local/Cellar/node/10.11.0/bin/node -r esm server.js
koa+http2s serving on port 8443
http2s serving on port 8444
Error [ERR_HTTP2_INVALID_STREAM]: The stream has been destroyed
    at ServerHttp2Stream.sendTrailers (internal/http2/core.js:1786:13)
    at ServerHttp2Stream.onStreamTrailersReady (internal/http2/compat.js:382:8)
    at ServerHttp2Stream.emit (events.js:182:13)
    at ServerHttp2Stream.EventEmitter.emit (domain.js:442:20)
    at Http2Stream.onStreamTrailers [as ontrailers] (internal/http2/core.js:325:15)
    at ServerHttp2Stream.submitRstStream (internal/http2/core.js:335:19)
    at ServerHttp2Stream.finishCloseStream (internal/http2/core.js:1523:3)
    at closeStream (internal/http2/core.js:1507:7)
    at ServerHttp2Stream.close (internal/http2/core.js:1840:5)
    at state.streams.forEach (internal/http2/core.js:2687:46)

Using the 8444 port (no Koa) I was not able to crash it.

[edevil]

This issue seems like a race-condition. Like @damianobarbati mentions, the await sleep(50) call prevents the issue from happening (at least for the number of requests I tried). sleep(0) also seems to delay the problem for a few more requests. I also managed to reproduce the issue using a simple app.use(async ctx => {}) handler, albeit after a lot more requests.

[edevil]

I've fixed the issue in Node, and the PR has been merged. https://github.com/nodejs/node/pull/23146

If anyone wants to try they can build the latest master or wait for the next release.

[fl0w]

Did anyone have a chance to verify the fix?

[fl0w]

I am going to close this issue as the PR is merged and released and nobody has raised concerns/question about this since late 2018.