Azure Functions Python日志顺序异常：子模块日志晚于主函数结束

原因分析 #

这是Python logging 模块的异步缓冲机制结合Azure Functions平台日志处理逻辑导致的：

• Python默认会对日志输出做缓冲以提升IO性能，子模块里的logging.info("subfntest")会先存入缓冲区，而非立刻写入输出流。
• 主函数的main_end日志可能刚好在更早的缓冲批次被提交，或者函数执行到return前的操作触发了部分缓冲刷新，但子模块的日志缓冲区还没被强制刷新，直到函数执行完成后才被平台统一处理，最终导致日志顺序错乱。

解决方法 #

方法1：手动强制刷新日志缓冲区 #

在子模块日志输出后，或者主函数调用子模块后，手动刷新所有日志处理器的缓冲区，确保日志立刻输出：

修改子模块submodule/subfntest.py：

import logging

def subfntest()->None:
    logging.info("subfntest")
    # 遍历所有日志处理器并刷新缓冲区
    for handler in logging.getLogger().handlers:
        handler.flush()

或者在主函数中调用子模块后刷新：

@app.route(route="fntest")
def fntest(req: func.HttpRequest) -> func.HttpResponse:
    
    logging.info('main_start')
    subfntest()
    # 刷新日志缓冲区
    for handler in logging.getLogger().handlers:
        handler.flush()
    logging.info('main_end')

    return func.HttpResponse(
             "This HTTP triggered function executed successfully.",
             status_code=200
        )

方法2：修改日志配置，关闭缓冲 #

在函数启动时重置日志配置，使用无缓冲的输出处理器：

在function_app.py开头添加：

import logging
import sys

# 重置日志系统，使用无缓冲的StreamHandler
logging.basicConfig(
    level=logging.INFO,
    format='%(asctime)s %(levelname)s %(message)s',
    handlers=[logging.StreamHandler(sys.stdout)]
)

# 确保所有处理器无缓冲
for handler in logging.getLogger().handlers:
    if isinstance(handler, logging.StreamHandler):
        # 强制关闭缓冲
        handler.stream = sys.stdout
        handler.flush()

验证效果 #

修改后重新部署或运行函数，日志顺序会变为：

2023-07-17 12:37:20.097 Executing 'Functions.fntest' (Reason='This function was programmatically called via the host APIs.', Id=2c45312c-1d4e-4271-bf74-8439efdec03d)
2023-07-17 12:37:20.119 main_start Information
2023-07-17 12:37:20.121 subfntest Information
2023-07-17 12:37:20.123 main_end Information
2023-07-17 12:37:20.139 Executed 'Functions.fntest' (Succeeded, Id=2c45312c-1d4e-4271-bf74-8439efdec03d, Duration=42ms) Information

内容的提问来源于stack exchange，提问作者rmbt