http2 throws ERR_HTTP2_INVALID_STREAM with minor amount of concurrency #1229

buu700 · 2018-08-05T05:54:25Z

Moving from nodejs/node#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.

The text was updated successfully, but these errors were encountered:

dougwilson · 2018-08-05T05:57:34Z

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 · 2018-08-05T06:16:50Z

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 · 2018-08-05T06:22:30Z

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 · 2018-08-05T06:28:36Z

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 · 2018-08-05T06:29:36Z

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

buu700 · 2018-08-05T06:31:09Z

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:

cd
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 · 2018-08-05T06:33:11Z

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 · 2018-09-26T08:48:45Z

@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 · 2018-09-26T13:50:04Z

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 · 2018-09-26T13:54:03Z

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

buu700 · 2018-09-26T14:01:07Z

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

damianobarbati · 2018-09-26T14:07:37Z

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 · 2018-09-28T08:38:50Z

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 · 2018-09-28T09:04:36Z

@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 · 2018-09-28T09:06:13Z

@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 · 2018-09-28T09:50:29Z

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 · 2018-09-28T10:16:06Z

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 · 2018-10-03T09:10:44Z

I've fixed the issue in Node, and the PR has been merged. nodejs/node#23146

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

fl0w · 2018-11-09T23:09:28Z

Did anyone have a chance to verify the fix?

fl0w · 2019-03-13T13:43:47Z

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.

fl0w added the http/2 label Sep 24, 2018

edevil mentioned this issue Sep 28, 2018

http2: don't send trailers on a closed connection nodejs/node#23146

Closed

2 tasks

fl0w closed this as completed Mar 13, 2019

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

http2 throws ERR_HTTP2_INVALID_STREAM with minor amount of concurrency #1229

http2 throws ERR_HTTP2_INVALID_STREAM with minor amount of concurrency #1229

buu700 commented Aug 5, 2018

dougwilson commented Aug 5, 2018

buu700 commented Aug 5, 2018 •

edited

Loading

dougwilson commented Aug 5, 2018

buu700 commented Aug 5, 2018

dougwilson commented Aug 5, 2018

buu700 commented Aug 5, 2018 •

edited

Loading

dougwilson commented Aug 5, 2018

damianobarbati commented Sep 26, 2018 •

edited

Loading

buu700 commented Sep 26, 2018

edevil commented Sep 26, 2018

buu700 commented Sep 26, 2018

damianobarbati commented Sep 26, 2018

damianobarbati commented Sep 28, 2018

edevil commented Sep 28, 2018 •

edited

Loading

damianobarbati commented Sep 28, 2018 •

edited

Loading

edevil commented Sep 28, 2018

edevil commented Sep 28, 2018

edevil commented Oct 3, 2018

fl0w commented Nov 9, 2018

fl0w commented Mar 13, 2019

http2 throws ERR_HTTP2_INVALID_STREAM with minor amount of concurrency #1229

http2 throws ERR_HTTP2_INVALID_STREAM with minor amount of concurrency #1229

Comments

buu700 commented Aug 5, 2018

dougwilson commented Aug 5, 2018

buu700 commented Aug 5, 2018 • edited Loading

dougwilson commented Aug 5, 2018

buu700 commented Aug 5, 2018

dougwilson commented Aug 5, 2018

buu700 commented Aug 5, 2018 • edited Loading

dougwilson commented Aug 5, 2018

damianobarbati commented Sep 26, 2018 • edited Loading

buu700 commented Sep 26, 2018

edevil commented Sep 26, 2018

buu700 commented Sep 26, 2018

damianobarbati commented Sep 26, 2018

damianobarbati commented Sep 28, 2018

edevil commented Sep 28, 2018 • edited Loading

damianobarbati commented Sep 28, 2018 • edited Loading

edevil commented Sep 28, 2018

edevil commented Sep 28, 2018

edevil commented Oct 3, 2018

fl0w commented Nov 9, 2018

fl0w commented Mar 13, 2019

buu700 commented Aug 5, 2018 •

edited

Loading

buu700 commented Aug 5, 2018 •

edited

Loading

damianobarbati commented Sep 26, 2018 •

edited

Loading

edevil commented Sep 28, 2018 •

edited

Loading

damianobarbati commented Sep 28, 2018 •

edited

Loading