feat: improved query logging

CHANGELOG.md

@@ -11,6 +11,12 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
 
 ### Changed
 
+- Improved query logging:
+  + Don't log queries that are `undefined`
+  + Log `operationName`
+  + Log `variables` when not in production
+  + Sanitize arguments and their values in queries when in production
+
 ### Fixed
 
 ### Removed

lib/GraphQLAdapter.js

@@ -1,10 +1,8 @@
-const cds = require('@sap/cds')
-const LOG = cds.log('graphql')
 const express = require('express')
-const { createHandler } = require('graphql-http/lib/use/express')
 const { generateSchema4 } = require('./schema')
+const queryLogger = require('./logger')
 const graphiql = require('../app/graphiql')
-const { decodeURIComponent } = cds.utils
+const { createHandler } = require('graphql-http/lib/use/express')
 
 function GraphQLAdapter(options) {
   const router = express.Router()
@@ -15,13 +13,12 @@ function GraphQLAdapter(options) {
 
   router
     .use(express.json()) //> required by logger below
-    .use((req, _, next) => {
-      LOG.info(req.method, req.body?.query || decodeURIComponent(req.query.query))
-      next()
-    })
+    .use(queryLogger)
 
   if (options.graphiql) router.use(graphiql)
+
   router.use((req, res) => createHandler({ schema, context: { req, res }, ...options })(req, res))
+
   return router
 }
 

lib/logger.js

@@ -0,0 +1,47 @@
+const cds = require('@sap/cds')
+const { decodeURIComponent } = cds.utils
+const LOG = cds.log('graphql')
+const util = require('util')
+
+const IS_PRODUCTION = process.env.NODE_ENV === 'production'
+
+const queryLogger = (req, _, next) => {
+  let query = req.body?.query || (req.query.query && decodeURIComponent(req.query.query))
+  // Only log requests that contain a query
+  if (!query) {
+    next()
+    return
+  }
+  query = query.trim()
+
+  const operationName = req.body?.operationName || req.query?.operationName
+
+  let variables = req.body?.variables || req.query?.variables
+  if (typeof variables === 'string') {
+    try {
+      // variables is a JSON string if taken from req.query.variables
+      variables = JSON.parse(variables)
+    } catch (e) {
+      // Ignore parsing errors, handled by GraphQL server
+    }
+  }
+  if (IS_PRODUCTION && variables) variables = '***'
+
+  // Only add properties to object that aren't undefined
+  const queryInfo = Object.fromEntries(Object.entries({ operationName, variables }).filter(([, v]) => v))
+  // Only format queryInfo if it contains properties
+  const formattedQueryInfo =
+    Object.keys(queryInfo).length > 0 ? util.formatWithOptions({ colors: false, depth: null }, queryInfo) : undefined
+
+  // If query is multiline string, add newline padding to front
+  let formattedQuery = query.includes('\n') ? `\n${query}` : query
+  // Sanitize all values between parentheses
+  if (IS_PRODUCTION) formattedQuery = formattedQuery.replace(/\([\s\S]*?\)/g, '( *** )')
+
+  // Don't log undefined values
+  LOG.info(...[req.method, formattedQueryInfo, formattedQuery].filter(e => e))
+
+  next()
+}
+
+module.exports = queryLogger

test/resources/bookshop-graphql/package.json

@@ -0,0 +1,15 @@
+{
+  "cds": {
+    "requires": {
+      "db": {
+        "kind": "sqlite",
+        "credentials": {
+          "database": ":memory:"
+        }
+      },
+      "auth": {
+        "kind": "mocked"
+      }
+    }
+  }
+}

test/tests/logger-dev.test.js

@@ -0,0 +1,253 @@
+describe('graphql - query logging in development', () => {
+  const cds = require('@sap/cds/lib')
+  const path = require('path')
+  const { gql } = require('../util')
+  const util = require('util')
+
+  const { axios, GET, POST, data } = cds.test(path.join(__dirname, '../resources/bookshop-graphql'))
+  // Prevent axios from throwing errors for non 2xx status codes
+  axios.defaults.validateStatus = false
+  data.autoReset(true)
+
+  const _format = e => util.formatWithOptions({ colors: false, depth: null }, ...(Array.isArray(e) ? e : [e]))
+
+  let _log
+
+  beforeEach(() => {
+    _log = jest.spyOn(console, 'info')
+  })
+
+  afterEach(() => {
+    jest.clearAllMocks()
+  })
+
+  describe('POST requests', () => {
+    test('Do not log requests with undefined queries', async () => {
+      await POST('/graphql')
+      expect(_log.mock.calls.length).toEqual(0)
+    })
+
+    test('Log should contain HTTP method', async () => {
+      const query = gql`
+        {
+          AdminService {
+            Books {
+              nodes {
+                title
+              }
+            }
+          }
+        }
+      `
+      await POST('/graphql', { query })
+      expect(_format(_log.mock.calls[0])).toContain('POST')
+    })
+
+    test('Log should not contain operationName if none was provided', async () => {
+      const query = gql`
+        {
+          AdminService {
+            Books {
+              nodes {
+                title
+              }
+            }
+          }
+        }
+      `
+      await POST('/graphql', { query })
+      expect(_format(_log.mock.calls[0])).not.toContain('operationName')
+    })
+
+    test('Log should not contain variables if none were provided', async () => {
+      const query = gql`
+        {
+          AdminService {
+            Books {
+              nodes {
+                title
+              }
+            }
+          }
+        }
+      `
+      await POST('/graphql', { query })
+      expect(_format(_log.mock.calls[0])).not.toContain('variables')
+    })
+
+    test('Log should contain operationName and its value', async () => {
+      const operationName = 'ListBooks'
+      const query = gql`
+        query ListAuthors {
+          AdminService {
+            Authors {
+              nodes {
+                name
+              }
+            }
+          }
+        }
+        query ${operationName} {
+          AdminService {
+            Books {
+              nodes {
+                title
+              }
+            }
+          }
+        }
+      `
+      await POST('/graphql', { operationName, query })
+      expect(_format(_log.mock.calls[0])).toContain(`operationName: '${operationName}'`)
+    })
+
+    test('Log should contain literal values', async () => {
+      const secretTitle = 'secret'
+      const query = gql`
+        mutation {
+          AdminService {
+            Books {
+              create (input: { title: "${secretTitle}" }) {
+                title
+              }
+            }
+          }
+        }
+      `
+      await POST('/graphql', { query })
+      expect(_format(_log.mock.calls[0])).toContain(secretTitle)
+    })
+
+    test('Log should contain variables and their values', async () => {
+      const query = gql`
+        query ($filter: [AdminService_Books_filter]) {
+          AdminService {
+            Books(filter: $filter) {
+              nodes {
+                title
+              }
+            }
+          }
+        }
+      `
+      const variables = { filter: { ID: { ge: 250 } } }
+      await POST('/graphql', { query, variables })
+      expect(_format(_log.mock.calls[0])).toContain(`variables: ${_format(variables)}`)
+    })
+  })
+
+  describe('GET requests', () => {
+    test('Do not log requests with undefined queries', async () => {
+      await GET('/graphql')
+      expect(_log.mock.calls.length).toEqual(0)
+    })
+
+    test('Log should contain HTTP method', async () => {
+      const query = gql`
+        {
+          AdminService {
+            Books {
+              nodes {
+                title
+              }
+            }
+          }
+        }
+      `
+      await GET(`/graphql?query=${query}`)
+      expect(_format(_log.mock.calls[0])).toContain('GET')
+    })
+
+    test('Log should not contain operationName if none was provided', async () => {
+      const query = gql`
+        {
+          AdminService {
+            Books {
+              nodes {
+                title
+              }
+            }
+          }
+        }
+      `
+      await GET(`/graphql?query=${query}`)
+      expect(_format(_log.mock.calls[0])).not.toContain('operationName')
+    })
+
+    test('Log should not contain variables if none were provided', async () => {
+      const query = gql`
+        {
+          AdminService {
+            Books {
+              nodes {
+                title
+              }
+            }
+          }
+        }
+      `
+      await GET(`/graphql?query=${query}`)
+      expect(_format(_log.mock.calls[0])).not.toContain('variables')
+    })
+
+    test('Log should contain operationName and its value', async () => {
+      const operationName = 'ListBooks'
+      const query = gql`
+        query ListAuthors {
+          AdminService {
+            Authors {
+              nodes {
+                name
+              }
+            }
+          }
+        }
+        query ${operationName} {
+          AdminService {
+            Books {
+              nodes {
+                title
+              }
+            }
+          }
+        }
+      `
+      await GET(`/graphql?operationName=${operationName}&query=${query}`)
+      expect(_format(_log.mock.calls[0])).toContain(`operationName: '${operationName}'`)
+    })
+
+    test('Log should contain literal values', async () => {
+      const secretTitle = 'secret'
+      const query = gql`
+        query {
+          AdminService {
+            Books(filter: { title: { ne: "${secretTitle}"}}) {
+              nodes {
+                title
+              }
+            }
+          }
+        }
+      `
+      await GET(`/graphql?query=${query}`)
+      expect(_format(_log.mock.calls[0])).toContain(secretTitle)
+    })
+
+    test('Log should contain variables and their values', async () => {
+      const query = gql`
+        query ($filter: [AdminService_Books_filter]) {
+          AdminService {
+            Books(filter: $filter) {
+              nodes {
+                title
+              }
+            }
+          }
+        }
+      `
+      const variables = { filter: { ID: { ge: 250 } } }
+      await GET(`/graphql?query=${query}&variables=${JSON.stringify(variables)}`)
+      expect(_format(_log.mock.calls[0])).toContain(`variables: ${_format(variables)}`)
+    })
+  })
+})