Clarification on InterceptHandler behavior

[BayerSe]

Hello,

I've got another question where I'd need some help. In particular, I'd like to understand the following behavior. If I open a fresh console and print all loggers

import logging
for logger in [logging.getLogger(name) for name in logging.root.manager.loggerDict]:
    print(logger)

I get the following output:

<Logger _plotly_utils.optional_imports (WARNING)>
<Logger _plotly_utils (WARNING)>
<Logger _shaded_thriftpy.server (DEBUG)>
<Logger _shaded_thriftpy (DEBUG)>
<Logger concurrent.futures (WARNING)>
<Logger concurrent (WARNING)>
<Logger asyncio (WARNING)>

... a mixture of different loggers and log levels.

If I now apply the InterceptHandler and reprint the loggers:

import inspect
import logging

from loguru import logger


class InterceptHandler(logging.Handler):
    def emit(self, record: logging.LogRecord) -> None:
        # Get corresponding Loguru level if it exists.
        level: str | int
        try:
            level = logger.level(record.levelname).name
        except ValueError:
            level = record.levelno

        # Find caller from where originated the logged message.
        frame, depth = inspect.currentframe(), 0
        while frame and (depth == 0 or frame.f_code.co_filename == logging.__file__):
            frame = frame.f_back
            depth += 1

        logger.opt(depth=depth, exception=record.exc_info).log(
            level, record.getMessage()
        )


logging.basicConfig(handlers=[InterceptHandler()], level=0, force=True)

for logger in [logging.getLogger(name) for name in logging.root.manager.loggerDict]:
    print(logger)

I get

<Logger _plotly_utils.optional_imports (NOTSET)>
<Logger _plotly_utils (NOTSET)>
<Logger _shaded_thriftpy.server (DEBUG)>
<Logger _shaded_thriftpy (DEBUG)>
<Logger concurrent.futures (NOTSET)>
<Logger concurrent (NOTSET)>
<Logger asyncio (NOTSET)>

I guess that the NOTSET comes from level=0 in the basicConfig call? If that is the case, why are _shaded_thriftpy.server and _shaded_thriftpy still at DEBUG?

This happens for other libraries too, not only the internal stuff: some stay at their original level, some switch to NOTSET.

[Delgan]

Hello @BayerSe.

What you are observing is an inherent characteristic of the standard logging behavior. This is explained in the official documentation. The following paragraph is particularly relevant:

Loggers have a concept of effective level. If a level is not explicitly set on a logger, the level of its parent is used instead as its effective level. If the parent has no explicit level set, its parent is examined, and so on - all ancestors are searched until an explicitly set level is found. The root logger always has an explicit level set (WARNING by default). When deciding whether to process an event, the effective level of the logger is used to determine whether the event is passed to the logger’s handlers.

In your case, it appears that loggers from _shaded_thriftpy were specifically configured with DEBUG level, while others ones "inherited" the level from the root logger, which is WARNING by default. Once you call basicConfig() with level=0, these loggers are updated accordingly (NOTSET is 0), while the _shaded_thriftpy's logger remain unchanged since it has its own explicit level.

[BayerSe]

Hi @Delgan

Many thanks for the insights! For an exemplary library (rq) I was indeed able to find the place where the logging level is explicitly set.