A proper way to defer rendering log message?

[MasterGroosha]

Hello. First of all, thank you so much for this awesome library, and pardon me for more theoretical question. As there is no "Discussions" tab, going to ask this here.

In the documentation, the author says:

Here it is implied, that if you use string interpolation instead of f-strings, this would defer rendering text and if log level is higher that the caller's, then text will not be rendered, possibly saving some time on calling expensive function.

However, this is not really like that, as simply using string interpolation will still make the call:

import logging


def simple_func():
    print("Called!")
    return 5


logging.basicConfig(level=logging.WARNING)

logging.debug(f"Running with number {simple_func()}")
logging.debug("Running with number %s", simple_func())

And it is the same with structlog:

import logging

import structlog
from structlog import WriteLoggerFactory
from structlog.types import FilteringBoundLogger


def get_processors() -> list:
    processors = [
        structlog.processors.TimeStamper(),
        structlog.processors.add_log_level,
        structlog.dev.ConsoleRenderer(),
    ]
    return processors


def get_structlog_config() -> dict:
    min_level = logging.INFO

    return {
        "processors": get_processors(),
        "cache_logger_on_first_use": True,
        "wrapper_class": structlog.make_filtering_bound_logger(min_level),
        "logger_factory": WriteLoggerFactory()
    }


def simple_func():
    print("Called!")
    return 5


logger: FilteringBoundLogger = structlog.get_logger()
structlog.configure(**get_structlog_config())


logger.debug(f"Running with number {simple_func()}", extra="extra_f_string")
logger.debug("Running with number %s", simple_func(), extra="extra_interpolate")

In both examples, there will be two "Called!" strings in the console.

Am I missing something? Is there any other configuration needed to avoid rendering log text when overall log level is higher? Also, what's the analogue of "isEnabledFor" in structlog?

Thanks in advance!

[hynek]

What you're missing is that normal Python code has no control over over how its function argument values are created. structlog only gets the result of your function call and doesn't know it was created by calling a function.

What the delay means is that the string isn't rendered, based on those arguments unless necessary.

---

The best I can offer you off-cuff is setting some key to a special value and writing a processor that executes your expensive function based on that.

[trim21]

OK, I just find that a existing library for this: https://github.com/o3bvv/lazy-string

import structlog
from lazy_string import LazyString


log = structlog.get_logger()


def make_foo() -> str:
    return "foo"


log.info("hello %s", LazyString(make_foo)) # 2024-09-23 00:59:12 [info     ] hello foo