Journalisation en Python dans Django

Question

Je développe une application Django et j'essaie d'utiliser le module de journalisation de Python pour la journalisation des erreurs et des traces. Idéalement, j'aimerais avoir différents loggers configurés pour différentes zones du site. Jusqu'à présent, j'ai réussi à faire fonctionner tout cela, mais il y a une chose qui me laisse perplexe.

J'ai le journal Root qui va vers sys.stderr, et j'ai configuré un autre journal pour écrire dans un fichier. Ceci est dans mon fichier settings.py :

sviewlog = logging.getLogger('MyApp.views.scans')
view_log_handler = logging.FileHandler('C:\\MyApp\\logs\\scan_log.log')
view_log_handler.setLevel(logging.INFO)
view_log_handler.setFormatter(logging.Formatter('%(asctime)s %(name)-12s %(levelname)-8s %(message)s'))
sviewlog.addHandler(view_log_handler)

Cela semble assez simple. Mais voici le problème : tout ce que j'écris dans le sviewlog est écrit deux fois dans le fichier journal. Le logger Root ne l'imprime qu'une fois. C'est comme si addHandler() était appelé deux fois. Et lorsque je passe mon code dans un débogueur, c'est exactement ce que je vois. Le code dans settings.py est exécuté deux fois, donc deux FileHandlers sont créés et ajoutés à la même instance de logger. Mais pourquoi ? Et comment puis-je contourner ce problème ?

Quelqu'un peut-il me dire ce qui se passe ici ? J'ai essayé de déplacer le code d'instanciation du logger/handler sviewlog dans le fichier où il est utilisé (puisque cela me semble être l'endroit approprié), mais j'ai le même problème. La plupart des exemples que j'ai vus en ligne n'utilisent que le logger Root, et je préférerais avoir plusieurs loggers.

Answer 1

Permettez-moi de répondre à ma propre question. Le problème sous-jacent ici est que settings.py est importé deux fois, ou peut-être même plus (Voir ici ). (Je ne comprends toujours pas pourquoi. Peut-être qu'un expert de Django pourrait me l'expliquer). Cela semble être vrai pour certains autres modules également. À ce stade, je ne pense pas qu'il soit sage de faire des hypothèses sur le nombre de fois que settings.py sera importé. D'ailleurs, de telles suppositions ne sont pas sûres en général. J'ai eu ce code dans d'autres endroits que settings.py, et les résultats sont similaires.

Vous devez coder autour de cela. En d'autres termes, vous devez vérifier l'existence de gestionnaires dans votre journal avant d'en ajouter d'autres. C'est un peu laid parce qu'il est parfaitement raisonnable d'avoir plusieurs gestionnaires -- même du même type -- attachés à un logger. Il existe quelques solutions pour résoudre ce problème. La première consiste à vérifier la propriété handlers de votre objet logger. Si vous ne voulez qu'un seul gestionnaire et que votre longueur > 0, alors ne l'ajoutez pas. Personnellement, je n'aime pas cette solution, car elle devient désordonnée avec plus de gestionnaires.

Je préfère quelque chose comme ceci (merci à Thomas Guettler) :

# file logconfig.py
if not hasattr(logging, "set_up_done"):
    logging.set_up_done=False

def set_up(myhome):
    if logging.set_up_done:
        return
    # set up your logging here
    # ...
    logging.set_up_done=True

Je dois dire que j'aimerais que le fait que Django importe settings.py plusieurs fois soit mieux documenté. Et j'imagine que ma configuration est en quelque sorte à l'origine de cette importation multiple, mais j'ai du mal à trouver ce qui cause le problème et pourquoi. Peut-être que je n'ai pas pu trouver cela dans leurs documents, mais je pense que c'est le genre de chose dont vous devez avertir vos utilisateurs.

Answer 2

À partir de la version 1.3, Django utilise la journalisation standard de python, configurée avec l'attribut LOGGING (documenté ici : 1.3 , dev ).

Référence en matière de journalisation dans Django : 1.3 , dev .

Answer 3

Il est difficile de faire des commentaires sur votre cas spécifique. Si settings.py est exécuté deux fois, alors il est normal que vous obteniez deux lignes pour chaque journal envoyé.

Nous avons rencontré le même problème et nous avons donc mis en place dans nos projets un module dédié à la journalisation. Ce module a un pattern "module singleton", de sorte que nous n'exécutons le code intéressant qu'une seule fois.

Ça ressemble à ça :

def init_logging():
    stdoutHandler = logging.StreamHandler( sys.stdout )
    stdoutHandler.setLevel( DEBUG )
    stdoutHandler.setFormatter( logging.Formatter( LOG_FORMAT_WITH_TIME ) )
    logging.getLogger( LOG_AREA1 ).addHandler( stdoutHandler )

logInitDone=False #global variable controlling the singleton.
if not logInitDone:
    logInitDone = True
    init_logging()

Importer le fichier log.py la première fois configurera la journalisation correctement.

Answer 4

Je fais revivre un vieux fil de discussion, mais je rencontrais des messages en double en utilisant la journalisation Python de Django 1.3 avec l'option format dictConfig .

El disable_existing_loggers élimine le problème de duplication des gestionnaires/journaux en cas de chargements multiples de settings.py, mais vous pouvez toujours obtenir des messages de journal en double si vous ne spécifiez pas l'option propagate booléen de manière appropriée sur le logger . A savoir, assurez-vous que vous définissez propagate=False pour les enregistreurs d'enfants. Par exemple,

'loggers': {
    'django': {
        'handlers':['null'],
        'propagate': True,
        'level':'INFO',
    },
    'django.request': {
        'handlers': ['console'],
        'level': 'ERROR',
        'propagate': False,
    },
    'project': {
        'handlers': ['console', 'project-log-file'],
        'level': 'DEBUG',
        'propagate': True,
    },
    'project.customapp': {
        'handlers': ['console', 'customapp-log-file'],
        'level': 'DEBUG',
        'propagate': False,
    },
}

Ici, project.customapp fixe propagate=False afin qu'elle ne soit pas prise en compte par le programme project logger également. Le site Documentation sur la journalisation dans Django sont excellents, comme toujours.

Answer 5

Pour répondre à la question de savoir pourquoi "Django importe settings.py plusieurs fois" : ce n'est pas le cas.

En fait, il est importé deux fois (passez le premier morceau de code pour aller droit au but, mais c'est une bonne lecture si vous avez le temps) :

http://blog.dscpl.com.au/2010/03/improved-wsgi-script-pour-utiliser-avec.html

PS- Désolé de raviver un vieux fil.