Enregistrement Python (nom de la fonction, nom du fichier, numéro de ligne) à l'aide d'un seul fichier

Question

J'essaie d'apprendre comment fonctionne une application. Pour ce faire, j'insère des commandes de débogage à la première ligne du corps de chaque fonction dans le but d'enregistrer le nom de la fonction ainsi que le numéro de ligne (dans le code) où j'envoie un message à la sortie du journal. Enfin, étant donné que cette application comprend de nombreux fichiers, je souhaite créer un seul fichier journal afin de mieux comprendre le flux de contrôle de l'application.

Voici ce que je sais :

1. pour obtenir le nom de la fonction, je peux utiliser function_name.__name__ mais je ne veux pas utiliser le nom de la fonction (afin de pouvoir rapidement copier et coller un nom de fonction générique). Log.info("Message") dans le corps de toutes les fonctions). Je sais que cela pourrait être fait en C en utilisant __func__ macro mais je ne suis pas sûr pour python.

2. pour obtenir le nom du fichier et le numéro de ligne, j'ai vu que (et je crois que) mon application utilise Python locals() mais dans une syntaxe que je ne connais pas complètement, par exemple : options = "LOG.debug('%(flag)s : %(flag_get)s' % locals()) et j'ai essayé de l'utiliser comme LOG.info("My message %s" % locals()) ce qui donne quelque chose comme {'self': <__main__.Class_name object at 0x22f8cd0>} . Quel est votre avis à ce sujet ?

3. Je sais comment utiliser la journalisation et y ajouter un gestionnaire pour enregistrer dans un fichier, mais je ne suis pas sûr qu'un seul fichier puisse être utilisé pour enregistrer tous les messages de journalisation dans l'ordre correct des appels de fonction dans le projet.

Answer 1

La bonne réponse à cette question est d'utiliser l'outil déjà fourni funcName variable

import logging
logger = logging.getLogger(__name__)
FORMAT = "[%(filename)s:%(lineno)s - %(funcName)20s() ] %(message)s"
logging.basicConfig(format=FORMAT)
logger.setLevel(logging.DEBUG)

Ensuite, il suffit d'ajouter ce que l'on veut :

logger.debug('your message') 

Exemple de sortie d'un script sur lequel je travaille en ce moment :

[invRegex.py:150 -          handleRange() ] ['[A-Z]']
[invRegex.py:155 -     handleRepetition() ] [[<__main__.CharacterRangeEmitter object at 0x10ba03050>, '{', '1', '}']]
[invRegex.py:197 -          handleMacro() ] ['\\d']
[invRegex.py:155 -     handleRepetition() ] [[<__main__.CharacterRangeEmitter object at 0x10ba03950>, '{', '1', '}']]
[invRegex.py:210 -       handleSequence() ] [[<__main__.GroupEmitter object at 0x10b9fedd0>, <__main__.GroupEmitter object at 0x10ba03ad0>]]

Answer 2

Vous avez quelques questions marginalement liées les unes aux autres.

Je commencerai par le plus simple : (3). En utilisant logging vous pouvez regrouper tous les appels dans un seul fichier journal ou une autre cible de sortie : ils seront présentés dans l'ordre dans lequel ils se sont produits dans le processus.

Prochaine étape : (2). locals() fournit une dictée de la portée actuelle. Ainsi, dans une méthode qui n'a pas d'autres arguments, vous avez self qui contient une référence à l'instance actuelle. L'astuce utilisée qui vous laisse perplexe est le formatage de la chaîne de caractères à l'aide d'un dict en tant que RHS de la fonction % de l'opérateur. "%(foo)s" % bar sera remplacée par la valeur de bar["foo"] est.

Enfin, vous pouvez utiliser quelques astuces d'introspection, similaires à celles utilisées par pdb qui peut enregistrer plus d'informations :

def autolog(message):
    "Automatically log the current function details."
    import inspect, logging
    # Get the previous frame in the stack, otherwise it would
    # be this function!!!
    func = inspect.currentframe().f_back.f_code
    # Dump the message + the name of this function to the log.
    logging.debug("%s: %s in %s:%i" % (
        message, 
        func.co_name, 
        func.co_filename, 
        func.co_firstlineno
    ))

Cette opération enregistre le message transmis, ainsi que le nom (original) de la fonction, le nom du fichier dans lequel la définition apparaît et la ligne de ce fichier. Jetez un coup d'œil à inspect - Inspecter les objets vivants pour plus de détails.

Comme je l'ai mentionné dans mon commentaire précédent, vous pouvez également déposer dans un pdb l'invite de débogage interactif à tout moment en insérant la ligne import pdb; pdb.set_trace() et de réexécuter votre programme. Cela vous permet de parcourir le code et d'inspecter les données à votre guise.

Answer 3

funcname , linename y lineno fournissent des informations sur la dernière fonction qui a procédé à l'enregistrement.

Si vous avez un wrapper de logger (par exemple un singleton logger), alors la réponse de @synthesizerpatel pourrait ne pas fonctionner pour vous.

Pour connaître les autres appelants de la pile d'appels, vous pouvez procéder comme suit :

import logging
import inspect

class Singleton(type):
    _instances = {}

    def __call__(cls, *args, **kwargs):
        if cls not in cls._instances:
            cls._instances[cls] = super(Singleton, cls).__call__(*args, **kwargs)
        return cls._instances[cls]

class MyLogger(metaclass=Singleton):
    logger = None

    def __init__(self):
        logging.basicConfig(
            level=logging.INFO,
            format="%(asctime)s - %(threadName)s - %(message)s",
            handlers=[
                logging.StreamHandler()
            ])

        self.logger = logging.getLogger(__name__ + '.logger')

    @staticmethod
    def __get_call_info():
        stack = inspect.stack()

        # stack[1] gives previous function ('info' in our case)
        # stack[2] gives before previous function and so on

        fn = stack[2][1]
        ln = stack[2][2]
        func = stack[2][3]

        return fn, func, ln

    def info(self, message, *args):
        message = "{} - {} at line {}: {}".format(*self.__get_call_info(), message)
        self.logger.info(message, *args)

Answer 4

J'aime la réponse donnée par @synthesizerpatel mais j'aime mieux ce format pour inclure le nom du niveau.

FORMAT = "[%(asctime)s %(filename)s->%(funcName)s():%(lineno)s]%(levelname)s: %(message)s"
logging.basicConfig(format=FORMAT, level=logging.INFO)

Il en résulte quelque chose comme :

[2022-04-25 11:00:50,885 main.py->loop():21]INFO: looping

Pour le point 3, vous pouvez vous connecter à un fichier en utilisant filename dans la configuration de base :

logging.basicConfig(format=FORMAT, level=logging.INFO, filename='main.log')

mais je préfère mettre en place un fichier journal tournant afin qu'il ne grossisse pas de manière incontrôlée avec RotatingFileHandler. Il s'affichera également dans la console en même temps qu'il écrira dans le fichier journal.

Exemple complet main.py

import logging                                                                                         
from logging.handlers import RotatingFileHandler                                                       
import time                                                                                            

#Setup logger                                                                                          
logger = logging.getLogger(__name__)                                                                   
FORMAT = "[%(asctime)s %(filename)s->%(funcName)s():%(lineno)s]%(levelname)s: %(message)s"             
logging.basicConfig(format=FORMAT, level=logging.INFO)                                                 
#Log to file                                                                                           
logging_filename = 'main.log'                                                                          
handler = RotatingFileHandler(logging_filename, maxBytes=1000000, backupCount=10) #10 files of 1MB each
handler.setFormatter(logging.Formatter(FORMAT))                                                        
logger.addHandler(handler)                                                                             

def main():                                                                                            
  while True:                                                                                        
    loop()                                                                                         
    time.sleep(1)                                                                                  

def loop():                                                                                            
  logger.info('looping')                                                                             

if __name__== "__main__":                                                                              
  main()