En savoir plus sur la journalisation à l'aide du module de journalisation de Python ①

introduction

Je suis sûr que beaucoup de gens l'ont fait en spécifiant un nom de logger et en utilisant une instance de logger (comme getLogger (__ name __) en python). Je pense qu'il y a beaucoup de gens qui ne pensent qu'à ce nom d'enregistreur et au nom à enregistrer. J'ai donc essayé d'apprendre à créer une bibliothèque de journalisation commune avec Easy Python.

Préoccupations

Voici un bref résumé de vos préoccupations lors de la connexion. Gardez à l'esprit que ceux-ci ne sont ni nécessaires ni suffisants et que cet article ne propose pas de solution pour tous.

―― Comment utilisez-vous le nom que vous avez défini lors de l'utilisation de l'enregistreur?

• Est-ce que l'enregistreur est sûr pour les threads? (N'est-ce pas un accident d'écrire dans un fichier à partir de plusieurs threads?)
• Le processus de l'enregistreur est-il sûr? (N'est-ce pas un accident d'écrire dans un fichier à partir de plusieurs processus?)
• Est-ce que l'enregistrement d'une E / S bloquante?

supposition

Cet article est destiné à Python et Flask, que j'utilise souvent pour implémenter du code de validation. D'autre part, les préoccupations mentionnées ci-dessus sont communes aux langages et aux systèmes d'exploitation (couramment utilisés comme Linux). En d'autres termes, savoir comment le langage et le cadre sélectionnés cette fois se rapprochent / ce à quoi le programmeur devrait se soucier lors de leur utilisation peut également être utilisé lors de l'utilisation d'autres langages et frameworks. Je crois que ça pourrait l'être.

Commencer à étudier

L'introduction est devenue plus longue.

Instance de l'enregistreur et arborescence de l'enregistreur

À propos de l'instance Logger

Pour comprendre la bibliothèque de journalisation, nous devons d'abord connaître l'instance Logger.

Lors de l'écriture de journaux à l'aide du package de journalisation, nous demandons à l'instance Logger de faire le travail. Les instances de journalisation sont conçues pour être la ** seule instance ** responsable de certaines activités de journalisation. Un bon moyen pour les programmeurs d'utiliser une instance de Logger dans leur code est d'appeler une fonction de journalisation attachée au module de journalisation (comme logging.warning ()) ou d'obtenir une instance de Logger avec getLogger (name = None). Est d'appeler cette méthode de journalisation. (Ce n'est pas une nouvelle instance de la classe Logger!)

Comme vous pouvez le voir en lisant le module de journalisation, chaque fonction de journalisation du module de journalisation appelle lui-même la [méthode d'instance de journalisation racine]. Je suis](https://github.com/python/cpython/blob/3.8/Lib/logging/init.py#L2047). L'enregistreur racine est généré lorsque le module de journalisation est chargé et est conservé dans la portée du module.

Comment l'utiliser, c'est comme ça.

use_root_logger.py

import logging

# https://docs.python.org/ja/3/library/logging.html
# https://docs.python.org/ja/3/howto/logging.html
logging.warning('Watch out!')  # will print a message to the console
logging.info('I told you so')  # will not print anything

Ensuite, à propos de l'instance Logger. Il n'y a qu'une seule instance de Logger sur le même processus qui peut être obtenue par getLogger (name = None). En d'autres termes, c'est Singleton. Chaque instance de Logger est gérée par logging.Manager, et logging.Manager lui-même est [instancié](https: /) afin qu'il devienne un champ de classe de la classe logging.Logger lorsque le module de journalisation est chargé. /github.com/python/cpython/blob/3.8/Lib/logging/init.py#L1890). logging.Manager recherche une instance Logger existante avec le nom de l'argument comme clé et retourne cette instance si elle existe.

Vous n'avez pas à réfléchir sérieusement, et voici comment l'utiliser.

use_get_logger.py

import logging

# https://docs.python.org/ja/3/library/logging.html
# https://docs.python.org/ja/3/howto/logging.html
logger = logging.getLogger('simple_example')
#Omission
logger.warning('warn message')

Arbre enregistreur

Le mot root logger est sorti. Dans de nombreuses bibliothèques de journalisation, Logger est un singleton et possède une structure arborescente. (Au moins, je connais la journalisation python, java java.util.logging, org.apache.logging.log4j. C # NLog était certainement le même.)

L'enregistreur dans le module d'enregistrement est conçu pour avoir une structure arborescente avec l'enregistreur racine comme sommet. Il est peut-être plus facile d’imaginer qu’il s’agit d’une structure de répertoires pour les personnes travaillant sur Internet et les ingénieurs d’infrastructure Windows comme moi. Il peut y avoir de nombreuses raisons pour cette conception, mais je pense que le plus grand avantage est que les espaces de noms peuvent être séparés et que la seule ressource peut être clairement affichée. Puisque logging.Manager identifie et gère les instances de Logger par des chaînes, il est facile de maintenir l'unicité de la ressource appelée instance de Logger car la méthode de création d'une arborescence comme FQDN est morte.

Par exemple, disons que vous avez créé un service d'assistance pour les voyageurs à Shimoro Onsen. Le système de réservation a l'ID de sous-système "book", le web de réservation a "web", l'API a "api", OSS est utilisé comme cadre de développement et les journaux sont séparés car ils sont gérés par des équipes différentes. Si tel est le cas, il est pratique de diviser l'instance de Logger par cette unité. Comme ça.

gero_onsen.py

web_book_logger = logging.getLogger('gero.book.web')
... #Définir un gestionnaire à insérer dans la base de données affichée sur l'écran utilisateur de gestion

api_book_logger = logging.getLogger('gero.book.api')
... #Configurer les gestionnaires pour qu'ils volent vers CloudWatch Logs

from flask import Flask
app = Flask('gero')
app.logger.addHandler(...) #Configurer un gestionnaire pour informer l'équipe d'infrastructure de Slack

Étant donné que les noms des enregistreurs peuvent être classés et identifiés en les reliant avec «.», Le risque de porter accidentellement le nom et, par conséquent, d'écraser le fonctionnement de l'enregistreur peut être réduit.

Il existe également une autre fonctionnalité qui convient aux développeurs. Autrement dit, le contenu défini dans le Logger supérieur est hérité par l'enfant.

Dans l'exemple précédent, si vous modifiez le niveau de journalisation de "gero. ** book **", les niveaux de journal de "gero. ** book.web **" et "gero. ** book.api **" changeront également. , Gero.book ". Vous pouvez passer de l'état de débogage à l'état non-deubg en commutant uniquement l'instance supérieure de Logger sans modifier les paramètres de toutes les instances de Logger. C'est utile.

• Comme cela sera décrit plus loin, cela ressemble plus à l'enfant utilisant le parent Logger ou Handler, plutôt qu'aux paramètres propagés du parent à l'enfant.

Déplaçons-le.

logger_tree_exam_child1.py

import logging
import sys


def init_logger():
    # INIT
    global gero_book_logger
    global gero_question_logger
    global gero_book_web_logger
    # gero.book
    gero_book_logger = logging.getLogger('gero.book')
    gero_book_handler = logging.StreamHandler()
    gero_book_formatter = logging.Formatter(fmt='%(asctime)-15s [%(name)s] %(message)s')
    gero_book_handler.setFormatter(gero_book_formatter)
    gero_book_logger.addHandler(gero_book_handler)

    # gero.question
    gero_question_logger = logging.getLogger('gero_question')
    gero_question_handler = logging.StreamHandler()
    gero_question_formatter = logging.Formatter(fmt='%(asctime)-15s [%(name)s] %(message)s')
    gero_question_handler.setFormatter(gero_question_formatter)
    gero_question_logger.addHandler(gero_question_handler)

    # gero.book.web (gero.Faire un enfant du livre)
    gero_book_web_logger = logging.getLogger('gero.book.web')
    # handler,formateur non défini


init_logger()

# PRINT
print('test 1-1: "gero.book.Existe-t-il un journal Web?"', file=sys.stderr)
# SET LOG LEVEL (gero.book.Ne pas définir sur le Web)
gero_book_logger.setLevel(logging.DEBUG)
gero_question_logger.setLevel(logging.INFO)

# gero.book
gero_book_logger.debug('debug now')
gero_book_logger.info('info now')
gero_book_logger.warning('warning now')
gero_book_logger.error('error now')
gero_book_logger.critical('critical now')

# gero.question
gero_question_logger.debug('debug now')
gero_question_logger.info('info now')
gero_question_logger.warning('warning now')
gero_question_logger.error('error now')
gero_question_logger.critical('critical now')

# gero.book.web
gero_book_web_logger.debug('debug now')
gero_book_web_logger.info('info now')
gero_book_web_logger.warning('warning now')
gero_book_web_logger.error('error now')
gero_book_web_logger.critical('critical now')

print('test 1-2: "gero.Si vous modifiez le niveau d'erreur de l'enregistreur de livres, gero.book.Le niveau du web changera-t-il?"', file=sys.stderr)
gero_book_logger.setLevel(logging.ERROR)

# gero.book.web
gero_book_web_logger.debug('debug now')
gero_book_web_logger.info('info now')
gero_book_web_logger.warning('warning now')
gero_book_web_logger.error('error now')
gero_book_web_logger.critical('critical now')

Le résultat de l'exécution est le suivant.

test 1-1: "gero.book.Existe-t-il un journal Web?"
2020-09-05 13:51:02,874 [gero.book] debug now
2020-09-05 13:51:02,875 [gero.book] info now
2020-09-05 13:51:02,875 [gero.book] warning now
2020-09-05 13:51:02,875 [gero.book] error now
2020-09-05 13:51:02,875 [gero.book] critical now
2020-09-05 13:51:02,875 [gero_question] info now
2020-09-05 13:51:02,875 [gero_question] warning now
2020-09-05 13:51:02,875 [gero_question] error now
2020-09-05 13:51:02,875 [gero_question] critical now
2020-09-05 13:51:02,875 [gero.book.web] debug now
2020-09-05 13:51:02,875 [gero.book.web] info now
2020-09-05 13:51:02,875 [gero.book.web] warning now
2020-09-05 13:51:02,875 [gero.book.web] error now
2020-09-05 13:51:02,876 [gero.book.web] critical now
test 1-2: "gero.Si vous modifiez le niveau d'erreur de l'enregistreur de livres, gero.book.Le niveau du web changera-t-il?"
2020-09-05 13:51:02,876 [gero.book.web] error now
2020-09-05 13:51:02,876 [gero.book.web] critical now

Process finished with exit code 0

En modifiant le niveau de journalisation de l'instance Logger parent, vous pouvez voir que le niveau de sortie du journal de l'enfant change. Et si vous définissez votre propre niveau de journal pour l'instance Logger enfant, ou si vous définissez votre propre Handler pour l'instance Loggger enfant, et que vous modifiez le niveau de journal pour l'instance Logger parent?

logger_tree_exam_child1.py

import logging
import sys

"""Si vous définissez votre propre niveau de journal pour les instances de Logger enfants
"""


def init_logger():
    # INIT
    global gero_book_logger
    global gero_book_web_logger
    # gero.book
    gero_book_logger = logging.getLogger('gero.book')
    gero_book_handler = logging.StreamHandler()
    gero_book_formatter = logging.Formatter(fmt='%(asctime)-15s [%(name)s] %(message)s')
    gero_book_handler.setFormatter(gero_book_formatter)
    gero_book_logger.addHandler(gero_book_handler)

    # gero.book.web (gero.Faire un enfant du livre)
    gero_book_web_logger = logging.getLogger('gero.book.web')
    # handler,formateur non défini


init_logger()

# PRINT
print('test 2-1: "gero.book.Après avoir défini le niveau de journalisation sur le Web séparément, gero.Changer le niveau de journal du livre"', file=sys.stderr)
# SET LOG LEVEL
gero_book_logger.setLevel(logging.DEBUG)
gero_book_web_logger.setLevel(logging.DEBUG)

print('Changer avant', file=sys.stderr)
# gero.book
gero_book_logger.debug('Devrait sortir')
gero_book_logger.info('Devrait sortir')
gero_book_logger.warning('Devrait sortir')
gero_book_logger.error('Devrait sortir')
gero_book_logger.critical('Devrait sortir')

# gero.book.web
gero_book_web_logger.debug('Devrait sortir')
gero_book_web_logger.info('Devrait sortir')
gero_book_web_logger.warning('Devrait sortir')
gero_book_web_logger.error('Devrait sortir')
gero_book_web_logger.critical('Devrait sortir')

print('Après le changement', file=sys.stderr)
gero_book_logger.setLevel(logging.WARNING)

# gero.book
gero_book_logger.debug('N'apparait pas')
gero_book_logger.info('N'apparait pas')
gero_book_logger.warning('Devrait sortir')
gero_book_logger.error('Devrait sortir')
gero_book_logger.critical('Devrait sortir')

# gero.book.web
gero_book_web_logger.debug('Voulez-vous sortir? N'apparait pas?')
gero_book_web_logger.info('Voulez-vous sortir? N'apparait pas?')
gero_book_web_logger.warning('Devrait sortir')
gero_book_web_logger.error('Devrait sortir')
gero_book_web_logger.critical('Devrait sortir')

Le résultat de l'exécution est le suivant. Il semble que le niveau de journalisation défini pour l'instance enfant gero.book.web fonctionne.

test 2-1: "gero.book.Après avoir défini le niveau de journalisation sur le Web séparément, gero.Changer le niveau de journal du livre"
Changer avant
2020-09-06 03:11:27,524 [gero.book]Devrait sortir
2020-09-06 03:11:27,525 [gero.book]Devrait sortir
2020-09-06 03:11:27,525 [gero.book]Devrait sortir
2020-09-06 03:11:27,525 [gero.book]Devrait sortir
2020-09-06 03:11:27,525 [gero.book]Devrait sortir
2020-09-06 03:11:27,525 [gero.book.web]Devrait sortir
2020-09-06 03:11:27,525 [gero.book.web]Devrait sortir
2020-09-06 03:11:27,525 [gero.book.web]Devrait sortir
2020-09-06 03:11:27,525 [gero.book.web]Devrait sortir
2020-09-06 03:11:27,525 [gero.book.web]Devrait sortir
Après le changement
2020-09-06 03:11:27,525 [gero.book]Devrait sortir
2020-09-06 03:11:27,525 [gero.book]Devrait sortir
2020-09-06 03:11:27,525 [gero.book]Devrait sortir
2020-09-06 03:11:27,525 [gero.book.web]Voulez-vous sortir? N'apparait pas?
2020-09-06 03:11:27,526 [gero.book.web]Voulez-vous sortir? N'apparait pas?
2020-09-06 03:11:27,526 [gero.book.web]Devrait sortir
2020-09-06 03:11:27,526 [gero.book.web]Devrait sortir
2020-09-06 03:11:27,526 [gero.book.web]Devrait sortir

Process finished with exit code 0

Ajoutons maintenant un gestionnaire à gero.book.web. Cette fois, nous ne définissons pas le niveau de journalisation pour gero.book.web.

logger_tree_exam_child3.py

import logging
import sys

"""Si vous définissez votre propre gestionnaire pour une instance de Loggger enfant
"""


def init_logger():
    # INIT
    global gero_book_logger
    global gero_book_web_logger
    # gero.book
    gero_book_logger = logging.getLogger('gero.book')
    gero_book_handler = logging.StreamHandler()
    gero_book_formatter = logging.Formatter(fmt='%(asctime)-15s [%(name)s] %(message)s')
    gero_book_handler.setFormatter(gero_book_formatter)
    gero_book_logger.addHandler(gero_book_handler)

    # gero.book.web (gero.Faire un enfant du livre)
    gero_book_web_logger = logging.getLogger('gero.book.web')


init_logger()

# PRINT
print('test 3-1: "gero.book.Après avoir défini le niveau de journalisation sur le Web séparément, gero.Changer le niveau de journal du livre"', file=sys.stderr)
# SET LOG LEVEL
gero_book_logger.setLevel(logging.DEBUG)

print('Changer avant', file=sys.stderr)
# gero.book
gero_book_logger.debug('Devrait sortir')
gero_book_logger.info('Devrait sortir')
gero_book_logger.warning('Devrait sortir')
gero_book_logger.error('Devrait sortir')
gero_book_logger.critical('Devrait sortir')

# gero.book.web
gero_book_web_logger.debug('Devrait sortir')
gero_book_web_logger.info('Devrait sortir')
gero_book_web_logger.warning('Devrait sortir')
gero_book_web_logger.error('Devrait sortir')
gero_book_web_logger.critical('Devrait sortir')

print('Après le changement', file=sys.stderr)
print('- gero.book.Gestionnaire ajouté au côté Web', file=sys.stderr)
gero_book_web_handler = logging.StreamHandler()
gero_book_web_formatter = logging.Formatter(fmt='%(asctime)-15s [%(name)s] ### this is web ### %(message)s')
gero_book_web_handler.setFormatter(gero_book_web_formatter)
gero_book_web_logger.addHandler(gero_book_web_handler)
print('- gero.Changer le niveau du journal du livre en AVERTISSEMENT', file=sys.stderr)
gero_book_logger.setLevel(logging.WARNING)

# gero.book
gero_book_logger.debug('N'apparait pas')
gero_book_logger.info('N'apparait pas')
gero_book_logger.warning('Devrait sortir')
gero_book_logger.error('Devrait sortir')
gero_book_logger.critical('Devrait sortir')

# gero.book.web
gero_book_web_logger.debug('Voulez-vous sortir? N'apparait pas?')
gero_book_web_logger.info('Voulez-vous sortir? N'apparait pas?')
gero_book_web_logger.warning('Devrait sortir')
gero_book_web_logger.error('Devrait sortir')
gero_book_web_logger.critical('Devrait sortir')

print(gero_book_web_logger.handlers)

Le résultat de l'exécution est le suivant. Il existe deux journaux pour gero.book.web. Puisque le gestionnaire ajouté est vraiment «ajouté», le comportement est que le gestionnaire du journal parent et le gestionnaire d'origine sont émis. En outre, le journal du gestionnaire d'origine a été déplacé selon le LogLevel parent.

test 3-1: "gero.book.Après avoir défini le niveau de journalisation sur le Web séparément, gero.Changer le niveau de journal du livre"
Changer avant
2020-09-06 03:21:11,709 [gero.book]Devrait sortir
2020-09-06 03:21:11,709 [gero.book]Devrait sortir
2020-09-06 03:21:11,710 [gero.book]Devrait sortir
2020-09-06 03:21:11,710 [gero.book]Devrait sortir
2020-09-06 03:21:11,710 [gero.book]Devrait sortir
2020-09-06 03:21:11,710 [gero.book.web]Devrait sortir
2020-09-06 03:21:11,710 [gero.book.web]Devrait sortir
2020-09-06 03:21:11,710 [gero.book.web]Devrait sortir
2020-09-06 03:21:11,710 [gero.book.web]Devrait sortir
2020-09-06 03:21:11,710 [gero.book.web]Devrait sortir
Après le changement
- gero.book.Gestionnaire ajouté au côté Web
- gero.Changer le niveau du journal du livre en AVERTISSEMENT
2020-09-06 03:21:11,710 [gero.book]Devrait sortir
2020-09-06 03:21:11,710 [gero.book]Devrait sortir
2020-09-06 03:21:11,710 [gero.book]Devrait sortir
2020-09-06 03:21:11,711 [gero.book.web] ### this is web ###Devrait sortir
2020-09-06 03:21:11,711 [gero.book.web]Devrait sortir
2020-09-06 03:21:11,711 [gero.book.web] ### this is web ###Devrait sortir
2020-09-06 03:21:11,711 [gero.book.web]Devrait sortir
2020-09-06 03:21:11,711 [gero.book.web] ### this is web ###Devrait sortir
2020-09-06 03:21:11,711 [gero.book.web]Devrait sortir
[<StreamHandler <stderr> (NOTSET)>]

Process finished with exit code 0

Dans l'exemple de code ci-dessus, j'ai écrit un petit print (gero_book_web_logger.handlers) à la fin. Le résultat de cette exécution est «[<StreamHandler (NOTSET)>]». Il n'y a qu'un seul. Cela signifie que le niveau inférieur n'a pas le gestionnaire défini au niveau supérieur. La relation parent-enfant entre les instances de Logger ressemble plus au comportement selon lequel une instance de Logger enfant sait qui est son instance de Logger parent et appelle également sa méthode de journalisation (héritage de classe). Parfois, cela se comporte comme appeler une méthode du côté de la superclasse d'une méthode qui est remplacée dans une classe enfant). Cette implémentation est basée sur l'implémentation suivante de la méthode callHandlers ().

logging/__init__.py

#Abréviation
    def callHandlers(self, record):
        #Abréviation
        c = self
        found = 0
        while c:
            for hdlr in c.handlers:
                found = found + 1
                if record.levelno >= hdlr.level:
                    hdlr.handle(record)
            if not c.propagate:
                c = None    #break out
            else:
                c = c.parent
        #Abréviation

Examen des instances de Logger

Ainsi, le nom spécifié par getLogger (nom = Aucun) n'est pas seulement un nom, c'est comme le chemin absolu de Logger, et il est hiérarchique. De plus, on peut voir que les réglages effectués au niveau supérieur sont hérités par l'enfant, et que les réglages effectués par l'enfant sont prioritaires.

A partir de ces actions, je peux imaginer qu'il sera plus facile à utiliser si vous l'utilisez de la manière suivante.

1. Pour la journalisation telle que la journalisation sans but, attribuez un gestionnaire à une instance de Logger supérieure.
2. À l'exception des situations où vous souhaitez que l'instance de Logger enfant crache un autre niveau de journal dans un but spécifique, il est plus facile de le modifier en le contrôlant avec le niveau de journal parent sans définir le niveau de journal (en supposant dev → prd, etc.) Si).

• L'objectif spécifique est, par exemple, lorsque vous souhaitez créer un journal de trace uniquement pour les exceptions dictées.
• Si vous décidez d'utiliser un journal de trace uniquement, vous cracherez probablement une trace de pile dans le journal, mais il est désagréable (je pense) de le cracher dans le journal avec logger.warning (), par exemple.
• Dans un tel cas, par exemple, il existe un plan de conception comme suit.
• Le système de débogage d'impression (y compris la trace de pile) est émis avec DEBUG. --Logger pour les journaux de trace uniquement définit LogLevel sur DEBUG.

1. Il est plus facile d'utiliser les journaux si le gestionnaire est défini en fonction de l'objectif de chaque instance de Logger pour cracher les journaux (par exemple, il est plus facile de recracher uniquement le journal d'accès du service dans un fichier dédié et de l'agréger, ou de créer un journal dédié pour les exceptions).
2. Le processus ci-dessus ne doit être effectué qu'une seule fois dans le processus d'initialisation lorsque l'application démarre. L'instance déjà définie par logging.get_logger (" path.to.logger ") est récupérée.

Épilogue

Cet article mentionne d'abord comment utiliser la fonction de journalisation (c'est-à-dire root logger) du module logging, qui est également mentionné dans la documentation officielle de Python, pour aider à organiser l'idée. Cependant, je ne recommande personnellement pas d'utiliser l'enregistreur de racine. Il est facile de faire quelque chose comme "Si vous essayez de cracher les journaux d'un programme que vous avez écrit, vous obtiendrez beaucoup de journaux d'autres bibliothèques que vous importez et vous êtes mort sur le disque plein."

D'un autre côté, les bibliothèques de journalisation et de journalisation sont si profondes qu'elles ne sont pas faciles à écrire proprement, j'ai donc décidé d'étudier à partir de zéro et de les laisser dans l'article.

Links

Ci-dessous, divers coups de langue.

--logging --- Fonction de journalisation pour Python

• https://docs.python.org/ja/3/library/logging.html
• Logging HOWTO
  • https://docs.python.org/ja/3/howto/logging.html
• python/cpython - Github
  • https://github.com/python/cpython/tree/3.8/Lib/logging