日志对于程序运行和技术人员来说是很必要且非常重要的,排查问题一般都是从分析程序运行日志开始的,再复杂再庞大的程序都必须要有日志输入,否则就算不上合格的程序。Python中为技术人员提供了方便的logging模块来定义和输出日志。

  先来看下logging的日志级别和简单的输出,如下例子:

#导入日志模块logging
import logging
# 输出不同级别的log
logging.debug('This is debug info')
logging.info('This is information')
logging.warn('This is warning message')
logging.error('This is error message')
logging.fatal('This is fatal message, it is same as logger.critical')
logging.critical('This is critical message')

运行结果:
WARNING:root:This is warning message
ERROR:root:This is error message
CRITICAL:root:This is fatal message, it is same as logger.critical
CRITICAL:root:This is critical message

  从上述例子中可以看出默认情况下python的logging模块将日志打印到了标准输出中,且只显示了大于等于WARNING级别的日志,这说明默认的日志级别设置为WARNING(日志级别等级CRITICAL > ERROR > WARNING > INFO > DEBUG > NOTSET),默认的日志格式为日志级别:Logger名称(默认的logger名称是root):用户输出消息。

  我们可以通过logging模块的basicConfig函数对输出日志格式、位置、级别进行自定义,如下例子:

#basicConfig定义日志级别,日志格式,输出位置
import logging
logging.basicConfig(level=logging.DEBUG,
                   format='%(asctime)s %(filename)s[line:%(lineno)d] %(levelname)s %(message)s',
                   datefmt='%a, %d %b %Y %H:%M:%S',
                   filename='test.log',
                   filemode='w')
logging.debug('debug message')
logging.info('info message')
logging.warning('warning message')
logging.error('error message')
logging.critical('critical message')

运行结果:
cat test.log
Thu, 10 Nov 2017 10:03:44 rizhi.py[line:20] DEBUG debug message
Thu, 10 Nov 2017 10:03:44 rizhi.py[line:21] INFO info message
Thu, 10 Nov 2017 10:03:44 rizhi.py[line:22] WARNING warning message
Thu, 10 Nov 2017 10:03:44 rizhi.py[line:23] ERROR error message
Thu, 10 Nov 2017 10:03:44 rizhi.py[line:24] CRITICAL critical message

  从例子中看出在logging.basicConfig()函数中可通过具体参数来更改logging模块默认行为,可用参数有:
  filename:用指定的文件名,这样日志会被存储在指定的文件中。
  filemode:文件打开方式,在指定了filename时使用这个参数,默认值为“a”还可指定为“w”。
  format:指定使用的日志显示格式。 
  datefmt:指定日期时间格式。 
  level:设置的日志级别 
  stream:用指定的stream创建StreamHandler。可以指定输出到sys.stderr,sys.stdout或者文件,默认为  sys.stderr。若同时列出了filename和stream两个参数,则stream参数会被忽略。
  其中format参数中可能用到的格式化串:
  %(name)s     Logger的名字
  %(levelno)s     数字形式的日志级别
  %(levelname)s     文本形式的日志级别
  %(pathname)s     调用日志输出函数的模块的完整路径名,可能没有
  %(filename)s     调用日志输出函数的模块的文件名
  %(module)s     调用日志输出函数的模块名
  %(funcName)s     调用日志输出函数的函数名
  %(lineno)d     调用日志输出函数的语句所在的代码行
  %(created)f     当前时间,用UNIX标准的表示时间的浮 点数表示
  %(relativeCreated)d     输出日志信息时的,自Logger创建以 来的毫秒数
  %(asctime)s     字符串形式的当前时间。默认格式是 “2003-07-08 16:49:45,896”。逗号后面的是毫秒
  %(thread)d     线程ID。可能没有
  %(threadName)s     线程名。可能没有
  %(process)d     进程ID。可能没有
  %(message)s    用户输出的消息

  logging.basicConfig()函数提供的日志输出方式已经足够灵活,但还有另外一个更灵活的模块级函数logging.getLogger(),返回一个logger对象,如果没有指定名字将返回root logger。为了了解这个函数,我们需要先了解下Logger,Handler,Formatter,Filter的概念。

  Logger对象提供应用程序可直接使用的接口,Handler发送日志到适当的目的地,Filter提供了过滤日志信息的方法,Formatter指定日志显示格式。

 例子:演示 logging.getLogger()用法

import logging
# 创建一个logger
logger = logging.getLogger()
logger1 = logging.getLogger('mylogger')
logger1.setLevel(logging.DEBUG)
logger2 = logging.getLogger('mylogger')
logger2.setLevel(logging.INFO)
logger3 = logging.getLogger('mylogger.child1')
logger3.setLevel(logging.WARNING)
# 创建一个handler,用于写入日志文件
fh = logging.FileHandler('test.log')
# 再创建一个handler,用于输出到控制台
ch = logging.StreamHandler()
# 定义handler的输出格式formatter
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
fh.setFormatter(formatter)
ch.setFormatter(formatter)
# 定义一个filter
filter1 = logging.Filter('mylogger')
filter2 = logging.Filter('mylogger.child1')
# fh.addFilter(filter)
# 给logger添加handler
logger.addHandler(fh)
logger.addHandler(ch)
logger1.addFilter(filter1)
logger1.addHandler(fh)
logger1.addHandler(ch)
logger2.addFilter(filter1)
logger2.addHandler(fh)
logger2.addHandler(ch)
logger3.addFilter(filter2)
logger3.addHandler(fh)
logger3.addHandler(ch)
# 记录一条日志
logger.debug('logger debug message')
logger.info('logger info message')
logger.warning('logger warning message')
logger.error('logger error message')
logger.critical('logger critical message')
logger1.debug('logger1 debug message')
logger1.info('logger1 info message')
logger1.warning('logger1 warning message')
logger1.error('logger1 error message')
logger1.critical('logger1 critical message')
logger2.debug('logger2 debug message')
logger2.info('logger2 info message')
logger2.warning('logger2 warning message')
logger2.error('logger2 error message')
logger2.critical('logger2 critical message')
logger3.debug('logger3 debug message')
logger3.info('logger3 info message')
logger3.warning('logger3 warning message')
logger3.error('logger3 error message')
logger3.critical('logger3 critical message')

运行结果:
2017-11-09 22:51:59,654 - root - WARNING - logger warning message
2017-11-09 22:51:59,654 - root - ERROR - logger error message
2017-11-09 22:51:59,654 - root - CRITICAL - logger critical message
2017-11-09 22:51:59,655 - mylogger - INFO - logger1 info message
2017-11-09 22:51:59,655 - mylogger - INFO - logger1 info message
2017-11-09 22:51:59,655 - mylogger - WARNING - logger1 warning message
2017-11-09 22:51:59,655 - mylogger - WARNING - logger1 warning message
2017-11-09 22:51:59,655 - mylogger - ERROR - logger1 error message
2017-11-09 22:51:59,655 - mylogger - ERROR - logger1 error message
2017-11-09 22:51:59,655 - mylogger - CRITICAL - logger1 critical message
2017-11-09 22:51:59,655 - mylogger - CRITICAL - logger1 critical message
2017-11-09 22:51:59,655 - mylogger - INFO - logger2 info message
2017-11-09 22:51:59,655 - mylogger - INFO - logger2 info message
2017-11-09 22:51:59,655 - mylogger - WARNING - logger2 warning message
2017-11-09 22:51:59,655 - mylogger - WARNING - logger2 warning message
2017-11-09 22:51:59,655 - mylogger - ERROR - logger2 error message
2017-11-09 22:51:59,655 - mylogger - ERROR - logger2 error message
2017-11-09 22:51:59,655 - mylogger - CRITICAL - logger2 critical message
2017-11-09 22:51:59,655 - mylogger - CRITICAL - logger2 critical message
2017-11-09 22:51:59,657 - mylogger.child1 - WARNING - logger3 warning message
2017-11-09 22:51:59,657 - mylogger.child1 - WARNING - logger3 warning message
2017-11-09 22:51:59,657 - mylogger.child1 - WARNING - logger3 warning message
2017-11-09 22:51:59,657 - mylogger.child1 - ERROR - logger3 error message
2017-11-09 22:51:59,657 - mylogger.child1 - ERROR - logger3 error message
2017-11-09 22:51:59,657 - mylogger.child1 - ERROR - logger3 error message
2017-11-09 22:51:59,657 - mylogger.child1 - CRITICAL - logger3 critical message
2017-11-09 22:51:59,657 - mylogger.child1 - CRITICAL - logger3 critical message
2017-11-09 22:51:59,657 - mylogger.child1 - CRITICAL - logger3 critical message

  logger = logging.getLogger()返回一个默认的Logger也即root Logger,并应用默认的日志级别、Handler和Formatter设置。也可以通过Logger.setLevel(lel)指定最低的日志级别,可用的日志级别有logging.DEBUG、logging.INFO、logging.WARNING、logging.ERROR、logging.CRITICAL。

  Logger.debug()、Logger.info()、Logger.warning()、Logger.error()、Logger.critical()输出不同级别的日志,只有日志等级大于或等于设置的日志级别的日志才会被输出。

(1)从上述例子中可以发现通过logger1.setLevel(logging.DEBUG)将logger1的日志级别设置为了DEBUG,但没有输出DEBUG级别的日志信息,而是从INFO级别的日志开始了显示,这是因为logger1和logger2对应的是同一个Logger实例mylogger,只要logging.getLogger(name)中名称参数name相同则返回的Logger实例就是同一个,且仅有一个,也即name与Logger实例一一对应。在logger2实例中通过logger2.setLevel(logging.INFO)设置mylogger的日志级别为logging.INFO,所以最后logger1的输出遵从了后来设置的日志级别。

logger1 = logging.getLogger('mylogger')
logger1.setLevel(logging.DEBUG)
logger2 = logging.getLogger('mylogger')
logger2.setLevel(logging.INFO)

(2)从例子输出可以看出logger1、logger2对应的每个输出分别显示两次,logger3对应的输出显示3次,这是因为通过logger = logging.getLogger()显示的创建了root Logger,而logger1 = logging.getLogger('mylogger')创建了root Logger的子类(root.)mylogger,以此类推,logger2同样。

logger3 = logging.getLogger('mylogger.child1')
logger3.setLevel(logging.WARNING)

(3)Formatter对象设置日志信息最后的规则、结构和内容,默认的时间格式为%Y-%m-%d %H:%M:%S。

formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
fh.setFormatter(formatter)
ch.setFormatter(formatter)

(4)Filter限制只有满足过滤规则的日志才会输出。比如我们定义了filter = logging.Filter('a.b.c'),并将这个Filter添加到了一个Handler上,则使用该Handler的Logger中只有名字带a.b.c前缀的Logger才能输出其日志。

filter1 = logging.Filter('mylogger')
filter2 = logging.Filter('mylogger.child1')