hynek / structlog

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

Async logger calls report incorrect call site parameters #615

Closed IanTaylorFB closed 5 months ago

IanTaylorFB commented 6 months ago

It appears that the async logger calls (adebug, ainfo, ...) are unable to access the correct stack frame / call site parameters because the calls are dispatched via concurrent.futures.thread.

I need compatibility with stdlib logging as well as structlog, and I do need function names and line numbers, so here's my mre, using Python 3.11.8 and structlog 24.1.0:

import asyncio
import logging
import logging.config

import structlog

def get_common_processors():
    return [
        structlog.contextvars.merge_contextvars,
        structlog.stdlib.add_logger_name,
        structlog.stdlib.add_log_level,
        structlog.stdlib.PositionalArgumentsFormatter(),
        structlog.processors.CallsiteParameterAdder(
            [
                structlog.processors.CallsiteParameter.FUNC_NAME,
                structlog.processors.CallsiteParameter.LINENO,
            ],
        ),
    ]

def get_structlog_processors():
    return [
        structlog.stdlib.ProcessorFormatter.wrap_for_formatter,
    ]

structlog.configure(
    processors=get_common_processors() + get_structlog_processors(),
    logger_factory=structlog.stdlib.LoggerFactory(),
    wrapper_class=structlog.stdlib.BoundLogger,
)

logging.config.dictConfig(
    {
        "version": 1,
        "disable_existing_loggers": False,
        "formatters": {
            "console_formatter": {
                "()": structlog.stdlib.ProcessorFormatter,
                "processor": structlog.dev.ConsoleRenderer(
                    sort_keys=True, colors=True
                ),
                "foreign_pre_chain": get_common_processors(),
            }
        },
        "handlers": {
            "console_handler": {
                "class": "logging.StreamHandler",
                "formatter": "console_formatter",
            }
        },
        "loggers": {
            "": {
                "handlers": ["console_handler"],
                "level": logging.INFO,
            },
        }
    }
)

def logging_main():
    logger = logging.getLogger()
    logger.info(" [info] should report 'func_name=logging_main   lineno=67'")

async def structlog_main():
    logger = structlog.get_logger()
    logger.info(" [info] should report 'func_name=structlog_main lineno=72'")
    await logger.ainfo("[ainfo] should report 'func_name=structlog_main lineno=73'")

if __name__ == "__main__":
    logging_main()
    loop = asyncio.get_event_loop()
    loop.run_until_complete(structlog_main())
    loop.close()

And the output is like this:

[info     ]  [info] should report 'func_name=logging_main   lineno=67' [root] func_name=logging_main lineno=67
[info     ]  [info] should report 'func_name=structlog_main lineno=72' [__main__] func_name=structlog_main lineno=72
[info     ] [ainfo] should report 'func_name=structlog_main lineno=73' [__main__] func_name=run lineno=58

You can see the async call reports the function and line number from concurrent.futures.thread, instead of the function and line number from the mre.

Questions:

  1. Am I missing something? Or have something wrong?
  2. Should I just stick to the synchronous calls? Will this block me significantly?

Thanks for any insights!

hynek commented 5 months ago

Oof yeah it looks like we've only added tests for AsyncBoundLogger (that is kinda deprecated) but not to the vanilla a.*()methods. 😳

I'll see what I can do. As for your 2 point: as long as your loggers don't block a lot on IO, the benefits of async logging is dubious at best, but people asked for it a lot and it might improve further with free-threading.