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:

1. It's some what ugly;
2. 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)))

Answer 1

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.

Answer 2

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):