From 57f4e0840aa70952b8935e514cc170e8833d9e9d Mon Sep 17 00:00:00 2001 From: Davide Arena Date: Wed, 18 Oct 2023 22:04:24 +0200 Subject: [PATCH 1/5] feat: add logMessage option for custom log message --- index.js | 46 ++++++++- test/logMessage.test.js | 205 ++++++++++++++++++++++++++++++++++++++++ 2 files changed, 248 insertions(+), 3 deletions(-) create mode 100644 test/logMessage.test.js diff --git a/index.js b/index.js index bc3f5a0..c013f83 100644 --- a/index.js +++ b/index.js @@ -6,6 +6,19 @@ function noop () { return undefined } +function isArrayOfStrings (arr) { + if (!Array.isArray(arr)) { + return false + } + + for (let i = 0; i < arr.length; i++) { + if (typeof arr[i] !== 'string') { + return false + } + } + return true +} + function simpleBody (_context, body) { return body.query } @@ -21,13 +34,28 @@ function conditionalBody (fn, context, body) { return undefined } +function customLogMessage (fn, context) { + try { + const logMessage = fn(context) + + // Custom message value could be a string or a string array (pino formatting) + if (typeof logMessage === 'string' || isArrayOfStrings(logMessage)) { + return logMessage + } + } 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 +64,10 @@ function mercuriusLogging (app, opts, next) { ? conditionalBody.bind(null, opts.logBody) : noop + options.buildLogMessage = typeof opts.logMessage === 'function' + ? customLogMessage.bind(null, opts.logMessage) + : noop + app.graphql.addHook('preExecution', logGraphQLDetails.bind(null, options)) next() } @@ -66,7 +98,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 +107,15 @@ 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 (Array.isArray(logMessage)) { + return context.reply.request.log[opts.logLevel](logData, ...logMessage) + } + + return context.reply.request.log[opts.logLevel](logData, logMessage) } function readOperationName (document) { diff --git a/test/logMessage.test.js b/test/logMessage.test.js new file mode 100644 index 0000000..fcf36db --- /dev/null +++ b/test/logMessage.test.js @@ -0,0 +1,205 @@ +'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 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 a string array', async (t) => { + t.plan(5) + + const customLogMessage = (context) => [`This is a request made with method ${context.reply.request.method} by %s`, 'AdminUser'] + + 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 AdminUser') + 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 + } + }) +}) From 14afe9aa9dc8abb8f01e0f704bda689b91a71917 Mon Sep 17 00:00:00 2001 From: Davide Arena Date: Thu, 19 Oct 2023 09:01:42 +0200 Subject: [PATCH 2/5] feat: update documentation with logMessage option --- README.md | 58 +++++++++++++++++++++++++++++++++++++++++ test/logMessage.test.js | 4 +-- 2 files changed, 60 insertions(+), 2 deletions(-) diff --git a/README.md b/README.md index f59a0ea..403bf34 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 `string array`. If function provided doesn't return an allowed value, log message will be `undefined`. + +#### 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 a string array + +```js +app.register(mercuriusLogging, { + logMessage: function (context) { + return [`This is a request made with method ${context.reply.request.method} by foo%s` , `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/test/logMessage.test.js b/test/logMessage.test.js index fcf36db..fcf430c 100644 --- a/test/logMessage.test.js +++ b/test/logMessage.test.js @@ -166,13 +166,13 @@ test('should log with msg using a logMessage function returning a string', async test('should log with msg using a logMessage function returning a string array', async (t) => { t.plan(5) - const customLogMessage = (context) => [`This is a request made with method ${context.reply.request.method} by %s`, 'AdminUser'] + 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 AdminUser') + 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'] From 52e37e1d17ded29ef603f8c3cde7f346a1158def Mon Sep 17 00:00:00 2001 From: Davide Arena Date: Fri, 20 Oct 2023 22:10:15 +0200 Subject: [PATCH 3/5] chore: add test for uncovered usecases --- test/logMessage.test.js | 82 +++++++++++++++++++++++++++++++++++++++++ 1 file changed, 82 insertions(+) diff --git a/test/logMessage.test.js b/test/logMessage.test.js index fcf430c..620179d 100644 --- a/test/logMessage.test.js +++ b/test/logMessage.test.js @@ -122,6 +122,88 @@ test('should log without msg using a logMessage function returning an undefined }) }) +test('should log without msg using a logMessage function returning an array containing non string value', async (t) => { + t.plan(5) + + const customLogMessage = (context) => ['foobar', 3] + + 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) From 305f52ed88abac19de80afae1b327cbe56b49f62 Mon Sep 17 00:00:00 2001 From: Davide Arena Date: Wed, 25 Oct 2023 16:56:12 +0200 Subject: [PATCH 4/5] feat: fix docs, refactor dynamic log message function call and update test --- README.md | 16 +++++++-------- index.js | 30 +++++++--------------------- test/logMessage.test.js | 43 +---------------------------------------- 3 files changed, 16 insertions(+), 73 deletions(-) diff --git a/README.md b/README.md index 403bf34..2ca8232 100644 --- a/README.md +++ b/README.md @@ -246,7 +246,7 @@ 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 `string array`. If function provided doesn't return an allowed value, log message will be `undefined`. +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 @@ -267,13 +267,13 @@ Here's an output example "queries": [ "firstQuery:myTeam", "secondQuery:myTeam" - ], - "msg": "This is a request made with method POST" - } + ] + }, + "msg": "This is a request made with method POST" } ``` -#### Example returning a string array +#### Example returning an array ```js app.register(mercuriusLogging, { @@ -292,9 +292,9 @@ Here's an output example "queries": [ "firstQuery:myTeam", "secondQuery:myTeam" - ], - "msg": "This is a request made with method POST by foobar" - } + ] + }, + "msg": "This is a request made with method POST by foobar" } ``` diff --git a/index.js b/index.js index c013f83..db79c32 100644 --- a/index.js +++ b/index.js @@ -6,19 +6,6 @@ function noop () { return undefined } -function isArrayOfStrings (arr) { - if (!Array.isArray(arr)) { - return false - } - - for (let i = 0; i < arr.length; i++) { - if (typeof arr[i] !== 'string') { - return false - } - } - return true -} - function simpleBody (_context, body) { return body.query } @@ -37,11 +24,7 @@ function conditionalBody (fn, context, body) { function customLogMessage (fn, context) { try { const logMessage = fn(context) - - // Custom message value could be a string or a string array (pino formatting) - if (typeof logMessage === 'string' || isArrayOfStrings(logMessage)) { - return logMessage - } + return logMessage } catch (error) { context.app.log.debug(error, 'mercurius-logging: error in logMessage function') } @@ -66,7 +49,7 @@ function mercuriusLogging (app, opts, next) { options.buildLogMessage = typeof opts.logMessage === 'function' ? customLogMessage.bind(null, opts.logMessage) - : noop + : undefined app.graphql.addHook('preExecution', logGraphQLDetails.bind(null, options)) next() @@ -109,13 +92,14 @@ function logGraphQLDetails (opts, schema, document, context) { } } - const logMessage = opts.buildLogMessage(context) + const logMessage = opts.buildLogMessage?.(context) - if (Array.isArray(logMessage)) { - return context.reply.request.log[opts.logLevel](logData, ...logMessage) + if (!logMessage) { + context.reply.request.log[opts.logLevel](logData) + return } - return context.reply.request.log[opts.logLevel](logData, logMessage) + 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 index 620179d..21edcfc 100644 --- a/test/logMessage.test.js +++ b/test/logMessage.test.js @@ -122,47 +122,6 @@ test('should log without msg using a logMessage function returning an undefined }) }) -test('should log without msg using a logMessage function returning an array containing non string value', async (t) => { - t.plan(5) - - const customLogMessage = (context) => ['foobar', 3] - - 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) @@ -245,7 +204,7 @@ test('should log with msg using a logMessage function returning a string', async }) }) -test('should log with msg using a logMessage function returning a string array', async (t) => { +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'] From 7f3523becb30aa194df0884dd1c48c5b4a6bc2c9 Mon Sep 17 00:00:00 2001 From: Manuel Spigolon Date: Thu, 26 Oct 2023 18:18:46 +0200 Subject: [PATCH 5/5] Apply suggestions from code review --- README.md | 2 +- index.js | 3 +-- 2 files changed, 2 insertions(+), 3 deletions(-) diff --git a/README.md b/README.md index 2ca8232..c40afed 100644 --- a/README.md +++ b/README.md @@ -278,7 +278,7 @@ Here's an output example ```js app.register(mercuriusLogging, { logMessage: function (context) { - return [`This is a request made with method ${context.reply.request.method} by foo%s` , `bar` ] + return ['This is a request made with method %s by foo%s', context.reply.request.method, 'bar' ] } }) ``` diff --git a/index.js b/index.js index db79c32..908e01e 100644 --- a/index.js +++ b/index.js @@ -23,8 +23,7 @@ function conditionalBody (fn, context, body) { function customLogMessage (fn, context) { try { - const logMessage = fn(context) - return logMessage + return fn(context) } catch (error) { context.app.log.debug(error, 'mercurius-logging: error in logMessage function') }