hynek / structlog

Simple, powerful, and fast logging for Python.
https://www.structlog.org/
Other
3.48k stars 220 forks source link

Processor `logger` argument is None when using Python's logging. #613

Closed oscaroteromar closed 4 months ago

oscaroteromar commented 6 months ago

Describe the bug

I have an hybrid configuration which uses structlog loggers and Python's logging loggers. I have applied different processors, some custom, in order to format my logs. In one of my custom processors, I want to do some formatting depending on the log level set in the configuration. For this, I access the first argument logger that arrives to the processor, like:

class DummyProcessor:

    def __call__(self, logger: BindableLogger | None, method_name: str, event_dict: EventDict) -> dict:
        # We would like to check the log level of the logger to run
        # some code. When the `logger` is None, we never access to the
        #  second part of the condition.
        if logger is not None and not logger.isEnabledFor(logging.DEBUG):
          print("Run some code")
        return event_dict

Here comes the problem: when the logger that emits the log is a structlog logger (logger = structlog.stdlib.get_logger("testing_sructlog")), I have no problem since the given object is <_FixedFindCallerLogger testing_sructlog (DEBUG)>, however, when the logger comes from Python's logging, the logger argument is None. I'd like to get a valid object always for logger in order to access the log level and proceed.

To reproduce

Please, check the following repository which contains an emulation of my real problem in order to reproduce it.

Current output:

$ python main.py
logger argument is <_FixedFindCallerLogger testing_sructlog (DEBUG)>
2024-04-05T15:02:51+0000 [debug    ] A log test from logging.       [testing_sructlog]
logger argument is None
2024-04-05T15:02:51+0000 [debug    ] A log test from structlog.     [testing_sructlog]

Expected output (more or less):

$ python main.py
logger argument is <_FixedFindCallerLogger testing_sructlog (DEBUG)>
2024-04-05T15:02:51+0000 [debug    ] A log test from logging.       [testing_sructlog]
logger argument is <a valid object like logging.Logger> 
2024-04-05T15:02:51+0000 [debug    ] A log test from structlog.     [testing_sructlog]

Versions

Python 3.10.13 Structlog 24.1.0


Is this a bug or is it an intended behaviour?

Thank you in advance!

hynek commented 4 months ago

I believe the information you're looking for should be in event_dict["_record"]?

oscaroteromar commented 4 months ago

Thanks for the response! It's true that I can access the log level as you say

(Pdb) a
self = <logging_config.DummyProcessor object at 0x108a5c490>
logger = None
method_name = 'debug'
event_dict = {'event': 'A log test from structlog.', '_record': <LogRecord: testing_sructlog, 10, /Users/<...>/structlog-issue/main.py, 41, "A log test from structlog.">, '_from_structlog': False}
(Pdb) p event_dict['_record'].levelno
10
(Pdb) p event_dict['_record'].levelname
'DEBUG'
(Pdb)

I'll use this for the workaround, thank you!