Traceback when using stdlib.filter_by_level with Python Standard Logging Library

[abramjstamper]

Just started using structlog recently; I've have found it's a great library to work with. Appreciate your all your hard work!

I'm using it both for internal logging library and for formatting the root python logging library's messages. Both are printing JSON to stdout. I get a traceback when I try to use structlog.stdlib.filter_by_level. Actually, I run into several similar tracebacks for several processors from the structlog.stdlib library. With these processors commented out, I am able to successfully encode JSON logs to the console from 3rd party libraries using the built in Python logger.

However, I was hoping to utilize the additional processors listed in the documentation. I checked for similar issues in GH and the documentation on integrating with the stdlib python logger, but didn't find any solutions. I'm hoping to understand if there was any insight here on something I'm doing wrong - configuring the python standard library to use structlog or if I'm using the processors incorrectly? Otherwise, I think this might be a bug with structlog.

After some review of the stack trace, I think the issue may comes from isEnabeldFor not being available on whatever object structlog.stdlib.ProcessorFormatter provides as it seems to only exist on structlog.stdlib.BoundLogger.

dev:api logs  api:   File "/root/.pyenv/versions/3.8.12/lib/python3.8/logging/__init__.py", line 1085, in emit
dev:api logs  api:     msg = self.format(record)
dev:api logs  api:   File "/root/.pyenv/versions/3.8.12/lib/python3.8/logging/__init__.py", line 929, in format
dev:api logs  api:     return fmt.format(record)
dev:api logs  api:   File "/root/.pyenv/versions/3.8/lib/python3.8/site-packages/structlog/stdlib.py", line 1046, in format
dev:api logs  api:     ed = p(logger, meth_name, ed)
dev:api logs  api:   File "/root/.pyenv/versions/3.8/lib/python3.8/site-packages/structlog/stdlib.py", line 744, in filter_by_level
dev:api logs  api:     if logger.isEnabledFor(_NAME_TO_LEVEL[method_name]):
dev:api logs  api: AttributeError: 'NoneType' object has no attribute 'isEnabledFor'

I'm attempting to configure it like this for each logger instance respectively.

# internal application logging
internal_processors = [
    structlog.contextvars.merge_contextvars,
    structlog.processors.add_log_level,
    structlog.processors.UnicodeDecoder(),
    structlog.processors.StackInfoRenderer(),
    structlog.processors.dict_tracebacks,
    structlog.processors.TimeStamper(fmt="iso", utc=True),
    structlog.processors.EventRenamer(to="message"),
    structlog.processors.CallsiteParameterAdder(<omitted>),
    structlog.processors.JSONRenderer(serializer=dumps)
]

structlog.configure(
    cache_logger_on_first_use=True,
    wrapper_class=structlog.make_filtering_bound_logger(20),
    processors=internal_processors,
    logger_factory=structlog.BytesLoggerFactory(),
)


# stdlib python logging
formatter = structlog.stdlib.ProcessorFormatter(
    processors=[
        structlog.stdlib.PositionalArgumentsFormatter(),
        # structlog.stdlib.filter_by_level,
        structlog.stdlib.add_log_level,
        structlog.stdlib.add_logger_name,
        # structlog.stdlib.ExtraAdder,
        # structlog.stdlib.StackInfoRenderer,
        structlog.processors.TimeStamper(fmt="iso", utc=True),
        structlog.processors.EventRenamer(to="message"),
        structlog.stdlib.ProcessorFormatter.remove_processors_meta,
        structlog.processors.JSONRenderer(),
    ],
)
handler = logging.StreamHandler()
handler.setFormatter(formatter)
root_logger = logging.getLogger()
root_logger.addHandler(handler)
root_logger.setLevel(logging.INFO)```

[hynek]

Hmm filter_by_level makes no sense in a ProcessorFormatter processor, because filtering at this point is done by logging.

Generally speaking the execution environment within ProcessorFormatter is very different than within structlog proper.

[sshishov]

Hi @hynek , thank you very much for the comment.

Could we have an explanation which processors cannot be used in stdlib configuration?
Also I have a small confusion between processors and foreign_pre_chain? When I should use which?

Example:

COMMON_PRE_CHAIN: list[structlog.typing.Processor] = [
    structlog.contextvars.merge_contextvars,
    structlog.stdlib.filter_by_level,  # <-- this "common" processor is causing issues in stdlib configuration
    structlog.processors.TimeStamper(fmt='iso'),
    structlog.stdlib.add_logger_name,
    structlog.stdlib.add_log_level,
    structlog.stdlib.PositionalArgumentsFormatter(),
    structlog.processors.StackInfoRenderer(),
    structlog.processors.UnicodeDecoder(),
]

LOGGING: dict[str, t.Any] = {
    'version': 1,
    'disable_existing_loggers': False,
    'filters': {'event_blacklist': {'()': 'app.settings.components.DevelopmentFilter'}},
    'formatters': {
        'plain_console': {
            '()': structlog.stdlib.ProcessorFormatter,
            'processors': [structlog.stdlib.ProcessorFormatter.remove_processors_meta, structlog.dev.ConsoleRenderer()],  # <-- what is the difference between processors here and `foreign_pre_chain` later on? One is used for `structlog` logs and another for `stdlib` logs? We are trying it to keep "the same"
            'foreign_pre_chain': COMMON_PRE_CHAIN,  # <-- the issue is caused here with the same example
        },
    },
}

structlog.configure(
    processors=[*COMMON_PRE_CHAIN, structlog.stdlib.ProcessorFormatter.wrap_for_formatter],
    logger_factory=structlog.stdlib.LoggerFactory(),
    wrapper_class=structlog.stdlib.BoundLogger,
    cache_logger_on_first_use=True,
)

With the following configuration we have exactly the same traceback. In the documentation it is stated that you should keep your structlog configuration and stdlib logging configuration as close as possible (to have similar logs).

Could you please explain which processors we can't/shouldn't use in foreign_pre_chain?

[hynek]

structlog.stdlib.ProcessorFormatter's processors are executed on every log entry that arrives in ProcessorFormatter. That is: log entries coming from logging and entries that have been looped back into structlog (see also the graph at https://www.structlog.org/en/stable/standard-library.html#rendering-using-structlog-based-formatters-within-logging)

structlog.stdlib.ProcessorFormatter's foreign_pre_chain is run only on log entries coming from logging before handing it over to the processors in the previous paragraph. This chain is mostly to add data that you might want to use on processors like structlog-style timestamps etc.

I cannot answer your question in general because it's complicated. OP's problem was that they used a processor that needed a stdlib logger to get the log level. I'm not even sure what your problem is.