使用python的logging模块

一、从一个使用场景开始

开发一个日志系统， 既要把日志输出到控制台， 还要写入日志文件

Python代码:

import logging

# 创建一个logger
logger = logging.getLogger('mylogger')
logger.setLevel(logging.DEBUG)

# 创建一个handler，用于写入日志文件
fh = logging.FileHandler('test.log')
fh.setLevel(logging.DEBUG)

# 再创建一个handler，用于输出到控制台
ch = logging.StreamHandler()
ch.setLevel(logging.DEBUG)

# 定义handler的输出格式
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
fh.setFormatter(formatter)
ch.setFormatter(formatter)

# 给logger添加handler
logger.addHandler(fh)
logger.addHandler(ch)

# 记录一条日志
logger.info('foorbar')

运行后， 在控制台和日志文件都有一条日志：

2011-08-31 19:18:29,816 - mylogger - INFO - foorbar
2011-08-31 19:18:29,816 - mylogger - INFO - foorbar

二、logging模块的API

结合上面的例子，我们说下几个最常使用的API

1）logging.getLogger([name])

返回一个logger实例，如果没有指定name，返回root logger。只要name相同，返回的logger实例都是同一个而且只有一个，即name和logger实例是一一对应的。这意味着，无需把logger实例在各个模块中传递。只要知道name，就能得到同一个logger实例

2）Logger.setLevel(lvl)

设置logger的level， level有以下几个级别：

NOTSET < DEBUG < INFO < WARNING < ERROR < CRITICAL

如果把looger的级别设置为INFO， 那么小于INFO级别的日志都不输出， 大于等于INFO级

别的日志都输出

Python代码

logger.debug("foobar") # 不输出

logger.info("foobar") # 输出

logger.warning("foobar") # 输出

logger.error("foobar") # 输出

logger.critical("foobar") # 输出

3）Logger.addHandler(hdlr)

logger可以雇佣handler来帮它处理日志， handler主要有以下几种：

StreamHandler: 输出到控制台

FileHandler: 输出到文件

handler还可以设置自己的level以及输出格式。

4）logging.basicConfig([**kwargs])

* 这个函数用来配置root logger， 为root logger创建一个StreamHandler， 设置默认的格式。

* 这些函数： logging.debug()、logging.info()、logging.warning()、logging.error()、logging.critical() 如果调用的时候发现root logger没有任何handler， 会自动调用basicConfig添加一个handler

* 如果root logger已有handler， 这个函数不做任何事情

使用basicConfig来配置root logger的输出格式和level：

Python代码

import logging

logging.basicConfig(format='%(levelname)s:%(message)s', level=logging.DEBUG)

logging.debug('This message should appear on the console')

三、关于root logger以及logger的父子关系

前面多次提到root logger， 实际上logger实例之间还有父子关系， root logger就是处于最顶层的logger， 它是所有logger的祖先。

1）root logger是默认的logger。

如果不创建logger实例， 直接调用logging.debug()、logging.info()、logging.warning()、logging.error()、logging.critical()这些函数，那么使用的logger就是 root logger， 它可以自动创建，也是单实例的。

2）如何得到root logger

通过logging.getLogger()或者logging.getLogger("")得到root logger实例。

3）默认的level

root logger默认的level是logging.WARNING

4）如何表示父子关系

logger的name的命名方式可以表示logger之间的父子关系. 比如：

parent_logger = logging.getLogger('foo')

child_logger = logging.getLogger('foo.bar')

5）什么是effective level

logger有一个概念，叫effective level。 如果一个logger没有显示地设置level，那么它就用父亲的level。如果父亲也没有显示地设置level， 就用父亲的父亲的level，以此推....

最后到达root logger，一定设置过level。默认为logging.WARNING

child loggers得到消息后，既把消息分发给它的handler处理，也会传递给所有祖先logger处理。

来看一个例子

Python代码

import logging

# 设置root logger
r = logging.getLogger()
ch = logging.StreamHandler()
ch.setLevel(logging.DEBUG)
formatter = logging.Formatter('%(asctime)s - %(levelname)s - %(message)s')
ch.setFormatter(formatter)
r.addHandler(ch)

# 创建一个logger作为父亲
p = logging.getLogger('foo')
p.setLevel(logging.DEBUG)
ch = logging.StreamHandler()
ch.setLevel(logging.DEBUG)
formatter = logging.Formatter('%(asctime)s - %(message)s')
ch.setFormatter(formatter)
p.addHandler(ch)

# 创建一个孩子logger
c = logging.getLogger('foo.bar')
c.debug('foo')

输出如下：

2011-08-31 21:04:29,893 - foo
2011-08-31 21:04:29,893 - DEBUG - foo

可见， 孩子logger没有任何handler，所以对消息不做处理。但是它把消息转发给了它的父亲以及root logger。最后输出两条日志。

四、输出执行的程序名。

其实这一点并不困难，下面就是告诉你如何做。

import logging

log = None
FORMAT = "%(levelname)-8s %(asctime)-15s %(filename)s,%(lineno)d] %(message)s"

def get_logger(format=FORMAT, datafmt=None):
global log
handler = logging.StreamHandler()
fmt = logging.Formatter(format, datafmt)
handler.setFormatter(fmt)

log = logging.getLogger('uliweb')
log.addHandler(handler)
log.setLevel(logging.INFO)
return log

if __name__ == '__main__':
log = get_logger()
log.error('This is an error %s', 'aaaa')
log.warning('This is an warning')
try:
1/0
except Exception, e:
log.exception(e

官方文档对exception方法的解释：

exception(msg, *args)

Log a message with severity 'ERROR' on the root logger, with exception information.

上面的测试代码输出结果为：

ERROR    2009-02-10 10:03:10,733 log.py,19] This is an error aaaa
WARNING 2009-02-10 10:03:10,733 log.py,20] This is an warning
ERROR    2009-02-10 10:03:10,733 log.py,24] integer division or modulo by zero
Traceback (most recent call last):
File "D:\project\svn\uliweb\uliweb\utils\log.py", line 22, in <module>
1/0
ZeroDivisionError: integer division or modulo by zero

五、设置Handler自已的日志格式

每个Handler可以设置自已的日志格式，上面我预定义了一个FORMAT，其中%(asctime)-15s用来输出日，精确到毫秒，%(filename)s 输出文件主名，%(lineno)d为执行的行号，%(message)是用来输出用户的日志。这些参数都是logging自带的，在logging.py中的Formatter类中的详细的描述：

%(name)s               Name of the logger (logging channel)
%(levelno)s             Numeric logging level for the message (DEBUG, INFO,WARNING, ERROR, CRITICAL)
%(levelname)s        Text logging level for the message ("DEBUG", "INFO", "WARNING", "ERROR", "CRITICAL")
%(pathname)s        Full pathname of the source file where the logging call was issued (if available)
%(filename)s           Filename portion of pathname
%(module)s            Module (name portion of filename)
%(lineno)d              Source line number where the logging call was issued (if available)
%(funcName)s        Function name
%(created)f            Time when the LogRecord was created (time.time() return value)
%(asctime)s           Textual time when the LogRecord was created
%(msecs)d             Millisecond portion of the creation time
%(relativeCreated)d Time in milliseconds when the LogRecord was created,  relative to the time the logging module was loaded (typically at application startup time)
%(thread)d             Thread ID (if available)
%(threadName)s     Thread name (if available)
%(process)d           Process ID (if available)
%(message)s          The result of record.getMessage(), computed just as the record is emitted

比文档好象详细多了。