python python-3.x azure-functions python-multithreading

Python Logging Statements in Secondary Threads Not Appearing in Azure Function Logs

The Background

I am deploying Python code to an Azure Function which utilises threading to handle concurrent processes, and logging the process of the code as it executes. I am testing my function app code locally on VSCode using Azure Function core tools before deploying to my function app.

I am expecting all log statements in the code to appear in both the local terminal when testing using Azure Function core tools, and in the logging section of the function app when the code is triggered through the app.

The Problem

The logging statements within the worker function which is called through a thread do not appear in the function app logs despite appearing in the local terminal. Attempts to make the logs visible in the function app log terminal such as configuring a logger object and passing the context invocation id can be seen in the code.

The Versions

Python version 3.10.10 (py).

Azure Functions Core Tools
Core Tools Version: 4.0.5148 Commit hash: N/A (64-bit)
Function Runtime Version: 4.17.3.20392

Python Package
azure-functions==1.13.3

VS Code: Version 1.92.0 (system setup)

The Code

# 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")

Actual Output

Local terminal in VSCode (testing the app using Azure Function core tools, certain ids have been anonymised)

[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)

Output in Azure Function app logs [function app -> function -> logs tab (between invocations and metrics]

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)

The function app logs are being viewed here: The Azure Function Log Terminal

Expected Output

All logging statements shown in the local terminal during testing to also appear in the function app logs

Relevant Resources

Attempted to use the top answer from this question but I could not make it work as I think some argument names have been changed: How to redirect logs from secondary threads in Azure Functions using Python
Attempted to use Ryan Hill's response from this post but it raised the error "azure.functions has not method logging": https://learn.microsoft.com/en-us/answers/questions/1275935/how-do-you-configure-logging-properly-in-a-multi-t
Similar issue raised in this thread: https://github.com/Azure/azure-functions-python-worker/issues/1358

Solution

Keep the logs screen open when you upload the file to the storage container.

Uploaded a text file to the storage container inputcontainer:

enter image description here

Able to see the logs under function app=>logs section in portal:

enter image description here

You can find the complete function logs including log information in Application insights of your function app.

Navigate to Function app=>Settings=>Application insights, click on the connected resource:

enter image description here

The function logs can be monitored under Investigate=>Transaction search:

Able to see all the log statements related threads as below:

enter image description here

These logs can be monitored under Application insights=>Monitoring=>Logs as well.

Fetch the logs using traces query:

enter image description here