vendredi 12 août 2016

Python Logging & Logger - CE QU'IL NE FAUT PAS RATER

Petit détour sur les méthodes de logging Python et une erreur assez répandue (je pense).

Dans le blog victorlin, j'ai trouvé l'exemple suivant à propos du logging, exemple qui recèle une erreur dans la façon d'utiliser le logger :

import logging
logging.basicConfig(level=logging.INFO)
logger = logging.getLogger(__name__)

logger.info('Start reading database')
# read database here

records = {'john': 55, 'tom': 66}
logger.debug('Records: %s', records)
logger.info('Updating records ...')
# update records here

logger.info('Finish updating records')

Il y a comme un bug!
Si ce code est parfaitement fonctionnel, il y a quelque-chose qui me choque.
  1. Il faut créer un "logger" pour pouvoir logger
  2. Ou passer le logger d'objet en objet si on ne veut pas en créer à tour de bras.
Si vous avez une grosse application, vous allez vous retrouver avec des logger dans tous les coins (classe, fichier, etc) pour enregistrer des messages... alors que tout ce qui vous intéresse c'est faire du logging d'information (info ou degug) pour les utiliser quand cela sera utile.

Découpler logging et logger
Le plus approprié, il me semble, est de faire du logging agnostique, sans se préoccuper de la question "si cela intéresse un logger ou non"! En gros, découpler le logger et les opérations de logging dans le code.
Cela se fait très simplement en écrivant les traces directement sur "logging".

import logging

logging.debug(' %r _fire_select(): %r ' % (self, selection) ) 
logging.debug('%r _fire_cancel()' % self )

Utiliser un logger pour garder une trace
Ensuite, au besoin, il suffit de créer un logger pour garder une trace des messages qui passent comme ceci:

logger = logging.getLogger()
handler = logging.StreamHandler() # Logging vers console
formatter = logging.Formatter(
    '%(asctime)s [%(levelname)s] -> %(message)s')
handler.setFormatter(formatter)
logger.addHandler(handler)
logger.setLevel(logging.INFO) # ou DEBUG 

Et toutes les opérations loggin.info, logging.debug, etc tomberons dans logger :-)
Cela va singulièrement simplifier la codage des opérations de logging dans vis classes :-)

1 commentaire:

SAID OMAR a dit…

Perso, j'utilise la première forme mais avec des loggers sémantiques.

Admettons qu'il s'agisse d'une application web. Dans le fichier de conf je définis mes familles de loggers, disons: VIEWS, MODELS (et CONTROLLERS).

Suivant le niveau je ferai appel au logger parent:
logger = logging.getLogger("VIEWS")
ou a un logger descendant
logger = logging.getLogger("VIEWS.")

Ainsi je réduis le nombre de loggers et mes loggers deviennent sémantiques:
user_register_view_logger = logging.getLogger("VIEWS.USER.REGISTER") nous donnera une log de la forme:

User_register_view_logger.info("user TEST s'est ajouté ")
VIEWS.USER.REGISTER: user TEST s'est ajouté