From b54a97fc1be26a562e1fa5b80428d103d25cfdf9 Mon Sep 17 00:00:00 2001 From: Bob Evans Date: Wed, 31 Jan 2024 08:47:59 -0500 Subject: [PATCH] fix: Updated winston instrumentation to wrap configure to properly retain our transporter to do log forwarding (#1987) --- lib/instrumentation/winston.js | 48 ++++++++++++++- test/versioned/winston/winston.tap.js | 85 +++++++++++++++++++++++++++ 2 files changed, 131 insertions(+), 2 deletions(-) diff --git a/lib/instrumentation/winston.js b/lib/instrumentation/winston.js index adb1e87872..cae9466262 100644 --- a/lib/instrumentation/winston.js +++ b/lib/instrumentation/winston.js @@ -29,7 +29,8 @@ module.exports = function instrument(agent, winston, _, shim) { shim.wrap(winston, 'createLogger', function wrapCreate(shim, createLogger) { return function wrappedCreateLogger() { const args = shim.argsToArray.apply(shim, arguments) - const opts = args[0] || {} + // re-assign the first arg to an object if does not exist so we can assign the default formatter + const opts = (args[0] = args[0] || {}) if (isStream(opts)) { return createLogger.apply(this, args) } @@ -39,6 +40,7 @@ module.exports = function instrument(agent, winston, _, shim) { opts, agent, winston, + shim, registerLogger: createLogger }) } @@ -61,13 +63,29 @@ module.exports = function instrument(agent, winston, _, shim) { opts, agent, winston, + shim, registerLogger: add }) } }) } -function performInstrumentation({ obj, args, opts, agent, winston, registerLogger }) { +/** + * Does the necessary instrumentation depending on application_logging configuration. + * It will register a formatter to track metrics or decorate message in formatter(if local log decoration) + * and register a transport do to the log fowarding + * + * @param {object} params object passed to function + * @param {object} params.obj instance of winston logger + * @param {Array} params.args arguments passed to the logger creation method(createLogger or logger.add) + * @param {object} params.opts the logger options argument + * @param {Agent} params.agent NR instance + * @param {object} params.winston the winston export + * @param {Shim} params.shim shim instance + * @param {Function} params.registerLogger the function to create winston logger + * @returns {object} the winston logger instance with relevant instrumentation + */ +function performInstrumentation({ obj, args, opts, agent, winston, shim, registerLogger }) { const config = agent.config createModuleUsageMetric('winston', agent.metrics) @@ -80,11 +98,37 @@ function performInstrumentation({ obj, args, opts, agent, winston, registerLogge if (isLogForwardingEnabled(config, agent)) { winstonLogger.add(new NrTransport({ agent })) + wrapConfigure({ shim, winstonLogger, agent }) } return winstonLogger } +/** + * Wraps logger.configure and checks the transports key in the arguments and adds the NrTransport as + * it will get cleared in configure. + * + * @param {object} params object passed to function + * @param {object} params.shim shim instance + * @param {object} params.winstonLogger instance of logger + * @param {object} params.agent NR agent + */ +function wrapConfigure({ shim, winstonLogger, agent }) { + shim.wrap(winstonLogger, 'configure', function nrConfigure(shim, configure) { + return function wrappedConfigure() { + const args = shim.argsToArray.apply(shim, arguments) + const transportsArg = args?.[0]?.transports + if (this.transports.length) { + const nrTransport = new NrTransport({ agent }) + args[0].transports = Array.isArray(transportsArg) + ? [...transportsArg, nrTransport] + : nrTransport + } + return configure.apply(this, args) + } + }) +} + /** * Apply a formatter to keep track of logging metrics, and in the case of local decorating appending * the NR-LINKING metadata to message. We want to do this first so any formatter that is transforming diff --git a/test/versioned/winston/winston.tap.js b/test/versioned/winston/winston.tap.js index 9dd5ddb630..63e89a4aac 100644 --- a/test/versioned/winston/winston.tap.js +++ b/test/versioned/winston/winston.tap.js @@ -267,6 +267,34 @@ tap.test('winston instrumentation', (t) => { logWithAggregator({ logger, stream: jsonStream, t, helper, agent }) }) + t.test('should add linking metadata when using logger.configure', (t) => { + const handleMessages = makeStreamTest(() => { + const msgs = agent.logs.getEvents() + t.equal(msgs.length, 2, 'should add both logs to aggregator') + msgs.forEach((msg) => { + logForwardingMsgAssertion(t, msg, agent) + t.ok(msg.original_timestamp, 'should put customer timestamp on original_timestamp') + }) + t.end() + }) + const assertFn = originalMsgAssertion.bind(null, { t, timestamp: true }) + const jsonStream = concat(handleMessages(assertFn)) + // Example Winston setup to test + const logger = winston.createLogger() + logger.configure({ + format: winston.format.timestamp('YYYY-MM-DD HH:mm:ss'), + transports: [ + // Log to a stream so we can test the output + new winston.transports.Stream({ + level: 'info', + stream: jsonStream + }) + ] + }) + + logWithAggregator({ logger, stream: jsonStream, t, helper, agent }) + }) + t.test('should properly reformat errors on msgs to log aggregator', (t) => { const name = 'TestError' const errorMsg = 'throw uncaught exception test' @@ -519,6 +547,63 @@ tap.test('winston instrumentation', (t) => { }) } + t.test(`should count logger metrics for logger.configure`, (t) => { + setup({ + application_logging: { + enabled: true, + metrics: { + enabled: true + }, + forwarding: { enabled: false }, + local_decorating: { enabled: false } + } + }) + + const logger = winston.createLogger() + logger.configure({ + transports: [ + new winston.transports.Stream({ + level: 'debug', + // We don't care about the output for this test, just + // total lines logged + stream: nullStream + }) + ] + }) + + helper.runInTransaction(agent, 'winston-test', () => { + const logLevels = { + debug: 20, + info: 5, + warn: 3, + error: 2 + } + for (const [logLevel, maxCount] of Object.entries(logLevels)) { + for (let count = 0; count < maxCount; count++) { + const msg = `This is log message #${count} at ${logLevel} level` + logger[logLevel](msg) + } + } + + // Close the stream so that the logging calls are complete + nullStream.end() + + let grandTotal = 0 + for (const [logLevel, maxCount] of Object.entries(logLevels)) { + grandTotal += maxCount + const metricName = LOGGING.LEVELS[logLevel.toUpperCase()] + const metric = agent.metrics.getMetric(metricName) + t.ok(metric, `ensure ${metricName} exists`) + t.equal(metric.callCount, maxCount, `ensure ${metricName} has the right value`) + } + const metricName = LOGGING.LINES + const metric = agent.metrics.getMetric(metricName) + t.ok(metric, `ensure ${metricName} exists`) + t.equal(metric.callCount, grandTotal, `ensure ${metricName} has the right value`) + t.end() + }) + }) + const configValues = [ { name: 'application_logging is not enabled',