Repository: pinojs/hapi-pino
Pull request #88 (2019-10-15 22:05:18)

fix missing req in "request complete" event when using getChildBindings and options.logRequestStart feature
### Commit 1: Bugfix
After my recent `getChildBindings` addition, if you omit `req` from your child bindings, then the "request complete" log event does not include the `req`

### Commit 2: Feature addition
Adding a `options.logRequestStart` boolean that automatically logs each new request as soon as it comes in.

This pairs nicely with `getChildBindings` when you omit the `req`, as it logs the request and the response separately without duplicating information.  The two events (and any events in the middle at the app-level) can be linked together with a requestId e.g. 
```js
logRequestStart: true,
getChildBindings: (request) => ({ requestId: request.headers['x-request-id'] }),
```

Background/approach context:
I originally tried making the new "request start" event a custom function like `options.onRequestStart: (request) => void`, where you could do / log whatever you wanted. After doing that it felt weird that the "request complete" behavior was hardcoded, so I then made that overriddable.  I had these configured such that the start function defaulted to a noop (i.e. the current behavior) and the complete function defaulted to its current behavior... But the way they interact with my recent `getChildBindings()`, noteably when you omit the `req` field, adds some weird corner cases.  But after doing all this and trying to write the README change, I decided that this approach was too complicated and too convoluted given the current defaults/behavior.  I ended up changing the implementation to the current version, which makes the feature much simpler, clearer, and easier to use.  The main drawback of the current approach is hard coding the content of the new "request start" event, which seems acceptable to me. 


coveralls: 
[![Coverage Status](https://coveralls.io/builds/26334150/badge)](https://coveralls.io/builds/26334150)

Coverage increased (+0.09%) to 99.018% when pulling **3753567a12e6f971046fb2548af3533695e2a588 on devshackio:feat-logRequestStart** into **0a94d6932c5aaeb451b2f4573a2a87336ce8ac0e on pinojs:master**.


Patch:
diff --git a/README.md b/README.md
index 88cc41a..4b8fbee 100644
--- a/README.md
+++ b/README.md
@@ -96,6 +96,8 @@ events"](#hapievents) section.
 ### Options
 - `[logPayload]` – when enabled, add the request payload as `payload` to the `response` event log. Defaults to `false`.
 - `[logRouteTags]` – when enabled, add the request route tags (as configured in hapi `route.options.tags`) `tags` to the `response` event log. Defaults to `false`.
+- `[logRequestStart]` - when enabled, add a log.info() at the beginning of Hapi requests.   Defaults to `false`
+  Note: when `logRequestStart` is enabled and `getChildBindings` is configured to omit the `req` field, then the `req` field will be omitted from the "request complete" log event. This behavior is useful if you want to separate requests from responses and link the two via requestId (frequently done via `headers['x-request-id']`) , where "request start" only logs the request and a requestId, and "request complete" only logs the response and the requestId.
 - `[stream]` - the binary stream to write stuff to, defaults to
   `process.stdout`.
 - `[prettyPrint]` - pretty print the logs (same as `node server |
diff --git a/index.js b/index.js
index 407a078..da08fb7 100644
--- a/index.js
+++ b/index.js
@@ -68,6 +68,7 @@ async function register (server, options) {
 
   const mergeHapiLogData = options.mergeHapiLogData
   const getChildBindings = options.getChildBindings ? options.getChildBindings : (request) => ({ req: request })
+  const logRequestStart = options.logRequestStart
 
   // expose logger as 'server.logger()'
   server.decorate('server', 'logger', () => logger)
@@ -82,6 +83,12 @@ async function register (server, options) {
     const childBindings = getChildBindings(request)
     request.logger = logger.child(childBindings)
 
+    if (logRequestStart) {
+      request.logger.info({
+        req: request
+      }, 'request start')
+    }
+
     return h.continue
   })
 
@@ -126,6 +133,9 @@ async function register (server, options) {
       {
         payload: options.logPayload ? request.payload : undefined,
         tags: options.logRouteTags ? request.route.settings.tags : undefined,
+        // note: pino doesnt support unsetting a key, so this next line
+        // has the effect of setting it or "leaving it as it was" if it was already added via child bindings
+        req: logRequestStart ? undefined : request,
         res: request.raw.res,
         responseTime: (info.completed !== undefined ? info.completed : info.responded) - info.received
       },


Test patch:
diff --git a/test.js b/test.js
index 131d085..b3b032a 100644
--- a/test.js
+++ b/test.js
@@ -810,7 +810,7 @@ experiment('request.logger.child() bindings', () => {
       done = resolve
     })
     const stream = sink(data => {
-      expect(data.req).to.be.undefined()
+      expect(data.req).to.not.be.undefined()
       expect(data.custom).to.not.be.undefined()
       done()
     })
@@ -829,6 +829,134 @@ experiment('request.logger.child() bindings', () => {
   })
 })
 
+experiment('options.logRequestStart', () => {
+  test('is default/false/omitted; only response events are logged, containing both the req and res', 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 completed')
+      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'
+      }
+    }
+
+    await server.register(plugin)
+    await server.inject('/something')
+    await finish
+  })
+
+  test('when options.logRequestStart is true, log an event at the beginning of each request', 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 start')
+      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
+      }
+    }
+
+    await server.register(plugin)
+    await server.inject('/something')
+    await finish
+  })
+
+  test('when options.logRequestStart is true and options.getChildBindings does not omit req field, the onRequestComplete log event includes the req field', async () => {
+    const server = getServer()
+    let done
+    const finish = new Promise(function (resolve, reject) {
+      done = resolve
+    })
+    let count = 0
+    const stream = sink((data, enc, cb) => {
+      if (count === 0) {
+        expect(data.msg).to.equal('request start')
+        expect(data.req).to.be.an.object()
+        expect(data.res).to.be.undefined()
+      } else {
+        expect(data.msg).to.equal('request completed')
+        expect(data.req).to.be.an.object()
+        expect(data.res).to.be.an.object()
+        done()
+      }
+      count++
+      cb()
+    })
+    const plugin = {
+      plugin: Pino,
+      options: {
+        stream: stream,
+        level: 'info',
+        logRequestStart: true
+      }
+    }
+
+    await server.register(plugin)
+    await server.inject('/something')
+    await finish
+  })
+
+  test('when options.logRequestStart is true and options.getChildBindings omits the req field, the onRequestComplete log event omits the req field', async () => {
+    const server = getServer()
+    let done
+    const finish = new Promise(function (resolve, reject) {
+      done = resolve
+    })
+    let count = 0
+    const stream = sink((data, enc, cb) => {
+      if (count === 0) {
+        expect(data.msg).to.equal('request start')
+        expect(data.req).to.be.an.object()
+        expect(data.res).to.be.undefined()
+        expect(data.requestId).to.equal('request1234')
+      } else {
+        expect(data.msg).to.equal('request completed')
+        expect(data.req).to.be.undefined()
+        expect(data.res).to.be.an.object()
+        expect(data.requestId).to.equal('request1234')
+        done()
+      }
+      count++
+      cb()
+    })
+    const plugin = {
+      plugin: Pino,
+      options: {
+        stream: stream,
+        level: 'info',
+        getChildBindings: (req) => ({ requestId: 'request1234' }),
+        logRequestStart: true
+      }
+    }
+
+    await server.register(plugin)
+    await server.inject('/something')
+    await finish
+  })
+})
+
 experiment('logging with mergeHapiLogData option enabled', () => {
   test("log event data is merged into pino's log object", async () => {
     const server = getServer()