New relic log forwarder ignores formatter

[christophe-riolo]

Description
We have an application that instruments our log records with extra attributes that later get formatted by the NewRelicContextFormatter. Our application defines this instrumenting LogFactory, sets the proper Formatter to the root Handler, but all this is for nought because the NewRelicLogForwardingHandler does not use the formatter, it does not format the record's message at all.

Expected Behavior
The message is formatted, notably the extra attributes in the LogRecord are added in the form extra.* in the information displayed in New Relic as well as logger name, file name, line number etc.

Troubleshooting or NR Diag results
I went through the troubleshooting and noticed that the instructions to check that everything is set up properly, we need to check that we have span.id and trace.id but those are not set by the NewRelicContextFormatter

Steps to Reproduce
Follow the manual setup from https://docs.newrelic.com/docs/logs/logs-context/configure-logs-context-python/

Your Environment
New relic agent version = "8.5.0"
Python 3.10.9
Linux: archlinux but also happening in our docker image

Additional context
I realized that the NewrelicLogForwardingHandler uses the unformatted record.getMessage instead of self.format(record); making that change fixes the issue if I manually configure my application to have a NewRelicLogForwardingHandler with the NewRelicContextFormatter as a formatter. However, I still get the default forwarding agent logs without the formatting. I will provide some more data:

Modified class

class NewRelicLogForwardingHandler(logging.Handler):
    def emit(self, record):
        try:
            # This is not taking the case with _nr_original_message into account
            message = self.format(record)
            record_log_event(message, record.levelname, int(record.created * 1000))
        except Exception:
            self.handleError(record)

Logging dict config:

    'handlers': {
        'newrelic': {
            'class': 'newrelic.api.log.NewRelicLogForwardingHandler',
            'formatter': 'NewRelicContextFormatter',
        },
    },
    'root': {
        'level': 'INFO',
        'handlers': ['newrelic'],
    },

Automatically forwarded:

{
  "entity.guid": "**",
  "entity.guids": "***",
  "entity.name": "app",
  "entity.type": "SERVICE",
  "hostname": "christophe",
  "level": "INFO",
  "message": "Response: status_code=401",
  "newrelic.source": "logs.APM",
  "span.id": "4b3615aebc629877",
  "timestamp": 1672323908227,
  "trace.id": "512ed4c040f5969add648040d6f3ef8b"
}

From my manually defined handler:

{
  "entity.guid": "***",
  "entity.guids": "***",
  "entity.name": "app",
  "entity.type": "SERVICE",
  "extra.app_id": "***",
  "extra.http_request.protocol": "HTTP/1.1",
  "extra.http_request.referer": "null",
  "extra.http_request.remote_ip": "127.0.0.1",
  "extra.http_request.request_method": "POST",
  "extra.http_request.request_size": 452,
  "extra.http_request.request_url": "***",
  "extra.http_request.user_agent": "curl/7.87.0",
  "extra.request_id": "ea6f38fd-b834-48c4-97a7-a7951000145c",
  "extra.response_body.error.code": 401,
  "extra.response_body.error.message": "Unauthorized",
  "extra.time_elapsed": 0.004572868347167969,
  "extra.time_start": 1672322157.3531582,
  "file.name": "/home/chris/projects/***.py",
  "hostname": "christophe",
  "level": "INFO",
  "line.number": 240,
  "logger.name": "lib.common.blueprints",
  "message": "Response: status_code=401",
  "newrelic.source": "logs.APM",
  "process.id": 217239,
  "process.name": "MainProcess",
  "severity": "INFO",
  "span.id": "4d8f5d780bd5a0da",
  "thread.id": 140178617263808,
  "thread.name": "Thread-7 (process_request_thread)",
  "timestamp": 1672322157357,
  "trace.id": "d8014c0a3505ec76247c8750f81df0bd"
}

[stale]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

[sarunassaulis]

I ran into this issue as well, with very similar setup - Django + gunicorn, using newrelic-admin wrapper.

The fix suggested by @christophe-riolo does work. However, by explicitly using NewrelicLogForwardingHandler, I am now getting messages logged twice, I assume once by newrelic-admin, only with the record.getMessage() contents, and another one, forwarded by the fixed handler, with all the relevant log record details.

[Eden-Eliel]

Hey, I ran into this issue as well.

As @christophe-riolo suggested, I have added the NewrelicLogForwardingHandler class, and it does work.
However, I had the same issue as @sarunassaulis and it logged twice.

After digging a bit in the code, I have found a workaround for the double logging:

[import-hook:logging]
enabled = false

Adding this to the newrelic.ini fixed the issue of logging twice, and kept only the log from the new handler (NewrelicLogForwardingHandler)

Hope it helps someone.

[sh-at-cs]

Thanks for the workarounds in this issue!

It's kind of strange that NewRelic's officially supported configurations (as listed here) are

• automatic log formatting & automatic log forwarding,
• automatic log formatting & external log forwarding, and
• manual log formatting & external log forwarding,

while

• manual log formatting & automatic log forwarding

is not supported. My guess would've been that the latter is the one people will be most interested in as it allows attaching custom metadata etc. and that wanting to set up external log forwarding would be a niche requirement...

[TimPansino]

This should be changed on the newest version of the agent