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)

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 = 
func   = 

key    = Specific
method = 
func   = 

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.