How to redirect logs from secondary threads in Azure Functions using Python

Question

I am using Azure functions to run a Python script that launches multiple threads (for performance reasons). Everything is working as expected, except for the fact that only the info logs from the main() thread appear on the Azure Functions log. All the logs that I am using in the "secondary" threads that I start in main() do not appear in the Azure Functions logs.

Is there a way to ensure that the logs from the secondary threads show on the Azure Functions log?

The modules that I am using are "logging" and "threading".

I am using Python 3.6; I have already tried to lower the logging level in the secondary threads, but this did not help unfortunately. The various secondary thread functions are in different modules.

My function has a structure similar to the following pseudo-code:

def main()->None:
  logging.basicConfig(level=logging.INFO)
  logging.info("Starting the process...")
  thread1 = threading.Thread(target=foo,args=("one arg",))
  thread2 = threading.Thread(target=foo,args=("another arg",))
  thread3 = threading.Thread(target=foo,args=("yet another arg",))
  thread1.start()
  thread2.start()
  thread3.start()
  logging.info("All threads started successfully!")
  return

# in another module

def foo(st:str)->None:
  logging.basicConfig(level=logging.INFO)
  logging.info(f"Starting thread for arg {st}")

The current Azure log output is:

INFO: Starting the process...
INFO: "All threads started successfully!"

I would like it to be something like:

INFO: Starting the process...
INFO: Starting thread for arg one arg
INFO: Starting thread for arg another arg
INFO: Starting thread for arg yet another arg
INFO: All threads started successfully!

(of course the order of the secondary threads could be anything)

Answer 1

Azure functions Python worker framework sets AsyncLoggingHandler as a handler to the root logger. From this handler to its destination it seems logs are filtered along the path by an invocation_id.

An invocation_id is set if the framework starts threads itself, as it does for the main sync function. On the other hand if we start threads ourselves from the main function, we must set the invocation_id in the started thread for the logs to reach its destination.

This azure_functions_worker.dispatcher.get_current_invocation_id function checks if the current thread has a running event loop. If no running loop is found, it just checks azure_functions_worker.dispatcher._invocation_id_local, which is thread local storage, for an attribute named v for the value of invocation_id.

Because the threads we start doesn't have a running event loop, we have to get invocation_id from the context and set it on azure_functions_worker.dispatcher._invocation_id_local.v in every thread we start. The invocation_id is made available by the framework in context parameter of main function.

Tested it on Ubuntu 18.04, azure-functions-core-tools-4 and Python 3.8.

import sys
import azure.functions as func
import logging
import threading

# import thread local storage
from azure_functions_worker.dispatcher import (
    _invocation_id_local as tls,
)


def main(req: func.HttpRequest, context: func.Context) -> func.HttpResponse:
    logging.info("Starting the process...")
    thread1 = threading.Thread(
        target=foo,
        args=(
            context,
            "one arg",
        ),
    )
    thread2 = threading.Thread(
        target=foo,
        args=(
            context,
            "another arg",
        ),
    )
    thread3 = threading.Thread(
        target=foo,
        args=(
            context,
            "yet another arg",
        ),
    )
    thread1.start()
    thread2.start()
    thread3.start()
    logging.info("All threads started successfully!")

    name = req.params.get("name")
    if not name:
        try:
            req_body = req.get_json()
        except ValueError:
            pass
        else:
            name = req_body.get("name")

    if name:
        return func.HttpResponse(
            f"Hello, {name}. This HTTP triggered function executed successfully."
        )
    else:
        return func.HttpResponse(
            "This HTTP triggered function executed successfully. Pass a name in the query string or in the request body for a personalized response.",
            status_code=200,
        )


# in another module


def foo(context, st: str) -> None:
    # invocation_id_local = sys.modules[
    #     "azure_functions_worker.dispatcher"
    # ]._invocation_id_local
    # invocation_id_local.v = context.invocation_id

    tls.v = context.invocation_id

    logging.info(f"Starting thread for arg {st}")

https://github.com/Azure/azure-functions-python-worker/blob/81b84102dc14b7d209ad7e00be68f25c37987c1e/azure_functions_worker/dispatcher.py