python基础学习十 logging模块详细使用

　　很多程序都有记录日志的需求，并且日志中包含的信息既有正常的程序访问日志，还可能有错误、警告等信息输出，python的logging模块提供了标准的日志接口，你可以通过它存储各种格式的日志，主要用于输出运行日志，可以设置输出日志的等级、日志保存路径、日志文件回滚等；

使用logging的优势：

a）你可以控制消息的级别，过滤掉那些并不重要的消息。

b）你可决定输出到什么地方，以及怎么输出。有许多的重要性别级可供选择，debug、info、warning、error 以及 critical。通过赋予 logger 或者 handler 不同的级别，你就可以只输出错误消息到特定的记录文件中，或者在调试时只记录调试信息。

 

1. logging日志框架

主要包括四部分：

  • Loggers: 可供程序直接调用的接口，app通过调用提供的api来记录日志
  • Handlers: 决定将日志记录分配至正确的目的地
  • Filters:对日志信息进行过滤， 提供更细粒度的日志是否输出的判断
  • Formatters: 制定最终记录打印的格式布局

1）loggers

loggers 就是程序可以直接调用的一个日志接口，可以直接向logger写入日志信息。logger并不是直接实例化使用的，而是通过logging.getLogger(name)来获取对象，事实上logger对象是单例模式，logging是多线程安全的，也就是无论程序中哪里需要打日志获取到的logger对象都是同一个。但是不幸的是logger并不支持多进程，这个在后面的章节再解释，并给出一些解决方案。

【注意】loggers对象是有父子关系的，当没有父logger对象时它的父对象是root，当拥有父对象时父子关系会被修正。举个例子，logging.getLogger("abc.xyz") 会创建两个logger对象，一个是abc父对象，一个是xyz子对象，同时abc没有父对象，所以它的父对象是root。但是实际上abc是一个占位对象（虚的日志对象），可以没有handler来处理日志。但是root不是占位对象，如果某一个日志对象打日志时，它的父对象会同时收到日志，所以有些使用者发现创建了一个logger对象时会打两遍日志，就是因为他创建的logger打了一遍日志，同时root对象也打了一遍日志。

2）Handlers

Handlers 将logger发过来的信息进行准确地分配，送往正确的地方。举个栗子，送往控制台或者文件或者both或者其他地方(进程管道之类的)。它决定了每个日志的行为，是之后需要配置的重点区域。

每个Handler同样有一个日志级别，一个logger可以拥有多个handler也就是说logger可以根据不同的日志级别将日志传递给不同的handler。当然也可以相同的级别传递给多个handlers这就根据需求来灵活的设置了。

3）Filters

Filters 提供了更细粒度的判断，来决定日志是否需要打印。原则上handler获得一个日志就必定会根据级别被统一处理，但是如果handler拥有一个Filter可以对日志进行额外的处理和判断。例如Filter能够对来自特定源的日志进行拦截or修改甚至修改其日志级别（修改后再进行级别判断）。

logger和handler都可以安装filter甚至可以安装多个filter串联起来。

4） Formatters

Formatters 指定了最终某条记录打印的格式布局。Formatter会将传递来的信息拼接成一条具体的字符串，默认情况下Format只会将信息%(message)s直接打印出来。Format中有一些自带的LogRecord属性可以使用，如下表格:

一个Handler只能拥有一个Formatter 因此如果要实现多种格式的输出只能用多个Handler来实现。

上图只是一部分，更详细的在docs.python.org里找logging模块。

 

2. 日志级别

在记录日志时, 日志消息都会关联一个级别(“级别”本质上是一个非负整数)。系统默认提供了6个级别，它们分别是：

 

可以给日志对象(Logger Instance)设置日志级别，低于该级别的日志消息将会被忽略，也可以给Hanlder设置日志级别，对于低于该级别的日志消息, Handler也会忽略。

 

3. 常用函数

1）logging.basicConfig([**kwargs]):

为日志模块配置基本信息。kwargs 支持如下几个关键字参数：
filename ：日志文件的保存路径。如果配置了些参数，将自动创建一个FileHandler作为Handler；
filemode ：日志文件的打开模式。 默认值为’a’，表示日志消息以追加的形式添加到日志文件中。如果设为’w’, 那么每次程序启动的时候都会创建一个新的日志文件；
format ：设置日志输出格式；
datefmt ：定义日期格式；
level ：设置日志的级别.对低于该级别的日志消息将被忽略；
stream ：设置特定的流用于初始化StreamHandler；

 

2）logging.getLogger([name])

创建Logger对象。日志记录的工作主要由Logger对象来完成。在调用getLogger时要提供Logger的名称（注：多次使用相同名称来调用getLogger，返回的是同一个对象的引用。），Logger实例之间有层次关系，这些关系通过Logger名称来体现，如：

p = logging.getLogger(“root”)

c1 = logging.getLogger(“root.c1”)

c2 = logging.getLogger(“root.c2”)

例子中，p是父logger, c1,c2分别是p的子logger。c1, c2将继承p的设置。如果省略了name参数, getLogger将返回日志对象层次关系中的根Logger。

 

4.基本使用

1） 简单的将日志打印到屏幕

1 import logging  
2   
3 logging.debug('this is debug message')  
4 logging.info('this is info message')  
5 logging.warning('this is warning message')  
6   
7 #打印结果：WARNING:root:this is warning message

默认情况下，logging将日志打印到屏幕，日志级别为WARNING；
日志级别大小关系为：CRITICAL > ERROR > WARNING > INFO > DEBUG > NOTSET，当然也可以自己定义日志级别。

2）通过logging.basicConfig函数对日志的输出格式及方式做相关配置

 1 import logging  
 2   
 3 logging.basicConfig(level=logging.DEBUG, format='%(asctime)s - %(name)s - %(message)s')  
 4   
 5 logging.debug('this is debug message')  
 6 logging.info('this is info message')  
 7 logging.warning('this is warning message')  
 8   
 9 ''''' 
10 结果： 
11 2017-08-23 14:22:25,713 - root - this is debug message 
12 2017-08-23 14:22:25,713 - root - this is info message 
13 2017-08-23 14:22:25,714 - root - this is warning message 
14 '''

logging.basicConfig函数各参数:
filename: 指定日志文件名
filemode: 和file函数意义相同，指定日志文件的打开模式，'w'或'a'
format: 指定输出的格式和内容，format可以输出很多有用信息，如上例所示:
 %(levelno)s: 打印日志级别的数值
 %(levelname)s: 打印日志级别名称
 %(pathname)s: 打印当前执行程序的路径，其实就是sys.argv[0]
 %(filename)s: 打印当前执行程序名
 %(funcName)s: 打印日志的当前函数
 %(lineno)d: 打印日志的当前行号
 %(asctime)s: 打印日志的时间
 %(thread)d: 打印线程ID
 %(threadName)s: 打印线程名称
 %(process)d: 打印进程ID
 %(message)s: 打印日志信息
datefmt: 指定时间格式，同time.strftime()
level: 设置日志级别，默认为logging.WARNING
stream: 指定将日志的输出流，可以指定输出到sys.stderr,sys.stdout或者文件，默认输出到sys.stderr，当stream和filename同时指定时，stream被忽略

3）将日志同时输出到文件和屏幕

import logging
logger = logging.getLogger(__name__)
logger.setLevel(level = logging.INFO)
handler = logging.FileHandler("log.txt")
handler.setLevel(logging.INFO)
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
handler.setFormatter(formatter)
 
console = logging.StreamHandler()
console.setLevel(logging.INFO)
 
logger.addHandler(handler)
logger.addHandler(console)
 
logger.info("Start print log")
logger.debug("Do something")
logger.warning("Something maybe fail.")
logger.info("Finish")

可以在log.txt文件和控制台中看到：

可以发现，logging有一个日志处理的主对象，其他处理方式都是通过addHandler添加进去，logging中包含的handler主要有如下几种：

4）传给syslogserver，邮箱

1 from logging import handlers  
2   
3 #日志传送到syslog server  
4 syslog_handler = handlers.SysLogHandler(address=('192.168.168.1', 514))  
5   
6 #日志传送给邮箱  
7 mail_handler = handlers.SMTPHandler('192.168.168.1', 'winter@126.com', 'elly@163.com', 'subject')
8 #邮件给多人
9 mail_handler = handlers.SMTPHandler('192.168.168.1', 'winter@126.com', （'elly@163.com', 'dxd@126.com'), 'subject')

5）日志回滚

如果你用 FileHandler 写日志，文件的大小会随着时间推移而不断增大。最终有一天它会占满你所有的磁盘空间。为了避免这种情况出现，你可以在你的生成环境中使用 RotatingFileHandler 替代 FileHandler。

 1 import logging  
 2 from logging.handlers import RotatingFileHandler  
 3 logger = logging.getLogger(__name__)  
 4 logger.setLevel(level = logging.INFO)  
 5 #定义一个RotatingFileHandler，最多备份3个日志文件，每个日志文件最大1K  
 6 rHandler = RotatingFileHandler("log.txt",maxBytes = 1*1024,backupCount = 3)  
 7 rHandler.setLevel(logging.INFO)  
 8 formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')  
 9 rHandler.setFormatter(formatter)  
10    
11 console = logging.StreamHandler()  
12 console.setLevel(logging.INFO)  
13 console.setFormatter(formatter)  
14    
15 logger.addHandler(rHandler)  
16 logger.addHandler(console)  
17    
18 logger.info("Start print log")  
19 logger.debug("Do something")  
20 logger.warning("Something maybe fail.")  
21 logger.info("Finish")

5. 多模块使用logging配置

1）通过继承关系实现

 1 import logging
 2 
 3 logger = logging.getLogger('mainModule')
 4 logger.setLevel(level=logging.INFO)
 5 
 6 formatter = logging.Formatter(
 7     '%(asctime)s - %(name)s - %(levelname)s - %(message)s')
 8 
 9 handler = logging.FileHandler('log.txt')
10 handler.setLevel(logging.INFO)
11 handler.setFormatter(formatter)
12 
13 console = logging.StreamHandler()
14 console.setLevel(logging.INFO)
15 console.setFormatter(formatter)
16 
17 logger.addHandler(handler)
18 logger.addHandler(console)
19 
20 # 在其他模块导入该日志接口module_logger即可
21 module_logger = logging.getLogger('mainModule.sub')
22 module_logger.info('this is another module using logging')

说明：

首先定义了logger'mainModule'，并对它进行了配置，就可以在解释器进程里面的其他地方通过getLogger('mainModule')得到的对象都是一样的，不需要重新配置，可以直接使用。

定义的该logger的子logger，都可以共享父logger的定义和配置，所谓的父子logger是通过命名来识别，任意以'mainModule'开头的logger都是它的子logger，例如'mainModule.sub'。

实际开发一个application，首先可以通过logging配置文件编写好这个application所对应的配置，可以生成一个根logger，如'PythonAPP'，然后在主函数中通过fileConfig加载logging配置，接着在application的其他地方、不同的模块中，可以使用根logger的子logger，如'PythonAPP.Core'，'PythonAPP.Web'来进行log，而不需要反复的定义和配置各个模块的logger。

2）通过logging.config模块配置日志

 1 #logger.conf  
 2 ###############################################  
 3 [loggers]  
 4 keys=root,example01,example02  
 5 [logger_root]  
 6 level=DEBUG  
 7 handlers=hand01,hand02  
 8 [logger_example01]  
 9 handlers=hand01,hand02  
10 qualname=example01  
11 propagate=0  
12 [logger_example02]  
13 handlers=hand01,hand03  
14 qualname=example02  
15 propagate=0  
16 ###############################################  
17 [handlers]  
18 keys=hand01,hand02,hand03  
19 [handler_hand01]  
20 class=StreamHandler  
21 level=INFO  
22 formatter=form02  
23 args=(sys.stderr,)  
24 [handler_hand02]  
25 class=FileHandler  
26 level=DEBUG  
27 formatter=form01  
28 args=('myapp.log', 'a')  
29 [handler_hand03]  
30 class=handlers.RotatingFileHandler  
31 level=INFO  
32 formatter=form02  
33 args=('myapp.log', 'a', 10*1024*1024, 5)  
34 ###############################################  
35 [formatters]  
36 keys=form01,form02  
37 [formatter_form01]  
38 format=%(asctime)s %(filename)s[line:%(lineno)d] %(levelname)s %(message)s  
39 datefmt=%a, %d %b %Y %H:%M:%S  
40 [formatter_form02]  
41 format=%(name)-12s: %(levelname)-8s %(message)s  
42 datefmt=%a, %d %b %Y %H:%M:%S

example01

1 import logging  
2 import logging.config  
3    
4 logging.config.fileConfig("logger.conf")  
5 logger = logging.getLogger("example01")  
6    
7 logger.debug('This is debug message')  
8 logger.info('This is info message')  
9 logger.warning('This is warning message')

 

example02

1 import logging  
2 import logging.config  
3    
4 logging.config.fileConfig("logger.conf")  
5 logger = logging.getLogger("example02")  
6    
7 logger.debug('This is debug message')  
8 logger.info('This is info message')  
9 logger.warning('This is warning message')

python2.7以后，可以从字典中加载logging配置，也就意味着可以通过JSON或者YAML文件加载日志的配置

3）通过JSON加载日志配置

 1 {  
 2     "version":1,  
 3     "disable_existing_loggers":false,  
 4     "formatters":{  
 5         "simple":{  
 6             "format":"%(asctime)s - %(name)s - %(levelname)s - %(message)s"  
 7         }  
 8     },  
 9     "handlers":{  
10         "console":{  
11             "class":"logging.StreamHandler",  
12             "level":"DEBUG",  
13             "formatter":"simple",  
14             "stream":"ext://sys.stdout"  
15         },  
16         "info_file_handler":{  
17             "class":"logging.handlers.RotatingFileHandler",  
18             "level":"INFO",  
19             "formatter":"simple",  
20             "filename":"info.log",  
21             "maxBytes":"10485760",  
22             "backupCount":20,  
23             "encoding":"utf8"  
24         },  
25         "error_file_handler":{  
26             "class":"logging.handlers.RotatingFileHandler",  
27             "level":"ERROR",  
28             "formatter":"simple",  
29             "filename":"errors.log",  
30             "maxBytes":10485760,  
31             "backupCount":20,  
32             "encoding":"utf8"  
33         }  
34     },  
35     "loggers":{  
36         "my_module":{  
37             "level":"ERROR",  
38             "handlers":["info_file_handler"],  
39             "propagate":"no"  
40         }  
41     },  
42     "root":{  
43         "level":"INFO",  
44         "handlers":["console","info_file_handler","error_file_handler"]  
45     }  
46 }

通过JSON加载配置文件，然后通过logging.dictConfig配置logging

 1 import json  
 2 import logging.config  
 3 import os  
 4    
 5 def setup_logging(default_path = "logging.json",default_level = logging.INFO,env_key = "LOG_CFG"):  
 6     path = default_path  
 7     value = os.getenv(env_key,None)  
 8     if value:  
 9         path = value  
10     if os.path.exists(path):  
11         with open(path,"r") as f:  
12             config = json.load(f)  
13             logging.config.dictConfig(config)  
14     else:  
15         logging.basicConfig(level = default_level)  
16    
17 def func():  
18     logging.info("start func")  
19    
20     logging.info("exec func")  
21    
22     logging.info("end func")  
23    
24 if __name__ == "__main__":  
25     setup_logging(default_path = "logging.json")  
26     func()

使用JSON的一个优点就是json是一个标准库，不需要额外安装。但是，有人更喜欢YAML。无论读起来还是写起来都比较容易

4）通过YAML文件配置

通过YAML文件进行配置，比JSON看起来更加简介明了，

 1 version: 1  
 2 disable_existing_loggers: False  
 3 formatters:  
 4         simple:  
 5             format: "%(asctime)s - %(name)s - %(levelname)s - %(message)s"  
 6 handlers:  
 7     console:  
 8             class: logging.StreamHandler  
 9             level: DEBUG  
10             formatter: simple  
11             stream: ext://sys.stdout  
12     info_file_handler:  
13             class: logging.handlers.RotatingFileHandler  
14             level: INFO  
15             formatter: simple  
16             filename: info.log  
17             maxBytes: 10485760  
18             backupCount: 20  
19             encoding: utf8  
20     error_file_handler:  
21             class: logging.handlers.RotatingFileHandler  
22             level: ERROR  
23             formatter: simple  
24             filename: errors.log  
25             maxBytes: 10485760  
26             backupCount: 20  
27             encoding: utf8  
28 loggers:  
29     my_module:  
30             level: ERROR  
31             handlers: [info_file_handler]  
32             propagate: no  
33 root:  
34     level: INFO  
35     handlers: [console,info_file_handler,error_file_handler]

通过YAML加载配置文件，然后通过logging.dictConfig配置logging

 1 import yaml  
 2 import logging.config  
 3 import os  
 4    
 5 def setup_logging(default_path = "logging.yaml",default_level = logging.INFO,env_key = "LOG_CFG"):  
 6     path = default_path  
 7     value = os.getenv(env_key,None)  
 8     if value:  
 9         path = value  
10     if os.path.exists(path):  
11         with open(path,"r") as f:  
12             config = yaml.load(f)  
13             logging.config.dictConfig(config)  
14     else:  
15         logging.basicConfig(level = default_level)  
16    
17 def func():  
18     logging.info("start func")  
19    
20     logging.info("exec func")  
21    
22     logging.info("end func")  
23    
24 if __name__ == "__main__":  
25     setup_logging(default_path = "logging.yaml")  
26     func()

 接下来，你就可以在运行程序的时候调用setup_logging来启动日志记录了。它默认会读取logging.json或logging.yaml文件。你也可以设置环境变量LOG_CFG从指定的路径加载日志配置，例如：

LOG_CFG = my_logging.json python my_server.py

如果你喜欢YAML：

LOG_CFG = my_logging.yaml python my_server.py

 

注意：配置文件中“disable_existing_loggers” 参数设置为 False；如果不设置为False，创建了 logger，然后你又在加载日志配置文件之前就导入了模块。logging.fileConfig 与 logging.dictConfig 默认情况下会使得已经存在的 logger 失效。那么，这些配置信息就不会应用到你的 Logger 上。“disable_existing_loggers” = False解决了这个问题

 

 6. 捕捉异常并使用traceback记录它

出问题时记录下来是个好习惯，python中的traceback模块用于记录异常信息，我们可以在logger中记录下traceback

比如下面的例子：

1 try:  
2     open('/path/to/does/not/exist', 'rb')  
3 except (SystemExit, KeyboardInterrupt):  
4     raise  
5 except Exception, e:  
6     logger.error('Failed to open file', exc_info=True)

结果为：

1 ERROR:__main__:Failed to open file  
2 Traceback (most recent call last):  
3   File "example.py", line 6, in <module>  
4     open('/path/to/does/not/exist', 'rb')  
5 IOError: [Errno 2] No such file or directory: '/path/to/does/not/exist'

 

你也可以调用 logger.exception(msg, _args)，它等价于 logger.error(msg, exc_info=True, _args)。

将

 logger.error('Failed to open file', exc_info=True)

替换为：

logger.exception('Failed to open file')

7. logger间的继承关系

1） logger间存在继承关系

logger 通过名字来决定继承关系，如果一个logger的名字是"mydest"，另一个logger的名字是"mydest.dest1" （getLogger("mydest.dest1")）,那么就称后者是前者的子logger，会继承前者的配置。上面的代码没有指定logger，直接调用logging.debug等方法时，会使用所有logger的祖先类RootLogger。

从上面的代码运行结果可以猜测出，该RootLogger设置的日志级别是logging.WARN，输出目的地是标准流。从源码可以更清楚的看出来：

root = RootLogger(WARNING)  #设置root用户的日志级别为WARNING

至于rootLogger的输出目的地的配置，我们跟踪logging.debug的源代码来看一下：

1 def debug(msg, *args, **kwargs):
2     """ 
3     Log a message with severity 'DEBUG' on the root logger. 
4     """
5 if len(root.handlers) == 0:
6     basicConfig()
7 root.debug(msg, *args, **kwargs)

大约可以看到，如果rootLogger没有配置handler，就会不带参数运行basicConfig函数，我们看一下basicConfig的源代码：

 1 def basicConfig(**kwargs):
 2     #有帮助文档，这里不列出
 3     _acquireLock()
 4     try:
 5         if len(root.handlers) == 0:
 6             filename = kwargs.get("filename")
 7             if filename:
 8                 mode = kwargs.get("filemode", 'a')
 9                 hdlr = FileHandler(filename, mode)
10             else:
11                 stream = kwargs.get("stream")
12                 hdlr = StreamHandler(stream)
13             fs = kwargs.get("format", BASIC_FORMAT)
14             dfs = kwargs.get("datefmt", None)
15             fmt = Formatter(fs, dfs)
16             hdlr.setFormatter(fmt)
17             root.addHandler(hdlr)
18             level = kwargs.get("level")
19             if level is not None:
20                 root.setLevel(level)
21     finally:
22         _releaseLock()

因为参数为空，所以我们就看出了，该rootLoger使用了不带参数的StreamHandler，也可以看到诸如format之类的默认配置。之后我们跟踪StreamHandler(因为我们想看到日志输出目的地的配置，而handler就是控制日志流向的，所以我们要跟踪它)的源代码：

 1 class StreamHandler(Handler):
 2     """
 3     A handler class which writes logging records, appropriately formatted,
 4     to a stream. Note that this class does not close the stream, as
 5     sys.stdout or sys.stderr may be used.
 6     """
 7 
 8     def __init__(self, stream=None):
 9         """
10         Initialize the handler.
11 
12         If stream is not specified, sys.stderr is used.
13         """
14         Handler.__init__(self)
15         if stream is None:
16             stream = sys.stderr
17         self.stream = stream

不带参数的StreamHandler将会把日志流定位到sys.stderr流，标准错误流同样会输出到控制台。

2） basicConfig函数用来配置RootLogger

basicConfig函数仅用来配置RootLogger，rootLogger是所有Logger的祖先Logger，所以其他一切Logger会继承该Logger的配置。

3） 通过示例详细讨论Logger配置的继承关系

首先准备下继承条件：log2继承自log1，logger的名称可以随意，要注意‘.’表示的继承关系。

 1 # coding:utf-8   
 2 import logging  
 3   
 4 log1 = logging.getLogger("mydear")  
 5   
 6 log1.setLevel(logging.WARNING)  
 7   
 8 log1.addHandler(StreamHandler())  
 9   
10 log2 = logging.getLogger("mydear.app")  
11   
12 log2.error("display")  
13   
14 log2.info("not display")

a）level的继承

原则：子logger写日志时，优先使用本身设置了的level；如果没有设置，则逐层向上级父logger查询，直到查询到为止。最极端的情况是，使用rootLogger的默认日志级别logging.WARNING。

从源代码中看更为清晰， 感谢python的所见即所得：

 1 def getEffectiveLevel(self):
 2     """
 3     Get the effective level for this logger.
 4 
 5     Loop through this logger and its parents in the logger hierarchy,
 6     looking for a non-zero logging level. Return the first one found.
 7     """
 8     logger = self
 9     while logger:
10         if logger.level:
11             return logger.level
12         logger = logger.parent
13     return NOTSET

b）handler的继承

原则：先将日志对象传递给子logger的所有handler处理，处理完毕后，如果该子logger的propagate属性没有设置为0，则将日志对象向上传递给第一个父Logger，该父logger的所有handler处理完毕后，如果它的propagate也没有设置为0，则继续向上层传递，以此类推。最终的状态，要么遇到一个Logger，它的propagate属性设置为了0；要么一直传递直到rootLogger处理完毕。

在上面实例代码的基础上，我们再添加一句代码，即：

 1 import logging
 2 
 3 log1 = logging.getLogger("mydear")
 4 
 5 log1.setLevel(logging.WARNING)
 6 
 7 log1.addHandler(logging.StreamHandler())
 8 
 9 log2 = logging.getLogger("mydear.app")
10 
11 log2.error("display")
12 
13 log2.info("not display")
14 
15 print log2.handlers  # 打印log2绑定的handler

输出结果为：

display
[]

说好的继承，但是子logger竟然没有绑定父类的handler，what's wrong?

看到下面调用handler的源代码，就真相大白了。可以理解成，这不是真正的(类)继承，只是"行为上的继承":

 1 def callHandlers(self, record):  
 2     """ 
 3     Pass a record to all relevant handlers. 
 4  
 5     Loop through all handlers for this logger and its parents in the 
 6     logger hierarchy. If no handler was found, output a one-off error 
 7     message to sys.stderr. Stop searching up the hierarchy whenever a 
 8     logger with the "propagate" attribute set to zero is found - that 
 9     will be the last logger whose handlers are called. 
10     """  
11     c = self  
12     found = 0  
13     while c:  
14         for hdlr in c.handlers:  
15             found = found + 1  
16             if record.levelno >= hdlr.level:  
17                 hdlr.handle(record)  
18         if not c.propagate:  
19             c = None  # break out  
20         else:  
21             c = c.parent  
22     if (found == 0) and raiseExceptions and not self.manager.emittedNoHandlerWarning:  
23         sys.stderr.write("No handlers could be found for logger"  
24                          " \"%s\"\n" % self.name)  
25         self.manager.emittedNoHandlerWarning = 1

8. logging遇到多进程

在handler中有一个class配置，可能有些读者并不是很懂。其实这个是logging里面原先就写好的一些handler类，你可以在这里直接调用。class指向的类相当于具体处理的Handler的执行者。在logging的文档中可以知道这里所有的Handler类都是线程安全的(但是GIL的存在，多线程基本可以无视)，大家可以放心使用。所以一般情况下python要实现并行操作或者并行计算的时候都是使用多进程。但是logging并不是进程安全的，如果是用多进程来输出日志，则只有一个进程会切换，其他进程会在原来的文件中继续打，还有可能某些进程切换的时候早就有别的进程在新的日志文件里打入东西了，那么他会无情删掉之，再建立新的日志文件。会很乱很乱，完全没法开心的玩耍。

现在我们就来解决这个问题，以日志回滚使用的TimedRotatingFileHandler 这个类为例：

1）线程不安全的原因

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

 1 def doRollover(self):
 2     """
 3     do a rollover; in this case, a date/time stamp is appended to the filename
 4     when the rollover happens.  However, you want the file to be named for the
 5     start of the interval, not the current time.  If there is a backup count,
 6     then we have to get a list of matching filenames, sort them and remove
 7     the one with the oldest suffix.
 8     """
 9     if self.stream:
10         self.stream.close()
11         self.stream = None
12     # get the time that this sequence started at and make it a TimeTuple
13     currentTime = int(time.time())
14     dstNow = time.localtime(currentTime)[-1]
15     t = self.rolloverAt - self.interval
16     if self.utc:
17         timeTuple = time.gmtime(t)
18     else:
19         timeTuple = time.localtime(t)
20         dstThen = timeTuple[-1]
21         if dstNow != dstThen:
22             if dstNow:
23                 addend = 3600
24             else:
25                 addend = -3600
26             timeTuple = time.localtime(t + addend)
27     dfn = self.baseFilename + "." + time.strftime(self.suffix, timeTuple)
28     if os.path.exists(dfn):
29         os.remove(dfn)
30     # Issue 18940: A file may not have been created if delay is True.
31     if os.path.exists(self.baseFilename):
32         os.rename(self.baseFilename, dfn)
33     if self.backupCount > 0:
34         for s in self.getFilesToDelete():
35             os.remove(s)
36     if not self.delay:
37         self.stream = self._open()
38     newRolloverAt = self.computeRollover(currentTime)
39     while newRolloverAt <= currentTime:
40         newRolloverAt = newRolloverAt + self.interval
41     # If DST changes and midnight or weekly rollover, adjust for this.
42     if (self.when == 'MIDNIGHT' or self.when.startswith('W')) and not self.utc:
43         dstAtRollover = time.localtime(newRolloverAt)[-1]
44         if dstNow != dstAtRollover:
45             if not dstNow:  # DST kicks in before next rollover, so we need to deduct an hour
46                 addend = -3600
47             else:  # DST bows out before next rollover, so we need to add an hour
48                 addend = 3600
49             newRolloverAt += addend
50     self.rolloverAt = newRolloverAt

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

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

b）判断 current.log.2016-06-01 是否存在，如果存在就删除

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

d）重新打开新文件（我观察到源代码中默认是”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。
好了这里看上去很复杂，实际上就是因为对于文件操作时，没有对多进程进行一些约束，而导致的问题。
那么如何优雅地解决这个问题呢。我提出了两种方案，当然我会在下面提出更多可行的方案供大家尝试。

2）解决方案1

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

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

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

 1 class SafeRotatingFileHandler(TimedRotatingFileHandler):  
 2   
 3 def __init__( self, filename, when='h', interval=1, backupCount=0, encoding=None, delay=False, utc=False):  
 4     TimedRotatingFileHandler.__init__( self, filename, when, interval, backupCount, encoding, delay, utc)  
 5   
 6 """ 
 7 Override doRollover 
 8 lines commanded by "##" is changed by cc 
 9 """  
10   
11 def doRollover(self):  
12     """ 
13     do a rollover; in this case, a date/time stamp is appended to the filename 
14     when the rollover happens.  However, you want the file to be named for the 
15     start of the interval, not the current time.  If there is a backup count, 
16     then we have to get a list of matching filenames, sort them and remove 
17     the one with the oldest suffix. 
18     Override,   1. if dfn not exist then do rename 
19                 2. _open with "a" model 
20     """  
21   
22     if self.stream:  
23         self.stream.close()  
24         self.stream = None  
25     # get the time that this sequence started at and make it a TimeTuple  
26     currentTime = int(time.time())  
27     dstNow = time.localtime(currentTime)[-1]  
28     t = self.rolloverAt - self.interval  
29     if self.utc:  
30         timeTuple = time.gmtime(t)  
31     else:  
32         timeTuple = time.localtime(t)  
33         dstThen = timeTuple[-1]  
34         if dstNow != dstThen:  
35             if dstNow:  
36                 addend = 3600  
37             else:  
38                 addend = -3600  
39             timeTuple = time.localtime(t + addend)  
40     dfn = self.baseFilename + "." + time.strftime(self.suffix, timeTuple)  
41     # if os.path.exists(dfn):  
42     # os.remove(dfn)  
43     # Issue 18940: A file may not have been created if delay is True.  
44     # if os.path.exists(self.baseFilename):  
45     if not os.path.exists(dfn) and os.path.exists(self.baseFilename):  
46         os.rename(self.baseFilename, dfn)  
47     if self.backupCount > 0:  
48         for s in self.getFilesToDelete():  
49             os.remove(s)  
50     if not self.delay:  
51         self.mode = "a"  
52         self.stream = self._open()  
53     newRolloverAt = self.computeRollover(currentTime)  
54     while newRolloverAt <= currentTime:  
55         newRolloverAt = newRolloverAt + self.interval  
56     # If DST changes and midnight or weekly rollover, adjust for this.  
57     if (self.when == 'MIDNIGHT' or self.when.startswith('W')) and not self.utc:  
58         dstAtRollover = time.localtime(newRolloverAt)[-1]  
59         if dstNow != dstAtRollover:  
60             if not dstNow:  # DST kicks in before next rollover, so we need to deduct an hour  
61                 addend = -3600  
62             else:  # DST bows out before next rollover, so we need to add an hour  
63                 addend = 3600  
64             newRolloverAt += addend  
65     self.rolloverAt = newRolloverAt

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

3）解决方案2

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

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

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

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()

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

4）解决方案3---进程安全的ConcurrentLogHandler

如果多进程多线程使用，推荐 ConcurrentLogHandler，需要安装

安装： 

pip install ConcurrentLogHandler

a）使用案例一

def init_log():
    logfile = "/data1/restful_log/restful_api_thread.log"
    filesize = 800*1024*1024
    log = getLogger()
    rotate_handler = ConcurrentRotatingFileHandler(logfile, "a", filesize, encoding="utf-8")

    datefmt_str = '%Y-%m-%d %H:%M:%S'
    format_str = '%(asctime)s\t%(levelname)s\t%(message)s '
    formatter = Formatter(format_str, datefmt_str)
    rotate_handler.setFormatter(formatter)

    log.addHandler(rotate_handler)
    log.setLevel(WARN)

    return log

ConcurrentRotatingFileHandler参数说明： 
filename: 日志文件地址，相对地址或绝对地址均可

mode: 默认为"a"

maxBytes：文件长度，超过最大长度自动分片，最初日志都会写入filename里面，到达设置的最大长度之后进行分片，分片后文件名为filename.1 filename.2，以此类推

backupCount：最大日志文件保留数量，默认为0即不会删除日志文件

encoding：日志文件编码格式，默认为gbk

b）使用案例二

建一个目录，下面的文件都放到这个目录中：

logging-config.yaml

version: 1    
    
formatters:    
    simple:    
        format: '%(asctime)s - %(name)s - %(levelname)s - %(message)s'    
    
handlers:    
    console:    
        class: logging.StreamHandler    
        level: DEBUG    
        formatter: simple    
        stream: ext://sys.stdout    
    
loggers:    
    simpleExample:    
        level: DEBUG    
        handlers: [console]    
        propagate: no    
    
root:    
    level: DEBUG    
    handlers: [console]

 

 testlogging.py

#!/usr/bin/python2.7    
#-*- coding: UTF-8 -*-    
#    
# Using ConcurrentLogHandler:    
#   wget https://pypi.python.org/packages/fd/e5/0dc4f256bcc6484d454006b02f33263b20f762a433741b29d53875e0d763/ConcurrentLogHandler-0.9.1.tar.gz#md5=9609ecc4c269ac43f0837d89f12554c3    
#   cd ConcurrentLogHandler-0.9.1    
#   python2.7 setup.py install    
###########################################################    
import logging, logging.config    
import cloghandler    
    
import yaml    
    
###########################################################    
# create logger    
# 使用代码创建logger    
logger = logging.getLogger('simple_example')    
logger.setLevel(logging.DEBUG)    
    
# create console handler and set level to debug    
ch = logging.StreamHandler()    
ch.setLevel(logging.DEBUG)    
    
# create formatter    
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')    
    
# add formatter to ch    
ch.setFormatter(formatter)    
    
# add ch to logger    
logger.addHandler(ch)    
    
# 'application' code    
logger.debug('debug message')    
logger.info('info message')    
logger.warn('warn message')    
logger.error('error message')    
logger.critical('critical message')    
    
    
###########################################################    
# basicConfig    
logging.basicConfig(format='%(asctime)s %(message)s', datefmt='%m/%d/%Y %I:%M:%S %p')    
logging.warning('is when this event was logged.')    
    
    
###########################################################    
# using yaml config file    
f = open("logging-config.yaml")    
dictcfg = yaml.load(f)    
f.close()    
    
logging.config.dictConfig(dictcfg)    
    
#logging.config.fileConfig("logging.config")    
log = logging.getLogger("root")    
log.info("==YAML== Here is a very exciting log message")    
    
###########################################################    
# using ini config file    
logging.config.fileConfig("logging-config.ini")    
log = logging.getLogger("simpleExample")    
log.info("==INI== Here is a very exciting log message")    
    
    
###########################################################    
# using inline code config    
logging.config.dictConfig({    
    'version': 1,    
    'disable_existing_loggers': True,    
    'formatters': {    
        'verbose': {    
            'format': "[%(asctime)s] %(levelname)s [%(name)s:%(lineno)s] %(message)s",    
            'datefmt': "%Y-%m-%d %H:%M:%S",    
        },    
        'simple': {    
            'format': '%(levelname)s %(message)s',    
        },    
    },    
    'handlers': {    
        'null': {    
            'level': 'DEBUG',    
            'class': 'logging.NullHandler',    
        },    
        'console': {    
            'level': 'DEBUG',    
            'class': 'logging.StreamHandler',    
            'formatter': 'verbose',    
        },    
        'file': {    
            'level': 'DEBUG',    
            'class': 'cloghandler.ConcurrentRotatingFileHandler',    
            'maxBytes': 1024 * 1024 * 10,   # 当达到10MB时分割日志    
            'backupCount': 10,              # 最多保留10份文件    
            'delay': True,                  # If delay is true, file opening is deferred until the first call to emit    
            'filename': 'sample-site.log',    
            'formatter': 'verbose',    
        },    
        'file2': {    
            'level': 'DEBUG',    
            'class': 'cloghandler.ConcurrentRotatingFileHandler',    
            'maxBytes': 1024 * 1024 * 10,   # 当达到10MB时分割日志    
            'backupCount': 10,              # 最多保留10份文件    
            'delay': True,                  # If delay is true, file opening is deferred until the first call to emit    
            'filename': 'sample-site2.log',    
            'formatter': 'verbose',    
        },    
    },    
    'loggers': {    
        '': {    
            'handlers': ['file'],    
            'level': 'INFO',    
        },    
        'root': {    
            'handlers': ['console'],    
            'level': 'INFO',    
            'propagate': 0,    
        },    
        'root2': {    
            'handlers': ['console'],    
            'level': 'INFO',    
            'propagate': 1,    
        },    
    },    
})    
    
logger = logging.getLogger("root")    
logger.info("==== Here is a very exciting log message")    
    
logger = logging.getLogger("root2")    
logger.info("==== Here is a very exciting log message2")

 

9. 小知识点

1）使用__name__作为logger的名称

虽然不是非得将 logger 的名称设置为 __name__ ，但是这样做会给我们带来诸多益处。在 python 中，变量 __name__ 的名称就是当前模块的名称。比如，在模块 “foo.bar.my_module” 中调用 logger.getLogger(__name__) 等价于调用logger.getLogger(“foo.bar.my_module”) 。当你需要配置 logger 时，你可以配置到 “foo” 中，这样包 foo 中的所有模块都会使用相同的配置。当你在读日志文件的时候，你就能够明白消息到底来自于哪一个模块。

 

posted on 2018-03-14 14:39  louis_w  阅读(7405)  评论(1)  编辑  收藏  举报

导航