日志Cookbook

Author:Vinay Sajip <vinay_sajip at red-dove dot com>

这个页面包含一些关于日志的“菜谱”,它们的实用性经过了时间考验。

在多个模块中使用日志

多次调用logging.getLogger('someLogger')会返回对同一个记录器对象的引用。不仅在同一个模块中如此,跨模块也是一样,只要它们在同一个Python解释器进程中。我保证它们都是指向同一个对象;此外,应用程序代码可以在一个模块中定义和配置父记录器,并在单独的模块中创建(但不配置)子记录器,并且所有对子进程的记录器调用将传递给父级。这是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()

多个处理器和格式化器

记录器是简单的Python对象。addHandler()方法并不限制可被添加的处理器的数目。应用可以将所有级别的消息记录到文本文件,同时将错误及其以上的消息输出到控制台,这通常是很有用的。要达到这个目的,只要合适地配置处理器。应用代码中对日志函数的调用可以保持不变。这里对前面的基于模块的配置的例子做了很小的改动:

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

我们可以看到,应用程序的代码并不关心是否存在多个日志处理器。程序代码的改动很小,我们只是添加并配置了一个叫做fh的日志处理器。

在编写和测试应用程序时,用更高或更低级别的过滤器来创建新的日志处理器是很有用的。记住不要使用print语句来除错,而应该用logger.debug:和print语句不同(你将来不得不删除或者注释掉它们),logger.debug语句可以保留在源代码中,因为你可以随时使它们失效。当需要时,唯一要变动的就是将记录器/处理器的级别修改为DEBUG。

记录到多个目的地

假定你需要根据不同的条件,以不同的消息格式将日志记录到控制台和文件。假定你希望将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消息只存在于文件中。其它的消息则在两个目的地中都有。

这个例子使用了控制台处理器和文件处理器,但是你可以使用任意处理器的组合。

配置服务器的例子

这是一个使用了日志配置服务器的模块的例子:

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实例:

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地址)。尽管可以通过使用extra参数来达到目的,但是这样并不方便。又或者倾向于给每个连接创建一个Logger实例,但这并不是个好主意,因为这些实例不能被垃圾回收。Logger实例的数量依赖于在应用中使用日志的粒度级别,这本身在实践中并不是个问题,难就难在如果Logger实例的数量本质上不受限制的话它将很难管理。

使用LoggerAdapter来处理上下文信息

除了日志事件信息,还在输出中包含上下文信息,一个简单的方法就是使用LoggerAdapter类。这个类设计得就像Logger一样,所以可以呼叫debug()info()warning()error()exception()critical()log()这些方法有着与它们在Logger中的对等物相同的签名,所以可以交换地使用这两个类型的实例。

当你创建LoggerAdapter实例时,你传递一个Logger实例和一个包含上下文信息的类字典对象。当调用LoggerAdapter实例的日志方法时,它将调用委托给底层的Logger实例(构造LoggerAdapter时传进来的参数),在委托的过程中安排传递上下文信息。这是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)

上下文信息通过LoggerAdapterprocess()方法被加入到日志输出。日志调用时的消息和关键字参数被传递给process方法,该方法传回(可能)修改过的版本,然后用以调用底层的记录器。该方法的默认实现不修改消息,然后给关键字参数添加一个‘extra’的键,对应的值为构造LoggerAdapter时传入的类字典对象。当然,如果调用方法时已经传入了个‘extra’关键字参数,则它会被默默地覆盖掉。

使用'extra'的好处就是类字典对象的值被合并到LogRecord实例的__dict__中,这样就可以定制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

可以这样使用:

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

用适配器记录的任何事件在其日志消息之前都会添加some_conn_id的值。

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

不必给LoggerAdapter传递一个真正的字典,你可以传递一个类实例,只要该类实现了__getitem____iter__,它看起来像一个需要被记日志的字典。如果需要动态生成值的时候这就很有用(与此对比,字典的值是个常量)。

使用过滤器来处理上下文信息

也可以通过使用用户定义的Filter来给日志输出添加上下文信息。Filter实例可以修改传递给它们的LogRecords,包括添加额外的属性,这些属性可以用合适的格式化字符串来输出,必要时可以使用自定义的Formatter

例如,有一个web应用,被处理的请求(或者至少是感兴趣的部分)可以存储于线程本地(threading.local)变量中,然后从Filter来访问它并向LogRecord添加请求中的一些信息,比如远端IP地址和远端用户名,像上述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,然后由一个单独的进程来实现一个套接字服务器,它从套接字中读取并记录日志到文件。(如果愿意,也可以让某个已存的进程的一个线程专门来做此事。)这一章详细的描述了这个方法并包括了一个可以工作的套接字接收器,可以在你的应用中使用它作为起点。

如果你正在使用最新的包括multiprocessing模块的Python,你可以自定义处理器,使用模块中的Lock类来序列化多进程中对文件的访问。当前的FileHandler及其子类并没有使用multiprocessing,但是在将来是有可能使用的。注意当前multiprocessing模块没有在所有的平台上都提供可以工作的锁定机制(参见http://bugs.python.org/issue3770)。

使用文件循环

有时候你希望日志文件增长到一个特定大小,然后打开一个新的文件并在其中记录日志。你也希望保持一定数量的日志文件,当文件数量达到上限时循环文件,这样文件的数量及其文件的大小都不会太大。对于这种使用场景,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(.1变成.2),.6文件就被删掉。

很明显这个例子作为极端将日志长度设得很短。你应该将maxBytes设为一个合适的值。

基于字典配置的例子

下面是一个日志配置字典的例子,它来自于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文档的相关章节

在发给SysLogHandler的消息中插入BOM

RFC 5424要求发给syslog服务进程的Unicode消息为有如下结构的一组字节:一个可选的纯ASCII部分,然后是一个UTF-8的BOM(字节顺序标记),然后是UTF-8编码的Unicode。(参见该规范的相关章节。)

在Python 2.6和2.7中,向消息中添加BOM的代码被加入到SysLogHandler,不幸的是,它的实现并不正确,BOM出现在消息的开头,它之前不能有任何纯ASCII的部分。

由于行为被破坏,错误插入BOM的代码被从Python 2.7.4及其以后中移除。尽管如此,它没有被取代,如果希望产生RFC 5424兼容的消息——可选的纯ASCII部分,BOM,然后是Unicode,你可以这样做:

  1. SysLogHandler实例附上一个Formatter实例,格式化字符串类似于:

    u'ASCII section\ufeffUnicode section'
    

    Unicode码点u'\ufeff'如果以UTF-8来编码的话,将会编码成UTF-8 BOM,即字节串'\xef\xbb\xbf'

  2. 将'ASCII section'替换成任何你希望的占位符,只要保证替换后数据总是ASCII即可(UTF-8编码后它们不会改变)。

  3. 将'Unicode section'替换为任何你希望的占位符;如果替换后的数据包含了ASCII以外的字符,没关系,它们将会编码为UTF-8。

如果格式化的消息为Unicode,它们会被SysLogHandler编码为UTF-8。如果遵从上述规则,就可以产生RFC 5424兼容的消息。否则的话,logging不会抱怨,但是你的消息不是RFC 5424兼容的,syslog服务进程会抱怨。

实现结构化的日志

尽管大多数日志消息都是由人来读的,因此不一定能由机器来解析,但是在某些场景下你希望输出消息具有结构化的格式,能由程序来解析的(不需要复杂的正则表达式)。使用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))

运行上述脚本,打印出:

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()

运行上述脚本,打印出:

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

请注意根据所用的Python的版本不同,项目的顺序有可能会不同。

通过dictConfig()自定义处理器

有时候你希望以特殊的方式自定义日志处理器,如果使用dictConfig()的话可以不用继承处理器。例如,假定你希望设置日志文件的所有权。在POSIX中,使用shutil.chown()可以很容易做到这点,但是标准库中的文件处理器并不提供内置的支持。可以自定义处理器的创建过程,如下使用一个简单的函数:

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)

可以在传递给dictConfig()的日志配置中指明通过调用该函数来创建日志处理器:

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被用作文件的用户和组,以做演示之用。把所有的组装起来,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版本之前,你需要用os.chown()实现用于修改所有权的代码。

实践中,处理器创建函数可能处于项目中某个功能模块。作为如下配置的替换:

'()': owned_file_handler,

你可以使用,例如:

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

project.util可以替换为函数所在的真正的包名。在上述脚本中,使用'ext://__main__.owned_file_handler'也可以工作。这里,真正的可调用对象由dictConfig()ext://规格中解析出来。

参照此例子可以实现其它类型的文件更改,比如用os.chmod()设定特定的POSIX权限位。

当然此方法可以用于FileHandler以外的处理器类型,例如循环文件处理器,甚至一个完全不一样的处理器类型。

通过dictConfig()配置过滤器

可以使用dictConfig()配置过滤器,乍看可能不那么明显(所以有这个处方)。既然Filter是标准库中唯一的过滤器类,不太见得它能满足许多需求(它以基类的方式存在),典型地你继承Filter类并重写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')

这个例子显示了如何以关键字参数的形式,将配置数据传递给可调用对象,以构造实例。运行脚本将打印:

changed: hello

显示过滤器如同配置的那样工作。

额外要注意的两点:

  • 如果无法在配置中直接引用可调用对象(例如它在不同的模块,无法在配置字典所在的地方直接导入它),可以使用ext://...这样的形式,详见访问外部对象例如,在上例中可以使用'ext://__main__.MyFilter'以替换MyFilter
  • 除了过滤器,该技术也可用于配置自定义的处理器和格式化器。参见用户定义的对象以了解更多关于logging如何在配置中支持使用用户定义对象的信息,参见上述在dictConfig()中自定义处理器处方。