Add support for custom messages on request completion/receive/failure (…

…#163)

README.md

@@ -120,6 +120,12 @@ events"](#hapievents) section.
   two via requestId (frequently done via `headers['x-request-id']`) , where "request start" only logs the request and a requestId,
   and `request completed` only logs the response and the requestId.
 
+### `options.customRequestStartMessage`
+
+  **Default**: 'request start'
+
+  Set to a `function (request) => { /* returns message string */ }`. This function will be invoked at each request received, setting "msg" property to returned string. If not set, default value will be used.
+
 ### `options.logRequestComplete: boolean | (Request) => Boolean`
 
   **Default**: true
@@ -128,6 +134,18 @@ events"](#hapievents) section.
 
   For convenience, you can pass in `true` to always log `request complete` events, or `false` to disable logging `request complete` events
 
+### `options.customRequestCompleteMessage`
+
+  **Default**: '[response] ${request.method} ${request.path} ${request.raw.res.statusCode} (${responseTime}ms)'
+
+  Set to a `function (request, responseTime) => { /* returns message string */ }`. This function will be invoked at each completed request, setting "msg" property to returned string. If not set, default value will be used.
+
+### `options.customRequestErrorMessage`
+
+  **Default**: `error.message`
+
+  Set to a `function (request, err) => { /* returns message string */ }`. This function will be invoked at each failed request, setting "msg" property to returned string. If not set, default value will be used.
+
 ### `options.stream` Pino.DestinationStream
 
   **Default**: `process.stdout`

index.js

@@ -94,6 +94,10 @@ async function register (server, options) {
       ? () => !!options.logRequestComplete
       : () => true
 
+  const requestStartMessage = options.customRequestStartMessage || function () { return 'request start' }
+  const requestCompleteMessage = options.customRequestCompleteMessage || function (request, responseTime) { return `[response] ${request.method} ${request.path} ${request.raw.res.statusCode} (${responseTime}ms)` }
+  const requestErrorMessage = options.customRequestErrorMessage || function (request, error) { return error.message } // Will default to `Internal Server Error` by hapi
+
   // expose logger as 'server.logger'
   server.decorate('server', 'logger', logger)
 
@@ -110,7 +114,7 @@ async function register (server, options) {
     if (shouldLogRequestStart(request)) {
       request.logger.info({
         req: childBindings.req ? undefined : request
-      }, 'request start')
+      }, requestStartMessage(request))
     }
 
     return h.continue
@@ -147,7 +151,7 @@ async function register (server, options) {
           tags: event.tags,
           err: event.error
         },
-        event.error.message // Will default to `Internal Server Error` by hapi
+        requestErrorMessage(request, event.error)
       )
     } else if (event.channel === 'app' && !isCustomTagsLoggingIgnored(event, ignoredEventTags.request)) {
       logEvent(request.logger, event)
@@ -177,7 +181,7 @@ async function register (server, options) {
           res: request.raw.res,
           responseTime
         },
-        `[response] ${request.method} ${request.path} ${request.raw.res.statusCode} (${responseTime}ms)`
+        requestCompleteMessage(request, responseTime)
       )
     }
   })

test.js

@@ -349,6 +349,43 @@ experiment('logs each request', () => {
     await finish
   })
 
+  test('handles 500s with options.customRequestErrorMessage', async () => {
+    const server = getServer()
+    let count = 0
+    let done
+    const finish = new Promise(function (resolve, reject) {
+      done = resolve
+    })
+
+    const stream = sink((data, enc, cb) => {
+      if (count === 0) {
+        expect(data.err.message).to.equal('foobar')
+        expect(data.level).to.equal(50)
+        expect(data.msg).to.match(/request failed for get \/error with error: foobar/)
+      } else {
+        expect(data.res.statusCode).to.equal(500)
+        expect(data.level).to.equal(30)
+        expect(data.msg).to.match(/get \/error 500 \(\d*ms\)/)
+        done()
+      }
+      count++
+      cb()
+    })
+    const plugin = {
+      plugin: Pino,
+      options: {
+        stream: stream,
+        level: 'info',
+        logRequestComplete: true,
+        customRequestErrorMessage: (request, error) => `request failed for ${request.method} ${request.path} with error: ${error.message}`
+      }
+    }
+
+    await server.register(plugin)
+    await server.inject('/error')
+    await finish
+  })
+
   test('handles bad encoding', async () => {
     const server = getServer()
     let done
@@ -1241,6 +1278,33 @@ experiment('options.logRequestStart', () => {
     await server.inject('/something')
     await finish
   })
+
+  test('when options.logRequestStart is true and options.customRequestStartMessage is set', async () => {
+    const server = getServer()
+    let done
+    const finish = new Promise(function (resolve, reject) {
+      done = resolve
+    })
+    const stream = sink(data => {
+      expect(data.msg).to.equal('request for /something')
+      expect(data.req).to.be.an.object()
+      expect(data.req.id).to.be.a.string()
+      done()
+    })
+    const plugin = {
+      plugin: Pino,
+      options: {
+        stream: stream,
+        level: 'info',
+        logRequestStart: true,
+        customRequestStartMessage: (request) => `request for ${request.path}`
+      }
+    }
+
+    await server.register(plugin)
+    await server.inject('/something')
+    await finish
+  })
 })
 
 experiment('options.logRequestComplete', () => {
@@ -1384,6 +1448,35 @@ experiment('options.logRequestComplete', () => {
     })
     await finish
   })
+
+  test('when options.logRequestComplete is true and options.customRequestCompleteMessage is set', async () => {
+    const server = getServer()
+    let done
+    const finish = new Promise(function (resolve, reject) {
+      done = resolve
+    })
+
+    const stream = sink(data => {
+      expect(data.msg).to.match(/request completed for get \/something with 200 after \d*ms/)
+      expect(data.req).to.be.an.object()
+      expect(data.req.id).to.exists()
+      expect(data.res).to.be.an.object()
+      done()
+    })
+    const plugin = {
+      plugin: Pino,
+      options: {
+        stream: stream,
+        level: 'info',
+        logRequestComplete: true,
+        customRequestCompleteMessage: (request, responseTime) => `request completed for ${request.method} ${request.path} with ${request.response.statusCode} after ${responseTime}ms`
+      }
+    }
+
+    await server.register(plugin)
+    await server.inject('/something')
+    await finish
+  })
 })
 
 experiment('logging with mergeHapiLogData option enabled', () => {