Python logging et héritage de loggers
Par Florian Strzelecki -
Prenons un exemple simple, un fichier log.py
qui va définir deux loggers : main
et main.part
. Ces loggers pourraient très bien être définis dans un package main
et son sous-module part
. Pour l'exemple, nous allons faire beaucoup plus simple :
from logging import getLogger
from logging.config import dictConfig
if __name__ == '__main__':
dictConfig({
'version': 1,
'handlers': {
'console': {
'level': 'INFO',
'class': 'logging.StreamHandler'
}
},
'loggers': {
'main': {
'level': 'INFO',
'handlers': ['console', ],
}
}
})
main = getLogger('main')
part = getLogger('main.part')
main.info('My message on the main logger.')
part.info('And my second message on the main.part logger.')
Ici, il y a donc :
- Un logger qui s'appelle
main
, - Un logger qui s'appelle
main.part
, - Une configuration du logger
main
qui va utiliser unhandler
appeléconsole
(pour afficher les messages sur la console).
Si vous faites python log.py
c'est ceci qui devrait s'afficher dans votre console :
$ python log.py
My message on the main logger.
And my second message on the main.part logger.
Sauf que si vous retirez la partie dictConfig
de ce bout de code, plus rien ne s'affiche. Il y a donc bien quelque chose à regarder de ce côté là.
Héritage des loggers
Sans rentrer dans les détails, le dictionnaire utilisé permet de configurer les loggers. Si vous regardez bien, vous pouvez voir une ligne pour le logger main
, il n'y en a aucune pour le logger main.part
. Cependant, les deux fonctionnent très bien, et leurs messages s'affichent tous les deux : c'est grâce au mécanisme d'héritage des loggers que cela est possible.
Vous pouvez toujours aller voir le code du module logging
de python pour comprendre, mais voici en résumé ce qu'il en est :
- Un logger "hérite" d'un logger parent si son nom est composé du nom du parent puis de son nom, le tout concaténé par un point (comme dans
main.part
, qui hérite donc demain
). - Un logger peut hériter d'un logger qui hérite d'un autre. Par exemple,
main.part.sub
hérite demain.part
, qui hérite lui-même demain
. - À chaque fois qu'un message est donné au logger fils, il va le traiter, puis le donner à son parent (s'il existe).
- Le parent de tous les loggers s'appelle
root
. Il est défini automatiquement et dispose d'un comportement un peu à part (qui ne sera pas abordé ici, restons à des choses plus simples).
Donc, lorsque vous configurez le logger main
, vous configurez en même temps tous ses fils : main.part
, mais n'importe quel logger dont le nom commence par main.
utilisera cette configuration.
Changement de niveau
Maintenant que vous connaissez cet héritage de logger, vous pouvez jouer un peu avec, et simplifier grandement votre configuration de logs. Mais disons que vous ayez envie de logger uniquement les erreurs dans main
, mais de logger aussi les informations (voire les messages de debug, ce sera le même principe) avec le logger main.part
. Voici ce que vous pourriez commencer par faire :
dictConfig({
'version': 1,
'handlers': {
'console': {
'level': 'INFO',
'class': 'logging.StreamHandler'
}
},
'loggers': {
'main': {
'level': 'ERROR',
'handlers': ['console', ],
},
'main.part': {
'level': 'INFO',
}
}
})
Puis en appelant ces lignes :
main.info('My message on the main logger (should not be displayed).')
main.error('My error message on the main logger (should be displayed)')
part.info('And my second message on the main.part logger (should be displayed).')
Vous obtiendrez cette sortie console :
$ python log.py
My error message on the main logger (should be displayed)
And my second message on the main.part logger (should be displayed).
Ainsi, le message d'erreur est affiché, mais pas le message d'information pour le logger main
. Le logger main.part
quant à lui continue d'afficher ses messages d'information.
Formatage des messages et propagation
Bon, mais prenons un cas plus complexe : vous pourriez avoir envie de formater vos messages différemment en fonction du logger - et ce pour une raison qui vous est propre, je ne juge pas de vos motivations, chacun logue comme il l'entend.
Pour formater un message, il faut définir un "formatter", et l'utiliser dans un "handler". Ce qui se fait de cette façon :
dictConfig({
'version': 1,
'formatters': {
'brief': {
'format': '[BRIEF] %(levelname)s %(message)s',
},
},
'handlers': {
'console': {
'level': 'INFO',
'class': 'logging.StreamHandler',
'formatter': 'brief',
},
},
'loggers': {
'main': {
'level': 'ERROR',
'handlers': ['console', ],
},
'main.part': {
'level': 'INFO',
}
}
})
Ce qui va donner cette sortie :
$ python log.py
[BRIEF] ERROR My error message on the main logger (should be displayed)
[BRIEF] INFO And my second message on the main.part logger (should be displayed).
Ce qui n'est pas encore ce que nous voulons : il nous faut un nouveau formateur qui va afficher des informations supplémentaires (la date et le nom du logger) et l'utiliser pour le logger main.part
:
dictConfig({
'version': 1,
'formatters': {
'brief': {
'format': '[BRIEF] %(levelname)s %(message)s',
},
'long': {
'format': '[LONG] %(levelname)s %(asctime)s %(name)s %(message)s'
}
},
'handlers': {
'console': {
'level': 'INFO',
'class': 'logging.StreamHandler',
'formatter': 'brief',
},
'console_long': {
'level': 'INFO',
'class': 'logging.StreamHandler',
'formatter': 'long',
}
},
'loggers': {
'main': {
'level': 'ERROR',
'handlers': ['console', ],
},
'main.part': {
'level': 'INFO',
'handlers': ['console_long', ],
}
}
})
Vous pouvez noter que l'usage du formatter
se fait au niveau du handler
, et qu'il faut donc utiliser ce handler
dans le logger.
Ce qui va nous donner ceci en terme de sortie :
$ python log.py
[BRIEF] ERROR My error message on the main logger (should be displayed)
[LONG] INFO 2014-11-02 22:03:33,174 main.part And my second message on the main.part logger (should be displayed).
[BRIEF] INFO And my second message on the main.part logger (should be displayed).
Or, ce n'est pas tout à fait ce que nous voulons : le message du logger main.part
est affiché deux fois ! Voici ce qui s'est produit :
- Le logger
main.part
reçoit un message de niveauINFO
, qu'il peut traiter car au bon niveau de log. Il l'envoie alors à sonhandler
pour en traiter l'émission. - Son
handler
s'appelleconsole_long
, et ce dernier utiliser un formateur spécifique, qui affiche les messages. - Le logger
main.part
reprend la main et regarde son paramètre de propagation : il vautTrue
(la valeur par défaut), il transmet donc à son logger parentmain
. - Le logger
main
reçoit le message, qu'il peut traiter aussi. Il l'envoie donc à son proprehandler
. - C'est donc
console
qui traite cette fois-ci le message, et l'affiche aussi à son tour.
Il est possible de résoudre ce problème en utilisant le paramètre propagate
du logger main.part
, pour lui dire de ne pas transmettre ses messages au logger parent :
dictConfig({
# ... formatters and handlers sections ...
# ... loggers section ...
'main.part': {
'level': 'INFO',
'handlers': ['console_long', ],
'propagate': False,
}
# ...
$ python log.py
[BRIEF] ERROR My error message on the main logger (should be displayed)
[LONG] INFO 2014-11-02 22:07:33,359 main.part And my second message on the main.part logger (should be displayed).
Et voilà ! Mais que s'est-il passé exactement ?
- Le logger
main.part
reçoit un message de niveauINFO
, qu'il peut traiter car au bon niveau de log. Il l'envoie alors à sonhandler
pour en traiter l'émission. - Son
handler
s'appelleconsole_long
, et ce dernier utiliser un formateur spécifique, qui affiche les messages. - Le logger
main.part
reprend la main et regarde son paramètre de propagation : il vautFalse
, il ne transmet donc rien à son parent, qui n'est donc jamais appelé.
C'est donc sur le passage au logger parent que le paramètre propagate
agit. Et avec ça, vous pouvez déjà faire beaucoup de choses - à votre convenance, comme toujours.