Python日志教程

本文翻译自logging howto

基础教程

日志是跟踪软件运行时发生事件的一种手段。Python开发者在代码中调用logging模块的方法，用于记录某些事件已经发生。事件一般是描述性信息，其中可能会包含一些数据。事件中也包含了开发者对事件的重视程度；重视程度也可以称为级别或者严重性。

记录时机

logging模块提供了一组纪录日志的功能，有debug(), info(), warning(),error()和critical()。下表说明了这些功能的使用场景。

任务	该使用的功能
显示控制台输出，用于一般性的命令行脚本和程序	print()
报告程序正常运行期间发生的事件	logging.info()或者logging.debug()
特定运行事件的警告	如果问题是可以避免的，并且应该修改客户端应用程序以消除警告，使用warnings.warn(); 客户端不需要作出改变，但是事件仍然应该注意，使用logging.warning()
报告运行时的错误	抛出异常
非异常形式报告运行时的错误	logging.error()、logging.exception()或者logging.critical()

logging模块中的函数根据事件的严重性命名，如下表。

级别	使用时机
DEBUG	获取详细信息，通常时诊断问题时
INFO	确认程序按预期工作
WARNING	表明发生了一些意外的事情，或者用来指示在不久的将来会发生的问题。软件依然如预期工作
ERROR	因为更严重的问题，软件无法执行某些功能
CRITICAL	一个严重的问题，表示程序本身可能无法继续运行下去

默认的级别是WARNING，这意味着除非logging模块有其他的配置，否则只记录此级别或以上级别的事件。

记录的事件可以用不同的方式处理。最简单的方法是将这些事件打印到控制台。另外一个常用的方法是将事件记录到文件中。

简单的例子

一个非常简单的例子如下：

import logging
logging.warning('Watch out!') # 控制台打印
logging.info('I told you so') # 不会打印任何信息

如果运行上面的脚本，会在控制台输出如下信息：

WARNING:root:Watch out!

注意INFO级别信息没有打印出来，因为默认的级别是WARNING。打印的消息包括日志级别和描述的信息。先不用管其中的"root"信息，后面会解释。如果需要的话，可以配置输出格式；格式也会在后面提到。

写入文件

将日志写入文件是非常常见的场景，请看下面的例子。一定要在新的Python解释器中运行下面的脚本：

import logging
logging.basicConfig(filename='example.log', level=logging.DEBUG)
logging.debug('This message should go to the log file')
logging.info('So should this')
logging.warning('And this, too')

如果打开这个文件，会看到下面的信息：

DEBUG:root:This message should go to the log file
INFO:root:So should this
WARNING:root:And this, too

这个例子还显示了如何设置日志的级别。由于级别设置为DEBUG，所有的信息都会记录下来。

如果想要通过类似--log=INFO命令行参数设置日志级别，并且将传入的级别存入loglevel变量，然后通过getattr(logging, loglevel.upper())获取级别变量，并传入basicConfig()，可以通过下面的代码对参数进行校验：

numeric_level = getattr(logging, loglevel.upper(), None)
if not isinstance(numberic_level, int):
    raise ValueError('Invalid log level: %s' % loglevel)
logging.basicConfig(level=numeric_level, ...)

应该在debug(), info()等方法之前调用basicConfig()。因为它是一次性的配置，只有第一次的调用是有效的。

如果多次运行上面的脚本，日志将会追加到文件example.log中。可以通过修改filemode参数修改这一行为。

logging.basicConfig(filename='example.log', filemode='w', level=logging.DEBUG)

输出和之前是一样的，但是每次运行会丢失之前的消息。

多模块日志

如果程序由多个模块组成，可以参考下面的例子组织日志

# myapp.py
import logging
import mylib

def main():
    logging.basicConfig(filename='myapp.log', level=logging.INFO)
    logging.info('Started')
    mylib.do_something()
    logging.info('Finished')
    
if __name__ == '__main__':
    main()

# mylib.py
import logging

def do_something():
    logging.info('Doing something')

运行myapp.py，将会在myapp.log中看到：

INFO:root:Started
INFO:root:Doing something
INFO:root:Finished

可以通过类似的模式将其推广到多个模块。不过，对于这种简单的使用，只能通过查看事件描述来判断日志的来源。

记录变量

要记录变量数据，需要使用事件描述消息的格式，并附加变量作为参数。比如：

import logging
logging.warning('%s before you %s', 'Look', 'leap!')

会显示

WARNING:root:Look before you leap!

可以看到，使用的是%风格的字符串格式。这是为了向后兼容。logging模块也支持更新的格式化选项，但是探索这些不在本教程的范围之内。

改变日志格式

要改变日志格式，需要指定新的格式：

import logging
logging.basicConfig(format='%(levelname)s:%(message)s', level=logging.DEBUG)
logging.debug('This message should appear on the console')
logging.info('So should this')
logging.warning('And this, too')

上面的脚本会打印：

DEBUG:This message should appear on the console
INFO:So should this
WARNING:And this, too

请注意，前面例子中的"root"已经消失了。完整的格式说明见LogRecord attribute，但是对于简单的应用来说，只需要记录事件级别，信息和时间就足够了。

消息中显示时间信息

要展示事件的时间，可以在格式串中加入'%(asctime)s':

import logging
logging.basicConfig(format='%(asctime)s %(message)s')
logging.warning('is when this event was logged.')

上面的脚本会打印

2010-12-12 11:41:42,612 is when this event was logged.

默认展示的时间格式是ISO8601。如果需要更多的控制，可以通过传递datafmt参数给basicConfig来实现，比如：

import logging
logging.basicConfig(format='%(asctime)s %(message)s', datefmt='%m/%d/%Y %I:%M:%S %p')
logging.warning('is when this event was logged.')

上面的脚本会打印以下信息：

12/12/2010 11:46:36 AM is when this event was logged.

参数datefmt支持的格式time.strftime()也支持。

后续教程

以上就是logging模块的基础教程，掌握上面的内容就可以进行常规日志记录。logging模块提供了更多的功能，想要充分利用它，请看下面的章节。

进阶教程

logging模块采用模块化的设计，并提供了几类组件：记录器，处理器，过滤器和格式器。

• 记录器提供应用程序代码使用的接口。
• 处理器将记录器生成的记录发送到相应的位置。
• 过滤器对记录进行过滤，决定哪些日志会被输出。
• 格式器决定输出的格式。

日志事件以LogRecord实例的形式在记录器，处理器，过滤器和格式器之间传递。

一般通过调用Logger实例(下面简称为记录器)中的方法来记录日志。每个实例都有名字，这些名字在命名空间层级中由点连接。比如，名为'scan'的记录器是'scan.text'，'scan.html'和'scan.pdf'的父记录器。记录器的名字可以任意取。

一个命名记录器的良好习惯是使用模块名，比如下面：

logger = logging.getLogger(__name__)

使用这种命名可以记录模块的继承关系。

记录器层次结构的根被称之为根记录器。函数debug(), info(), warning(), error(), critical()其实调用的就是根记录器中同名的方法。这些函数和方法记录的日志中，记录器名字为'root'。

可以将不同的日志信息记录到不同的地方。logging模块支持将日志写入多个目的位置，其中包括文件、HTTP GET/POST地址、邮件(SMTP协议)、通用socket、操作系统日志机制(比如syslog和Windows NT的事件记录)。目的位置由处理器来指定。可以根据需求构造自己的处理器类。

默认情况下，任何日志都不设置目的地。可以通过basicConfig()指定一个目的地。debug(), info(), warning(), error()和critical()会在被调用时检查是否设置了目的地；如果没有设置，则在将消息委托给根记录器之前，将目的器设置为控制台(sys.stderr)，并使用默认格式输出消息。

basicConfig()的默认设置是：

日志级别:记录器名字:消息

日志流

记录器和处理器对日志事件的处理流程如下图：

记录器

Logger对象有三个功能。第一，提供接口给应用程序代码，应用程序代码在运行时通过调用这些接口记录日志。第二，根据设置的日志等级(默认过滤规则)或者过滤器来确定输出的日志消息。第三，将日志消息传递给所有与之相关的处理器。

记录器对象中使用最广泛的方法分为两类：配置和发送消息。

下面是最常用的配置方法：

• Logger.setLevel()指定记录器处理的日志级别，内置的最低级别是debug，最高级别是critical。比如，如果配置的日志级别是INFO，那么记录器只会处理INFO，WARNING，ERROR和CRITICAL级别的日志，DEBUG级别的日志将被自动忽略。
• Logger.addHandler()和Logger.removeHandler()会从记录器对象中添加或者移除处理器。
• Logger.addFilter()和Logger.removeFilter()方法会从记录器对象中添加或者移除过滤器。

不需要每次创建记录器时都调用这些方法。

配置好记录器对象后，可以通过下面的方法创建日志消息：

• Logger.debug(), Logger.info(), Logger.warning(), Logger.error()和 Logger.critical()都用来创建和方法名对应级别的日志记录。消息实际上是格式字符串，可能包含标准字符串替换语法%s, %d, %f等等。其余的参数是消息中的替换字段对应的对象列表。这些方法只关心**kwargs中的exc_info关键字，并使用它来确定是否记录异常信息。
• Logger.exception()和Logger.error()差不多。不过Logger.exception()会转储堆栈跟踪信息。只能在异常处理中调用这个方法。
• Logger.log()将日志级别作为显式参数。和上面列出的方法相比，这个方法有点啰嗦，不过可以使用该方法记录自定义级别日志。

getLogger()返回具有指定名字的记录器的引用，如果没有指定名字，则返回root。用'.'连接命名空间的层次构成了这些名字。使用同样的名字多次调用getLogger()会返回指向同一记录器的引用。分层列表中位置靠下的记录器是位置靠上的记录器的子记录器。比如，对名字为foo的记录器来说，名字为foo.bar, foo.bar.baz和foo.bam的记录器是它的子记录器。

记录器有有效级别的概念。如果没有显式设置级别，则使用父记录器的级别作为其有效级别。如果父记录器也没有设置，则一直向上寻找，直到找到显式设置的级别。根记录器始终具有显式级别设置(默认为WARNING)。在决定是否处理事件时，使用记录器的有效级别来确定是否将事件传递给处理器。

子记录器将消息传播到与其祖先记录器相关联的处理器。因此，无需为所有的日志记录器定义和配置处理器。为顶级记录器配置处理器，并根据需要创建子记录器就足够了。(不过，也可以将propagate属性设置为False来关闭这一行为)。

处理器

处理器负责将适当的日志消息(基于日志的级别)分派到指定的目标。Logger对象可以通过使用addHandler()方法添加零或者更多的处理器对象。比如，应用程序可能希望将所有的日志消息发送到日志文件，error及更高级别的日志输出到stdout，critical级别的日志通过邮件告警。这个场景需要三个单独的处理器，其中每个处理器负责将特定级别的消息发送到特定位置。

标准库包含相当多不同类型的处理器(参阅Useful Handlers)。

开发者需要关心的处理器方法很少。使用内置处理器需要关心以下的配置方法：

• setLevel()方法，和记录器中的同名方法一样，这个方法设置日志能分派到目的地的最低级别。
• setFormatter()设置处理器使用的格式器。
• addFilter()和removeFilter()分别用于在配置中添加和移除过滤器对象。

应用代码不应该直接初始化并使用Handler类的实例。Handler类是一个基类，用于定义所有处理器应具有的接口，并定义一些子类可以使用(或覆盖)的默认行为。

格式器

格式器配置日志消息显示的最终顺序，结构和内容。和基础的logging.Handler类不同，应用程序代码可以实例化格式器类。如果应用程序需要特殊行为，可以自定义子类。构造函数使用两个可选参数--消息格式字符串和日期格式字符串。

logging.Formatter.__init__(fmt=None, datefmt=None)

如果没有消息格式字符串，默认使用原始消息。如果没有日期格式字符串，默认的格式为：

%Y-%m-%d %H:%M:%S

下面的消息格式字符串记录的顺序为：人类可读的时间格式，消息的级别，消息的内容。

'%(asctime)s - %(levelname)s - %(message)s'

配置

程序员可以通过三种方式配置日志记录：

• 在代码中显示创建记录器，处理器和格式器
• 创建配置文件，并用fileConfig()函数读取
• 创建配置字典，并传入dictConfig()方法。

后两种方法的文档见Configuration functions。下面的示例使用Python代码配置了一个非常简单的记录器，一个控制台处理器和一个简单的格式器：

# coding=utf8
import logging

# 创建记录器
logger = logging.getLogger('simple_example')
logger.setLevel(logging.DEBUG)

# 创建控制台处理器，将级别设置为DEBUG
ch = logging.StreamHandler()
ch.setLevel(logging.DEBUG)

# 创建格式器
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')

# 处理器中添加格式器
ch.setFormatter(formatter)

# 记录器中添加处理器
logger.addHandler(ch)

# 应用代码
logger.debug('debug message')
logger.info('info message')
logger.warn('warn message')
logger.error('error message')
logger.critical('critical message')

运行上面的脚本会产生如下输出：

$ python simple_logging.module.py 
2017-04-25 15:59:13,321 - simple_example - DEBUG - debug message
2017-04-25 15:59:13,321 - simple_example - INFO - info message
2017-04-25 15:59:13,321 - simple_example - WARNING - warn message
2017-04-25 15:59:13,321 - simple_example - ERROR - error message
2017-04-25 15:59:13,321 - simple_example - CRITICAL - critical message

下面的Python模块创建一个记录器，处理器和格式器，除了对象名字和上面例子不同外，其他都一样：

import logging
import logging.config

logging.config.fileConfig('logging.conf')

logger = logging.getLogger('simpleExample')

logger.debug('debug message')
logger.info('info message')
logger.warn('warn message')
logger.error('error message')
logger.critical('critical message')

logging.conf文件如下：

[loggers]
keys=root,simpleExample

[handlers]
keys=consoleHandler

[formatters]
keys=simpleFormatter

[logger_root]
level=DEBUG
handlers=consoleHandler

[logger_simpleExample]
level=DEBUG
handlers=consoleHandler
qualname=simpleExample
propagate=0

[handler_consoleHandler]
class=StreamHandler
level=DEBUG
formatter=simpleFormatter
args=(sys.stdout,)

[formatter_simpleFormatter]
format=%(asctime)s - %(name)s - %(levelname)s - %(message)s
datefmt=

产生的输出和上面例子相同：

$ python simple_logging_config.py 
2017-04-25 16:08:46,631 - simpleExample - DEBUG - debug message
2017-04-25 16:08:46,631 - simpleExample - INFO - info message
2017-04-25 16:08:46,631 - simpleExample - WARNING - warn message
2017-04-25 16:08:46,631 - simpleExample - ERROR - error message
2017-04-25 16:08:46,631 - simpleExample - CRITICAL - critical message

可以看到，相比使用Python代码，配置文件有隔离配置与代码和易于修改这些优点。

没有配置的情况

如果没有配置日志，可能会出现需要输出日志但是没有处理器的情况。在这种情况下，logging模块的行为取决于Python版本。

对于Python2.x版本，行为如下：

• 如果logging.raiseExceptions是False(生产模式)，日志事件被丢弃。
• 如果logging.raiseExceptions是True(开发模式)，会打印消息'No handlers could be found for logger X.Y.Z'。

为库配置日志

在开发的库中记录日志时，应该留下文档，注明记录日志的方式--比如所使用记录器的名字。同时也需要考虑日志的配置。如果应用程序没有配置日志，而库代码又调用了logging接口，那么一条错误消息将被打印到sys.stderr。

如果不希望打印这条消息，可以在库的顶层记录器中添加一个空处理器。日志事件总是会找到处理器，而空处理器不会产生任何输出，因此可以避免打印错误消息。如果库的使用者在应用中配置了日志并且添加了处理器，那么库中的日志调用将会被发送到这些处理器。

logging模块包块了空处理器：NullHandler(Python2.7版本或以上)。如果要在不配置日志的情况下阻止错误信息发送到sys.stderr，可以将该处理器实例添加到命名空间中的顶层记录器中。如果foo库的记录器名为'foo.x'，'foo.x.y'之类的话，那么下面的代码

import logging
logging.getLogger('foo').addHandler(logging.NullHandler())

将会有预期的效果。如果组织生成多个库，则指定记录器的名字应该是'orgname.foo'。

日志级别

日志级别的数值如下表所示。如果要自定义级别，并且需要自定义级别具有特定值，那么需要关注这些。如果自定义的级别和预定义级别有相同的数值，它将覆盖预定义的值；预定义的名字将会丢失。

名字	数值
CRITICAL	50
ERROR	40
WARNING	30
INFO	20
DEBUG	10
NOTSET	0

级别还可以和记录器相关联，由开发人员设置或者通过加载保存的日志记录配置。如果记录器的日志级别高于方法调用的级别，则不会生成日志消息。这是控制日志输出的基本机制。

日志消息封装在LogRecord对象中。当记录器决定记录事件时，会创建一个LogRecord实例。

消息由处理器(Handler子类)来调度处理。处理器负责确保日志(以LogRecord的形式)位于特定位置(或一组位置)，这对于该日志的目标受众(例如终端用户，支持人员，系统管理员，开发人员)是很有用的。处理器被用于将LogRecord传递到特定位置。每个记录器都可以有零个，一个或多个与它相关联的处理器(通过Logger的addHandler()方法)。除了与记录器直接关联的处理器外，还会调用与该记录器的祖先记录器关联的所有处理器来分派消息(除非记录器的传播标识设置为false值)。

就像记录器一样，处理器可以具有与它们相关联的级别。处理器的级别和记录器的级别都用作过滤。如果处理器决定调度事件，emit()方法会将消息发送到其目标。绝大多数Handler的子类需要重写emit()方法。

自定义级别

可以自定义日志级别，但是没有必要那样做，因为现有的级别都是根据实际经验选择的。不过，如果确实需要自定义级别，那么在操作的时候应该特别小心，如果正在开发一个库，自定义级别可能是一个非常糟糕的主意。这是因为如果多个库作者都自定义级别，那么这种多个库的记录输出可能会一起使用，这对开发人员来说是非常难控制和解释的，因为给定的数值在不同的库中可能有不同的意义。

有用的处理器

除了基类Handler，logging模块也提供了很多的子类：

• StreamHandler实例将消息发送到流(类文件对象)。
• FileHandler实例将消息发送到磁盘文件。
• BaseRotatingHandler是处理器的基类。一般不直接使用这个类。而是使用RotatingFileHandler或者TimedRotatingFileHandler。
• RotatingFileHandler实例将日志发送到磁盘文件，同时支持最大文件大小和日志文件轮转。
• TimedRotatingFileHandler实例将日志发送到磁盘文件，并在给定时间间隔内轮转日志文件。
• SocketHandler实例通过TCP/IP套接字发送日志。
• DatagramHandler实例通过UDP套接字发送日志。
• SMTPHandler实例将日志发送到指定的电子邮件地址。
• SysLogHandler实例将日志发送到Unix syslog守护程序中，这个守护程序可能在远程计算机上。
• NTEventLogHandler实例将日志发送到Windows NT/2000/XP的日志事件中。
• MemoryHandler实例将日志发送到内存缓冲区中，满足特定条件会刷新该缓冲区。
• HTTPHandler实例使用GET或者POST语意向HTTP服务器发送日志。
• WatchedFileHandler实例监视正在记录日志的文件。如果文件有了更改，则使用文件名关闭并重新打开。此处理器仅适用于类Unix系统；Windows不支持使用这样的机制。
• NullHandler实例对错误消息什么都不做。当库的开发者想使用logging，但是想避免'No handlers could be found for logger XXX'时，可以在记录器上添加这个处理器。

NullHandler在Python2.7中加入。

NullHandler、StreamHandler和FileHandler在logging核心部分中定义。其他的处理器在logging.handlers这个字模块中定义。

日志在通过Formatter类的格式化后进行展示。

可以使用BufferingFormatter批量格式化多个消息。除了格式化字符串外，还提供了处理头部和尾部字符串格式的方法。

当基于日志级别的过滤满足不了需求时，可以通过addFilter()方法为Logger实例添加Filter实例。在决定进一步处理消息前，记录器和处理器都会查阅所有过滤器的权限。如果任何过滤器返回false值，则不会进一步处理该消息。

Filter的基本功能允许通过特定名字的记录器进行过滤。如果使用此功能，则只有指定名字的记录器和其子孙的消息将通过，其他的消息将被丢弃。

异常处理

设计上，logging模块在生产模式下不会抛出异常。这样的好处是，在logging模块出现配置错误，网络或者其他类似的错误时，不会导致应用程序过早终止。

SystemExit和KeyboardInterrupt会正常抛出。其他Handler子类的emit()方法抛出的异常会传递给handleError()方法。

handleError()的默认实现会检查raiseExceptions变量是否设置。如果设置，栈回溯信息将打印到sys.stderr。如果没有设置，则不会抛出异常。

记录任意对象

在前面的例子中，假定了记录事件时传递的消息是一个字符串。但是，这不是唯一的可能性。可以将任意对象作为消息传递，当日志系统需要将其转换成字符串表示时，将调用对象的__str__()方法。

优化

消息将会最后被格式化输出。如果记录器只是丢弃事件，那么调用带参数的logging方法开销可能会很大。要避免这样的开销，可以使用isEnabledFor()方法。该方法接受级别作为参数，如果记录器创建该级别的参数，则返回true。可以通过下面的方式调用：

if logger.isEnabledFor(logging.DEBUG):
    logger.debug('Message with %s, %s', expensive_func1(), expensive_func2())

当记录器的级别设置为DEBUG时，expensive_func1和expensive_func2不会被调用。

对于需要对采集日志有更精确控制的应用程序，还有其他的优化策略。对于一些开发者可能不需要的信息，下表给出了一些优化建议：

不想采集的信息	优化策略
不想知道调用的来源	将logging._srcfile设置为None。这个配置会避免sys._getframe()被调用，在PyPy环境下运行的代码会更快
线程信息	将logging.logThreads设置为0
进程信息	将logging.logProcesses设置为0