From c6c3ac90767e2c1f1ed648bbad329078fab2df6f Mon Sep 17 00:00:00 2001 From: James Sumners Date: Thu, 1 Aug 2024 09:37:19 -0400 Subject: [PATCH 1/2] fix: Pick log message from merging object in Pino instrumentation --- lib/instrumentation/pino/pino.js | 13 +++++++++++-- test/versioned/pino/pino.tap.js | 31 ++++++++++++++++++++++++++++++- 2 files changed, 41 insertions(+), 3 deletions(-) diff --git a/lib/instrumentation/pino/pino.js b/lib/instrumentation/pino/pino.js index 99df433c47..1b5512fde6 100644 --- a/lib/instrumentation/pino/pino.js +++ b/lib/instrumentation/pino/pino.js @@ -15,6 +15,7 @@ const { } = require('../../util/application-logging') const semver = require('semver') +// eslint-disable-next-line sonarjs/cognitive-complexity module.exports = function instrument(shim, tools) { const pinoVersion = shim.pkgVersion @@ -50,13 +51,21 @@ module.exports = function instrument(shim, tools) { return function wrappedAsJson() { const args = shim.argsToArray.apply(shim, arguments) const level = this?.levels?.labels?.[args[2]] + // Pino log methods accept a singular object (a merging object) that can + // have a `msg` property for the log message. In such cases, we need to + // update that log property instead of the second parameter. + const useMergeObj = args[1] === undefined && Object.hasOwn(args[0], 'msg') if (isMetricsEnabled(config)) { incrementLoggingLinesMetrics(level, metrics) } if (isLocalDecoratingEnabled(config)) { - args[1] += agent.getNRLinkingMetadata() + if (useMergeObj === true) { + args[0].msg += agent.getNRLinkingMetadata() + } else { + args[1] += agent.getNRLinkingMetadata() + } } /** @@ -69,7 +78,7 @@ module.exports = function instrument(shim, tools) { if (isLogForwardingEnabled(config, agent)) { const chindings = this[symbols.chindingsSym] const formatLogLine = reformatLogLine({ - msg: args[1], + msg: useMergeObj === true ? args[0].msg : args[1], logLine, agent, chindings, diff --git a/test/versioned/pino/pino.tap.js b/test/versioned/pino/pino.tap.js index af7537fc8d..e4d4d2ad1b 100644 --- a/test/versioned/pino/pino.tap.js +++ b/test/versioned/pino/pino.tap.js @@ -83,7 +83,7 @@ tap.test('Pino instrumentation', (t) => { const message = 'pino decorating test' helper.runInTransaction(agent, 'pino-test', async () => { logger.info(message) - const line = await once(stream, 'data') + let line = await once(stream, 'data') originalMsgAssertion({ t, includeLocalDecorating: true, @@ -91,6 +91,20 @@ tap.test('Pino instrumentation', (t) => { logLine: line }) t.same(agent.logs.getEvents(), [], 'should not add any logs to log aggregator') + + // Verify that merging object only logs get decorated: + logger.info({ msg: message }) + line = await once(stream, 'data') + console.log(line) + t.equal(line.msg.startsWith(`${message} NR-LINKING|test-guid`), true) + originalMsgAssertion({ + t, + includeLocalDecorating: true, + hostname: agent.config.getHostnameSafe(), + logLine: line + }) + t.same(agent.logs.getEvents(), [], 'should not add any logs to log aggregator') + t.end() }) }) @@ -375,4 +389,19 @@ tap.test('Pino instrumentation', (t) => { }) }) }) + + t.test('should honor msg key in merging object (issue 2410)', async (t) => { + t.context.config = setupAgent(t.context, { application_logging: { enabled: true } }) + const { agent, config, pino } = t.context + const localStream = sink() + const localLogger = pino({ base: undefined }, localStream) + const message = 'pino unit test' + const level = 'info' + localLogger[level]({ msg: message }) + await once(localStream, 'data') + t.equal(agent.logs.getEvents().length, 1, 'should have 1 log in aggregator') + const formattedLine = agent.logs.getEvents()[0]() + t.validateAnnotations({ line: formattedLine, message, level, config }) + t.end() + }) }) From d424589cac1d2e48f27128b943ebb594916818a2 Mon Sep 17 00:00:00 2001 From: James Sumners Date: Thu, 1 Aug 2024 12:29:09 -0400 Subject: [PATCH 2/2] address feedback --- test/versioned/pino/pino.tap.js | 1 - 1 file changed, 1 deletion(-) diff --git a/test/versioned/pino/pino.tap.js b/test/versioned/pino/pino.tap.js index e4d4d2ad1b..88ea70637b 100644 --- a/test/versioned/pino/pino.tap.js +++ b/test/versioned/pino/pino.tap.js @@ -95,7 +95,6 @@ tap.test('Pino instrumentation', (t) => { // Verify that merging object only logs get decorated: logger.info({ msg: message }) line = await once(stream, 'data') - console.log(line) t.equal(line.msg.startsWith(`${message} NR-LINKING|test-guid`), true) originalMsgAssertion({ t,