Repository: pinojs/pino-http
Pull request #18 (2016-12-08 15:27:23)

Print log for aborted connections
It's possible that requests takes so long that it's either aborted by the browser or by the http.Server.
In both cases, there is no log call saying that the connection is dead, which gives the feeling in the logs, that request is still in progress.


Patch:
diff --git a/logger.js b/logger.js
index f357fcd..f425296 100644
--- a/logger.js
+++ b/logger.js
@@ -46,13 +46,22 @@ function pinoLogger (opts, stream) {
     }, 'request completed')
   }
 
+  function onReqAborted () {
+    var res = this.res
+    res.statusCode = 408
+    onResFinished.call(res, new Error('Aborted'))
+  }
+
   function loggingMiddleware (req, res, next) {
     req.id = genReqId(req)
     req.log = res.log = logger.child({req: req})
     res.startTime = Date.now()
+    if (!req.res) { req.res = res }
 
     res.on('finish', onResFinished)
     res.on('error', onResFinished)
+    // it's possible that browser aborts connection, or http-server because of timeout
+    req.on('aborted', onReqAborted)
 
     if (next) {
       next()


Test patch:
diff --git a/test.js b/test.js
index 6f958bd..450e2bc 100644
--- a/test.js
+++ b/test.js
@@ -29,7 +29,7 @@ function setup (t, logger, cb, handler) {
 
 function doGet (server) {
   var address = server.address()
-  http.get('http://' + address.address + ':' + address.port)
+  return http.get('http://' + address.address + ':' + address.port)
 }
 
 test('default settings', function (t) {
@@ -257,3 +257,76 @@ test('support a custom instance with custom genReqId function', function (t) {
     t.end()
   })
 })
+
+test('react on aborted event from clientside', function (t) {
+  var dest = split(JSON.parse)
+
+  var idToTest
+  function genReqId (req) {
+    t.ok(req.url, 'The first argument must be the request parameter')
+    idToTest = (Date.now() + Math.random()).toString(32)
+    return idToTest
+  }
+
+  var logger = pinoHttp({
+    logger: pino({
+      serializers: pino.stdSerializers
+    }, dest),
+    genReqId: genReqId
+  })
+
+  setup(t, logger, function (err, server) {
+    t.error(err)
+    var address = server.address()
+    var request = http.get({
+      host: address.address,
+      port: address.port
+    })
+    // need this in order to prevent unhadled socket handup
+    request.on('error', function () {})
+    setTimeout(function () {
+      // break the connection from the clientside
+      request.abort()
+    }, 100)
+  }, logger)
+
+  dest.on('data', function (line) {
+    t.equal(line.msg, 'request errored', 'message is set')
+    t.equal(line.err.message, 'Aborted', 'error message is set')
+    t.equal(line.res.statusCode, 408, 'statusCode is 408')
+    t.end()
+  })
+})
+
+test('react on aborted event from server', function (t) {
+  var dest = split(JSON.parse)
+
+  var idToTest
+  function genReqId (req) {
+    t.ok(req.url, 'The first argument must be the request parameter')
+    idToTest = (Date.now() + Math.random()).toString(32)
+    return idToTest
+  }
+
+  var logger = pinoHttp({
+    logger: pino({
+      serializers: pino.stdSerializers
+    }, dest),
+    genReqId: genReqId
+  })
+
+  setup(t, logger, function (err, server) {
+    server.timeout = 100
+    t.error(err)
+    var request = doGet(server)
+    // need this in order to prevent unhadled socket handup
+    request.on('error', function () {})
+  }, logger)
+
+  dest.on('data', function (line) {
+    t.equal(line.msg, 'request errored', 'message is set')
+    t.equal(line.err.message, 'Aborted', 'error message is set')
+    t.equal(line.res.statusCode, 408, 'statusCode is 408')
+    t.end()
+  })
+})