Python 로깅 모듈에 대한 심층적인 이해
- 零到壹度원래의
- 2018-04-03 15:02:061984검색
이 글은 주로 Python 로깅 모듈에 대한 심층적인 이해를 소개하는 글입니다. 다중 프로세스 환경에서 로깅을 사용하여 로그를 출력하는 방법을 주로 설명합니다. 분할 로그 문서. 이제 모든 사람과 공유하고 참고용으로 제공합니다. 편집기를 따라 살펴보겠습니다1. 로깅 모듈 소개Python의 로깅 모듈은 유연한 표준 모듈을 제공하므로 모든 Python 프로그램은 이 타사 모듈을 사용하여 로깅을 구현할 수 있습니다. python 로깅 공식 문서
로깅 프레임워크는 주로 네 부분으로 구성됩니다.
로거: 프로그램에서 직접 호출할 수 있는 인터페이스
핸들러: 로그 레코드를 올바른 대상에 할당하는 방법을 결정합니다.
-
필터 : 로그 출력 여부에 대한 보다 세밀한 판단 제공
포맷: 최종 기록 인쇄의 형식 레이아웃 공식화
2. 로깅
로거
로거 구성은 프로그램이 직접 호출할 수 있고, 로그 정보를 로거에 직접 쓸 수 있는 로깅 인터페이스입니다. 로거는 직접 인스턴스화되지 않지만 logging.getLogger(name)来获取对象，事实上logger对象是单例模式，logging是多线程安全的，也就是无论程序中哪里需要打日志获取到的logger对象都是同一个。但是不幸的是logger并不支持多进程，这个在后面的章节再解释，并给出一些解决方案。
【注意】loggers对象是有父子关系的，当没有父logger对象时它的父对象是root，当拥有父对象时父子关系会被修正。举个例子logging.getLogger("abc.xyz")를 통해 두 개의 로거 개체가 생성됩니다. 하나는 abc 상위 개체이고 다른 하나는 xyz 하위 개체입니다. 동시에 abc에는 상위 개체가 없으므로 상위 개체는 루트입니다. 그러나 실제로 abc는 자리 표시자 개체(가상 로그 개체)이며 로그를 처리하는 핸들러가 없습니다. 그러나 루트는 자리 표시자 개체가 아닙니다. 로그 개체가 로그를 작성하면 해당 상위 개체가 동시에 로그를 수신하게 됩니다. 따라서 일부 사용자는 로거 개체를 만들 때 두 번 로그를 기록하기 때문입니다. 생성된 로그는 로그가 한 번 기록되고, 루트 개체도 한 번 기록됩니다.
각 로거에는 로그 수준이 있습니다. 로깅에는 다음 수준이 정의되어 있습니다
| Level | 숫자 값 |
|---|---|
| NOTSET | 0 |
| DEBUG | 10 |
| INFO | 20 |
| 경고 | 30 |
| ERROR | 40 |
| CRITICAL | 50 |
로거는 로그 정보를 수신하면 먼저 해당 수준을 충족하는지 판단하여 처리하기로 결정하면 처리를 위해 해당 정보를 핸들러에 전달합니다.
Handlers
Handlers는 로거가 보낸 정보를 정확하게 분배하여 올바른 위치로 보냅니다. 예를 들어 콘솔이나 파일, 둘 다 또는 다른 위치(프로세스 파이프 등)로 보냅니다. 각 로그의 동작을 결정하며 나중에 구성해야 하는 핵심 영역입니다.
각 핸들러에는 로그 수준도 있습니다. 로거에는 여러 개의 핸들러가 있을 수 있습니다. 즉, 로거는 다양한 로그 수준에 따라 다양한 핸들러에 로그를 전달할 수 있습니다. 물론 동일한 수준을 여러 핸들러에 전달할 수도 있으며 필요에 따라 유연하게 설정할 수 있습니다.
필터
필터는 로그를 인쇄해야 하는지 여부를 결정하는 데 있어 더욱 세밀한 판단을 제공합니다. 핸들러가 로그를 획득하면 레벨에 따라 균일하게 처리하는 것을 원칙으로 하지만, 핸들러에 필터가 있는 경우 로그에 대한 추가 처리 및 판단을 수행할 수 있다. 예를 들어 필터는 특정 소스의 로그를 가로채거나 수정할 수 있으며 심지어 로그 수준을 수정할 수도 있습니다(수준은 수정 후 판단됩니다).
로거와 핸들러 모두 필터를 설치할 수 있으며, 여러 필터를 직렬로 설치할 수도 있습니다.
Formatters
Formatters는 특정 레코드를 인쇄하기 위한 최종 형식 레이아웃을 지정합니다. Formatter는 전달된 정보를 특정 문자열로 연결합니다. 기본적으로 Format은 정보만 직접 인쇄합니다. 다음 표와 같이 Format에서 사용할 수 있는 몇 가지 기본 제공 LogRecord 속성이 있습니다.%(message)s
| Attribute | Format | Description |
|---|---|---|
| asctime | %(asctime)s | 로그 시간을 읽을 수 있는 형식으로 구성합니다. 기본적으로 '2016-02-08 12: 00:00,123'밀리초까지 정확함 |
| filename | %(filename)s | path |
| funcName | %(funcName)s | 어떤 함수에 의해 발행된 로그 |
| 레벨이름 | %(levelname)s | 로그의 최종 레벨(필터로 수정됨) |
| message | %(message)s | 로그 정보 |
| llineno | %(lineno) d | 현재 log |
| pathname | %(pathname) s | full path |
| process | %(프로세스) s | current의 줄 번호 프로세스 |
| thread | %(thread)s | 현재 스레드 |
핸들러는 하나의 포맷터만 가질 수 있으므로 여러 형식으로 출력하려면 여러 핸들러만 사용할 수 있습니다.
3. 로깅 구성
간단한 구성
우선 로거 장에서 기본 로그 개체 루트가 있다고 설명했습니다. 이 루트 로그 개체의 장점은 구성 및 로깅에 직접 로깅을 사용할 수 있다는 것입니다. . 예:
logging.basicConfig(level=logging.INFO,filename='logger.log')
logging.info("info message")여기서 간단한 구성은 언제든지 사용할 수 있는 루트 로그 개체를 나타냅니다. 각 로거는 싱글톤 개체이므로 구성 후 프로그램 어디에서나 호출할 수 있습니다. 실제로 루트 로그 개체를 구성하려면 basicConfig만 호출하면 됩니다. 실제로 이 방법은 매우 효과적이고 사용하기 쉽습니다. 이는 로거가 호출될 때 로그를 처리할 수 있는 처리기가 하나 이상 있도록 보장합니다.
간단한 구성은 다음과 같이 설정할 수 있습니다.
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')코드 구성
또 다른 자세한 설정 방법은 코드에서 구성하는 것이지만 이 설정 방법은 결국 가장 적게 사용되는 방법입니다. 설정을 확인하세요. 하지만 여기서는 많이 사용되지는 않지만 필요할 때 사용할 수 있다는 간략한 소개를 제공합니다. (추후 추가 예정)
구성 파일 구성
파이썬으로 기록한 구성 파일은 ConfigParser의 기능을 기반으로 합니다. 즉, 구성 파일의 형식도 이와 같이 작성됩니다. 좀 더 일반적인 구성 파일을 먼저 제공하고 자세히 설명하겠습니다
############################################## [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 ##############################################
다시 읽어보면 규칙도 찾을 수 있을 거라 믿습니다. 각 로거, 핸들러 또는 포맷터에는 키 이름이 있습니다. 로거를 예로 들면, 먼저 로거를 나타내기 위해 [로거] 구성에 키 이름을 추가해야 합니다. 그런 다음 [loggers_xxxx]를 사용합니다. 여기서 xxxx는 이 로거를 구체적으로 구성하기 위한 키 이름입니다. log02에서는 레벨과 핸들러 이름을 구성했습니다. 물론 여러 핸들러를 구성할 수도 있습니다. 이 핸들러 이름에 따라 [handlers]로 이동하여 특정 핸들러의 구성 등을 찾습니다.
그런 다음 코드에서 다음과 같은 구성 파일을 로드하세요
logging.config.fileConfig(log_conf_file)
在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 == 'MIDNIGHT' or self.when.startswith('W')) 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
我们观察 if os.path.exists(dfn) 这一行开始，这里的逻辑是如果 dfn 这个文件存在，则要先删除掉它，然后将 baseFilename 这个文件重命名为 dfn 文件。然后再重新打开 baseFilename这个文件开始写入东西。那么这里的逻辑就很清楚了
假设当前日志文件名为 current.log 切分后的文件名为 current.log.2016-06-01
判断 current.log.2016-06-01 是否存在，如果存在就删除
将当前的日志文件名 改名为current.log.2016-06-01
重新打开新文件（我观察到源代码中默认是”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 中逻辑的缺陷。我们只需要稍微修改一下逻辑即可：
判断切分后的文件 current.log.2016-06-01 是否存在，如果不存在则进行重命名。（如果存在说明有其他进程切过了，我不用切了，换一下句柄即可）
以”a”模式 打开 current.log
发现修改后就这么简单~
talking is cheap show me the code:不要以为代码那么长，其实修改部分就是 “##” 注释的地方而已，其他都是照抄源代码。这个类继承了 TimedRotatingFileHandler 重写了这个切分的过程。这个解决方案十分优雅，改换的地方非常少，也十分有效。但有网友提出，这里有一处地方依然不完美，就是rename的那一步，如果就是这么巧，同时两个或者多个进程进入了 if 语句，先后开始 rename 那么依然会发生删除掉日志的情况。确实这种情况确实会发生，由于切分文件一天才一次，正好切分的时候同时有两个Handler在操作，又正好同时走到这里，也是蛮巧的，但是为了完美，可以加上一个文件锁，if 之后加锁，得到锁之后再判断一次，再进行rename这种方式就完美了。代码就不贴了，涉及到锁代码，影响美观。
class SafeRotatingFileHandler(TimedRotatingFileHandler): def __init__(self, filename, when='h', 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 == 'MIDNIGHT' or self.when.startswith('W')) 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
解决方案2
我认为最简单有效的解决方案。重写FileHandler类（这个类是所有写入文件的Handler都需要继承的TimedRotatingFileHandler 就是继承的这个类；我们增加一些简单的判断和操作就可以。
我们的逻辑是这样的：
判断当前时间戳是否与指向的文件名是同一个时间
-
如果不是，则切换 指向的文件即可
结束，是不是很简单的逻辑。
talking is cheap show me the code
check_baseFilename 就是执行逻辑1判断；build_baseFilename 就是执行逻辑2换句柄。就这么简单完成了。
这种方案与之前不同的是，当前文件就是 current.log.2016-06-01 ，到了明天当前文件就是current.log.2016-06-02 没有重命名的情况，也没有删除的情况。十分简洁优雅。也能解决多进程的logging问题。
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+'.'+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 = 'a' if not self.delay: self.stream = self._open()
解决方案其他
当然还有其他的解决方案，例如由一个logging进程统一打日志，其他进程将所有的日志内容打入logging进程管道由它来打理。还有将日志打入网络socket当中也是同样的道理。
5. 参考资料
python logging 官方文档
林中小灯的切分方案，方案一就是从这儿来的
위 내용은 Python 로깅 모듈에 대한 심층적인 이해의 상세 내용입니다. 자세한 내용은 PHP 중국어 웹사이트의 기타 관련 기사를 참조하세요!