Extraño: el registrador solo usa el formateador del primer controlador para las excepciones

Question

Me doy cuenta de que el módulo de registro se comporta de manera graciosa. Me estoy perdiendo de algo ?

Estoy haciendo lo habitual de tener dos controladores: un StreamHandler para registrar solo INFO y superior a la consola, y un FileHandler que también manejará toda la información de DEPURACIÓN.

Funcionó bien hasta que decidí tener un formato diferente para las excepciones. Quería un stacktrace completo en el archivo, pero solo el tipo de excepción y el valor en la consola. Dado que los manejadores tienen una función setFormatter, y dado que parece fácil escribir una subclase de registro. Por lo demás, pensé que funcionaría.

El controlador de la consola y el manejador de archivos tienen su propio formateador. Las instrucciones de impresión en el código lo demuestran. Sin embargo, la llamada a logger.exception solo usará el formato Excepción del primer controlador agregado => la excepción se registra en el archivo con el formato que debería tener en la consola. Cambia el orden de las líneas de logger.addHandler y luego está el formatException del controlador de archivos que se usa en todas partes.

import logging 
import sys 

class ConsoleFormatter(logging.Formatter): 
    def formatException(self, exc_info): 
     # Ugly but obvious way to see who's talking. 
     return "CONSOLE EXCEPTION %s: %s" % exc_info[:2] 

def setup(path): 
    logger = logging.getLogger() 
    # 
    file_handler = logging.FileHandler(path, mode='w') 
    if __debug__: 
     file_handler.setLevel(logging.DEBUG) 
    else: 
     file_handler.setLevel(logging.INFO) 
    formatter = logging.Formatter("%(asctime)s %(levelname)-8s " 
            "%(name)-16s %(message)s " 
            "[%(filename)s@%(lineno)d in %(funcName)s]") 
    file_handler.setFormatter(formatter) 

    # 
    console_handler = logging.StreamHandler(sys.stderr) 
    console_handler.setLevel(logging.INFO) 
    console_formatter = ConsoleFormatter("%(levelname)-8s - %(message)s") 
    console_handler.setFormatter(console_formatter) 

    # >>> FUN HAPPENS HERE <<< 
    # Only the formatter of the first handler is used ! Both on the console 
    # and in the file. Change the order of these two lines to see. 
    logger.addHandler(console_handler) 
    logger.addHandler(file_handler) 
    # 
    # Proof that the two handlers have different formatters: 
    print logger.handlers 
    print file_handler.formatter.formatException 
    print console_formatter.formatException 
    # 
    logger.setLevel(logging.DEBUG) 
    logger.info("Logger ready.") 

setup('test.log') 
logger = logging.getLogger() 
logger.debug("Only visible in the file.") 
try: 
    1/0 
except ZeroDivisionError: 
    logger.exception("boom") 

¿Qué está pasando?

EDITAR: Estoy usando python 2.6 por cierto. EDITAR: Typo en el código sobre el nombre de la variable "console_formatter" corregido.

Answer 1

He encontrado su problema! Si nos fijamos en logger/__init__.py en el código fuente de Formatter.format, en la línea 440 (por py2.6), verá lo siguiente:

 if record.exc_info: 
      # Cache the traceback text to avoid converting it multiple times 
      # (it's constant anyway) 
      if not record.exc_text: 
       record.exc_text = self.formatException(record.exc_info) 

Esto no es cierto en su caso, ya que está anulando formatException. Si comenta el if not record.exc_text (y corrige la sangría en consecuencia), parece funcionar como se esperaba.

El error parece ser que ya se informó aquí: http://bugs.python.org/issue6435

Answer 2

La primera vez que me encontré con su código, que tiene un rastreo:

Traceback (most recent call last): 
    File "logger.py", line 42, in <module> 
    setup('test.log') 
    File "logger.py", line 37, in setup 
    print console_formatter.formatException 
NameError: global name 'console_formatter' is not defined 

Eso es probablemente el origen del problema. Los formatos eran correctas cuando cambié el código console_handler:

console_handler = logging.StreamHandler(sys.stderr) 
console_handler.setLevel(logging.INFO) 
console_formatter = ConsoleFormatter("%(levelname)-8s - %(message)s") 
console_handler.setFormatter(console_formatter) 

Answer 3

Este es el código que se me ocurrió. Hace el trabajo :).

class CachelessFormatter(logging.Formatter): 
    # I came up with that after reading the answers to 
    #  http://stackoverflow.com/questions/5875225/ 
    # which pointed me to 
    #  http://bugs.python.org/issue6435 
    # I still think Vinay Sajip has a bit of an attitude :p. 
    def format(self, record): 
     # Disable the caching of the exception text. 
     backup = record.exc_text 
     record.exc_text = None 
     s = logging.Formatter.format(self, record) 
     record.exc_test = backup 
     return s 

class ConsoleFormatter(CachelessFormatter): 
    def formatException(self, exc_info): 
     return "   %s: %s" % exc_info[:2] 

def setup(path): 
    file_handler = logging.FileHandler(path, mode='w') 
    file_handler.setLevel(logging.DEBUG) 
    formatter = CachelessFormatter("%(asctime)s %(levelname)-8s " 
            "%(name)-16s %(message)s " 
            "[%(filename)s@%(lineno)d in %(funcName)s]") 
    file_handler.setFormatter(formatter) 

    console_handler = logging.StreamHandler(sys.stderr) 
    console_handler.setLevel(logging.INFO) 
    formatter = ConsoleFormatter("%(levelname)-8s - %(message)s") 
    console_handler.setFormatter(formatter) 

    logger = logging.getLogger() 
    logger.addHandler(file_handler) 
    logger.addHandler(console_handler) 
    if __debug__: 
     logger.setLevel(logging.DEBUG) 
    else: 
     logger.setLevel(logging.INFO) 
    logger.info("Logger ready.") 

if __name__ == '__main__': 
    setup('test.log') 
    logger = logging.getLogger() 
    logger.debug("Only shows in the file") 
    try: 
     1/0 
    except ZeroDivisionError: 
     pass 
    logger.exception("boom")