From c1696378b2e86e195090ff8b3893dfca1fea8ff6 Mon Sep 17 00:00:00 2001 From: Davide Arena <75489599+DavideArena@users.noreply.github.com> Date: Thu, 26 Oct 2023 18:36:43 +0200 Subject: [PATCH] feat: log using custom msg (#31) * feat: add logMessage option for custom log message * feat: update documentation with logMessage option * chore: add test for uncovered usecases * feat: fix docs, refactor dynamic log message function call and update test * Apply suggestions from code review --------- Co-authored-by: Davide Arena Co-authored-by: Manuel Spigolon --- README.md | 58 ++++++++++ index.js | 29 ++++- test/logMessage.test.js | 246 ++++++++++++++++++++++++++++++++++++++++ 3 files changed, 330 insertions(+), 3 deletions(-) create mode 100644 test/logMessage.test.js diff --git a/README.md b/README.md index f59a0ea..c40afed 100644 --- a/README.md +++ b/README.md @@ -142,6 +142,7 @@ app.register(mercuriusLogging, { logBody: true, // default: false logVariables: true, // default: false logRequest: true // default: false + logMessage: function(context) // default: undefined }) ``` @@ -243,6 +244,63 @@ If you want to include the request's variables in the log output, set this optio ``` +### logMessage + +If you want to put a custom message inside the log output, you can set this option as a `function(context)` which returns a `string` or an `array` containing Pino supported values. + +#### Example returning a string + +```js +app.register(mercuriusLogging, { + logMessage: function (context) { + return `This is a request made with method ${context.reply.request.method}` + } +}) +``` + +Here's an output example + +```json +{ + "level": 30, + "graphql": { + "queries": [ + "firstQuery:myTeam", + "secondQuery:myTeam" + ] + }, + "msg": "This is a request made with method POST" +} +``` + +#### Example returning an array + +```js +app.register(mercuriusLogging, { + logMessage: function (context) { + return ['This is a request made with method %s by foo%s', context.reply.request.method, 'bar' ] + } +}) +``` + +Here's an output example + +```json +{ + "level": 30, + "graphql": { + "queries": [ + "firstQuery:myTeam", + "secondQuery:myTeam" + ] + }, + "msg": "This is a request made with method POST by foobar" +} +``` + + + + ## License Copyright [Manuel Spigolon](https://github.com/Eomm), Licensed under [MIT](./LICENSE). diff --git a/index.js b/index.js index bc3f5a0..908e01e 100644 --- a/index.js +++ b/index.js @@ -21,13 +21,23 @@ function conditionalBody (fn, context, body) { return undefined } +function customLogMessage (fn, context) { + try { + return fn(context) + } catch (error) { + context.app.log.debug(error, 'mercurius-logging: error in logMessage function') + } + return undefined +} + function mercuriusLogging (app, opts, next) { const options = Object.assign({}, { logLevel: 'info', prependAlias: false, logBody: false, logVariables: false, - logRequest: false + logRequest: false, + logMessage: undefined }, opts) options.buildBody = opts.logBody === true @@ -36,6 +46,10 @@ function mercuriusLogging (app, opts, next) { ? conditionalBody.bind(null, opts.logBody) : noop + options.buildLogMessage = typeof opts.logMessage === 'function' + ? customLogMessage.bind(null, opts.logMessage) + : undefined + app.graphql.addHook('preExecution', logGraphQLDetails.bind(null, options)) next() } @@ -66,7 +80,7 @@ function logGraphQLDetails (opts, schema, document, context) { ? requestBody.find(isCurrentOperation) : requestBody - context.reply.request.log[opts.logLevel]({ + const logData = { req: opts.logRequest === true ? context.reply.request : undefined, graphql: { queries: queryOps.length > 0 ? queryOps : undefined, @@ -75,7 +89,16 @@ function logGraphQLDetails (opts, schema, document, context) { body: opts.buildBody(context, currentBody), variables: opts.logVariables === true ? currentBody?.variables || null : undefined } - }) + } + + const logMessage = opts.buildLogMessage?.(context) + + if (!logMessage) { + context.reply.request.log[opts.logLevel](logData) + return + } + + context.reply.request.log[opts.logLevel].apply(context.reply.request.log, [logData].concat(logMessage)) } function readOperationName (document) { diff --git a/test/logMessage.test.js b/test/logMessage.test.js new file mode 100644 index 0000000..21edcfc --- /dev/null +++ b/test/logMessage.test.js @@ -0,0 +1,246 @@ +'use strict' + +const test = require('ava') +const { buildApp, jsonLogger } = require('./_helper') + +test('should log without msg when logMessage is undefined', async (t) => { + t.plan(5) + + const stream = jsonLogger( + line => { + t.is(line.req, undefined) + t.is(line.reqId, 'req-1') + t.deepEqual(line.msg, undefined) + t.deepEqual(line.graphql, { + operationName: 'logMe', + queries: ['add', 'add', 'echo', 'counter'] + }) + }) + + const app = buildApp(t, { stream }) + + const query = `query logMe{ + four: add(x: 2, y: 2) + six: add(x: 3, y: 3) + echo(msg: "hello") + counter + }` + + const response = await app.inject({ + method: 'POST', + headers: { 'content-type': 'application/json' }, + url: '/graphql', + body: JSON.stringify({ query }) + }) + t.deepEqual(response.json(), { + data: { + four: 4, + six: 6, + echo: 'hellohello', + counter: 0 + } + }) +}) + +test('should log without msg when logMessage is\'nt a valid function', async (t) => { + t.plan(5) + + const stream = jsonLogger( + line => { + t.is(line.req, undefined) + t.is(line.reqId, 'req-1') + t.deepEqual(line.msg, undefined) + t.deepEqual(line.graphql, { + operationName: 'logMe', + queries: ['add', 'add', 'echo', 'counter'] + }) + }) + + const app = buildApp(t, { stream }, { logMessage: 1234 }) + + const query = `query logMe{ + four: add(x: 2, y: 2) + six: add(x: 3, y: 3) + echo(msg: "hello") + counter + }` + + const response = await app.inject({ + method: 'POST', + headers: { 'content-type': 'application/json' }, + url: '/graphql', + body: JSON.stringify({ query }) + }) + t.deepEqual(response.json(), { + data: { + four: 4, + six: 6, + echo: 'hellohello', + counter: 0 + } + }) +}) + +test('should log without msg using a logMessage function returning an undefined value', async (t) => { + t.plan(5) + + const customLogMessage = (context) => undefined + + const stream = jsonLogger( + line => { + t.is(line.req, undefined) + t.is(line.reqId, 'req-1') + t.deepEqual(line.msg, undefined) + t.deepEqual(line.graphql, { + operationName: 'logMe', + queries: ['add', 'add', 'echo', 'counter'] + }) + }) + + const app = buildApp(t, { stream }, { logMessage: customLogMessage }) + + const query = `query logMe{ + four: add(x: 2, y: 2) + six: add(x: 3, y: 3) + echo(msg: "hello") + counter + }` + + const response = await app.inject({ + method: 'POST', + headers: { 'content-type': 'application/json' }, + url: '/graphql', + body: JSON.stringify({ query }) + }) + t.deepEqual(response.json(), { + data: { + four: 4, + six: 6, + echo: 'hellohello', + counter: 0 + } + }) +}) + +test('should log without msg using a logMessage function throwing an error', async (t) => { + t.plan(5) + + const customLogMessage = (context) => { throw new Error() } + + const stream = jsonLogger( + line => { + t.is(line.req, undefined) + t.is(line.reqId, 'req-1') + t.deepEqual(line.msg, undefined) + t.deepEqual(line.graphql, { + operationName: 'logMe', + queries: ['add', 'add', 'echo', 'counter'] + }) + }) + + const app = buildApp(t, { stream }, { logMessage: customLogMessage }) + + const query = `query logMe{ + four: add(x: 2, y: 2) + six: add(x: 3, y: 3) + echo(msg: "hello") + counter + }` + + const response = await app.inject({ + method: 'POST', + headers: { 'content-type': 'application/json' }, + url: '/graphql', + body: JSON.stringify({ query }) + }) + t.deepEqual(response.json(), { + data: { + four: 4, + six: 6, + echo: 'hellohello', + counter: 0 + } + }) +}) + +test('should log with msg using a logMessage function returning a string', async (t) => { + t.plan(5) + + const customLogMessage = (context) => `This is a request made with method ${context.reply.request.method}` + + const stream = jsonLogger( + line => { + t.is(line.req, undefined) + t.is(line.reqId, 'req-1') + t.deepEqual(line.msg, 'This is a request made with method POST') + t.deepEqual(line.graphql, { + operationName: 'logMe', + queries: ['add', 'add', 'echo', 'counter'] + }) + }) + + const app = buildApp(t, { stream }, { logMessage: customLogMessage }) + + const query = `query logMe{ + four: add(x: 2, y: 2) + six: add(x: 3, y: 3) + echo(msg: "hello") + counter + }` + + const response = await app.inject({ + method: 'POST', + headers: { 'content-type': 'application/json' }, + url: '/graphql', + body: JSON.stringify({ query }) + }) + t.deepEqual(response.json(), { + data: { + four: 4, + six: 6, + echo: 'hellohello', + counter: 0 + } + }) +}) + +test('should log with msg using a logMessage function returning an array', async (t) => { + t.plan(5) + + const customLogMessage = (context) => [`This is a request made with method ${context.reply.request.method} by foo%s`, 'bar'] + + const stream = jsonLogger( + line => { + t.is(line.req, undefined) + t.is(line.reqId, 'req-1') + t.deepEqual(line.msg, 'This is a request made with method POST by foobar') + t.deepEqual(line.graphql, { + operationName: 'logMe', + queries: ['add', 'add', 'echo', 'counter'] + }) + }) + + const app = buildApp(t, { stream }, { logMessage: customLogMessage }) + + const query = `query logMe{ + four: add(x: 2, y: 2) + six: add(x: 3, y: 3) + echo(msg: "hello") + counter + }` + + const response = await app.inject({ + method: 'POST', + headers: { 'content-type': 'application/json' }, + url: '/graphql', + body: JSON.stringify({ query }) + }) + t.deepEqual(response.json(), { + data: { + four: 4, + six: 6, + echo: 'hellohello', + counter: 0 + } + }) +})