Open ManelBH opened 7 months ago
Just updated my core tools but still the same;
Core Tools Version: 4.0.5455 Function Runtime Version: 4.27.5.21554
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.
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.
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,
@gavin-aguiar pls comment validate.Thanks
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: https://github.com/Azure-Samples/fastapi-on-azure-functions/issues/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.
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.
Was there any fixes on this? As we are trying to migrate to fastAPI
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",
}
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:
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