Best way to override lineno in Python logger

Question

I wrote a decorator that registers the arguments used to call a particular function or method. As shown below, it works well, except that the line number specified in logRecord is the decorator line number, not the func line number that is 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 example leads to the following conclusion.

 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 line numbers all point to the decorator.

With inspect.getsourcelines(func) I can get the line number that interests me, but trying to rewrite lineno in logger.debug results in an error. What is the best approach so that the line number of the wrapped function appears in the registration statement?

Answer 1

As Martijn points out, things change sometimes. However, since you are using Python 2 (iterators returned it), the following code will work if you don't mind when logging monkeys:

 from functools import wraps import logging class ArgLogger(object): """ Singleton class -- will only be instantiated once because of the monkey-patching of logger. """ singleton = None def __new__(cls): self = cls.singleton if self is not None: return self self = cls.singleton = super(ArgLogger, cls).__new__(cls) self.code_location = None # Do the monkey patch exactly one time def findCaller(log_self): self.code_location, code_location = None, self.code_location if code_location is not None: return code_location return old_findCaller(log_self) old_findCaller = logging.Logger.findCaller logging.Logger.findCaller = findCaller return self def log_args(self, logger, level=logging.DEBUG): """Decorator to log arguments passed to func.""" def inner_func(func): co = func.__code__ code_loc = (co.co_filename, co.co_firstlineno, co.co_name) @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 = "{name}({arg_str})".format(name=func.__name__, arg_str=", ".join(arg_list)) self.code_location = code_loc logger.log(level, msg) return func(*args, **kwargs) return return_func return inner_func log_args = ArgLogger().log_args 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 def test_regular_log(): logger.debug("Logging without ArgLog still works fine") 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) test_regular_log() 

Answer 2

Another possibility is to subclass Logger to override Logger.makeRecord . This is the method that calls KeyError if you try to change any of the standard attributes (e.g. rv.lineno ) in 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 providing extra to call logger.log :

 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) 

gives

 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) 

---

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 class is changed to UpdateableLogger , so calling logger.log can change lineno , and then the original logger class will be restored.

Doing this this way: avoiding the monkey patches Logger.makeRecord - all Logger behave exactly the same as before outside the decorated functions.

---

For comparison, this approach is shown here .

Answer 3

You cannot easily change the line number because the Logger.findCaller() method retrieves this information through introspection.

You can rebuild the function and code objects for the wrapper function you are creating, but it is really very hairy (see the hoops and Veedrac going to this post ) and will lead to problems when you have an error, since your trace will show incorrect source lines .

You better add the line number as well as the name of your module (as this can also be very different) to your journal output manually:

 arg_log_fmt = "{name}({arg_str}) in {filename}:{lineno}" # ... codeobj = func.__code__ msg = arg_log_fmt.format( name=func.__name__, arg_str=", ".join(arg_list), filename=codeobj.co_filename, lineno=codeobj.co_firstlineno) 

Since you always have a function, I used more direct introspection to get the first line number for this function through the associated code object.

Answer 4

This is an old post, but this answer may still be useful for someone else.

One problem with existing solutions is that there are several options that provide the logging context , and all of them must be fixed if you want to support arbitrary logging formatting tools.

It turns out that this arose as a problem with the Python log library about a year ago , and as a result, the stacklevel keyword argument was added in Python 3.8 . With this function, you can simply change your log call to set the stack level to 2 (one level higher, where in your example logger.log ):

 logger.log(level, msg, stacklevel=2) 

Since Python 3.8 has not yet been released (at the time of receiving this answer), you can findCaller your logger using findCaller and _log updated in Python 3.8 .

I have a utility logging library called logquacious , where I do the same thing as patches for monkeys. You can reuse the patch_logger class that I defined in logquacious, and update the above logging example:

 from logquacious.backport_configurable_stacklevel import patch_logger logger = logging.getLogger(__name__) logger.__class__ = patch_logger(logger.__class__) 

As already mentioned in unutbu's answer, it would be nice to undo this patch of monkeys outside the area in which it was used, which is what some other code in this file does.