Ayúdame a comprender el módulo de registro de python y sus controladores

Question

Realmente extraño algo básico sobre el módulo de registro de Python.

En el siguiente código, creo un objeto logger (log) y le agrego dos manejadores. Uno con nivel 'INFO' y otro con nivel 'ADVERTENCIA'. Se supone que ambos deben imprimir en stdout. Espero que llamar a log.info(msg) resultará en una copia de msg en mi stdout y llamar a log.warn(msg) para obtener en dos copias de msg impresas en mi stdout. Aquí está el código:

import logging 
import sys 


logging.basicConfig() 
log = logging.getLogger('myLogger') 
log.handlers = [] 
h1 = logging.StreamHandler(sys.stdout) 
h1.level = logging.INFO 
h1.formatter = logging.Formatter('H1 H1 %(message)s ') 
h2 = logging.StreamHandler(sys.stdout) 
h2.level = logging.WARNING 
h2.formatter = logging.Formatter('H2 H2 %(message)s') 
log.addHandler(h1) 
log.addHandler(h2) 

print 'log.level == %s'%logging.getLevelName(log.level) 
print 'log.info' 
log.info('this is some info') 
print 'done' 
print 'log.warn' 
log.warn('this is a warning') 
print 'done' 

La salida es realmente muy extraña para mí. La llamada .info no produce ningún efecto visual. Sin embargo, llamar al warn da como resultado dos copias de msg impresas en stdout (lo cual está bien), pero también una copia impresa en stderr (¿por qué?). Este es el resultado del código anterior. Tenga en cuenta el formato de la última línea en esta salida. Esta línea está impresa en stderr.

log.level == NOTSET 
log.info 
done 
log.warn 
H1 H1 this is a warning 
H2 H2 this is a warning 
done 
WARNING:myLogger:this is a warning 

Así que mis preguntas son:

1. ¿Por qué mi llamada a info resultado en ninguna salida, a pesar de que el nivel h1 's es INFO?
2. ¿por qué mi llamada al warn da como resultado una salida adicional a stderr?

Answer 1

Hay dos cosas que usted necesita saber:

1. El registrador de raíz se inicializa con un nivel de WARNING.

   Cualquier mensaje de registro que llegue a un registrador se descarta si su nivel está por debajo del nivel del registrador. Si el nivel de un registrador no está establecido, tomará su "nivel efectivo" de su registrador padre. Entonces, si el registrador de raíz tiene un nivel de WARNING, todos los registradores tienen un nivel efectivo predeterminado de WARNING.Si no lo configura de otra manera, se descartarán todos los mensajes de registro con un nivel inferior.

2. Cuando llame al basicConfig(), el sistema configura automáticamente un StreamHandler en el registrador raíz que imprime al flujo de error estándar.

   Cuando su programa imprime los mensajes de registro, en realidad hay tres manipuladores: los dos que ha agregado, que tienen sus propios niveles, y otra del sistema que va a imprimir cualquier mensaje no rechazados por su registrador. Es por eso que obtiene la línea

   WARNING:myLogger:this is a warning 
   

   Procede del registrador de sistema. No hace esto para el mensaje de nivel INFO, porque como se comentó anteriormente, el registrador de raíz está configurado para rechazar esos mensajes de forma predeterminada.

   Si no desea esta salida, no llame al basicConfig().

Más información: http://docs.python.org/howto/logging.html

Answer 2

En realidad, hay cinco niveles de registro: depuración, información, advertencia, error y crítico. Veo que cuando configuras tu registrador no estás configurando explícitamente tu nivel: creo que el registrador puede establecer una advertencia por defecto si el nivel no está establecido.

En cuanto a por qué se imprime varias veces para advertencia, creo que esto se debe a la creación de dos controladores para información & advertencia. Lo que sucede es que el logger cae en cascada desde la advertencia -> info -> depurar, llamando al manejador de cada uno. Como su nivel está configurado como advertencia, se ignora el controlador de información. Además, creo que los mensajes de advertencia normalmente se escriben en sys.stderr.

intente lo siguiente:

logging.basicConfig(level=logging.INFO) 

Ver también:

• Logging module docs
• Logging basic example