[Bug] http.IncomingMessage.destroyed is true after payload read since v15.5.0

[dr-js]

• 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 true

How 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.

[dr-js]

Update:

I added request.socket.destroyed to 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.destroyed except the class Extends: <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.destroyed behaves consistently:

diff --git a/linux-12.txt b/linux-15.5.txt
index ff2b77d..cab1b33 100644
--- a/linux-12.txt
+++ b/linux-15.5.txt
@@ -1,71 +1,71 @@
-## TEST ENV v12.20.0 linux x64 ##
+## TEST ENV v15.5.0 linux x64 ##
 ## testNormalPost ##
 [httpServer] created
 - [httpRequest] created
 [httpServer] same socket true
-[httpServer] soc/req/res.destroyed false false undefined
-[httpServer] soc/req/res.destroyed read false false undefined
+[httpServer] soc/req/res.destroyed false false false
+[httpServer] soc/req/res.destroyed read false true false
 [httpServer] requestBuffer.length 320
-[httpServer] soc/req/res.destroyed wait128 false false undefined
-[httpServer] soc/req/res.destroyed end false false undefined
+[httpServer] soc/req/res.destroyed wait128 false true false
+[httpServer] soc/req/res.destroyed end false true false
 - [httpRequest] same socket true
-- [httpRequest] soc/req/res.destroyed false undefined false
-- [httpRequest] soc/req/res.destroyed read false undefined false
+- [httpRequest] soc/req/res.destroyed false false false
+- [httpRequest] soc/req/res.destroyed read false false true
 - [httpRequest] responseBuffer.length 320
-[httpServer] soc/req/res.destroyed close true false undefined
+[httpServer] soc/req/res.destroyed close true true true

[lpinca]

I think the change was introduced with #33035.

cc: @nodejs/http

[benjamingr]

cc @nodejs/streams

[ronag]

I think the behavior is correct. Is this actually a problem?

[dr-js]

@ronag

From a server point of view when:

• the request/IncommingMessage has received all header & payload,
  so request.destroyed can be true, or false (old behavior)
• the response/ServerResponse still waits for statusCode & payload,
  so response.destroyed is false

But the underlying response.socket/request.socket is the same socket, and socket.destroyed is false, for me the main confusing point is:

• with old behavior, I think both as a wrapper of socket, so each delegates the Readable/Writable part of Duplex, thus both report socket.destroyed to be false
• the new behavior is more like the request is a new Readable forked from the socket, so request.destroyed can be independent of the socket.destroyed value

This 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 to request.socket.destroyed.

Update:
The doced property to check should be IncommingMessage.aborted/complete, I think I choose to check Stream.destroyed for it seemed to work for both request (IncommingMessage/ClientRequest).

[ronag]

Don't use:

• IncommingMessage.aborted
• IncommingMessage.complete
• IncommingMessage.socket
• IncommingMessage.on('aborted')

IMO all of them should be deprecated.

Do use:

• IncommingMessage.destroyed
• IncommingMessage.readableEnded
• IncommingMessage.on('error')

[mcollina]

the new behavior is more like the request is a new Readable forked from the socket.

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]

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]

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 IncomingMessage to the doc?

[ronag]

Should we add some of the clarification for IncomingMessage to the doc?

PR welcome. Feel free to close issue.

[dr-js]

PR added: #36641
And sorry for the late response.