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]

you can do this, it works for both json output and text output (at least in latest version):

logger = get_logger()

class LazyValueLogLine:

    def __init__(self, msg, fn):
        self.msg = msg
        self.fn = fn

    def __repr__(self):
        return self.msg % self.fn()

logger.debug(LazyValueLogLine("hello %s", simple_func))
logger.info(LazyValueLogLine("hello %s", simple_func))

simple_func will only be called once for info level log

---

this would be much easier if structlog are using new format style formatting(for example, loguru), then we only need to wrap args with LazyValue instead of whole line, but there is no magic method for percent formatting...

class LazyValue:
    def __init__(self, fn):
        self.fn = fn

    def __format__(self, format_spec):
        return format(self.fn(), format_spec)

logger.info("hello {} from {}", LazyValue(simple_func), "Alice")