Log stdlib's logging extra-s

[saabeilin]

Quite many people use python's stdlib logging with extras, say, logger.info("message", extra={'a': 'b'}). It's quite obvious how to format these messages in a customer way with stdlib, and many formatters (say, LogstashV1Formatter) render them by default. However, these are ignored when the rest of the logging and rendering is done via structlog.

Would be great to have the extra dictionary contents from stdlib logging passed to structlog, so

stdlib_logger.info("TEST from %s logger", 'stdlib', extra={'a': 'b'})

and

struct_logger.info("TEST from %s logger", 'struct', a='b')

would produce equivalent results.

Typical use-case:

• the underlying library uses stdlib logging,
• the application uses structlog.

[hynek]

To double-check, this is about pumping stdlib logs through structlog, correct? I guess that shouldn't be too hard to implement.

[techdragon]

I'd love to see this go further than just having stdlib logs through structlog. I'd really love it if I could tell structlog to use the extras dictionary for its own extra data, almost as a stdlib in structlog clothing. But I'm guessing this is probably not a workable option for many reasons.

[morganchristiansson]

Really? Why isn't logging structured logs through stdlib supported by structlog?

I assumed that it would work with nothing mentioned in the documentation.

[hynek]

So I've looked at this and it…interesting.

You'd think you can access extra somewhere, however it just added to LogRecords as attributes:

https://github.com/python/cpython/blob/1cbaa505d007e11c4a1f0d2073d72b6c02c7147c/Lib/logging/__init__.py#L1597-L1601

This means there is no way to know what extra attributes have been added.

There's two ways to go around this:

1. you know your extras and extract them from _record in a processor that you run within ProcessorFormatter's foreign_pre_chain argument.
2. you just iterate over _record.__dict__ and throw away what you don't care about ibid.

Both are already possible – here's an example for #2:

def copy_record(_, __, ed):
    ignores = ["msg", "message", "args"]
    for k, v in ed["_record"].__dict__.items():
        if k in ignores:
            continue

        ed[k] = v

    return ed

It removes "msg" and "message" because they're redundant and copies it over into the event dict:

foo=42 event='from structlog' logger='__main__' level='info' timestamp='2021-11-11T07:20:33.812186Z'

event='from stdlib' logger='root' level='info' timestamp='2021-11-11T07:20:33.812572Z' name='root' levelname='INFO' levelno=20 pathname='/Users/hynek/FOSS/structlog/t.py' filename='t.py' module='t' exc_info=None exc_text=None stack_info=None lineno=64 funcName='<module>' created=1636615233.812545 msecs=812.5450611114502 relativeCreated=177.2611141204834 thread=4809659904 threadName='MainThread' processName='MainProcess' process=407 foo=42

I guess I could add something like RecordCopier(drop=["msg", "message", "created", "msecs", "relativeCreated", "levelname", "lavelno"], drop_nones=True) – is that something that you'd like? To be clear: all of that is already possible.

[hynek]

Full example:

from __future__ import annotations

import logging

import structlog


def copy_record(_, __, ed):
    ignores = ["msg", "message", "args"]
    for k, v in ed["_record"].__dict__.items():
        if k in ignores:
            continue

        ed[k] = v

    return ed


shared_processors: list[structlog.types.Processor] = [
    structlog.stdlib.add_logger_name,
    structlog.stdlib.add_log_level,
    structlog.processors.TimeStamper(fmt="iso", utc=True),
    structlog.processors.StackInfoRenderer(),
    structlog.processors.format_exc_info,
]

formatter = structlog.stdlib.ProcessorFormatter(
    foreign_pre_chain=[*shared_processors, copy_record],  # <----
    processor=structlog.processors.KeyValueRenderer(),
)

handler = logging.StreamHandler()
handler.setFormatter(formatter)
root_logger = logging.getLogger()
root_logger.addHandler(handler)
root_logger.setLevel(logging.INFO)


structlog.configure(
    processors=[
        structlog.stdlib.filter_by_level,
        *shared_processors,
        structlog.stdlib.PositionalArgumentsFormatter(),
        structlog.stdlib.ProcessorFormatter.wrap_for_formatter,
    ],
    context_class=dict,
    logger_factory=structlog.stdlib.LoggerFactory(),
    cache_logger_on_first_use=True,
)


logger = structlog.get_logger()


structlog.get_logger().info("from structlog", foo=42)
logging.getLogger().info("from %s", "stdlib", extra={"foo": 42})