From 42b3df4dc81073ced07161fcda9dbf12acf39a33 Mon Sep 17 00:00:00 2001 From: Adri Van Houdt Date: Wed, 16 Mar 2022 18:36:16 +0100 Subject: [PATCH] fix!: prevent `req` being added twice to the response and request start log (#157) There is no way to know in the response log event handling if the request was already added through the child bindings in `onRequest`. And there was no way as a user to fix this behaviour properly. So now `req` will be added once but you need to make sure that you pass it in `childBindings` for the response. Request start event will have it regardless but also only once. This is a breaking change as some people will have removed the `req` from the `childBindings` to get around this issue. Fixes https://github.com/pinojs/hapi-pino/issues/91 --- README.md | 25 +++++++++++--------- index.js | 7 ++---- test.js | 69 ++++++++++++++++++++++++++++++++++++++++++++++++++++++- 3 files changed, 84 insertions(+), 17 deletions(-) diff --git a/README.md b/README.md index bcd2763..713848e 100644 --- a/README.md +++ b/README.md @@ -116,7 +116,7 @@ events"](#hapievents) section. For convenience, you can pass in `true` to always log `request start` events, or `false` to disable logging `request start` events Note: when `logRequestStart` is enabled and `getChildBindings` is configured to omit the `req` field, then the `req` field will be - omitted from the `request completed` log event. This behavior is useful if you want to separate requests from responses and link the + omitted from the `request completed` log event but the `req` field will always be there for the start log. 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 completed` only logs the response and the requestId. @@ -159,7 +159,8 @@ events"](#hapievents) section. **Example**: To redact the authorization header in the logs: - ``` + + ```js { req: require('pino-noir')(['req.headers.authorization']).req res: ... @@ -206,6 +207,8 @@ events"](#hapievents) section. Takes a function with the request as an input, and returns the object that will be passed into pinoLogger.child(). + Note: Omitting `req` from the child bindings will omit it from all logs, most notably the response log, except "request start". + ### `options.ignorePaths: string[]` Takes an array of string routes and disables logging for each. Useful for health checks or any route that does not need logging. @@ -247,7 +250,7 @@ events"](#hapievents) section. **Default**: `{ log: '*', request: '*' }`, Logs all the events emitted by server.log and request.log without filtering event tags - **Example**: + **Example**: Do not log the events for DEBUG and TEST tag ```js ignoredEventTags: { log: ['DEBUG', 'TEST'], request: ['DEBUG', 'TEST'] } @@ -258,7 +261,7 @@ events"](#hapievents) section. ### `options.level: Pino.Level` **Default**: `'info'` - Set the minumum level that Pino should log out. See [Level](https://github.com/pinojs/pino/blob/master/docs/api.md#level). + Set the minimum level that Pino should log out. See [Level](https://github.com/pinojs/pino/blob/master/docs/api.md#level). **Example**: Configure Pino to output all `debug` or higher events: @@ -281,19 +284,19 @@ events"](#hapievents) section. **hapi-pino** decorates the Hapi request with: -* `request.logger`, which is an instance of [pino][pino] bound to the current request, so you can trace all the logs of a given request. See [pino][pino] doc for the way to actual log. +- `request.logger`, which is an instance of [pino][pino] bound to the current request, so you can trace all the logs of a given request. See [pino][pino] doc for the way to actual log. ### Hapi Events **hapi-pino** listens to some Hapi events: -* `'onRequest'`, to create a request-specific child logger -* `'response'`, to log at `'info'` level when a request is completed -* `'request'`, to support logging via the Hapi `request.log()` method and to log at `'warn'` level when a request errors or when request received contains an invalid `accept-encoding` header, see `tags` and `allTags` options. -* `'log'`, to support logging via the Hapi `server.log()` method and to log in case of an internal server event, see `tags` and `allTags` options. -* `'onPostStart'`, to log when the server is started -* `'onPostStop'`, to log when the server is stopped +- `'onRequest'`, to create a request-specific child logger +- `'response'`, to log at `'info'` level when a request is completed +- `'request'`, to support logging via the Hapi `request.log()` method and to log at `'warn'` level when a request errors or when request received contains an invalid `accept-encoding` header, see `tags` and `allTags` options. +- `'log'`, to support logging via the Hapi `server.log()` method and to log in case of an internal server event, see `tags` and `allTags` options. +- `'onPostStart'`, to log when the server is started +- `'onPostStop'`, to log when the server is stopped ## Acknowledgements diff --git a/index.js b/index.js index e0bc685..128a006 100644 --- a/index.js +++ b/index.js @@ -109,7 +109,7 @@ async function register (server, options) { if (shouldLogRequestStart(request)) { request.logger.info({ - req: request + req: childBindings.req ? undefined : request }, 'request start') } @@ -167,16 +167,13 @@ async function register (server, options) { request.logger = logger.child(childBindings) } + // If you want `req` to be added either use the default `getChildBindings` or make sure `req` is passed in your custom bindings. const responseTime = (info.completed !== undefined ? info.completed : info.responded) - info.received - request.logger.info( { payload: options.logPayload ? request.payload : undefined, queryParams: options.logQueryParams ? request.query : 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: shouldLogRequestStart(request) ? undefined : request, res: request.raw.res, responseTime }, diff --git a/test.js b/test.js index 0c318b8..7c7849c 100644 --- a/test.js +++ b/test.js @@ -165,6 +165,36 @@ experiment('logs each request', () => { await finish }) + test('without duplicate req data', async () => { + const server = getServer() + let done + + const finish = new Promise(function (resolve, reject) { + done = resolve + }) + + // We do a manual setup here compared to other tests + // as the `JSON.parse` in the `sink` function hides the double key from us. + const stream = split() + stream.pipe(writeStream.obj((data) => { + expect(data.match(/"req":/g).length).to.equal(1) + + done() + })) + + const plugin = { + plugin: Pino, + options: { + stream: stream, + level: 'info' + } + } + + await server.register(plugin) + await server.inject('/something') + await finish + }) + test('track responseTime', async () => { const server = getServer() @@ -584,6 +614,7 @@ experiment('logs through request.log', () => { (data, enc, cb) => { if (data.tags) { expect(data.data).to.equal('hello logger') + expect(data.req).to.not.be.undefined() resolver() } cb() @@ -907,7 +938,7 @@ experiment('request.logger.child() bindings', () => { done = resolve }) const stream = sink(data => { - expect(data.req).to.not.be.undefined() + expect(data.req).to.be.undefined() expect(data.custom).to.not.be.undefined() done() }) @@ -1142,6 +1173,42 @@ experiment('options.logRequestStart', () => { await server.inject('/something') await finish }) + + test('when options.logRequestStart is true, don\'t log req twice ', async () => { + const server = getServer() + let done + + const finish = new Promise(function (resolve, reject) { + done = resolve + }) + + // We do a manual setup here compared to other tests + // as the `JSON.parse` in the `sink` function hides the double key from us. + const stream = split() + stream.pipe(writeStream.obj((data, enc, cb) => { + expect(data.match(/"req":/g).length).to.equal(1) + + // If we get to the response log we're done + if (data.includes('"responseTime":')) { + done() + } + + cb() + })) + + const plugin = { + plugin: Pino, + options: { + stream: stream, + level: 'info', + logRequestStart: true + } + } + + await server.register(plugin) + await server.inject('/something') + await finish + }) }) experiment('options.logRequestComplete', () => {