feat: improved query logging (#85)

schwma · johannes-vogel · web-flow · commit b46cbcc861b8 · 2023-07-04T14:49:04.000+02:00
* Don't log 'GET undefined' when missing query

* WIP improved request logger

* Add operationName and variables to object

* Extract request logger to own module

* Add changelog entry

* Reformat changelog entry

* Remove outdated changelog entry

* Remove padding after query

* Prettier format

* Log `operationName` and `variables` from URL query parameter

* Parse variables JSON string if taken from `req.query`

* Add typeof object short-circuiting before Object.keys

* Sanitize arguments and their values in production

* Reorder changelog entries

* Rename requestLogger to queryLogger

* Add query logging tests

* Rename `logger.test.js` to `logger-dev.test.js`

* Add test for log sanetization in production

* Prettier format

* Fix logger module path

* Fix truncation of nested variables

* Fix typo

* Move object formatting to only affect query info object

* Add and improve comments

* Log variables object as '***' in production

* Fix typo

* Use mocked instead of dummy auth

* Add dev logging tests to prod to ensure no unwanted values are sanitized

* Add tests that ensures literal values are not sanitized in dev

* Use `{color:false,depth:null}` options for formatting everywhere

* Prettier format

* Fix property name typo `color`-&gt;`colors` and helper function call

* Move changelog entries from added to changed section

---------

Co-authored-by: Johannes Vogel &lt;31311694+johannes-vogel@users.noreply.github.com&gt;
diff --git a/CHANGELOG.md b/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
diff --git a/lib/GraphQLAdapter.js b/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
 }
 
diff --git a/lib/logger.js b/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
diff --git a/test/resources/bookshop-graphql/package.json b/test/resources/bookshop-graphql/package.json
@@ -0,0 +1,15 @@
+{
+  "cds": {
+    "requires": {
+      "db": {
+        "kind": "sqlite",
+        "credentials": {
+          "database": ":memory:"
+        }
+      },
+      "auth": {
+        "kind": "mocked"
+      }
+    }
+  }
+}
diff --git a/test/tests/logger-dev.test.js b/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)}`)
+    })
+  })
+})
diff --git a/test/tests/logger-prod.test.js b/test/tests/logger-prod.test.js
