Python : Logs are not coming in App Insight for async function using eventloop

[amitnanaware]

I am using azure function for one of our python function. We are using eventloop as described in document.

Below is sample of __init__.py

from typing import List
import logging
import json
import asyncio

import azure.functions as func

from .somepackage import SomeClass


async def main(events: List[func.EventHubEvent]):  # pragma: no cover
    """
    Starter function for the azure functions
    @param events:
    @return:
    """
    loop = asyncio.get_event_loop()
    tasks = []
    logging.info("Got %s events" % len(events))
    for idx, event in enumerate(events):
        event_body = json.loads(event.get_body().decode('utf8'))
        properties = event.metadata['PropertiesArray'][idx]
        logging.info("Got Event : %s with properties %s" % (event_body, properties))
        try:

            tasks.append(
                asyncio.create_task(wrapper_function(loop, event_body, properties)))
        except Exception as e:
            logging.exception("Error occurred while processing surface event trigger")
    if tasks:
        result, _ = await asyncio.wait(tasks)
        logging.info("Function : event processing done")


async def wrapper_function(event_loop, event_body, properties):
    some_obj = SomeClass()
    result = await event_loop.run_in_executor(None, some_obj.run, event_body, properties)
    return result

and this is content of somepackage.py file,

import logging


class SomeClass(object):

    def __init__(self):
        logging.info("Object created")

    def run(self, event_body, props):
        logging.info("event body is %s" % event_body)
        logging.info("Properties are %s" % props)

The logging statements from run function are not coming to app insight which is connected to our azure functions. If I use normal function instead of async eventloop it push the logs to app insight.

Please let me know if more details required on this.

Thanks

[shreyabatra4]

Hi @amitnanaware, are you still facing this issue?

[amitnanaware]

Hi @shreyabatra4 yes this issue is still exists.

On Mon, 7 Feb 2022 at 11:40 PM, Shreya Batra @.***> wrote:

Hi @amitnanaware https://github.com/amitnanaware, are you still facing this issue?

— Reply to this email directly, view it on GitHub https://github.com/Azure/azure-functions-python-worker/issues/898#issuecomment-1031765419, or unsubscribe https://github.com/notifications/unsubscribe-auth/AHBOPPETM4FILEWK2KYSX5DU2ADJ7ANCNFSM5F3GAJPA . Triage notifications on the go with GitHub Mobile for iOS https://apps.apple.com/app/apple-store/id1477376905?ct=notification-email&mt=8&pt=524675 or Android https://play.google.com/store/apps/details?id=com.github.android&referrer=utm_campaign%3Dnotification-email%26utm_medium%3Demail%26utm_source%3Dgithub.

You are receiving this because you were mentioned.Message ID: @.***>

[YunchuWang]

@amitnanaware thanks for raising this issue! We have investigated and root caused the problem. Essentially the host checks if invocation_id field (id generated by the host to identify each call to your function in function app.) is present in generated LogRecord object which wraps your log message, if yes then only it will log messages to AppInsights. For the missing logs you can't find in AppInsights is because invocation_id field is missing in LogRecord objects of your log messages.

Currently for the case if a function is a single threaded blocking function, invocation id is only set to thread local variable(_invocation_id_local) in worker managed executor's threads. (https://github.com/Azure/azure-functions-python-worker/blob/dev/azure_functions_worker/dispatcher.py#L644-L648). We do not set invocation_id to customer managed executor's threads, and even trying to set it, that _invocation_id_local variable is not accessible outside worker module and is not considered good practice.

(more for details at https://github.com/Azure/azure-functions-python-worker/blob/dev/azure_functions_worker/dispatcher.py#L742-L754 and https://github.com/Azure/azure-functions-host/blob/dev/src/WebJobs.Script.Grpc/Channel/GrpcWorkerChannel.cs#L696-L732).

Unfortunately sorry, there is no quick mitigation at current moment. We are tracking it internally and will continue investigating/working on good solutions as soon as possible.

[YunchuWang]

Tracking internally for investigation/fixing, closing this issue

[hrichardlee]

@YunchuWang do you know if this issue has been fixed or is still outstanding? I'm seeing similar symptoms (logs from an async function in an Azure Function have no effect, logs on the main thread show up in Application Insights as expected)

[TroyWitthoeft]

Same question. @YunchuWang - we closed the issue, but is it fixed?

If I create an azure function in python that spawns an async task, does not await it, and immediately returns a 202 to the caller, do I have any way to pipe that async task's logs to application insights?

[polavishnu4444]

Is this updated and fixed? Or still being tracked internally and someday appear suddenly in App Insights?

[YunchuWang]

sorry for late reply, the root cause of the issue is identified as event_loop.run_in_executor is executing the functions in eventloop's default threadpoolexecutor (https://docs.python.org/3/library/asyncio-eventloop.html#executing-code-in-thread-or-process-pools) which does not set the invocation id in thread local variable(_invocation_id_local https://github.com/Azure/azure-functions-python-worker/blob/c7a52362c0fcc50378a7a62b86b03b5a03836365/azure_functions_worker/dispatcher.py#L686-L694). please try the following example which executes run function in worker event loop asynchronously and logs are sent to appinsights:

let me know if you have any questions after trying

import threading
import logging
import json
import asyncio
import azure.functions as func

class SomeClass(object):

    def __init__(self):
        logging.info("Object created")

    def run(self, event_body, props):
        logging.info("Event body is %s" % event_body)
        logging.info("Properties are %s" % props)



async def main(req: func.HttpRequest) -> func.HttpResponse:
    result, _ = await asyncio.wait([asyncio.create_task(wrapper_function({"hello_azure_bw_2022": "sss"}, {"ee": "ss"}))])
    logging.info("Function : event processing done")
    print("Task assigned to thread: {}".format(
        threading.current_thread().name))
    return func.HttpResponse(
        json.dumps({'result': 'ok'}),
        status_code=200,
        mimetype="application/json"
    )


async def wrapper_function(event_body, properties):
    some_obj = SomeClass()
    return some_obj.run(event_body, properties)

[wallflower762]

I am trying to apply the above work around but have encountered 2 issues:

1. I am using the Azure storage queue trigger rather than http, so the context object is not available. How do I get the invocation_id?
2. Where you call wrapper_function, you pass 3 arguments to a function that accepts 2 arguments. How does this work?

[YunchuWang]

@wallflower762 updated the example, can you try again? thanks for feedback

[ghost]

This issue has been automatically marked as stale because it has been marked as requiring author feedback but has not had any activity for 4 days. It will be closed if no further activity occurs within 3 days of this comment.

[wallflower762]

I've just got back from holidays. I'll try and test this out in the next few weeks.

[ghost]

This issue has been automatically marked as stale because it has been marked as requiring author feedback but has not had any activity for 4 days. It will be closed if no further activity occurs within 3 days of this comment.