Vertiefte Kenntnisse des Python-Protokollierungsmoduls

零到壹度
Freigeben: 2018-04-03 15:02:06
Original
1930 Leute haben es durchsucht

Dieser Artikel führt hauptsächlich in ein tiefgreifendes Verständnis des Python-Protokollierungsmoduls ein. Der Herausgeber findet es recht gut. Es wird hauptsächlich die Verwendung der Protokollierung zur Ausgabe von Protokollen in einem Multiprozess erläutert Umgebung. So teilen Sie Protokolldateien sicher auf. Jetzt teile ich es mit Ihnen und gebe es als Referenz. Folgen wir dem Editor und werfen wir einen Blick darauf

1 Einführung in das Protokollierungsmodul

Das Protokollierungsmodul von Python bietet ein flexibles Standardmodul, das es jedem Python-Programm ermöglicht, dieses Modul eines Drittanbieters zu verwenden Protokollierung implementieren. Offizielle Dokumentation zur Python-Protokollierung

Das Protokollierungsframework besteht hauptsächlich aus vier Teilen:

  • Logger: eine Schnittstelle, die direkt vom Programm aufgerufen werden kann

  • Handler: Bestimmen, ob Protokolldatensätze dem richtigen Ziel zugewiesen werden

  • Filter: Bieten eine detailliertere Beurteilung, ob Protokolle ausgegeben werden sollen

  • Formatierer: Entwickeln Sie das Formatlayout für den endgültigen Datensatzdruck

2. Die Zusammensetzung der Protokollierung

Logger

Logger ist eine Protokollierungsschnittstelle, die direkt vom Programm aufgerufen werden kann und Protokollinformationen direkt in den Logger schreiben kann . Der Logger wird nicht direkt instanziiert, sondern das Objekt wird über logging.getLogger(name) abgerufen. Tatsächlich handelt es sich bei dem Logger-Objekt um einen Singleton-Modus, und die Protokollierung ist Multithread-sicher. Das heißt, das Logger-Objekt wird unabhängig von der Stelle im Programm abgerufen protokolliert werden. Es ist das Gleiche. Leider unterstützt der Logger keine Multiprozesse. Dies wird in den folgenden Kapiteln erläutert und es werden einige Lösungen gegeben.
[Hinweis] Das Logger-Objekt hat eine Eltern-Kind-Beziehung. Wenn kein Eltern-Logger-Objekt vorhanden ist, wird die Eltern-Kind-Beziehung korrigiert. Beispielsweise erstellt logging.getLogger("abc.xyz") zwei Logger-Objekte, eines ist das übergeordnete Objekt „abc“ und das andere ist das untergeordnete Objekt „xyz“. Gleichzeitig hat abc kein übergeordnetes Objekt, sodass sein übergeordnetes Objekt das Stammobjekt ist. Tatsächlich ist abc jedoch ein Platzhalterobjekt (virtuelles Protokollobjekt), und es gibt keinen Handler zum Verarbeiten des Protokolls. Root ist jedoch kein Platzhalterobjekt. Wenn ein Protokollobjekt protokolliert, erhält es gleichzeitig das Protokoll. Daher stellen einige Benutzer fest, dass sie beim Erstellen eines Protokollierungsobjekts zweimal protokollieren, da der von ihnen erstellte Protokollierer Protokolle erstellt. Das Protokoll wird einmal protokolliert, und das Stammobjekt wird ebenfalls einmal protokolliert.

Jeder Logger hat eine Protokollebene. Die folgenden Ebenen sind in der Protokollierung definiert

Level Numeric value
NOTSET 0
DEBUG 10
INFO 20
WARNING 30
ERROR 40
CRITICAL 50

Wenn ein Logger die Protokollinformationen empfängt, stellt er zunächst fest, ob sie die Stufe erfüllen. Wenn er sich für die Verarbeitung entscheidet, gibt er die Informationen zur Verarbeitung an Handler weiter.

Handler

Handler verteilen die vom Logger gesendeten Informationen genau und senden sie an die richtige Stelle. Senden Sie es beispielsweise an die Konsole oder Datei oder an beide oder andere Orte (Prozesspipelines und dergleichen). Es bestimmt das Verhalten jedes Protokolls und ist der Schlüsselbereich, der später konfiguriert werden muss.

Jeder Handler hat auch eine Protokollebene. Ein Logger kann mehrere Handler haben, was bedeutet, dass der Logger Protokolle entsprechend unterschiedlicher Protokollebene an verschiedene Handler weiterleiten kann. Natürlich kann die gleiche Ebene auch an mehrere Handler übergeben werden, die je nach Bedarf flexibel eingestellt werden können.

Filter

Filter ermöglichen eine detailliertere Beurteilung, ob das Protokoll gedruckt werden muss. Wenn der Handler ein Protokoll erhält, wird es grundsätzlich einheitlich entsprechend der Ebene verarbeitet. Wenn der Handler jedoch über einen Filter verfügt, kann er eine zusätzliche Verarbeitung und Beurteilung des Protokolls durchführen. Beispielsweise kann Filter Protokolle von einer bestimmten Quelle abfangen oder ändern oder sogar deren Protokollebene ändern (die Ebene wird nach der Änderung beurteilt).

Sowohl Logger als auch Handler können Filter installieren und sogar mehrere Filter können in Reihe installiert werden.

Formatter

Formatter geben das Formatlayout für den endgültigen Druck eines bestimmten Datensatzes an. Formatter fügt die übergebenen Informationen in eine bestimmte Zeichenfolge ein. Standardmäßig druckt Format die Informationen nur %(message)s direkt aus. Es gibt einige integrierte LogRecord-Eigenschaften, die im Format verwendet werden können, wie in der folgenden Tabelle gezeigt:

Attribut Format Beschreibung
asctime %(asctime)s Konstruieren Sie die Zeit des Protokolls in einer lesbaren Form, standardmäßig ist sie „2016-02-08 12:00:00,123“ mit einer Genauigkeit von Millisekunden
Dateiname %(filename)s Dateiname mit Pfad
funcName %(funcName ) s von welcher Funktion ausgegebenes Protokoll
Levelname %(levelname)s Die letzte Ebene des Protokolls (empfangen). durch Filter geändert)
Nachricht %(message)s Protokollnachricht
lineno %(lineno)d Die Zeilennummer des aktuellen Protokolls
Pfadname %( pathname)s Vollständiger Pfad
Prozess %(process)s Aktueller Prozess
Thread %(thread)s Aktueller Thread

Ein Handler kann nur einen Formatierer haben. Wenn Sie also eine Ausgabe in mehreren Formaten erreichen möchten, können Sie nur mehrere Handler verwenden.

3. Protokollierungskonfiguration

Einfache Konfiguration

Zuallererst haben wir im Logger-Kapitel einen Standard-Protokollobjektstamm. Der Vorteil dieses Stammprotokollobjekts ist kann die Protokollierung direkt zur Konfiguration und Protokollierung verwenden. Zum Beispiel:

logging.basicConfig(level=logging.INFO,filename='logger.log')
logging.info("info message")
Nach dem Login kopieren


Die einfache Konfiguration hier bezieht sich also auf das Root-Protokollobjekt, das jederzeit verwendet werden kann. Jeder Logger ist ein Singleton-Objekt und kann daher nach der Konfiguration an einer beliebigen Stelle im Programm aufgerufen werden. Wir müssen nur basicConfig aufrufen, um das Root-Protokollobjekt einfach zu konfigurieren. Tatsächlich ist diese Methode sehr effektiv und einfach zu verwenden. Dadurch wird sichergestellt, dass beim Aufruf eines Loggers mindestens ein Handler vorhanden ist, der das Protokoll verarbeiten kann.
Eine einfache Konfiguration kann grob wie folgt eingerichtet werden:

logging.basicConfig(level=logging.INFO,
         format='%(asctime)s %(filename)s[line:%(lineno)d] %(levelname)s %(message)s',
         datefmt='[%Y-%m_%d %H:%M:%S]',
         filename='../log/my.log',
         filemode='a')
Nach dem Login kopieren

Code-Konfiguration

Eine weitere detailliertere Einstellungsmethode besteht darin, sie im Code zu konfigurieren, aber diese Einstellungsmethode ist die geringste Schließlich möchte niemand die Einstellungen fest in den Code einbinden. Aber hier ist eine kurze Einführung. Obwohl es nicht oft verwendet wird, können Sie es bei Bedarf trotzdem verwenden. (Wird später hinzugefügt)

Konfiguration der Konfigurationsdatei

Die Protokollierungskonfigurationsdatei in Python basiert auf der Funktion von ConfigParser. Mit anderen Worten: Auch das Format der Konfigurationsdatei wird auf diese Weise geschrieben. Lassen Sie mich Ihnen zunächst eine allgemeinere Konfigurationsdatei geben und sie dann im Detail erklären.

##############################################
[loggers]
keys=root, log02
 
[logger_root]
level=INFO
handlers=handler01
 
 
[logger_log02]
level=DEBUG
handler=handler02
qualname=log02
##############################################
[handlers]
keys=handler01,handler02
 
[handler_handler01]
class=FileHandler
level=INFO
formatter=form01
args=('../log/cv_parser_gm_server.log',"a")
 
[handler_handler02]
class=StreamHandler
level=NOTSET
formatter=form01
args=(sys.stdout,)
##############################################
[formatters]
keys=form01,form02
 
[formatter_form01]
format=%(asctime)s %(filename)s[line:%(lineno)d] %(levelname)s %(process)d %(message)s
datefmt=[%Y-%m-%d %H:%M:%S]
 
[formatter_form02]
format=(message)s
##############################################
Nach dem Login kopieren


Ich glaube, dass ich nach dem erneuten Lesen die Regeln finden werde Verwenden Sie #, um ein paar große Stücke zu markieren. Jeder Logger, Handler oder Formatierer hat einen Schlüsselnamen. Am Beispiel des Loggers müssen Sie zunächst den Schlüsselnamen zur Konfiguration [loggers] hinzufügen, um den Logger darzustellen. Verwenden Sie dann [loggers_xxxx], wobei xxxx der Schlüsselname ist, um diesen Logger speziell zu konfigurieren. In log02 habe ich die Ebene und einen Handlernamen konfiguriert. Gehen Sie anhand dieses Handlernamens zu [Handler], um die Konfiguration des jeweiligen Handlers usw. zu finden.
Dann laden Sie im Code die Konfigurationsdatei wie folgt

logging.config.fileConfig(log_conf_file)
Nach dem Login kopieren

在handler中有一个class配置,可能有些读者并不是很懂。其实这个是logging里面原先就写好的一些handler类,你可以在这里直接调用。class指向的类相当于具体处理的Handler的执行者。在logging的文档中可以知道这里所有的Handler类都是线程安全的,大家可以放心使用。那么问题就来了,如果多进程怎么办呢。在下一章我主要就是重写Handler类,来实现在多进程环境下使用logging。 我们自己重写或者全部新建一个Handler类,然后将class配置指向自己的Handler类就可以加载自己重写的Handler了。

4. logging遇到多进程(important)

这部分其实是我写这篇文章的初衷。python中由于某种历史原因,多线程的性能基本可以无视。所以一般情况下python要实现并行操作或者并行计算的时候都是使用多进程。但是 python 中logging 并不支持多进程,所以会遇到不少麻烦。
本次就以 TimedRotatingFileHandler 这个类的问题作为例子。这个Handler本来的作用是:按天切割日志文件。(当天的文件是xxxx.log 昨天的文件是xxxx.log.2016-06-01)。这样的好处是,一来可以按天来查找日志,二来可以让日志文件不至于非常大, 过期日志也可以按天删除。
但是问题来了,如果是用多进程来输出日志,则只有一个进程会切换,其他进程会在原来的文件中继续打,还有可能某些进程切换的时候早就有别的进程在新的日志文件里打入东西了,那么他会无情删掉之,再建立新的日志文件。反正将会很乱很乱,完全没法开心的玩耍。
所以这里就想了几个办法来解决多进程logging问题

原因

在解决之前,我们先看看为什么会导致这样的原因。
先将 TimedRotatingFileHandler 的源代码贴上来,这部分是切换时所作的操作:

 def doRollover(self):
        """
        do a rollover; in this case, a date/time stamp is appended to the filename
        when the rollover happens.  However, you want the file to be named for the
        start of the interval, not the current time.  If there is a backup count,
        then we have to get a list of matching filenames, sort them and remove
        the one with the oldest suffix.
        """
        if self.stream:
            self.stream.close()
            self.stream = None
        # get the time that this sequence started at and make it a TimeTuple
        currentTime = int(time.time())
        dstNow = time.localtime(currentTime)[-1]
        t = self.rolloverAt - self.interval
        if self.utc:
            timeTuple = time.gmtime(t)
        else:
            timeTuple = time.localtime(t)
            dstThen = timeTuple[-1]
            if dstNow != dstThen:
                if dstNow:
                    addend = 3600
                else:
                    addend = -3600
                timeTuple = time.localtime(t + addend)
        dfn = self.baseFilename + "." + time.strftime(self.suffix, timeTuple)
        if os.path.exists(dfn):
            os.remove(dfn)
        # Issue 18940: A file may not have been created if delay is True.
        if os.path.exists(self.baseFilename):
            os.rename(self.baseFilename, dfn)
        if self.backupCount > 0:
            for s in self.getFilesToDelete():
                os.remove(s)
        if not self.delay:
            self.stream = self._open()
        newRolloverAt = self.computeRollover(currentTime)
        while newRolloverAt <= currentTime:
            newRolloverAt = newRolloverAt + self.interval
        #If DST changes and midnight or weekly rollover, adjust for this.
        if (self.when == &#39;MIDNIGHT&#39; or self.when.startswith(&#39;W&#39;)) and not self.utc:
            dstAtRollover = time.localtime(newRolloverAt)[-1]
            if dstNow != dstAtRollover:
                if not dstNow:  # DST kicks in before next rollover, so we need to deduct an hour
                    addend = -3600
                else:           # DST bows out before next rollover, so we need to add an hour
                    addend = 3600
                newRolloverAt += addend
        self.rolloverAt = newRolloverAt
Nach dem Login kopieren


我们观察 if os.path.exists(dfn) 这一行开始,这里的逻辑是如果 dfn 这个文件存在,则要先删除掉它,然后将 baseFilename 这个文件重命名为 dfn 文件。然后再重新打开 baseFilename这个文件开始写入东西。那么这里的逻辑就很清楚了

  1. 假设当前日志文件名为 current.log 切分后的文件名为 current.log.2016-06-01

  2. 判断 current.log.2016-06-01 是否存在,如果存在就删除

  3. 将当前的日志文件名 改名为current.log.2016-06-01

  4. 重新打开新文件(我观察到源代码中默认是”a” 模式打开,之前据说是”w”)

于是在多进程的情况下,一个进程切换了,其他进程的句柄还在 current.log.2016-06-01 还会继续往里面写东西。又或者一个进程执行切换了,会把之前别的进程重命名的 current.log.2016-06-01 文件直接删除。又或者还有一个情况,当一个进程在写东西,另一个进程已经在切换了,会造成不可预估的情况发生。还有一种情况两个进程同时在切文件,第一个进程正在执行第3步,第二进程刚执行完第2步,然后第一个进程 完成了重命名但还没有新建一个新的 current.log 第二个进程开始重命名,此时第二个进程将会因为找不到 current 发生错误。如果第一个进程已经成功创建了 current.log 第二个进程会将这个空文件另存为 current.log.2016-06-01。那么不仅删除了日志文件,而且,进程一认为已经完成过切分了不会再切,而事实上他的句柄指向的是current.log.2016-06-01。
好了这里看上去很复杂,实际上就是因为对于文件操作时,没有对多进程进行一些约束,而导致的问题。
那么如何优雅地解决这个问题呢。我提出了两种方案,当然我会在下面提出更多可行的方案供大家尝试。

解决方案1

先前我们发现 TimedRotatingFileHandler 中逻辑的缺陷。我们只需要稍微修改一下逻辑即可:

  1. 判断切分后的文件 current.log.2016-06-01 是否存在,如果不存在则进行重命名。(如果存在说明有其他进程切过了,我不用切了,换一下句柄即可)

  2. 以”a”模式 打开 current.log
    发现修改后就这么简单~
    talking is cheap show me the code:

  3. 不要以为代码那么长,其实修改部分就是 “##” 注释的地方而已,其他都是照抄源代码。这个类继承了 TimedRotatingFileHandler 重写了这个切分的过程。这个解决方案十分优雅,改换的地方非常少,也十分有效。但有网友提出,这里有一处地方依然不完美,就是rename的那一步,如果就是这么巧,同时两个或者多个进程进入了 if 语句,先后开始 rename 那么依然会发生删除掉日志的情况。确实这种情况确实会发生,由于切分文件一天才一次,正好切分的时候同时有两个Handler在操作,又正好同时走到这里,也是蛮巧的,但是为了完美,可以加上一个文件锁,if 之后加锁,得到锁之后再判断一次,再进行rename这种方式就完美了。代码就不贴了,涉及到锁代码,影响美观。

  4. class SafeRotatingFileHandler(TimedRotatingFileHandler):
    def __init__(self, filename, when=&#39;h&#39;, interval=1, backupCount=0, encoding=None, delay=False, utc=False):
         TimedRotatingFileHandler.__init__(self, filename, when, interval, backupCount, encoding, delay, utc)
    """
    Override doRollover
    lines commanded by "##" is changed by cc
    """
    def doRollover(self):
         """
         do a rollover; in this case, a date/time stamp is appended to the filename
         when the rollover happens.  However, you want the file to be named for the
         start of the interval, not the current time.  If there is a backup count,
         then we have to get a list of matching filenames, sort them and remove
         the one with the oldest suffix.
     
         Override,   1. if dfn not exist then do rename
                     2. _open with "a" model
         """
         if self.stream:
             self.stream.close()
             self.stream = None
         # get the time that this sequence started at and make it a TimeTuple
         currentTime = int(time.time())
         dstNow = time.localtime(currentTime)[-1]
         t = self.rolloverAt - self.interval
         if self.utc:
             timeTuple = time.gmtime(t)
         else:
             timeTuple = time.localtime(t)
             dstThen = timeTuple[-1]
             if dstNow != dstThen:
                 if dstNow:
                     addend = 3600
                 else:
                     addend = -3600
                 timeTuple = time.localtime(t + addend)
         dfn = self.baseFilename + "." + time.strftime(self.suffix, timeTuple)
    ##        if os.path.exists(dfn):
    ##            os.remove(dfn)
     
         # Issue 18940: A file may not have been created if delay is True.
    ##        if os.path.exists(self.baseFilename):
         if not os.path.exists(dfn) and os.path.exists(self.baseFilename):
             os.rename(self.baseFilename, dfn)
         if self.backupCount > 0:
             for s in self.getFilesToDelete():
                 os.remove(s)
         if not self.delay:
             self.mode = "a"
             self.stream = self._open()
         newRolloverAt = self.computeRollover(currentTime)
         while newRolloverAt <= currentTime:
             newRolloverAt = newRolloverAt + self.interval
         #If DST changes and midnight or weekly rollover, adjust for this.
         if (self.when == &#39;MIDNIGHT&#39; or self.when.startswith(&#39;W&#39;)) and not self.utc:
             dstAtRollover = time.localtime(newRolloverAt)[-1]
             if dstNow != dstAtRollover:
                 if not dstNow:  # DST kicks in before next rollover, so we need to deduct an hour
                     addend = -3600
                 else:           # DST bows out before next rollover, so we need to add an hour
                     addend = 3600
                 newRolloverAt += addend
         self.rolloverAt = newRolloverAt
    Nach dem Login kopieren

解决方案2

我认为最简单有效的解决方案。重写FileHandler类(这个类是所有写入文件的Handler都需要继承的TimedRotatingFileHandler 就是继承的这个类;我们增加一些简单的判断和操作就可以。
我们的逻辑是这样的:

  1. 判断当前时间戳是否与指向的文件名是同一个时间

  2. 如果不是,则切换 指向的文件即可
    结束,是不是很简单的逻辑。
    talking is cheap show me the code


check_baseFilename 就是执行逻辑1判断;build_baseFilename 就是执行逻辑2换句柄。就这么简单完成了。
这种方案与之前不同的是,当前文件就是 current.log.2016-06-01 ,到了明天当前文件就是current.log.2016-06-02 没有重命名的情况,也没有删除的情况。十分简洁优雅。也能解决多进程的logging问题。

  1. class SafeFileHandler(FileHandler):
    def __init__(self, filename, mode, encoding=None, delay=0):
         """
         Use the specified filename for streamed logging
         """
         if codecs is None:
             encoding = None
         FileHandler.__init__(self, filename, mode, encoding, delay)
         self.mode = mode
         self.encoding = encoding
         self.suffix = "%Y-%m-%d"
         self.suffix_time = ""
     
    def emit(self, record):
         """
         Emit a record.
     
         Always check time
         """
         try:
             if self.check_baseFilename(record):
                 self.build_baseFilename()
             FileHandler.emit(self, record)
         except (KeyboardInterrupt, SystemExit):
             raise
         except:
             self.handleError(record)
     
    def check_baseFilename(self, record):
         """
         Determine if builder should occur.
     
         record is not used, as we are just comparing times,
         but it is needed so the method signatures are the same
         """
         timeTuple = time.localtime()
     
         if self.suffix_time != time.strftime(self.suffix, timeTuple) or not os.path.exists(self.baseFilename+&#39;.&#39;+self.suffix_time):
             return 1
         else:
             return 0
    def build_baseFilename(self):
         """
         do builder; in this case,
         old time stamp is removed from filename and
         a new time stamp is append to the filename
         """
         if self.stream:
             self.stream.close()
             self.stream = None
     
         # remove old suffix
         if self.suffix_time != "":
             index = self.baseFilename.find("."+self.suffix_time)
             if index == -1:
                 index = self.baseFilename.rfind(".")
             self.baseFilename = self.baseFilename[:index]
     
         # add new suffix
         currentTimeTuple = time.localtime()
         self.suffix_time = time.strftime(self.suffix, currentTimeTuple)
         self.baseFilename  = self.baseFilename + "." + self.suffix_time
     
         self.mode = &#39;a&#39;
         if not self.delay:
             self.stream = self._open()
    Nach dem Login kopieren

    解决方案其他

    当然还有其他的解决方案,例如由一个logging进程统一打日志,其他进程将所有的日志内容打入logging进程管道由它来打理。还有将日志打入网络socket当中也是同样的道理。


    5. 参考资料

    python logging 官方文档
    林中小灯的切分方案,方案一就是从这儿来的

    Das obige ist der detaillierte Inhalt vonVertiefte Kenntnisse des Python-Protokollierungsmoduls. Für weitere Informationen folgen Sie bitte anderen verwandten Artikeln auf der PHP chinesischen Website!

Verwandte Etiketten:
Quelle:php.cn
Erklärung dieser Website
Der Inhalt dieses Artikels wird freiwillig von Internetnutzern beigesteuert und das Urheberrecht liegt beim ursprünglichen Autor. Diese Website übernimmt keine entsprechende rechtliche Verantwortung. Wenn Sie Inhalte finden, bei denen der Verdacht eines Plagiats oder einer Rechtsverletzung besteht, wenden Sie sich bitte an admin@php.cn
Beliebte Tutorials
Mehr>
Neueste Downloads
Mehr>
Web-Effekte
Quellcode der Website
Website-Materialien
Frontend-Vorlage