在日志中包含上下文信息及python logging详解

Posted 2020-11-19 xybaby

 

　　之前写过一篇文章日志的艺术（The art of logging），提到了输出日志的时候记录上下文信息的重要性，我认为上下文信息包括：

• when：log事件发生的时间
• where：log事件发生在哪个模块（文件、函数）
• how important：log 事件的紧急程度
• who：事件产生者的唯一标识
• what：具体的事件内容，以及其他所必须的上下文信息

　　其中，when、where、how important都很容易通过logging框架自动包含，但是who（事件生产者的唯一标识）就不能框架自动填充了。比如在服务器端，同时有大量的用户，如果日志缺乏用户唯一标识，如（User can not login），那么可以说这样的日志是毫无意义的。特别是当线上出问题的时候，而且是偶发的问题的时候，日志往往是查找问题的唯一途径，如果这个时候日志信息不充分，那就很让人抓狂了。

　　虽然在团队中强调过很多次，但是很多同事还是会输出毫无意义的log，也曾试过静态代码检查或者运行时分析，不过都不太优雅，于是希望能够自动添加一些重要的上下文信息，比如用户唯一标识。

　　虽然每天都在打log，但事实上我以前也没有深度了解过python logging模块，于是借着这个机会，仔细看了一下logging文档与源码。

　　这里补充一句，虽然网上有很多文章介绍python logging模块，但还是建议直接看官方资料，顺序如下：tutorial、api document、cookbook、源码

　　本文地址：https://www.cnblogs.com/xybaby/p/9176140.html

初识python logging

　　logging模块是python官方提供的、标准的日志模块。看代码的话是借鉴了许多log4j中的概念和思想。

　　logging模块包括以下几大组件：

• Loggers expose the interface that application code directly uses.
• Handlers send the log records (created by loggers) to the appropriate destination.
• Filters provide a finer grained facility for determining which log records to output.
• Formatters specify the layout of log records in the final output.

　　下面结合一个更完整的例子来逐个介绍。example1.py

 1 import logging
 2 class ContextFilter(logging.Filter):
 3     def filter(self, record):
 4         record.userid = ‘123‘
 5         return True
 6 
 7 
 8 if __name__ == ‘__main__‘:
 9     # create logger
10     logger = logging.getLogger(‘simple_example‘)
11     logger.setLevel(logging.DEBUG)
12 
13     # create console handler and set level to debug
14     ch = logging.StreamHandler()
15     ch.setLevel(logging.DEBUG)
16     # create formatter for console handler
17     formatter = logging.Formatter(‘%(asctime)s - %(name)s - %(levelname)s - %(message)s‘)
18     # add formatter to console handler
19     ch.setFormatter(formatter)
20 
21     # create file handler and set level to warn
22     fh = logging.FileHandler(‘spam.log‘)
23     fh.setLevel(logging.WARN)
24     # create formatter for file handler
25     formatter = logging.Formatter(‘%(asctime)s - %(name)s - %(levelname)s - %(userid)s - %(message)s‘)
26     # add formatter to file handler
27     fh.setFormatter(formatter)
28     # add context filter to file handler
29     fh.addFilter(ContextFilter())
30 
31     # add ch、fh to logger
32     logger.addHandler(ch)
33     logger.addHandler(fh)
34 
35     # ‘application‘ code
36     logger.debug(‘debug message‘)
37     logger.info(‘info message‘)
38     logger.warn(‘warn message %s‘, ‘args‘)
39     logger.error(‘error message‘)
40     logger.critical(‘critical message‘)

 

　　console输出结果：

2018-06-10 10:44:32,342 - simple_example - DEBUG - debug message
2018-06-10 10:44:32,342 - simple_example - INFO - info message
2018-06-10 10:44:32,342 - simple_example - WARNING - warn message args
2018-06-10 10:44:32,342 - simple_example - ERROR - error message
2018-06-10 10:44:32,342 - simple_example - CRITICAL - critical message

　　文件内容：

2018-06-10 10:44:32,342 - simple_example - WARNING - 123 - warn message args
2018-06-10 10:44:32,342 - simple_example - ERROR - 123 - error message
2018-06-10 10:44:32,342 - simple_example - CRITICAL - 123 - critical message

logging模块解析

logger

　　logger是直接提供给应用程序使用的接口。一般来说，logging的其他几个组件（Handler、Filter、Formatter）都是在初始化Logger的时候使用。

　　logger提供了以下API（部分、重要的）：

Logger.setLevel(level)
　　Sets the threshold for this logger to level. Logging messages which are less severe than level will be ignored.
Logger.isEnabledFor(lvl)
　　Indicates if a message of severity lvl would be processed by this logger.
Logger.debug(msg, *args, **kwargs)
　　Logs a message with level DEBUG on this logger.

Logger.info(msg, *args, **kwargs)
　　Logs a message with level INFO on this logger.

Logger.warning(msg, *args, **kwargs)
　　Logs a message with level WARNING on this logger. same as Logger.warn

Logger.error(msg, *args, **kwargs)
　　Logs a message with level ERROR on this logger.

Logger.critical(msg, *args, **kwargs)
　　Logs a message with level CRITICAL on this logger. same as Logger.fatal

Logger.addFilter(filter)
　　Adds the specified filter filter to this logger.
Logger.removeFilter(filter)
　　Removes the specified filter filter from this logger.
Logger.addHandler(hdlr)
　　Adds the specified handler hdlr to this logger.
Logger.removeHandler(hdlr)
　　Removes the specified handler hdlr from this logger.　

logger实例

　　Logger对象不是通过实例化Logger而来的，都是通过 logging.get_logger(name) 获得一个与name关联的logger对象，logging内部会维护这个映射关系，用同样的name反复调用getLogger，事实上返回的是同一个对象。

Multiple calls to getLogger() with the same name will always return a reference to the same Logger object.

　　logger有一个父子关系，比如：

1 a_logger = logging.getLogger(‘A’） 
2 ab_logger = logging.getLogger(‘A.B’）

 　　通过name的层次关系就可以看出a_logger是ab_logger的parent。这个父子关系是会影响到日志的输出的，后面介绍logging流程的时候可以看到。不过我并没有使用过这种层级关系，所以本文也不会展开介绍。

log level

　　log level即日志的重要等级，意味着不同的紧急程度，不同的处理方式。python logging中，包含以下log level：

　　

　　上表也给出了什么时候使用什么级别的Log level的建议。

　　只有当写日志时候的log level大于等于logger的level阈值(通过setLevel设置)时，日志才可能被输出。

　　比如example1.py中，输出到文件时，debug message、info message并没有输出，因为file handler的logger level是warning，DEBUG和INFO都小于WARNING。

FIlter && Handler

　　从logger中Filter、Handler相关的接口可以看到一个logger可以包含多个handler，多个Filter

　　在example1.py中，logger对象指定了两个handler，第14行的StreamHandler，以及第16行的FileHandler。

Handler

　　Handler定义了如何处理一条日志，是本地打印，还是输出到文件，还是通过网络发送。

　　可以这么理解，日志代表的是一个事件（event），输出日志的应用程序是生产者，而handler是消费者，消费者可以有多个。

　　Handler有以下API：

Handler.setLevel(level)
　　Sets the threshold for this handler to level. Logging messages which are less severe than level will be ignored.
Handler.setFormatter(fmt)
　　Sets the Formatter for this handler to fmt.
Handler.addFilter(filter)
　　Adds the specified filter filter to this handler.
Handler.removeFilter(filter)
　　Removes the specified filter filter from this handler.

　　对于上述API，首先setFormatter表明了日志的格式，这里是“set”，而不是“add”，这个很好理解。其次，Handler有一些与Logger相同的函数：setLevel、addFilter、removeFilter。为啥要用相同的API，在tutorial中是这样介绍的：

Why are there two setLevel() methods? The level set in the logger determines which severity of messages it will pass to its handlers. The level set in each handler determines which messages that handler will send on.

　　但个人认为这个解释很牵强，我觉得在handler（日志事件的消费者）指定过滤条件更合理、更直观。在生产者添加logLevel的目的只是为了开发调试方便：开发的时候通过debug输出调试信息，开发的时候设置高于DEBUG的log level来避免输出这些调试信息。

　　python logging提供了大量的实用的Handler，可以写到标准输出、文件、linux syslog、邮件、远程服务器。

Formatter

responsible for converting a LogRecord to (usually) a string which can be interpreted by either a human or an external system　　

　　可以看到，Formatter将LogRecord输出成字符串。应用程序每输出一条日志的时候，就会创建一个LogRecord对象。看看上述例子：

formatter = logging.Formatter(‘%(asctime)s - %(name)s - %(levelname)s - %(message)s‘)
logger.warn(‘warn message %s‘, ‘args‘)

对应输出： 
　　2018-06-10 10:44:32,342 - simple_example - WARNING - warn message args

　　可以看到，Formatter指定了输出了格式与内容，在logger.warn的两个输入参数组成了formatter中的 %(message)s ，而formatter中的 %(asctime) 等则是在生成LogRecord填充

　　以下是默认提供的属性：

　　

　　如果一个handler没有指定Formatter，那么默认的formatter就是 logging.Formatter(‘%(message)s‘) ，在上面的例子中，对于warn这条日志，那么输出结果是 warn message args 

Filter

Filters can be used by Handlers and Loggers for more sophisticated filtering than is provided by levels.

filter(record)

　　Is the specified record to be logged? Returns zero for no, nonzero for yes. If deemed appropriate, the record may be modified in-place by this method.

　　Filter提供的是比log level更精确的过滤控制，只有当Filter.filter函数返回True的时候，这条日志才会被输出。

　　由于Filter.filter函数的参数是LogRecord实例，那么可以修改LogRecord的属性。在example1.py 第25行  formatter = logging.Formatter(‘%(asctime)s - %(name)s - %(levelname)s - %(userid)s - %(message)s‘) file formatter中指定了属性%(userid)s， 但userid并不在Formatter的属性列表中，这个userid其实就是通过自定义的ContextFilter来实现的，在ContextFilter.filter中，给record对象添加了userid属性。后面还会细讲。

　　官方给出了很多例子，都是通过Filter来修改LogRecord的内容，来输出一些上下文信息（contextual information）。但是我觉得这是一个不好的设计，顾名思义，Filter应该只做过滤的事情，理论上不应该修改输入，builtin filter函数就是这样的。

logging流程

　　从上述的介绍中可以看出，应用层打印的一条日志，需要经过很多步才能最终落地；既受到logger（生产者）的log level、Filter过滤，又要受到Handler（消费者）的log level、Filter过滤。

　　tutorial中给出了一个完整的流程图：

　　

 

logging性能

lazy logging

　　在日志的艺术（The art of logging）一文中提到了lazy logging，即避免过早求值，把字符串的格式化推迟。但对于下面的语句

logger.debug(‘Message with %s, %s‘, expensive_func1(), expensive_func2())

　　虽然不会过早的字符串格式化（format），但是expensive_func1、expensive_func2这两个函数一定会调用，不管日志是否会被输出。如何避免调用这两个函数，解决办法是这样的

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

　　即先判断是否能够输出DEBUG等级的log，然后再调用logger.debug，这样就避免了调用expensive_func1、expensive_func2这两个函数

　　在这里，除了优化性能，还有一个好处就是让代码的意图更加明显（explicit），如果expensive_func是有副作用（side affect），即会改变某些内部状态，那么用这样的代码能更清楚表达expensive_func 不一定会被调用。当然，写在日志里面的表达式不应该有任何副作用、函数也应该是pure function。

性能开关

　　python logging模块的性能是较差的，不仅仅是Python语言的问题，更多的是logging模块的实现问题。

　　前面提到，应用程序的每一条日志都会生成一个LogRecord对象，然后Formatter将其转换成string，怎么转化的呢，其实核心就一句代码 s = self._fmt % record.__dict__ self是Formatter实例，_fmt即初始化Formatter时传入的参数，record即LogRecord实例。由于LogRecord不知道Formatter需要用到哪些属性，所以干脆计算出所有的属性（见图一），这是eager evaluation，lazy evaluation应该更适合。

　　也许Formatter只用到了%(message)s 属性，即只需要对logger.debug的输入参数求值即可，但是LogRecord还是会去反复计算线程id、进程id、应用程序的调用信息（文件、函数、行号），这些都是很耗的操作。

　　对于部分确定不会用到的属性，可以通过开关关掉：

What you don’t want to collect	How to avoid collecting it
Information about where calls were made from.	Set logging._srcfile to None. This avoids calling sys._getframe(), which may help to speed up your code in environments like PyPy (which can’t speed up code that uses sys._getframe()).
Threading information.	Set logging.logThreads to 0.
Process information.	Set logging.logProcesses to 0.

　　

　　通过下面的代码测试（注释第3到6行），关掉之后有25%左右的性能提升

 1 import time
 2 import logging
 3 logging._srcfile = None
 4 logging.logThreads = 0
 5 logging.logMultiprocessing = 0
 6 logging.logProcesses = 0
 7 
 8 if __name__ == ‘__main__‘:
 9     logger = logging.getLogger(‘simple_example‘)
10     logger.setLevel(logging.DEBUG)
11 
12     null = logging.NullHandler()
13     logger.addHandler(null)
14 
15     begin = time.time()
16     for i in xrange(100000):
17         logger.debug(‘debug message‘)
18         logger.info(‘info message‘)
19         logger.warn(‘warn message‘)
20         logger.error(‘error message‘)
21         logger.critical(‘critical message‘)
22     print ‘cost‘, time.time() - begin

 

　　进一步，logging为了线程安全，每个Handler都会持有一个互斥锁，每次写日志的时候都会获取锁，写完之后再释放锁。由于GIL的问题，多线程并不能给某些类型的python程序代码性能提升。因此，如果应用程序能保证是单线程，那么可以设置 logging.thread = None 来避免使用锁，简单测试过也会有15%左右性能提升

logging实用

　　再来看几个logging使用方法或者技巧

同一个logger，不同的handler

　　在前面介绍logging.Logger的时候已经提到，一个logger（生产者）可以有多个handler（消费者）。不同的handler可以有不同的输出格式（Formatter），不同的输出过滤条件（level、Filter）。

　　比如对于线上项目，会有INFO、WARN、ERROR（FATAL）级别的日志产生。不同级别的日志待遇是不一样的，INFO级别的日志，一般只会在查问题的时候用到，记录到文件就行了；而WARN及以上级别的日志，就需要被监控系统采集、统计，会使用到SysLogHandler，然后配合ELK；而对于ERROR或者FATAL级别的日志，需要直接给值班账号发邮件（短信）。

　　对于SyslogHandler，使用syslog_tag来设置分发方式是比较高效的，具体可见由一个简单需求到Linux环境下的syslog、unix domain socket。需要注意的是，默认情况下每一个handler都会持有一个unix domain socket的文件描述符。

上下文信息（contextual information）

　　回到文章开始的问题，如何在日志中输出必须的上下文信息，还是以用户唯一标识（userid）为例。

　　要做到这个事情，有不同的策略。上策是自动化，自动输出补全上下文信息；中策是检测，如果不包含上下文信息，静态代码检查或者运行时报错；下策是强调，这个最不靠谱。

　　在前面已经提到，将LogRecord输出成字符串核心就是  s = self._fmt % record.__dict__  ，_fmt是Formatter初始化格式，如果我们需要在_fmt中添加了自定义属性，如userid，那么只需要保证record.__dict__中有 ‘userid’ 这个key就行了。

　　接下来看看具体的方法：

第一：使用Filter

　　如example2所示，直接在给record设置了userid属性。

　　但使用Filter有一个缺点，不太灵活，Filter一般在初始化Logger（handler）的时候使用，但userid信息实在调用时才能明确的，而且显然不会只有一个useid。

第二：使用extra参数

　　再来看看  Logger.debug(msg, *args, **kwargs) 

　　kwargs中可以包含两个特殊的key：exc_info, extra。

The second keyword argument is extra which can be used to pass a dictionary which is used to populate the __dict__ of the LogRecord created for the logging event with user-defined attributes. These custom attributes can then be used as you like. For example, they could be incorporated into logged messages. 

　　具体怎么做到的？看源码就很清楚了

 1     def makeRecord(self, name, level, fn, lno, msg, args, exc_info, func=None, extra=None):
 2         """
 3         A factory method which can be overridden in subclasses to create
 4         specialized LogRecords.
 5         """
 6         rv = LogRecord(name, level, fn, lno, msg, args, exc_info, func)
 7         if extra is not None:
 8             for key in extra:
 9                 if (key in ["message", "asctime"]) or (key in rv.__dict__):
10                     raise KeyError("Attempt to overwrite %r in LogRecord" % key)
11                 rv.__dict__[key] = extra[key]
12         return rv

 

　　在生成LogRecord的时候会直接把extra的值赋给LogRecord.__dict__.

　　因此，example2代码可以改写成这样：

 1 # -*- coding: utf-8 -
 2 import logging
 3 class ContextFilter(logging.Filter):
 4     def filter(self, record):
 5         record.userid = ‘123‘
 6         return True
 7 
 8 
 9 if __name__ == ‘__main__‘:
10     # create logger
11     logger = logging.getLogger(‘simple_example‘)
12     logger.setLevel(logging.DEBUG)
13 
14     # create console handler and set level to debug
15     ch = logging.StreamHandler()
16     ch.setLevel(logging.DEBUG)
17     # create formatter for console handler
18     formatter = logging.Formatter(‘%(asctime)s - %(name)s - %(levelname)s - %(message)s‘)
19     # add formatter to console handler
20     ch.setFormatter(formatter)
21 
22     # create file handler and set level to warn
23     fh = logging.FileHandler(‘spam.log‘)
24     fh.setLevel(logging.WARN)
25     # create formatter for file handler
26     formatter = logging.Formatter(‘%(asctime)s - %(name)s - %(levelname)s - %(userid)s - %(message)s‘)
27     # add formatter to file handler
28     fh.setFormatter(formatter)
29     # add context filter to file handler
30     # fh.addFilter(ContextFilter())
31 
32     # add ch、fh to logger
33     logger.addHandler(ch)
34     logger.addHandler(fh)
35 
36     # ‘application‘ code
37     logger.debug(‘debug message‘, extra={‘userid‘: ‘1‘})
38     logger.info(‘info message‘, extra={‘userid‘: ‘2‘})
39     logger.warn(‘warn message %s‘, ‘args‘, extra={‘userid‘: ‘3‘})
40     logger.error(‘error message‘, extra={‘userid‘: ‘4‘})
41     logger.critical(‘critical message‘, extra={‘userid‘: ‘5‘})

使用extra替代filter

 

　　使用extra，比Filter更加灵活，每一条日志都可以根据实际情况指定不同的userid。但问题是每一条日志都需要写额外的extra参数，既是在某些环节下extra参数内容都是一样的。

　　当然，如果漏了extra，会报trace，也就是上面提到的中策的效果。

第三：使用LoggerAdapter

 　　使用LoggerAdapter避免了每条日志需要添加extra参数的问题，达到了上策的效果。LoggerAdapter实现很简单，一看代码就明白。

 1 class LoggerAdapter(object):
 2     def __init__(self, logger, extra):
 3         self.logger = logger
 4         self.extra = extra
 5 
 6     def process(self, msg, kwargs):
 7         """
 8         Process the logging message and keyword arguments passed in to
 9         a logging call to insert contextual information. You can either
10         manipulate the message itself, the keyword args or both. Return
11         the message and kwargs modified (or not) to suit your needs.
12         Normally, you‘ll only need to override this one method in a
13         LoggerAdapter subclass for your specific needs.
14         """
15         kwargs["extra"] = self.extra
16         return msg, kwargs
17 
18     def debug(self, msg, *args, **kwargs):
19         msg, kwargs = self.process(msg, kwargs)
20         self.logger.debug(msg, *args, **kwargs)

 

　　直接使用LoggerAdapter.extra覆盖掉kwargs[‘extra‘]，当然我觉得覆盖并不是一个好主意，用update应该更合适。

　　假设类UserRequest处理用户请求，那么每个UserRequest实例都持有一个  LoggerAdapter(logger, {‘userid‘: realuserid}) ,这样写日志的时候就不会额外指定上下文信息（userid)了

 缓存日志内容，延迟输出

　　来自cookbook buffering-logging-messages-and-outputting-them-conditionally

　　这是个非常有趣，且有用的想法。某些场景下，我们需要缓存一些日志，只有当满足某些条件的时候再输出。比如在线上查bug，需要加一些额外的调试（DEBUG或INFO）日志，但是只有当bug复现的情况下（ERROR日志标志问题复现了）才需要打印这些调试日志，因此可以先缓存，当出现了ERROR日志的时候再打印出所有的调试日志。

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

 

　　不过上面的例子只适合单个函数调用的情况，而实际环境中，查一个BUG可能需要追踪的是一个调用流程。

总结

　　python logging模块还有一些功能并未在文章介绍，比如丰富多样的Handler，比如各种logger配置方式（除了在代码中指定loglevel、formatter、filter，还可以写配置文件，甚至从网络读取配置）。

　　python logging本身功能就有丰富，而且也比较好扩展，如果有什么需求，建议先好好看看文档。

references

日志的艺术（The art of logging）

logging — Logging facility for Python

python logging tutorial

logging cookbook