Décorateur de trace

This entry was posted in Programmation and tagged decorateur inspect introspection log on by

(Ceci est un post invité de xonop sous licence creative common 3.0 unported.)

Suite aux superbes articles sur les décorateurs et sur l’écriture des logs en python j’ai voulu mettre en pratique dans mon projet.
C’est là que les ennuis ont commencé !

Objectif :

Créer un décorateur qui me permette de tracer le passage dans certaines méthodes.
Celui-ci doit :

  • Être débrayable facilement.
  • Récupérer automatiquement le nom de la méthode, sa classe et son module.

Première étape : le logger

Avant toute chose mettons en place l’environnement pour pouvoir tracer en utilisant le module logging.
Pour simplifier les exemples, nous associons un seul handler de type terminal.
La fonction log_debug permet de faire appel au logger pour tracer une information.

logger.py :

import functools
import logging
 
__DECO_ACTIVATED = True
__logger = None
 
def init_logger():
    global __logger
    __logger = logging.getLogger()
    __logger.setLevel(logging.DEBUG)
    terminalHandler = logging.StreamHandler()
    terminalHandler.setLevel(logging.DEBUG)
    __logger.addHandler(terminalHandler)
 
def log_debug(text):
    __logger.debug(text)

Deuxième étape : le décorateur, version basique

Pour commencer, le décorateur débrayable :

logger.py :

def log_decorator(func):
    if not __DECO_ACTIVATED:
        return func
 
    @functools.wraps(func)
    def wrapped(*args, **kwargs):
        __logger.debug("BEGIN")
        data = func(*args, **kwargs)
        __logger.debug("END")
        return data
    return wrapped

Remarques :

  • La fonction est décorée selon la valeur de la variable __DECO_ACTIVATED.
  • La fonction wraps du module functools reporte les attributs de la fonction originale sur la version wrappée (dont les docstrings).

Et maintenant un module pour tester ça :

main.py :

import logger
 
class Generic():
    @logger.log_decorator
    def do_it(self, arg1):
        logger.log_debug(arg1)
 
if __name__ == "__main__":
    logger.init_logger()
    generic = Generic()
    generic.do_it("NOW")

Et voilà le résultat :

BEGIN
NOW
END

Troisième étape : les noms de module et de fonction

Ces informations se récupèrent facilement, voici la nouvelle version du décorateur :

logger.py :

def log_decorator(func):
    if not __DECO_ACTIVATED:
        return func
    module_name = func.__module__    func_name = func.__name__ 
    @functools.wraps(func)
    def wrapped(*args, **kwargs):
        msg = "Module={} Function={}".format(module_name, func_name)        __logger.debug("BEGIN " + msg)
        data = func(*args, **kwargs)
        __logger.debug("END " + msg)
        return data
    return wrapped

Et maintenant le résultat :

BEGIN Module=__main__ Function=do_it
NOW
END Module=__main__ Function=do_it

Jusqu’ici tout va bien.

Quatrième étape : le nom de la classe

Et c’est maintenant que les choses se corsent !
Tout d’abord, l’objet func que nous manipulons est une fonction et non une méthode de classe :

print(func)
<function Generic.do_it at 0x00C70348>

En effet lors de l’exécution du décorateur, la classe en tant qu’objet n’existe pas encore.
Il n’y a pas de lien direct entre la fonction et sa future classe.

Bon nombre de développeurs bien intentionnés nous conseillent d’utiliser self pour déterminer sa classe.

Oui mais :

  • Si la fonction n’est pas une méthode, pas de self !
  • La classe n’est pas obligatoirement celle de la méthode. Il peut s’agir d’une classe héritée.

Pour s’en convaincre, voici le nouveau décorateur :

logger.py :

def log_decorator(func):
    if not __DECO_ACTIVATED:
        return func
    module_name = func.__module__
    func_name = func.__name__
 
    @functools.wraps(func)
    def wrapped(*args, **kwargs):
        try:            class_name = args[0].__class__.__name__        except IndexError:            class_name = ""        msg = "Module={} Class={} Function={}".format(            module_name, class_name, func_name)        __logger.debug("BEGIN " + msg)
        data = func(*args, **kwargs)
        __logger.debug("END " + msg)
        return data
    return wrapped

Et maintenant le module de tests :

main.py :

import logger
 
class Generic():
    @logger.log_decorator
    def do_it(self, arg1):
        logger.log_debug(arg1)
 
class Specific(Generic):    @logger.log_decorator    def do_it(self, arg1):        super().do_it(arg1) 
if __name__ == "__main__":
    logger.init_logger()
    specific = Specific()    specific.do_it("NOW")

Et le résultat tant attendu :

BEGIN Module=__main__ Class=Specific Function=do_it
BEGIN Module=__main__ Class=Specific Function=do_it
NOW
END Module=__main__ Class=Specific Function=do_it
END Module=__main__ Class=Specific Function=do_it

Et là c’est le drâme, on a perdu la classe Generic ! Mais analysons plutôt l’exécution :

  • Appel de la méthode Specific.do_it() vu que l’objet generic est une instance de cette classe.
  • Appel de la méthode Generic.do_it() par le biais de l’instruction super().do_it()

Comme prévu, la classe de l’objet self ne change pas que l’on soit dans une méthode de la classe ou de l’une de ses super-classes.

Quatrième étape : autre approche

Ne pouvant déterminer directement la classe d’appartenance de la fonction, essayons de la chercher dans le module.
Pour commencer il nous faut l’objet module alors que nous ne connaissons que son nom.
Le module inspect propose justement ce service grâce à getmodule.
Voici le décorateur modifié :

logger.py :

import inspect
 
def log_decorator(func):
    if not __DECO_ACTIVATED:
        return func
    module_name = func.__module__
    module_obj = inspect.getmodule(func)    class_name = "UNKNOWN"    for key, obj in module_obj.__dict__.items():        try:            members = obj.__dict__            method = members[func.__name__]            if method == func:                class_name = key                break        except (KeyError, AttributeError):            pass    func_name = func.__name__
 
    @functools.wraps(func)
    def wrapped(*args, **kwargs):
        msg = "Module={} Class={} Function={}".format(
            module_name, class_name, func_name)
        __logger.debug("BEGIN " + msg)
        data = func(*args, **kwargs)
        __logger.debug("END " + msg)
        return data
 
    return wrapped

Pour rechercher la fonction, le décorateur doit :

  • Lister les objets du module.
  • Rechercher pour chaque objet le nom de la fonction dans les attributs de celui-ci. Si l’attribut correspond à notre fonction, c’est gagné !

Nous obtenons alors :

BEGIN Module=__main__ Class=UNKNOWN Function=do_it
BEGIN Module=__main__ Class=UNKNOWN Function=do_it
NOW
END Module=__main__ Class=UNKNOWN Function=do_it
END Module=__main__ Class=UNKNOWN Function=do_it

Pas glop ça marche pas !
Regardons le contenu du module avant la recherche :

print(module_obj.__dict__.keys())
dict_keys(['__builtins__', '__name__', '__file__', '__doc__', '__loader__',
           '__cached__', 'logger', '__package__'])

Curieusement les classes n’apparaissent pas, mais c’est tout à fait normal.
Comme vu précédemment, lors de l’exécution du décorateur la classe est en instance de création.
Il faut donc faire cette recherche lors de l’exécution de la fonction wrappée.

Le décorateur devient donc :

logger.py :

def log_decorator(func):
    if not __DECO_ACTIVATED:
        return func
    module_name = func.__module__
    module_obj = inspect.getmodule(func)
    func_name = func.__name__
 
    @functools.wraps(func)
    def wrapped(*args, **kwargs):
        class_name = "UNKNOWN"        for key, obj in module_obj.__dict__.items():            try:                members = obj.__dict__                method = members[func.__name__]                if method == func:                    class_name = key                    break            except (KeyError, AttributeError):                pass        msg = "Module={} Class={} Function={}".format(            module_name, class_name, func_name)        __logger.debug("BEGIN " + msg)
        data = func(*args, **kwargs)
        __logger.debug("END " + msg)
        return data
 
    return wrapped

Et le résultat :

BEGIN Module=__main__ Class=UNKNOWN Function=do_it
BEGIN Module=__main__ Class=UNKNOWN Function=do_it
NOW
END Module=__main__ Class=UNKNOWN Function=do_it
END Module=__main__ Class=UNKNOWN Function=do_it

Pas glop 2 le retour !
Faisons appel au débogueur suprême : print

key    = Generic
method = <function Generic.do_it at 0x00D07C90>
func   = <function Specific.do_it at 0x00D07CD8>
 
key    = Specific
method = <function Specific.do_it at 0x00D07D20>
func   = <function Specific.do_it at 0x00D07CD8>

Effectivement les références ne correspondent pas, et encore une fois, rien de plus normal.
La fonction d’origine a été wrappée donc celle présente dans le module n’est plus celle d’origine.
Qu’à cela ne tienne, recherchons-là !

Après la déclaration de la fonction wrapped, le décorateur la mémorise dans la variable wrapped_function.
Elle sera utilisée à l’exécution de la fonction.

logger.py :

def log_decorator(func):
    if not __DECO_ACTIVATED:
        return func
    module_name = func.__module__
    module_obj = inspect.getmodule(func)
    func_name = func.__name__
 
    @functools.wraps(func)
    def wrapped(*args, **kwargs):
        class_name = "UNKNOWN"
        for key, obj in module_obj.__dict__.items():
            try:
                members = obj.__dict__
                method = members[func.__name__]
                if method == wrapped_function:                    class_name = key
                    break
            except (KeyError, AttributeError):
                pass
        msg = "Module={} Class={} Function={}".format(
            module_name, class_name, func_name)
        __logger.debug("BEGIN " + msg)
        data = func(*args, **kwargs)
        __logger.debug("END " + msg)
        return data
 
    wrapped_function = wrapped    return wrapped

Et maintenant le résultat :

BEGIN Module=__main__ Class=Specific Function=do_it
BEGIN Module=__main__ Class=Generic Function=do_it
NOW
END Module=__main__ Class=Generic Function=do_it
END Module=__main__ Class=Specific Function=do_it

Ouf ! Ca marche !

Au menu du prochain épisode : logger la valeur de certains paramètres passés à la fonction décorée.

Xavier O. avec l’aide précieuse de Laurent B.

14 thoughts on “Décorateur de trace”

  • foxmask

    un peu dur à suivre (ou alors je ne suis pas reveillé). Peut-etre qu’une mise en évidence des lignes de code qui ont changé entre chaque étape aurait aidé.

  • Etienne

    Merci, très intéressant comme challenge. Je viens de passer deux heures à décortiquer tout ça et j’ai appris plein de chose.

    Cela dit je suis d’accord avec foxmax: c’est dur à suivre. Trop de rebondissements. Et aussi beaucoup de sujets différents abordés. Mais bon, rien n’est parfait en ce bas monde.

    Pour clarifier un peu le truc, déjà, je préciserais que ton décorateur est dans un module appelé “logger”. Ensuite, personnellement, j’enlèverais les double “__” dans logger: ça fait mal aux yeux et ça sert à rien (je trouve).

    Plus important, j’utiliserais une “new style class” en héritant de object, et je me passerais du

    super().do_it(arg)

    dans la classe Specific. Ce qui donnerait quelque chose comme ça:

    class Generic(object):
    @logger.log_decorator
    def do_it(self, arg1):
        logger.log_debug(arg1)
 
 
class Specific(Generic):
    pass

    … qui correspond plus à ce qu’on fait dans la vie réelle et est plus clair à lire.

    Incidemment, hériter de object dans Generic permet d’accéder à “l’arbre généalogique” de la classe par le biais de args[0].__class__.__mro__ dans la fonction wrapped de log_decorator, ce qui renvoie quelque chose comme ça:
    (class '__main__.Specific', class '__main__.Generic', type 'object').
    On a donc pas besoin de inspect. Il suffit, comme tu le propose, de voir si func.__name__ fait partie des méthodes des classes de la liste, et t’as la classe “d’origine” de la méthode:

    for klass in args[0].__class__.__mro__:
    if func.__name__ in klass.__dict__:
        orig_class = klass.__name__

    Ce qui allège considérablement le code.

  • xonop Post author

    @foxmask :
    Excellente remarque. Dès que je trouve comment modifier mon article, j’ajoute quelques surbrillances bien senties.

    @Etienne :
    Bien vu, je vais ajouter une phrase pour préciser que mes fonctions de log sont placées dans le module logger.

    Le “__” en préfixe est une convention que j’utilise pour bien préciser que la variable a une portée limitée au module.

    Sinon concernant ta proposition de modification, bonne suggestion mais en en fait non.
    Si la fonction n’est pas une méthode, pas de self.
    Par ailleurs, mon exemple permet de présenter le cas où une méthode est définie simultanément dans une classe et dans sa super-classe (cas assez fréquent s’il en est).
    Et dans ce cas précis, la fonction retourne le même nom de classe que l’on se trouve dans la méthode de la classe ou celle de la super-classe.
    La preuve en image :

    BEGIN Module=__main__ Class=Generic Function=do_it
BEGIN Module=__main__ Class=Generic Function=do_it
NOW
END Module=__main__ Class=Generic Function=do_it
END Module=__main__ Class=Generic Function=do_it

    Cela dit, ta méthode est intéressante puisqu’elle permet de limiter le champ de recherche de ma fonction aux seules classes appartenant à l’arbre d’héritage.

  • Etienne

    Par ailleurs, mon exemple permet de présenter le cas où une méthode est définie simultanément dans une classe et dans sa super-classe (cas assez fréquent s’il en est).

    Juste. Il faut rajouter un break je pense:

    for klass in args[0].__class__.__mro__:
    if func.__name__ in klass.__dict__:
        orig_class = klass.__name__
        break

    C’est là que je remarque que tu testes l’égalité des objets fonction, et pas de leur nom. C’est malin, je retiens.

    Si la fonction n’est pas une méthode, pas de self.

    On teste l’existence d’une instance de classe. Si pas de self, c’est pas une méthode. Et on traite la fonction en conséquence (déterminer le module ou elle a été définie)

    Mais bon, je pense que tout ça n’est pas tellement important. Ton code le fait c’est ça qui compte.

  • Sam

    Je tiens juste à préciser combien Max et moi on apprécie d’avoir des réactions aussi constructives sur le site :

    – les comments sont pertinents
    – ils sont polis
    – ils sont suivis de réactions positives et utiles par l’auteur
    – et ensuite le débat continue cordialement avec une vraie valeur ajoutée

    Pour un site de troll Python et de cul, on a une super communauté \o/

  • kontre

    +1 Etienne
    J’ai lu rapidos la réponse que tu (Sam) as faite au pavé sur l’article des salopes, je ne suis pas forcément d’accord avec toi mais je n’ai jamais vu quelqu’un répondre à un commentaire sur un sujet de ce type de manière aussi calme, raisonnée et construite. Ce n’est qu’un exemple, mais ça aide à créer une ambiance générale. Merci.

    Par contre j’avoue que pour cet article je n’ai pas encore eu la motivation de comprendre à fond. Il faudra que je potasse les décorateurs un jour.

  • Sam

    Tout le monde peut être en désacord, tant que c’est un désacord cordial.

  • xonop Post author

    Petite mise à jour de l’article, pour chaque source :

    – Ajout du nom de fichier.
    – Mise en évidence des modifications.

    Bonne lecture !

  • Sam

    Ah putain j’ai oublié de répondre à ta question sur comment mettre en avant une partie du code, sorry. En plus je savais pas comment faire :-p

Comments are closed.

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