Décorateur de trace
lundi 15 avril 2013 à 19:33(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’objetgeneric
est une instance de cette classe. - Appel de la méthode
Generic.do_it()
par le biais de l’instructionsuper().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.