Repository: pinojs/hapi-pino (js)

Issue:
Request completed message is not super useful
The default message for the request completed log is `request completed`.
Which is not really useful. And definitely not in logging solutions like Google Cloud log where it uses this as the message to show.
<img width="512" alt="image" src="https://user-images.githubusercontent.com/2361826/157905593-c4b7913b-995b-4c0d-87eb-4d62ab4e6ec0.png">

The workaround is to add the needed fields to the summary of the log line but I think it might be more useful to log a summary of the request. e.g. `[response] get /version 200 (29ms)` => `[event type] method url statusCode (responseTime)`

Pull request:
feat: change response message to response summary
Fixes #155

Patch:
diff --git a/index.js b/index.js
index 6d011d7..e0bc685 100644
--- a/index.js
+++ b/index.js
@@ -37,7 +37,7 @@ async function register (server, options) {
     options.logEvents = ['onPostStart', 'onPostStop', 'response', 'request-error']
   }
 
-  var logger
+  let logger
   if (options.instance) {
     logger = options.instance
     const overrideDefaultErrorSerializer =
@@ -51,7 +51,7 @@ async function register (server, options) {
       options.transport.caller = getCallerFile()
     }
     options.stream = options.stream || process.stdout
-    var stream = options.stream || process.stdout
+    const stream = options.stream || process.stdout
     logger = pino(options, stream)
   }
 
@@ -69,7 +69,7 @@ async function register (server, options) {
     tagToLevelValue[tag] = logger.levels.values[tagToLevels[tag]]
   }
 
-  var ignoreTable = {}
+  const ignoreTable = {}
   if (options.ignorePaths) {
     for (let i = 0; i < options.ignorePaths.length; i++) {
       ignoreTable[options.ignorePaths[i]] = true
@@ -166,6 +166,9 @@ async function register (server, options) {
         const childBindings = getChildBindings(request)
         request.logger = logger.child(childBindings)
       }
+
+      const responseTime = (info.completed !== undefined ? info.completed : info.responded) - info.received
+
       request.logger.info(
         {
           payload: options.logPayload ? request.payload : undefined,
@@ -175,9 +178,9 @@ async function register (server, options) {
           // has the effect of setting it or "leaving it as it was" if it was already added via child bindings
           req: shouldLogRequestStart(request) ? undefined : request,
           res: request.raw.res,
-          responseTime: (info.completed !== undefined ? info.completed : info.responded) - info.received
+          responseTime
         },
-        'request completed'
+        `[response] ${request.method} ${request.path} ${request.raw.res.statusCode} (${responseTime}ms)`
       )
     }
   })
@@ -215,7 +218,7 @@ async function register (server, options) {
       return false
     }
 
-    for (var index = ignoreTags.length; index >= 0; index--) {
+    for (let index = ignoreTags.length; index >= 0; index--) {
       if (routeTags.includes(ignoreTags[index])) {
         return true
       }
@@ -229,7 +232,7 @@ async function register (server, options) {
   }
 
   function tryAddEvent (server, options, type, event, cb) {
-    var name = typeof event === 'string' ? event : event.name
+    const name = typeof event === 'string' ? event : event.name
     if (isEnabledLogEvent(options, name)) {
       if (type === 'on') {
         server.events.on(event, cb)
@@ -247,12 +250,12 @@ async function register (server, options) {
       return
     }
 
-    var tags = event.tags
-    var data = event.data
+    const tags = event.tags
+    let data = event.data
 
-    var logObject
+    let logObject
     if (mergeHapiLogData) {
-      if (typeof data === 'string') {
+      if (typeof data === 'string' || typeof data === 'number') {
         data = { [messageKey]: data }
       }
 
diff --git a/package.json b/package.json
index e46b4c8..cf6ae53 100644
--- a/package.json
+++ b/package.json
@@ -20,24 +20,24 @@
   ],
   "license": "MIT",
   "devDependencies": {
-    "@hapi/code": "^8.0.0",
+    "@hapi/code": "^8.0.7",
     "@hapi/hapi": "^20.2.1",
-    "@hapi/lab": "^24.3.2",
-    "coveralls": "^3.0.11",
+    "@hapi/lab": "^24.5.1",
+    "coveralls": "^3.1.1",
     "flush-write-stream": "^2.0.0",
     "make-promises-safe": "^5.1.0",
-    "pino-pretty": "^7.2.0",
+    "pino-pretty": "^7.5.3",
     "pre-commit": "^1.2.2",
-    "split2": "^3.1.1",
-    "standard": "^14.3.3",
-    "tsd": "^0.18.0"
+    "split2": "^4.1.0",
+    "standard": "^16.0.4",
+    "tsd": "^0.19.1"
   },
   "dependencies": {
-    "@hapi/hoek": "^9.0.0",
-    "@types/hapi__hapi": "^20.0.9",
-    "abstract-logging": "^2.0.0",
+    "@hapi/hoek": "^9.2.1",
+    "@types/hapi__hapi": "^20.0.10",
+    "abstract-logging": "^2.0.1",
     "get-caller-file": "^2.0.5",
-    "pino": "^7.0.0"
+    "pino": "^7.8.1"
   },
   "repository": {
     "type": "git",


Test patch:
diff --git a/test.js b/test.js
index aa3d5f0..0c318b8 100644
--- a/test.js
+++ b/test.js
@@ -49,7 +49,7 @@ function getServer () {
 }
 
 function sink (func) {
-  var result = split(JSON.parse)
+  const result = split(JSON.parse)
   result.pipe(writeStream.obj(func))
   return result
 }
@@ -155,7 +155,7 @@ experiment('logs each request', () => {
     await registerWithSink(server, 'info', data => {
       expect(data.req.id).to.exists()
       expect(data.res.statusCode).to.equal(200)
-      expect(data.msg).to.equal('request completed')
+      expect(data.msg).to.match(/get \/something 200 \(\d*ms\)/)
       expect(data.responseTime).to.be.at.least(0)
       done()
     })
@@ -185,7 +185,7 @@ experiment('logs each request', () => {
 
     await registerWithSink(server, 'info', data => {
       expect(data.res.statusCode).to.equal(200)
-      expect(data.msg).to.equal('request completed')
+      expect(data.msg).to.match(/\[response\] get \/ 200 \(\d*ms\)/)
       expect(data.responseTime).to.be.at.least(10)
       done()
     })
@@ -214,7 +214,7 @@ experiment('logs each request', () => {
 
     await registerWithSink(server, 'info', data => {
       expect(data.res.statusCode).to.equal(200)
-      expect(data.msg).to.equal('request completed')
+      expect(data.msg).to.match(/\[response\] get \/ 200 \(\d*ms\)/)
       expect(data.responseTime)
         .to.be.a.number()
         .greaterThan(0)
@@ -247,7 +247,7 @@ experiment('logs each request', () => {
     })
     await registerWithSink(server, 'info', (data, enc, cb) => {
       expect(data.res.statusCode).to.equal(200)
-      expect(data.msg).to.equal('request completed')
+      expect(data.msg).to.match(/\[response\] get \/ 200 \(\d*ms\)/)
       cb()
       done()
     })
@@ -277,7 +277,7 @@ experiment('logs each request', () => {
       } else {
         expect(data.res.statusCode).to.equal(500)
         expect(data.level).to.equal(30)
-        expect(data.msg).to.equal('request completed')
+        expect(data.msg).to.match(/get \/ 500 \(\d*ms\)/)
         done()
       }
       count++
@@ -329,7 +329,7 @@ experiment('logs each request', () => {
         expect(data.msg).to.equal('hello logger')
       } else {
         expect(data.res.statusCode).to.equal(200)
-        expect(data.msg).to.equal('request completed')
+        expect(data.msg).to.match(/get \/ 200 \(\d*ms\)/)
         done()
       }
       count++
@@ -386,7 +386,7 @@ experiment('logs each request', () => {
 
     await registerWithSink(server, 'info', data => {
       expect(data.res.statusCode).to.equal(200)
-      expect(data.msg).to.equal('request completed')
+      expect(data.msg).to.match(/\[response\] get \/ 200 \(\d*ms\)/)
       done()
     })
 
@@ -935,7 +935,7 @@ experiment('options.logRequestStart', () => {
     })
 
     const stream = sink(data => {
-      expect(data.msg).to.equal('request completed')
+      expect(data.msg).to.match(/\[response\] get \/something 200 \(\d*ms\)/)
       expect(data.req).to.be.an.object()
       expect(data.req.id).to.exists()
       expect(data.res).to.be.an.object()
@@ -962,7 +962,7 @@ experiment('options.logRequestStart', () => {
     })
 
     const stream = sink(data => {
-      expect(data.msg).to.equal('request completed')
+      expect(data.msg).to.match(/\[response\] get \/something 200 \(\d*ms\)/)
       expect(data.req).to.be.an.object()
       expect(data.req.id).to.exists()
       expect(data.res).to.be.an.object()
@@ -1033,13 +1033,13 @@ experiment('options.logRequestStart', () => {
     const stream = sink((data, enc, cb) => {
       if (count === 0) {
         expect(data.req.url).to.endWith('/ignored')
-        expect(data.msg).to.equal('request completed')
+        expect(data.msg).to.match(/\[response\] get \/ignored 200 \(\d*ms\)/)
       } else if (count === 1) {
         expect(data.req.url).to.endWith('/foo')
         expect(data.msg).to.equal('request start')
       } else {
         expect(data.req.url).to.endWith('/foo')
-        expect(data.msg).to.equal('request completed')
+        expect(data.msg).to.match(/\[response\] get \/foo 200 \(\d*ms\)/)
         done()
       }
       count++
@@ -1083,7 +1083,7 @@ experiment('options.logRequestStart', () => {
         expect(data.req).to.be.an.object()
         expect(data.res).to.be.undefined()
       } else {
-        expect(data.msg).to.equal('request completed')
+        expect(data.msg).to.match(/\[response\] get \/something 200 \(\d*ms\)/)
         expect(data.req).to.be.an.object()
         expect(data.res).to.be.an.object()
         done()
@@ -1119,7 +1119,7 @@ experiment('options.logRequestStart', () => {
         expect(data.res).to.be.undefined()
         expect(data.requestId).to.equal('request1234')
       } else {
-        expect(data.msg).to.equal('request completed')
+        expect(data.msg).to.match(/\[response\] get \/something 200 \(\d*ms\)/)
         expect(data.req).to.be.undefined()
         expect(data.res).to.be.an.object()
         expect(data.requestId).to.equal('request1234')
@@ -1153,7 +1153,7 @@ experiment('options.logRequestComplete', () => {
     })
 
     const stream = sink(data => {
-      expect(data.msg).to.equal('request completed')
+      expect(data.msg).to.match(/\[response\] get \/something 200 \(\d*ms\)/)
       expect(data.req).to.be.an.object()
       expect(data.req.id).to.exists()
       expect(data.res).to.be.an.object()
@@ -1180,7 +1180,7 @@ experiment('options.logRequestComplete', () => {
     })
 
     const stream = sink(data => {
-      expect(data.msg).to.equal('request completed')
+      expect(data.msg).to.match(/\[response\] get \/something 200 \(\d*ms\)/)
       expect(data.req).to.be.an.object()
       expect(data.req.id).to.exists()
       expect(data.res).to.be.an.object()
@@ -1258,7 +1258,7 @@ experiment('options.logRequestComplete', () => {
     })
     const stream = sink((data, enc, cb) => {
       expect(data.req.url).to.endWith('/foo')
-      expect(data.msg).to.equal('request completed')
+      expect(data.msg).to.match(/\[response\] get \/foo 200 \(\d*ms\)/)
       done()
     })
     const logger = require('pino')(stream)
@@ -1336,6 +1336,30 @@ experiment('logging with mergeHapiLogData option enabled', () => {
     await finish
   })
 
+  test('when data is a number, merge it as msg property', async () => {
+    const server = getServer()
+    let done
+    const finish = new Promise(function (resolve, reject) {
+      done = resolve
+    })
+    const stream = sink(data => {
+      expect(data).to.include({ msg: 1 })
+      done()
+    })
+    const plugin = {
+      plugin: Pino,
+      options: {
+        stream: stream,
+        level: 'info',
+        mergeHapiLogData: true
+      }
+    }
+
+    await server.register(plugin)
+    server.log(['info'], 1)
+    await finish
+  })
+
   test('respects `messageKey` option', async () => {
     const server = getServer()
     let done
@@ -1740,7 +1764,7 @@ experiment('ignore response logs for paths in ignorePaths', () => {
     })
     const stream = sink(data => {
       expect(data.req.url).to.endWith('/foo')
-      expect(data.msg).to.equal('request completed')
+      expect(data.msg).to.match(/\[response\] put \/foo 404 \(\d*ms\)/)
       resolver()
     })
     const logger = require('pino')(stream)
@@ -1777,7 +1801,7 @@ experiment('ignore response logs for tags in ignoreTags', () => {
     })
     const stream = sink(data => {
       expect(data.req.url).to.endWith('/foo')
-      expect(data.msg).to.equal('request completed')
+      expect(data.msg).to.match(/\[response\] put \/foo 404 \(\d*ms\)/)
       resolver()
     })
     const logger = require('pino')(stream)
@@ -1814,7 +1838,7 @@ experiment('ignore response logs with ignoreFunc', () => {
     })
     const stream = sink(data => {
       expect(data.req.url).to.endWith('/foo')
-      expect(data.msg).to.equal('request completed')
+      expect(data.msg).to.match(/\[response\] put \/foo 404 \(\d*ms\)/)
       resolver()
     })
     const logger = require('pino')(stream)