[BUG] Logging not working from other threads

[ManelBH]

Reopenning #1158 because it's still broken in later versions:

Investigative information

Python version: 3.10.11
Core Tools Version: 4.0.5413
Function Runtime Version: 4.25.3.21264

Repro steps

dispatch a function that uses logging to a background thread

Expected behavior

The logged text appears in the logs

Actual behavior

The text isn't logged

Example:

import logging
from concurrent.futures import ThreadPoolExecutor
import azure.functions as func

def main(req: func.HttpRequest) -> func.HttpResponse:
    logging.info('Python HTTP trigger function processed a request.')

    with ThreadPoolExecutor() as pool:
        pool.submit(foo)

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


def foo():
    logging.info("Hello from foo")
    print("foo completed")

When I trigger this, In the console I can see "foo completed" but not "Hello from foo".

Contents of the requirements.txt file:

azure-functions==1.17.0

[ManelBH]

Just updated my core tools but still the same;

Core Tools Version: 4.0.5455
Function Runtime Version: 4.27.5.21554

[ManelBH]

Upon further investigation it looks like the"fix" was to pass to the client the responsibility of setting the thread's invocation_id which was the root cause.

def thread_function(context: func.Context, message: int):
    context.local_thread.invocation_id = context.invocation_id
    logging.info(message)

But this isn't a good solution, setting aside this is a runtime detail, we don't always control how the threads are created. For example when using the FastAPI framework which is what motivated the original issue. This is something the runtime should handle on its own.

[ashic]

I think I might be seeing something related to this. I'm working on a reproduction of the issue. With fastapi, a ContextVar set in a middleware sometimes disappears further down the request processing, specially if there's asyncio.gather on multiple async tasks. Running in uvicorn or gunicorn with many workers and threads doesn't cause the issue, but using AsgiMiddleware to wrap it in an azure function host does cause the failure. It appears the context gets lost.

[sriram9143]

ManelBH, I am facing the similar issue, But even after setting the thread's invocation_id as you mentioned,

def thread_function(context: func.Context, message: int):
    context.local_thread.invocation_id = context.invocation_id
    logging.info(message)

If suppose, we have a case where we also need to log something from inside of for-each loop of a function as below

def thread_function(context: func.Context, message: int):
    context.local_thread.invocation_id = context.invocation_id
    for i in range(0,10,1):
        logging.info(message)

The text isn't logged. It's only logging for the first message. Please do let me know if anyone has a fix for this,

[bhagyshricompany]

@gavin-aguiar pls comment validate.Thanks

[EvanR-Dev]

The reasoning behind the fix is that threads initiated by a user do not inherently contain a running event loop. Therefore, the worker validates whether threads have a running event loop; those lacking it will reference the local storage for that specific executing thread. To allow users access and distinguish these threads from other runtime threads, thread_local_storage has been exposed for safe usage.

For other runtime threads such as with FastAPI, this is a different issue with special cases. This issue here captures part of it: Azure-Samples/fastapi-on-azure-functions#11
which can be fixed by fetching the current logging instance as shown in the thread. But the logs will not be tracked properly in Application Insights. This highlights an issue in communicating with the host & App Insights - the logs are not properly being picked up and will require further investigation.

[EvanR-Dev]

This can be done inside a loop, here is a sample that I have tested with:

import azure.functions as func
import threading
import logging

app = func.FunctionApp(http_auth_level=func.AuthLevel.ANONYMOUS)

@app.route(route="http_trigger")
def http_trigger(req: func.HttpRequest, context: func.Context) -> func.HttpResponse:
    t1 = threading.Thread(target=thread_function, args=(context, 'Thread1 used.'))
    t1.start()
    
    return func.HttpResponse("Ok", status_code=200)
    
def thread_function(context: func.Context, message: str):
    context.thread_local_storage.invocation_id = context.invocation_id
    for _ in range(10):
        logging.info(message)

This prints Thread1 used. 10 times.

[sepira]

Was there any fixes on this? As we are trying to migrate to fastAPI

[nikie]

Azure Functions Python worker passes the invocation_id and thread_local_storage parameters inside
the ASGI request's scope attributes. They can be used to configure logging as per the Azure documentation
https://learn.microsoft.com/en-us/azure/azure-functions/functions-reference-python?tabs=asgi%2Capplication-level&pivots=python-mode-decorators (Logging from created threads).

The following workaround enables logs for FastAPI synchronous route handlers. Not very convenient as each sync handler needs to be wrapped with a decorator and have a Request parameter, but works.

from functools import wraps

from fastapi import Request


def logging_context_wrapper(func):
    """Passes invocation_id to the thread local context to enable proper Azure Functions logging.

    Can be applied to a sync handler which has request: Request parameter - to get the context from.
    """

    request_param = next(
        (param for (param, annotation) in func.__annotations__.items() if annotation is Request),
        None,
    )
    if not request_param:
        raise Exception("Function must have a request parameter of type Request.")

    @wraps(func)
    def wrapper(*args, **kwargs):
        request = kwargs[request_param]
        thread_local_storage = request.scope.get("azure_functions.thread_local_storage")
        if thread_local_storage is not None:
            thread_local_storage.invocation_id = request.scope.get("azure_functions.invocation_id")
        return func(*args, **kwargs)

    return wrapper

Usage:

from fastapi import Request


@app.get("/sample")
@logging_context_wrapper
def sample_handler(request: Request):
    logging.info("Sample log")
    return {
        "message": "Sample response",
    }

[anguspmitchell]

@nikie your solution worked for me, although not out of the box, since I was using some custom middleware written a couple years ago.

I also experienced some other quirks with Azure logging. I expanded upon it here - https://stackoverflow.com/a/78738009/5469472