Why are logging statement in python evaluated regardless of level?

Question

Why are logging statement in python evaluated regardless of level?

In this code for example, I expected the "I was executed" statement to be printed only when the script is called with "-d", but it is always printed! This means that logging statement can have an unexpected impact on code run at higher logging levels.

#!/usr/bin/env python3

#import time
import argparse
import logging

logging.basicConfig(format='==> %(module)s, %(funcName)s %(message)s', level=logging.ERROR)

def logme():
    #time.sleep(10)
    print('I was executed ☠')
    return 'loggging all the things...'

if __name__ == "__main__":
    parser = argparse.ArgumentParser()
    parser.add_argument("--debug", "-d",
                         action='store_true',
                         help="Debug mode (very verbose)",
                        )

    args = parser.parse_args()
    if args.debug:
        logging.getLogger().setLevel(logging.DEBUG)

print('hello')
logging.debug('{}'.format(logme()))
print('bye')

Is this a bug in the logging module?

Answer 1

It boils down to how the statement is evaluated. In

logging.debug('{}'.format(logme()))

The parameter is evaluated first, then logger.debug is called. So, we evaluate '{}'.format(logme()), then pass the result to logging.debug. It's effectively

x = '{}'.format(logme())
logging.debug(x)

Let's test this out:

def run_later(x):
    print("function call")

def effect():
    print("parameter evaluation")

run_later(effect())
>>> parameter evaluation
>>> function call