mensajes de registro que aparecen dos veces con Python Logging

Estoy usando el registro de Python y, por alguna razón, todos mis mensajes aparecen dos veces.

Tengo un módulo para configurar el registro:

# BUG: It's outputting logging messages twice - not sure why - it's not the propagate setting.
def configure_logging(self, logging_file):
    self.logger = logging.getLogger("my_logger")
    self.logger.setLevel(logging.DEBUG)
    self.logger.propagate = 0
    # Format for our loglines
    formatter = logging.Formatter("%(asctime)s - %(name)s - %(levelname)s - %(message)s")
    # Setup console logging
    ch = logging.StreamHandler()
    ch.setLevel(logging.DEBUG)
    ch.setFormatter(formatter)
    self.logger.addHandler(ch)
    # Setup file logging as well
    fh = logging.FileHandler(LOG_FILENAME)
    fh.setLevel(logging.DEBUG)
    fh.setFormatter(formatter)
    self.logger.addHandler(fh)

Más adelante, llamo a este método para configurar el registro:

if __name__ == '__main__':
    tom = Boy()
    tom.configure_logging(LOG_FILENAME)
    tom.buy_ham()

Y luego, dentro de, digamos, el módulo buy_ham, llamaría:

self.logger.info('Successfully able to write to %s' % path)

Y por alguna razón, todos los mensajes aparecen dos veces. Comenté uno de los controladores de transmisión, sigue siendo lo mismo. Un poco extraño, no estoy seguro de por qué sucede esto ... jajaja. Suponiendo que me haya perdido algo obvio.

Saludos, Victor

Está llamando configure_loggingdos veces (tal vez en el __init__método de Boy): getLoggerdevolverá el mismo objeto, pero addHandlerno verifica si ya se ha agregado un controlador similar al registrador.

Intente rastrear llamadas a ese método y eliminar uno de estos. O configure una bandera logging_initializedinicializada a Falseen el __init__método de Boyy cambie configure_loggingpara no hacer nada si lo logging_initializedestá True, y para configurarla Truedespués de haber inicializado el registrador.

Si el programa crea varios Boycasos, usted tiene que cambiar la forma de hacer las cosas con un global de configure_loggingla función de la adición de los controladores y el Boy.configure_loggingmétodo sólo inicializar el self.loggeratributo.

Otra forma de resolver esto es verificando el atributo de manejadores de su registrador:

logger = logging.getLogger('my_logger')
if not logger.handlers:
    # create the handlers and call logger.addHandler(logging_handler)

Si está viendo este problema y no está agregando el controlador dos veces, vea la respuesta de abarnert aquí

De los documentos :

Nota: si adjunta un controlador a un registrador y uno o más de sus antepasados, puede emitir el mismo registro varias veces. En general, no debería necesitar adjuntar un controlador a más de un registrador; si simplemente lo adjunta al registrador apropiado que está más alto en la jerarquía del registrador, verá todos los eventos registrados por todos los registradores descendientes, siempre que se propaguen el ajuste se deja establecido en Verdadero. Un escenario común es adjuntar controladores solo al registrador raíz y dejar que la propagación se encargue del resto.

Entonces, si desea un controlador personalizado en "prueba", y no desea que sus mensajes también vayan al controlador raíz, la respuesta es simple: desactive su indicador de propagación:

logger.propagate = Falso

El controlador se agrega cada vez que llama desde el exterior. Intente quitar el controlador después de terminar su trabajo:

self.logger.removeHandler(ch)

Soy un novato en Python, pero esto pareció funcionar para mí (Python 2.7)

while logger.handlers:
     logger.handlers.pop()

En mi caso, lo configuraría logger.propagate = Falsepara evitar la doble impresión.

En el siguiente código, si lo elimina logger.propagate = False, verá una impresión doble.

import logging
from typing import Optional

_logger: Optional[logging.Logger] = None

def get_logger() -> logging.Logger:
    global _logger
    if _logger is None:
        raise RuntimeError('get_logger call made before logger was setup!')
    return _logger

def set_logger(name:str, level=logging.DEBUG) -> None:
    global _logger
    if _logger is not None:
        raise RuntimeError('_logger is already setup!')
    _logger = logging.getLogger(name)
    _logger.handlers.clear()
    _logger.setLevel(level)
    ch = logging.StreamHandler()
    ch.setLevel(level)
    # warnings.filterwarnings("ignore", "(Possibly )?corrupt EXIF data", UserWarning)
    ch.setFormatter(_get_formatter())
    _logger.addHandler(ch)
    _logger.propagate = False # otherwise root logger prints things again


def _get_formatter() -> logging.Formatter:
    return logging.Formatter(
        '[%(asctime)s] [%(name)s] [%(levelname)s] %(message)s')

Una llamada a las logging.debug()llamadas logging.basicConfig()si no hay controladores raíz instalados. Eso me estaba sucediendo en un marco de prueba en el que no podía controlar el orden en que se activaban los casos de prueba. Mi código de inicialización estaba instalando el segundo. El predeterminado usa logging.BASIC_FORMAT que no quería.

Parece que si envía algo al registrador (accidentalmente) y luego lo configura, es demasiado tarde. Por ejemplo, en mi código tenía

logging.warning("look out)"

...
ch = logging.StreamHandler(sys.stdout)
root = logging.getLogger()
root.addHandler(ch)

root.info("hello")

Obtendría algo como (ignorando las opciones de formato)

look out
hello
hello

y todo se escribió en stdout dos veces. Creo que esto se debe a que la primera llamada a logging.warningcrea un nuevo controlador automáticamente y luego agregué explícitamente otro controlador. El problema desapareció cuando eliminé la primera logging.warningllamada accidental .

Me estaba dando una situación extraña en la que los registros de la consola se duplicaban, pero los registros de mis archivos no. Después de un montón de excavaciones, lo descubrí.

Tenga en cuenta que los paquetes de terceros pueden registrar registradores. Esto es algo a tener en cuenta (y en algunos casos no se puede prevenir). En muchos casos, el código de terceros comprueba si hay controladores de registro raíz existentes ; y si no lo hay, registran un nuevo controlador de consola.

Mi solución a esto fue registrar mi registrador de consola en el nivel raíz:

rootLogger = logging.getLogger()  # note no text passed in--that's how we grab the root logger
if not rootLogger.handlers:
        ch = logging.StreamHandler()
        ch.setLevel(logging.INFO)
        ch.setFormatter(logging.Formatter('%(process)s|%(levelname)s] %(message)s'))
        rootLogger.addHandler(ch)