辅助线程中的 Python 日志记录语句未出现在 Azure 函数日志中

Question

背景

我正在将 Python 代码部署到 Azure Function，该函数利用线程来处理并发进程，并在代码执行时记录代码的进程。在部署到我的函数应用程序之前，我正在使用 Azure Function 核心工具在 VSCode 上本地测试我的函数应用程序代码。

我希望代码中的所有日志语句在使用 Azure Function 核心工具进行测试时出现在本地终端中，以及在通过应用程序触发代码时出现在函数应用程序的日志记录部分中。

问题

通过线程调用的工作函数内的日志语句不会出现在函数应用程序日志中，尽管出现在本地终端中。代码中可以看到尝试使日志在函数应用日志终端中可见，例如配置记录器对象和传递上下文调用 id。

版本

Python 版本 3.10.10 (py)。

Azure Functions 核心工具
核心工具版本：4.0.5148 提交哈希：N/A（64 位）
函数运行时版本：4.17.3.20392

Python 包
天蓝色函数==1.13.3

VS Code：版本1.92.0（系统设置）

代码

# Imports
import azure.functions as func
import logging
import threading
import time
import sys

# Start of the function
# Wrap around a function to trigger that
# function from the azure function
app = func.FunctionApp()

# Define a thread-local storage object
thread_local = threading.local()

class ContextFilter(logging.Filter):
    """
    Logging filter to add invocation ID from
    thread-local storage to log records.
    """
    def __init__(self, thread_local):
        super().__init__()
        self.thread_local = thread_local
        
    def filter(self, record):
        record.invocation_id = getattr(self.thread_local, 'invocation_id', 'N/A')
        return True

# Initialise logging object and set level to info
def configure_logger():
    """
    Function to configure logger.
    """
    logger = logging.getLogger(__name__)
    logger.setLevel(logging.INFO)

    # Remove any existing handlers
    if logger.hasHandlers():
        logger.handlers.clear()

    # Create console handler and set level to info
    ch = logging.StreamHandler()
    ch.setLevel(logging.INFO)

    # Create formatter
    formatter = logging.Formatter('%(message)s')
    ch.setFormatter(formatter)

    # Add filter to handler
    ch.addFilter(ContextFilter(thread_local))

    # Add handler to logger
    logger.addHandler(ch)
    
    return logger

# Configure global logger
logger = configure_logger()

def worker(number, invocation_id):
    """
    Function that is called within the thread.
    """
    # Each thread must set its own thread-local data
    thread_local.invocation_id = invocation_id
    
    # Ensure logger configuration within the thread
    thread_logger = configure_logger()
    
    thread_logger.info(f'Thread {number} is starting')
    time.sleep(1)
    thread_logger.info(f'Thread {number} is finishing')
    
    # Ensure logs are flushed
    for handler in thread_logger.handlers:
        handler.flush()

@app.blob_trigger(arg_name="myblob", path="inputcontainer/{name}", connection="MyStorageConnectionString") 
def azure_function_entrypoint(myblob: func.InputStream, context: func.Context):
    """
    Main function run by Azure Function app.
    """
    # Store invocation ID in thread-local storage
    thread_local.invocation_id = context.invocation_id
    
    logger.info("Main function: Start of thread loop")
    for i in range(5):
        thread = threading.Thread(target=worker, args=(i, context.invocation_id))
        thread.start()
        thread.join()
    logger.info("Main function: End of thread loop")

实际产量

VSCode 中的本地终端（使用 Azure Function 核心工具测试应用程序，某些 ID 已匿名）

[2024-08-06T09:59:45.174Z] Executing 'Functions.azure_function_entrypoint' (Reason='New blob detected(LogsAndContainerScan): inputcontainer/<file name>', Id=<id>)
[2024-08-06T09:59:45.181Z] Trigger Details: MessageId: <message id>, DequeueCount: 1, InsertedOn: <datetime>, BlobCreated: <datetime>, BlobLastModified: <datetime>
[2024-08-06T09:59:45.291Z] Main function: Start of thread loop
[2024-08-06T09:59:45.294Z] Thread 0 is starting
[2024-08-06T09:59:45.305Z] Main function: Start of thread loop
[2024-08-06T09:59:46.301Z] Thread 0 is finishing
[2024-08-06T09:59:46.305Z] Thread 1 is starting
[2024-08-06T09:59:47.310Z] Thread 1 is finishing
[2024-08-06T09:59:47.317Z] Thread 2 is starting
[2024-08-06T09:59:48.319Z] Thread 2 is finishing
[2024-08-06T09:59:47.310Z] Thread 1 is finishing
[2024-08-06T09:59:47.317Z] Thread 2 is starting
[2024-08-06T09:59:47.310Z] Thread 1 is finishing
[2024-08-06T09:59:47.310Z] Thread 1 is finishing
[2024-08-06T09:59:47.310Z] Thread 1 is finishing
[2024-08-06T09:59:47.317Z] Thread 2 is starting
[2024-08-06T09:59:48.319Z] Thread 2 is finishing
[2024-08-06T09:59:48.323Z] Thread 3 is starting
[2024-08-06T09:59:48.433Z] Host lock lease acquired by instance ID '<Instance ID>'.
[2024-08-06T09:59:49.327Z] Thread 3 is finishing
[2024-08-06T09:59:49.331Z] Thread 4 is starting
[2024-08-06T09:59:50.339Z] Thread 4 is finishing
[2024-08-06T09:59:50.342Z] Main function: End of thread loop
[2024-08-06T09:59:50.345Z] Main function: End of thread loop
[2024-08-06T09:59:50.410Z] Executed 'Functions.azure_function_entrypoint' (Succeeded, Id=<id>, Duration=5384ms)

Azure 函数应用程序日志中的输出 [函数应用程序 -> 函数 -> 日志选项卡（在调用和指标之间）

2024-08-06T10:27:11Z   [Information]   Executing 'Functions.azure_function_entrypoint' (Reason='New blob detected(LogsAndContainerScan): inputcontainer/<file name>', Id=<id>)
2024-08-06T10:27:11Z   [Information]   Trigger Details: MessageId: <message id>, DequeueCount: 1, InsertedOn: <datetime>, BlobCreated: <datetime>, BlobLastModified: <datetime>
2024-08-06T10:27:11Z   [Verbose]   Sending invocation id: '<invocation id>
2024-08-06T10:27:11Z   [Verbose]   Posting invocation id:<invocation id> on workerId:<worker id>
2024-08-06T10:27:11Z   [Information]   Main function: Start of thread loop
2024-08-06T10:27:12Z   [Information]   Main function: End of thread loop
2024-08-06T10:27:12Z   [Information]   Executed 'Functions.azure_function_entrypoint' (Succeeded, Id=<id>, Duration=5284ms)

正在此处查看功能应用程序日志： Azure 函数日志终端