使用 Python 的话用不着像 Java 那样是考虑用 Logback 还是 Log4J 的问题，因为它内置提供了完备功能的 logging 库。虽然 JDK 也有 java.util.logging(JUL), 它的特性其实也不差，如日志级别，输出格式，不同的输出目的地的选择，但在 Logback 和 Log4J 的光环之下几乎无人问津。相比而言 Python 的 logging 却极为受宠，非必要时基本不会去考虑引入第三方的日志库，如 Loguru, LogBook, Structlog, Picologging, 尽管它们也很出色，毕竟是庶出。
logging 的最基本用法
在基本前面加是最 字，是因为这一节仅仅是如何让 logging 作为 print() 的替代品，暂不涉及到参数的传递，异常的输出，以及格式定制，日志往哪里输出的问题。
|
1 2 3 |
import logging logging.info("hello") |
运行，什么也看不到，因为 Python logging 的默认级别是 warning, 这不符合人的基本认知，一般 logging.info() 起码是用来替代 print() 的，居然直接用无法输出，不知该库的设计者是怎么个想法。
如果用
|
1 |
logging.warning("hello") |
输出便是
WARNING:root:hello
但谁会突兀的用 logging.warning() 代替 print 呢？所以还是需要配置 logging 的默认级别为 INFO。在设置 LogLevel 之前先查看一下它的默认级别，用代码
|
1 2 |
print(logging.root.level) print(logging.getLevelNamesMapping()) |
将会看到
30
{'CRITICAL': 50, 'FATAL': 50, 'ERROR': 40, 'WARN': 30, 'WARNING': 30, 'INFO': 20, 'DEBUG': 10, 'NOTSET': 0}
所以对应的 30 为 WARN
|
1 2 |
logging.root.setLevel(logging.INFO) logging.info("hello") |
现在有了
INFO:root:hello
到目前为止我们一直专注到 root logger, 像 Java 的 Logback 和 Log4J 一样，对 root 的 LogLevel 设置会自动应用到其他的 logger, 但前提是 root logger 有过一次日志输出调用
|
1 2 3 4 5 |
logging.root.setLevel(logging.INFO) logging.info("hello") # 注释掉该行将看不到 hello again 输出 log_abc = logging.getLogger("abc") log_abc.info("hello again") |
输出为
INFO:root:hello
INFO:abc:hello again
要是把第二行的 logging.info("hello") 注释掉的话，就没有 hello again 了，原因是在第一次 logging.xxx("hello") 调用时会进行 basicConfig 的配置
|
1 2 3 4 |
def info(msg, *args, **kwargs): if len(root.handlers) == 0: basicConfig() root.info(msg, *args, **kwargs) |
因此更为主动配置 root 及其他所有 logger 的输出级别的做法是直接用 basicConfig()
|
1 2 3 4 |
logging.basicConfig(level=logging.INFO) log_abc = logging.getLogger("abc") log_abc.info("hello again") |
这样所有的 logger 就有了 INFO 级别了，上面的输出为
INFO:abc:hello again
Python logging 默认的日志输出格式是
'%(levelname)s:%(name)s:%(message)s'
Python logging 中的 logger
Python 有一个开箱即用的 logger 实例，即 logging, 如果不想要申明别的 logger 的话，完全可以用 logging.info(), logging.error() 一撸到底，通过 LogFormat 在日志在输出所在的模块, 方法, 代码行等信息。
当然也可以像 Java 那样为每个包和模块创建自己的 logger 实例， 通常做法是
|
1 |
logger = logging.getLogger(__name__) |
__name__ 包含了包名和模块名，比如上面代码声明在 xxx/yyy/zzz.py 中，则创建的 logger 名为 xxx.yyy.zzz，如果 logging.getLogger(__name__) 声明在 xxx/yyy/__init__.py 文件中的话，创建的 logger 名为 xxx.yyy。和 Logback 和 Log4J 一样，xxx.yyy.zzz 的 logger名实际构建出了 logger 之间的父子关系，如
logging.getLogger("xxx.yyy.zzz") 和 logging.getLogger("xxx.yyy.kkk") 是 logging.getLogger("xxx.yyy") 的 children.
|
1 2 3 4 5 6 7 8 |
logger_p = logging.getLogger('xxx.yyy') logger_p.setLevel(logging.DEBUG) logger_c1 = logging.getLogger('xxx.yyy.zzz') logger_c2 = logging.getLogger('xxx.yyy.kkk') print(logger_p.getChildren()) print(logging.getLogger("xxx")) |
输出为
{<Logger xxx.yyy.zzz (DEBUG)>, <Logger xxx.yyy.kkk (DEBUG)>}
<Logger xxx (WARNING)>
并且父 logger 的配置会影响到其所有子 logger
logging 的参数与异常输出
logger 的日志输出方法有 debug(), info(), warning(), error(), fatal() 和 critical(), 还有 exception(), 从日志级别来讲 fatal() 和 critical() 是在一个级别，即 50。它们的方法原型都是一样的，以 info() 为例
|
1 |
def info(self, msg, *args, **kwargs): |
如果在 IntelliJ IDEA 或 PyCharm 中自动提示时把其中的 **kwargs 可能支持值更明确化
|
1 |
logging.info(msg, args, exc_info, stack_info, stacklevel, extra) |
实际上是无论 info(), warning() 等方法都会来到 logging.__init__.py 中的
|
1 |
def _log(self, level, msg, args, exc_info=None, extra=None, stack_info=False, stacklevel=1): |
msg 和 args 是调用 msg % args 来格式化消息
|
1 |
logging.info("%s says hello to %s", "aa", "bb") |
INFO:root:aa says hello to bb
所以 msg 中的 % 点位符与所提供的参数数量不符都会看到类似下面的错误
太少
msg = msg % self.args
~~~~^~~~~~~~~~~
TypeError: not enough arguments for format string
太多
msg = msg % self.args
~~~~^~~~~~~~~~~
TypeError: not all arguments converted during string formatting
输出异常信息
|
1 2 3 4 |
try: raise Exception("something wrong") except Exception as ex: logging.error("got error due to %s", str(ex)) |
输出为
ERROR:root:got error due to something wrong
Python 的 logging 可不能像 Logback 和 Log4J 那样在最后位置上放上 ex 本身就会输出异常栈信息，在 Python 中 logging.error("error", ex) 会报错的。
正确的做法是用 exc_info=True 或 stack_info=True 参数
|
1 |
logging.error("got error due to %s", str(ex), exc_info=True) |
输出为
|
1 2 3 4 5 |
ERROR:root:got error due to something wrong Traceback (most recent call last): File "/opt/project/test.py", line 6, in <module> raise Exception("something wrong") Exception: something wrong |
同时加上 stack_info=True
|
1 |
logging.error("got error due to %s", str(ex), exc_info=True, stack_info=True) |
后的输出为
|
1 2 3 4 5 6 7 8 |
ERROR:root:got error due to something wrong Traceback (most recent call last): File "/opt/project/test.py", line 6, in <module> raise Exception("something wrong") Exception: something wrong Stack (most recent call last): File "/opt/project/test.py", line 8, in <module> logging.error("got error due to %s", str(ex), exc_info=True, stack_info=True) |
或者用 exception() 方法替代直接 error() 方法，exception() 方法的实现是
|
1 2 |
def exception(self, msg, *args, exc_info=True, **kwargs): self.error(msg, *args, exc_info=exc_info, **kwargs) |
exception() 就是 exc_info=True 的 error() 方法。
stacklevel 参数的功效
stacklevel 默认为 1，即输出调用 logging 方法的当前代码处的信息(即当前桢)，这其实是回溯的，stacklevel=1 即为栈底，stacklevel=2 则往顶上一层，感觉保持默认的 stacklevel=1 就足够了。为了演示 stacklevel 的效果，需要配置一下日志的输出格式，让其初输出包，模块，函数及代码行的信息
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 |
import logging logging.basicConfig( level=logging.INFO, format="%(asctime)s - %(levelname)s %(module)s - %(funcName)s:%(lineno)d - %(message)s") def foo(): bar() def bar(): logging.info("hello", stacklevel=1) if __name__ == '__main__': foo() |
上面的代码输出为
2024-10-16 19:38:26,460 - INFO test - bar:12 - hello
即调用 logging.info("hello", stacklevel=1) 处的信息，如果把 stacklevel 调整为 2 (stacklevel=2)，输出则变为
2024-10-16 19:39:48,881 - INFO test - foo:8 - hello
即 %(module)s - %(funcName)s:%(lineno)d 全部回到了上一层 foo() 的调用处，其实意义不大。如果再往，比如设置一个很大的值，像 stacklevel=20，不回有错，再大也是在最顶层，输出信息就是
2024-10-16 19:41:04,182 - INFO test - <module>:15 - hello
logger 方法的 extra 参数
logging.info(extra: dict) 的 extra 参数是用来补充在日志格式中自定义的字段或覆盖 LogRecord attributes 中预定义的字段值，但覆盖 asctime 和 message 是不被允许的。从下面的例子中可以很轻松的理解
|
1 2 3 4 5 6 7 8 |
logging.basicConfig( level=logging.INFO, format="%(asctime)s %(request_id)s %(user_id)s - %(message)s") if __name__ == '__main__': request_id= 'xx-yy-zz' user_id = '001' logging.info("hello extra example", extra={'request_id': f'{request_id=}', 'user_id': f'{user_id=}'}) |
输出为
2024-10-16 19:54:44,345 request_id='xx-yy-zz' user_id='001' - hello extra example
这很方便我们在 format 中自定义字段，但问题是在每次 logging.info() 等方法中都必须提供自定义字段的值，否则在最后格式化日志消息是会报错。
Python logging 的扩展点
说到 Python logging 的扩展点，不得不回到 basicConfig() 方法调用
在使用 basicConfig() 方法时留意到它可不止是用到配置 level 的，它几乎是 Python logging 的精髓所在
参数的简单讲解
- filename, filemode, encoding, errors: 日志文件名和打开文件的模式(默认为 a) 和文件编码, 指定了 filename 的话日志只输出到文件。没有 handlers 参数则由 filename 决定是创建 FileHandler(filename, filemode, encoding, errors) 还是 StreamHandler(stream|none)
- format: 日志输出格式，预定义字段请参考 LogRecord attributes
- datefmt: 默认时间格式为 '%Y-%m-%d %H:%M:%S'
- style: 可选值为 "%", "{", 和 "$", 它决定了在 format 中是用
%(name)s,${name}, 还是{name}, 与 logger.info("hello %s", "Pythong") 中的 "%s" 无关 - stream: 未指定 handlers 将使用 stream 创建 StreamHandle(stream) 作为唯一的 handler
- handlers, force: 如果指定了值，则将忽略 filename, stream, 直接用该 handlers，force=True/False, 决定是否先把 root logger 中已有的 handlers 清空并关闭，然后添加参数 handlers 中的 handler 到 root 的 handlers 列表。force 默认为 False, force 用于擦除系统已注册的 handler 还是挺有用，比如给 Python AWS Lambda 重新配置 handler
Python logging 的主要的扩展类是 Filter, Handler, 以及 Format 中的自定义字段，它们与 Logger 的关系交织在一起，例如
|
1 2 3 4 5 |
logger.addFilter(filter) logger.addHandler(handler) logger.handlers[0].addFilter(filter) logger.handlers[1].setFormatter(formatter) |
filter 既可以关联到 logger 也可以关联到 handler, formatter 配置在 handler 上的，handler 是与 logger 相关联的. filter 处理的是 LogRecord, 除此之外还有 LoggerAdapter 类。
而最终 logger.addFilter(filter) 也会把 filter 添加到相关联 handler 上去。Python logging 起决定性的作用是 Handler, 一个 logger 可以对应一或多个 Handler 决定以什么格式向哪里输出，每个 Handler 有 filter 来处理 LogRecord
logger, handler, format, filter 之间的关系大概是下图的样子
除了 logging.basicConfig()，还有 logging.config 中的另外两个配置函数, 方法原型如下
|
1 2 3 4 |
import logging.config logging.config.fileConfig(fname:str|bytes|PathLike[str]|IO[str]|RawConfigParser, defaults, disable_existing_loggers, encoding) logging.config.dictConfig(config: _DictConfigArgs | dict[str, Any]) |
fileConfig()
fileConfig() 需要是一个能被 Python 的 configparser 解析的类似于 Windows INI 文件格式. 下面是一个 fileConfig 例子，文件名为 logconfig.ini
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 |
[loggers] keys=root,sampleLogger [handlers] keys=consoleHandler,fileHandler [formatters] keys=simpleFormatter,detailedFormatter [logger_root] level=INFO handlers=consoleHandler [logger_sampleLogger] level=DEBUG handlers=fileHandler qualname=sampleLogger propagate=0 [handler_consoleHandler] class=StreamHandler level=INFO formatter=simpleFormatter args=(sys.stdout,) [handler_fileHandler] class=FileHandler level=DEBUG formatter=detailedFormatter args=('sample.log', 'a') [formatter_simpleFormatter] format=%(asctime)s - %(name)s - %(levelname)s - %(message)s [formatter_detailedFormatter] format=%(asctime)s - %(name)s - %(levelname)s - %(message)s - %(pathname)s:%(lineno)d |
Python 代码
|
1 2 3 4 5 6 |
import logging import logging.config logging.config.fileConfig("logconfig.ini") logging.info("hello console") logging.getLogger("sampleLogger").info("hello file") |
在控制台输出为
2024-10-16 21:10:42,318 - root - INFO - hello console
在 sample.log 文件中的输出为
2024-10-16 21:10:42,319 - sampleLogger - INFO - hello file - /opt/project/test.py:11
logger.config.configDict() 的方式这里不细说，Python 的 logging 不同于 Java 的 Logback/Log4J, 个人感觉用 Python 代码的配置方式似乎要优于 fileConfig() 和 configDict() 的配置方式，更易于理解与排错。
一个相当于 Java 的 MDC 实现
MDC 类
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 |
import logging import threading class MDC(logging.Filter): def __init__(self): super().__init__() self.thread_local = threading.local() self.thread_local.mdc = {} def request_id(self, request_id): self.set('request_id', request_id) return self def user_id(self, user_id): self.set('user_id', user_id) return self def clear(self, key): if key in self.thread_local.mdc: del self.thread_local[key] def set(self, key, value): self.thread_local.mdc[key] = value def get_xfields_string(self): return " ".join([f'{key}={value}' for (key, value) in self.thread_local.mdc.items()]) def filter(self, record): record.xfields = self.get_xfields_string() return True |
配置使用 MDC 类
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 |
from logging import StreamHandler mdc = MDC() handler = StreamHandler(None) handler.addFilter(mdc) logging.basicConfig( level=logging.INFO, format= '%(asctime)s - %(levelname)s - %(module)s - %(funcName)s:%(lineno)d - %(xfields)s message="%(message)s"', handlers=[handler], force=True ) mdc.request_id("xxx-yyy-zzz").user_id('yanbin') logging.info("hello") mdc.request_id("aaa-bbb-ccc") mdc.set("app_name", "demo") logging.getLogger("abc").info("hello") |
输出为
2024-10-16 21:47:23,429 - INFO - test - <module>:48 - request_id=xxx-yyy-zzz user_id=yanbin message="hello"
2024-10-16 21:47:23,431 - INFO - test - <module>:52 - request_id=aaa-bbb-ccc user_id=yanbin app_name=demo message="hello"
最后，也没什么好总结的，就一篇关于 Python logging 的使用笔记，自然有些杂乱无章，方便日后重新翻出来参考。
2024-10-21 补充一个 ContextVar 版本的 MDC 实现
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 |
import logging from contextvars import ContextVar class MDC(logging.Filter): def __init__(self): super().__init__() self.mdc = ContextVar("MDC") self.mdc.set({}) def request_id(self, request_id): self.set('request_id', request_id) return self def user_id(self, user_id): self.set('user_id', user_id) return self def clear(self, key): if key in self.mdc.get(): del self.mdc.get()[key] def set(self, key, value): self.mdc.get()[key] = value def get_xfields_string(self): return " ".join([f'{key}={value}' for (key, value) in self.mdc.get().items()]) def filter(self, record): record.xfields = self.get_xfields_string() return True |
不仅适用于多线程环境也能用于 asyncio 中。
本文链接 https://yanbin.blog/python-logging-usages/, 来自 隔叶黄莺 Yanbin Blog
[版权声明] 
本文采用 署名-非商业性使用-相同方式共享 4.0 国际 (CC BY-NC-SA 4.0) 进行许可。