【译】 Logging Cookbook

2016-12-06

译注：这篇文章译自 Python HOWTOs 中的一篇文章 Loggin Cookbook，作者是 Vinay Sajip。除了 Inserting a BOM into messages sent to a SysLogHandler 和 Speaking logging messages 两小部分个人觉得没有多大意义，其他部分都翻译了。在部分地方有进行了意译和删节。说实话，文章的内容不错，但文笔实在不咋地，不少地方理解起来都很费神。

本文包含了一些 logging 相关的使用方法（recipe）。这些方法在过去被发现很有用。

多模块中使用 logging

多次调用 logging.getLogger(‘someLogger’) 返回对同一个 logger 对象的引用。这种情况不仅出现在单一模块中，而且也会跨模块出现，只要该 logger 对象存在于同一个 Python 解析进程内。对同一模块的引用会出现这种情况；另外，应用程序可以在一个模块中定义和配置一个父 logger，在另一个模块中定义（但不配置）一个子 logger，这样，对所有子 logger 的调用都会向上传递到父 logger。下边是 main 模块：

import logging
import auxiliary_module

# create logger with 'spam_application'
logger = logging.getLogger('spam_application')
logger.setLevel(logging.DEBUG)
# create file handler which logs even debug messages
fh = logging.FileHandler('spam.log')
fh.setLevel(logging.DEBUG)
# create console handler with a higher log level
ch = logging.StreamHandler()
ch.setLevel(logging.ERROR)
# create formatter and add it to the handlers
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
fh.setFormatter(formatter)
ch.setFormatter(formatter)
# add the handlers to the logger
logger.addHandler(fh)
logger.addHandler(ch)

logger.info('creating an instance of auxiliary_module.Auxiliary')
a = auxiliary_module.Auxiliary()
logger.info('created an instance of auxiliary_module.Auxiliary')
logger.info('calling auxiliary_module.Auxiliary.do_something')
a.do_something()
logger.info('finished auxiliary_module.Auxiliary.do_something')
logger.info('calling auxiliary_module.some_function()')
auxiliary_module.some_function()
logger.info('done with auxiliary_module.some_function()')

下边是 auxiliary 模块：

import logging

# create logger
module_logger = logging.getLogger('spam_application.auxiliary')

class Auxiliary:
    def __init__(self):
        self.logger = logging.getLogger('spam_application.auxiliary.Auxiliary')
        self.logger.info('creating an instance of Auxiliary')

    def do_something(self):
        self.logger.info('doing something')
        a = 1 + 1
        self.logger.info('done doing something')

def some_function():
    module_logger.info('received a call to "some_function"')

输出如下所示：

2005-03-23 23:47:11,663 - spam_application - INFO -
   creating an instance of auxiliary_module.Auxiliary
2005-03-23 23:47:11,665 - spam_application.auxiliary.Auxiliary - INFO -
   creating an instance of Auxiliary
2005-03-23 23:47:11,665 - spam_application - INFO -
   created an instance of auxiliary_module.Auxiliary
2005-03-23 23:47:11,668 - spam_application - INFO -
   calling auxiliary_module.Auxiliary.do_something
2005-03-23 23:47:11,668 - spam_application.auxiliary.Auxiliary - INFO -
   doing something
2005-03-23 23:47:11,669 - spam_application.auxiliary.Auxiliary - INFO -
   done doing something
2005-03-23 23:47:11,670 - spam_application - INFO -
   finished auxiliary_module.Auxiliary.do_something
2005-03-23 23:47:11,671 - spam_application - INFO -
   calling auxiliary_module.some_function()
2005-03-23 23:47:11,672 - spam_application.auxiliary - INFO -
   received a call to 'some_function'
2005-03-23 23:47:11,673 - spam_application - INFO -
   done with auxiliary_module.some_function()

多线程日志

记录多线程日志很简单就能做到。下边的例子展示了从 main (initial) 和另一个线程中记录日志：

import logging
import threading
import time

def worker(arg):
    while not arg['stop']:
        logging.debug('Hi from myfunc')
        time.sleep(0.5)

def main():
    logging.basicConfig(level=logging.DEBUG, format='%(relativeCreated)6d %(threadName)s %(message)s')
    info = {'stop': False}
    thread = threading.Thread(target=worker, args=(info,))
    thread.start()
    while True:
        try:
            logging.debug('Hello from main')
            time.sleep(0.75)
        except KeyboardInterrupt:
            info['stop'] = True
            break
    thread.join()

if __name__ == '__main__':
    main()

当运行的时候，这个程序打印出类似如下的内容：

   0 Thread-1 Hi from myfunc
   3 MainThread Hello from main
 505 Thread-1 Hi from myfunc
 755 MainThread Hello from main
1007 Thread-1 Hi from myfunc
1507 MainThread Hello from main
1508 Thread-1 Hi from myfunc
2010 Thread-1 Hi from myfunc
2258 MainThread Hello from main
2512 Thread-1 Hi from myfunc
3009 MainThread Hello from main
3013 Thread-1 Hi from myfunc
3515 Thread-1 Hi from myfunc
3761 MainThread Hello from main
4017 Thread-1 Hi from myfunc
4513 MainThread Hello from main
4518 Thread-1 Hi from myfunc

就如我们期望的，日志交错输出（译注：线程执行顺序不定）。当然，对更多的线程，这种记录日志的方法也是可行的。

多 handler 和多 formatter

Logger 是普通 Python 对象。（它的）方法 addHandler 对能够添加的 handler 数量没有上下限限制。有时，将所有级别日志记录到文本文件而同时将错误以上级别的日志输出到控制台，对应用程序来说很有效。要达到这个目的，只要简单配置合适的 handler 即可。应用程序中的日志调用代码将可以保持不变。下边例子来自对前文中基于模块配置的日志例子的细微修改：

import logging

logger = logging.getLogger('simple_example')
logger.setLevel(logging.DEBUG)
# create file handler which logs even debug messages
fh = logging.FileHandler('spam.log')
fh.setLevel(logging.DEBUG)
# create console handler with a higher log level
ch = logging.StreamHandler()
ch.setLevel(logging.ERROR)
# create formatter and add it to the handlers
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
ch.setFormatter(formatter)
fh.setFormatter(formatter)
# add the handlers to logger
logger.addHandler(ch)
logger.addHandler(fh)

# 'application' code
logger.debug('debug message')
logger.info('info message')
logger.warn('warn message')
logger.error('error message')
logger.critical('critical message')

需要注意的是，应用程序并不关心多 handler 的情况（译注：也即单 hander 和多 handler 对应用程序来说是一样的），修改的只是新的 handler fh 的添加和配置。

这种能够创建高或低日志级别的 handler 的能力，对于编写和测试应用程序来说是非常有帮助的。使用 logger.debug 语句用于调试而不是用 print 语句。使用 print 语句，你后续需要删除这些语句或者注释掉它们；而使用 logger.debug 语句，这些语句可以原封不动一直存在于源代码中，且它们会一直保持休眠状态直到你需要用到它们，在那时，你只需要修改 logger 和 handler 的日志级别。

输出日志到多个地方

假定你想要在不同环境中，记录到控制台和文件的日志有不同的消息格式；日志级别大于等于 DEBUG 的记录到文件，大于等于 INFO 级别的输出到控制台。我们同时也假定，记录到文件的日志需要包含时间戳，而输出到控制台的不需要。下边代码展示了我们如何做到这些：

import logging

# set up logging to file - see previous section for more details
logging.basicConfig(level=logging.DEBUG,
                    format='%(asctime)s %(name)-12s %(levelname)-8s %(message)s',
                    datefmt='%m-%d %H:%M',
                    filename='/temp/myapp.log',
                    filemode='w')
# define a Handler which writes INFO messages or higher to the sys.stderr
console = logging.StreamHandler()
console.setLevel(logging.INFO)
# set a format which is simpler for console use
formatter = logging.Formatter('%(name)-12s: %(levelname)-8s %(message)s')
# tell the handler to use this format
console.setFormatter(formatter)
# add the handler to the root logger
logging.getLogger('').addHandler(console)

# Now, we can log to the root logger, or any other logger. First the root...
logging.info('Jackdaws love my big sphinx of quartz.')

# Now, define a couple of other loggers which might represent areas in your
# application:

logger1 = logging.getLogger('myapp.area1')
logger2 = logging.getLogger('myapp.area2')

logger1.debug('Quick zephyrs blow, vexing daft Jim.')
logger1.info('How quickly daft jumping zebras vex.')
logger2.warning('Jail zesty vixen who grabbed pay from quack.')
logger2.error('The five boxing wizards jump quickly.')

当你运行这个代码，在控制台你可以看到：

root        : INFO     Jackdaws love my big sphinx of quartz.
myapp.area1 : INFO     How quickly daft jumping zebras vex.
myapp.area2 : WARNING  Jail zesty vixen who grabbed pay from quack.
myapp.area2 : ERROR    The five boxing wizards jump quickly.

在文件中，你可以看到：

10-22 22:19 root         INFO     Jackdaws love my big sphinx of quartz.
10-22 22:19 myapp.area1  DEBUG    Quick zephyrs blow, vexing daft Jim.
10-22 22:19 myapp.area1  INFO     How quickly daft jumping zebras vex.
10-22 22:19 myapp.area2  WARNING  Jail zesty vixen who grabbed pay from quack.
10-22 22:19 myapp.area2  ERROR    The five boxing wizards jump quickly.

就如你所看到的，只有 DEBUG 级别的日志出现在文件中，其余的日志则被同时记录到文件和控制台。

这个例子使用了控制台和文件 handler，但是你可以使用任意数量和任何组合的 handler。

服务器配置样例

下例展示了一个服务器配置样例：

import logging
import logging.config
import time
import os

# read initial config file
logging.config.fileConfig('logging.conf')

# create and start listener on port 9999
t = logging.config.listen(9999)
t.start()

logger = logging.getLogger('simpleExample')

try:
    # loop through logging calls to see the difference
    # new configurations make, until Ctrl+C is pressed
    while True:
        logger.debug('debug message')
        logger.info('info message')
        logger.warn('warn message')
        logger.error('error message')
        logger.critical('critical message')
        time.sleep(5)
except KeyboardInterrupt:
    # cleanup
    logging.config.stopListening()
    t.join()

下边例子接受一个文件并把该文件发送到服务器：

#!/usr/bin/env python
import socket, sys, struct

with open(sys.argv[1], 'rb') as f:
    data_to_send = f.read()

HOST = 'localhost'
PORT = 9999
s = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
print('connecting...')
s.connect((HOST, PORT))
print('sending config...')
s.send(struct.pack('>L', len(data_to_send)))
s.send(data_to_send)
s.close()
print('complete')

跨网络发送和接收日志事件

假定你想跨网络发送日志事件，然后在接收端进行处理。一个简单的做法就是在发送端将一个 SocketHandler 实例添加到 root logger：

import logging, logging.handlers

rootLogger = logging.getLogger('')
rootLogger.setLevel(logging.DEBUG)
socketHandler = logging.handlers.SocketHandler('localhost',
                    logging.handlers.DEFAULT_TCP_LOGGING_PORT)
# don't bother with a formatter, since a socket handler sends the event as
# an unformatted pickle
rootLogger.addHandler(socketHandler)

# Now, we can log to the root logger, or any other logger. First the root...
logging.info('Jackdaws love my big sphinx of quartz.')

# Now, define a couple of other loggers which might represent areas in your
# application:

logger1 = logging.getLogger('myapp.area1')
logger2 = logging.getLogger('myapp.area2')

logger1.debug('Quick zephyrs blow, vexing daft Jim.')
logger1.info('How quickly daft jumping zebras vex.')
logger2.warning('Jail zesty vixen who grabbed pay from quack.')
logger2.error('The five boxing wizards jump quickly.')

在接收端，你可以使用 SocketServer 模块来搭建一个接收器。下边是一个简单的可工作的例子：

import pickle
import logging
import logging.handlers
import SocketServer
import struct


class LogRecordStreamHandler(SocketServer.StreamRequestHandler):
    """Handler for a streaming logging request.

    This basically logs the record using whatever logging policy is
    configured locally.
    """

    def handle(self):
        """
        Handle multiple requests - each expected to be a 4-byte length,
        followed by the LogRecord in pickle format. Logs the record
        according to whatever policy is configured locally.
        """
        while True:
            chunk = self.connection.recv(4)
            if len(chunk) < 4:
                break
            slen = struct.unpack('>L', chunk)[0]
            chunk = self.connection.recv(slen)
            while len(chunk) < slen:
                chunk = chunk + self.connection.recv(slen - len(chunk))
            obj = self.unPickle(chunk)
            record = logging.makeLogRecord(obj)
            self.handleLogRecord(record)

    def unPickle(self, data):
        return pickle.loads(data)

    def handleLogRecord(self, record):
        # if a name is specified, we use the named logger rather than the one
        # implied by the record.
        if self.server.logname is not None:
            name = self.server.logname
        else:
            name = record.name
        logger = logging.getLogger(name)
        # N.B. EVERY record gets logged. This is because Logger.handle
        # is normally called AFTER logger-level filtering. If you want
        # to do filtering, do it at the client end to save wasting
        # cycles and network bandwidth!
        logger.handle(record)

class LogRecordSocketReceiver(SocketServer.ThreadingTCPServer):
    """
    Simple TCP socket-based logging receiver suitable for testing.
    """

    allow_reuse_address = 1

    def __init__(self, host='localhost',
                 port=logging.handlers.DEFAULT_TCP_LOGGING_PORT,
                 handler=LogRecordStreamHandler):
        SocketServer.ThreadingTCPServer.__init__(self, (host, port), handler)
        self.abort = 0
        self.timeout = 1
        self.logname = None

    def serve_until_stopped(self):
        import select
        abort = 0
        while not abort:
            rd, wr, ex = select.select([self.socket.fileno()],
                                       [], [],
                                       self.timeout)
            if rd:
                self.handle_request()
            abort = self.abort

def main():
    logging.basicConfig(
        format='%(relativeCreated)5d %(name)-15s %(levelname)-8s %(message)s')
    tcpserver = LogRecordSocketReceiver()
    print('About to start TCP server...')
    tcpserver.serve_until_stopped()

if __name__ == '__main__':
    main()

首先运行服务端，再运行客户端。在客户端，控制台不会有任何输出；在服务端，你应该能够看到如下输出：

About to start TCP server...
   59 root            INFO     Jackdaws love my big sphinx of quartz.
   59 myapp.area1     DEBUG    Quick zephyrs blow, vexing daft Jim.
   69 myapp.area1     INFO     How quickly daft jumping zebras vex.
   69 myapp.area2     WARNING  Jail zesty vixen who grabbed pay from quack.
   69 myapp.area2     ERROR    The five boxing wizards jump quickly.

需要注意的是，在某些场景，使用 pickle 存在一些安全问题。如果这些问题影响到你，你可以使用通过覆写 makePickle() 方法来使用替补序列化方案，同时调整以上代码以适应你的替补方案。

添加上下文信息到你的日志输出中

有时，你想要日志输出中除了包含传递给日志调用的参数，还要包含上下文信息。例如，在一个网络应用程序中，记录客户端具体信息的日志是很有必要的（如客户端的用户名或 IP 地址）。尽管你可以使用额外的参数达到这个目的，但用这种方法来传递信息总不是方便的。虽然通过在每个连接创建 Logger 实例的方法很诱人，但这种方法并不是一个好主意，因为这些实例不会被垃圾管理器回收。在实际操作中，这并不会是个问题，但当 Logger 实例的数量依赖于你想要使用的日志的粒度水平，且它们的数量不受控制时，对它们的管理将很困难。

使用 LoggerAdapter 传递上下文信息

一个跟随日志事件传递上下文信息的简单方法就是使用 LoggerAdapter 类。这个类被设计的看起来像 Logger，所以你可以调用 debug()、info()、warning()、error()、exception()、critical() 和 log() 方法。这些方法跟 Logger 类中相对应的方法有相同功能（signature），所以我们可以交换地使用这两个类的实例。

当你创建了一个 LoggerAdapter 的实例，你将一个 Logger 实例和一个包含上下文信息的字典型对象传递给它。当你调用 LoggerAdapter 实例中的一个方法时，它将这个调用委托给初始化于 LoggerAdapter 构造函数的 Logger 实例，并组织将上下文信息传递给这个委托调用。下边是 LoggerAdapter 的代码片段：

def debug(self, msg, *args, **kwargs):
    """
    Delegate a debug call to the underlying logger, after adding
    contextual information from this adapter instance.
    """
    msg, kwargs = self.process(msg, kwargs)
    self.logger.debug(msg, *args, **kwargs)

LoggerAdapter 中的 process() 方法将上下文信息添加到日志输出中。它接收日志调用传递过来的消息参数和关键词参数，并且返回修改过后的对应参数，以被 Logger 实例使用。这个方法的默认实现中，不处理消息参数，但在关键词参数中插入一个名为 “extra” 的 key。当然了，如果这个关键词参数已经包含了 “extra” key，那它将会被覆写。

使用 “extra” 的优势在于字典型对象会被合并到 LogRecord 实例的 __dict__参数，这样允许知道字典型对象的 key 的 Formatter 实例使用自定义的字符串。如果你需要一个不一样的方法，比如，你想要将上下文信息依附到消息的前边或者后边，你只需要创建一个 LoggerAdapter 的子类并重写 process() 函数，以满足你所需。下边就是一个简单的例子：

class CustomAdapter(logging.LoggerAdapter):
    """
    This example adapter expects the passed in dict-like object to have a
    'connid' key, whose value in brackets is prepended to the log message.
    """
    def process(self, msg, kwargs):
        return '[%s] %s' % (self.extra['connid'], msg), kwargs

你可以这样使用这个类：

1 2	logger = logging.getLogger(__name__) adapter = CustomAdapter(logger, {'connid': some_conn_id})

这样，adapter 记录的日志都会将 some_conn_id 依附到消息的前边。

使用对象而不是字典来传递上下文信息

你不需要传递一个真正的字典给 LoggerAdapter ——你可以传递一个实现了 __getitem__和 __iter__ 的类的实例（看起来可以像一个字典一样记录日志）给它。这种方法将会很有用，如果你要动态地生成数值（而字典的值是固定的）。

使用 Filter 来传递上下文信息

你也可以通过一个自定义的 Filter 来添加上下文信息到日志输出。Filter 实例可以修改传递给它们的 LogRecords，包括添加额外的可以使用适当格式输出的属性或自定义的 Formatter。

例如，在一个 Web 应用中，处理过后的请求可以存储在 threadlocal (threading.local) 变量，然后通过 Filter 访问，来添加请求的信息，即 IP 地址、远程用户名到 LogRecord，使用上边 LoggerAdapter 例子的属性名 “ip”、“user”。在那种情况下，同一格式化字符串可以用于获得跟上例类似的输出。下边是样例代码：

import logging
from random import choice

class ContextFilter(logging.Filter):
    """
    This is a filter which injects contextual information into the log.

    Rather than use actual contextual information, we just use random
    data in this demo.
    """

    USERS = ['jim', 'fred', 'sheila']
    IPS = ['123.231.231.123', '127.0.0.1', '192.168.0.1']

    def filter(self, record):

        record.ip = choice(ContextFilter.IPS)
        record.user = choice(ContextFilter.USERS)
        return True

if __name__ == '__main__':
    levels = (logging.DEBUG, logging.INFO, logging.WARNING, logging.ERROR, logging.CRITICAL)
    logging.basicConfig(level=logging.DEBUG,
                        format='%(asctime)-15s %(name)-5s %(levelname)-8s IP: %(ip)-15s User: %(user)-8s %(message)s')
    a1 = logging.getLogger('a.b.c')
    a2 = logging.getLogger('d.e.f')

    f = ContextFilter()
    a1.addFilter(f)
    a2.addFilter(f)
    a1.debug('A debug message')
    a1.info('An info message with %s', 'some parameters')
    for x in range(10):
        lvl = choice(levels)
        lvlname = logging.getLevelName(lvl)
        a2.log(lvl, 'A message at %s level with %d %s', lvlname, 2, 'parameters')

运行，可以得到如下结果：

2010-09-06 22:38:15,292 a.b.c DEBUG    IP: 123.231.231.123 User: fred     A debug message
2010-09-06 22:38:15,300 a.b.c INFO     IP: 192.168.0.1     User: sheila   An info message with some parameters
2010-09-06 22:38:15,300 d.e.f CRITICAL IP: 127.0.0.1       User: sheila   A message at CRITICAL level with 2 parameters
2010-09-06 22:38:15,300 d.e.f ERROR    IP: 127.0.0.1       User: jim      A message at ERROR level with 2 parameters
2010-09-06 22:38:15,300 d.e.f DEBUG    IP: 127.0.0.1       User: sheila   A message at DEBUG level with 2 parameters
2010-09-06 22:38:15,300 d.e.f ERROR    IP: 123.231.231.123 User: fred     A message at ERROR level with 2 parameters
2010-09-06 22:38:15,300 d.e.f CRITICAL IP: 192.168.0.1     User: jim      A message at CRITICAL level with 2 parameters
2010-09-06 22:38:15,300 d.e.f CRITICAL IP: 127.0.0.1       User: sheila   A message at CRITICAL level with 2 parameters
2010-09-06 22:38:15,300 d.e.f DEBUG    IP: 192.168.0.1     User: jim      A message at DEBUG level with 2 parameters
2010-09-06 22:38:15,301 d.e.f ERROR    IP: 127.0.0.1       User: sheila   A message at ERROR level with 2 parameters
2010-09-06 22:38:15,301 d.e.f DEBUG    IP: 123.231.231.123 User: fred     A message at DEBUG level with 2 parameters
2010-09-06 22:38:15,301 d.e.f INFO     IP: 123.231.231.123 User: fred     A message at INFO level with 2 parameters

多进程输出日志到单一文件

尽管 logging 模块是线程安全的，而且单一进程的多线程输出日志到单一文件也是支持的，但多进程输出日志到单一文件却是不支持的，因为在 Python 中，多进程序列化访问单一文件没有标准的方法。如果你需要多进程输出日志到单一文件，其中一个方法就是让所有的进程将日志输出到 SocketHandler，然后用一个单独的服务器进程从 socket 读取数据并将日志写到文件中（如果你喜欢，你也可以从已存在的进程中派发一个线程来做这件事）。这一节详细描述了这种方法和包含了一个可以工作的 socket 接收器，这个接收器可以作为你开发自己应用程序的开始。

如果你正在使用一个较新的包括 multiprocessing 模块的 Python 版本，你可以写一个使用这个模块中 Lock 类的 handler，以序列化多进程对单一文件的访问。已知的 FileHandler 和子类目前都没有利用 multiprocessing 这个模块，尽管未来它们可能会实现。需要注意的是，multiprocessing 模块并不是在所有平台都实现了可以工作的锁（见 https://bugs.python.org/issue3770 ）。

使用文件周转（File Rotation）

有时你想要日志文件只增长到指定的大小，然后就新建新的日志文件并将日志写到该文件。你可能想只保留指定数量的日志文件，并且当这些文件都已经创建，轮转写入日志到这些文件，以保证文件的数量和文件大小在限定范围之内。为了这个，logging 模块提供了 RotatingFileHandler：

import glob
import logging
import logging.handlers

LOG_FILENAME = 'logging_rotatingfile_example.out'

# Set up a specific logger with our desired output level
my_logger = logging.getLogger('MyLogger')
my_logger.setLevel(logging.DEBUG)

# Add the log message handler to the logger
handler = logging.handlers.RotatingFileHandler(
              LOG_FILENAME, maxBytes=20, backupCount=5)

my_logger.addHandler(handler)

# Log some messages
for i in range(20):
    my_logger.debug('i = %d' % i)

# See what files are created
logfiles = glob.glob('%s*' % LOG_FILENAME)

for filename in logfiles:
    print(filename)

执行这个代码段会生成 6 个独立的文件，每一个文件都包含了部分日志：

logging_rotatingfile_example.out
logging_rotatingfile_example.out.1
logging_rotatingfile_example.out.2
logging_rotatingfile_example.out.3
logging_rotatingfile_example.out.4
logging_rotatingfile_example.out.5

最新的当前文件一直是 logging_rotatingfile_example.out ，并且每当该文件达到大小限制时，它就会被重命名添加后缀 .1。其他的日志文件也会被重命名递增后缀（如 .1 变成 .2），后缀为 .6 的文件则会被删除。

一个基于字典配置的案例

下边是一个日志字典配置的例子——从 Django 项目文档获取得到。这个字典会被传递给 dictConfig() 来使得配置生效：

LOGGING = {
    'version': 1,
    'disable_existing_loggers': True,
    'formatters': {
        'verbose': {
            'format': '%(levelname)s %(asctime)s %(module)s %(process)d %(thread)d %(message)s'
        },
        'simple': {
            'format': '%(levelname)s %(message)s'
        },
    },
    'filters': {
        'special': {
            '()': 'project.logging.SpecialFilter',
            'foo': 'bar',
        }
    },
    'handlers': {
        'null': {
            'level':'DEBUG',
            'class':'django.utils.log.NullHandler',
        },
        'console':{
            'level':'DEBUG',
            'class':'logging.StreamHandler',
            'formatter': 'simple'
        },
        'mail_admins': {
            'level': 'ERROR',
            'class': 'django.utils.log.AdminEmailHandler',
            'filters': ['special']
        }
    },
    'loggers': {
        'django': {
            'handlers':['null'],
            'propagate': True,
            'level':'INFO',
        },
        'django.request': {
            'handlers': ['mail_admins'],
            'level': 'ERROR',
            'propagate': False,
        },
        'myproject.custom': {
            'handlers': ['console', 'mail_admins'],
            'level': 'INFO',
            'filters': ['special']
        }
    }
}

关于这个配置更多信息，你可以参考 Django 文档的相关章节。

实现结构化日志

大多数的日志消息都设计为方便人类阅读，因此并不方便及其处理，但还是存在一些场景，你想让日志消息结构化输出，以便程序能够处理（不用复杂的正则表达式来过滤日志消息）。使用 logging 模块很容易就可以做到这点。要做到这点有很多种方法，但以下是一个简单的使用 JSON 来序列化事件以便于机器解析的方法：

import json
import logging

class StructuredMessage(object):
    def __init__(self, message, **kwargs):
        self.message = message
        self.kwargs = kwargs

    def __str__(self):
        return '%s >>> %s' % (self.message, json.dumps(self.kwargs))

_ = StructuredMessage   # optional, to improve readability

logging.basicConfig(level=logging.INFO, format='%(message)s')
logging.info(_('message 1', foo='bar', bar='baz', num=123, fnum=123.456))

运行以上程序，输出：

1	message 1 >>> {"fnum": 123.456, "num": 123, "bar": "baz", "foo": "bar"}

需要注意的是，元素输出顺序在不同 Python 版本中可能不一样。

如果你需要更加专业的处理，你可以使用自定义的 JSON 编码器。下边就是一个完整的例子：

from __future__ import unicode_literals

import json
import logging

# This next bit is to ensure the script runs unchanged on 2.x and 3.x
try:
    unicode
except NameError:
    unicode = str

class Encoder(json.JSONEncoder):
    def default(self, o):
        if isinstance(o, set):
            return tuple(o)
        elif isinstance(o, unicode):
            return o.encode('unicode_escape').decode('ascii')
        return super(Encoder, self).default(o)

class StructuredMessage(object):
    def __init__(self, message, **kwargs):
        self.message = message
        self.kwargs = kwargs

    def __str__(self):
        s = Encoder().encode(self.kwargs)
        return '%s >>> %s' % (self.message, s)

_ = StructuredMessage   # optional, to improve readability

def main():
    logging.basicConfig(level=logging.INFO, format='%(message)s')
    logging.info(_('message 1', set_value=set([1, 2, 3]), snowman='\u2603'))

if __name__ == '__main__':
    main()

运行以上代码，输出：

1	message 1 >>> {"snowman": "\u2603", "set_value": [1, 2, 3]}

需要注意的是，元素输出顺序在不同 Python 版本中可能不一样。

用 dictConfig() 自定义 handler

有些时候，你可能想要以特定方式自定义 handler。如果你使用 dictConfig()，你可能就可以做到这一点而不用新建子类。作为一个例子，假定你想要设定日志文件的所有者。在 POSIX 兼容的机器，用 os.chown() 就可以容易做到，但标准库 stdlib 中的文件 handler 没有提供內建支持。你可以采用（类似）如下简单函数来自定义创建 handler：

def owned_file_handler(filename, mode='a', encoding=None, owner=None):
    if owner:
        import os, pwd, grp
        # convert user and group names to uid and gid
        uid = pwd.getpwnam(owner[0]).pw_uid
        gid = grp.getgrnam(owner[1]).gr_gid
        owner = (uid, gid)
        if not os.path.exists(filename):
            open(filename, 'a').close()
        os.chown(filename, *owner)
    return logging.FileHandler(filename, mode, encoding)

接下来你可以在日志配置文件中指定将会创建的 handler：

LOGGING = {
    'version': 1,
    'disable_existing_loggers': False,
    'formatters': {
        'default': {
            'format': '%(asctime)s %(levelname)s %(name)s %(message)s'
        },
    },
    'handlers': {
        'file':{
            # The values below are popped from this dictionary and
            # used to create the handler, set the handler's level and
            # its formatter.
            '()': owned_file_handler,
            'level':'DEBUG',
            'formatter': 'default',
            # The values below are passed to the handler creator callable
            # as keyword arguments.
            'owner': ['pulse', 'pulse'],
            'filename': 'chowntest.log',
            'mode': 'w',
            'encoding': 'utf-8',
        },
    },
    'root': {
        'handlers': ['file'],
        'level': 'DEBUG',
    },
}

在这个例子中，为了展示，我设定了文件的所有者和所有组为 pulse 用户 pulse 组。把他们组合在一起为一个可运行的脚本 chowntest.py：

import logging, logging.config, os, shutil

def owned_file_handler(filename, mode='a', encoding=None, owner=None):
    if owner:
        if not os.path.exists(filename):
            open(filename, 'a').close()
        shutil.chown(filename, *owner)
    return logging.FileHandler(filename, mode, encoding)

LOGGING = {
    'version': 1,
    'disable_existing_loggers': False,
    'formatters': {
        'default': {
            'format': '%(asctime)s %(levelname)s %(name)s %(message)s'
        },
    },
    'handlers': {
        'file':{
            # The values below are popped from this dictionary and
            # used to create the handler, set the handler's level and
            # its formatter.
            '()': owned_file_handler,
            'level':'DEBUG',
            'formatter': 'default',
            # The values below are passed to the handler creator callable
            # as keyword arguments.
            'owner': ['pulse', 'pulse'],
            'filename': 'chowntest.log',
            'mode': 'w',
            'encoding': 'utf-8',
        },
    },
    'root': {
        'handlers': ['file'],
        'level': 'DEBUG',
    },
}

logging.config.dictConfig(LOGGING)
logger = logging.getLogger('mylogger')
logger.debug('A debug message')

要运行这个程序，你可能需要 root 权限：

$ sudo python3.3 chowntest.py
$ cat chowntest.log
2013-11-05 09:34:51,128 DEBUG mylogger A debug message
$ ls -l chowntest.log
-rw-r--r-- 1 pulse pulse 55 2013-11-05 09:34 chowntest.log

需要注意的是，这个例子使用的 Python 版本是 3.3，这也是 shutil.chown() 会出现的原因。这种方法在支持 dictConfig() 的 Python 版本中应该都可以工作——也即，Python 2.7、3.2 以及后续版本。3.3 之前的 Python 版本，你需要实现实际的所有者变更，如 os.chown()。

实际上，这个 handler 创建函数可能在你项目中的某个公共模块中。在这种情况下，不使用如下配置：

1	'()': owned_file_handler,

而是可以使用如：

1	'()': 'ext://project.util.owned_file_handler',

其中，project.util 可以替换为函数所在的包名。在上边可以运行的代码中，使用 ‘ext://main.owned_file_handler’ 应该可以工作。这里，实际的可调用函数是 dictConfig() 从 ext:// 格式中解析得来。

这个例子同样也之处了你如何使用相同方式实现文件的其他类型的变化——如，设置 POSIX 权限位——使用 os.chmod()。

当然，这种方式也可以拓展到其他类型的 handler 而不是 FileHandler——例如，周转文件 handler、或者其他类型 handler。

用 dictConfig() 自定义 filter

你可以用 dictConfig() 来配置 filter，尽管咋看之下不知道怎么做（所以才有这个教程）。因为 Filter 是标准库中仅有的 filter 类，所以它不大可能迎合太多需求（作为一个基类）。通常你需要定义自己的 Filter 子类并覆写 filter() 函数。要做到这一点，在配置字典中为 filter 定义一个 “()” key，指定用于创建 filter 的回调函数（用一个类来实现是最明显的，但你可以提供任意可返回 Filter 实例的回调函数）。下边是一个完整的例子：

import logging
import logging.config
import sys

class MyFilter(logging.Filter):
    def __init__(self, param=None):
        self.param = param

    def filter(self, record):
        if self.param is None:
            allow = True
        else:
            allow = self.param not in record.msg
        if allow:
            record.msg = 'changed: ' + record.msg
        return allow

LOGGING = {
    'version': 1,
    'filters': {
        'myfilter': {
            '()': MyFilter,
            'param': 'noshow',
        }
    },
    'handlers': {
        'console': {
            'class': 'logging.StreamHandler',
            'filters': ['myfilter']
        }
    },
    'root': {
        'level': 'DEBUG',
        'handlers': ['console']
    },
}

if __name__ == '__main__':
    logging.config.dictConfig(LOGGING)
    logging.debug('hello')
    logging.debug('hello - noshow')

这个例子展示了你如何通过传递关键字参数形式的配置文件到回调函数，来创建一个 Filter 实例。运行这个例子，输出如下：

1	changed: hello

证明了 filter 如预期般运行。

另外还有一些需要注意的地方：

如果你不能够在配置中直接引用回调函数（例如，回调函数在不同的模块，所以你不能够直接把它导入到配置中），你可以使用在访问外部对象中描述的 ext://… 形式。例如，你可以在上述例子中使用 ‘ext://main.MyFilter’ 而不是 MyFilter。
这种方法除了可用于 filter，也可以用于自定义 handler 和 formatter。请查看用户自定义对象获取 logging 如何支持在配置中使用自定义对象的更多信息，和该文中的用 dictConfig() 自定义 handler 部分。

自定义异常输出格式

有时你可以想自定义异常输出格式——假定你想每一个日志事件输出一行。你可以自定义 formatter 类，就像下例所做的：

import logging

class OneLineExceptionFormatter(logging.Formatter):
    def formatException(self, exc_info):
        """
        Format an exception so that it prints on a single line.
        """
        result = super(OneLineExceptionFormatter, self).formatException(exc_info)
        return repr(result) # or format into one line however you want to

    def format(self, record):
        s = super(OneLineExceptionFormatter, self).format(record)
        if record.exc_text:
            s = s.replace('\n', '') + '|'
        return s

def configure_logging():
    fh = logging.FileHandler('output.txt', 'w')
    f = OneLineExceptionFormatter('%(asctime)s|%(levelname)s|%(message)s|',
                                  '%d/%m/%Y %H:%M:%S')
    fh.setFormatter(f)
    root = logging.getLogger()
    root.setLevel(logging.DEBUG)
    root.addHandler(fh)

def main():
    configure_logging()
    logging.info('Sample message')
    try:
        x = 1 / 0
    except ZeroDivisionError as e:
        logging.exception('ZeroDivisionError: %s', e)

if __name__ == '__main__':
    main()

运行代码，会生成一个只有两行的文件：

1
2

28/01/2015 07:21:23|INFO|Sample message|
28/01/2015 07:21:23|ERROR|ZeroDivisionError: integer division or modulo by zero|'Traceback (most recent call last):\n  File "logtest7.py", line 30, in main\n    x = 1 / 0\nZeroDivisionError: integer division or modulo by zero'|

尽管上例很简单，但它指出了如何根据你的需要来格式化异常输出。如果要求更加专业化，traceback 模块将有很大帮助。

缓存日志消息并有条件输出

在有些情况下，你可以想要把日志输出到一个临时地方，然后只在特定条件下输出它们。例如，你可能想要记录一个函数的调试日志，但如果该函数成功执行没有错误，你不想要把调试日志输出到日志文件中；如果函数执行发生错误，你想要所有的调试日志和错误一起输出。

这里有一个例子展示如何使用装饰器做到这一点。这个例子使用了 logging.handlers.MemoryHandler ——这个 handler 允许缓存日志，直到达到特定条件才输出日志（flush）——来将日志消息传递给另一个 handler （目的 handler）处理。默认情况下，当缓冲区满或者当日志事件的级别大于等于设定的临界值，MemoryHandler 会将日志输出。你可以使用这个例子构造一个更加专业化的 MemoryHandler 子类。

这个例子中有一个简单的函数 foo，轮询所有的日志级别，并输出它正在记录的日志级别到 sys.stderr，然后把那个级别的日志信息记录下来。你可以向它传递一个参数，当该参数为真，它会记录 ERROR 和 CRITICAL 级别的日志；否则，它只记录 DEBUG、INFO 和 WARNING 级别的日志。

这个例子用可以执行条件化日志记录的装饰器来装饰函数 foo。这个装饰器接受一个 logger 作为参数，并将一个 memory handler 依附到被装饰函数上。这个装饰器可以接受额外的参数目标 handler、日志输出是的日志级别，以及缓存的容量。这几个参数的默认值是写到 sys.stderr 的 StreamHandler、logging.ERROR 和 100。

下边是代码：

import logging
from logging.handlers import MemoryHandler
import sys

logger = logging.getLogger(__name__)
logger.addHandler(logging.NullHandler())

def log_if_errors(logger, target_handler=None, flush_level=None, capacity=None):
    if target_handler is None:
        target_handler = logging.StreamHandler()
    if flush_level is None:
        flush_level = logging.ERROR
    if capacity is None:
        capacity = 100
    handler = MemoryHandler(capacity, flushLevel=flush_level, target=target_handler)

    def decorator(fn):
        def wrapper(*args, **kwargs):
            logger.addHandler(handler)
            try:
                return fn(*args, **kwargs)
            except Exception:
                logger.exception('call failed')
                raise
            finally:
                super(MemoryHandler, handler).flush()
                logger.removeHandler(handler)
        return wrapper

    return decorator

def write_line(s):
    sys.stderr.write('%s\n' % s)

def foo(fail=False):
    write_line('about to log at DEBUG ...')
    logger.debug('Actually logged at DEBUG')
    write_line('about to log at INFO ...')
    logger.info('Actually logged at INFO')
    write_line('about to log at WARNING ...')
    logger.warning('Actually logged at WARNING')
    if fail:
        write_line('about to log at ERROR ...')
        logger.error('Actually logged at ERROR')
        write_line('about to log at CRITICAL ...')
        logger.critical('Actually logged at CRITICAL')
    return fail

decorated_foo = log_if_errors(logger)(foo)

if __name__ == '__main__':
    logger.setLevel(logging.DEBUG)
    write_line('Calling undecorated foo with False')
    assert not foo(False)
    write_line('Calling undecorated foo with True')
    assert foo(True)
    write_line('Calling decorated foo with False')
    assert not decorated_foo(False)
    write_line('Calling decorated foo with True')
    assert decorated_foo(True)

执行代码，输出如下：

Calling undecorated foo with False
about to log at DEBUG ...
about to log at INFO ...
about to log at WARNING ...
Calling undecorated foo with True
about to log at DEBUG ...
about to log at INFO ...
about to log at WARNING ...
about to log at ERROR ...
about to log at CRITICAL ...
Calling decorated foo with False
about to log at DEBUG ...
about to log at INFO ...
about to log at WARNING ...
Calling decorated foo with True
about to log at DEBUG ...
about to log at INFO ...
about to log at WARNING ...
about to log at ERROR ...
Actually logged at DEBUG
Actually logged at INFO
Actually logged at WARNING
Actually logged at ERROR
about to log at CRITICAL ...
Actually logged at CRITICAL

就如你所看到的，日志只在当级别大于等于 ERROR 时才会输出。但是，低于该级别的日志也会被记录下来。

你当然也可以使用传统的装饰器语法：

1
2
3

@log_if_errors(logger)
def foo(fail=False):
    ...

通过配置使用 UTC (GMT) 格式化时间

有时你可能想要用 UTC 来格式化时间，这可以通过使用类 UTCFormatter 来做到：

import logging
import time

class UTCFormatter(logging.Formatter):
    converter = time.gmtime

然后在你的代码中用 UTCFormatter 代替 Formatter。如果你想要通过配置来达到这点，你可以像下例一样使用 dictConfig() 函数：

import logging
import logging.config
import time

class UTCFormatter(logging.Formatter):
    converter = time.gmtime

LOGGING = {
    'version': 1,
    'disable_existing_loggers': False,
    'formatters': {
        'utc': {
            '()': UTCFormatter,
            'format': '%(asctime)s %(message)s',
        },
        'local': {
            'format': '%(asctime)s %(message)s',
        }
    },
    'handlers': {
        'console1': {
            'class': 'logging.StreamHandler',
            'formatter': 'utc',
        },
        'console2': {
            'class': 'logging.StreamHandler',
            'formatter': 'local',
        },
    },
    'root': {
        'handlers': ['console1', 'console2'],
   }
}

if __name__ == '__main__':
    logging.config.dictConfig(LOGGING)
    logging.warning('The local time is %s', time.asctime())

运行脚本，输出如下：

1 2	2015-10-17 12:53:29,501 The local time is Sat Oct 17 13:53:29 2015 2015-10-17 13:53:29,501 The local time is Sat Oct 17 13:53:29 2015

使用上下文管理器有选择性地记录日志

有些时候，临时地改变日志配置但在最后恢复原来的配置是很有用的。对于这点，采用上下文管理器是最显而易见的保存和恢复上下文方法。下边是一个简单的上下文管理器例子，它允许你改变日志级别和添加 handler：

import logging
import sys

class LoggingContext(object):
    def __init__(self, logger, level=None, handler=None, close=True):
        self.logger = logger
        self.level = level
        self.handler = handler
        self.close = close

    def __enter__(self):
        if self.level is not None:
            self.old_level = self.logger.level
            self.logger.setLevel(self.level)
        if self.handler:
            self.logger.addHandler(self.handler)

    def __exit__(self, et, ev, tb):
        if self.level is not None:
            self.logger.setLevel(self.old_level)
        if self.handler:
            self.logger.removeHandler(self.handler)
        if self.handler and self.close:
            self.handler.close()
        # implicit return of None => don't swallow exceptions

如果你指定了日志级别，那 logger 的日志级别就会在 with 代码块中被指定；如果指定了 handler，那该 handler 就会分别在 with 代码块的入口处（entry）和出口处（exit）被添加和移除。你也可以让这个管理器在 with 代码块的出口处关闭 handler——你可以做的更多如果你不需要这个 handler。

为了展示这个管理器怎么工作，我们把以下代码添加到以上代码中：

if __name__ == '__main__':
    logger = logging.getLogger('foo')
    logger.addHandler(logging.StreamHandler())
    logger.setLevel(logging.INFO)
    logger.info('1. This should appear just once on stderr.')
    logger.debug('2. This should not appear.')
    with LoggingContext(logger, level=logging.DEBUG):
        logger.debug('3. This should appear once on stderr.')
    logger.debug('4. This should not appear.')
    h = logging.StreamHandler(sys.stdout)
    with LoggingContext(logger, level=logging.DEBUG, handler=h, close=True):
        logger.debug('5. This should appear twice - once on stderr and once on stdout.')
    logger.info('6. This should appear just once on stderr.')
    logger.debug('7. This should not appear.')

刚开始我们设置 logger 的日志级别为 INFO，所以消息 #1 输出而 #2 不输出。然后我们在 with 代码块临时改变日志级别为 DEBUG，所以消息 #3 输出；with 代码块退出时，恢复日志级别为 INFO，所以消息 #4 不输出。接下来，在 with 代码块设置日志级别为 DEBUG，但同时添加一个输出到 sys.stdout 的 handler，所以，消息 #5 输出两次（一次通过 stderr，一次通过 stdout）； with 代码块退出后，设置恢复到初始的状态，所以消息 #6 输出（像消息 #1），但消息 #7 不输出（就像消息 #2）。

运行代码，输出如下：

$ python logctx.py
1. This should appear just once on stderr.
3. This should appear once on stderr.
5. This should appear twice - once on stderr and once on stdout.
5. This should appear twice - once on stderr and once on stdout.
6. This should appear just once on stderr.

如果我们把 stderr 指向 /dev/null，执行代码，我们将得到如下结果：

1 2	$ python logctx.py 2>/dev/null 5. This should appear twice - once on stderr and once on stdout.

同样，我们将 stdout 指向 /dev/null，可以得到：

$ python logctx.py >/dev/null
1. This should appear just once on stderr.
3. This should appear once on stderr.
5. This should appear twice - once on stderr and once on stdout.
6. This should appear just once on stderr.