From dd773e83a98a28e96ac77daae063946ab14b00a5 Mon Sep 17 00:00:00 2001 From: Jonathan Samines Date: Wed, 25 May 2022 07:46:47 -0600 Subject: [PATCH] Add support for custom messages on request completion/receive/failure (#163) --- README.md | 18 +++++++++++ index.js | 10 ++++-- test.js | 93 +++++++++++++++++++++++++++++++++++++++++++++++++++++++ 3 files changed, 118 insertions(+), 3 deletions(-) diff --git a/README.md b/README.md index 713848e..227d734 100644 --- a/README.md +++ b/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` diff --git a/index.js b/index.js index 3ba5e47..6e54cbe 100644 --- a/index.js +++ b/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) ) } }) diff --git a/test.js b/test.js index 210b00c..1737429 100644 --- a/test.js +++ b/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', () => {