La mejor manera de anular lineno en el registrador Python

He escrito un decorador que registra los argumentos utilizados para llamar a una función o método en particular. Como se muestra a continuación, funciona bien, excepto que el número de línea indicado en el logRecord es el número de línea del decorador en lugar del número de línea de la func que se está ajustando:

 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) 

Esta muestra da como resultado el siguiente resultado.

 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(, 1, c=3, b=2) 

Tenga en cuenta que todos los números de línea apuntan al decorador.

Con inspect.getsourcelines(func) puedo obtener el número de línea que me interesa, pero un bash de lineno en logger.debug produce un error. ¿Cuál es el mejor método para lograr que el número de línea de la función ajustada aparezca en la statement de registro?

Como señala Martijn, las cosas a veces cambian. Sin embargo, ya que estás usando Python 2 (los iteritems lo regalaron), el siguiente código funcionará si no te importa el registro de parches de mono:

 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() 

Otra posibilidad es subclase Logger para anular Logger.makeRecord . Este es el método que genera un KeyError si intenta cambiar cualquiera de los atributos estándar (como rv.lineno ) en el 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] 

Al eliminar esta precaución, podemos anular el valor de lineno al proporcionar un argumento extra a la llamada 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) 

rendimientos

 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) 

La línea

  UpdateableLogger = type('UpdateableLogger', (type(logger),), dict(makeRecord=makeRecord)) 

crea una nueva clase que es una subclase de type(logger) que reemplaza a makeRecord . Dentro de return_func , la clase del logger se cambia a UpdateableLogger para que la llamada a logger.log pueda modificar lineno y luego se restaure la clase del registrador original.

Al hacerlo de esta manera, evitando el parcheo de Logger.makeRecord , todos los logger comportan exactamente como antes de las funciones decoradas.


A modo de comparación, el enfoque de parcheo de monos se muestra aquí .

No puede cambiar fácilmente el número de línea, porque el método Logger.findCaller() extrae esta información a través de la introspección.

Podría reconstruir la función y codificar los objetos para la función de envoltura que genera, pero eso es muy delicado (vea los pasos que I y Veedrac saltan a través de esta publicación ) y dará lugar a problemas cuando tenga un error, como su rastreador. mostrará las líneas de origen incorrectas!

Sería mejor agregar el número de línea, así como el nombre de su módulo (ya que también puede diferir) a su salida de registro manualmente:

 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) 

Como siempre tiene una función aquí, utilicé un poco más de introspección directa para obtener el primer número de línea para la función, a través del código asociado.