Deferring Log Message Construction-Formatting

When I started to dive into Kotlin, among many surprising pieces of code I remember coming across some strange loggin code like this:

logger.debug { "Person location is: $formatLocation(p1.location)" }

So they are passing a lambda expression (that returns a string) to the debug() function rather than passing the string itself. OK, this makes good sense if formatting that string is expensive, cause if because of our log-level the message is not going to be printed, performing its expensive formatting is a waste of resources. So wrapping the string generation in a lambda is deferring the operation to the logger itself, so if it's not needed it won't be performed. The above code is using kotlin-logging a wrapper over sfl4j. You can read a nice article here.

I have not found any Python logging wrapper allowing that, but indeed the logging standard module partially provides the feature, and implementing the full feature is pretty simple. Let's see.

I was not aware that the different logging methods in the logger object can receive not just an string, but also a string and arguments. If that's the case, the library will apply "printf style" to that string and those arguments. That's nice and clever, but has some limitations. First, we have to use the old "printf style" syntax, rather than modern f-strings. Second, that's fine if we are just using the string formatting mini-language for the formatting, and if the arguments to be logged do not have to be calculated, cause in both cases that operation would be performed before invoking the logger, so not deferred and always executed.

logger.info("{%s} - {%s}", 24, 28)

So let's see how to overcome those limitations. Python has lambda expressions, so to get the same fully deferred behaviour that we have in Kotlin we would need a specialization of the logging.logger class with overriden methods accepting callables rather than strings. But that also involves some specialization of the logger creation itself, to return this logger rather than the standard one. While searching if such kind of wstuff already exists in some nice pip module (that does not seem so) I came across a simple, clever and very nice solution by means of a "LazyMessage" class. Well, it's a bit strange cause the code in that stackoverflow discussion is overriding the __format__ method in that class, that seems wrong, what you really have to override is the __str__ method. So we just need to wrap our messages in a lambda and an instance of LazyMessage

import logging

class LazyMessage(object):
    def __init__(self,func):
        self.func=func
    def __str__(self):
        return self.func()


logging.basicConfig(level=logging.INFO)
logger = logging.getLogger("log")

def get_price():
	print("getting price")
	return 1111

# these 2 calls won't be logged due to the log level
# but here the call to get get_price() is performed anyway
logger.debug(f"current price is {get_price()}")
# getting price

# while here thanks to LazyMessage we avoid the call to get_price()
logger.debug(LazyMessage(lambda: f"current price is {get_price()}"))

print("...........")

# these 2 calls get logged. We just verify that LazyMessage __str__ is invoked correctly
logger.info(f"current price is {get_price()}")
# getting price
# INFO:log:current price is 1111

logger.info(LazyMessage(lambda: f"current price is {get_price()}"))
# getting price
# INFO:log:current price is 1111

There's another related topic I'll mention here. f-strings are evaluated just at the point where they are declared. If we want to use them as a template that we declare somewhere (even in a template file) an we use later in differet places, we have to use a trick. We can use a normal string that mimics an f-string, and evaluate it later on just by using eval(). This is the python equivalent to what I discuss in this JavaScript and C# post from years ago.

def lazy_fstring(fst: str, **kargs) -> str:
    """receives a pseudo-fstring and performs the evaluation"""
    fst = 'f"""' + fst + '"""'
    return eval(fst)


# notice that this is not a real f-string, it lacks the initial f
fst = "{kargs['p1']} says hi to {kargs['p2']}"
msg = lazy_fstring(fst, p1="Xose", p2="Francois")
print(msg)