Python best practice when logging optional arguments

Question

I have a method that accepts one or more optional arguments and I'd like to log them, following the best practice of lazy interpolation of log values:

def frobnicate(a: str, b: int, c: typing.Optional[float] = None):
    # note: c = None actually means absence of data, it's not a placeholder for a default value
    mylogger.debug('frobnicate(%s, %d, %.2f)', a, b, c)

Of course that code snipped doesn't work for c = None because it chokes on the %f.

My best solution so far is formatting directly as string:

def frobnicate(a: str, b: int, c: typing.Optional[float] = None):
    mylogger.debug('frobnicate(%s, %d, %s)', a, b, c)

which semantically works and I use it most of the time, but has the problem of preventing control over the actual conversion of the not-None case. The latter could be done with something like this:

def frobnicate(a: str, b: int, c: typing.Optional[float] = None):
    mylogger.debug(
        'frobnicate(%s, %d, %s)', a, b,
        f"{c:.2f}" if isinstance(c, float) else str(c)
    )

This latter version is not only defeating lazy evaluation of logging arguments (because it is converting to string beforehand) but also making it worse with an additional isinstance() check. I also find it a little ugly style-wise but that could be me :)

My current opinion here is that if we want to strictly adhere to lazy evaluation we have to stay within the limitations of %-based string formatting and AFAIK there is not a way to express "use this format if not None else tell me it's None". In the end it's either a choice between "accept whatever conversion format is the default" and "sacrifice lazy evaluation in exchange of control over string formatting".

I would like to know if my solution is aligned with general consensus or if anyone has a better take on this, maybe I'm missing some think-out-of-the-box stuff.

Answer 1

Like @RichardNeumann said, you can delegate the formatting and logging to a decorator. Something like:

def log_this(func):
    def f(*args):
        # Here we build the string from the arguments
        args_str = '('
        for arg in args:
            if isinstance(arg, float):
                args_str += '%.2f' % arg
            elif isinstance(arg, int):
                args_str += '%d' % arg
            elif isinstance(arg, str):
                args_str += '"%s"' % arg
            else:
                args_str += '%s' % arg
            args_str += ', '
        args_str = args_str[:-2] + ')'
        # Then we print the string
        print(f'Attempting call: {func.__name__}{args_str}')
        # Finally, we call the wrapped function
        return func(*args)
    return f

And then use it like this:

@log_this
def add(a, b, foo=None):
    if foo is None:
        return 0
    return a + b
    
add(1, 2)
# output: Attempting call: add(1, 2)

add(1.5, 3.82)
# output: Attempting call: add(1.50, 3.82)

add('foo', 'bar')
# output: Attempting call: add("foo", "bar")

add('x', 'y', None)
# output: Attempting call: add("x", "y", None)

Here I am simply printing the call with the positional arguments to stdout, but you can easily adapt this to work with Python's loggers and keyword arguments as well. Then you just need to decorate all functions that you wish to log.

Answer 2

For logging, I would generally not want to simply convert values to strings, but use repr to get a representation.

I agree with @jfaccioni that you probably want to use a decorator to prevent code duplication for every place you want to log like this.

To have control over the representations of different types, I suggest using reprlib, like so:

from reprlib import Repr
from functools import wraps
from collections.abc import Callable
import typing

P = typing.ParamSpec('P')
T = typing.TypeVar('T')

class DebugLogRepr(Repr):
    def repr_float(self, obj: float, level: int) -> str:
        return f"{obj:.2f}"

debugLogRepr = DebugLogRepr()

def log_arguments(f: Callable[P, T]) -> Callable[P, T]:
    @wraps(f)
    def wrapped_f(*args):
        mylogger.debug('%s%s', f.__name__, debugLogRepr.repr(args))
        return f(*args)
    return wrapped_f

@log_arguments
def frobnicate(a: str, b: int, c: typing.Optional[float] = None):
    ...

This makes use of the fact that args is a tuple to automatically format all the arguments.

Sadly, I don't think there is a good way to avoid formatting the arguments if it is not needed to do so.

Note that like @jfaccioni's answer, it only supports positional arguments, but it's easy enough to extend it to allow keyword arguments.

Answer 3

I wouldn't bother in the short term and just use locals():

log.debug('frobnicate(%r)', locals())

However, if you wanted something more 'professional' for the long term, I'd just log the whole tuple of args at once:

log.debug('frobnicate%r', (a, b, c))

This second one won't give you the variable names, but you can deduce them by their order.