Usando functools.wraps con un decorador de registro

Question

Estoy tratando de escribir un decorador simple que registra una declaración dada antes de llamar a la función decorada. Las declaraciones registradas deberían parecer que provienen de la misma función, que pensé que era el propósito de functools.wraps().

¿Por qué el siguiente código:

import logging 
logging.basicConfig(
    level=logging.DEBUG, 
    format='%(funcName)20s - %(message)s') 

from functools import wraps 

def log_and_call(statement): 
    def decorator(func): 
     @wraps(func) 
     def wrapper(*args, **kwargs): 
      logging.info(statement)    
      return func(*args, **kwargs) 
     return wrapper 
    return decorator 


@log_and_call("This should be logged by 'decorated_function'") 
def decorated_function(): 
    logging.info('I ran') 

decorated_function() 

dan lugar a estados de registro como:

   wrapper - This should be logged by 'decorated_function' 
    decorated_function - I ran 

pensé que la llamada a envolturas renombraría envoltorio con el nombre de decorated_function.

Estoy usando python 2.7.1.

Answer 1

Desafortunadamente logging usa el objeto de código de función para inferir el nombre. Podría solucionar esto utilizando el argumento de palabra clave extra para especificar algunos atributos adicionales para el registro, que luego podría usar durante el formateo. Se podría hacer algo como:

logging.basicConfig(
    level=logging.DEBUG, 
    format='%(real_func_name)20s - %(message)s', 
) 

... 

logging.info(statement, extra={'real_func_name': func.__name__}) 

La única desventaja de este enfoque es que usted tiene que pasar en el diccionario extra cada vez. Para evitar que se podría utilizar un formateador personalizado y lo han anular funcName:

import logging 
from functools import wraps 

class CustomFormatter(logging.Formatter): 
    """Custom formatter, overrides funcName with value of name_override if it exists""" 
    def format(self, record): 
     if hasattr(record, 'name_override'): 
      record.funcName = record.name_override 
     return super(CustomFormatter, self).format(record) 

# setup logger and handler 
logger = logging.getLogger(__file__) 
handler = logging.StreamHandler() 
logger.setLevel(logging.DEBUG) 
handler.setLevel(logging.DEBUG) 
handler.setFormatter(CustomFormatter('%(funcName)20s - %(message)s')) 
logger.addHandler(handler) 

def log_and_call(statement): 
    def decorator(func): 
     @wraps(func) 
     def wrapper(*args, **kwargs): 
      # set name_override to func.__name__ 
      logger.info(statement, extra={'name_override': func.__name__}) 
      return func(*args, **kwargs) 
     return wrapper 
    return decorator 

@log_and_call("This should be logged by 'decorated_function'") 
def decorated_function(): 
    logger.info('I ran') 

decorated_function() 

cual hace lo que quiere:

% python logging_test.py 
    decorated_function - This should be logged by 'decorated_function' 
    decorated_function - I ran 

Answer 2

Sospecho que el módulo de registro utiliza el atributo __name__ en un objeto de función. Eso no suele cambiar, incluso si se asigna la función a otro nombre ... te gustaría ver los mismos resultados haciendo algo como:

def foo() 
    logging.info("in foo") 
bar = foo 
bar() 

Usted recibirá foo - in foo, no bar - in foo cuando se llama a la barra.

Los decoradores están haciendo algo similar bajo el capó.

Answer 3

A diferencia de usted puede sospechar, la tala de árboles. funciones no utilice el atributo __name__. Esto implica usar @wraps (o configurar el __name__ del contenedor manualmente) ¡no funciona!

En su lugar, se muestra el nombre del programa, el marco de llamada. Contiene una lista de código-elementos (básicamente la pila). Allí se lee el nombre de la función, así como el nombre del archivo y el número de línea. Cuando se utiliza un decorador de registros, el nombre de la envoltura siempre es impreso, ya que es el que llama al registro.

BTW. El registro. nivel() funciona llamando a logging._log(*level*, ...), que llama a otras funciones (registro) también. Que todos terminan en la pila. Para evitar que se muestren esas funciones de registro, se busca en la lista de marcos la primera función (más baja) cuyo nombre de archivo no es parte de 'registro'. Esa debería ser la verdadera función de registro: el registrador de llamadas. func().

Lamentablemente, es wrapper.

Sería, sin embargo, será posible utilizar un registro de decorador: cuando forma parte del archivo de origen de registro. Pero no hay ninguno (todavía)