Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

NGHTTP2_REFUSED_STREAM on www.facebook.com #1285

Closed
duongvanba opened this issue May 25, 2020 · 19 comments
Closed

NGHTTP2_REFUSED_STREAM on www.facebook.com #1285

duongvanba opened this issue May 25, 2020 · 19 comments
Assignees
Labels
enhancement This change will extend Got features external The issue related to an external project

Comments

@duongvanba
Copy link

duongvanba commented May 25, 2020

Describe the bug

  • Node.js version: v10.20.1
  • OS & version: Ubuntu 18.04

I send 1k concurency request to facebook.com, there are no error util i send 1k request, it show NGHTTP2_REFUSED_STREAM (this is only error I see)
I don't have this problem when use request/request, i have 1k/1k success request without any error. But with got i have above error althought speed is very good
Can you fix this issue

Link code

@sindresorhus
Copy link
Owner

The first I would recommend is upgrading to Node.js 12 or 14. Also try turning off retrying. If it’s still the same issue, try to create a reduced test case that reproduces the problem.

@duongvanba
Copy link
Author

Still error on nodejs 14 bro

@duongvanba
Copy link
Author

duongvanba commented May 25, 2020

I see problem only happen when I use HTTP2 option
I think this error is come from HTTP2-warpper module

@szmarczak
Copy link
Collaborator

It definitely is caused by http2-wrapper. Seems like the H2 session is overloaded, but in that case ENHANCE_YOUR_CALM should be thrown...

@duongvanba
Copy link
Author

So are there any suggestion for me ?

@szmarczak
Copy link
Collaborator

Not yet. I'll be active again in 3 weeks as I'm heavily preparing for the maturity exams here. Feel free to experiment though.

@duongvanba
Copy link
Author

The first I would recommend is upgrading to Node.js 12 or 14. Also try turning off retrying. If it’s still the same issue, try to create a reduced test case that reproduces the problem.

Problem only on got bro, I use fetch-h2 then I didnot have this problem

@szmarczak
Copy link
Collaborator

szmarczak commented Jul 6, 2020

Node.js 14.5.0, 10-15 Mbps connection, WiFi 50% signal
Start testing GOT
==> Test with 1000 concurrent request
(node:73757) DeprecationWarning: Got: "options.rejectUnauthorized" is now deprecated, please use "options.https.rejectUnauthorized"
(Use `node --trace-deprecation ...` to show where the warning was created)
┌────────────────────┬───────────────────────────┐
│      (index)       │          Values           │
├────────────────────┼───────────────────────────┤
│        name        │ 'Got + HTTP2 + DNS CACHE' │
│         n          │           1000            │
│    request_time    │           1570            │
│      success       │           1000            │
│        fail        │             0             │
│ request_per_second │    0.6369426751592356     │
│   ms_per_request   │           1.57            │
└────────────────────┴───────────────────────────┘
==> Test with 1000 concurrent request
┌────────────────────┬───────────────────────────┐
│      (index)       │          Values           │
├────────────────────┼───────────────────────────┤
│        name        │ 'Got + HTTP2 + DNS CACHE' │
│         n          │           1000            │
│    request_time    │           1269            │
│      success       │            953            │
│        fail        │            47             │
│ request_per_second │    0.7509850275807722     │
│   ms_per_request   │    1.3315844700944386     │
└────────────────────┴───────────────────────────┘
[Set Iterator] {
  'Stream closed with error code NGHTTP2_REFUSED_STREAM'
}
==> Test with 1000 concurrent request
┌────────────────────┬───────────────────────────┐
│      (index)       │          Values           │
├────────────────────┼───────────────────────────┤
│        name        │ 'Got + HTTP2 + DNS CACHE' │
│         n          │           1000            │
│    request_time    │           1149            │
│      success       │           1000            │
│        fail        │             0             │
│ request_per_second │    0.8703220191470844     │
│   ms_per_request   │           1.149           │
└────────────────────┴───────────────────────────┘
==> Test with 1000 concurrent request
┌────────────────────┬───────────────────────────┐
│      (index)       │          Values           │
├────────────────────┼───────────────────────────┤
│        name        │ 'Got + HTTP2 + DNS CACHE' │
│         n          │           1000            │
│    request_time    │           1130            │
│      success       │           1000            │
│        fail        │             0             │
│ request_per_second │    0.8849557522123894     │
│   ms_per_request   │           1.13            │
└────────────────────┴───────────────────────────┘
==> Test with 1000 concurrent request
┌────────────────────┬───────────────────────────┐
│      (index)       │          Values           │
├────────────────────┼───────────────────────────┤
│        name        │ 'Got + HTTP2 + DNS CACHE' │
│         n          │           1000            │
│    request_time    │           1100            │
│      success       │           1000            │
│        fail        │             0             │
│ request_per_second │    0.9090909090909091     │
│   ms_per_request   │            1.1            │
└────────────────────┴───────────────────────────┘
==> Test with 1000 concurrent request
┌────────────────────┬───────────────────────────┐
│      (index)       │          Values           │
├────────────────────┼───────────────────────────┤
│        name        │ 'Got + HTTP2 + DNS CACHE' │
│         n          │           1000            │
│    request_time    │           1160            │
│      success       │            988            │
│        fail        │            12             │
│ request_per_second │    0.8517241379310345     │
│   ms_per_request   │     1.174089068825911     │
└────────────────────┴───────────────────────────┘
[Set Iterator] {
  'Stream closed with error code NGHTTP2_REFUSED_STREAM'
}
==> Test with 1000 concurrent request
┌────────────────────┬───────────────────────────┐
│      (index)       │          Values           │
├────────────────────┼───────────────────────────┤
│        name        │ 'Got + HTTP2 + DNS CACHE' │
│         n          │           1000            │
│    request_time    │           1177            │
│      success       │           1000            │
│        fail        │             0             │
│ request_per_second │    0.8496176720475785     │
│   ms_per_request   │           1.177           │
└────────────────────┴───────────────────────────┘
==> Test with 1000 concurrent request
┌────────────────────┬───────────────────────────┐
│      (index)       │          Values           │
├────────────────────┼───────────────────────────┤
│        name        │ 'Got + HTTP2 + DNS CACHE' │
│         n          │           1000            │
│    request_time    │           1264            │
│      success       │           1000            │
│        fail        │             0             │
│ request_per_second │    0.7911392405063291     │
│   ms_per_request   │           1.264           │
└────────────────────┴───────────────────────────┘
==> Test with 1000 concurrent request
┌────────────────────┬───────────────────────────┐
│      (index)       │          Values           │
├────────────────────┼───────────────────────────┤
│        name        │ 'Got + HTTP2 + DNS CACHE' │
│         n          │           1000            │
│    request_time    │           1107            │
│      success       │           1000            │
│        fail        │             0             │
│ request_per_second │    0.9033423667570009     │
│   ms_per_request   │           1.107           │
└────────────────────┴───────────────────────────┘
==> Test with 1000 concurrent request
┌────────────────────┬───────────────────────────┐
│      (index)       │          Values           │
├────────────────────┼───────────────────────────┤
│        name        │ 'Got + HTTP2 + DNS CACHE' │
│         n          │           1000            │
│    request_time    │           1231            │
│      success       │           1000            │
│        fail        │             0             │
│ request_per_second │    0.8123476848090982     │
│   ms_per_request   │           1.231           │
└────────────────────┴───────────────────────────┘
┌─────────┬───────────────────────────┬──────┬──────────────┬─────────┬──────┬────────────────────┬────────────────────┐
│ (index) │           name            │  n   │ request_time │ success │ fail │ request_per_second │   ms_per_request   │
├─────────┼───────────────────────────┼──────┼──────────────┼─────────┼──────┼────────────────────┼────────────────────┤
│    0    │ 'Got + HTTP2 + DNS CACHE' │ 1000 │     1570     │  1000   │  0   │ 0.6369426751592356 │        1.57        │
│    1    │ 'Got + HTTP2 + DNS CACHE' │ 1000 │     1269     │   953   │  47  │ 0.7509850275807722 │ 1.3315844700944386 │
│    2    │ 'Got + HTTP2 + DNS CACHE' │ 1000 │     1149     │  1000   │  0   │ 0.8703220191470844 │       1.149        │
│    3    │ 'Got + HTTP2 + DNS CACHE' │ 1000 │     1130     │  1000   │  0   │ 0.8849557522123894 │        1.13        │
│    4    │ 'Got + HTTP2 + DNS CACHE' │ 1000 │     1100     │  1000   │  0   │ 0.9090909090909091 │        1.1         │
│    5    │ 'Got + HTTP2 + DNS CACHE' │ 1000 │     1160     │   988   │  12  │ 0.8517241379310345 │ 1.174089068825911  │
│    6    │ 'Got + HTTP2 + DNS CACHE' │ 1000 │     1177     │  1000   │  0   │ 0.8496176720475785 │       1.177        │
│    7    │ 'Got + HTTP2 + DNS CACHE' │ 1000 │     1264     │  1000   │  0   │ 0.7911392405063291 │       1.264        │
│    8    │ 'Got + HTTP2 + DNS CACHE' │ 1000 │     1107     │  1000   │  0   │ 0.9033423667570009 │       1.107        │
│    9    │ 'Got + HTTP2 + DNS CACHE' │ 1000 │     1231     │  1000   │  0   │ 0.8123476848090982 │       1.231        │
└─────────┴───────────────────────────┴──────┴──────────────┴─────────┴──────┴────────────────────┴────────────────────┘

@szmarczak
Copy link
Collaborator

Reproducible with http2-wrapper only:

const http2 = require('.');

(async () => {
    const url = 'https://www.facebook.com/video/autoplay/nux/';

    const headers = {
        'User-Agent': 'Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/79.0.3945.130 Safari/537.36',
        'Origin': 'https://www.facebook.com',
        'Referer': 'https://www.facebook.com',
        'cache-control': 'no-cache',
		'accept-language': 'en-US,en',
		'content-type': 'application/x-www-form-urlencoded'
	};

    const form = {
        "__user":"0",
        "__a":"1",
        "__dyn":"7xeUmLwjbgmg9odoKEaVuC1swXCwAxu13wqovzErxuEc8uKewhE4mdwJx64e2u3mcw9m3y4o3Bwxxm0xU5y1wKE4W15w8i1rwnEszU2rxK4obHxK8wgolzUOmVo7y1NwgEcHzoaEaoGqfw8u1txm2l2Utwwwi83NwKwFxe0H8-7Eoxmm1Dwdq1iwmE",
        "__csr":"",
        "__req":"1",
        "__beoa":"0",
        "__pc":"PHASED:DEFAULT",
        "dpr":"1",
        "__ccg":"GOOD",
        "__rev":"1002161514",
        "__s":"u7q08f:t588bh:qe2d9f",
        "__hsi":"6830736561003934072-0",
        "__comet_req":"0",
        "lsd":"AVpPhxkG",
        "jazoest":"2745",
        "__spin_r":"1002161514",
        "__spin_b":"trunk",
        "__spin_t":"1590404790"
    };

	const body = (new URLSearchParams(form)).toString();

	const sendRequest = () => new Promise((resolve, reject) => {
		const request = http2.request(url, { method: 'POST', headers});
		request.end(body);

		request.once('error', reject);

		const data = [];
		request.once('response', response => {
			response.on('data', chunk => {
				data.push(chunk);
			});

			response.once('end', () => {
				resolve(Buffer.concat(data).toString());
			});
		});
	});

    const result = [];

    const test = async (name, n, func) => {
        const errors = new Set();
        const time = Date.now();
        let success = 0;
		let fail = 0;

        await Promise.all(new Array(n).fill(0).map(async () => {
            try {
                const data = await func();
                JSON.parse(data.slice(9));
                success++;
            } catch (e) {
				console.log(e);
                errors.add(e.message);
                fail++;
            };
		}));

        const request_time = Date.now() - time;
        const request_per_second = success / request_time;
        const ms_per_request = request_time / success;
        const rs = { name, n, request_time, success, fail, request_per_second, ms_per_request };
        console.table(rs);
        errors.size > 0 && console.error(errors.values());
        result.push(rs);
    }

    for (let i = 1, n = 1000; i <= 10; i++) {
        console.log(`==> Test with ${n} concurrent request`)
		await test('HTTP2', n, sendRequest);
    }

    console.table(result)
})();

@szmarczak
Copy link
Collaborator

Interestingly it doesn't reproduce with GET.

Related:
square/okhttp#2543
square/okhttp#2506
golang/go#20985

@szmarczak
Copy link
Collaborator

Well it's definitely not an issue with maxConcurrentStreams since I tried setting a limit to 50 (max is at 100) requests per session and it still happened.

@szmarczak
Copy link
Collaborator

Doesn't happen also when Agent's maxFreeSessions option is set to 2.

@szmarczak
Copy link
Collaborator

Doesn't reproduce when Agent's maxSession option is set to 1. It has to be at least 2.

@szmarczak
Copy link
Collaborator

I have identified the source. Assume you want to make 200 requests. So this happens:

  1. A session is created, let's say session A. It says it can handle only 100 requests concurrently.
  2. We want to handle 200 requests concurrently, so session B is created.
  3. We sent successfully 100 requests to A.
  4. We sent successfully 80 requests to B. The next 20 requests is still in the queue (e.g. it can be delayed in the Node.js event loop).
  5. Session A responded to first e.g. 5 requests and now is free (meaning it can accept other requests).
  6. Session B responded to its first request and also wants to be free, but since A became first and maxFreeSessions is set to 1, sessionB.close() is executed.
  7. Session B knows that we want to close so it closes some requests with REFUSED_STREAM. The error means that these requets are unprocessed and are safe to retry.

The thing is that session B can reject more requests than session A has available. That needs to be fixed.

@szmarczak szmarczak added enhancement This change will extend Got features external The issue related to an external project labels Jul 7, 2020
@szmarczak szmarczak self-assigned this Jul 7, 2020
@szmarczak
Copy link
Collaborator

Unfortunately REFUSED_STREAM can throw even if the body was successfully uploaded. So, calling session.close() straight is definitely not the correct solution here.

@szmarczak
Copy link
Collaborator

szmarczak commented Jul 9, 2020

Results with the fix
==> Test with 1000 concurrent request
┌────────────────────┬────────────────────┐
│      (index)       │       Values       │
├────────────────────┼────────────────────┤
│        name        │      'HTTP2'       │
│         n          │        1000        │
│    request_time    │        813         │
│      success       │        1000        │
│        fail        │         0          │
│ request_per_second │ 1.2300123001230012 │
│   ms_per_request   │       0.813        │
└────────────────────┴────────────────────┘
==> Test with 1000 concurrent request
┌────────────────────┬────────────────────┐
│      (index)       │       Values       │
├────────────────────┼────────────────────┤
│        name        │      'HTTP2'       │
│         n          │        1000        │
│    request_time    │        664         │
│      success       │        1000        │
│        fail        │         0          │
│ request_per_second │ 1.5060240963855422 │
│   ms_per_request   │       0.664        │
└────────────────────┴────────────────────┘
==> Test with 1000 concurrent request
┌────────────────────┬────────────────────┐
│      (index)       │       Values       │
├────────────────────┼────────────────────┤
│        name        │      'HTTP2'       │
│         n          │        1000        │
│    request_time    │        618         │
│      success       │        1000        │
│        fail        │         0          │
│ request_per_second │ 1.6181229773462784 │
│   ms_per_request   │       0.618        │
└────────────────────┴────────────────────┘
==> Test with 1000 concurrent request
┌────────────────────┬───────────────────┐
│      (index)       │      Values       │
├────────────────────┼───────────────────┤
│        name        │      'HTTP2'      │
│         n          │       1000        │
│    request_time    │        434        │
│      success       │       1000        │
│        fail        │         0         │
│ request_per_second │ 2.304147465437788 │
│   ms_per_request   │       0.434       │
└────────────────────┴───────────────────┘
==> Test with 1000 concurrent request
┌────────────────────┬────────────────────┐
│      (index)       │       Values       │
├────────────────────┼────────────────────┤
│        name        │      'HTTP2'       │
│         n          │        1000        │
│    request_time    │        416         │
│      success       │        1000        │
│        fail        │         0          │
│ request_per_second │ 2.4038461538461537 │
│   ms_per_request   │       0.416        │
└────────────────────┴────────────────────┘
==> Test with 1000 concurrent request
┌────────────────────┬────────────────────┐
│      (index)       │       Values       │
├────────────────────┼────────────────────┤
│        name        │      'HTTP2'       │
│         n          │        1000        │
│    request_time    │        430         │
│      success       │        1000        │
│        fail        │         0          │
│ request_per_second │ 2.3255813953488373 │
│   ms_per_request   │        0.43        │
└────────────────────┴────────────────────┘
==> Test with 1000 concurrent request
┌────────────────────┬────────────────────┐
│      (index)       │       Values       │
├────────────────────┼────────────────────┤
│        name        │      'HTTP2'       │
│         n          │        1000        │
│    request_time    │        572         │
│      success       │        1000        │
│        fail        │         0          │
│ request_per_second │ 1.7482517482517483 │
│   ms_per_request   │       0.572        │
└────────────────────┴────────────────────┘
==> Test with 1000 concurrent request
┌────────────────────┬────────────────────┐
│      (index)       │       Values       │
├────────────────────┼────────────────────┤
│        name        │      'HTTP2'       │
│         n          │        1000        │
│    request_time    │        668         │
│      success       │        1000        │
│        fail        │         0          │
│ request_per_second │ 1.4970059880239521 │
│   ms_per_request   │       0.668        │
└────────────────────┴────────────────────┘
==> Test with 1000 concurrent request
┌────────────────────┬────────────────────┐
│      (index)       │       Values       │
├────────────────────┼────────────────────┤
│        name        │      'HTTP2'       │
│         n          │        1000        │
│    request_time    │        655         │
│      success       │        1000        │
│        fail        │         0          │
│ request_per_second │ 1.5267175572519085 │
│   ms_per_request   │       0.655        │
└────────────────────┴────────────────────┘
==> Test with 1000 concurrent request
┌────────────────────┬────────────────────┐
│      (index)       │       Values       │
├────────────────────┼────────────────────┤
│        name        │      'HTTP2'       │
│         n          │        1000        │
│    request_time    │        692         │
│      success       │        1000        │
│        fail        │         0          │
│ request_per_second │ 1.4450867052023122 │
│   ms_per_request   │       0.692        │
└────────────────────┴────────────────────┘
┌─────────┬─────────┬──────┬──────────────┬─────────┬──────┬────────────────────┬────────────────┐
│ (index) │  name   │  n   │ request_time │ success │ fail │ request_per_second │ ms_per_request │
├─────────┼─────────┼──────┼──────────────┼─────────┼──────┼────────────────────┼────────────────┤
│    0    │ 'HTTP2' │ 1000 │     813      │  1000   │  0   │ 1.2300123001230012 │     0.813      │
│    1    │ 'HTTP2' │ 1000 │     664      │  1000   │  0   │ 1.5060240963855422 │     0.664      │
│    2    │ 'HTTP2' │ 1000 │     618      │  1000   │  0   │ 1.6181229773462784 │     0.618      │
│    3    │ 'HTTP2' │ 1000 │     434      │  1000   │  0   │ 2.304147465437788  │     0.434      │
│    4    │ 'HTTP2' │ 1000 │     416      │  1000   │  0   │ 2.4038461538461537 │     0.416      │
│    5    │ 'HTTP2' │ 1000 │     430      │  1000   │  0   │ 2.3255813953488373 │      0.43      │
│    6    │ 'HTTP2' │ 1000 │     572      │  1000   │  0   │ 1.7482517482517483 │     0.572      │
│    7    │ 'HTTP2' │ 1000 │     668      │  1000   │  0   │ 1.4970059880239521 │     0.668      │
│    8    │ 'HTTP2' │ 1000 │     655      │  1000   │  0   │ 1.5267175572519085 │     0.655      │
│    9    │ 'HTTP2' │ 1000 │     692      │  1000   │  0   │ 1.4450867052023122 │     0.692      │
└─────────┴─────────┴──────┴──────────────┴─────────┴──────┴────────────────────┴────────────────┘

@duongvanba
Copy link
Author

nodejs/node#32978
Bro i think error is come from nodejs, not your library

@szmarczak
Copy link
Collaborator

No, this one is from my library. I wrongly introduced session closing.

@Ca11back
Copy link

Ca11back commented Dec 24, 2022

I don't why I can still get this error, and the concurency may be only 1~50/sec
http2-wrapper 2.2.0
got 12.5.3
node 19.3.0
run with the pm2

RequestError: Stream closed with error code NGHTTP2_REFUSED_STREAM
     at ClientRequest.<anonymous> (file:///home/ubuntu/koa/node_modules/got/dist/source/core/index.js:789:107)
     at Object.onceWrapper (node:events:628:26)
     at ClientRequest.emit (node:events:525:35)
     at emitErrorNT (node:internal/streams/destroy:151:8)
     at emitErrorCloseNT (node:internal/streams/destroy:116:3)
     at process.processTicksAndRejections (node:internal/process/task_queues:82:21)
     at new NodeError (node:internal/errors:400:5)
     at ClientHttp2Stream._destroy [as __destroy] (node:internal/http2/core:2348:13)
     at stream._destroy (/home/ubuntu/koa/node_modules/http2-wrapper/source/utils/delay-async-destroy.js:12:10)
     at _destroy (node:internal/streams/destroy:109:10)
     at ClientHttp2Stream.destroy (node:internal/streams/destroy:71:5)
     at Http2Stream.onStreamClose (node:internal/http2/core:551:12)
     at Http2Stream.callbackTrampoline (node:internal/async_hooks:130:17)

Any idea?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
enhancement This change will extend Got features external The issue related to an external project
Projects
None yet
Development

No branches or pull requests

4 participants