diff --git a/CHANGELOG.md b/CHANGELOG.md index 726d0f15..238343dc 100644 --- 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 index ed73877a..497344b0 100644 --- 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 new file mode 100644 index 00000000..ee865feb --- /dev/null +++ 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 new file mode 100644 index 00000000..4b36951d --- /dev/null +++ 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 new file mode 100644 index 00000000..b686e40e --- /dev/null +++ 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 new file mode 100644 index 00000000..668bec09 --- /dev/null +++ b/test/tests/logger-prod.test.js @@ -0,0 +1,264 @@ +describe('graphql - query logging with sanitization 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 _format = e => util.formatWithOptions({ colors: false, depth: null }, ...(Array.isArray(e) ? e : [e])) + + 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('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 not 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])).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(_format(_log.mock.calls[0])).not.toContain('$input') + expect(_format(_log.mock.calls[0])).not.toContain(secretTitle) + }) + }) + + 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 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(_format(_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(_format(_log.mock.calls[0])).not.toContain('$filter') + expect(_format(_log.mock.calls[0])).not.toContain(secretTitle) + }) + }) +})