Skip to content

Commit a41951c

Browse files
iunanuaszegedi
iunanua
and
szegedi
authored
log template messages and errors (#4856)
* log.error accepting multiple arguments * clean up * warn, info, debug methods * Update packages/dd-trace/src/log/writer.js Co-authored-by: Attila Szegedi <[email protected]> * attila suggestion * include error type in the telemetry log * remove optional chaining to work in node 12 * remove optional chainingand ?? to work in node 12 --------- Co-authored-by: Attila Szegedi <[email protected]>
1 parent 9c081c8 commit a41951c

8 files changed

Lines changed: 173 additions & 56 deletions

File tree

‎packages/dd-trace/src/log/index.js‎

Lines changed: 10 additions & 13 deletions
Original file line numberDiff line numberDiff line change
@@ -4,6 +4,7 @@ const coalesce = require('koalas')
44
const { isTrue } = require('../util')
55
const { debugChannel, infoChannel, warnChannel, errorChannel } = require('./channels')
66
const logWriter = require('./writer')
7+
const { Log } = require('./log')
78

89
const memoize = func => {
910
const cache = {}
@@ -18,10 +19,6 @@ const memoize = func => {
1819
return memoized
1920
}
2021

21-
function processMsg (msg) {
22-
return typeof msg === 'function' ? msg() : msg
23-
}
24-
2522
const config = {
2623
enabled: false,
2724
logger: undefined,
@@ -52,37 +49,37 @@ const log = {
5249
reset () {
5350
logWriter.reset()
5451
this._deprecate = memoize((code, message) => {
55-
errorChannel.publish(message)
52+
errorChannel.publish(Log.parse(message))
5653
return true
5754
})
5855

5956
return this
6057
},
6158

62-
debug (message) {
59+
debug (...args) {
6360
if (debugChannel.hasSubscribers) {
64-
debugChannel.publish(processMsg(message))
61+
debugChannel.publish(Log.parse(...args))
6562
}
6663
return this
6764
},
6865

69-
info (message) {
66+
info (...args) {
7067
if (infoChannel.hasSubscribers) {
71-
infoChannel.publish(processMsg(message))
68+
infoChannel.publish(Log.parse(...args))
7269
}
7370
return this
7471
},
7572

76-
warn (message) {
73+
warn (...args) {
7774
if (warnChannel.hasSubscribers) {
78-
warnChannel.publish(processMsg(message))
75+
warnChannel.publish(Log.parse(...args))
7976
}
8077
return this
8178
},
8279

83-
error (err) {
80+
error (...args) {
8481
if (errorChannel.hasSubscribers) {
85-
errorChannel.publish(processMsg(err))
82+
errorChannel.publish(Log.parse(...args))
8683
}
8784
return this
8885
},

‎packages/dd-trace/src/log/log.js‎

Lines changed: 52 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,52 @@
1+
'use strict'
2+
3+
const { format } = require('util')
4+
5+
class Log {
6+
constructor (message, args, cause, delegate) {
7+
this.message = message
8+
this.args = args
9+
this.cause = cause
10+
this.delegate = delegate
11+
}
12+
13+
get formatted () {
14+
const { message, args } = this
15+
16+
let formatted = message
17+
if (message && args && args.length) {
18+
formatted = format(message, ...args)
19+
}
20+
return formatted
21+
}
22+
23+
static parse (...args) {
24+
let message, cause, delegate
25+
26+
const lastArg = args[args.length - 1]
27+
if (lastArg && typeof lastArg === 'object' && lastArg.stack) { // lastArg instanceof Error?
28+
cause = args.pop()
29+
}
30+
31+
const firstArg = args.shift()
32+
if (firstArg) {
33+
if (typeof firstArg === 'string') {
34+
message = firstArg
35+
} else if (typeof firstArg === 'object') {
36+
message = String(firstArg.message || firstArg)
37+
} else if (typeof firstArg === 'function') {
38+
delegate = firstArg
39+
} else {
40+
message = String(firstArg)
41+
}
42+
} else if (!cause) {
43+
message = String(firstArg)
44+
}
45+
46+
return new Log(message, args, cause, delegate)
47+
}
48+
}
49+
50+
module.exports = {
51+
Log
52+
}

‎packages/dd-trace/src/log/writer.js‎

Lines changed: 50 additions & 19 deletions
Original file line numberDiff line numberDiff line change
@@ -2,6 +2,7 @@
22

33
const { storage } = require('../../../datadog-core')
44
const { LogChannel } = require('./channels')
5+
const { Log } = require('./log')
56
const defaultLogger = {
67
debug: msg => console.debug(msg), /* eslint-disable-line no-console */
78
info: msg => console.info(msg), /* eslint-disable-line no-console */
@@ -22,15 +23,15 @@ function withNoop (fn) {
2223
}
2324

2425
function unsubscribeAll () {
25-
logChannel.unsubscribe({ debug, info, warn, error })
26+
logChannel.unsubscribe({ debug: onDebug, info: onInfo, warn: onWarn, error: onError })
2627
}
2728

2829
function toggleSubscription (enable, level) {
2930
unsubscribeAll()
3031

3132
if (enable) {
3233
logChannel = new LogChannel(level)
33-
logChannel.subscribe({ debug, info, warn, error })
34+
logChannel.subscribe({ debug: onDebug, info: onInfo, warn: onWarn, error: onError })
3435
}
3536
}
3637

@@ -51,32 +52,62 @@ function reset () {
5152
toggleSubscription(false)
5253
}
5354

54-
function error (err) {
55-
if (typeof err !== 'object' || !err) {
56-
err = String(err)
57-
} else if (!err.stack) {
58-
err = String(err.message || err)
55+
function getErrorLog (err) {
56+
if (err && typeof err.delegate === 'function') {
57+
const result = err.delegate()
58+
return Array.isArray(result) ? Log.parse(...result) : Log.parse(result)
59+
} else {
60+
return err
5961
}
62+
}
6063

61-
if (typeof err === 'string') {
62-
err = new Error(err)
63-
}
64+
function onError (err) {
65+
const { formatted, cause } = getErrorLog(err)
66+
67+
// calling twice logger.error() because Error cause is only available in nodejs v16.9.0
68+
// TODO: replace it with Error(message, { cause }) when cause has broad support
69+
if (formatted) withNoop(() => logger.error(new Error(formatted)))
70+
if (cause) withNoop(() => logger.error(cause))
71+
}
72+
73+
function onWarn (log) {
74+
const { formatted, cause } = getErrorLog(log)
75+
if (formatted) withNoop(() => logger.warn(formatted))
76+
if (cause) withNoop(() => logger.warn(cause))
77+
}
6478

65-
withNoop(() => logger.error(err))
79+
function onInfo (log) {
80+
const { formatted, cause } = getErrorLog(log)
81+
if (formatted) withNoop(() => logger.info(formatted))
82+
if (cause) withNoop(() => logger.info(cause))
6683
}
6784

68-
function warn (message) {
69-
if (!logger.warn) return debug(message)
70-
withNoop(() => logger.warn(message))
85+
function onDebug (log) {
86+
const { formatted, cause } = getErrorLog(log)
87+
if (formatted) withNoop(() => logger.debug(formatted))
88+
if (cause) withNoop(() => logger.debug(cause))
7189
}
7290

73-
function info (message) {
74-
if (!logger.info) return debug(message)
75-
withNoop(() => logger.info(message))
91+
function error (...args) {
92+
onError(Log.parse(...args))
93+
}
94+
95+
function warn (...args) {
96+
const log = Log.parse(...args)
97+
if (!logger.warn) return onDebug(log)
98+
99+
onWarn(log)
100+
}
101+
102+
function info (...args) {
103+
const log = Log.parse(...args)
104+
if (!logger.info) return onDebug(log)
105+
106+
onInfo(log)
76107
}
77108

78-
function debug (message) {
79-
withNoop(() => logger.debug(message))
109+
function debug (...args) {
110+
onDebug(Log.parse(...args))
80111
}
81112

82113
module.exports = { use, toggle, reset, error, warn, info, debug }

‎packages/dd-trace/src/telemetry/logs/index.js‎

Lines changed: 16 additions & 11 deletions
Original file line numberDiff line numberDiff line change
@@ -35,18 +35,23 @@ function onLog (log) {
3535
}
3636

3737
function onErrorLog (msg) {
38-
if (msg instanceof Error) {
39-
onLog({
40-
level: 'ERROR',
41-
message: msg.message,
42-
stack_trace: msg.stack
43-
})
44-
} else if (typeof msg === 'string') {
45-
onLog({
46-
level: 'ERROR',
47-
message: msg
48-
})
38+
const { message, cause } = msg
39+
if (!message && !cause) return
40+
41+
const telLog = {
42+
level: 'ERROR',
43+
44+
// existing log.error(err) without message will be reported as 'Generic Error'
45+
message: message ?? 'Generic Error'
4946
}
47+
48+
if (cause) {
49+
telLog.stack_trace = cause.stack
50+
const errorType = cause.name ?? 'Error'
51+
telLog.message = `${errorType}: ${telLog.message}`
52+
}
53+
54+
onLog(telLog)
5055
}
5156

5257
function start (config) {

‎packages/dd-trace/src/telemetry/logs/log-collector.js‎

Lines changed: 3 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -48,16 +48,11 @@ function sanitize (logEntry) {
4848
.map(line => line.replace(ddBasePath, ''))
4949

5050
logEntry.stack_trace = stackLines.join(EOL)
51-
if (logEntry.stack_trace === '') {
52-
// If entire stack was removed, we'd just have a message saying "omitted"
53-
// in which case we'd rather not log it at all.
51+
if (logEntry.stack_trace === '' && !logEntry.message) {
52+
// If entire stack was removed and there is no message we'd rather not log it at all.
5453
return null
5554
}
5655

57-
if (!isDDCode) {
58-
logEntry.message = 'omitted'
59-
}
60-
6156
return logEntry
6257
}
6358

@@ -82,7 +77,7 @@ const logCollector = {
8277
return true
8378
}
8479
} catch (e) {
85-
log.error(`Unable to add log to logCollector: ${e.message}`)
80+
log.error('Unable to add log to logCollector: %s', e.message)
8681
}
8782
return false
8883
},

‎packages/dd-trace/test/log.spec.js‎

Lines changed: 29 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -160,6 +160,7 @@ describe('log', () => {
160160
expect(console.error.firstCall.args[0]).to.have.property('message', 'error')
161161
})
162162

163+
// NOTE: There is no usage for this case. should we continue supporting it?
163164
it('should convert empty values to errors', () => {
164165
log.error()
165166

@@ -191,6 +192,34 @@ describe('log', () => {
191192
expect(console.error.firstCall.args[0]).to.be.instanceof(Error)
192193
expect(console.error.firstCall.args[0]).to.have.property('message', 'error')
193194
})
195+
196+
it('should allow a message + Error', () => {
197+
log.error('this is an error', new Error('cause'))
198+
199+
expect(console.error).to.have.been.called
200+
expect(console.error.firstCall.args[0]).to.be.instanceof(Error)
201+
expect(console.error.firstCall.args[0]).to.have.property('message', 'this is an error')
202+
expect(console.error.secondCall.args[0]).to.be.instanceof(Error)
203+
expect(console.error.secondCall.args[0]).to.have.property('message', 'cause')
204+
})
205+
206+
it('should allow a templated message', () => {
207+
log.error('this is an error of type: %s code: %i', 'ERR', 42)
208+
209+
expect(console.error).to.have.been.called
210+
expect(console.error.firstCall.args[0]).to.be.instanceof(Error)
211+
expect(console.error.firstCall.args[0]).to.have.property('message', 'this is an error of type: ERR code: 42')
212+
})
213+
214+
it('should allow a templated message + Error', () => {
215+
log.error('this is an error of type: %s code: %i', 'ERR', 42, new Error('cause'))
216+
217+
expect(console.error).to.have.been.called
218+
expect(console.error.firstCall.args[0]).to.be.instanceof(Error)
219+
expect(console.error.firstCall.args[0]).to.have.property('message', 'this is an error of type: ERR code: 42')
220+
expect(console.error.secondCall.args[0]).to.be.instanceof(Error)
221+
expect(console.error.secondCall.args[0]).to.have.property('message', 'cause')
222+
})
194223
})
195224

196225
describe('toggle', () => {

‎packages/dd-trace/test/telemetry/logs/index.spec.js‎

Lines changed: 11 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -4,6 +4,7 @@ require('../../setup/tap')
44

55
const { match } = require('sinon')
66
const proxyquire = require('proxyquire')
7+
const { Log } = require('../../../src/log/log')
78

89
describe('telemetry logs', () => {
910
let defaultConfig
@@ -141,13 +142,14 @@ describe('telemetry logs', () => {
141142
it('should be called when an Error object is published to datadog:log:error', () => {
142143
const error = new Error('message')
143144
const stack = error.stack
144-
errorLog.publish(error)
145+
errorLog.publish({ cause: error })
145146

146-
expect(logCollectorAdd).to.be.calledOnceWith(match({ message: 'message', level: 'ERROR', stack_trace: stack }))
147+
expect(logCollectorAdd)
148+
.to.be.calledOnceWith(match({ message: `${error.name}: Generic Error`, level: 'ERROR', stack_trace: stack }))
147149
})
148150

149151
it('should be called when an error string is published to datadog:log:error', () => {
150-
errorLog.publish('custom error message')
152+
errorLog.publish({ message: 'custom error message' })
151153

152154
expect(logCollectorAdd).to.be.calledOnceWith(match({
153155
message: 'custom error message',
@@ -161,6 +163,12 @@ describe('telemetry logs', () => {
161163

162164
expect(logCollectorAdd).not.to.be.called
163165
})
166+
167+
it('should not be called when an object without message and stack is published to datadog:log:error', () => {
168+
errorLog.publish(Log.parse(() => new Error('error')))
169+
170+
expect(logCollectorAdd).not.to.be.called
171+
})
164172
})
165173
})
166174

‎packages/dd-trace/test/telemetry/logs/log-collector.spec.js‎

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -63,7 +63,7 @@ describe('telemetry log collector', () => {
6363
})).to.be.true
6464
})
6565

66-
it('should not include original message if first frame is not a dd frame', () => {
66+
it('should include original message if first frame is not a dd frame', () => {
6767
const thirdPartyFrame = `at callFn (/this/is/not/a/dd/frame/runnable.js:366:21)
6868
at T (${ddBasePath}packages/dd-trace/test/telemetry/logs/log_collector.spec.js:29:21)`
6969
const stack = new Error('Error 1')
@@ -77,7 +77,7 @@ describe('telemetry log collector', () => {
7777

7878
expect(logCollector.add({ message: 'Error 1', level: 'ERROR', stack_trace: stack })).to.be.true
7979
expect(logCollector.hasEntry({
80-
message: 'omitted',
80+
message: 'Error 1',
8181
level: 'ERROR',
8282
stack_trace: ddFrames
8383
})).to.be.true

0 commit comments

Comments
 (0)