diff --git a/packages/dd-trace/src/flare/file.js b/packages/dd-trace/src/flare/file.js new file mode 100644 index 00000000000..00388e14c5b --- /dev/null +++ b/packages/dd-trace/src/flare/file.js @@ -0,0 +1,44 @@ +'use strict' + +const { Writable } = require('stream') + +const INITIAL_SIZE = 64 * 1024 + +class FlareFile extends Writable { + constructor () { + super() + + this.length = 0 + + this._buffer = Buffer.alloc(INITIAL_SIZE) + } + + get data () { + return this._buffer.subarray(0, this.length) + } + + _write (chunk, encoding, callback) { + const length = Buffer.byteLength(chunk) + + this._reserve(length) + + if (Buffer.isBuffer(chunk)) { + this.length += chunk.copy(this._buffer, this.length) + } else { + this.length += this._buffer.write(chunk, encoding) + } + + callback() + } + + _reserve (length) { + while (this.length + length > this._buffer.length) { + const buffer = Buffer.alloc(this.length * 2) + + this._buffer.copy(buffer) + this._buffer = buffer + } + } +} + +module.exports = FlareFile diff --git a/packages/dd-trace/src/flare/index.js b/packages/dd-trace/src/flare/index.js new file mode 100644 index 00000000000..70ec4ccd75e --- /dev/null +++ b/packages/dd-trace/src/flare/index.js @@ -0,0 +1,98 @@ +'use strict' + +const log = require('../log') +const startupLog = require('../startup-log') +const FlareFile = require('./file') +const { LogChannel } = require('../log/channels') +const request = require('../exporters/common/request') +const FormData = require('../exporters/common/form-data') + +const MAX_LOG_SIZE = 12 * 1024 * 1024 // 12MB soft limit +const TIMEOUT = 20 * 1000 * 60 + +let logChannel = null +let tracerLogs = null +let timer +let tracerConfig = null + +const logger = { + debug: (msg) => recordLog(msg), + info: (msg) => recordLog(msg), + warn: (msg) => recordLog(msg), + error: (err) => recordLog(err.stack) +} + +const flare = { + enable (tracerConfig_) { + tracerConfig = tracerConfig_ + }, + + disable () { + tracerConfig = null + + flare.cleanup() + }, + + prepare (logLevel) { + if (!tracerConfig) return + + logChannel?.unsubscribe(logger) + logChannel = new LogChannel(logLevel) + logChannel.subscribe(logger) + tracerLogs = tracerLogs || new FlareFile() + timer = timer || setTimeout(flare.cleanup, TIMEOUT) + }, + + send (task) { + if (!tracerConfig) return + + const tracerInfo = new FlareFile() + + tracerInfo.write(JSON.stringify(startupLog.tracerInfo(), null, 2)) + + flare._sendFile(task, tracerInfo, 'tracer_info.txt') + flare._sendFile(task, tracerLogs, 'tracer_logs.txt') + + flare.cleanup() + }, + + cleanup () { + logChannel?.unsubscribe(logger) + timer = clearTimeout(timer) + logChannel = null + tracerLogs = null + }, + + _sendFile (task, file, filename) { + if (!file) return + + const form = new FormData() + + form.append('case_id', task.case_id) + form.append('hostname', task.hostname) + form.append('email', task.user_handle) + form.append('source', 'tracer_nodejs') + form.append('flare_file', file.data, { filename }) + + request(form, { + url: tracerConfig.url, + hostname: tracerConfig.hostname, + port: tracerConfig.port, + method: 'POST', + path: '/tracer_flare/v1', + headers: form.getHeaders() + }, (err) => { + if (err) { + log.error(err) + } + }) + } +} + +function recordLog (msg) { + if (tracerLogs.length > MAX_LOG_SIZE) return + + tracerLogs.write(`${msg}\n`) // TODO: gzip +} + +module.exports = flare diff --git a/packages/dd-trace/src/log/channels.js b/packages/dd-trace/src/log/channels.js index 0bf84871b34..545fef4195a 100644 --- a/packages/dd-trace/src/log/channels.js +++ b/packages/dd-trace/src/log/channels.js @@ -3,44 +3,69 @@ const { channel } = require('dc-polyfill') const Level = { - Debug: 'debug', - Info: 'info', - Warn: 'warn', - Error: 'error' + trace: 20, + debug: 20, + info: 30, + warn: 40, + error: 50, + critical: 50, + off: 100 } -const defaultLevel = Level.Debug +const debugChannel = channel('datadog:log:debug') +const infoChannel = channel('datadog:log:info') +const warnChannel = channel('datadog:log:warn') +const errorChannel = channel('datadog:log:error') -// based on: https://github.com/trentm/node-bunyan#levels -const logChannels = { - [Level.Debug]: createLogChannel(Level.Debug, 20), - [Level.Info]: createLogChannel(Level.Info, 30), - [Level.Warn]: createLogChannel(Level.Warn, 40), - [Level.Error]: createLogChannel(Level.Error, 50) -} +const defaultLevel = Level.debug -function createLogChannel (name, logLevel) { - const logChannel = channel(`datadog:log:${name}`) - logChannel.logLevel = logLevel - return logChannel +function getChannelLogLevel (level) { + return level && typeof level === 'string' + ? Level[level.toLowerCase().trim()] || defaultLevel + : defaultLevel } -function getChannelLogLevel (level) { - let logChannel - if (level && typeof level === 'string') { - logChannel = logChannels[level.toLowerCase().trim()] || logChannels[defaultLevel] - } else { - logChannel = logChannels[defaultLevel] +class LogChannel { + constructor (level) { + this._level = getChannelLogLevel(level) + } + + subscribe (logger) { + if (Level.debug >= this._level) { + debugChannel.subscribe(logger.debug) + } + if (Level.info >= this._level) { + infoChannel.subscribe(logger.info) + } + if (Level.warn >= this._level) { + warnChannel.subscribe(logger.warn) + } + if (Level.error >= this._level) { + errorChannel.subscribe(logger.error) + } + } + + unsubscribe (logger) { + if (debugChannel.hasSubscribers) { + debugChannel.unsubscribe(logger.debug) + } + if (infoChannel.hasSubscribers) { + infoChannel.unsubscribe(logger.info) + } + if (warnChannel.hasSubscribers) { + warnChannel.unsubscribe(logger.warn) + } + if (errorChannel.hasSubscribers) { + errorChannel.unsubscribe(logger.error) + } } - return logChannel.logLevel } module.exports = { - Level, - getChannelLogLevel, + LogChannel, - debugChannel: logChannels[Level.Debug], - infoChannel: logChannels[Level.Info], - warnChannel: logChannels[Level.Warn], - errorChannel: logChannels[Level.Error] + debugChannel, + infoChannel, + warnChannel, + errorChannel } diff --git a/packages/dd-trace/src/log/writer.js b/packages/dd-trace/src/log/writer.js index 798d6269f14..bc4a5b20621 100644 --- a/packages/dd-trace/src/log/writer.js +++ b/packages/dd-trace/src/log/writer.js @@ -1,8 +1,7 @@ 'use strict' const { storage } = require('../../../datadog-core') -const { getChannelLogLevel, debugChannel, infoChannel, warnChannel, errorChannel } = require('./channels') - +const { LogChannel } = require('./channels') const defaultLogger = { debug: msg => console.debug(msg), /* eslint-disable-line no-console */ info: msg => console.info(msg), /* eslint-disable-line no-console */ @@ -12,7 +11,7 @@ const defaultLogger = { let enabled = false let logger = defaultLogger -let logLevel = getChannelLogLevel() +let logChannel = new LogChannel() function withNoop (fn) { const store = storage.getStore() @@ -23,45 +22,21 @@ function withNoop (fn) { } function unsubscribeAll () { - if (debugChannel.hasSubscribers) { - debugChannel.unsubscribe(onDebug) - } - if (infoChannel.hasSubscribers) { - infoChannel.unsubscribe(onInfo) - } - if (warnChannel.hasSubscribers) { - warnChannel.unsubscribe(onWarn) - } - if (errorChannel.hasSubscribers) { - errorChannel.unsubscribe(onError) - } + logChannel.unsubscribe({ debug, info, warn, error }) } -function toggleSubscription (enable) { +function toggleSubscription (enable, level) { unsubscribeAll() if (enable) { - if (debugChannel.logLevel >= logLevel) { - debugChannel.subscribe(onDebug) - } - if (infoChannel.logLevel >= logLevel) { - infoChannel.subscribe(onInfo) - } - if (warnChannel.logLevel >= logLevel) { - warnChannel.subscribe(onWarn) - } - if (errorChannel.logLevel >= logLevel) { - errorChannel.subscribe(onError) - } + logChannel = new LogChannel(level) + logChannel.subscribe({ debug, info, warn, error }) } } function toggle (enable, level) { - if (level !== undefined) { - logLevel = getChannelLogLevel(level) - } enabled = enable - toggleSubscription(enabled) + toggleSubscription(enabled, level) } function use (newLogger) { @@ -73,26 +48,9 @@ function use (newLogger) { function reset () { logger = defaultLogger enabled = false - logLevel = getChannelLogLevel() toggleSubscription(false) } -function onError (err) { - if (enabled) error(err) -} - -function onWarn (message) { - if (enabled) warn(message) -} - -function onInfo (message) { - if (enabled) info(message) -} - -function onDebug (message) { - if (enabled) debug(message) -} - function error (err) { if (typeof err !== 'object' || !err) { err = String(err) diff --git a/packages/dd-trace/src/proxy.js b/packages/dd-trace/src/proxy.js index 7d47b059142..025fac51675 100644 --- a/packages/dd-trace/src/proxy.js +++ b/packages/dd-trace/src/proxy.js @@ -40,6 +40,7 @@ class Tracer extends NoopProxy { this._pluginManager = new PluginManager(this) this.dogstatsd = new NoopDogStatsDClient() this._tracingInitialized = false + this._flare = new LazyModule(() => require('./flare')) // these requires must work with esm bundler this._modules = { @@ -90,6 +91,25 @@ class Tracer extends NoopProxy { } this._enableOrDisableTracing(config) }) + + rc.on('AGENT_CONFIG', (action, conf) => { + if (!conf?.name?.startsWith('flare-log-level.')) return + + if (action === 'unapply') { + this._flare.disable() + } else if (conf.config?.log_level) { + this._flare.enable(config) + this._flare.module.prepare(conf.config.log_level) + } + }) + + rc.on('AGENT_TASK', (action, conf) => { + if (action === 'unapply' || !conf) return + if (conf.task_type !== 'tracer_flare' || !conf.args) return + + this._flare.enable(config) + this._flare.module.send(conf.args) + }) } if (config.isGCPFunction || config.isAzureFunction) { diff --git a/packages/dd-trace/src/startup-log.js b/packages/dd-trace/src/startup-log.js index af3aa858476..12086ae1168 100644 --- a/packages/dd-trace/src/startup-log.js +++ b/packages/dd-trace/src/startup-log.js @@ -37,6 +37,23 @@ function startupLog ({ agentError } = {}) { return } + const out = tracerInfo({ agentError }) + + if (agentError) { + out.agent_error = agentError.message + } + + info('DATADOG TRACER CONFIGURATION - ' + out) + if (agentError) { + warn('DATADOG TRACER DIAGNOSTIC - Agent Error: ' + agentError.message) + errors.agentError = { + code: agentError.code ? agentError.code : '', + message: `Agent Error:${agentError.message}` + } + } +} + +function tracerInfo () { const url = config.url || `http://${config.hostname || 'localhost'}:${config.port}` const out = { @@ -59,9 +76,6 @@ function startupLog ({ agentError } = {}) { out.enabled = config.enabled out.service = config.service out.agent_url = url - if (agentError) { - out.agent_error = agentError.message - } out.debug = !!config.debug out.sample_rate = config.sampler.sampleRate out.sampling_rules = samplingRules @@ -87,18 +101,7 @@ function startupLog ({ agentError } = {}) { // out.service_mapping // out.service_mapping_error - info('DATADOG TRACER CONFIGURATION - ' + out) - if (agentError) { - warn('DATADOG TRACER DIAGNOSTIC - Agent Error: ' + agentError.message) - errors.agentError = { - code: agentError.code ? agentError.code : '', - message: `Agent Error:${agentError.message}` - } - } - - config = undefined - pluginManager = undefined - samplingRules = undefined + return out } function setStartupLogConfig (aConfig) { @@ -118,5 +121,6 @@ module.exports = { setStartupLogConfig, setStartupLogPluginManager, setSamplingRules, + tracerInfo, errors } diff --git a/packages/dd-trace/test/flare.spec.js b/packages/dd-trace/test/flare.spec.js new file mode 100644 index 00000000000..ac4133cd9e9 --- /dev/null +++ b/packages/dd-trace/test/flare.spec.js @@ -0,0 +1,161 @@ +'use strict' + +const Config = require('../src/config') +const { channel } = require('dc-polyfill') +const express = require('express') +const getPort = require('get-port') +const http = require('http') +const upload = require('multer')() +const proxyquire = require('proxyquire').noCallThru() + +require('./setup/tap') + +const debugChannel = channel('datadog:log:debug') + +describe('Flare', () => { + let flare + let startupLog + let tracerConfig + let task + let port + let server + let listener + let socket + let handler + + const createServer = () => { + const app = express() + + app.post('/tracer_flare/v1', upload.any(), (req, res) => { + res.sendStatus(200) + handler(req) + }) + + server = http.createServer(app) + server.on('connection', socket_ => { + socket = socket_ + }) + + listener = server.listen(port) + } + + beforeEach(() => { + startupLog = { + tracerInfo: () => ({ + lang: 'nodejs' + }) + } + + flare = proxyquire('../src/flare', { + '../startup-log': startupLog + }) + + return getPort().then(port_ => { + port = port_ + }) + }) + + beforeEach(() => { + tracerConfig = new Config({ + url: `http://127.0.0.1:${port}` + }) + + task = { + case_id: '111', + hostname: 'myhostname', + user_handle: 'user.name@datadoghq.com' + } + + createServer() + }) + + afterEach(done => { + handler = null + flare.disable() + listener.close() + socket && socket.end() + server.on('close', () => { + server = null + listener = null + socket = null + + done() + }) + }) + + it('should send a flare', done => { + handler = req => { + try { + expect(req.body).to.include({ + case_id: task.case_id, + hostname: task.hostname, + email: task.user_handle, + source: 'tracer_nodejs' + }) + + done() + } catch (e) { + done(e) + } + } + + flare.enable(tracerConfig) + flare.send(task) + }) + + it('should send the tracer info', done => { + handler = req => { + try { + expect(req.files).to.have.length(1) + expect(req.files[0]).to.include({ + fieldname: 'flare_file', + originalname: 'tracer_info.txt', + mimetype: 'application/octet-stream' + }) + + const content = JSON.parse(req.files[0].buffer.toString()) + + expect(content).to.have.property('lang', 'nodejs') + + done() + } catch (e) { + done(e) + } + } + + flare.enable(tracerConfig) + flare.send(task) + }) + + it('should send the tracer logs', done => { + handler = req => { + try { + const file = req.files[0] + + if (file.originalname !== 'tracer_logs.txt') return + + expect(file).to.include({ + fieldname: 'flare_file', + originalname: 'tracer_logs.txt', + mimetype: 'application/octet-stream' + }) + + const content = file.buffer.toString() + + expect(content).to.equal('foo\nbar\n') + + done() + } catch (e) { + done(e) + } + } + + flare.enable(tracerConfig) + flare.prepare('debug') + + debugChannel.publish('foo') + debugChannel.publish('bar') + + flare.send(task) + }) +}) diff --git a/packages/dd-trace/test/proxy.spec.js b/packages/dd-trace/test/proxy.spec.js index 3bfef7474b3..07fcd41eca6 100644 --- a/packages/dd-trace/test/proxy.spec.js +++ b/packages/dd-trace/test/proxy.spec.js @@ -26,6 +26,7 @@ describe('TracerProxy', () => { let iast let PluginManager let pluginManager + let flare let remoteConfig let rc let dogStatsD @@ -156,6 +157,14 @@ describe('TracerProxy', () => { disable: sinon.spy() } + flare = { + enable: sinon.spy(), + disable: sinon.spy(), + prepare: sinon.spy(), + send: sinon.spy(), + cleanup: sinon.spy() + } + remoteConfig = { enable: sinon.stub() } @@ -184,7 +193,8 @@ describe('TracerProxy', () => { './appsec/remote_config': remoteConfig, './appsec/sdk': AppsecSdk, './dogstatsd': dogStatsD, - './noop/dogstatsd': NoopDogStatsDClient + './noop/dogstatsd': NoopDogStatsDClient, + './flare': flare }) proxy = new Proxy() @@ -249,6 +259,57 @@ describe('TracerProxy', () => { expect(pluginManager.configure).to.have.been.calledWith(config) }) + it('should support enabling debug logs for tracer flares', () => { + const logLevel = 'debug' + + proxy.init() + + rc.emit('AGENT_CONFIG', 'apply', { + config: { + log_level: logLevel + }, + name: 'flare-log-level.debug' + }) + + expect(flare.enable).to.have.been.calledWith(config) + expect(flare.prepare).to.have.been.calledWith(logLevel) + }) + + it('should support sending tracer flares', () => { + const task = { + case_id: '111', + hostname: 'myhostname', + user_handle: 'user.name@datadoghq.com' + } + + proxy.init() + + rc.emit('AGENT_TASK', 'apply', { + args: task, + task_type: 'tracer_flare', + uuid: 'd53fc8a4-8820-47a2-aa7d-d565582feb81' + }) + + expect(flare.enable).to.have.been.calledWith(config) + expect(flare.send).to.have.been.calledWith(task) + }) + + it('should cleanup flares when the config is removed', () => { + const conf = { + config: { + log_level: 'debug' + }, + name: 'flare-log-level.debug' + } + + proxy.init() + + rc.emit('AGENT_CONFIG', 'apply', conf) + rc.emit('AGENT_CONFIG', 'unapply', conf) + + expect(flare.disable).to.have.been.called + }) + it('should support applying remote config', () => { const RemoteConfigProxy = proxyquire('../src/proxy', { './tracer': DatadogTracer,