之前写过一篇文章日志的艺术(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 https://docs.python.org/2/howto/logging.html#logging-howto ,api document https://docs.python.org/2/library/logging.html# , https://docs.python.org/2/howto/logging-cookbook.html#logging-cookbook , 源码 https://github.com/python/cpython/blob/2.7/Lib/logging/__init__.py
本文地址: 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
- import logging
- class ContextFilter(logging.Filter):
- def filter(self, record):
- record.userid = '123'
- return True
- if __name__ == '__main__':
- # create logger
- logger = logging.getLogger('simple_example')
- logger.setLevel(logging.DEBUG)
- # create console handler and set level to debug
- ch = logging.StreamHandler()
- ch.setLevel(logging.DEBUG)
- # create formatter for console handler
- formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
- # add formatter to console handler
- ch.setFormatter(formatter)
- # create file handler and set level to warn
- fh = logging.FileHandler('spam.log')
- fh.setLevel(logging.WARN)
- # create formatter for file handler
- formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(userid)s - %(message)s')
- # add formatter to file handler
- fh.setFormatter(formatter)
- # add context filter to file handler
- fh.addFilter(ContextFilter())
- # add ch,fh to logger
- logger.addHandler(ch)
- logger.addHandler(fh)
- # 'application' code
- logger.debug('debug message')
- logger.info('info message')
- logger.warn('warn message %s', 'args')
- logger.error('error message')
- 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() https://docs.python.org/2/library/logging.html#logging.getLogger with the same name will always return a reference to the same Logger object.
logger 有一个父子关系, 比如:
- a_logger = logging.getLogger('A')
- 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() https://docs.python.org/2/library/sys.html#sys._getframe , which may help to speed up your code in environments like PyPy (which can’t speed up code that uses sys._getframe() https://docs.python.org/2/library/sys.html#sys._getframe ). |
Threading information. | Set logging.logThreads to 0. |
Process information. | Set logging.logProcesses to 0. |
通过下面的代码测试(注释第 3 到 6 行), 关掉之后有 25% 左右的性能提升
- import time
- import logging
- logging._srcfile = None
- logging.logThreads = 0
- logging.logMultiprocessing = 0
- logging.logProcesses = 0
- if __name__ == '__main__':
- logger = logging.getLogger('simple_example')
- logger.setLevel(logging.DEBUG)
- null = logging.NullHandler()
- logger.addHandler(null)
- begin = time.time()
- for i in xrange(100000):
- logger.debug('debug message')
- logger.info('info message')
- logger.warn('warn message')
- logger.error('error message')
- logger.critical('critical message')
- 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.
具体怎么做到的? 看源码就很清楚了
- def makeRecord(self, name, level, fn, lno, msg, args, exc_info, func=None, extra=None):
- """
- A factory method which can be overridden in subclasses to create
- specialized LogRecords.
- """
- rv = LogRecord(name, level, fn, lno, msg, args, exc_info, func)
- if extra is not None:
- for key in extra:
- if (key in ["message", "asctime"]) or (key in rv.__dict__):
- raise KeyError("Attempt to overwrite %r in LogRecord" % key)
- rv.__dict__[key] = extra[key]
- return rv
- 在生成 LogRecord 的时候会直接把 extra 的值赋给 LogRecord.__dict__.
- 因此, example2 代码可以改写成这样:
- # -*- coding: utf-8 -
- import logging
- class ContextFilter(logging.Filter):
- def filter(self, record):
- record.userid = '123'
- return True
- if __name__ == '__main__':
- # create logger
- logger = logging.getLogger('simple_example')
- logger.setLevel(logging.DEBUG)
- # create console handler and set level to debug
- ch = logging.StreamHandler()
- ch.setLevel(logging.DEBUG)
- # create formatter for console handler
- formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
- # add formatter to console handler
- ch.setFormatter(formatter)
- # create file handler and set level to warn
- fh = logging.FileHandler('spam.log')
- fh.setLevel(logging.WARN)
- # create formatter for file handler
- formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(userid)s - %(message)s')
- # add formatter to file handler
- fh.setFormatter(formatter)
- # add context filter to file handler
- # fh.addFilter(ContextFilter())
- # add ch,fh to logger
- logger.addHandler(ch)
- logger.addHandler(fh)
- # 'application' code
- logger.debug('debug message', extra={'userid': '1'})
- logger.info('info message', extra={'userid': '2'})
- logger.warn('warn message %s', 'args', extra={'userid': '3'})
- logger.error('error message', extra={'userid': '4'})
- logger.critical('critical message', extra={'userid': '5'})
- 使用 extra 替代 filter
- 使用 extra, 比 Filter 更加灵活, 每一条日志都可以根据实际情况指定不同的 userid. 但问题是每一条日志都需要写额外的 extra 参数, 既是在某些环节下 extra 参数内容都是一样的.
- 当然, 如果漏了 extra, 会报 trace, 也就是上面提到的中策的效果.
- 第三: 使用 LoggerAdapter
- 使用 LoggerAdapter 避免了每条日志需要添加 extra 参数的问题, 达到了上策的效果. LoggerAdapter 实现很简单, 一看代码就明白.
- class LoggerAdapter(object):
- def __init__(self, logger, extra):
- self.logger = logger
- self.extra = extra
- def process(self, msg, kwargs):
- """
- Process the logging message and keyword arguments passed in to
- a logging call to insert contextual information. You can either
- manipulate the message itself, the keyword args or both. Return
- the message and kwargs modified (or not) to suit your needs.
- Normally, you'll only need to override this one method in a
- LoggerAdapter subclass for your specific needs.
- """kwargs["extra"] = self.extra
- return msg, kwargs
- def debug(self, msg, *args, **kwargs):
- msg, kwargs = self.process(msg, kwargs)
- self.logger.debug(msg, *args, **kwargs)
直接使用 LoggerAdapter.extra 覆盖掉 kwargs['extra'], 当然我觉得覆盖并不是一个好主意, 用 update 应该更合适.
假设类 UserRequest 处理用户请求, 那么每个 UserRequest 实例都持有一个 LoggerAdapter(logger, {'userid': realuserid}) , 这样写日志的时候就不会额外指定上下文信息 (userid) 了
缓存日志内容, 延迟输出
- @log_if_errors(logger)
- def foo(fail=False):
- logging - Logging facility for Python https://docs.python.org/2/library/logging.html#
- python logging tutorial https://docs.python.org/2/howto/logging.html#logging-howto
- logging cookbook https://docs.python.org/2/howto/logging-cookbook.html#logging-cookbook
来源: https://www.cnblogs.com/xybaby/p/9176140.html