From 89f830d71bca4e699ed9ee76f66cb48bbe59aa92 Mon Sep 17 00:00:00 2001 From: Igor Unanua Date: Tue, 19 Nov 2024 09:03:03 +0100 Subject: [PATCH] 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 * 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 --- packages/dd-trace/src/log/index.js | 23 +++---- packages/dd-trace/src/log/log.js | 52 ++++++++++++++ packages/dd-trace/src/log/writer.js | 69 ++++++++++++++----- packages/dd-trace/src/telemetry/logs/index.js | 27 +++++--- .../src/telemetry/logs/log-collector.js | 11 +-- packages/dd-trace/test/log.spec.js | 29 ++++++++ .../test/telemetry/logs/index.spec.js | 14 +++- .../test/telemetry/logs/log-collector.spec.js | 4 +- 8 files changed, 173 insertions(+), 56 deletions(-) create mode 100644 packages/dd-trace/src/log/log.js diff --git a/packages/dd-trace/src/log/index.js b/packages/dd-trace/src/log/index.js index 726d7d1e5e7..3a5392340df 100644 --- a/packages/dd-trace/src/log/index.js +++ b/packages/dd-trace/src/log/index.js @@ -4,6 +4,7 @@ const coalesce = require('koalas') const { isTrue } = require('../util') const { debugChannel, infoChannel, warnChannel, errorChannel } = require('./channels') const logWriter = require('./writer') +const { Log } = require('./log') const memoize = func => { const cache = {} @@ -18,10 +19,6 @@ const memoize = func => { return memoized } -function processMsg (msg) { - return typeof msg === 'function' ? msg() : msg -} - const config = { enabled: false, logger: undefined, @@ -52,37 +49,37 @@ const log = { reset () { logWriter.reset() this._deprecate = memoize((code, message) => { - errorChannel.publish(message) + errorChannel.publish(Log.parse(message)) return true }) return this }, - debug (message) { + debug (...args) { if (debugChannel.hasSubscribers) { - debugChannel.publish(processMsg(message)) + debugChannel.publish(Log.parse(...args)) } return this }, - info (message) { + info (...args) { if (infoChannel.hasSubscribers) { - infoChannel.publish(processMsg(message)) + infoChannel.publish(Log.parse(...args)) } return this }, - warn (message) { + warn (...args) { if (warnChannel.hasSubscribers) { - warnChannel.publish(processMsg(message)) + warnChannel.publish(Log.parse(...args)) } return this }, - error (err) { + error (...args) { if (errorChannel.hasSubscribers) { - errorChannel.publish(processMsg(err)) + errorChannel.publish(Log.parse(...args)) } return this }, diff --git a/packages/dd-trace/src/log/log.js b/packages/dd-trace/src/log/log.js new file mode 100644 index 00000000000..a9ec407291a --- /dev/null +++ b/packages/dd-trace/src/log/log.js @@ -0,0 +1,52 @@ +'use strict' + +const { format } = require('util') + +class Log { + constructor (message, args, cause, delegate) { + this.message = message + this.args = args + this.cause = cause + this.delegate = delegate + } + + get formatted () { + const { message, args } = this + + let formatted = message + if (message && args && args.length) { + formatted = format(message, ...args) + } + return formatted + } + + static parse (...args) { + let message, cause, delegate + + const lastArg = args[args.length - 1] + if (lastArg && typeof lastArg === 'object' && lastArg.stack) { // lastArg instanceof Error? + cause = args.pop() + } + + const firstArg = args.shift() + if (firstArg) { + if (typeof firstArg === 'string') { + message = firstArg + } else if (typeof firstArg === 'object') { + message = String(firstArg.message || firstArg) + } else if (typeof firstArg === 'function') { + delegate = firstArg + } else { + message = String(firstArg) + } + } else if (!cause) { + message = String(firstArg) + } + + return new Log(message, args, cause, delegate) + } +} + +module.exports = { + Log +} diff --git a/packages/dd-trace/src/log/writer.js b/packages/dd-trace/src/log/writer.js index bc4a5b20621..4724253244b 100644 --- a/packages/dd-trace/src/log/writer.js +++ b/packages/dd-trace/src/log/writer.js @@ -2,6 +2,7 @@ const { storage } = require('../../../datadog-core') const { LogChannel } = require('./channels') +const { Log } = require('./log') const defaultLogger = { debug: msg => console.debug(msg), /* eslint-disable-line no-console */ info: msg => console.info(msg), /* eslint-disable-line no-console */ @@ -22,7 +23,7 @@ function withNoop (fn) { } function unsubscribeAll () { - logChannel.unsubscribe({ debug, info, warn, error }) + logChannel.unsubscribe({ debug: onDebug, info: onInfo, warn: onWarn, error: onError }) } function toggleSubscription (enable, level) { @@ -30,7 +31,7 @@ function toggleSubscription (enable, level) { if (enable) { logChannel = new LogChannel(level) - logChannel.subscribe({ debug, info, warn, error }) + logChannel.subscribe({ debug: onDebug, info: onInfo, warn: onWarn, error: onError }) } } @@ -51,32 +52,62 @@ function reset () { toggleSubscription(false) } -function error (err) { - if (typeof err !== 'object' || !err) { - err = String(err) - } else if (!err.stack) { - err = String(err.message || err) +function getErrorLog (err) { + if (err && typeof err.delegate === 'function') { + const result = err.delegate() + return Array.isArray(result) ? Log.parse(...result) : Log.parse(result) + } else { + return err } +} - if (typeof err === 'string') { - err = new Error(err) - } +function onError (err) { + const { formatted, cause } = getErrorLog(err) + + // calling twice logger.error() because Error cause is only available in nodejs v16.9.0 + // TODO: replace it with Error(message, { cause }) when cause has broad support + if (formatted) withNoop(() => logger.error(new Error(formatted))) + if (cause) withNoop(() => logger.error(cause)) +} + +function onWarn (log) { + const { formatted, cause } = getErrorLog(log) + if (formatted) withNoop(() => logger.warn(formatted)) + if (cause) withNoop(() => logger.warn(cause)) +} - withNoop(() => logger.error(err)) +function onInfo (log) { + const { formatted, cause } = getErrorLog(log) + if (formatted) withNoop(() => logger.info(formatted)) + if (cause) withNoop(() => logger.info(cause)) } -function warn (message) { - if (!logger.warn) return debug(message) - withNoop(() => logger.warn(message)) +function onDebug (log) { + const { formatted, cause } = getErrorLog(log) + if (formatted) withNoop(() => logger.debug(formatted)) + if (cause) withNoop(() => logger.debug(cause)) } -function info (message) { - if (!logger.info) return debug(message) - withNoop(() => logger.info(message)) +function error (...args) { + onError(Log.parse(...args)) +} + +function warn (...args) { + const log = Log.parse(...args) + if (!logger.warn) return onDebug(log) + + onWarn(log) +} + +function info (...args) { + const log = Log.parse(...args) + if (!logger.info) return onDebug(log) + + onInfo(log) } -function debug (message) { - withNoop(() => logger.debug(message)) +function debug (...args) { + onDebug(Log.parse(...args)) } module.exports = { use, toggle, reset, error, warn, info, debug } diff --git a/packages/dd-trace/src/telemetry/logs/index.js b/packages/dd-trace/src/telemetry/logs/index.js index 54e7c51fa97..c535acb9cdd 100644 --- a/packages/dd-trace/src/telemetry/logs/index.js +++ b/packages/dd-trace/src/telemetry/logs/index.js @@ -35,18 +35,23 @@ function onLog (log) { } function onErrorLog (msg) { - if (msg instanceof Error) { - onLog({ - level: 'ERROR', - message: msg.message, - stack_trace: msg.stack - }) - } else if (typeof msg === 'string') { - onLog({ - level: 'ERROR', - message: msg - }) + const { message, cause } = msg + if (!message && !cause) return + + const telLog = { + level: 'ERROR', + + // existing log.error(err) without message will be reported as 'Generic Error' + message: message ?? 'Generic Error' } + + if (cause) { + telLog.stack_trace = cause.stack + const errorType = cause.name ?? 'Error' + telLog.message = `${errorType}: ${telLog.message}` + } + + onLog(telLog) } function start (config) { diff --git a/packages/dd-trace/src/telemetry/logs/log-collector.js b/packages/dd-trace/src/telemetry/logs/log-collector.js index 182842fc4c4..9103fd1c47d 100644 --- a/packages/dd-trace/src/telemetry/logs/log-collector.js +++ b/packages/dd-trace/src/telemetry/logs/log-collector.js @@ -48,16 +48,11 @@ function sanitize (logEntry) { .map(line => line.replace(ddBasePath, '')) logEntry.stack_trace = stackLines.join(EOL) - if (logEntry.stack_trace === '') { - // If entire stack was removed, we'd just have a message saying "omitted" - // in which case we'd rather not log it at all. + if (logEntry.stack_trace === '' && !logEntry.message) { + // If entire stack was removed and there is no message we'd rather not log it at all. return null } - if (!isDDCode) { - logEntry.message = 'omitted' - } - return logEntry } @@ -82,7 +77,7 @@ const logCollector = { return true } } catch (e) { - log.error(`Unable to add log to logCollector: ${e.message}`) + log.error('Unable to add log to logCollector: %s', e.message) } return false }, diff --git a/packages/dd-trace/test/log.spec.js b/packages/dd-trace/test/log.spec.js index f2ec9a02a1f..a035c864f71 100644 --- a/packages/dd-trace/test/log.spec.js +++ b/packages/dd-trace/test/log.spec.js @@ -160,6 +160,7 @@ describe('log', () => { expect(console.error.firstCall.args[0]).to.have.property('message', 'error') }) + // NOTE: There is no usage for this case. should we continue supporting it? it('should convert empty values to errors', () => { log.error() @@ -191,6 +192,34 @@ describe('log', () => { expect(console.error.firstCall.args[0]).to.be.instanceof(Error) expect(console.error.firstCall.args[0]).to.have.property('message', 'error') }) + + it('should allow a message + Error', () => { + log.error('this is an error', new Error('cause')) + + expect(console.error).to.have.been.called + expect(console.error.firstCall.args[0]).to.be.instanceof(Error) + expect(console.error.firstCall.args[0]).to.have.property('message', 'this is an error') + expect(console.error.secondCall.args[0]).to.be.instanceof(Error) + expect(console.error.secondCall.args[0]).to.have.property('message', 'cause') + }) + + it('should allow a templated message', () => { + log.error('this is an error of type: %s code: %i', 'ERR', 42) + + expect(console.error).to.have.been.called + expect(console.error.firstCall.args[0]).to.be.instanceof(Error) + expect(console.error.firstCall.args[0]).to.have.property('message', 'this is an error of type: ERR code: 42') + }) + + it('should allow a templated message + Error', () => { + log.error('this is an error of type: %s code: %i', 'ERR', 42, new Error('cause')) + + expect(console.error).to.have.been.called + expect(console.error.firstCall.args[0]).to.be.instanceof(Error) + expect(console.error.firstCall.args[0]).to.have.property('message', 'this is an error of type: ERR code: 42') + expect(console.error.secondCall.args[0]).to.be.instanceof(Error) + expect(console.error.secondCall.args[0]).to.have.property('message', 'cause') + }) }) describe('toggle', () => { diff --git a/packages/dd-trace/test/telemetry/logs/index.spec.js b/packages/dd-trace/test/telemetry/logs/index.spec.js index f00c8f17655..0d18b6e847b 100644 --- a/packages/dd-trace/test/telemetry/logs/index.spec.js +++ b/packages/dd-trace/test/telemetry/logs/index.spec.js @@ -4,6 +4,7 @@ require('../../setup/tap') const { match } = require('sinon') const proxyquire = require('proxyquire') +const { Log } = require('../../../src/log/log') describe('telemetry logs', () => { let defaultConfig @@ -141,13 +142,14 @@ describe('telemetry logs', () => { it('should be called when an Error object is published to datadog:log:error', () => { const error = new Error('message') const stack = error.stack - errorLog.publish(error) + errorLog.publish({ cause: error }) - expect(logCollectorAdd).to.be.calledOnceWith(match({ message: 'message', level: 'ERROR', stack_trace: stack })) + expect(logCollectorAdd) + .to.be.calledOnceWith(match({ message: `${error.name}: Generic Error`, level: 'ERROR', stack_trace: stack })) }) it('should be called when an error string is published to datadog:log:error', () => { - errorLog.publish('custom error message') + errorLog.publish({ message: 'custom error message' }) expect(logCollectorAdd).to.be.calledOnceWith(match({ message: 'custom error message', @@ -161,6 +163,12 @@ describe('telemetry logs', () => { expect(logCollectorAdd).not.to.be.called }) + + it('should not be called when an object without message and stack is published to datadog:log:error', () => { + errorLog.publish(Log.parse(() => new Error('error'))) + + expect(logCollectorAdd).not.to.be.called + }) }) }) diff --git a/packages/dd-trace/test/telemetry/logs/log-collector.spec.js b/packages/dd-trace/test/telemetry/logs/log-collector.spec.js index 168378a2251..1cb99cef518 100644 --- a/packages/dd-trace/test/telemetry/logs/log-collector.spec.js +++ b/packages/dd-trace/test/telemetry/logs/log-collector.spec.js @@ -63,7 +63,7 @@ describe('telemetry log collector', () => { })).to.be.true }) - it('should not include original message if first frame is not a dd frame', () => { + it('should include original message if first frame is not a dd frame', () => { const thirdPartyFrame = `at callFn (/this/is/not/a/dd/frame/runnable.js:366:21) at T (${ddBasePath}packages/dd-trace/test/telemetry/logs/log_collector.spec.js:29:21)` const stack = new Error('Error 1') @@ -77,7 +77,7 @@ describe('telemetry log collector', () => { expect(logCollector.add({ message: 'Error 1', level: 'ERROR', stack_trace: stack })).to.be.true expect(logCollector.hasEntry({ - message: 'omitted', + message: 'Error 1', level: 'ERROR', stack_trace: ddFrames })).to.be.true