PROF-9722: Send profiler errors to the telemetry log

packages/dd-trace/src/appsec/iast/iast-log.js

@@ -2,35 +2,9 @@
 
 const dc = require('dc-polyfill')
 const log = require('../../log')
-const { calculateDDBasePath } = require('../../util')
 
 const telemetryLog = dc.channel('datadog:telemetry:log')
 
-const ddBasePath = calculateDDBasePath(__dirname)
-const EOL = '\n'
-const STACK_FRAME_LINE_REGEX = /^\s*at\s/gm
-
-function sanitize (logEntry, stack) {
-  if (!stack) return logEntry
-
-  let stackLines = stack.split(EOL)
-
-  const firstIndex = stackLines.findIndex(l => l.match(STACK_FRAME_LINE_REGEX))
-
-  const isDDCode = firstIndex > -1 && stackLines[firstIndex].includes(ddBasePath)
-  stackLines = stackLines
-    .filter((line, index) => (isDDCode && index < firstIndex) || line.includes(ddBasePath))
-    .map(line => line.replace(ddBasePath, ''))
-
-  logEntry.stack_trace = stackLines.join(EOL)
-
-  if (!isDDCode) {
-    logEntry.message = 'omitted'
-  }
-
-  return logEntry
-}
-
 function getTelemetryLog (data, level) {
   try {
     data = typeof data === 'function' ? data() : data
@@ -42,18 +16,13 @@ function getTelemetryLog (data, level) {
       message = String(data.message || data)
     }
 
-    let logEntry = {
+    const logEntry = {
       message,
       level
     }
-
     if (data.stack) {
-      logEntry = sanitize(logEntry, data.stack)
-      if (logEntry.stack_trace === '') {
-        return
-      }
+      logEntry.stack_trace = data.stack
     }
-
     return logEntry
   } catch (e) {
     log.error(e)

packages/dd-trace/src/config.js

@@ -549,6 +549,7 @@ class Config {
       DD_IAST_REDACTION_VALUE_PATTERN,
       DD_IAST_REQUEST_SAMPLING,
       DD_IAST_TELEMETRY_VERBOSITY,
+      DD_INJECTION_ENABLED,
       DD_INSTRUMENTATION_TELEMETRY_ENABLED,
       DD_INSTRUMENTATION_CONFIG_ID,
       DD_LOGS_INJECTION,
@@ -705,7 +706,14 @@ class Config {
     this._setBoolean(env, 'telemetry.debug', DD_TELEMETRY_DEBUG)
     this._setBoolean(env, 'telemetry.dependencyCollection', DD_TELEMETRY_DEPENDENCY_COLLECTION_ENABLED)
     this._setValue(env, 'telemetry.heartbeatInterval', maybeInt(Math.floor(DD_TELEMETRY_HEARTBEAT_INTERVAL * 1000)))
-    this._setBoolean(env, 'telemetry.logCollection', coalesce(DD_TELEMETRY_LOG_COLLECTION_ENABLED, DD_IAST_ENABLED))
+    const hasTelemetryLogsUsingFeatures =
+      isTrue(DD_IAST_ENABLED) ||
+      isTrue(DD_PROFILING_ENABLED) ||
+      (typeof DD_INJECTION_ENABLED === 'string' && DD_INJECTION_ENABLED.split(',').includes('profiling'))
+        ? true
+        : undefined
+    this._setBoolean(env, 'telemetry.logCollection', coalesce(DD_TELEMETRY_LOG_COLLECTION_ENABLED,
+      hasTelemetryLogsUsingFeatures))
     this._setBoolean(env, 'telemetry.metrics', DD_TELEMETRY_METRICS_ENABLED)
     this._setBoolean(env, 'traceId128BitGenerationEnabled', DD_TRACE_128_BIT_TRACEID_GENERATION_ENABLED)
     this._setBoolean(env, 'traceId128BitLoggingEnabled', DD_TRACE_128_BIT_TRACEID_LOGGING_ENABLED)
@@ -786,8 +794,10 @@ class Config {
     this._setBoolean(opts, 'spanRemoveIntegrationFromService', options.spanRemoveIntegrationFromService)
     this._setBoolean(opts, 'startupLogs', options.startupLogs)
     this._setTags(opts, 'tags', tags)
-    this._setBoolean(opts, 'telemetry.logCollection', options.iastOptions &&
-    (options.iastOptions === true || options.iastOptions.enabled === true))
+    const hasTelemetryLogsUsingFeatures =
+      (options.iastOptions && (options.iastOptions === true || options.iastOptions?.enabled === true)) ||
+      (options.profiling && options.profiling === true)
+    this._setBoolean(opts, 'telemetry.logCollection', hasTelemetryLogsUsingFeatures)
     this._setBoolean(opts, 'traceId128BitGenerationEnabled', options.traceId128BitGenerationEnabled)
     this._setBoolean(opts, 'traceId128BitLoggingEnabled', options.traceId128BitLoggingEnabled)
     this._setString(opts, 'version', options.version || tags.version)

packages/dd-trace/src/profiling/profiler.js

@@ -5,6 +5,7 @@ const { Config } = require('./config')
 const { snapshotKinds } = require('./constants')
 const { threadNamePrefix } = require('./profilers/shared')
 const dc = require('dc-polyfill')
+const telemetryLog = dc.channel('datadog:telemetry:log')
 
 const profileSubmittedChannel = dc.channel('datadog:profiling:profile-submitted')
 
@@ -15,6 +16,19 @@ function maybeSourceMap (sourceMap, SourceMapper, debug) {
   ], debug)
 }
 
+function logError (logger, err) {
+  if (logger) {
+    logger.error(err)
+  }
+  if (telemetryLog.hasSubscribers) {
+    telemetryLog.publish({
+      message: err.message,
+      level: 'ERROR',
+      stack_trace: err.stack
+    })
+  }
+}
+
 class Profiler extends EventEmitter {
   constructor () {
     super()
@@ -28,13 +42,15 @@ class Profiler extends EventEmitter {
 
   start (options) {
     return this._start(options).catch((err) => {
-      if (options.logger) {
-        options.logger.error(err)
-      }
+      logError(options.logger, err)
       return false
     })
   }
 
+  _logError (err) {
+    logError(this._logger, err)
+  }
+
   async _start (options) {
     if (this._enabled) return true
 
@@ -61,7 +77,7 @@ class Profiler extends EventEmitter {
         })
       }
     } catch (err) {
-      this._logger.error(err)
+      this._logError(err)
     }
 
     try {
@@ -78,7 +94,7 @@ class Profiler extends EventEmitter {
       this._capture(this._timeoutInterval, start)
       return true
     } catch (e) {
-      this._logger.error(e)
+      this._logError(e)
       this._stop()
       return false
     }
@@ -167,7 +183,7 @@ class Profiler extends EventEmitter {
       profileSubmittedChannel.publish()
       this._logger.debug('Submitted profiles')
     } catch (err) {
-      this._logger.error(err)
+      this._logError(err)
       this._stop()
     }
   }
@@ -182,7 +198,7 @@ class Profiler extends EventEmitter {
     tags.snapshot = snapshotKind
     for (const exporter of this._config.exporters) {
       const task = exporter.export({ profiles, start, end, tags })
-        .catch(err => this._logger.error(err))
+        .catch(err => this._logError(err))
 
       tasks.push(task)
     }

packages/dd-trace/src/proxy.js

@@ -14,6 +14,7 @@ const dogstatsd = require('./dogstatsd')
 const NoopDogStatsDClient = require('./noop/dogstatsd')
 const spanleak = require('./spanleak')
 const { SSITelemetry } = require('./profiling/ssi-telemetry')
+const telemetryLog = require('dc-polyfill').channel('datadog:telemetry:log')
 
 class LazyModule {
   constructor (provider) {
@@ -104,6 +105,11 @@ class Tracer extends NoopProxy {
           this._profilerStarted = profiler.start(config)
         } catch (e) {
           log.error(e)
+          telemetryLog.publish({
+            message: e.message,
+            level: 'ERROR',
+            stack_trace: e.stack
+          })
         }
       } else if (ssiTelemetry.enabled()) {
         require('./profiling/ssi-telemetry-mock-profiler').start(config)

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

@@ -1,6 +1,7 @@
 'use strict'
 
 const log = require('../../log')
+const { calculateDDBasePath } = require('../../util')
 
 const logs = new Map()
 
@@ -29,6 +30,37 @@ function isValid (logEntry) {
   return logEntry?.level && logEntry.message
 }
 
+const ddBasePath = calculateDDBasePath(__dirname)
+const EOL = '\n'
+const STACK_FRAME_LINE_REGEX = /^\s*at\s/gm
+
+function sanitize (logEntry) {
+  const stack = logEntry.stack_trace
+  if (!stack) return logEntry
+
+  let stackLines = stack.split(EOL)
+
+  const firstIndex = stackLines.findIndex(l => l.match(STACK_FRAME_LINE_REGEX))
+
+  const isDDCode = firstIndex > -1 && stackLines[firstIndex].includes(ddBasePath)
+  stackLines = stackLines
+    .filter((line, index) => (isDDCode && index < firstIndex) || line.includes(ddBasePath))
+    .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.
+    return null
+  }
+
+  if (!isDDCode) {
+    logEntry.message = 'omitted'
+  }
+
+  return logEntry
+}
+
 const logCollector = {
   add (logEntry) {
     try {
@@ -37,9 +69,13 @@ const logCollector = {
       // NOTE: should errors have higher priority? and discard log entries with lower priority?
       if (logs.size >= maxEntries) {
         overflowedCount++
-        return
+        return false
       }
 
+      logEntry = sanitize(logEntry)
+      if (!logEntry) {
+        return false
+      }
       const hash = createHash(logEntry)
       if (!logs.has(hash)) {
         logs.set(hash, logEntry)
@@ -51,6 +87,11 @@ const logCollector = {
     return false
   },
 
+  // Used for testing
+  hasEntry (logEntry) {
+    return logs.has(createHash(logEntry))
+  },
+
   drain () {
     if (logs.size === 0) return
 

packages/dd-trace/test/appsec/iast/iast-log.spec.js

@@ -1,9 +1,5 @@
 const { expect } = require('chai')
 const proxyquire = require('proxyquire')
-const { calculateDDBasePath } = require('../../../src/util')
-
-const ddBasePath = calculateDDBasePath(__dirname)
-const EOL = '\n'
 
 describe('IAST log', () => {
   let iastLog
@@ -98,56 +94,5 @@ describe('IAST log', () => {
       expect(log.error.getCall(2).args[0]).to.be.eq('error2')
       expect(telemetryLog.publish).to.be.calledOnceWith({ message: 'errorAndPublish', level: 'ERROR' })
     })
-
-    it('should include original message and dd frames', () => {
-      const ddFrame = `at T (${ddBasePath}packages/dd-trace/test/telemetry/logs/log_collector.spec.js:29:21)`
-      const stack = new Error('Error 1')
-        .stack.replace(`Error 1${EOL}`, `Error 1${EOL}${ddFrame}${EOL}`)
-
-      const ddFrames = stack
-        .split(EOL)
-        .filter(line => line.includes(ddBasePath))
-        .map(line => line.replace(ddBasePath, ''))
-
-      iastLog.errorAndPublish({ message: 'Error 1', stack })
-
-      expect(telemetryLog.publish).to.be.calledOnce
-      const log = telemetryLog.publish.getCall(0).args[0]
-
-      expect(log.message).to.be.eq('Error 1')
-      expect(log.level).to.be.eq('ERROR')
-
-      log.stack_trace.split(EOL).forEach((frame, index) => {
-        if (index !== 0) {
-          expect(ddFrames.indexOf(frame) !== -1).to.be.true
-        }
-      })
-    })
-
-    it('should not 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')
-        .stack.replace(`Error 1${EOL}`, `Error 1${EOL}${thirdPartyFrame}${EOL}`)
-
-      const ddFrames = stack
-        .split(EOL)
-        .filter(line => line.includes(ddBasePath))
-        .map(line => line.replace(ddBasePath, ''))
-
-      iastLog.errorAndPublish({ message: 'Error 1', stack })
-
-      expect(telemetryLog.publish).to.be.calledOnce
-
-      const log = telemetryLog.publish.getCall(0).args[0]
-      expect(log.message).to.be.eq('omitted')
-      expect(log.level).to.be.eq('ERROR')
-
-      log.stack_trace.split(EOL).forEach((frame, index) => {
-        if (index !== 0) {
-          expect(ddFrames.indexOf(frame) !== -1).to.be.true
-        }
-      })
-    })
   })
 })

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

@@ -5,6 +5,7 @@ require('../../setup/tap')
 const { calculateDDBasePath } = require('../../../src/util')
 
 const ddBasePath = calculateDDBasePath(__dirname)
+const EOL = '\n'
 
 describe('telemetry log collector', () => {
   const logCollector = require('../../../src/telemetry/logs/log-collector')
@@ -41,6 +42,46 @@ describe('telemetry log collector', () => {
       expect(logCollector.add({ message: 'Error 1', level: 'WARN', stack_trace: `stack 1\n${ddFrame}` })).to.be.true
       expect(logCollector.add({ message: 'Error 1', level: 'DEBUG', stack_trace: `stack 1\n${ddFrame}` })).to.be.true
     })
+
+    it('should include original message and dd frames', () => {
+      const ddFrame = `at T (${ddBasePath}packages/dd-trace/test/telemetry/logs/log_collector.spec.js:29:21)`
+      const stack = new Error('Error 1')
+        .stack.replace(`Error 1${EOL}`, `Error 1${EOL}${ddFrame}${EOL}`)
+
+      const ddFrames = stack
+        .split(EOL)
+        .filter(line => line.includes(ddBasePath))
+        .map(line => line.replace(ddBasePath, ''))
+        .join(EOL)
+
+      expect(logCollector.add({ message: 'Error 1', level: 'ERROR', stack_trace: stack })).to.be.true
+
+      expect(logCollector.hasEntry({
+        message: 'Error 1',
+        level: 'ERROR',
+        stack_trace: `Error: Error 1${EOL}${ddFrames}`
+      })).to.be.true
+    })
+
+    it('should not 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')
+        .stack.replace(`Error 1${EOL}`, `Error 1${EOL}${thirdPartyFrame}${EOL}`)
+
+      const ddFrames = stack
+        .split(EOL)
+        .filter(line => line.includes(ddBasePath))
+        .map(line => line.replace(ddBasePath, ''))
+        .join(EOL)
+
+      expect(logCollector.add({ message: 'Error 1', level: 'ERROR', stack_trace: stack })).to.be.true
+      expect(logCollector.hasEntry({
+        message: 'omitted',
+        level: 'ERROR',
+        stack_trace: ddFrames
+      })).to.be.true
+    })
   })
 
   describe('drain', () => {