I have written a decorator which logs the arguments used to call a particular function or method. As shown below, it works well except that the line number reported in the logRecord is the line number of the decorator rather than the line number of func that is being wrapped:
from functools import wraps
import inspect
import logging
arg_log_fmt = "{name}({arg_str})"
def log_args(logger, level=logging.DEBUG):
"""Decorator to log arguments passed to func."""
def inner_func(func):
line_no = inspect.getsourcelines(func)[-1]
@wraps(func)
def return_func(*args, **kwargs):
arg_list = list("{!r}".format(arg) for arg in args)
arg_list.extend("{}={!r}".format(key, val)
for key, val in kwargs.iteritems())
msg = arg_log_fmt.format(name=func.__name__,
arg_str=", ".join(arg_list))
logger.log(level, msg)
return func(*args, **kwargs)
return return_func
return inner_func
if __name__ == "__main__":
logger = logging.getLogger(__name__)
handler = logging.StreamHandler()
fmt = "%(asctime)s %(levelname)-8.8s [%(name)s:%(lineno)4s] %(message)s"
handler.setFormatter(logging.Formatter(fmt))
logger.addHandler(handler)
logger.setLevel(logging.DEBUG)
@log_args(logger)
def foo(x, y, z):
pass
class Bar(object):
@log_args(logger)
def baz(self, a, b, c):
pass
foo(1, 2, z=3)
foo(1, 2, 3)
foo(x=1, y=2, z=3)
bar = Bar()
bar.baz(1, c=3, b=2)
This sample results in the following output
2015-09-07 12:42:47,779 DEBUG [__main__: 25] foo(1, 2, z=3)
2015-09-07 12:42:47,779 DEBUG [__main__: 25] foo(1, 2, 3)
2015-09-07 12:42:47,779 DEBUG [__main__: 25] foo(y=2, x=1, z=3)
2015-09-07 12:42:47,779 DEBUG [__main__: 25] baz(<__main__.Bar object at 0x1029094d0>, 1, c=3, b=2)
Note that the line numbers all point to the decorator.
With inspect.getsourcelines(func) I can get the line number I'm interested in, but an attempt to over-write lineno in logger.debug results in an error. What is the best approach to getting the line number of the wrapped function to appear in the logging statement?
Changes to the Python language starting in 3.8 have made some of the answers to this question moot. Thanks to @Tony S Yu for pointing out the change that makes this more idiomatic argument-logging decorator possible:
from functools import wraps
import logging
import os
import sys
def log_args(logger, level=logging.DEBUG, is_method=False):
"""Decorator to log arguments passed to func."""
def inner_func(func):
@wraps(func)
def return_func(*args, **kwargs):
arg_log_fmt = "{name}({arg_str})"
arg_list = []
if is_method: # get class name from arg[0]
class_name = args[0].__class__.__name__
arg_log_fmt = class_name + "." + arg_log_fmt
if len(args) > 1:
arg_list.extend("{!r}".format(arg) for arg in args[1:])
else:
arg_list.extend("{!r}".format(arg) for arg in args)
arg_list.extend("{}={!r}".format(key, val)
for key, val in kwargs.items())
msg = arg_log_fmt.format(name=func.__name__,
arg_str=", ".join(arg_list))
# set stacklevel=2 to get lineno from the file defining
# the function being wrapped, not this file. Needs Python >= 3.8
logger.log(level, msg, stacklevel=2)
return func(*args, **kwargs)
return return_func
return inner_func
if __name__ == "__main__":
logging.basicConfig(
level=logging.DEBUG,
format="%(levelname)-8.8s [%(name)s:%(lineno)4s] %(message)s"
)
logger = logging.getLogger(__name__)
@log_args(logger)
def foo(x, y, z):
pass
class Bar(object):
@log_args(logger, is_method=True)
def baz(self, *args, **kwargs):
pass
foo(1, 2, z=3)
bar = Bar()
bar.baz(1, c=3, b=2)
bar.baz()
With this output:
DEBUG [__main__: 48] foo(1, 2, z=3)
DEBUG [__main__: 51] Bar.baz(1, c=3, b=2)
DEBUG [__main__: 52] Bar.baz()