Skip to content

Commit

Permalink
PROF-9722: Send profiler errors to the telemetry log (#4278)
Browse files Browse the repository at this point in the history
  • Loading branch information
@szegedi @khanayan123
szegedi authored and khanayan123 committed May 16, 2024
1 parent 0325725 commit 6ec5377
Show file tree
Hide file tree
Showing 7 changed files with 127 additions and 99 deletions.
35 changes: 2 additions & 33 deletions packages/dd-trace/src/appsec/iast/iast-log.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand All @@ -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)
Expand Down
16 changes: 13 additions & 3 deletions packages/dd-trace/src/config.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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,
Expand Down Expand Up @@ -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)
Expand Down Expand Up @@ -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)
Expand Down
30 changes: 23 additions & 7 deletions packages/dd-trace/src/profiling/profiler.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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')

Expand All @@ -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()
Expand All @@ -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

Expand All @@ -61,7 +77,7 @@ class Profiler extends EventEmitter {
})
}
} catch (err) {
this._logger.error(err)
this._logError(err)
}

try {
Expand All @@ -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
}
Expand Down Expand Up @@ -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()
}
}
Expand All @@ -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)
}
Expand Down
6 changes: 6 additions & 0 deletions packages/dd-trace/src/proxy.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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) {
Expand Down Expand Up @@ -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)
Expand Down
43 changes: 42 additions & 1 deletion packages/dd-trace/src/telemetry/logs/log-collector.js
View file
Original file line number Diff line number Diff line change
@@ -1,6 +1,7 @@
'use strict'

const log = require('../../log')
const { calculateDDBasePath } = require('../../util')

const logs = new Map()

Expand Down Expand Up @@ -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 {
Expand All @@ -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)
Expand All @@ -51,6 +87,11 @@ const logCollector = {
return false
},

// Used for testing
hasEntry (logEntry) {
return logs.has(createHash(logEntry))
},

drain () {
if (logs.size === 0) return

Expand Down
55 changes: 0 additions & 55 deletions packages/dd-trace/test/appsec/iast/iast-log.spec.js
View file
Original file line number Diff line number Diff line change
@@ -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
Expand Down Expand Up @@ -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
}
})
})
})
})
41 changes: 41 additions & 0 deletions packages/dd-trace/test/telemetry/logs/log-collector.spec.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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')
Expand Down Expand Up @@ -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', () => {
Expand Down

0 comments on commit 6ec5377

Please sign in to comment.