Repository navigation
[Bug] http.IncomingMessage.destroyed is true after payload read since v15.5.0 #36617
Description
- Version: v15.5.0
- Platform: linux/win32/darwin
- Subsystem: http
What steps will reproduce the bug?
Can test with the following script: (added two more test on closing)
[test-nodejs-v15.5.0-http-stream-destroyed.js]
console.log(`## TEST ENV ${process.version} ${process.platform} ${process.arch} ##`)
// test for the HTTP `stream.destroyed` change in nodejs v15.5.0
const { createServer, request } = require('http')
const readableStreamToBufferAsync = (readableStream) => new Promise((resolve, reject) => { // the stream is handled
const data = []
readableStream.on('error', reject)
readableStream.on('close', () => reject(new Error('unexpected stream close'))) // for close before end, should already resolved for normal close
readableStream.on('end', () => resolve(Buffer.concat(data)))
readableStream.on('data', (chunk) => data.push(chunk))
})
const setTimeoutAsync = (wait = 0) => new Promise((resolve) => setTimeout(resolve, wait))
const log = (...args) => console.log(...args) // const log = (...args) => console.log(new Date().toISOString(), ...args) // NOTE: for log time to debug
const HOSTNAME = '127.0.0.1'
const PORT = 3000
const PAYLOAD_BUFFER = Buffer.from('test-'.repeat(64))
const testNormalPost = () => new Promise((resolve) => {
log('## testNormalPost ##')
// basic server
const httpServer = createServer()
httpServer.listen(PORT, HOSTNAME)
httpServer.on('request', async (request, response) => {
log('[httpServer] request|response.destroyed', request.destroyed, response.destroyed)
const requestBuffer = await readableStreamToBufferAsync(request)
log('[httpServer] request|response.destroyed read', request.destroyed, response.destroyed)
log('[httpServer] requestBuffer.length', requestBuffer.length)
await setTimeoutAsync(128)
log('[httpServer] request|response.destroyed 128', request.destroyed, response.destroyed)
response.end(requestBuffer)
log('[httpServer] request|response.destroyed end', request.destroyed, response.destroyed)
httpServer.close(() => {
log('[httpServer] request|response.destroyed close', request.destroyed, response.destroyed)
resolve()
})
})
log('[httpServer] created')
// POST request
const httpRequest = request(`http://${HOSTNAME}:${PORT}`, { method: 'POST' })
httpRequest.on('response', async (httpResponse) => {
log('- [httpRequest] httpRequest|httpResponse.destroyed', httpRequest.destroyed, httpResponse.destroyed)
const responseBuffer = await readableStreamToBufferAsync(httpResponse)
log('- [httpRequest] httpRequest|httpResponse.destroyed read', httpRequest.destroyed, httpResponse.destroyed)
log('- [httpRequest] responseBuffer.length', responseBuffer.length)
})
httpRequest.end(PAYLOAD_BUFFER)
log('- [httpRequest] created')
})
const testClientClose = () => new Promise((resolve) => {
log('## testClientClose ##')
// basic server
const httpServer = createServer()
httpServer.listen(PORT, HOSTNAME)
httpServer.on('request', async (request, response) => {
log('[httpServer] request|response.destroyed', request.destroyed, response.destroyed)
const requestBuffer = await readableStreamToBufferAsync(request)
log('[httpServer] request|response.destroyed read', request.destroyed, response.destroyed)
log('[httpServer] requestBuffer.length', requestBuffer.length)
await setTimeoutAsync(128)
log('[httpServer] request|response.destroyed 128', request.destroyed, response.destroyed)
response.end(requestBuffer)
log('[httpServer] request|response.destroyed end', request.destroyed, response.destroyed)
httpServer.close(() => {
log('[httpServer] request|response.destroyed close', request.destroyed, response.destroyed)
resolve()
})
})
log('[httpServer] created')
// POST request
const httpRequest = request(`http://${HOSTNAME}:${PORT}`, { method: 'POST' })
httpRequest.on('response', async (httpResponse) => {
log('- [SHOULD NOT REACH THIS] [httpRequest] httpRequest|httpResponse.destroyed', httpRequest.destroyed, httpResponse.destroyed)
})
httpRequest.end(PAYLOAD_BUFFER)
httpRequest.on('error', (error) => {
log('- [httpRequest] httpRequest.destroyed error', httpRequest.destroyed)
log('- [httpRequest] error', error.message)
})
setTimeoutAsync(64).then(() => {
log('- [httpRequest] httpRequest.destroy!')
httpRequest.destroy()
log('- [httpRequest] httpRequest.destroyed destroy', httpRequest.destroyed)
})
log('- [httpRequest] created')
})
const testServerClose = () => new Promise((resolve) => {
log('## testServerClose ##')
// basic server
const httpServer = createServer()
httpServer.listen(PORT, HOSTNAME)
httpServer.on('request', async (request, response) => {
log('[httpServer] request.destroy!')
request.destroy()
log('[httpServer] request|response.destroyed destroy', request.destroyed, response.destroyed)
httpServer.close(() => {
log('[httpServer] request|response.destroyed close', request.destroyed, response.destroyed)
resolve()
})
})
log('[httpServer] created')
// POST request
const httpRequest = request(`http://${HOSTNAME}:${PORT}`, { method: 'POST' })
httpRequest.on('response', async (httpResponse) => {
log('- [SHOULD NOT REACH THIS] [httpRequest] httpRequest|httpResponse.destroyed', httpRequest.destroyed, httpResponse.destroyed)
})
httpRequest.end(PAYLOAD_BUFFER)
httpRequest.on('error', (error) => {
log('- [httpRequest] httpRequest.destroyed error', httpRequest.destroyed)
log('- [httpRequest] error', error.message)
})
log('- [httpRequest] created')
})
const wait32 = () => setTimeoutAsync(32)
Promise.resolve()
.then(testNormalPost).then(wait32)
.then(testClientClose).then(wait32)
.then(testServerClose).then(wait32)
// repeat
.then(testNormalPost).then(wait32)
.then(testClientClose).then(wait32)
.then(testServerClose).then(wait32)
The GitHub Action run for 12/14/15.4/15.5 with linux/win32/darwin: https://github.com/dr-js/dr-js/actions/runs/442120897 (should last for 60 days)
The run output: test-output.zip
The main difference between 15.4 and 15.5 is: (used linux output)
diff --git a/test-output/linux-15.4.txt b/test-output/linux-15.5.txt
index f12d3bf..4f0e70a 100644
--- a/test-output/linux-15.4.txt
+++ b/test-output/linux-15.5.txt
@@ -1,21 +1,21 @@
-## TEST ENV v15.4.0 linux x64 ##
+## TEST ENV v15.5.0 linux x64 ##
## testNormalPost ##
[httpServer] created
- [httpRequest] created
[httpServer] request|response.destroyed false false
-[httpServer] request|response.destroyed read false false
+[httpServer] request|response.destroyed read true false
[httpServer] requestBuffer.length 320
-[httpServer] request|response.destroyed 128 false false
-[httpServer] request|response.destroyed end false false
+[httpServer] request|response.destroyed 128 true false
+[httpServer] request|response.destroyed end true false
- [httpRequest] httpRequest|httpResponse.destroyed false false
-- [httpRequest] httpRequest|httpResponse.destroyed read false false
+- [httpRequest] httpRequest|httpResponse.destroyed read false true
- [httpRequest] responseBuffer.length 320
[httpServer] request|response.destroyed close true trueHow often does it reproduce? Is there a required condition?
Should always reproduce in v15.5.0.
What is the expected behavior?
No behavior change in minor release.
What do you see instead?
The issue is in Nodejs v15.5.0, the http.IncomingMessage.destroyed or the request.destroyed in server response, is set true as soon as the request payload is retrieved.
In earlier versions, the change to true will not be sooner than response.destroyed.
Additional information
The new behavior makes sense in some way.
But when thinking the request and response as wrapper of the same underlying socket, I think both should be destroyed (or not) at the same time.
And response.destroyed is undefined in Nodejs v12, so only request.destroyed is checkable.
For my usage, I check the request.destroyed in server response to see if the socket is still "alive", and this behavior change make the check pass and main logic/result get skipped.
Activity
@dr-js/core@0.4.3-dev.1
dr-js commentedon Dec 24, 2020
Update:
I added
request.socket.destroyedto the test, and seems like that's the correct value I should check against, and it's consistent since v12.I rechecked the HTTP API doc, there's no mention of
http.IncomingMessage.destroyedexcept the classExtends: <stream.Readable>, so maybe this should be treated as undocumented behavior change instead of bug?The test branch, updated CI run, and run output: test-output-update.zip
And the updated main diff shows
socket.destroyedbehaves consistently:@dr-js/core@0.4.3
lpinca commentedon Dec 26, 2020
I think the change was introduced with #33035.
cc: @nodejs/http
benjamingr commentedon Dec 26, 2020
cc @nodejs/streams
ronag commentedon Dec 26, 2020
I think the behavior is correct. Is this actually a problem?
dr-js commentedon Dec 27, 2020
@ronag
From a server point of view when:
request/IncommingMessagehas received all header & payload,so
request.destroyedcan betrue, orfalse(old behavior)response/ServerResponsestill waits for statusCode & payload,so
response.destroyedisfalseBut the underlying
response.socket/request.socketis the samesocket, andsocket.destroyedisfalse, for me the main confusing point is:socket, so each delegates the Readable/Writable part of Duplex, thus both reportsocket.destroyedto befalserequestis a new Readable forked from thesocket, sorequest.destroyedcan be independent of thesocket.destroyedvalueThis behavior change caused a concept change for me, so maybe it should be marked a break change?
Or my concept for the old behavior is wrong.
For me the code fix is to drop some unused
request.destroyed, and change others torequest.socket.destroyed.Update:
The doced property to check should be
IncommingMessage.aborted/complete, I think I choose to checkStream.destroyedfor it seemed to work for bothrequest(IncommingMessage/ClientRequest).ronag commentedon Dec 27, 2020
Don't use:
IncommingMessage.abortedIncommingMessage.completeIncommingMessage.socketIncommingMessage.on('aborted')IMO all of them should be deprecated.
Do use:
IncommingMessage.destroyedIncommingMessage.readableEndedIncommingMessage.on('error')mcollina commentedon Dec 27, 2020
This has always been true since Readable was introduced. IncomingMessage is a new Readable that gets its data from the underlining socket. This matches the reality as the same socket is reused multiple times in case of keep-alive.
I consider the new behavior to be less surprising given the current implementation.
mcollina commentedon Dec 27, 2020
In hindsight, #33035 could have been flagged semver-major - I'm not sure it's worth a revert in v15. Note that it has already flagged to not backport it to LTS lines.
dr-js commentedon Dec 27, 2020
Thanks for the explanation!
With my confusion solved and code fix done, I think I should close this issue, if this do not affect more code repo.
Should we add some of the clarification for
IncomingMessageto the doc?ronag commentedon Dec 27, 2020
PR welcome. Feel free to close issue.
dr-js commentedon Dec 27, 2020
PR added: #36641
And sorry for the late response.
6 remaining items
doc: document http.IncomingMessage behaviour change
doc: document http.IncomingMessage behaviour change
doc: deprecate (doc-only) http abort related
doc: deprecate (doc-only) http abort related
doc: deprecate (doc-only) http abort related