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 <[email protected]> * update log writter and add tests * fix linter error --------- Co-authored-by: Roch Devost <[email protected]>
DataDog · Dec 19, 2024 · a11aeb5 · a11aeb5
1 parent ebc886c
commit a11aeb5
Show file tree

Hide file tree

Showing 5 changed files with 62 additions and 7 deletions.
diff --git 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
@@ -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
@@ -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,15 +24,15 @@ 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) {
   unsubscribeAll()
 
   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
@@ -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
@@ -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)