diff --git a/packages/dd-trace/src/appsec/iast/iast-log.js b/packages/dd-trace/src/appsec/iast/iast-log.js index 25b33c3bf44..95154d89452 100644 --- a/packages/dd-trace/src/appsec/iast/iast-log.js +++ b/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) diff --git a/packages/dd-trace/src/config.js b/packages/dd-trace/src/config.js index 198f546afd3..ae890f688c5 100644 --- a/packages/dd-trace/src/config.js +++ b/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) diff --git a/packages/dd-trace/src/profiling/profiler.js b/packages/dd-trace/src/profiling/profiler.js index 66432480a35..2c0ebcd5584 100644 --- a/packages/dd-trace/src/profiling/profiler.js +++ b/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) } diff --git a/packages/dd-trace/src/proxy.js b/packages/dd-trace/src/proxy.js index 1f2e5e119a2..98401a1769f 100644 --- a/packages/dd-trace/src/proxy.js +++ b/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) diff --git a/packages/dd-trace/src/telemetry/logs/log-collector.js b/packages/dd-trace/src/telemetry/logs/log-collector.js index 740f5453797..182842fc4c4 100644 --- a/packages/dd-trace/src/telemetry/logs/log-collector.js +++ b/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 diff --git a/packages/dd-trace/test/appsec/iast/iast-log.spec.js b/packages/dd-trace/test/appsec/iast/iast-log.spec.js index b04dbec0faa..47d8fb7e728 100644 --- a/packages/dd-trace/test/appsec/iast/iast-log.spec.js +++ b/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 - } - }) - }) }) }) 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 57f634db2ef..168378a2251 100644 --- a/packages/dd-trace/test/telemetry/logs/log-collector.spec.js +++ b/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', () => {