Blog // Exirel.me

Python logging et héritage de loggers

Par Florian Strzelecki - 22:20 - 02.11.2014

Tags : Python, Documentation, Programmation, logging

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 :

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 :

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 :

  1. Le logger main.part reçoit un message de niveau INFO, qu'il peut traiter car au bon niveau de log. Il l'envoie alors à son handler pour en traiter l'émission.
  2. Son handler s'appelle console_long, et ce dernier utiliser un formateur spécifique, qui affiche les messages.
  3. Le logger main.part reprend la main et regarde son paramètre de propagation : il vaut True (la valeur par défaut), il transmet donc à son logger parent main.
  4. Le logger main reçoit le message, qu'il peut traiter aussi. Il l'envoie donc à son propre handler.
  5. 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 ?

  1. Le logger main.part reçoit un message de niveau INFO, qu'il peut traiter car au bon niveau de log. Il l'envoie alors à son handler pour en traiter l'émission.
  2. Son handler s'appelle console_long, et ce dernier utiliser un formateur spécifique, qui affiche les messages.
  3. Le logger main.part reprend la main et regarde son paramètre de propagation : il vaut False, 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.