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?
Another possibility is to subclass Logger
to override Logger.makeRecord
. This is the method that raises a KeyError
if you try to change any of the standard attributes (like rv.lineno
) in the LogRecord
:
for key in extra:
if (key in ["message", "asctime"]) or (key in rv.__dict__):
raise KeyError("Attempt to overwrite %r in LogRecord" % key)
rv.__dict__[key] = extra[key]
By removing this precaution, we can override the lineno value by supplying an
extra
argument to the logger.log
call:
logger.log(level, msg, extra=dict(lineno=line_no))
from functools import wraps
import inspect
import logging
arg_log_fmt = "{name}({arg_str})"
def makeRecord(self, name, level, fn, lno, msg, args, exc_info, func=None, extra=None):
"""
A factory method which can be overridden in subclasses to create
specialized LogRecords.
"""
rv = logging.LogRecord(name, level, fn, lno, msg, args, exc_info, func)
if extra is not None:
rv.__dict__.update(extra)
return rv
def log_args(logger, level=logging.DEBUG, cache=dict()):
"""Decorator to log arguments passed to func."""
logger_class = logger.__class__
if logger_class in cache:
UpdateableLogger = cache[logger_class]
else:
cache[logger_class] = UpdateableLogger = type(
'UpdateableLogger', (logger_class,), dict(makeRecord=makeRecord))
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.__class__ = UpdateableLogger
try:
logger.log(level, msg, extra=dict(lineno=line_no))
finally:
logger.__class__ = logger_class
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)
yields
2015-09-07 16:01:22,332 DEBUG [__main__: 48] foo(1, 2, z=3)
2015-09-07 16:01:22,332 DEBUG [__main__: 48] foo(1, 2, 3)
2015-09-07 16:01:22,332 DEBUG [__main__: 48] foo(y=2, x=1, z=3)
2015-09-07 16:01:22,332 DEBUG [__main__: 53] baz(<__main__.Bar object at 0x7f17f75b0490>, 1, c=3, b=2)
The line
UpdateableLogger = type('UpdateableLogger', (type(logger),),
dict(makeRecord=makeRecord))
creates a new class which is a subclass of type(logger)
which overrides makeRecord
.
Inside return_func
, the logger
's class is changed to UpdateableLogger
so the call to logger.log
can modify lineno
and then the original logger class is restored.
By doing it this way -- by avoiding monkey-patching Logger.makeRecord
-- all logger
s behave exactly as before outside the decorated functions.
For comparison, the monkey-patching approach is shown here.
If you love us? You can donate to us via Paypal or buy me a coffee so we can maintain and grow! Thank you!
Donate Us With