[DI] Support custom logger in worker thread (#6128)

watson · web-flow · commit 3c9fc50bd9ec · 2025-07-18T22:13:03.000+02:00
If the tracer is configured with a custom logger, it should be used in
the Dynamic Instrumentation/Live Debugging worker thread.

This changes how logs are handled in the worker thread: Instead of
logging them directly to STDOUT/STDERR, they are sent back to the main
thread for processing in the main logger.
diff --git a/integration-tests/debugger/custom-logger.spec.js b/integration-tests/debugger/custom-logger.spec.js
@@ -4,11 +4,26 @@ const assert = require('node:assert')
 const { setup } = require('./utils')
 
 describe('Dynamic Instrumentation', function () {
-  const t = setup()
+  const stdio = []
+  const stderr = []
+  const t = setup({
+    env: {
+      DD_TRACE_DEBUG: 'true'
+    },
+    silent: true,
+    stdioHandler (data) {
+      stdio.push(data.toString())
+    },
+    stderrHandler (data) {
+      stderr.push(data.toString())
+    },
+  })
 
-  it('should not abort if a custom logger is used', function (done) {
-    t.agent.on('debugger-input', ({ payload: [payload] }) => {
-      assert.strictEqual(payload.message, 'Hello World!')
+  it('should log to the custom logger from the worker thread', function (done) {
+    t.agent.on('debugger-input', () => {
+      assert(stdio.some((line) => line.startsWith('[CUSTOM LOGGER][DEBUG]: [debugger]')))
+      assert(stdio.some((line) => line.startsWith('[CUSTOM LOGGER][DEBUG]: [debugger:devtools_client]')))
+      assert.strictEqual(stderr.length, 0)
       done()
     })
 
diff --git a/integration-tests/debugger/target-app/custom-logger.js b/integration-tests/debugger/target-app/custom-logger.js
@@ -2,10 +2,10 @@
 
 require('dd-trace').init({
   logger: {
-    error: err => console.error(err), // eslint-disable-line no-console
-    warn: message => console.warn(message), // eslint-disable-line no-console
-    info: message => console.info(message), // eslint-disable-line no-console
-    debug: message => console.debug(message) // eslint-disable-line no-console
+    error: (...args) => console.log('[CUSTOM LOGGER][ERROR]:', ...args), // eslint-disable-line no-console
+    warn: (...args) => console.log('[CUSTOM LOGGER][WARN]:', ...args), // eslint-disable-line no-console
+    info: (...args) => console.log('[CUSTOM LOGGER][INFO]:', ...args), // eslint-disable-line no-console
+    debug: (...args) => console.log('[CUSTOM LOGGER][DEBUG]:', ...args) // eslint-disable-line no-console
   }
 })
 
diff --git a/integration-tests/debugger/utils.js b/integration-tests/debugger/utils.js
@@ -17,7 +17,7 @@ module.exports = {
   setup
 }
 
-function setup ({ env, testApp, testAppSource, dependencies } = {}) {
+function setup ({ env, testApp, testAppSource, dependencies, silent, stdioHandler, stderrHandler } = {}) {
   let sandbox, cwd
 
   const breakpoints = getBreakpointInfo({
@@ -101,8 +101,9 @@ function setup ({ env, testApp, testAppSource, dependencies } = {}) {
         DD_TRACE_DEBUG: process.env.DD_TRACE_DEBUG, // inherit to make debugging the sandbox easier
         DD_REMOTE_CONFIG_POLL_INTERVAL_SECONDS: pollInterval,
         ...env
-      }
-    })
+      },
+      silent: silent ?? false
+    }, stdioHandler, stderrHandler)
     t.axios = Axios.create({ baseURL: t.proc.url })
   })
 
diff --git a/packages/dd-trace/src/debugger/config.js b/packages/dd-trace/src/debugger/config.js
@@ -3,8 +3,10 @@
 module.exports = function getDebuggerConfig (config) {
   return {
     commitSHA: config.commitSHA,
+    debug: config.debug,
     dynamicInstrumentation: config.dynamicInstrumentation,
     hostname: config.hostname,
+    logLevel: config.logLevel,
     port: config.port,
     repositoryUrl: config.repositoryUrl,
     runtimeId: config.tags['runtime-id'],
diff --git a/packages/dd-trace/src/debugger/devtools_client/breakpoints.js b/packages/dd-trace/src/debugger/devtools_client/breakpoints.js
@@ -12,7 +12,7 @@ const {
   breakpointToProbes,
   probeToLocation
 } = require('./state')
-const log = require('../../log')
+const log = require('./log')
 
 let sessionStarted = false
 const probes = new Map()
diff --git a/packages/dd-trace/src/debugger/devtools_client/config.js b/packages/dd-trace/src/debugger/devtools_client/config.js
@@ -2,7 +2,7 @@
 
 const { workerData: { config: parentConfig, parentThreadId, configPort } } = require('node:worker_threads')
 const { format } = require('node:url')
-const log = require('../../log')
+const log = require('./log')
 
 const config = module.exports = {
   ...parentConfig,
diff --git a/packages/dd-trace/src/debugger/devtools_client/index.js b/packages/dd-trace/src/debugger/devtools_client/index.js
@@ -9,7 +9,7 @@ const { getStackFromCallFrames } = require('./state')
 const { ackEmitting } = require('./status')
 const { parentThreadId } = require('./config')
 const { MAX_SNAPSHOTS_PER_SECOND_GLOBALLY } = require('./defaults')
-const log = require('../../log')
+const log = require('./log')
 const { version } = require('../../../../../package.json')
 const { NODE_MAJOR } = require('../../../../../version')
 
diff --git a/packages/dd-trace/src/debugger/devtools_client/log.js b/packages/dd-trace/src/debugger/devtools_client/log.js
@@ -0,0 +1,19 @@
+'use strict'
+
+const { workerData } = require('node:worker_threads')
+
+// For testing purposes, we allow `workerData` to be undefined and fallback to a default config
+const { config: { debug, logLevel }, logPort } = workerData ?? { config: { debug: false } }
+
+const LEVELS = ['error', 'warn', 'info', 'debug']
+const on = (level, ...args) => {
+  if (typeof args[0] === 'function') {
+    args = [args[0]()]
+  }
+  logPort.postMessage({ level, args })
+}
+const off = () => {}
+
+for (const level of LEVELS) {
+  module.exports[level] = debug && LEVELS.indexOf(logLevel) >= LEVELS.indexOf(level) ? on.bind(null, level) : off
+}
diff --git a/packages/dd-trace/src/debugger/devtools_client/remote_config.js b/packages/dd-trace/src/debugger/devtools_client/remote_config.js
@@ -3,7 +3,7 @@
 const { workerData: { probePort } } = require('node:worker_threads')
 const { addBreakpoint, removeBreakpoint, modifyBreakpoint } = require('./breakpoints')
 const { ackReceived, ackInstalled, ackError } = require('./status')
-const log = require('../../log')
+const log = require('./log')
 
 // Example log line probe (simplified):
 // {
diff --git a/packages/dd-trace/src/debugger/devtools_client/send.js b/packages/dd-trace/src/debugger/devtools_client/send.js
@@ -7,7 +7,7 @@ const config = require('./config')
 const JSONBuffer = require('./json-buffer')
 const request = require('../../exporters/common/request')
 const { GIT_COMMIT_SHA, GIT_REPOSITORY_URL } = require('../../plugins/util/tags')
-const log = require('../../log')
+const log = require('./log')
 const { version } = require('../../../../../package.json')
 const { getEnvironmentVariable } = require('../../config-helper')
 
diff --git a/packages/dd-trace/src/debugger/devtools_client/snapshot/index.js b/packages/dd-trace/src/debugger/devtools_client/snapshot/index.js
@@ -2,7 +2,7 @@
 
 const { getRuntimeObject } = require('./collector')
 const { processRawState } = require('./processor')
-const log = require('../../../log')
+const log = require('../log')
 
 const DEFAULT_MAX_REFERENCE_DEPTH = 3
 const DEFAULT_MAX_COLLECTION_SIZE = 100
diff --git a/packages/dd-trace/src/debugger/devtools_client/state.js b/packages/dd-trace/src/debugger/devtools_client/state.js
@@ -4,7 +4,7 @@ const { join, dirname } = require('path')
 const { normalize } = require('source-map/lib/util')
 const { loadSourceMapSync } = require('./source-maps')
 const session = require('./session')
-const log = require('../../log')
+const log = require('./log')
 
 const WINDOWS_DRIVE_LETTER_REGEX = /[a-zA-Z]/
 
diff --git a/packages/dd-trace/src/debugger/devtools_client/status.js b/packages/dd-trace/src/debugger/devtools_client/status.js
@@ -5,7 +5,7 @@ const config = require('./config')
 const JSONBuffer = require('./json-buffer')
 const request = require('../../exporters/common/request')
 const FormData = require('../../exporters/common/form-data')
-const log = require('../../log')
+const log = require('./log')
 
 module.exports = {
   ackReceived,
diff --git a/packages/dd-trace/src/debugger/index.js b/packages/dd-trace/src/debugger/index.js
@@ -26,6 +26,7 @@ function start (config, rc) {
 
   const rcAckCallbacks = new Map()
   const probeChannel = new MessageChannel()
+  const logChannel = new MessageChannel()
   configChannel = new MessageChannel()
 
   process[Symbol.for('datadog:node:util:types')] = types
@@ -55,6 +56,11 @@ function start (config, rc) {
   })
   probeChannel.port2.on('messageerror', (err) => log.error('[debugger] received "messageerror" on probe port', err))
 
+  logChannel.port2.on('message', ({ level, args }) => {
+    log[level](...args)
+  })
+  logChannel.port2.on('messageerror', (err) => log.error('[debugger] received "messageerror" on log port', err))
+
   worker = new Worker(
     join(__dirname, 'devtools_client', 'index.js'),
     {
@@ -64,9 +70,10 @@ function start (config, rc) {
         config: getDebuggerConfig(config),
         parentThreadId,
         probePort: probeChannel.port1,
+        logPort: logChannel.port1,
         configPort: configChannel.port1
       },
-      transferList: [probeChannel.port1, configChannel.port1]
+      transferList: [probeChannel.port1, logChannel.port1, configChannel.port1]
     }
   )
 
@@ -95,6 +102,8 @@ function start (config, rc) {
   worker.unref()
   probeChannel.port1.unref()
   probeChannel.port2.unref()
+  logChannel.port1.unref()
+  logChannel.port2.unref()
   configChannel.port1.unref()
   configChannel.port2.unref()
 }
diff --git a/packages/dd-trace/test/debugger/config.spec.js b/packages/dd-trace/test/debugger/config.spec.js
@@ -14,17 +14,21 @@ describe('getDebuggerConfig', function () {
     const config = getDebuggerConfig(tracerConfig)
     assert.deepStrictEqual(Object.keys(config), [
       'commitSHA',
+      'debug',
       'dynamicInstrumentation',
       'hostname',
+      'logLevel',
       'port',
       'repositoryUrl',
       'runtimeId',
       'service',
       'url',
     ])
     assert.strictEqual(config.commitSHA, tracerConfig.commitSHA)
+    assert.strictEqual(config.debug, tracerConfig.debug)
     assert.deepStrictEqual(config.dynamicInstrumentation, tracerConfig.dynamicInstrumentation)
     assert.strictEqual(config.hostname, tracerConfig.hostname)
+    assert.strictEqual(config.logLevel, tracerConfig.logLevel)
     assert.strictEqual(config.port, tracerConfig.port)
     assert.strictEqual(config.repositoryUrl, tracerConfig.repositoryUrl)
     assert.strictEqual(config.runtimeId, tracerConfig.tags['runtime-id'])
diff --git a/packages/dd-trace/test/debugger/devtools_client/log.spec.js b/packages/dd-trace/test/debugger/devtools_client/log.spec.js
@@ -0,0 +1,108 @@
+'use strict'
+
+require('../../setup/mocha')
+
+const assert = require('node:assert')
+
+describe('worker thread logger', function () {
+  it('should log to the provided message channel', function (done) {
+    const logChannel = new MessageChannel()
+    const log = proxyquire('../src/debugger/devtools_client/log', {
+      'node:worker_threads': {
+        workerData: { logPort: logChannel.port1, config: { debug: true, logLevel: 'debug' } }
+      }
+    })
+
+    const expected = [
+      { level: 'error', args: ['test1'] },
+      { level: 'warn', args: ['test2'] },
+      { level: 'info', args: ['test3'] },
+      { level: 'debug', args: ['test4'] }
+    ]
+
+    logChannel.port2.on('message', (message) => {
+      assert.deepStrictEqual(message, expected.shift())
+      if (expected.length === 0) done()
+    })
+
+    log.error('test1')
+    log.warn('test2')
+    log.info('test3')
+    log.debug('test4')
+  })
+
+  it('should respect the debug flag', function (done) {
+    const logChannel = new MessageChannel()
+    const log = proxyquire('../src/debugger/devtools_client/log', {
+      'node:worker_threads': {
+        workerData: { logPort: logChannel.port1, config: { debug: false, logLevel: 'debug' } }
+      }
+    })
+
+    logChannel.port2.on('message', () => {
+      throw new Error('should not have logged')
+    })
+
+    log.error('test1')
+    log.warn('test2')
+    log.info('test3')
+    log.debug('test4')
+
+    setImmediate(done)
+  })
+
+  it('should should resolve the function argument', function (done) {
+    const logChannel = new MessageChannel()
+    const log = proxyquire('../src/debugger/devtools_client/log', {
+      'node:worker_threads': {
+        workerData: { logPort: logChannel.port1, config: { debug: true, logLevel: 'debug' } }
+      }
+    })
+
+    logChannel.port2.on('message', (message) => {
+      assert.deepStrictEqual(message, { level: 'debug', args: ['logged'] })
+      done()
+    })
+
+    const message = 'logged'
+    log.debug(() => message)
+  })
+
+  describe('log level', function () {
+    it('info', checkLogLevel('info', ['error', 'warn', 'info']))
+
+    it('warn', checkLogLevel('warn', ['error', 'warn']))
+
+    it('error', checkLogLevel('error', ['error']))
+  })
+})
+
+function checkLogLevel (level, expectedLevels) {
+  const levels = ['error', 'warn', 'info', 'debug']
+
+  return function (done) {
+    const logChannel = new MessageChannel()
+    const log = proxyquire('../src/debugger/devtools_client/log', {
+      'node:worker_threads': {
+        workerData: { logPort: logChannel.port1, config: { debug: true, logLevel: level } }
+      }
+    })
+
+    const expected = expectedLevels.map((level) => ({ level, args: ['logged'] }))
+
+    logChannel.port2.on('message', (message) => {
+      assert.deepStrictEqual(message, expected.shift())
+      if (expected.length === 0) done()
+    })
+
+    for (const level of expectedLevels) {
+      log[level]('logged')
+    }
+
+    for (const level of levels) {
+      if (!expectedLevels.includes(level)) {
+        log[level]('not logged')
+      }
+    }
+  }
+}
