From a11aeb50f6170c6cb567d7da6aa67a60bd034727 Mon Sep 17 00:00:00 2001 From: Ida Liu <119438987+ida613@users.noreply.github.com> Date: Thu, 19 Dec 2024 10:21:09 -0500 Subject: [PATCH] add logging for priority sampler (#5028) * add logging * update logging * update log traceChannel * update logging * make log.trace take callbacks * fix linter errors * update log.trace * Update packages/dd-trace/src/log/index.js Co-authored-by: Roch Devost * update log writter and add tests * fix linter error --------- Co-authored-by: Roch Devost --- packages/dd-trace/src/log/channels.js | 11 +++++++++-- packages/dd-trace/src/log/index.js | 12 +++++++++++- packages/dd-trace/src/log/writer.js | 17 ++++++++++++++--- packages/dd-trace/src/priority_sampler.js | 12 +++++++++++- packages/dd-trace/test/log.spec.js | 17 +++++++++++++++++ 5 files changed, 62 insertions(+), 7 deletions(-) diff --git a/packages/dd-trace/src/log/channels.js b/packages/dd-trace/src/log/channels.js index 545fef4195a..b3b10624705 100644 --- a/packages/dd-trace/src/log/channels.js +++ b/packages/dd-trace/src/log/channels.js @@ -3,7 +3,7 @@ const { channel } = require('dc-polyfill') const Level = { - trace: 20, + trace: 10, debug: 20, info: 30, warn: 40, @@ -12,6 +12,7 @@ const Level = { off: 100 } +const traceChannel = channel('datadog:log:trace') const debugChannel = channel('datadog:log:debug') const infoChannel = channel('datadog:log:info') const warnChannel = channel('datadog:log:warn') @@ -31,6 +32,9 @@ class LogChannel { } subscribe (logger) { + if (Level.trace >= this._level) { + traceChannel.subscribe(logger.trace) + } if (Level.debug >= this._level) { debugChannel.subscribe(logger.debug) } @@ -46,6 +50,9 @@ class LogChannel { } unsubscribe (logger) { + if (traceChannel.hasSubscribers) { + traceChannel.unsubscribe(logger.trace) + } if (debugChannel.hasSubscribers) { debugChannel.unsubscribe(logger.debug) } @@ -63,7 +70,7 @@ class LogChannel { module.exports = { LogChannel, - + traceChannel, debugChannel, infoChannel, warnChannel, diff --git a/packages/dd-trace/src/log/index.js b/packages/dd-trace/src/log/index.js index 3a5392340df..213b6ccc8e6 100644 --- a/packages/dd-trace/src/log/index.js +++ b/packages/dd-trace/src/log/index.js @@ -2,7 +2,7 @@ const coalesce = require('koalas') const { isTrue } = require('../util') -const { debugChannel, infoChannel, warnChannel, errorChannel } = require('./channels') +const { traceChannel, debugChannel, infoChannel, warnChannel, errorChannel } = require('./channels') const logWriter = require('./writer') const { Log } = require('./log') @@ -56,6 +56,16 @@ const log = { return this }, + trace (...args) { + if (traceChannel.hasSubscribers) { + const logRecord = {} + Error.captureStackTrace(logRecord, this.trace) + const stack = logRecord.stack.split('\n')[1].replace(/^\s+at ([^\s]) .+/, '$1') + traceChannel.publish(Log.parse('Trace', args, { stack })) + } + return this + }, + debug (...args) { if (debugChannel.hasSubscribers) { debugChannel.publish(Log.parse(...args)) diff --git a/packages/dd-trace/src/log/writer.js b/packages/dd-trace/src/log/writer.js index 4724253244b..a721f7f9e35 100644 --- a/packages/dd-trace/src/log/writer.js +++ b/packages/dd-trace/src/log/writer.js @@ -4,6 +4,7 @@ const { storage } = require('../../../datadog-core') const { LogChannel } = require('./channels') const { Log } = require('./log') const defaultLogger = { + trace: msg => console.trace(msg), /* eslint-disable-line no-console */ debug: msg => console.debug(msg), /* eslint-disable-line no-console */ info: msg => console.info(msg), /* eslint-disable-line no-console */ warn: msg => console.warn(msg), /* eslint-disable-line no-console */ @@ -23,7 +24,7 @@ function withNoop (fn) { } function unsubscribeAll () { - logChannel.unsubscribe({ debug: onDebug, info: onInfo, warn: onWarn, error: onError }) + logChannel.unsubscribe({ trace: onTrace, debug: onDebug, info: onInfo, warn: onWarn, error: onError }) } function toggleSubscription (enable, level) { @@ -31,7 +32,7 @@ function toggleSubscription (enable, level) { if (enable) { logChannel = new LogChannel(level) - logChannel.subscribe({ debug: onDebug, info: onInfo, warn: onWarn, error: onError }) + logChannel.subscribe({ trace: onTrace, debug: onDebug, info: onInfo, warn: onWarn, error: onError }) } } @@ -88,6 +89,12 @@ function onDebug (log) { if (cause) withNoop(() => logger.debug(cause)) } +function onTrace (log) { + const { formatted, cause } = getErrorLog(log) + if (formatted) withNoop(() => logger.trace(formatted)) + if (cause) withNoop(() => logger.trace(cause)) +} + function error (...args) { onError(Log.parse(...args)) } @@ -110,4 +117,8 @@ function debug (...args) { onDebug(Log.parse(...args)) } -module.exports = { use, toggle, reset, error, warn, info, debug } +function trace (...args) { + onTrace(Log.parse(...args)) +} + +module.exports = { use, toggle, reset, error, warn, info, debug, trace } diff --git a/packages/dd-trace/src/priority_sampler.js b/packages/dd-trace/src/priority_sampler.js index f9968a41194..3a89f71f664 100644 --- a/packages/dd-trace/src/priority_sampler.js +++ b/packages/dd-trace/src/priority_sampler.js @@ -1,5 +1,6 @@ 'use strict' +const log = require('./log') const RateLimiter = require('./rate_limiter') const Sampler = require('./sampler') const { setSamplingRules } = require('./startup-log') @@ -44,16 +45,19 @@ class PrioritySampler { this.update({}) } - configure (env, { sampleRate, provenance = undefined, rateLimit = 100, rules = [] } = {}) { + configure (env, opts = {}) { + const { sampleRate, provenance = undefined, rateLimit = 100, rules = [] } = opts this._env = env this._rules = this._normalizeRules(rules, sampleRate, rateLimit, provenance) this._limiter = new RateLimiter(rateLimit) + log.trace(env, opts) setSamplingRules(this._rules) } isSampled (span) { const priority = this._getPriorityFromAuto(span) + log.trace(span) return priority === USER_KEEP || priority === AUTO_KEEP } @@ -67,6 +71,8 @@ class PrioritySampler { if (context._sampling.priority !== undefined) return if (!root) return // noop span + log.trace(span, auto) + const tag = this._getPriorityFromTags(context._tags, context) if (this.validate(tag)) { @@ -94,6 +100,8 @@ class PrioritySampler { samplers[DEFAULT_KEY] = samplers[DEFAULT_KEY] || defaultSampler this._samplers = samplers + + log.trace(rates) } validate (samplingPriority) { @@ -117,6 +125,8 @@ class PrioritySampler { context._sampling.mechanism = mechanism const root = context._trace.started[0] + + log.trace(span, samplingPriority, mechanism) this._addDecisionMaker(root) } diff --git a/packages/dd-trace/test/log.spec.js b/packages/dd-trace/test/log.spec.js index a035c864f71..ac2feea9f7a 100644 --- a/packages/dd-trace/test/log.spec.js +++ b/packages/dd-trace/test/log.spec.js @@ -86,6 +86,7 @@ describe('log', () => { sinon.stub(console, 'error') sinon.stub(console, 'warn') sinon.stub(console, 'debug') + sinon.stub(console, 'trace') error = new Error() @@ -104,6 +105,7 @@ describe('log', () => { console.error.restore() console.warn.restore() console.debug.restore() + console.trace.restore() }) it('should support chaining', () => { @@ -139,6 +141,21 @@ describe('log', () => { }) }) + describe('trace', () => { + it('should not log to console by default', () => { + log.trace('trace') + + expect(console.trace).to.not.have.been.called + }) + + it('should log to console after setting log level to trace', () => { + log.toggle(true, 'trace') + log.trace('argument') + + expect(console.trace).to.have.been.calledTwice + }) + }) + describe('error', () => { it('should log to console by default', () => { log.error(error)