Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

fix: Pick log message from merging object in Pino instrumentation #2421

Merged
merged 2 commits into from
Aug 1, 2024
Merged

fix: Pick log message from merging object in Pino instrumentation #2421

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
c6c3ac9
fix: Pick log message from merging object in Pino instrumentation
jsumners-nr Aug 1, 2024
d424589
address feedback
jsumners-nr Aug 1, 2024
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
13 changes: 11 additions & 2 deletions lib/instrumentation/pino/pino.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -15,6 +15,7 @@ const {
} = require('../../util/application-logging')
const semver = require('semver')

// eslint-disable-next-line sonarjs/cognitive-complexity
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The intent is to refactor code and not ignore these.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

There are a lot of enclosed variables and the function itself uses the Pino instance for this. I think any refactor is going to be more difficult to reason through. Also, what is this rule doing to determine complexity?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

In this particular case, the rule is saying the instrument(shim, tools) function has exceeded the threshold and that function has not been modified. The thing that was modified was an enclosed function: wrappedAsJson. The two should be considered separately, but it seems the tool is unable to distinguish between the two.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It's based mostly on nesting functions. you can read more about it here. we can defer but can you file a ticket to address?

module.exports = function instrument(shim, tools) {
const pinoVersion = shim.pkgVersion

Expand Down Expand Up @@ -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()
}
}

/**
Expand All @@ -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,
Expand Down
30 changes: 29 additions & 1 deletion test/versioned/pino/pino.tap.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -83,14 +83,27 @@ 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,
hostname: agent.config.getHostnameSafe(),
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')
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()
})
})
Expand Down Expand Up @@ -375,4 +388,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()
})
})
Loading