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 <[email protected]>
Co-authored-by: Manuel Spigolon <[email protected]>

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).

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) {

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
+    }
+  })
+})