From c91df0b4871769bb5ac7922a595be38f415bb238 Mon Sep 17 00:00:00 2001 From: Marcel Schwarz Date: Mon, 9 Jan 2023 17:24:03 +0100 Subject: [PATCH 01/33] Don't log 'GET undefined' when missing query --- CHANGELOG.md | 1 + index.js | 2 +- 2 files changed, 2 insertions(+), 1 deletion(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 0a1f912c..02cf72ac 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -14,6 +14,7 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ### Fixed - Fixed a server crash that occourred if an entity property is named `localized`. +- Log `GET` instead of `GET undefined` when no query was specified ### Removed diff --git a/index.js b/index.js index a30a3d82..fe1b9984 100644 --- a/index.js +++ b/index.js @@ -12,7 +12,7 @@ function CDSGraphQLAdapter (options) { return express.Router() .use (express.json()) //> required by logger below .use ((req,_,next)=>{ - LOG.info (req.method, req.body?.query || decodeURIComponent(req.query.query)) + LOG.info (req.method, req.body?.query || req.query.query && decodeURIComponent(req.query.query) || '') next() }) .use (new GraphQLAdapter (services, options)) From def64fa0b3f1e35148899b9d036a16fdab3b879f Mon Sep 17 00:00:00 2001 From: Marcel Schwarz Date: Fri, 20 Jan 2023 10:45:48 +0100 Subject: [PATCH 02/33] WIP improved request logger --- index.js | 13 ++++++++++++- 1 file changed, 12 insertions(+), 1 deletion(-) diff --git a/index.js b/index.js index fe1b9984..b26ed771 100644 --- a/index.js +++ b/index.js @@ -12,7 +12,18 @@ function CDSGraphQLAdapter (options) { return express.Router() .use (express.json()) //> required by logger below .use ((req,_,next)=>{ - LOG.info (req.method, req.body?.query || req.query.query && decodeURIComponent(req.query.query) || '') + const query = req.body?.query || req.query.query && decodeURIComponent(req.query.query) + if (!query) { + next() + return + } + + const formattedQuery = query.includes('\n') && !query.startsWith('\n') ? '\n' + query + '\n' : query + const operationName = req.body?.operationName && { operationName: req.body.operationName } + const variables = process.env.NODE_ENV !== 'production' && req.body?.variables && { variables: req.body.variables } + + LOG.info (...[req.method, operationName, formattedQuery, variables].filter(e => e)) + next() }) .use (new GraphQLAdapter (services, options)) From 51a1b81b10c783754fc51a9251b08cfc8cdce742 Mon Sep 17 00:00:00 2001 From: Marcel Schwarz Date: Tue, 18 Apr 2023 17:37:56 +0200 Subject: [PATCH 03/33] Add operationName and variables to object --- index.js | 15 ++++++++++----- 1 file changed, 10 insertions(+), 5 deletions(-) diff --git a/index.js b/index.js index b26ed771..ab43e5ff 100644 --- a/index.js +++ b/index.js @@ -12,17 +12,22 @@ function CDSGraphQLAdapter (options) { return express.Router() .use (express.json()) //> required by logger below .use ((req,_,next)=>{ - const query = req.body?.query || req.query.query && decodeURIComponent(req.query.query) + let query = req.body?.query || req.query.query && decodeURIComponent(req.query.query) if (!query) { next() return } + query = query.trim() - const formattedQuery = query.includes('\n') && !query.startsWith('\n') ? '\n' + query + '\n' : query - const operationName = req.body?.operationName && { operationName: req.body.operationName } - const variables = process.env.NODE_ENV !== 'production' && req.body?.variables && { variables: req.body.variables } + const { operationName } = req.body + const { variables } = process.env.NODE_ENV !== 'production' && req.body + // Only add properties to object that aren't undefined + const queryInfo = Object.fromEntries(Object.entries({ operationName, variables}).filter(([,v]) => v)) + // If query is multiline string, add padding + const formattedQuery = query.includes('\n') ? `\n${query}\n` : query - LOG.info (...[req.method, operationName, formattedQuery, variables].filter(e => e)) + // Don't log undefined values or empty objects + LOG.info (...[req.method, queryInfo, formattedQuery].filter(e => e && Object.keys(e).length > 0)) next() }) From 144131e72152821dc5e782018d9237c9b8140053 Mon Sep 17 00:00:00 2001 From: Marcel Schwarz Date: Tue, 18 Apr 2023 17:41:55 +0200 Subject: [PATCH 04/33] Extract request logger to own module --- index.js | 25 ++----------------------- lib/logger.js | 26 ++++++++++++++++++++++++++ 2 files changed, 28 insertions(+), 23 deletions(-) create mode 100644 lib/logger.js diff --git a/index.js b/index.js index ab43e5ff..b319c024 100644 --- a/index.js +++ b/index.js @@ -1,8 +1,6 @@ const GraphQLAdapter = require('./lib') -const cds = require ('@sap/cds') -const { decodeURIComponent } = cds.utils -const LOG = cds.log('graphql') const express = require ('express') +const requestLogger = require('./lib/logger') function CDSGraphQLAdapter (options) { const {services} = options @@ -11,26 +9,7 @@ function CDSGraphQLAdapter (options) { return express.Router() .use (express.json()) //> required by logger below - .use ((req,_,next)=>{ - let query = req.body?.query || req.query.query && decodeURIComponent(req.query.query) - if (!query) { - next() - return - } - query = query.trim() - - const { operationName } = req.body - const { variables } = process.env.NODE_ENV !== 'production' && req.body - // Only add properties to object that aren't undefined - const queryInfo = Object.fromEntries(Object.entries({ operationName, variables}).filter(([,v]) => v)) - // If query is multiline string, add padding - const formattedQuery = query.includes('\n') ? `\n${query}\n` : query - - // Don't log undefined values or empty objects - LOG.info (...[req.method, queryInfo, formattedQuery].filter(e => e && Object.keys(e).length > 0)) - - next() - }) + .use (requestLogger) .use (new GraphQLAdapter (services, options)) } diff --git a/lib/logger.js b/lib/logger.js new file mode 100644 index 00000000..04f7509e --- /dev/null +++ b/lib/logger.js @@ -0,0 +1,26 @@ +const cds = require ('@sap/cds') +const { decodeURIComponent } = cds.utils +const LOG = cds.log('graphql') + +const requestLogger = (req, _, next) => { + let query = req.body?.query || (req.query.query && decodeURIComponent(req.query.query)) + if (!query) { + next() + return + } + query = query.trim() + + const { operationName } = req.body + const { variables } = process.env.NODE_ENV !== 'production' && req.body + // Only add properties to object that aren't undefined + const queryInfo = Object.fromEntries(Object.entries({ operationName, variables }).filter(([, v]) => v)) + // If query is multiline string, add padding + const formattedQuery = query.includes('\n') ? `\n${query}\n` : query + + // Don't log undefined values or empty objects + LOG.info(...[req.method, queryInfo, formattedQuery].filter(e => e && Object.keys(e).length > 0)) + + next() +} + +module.exports = requestLogger \ No newline at end of file From 1a104378fedb6c67a3d61716b7261378177f20f8 Mon Sep 17 00:00:00 2001 From: Marcel Schwarz Date: Tue, 18 Apr 2023 17:44:16 +0200 Subject: [PATCH 05/33] Add changelog entry --- CHANGELOG.md | 2 ++ 1 file changed, 2 insertions(+) diff --git a/CHANGELOG.md b/CHANGELOG.md index 6031f76a..869fb508 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -9,6 +9,8 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ### Added +- Improved query logging, including `operationName` and logging of `variables` when not in production + ### Changed - Improved consistency of handling results of different types returned by custom handlers in CRUD resolvers: From 1da76709b6825aaec5020efa889f2d656618aaf7 Mon Sep 17 00:00:00 2001 From: Marcel Schwarz Date: Tue, 18 Apr 2023 17:44:28 +0200 Subject: [PATCH 06/33] Reformat changelog entry --- CHANGELOG.md | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 869fb508..7cf50c7c 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -9,7 +9,10 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ### Added -- Improved query logging, including `operationName` and logging of `variables` when not in production +- Improved query logging: + + Log `operationName` + + Log `variables` when not in production + + Don't log queries that are undefined ### Changed From efcb5d3e3e9ab19d539eb9acbc2af27e1bfbcb99 Mon Sep 17 00:00:00 2001 From: Marcel Schwarz Date: Tue, 18 Apr 2023 17:45:45 +0200 Subject: [PATCH 07/33] Remove outdated changelog entry --- CHANGELOG.md | 2 -- 1 file changed, 2 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 7cf50c7c..9134cf2f 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -23,8 +23,6 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ### Fixed -- Log `GET` instead of `GET undefined` when no query was specified - ### Removed ## Version 0.4.1 - 2023-03-29 From 9dfcbf6007331398bd4f0286e37d48a78446a79a Mon Sep 17 00:00:00 2001 From: Marcel Schwarz Date: Tue, 18 Apr 2023 18:06:55 +0200 Subject: [PATCH 08/33] Remove padding after query --- lib/logger.js | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/lib/logger.js b/lib/logger.js index 04f7509e..fb1d59bf 100644 --- a/lib/logger.js +++ b/lib/logger.js @@ -15,7 +15,7 @@ const requestLogger = (req, _, next) => { // Only add properties to object that aren't undefined const queryInfo = Object.fromEntries(Object.entries({ operationName, variables }).filter(([, v]) => v)) // If query is multiline string, add padding - const formattedQuery = query.includes('\n') ? `\n${query}\n` : query + const formattedQuery = query.includes('\n') ? `\n${query}` : query // Don't log undefined values or empty objects LOG.info(...[req.method, queryInfo, formattedQuery].filter(e => e && Object.keys(e).length > 0)) From e9f440def7cee7d693317e5235806a9e6968b9f9 Mon Sep 17 00:00:00 2001 From: Marcel Schwarz Date: Tue, 18 Apr 2023 18:07:15 +0200 Subject: [PATCH 09/33] Prettier format --- lib/logger.js | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/lib/logger.js b/lib/logger.js index fb1d59bf..daa4eedd 100644 --- a/lib/logger.js +++ b/lib/logger.js @@ -1,4 +1,4 @@ -const cds = require ('@sap/cds') +const cds = require('@sap/cds') const { decodeURIComponent } = cds.utils const LOG = cds.log('graphql') @@ -23,4 +23,4 @@ const requestLogger = (req, _, next) => { next() } -module.exports = requestLogger \ No newline at end of file +module.exports = requestLogger From af5dc0e66f2e12c9bf023a13e825a95584a2b90b Mon Sep 17 00:00:00 2001 From: Marcel Schwarz Date: Tue, 18 Apr 2023 18:10:34 +0200 Subject: [PATCH 10/33] Log `operationName` and `variables` from URL query parameter --- lib/logger.js | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/lib/logger.js b/lib/logger.js index daa4eedd..8662c5fb 100644 --- a/lib/logger.js +++ b/lib/logger.js @@ -10,8 +10,8 @@ const requestLogger = (req, _, next) => { } query = query.trim() - const { operationName } = req.body - const { variables } = process.env.NODE_ENV !== 'production' && req.body + const operationName = req.body?.operationName || req.query?.operationName + const variables = process.env.NODE_ENV !== 'production' && (req.body?.variables || req.query?.variables) // Only add properties to object that aren't undefined const queryInfo = Object.fromEntries(Object.entries({ operationName, variables }).filter(([, v]) => v)) // If query is multiline string, add padding From 283b4e1ead4bdf6a42152aad933e11eb2b9f00d9 Mon Sep 17 00:00:00 2001 From: Marcel Schwarz Date: Tue, 18 Apr 2023 18:20:34 +0200 Subject: [PATCH 11/33] Parse variables JSON string if taken from `req.query` --- lib/logger.js | 13 ++++++++++++- 1 file changed, 12 insertions(+), 1 deletion(-) diff --git a/lib/logger.js b/lib/logger.js index 8662c5fb..25e60b91 100644 --- a/lib/logger.js +++ b/lib/logger.js @@ -11,9 +11,20 @@ const requestLogger = (req, _, next) => { query = query.trim() const operationName = req.body?.operationName || req.query?.operationName - const variables = process.env.NODE_ENV !== 'production' && (req.body?.variables || req.query?.variables) + + let variables = process.env.NODE_ENV !== 'production' && (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 + } + } + // Only add properties to object that aren't undefined const queryInfo = Object.fromEntries(Object.entries({ operationName, variables }).filter(([, v]) => v)) + // If query is multiline string, add padding const formattedQuery = query.includes('\n') ? `\n${query}` : query From 5e30635f9537defbac99d4720749c134499f4d5b Mon Sep 17 00:00:00 2001 From: Marcel Schwarz Date: Tue, 18 Apr 2023 18:53:14 +0200 Subject: [PATCH 12/33] Add typeof object short-circuiting before Object.keys --- lib/logger.js | 6 +++++- 1 file changed, 5 insertions(+), 1 deletion(-) diff --git a/lib/logger.js b/lib/logger.js index 25e60b91..63b54e0b 100644 --- a/lib/logger.js +++ b/lib/logger.js @@ -29,7 +29,11 @@ const requestLogger = (req, _, next) => { const formattedQuery = query.includes('\n') ? `\n${query}` : query // Don't log undefined values or empty objects - LOG.info(...[req.method, queryInfo, formattedQuery].filter(e => e && Object.keys(e).length > 0)) + LOG.info( + ...[req.method, queryInfo, formattedQuery].filter( + e => e && (typeof e === 'object' ? Object.keys(e).length > 0 : true) + ) + ) next() } From 8df47d7508dc61e7db1efeccc0939896d6244994 Mon Sep 17 00:00:00 2001 From: Marcel Schwarz Date: Wed, 19 Apr 2023 13:38:15 +0200 Subject: [PATCH 13/33] Sanitize arguments and their values in production --- CHANGELOG.md | 1 + lib/logger.js | 7 +++++-- 2 files changed, 6 insertions(+), 2 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 9134cf2f..53c21d73 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -12,6 +12,7 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 - Improved query logging: + Log `operationName` + Log `variables` when not in production + + Sanitize arguments and their values in queries when in production + Don't log queries that are undefined ### Changed diff --git a/lib/logger.js b/lib/logger.js index 63b54e0b..0a6084a8 100644 --- a/lib/logger.js +++ b/lib/logger.js @@ -2,6 +2,8 @@ const cds = require('@sap/cds') const { decodeURIComponent } = cds.utils const LOG = cds.log('graphql') +const IS_PRODUCTION = process.env.NODE_ENV === 'production' + const requestLogger = (req, _, next) => { let query = req.body?.query || (req.query.query && decodeURIComponent(req.query.query)) if (!query) { @@ -12,7 +14,7 @@ const requestLogger = (req, _, next) => { const operationName = req.body?.operationName || req.query?.operationName - let variables = process.env.NODE_ENV !== 'production' && (req.body?.variables || req.query?.variables) + let variables = !IS_PRODUCTION && (req.body?.variables || req.query?.variables) if (typeof variables === 'string') { try { // variables is a JSON string if taken from req.query.variables @@ -26,7 +28,8 @@ const requestLogger = (req, _, next) => { const queryInfo = Object.fromEntries(Object.entries({ operationName, variables }).filter(([, v]) => v)) // If query is multiline string, add padding - const formattedQuery = query.includes('\n') ? `\n${query}` : query + let formattedQuery = query.includes('\n') ? `\n${query}` : query + if (IS_PRODUCTION) formattedQuery = formattedQuery.replace(/\([\s\S]*?\)/g, '( *** )') // Don't log undefined values or empty objects LOG.info( From b5e39afbec9539cfce49483eb56f81b34e030b69 Mon Sep 17 00:00:00 2001 From: Marcel Schwarz Date: Wed, 19 Apr 2023 13:39:29 +0200 Subject: [PATCH 14/33] Reorder changelog entries --- CHANGELOG.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 53c21d73..a0a6c0ef 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -10,10 +10,10 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ### Added - 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 - + Don't log queries that are undefined ### Changed From c7bfc36255e760c95b85092b1bee2ee0708ced8c Mon Sep 17 00:00:00 2001 From: Marcel Schwarz Date: Wed, 19 Apr 2023 17:00:16 +0200 Subject: [PATCH 15/33] Rename requestLogger to queryLogger --- index.js | 4 ++-- lib/logger.js | 4 ++-- 2 files changed, 4 insertions(+), 4 deletions(-) diff --git a/index.js b/index.js index b319c024..a6f265b9 100644 --- a/index.js +++ b/index.js @@ -1,6 +1,6 @@ const GraphQLAdapter = require('./lib') const express = require ('express') -const requestLogger = require('./lib/logger') +const queryLogger = require('./lib/logger') function CDSGraphQLAdapter (options) { const {services} = options @@ -9,7 +9,7 @@ function CDSGraphQLAdapter (options) { return express.Router() .use (express.json()) //> required by logger below - .use (requestLogger) + .use (queryLogger) .use (new GraphQLAdapter (services, options)) } diff --git a/lib/logger.js b/lib/logger.js index 0a6084a8..02ac306c 100644 --- a/lib/logger.js +++ b/lib/logger.js @@ -4,7 +4,7 @@ const LOG = cds.log('graphql') const IS_PRODUCTION = process.env.NODE_ENV === 'production' -const requestLogger = (req, _, next) => { +const queryLogger = (req, _, next) => { let query = req.body?.query || (req.query.query && decodeURIComponent(req.query.query)) if (!query) { next() @@ -41,4 +41,4 @@ const requestLogger = (req, _, next) => { next() } -module.exports = requestLogger +module.exports = queryLogger From 2341fe718723713ec8f0b835cb2aeeded13aab83 Mon Sep 17 00:00:00 2001 From: Marcel Schwarz Date: Fri, 21 Apr 2023 17:32:00 +0200 Subject: [PATCH 16/33] Add query logging tests --- test/tests/logger.test.js | 224 ++++++++++++++++++++++++++++++++++++++ 1 file changed, 224 insertions(+) create mode 100644 test/tests/logger.test.js diff --git a/test/tests/logger.test.js b/test/tests/logger.test.js new file mode 100644 index 00000000..ef9fb07a --- /dev/null +++ b/test/tests/logger.test.js @@ -0,0 +1,224 @@ +describe('graphql - query logging', () => { + 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 _formatLogLine = logLineArray => util.formatWithOptions({ colors: false }, ...logLineArray) + + let _log + + beforeEach(() => { + _log = jest.spyOn(console, 'info') + }) + + afterEach(() => { + jest.clearAllMocks() + delete process.env.NODE_ENV + }) + + 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(_formatLogLine(_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(_formatLogLine(_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(_formatLogLine(_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(_formatLogLine(_log.mock.calls[0])).toContain(`operationName: '${operationName}'`) + }) + + 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(_formatLogLine(_log.mock.calls[0])).toContain( + `variables: ${util.formatWithOptions({ colors: false }, 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(_formatLogLine(_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(_formatLogLine(_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(_formatLogLine(_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(_formatLogLine(_log.mock.calls[0])).toContain(`operationName: '${operationName}'`) + }) + + 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(_formatLogLine(_log.mock.calls[0])).toContain( + `variables: ${util.formatWithOptions({ colors: false }, variables)}` + ) + }) + }) +}) From d1e414da08c08518a3172bae08531d06359fea95 Mon Sep 17 00:00:00 2001 From: Marcel Schwarz Date: Thu, 29 Jun 2023 18:19:02 +0200 Subject: [PATCH 17/33] Rename `logger.test.js` to `logger-dev.test.js` --- test/tests/{logger.test.js => logger-dev.test.js} | 3 +-- 1 file changed, 1 insertion(+), 2 deletions(-) rename test/tests/{logger.test.js => logger-dev.test.js} (98%) diff --git a/test/tests/logger.test.js b/test/tests/logger-dev.test.js similarity index 98% rename from test/tests/logger.test.js rename to test/tests/logger-dev.test.js index ef9fb07a..e4dbbee0 100644 --- a/test/tests/logger.test.js +++ b/test/tests/logger-dev.test.js @@ -1,4 +1,4 @@ -describe('graphql - query logging', () => { +describe('graphql - query logging in development', () => { const cds = require('@sap/cds/lib') const path = require('path') const { gql } = require('../util') @@ -19,7 +19,6 @@ describe('graphql - query logging', () => { afterEach(() => { jest.clearAllMocks() - delete process.env.NODE_ENV }) describe('POST requests', () => { From bcb8899bed71fe90b54563994548d2f5c5a8fc61 Mon Sep 17 00:00:00 2001 From: Marcel Schwarz Date: Thu, 29 Jun 2023 18:22:19 +0200 Subject: [PATCH 18/33] Add test for log sanetization in production --- test/resources/bookshop-graphql/package.json | 15 +++ test/tests/logger-prod.test.js | 106 +++++++++++++++++++ 2 files changed, 121 insertions(+) create mode 100644 test/resources/bookshop-graphql/package.json create mode 100644 test/tests/logger-prod.test.js diff --git a/test/resources/bookshop-graphql/package.json b/test/resources/bookshop-graphql/package.json new file mode 100644 index 00000000..82f698e5 --- /dev/null +++ b/test/resources/bookshop-graphql/package.json @@ -0,0 +1,15 @@ +{ + "cds": { + "requires": { + "db": { + "kind": "sqlite", + "credentials": { + "database": ":memory:" + } + }, + "auth": { + "kind": "dummy" + } + } + } +} diff --git a/test/tests/logger-prod.test.js b/test/tests/logger-prod.test.js new file mode 100644 index 00000000..95bb14df --- /dev/null +++ b/test/tests/logger-prod.test.js @@ -0,0 +1,106 @@ +describe('graphql - query logging with sanetization in production', () => { + process.env.NODE_ENV = 'production' + const cds = require('@sap/cds/lib') + const path = require('path') + const { gql } = require('../util') + const util = require('util') + + const PROJECT_PATH = path.join(__dirname, '../resources/bookshop-graphql') + + const { axios, GET, POST, data } = cds.test(PROJECT_PATH) + // Prevent axios from throwing errors for non 2xx status codes + axios.defaults.validateStatus = false + data.autoReset(true) + + const _formatLogLine = logLineArray => util.formatWithOptions({ colors: false }, ...logLineArray) + + let _log + + beforeAll(async () => { + await cds.deploy(path.join(PROJECT_PATH, 'srv')) + }) + + beforeEach(() => { + _log = jest.spyOn(console, 'info') + }) + + afterEach(() => { + jest.clearAllMocks() + }) + + describe('POST requests', () => { + test('Log should not contain literal values', async () => { + const secretTitle = 'secret' + const query = gql` + mutation { + AdminService { + Books { + create (input: { title: "${secretTitle}" }) { + title + } + } + } + } + ` + await POST('/graphql', { query }) + expect(_formatLogLine(_log.mock.calls[0])).not.toContain(secretTitle) + }) + + test('Log should not contain variables or their values', async () => { + const secretTitle = 'secret' + const query = gql` + mutation ($input: [AdminService_Books_C]!) { + AdminService { + Books { + create(input: $input) { + title + } + } + } + } + ` + const variables = { input: { title: secretTitle } } + await POST('/graphql', { query, variables }) + expect(_formatLogLine(_log.mock.calls[0])).not.toContain('$input') + expect(_formatLogLine(_log.mock.calls[0])).not.toContain(secretTitle) + }) + }) + + describe('GET requests', () => { + test('Log should not 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(_formatLogLine(_log.mock.calls[0])).not.toContain(secretTitle) + }) + + test('Log should not contain variables or their values', async () => { + const secretTitle = 'secret' + const query = gql` + query ($filter: [AdminService_Books_filter]) { + AdminService { + Books(filter: $filter) { + nodes { + title + } + } + } + } + ` + const variables = { filter: { title: { ne: secretTitle } } } + await GET(`/graphql?query=${query}&variables=${JSON.stringify(variables)}`) + expect(_formatLogLine(_log.mock.calls[0])).not.toContain('$filter') + expect(_formatLogLine(_log.mock.calls[0])).not.toContain(secretTitle) + }) + }) +}) From 9512f6c27fe1f59ca20a157a7a1bf14aa9beef27 Mon Sep 17 00:00:00 2001 From: Marcel Schwarz Date: Thu, 29 Jun 2023 18:22:36 +0200 Subject: [PATCH 19/33] Prettier format --- lib/schema/mutation.js | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/lib/schema/mutation.js b/lib/schema/mutation.js index 8683f925..636d3ee5 100644 --- a/lib/schema/mutation.js +++ b/lib/schema/mutation.js @@ -28,7 +28,7 @@ module.exports = cache => { for (const key in service.entities) { const entity = service.entities[key] - + if (isCompositionOfAspect(entity)) continue const entityName = gqlName(key) From dd1a7729648ed99e78004f57a1142fb8e0928cf0 Mon Sep 17 00:00:00 2001 From: Marcel Schwarz Date: Thu, 29 Jun 2023 18:38:01 +0200 Subject: [PATCH 20/33] Fix logger module path --- lib/GraphQLAdapter.js | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/lib/GraphQLAdapter.js b/lib/GraphQLAdapter.js index 9725bde2..70c50fc9 100644 --- a/lib/GraphQLAdapter.js +++ b/lib/GraphQLAdapter.js @@ -1,6 +1,6 @@ const express = require('express') const { generateSchema4 } = require('./schema') -const queryLogger = require('./lib/logger') +const queryLogger = require('./logger') const graphiql = require('../app/graphiql') const { createHandler } = require('graphql-http/lib/use/express') From f62ffb859bc312ae2fbd53b461fe417196601ff4 Mon Sep 17 00:00:00 2001 From: Marcel Schwarz Date: Thu, 29 Jun 2023 18:54:39 +0200 Subject: [PATCH 21/33] Fix truncation of nested variables --- lib/logger.js | 7 ++++--- 1 file changed, 4 insertions(+), 3 deletions(-) diff --git a/lib/logger.js b/lib/logger.js index 02ac306c..2b5e05a0 100644 --- a/lib/logger.js +++ b/lib/logger.js @@ -1,6 +1,7 @@ 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' @@ -33,9 +34,9 @@ const queryLogger = (req, _, next) => { // Don't log undefined values or empty objects LOG.info( - ...[req.method, queryInfo, formattedQuery].filter( - e => e && (typeof e === 'object' ? Object.keys(e).length > 0 : true) - ) + ...[req.method, queryInfo, formattedQuery] + .filter(e => e && (typeof e === 'object' ? Object.keys(e).length > 0 : true)) + .map(e => util.formatWithOptions({ depth: null }, e)) ) next() From 7f58f6b67a731f387d402bf798f4ac0a7b4e607f Mon Sep 17 00:00:00 2001 From: Marcel Schwarz Date: Thu, 29 Jun 2023 19:17:03 +0200 Subject: [PATCH 22/33] Fix typo --- test/tests/logger-prod.test.js | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/test/tests/logger-prod.test.js b/test/tests/logger-prod.test.js index 95bb14df..72b1a3b1 100644 --- a/test/tests/logger-prod.test.js +++ b/test/tests/logger-prod.test.js @@ -1,4 +1,4 @@ -describe('graphql - query logging with sanetization in production', () => { +describe('graphql - query logging with sanitization in production', () => { process.env.NODE_ENV = 'production' const cds = require('@sap/cds/lib') const path = require('path') From e881919e64a28c3f363166864e089098ed8c3aad Mon Sep 17 00:00:00 2001 From: Marcel Schwarz Date: Fri, 30 Jun 2023 12:24:08 +0200 Subject: [PATCH 23/33] Move object formatting to only affect query info object --- lib/logger.js | 11 +++++------ 1 file changed, 5 insertions(+), 6 deletions(-) diff --git a/lib/logger.js b/lib/logger.js index 2b5e05a0..e2718abe 100644 --- a/lib/logger.js +++ b/lib/logger.js @@ -27,17 +27,16 @@ const queryLogger = (req, _, next) => { // 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({ depth: null }, queryInfo) : undefined // If query is multiline string, add padding let formattedQuery = query.includes('\n') ? `\n${query}` : query if (IS_PRODUCTION) formattedQuery = formattedQuery.replace(/\([\s\S]*?\)/g, '( *** )') - // Don't log undefined values or empty objects - LOG.info( - ...[req.method, queryInfo, formattedQuery] - .filter(e => e && (typeof e === 'object' ? Object.keys(e).length > 0 : true)) - .map(e => util.formatWithOptions({ depth: null }, e)) - ) + // Don't log undefined values + LOG.info(...[req.method, formattedQueryInfo, formattedQuery].filter(e => e)) next() } From 37e2e58c6a8a47d1350a2f413dc6ced885df5df0 Mon Sep 17 00:00:00 2001 From: Marcel Schwarz Date: Fri, 30 Jun 2023 12:24:32 +0200 Subject: [PATCH 24/33] Add and improve comments --- lib/logger.js | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/lib/logger.js b/lib/logger.js index e2718abe..2e408f72 100644 --- a/lib/logger.js +++ b/lib/logger.js @@ -7,6 +7,7 @@ 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 @@ -31,8 +32,9 @@ const queryLogger = (req, _, next) => { const formattedQueryInfo = Object.keys(queryInfo).length > 0 ? util.formatWithOptions({ depth: null }, queryInfo) : undefined - // If query is multiline string, add padding + // If query is multiline string, add newline padding to front let formattedQuery = query.includes('\n') ? `\n${query}` : query + // Sanetize all values between parentheses if (IS_PRODUCTION) formattedQuery = formattedQuery.replace(/\([\s\S]*?\)/g, '( *** )') // Don't log undefined values From 0f795c7d74b6acbacd731de7b4aa89595fa5a73c Mon Sep 17 00:00:00 2001 From: Marcel Schwarz Date: Fri, 30 Jun 2023 12:37:56 +0200 Subject: [PATCH 25/33] Log variables object as '***' in production --- lib/logger.js | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/lib/logger.js b/lib/logger.js index 2e408f72..6cf9f5c4 100644 --- a/lib/logger.js +++ b/lib/logger.js @@ -16,7 +16,7 @@ const queryLogger = (req, _, next) => { const operationName = req.body?.operationName || req.query?.operationName - let variables = !IS_PRODUCTION && (req.body?.variables || req.query?.variables) + let variables = req.body?.variables || req.query?.variables if (typeof variables === 'string') { try { // variables is a JSON string if taken from req.query.variables @@ -25,6 +25,7 @@ const queryLogger = (req, _, next) => { // 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)) From 61b7948a9fa1d2bd65f0578cc5035b2a601d6563 Mon Sep 17 00:00:00 2001 From: Marcel Schwarz Date: Fri, 30 Jun 2023 12:50:31 +0200 Subject: [PATCH 26/33] Fix typo --- lib/logger.js | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/lib/logger.js b/lib/logger.js index 6cf9f5c4..d286f145 100644 --- a/lib/logger.js +++ b/lib/logger.js @@ -35,7 +35,7 @@ const queryLogger = (req, _, next) => { // If query is multiline string, add newline padding to front let formattedQuery = query.includes('\n') ? `\n${query}` : query - // Sanetize all values between parentheses + // Sanitize all values between parentheses if (IS_PRODUCTION) formattedQuery = formattedQuery.replace(/\([\s\S]*?\)/g, '( *** )') // Don't log undefined values From 33284ce97c5ee82f862c45002c1dc87e5c1a33c3 Mon Sep 17 00:00:00 2001 From: Marcel Schwarz Date: Fri, 30 Jun 2023 12:55:32 +0200 Subject: [PATCH 27/33] Use mocked instead of dummy auth --- test/resources/bookshop-graphql/package.json | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/test/resources/bookshop-graphql/package.json b/test/resources/bookshop-graphql/package.json index 82f698e5..4b36951d 100644 --- a/test/resources/bookshop-graphql/package.json +++ b/test/resources/bookshop-graphql/package.json @@ -8,7 +8,7 @@ } }, "auth": { - "kind": "dummy" + "kind": "mocked" } } } From dbd68fcf2edac60cf1283f88ac72294795dace66 Mon Sep 17 00:00:00 2001 From: Marcel Schwarz Date: Fri, 30 Jun 2023 12:56:19 +0200 Subject: [PATCH 28/33] Add dev logging tests to prod to ensure no unwanted values are sanitized --- test/tests/logger-prod.test.js | 158 +++++++++++++++++++++++++++++++++ 1 file changed, 158 insertions(+) diff --git a/test/tests/logger-prod.test.js b/test/tests/logger-prod.test.js index 72b1a3b1..2f3e5330 100644 --- a/test/tests/logger-prod.test.js +++ b/test/tests/logger-prod.test.js @@ -29,6 +29,85 @@ describe('graphql - query logging with sanitization in production', () => { }) 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(_formatLogLine(_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(_formatLogLine(_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(_formatLogLine(_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(_formatLogLine(_log.mock.calls[0])).toContain(`operationName: '${operationName}'`) + }) + test('Log should not contain literal values', async () => { const secretTitle = 'secret' const query = gql` @@ -67,6 +146,85 @@ describe('graphql - query logging with sanitization in production', () => { }) 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(_formatLogLine(_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(_formatLogLine(_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(_formatLogLine(_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(_formatLogLine(_log.mock.calls[0])).toContain(`operationName: '${operationName}'`) + }) + test('Log should not contain literal values', async () => { const secretTitle = 'secret' const query = gql` From 2187ac2da551c6e0bd1a488de9bb68f291f28093 Mon Sep 17 00:00:00 2001 From: Marcel Schwarz Date: Fri, 30 Jun 2023 13:08:47 +0200 Subject: [PATCH 29/33] Add tests that ensures literal values are not sanitized in dev --- test/tests/logger-dev.test.js | 34 ++++++++++++++++++++++++++++++++++ 1 file changed, 34 insertions(+) diff --git a/test/tests/logger-dev.test.js b/test/tests/logger-dev.test.js index e4dbbee0..fd2a1ad9 100644 --- a/test/tests/logger-dev.test.js +++ b/test/tests/logger-dev.test.js @@ -101,6 +101,23 @@ describe('graphql - query logging in development', () => { expect(_formatLogLine(_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(_formatLogLine(_log.mock.calls[0])).toContain(secretTitle) + }) + test('Log should contain variables and their values', async () => { const query = gql` query ($filter: [AdminService_Books_filter]) { @@ -201,6 +218,23 @@ describe('graphql - query logging in development', () => { expect(_formatLogLine(_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(_formatLogLine(_log.mock.calls[0])).toContain(secretTitle) + }) + test('Log should contain variables and their values', async () => { const query = gql` query ($filter: [AdminService_Books_filter]) { From 9a08b36504fc60256f663e809fdce2e9dbe1d95d Mon Sep 17 00:00:00 2001 From: Marcel Schwarz Date: Fri, 30 Jun 2023 13:15:37 +0200 Subject: [PATCH 30/33] Use `{color:false,depth:null}` options for formatting everywhere --- lib/logger.js | 2 +- test/tests/logger-dev.test.js | 11 ++++------- test/tests/logger-prod.test.js | 3 ++- 3 files changed, 7 insertions(+), 9 deletions(-) diff --git a/lib/logger.js b/lib/logger.js index d286f145..307e0655 100644 --- a/lib/logger.js +++ b/lib/logger.js @@ -31,7 +31,7 @@ const queryLogger = (req, _, next) => { 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({ depth: null }, queryInfo) : undefined + Object.keys(queryInfo).length > 0 ? util.formatWithOptions({ color: false, depth: null }, queryInfo) : undefined // If query is multiline string, add newline padding to front let formattedQuery = query.includes('\n') ? `\n${query}` : query diff --git a/test/tests/logger-dev.test.js b/test/tests/logger-dev.test.js index fd2a1ad9..db9d4b84 100644 --- a/test/tests/logger-dev.test.js +++ b/test/tests/logger-dev.test.js @@ -9,7 +9,8 @@ describe('graphql - query logging in development', () => { axios.defaults.validateStatus = false data.autoReset(true) - const _formatLogLine = logLineArray => util.formatWithOptions({ colors: false }, ...logLineArray) + const _format = e => util.formatWithOptions({ color: false, depth: null }, e) + const _formatLogLine = logLineArray => _format(...logLineArray) let _log @@ -132,9 +133,7 @@ describe('graphql - query logging in development', () => { ` const variables = { filter: { ID: { ge: 250 } } } await POST('/graphql', { query, variables }) - expect(_formatLogLine(_log.mock.calls[0])).toContain( - `variables: ${util.formatWithOptions({ colors: false }, variables)}` - ) + expect(_formatLogLine(_log.mock.calls[0])).toContain(`variables: ${_format(variables)}`) }) }) @@ -249,9 +248,7 @@ describe('graphql - query logging in development', () => { ` const variables = { filter: { ID: { ge: 250 } } } await GET(`/graphql?query=${query}&variables=${JSON.stringify(variables)}`) - expect(_formatLogLine(_log.mock.calls[0])).toContain( - `variables: ${util.formatWithOptions({ colors: false }, variables)}` - ) + expect(_formatLogLine(_log.mock.calls[0])).toContain(`variables: ${_format(variables)}`) }) }) }) diff --git a/test/tests/logger-prod.test.js b/test/tests/logger-prod.test.js index 2f3e5330..442e68e8 100644 --- a/test/tests/logger-prod.test.js +++ b/test/tests/logger-prod.test.js @@ -12,7 +12,8 @@ describe('graphql - query logging with sanitization in production', () => { axios.defaults.validateStatus = false data.autoReset(true) - const _formatLogLine = logLineArray => util.formatWithOptions({ colors: false }, ...logLineArray) + const _format = e => util.formatWithOptions({ color: false, depth: null }, e) + const _formatLogLine = logLineArray => _format(...logLineArray) let _log From 13c98c467f700271d778557daca4eb9fc69634ac Mon Sep 17 00:00:00 2001 From: Marcel Schwarz Date: Fri, 30 Jun 2023 13:15:45 +0200 Subject: [PATCH 31/33] Prettier format --- lib/GraphQLAdapter.js | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/lib/GraphQLAdapter.js b/lib/GraphQLAdapter.js index 70c50fc9..497344b0 100644 --- a/lib/GraphQLAdapter.js +++ b/lib/GraphQLAdapter.js @@ -13,7 +13,7 @@ function GraphQLAdapter(options) { router .use(express.json()) //> required by logger below - .use (queryLogger) + .use(queryLogger) if (options.graphiql) router.use(graphiql) From 52d24c9491a426841253766f6e8f3de1058bea18 Mon Sep 17 00:00:00 2001 From: Marcel Schwarz Date: Fri, 30 Jun 2023 13:30:34 +0200 Subject: [PATCH 32/33] Fix property name typo `color`->`colors` and helper function call --- lib/logger.js | 2 +- test/tests/logger-dev.test.js | 27 +++++++++++++-------------- test/tests/logger-prod.test.js | 31 +++++++++++++++---------------- 3 files changed, 29 insertions(+), 31 deletions(-) diff --git a/lib/logger.js b/lib/logger.js index 307e0655..ee865feb 100644 --- a/lib/logger.js +++ b/lib/logger.js @@ -31,7 +31,7 @@ const queryLogger = (req, _, next) => { 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({ color: false, depth: null }, queryInfo) : undefined + 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 diff --git a/test/tests/logger-dev.test.js b/test/tests/logger-dev.test.js index db9d4b84..b686e40e 100644 --- a/test/tests/logger-dev.test.js +++ b/test/tests/logger-dev.test.js @@ -9,8 +9,7 @@ describe('graphql - query logging in development', () => { axios.defaults.validateStatus = false data.autoReset(true) - const _format = e => util.formatWithOptions({ color: false, depth: null }, e) - const _formatLogLine = logLineArray => _format(...logLineArray) + const _format = e => util.formatWithOptions({ colors: false, depth: null }, ...(Array.isArray(e) ? e : [e])) let _log @@ -41,7 +40,7 @@ describe('graphql - query logging in development', () => { } ` await POST('/graphql', { query }) - expect(_formatLogLine(_log.mock.calls[0])).toContain('POST') + expect(_format(_log.mock.calls[0])).toContain('POST') }) test('Log should not contain operationName if none was provided', async () => { @@ -57,7 +56,7 @@ describe('graphql - query logging in development', () => { } ` await POST('/graphql', { query }) - expect(_formatLogLine(_log.mock.calls[0])).not.toContain('operationName') + expect(_format(_log.mock.calls[0])).not.toContain('operationName') }) test('Log should not contain variables if none were provided', async () => { @@ -73,7 +72,7 @@ describe('graphql - query logging in development', () => { } ` await POST('/graphql', { query }) - expect(_formatLogLine(_log.mock.calls[0])).not.toContain('variables') + expect(_format(_log.mock.calls[0])).not.toContain('variables') }) test('Log should contain operationName and its value', async () => { @@ -99,7 +98,7 @@ describe('graphql - query logging in development', () => { } ` await POST('/graphql', { operationName, query }) - expect(_formatLogLine(_log.mock.calls[0])).toContain(`operationName: '${operationName}'`) + expect(_format(_log.mock.calls[0])).toContain(`operationName: '${operationName}'`) }) test('Log should contain literal values', async () => { @@ -116,7 +115,7 @@ describe('graphql - query logging in development', () => { } ` await POST('/graphql', { query }) - expect(_formatLogLine(_log.mock.calls[0])).toContain(secretTitle) + expect(_format(_log.mock.calls[0])).toContain(secretTitle) }) test('Log should contain variables and their values', async () => { @@ -133,7 +132,7 @@ describe('graphql - query logging in development', () => { ` const variables = { filter: { ID: { ge: 250 } } } await POST('/graphql', { query, variables }) - expect(_formatLogLine(_log.mock.calls[0])).toContain(`variables: ${_format(variables)}`) + expect(_format(_log.mock.calls[0])).toContain(`variables: ${_format(variables)}`) }) }) @@ -156,7 +155,7 @@ describe('graphql - query logging in development', () => { } ` await GET(`/graphql?query=${query}`) - expect(_formatLogLine(_log.mock.calls[0])).toContain('GET') + expect(_format(_log.mock.calls[0])).toContain('GET') }) test('Log should not contain operationName if none was provided', async () => { @@ -172,7 +171,7 @@ describe('graphql - query logging in development', () => { } ` await GET(`/graphql?query=${query}`) - expect(_formatLogLine(_log.mock.calls[0])).not.toContain('operationName') + expect(_format(_log.mock.calls[0])).not.toContain('operationName') }) test('Log should not contain variables if none were provided', async () => { @@ -188,7 +187,7 @@ describe('graphql - query logging in development', () => { } ` await GET(`/graphql?query=${query}`) - expect(_formatLogLine(_log.mock.calls[0])).not.toContain('variables') + expect(_format(_log.mock.calls[0])).not.toContain('variables') }) test('Log should contain operationName and its value', async () => { @@ -214,7 +213,7 @@ describe('graphql - query logging in development', () => { } ` await GET(`/graphql?operationName=${operationName}&query=${query}`) - expect(_formatLogLine(_log.mock.calls[0])).toContain(`operationName: '${operationName}'`) + expect(_format(_log.mock.calls[0])).toContain(`operationName: '${operationName}'`) }) test('Log should contain literal values', async () => { @@ -231,7 +230,7 @@ describe('graphql - query logging in development', () => { } ` await GET(`/graphql?query=${query}`) - expect(_formatLogLine(_log.mock.calls[0])).toContain(secretTitle) + expect(_format(_log.mock.calls[0])).toContain(secretTitle) }) test('Log should contain variables and their values', async () => { @@ -248,7 +247,7 @@ describe('graphql - query logging in development', () => { ` const variables = { filter: { ID: { ge: 250 } } } await GET(`/graphql?query=${query}&variables=${JSON.stringify(variables)}`) - expect(_formatLogLine(_log.mock.calls[0])).toContain(`variables: ${_format(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 index 442e68e8..668bec09 100644 --- a/test/tests/logger-prod.test.js +++ b/test/tests/logger-prod.test.js @@ -12,8 +12,7 @@ describe('graphql - query logging with sanitization in production', () => { axios.defaults.validateStatus = false data.autoReset(true) - const _format = e => util.formatWithOptions({ color: false, depth: null }, e) - const _formatLogLine = logLineArray => _format(...logLineArray) + const _format = e => util.formatWithOptions({ colors: false, depth: null }, ...(Array.isArray(e) ? e : [e])) let _log @@ -48,7 +47,7 @@ describe('graphql - query logging with sanitization in production', () => { } ` await POST('/graphql', { query }) - expect(_formatLogLine(_log.mock.calls[0])).toContain('POST') + expect(_format(_log.mock.calls[0])).toContain('POST') }) test('Log should not contain operationName if none was provided', async () => { @@ -64,7 +63,7 @@ describe('graphql - query logging with sanitization in production', () => { } ` await POST('/graphql', { query }) - expect(_formatLogLine(_log.mock.calls[0])).not.toContain('operationName') + expect(_format(_log.mock.calls[0])).not.toContain('operationName') }) test('Log should not contain variables if none were provided', async () => { @@ -80,7 +79,7 @@ describe('graphql - query logging with sanitization in production', () => { } ` await POST('/graphql', { query }) - expect(_formatLogLine(_log.mock.calls[0])).not.toContain('variables') + expect(_format(_log.mock.calls[0])).not.toContain('variables') }) test('Log should contain operationName and its value', async () => { @@ -106,7 +105,7 @@ describe('graphql - query logging with sanitization in production', () => { } ` await POST('/graphql', { operationName, query }) - expect(_formatLogLine(_log.mock.calls[0])).toContain(`operationName: '${operationName}'`) + expect(_format(_log.mock.calls[0])).toContain(`operationName: '${operationName}'`) }) test('Log should not contain literal values', async () => { @@ -123,7 +122,7 @@ describe('graphql - query logging with sanitization in production', () => { } ` await POST('/graphql', { query }) - expect(_formatLogLine(_log.mock.calls[0])).not.toContain(secretTitle) + expect(_format(_log.mock.calls[0])).not.toContain(secretTitle) }) test('Log should not contain variables or their values', async () => { @@ -141,8 +140,8 @@ describe('graphql - query logging with sanitization in production', () => { ` const variables = { input: { title: secretTitle } } await POST('/graphql', { query, variables }) - expect(_formatLogLine(_log.mock.calls[0])).not.toContain('$input') - expect(_formatLogLine(_log.mock.calls[0])).not.toContain(secretTitle) + expect(_format(_log.mock.calls[0])).not.toContain('$input') + expect(_format(_log.mock.calls[0])).not.toContain(secretTitle) }) }) @@ -165,7 +164,7 @@ describe('graphql - query logging with sanitization in production', () => { } ` await GET(`/graphql?query=${query}`) - expect(_formatLogLine(_log.mock.calls[0])).toContain('GET') + expect(_format(_log.mock.calls[0])).toContain('GET') }) test('Log should not contain operationName if none was provided', async () => { @@ -181,7 +180,7 @@ describe('graphql - query logging with sanitization in production', () => { } ` await GET(`/graphql?query=${query}`) - expect(_formatLogLine(_log.mock.calls[0])).not.toContain('operationName') + expect(_format(_log.mock.calls[0])).not.toContain('operationName') }) test('Log should not contain variables if none were provided', async () => { @@ -197,7 +196,7 @@ describe('graphql - query logging with sanitization in production', () => { } ` await GET(`/graphql?query=${query}`) - expect(_formatLogLine(_log.mock.calls[0])).not.toContain('variables') + expect(_format(_log.mock.calls[0])).not.toContain('variables') }) test('Log should contain operationName and its value', async () => { @@ -223,7 +222,7 @@ describe('graphql - query logging with sanitization in production', () => { } ` await GET(`/graphql?operationName=${operationName}&query=${query}`) - expect(_formatLogLine(_log.mock.calls[0])).toContain(`operationName: '${operationName}'`) + expect(_format(_log.mock.calls[0])).toContain(`operationName: '${operationName}'`) }) test('Log should not contain literal values', async () => { @@ -240,7 +239,7 @@ describe('graphql - query logging with sanitization in production', () => { } ` await GET(`/graphql?query=${query}`) - expect(_formatLogLine(_log.mock.calls[0])).not.toContain(secretTitle) + expect(_format(_log.mock.calls[0])).not.toContain(secretTitle) }) test('Log should not contain variables or their values', async () => { @@ -258,8 +257,8 @@ describe('graphql - query logging with sanitization in production', () => { ` const variables = { filter: { title: { ne: secretTitle } } } await GET(`/graphql?query=${query}&variables=${JSON.stringify(variables)}`) - expect(_formatLogLine(_log.mock.calls[0])).not.toContain('$filter') - expect(_formatLogLine(_log.mock.calls[0])).not.toContain(secretTitle) + expect(_format(_log.mock.calls[0])).not.toContain('$filter') + expect(_format(_log.mock.calls[0])).not.toContain(secretTitle) }) }) }) From d1cd6dd0965a17abf1187d0ff4db490352f59eda Mon Sep 17 00:00:00 2001 From: Marcel Schwarz Date: Tue, 4 Jul 2023 10:50:15 +0200 Subject: [PATCH 33/33] Move changelog entries from added to changed section --- CHANGELOG.md | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 4190e6aa..238343dc 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -9,14 +9,14 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ### Added +### 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 -### Changed - ### Fixed ### Removed