Tag: python

There is one thing that has bothered me for a couple of months. It felt wrong when I saw it in the codebase but I could not tell why it is wrong. It was just a hunch that something is not right, but not enough to make me look for a reason.

For last couple of days I have been struggling to sort out my bot configuration on Azure and decided I need a break from that. Python being something I know best is a good candidate to feel comfortable and in control again.

I have decided to finally answer the question that was buggin me. Why using f-strings in logger calls makes me uneasy? Why this feels wrong?

hero = "Mumen Rider"
logger.error(f"Class C, rank 1: {hero}")

f-strings

Most of the pythonistas would know by now what f-strings are. They are convenient way of constructing strings. Values can be included directly in the string what makes the string much more readable. Here is an example from Python 3’s f-Strings: An Improved String Formatting Syntax (Guide), which is worth at least skimming through if you know f-strings.

>>> name = "Eric"
>>> age = 74
>>> f"Hello, {name}. You are {age}."
'Hello, Eric. You are 74'

They have benefits and my team have been using them since. It’s fine as they are awesome however I feel that they should not be used when we talk about logging.

logging

I’m not talking about poor man’s logging which is print. This is an example of logging in Python

logger.info("This is an example of a log message, and a value of %s", 42)

When the code includes such line and when it is executed it outputs string according to log configuration. Of course your log level needs to match but I’m skipping this as it is not relevant here, I’ll get back to this later. The %s identifier in log messages means that anything passed into logger.info will replace the identifier. So the message will look like this.

INFO:MyLogger:This is an example of a log message, and a value of 42

logging + f-strings

Since logging accept strings and f-strings are so nice they could be used together. Yes, it is possible of course but I’d not use f-strings for such purpose. Best to illustrate why is an example followed with explanation.

    import logging
    logging.basicConfig(level=logging.ERROR)
    logger = logging.getLogger('klich.dev')

    class MyClass:
        def __str__(self):
            print('Calling __str__')
            return "Hiya"

    c = MyClass()
    print("F style")
    logger.debug(f'{c}')
    logger.info(f'{c}')
    logger.warning(f'{c}')
    logger.error(f'{c}')

    print()
    print("Regular style")
    logger.debug('%s', c)
    logger.info('%s', c)
    logger.warning('%s', c)
    logger.error('%s', c)

This short example creates logger and sets logging level to ERROR. This means that only calls of logger.error will produce output. __str__ method of object used in log messages prints information when it is called. So each level matching logger call will print Calling __str__ message and Hiya. Since there are two logger.error calls we should get four lines total. This is what actually is printed out.

    % python3 logg.py
    F style
    Calling __str__
    Calling __str__
    Calling __str__
    Calling __str__
    ERROR:klich.dev:Hiya

    Regular style
    Calling __str__
    ERROR:klich.dev:Hiya

We can see that logger lines using f-strings are calling __str__ even if the log message is not printed out. This is not a big penalty but it may compound to something significant if you have many log calls with f-strings.

what is going on

According to documentation on logging

Formatting of message arguments is deferred until it cannot be avoided.

Logger is smart enough to actually not format messages if it is not needed. It will refrain from calling __str__ until it is required, when it is passed to std out or to a file, or other with options supported by logger.

To dig a little bit more we can use dis module from python standard library. After feeding our code to dis.dis method we will get a list of operations that happend under the hood. For detailed explanation of what exact operations do have a look at ceval.c from Python’s sources.

    >>> import logging
    >>> logger = logging.getLogger()
    >>> def f1():
            logger.info("This is an example of a log message, and a value of %s", 42)

    >>> def f2():
            logger.info(f"This is an example of a log message, and a value of {42}")

    >>> import dis
    >>> dis.dis(f1)
                0 LOAD_GLOBAL              0 (logger)
                2 LOAD_METHOD              1 (info)
                4 LOAD_CONST               1 ('This is an example of a log message, and a value of %s')
                6 LOAD_CONST               2 (42)
                8 CALL_METHOD              2
                10 POP_TOP
                12 LOAD_CONST               0 (None)
                14 RETURN_VALUE
    >>> dis.dis(f2)
                0 LOAD_GLOBAL              0 (logger)
                2 LOAD_METHOD              1 (info)
                4 LOAD_CONST               1 ('This is an example of a log message, and a value of ')
                6 LOAD_CONST               2 (42)
                8 FORMAT_VALUE             0
                10 BUILD_STRING             2
                12 CALL_METHOD              1
                14 POP_TOP
                16 LOAD_CONST               0 (None)
                18 RETURN_VALUE

In this case we won’t get into much details, it is enough to see that f-strings add two additional operations of FORMAT_VALUE (Handles f-string value formatting.) and BUILD_STRING.

After this small research I can explain why we should not be using f-strings in this specific place which is logging. I also can put my uneasiness to rest.