Request streams from http2 intermittantly not emitting end event #31309
Comments
|
Archive to reproduce (contains the certs). You also have to point your host file such that |
|
(Created prior zip incorrectly) |
|
Updates on debugging. I was able to make this a bit easier to reproduce by adding more activity to the server: 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 I've also captured an additional This is the state of the request during the handling of the final ...and this is the state at the time of the request having been aborted: Doing a diff on the two, here's two takeaways I got:
|
|
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 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. |
|
Can you reproduce it when not using the compat API? Just to see if we can remove one layer of complexity. |
|
@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: 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: |
|
Strike that... while seeing if using the So this appears to be a problem with raw http2 streams, not just the compatibility API. |
DullReferenceException
changed the title
|
@nodejs/http2 seems related to http2 core |
|
@DullReferenceException: Can you see what other events you get? Does it emit e.g. |
|
It does not emit any |
|
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: |
|
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 :; doneHere'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. |
|
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. |
|
I just tried my repro on 12.4.0, and it does reproduce. So does 12.0.0. |
|
I used 12.4 for so long and didn't have any problem, this is how I read the request: req is a Http2ServerRequest object from Compatibility API. |
|
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. |
|
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 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. |
|
@akc42 what version(s) of node were you able to confirm this issue? |
|
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. |
|
I've upgraded to v13.9.0 and changed by code so that the 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) |
|
@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. |
|
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. |
|
@jasnell any progress on this? |
|
Hi, thanks for your thoughts. Since stream.on('end') is not reliable yet, my workoraund is: |
|
Any luck on this? This is affecting code in production for me. |
|
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. |
Adds support for reading from a stream where the final frame is a non-empty DATA frame with the END_STREAM flag set, instead of hanging waiting for another frame. When writing to a stream, uses a END_STREAM flag on final DATA frame instead of adding an empty DATA frame. BREAKING: http2 client now expects servers to properly support END_STREAM flag Fixes: nodejs#31309 Fixes: nodejs#33891 Refs: https://nghttp2.org/documentation/types.html#c.nghttp2_on_data_chunk_recv_callback
|
Just chiming in here - is this related to the bug I discovered here? #33687 |
|
@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 I suggest you use the workaround in the comment above which will "wake up" the stalled state. |
|
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. |
|
@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? |
|
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 If the documentation here is how I assume it to be, you might be able to do |
|
@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 |
|
@niftylettuce You're still going to drop a perfectly good connection. You'll send something like an error with status code
You'll have to modify https://github.com/stream-utils/raw-body/blob/0e1291f1d6cbc9ee8e16f893d091e417841c95e5/index.js#L240 in your To be honest, it might be easier to switch to |
|
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 niftylettuce@gmail.com with your PayPal or preferred means of receiving the bug bounty award for this? |
|
As I mentioned over email, the examples you had shared by email @clshortfuse did not work unfortunately. |
Adds support for reading from a stream where the final frame is a non-empty DATA frame with the END_STREAM flag set, instead of hanging waiting for another frame. When writing to a stream, uses a END_STREAM flag on final DATA frame instead of adding an empty DATA frame. BREAKING: http2 client now expects servers to properly support END_STREAM flag Fixes: nodejs#31309 Fixes: nodejs#33891 Refs: https://nghttp2.org/documentation/types.html#c.nghttp2_on_data_chunk_recv_callback PR-URL: nodejs#33875 Reviewed-By: Anna Henningsen <anna@addaleax.net> Reviewed-By: James M Snell <jasnell@gmail.com>
Adds support for reading from a stream where the final frame is a non-empty DATA frame with the END_STREAM flag set, instead of hanging waiting for another frame. When writing to a stream, uses a END_STREAM flag on final DATA frame instead of adding an empty DATA frame. BREAKING: http2 client now expects servers to properly support END_STREAM flag Fixes: nodejs#31309 Fixes: nodejs#33891 Refs: https://nghttp2.org/documentation/types.html#c.nghttp2_on_data_chunk_recv_callback
Adds support for reading from a stream where the final frame is a non-empty DATA frame with the END_STREAM flag set, instead of hanging waiting for another frame. Fixes: nodejs#31309 Refs: https://nghttp2.org/documentation/types.html#c.nghttp2_on_data_chunk_recv_callback PR-URL: nodejs#33875 Reviewed-By: Anna Henningsen <anna@addaleax.net> Reviewed-By: James M Snell <jasnell@gmail.com>
Adds support for reading from a stream where the final frame is a non-empty DATA frame with the END_STREAM flag set, instead of hanging waiting for another frame. When writing to a stream, uses a END_STREAM flag on final DATA frame instead of adding an empty DATA frame. BREAKING: http2 client now expects servers to properly support END_STREAM flag Fixes: #31309 Fixes: #33891 Refs: https://nghttp2.org/documentation/types.html#c.nghttp2_on_data_chunk_recv_callback PR-URL: #33875 Backport-PR-URL: #34838 Reviewed-By: Anna Henningsen <anna@addaleax.net> Reviewed-By: James M Snell <jasnell@gmail.com>
Adds support for reading from a stream where the final frame is a non-empty DATA frame with the END_STREAM flag set, instead of hanging waiting for another frame. Fixes: #31309 Refs: https://nghttp2.org/documentation/types.html#c.nghttp2_on_data_chunk_recv_callback PR-URL: #33875 Backport-PR-URL: #34857 Reviewed-By: Anna Henningsen <anna@addaleax.net> Reviewed-By: James M Snell <jasnell@gmail.com>
Adds support for reading from a stream where the final frame is a non-empty DATA frame with the END_STREAM flag set, instead of hanging waiting for another frame. When writing to a stream, uses a END_STREAM flag on final DATA frame instead of adding an empty DATA frame. BREAKING: http2 client now expects servers to properly support END_STREAM flag Fixes: nodejs#31309 Fixes: nodejs#33891 Refs: https://nghttp2.org/documentation/types.html#c.nghttp2_on_data_chunk_recv_callback PR-URL: nodejs#33875 Reviewed-By: Anna Henningsen <anna@addaleax.net> Reviewed-By: James M Snell <jasnell@gmail.com>
Adds support for reading from a stream where the final frame is a non-empty DATA frame with the END_STREAM flag set, instead of hanging waiting for another frame. When writing to a stream, uses a END_STREAM flag on final DATA frame instead of adding an empty DATA frame. BREAKING: http2 client now expects servers to properly support END_STREAM flag Fixes: #31309 Fixes: #33891 Refs: https://nghttp2.org/documentation/types.html#c.nghttp2_on_data_chunk_recv_callback Backport-PR-URL: #34845 PR-URL: #33875 Reviewed-By: Anna Henningsen <anna@addaleax.net> Reviewed-By: James M Snell <jasnell@gmail.com>
Adds support for reading from a stream where the final frame is a non-empty DATA frame with the END_STREAM flag set, instead of hanging waiting for another frame. When writing to a stream, uses a END_STREAM flag on final DATA frame instead of adding an empty DATA frame. BREAKING: http2 client now expects servers to properly support END_STREAM flag Fixes: #31309 Fixes: #33891 Refs: https://nghttp2.org/documentation/types.html#c.nghttp2_on_data_chunk_recv_callback Backport-PR-URL: #34845 PR-URL: #33875 Reviewed-By: Anna Henningsen <anna@addaleax.net> Reviewed-By: James M Snell <jasnell@gmail.com>
v12.14.0http2In 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
endevent is received. Thedataevents are firing fine, and all bytes are downloaded (a counter confirms that the number of bytes equalscontent-length). As you can imagine, this impacts things like middlewares which are waiting for theendevent 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:
I have a way to reproduce... sort of. Essentially I create a secure http2 server and spam it with JSON post requests.
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:
When this timeout abort occurs, I see from the server's logs:
If it helps, here's what the
console.dirof the request object shows. Maybe its state lends some clues as to what's going on: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.
The text was updated successfully, but these errors were encountered: