背景 近期在对其他同事进行维护的一个由 aiohttp 作为 web server 的 web 后端项目做相关优化的时候，发现了一个现象，项目中配置了 log ，但是该项目中除了将 log 输出到日志文件中外，所有的 API 请求都还会在控制台输出一条信息。但几乎进行相同配置的另一个项目则不会出现这个情况。出于技术的好奇决定一探究竟。
复现代码 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 37 38 39 40 41 42 43 44 45 import loggingfrom logging import Formatterfrom logging.handlers import RotatingFileHandlerfrom aiohttp import webdef setup_logger (): logger = logging.getLogger("app_log" ) logger.setLevel(logging.INFO) file_handler = RotatingFileHandler(filename='app_log.log' ) formatter = Formatter('%(asctime)s - %(levelname)s - %(message)s' ) file_handler.setFormatter(formatter) file_handler.setLevel(logging.INFO) logger.addHandler(file_handler) def config_server (): logging.info("数据库或其他 web 服务相关的配置" ) async def handle (request: web.Request ) -> web.Response: name = request.match_info.get('name' , "Anonymous" ) text = "Hello, " + name return web.Response(text=text) app = web.Application() app.add_routes([web.get('/' , handle), web.get('/{name}' , handle)]) def main (): logger = logging.getLogger("app_log" ) setup_logger() config_server() web.run_app(app, host="0.0.0.0" , port=8000 , access_log=logger) if __name__ == '__main__' : main()
运行上述代码，然后再访问 http://localhost:8000
控制台会输出类似如下的信息
1 2 3 4 > python script.py ======== Running on http://0.0.0.0:8000 ======== (Press CTRL+C to quit) INFO:app_log:127.0.0.1 [13/Mar/2024:15:40:54 +0000] "GET / HTTP/1.1" 200 167 "-" "PostmanRuntime/7.36.3"
同时，项目目录下会生成一个 app_log.log 文件，里面会有类似如下的信息
1 2024-03-13 23:40:54,815 - INFO - 127.0.0.1 [13/Mar/2024:15:40:54 +0000] "GET / HTTP/1.1" 200 167 "-" "PostmanRuntime/7.36.3"
我们所预期的是只有 app_log.log 文件中的信息，但是控制台中也会输出一条信息。
排查踩坑 首先是对两个表现不同的项目的 setup_logger 代码进行了对比，抛去变量的名称，其余配置都是一模一样。那就排除了配置的差异导致的问题
然后进行了项目依赖的对比，存在一些依赖的差异和版本的区别，但两个项目中都不涉及到 log 相关的依赖，所有的 log 都是使用的 Python 内置的 logging 模块。并且也尝试了交换环境来运行项目。但现象依然是一样的。
这些排查步骤都为能发现原因。没有办法，只能通过对比运行时来了解差别了。
运行时 aiohttp 代码分析 注意：一下原码分析过程基于 aiohttp==3.6.2 版本的 Tag 3.6.2 进行分析的。可能与最新版本的代码有所不同。
接下来就开始对代码启动 web_server 传入的 access_log 参数进行跟踪。在启动 web 服务后，通过
run_app -> _run_app -> AppRunner._make_server -> Application.make_handler -> Application._make_handler -> Server.__call__ -> RequestHandler
会将 access_log 传入到 RequestHandler
该类的 start
查看 start 函数的逻辑或者搜索传入该类的 access_log 可以知道是由 log_access
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 class RequestHandler (BaseProtocol ): def __init__ (self, access_log_class: Type [AbstractAccessLogger]=AccessLogger, access_log: Logger=access_logger, access_log_format: str =AccessLogger.LOG_FORMAT, ): self .access_log = access_log if access_log: self .access_logger = access_log_class( access_log, access_log_format) else : self .access_logger = None def log_access (self, request: BaseRequest, response: StreamResponse, time: float ) -> None : if self .access_logger is not None : self .access_logger.log(request, response, time) async def start (self ): while not self ._force_close: try : if self .access_log: self .log_access(request, resp, loop.time() - now) except : ...
同时，我们又看到 log_access 函数中的 self.access_logger 是在 __init__ 函数中使用 access_log_class 创建的，access_log_class 的值可以传入或使用默认值。向前回溯我们并未传入该参数。所以此处是默认值在起作用。再进入 AccessLogger.log
<remote_address> <request_start_time> "<first_request_line>" <response_status> <response_size> "<request_header:referer>" "<request_header:user_agent>"
例如：
127.0.0.1 [18/Mar/2024:15:22:08 +0000] "GET / HTTP/1.1" 200 167 "-" "PostmanRuntime/7.37.0"
此时也能看到使用了 self.logging.info 来进行日志的输出。 self.logging 就是我们最开始传入的 access_log 。也就是我们自己写的代码中的 logging.getLogger("app_log") 返回的对象。
运行时 python 代码分析 注意：以下代码基于 python3.7
首先，我们可以看到正常使用 logging.info 输出的日志实际上是创建了一个 rootLogger 对象。该对象的 name 属性值为 root ，默认的 level 为 WARNING ， 默认的 handlers 为空。
然后再关注 logging.getLoggername 参数，那么就会返回上文中提到的 root 对象。如果传入了 name 参数，那么就会返回 Logger.manager.getLogger(name) 的返回值。
1 2 3 4 5 def getLogger (name=None ): if name: return Logger.manager.getLogger(name) else : return root
Logger.managerLogger.root 初始化的 Manager
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 Logger.manager = Manager(Logger.root) class Manager (object ): def __init__ (self, rootnode ): self .root = rootnode self .loggerDict = {} def getLogger (self, name ): rv = None if not isinstance (name, str ): raise TypeError('A logger name must be a string' ) _acquireLock() try : if name in self .loggerDict: rv = self .loggerDict[name] if isinstance (rv, PlaceHolder): ph = rv rv = (self .loggerClass or _loggerClass)(name) rv.manager = self self .loggerDict[name] = rv self ._fixupChildren(ph, rv) self ._fixupParents(rv) else : rv = (self .loggerClass or _loggerClass)(name) rv.manager = self self .loggerDict[name] = rv self ._fixupParents(rv) finally : _releaseLock() return rv
查看上述代码可知， Manager 中存在一个 loggerDict 的字典用来管理所有的 Logger 对象。如果传入的 name 在 loggerDict 中存在，那么就会返回该 Logger 对象。如果不存在，那么就会创建一个新的 Logger 对象，并将其加入到 loggerDict 中。以此实现单例模式。
_fixupParents 的主要作用是解析其父节点，如果名称中携带有 . ，那么会创建一个 PlaceHolder 节点，如果前后文有使用该节点，那么会将其替换为真实的 Logger 节点。如果未使用，则该节点的父节点依然是 root 节点。
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 import loggingabcdefgh = logging.getLogger("abc.def.gh" ) abcdef = logging.getLogger("abc.def" ) abc = logging.getLogger("abc" ) abcd = logging.getLogger("ab.cd" ) print (abcdefgh, abcdefgh.parent) print (abcdef, abcdef.parent) print (abc, abc.parent) print (abcd, abcd.parent, abcd.parent.parent)
到此，我们就了解了 logging.getLogger 函数的工作原理。接下来我们再看看 logging.info 函数的实现，跟踪定位发现 logging.info 最后的打印操作是在 Logger 对象中的 callHandlers
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 def callHandlers (self, record ): c = self found = 0 while c: for hdlr in c.handlers: found = found + 1 if record.levelno >= hdlr.level: hdlr.handle(record) if not c.propagate: c = None else : c = c.parent if (found == 0 ): if lastResort: if record.levelno >= lastResort.level: lastResort.handle(record) elif raiseExceptions and not self .manager.emittedNoHandlerWarning: sys.stderr.write("No handlers could be found for logger" " \"%s\"\n" % self .name) self .manager.emittedNoHandlerWarning = True
此处可以看到， c.handlers 实际上是一个列表，我们在前文使用 logger.addHandler(file_handler) 即是将 file_handler 加入到了 c.handlers 中。然后调用 handlers 中的 handle 函数来处理日志的输出。当处理完 c.handlers 中的所有 handler 后，会将 c 设置为 c.parent ，然后继续处理 c.parent 中的 handlers 。直到 c 为 None 或者 c.propagate 为 False 时，结束循环。 c.handlers 的输出就是正常使用了配置中的文件进行了日志的输出。那么问题就出在了 c.parent 上。
但到此时为止，我们都没有对 root 节点进行任何的操作。按道理来说， root 节点当前的 handlers 应该是空的。但是此时通过调试发现，此时的 root 节点的 handlers 中存在 [<StreamHandler <stderr> (NOTSET)>] 的内容。
问题其实出现在了我们自己写的 config_server 函数中的 logging.info 中。 logging.info
1 2 3 4 def info (msg, *args, **kwargs ): if len (root.handlers) == 0 : basicConfig() root.info(msg, *args, **kwargs)
可以看到，如果 root.handlers 为空，那么就会调用 basicConfig 函数。 basicConfig 函数的实现如下：
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 def basicConfig (**kwargs ): _acquireLock() try : if len (root.handlers) == 0 : handlers = kwargs.pop("handlers" , None ) if handlers is None : filename = kwargs.pop("filename" , None ) mode = kwargs.pop("filemode" , 'a' ) if filename: h = FileHandler(filename, mode) else : stream = kwargs.pop("stream" , None ) h = StreamHandler(stream) handlers = [h] dfs = kwargs.pop("datefmt" , None ) style = kwargs.pop("style" , '%' ) fs = kwargs.pop("format" , _STYLES[style][1 ]) fmt = Formatter(fs, dfs, style) for h in handlers: if h.formatter is None : h.setFormatter(fmt) root.addHandler(h) finally : _releaseLock()
由于调用该函数时，未传递任何参数，故删除掉参数的处理逻辑，可以看到 handlers 初始化为了一个具有一个 StreamHandler 实例化对象元素的列表。 StreamHandler
1 2 3 4 5 6 class StreamHandler (Handler ): def __init__ (self, stream=None ): Handler.__init__(self ) if stream is None : stream = sys.stderr self .stream = stream
可以看到，如果未传入 stream 参数，那么就会使用 sys.stderr 作为默认的输出流。同时， StreamHandler 继承自 Handler 。在未传入 level 的时候，默认值为 NOTSET ，并且 fs = kwargs.pop("format", _STYLES[style][1]) 使用了 BASIC_FORMATlevelname:app_name:message 的格式。
所以此时的 root 节点的 handlers 中存在 [<StreamHandler <stderr> (NOTSET)>] 的内容。故此时 root 的 handlers 存在一个输到控制台的 handler 。所以每次调用 app_log 的 info 的时候。都会由 <StreamHandler <stderr> (NOTSET)> 输出一条日志到控制台。
至此，问题分析完毕
最后的尝试 将前面的测试代码稍作改动，将 config_server 函数中的 logging.info 注释掉。再次运行代码，然后在接口的 handler 中添加一个 if 语句后。按照如下顺序调用接口
1 2 3 curl http://localhost:8000/stolen curl http://localhost:8000 curl http://localhost:8000/stolen
控制台出现了入下的输出，会发现第一次请求没有输出，第二次和第三次请求出现了输出。结合上述原理。应该很容易理解了。
1 2 INFO:app_log:127.0.0.1 [19/Mar/2024:05:33:00 +0000] "GET / HTTP/1.1" 200 167 "-" "PostmanRuntime/7.37.0" INFO:app_log:127.0.0.1 [19/Mar/2024:05:33:02 +0000] "GET /stolen HTTP/1.1" 200 164 "-" "PostmanRuntime/7.37.0"
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 37 38 39 40 41 42 43 44 45 46 47 48 import loggingfrom logging import Formatterfrom logging.handlers import RotatingFileHandlerfrom aiohttp import webdef setup_logger (): logger = logging.getLogger("app_log" ) logger.setLevel(logging.INFO) file_handler = RotatingFileHandler(filename='app_log.log' ) formatter = Formatter('%(asctime)s - %(levelname)s - %(message)s' ) file_handler.setFormatter(formatter) file_handler.setLevel(logging.ERROR) logger.addHandler(file_handler) def config_server (): pass async def handle (request: web.Request ) -> web.Response: name = request.match_info.get('name' , "Anonymous" ) text = "Hello, " + name if name == "Anonymous" : logging.info("Console log: Hello, Anonymous" ) return web.Response(text=text) app = web.Application() app.add_routes([web.get('/' , handle), web.get('/{name}' , handle)]) def main (): logger = logging.getLogger("app_log" ) setup_logger() config_server() web.run_app(app, host="0.0.0.0" , port=8000 , access_log=logger) if __name__ == '__main__' : main()