Blog // Exirel.me

Python logging et log level

Par Florian Strzelecki - 23:59 - 03.11.2014

Tags : Python, Documentation, Programmation, logging

Dans le précédent article, je parlais de l'héritage des loggers, technique très pratique pour mutualiser des comportements ou au contraire de les séparer. Vous avez pu voir comment faire en sorte que deux loggers n'utilisent pas le même niveau de log ou pas les mêmes handlers.

Un point que je n'ai pas abordé (parmi tant d'autres) est la gestion du niveau de log : il existe deux configurations de niveau, puis à l'usage il suffit de choisir la bonne méthode pour le bon niveau de log désiré. Certes, j'ai utilisé le niveau de log des loggers, mais je n'ai pas vraiment utilisé la notion de log level du handler.

Commençons donc par un exemple simple, cette fois-ci avec un seul logger ayant deux handlers :

from logging import getLogger
from logging.config import dictConfig

if __name__ == '__main__':

    dictConfig({
        'version': 1,
        'handlers': {
            'console': {
                'level': 'INFO',
                'class': 'logging.StreamHandler',
            },
            'file': {
                'level': 'INFO',
                'class': 'logging.FileHandler',
                'filename': 'log.txt'
            }
        },
        'loggers': {
            'main': {
                'level': 'INFO',
                'handlers': ['console', 'file'],
            },
        }
    })

    main = getLogger('main')

    main.info('My message.')
    main.error('My error message.')

Ce qui donne comme résultat :

$ python log.py
My message.
My error message.

Et dans le fichier log.txt vous retrouverez exactement les même messages.

Un debug console

Pour un besoin quelconque, vous pourriez vous retrouver à devoir utiliser le niveau de log DEBUG. C'est plutôt pratique lors d'une phase de développement sans avoir besoin de nécessairement utiliser pdb. Votre première idée pourrait être de configurer le logger main au niveau DEBUG, comme ceci :

dictConfig({
    # ... Handlers ...
    # ... Loggers ...
    'loggers': {
        'main': {
            'level': 'DEBUG',
            'handlers': ['console', 'file'],
        },
    }
})

Puis d'écrire les appels suivants :

main.info('My debug message.')
main.info('My message.')
main.error('My error message.')

Sauf que l'affichage dans la console ne changerait pas d'un iota : seuls les messages de niveau INFO et ERROR s'affichent, et le message de niveau DEBUG est ignoré. Voici ce qu'il se passe :

  1. Le logger main reçoit un message de niveau DEBUG, qu'il peut traiter car au bon niveau de log. Il l'envoie alors à ses handlers, les uns après les autres, pour en traiter l'émission.
  2. Le handler qui s'appelle console reçoit le message, mais ne le traite pas car son niveau est inférieur à son niveau configuré (on dit que DEBUG est inférieur à INFO).
  3. Le handler qui s'appelle file reçoit le message, mais ne le traite pas car son niveau est inférieur à son niveau configuré.

Ainsi, il est donc nécessaire de configurer le niveau des handlers. Voici ce que cela donne en configurant le handler console (en laissant file au niveau INFO) :

dictConfig({
    'version': 1,
    'handlers': {
        'console': {
            'level': 'DEBUG',
            'class': 'logging.StreamHandler',
        },
        'file': {
            'level': 'INFO',
            'class': 'logging.FileHandler',
            'filename': 'log.txt'
        }
    },
    'loggers': {
        'main': {
            'level': 'DEBUG',
            'handlers': ['console', 'file'],
        },
    }
})

Ce qui donnera comme sortie console :

$ python log.py
My debug message.
My message.
My error message.

Vous remarquerez d'ailleurs que le niveau d'un handler n'a aucun effet sur les autres : chacun est bien indépendant des uns et des autres. C'est ce qui explique pourquoi vous ne retrouverez pas le message de DEBUG dans le fichier log.txt.

Log level, logger, handler, et héritage

Maintenant que vous avez compris le principe du niveau de log entre les handlers et les loggers, et que vous avez des notions d'héritage de loggers, vous devriez être capable de trouver par vous-même comment utiliser le même handler pour deux loggers, tout en faisant en sorte qu'un seul des deux publie ses logs au niveau DEBUG.

Tout d'abord, écrivons les quelques lignes d'appels des logs :

main = getLogger('main')
part = getLogger('main.part')

main.debug('My debug message.')
main.info('My message.')
main.error('My error message.')

part.debug('My part debug message (should not be displayed).')
part.info('My part message.')
part.error('My part error message.')

Notre but, c'est d'obtenir ceci comme sortie console :

$ python log.py
My debug message.
My message.
My error message.
My part message.
My part error message.

Et ceci dans le fichier de log :

My message.
My error message.
My part message.
My part error message.

C'est à dire, que la ligne part.debug(...) ne serve à rien car n'affichant rien ni dans la console ni dans le fichier.

Pour ce faire, il suffit de configurer comme ceci le logging :

dictConfig({
    'version': 1,
    'handlers': {
        'console': {
            'level': 'DEBUG',
            'class': 'logging.StreamHandler',
        },
        'file': {
            'level': 'INFO',
            'class': 'logging.FileHandler',
            'filename': 'log.txt'
        }
    },
    'loggers': {
        'main': {
            'level': 'DEBUG',
            'handlers': ['console', 'file'],
        },
        'main.part': {
            'level': 'INFO',
        }
    }
})

Cela fonctionne pour une raison simple : c'est le niveau du logger qui s'applique en premier lieu. Si le niveau est inférieur au niveau configuré pour un logger, le message est ignoré, et il n'est donc jamais transmis, ni à un handler, ni à un logger parent.

Héritage et situation inverse : le fils debug, le parent informe

Un dernier point pour la route : nous voulons à présent que les messages de DEBUG s'affichent dans la console pour le logger fils, mais pas pour le logger parent. Pour cela, rien de bien compliqué : il suffit de configurer main au niveau INFO, et main.part au niveau DEBUG :

dictConfig({
    # ... Handlers ...
    # ... Loggers ...
    'loggers': {
        'main': {
            'level': 'INFO',
            'handlers': ['console', 'file'],
        },
        'main.part': {
            'level': 'DEBUG',
        }
    }
})

Ce qui donne au final cette sortie console :

$ python log.py
My message.
My error message.
My part debug message.
My part message.
My part error message.

Ce qui se passe, c'est que les handlers du parent main sont utilisés tels qu'ils sont configurés par le logger main.part : dans ce cas là, ce n'est pas le niveau de log du parent qui est pris en compte, mais celui du fils uniquement.

Mais encore ?

Il existe une multitude de cas possibles, qui correspondent à des besoins très différents. Je dirais que les points clés lorsque l'on configure des loggers et des handlers, c'est de définir très clairement les types de messages qui doivent aller à un endroit ou à un autre, puis ensuite seulement de réfléchir aux noms des loggers et à leur héritage.

Il faut se rappeler alors que l'ordre de gestion du niveau d'un message est le suivant :

  1. Le message est traité par le logger si et seulement si le niveau du message est supérieur ou égal à celui du logger,
  2. Le message est émit par le handler si et seulement si le niveau du message est supérieur ou égal à celui du handler,
  3. Lorsqu'il y a héritage, peut importe le niveau du parent, c'est toujours le niveau du fils qui est pris en compte pour traiter un message,
  4. Tout problème peut être généralement résolu par un usage astucieux de 'propagate': False, et ce sans oublier de renseigner à nouveau tous les bons handlers voulus.

Et si vous avez des questions, mon email, mon compte twitter et mon compte Google+ sont ouverts !