以打印日志为荣之logging模块详细使用

啄木鸟社区里的Pythonic八荣八耻有一条:python

以打印日志为荣 , 以单步跟踪为耻;json

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

为何不用print打印输出?安全

这种方式对于简单脚本型程序有用,可是若是是复杂的系统,最好不要用。首先,这些print是没用的输出,大量使用颇有可能会被遗忘在代码里。再者,print 输出的全部信息都到了标准输出中,这将严重影响到你从标准输出中查看其它输出数据。restful

使用logging的优点:多线程

a)你能够控制消息的级别,过滤掉那些并不重要的消息。app

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

下面让咱们正式进入logging的世界:python2.7

1. logging日志框架

主要包括四部分:ide

  • 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. 经常使用函数

若是想要快速码代码,能够直接看第4节,基本使用

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

为日志模块配置基本信息。设置后能够直接使用logging来打印日志

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

 

logging.basicConfig(level=log_level, format='%(asctime)s %(filename)s[line:%(lineno)d] %(levelname)s %(message)s', datefmt='%a, %d %b %Y %H:%M:%S', filename='parser_result.log', filemode='w')

logging.debug('This is debug message')
logging.info('This is info message')
logging.warning('This is warning message')

 

注意打印日志时logging后跟的是小写的等级,设置等级时跟的时大写的等级

 

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。

3)logging.getLevelName(lvl)

获取日志级别对应的名称。例如:

1 import logging  
2   
3 #下面的结果都为DEBUG  
4 print logging.getLevelName(10)  
5 print logging.getLevelName(logging.DEBUG)  
6 #下面的结果都为ERROR  
7 print logging.getLevelName(40)  
8 print logging.getLevelName(logging.ERROR)  
View Code

4)logging.shutdown()

当再也不使用日志系统的时候,调用该方法,它会将日志flush到对应的目标域上。通常在系统退出的时候调用。

Logger对象经过调用logging.getLogger(name)来建立,它有以下经常使用的方法和属性:

2 - a)Logger.setLevel(lvl):

设置日志的级别。对于低于该级别的日志消息将被忽略。下面一个例子演示setLevel方法:

 1 logger = logging.getLogger('root.test')  
 2 logger.setLevel(logging.INFO)  
 3 console_handler = logging.StreamHandler()  
 4 console_handler.setLevel(logging.WARNING)  
 5 logger.addHandler(console_handler)  
 6   
 7 logger.info('info') #不会记录  
 8 logger.debug('debug') #不会记录  
 9 logger.warning('warning') #记录warning  
10 logger.error('error')   #记录error  
View Code

2 - b)打印消息

Logger.debug(msg [ ,*args [, **kwargs]])

记录DEBUG级别的日志信息。参数msg是信息的格式,args与kwargs分别是格式参数。

Logger.info(msg[ , *args[ , **kwargs] ] )

Logger.warnning(msg[ , *args[ , **kwargs] ] )

Logger.error(msg[ , *args[ , **kwargs] ] )

Logger.critical(msg[ , *args[ , **kwargs] ] )

记录相应级别的日志信息。参数的含义与Logger.debug同样。

2 - c)增长移除处理器

Logger.addHandler(hdlr)

Logger.removeHandler(hdlr)

添加/移除日志消息处理器。在讲述Handler时具体介绍。

2 - d)Logger.log(lvl, msg[ , *args[ , **kwargs] ] )

记录日志,参数lvl用户设置日志信息的级别。参数msg, *args, **kwargs的含义与Logger.debug同样。

2 - e)Logger.exception(msg[, *args])

以ERROR级别记录日志消息,异常跟踪信息将被自动添加到日志消息里。Logger.exception经过用在异常处理块中,如:

1 #异常信息也会添加到日志消息里
2 try:
3     raise IOError, 'this is a winter testing IOError'
4 except IOError:
5     logger.exception('record this error')
6     logger.warning(''.center(50,'-'))
View Code

2 - f)

Logger.addFilter(filt)

Logger.removeFilter(filt)

添加/移除日志消息过滤器。在讲述Filter时具体介绍。

2 - g)Logger.makeRecord(name, lvl, fn, lno, msg, args, exc_info[, func, extra])

建立LogRecord对象。日志消息被实例为一个LogRecord对象,并在日志类内处理。

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  
View Code

默认状况下,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 '''  
View Code

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)将日志同时输出到文件和屏幕

 1 import logging
 2 logger = logging.getLogger(__name__)
 3 logger.setLevel(level = logging.INFO)
 4 handler = logging.FileHandler("log.txt")
 5 handler.setLevel(logging.INFO)
 6 formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
 7 handler.setFormatter(formatter)
 8  
 9 console = logging.StreamHandler()
10 console.setLevel(logging.INFO)
11  
12 logger.addHandler(handler)
13 logger.addHandler(console)
14  
15 logger.info("Start print log")
16 logger.debug("Do something")
17 logger.warning("Something maybe fail.")
18 logger.info("Finish")
View Code

能够在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')
View Code

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")  
View Code

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')
View Code

说明:

首先定义了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  
View Code

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')  
View Code

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')  
View Code

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 }  
View Code

经过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()  
View Code

使用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]  
View Code

经过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()  
View Code

 接下来,你就能够在运行程序的时候调用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)  
View Code

结果为:

ERROR:__main__:Failed to open file  
Traceback (most recent call last):  
  File "example.py", line 6, in <module>  
    open('/path/to/does/not/exist', 'rb')  
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) 
View Code

大约能够看到,若是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()
View Code

由于参数为空,因此咱们就看出了,该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
View Code

不带参数的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")   
View Code

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
View Code

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
View Code

输出结果为:

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  
View Code

额,最简单的样例牵引出来这么多后台的逻辑,不过咱们懂一下也是有好处的。

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
View Code

咱们观察 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  
View Code

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

3)解决方案2

我认为最简单有效的解决方案。重写FileHandler类(这个类是全部写入文件的Handler都须要继承的TimedRotatingFileHandler 就是继承的这个类;咱们增长一些简单的判断和操做就能够。
咱们的逻辑是这样的:

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

b)若是不是,则切换 指向的文件便可
结束,是否是很简单的逻辑。
talking is cheap show me the code:

 1 class SafeFileHandler(FileHandler):  
 2   
 3 def __init__(self, filename, mode, encoding=None, delay=0):  
 4     """  
 5     Use the specified filename for streamed logging  
 6     """  
 7     if codecs is None:  
 8         encoding = None  
 9     FileHandler.__init__(self, filename, mode, encoding, delay)  
10     self.mode = mode  
11     self.encoding = encoding  
12     self.suffix = "%Y-%m-%d"  
13     self.suffix_time = ""  
14 def emit(self, record):  
15     """ 
16     Emit a record. 
17     Always check time 
18     """  
19     try:  
20         if self.check_baseFilename(record):  
21             self.build_baseFilename()  
22         FileHandler.emit(self, record)  
23     except (KeyboardInterrupt, SystemExit):  
24         raise  
25     except:  
26         self.handleError(record)  
27 def check_baseFilename(self, record):  
28     """ 
29     Determine if builder should occur. 
30     record is not used, as we are just comparing times, 
31     but it is needed so the method signatures are the same 
32     """  
33     timeTuple = time.localtime()  
34     if self.suffix_time != time.strftime(self.suffix, timeTuple) or not os.path.exists(  
35                             self.baseFilename + '.' + self.suffix_time):  
36         return 1  
37     else:  
38         return 0  
39 def build_baseFilename(self):  
40     """ 
41     do builder; in this case, 
42     old time stamp is removed from filename and 
43     a new time stamp is append to the filename 
44     """  
45     if self.stream:  
46         self.stream.close()  
47         self.stream = None  
48     # remove old suffix  
49     if self.suffix_time != "":  
50         index = self.baseFilename.find("." + self.suffix_time)  
51         if index == -1:  
52             index = self.baseFilename.rfind(".")  
53         self.baseFilename = self.baseFilename[:index]  
54     # add new suffix  
55     currentTimeTuple = time.localtime()  
56     self.suffix_time = time.strftime(self.suffix, currentTimeTuple)  
57     self.baseFilename = self.baseFilename + "." + self.suffix_time  
58     self.mode = 'a'  
59     if not self.delay:  
60         self.stream = self._open()  
View Code

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)使用案例一

 1 def init_log():
 2     logfile = "/data1/restful_log/restful_api_thread.log"
 3     filesize = 800*1024*1024
 4     log = getLogger()
 5     rotate_handler = ConcurrentRotatingFileHandler(logfile, "a", filesize, encoding="utf-8")
 6 
 7     datefmt_str = '%Y-%m-%d %H:%M:%S'
 8     format_str = '%(asctime)s\t%(levelname)s\t%(message)s '
 9     formatter = Formatter(format_str, datefmt_str)
10     rotate_handler.setFormatter(formatter)
11 
12     log.addHandler(rotate_handler)
13     log.setLevel(WARN)
14 
15     return log
View Code

ConcurrentRotatingFileHandler参数说明: 
filename: 日志文件地址,相对地址或绝对地址都可

mode: 默认为"a"

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

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

encoding:日志文件编码格式,默认为gbk

b)使用案例二

建一个目录,下面的文件都放到这个目录中:

logging-config.yaml

 1 version: 1    
 2     
 3 formatters:    
 4     simple:    
 5         format: '%(asctime)s - %(name)s - %(levelname)s - %(message)s'    
 6     
 7 handlers:    
 8     console:    
 9         class: logging.StreamHandler    
10         level: DEBUG    
11         formatter: simple    
12         stream: ext://sys.stdout    
13     
14 loggers:    
15     simpleExample:    
16         level: DEBUG    
17         handlers: [console]    
18         propagate: no    
19     
20 root:    
21     level: DEBUG    
22     handlers: [console]    
View Code

 testlogging.py

  1 #!/usr/bin/python2.7    
  2 #-*- coding: UTF-8 -*-    
  3 #    
  4 # Using ConcurrentLogHandler:    
  5 #   wget https://pypi.python.org/packages/fd/e5/0dc4f256bcc6484d454006b02f33263b20f762a433741b29d53875e0d763/ConcurrentLogHandler-0.9.1.tar.gz#md5=9609ecc4c269ac43f0837d89f12554c3    
  6 #   cd ConcurrentLogHandler-0.9.1    
  7 #   python2.7 setup.py install    
  8 ###########################################################    
  9 import logging, logging.config    
 10 import cloghandler    
 11     
 12 import yaml    
 13     
 14 ###########################################################    
 15 # create logger    
 16 # 使用代码建立logger    
 17 logger = logging.getLogger('simple_example')    
 18 logger.setLevel(logging.DEBUG)    
 19     
 20 # create console handler and set level to debug    
 21 ch = logging.StreamHandler()    
 22 ch.setLevel(logging.DEBUG)    
 23     
 24 # create formatter    
 25 formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')    
 26     
 27 # add formatter to ch    
 28 ch.setFormatter(formatter)    
 29     
 30 # add ch to logger    
 31 logger.addHandler(ch)    
 32     
 33 # 'application' code    
 34 logger.debug('debug message')    
 35 logger.info('info message')    
 36 logger.warn('warn message')    
 37 logger.error('error message')    
 38 logger.critical('critical message')    
 39     
 40     
 41 ###########################################################    
 42 # basicConfig    
 43 logging.basicConfig(format='%(asctime)s %(message)s', datefmt='%m/%d/%Y %I:%M:%S %p')    
 44 logging.warning('is when this event was logged.')    
 45     
 46     
 47 ###########################################################    
 48 # using yaml config file    
 49 f = open("logging-config.yaml")    
 50 dictcfg = yaml.load(f)    
 51 f.close()    
 52     
 53 logging.config.dictConfig(dictcfg)    
 54     
 55 #logging.config.fileConfig("logging.config")    
 56 log = logging.getLogger("root")    
 57 log.info("==YAML== Here is a very exciting log message")    
 58     
 59 ###########################################################    
 60 # using ini config file    
 61 logging.config.fileConfig("logging-config.ini")    
 62 log = logging.getLogger("simpleExample")    
 63 log.info("==INI== Here is a very exciting log message")    
 64     
 65     
 66 ###########################################################    
 67 # using inline code config    
 68 logging.config.dictConfig({    
 69     'version': 1,    
 70     'disable_existing_loggers': True,    
 71     'formatters': {    
 72         'verbose': {    
 73             'format': "[%(asctime)s] %(levelname)s [%(name)s:%(lineno)s] %(message)s",    
 74             'datefmt': "%Y-%m-%d %H:%M:%S",    
 75         },    
 76         'simple': {    
 77             'format': '%(levelname)s %(message)s',    
 78         },    
 79     },    
 80     'handlers': {    
 81         'null': {    
 82             'level': 'DEBUG',    
 83             'class': 'logging.NullHandler',    
 84         },    
 85         'console': {    
 86             'level': 'DEBUG',    
 87             'class': 'logging.StreamHandler',    
 88             'formatter': 'verbose',    
 89         },    
 90         'file': {    
 91             'level': 'DEBUG',    
 92             'class': 'cloghandler.ConcurrentRotatingFileHandler',    
 93             'maxBytes': 1024 * 1024 * 10,   # 当达到10MB时分割日志    
 94             'backupCount': 10,              # 最多保留10份文件    
 95             'delay': True,                  # If delay is true, file opening is deferred until the first call to emit    
 96             'filename': 'sample-site.log',    
 97             'formatter': 'verbose',    
 98         },    
 99         'file2': {    
100             'level': 'DEBUG',    
101             'class': 'cloghandler.ConcurrentRotatingFileHandler',    
102             'maxBytes': 1024 * 1024 * 10,   # 当达到10MB时分割日志    
103             'backupCount': 10,              # 最多保留10份文件    
104             'delay': True,                  # If delay is true, file opening is deferred until the first call to emit    
105             'filename': 'sample-site2.log',    
106             'formatter': 'verbose',    
107         },    
108     },    
109     'loggers': {    
110         '': {    
111             'handlers': ['file'],    
112             'level': 'INFO',    
113         },    
114         'root': {    
115             'handlers': ['console'],    
116             'level': 'INFO',    
117             'propagate': 0,    
118         },    
119         'root2': {    
120             'handlers': ['console'],    
121             'level': 'INFO',    
122             'propagate': 1,    
123         },    
124     },    
125 })    
126     
127 logger = logging.getLogger("root")    
128 logger.info("==== Here is a very exciting log message")    
129     
130 logger = logging.getLogger("root2")    
131 logger.info("==== Here is a very exciting log message2")   
View Code

9. 小知识点

1)使用__name__做为logger的名称

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

 2)全局共享logging配置

其实很简单,只须要执行:

logging.basicConfig(filename=‘', level=logging.DEBUG, filemode='w', format='%(asctime)s - %(name)s - %(levelname)s - %(message)s')

而后就能够在任何地方打印日志便可

logging.leve('')

暂时就到这里,之后继续扩展

相关文章
相关标签/搜索