Python: how to do lazy debug logging

Question

I have some python like this:

def foo():
    logger = logging.getLogger()
    # do something here
    logger.debug('blah blah {}'.format(expensive_func()))

foo()

where expensive_func() is a function that returns string and that it is expensive to execute.

When developping, the log level is set to DEBUG, and expensive_func() get executed, the message get logged, everything is fine.

The problem is that when I set the log level strictly greater than DEBUG, say WARNING, in production env, obviously the return value of expensive_func() won't get logged, but the expensive function itself will still be executed.

My question is: how to prevent python from excutting the expensive function when the logging level is WARNING?

I don't want to delete that debug line or add something like if level > DEBUG: return in the expensive function.

Thanks.

EDIT

I visited Lazy logger message string evaluation just now, but not satisfied with it, mainly because:

It's some what ugly;
Even if I wrap the expensive function with some Lazy class, what shoud I do when I have two expensive functions? (shown below).

class Lazy:
    def __init__(self, func, *a, **ka):
        self.func= func
        self.a = a
        self.ka= ka
    def __str__(self):
        return str(self.func(*self.a, **self.ka))

# Though this is ugly, it works
logger.debug('Message: %s', Lazy(expensive_func))

# What if I wanted to do this?
# logger.debug('Message: {}'.format(expf_1(expf_2(some_arg))))
# Maybe I can modify class Lazy to make something like this to work
# but it really doesn't feel right
# logger.debug('Message: {}', Lazy(expf_1, Lazy(expf_2, some_arg)))

I updated my answer to address your comment.

Vinay Sajip
– Vinay Sajip

2014-03-06 13:59:52 +00:00
Commented Mar 6, 2014 at 13:59 — Vinay Sajip
– Vinay Sajip, Commented Mar 6, 2014 at 13:59
possible duplicate of Lazy logger message string evaluation

durron597
– durron597

2015-08-28 16:08:35 +00:00
Commented Aug 28, 2015 at 16:08 — durron597
– durron597, Commented Aug 28, 2015 at 16:08

Vinay Sajip · Accepted Answer · 2014-03-06 13:59:21Z

13

Look at this part of the documentation.

Update: Logging already supports lazy evaluation, but slightly differently to the way described in your comnment. For example, see the following script:

import logging

def expensive_func(*args):
    print('Expensive func called: %s' % (args,))
    return sum(args)

class DeferredMessage(object):
    def __init__(self, func, *args):
        self.func = func
        self.args = args

    def __str__(self):
        return 'Message {0}'.format(self.func(*self.args))

if __name__ == '__main__':
    logging.basicConfig()
    logging.info(DeferredMessage(expensive_func, 1, 2))
    logging.warning(DeferredMessage(expensive_func, 3, 4))
    logging.error(DeferredMessage(expensive_func, 5, 6))

When the above script is run, it should print

Expensive func called: (3, 4)
WARNING:root:Message 7
Expensive func called: (5, 6)
ERROR:root:Message 11

which shows that a potentially expensive function is only called when necessary. The example above can, of course, be generalised to allow the format string to be passed to the DeferredMessage, and to use kwargs, and so on.

edited Mar 6, 2014 at 13:59

answered Jan 28, 2014 at 7:34

Vinay Sajip

100k15 gold badges184 silver badges196 bronze badges

Sign up to request clarification or add additional context in comments.

2 Comments

Not an ID Over a year ago

Thanks, I adopted this method. I can see that you are a maintainer of the logging package, is there any chance that this module will support some feature like this (lazy evaluation)? Maybe in a style like logger.debug('Message {}', F), where F is a tuple like (expensive_func, [arg1, arg2]). If the current log level is suitable, the expensive_func will get called by the logging module and then produces some string used to fill the blank.

jamesdlin May 17 at 0:11

It'd be nice if logging checked if the first argument is a callable to allow people to more directly do lazy evaluation with a 0-argument lambda, e.g.: logging.info(lambda: f"Message {expensive_func(1, 2)}").

schnittstabil · Accepted Answer · 2017-01-28 17:04:04Z

8

As Vinay Sajip suggests, you can do the following:

def foo():
    logger = logging.getLogger()
    if logger.isEnabledFor(logging.DEBUG):
        logger.debug('blah blah {}'.format(expensive_func()))
        logger.debug('Message: {}'.format(expf_1(expf_2(some_arg))))
        logger.debug('Message: {}', Lazy(expf_1, Lazy(expf_2, some_arg)))
foo()

Which is already lazy!

That's because the then-expressions

        logger.debug('blah blah {}'.format(expensive_func()))
        logger.debug('Message: {}'.format(expf_1(expf_2(some_arg))))
        logger.debug('Message: {}', Lazy(expf_1, Lazy(expf_2, some_arg)))

are only evaluated if and only if logger.isEnabledFor(logging.DEBUG) returns True, i.e. if and only if their evaluation is needed.

Even more

logging.info(DeferredMessage(expensive_func, 1, 2))

is not as lazy as one may think: DeferredMessage(expensive_func, 1, 2) have to be evaluated in an eager fashion. Which is in addition slower than evaluating:

    if logger.isEnabledFor(logging.DEBUG):

edited Jan 28, 2017 at 17:04

answered Mar 5, 2014 at 16:50

schnittstabil

6737 silver badges14 bronze badges

3 Comments

schnittstabil Over a year ago

See also my Lazy logger message string evaluation answer for benchmark results against the lazy class approach.

matanox Over a year ago

Hinging on a conditional statement for lazy logging bloats one's codebase a lot, it is hardly an elegant solution for an entire codebase.

jamesdlin May 17 at 5:22

This doesn't scale well. It should be rare that you'd need to call logger.debug multiple times like that (since they could all be a single call), and needing to add an if check for every single logger call is tedious, ugly, and more work to change if you ever want to upgrade or downgrade the severity of a log message.

o3bvv · Accepted Answer · 2017-06-30 14:43:11Z

1

You can use stringlike library to add laziness to your messages

E.g.:

logger.debug(
    'blah blah {value}'
    .format(
        value=LazyString(expensive_func)
    )
)

Lib link: https://github.com/CovenantEyes/py_stringlike

answered Jun 30, 2017 at 14:43

o3bvv

5,7363 gold badges27 silver badges26 bronze badges

Comments

Thomas Vincent · Accepted Answer · 2022-03-28 17:05:15Z

1

An iteration on Vinay Sajip's answer, to delegate lazy function call to the standard partial python function and also put the actual formatting in the expensive function (on_str is only wrapping):

from functools import partial

def expensive_format(*args):
    print('Expensive format called: %s' % (args,))
    return 'Message {0}'.format(sum(args))

class on_str(object):
    def __init__(self, func):
        self.func = func

    def __str__(self):
        return self.func()

if __name__ == '__main__':
    logging.basicConfig()
    logging.info(on_str(partial(expensive_format, 1, 2)))
    logging.warning(on_str(partial(expensive_format, 3, 4)))
    logging.error(on_str(partial(expensive_format, 5, 6)))

edited Mar 28, 2022 at 17:05

answered Mar 28, 2022 at 16:40

Thomas Vincent

1981 silver badge6 bronze badges

1 Comment

jamesdlin May 17 at 5:23

You don't need to use partial. You can just use lambda, which I think is more readable: logging.info(on_str(lambda: expensive_format(1, 2))).

jamesdlin · Accepted Answer · 2025-09-24 18:28:59Z

Here is a version of Vinay Sajip's answer that I think is a bit more general that uses what I think is nicer syntax:

import logging

class DeferredMessage:
    def __init__(self, callable):
        self.callable = callable

    def __str__(self):
        return self.callable()


def expensive_func(*args):
    print(f'Expensive func called: {args}')
    return sum(args)


logging.basicConfig()
logging.info(DeferredMessage(lambda: f'Message: {expensive_func(1, 2)}'))
logging.warning(DeferredMessage(lambda: f'Message: {expensive_func(3, 4)}'))
logging.error(DeferredMessage(lambda: f'Message: {expensive_func(5, 6)}'))

(This also is basically Thomas Vincent's answer using lambda instead of itertools.partial.)

I consider the syntax to be nicer because transforming naive calls is slightly more straightforward:

# Before
logging.info(f'Message: {expensive_func(1, 2)}')

# After
logging.info(DeferredMessage(lambda: f'Message: {expensive_func(1, 2)}'))

Taking another step further, we could make wrapper functions for logging.info/logging.debug/et al.:

def wrap_logging_func(logging_func):
    def wrapper(msg, *args, **kwargs):
        if callable(msg):
            assert not args and not kwargs
            return logging_func(DeferredMessage(msg))
        else:
            return logging_func(msg, *args, **kwargs)
    return wrapper


my_log_info = wrap_logging_func(logging.info)
my_log_warning = wrap_logging_func(logging.warning)

logging.basicConfig()

# Does not call expensive_func(1, 2)
my_log_info(lambda: f'Message: {expensive_func(1, 2)}')
my_log_warning(lambda: f'Message: {expensive_func(3, 4)}')

# Can still be used as before if lazy evaluation isn't needed.
my_log_info(f'Message: {expensive_func(1, 2)}')
my_log_warning(f'Message: {expensive_func(3, 4)}')
my_log_warning('Message: %d', expensive_func(3, 4))

Collectives™ on Stack Overflow

Python: how to do lazy debug logging

5 Answers 5

2 Comments

3 Comments

Comments

1 Comment

Comments

Your Answer

Linked

Hot Network Questions

Collectives™ on Stack Overflow

5 Answers 5

2 Comments

3 Comments

Comments

1 Comment

Comments

Your Answer

Sign up or log in

Post as a guest

Linked

Related