Écrire des logs en Python


Good morning…

Au lieu de mettre des print() partout qu’il va falloir retirer après et qui en plus ne servent à rien dans un processus daemonisé, utiliser les facilités de logging de Python peut se révéler un bon investissement. Investissement car le module logging est du même genre que urllib2, datetime ou os.path : on peut tout faire avec mais vaut mieux avoir la doc sous la main.

Pour les gens pressés

Avant de se lancer dans les explications, voici le snippet qui permet d’afficher les informations à l’écran et dans un fichier de log :

#!/usr/bin/env python
# -*- coding: utf-8 -*-
 
import logging
 
from logging.handlers import RotatingFileHandler
 
# création de l'objet logger qui va nous servir à écrire dans les logs
logger = logging.getLogger()
# on met le niveau du logger à DEBUG, comme ça il écrit tout
logger.setLevel(logging.DEBUG)
 
# création d'un formateur qui va ajouter le temps, le niveau
# de chaque message quand on écrira un message dans le log
formatter = logging.Formatter('%(asctime)s :: %(levelname)s :: %(message)s')
# création d'un handler qui va rediriger une écriture du log vers
# un fichier en mode 'append', avec 1 backup et une taille max de 1Mo
file_handler = RotatingFileHandler('activity.log', 'a', 1000000, 1)
# on lui met le niveau sur DEBUG, on lui dit qu'il doit utiliser le formateur
# créé précédement et on ajoute ce handler au logger
file_handler.setLevel(logging.DEBUG)
file_handler.setFormatter(formatter)
logger.addHandler(file_handler)
 
# création d'un second handler qui va rediriger chaque écriture de log
# sur la console
stream_handler = logging.StreamHandler()
stream_handler.setLevel(logging.DEBUG)
logger.addHandler(stream_handler)
 
# Après 3 heures, on peut enfin logguer
# Il est temps de spammer votre code avec des logs partout :
logger.info('Hello')
logger.warning('Testing %s', 'foo')

Cette config va afficher :

Hello
Testing foo

sur la console

Et :

2013-03-08 11:37:31,311 :: INFO :: Hello
2013-03-08 11:37:31,411 :: WARNING :: Testing foo

Dans le fichier de activity.log.

Quand vous passez en prod, mettez simplement une condition sur le stream handler, et le setLevel sur logging.WARN et vous êtes tranquile, quel que soit le nombre de logger.info que vous avez mis partout.

Mais bon, avouez le, si vous aviez dû le faire vous même, vous auriez abandonné avant de trouver. D’une manière générale, quand vous voyez des noms en camelCase comme setLevel dans une lib Python, c’est que la lib va être relou à utiliser.

Donc, faites comme moi, mettez cette config dans un fichier à part, et pour chaque nouveau projet, copier le bêtement. Comme ça vous aurez en une seconde la possibilité de logger dans un fichier et sur la console avec une désactivation facile.

Un peu de théorie

En Python, les logs se font à travers un logger. Le logger prend toute écriture que vous lui demandez, et regarde si le niveau de log est suffisamment haut pour continuer. Si non, il ignore l’entrée, si oui, il va passer le message à chaque handler.

Chaque handler fait le même test pour lui même : le niveau est il assez élevé pour moi ? Si non, il ne fait rien. Si oui, il écrit le log. La manière dont il écrit le log dépend du type du logger : le StreamHandler va écrire par défaut sur la console, le FileHandler dans un fichier, le SmtpHandler va envoyer un email, etc. Un logger peut avoir autant de handlers qu’il veut, et donc autant de type d’écritures qu’il veut.

Tout handler possède un formatter, qui est un objet qui décide dans quel format il va écrire la nouvelle entrée du log. Le formateur par défaut écrit juste le message, mais on peut lui demander (comme on l’a fait plus haut), d’écrire un timestamp, le niveau du message ou des choses plus complexes comme des éléments de la pile d’appel.

Vous avez suivi ? Allez, comme je suis sympa, je vous mets un dessin :

Schéma de l'organisation de la configuration d'un logger

Si vous saviez combien de temps prennent ces schémas à la con à faire...

Bref, pour configurer un logger en Python :

  • On créé un objet logger
  • On lui ajoute des handlers
  • On ajoute des formateurs aux handlers
  • On set les niveaux du loggers et des handlers

Et enfin, on peut logger avec logger.(info|warn|debug|error|critical).

Mais là vient s’intercaler un des plus grands mystères de l’histoire du logging : les niveaux. Personne ne se rappelle comme ça marche.

Si vous mettez un flingue sur la tête de quelqu’un et que vous lui donnez une dernière chance d’expliquer les niveaux de logging sinon vous le butez lui et toute sa famille, il se mettra à chouiner bêtement. Inutile de monter la pression en menaçant de profaner leurs tombes et violer leurs cadavres. Il ne sait tout simplement pas.

Donc, un bonne fois pour toute, voilà comment les niveaux marchent

Niveau Valeur Usage
CRITICAL 50 Le programme complet est en train de partir en couille.
ERROR 40 Une opération a foirée.
WARNING 30 Pour avertir que quelque chose mérite l’attention : enclenchement d’un mode particulier, detection d’une situation rare, un lib optionelle peut être installée.
INFO 20 Pour informer de la marche du programme. Par exemple : “Starting CSV parsing”
DEBUG 10 Pour dumper des information quand vous débuggez. Par exemple savoir ce qu’il y a dans ce putain de dictionnaire.

Vous spécifiez les niveaux une fois quand vous créez vos loggers et handlers avec setLevel. Vous passez à cette méthode une des valeurs suivantes : logging.DEBUG, logging.INFO, logging.WARNING, etc. C’est la valeur minimal qu’ils acceptent.

Ensuite, à chaque écriture de message dans le logger, vous passez le niveau avec le message:

>>> logger.log(logging.DEBUG, 'Message !')

Comme c’est relou à taper, Python fournit des raccourcis :

logger.debug('message') va faire logger.log(logging.DEBUG, 'message')

logger.error('message') va faire logger.log(logging.ERROR, 'message')

Etc

A chaque fois que vous allez envoyer un message, le logger (et chaque handler) va comparer le niveau du message avec le sien. Si le niveau du message est inférieur au sien, il l’ignore, sinon il l’écrit.

Exemple :

CRITICAL
ERROR
WARNING <- niveau du logger (ou du handler)
INFO    <- niveau du message
DEBUG

Le message est ignoré.

CRITICAL
ERROR   <- niveau du message
WARNING <- niveau du logger (ou du handler)
INFO
DEBUG

Le message est écrit.

CRITICAL
ERROR   <- niveau du message et du logger
WARNING
INFO
DEBUG

Le message est écrit.

Ce mécanisme permet de controler la sortie de votre programme. Si vous passez le programme en prod, vous avez sans doute plus envie de tous les messages d'information et de debug. Vous mettez alors le level sur, par exemple, ERROR, et vous aurez un log avec uniquement les erreurs.

Cette techique permet un gros niveau de granularité puisque non seulement le logger à un level, mais aussi chaque handler.

Exemple : vous avez un logger avec deux handlers, un qui va vers la console, et l'autre dans un fichier.

CRITICAL
ERROR
WARNING  <- niveau du handler fichier
INFO    <- niveau du logger et du handler console
DEBUG

Si un message arrive avec un niveau DEBUG, il est ignoré. Si il arrive avec un niveau INFO, il est affiché sur la console. Si il arrive avec un niveau WARNING ou plus, il est affiché sur la console ET mis dans le fichier.

Des combos de ouf

Rappelez-vous qu'on peut avoir autant de handlers qu'on veut, et même plusieurs handlers de même nature tels que deux handlers fichiers. Le premier peut par exemple logger les infos, et l'autre juste les erreurs.

Vous pouvez même créez vos propres niveaux (logging.CAMERDEGRAVE) et vos propres handlers. Un handler qui appelle une URL quand il y a une erreur, un handler qui met tout le debug en coloration syntaxique, un handler qui envoit un SMS en cas de critical, etc.

Les handlers disponibles dans la lib standard sont :

  • FileHandler: écrit tout dans un fichier.
  • RotatingFileHandler: écrit tout dans un fichier. Si le fichier depasse une certaine taile, renomme le fichier avec un compter, et recommence avec un nouveau fichier. Le nombre de backup est configurable.
  • TimedRotatingFileHandler: écrit tout dans un fichier. Après un certain temps, renomme le fichier avec un compter, et recommence avec un nouveau fichier. Le nombre de backup est configurable.
  • WatchedFileHandler: écrit dans un fichier, mais surveille si il n'a pas été modifié entre temps. Ne marche pas sous Windows
  • HTTPHandler: envoit le contenu par POST ou GET à l'URL donnée.
  • SMTPHandler: envoit le contenu par email.
  • MemoryHandler: garde tout en mémoire jusqu'à un certain temps, puis balance tout à un autre handler. Utile avec SMTPHandler.
  • BufferingHandler: accumule tout en mémoire, et vide régulièrement le buffer. Utile pour l'instrospection.
  • NTEventLogHandler: envoit les entrées sur le event log de Windows NT.
  • SysLogHandler: envoit les entrées sur un serveur syslog.
  • SocketHandler: envoit les entrées (picklées) via une socket.
  • DatagramHandler: envoit les entrées sur une socket datagram.

Traiter le fichier de log

90% du temps, vous voudrez juste un bon vieux fichier de log. Mais rien ne sert d'avoir un fichier de log si on ne peut pas le lire.

D'abord, choisissez le bon endroit pour le mettre. Si c'est juste du debug, le dossier courant fera l'affaire. Si vous pensez qu'il va rester longtemps mais qu'il faudra le vider de temps à autre (et qu'il ne contient pas des informations qui ne doivent être lues que par root), alors mettez le dans un fichier temporaire. Le module tempfile est votre ami.

Sinon, pour les logs plus sérieux, il faudra le mettre dans le dossier officiel pour les logs du systèmes. Par exemple pour Ubuntu server : /var/log.

Attention aux permissions d'écriture, vous risquez de vous retrouver avec une erreur à la con sur les bras. Vérifiez bien vos droits d'accès.

Ensuite, il faut bien choisir son format de log. Sauf cas particulier, j'utilise ce formatteur :

formatter = logging.Formatter('%(asctime)s :: %(levelname)s :: %(message)s')

Il produit des sorties du genre "TIMESTAMP :: LEVEL :: Message", par exemple :

2012-03-08 12:01:31,311 :: INFO :: My life for Aiur
2012-03-08 12:20:31,311 :: ERROR :: We require more Vespin Gaz
2012-03-08 12:37:31,311 :: WARNING :: We are under attack
2012-03-08 12:38:31,311 :: CRITICAL :: Nuclear launch detected

Ce format est facile à analyser car le séparateur a peu de risque de se retrouver dans le message.

On peut très rapidement filtrer uniquement les erreurs, par exemple sous bash on peut voir si il y a eu récement des erreurs ainsi :

tail -n 100 fichier.log | grep ERROR

Sous Python on peut faire des traitements super chiadés en deux secondes :

from datetime import datetime
 
lines = (ligne.split(' :: ') for ligne in open('fichier.log'))
errors = ((date, mes) for date, lvl, mes in lines if lvl in ('ERROR', 'CRITICAL'))
 
before, after = datetime(2012, 1, 12), datetime(2012, 3, 24)
parse = lambda d: datetime.strptime(d, '%Y-%m-%d %H:%M:%S,%f')
dated_line = ((date, mes) for date, mess in errors if before <= parse(date) <= after)
 
for date, message in dated_line:
    print date, message
 
# Affiche uniquement les message d'erreur ou criques qui sont arrivés entre
#  le 12 janviers 2012 et le 24 mars 2012

Et je ne vous parle même pas de ce qu'on peut faire avec des libs comme pandas.

Aller plus loin

Le log peut vous emener très loin. En vérité, non seulement on peut avoir plusieurs handlers, mais on peut aussi avoir plusieurs loggers.

Quand vous faites:

logger = logging.getLogger()

Vous récupérez ce qu'on appelle le logger "racine" (ou "root"). Mais vous pouvez aussi donner un nom au logger :

logger = logging.getLogger('encoding')

Ceci vous permet de préconfigurer le logger quelque part dans le programme, et de récupérer celui-ci en particulier à un autre endroit, sans se trimbaler la référence. logging.getLogger('encoding') n'a besoin d'être configuré qu'une fois, si vous refaites ça ailleurs, vous récupérez le même logger.

On peut même utiliser des sous-noms:

enc_aud_logger = logging.getLogger('encoding.audio')
enc_vid_logger = logging.getLogger('encoding.video')

Alors chaque logger aura sa propre config, MAIS, tout message envoyé sur un logger nommé "encoding.quelquechose" sera aussi automatiquement envoyé au logger "encoding" si il existe.

Vous pouvez donc créer une hierarchie de log, par exemple pour avoir un fichier par process, et un gros log central sur un serveur à part via socket. Ca ne m'a jamais servi, mais je me suis dit que je ferai circuler l'info.

Je n'ai pas parlé des filters, qui sont des objets qui permettent de faire la même chose que les niveaux, mais avec des règles d'écriture dans les logs plus avancées que juste "c'est le bon niveau". Et je n'ai pas abordé non plus les formateurs particuliers. Là on rentre dans le domaine de la drosophilie.

En revanche si vous avez le temps, je vous conseille de passer quelque temps sur les options de configuration (plein de recettes ici). En effet, en général on veut avoir un log configurable (c'est un peu le but de la manœuvre, sinon on ferait des print). Or, le logger peut se configurer de plein d'autres façons qu'avec du code Python.

On peut notamment déclarer la configuration avec un gros dictionaire (c'est ce que fait Django) ou avec un fichier ini.

Enfin, normalement ce package est thread-safe. Vous devriez pouvoir logger en toute impunité dans plusieurs threads. Je recommande quand même de faire la configuration du logger avant d'entrer dans un thread, on ne sait jamais.

Pour ceux qui veulent se plonger dans les méandres de tout ce qu'on peut faire avec logging, chechez la doc et cet article de l'auteur du module.


Télécharger le code de l'article

73 thoughts on “Écrire des logs en Python

  • foxmask

    coucou ;)

    au final quelque soit le langage (digne de ce nom) utilisé on utilise les memes handler/logger ; on n’est pas perdu ;) je pense notamment à log4j.

    sinon j’ai une version pour neuneu ‘comme moi’ sur le sujet prévu lundi ;)

  • Sam Post author

    D’ailleurs, toi qui est phpeux, y a un truc comme ça en PHP ? Je me souviens d’avoir codé ma propre lib il y a des années comme sujet de mémoire, mais si ça se trouve ça existait déjà.

  • foxmask

    ya une fonction syslog qui repose sur le meme syslog unix sinon chaque framework propose son systeme de log et une autre error_log

  • roro

    ça me rappelle le tuto de Maité sur le truffage de la dinde de Noel.
    Celui où à la fin tu as la fourchette à la main et la serviette autour du cou.

  • Teocali

    Ah mais ce module est clairement inspiré du monde java, hein, que ce soit par Log4J (avec lequel j’ai beauuucoup de mal, surtout depuis qu’il n’est plus maintenu) ou part java.logging. La preuve ? CamelCase :)
    Bon, sinon, je vous laisse je dois retourner a mon programme C++… :'( J’ai rarement eu autant l’impression d’avancer dans le noir qu’avec ce langage. Rendez-moi mon Java !

  • Sam Post author

    unittest, urllib2, xml, et logging ont été clairement écrits par des anciens codeurs java bourrés à l’irish coffee. Y des abstractions dans tous les sens, des adapteurs, le niveau 0 du pep8…

    C’est dans ces moments là que ça me donne envie de coder une alternative.

  • Teocali

    Pourquoi “ancien” ? c’est incompatible de faire les deux en même temps ? Bah merde… :)

    Plus serieusement, ça me fait penser… je me demande s’il est possible d’executer “simplement” (en utilisant les mecanismes internes) du code Python au sein d’un code Java. J’imagine que oui. Faudra que je me penche dessus.

  • Anucunnilinguiste

    @Sam

    “unittest, urllib2, xml, et logging ont été clairement écrits par des anciens codeurs java bourrés à l’irish coffee”

    On lit les mêmes articles ;)

  • Stéphane Bunel

    Bel article. A propos, pour l’avoir vécu, j’ai gardé dans un coin de ma tête qu’il ne faut pas utiliser ce module dans les parties de code qui nécessite un maximum de performance. En effet, même avec le debug désactivé (ex: niveau de sortie sur CRITICAL) il mange beaucoup de temps alors qu’il devrait juste ignorer le message de debug. Je ne sais pas pourquoi ni même si c’est toujours le cas.

  • Sam Post author

    C’est sûr. Heureusement un algo qui a besoin d’être rapide et en Python a rarement besoin de log. On met généralement les logs dans le code métier, qui lui est rarement le bottleneck.

  • François

    Moi, j’ai tendance à utiliser les sous-noms pour identifier (surtout en debug) la classe/le fichier qui écrit. C’est mon manque d’expérience qui fait faire ça ? puisque d’après ce que je comprends, tu ne fais pas ça. Un seul namespace n’est-il pas fouillis ?

    Merci.

  • Sam Post author

    C’est très bien d’utiliser des sous-noms. En général les gens font ça :

    getLogger(__name__)

    Comme ça c’est fait automatiquement.

    Moi je suis juste un feignant. Je me contente généralement d’un ou deux gros logs centralisés.

  • dodoecchi

    Merci pour ce super article, comme d’habitude.
    C’est vrai que les logs en python, sans la doc, c’est chaud patate :/

    quelques erreurs dans l’article :
    – ca particulier -> cas particulier
    – plein de recettes ici). -> lien cassé

  • Baronsed

    Des fichiers de log de 120 Go ? C’est là qu’il vaut mieux savoir maîtriser ed.

  • N.

    Donc le prochain article, c’est comment configurer le logging de django?

  • Sam Post author

    @gregR: ok. Rien en natif donc ?

    @N.: cest vrai que ça mérite.

  • Krypted

    Est-il possible d’intégrer un logger dans un autre logger ?
    Je m’explique :
    Je voudrais récupérer le logger “sqlalchemy” et le mettre dans un autre logger “monprogramme”

    Faut-il attacher au logger “sqlalchemy” le même handler que “monprogramme” ou y a-t’il une méthode plus propre?

  • foxmask

    @Baronsed : vaut mieux configurer son appender pour ne pas dépasser ‘x’ Mega et ‘y’ fichiers de log dans le rolling appender ; ca évite un fichier de 120G.

  • Sam Post author

    @Krypted: ça veut dire auoi “mettre” ? Tu veux qu’il se passe quoi quand tu fais quoi ?

  • Krypted

    En fait je voudrais pouvoir voir les logs de SQLAlchemy dans le fichier de log de mon application.
    En gros, ma classe de logs hérite de celle de CherryPy. J’ai donc mes logs persos + ceux de cherrypy dans le même fichier log. Je veux également ajouter ceux de SQLAlchemy.

    Je pensais pouvoir faire un :

    logger = logging.getLogger('sqlalchemy')

    Mais je ne sais pas quoi faire de cet objet.

  • DrFunk

    Salut.

    Ca fait un moment que je suis votre site et ses très bons articles en Python.
    Merci pour celui-ci sur le logging, j’avais commencé à utiliser un peu la librairie mais là ça met bien les choses au clair.
    Juste une correction : le lien vers le “logging Cookbook” en fin d’article est cassé, la bonne URL est http://docs.python.org/2/howto/logging-cookbook.html

    Continuez vos articles, je suis sûr qu’il y a plein de gens comme moi qui les lisent et les apprécient même s’ils le disent pas souvent ! (oui je sais, saÿmal…)

  • Sam Post author

    @Krypted: dans ce cas, ajoute un MemoryHandler dans le logger sqlalquemy qui va tout renvoyer dans un handler de ton logger.

  • GM

    “Enfin, normalement ce package est thread-safe.”

    Thread-safe peut-être, mais pas multiprocess-safe, donc gaffe.
    Ca m’est arrivé par le passé d’avoir plusieurs process du même script qui arrivent en concurrence sur un RotatingFileHandler, et qui font la rotation tous en même temps.

    Résultat : au lieu d’avoir 5 log.old de 50 Mio, j’avais 5 log.old de 100 octets, et le vieux log disparu.
    La solution : utiliser un verrou sur le fichier au moment de la création du logger.

  • Xavier O

    Suite aux excellents articles sur les décorateurs et le présent article, je me suis attelé à l’élaboration d’un module de logs.
    Ce faisant, je me suis heurté à un joli problème : dans l’exécution de mon décorateur, je suis incapable de déterminer la classe exacte de la méthode :
    1) La fonction n’est pas encore liée à la méthode.
    2) Si je passe par la variable “self”, la classe est celle de l’objet et non celle de la méthode exécutée.
    Y’a-t-il un moyen de trouver cette information ?
    Voici mon code :

    import functools
    import logging
    from logging import DEBUG, INFO, WARNING, ERROR, CRITICAL
    from logging import handlers
     
    LOG_FILENAME = "baom.log"
     
    __logger = None
     
    def initLogger(path):
        """
        @brief Initialisation du logger de l'application.
        @param path @c string chemin du fichier à générer.
        """
        global __logger
        __logger = logging.getLogger()
        __logger.setLevel(logging.DEBUG)
        fileFormater = logging.Formatter("%(asctime)s::%(levelname)s::%(message)s")
        fileHandler = handlers.RotatingFileHandler(cTools.pathJoin(path, LOG_FILENAME), 'a', 1000000, 1, "utf-8")
        fileHandler.setLevel(logging.DEBUG)
        fileHandler.setFormatter(fileFormater)
        __logger.addHandler(fileHandler)
        terminalHandler = logging.StreamHandler()
        terminalHandler.setLevel(logging.INFO)
        __logger.addHandler(terminalHandler)
     
    def logDeco(formatString=None, argList=None):
        """
        @brief Génère un décorateur effectuant un log de debug en début d'exécution.
        @param formatString @c string - Chaîne de mise en forme du texte à logger.
        @param argList [string] - Liste des arguments à logger.
        @return @c function
        """
        def decorator(func):
            # Construction de la liste des arguments et de leur valeur par défaut
            code = func.__code__
            defaults = func.__defaults__
            funcArgs = {}
            argDefaults = {}
            for index in range(code.co_argcount):
                funcArgs[code.co_varnames[index]] = index
                if defaults is not None:
                    defaultIndex = index - (code.co_argcount - len(defaults))
                    if index &gt;= code.co_argcount - len(defaults):
                        argDefaults[code.co_varnames[index]] = defaults[defaultIndex]
            @functools.wraps(func)
            def wrapped(*args, **kwargs):
                # Détermine s'il s'agit d'une méthode ou d'une fonction.
                if len(args) &gt; 0:
                    self = args[0]
                    if hasattr(self, func.__name__):
                        className = self.__class__.__name__
                    else:
                        className = None
                else:
                    className = None
                if argList is None:
                    text = ""
                else:
                    argValues = []
                    for arg in argList:
                        index = funcArgs[arg]
                        if index &gt;= len(args):
                            if arg in kwargs:
                                argValue = kwargs[arg]
                            else:
                                argValue = argDefaults[arg]
                        else:
                            argValue = args[index]
                        argValues.append(argValue)
                    text = formatString.format(*argValues)
                if className is None:
                    logText = "{}::{}::{}".format(func.__module__, func.__name__, text)
                else:
                    logText = "{}::{}::{}::{}".format(func.__module__, className, func.__name__, text)
                __logger.debug(logText)
                data = func(*args, **kwargs)
                return data
            return wrapped
        return decorator
  • Xavier O

    Merci Sam, je vais éclaircir ça un peu.

    Quel est mon objectif ?
    Je souhaite utiliser un décorateur pour tracer l’entrée dans certaines méthodes.
    Je logge le nom de la méthode, son module et le nom de sa classe.

    Qu’est-ce que j’ai essayé de faire ?

    Je récupère le nom de la méthode et son module en utilisant les attributs __module__ et __name__ de la fonction.
    Pour la classe, j’utilise la valeur du premier argument de la fonction qui contient l’instance de la classe.

    Voici une version simplifiée de ce que je fais :

    Le décorateur (decorateur.py) :

    import functools
     
    def decorer(func):
        module = func.__module__
        name = func.__name__
        @functools.wraps(func)
        def wrapped(*args, **kwargs):
            self = args[0]
            print(module, name, self.__class__.__name__)
            data = func(*args, **kwargs)
            return data
        return wrapped

    La classe générique (skigen.py) :

    import decorateur
     
    class Ski():
        def __init__(self, nom):
            self.__nom = nom
        @decorateur.decorer
        def skier(self):
            print(self.__nom, "fait du ski")

    La classe spécifique (skispec.py) :

    import decorateur
    import skigen
     
    class SkiAlpin(skigen.Ski):
        @decorateur.decorer
        def skier(self):
            super().skier()
            print("alpin")

    Mon test :

    import skigen
    import skispec
     
    ski = skigen.Ski("Toto")
    ski.skier()
     
    skiAlpin = skispec.SkiAlpin("Toto")
    skiAlpin.skier()

    Quels résultats ai-je obtenus ?


    skigen skier Ski
    Toto fait du ski
    skispec skier SkiAlpin
    skigen skier SkiAlpin
    Toto fait du ski
    alpin

    Qu’est-ce que je pense que j’aurais dû obtenir au lieu de cela ?


    skigen skier Ski
    Toto fait du ski
    skispec skier SkiAlpin
    skigen skier Ski
    Toto fait du ski
    alpin

    Quelle est ma situation ?
    J’utilise Python 3.2 sous Windows (pitié pas de tomate !).

  • Sam Post author

    Le résultat que tu obtiens est tout à fait logique : tu récupères la classe du self, et c’est le même self qui est passé à la méthode, et à super().

    Je suppose que tu veux la classe qui définit la méthode, auquel cas le module inspect devrait pouvoir aider. Pas testé, mais je te donne l’idée, de tête (je viens de me réveiller, donc à utiliser avec esprit critique) :

    from inspect inspect getmro
     
    def get_defining_class(method):
       # ou method.__class__ en python 3 je crois
       for cls in getmro(method.im_class):
         if method.__name__ in cls.__dict__: 
             return cls
       return None
     
    def decorer(func):
        @functools.wraps(func)
        def wrapped(*args, **kwargs):
            # c'est moins performant de récup 
            # les metadata ici mais ça évite
            # les potentiels erreurs de références
            module = func.__module__
            name = func.__name__
            cls = get_defining_class(func)
            print(module, name, cls.__name__)
            return func(*args, **kwargs)
     
        return wrapped
  • Xavier O

    Merci beaucoup, mais cela ne fonctionne malheureusement pas.
    Avec im_class :

    AttributeError: 'function' object has no attribute 'im_class'

    Avec __class__ :

    AttributeError: 'NoneType' object has no attribute '__name__'

    En fait func représente une fonction, il ne s’agit pas encore d’une méthode. Elle n’est pas encore “bindée”.
    Du coup aucun lien direct avec la classe parente.
    J’ai trouvée un algo qui devrait fonctionner, mais bon c’est tellement immonde que je ne me sens pas de le coder :
    1) Lire le fichier contenant le code de la fonction.
    2) Déterminer l’indentation utilisée.
    3) Déterminer le niveau d’indentation de la déclaration de fonction.
    4) Rechercher la déclaration de classe de niveau d’indentation N-1 avec le numéro de ligne le plus élevé tout en étant inférieur à celui de la déclaration de la fonction.
    Beurk ! J’espère trouver mieux !

  • Sam Post author

    Je vois ce que tu veux dire. Je regarde ça demain soir des que j’ai acces à mon ordi car je suis toujours sur la route. En attendant je te recommande de poster ça sur le forum de l’afpy et stackoverflow car ce sont des sites plus adaptés pour s’entre aider que les comments du blog.

  • Xavier O

    J’ai trouvé une solution. Je met ça en forme et surtout je la documente avant de la poster, si ça vous intéresse bien entendu.

  • Sam Post author

    Si tu te sens chaud, tu peux carrément faire un article invité, et on le poste en créative common. Comme ça tout le monde en profite.

  • djipey

    Bonjour.

    Très bon article. Je me demandais, il y a moyen de rediriger aussi les exceptions levées dans le fichier de log ? Tout en les gardant sur la sortie normale aussi, ce serait cool.

  • Sam Post author

    Oui, on peut attraper une exception comme ceci dans le décorateur:

    try:
        wrapper()
    except:
        # écrire dans le fichier de log
        raise # relève l'exception en l'état
  • djipey

    Oui, ça j’ai vu, mais je parlais de quelque chose de plus général. Attraper une expression particulière je sais faire, mais les attraper toutes (haha..), et ce de manière automatique, est-ce que c’est possible ?

    En somme je voudrais garder une trace de toutes les exceptions dans le fichier de log.

  • kontre

    Ben le code de Sam les attrappe toutes, et les loggues toutes, automatiquement. Teste, tu verras bien !

  • Sam Post author

    Alors, tu as deux approches :

    – soit tu met tout ton code dans un grand try / except (si tu as un seul point d’entrée, c’est facile et propre), et tu peux utiliser mon code
    – soit tu te hook sur le crash de la VM comme expliqué dans l’article http://sametmax.com/log-post-mortem-avec-python/

  • djipey

    Voilà, c’est bien plus clair. L’option 2), je ne pense pas qu’elle soit applicable à mon cas. C’est un programme PyQt, et ça ne plante pas totalement. Ça lève des exceptions c’est sûr, principalement dans mes algos, mais ça ne plante pas.

    Du coup, je pense que ça, ça devrait marcher:


    def main():
    try:
    app = QtGui.QApplication(sys.argv)
    ex = Fenetre()
    sys.exit(app.exec_())
    except:
    # écrire dans le fichier de log
    raise # relève l'exception en l'état

    C’est la fonction qui crée ma fenêtre. Par contre, je ne comprends pas ce qu’implique ta fonction “wrapper()” que tu donnes dans ton exemple plus haut. Ni comment tu peux récupérer l’exception pour l’écrire dans le log. Est-ce que tu sous-entends qu’il faut faire qqch comme :


    except Exception,e :
    log("Caught:", e)

  • Sam Post author

    Si tu cherches juste le message d’erreur, c’est tout ce dont tu as besoin (str(e) retourne le message), sinon, il faut ta tapper l’extraction de la stacktrace complète.

    wrapper() fait référence à la fonction dans laquelle tu enrobes ton appel dans un décorateur. Si tu n’est pas à l’aise avec les décorateurs personnalisés, fais un petit tour sur http://sametmax.com/comprendre-les-decorateurs-python-pas-a-pas-partie-1/, j’y ai mis tout ce qu’il te faut.

  • Luigi

    Petit coquille :

    Tesing foo

    devrait être Testing foo

    Encore un grand merci pour ce super tuto !

  • Guts

    Salut,

    Un petit merci pour le code et l’explication de code : ça m’a permis d’ajouter facilement un log dans mon programme et pour un débutant c’est le genre de truc indispensable !

    Par contre je suis pas parvenu à faire écrire mon sous-module dans le même fichier log :( J’ai cherché du côté de la doc officielle mais c’est pas vraiment très bavard (http://docs.python.org/2/howto/logging.html#logging-from-multiple-modules) Si quelqu’un a un petit bout de code qui explique un peu le zafèr…

    Autre question, @Sam dans l’un de tes comments, tu dis que le code est assez pourri vu du PEP8. Mais pour un module inclus dans la librairie standard ça la fout pas mal ?

  • Sam Post author

    Pour écrire depuis un sous-module, c’est pareil que depuis le module principal. Il faut juste que le nom du log soit le même, ou un dérivé genre “module” => “module.sous”.

    Quand au PEP8, il a été écrit APRES ces libs, justement pour éviter que ça ne se reproduise.

  • CaptainMurloc

    Hello !

    Merci pour ce super article, cela m’aide beaucoup (moi qui débute totalement en python). Je n’ai d’ailleurs pas de grandes connaissances en objet car j’ai été jetée dedans (le python) pour mon apprentissage et n’ai pas réellement de bases.

    Voici donc ma demande :

    J’ai récupérer le code de la section “Pour les gens pressés” (je ne suis pas spécialement pressée, mais du temps gagné reste du temps gagné (Obvious)).

    Tu dis :

    Donc, faites comme moi, mettez cette config dans un fichier à part, et pour chaque nouveau projet, copier le bêtement. Comme ça vous aurez en une seconde la possibilité de logger dans un fichier et sur la console avec une désactivation facile.”

    J’ai trouvé ça cool, mais je ne sais pas réellement si ce que j’essaie de faire (ce que je pense avoir déduit de ce que tu as dit) est réellement faisable. En effet, je voudrai : (les noms sont totalement illustratifs)
    – créer un fichier init_logger.py qui contiendrait le code que tu as posté
    – appeler ce fichier depuis un autre, admettons add_logs.py, et écrire dans le fichier de logs créé (du coup par init_logger, donc activity.log) mais à partir de add_logs.py

    J’ai modifié ton code en créant juste une fonction qui contient le reste du code pour pouvoir l’appeler depuis add_logs.py

    def initialisation() :
    # création de l'objet logger qui va nous servir à écrire dans les logs
    logger = logging.getLogger()
    # on met le niveau du logger à DEBUG, comme ça il écrit tout
    [...]

    A partir de là, j’ai donc fait l’import de init_logger dans add_logs.py et j’ai appelé la fonction initialisation().
    Cela fonctionne correctement, je récupère bien
    Hello
    Testing foo

    Mais comme je dis plus tôt, je ne vois pas trop comment faire pour écrire dans le fichier de logs depuis add_logs.
    Si cela n’est pas possible, soit. Mais comme je n’en suis pas sûre, je préfère demander ! :)

    J’espère tout de même que ce soit faisable (ce serait tellement plus propre ^^).
    A bientôt !

    – CaptainMurloc

  • Sam Post author

    Donne un nom à ton logger :

    logger = logging.getLogger("trop_cool")

    Et dans un autre fichier, si tu utilise le même nom, tu auras le même logger, qui écrit dans le même fichier.

  • Fred

    hello, très belle article.

    pouvez vous donner un exemple avec le SMTPHandler ?

    après plusieurs traitement ,

    le SMTPHandler va envoyer le rapport des traitements par mail

    Merci à vous

    cdt

    Fred

  • Sam Post author

    Ca ressemble à ça (de tête) :

    import logging
    logging.handlers
    
    log = logging.getLogger("mylogger")
    
    mailer = logging.handlers.SMTPHandler(mailhost='tonhost',
                                    fromaddr='ton_mail_denvoie',
                                    toaddrs=['liste', 'de', 'destinataires'],
                                    subject='Alerte rouge !',
                                    credentials=('username','password'),
                                    secure=None)
    mailer.setLevel(logging.ERROR)
    log.addHandler(mailer)
    

    Et ça enverra un mail pour toutes les erreurs logguées sur ce logger.

    Par contre le handler par défaut ne permet pas l’utilisation de TLS, ce qui est bien relou. Et la méthode de contournement est, pour ainsi dire, hum… http://mynthon.net/howto/-/python/python%20-%20logging.SMTPHandler-how-to-use-gmail-smtp-server.txt

    • Fred

      Merci Sam ! c’est exactement ce que je cherchais :-D

      du très très bon boulot votre site !

      Et si j’ai besoin de poser une question qui n’a pas de billet sur votre site ?

      Merci à vous

  • Fred

    Hello, sorry , je reviens dessus :

    je te cite :”

    import logging

    logging.handlers

    log = logging.getLogger(“mylogger”)

    mailer = logging.handlers.SMTPHandler(mailhost=’tonhost’,

    fromaddr=’ton_mail_denvoie’,

    toaddrs=[‘liste’, ‘de’, ‘destinataires’],

    subject=’Alerte rouge !’,

    credentials=(‘username’,’password’),

    secure=None)

    mailer.setLevel(logging.ERROR)

    log.addHandler(mailer)

    “”

    c’est parfait.

    mais supposons que j’ai une classe A et un autre fichier main.py

    j’ai des résultats d’instructions sur la classe A et je veux regrouper tous ces résultats et les envoyer par mail En Une Fois.

    dans la classe A :

    -> j’ai une liste qui va append toutes les résultats des erreurs des instructions

    dans le main.py

    -> j’appel la liste de la classe en paramètre:

    if any(‘CRITICAL’ in msg or ‘ERROR’ in msg or ‘FAILURE’ in msg for msg in A.ma_list):

    ….log.error(‘\n’.join(A.ma_list))

    Y a t-il moyen de faire autrement que de regrouper les résultats dans une liste pour les envoyer en un bloc ?

    Merci à toi.

    • Sam Post author

      Pose ta question sur IndedError, ça aura plus de visibilité.

  • Bru-noop

    Merci encore pour ce superbe article qui deconstruit un truc basique mais pas simple à comprendre. Je me suis mis à python il y a deux ans maintenant et 95% des fondamentaux que j’ai proviennent de ton blog, alors un grand merci à toi.

    Pour être plus juste je devrais même te reverser une partie de mon salaire !

  • MaxL

    Bonjour,

    Tout d’abord, merci pour tout ces articles, ma foi bien instructifs ! J’utilise régulièrement la routine de log proposée en début d’article, mais aujourd’hui je me heurte à un problème : je la définit dans mon script, et j’utilise l’objet logger dans des fonctions et classes qui sont définis dans un fichier annexe. Et là, c’est le drame : “name error:: global name logger is not defined”. Comme forcer logger à être global ? Il semble être local et ne pas passer dans les fonctions et classes, ce qui m’étonne un peu. Alors certes, il y a la possibilité de le passer en argument de mes fonctions et constructeurs, mais je ne trouve pas cela très propre…

    J’aimerai pouvoir passer un warning quand certaines exceptions sont levées (je fais du traitement de données qui a un fort taux de corruption, d’où des erreurs régulièrement)

    (j’ai aussi le même problème pour d’autres variables, mais c’est plus facilement contournable)

    Merci de votre aide !

  • Sam Post author

    Il faut faire dans tous les fichiers:

    import logging
    
    log = logging.getLogger(nom)
    

    Pour obtenir une référence au logger portant ce nom.

  • MaxL

    Merci de la réponse. J’ai essayé de rajouter cette ligne dans mon fichier de fonctions, puis dans une fonction, mais toujours la même chose, il n’arrive pas à accéder au logger défini plus haut …

    Ma construction de fichiers est la suivante :

    fichier_principal.py contenant :

    import logging

    logger = logging.getLogger()

    puis la définition comme proposé plus haut dans ce post.

    Et mon fichier de fonctions et classes :

    functions.py :

    import logging

    def mafonction():

    log = logging.getLogger(logger)

    etc..

    J’obtiens la même chose (NameError) que je définisse “log” avant ou dans ma définition de fonction.

    Merci de ton aide !

  • Sam Post author

    Ce n’est pas un problème de logging là, c’est un problème de base de programmation Python. Pour éviter de remplir les commentaires de l’article avec ce debuggage, ouvre un post sur indexerror.net.

  • Bob

    Après plusieurs utilisation du snippet je me suis rendu compte d’un petite typo:

    il faut remplacer steam_handler par stream_handler

    My 2 cents

  • Poil

    Hello,

    Un truc que je ne pige pas avec le logger Python

    J’ai une appli Flask :

    run.py

    testlog/mymod/init.py

    
    import logging
    
    logger = logging.getLogger(__name__)
    
    class MyMod(object):
    
    def __init__(self):
    
    logger.debug('kikoo')
    
    from logging_tree import printout
    
    printout()
    
    

    V2 : (logger self.logger)

    testlog/mymod/mymod.py

    
    from logging_tree import printout
    
    printout()
    
    

    J’ai en V1:

    Et en V2

    Notez que je n’ai pas le Disabled ce qui semble faire que ça tombe en marche, je ne comprend pas pourquoi …

    Note ma conf de logger

    <

    pre lang=”python>

    [loggers]

    keys = root

    [handlers]

    keys=syslog

    [formatters]

    keys=generic

    [logger_root]

    level=DEBUG

    handlers=syslog

    [handler_syslog]

    class=logging.handlers.SysLogHandler

    formatter=generic

    args = (‘/dev/log’, handlers.SysLogHandler.LOG_USER)

    [formatter_generic]

    format=%(name)s: [%(module)s:%(pathname)s:%(filename)s:%(lineno)s] [%(levelname)s] %(message)s

    class=logging.Formatter

    </>

  • Sam Post author

    Pose la question sur indexerror.net, le blog c’est pourri pour debugger.

  • ian0delond

    Je crois qu’il y a un problème avec l’article.

    Tu l’as écrasé en le remplaçant par la question de Poil. C’est dommage car l’article était bien rédigé.

Comments are closed.

Des questions Python sans rapport avec l'article ? Posez-les sur IndexError.