From 7d5d2407058ca3e922726da8bc55b8acbda2988c Mon Sep 17 00:00:00 2001 From: Adri Van Houdt Date: Mon, 14 Mar 2022 16:44:00 +0100 Subject: [PATCH] fix!: prevent `req` being added twice to the response and request start log 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, 85 insertions(+), 16 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 6d011d7..9ea4675 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') } @@ -166,14 +166,13 @@ async function register (server, options) { const childBindings = getChildBindings(request) 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. 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: (info.completed !== undefined ? info.completed : info.responded) - info.received }, diff --git a/test.js b/test.js index aa3d5f0..2c6dc12 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', () => {