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 中的全部模块都会使用相同的配置。当你在读日志文件的时候，你就可以明白消息到底来自于哪个模块。