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.

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

newrelic is wiping message object when uses log forwarding with pinohttp #2595

Closed
petermilan opened this issue Sep 20, 2024 · 11 comments · Fixed by #2600
Closed

newrelic is wiping message object when uses log forwarding with pinohttp #2595

petermilan opened this issue Sep 20, 2024 · 11 comments · Fixed by #2600

Comments

@petermilan
Copy link

petermilan commented Sep 20, 2024

Description

if the logger sends just object with message field, it is successfully logged through pinohttp into console, however the message is not present in forwarded log in newrelic

Expected Behavior

Pino log should be in newrelic should be equal to the log in console (containing message field)

Steps to Reproduce

newrelic.js:

exports.config = {
  app_name: 'Test newrelic pino',
  license_key: 'REDACTED',
  application_logging: {
    forwarding: {
      enabled: true,
      max_samples_stored: 10000,
    },
  },
};

index.js

require('newrelic');
const express = require('express');
const logger = require('pino-http');

const app = express();

app.use(logger());


app.get('/', (req, res) => {
  req.log.info({
    message: 'Test message',
    message2: 'foo bar',
  });
  res.end('hello world')
})
app.listen(3000)

then run following CURL:

curl --request GET \
  --url http://localhost:3000/ \
  --header 'User-Agent: insomnia/10.0.0'

as result of

  req.log.info({
    message: 'Test message',
    message2: 'foo bar',
  });
  • console will contain following log:
image
{"level":30,"time":1726833856289,"pid":2225,"hostname":"REDACTED","req":{"id":4,"method":"GET","url":"/","query":{},"params":{},"headers":{"host":"localhost:3000","cookie":"x-ms-gateway-slice=estsfd; stsservicecookie=estsfd","user-agent":"insomnia/10.0.0","accept":"*/*"},"remoteAddress":"::ffff:127.0.0.1","remotePort":58881},"res":{"statusCode":200,"headers":{"x-powered-by":"Express"}},"responseTime":2,"msg":"request completed"}

but in newrelic the message is not present:

{
  "entity.guid": "REDACTED",
  "entity.guids": "REDACTED",
  "entity.name": "REDACTED",
  "entity.type": "SERVICE",
  "hostname": "REDACTED",
  "level": "info",
  "message2": "foo bar",
  "newrelic.source": "logs.APM",
  "pid": 2225,
  "req.headers.accept": "text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.7",
  "req.headers.accept-encoding": "gzip, deflate, br, zstd",
  "req.headers.accept-language": "sk-SK,sk;q=0.9,cs-CZ;q=0.8,cs;q=0.7,en-US;q=0.6,en;q=0.5",
  "req.headers.cache-control": "max-age=0",
  "req.headers.connection": "keep-alive",
  "req.headers.cookie": "REDACTED",
  "req.headers.dnt": "1",
  "req.headers.host": "localhost:3000",
  "req.headers.sec-ch-ua": "\"Google Chrome\";v=\"129\", \"Not=A?Brand\";v=\"8\", \"Chromium\";v=\"129\"",
  "req.headers.sec-ch-ua-mobile": "?0",
  "req.headers.sec-ch-ua-platform": "\"macOS\"",
  "req.headers.sec-fetch-dest": "document",
  "req.headers.sec-fetch-mode": "navigate",
  "req.headers.sec-fetch-site": "none",
  "req.headers.sec-fetch-user": "?1",
  "req.headers.upgrade-insecure-requests": "1",
  "req.headers.user-agent": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/129.0.0.0 Safari/537.36",
  "req.id": 1,
  "req.method": "GET",
  "req.remoteAddress": "::1",
  "req.remotePort": 58422,
  "req.url": "/",
  "span.id": "REDACTED",
  "timestamp": 1726833780150,
  "trace.id": "REDACTED"
}

as can be seen, log contains only "message2": "foo bar", and message is missing.

Your Environment

macOS Sonoma 14.6.1 (23G93)
node -v
v22.5.1

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.

@workato-integration
Copy link

@jsumners-nr
Copy link
Contributor

The issue is at

const agentMeta = Object.assign({}, { timestamp: Date.now(), message: msg }, metadata)

Basically, at that point msg is undefined. So agentMeta looks like:

{
  "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')

@jsumners-nr
Copy link
Contributor

@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.

@petermilan
Copy link
Author

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.

@mrickard
Copy link
Member

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.

@github-project-automation github-project-automation bot moved this from Triage Needed: Unprioritized Features to Done: Issues recently completed in Node.js Engineering Board Sep 20, 2024
@jsumners-nr
Copy link
Contributor

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"
      ]
    }
  ]
}

@jsumners-nr
Copy link
Contributor

@petermilan when you issue pino.info({ message: 'something' }), what are you expecting to see? Are you expecting to see "something" in Pino's standard log message field (by default: msg)? Or are you expecting that no msg field will exist?

@petermilan
Copy link
Author

petermilan commented Sep 20, 2024

@jsumners-nr tbh, I was not expecting msg to be set, I was not aware of this functionality. I was just expecting to see same data as I am passing to the logger, to be logged.
And I would expect to see same data I see in stdout to be visible in newrelic. This is not the case, and was my worry of fact that I lost some data in newrelic.

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)

{"level":30,"time":1726853436371,"pid":18178,"hostname":"REDACTED","req":{"id":1,"method":"GET","url":"/","query":{},"params":{},"headers":{"host":"localhost:3000","cookie":"x-ms-gateway-slice=estsfd; stsservicecookie=estsfd","user-agent":"insomnia/10.0.0","accept":"*/*"},"remoteAddress":"::ffff:127.0.0.1","remotePort":54888},"message":"Test message","message2":"foo bar"}

newrelic through log forwarding (message is lost)

{
  "entity.guid": "REDACTED",
  "entity.guids": "REDACTED",
  "entity.name": "REDACTED",
  "entity.type": "SERVICE",
  "hostname": "REDACTED",
  "level": "info",
  "message2": "foo bar",
  "newrelic.source": "logs.APM",
  "pid": 18178,
  "req.headers.accept": "*/*",
  "req.headers.cookie": "x-ms-gateway-slice=estsfd; stsservicecookie=estsfd",
  "req.headers.host": "localhost:3000",
  "req.headers.user-agent": "insomnia/10.0.0",
  "req.id": 1,
  "req.method": "GET",
  "req.remoteAddress": "::ffff:127.0.0.1",
  "req.remotePort": 54888,
  "req.url": "/",
  "span.id": "REDACTED",
  "timestamp": 1726853436371,
  "trace.id": "REDACTED"
}

in my opinion log forwarding should mean that whole log will be forwarded as it is

@jsumners-nr
Copy link
Contributor

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.

@petermilan
Copy link
Author

petermilan commented Sep 20, 2024

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 ...
For me there would be always strongest argument to avoid loss of data.

perhaps better name of ticket would be:
Newrelic pinoHttp log forwarding is removing log.message field

It took me a while to figure out what is going on, and where the field is removed :)
But like I said, I can fix this on my side.

@jsumners-nr
Copy link
Contributor

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
Status: Done: Issues recently completed
3 participants