理解Python日志系统基础
python的 logging 模块是一个强大且灵活的日志记录框架。它基于一个层次化的日志器（logger）结构。最顶层是根日志器（root logger），所有未指定名称的日志器调用都默认使用它。开发者可以创建命名日志器，它们通常通过 logging.getlogger(__name__) 在模块中获取，形成一个以点分隔的层次结构。
日志消息的生命周期大致如下：
- 日志器接收消息： 当调用 _logger.error("...") 时，日志器接收到消息。
- 级别过滤： 日志器会根据其自身的日志级别判断是否处理该消息。
- 处理器处理： 如果消息通过了级别过滤，日志器会将其传递给所有附加的处理器（Handler）。
- 向上冒泡（Propagation）： 默认情况下，日志消息会向上冒泡，传递给其父日志器，直到根日志器。每个父日志器也会重复步骤2和3。
处理器负责将日志消息发送到不同的目的地，例如控制台、文件、数据库或自定义服务。为了实现更复杂的日志行为，我们经常会创建自定义处理器。
遇到的问题：命名日志器不触发根日志器的自定义处理器
在某些场景下，开发者可能需要在程序启动后动态地向根日志器添加一个自定义处理器。例如，一个Web应用可能在初始化时连接到数据库，并注册一个将日志写入数据库的处理器。
考虑以下代码结构：
立即学习“Python免费学习笔记（深入）”；
main.py
import logging
import MyLogger
from MyApp import MyApp
MyLogger.init() # 初始化日志配置，包括根日志器和控制台处理器
_logger = logging.getLogger() # 获取根日志器
def main() :
_logger.error( "main - root logger" ) # 根日志器直接记录，预期会输出
app = MyApp() # 实例化MyApp，MyApp的构造函数会向根日志器添加一个CallbackHandler
app.testLog() # 调用MyApp内部的命名日志器记录消息
if __name__ == "__main__" :
main()MyLogger.py
import logging
from logging import LogRecord
import logging.config
import os
from typing import Callable
LOG_PATH = "./logs"
LOGGING_CONFIG : dict = {
"version" : 1 ,
'formatters': {
'simple': {
'format': '%(name)s %(message)s'
},
},
"handlers" : {
"ConsoleHandler" : {
"class" : "logging.StreamHandler" ,
"formatter" : "simple" ,
} ,
} ,
"root" : {
"handlers" : [
"ConsoleHandler" ,
] ,
"level" : "DEBUG" ,
}
}
def init() :
os.makedirs( LOG_PATH , exist_ok = True )
logging.config.dictConfig( LOGGING_CONFIG )
class CallbackHandler( logging.Handler ) :
def __init__( self , level = logging.DEBUG , callback : Callable = None ) :
super().__init__( level )
self._callback = callback
def emit( self , record : LogRecord ) :
if self._callback is not None :
self._callback( record.name + " | " + record.msg )
MyApp.py
import logging
from MyLogger import CallbackHandler
_logger = logging.getLogger( __name__ ) # 获取命名日志器 'MyApp'
class MyApp :
def __init__( self ) :
rootLogger = logging.getLogger()
# 动态向根日志器添加一个自定义CallbackHandler
rootLogger.addHandler( CallbackHandler( callback = self.myCallback ) )
def myCallback( self , msg : str ) :
print( "CALLBACK: " + msg )
def testLog( self ) :
_logger.error( "MyApp.testLog() - named logger" ) # 命名日志器记录消息在上述设置中，我们期望 MyApp.testLog() 中由命名日志器发出的日志消息能够：
- 通过 ConsoleHandler 输出到控制台。
- 向上冒泡到根日志器。
- 触发根日志器上动态添加的 CallbackHandler，从而调用 myCallback 方法并打印 "CALLBACK: ..."。
然而，实际运行结果是 CallbackHandler.emit() 方法并未被调用，即 "CALLBACK: ..." 没有打印出来。这表明命名日志器的消息虽然可能被 ConsoleHandler 处理了（因为它是根日志器的一部分），但未能触发动态添加的 CallbackHandler。
根源分析：disable_existing_loggers 参数
问题的关键在于 logging.config.dictConfig 函数的一个默认行为：disable_existing_loggers 参数。根据Python logging 官方文档，当使用 dictConfig 配置日志系统时：
disable_existing_loggers：布尔值，默认为 True。如果为 True，所有在调用 dictConfig 之前存在的非根日志器都将被禁用。这可以防止在配置更改后旧的日志器继续发送消息。
这意味着，当 MyLogger.init() 调用 logging.config.dictConfig(LOGGING_CONFIG) 时，如果 MyApp.py 中的命名日志器 _logger = logging.getLogger(__name__) 已经在 dictConfig 调用之前被创建，那么这个 MyApp 日志器就会被禁用。一个被禁用的日志器将不会处理任何日志消息，也不会将其传播给父日志器。
在我们的示例中，main.py 导入 MyApp 模块时，MyApp.py 中的 _logger = logging.getLogger(__name__) 语句就会被执行，从而创建了名为 MyApp 的日志器实例。随后，MyLogger.init() 才被调用，执行 dictConfig。由于 MyApp 日志器在 dictConfig 之前就已存在，并且 disable_existing_loggers 默认为 True，因此 MyApp 日志器被禁用了，导致其发出的日志消息无法传播到根日志器，也就无法触发 CallbackHandler。
解决方案：显式设置 disable_existing_loggers 为 False
解决此问题的关键是确保 dictConfig 在配置日志系统时，不会禁用已经存在的日志器。这可以通过在 LOGGING_CONFIG 字典中显式设置 disable_existing_loggers 为 False 来实现。
修改 MyLogger.py 中的 LOGGING_CONFIG 如下：
# MyLogger.py (修正后)
import logging
from logging import LogRecord
import logging.config
import os
from typing import Callable
LOG_PATH = "./logs"
LOGGING_CONFIG : dict = {
"version" : 1 ,
"disable_existing_loggers" : False, # 关键修复：允许现有日志器继续工作
'formatters': {
'simple': {
'format': '%(name)s %(message)s'
},
},
"handlers" : {
"ConsoleHandler" : {
"class" : "logging.StreamHandler" ,
"formatter" : "simple" ,
} ,
} ,
"root" : {
"handlers" : [
"ConsoleHandler" ,
] ,
"level" : "DEBUG" ,
}
}
def init() :
os.makedirs( LOG_PATH , exist_ok = True )
logging.config.dictConfig( LOGGING_CONFIG )
class CallbackHandler( logging.Handler ) :
def __init__( self , level = logging.DEBUG , callback : Callable = None ) :
super().__init__( level )
self._callback = callback
def emit( self , record : LogRecord ) :
if self._callback is not None :
self._callback( record.name + " | " + record.msg )
通过这一简单的修改，dictConfig 将不再禁用在它被调用之前创建的日志器。这样，MyApp 模块中的命名日志器将保持启用状态，其发出的日志消息将能够正常向上冒泡到根日志器，从而触发根日志器上所有附加的处理器，包括我们动态添加的 CallbackHandler。
运行结果验证
使用修正后的 MyLogger.py 再次运行 main.py，你将看到如下输出（或类似输出）：
main - root logger MyApp.testLog() - named logger CALLBACK: MyApp | MyApp.testLog() - named logger
这证明了 CallbackHandler 现在能够正确地接收并处理来自命名日志器的消息。
最佳实践与注意事项
- 日志器初始化顺序： 理想情况下，应在应用程序启动的早期阶段，在任何命名日志器被实例化之前，完成日志系统的配置（包括 dictConfig）。这样可以避免 disable_existing_loggers 带来的潜在问题。然而，在复杂应用中，模块导入顺序可能导致日志器提前创建，此时 disable_existing_loggers: False 就显得尤为重要。
- disable_existing_loggers 的用途： 虽然在此场景下我们需要将其设置为 False，但理解其默认值为 True 的原因也很重要。在某些情况下，当应用程序需要完全重置日志配置，并希望确保旧的、可能不再相关的日志器不再活跃时，True 的默认值是有益的。它提供了一种清理机制。
- 日志级别与冒泡： 确保命名日志器和根日志器的日志级别都足够低，以便能够处理所需的日志消息。同时，确保命名日志器的 propagate 属性没有被设置为 False，否则它将不会将消息传递给父日志器。默认情况下 propagate 为 True。
总结
Python logging 模块的灵活性带来了强大的日志管理能力，但也包含了一些需要注意的细节。当遇到命名日志器消息未能触发根日志器上的自定义处理器时，logging.config.dictConfig 中 disable_existing_loggers 参数的默认行为往往是罪魁祸首。通过显式将其设置为 False，我们可以确保所有日志器都按预期工作，日志消息能够沿着日志器层次结构正确传播，并被所有相关处理器处理。理解这一机制对于构建健壮且可维护的Python应用程序日志系统至关重要。
