newrelic/newrelic-python-agent

Loguru finds the wrong module/function name

rafaelclp opened this issue · 0 comments

Context

Description
When I emit a log with loguru (e.g. logger.info("my log")), loguru can't correctly figure out what's the module and function that called logger.info. It always shows as loguru._logger:info.

This only happens after initializing thew newrelic agent, and it's caused by the loguru._logger newrelic hook (which is enabled by default). If I add the following lines to my newrelic.ini, the error goes away:

[import-hook:loguru._logger]
enabled = false

Steps to reproduce

import newrelic.agent
from loguru import logger

newrelic.agent.initialize("newrelic.ini")

def my_function():
    logger.info("initialized")

my_function()

Expected Output

2022-08-04 17:28:30.883 | INFO     | __main__:my_function:7 - initialized

Actual Output

2022-08-04 17:28:30.883 | INFO     | loguru._logger:info:1977 - initialized

What's causing this bug

Newrelic wraps all calls to loguru's Logger._log, and this causes an issue. Let's see why.

How loguru finds out module and function

To find out the module and function that called logger.info (or .error/.warning/...), loguru looks at the stack trace. Here is the relevant loguru code:

    def _log(self, level_id, static_level_no, from_decorator, options, message, args, kwargs):
        ...

        (exception, depth, record, lazy, colors, raw, capture, patcher, extra) = options

        frame = get_frame(depth + 2)

        ...

It finds the stacktrace frame two levels up (depth + 2), where depth is 0 by default. It expects the stack trace to be:

__main__:my_function
loguru._logger:info
loguru._logger:_log

However, newrelic breaks this assumption because it wraps the call to logger._log with another function, so the stack trace looks like this:

__main__:my_function
loguru._logger:info
newrelic.hooks.logger_loguru:wrap_log
loguru._logger:_log

When it looks two levels up, it sees loguru._logger:info instead of __main__.my_function, and that's why we always see that in the log instead of the expected.

Where does newrelic patch loguru?

In newrelic.config:initialize:

    _process_module_definition(
        "loguru._logger",
        "newrelic.hooks.logger_loguru",
        "instrument_loguru_logger",
    )

Which calls newrelic.hooks.logger_loguru:instrument_loguru_logger:

def instrument_loguru_logger(module):
    if hasattr(module, "Logger"):
        wrap_function_wrapper(module, "Logger.__init__", wrap_Logger_init)
        if hasattr(module.Logger, "_log"):
            wrap_function_wrapper(module, "Logger._log", wrap_log)

The last line wraps loguru._logger.Logger._log with wrap_log.