Log requests aborted during payload processing (#219)

* Log requests aborted during payload processing

* Bind server address and port to fix CI on Node 17 and above

logger.js

@@ -78,7 +78,7 @@ function pinoLogger (opts, stream) {
   delete opts.autoLogging
 
   const receivedMessage = opts.customReceivedMessage && typeof opts.customReceivedMessage === 'function' ? opts.customReceivedMessage : undefined
-  const successMessage = opts.customSuccessMessage || function () { return 'request completed' }
+  const successMessage = opts.customSuccessMessage || function (req, res) { return res.writableEnded ? 'request completed' : 'request aborted' }
   const errorMessage = opts.customErrorMessage || function () { return 'request errored' }
   delete opts.customSuccessfulMessage
   delete opts.customErroredMessage
@@ -91,6 +91,7 @@ function pinoLogger (opts, stream) {
   return loggingMiddleware
 
   function onResFinished (err) {
+    this.removeListener('close', onResFinished)
     this.removeListener('error', onResFinished)
     this.removeListener('finish', onResFinished)
 
@@ -178,6 +179,7 @@ function pinoLogger (opts, stream) {
           req.log[level](receivedMessage(req, res))
         }
 
+        res.on('close', onResFinished)
         res.on('finish', onResFinished)
       }
 

test/test.js

@@ -2,6 +2,8 @@
 
 const test = require('tap').test
 const http = require('http')
+const net = require('net')
+const stream = require('stream')
 const pinoHttp = require('../')
 const pino = require('pino')
 const split = require('split2')
@@ -12,6 +14,7 @@ const noop = function () {}
 
 const DEFAULT_REQUEST_RECEIVED_MSG = 'request received'
 const DEFAULT_REQUEST_COMPLETED_MSG = 'request completed'
+const DEFAULT_REQUEST_ABORTED_MSG = 'request aborted'
 const DEFAULT_REQUEST_ERROR_MSG = 'request errored'
 
 function setup (t, logger, cb, handler, next) {
@@ -354,6 +357,48 @@ test('responseTime for request emitting error event', function (t) {
   })
 })
 
+test('log requests aborted during payload', function (t) {
+  const dest = split(JSON.parse)
+  const logger = pinoHttp(dest)
+
+  function handle (req, res) {
+    logger(req, res)
+
+    const read = new stream.Readable({
+      read () {
+        if (this.called) {
+          return
+        }
+
+        this.called = true
+        this.push('delayed')
+      }
+    })
+
+    read.pipe(res)
+  }
+
+  function listen (err, server) {
+    t.error(err)
+
+    const client = net.connect(server.address().port, server.address().address, () => {
+      client.write('GET /delayed HTTP/1.1\r\n\r\n')
+    })
+
+    client.on('data', (data) => {
+      client.destroy()
+    })
+  }
+
+  setup(t, logger, listen, handle)
+
+  dest.on('data', function (line) {
+    t.ok(line.responseTime >= 0, 'responseTime is defined')
+    t.equal(line.msg, DEFAULT_REQUEST_ABORTED_MSG, 'message is set')
+    t.end()
+  })
+})
+
 test('no auto logging with autoLogging set to false', function (t) {
   const dest = split(JSON.parse)
   const logger = pinoHttp({ autoLogging: false }, dest)