newrelic is wiping message object when uses log forwarding with pinohttp #2595
Comments
|
The issue is at Basically, at that point {
"timestamp": 1726842894459,
"entity.name": "New Relic for Node.js tests",
"entity.type": "SERVICE",
"trace.id": "f68574cbbfd69beb2a3b52b59f250291",
"span.id": "4cd74b7072e6f440",
"message": undefined
}This is due to a misuse of the logger. As detailed in Pino's documentation (https://github.com/pinojs/pino/blob/0ab1bdd258acd00f82103206f385e4525010a8ff/docs/api.md#logging-method-parameters): // This is a simple merging object that does not have any
// properties interpreted by the logger:
logger.info({ message: 'whatever' })
// This "merging object" has a special property that
// correlates to the intended message to be logged.
logger.info({ msg: 'whatever' })
// This is equivalent to the previous line:
logger.info('whatever') |
|
@petermilan let's please reach a consensus about the nature of this before opening pull requests. We do not see this as a bug according to the given information. Please explain if you think otherwise, why. |
|
So the reason why I think it should be fixed is, that I would expect to see whatever log I see in the console, to see it in the newrelic. Fact that I see rendered message in console output of pino, and not in newrelic is very confusing - and was even hard to track down. Also the fact, that the message is visible in console feels, like they did not implemented console output behavior based on their documentation. |
|
Considering that the current behavior of the New Relic Node Agent reflects the documented behavior of the pino library, I wouldn't consider this a bug. It's best handled in application code, where pino's being used. |
|
I have the start of a reproduction if we decide to pick this up: issue-2595.test.js/*
* Copyright 2024 New Relic Corporation. All rights reserved.
* SPDX-License-Identifier: Apache-2.0
*/
'use strict'
const test = require('node:test')
const assert = require('node:assert')
const { Writable } = require('node:stream')
const helper = require('../../lib/agent_helper')
test('does not strip message property', (t, end) => {
const logs = []
const dest = new Writable({
write(chunk, encoding, callback) {
logs.push(JSON.parse(chunk.toString()))
callback()
}
})
const agent = helper.instrumentMockedAgent({
application_logging: {
forwarding: { enabled: true }
}
})
const pinoHttp = require('pino-http')
const { logger } = pinoHttp({ level: 'info' }, dest)
helper.runInTransaction(agent, (tx) => {
logger.info({ message: 'keep me', message2: 'me too' })
tx.end()
const agentLogs = agent.logs.getEvents()
assert.equal(agentLogs.length, 1, 'aggregator should have recorded log')
assert.equal(logs.length, 1, 'stream should have recorded one log')
// Verify the destination stream log has the expected properties.
assert.equal(logs[0].message, 'keep me')
assert.equal(logs[0].message2, 'me too')
const foundLog = agentLogs[0]()
// assert.equal(foundLog.message, 'keep me')
assert.equal(foundLog.message2, 'me too')
// The forwarded log should have all keys that were logged to the
// destination stream by Pino.
for (const key of Object.keys(logs[0])) {
assert.equal(Object.hasOwn(foundLog, key), true, `forwarded log should have key "${key}"`)
}
end()
})
})package.json{
"name": "pino-tests",
"targets": [{"name":"pino","minAgentVersion":"8.11.0"}],
"version": "0.0.0",
"private": true,
"tests": [
{
"engines": {
"node": ">=18"
},
"dependencies": {
"pino": ">=7.0.0",
"flush-write-stream": "2.0.0",
"split2": "4.1.0"
},
"files": [
"pino.tap.js"
]
},
{
"engines": {
"node": ">=18"
},
"dependencies": {
"pino": ">=7.0.0",
"pino-http": ">=10.3.0"
},
"files": [
"issue-2595.test.js"
]
}
]
} |
|
@petermilan when you issue |
|
@jsumners-nr tbh, I was not expecting I see your point with the documentation, so if you decide to close this based on documentation I am fine with it, however for me there would be stronger argument to not cause loss of data which is happening now stdout: (message field is message field) newrelic through log forwarding (message is lost) in my opinion log forwarding should mean that whole log will be forwarded as it is |
|
The catch is that, due to the name of the field in question, it is ambiguous about what should be done with it. I need to think more about this discussion. |
|
Thank you very much. I can fix this on my side by passing extra second argument in the logger, which will work. However I had lots of places in code relying on single object which worked in stdout, but when it came to need of debugging in newrelic I was blind, as the most important field was gone ... perhaps better name of ticket would be: It took me a while to figure out what is going on, and where the field is removed :) |
|
We have released a fix in https://github.com/newrelic/node-newrelic/releases/tag/v12.5.1 |
Description
if the logger sends just object with
messagefield, it is successfully logged through pinohttp into console, however the message is not present in forwarded log in newrelicExpected Behavior
Pino log should be in newrelic should be equal to the log in console (containing message field)
Steps to Reproduce
newrelic.js:
index.js
then run following CURL:
as result of
but in newrelic the message is not present:
as can be seen, log contains only
"message2": "foo bar",andmessageis missing.Your Environment
Additional context
It looks like somewhere in newrelic/instrumentation/pino - it is owerriding the message field in object using unexisting (optional) second parameter.
which results in empty message.
The text was updated successfully, but these errors were encountered: