Request streams from http2 intermittantly not emitting end event
-
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; emailAddress=jpage@godaddy.com
* 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; emailAddress=jpage@godaddy.com
* 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.