Skip to content

Commit 90a4d6e

Browse files
schwmaschwma
authored
fix(logging): sanitization if literal values contain parentheses (#210)
Example query: ```gql query MyQuery { AdminService { Books(filter: {title: {contains: ") foo"}}) { nodes { ID } } } } ``` Previous log output (in production): ```gql [graphql] - POST { operationName: 'MyQuery' } query MyQuery { AdminService { Books( *** ) foo"}}) { nodes { ID } } } } ``` New log output (in production): ```gql [graphql] - POST { operationName: 'MyQuery' } query MyQuery { AdminService { Books(filter: "***") { nodes { ID } } } } ```
1 parent d451137 commit 90a4d6e

File tree

7 files changed

+201
-78
lines changed

7 files changed

+201
-78
lines changed

‎CHANGELOG.md‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -15,6 +15,7 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
1515

1616
### Fixed
1717

18+
- Sanitization of logged queries, when running in production, if literal values contain parentheses
1819
- Read GraphiQL HTML file only once on startup, and only if GraphiQL is enabled, to avoid unnecessary file system access
1920

2021
### Removed

‎lib/GraphQLAdapter.js‎

Lines changed: 8 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -7,25 +7,23 @@ const { createHandler } = require('graphql-http/lib/use/express')
77
const { formatError } = require('./resolvers/error')
88

99
function GraphQLAdapter(options) {
10-
const router = express.Router()
11-
const { services } = options
1210
const defaults = { graphiql: true }
13-
const schema = generateSchema4(services)
1411
options = { ...defaults, ...options }
1512

1613
const errorFormatter = options.errorFormatter
1714
? require(path.join(cds.root, options.errorFormatter))
1815
: require('./errorFormatter') // default error formatter
1916

20-
router
21-
.use(express.json({ ...cds.env.server.body_parser })) //> required by logger below
22-
.use(queryLogger)
23-
24-
if (options.graphiql) router.use(require('../app/graphiql'))
17+
const schema = generateSchema4(options.services)
2518

26-
router.use((req, res) =>
19+
const queryHandler = (req, res) =>
2720
createHandler({ schema, context: { req, res, errorFormatter }, formatError, ...options })(req, res)
28-
)
21+
22+
const router = express.Router()
23+
24+
router.use(queryLogger)
25+
if (options.graphiql) router.use(require('../app/graphiql'))
26+
router.use(queryHandler)
2927

3028
return router
3129
}

‎lib/logger.js‎

Lines changed: 26 additions & 9 deletions
Original file line numberDiff line numberDiff line change
@@ -1,19 +1,23 @@
1+
const express = require('express')
2+
const router = express.Router()
13
const cds = require('@sap/cds')
24
const { decodeURIComponent } = cds.utils
35
const { IS_PRODUCTION } = require('./utils')
46
const util = require('util')
57
const LOG = cds.log('graphql')
8+
const { parse, visit, Kind, print } = require('graphql')
69

710
const _isEmptyObject = o => Object.keys(o).length === 0
811

9-
const queryLogger = (req, _, next) => {
12+
router.use(express.json({ ...cds.env.server.body_parser })) //> required by logger below
13+
14+
router.use(function queryLogger(req, _, next) {
1015
let query = req.body?.query || (req.query.query && decodeURIComponent(req.query.query))
1116
// Only log requests that contain a query
1217
if (!query) {
1318
next()
1419
return
1520
}
16-
query = query.trim()
1721

1822
const operationName = req.body?.operationName || req.query?.operationName
1923

@@ -38,15 +42,28 @@ const queryLogger = (req, _, next) => {
3842
? undefined
3943
: util.formatWithOptions({ colors: false, depth: null }, queryInfo)
4044

41-
// If query is multiline string, add newline padding to front
42-
let formattedQuery = query.includes('\n') ? `\n${query}` : query
43-
// Sanitize all values between parentheses
44-
if (IS_PRODUCTION) formattedQuery = formattedQuery.replace(/\([\s\S]*?\)/g, '( *** )')
45+
query = query.trim()
46+
47+
if (IS_PRODUCTION) {
48+
try {
49+
const ast = parse(query)
50+
// Sanitize all arguments unless they are variables
51+
visit(ast, {
52+
[Kind.ARGUMENT](node) {
53+
if (node.value.kind === Kind.VARIABLE) return
54+
node.value = { kind: Kind.STRING, value: '***' }
55+
}
56+
})
57+
query = print(ast)
58+
} catch {
59+
// If parsing or sanitizing the query fails, log the original query
60+
}
61+
}
4562

4663
// Don't log undefined values
47-
LOG.info(...[req.method, formattedQueryInfo, formattedQuery].filter(e => e))
64+
LOG.info(...[req.method, formattedQueryInfo, '\n', query].filter(e => e))
4865

4966
next()
50-
}
67+
})
5168

52-
module.exports = queryLogger
69+
module.exports = router

‎test/tests/error-handling-dev.test.js‎

Lines changed: 15 additions & 11 deletions
Original file line numberDiff line numberDiff line change
@@ -7,13 +7,17 @@ describe('graphql - error handling in development', () => {
77
// Prevent axios from throwing errors for non 2xx status codes
88
axios.defaults.validateStatus = false
99

10+
let _warn = []
11+
let _error = []
12+
1013
beforeEach(() => {
11-
jest.spyOn(console, 'warn')
12-
jest.spyOn(console, 'error')
14+
console.warn = (...s) => _warn.push(s) // eslint-disable-line no-console
15+
console.error = (...s) => _error.push(s) // eslint-disable-line no-console
1316
})
1417

1518
afterEach(() => {
16-
jest.clearAllMocks()
19+
_warn = []
20+
_error = []
1721
})
1822

1923
describe('Errors thrown by CDS', () => {
@@ -33,7 +37,7 @@ describe('graphql - error handling in development', () => {
3337
{
3438
message: expect.any(String),
3539
extensions: {
36-
code: expect.stringMatching(/ASSERT_MANDATORY|ASSERT_NOT_NULL/) ,
40+
code: expect.stringMatching(/ASSERT_MANDATORY|ASSERT_NOT_NULL/),
3741
target: 'notEmptyI',
3842
stacktrace: expect.any(Array)
3943
}
@@ -63,13 +67,13 @@ describe('graphql - error handling in development', () => {
6367
code: 'MULTIPLE_ERRORS',
6468
details: [
6569
{
66-
code: expect.stringMatching(/ASSERT_MANDATORY|ASSERT_NOT_NULL/) ,
70+
code: expect.stringMatching(/ASSERT_MANDATORY|ASSERT_NOT_NULL/),
6771
message: expect.any(String),
6872
target: 'notEmptyI',
6973
stacktrace: expect.any(Array)
7074
},
7175
{
72-
code: expect.stringMatching(/ASSERT_MANDATORY|ASSERT_NOT_NULL/) ,
76+
code: expect.stringMatching(/ASSERT_MANDATORY|ASSERT_NOT_NULL/),
7377
message: expect.any(String),
7478
target: 'notEmptyS',
7579
stacktrace: expect.any(Array)
@@ -132,7 +136,7 @@ describe('graphql - error handling in development', () => {
132136
code: 'MULTIPLE_ERRORS',
133137
details: [
134138
{ target: 'inRange', message: 'Wert ist erforderlich' },
135-
{ target: 'oneOfEnumValues', message: expect.any(String) },
139+
{ target: 'oneOfEnumValues', message: expect.any(String) }
136140
]
137141
}
138142
}
@@ -143,15 +147,15 @@ describe('graphql - error handling in development', () => {
143147
expect(response.data.errors[0].extensions.details[0].stacktrace[0]).not.toHaveLength(0) // Stacktrace exists and is not empty
144148
expect(response.data.errors[0].extensions.details[1].stacktrace[0]).not.toHaveLength(0) // Stacktrace exists and is not empty
145149

146-
const log = console.warn.mock.calls[0][1]
150+
const log = _warn[0][1]
147151
expect(log).toMatchObject({
148152
code: 'MULTIPLE_ERRORS',
149153
details: [
150154
{ target: 'inRange', code: expect.stringMatching(/ASSERT_MANDATORY|ASSERT_NOT_NULL/) },
151155
{ target: 'oneOfEnumValues', code: 'ASSERT_ENUM' }
152156
]
153157
})
154-
expect(console.warn.mock.calls[0][1]).not.toHaveProperty('stacktrace') // No stacktrace outside of error details
158+
expect(_warn[0][1]).not.toHaveProperty('stacktrace') // No stacktrace outside of error details
155159
})
156160
})
157161

@@ -335,7 +339,7 @@ describe('graphql - error handling in development', () => {
335339
expect(response.data.errors[0].extensions).not.toHaveProperty('stacktrace') // No stacktrace outside of error details
336340
expect(response.data.errors[0].extensions.details[0].stacktrace[0]).not.toHaveLength(0) // Stacktrace exists and is not empty
337341
expect(response.data.errors[0].extensions.details[1].stacktrace[0]).not.toHaveLength(0) // Stacktrace exists and is not empty
338-
expect(console.error.mock.calls[0][1]).toMatchObject({
342+
expect(_error[0][1]).toMatchObject({
339343
code: 'MULTIPLE_ERRORS',
340344
details: [
341345
{
@@ -354,7 +358,7 @@ describe('graphql - error handling in development', () => {
354358
}
355359
]
356360
})
357-
expect(console.error.mock.calls[0][1]).not.toHaveProperty('stacktrace') // No stacktrace outside of error details
361+
expect(_error[0][1]).not.toHaveProperty('stacktrace') // No stacktrace outside of error details
358362
})
359363

360364
test('Thrown error is modified in srv.on(error) handler', async () => {

‎test/tests/error-handling-prod.test.js‎

Lines changed: 11 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -8,15 +8,20 @@ describe('graphql - error handling in production', () => {
88
// Prevent axios from throwing errors for non 2xx status codes
99
axios.defaults.validateStatus = false
1010

11+
let _warn = []
12+
let _error = []
13+
1114
beforeEach(() => {
12-
jest.spyOn(console, 'warn')
13-
jest.spyOn(console, 'error')
15+
console.warn = (...s) => _warn.push(s) // eslint-disable-line no-console
16+
console.error = (...s) => _error.push(s) // eslint-disable-line no-console
1417
})
1518

1619
afterEach(() => {
17-
jest.clearAllMocks()
20+
_warn = []
21+
_error = []
1822
})
1923

24+
2025
describe('Errors thrown by CDS', () => {
2126
test('Single @mandatory validation error', async () => {
2227
const query = gql`
@@ -42,7 +47,7 @@ describe('graphql - error handling in production', () => {
4247
const response = await POST('/graphql', { query })
4348
expect(response.data).toMatchObject({ errors })
4449
expect(response.data.errors[0].extensions).not.toHaveProperty('stacktrace') // No stacktrace in production
45-
const log = console.warn.mock.calls[0][1] || JSON.parse(console.warn.mock.calls[0][0])
50+
const log = _warn[0][1] || JSON.parse(_warn[0][0])
4651
expect(log).toMatchObject({ code: expect.stringMatching(/ASSERT_MANDATORY|ASSERT_NOT_NULL/) , target: 'notEmptyI' })
4752
})
4853

@@ -148,7 +153,7 @@ describe('graphql - error handling in production', () => {
148153
expect(response.data.errors[0].extensions).not.toHaveProperty('stacktrace') // No stacktrace outside of error details
149154
expect(response.data.errors[0].extensions.details[0]).not.toHaveProperty('stacktrace') // No stacktrace in production
150155
expect(response.data.errors[0].extensions.details[1]).not.toHaveProperty('stacktrace') // No stacktrace in production
151-
const log = console.warn.mock.calls[0][1] || JSON.parse(console.warn.mock.calls[0][0])
156+
const log = _warn[0][1] || JSON.parse(_warn[0][0])
152157

153158
expect(log).toMatchObject({
154159
code: 'MULTIPLE_ERRORS',
@@ -322,7 +327,7 @@ describe('graphql - error handling in production', () => {
322327
expect(response.data).toMatchObject({ errors })
323328
expect(response.data.errors[0].extensions).not.toHaveProperty('stacktrace') // No stacktrace outside of error details
324329
expect(response.data.errors[0].extensions).not.toHaveProperty('details') // No details since one of the errors is 5xx
325-
const log = console.error.mock.calls[0][1] || JSON.parse(console.error.mock.calls[0][0])
330+
const log = _error[0][1] || JSON.parse(_error[0][0])
326331
expect(log).toMatchObject({
327332
code: 'MULTIPLE_ERRORS',
328333
details: [

‎test/tests/logger-dev.test.js‎

Lines changed: 18 additions & 19 deletions
Original file line numberDiff line numberDiff line change
@@ -10,23 +10,22 @@ describe('graphql - query logging in development', () => {
1010

1111
const _format = e => util.formatWithOptions({ colors: false, depth: null }, ...(Array.isArray(e) ? e : [e]))
1212

13-
let _log
13+
let _info = []
1414

15-
beforeEach(async () => {
16-
await data.reset()
17-
_log = jest.spyOn(console, 'info')
15+
beforeEach(() => {
16+
console.info = (...s) => _info.push(s) // eslint-disable-line no-console
1817
})
1918

2019
afterEach(() => {
21-
jest.clearAllMocks()
20+
_info = []
2221
})
2322

2423
describe('POST requests', () => {
2524
test('Do not log requests with undefined queries', async () => {
2625
const response = await POST('/graphql')
2726
expect(response.status).toEqual(400)
2827
expect(response.data.errors[0]).toEqual({ message: 'Missing query' })
29-
expect(_log.mock.calls.length).toEqual(0)
28+
expect(_info.length).toEqual(0)
3029
})
3130

3231
test('Log should contain HTTP method', async () => {
@@ -42,7 +41,7 @@ describe('graphql - query logging in development', () => {
4241
}
4342
`
4443
await POST('/graphql', { query })
45-
expect(_format(_log.mock.calls[0])).toContain('POST')
44+
expect(_format(_info[0])).toContain('POST')
4645
})
4746

4847
test('Log should not contain operationName if none was provided', async () => {
@@ -58,7 +57,7 @@ describe('graphql - query logging in development', () => {
5857
}
5958
`
6059
await POST('/graphql', { query })
61-
expect(_format(_log.mock.calls[0])).not.toContain('operationName')
60+
expect(_format(_info[0])).not.toContain('operationName')
6261
})
6362

6463
test('Log should not contain variables if none were provided', async () => {
@@ -74,7 +73,7 @@ describe('graphql - query logging in development', () => {
7473
}
7574
`
7675
await POST('/graphql', { query })
77-
expect(_format(_log.mock.calls[0])).not.toContain('variables')
76+
expect(_format(_info[0])).not.toContain('variables')
7877
})
7978

8079
test('Log should contain operationName and its value', async () => {
@@ -100,7 +99,7 @@ describe('graphql - query logging in development', () => {
10099
}
101100
`
102101
await POST('/graphql', { operationName, query })
103-
expect(_format(_log.mock.calls[0])).toContain(`operationName: '${operationName}'`)
102+
expect(_format(_info[0])).toContain(`operationName: '${operationName}'`)
104103
})
105104

106105
test('Log should contain literal values', async () => {
@@ -117,7 +116,7 @@ describe('graphql - query logging in development', () => {
117116
}
118117
`
119118
await POST('/graphql', { query })
120-
expect(_format(_log.mock.calls[0])).toContain(secretTitle)
119+
expect(_format(_info[0])).toContain(secretTitle)
121120
})
122121

123122
test('Log should contain variables and their values', async () => {
@@ -134,7 +133,7 @@ describe('graphql - query logging in development', () => {
134133
`
135134
const variables = { filter: { ID: { ge: 250 } } }
136135
await POST('/graphql', { query, variables })
137-
expect(_format(_log.mock.calls[0])).toContain(`variables: ${_format(variables)}`)
136+
expect(_format(_info[0])).toContain(`variables: ${_format(variables)}`)
138137
})
139138
})
140139

@@ -143,7 +142,7 @@ describe('graphql - query logging in development', () => {
143142
const response = await GET('/graphql')
144143
expect(response.status).toEqual(200)
145144
expect(response.data).toMatch(/html/i) // GraphiQL is returned
146-
expect(_log.mock.calls.length).toEqual(0)
145+
expect(_info.length).toEqual(0)
147146
})
148147

149148
test('Log should contain HTTP method', async () => {
@@ -159,7 +158,7 @@ describe('graphql - query logging in development', () => {
159158
}
160159
`
161160
await GET(`/graphql?query=${query}`)
162-
expect(_format(_log.mock.calls[0])).toContain('GET')
161+
expect(_format(_info[0])).toContain('GET')
163162
})
164163

165164
test('Log should not contain operationName if none was provided', async () => {
@@ -175,7 +174,7 @@ describe('graphql - query logging in development', () => {
175174
}
176175
`
177176
await GET(`/graphql?query=${query}`)
178-
expect(_format(_log.mock.calls[0])).not.toContain('operationName')
177+
expect(_format(_info[0])).not.toContain('operationName')
179178
})
180179

181180
test('Log should not contain variables if none were provided', async () => {
@@ -191,7 +190,7 @@ describe('graphql - query logging in development', () => {
191190
}
192191
`
193192
await GET(`/graphql?query=${query}`)
194-
expect(_format(_log.mock.calls[0])).not.toContain('variables')
193+
expect(_format(_info[0])).not.toContain('variables')
195194
})
196195

197196
test('Log should contain operationName and its value', async () => {
@@ -217,7 +216,7 @@ describe('graphql - query logging in development', () => {
217216
}
218217
`
219218
await GET(`/graphql?operationName=${operationName}&query=${query}`)
220-
expect(_format(_log.mock.calls[0])).toContain(`operationName: '${operationName}'`)
219+
expect(_format(_info[0])).toContain(`operationName: '${operationName}'`)
221220
})
222221

223222
test('Log should contain literal values', async () => {
@@ -234,7 +233,7 @@ describe('graphql - query logging in development', () => {
234233
}
235234
`
236235
await GET(`/graphql?query=${query}`)
237-
expect(_format(_log.mock.calls[0])).toContain(secretTitle)
236+
expect(_format(_info[0])).toContain(secretTitle)
238237
})
239238

240239
test('Log should contain variables and their values', async () => {
@@ -251,7 +250,7 @@ describe('graphql - query logging in development', () => {
251250
`
252251
const variables = { filter: { ID: { ge: 250 } } }
253252
await GET(`/graphql?query=${query}&variables=${JSON.stringify(variables)}`)
254-
expect(_format(_log.mock.calls[0])).toContain(`variables: ${_format(variables)}`)
253+
expect(_format(_info[0])).toContain(`variables: ${_format(variables)}`)
255254
})
256255
})
257256
})

0 commit comments

Comments
 (0)