Python Function with FastAPI: how to debug timeouts with no stacktrace in Application Insights

Question

Python Function with FastAPI: how to debug timeouts with no stacktrace in Application Insights

member45232 46

99% of you our fastapi requests are in the <500ms response time range. Yet we regularly see single requests that time out with no real pattern. From application insights we do not get a stacktrace or any info on what went wrong within our code. The "work" and logic the backend has to go through for generating the response is minimal, so we can't figure out why it fails sometimes.
How can we find the root cause of the timeouts?
Here is the information we see in Application insights:

EXCEPTION
Microsoft.Azure.WebJobs.Host.FunctionTimeoutException
Exception Properties
Show all
Event time 9/7/2022, 3:17:14.757 PM (Local time)
Message Timeout value of 00:05:00 was exceeded by function: Functions.app
Exception type Microsoft.Azure.WebJobs.Host.FunctionTimeoutException
Failed method Microsoft.Azure.WebJobs.Host.Executors.FunctionExecutor+<TryHandleTimeoutAsync>d__35.MoveNext
Custom Properties
HostInstanceId 99c-xxxxxxxxxxxx-8f8e
Category Host.Results
LogLevel Error
ProcessId 58
InvocationId 7146-xxxxx-f188c
prop__StartTime 2022-09-07T13:08:25.9510000Z
prop__Succeeded False
prop__EndTime 2022-09-07T13:17:14.7570000Z
prop__Name app
prop__InvocationId 7146-xxxxx-f188c
prop__FullName Functions.app
prop__Duration 00:08:48.8047449
prop__TriggerReason This function was programmatically called via the host APIs.
Call Stack

Microsoft.Azure.WebJobs.Host.FunctionTimeoutException:
at Microsoft.Azure.WebJobs.Host.Executors.FunctionExecutor+<TryHandleTimeoutAsync>d__35.MoveNext (Microsoft.Azure.WebJobs.Host, Version=3.0.34.0, Culture=neutral, PublicKeyToken=31EXCEPTION
Microsoft.Azure.WebJobs.Host.FunctionTimeoutException
Exception Properties
Show all
Event time 9/7/2022, 3:17:14.757 PM (Local time)
Message Timeout value of 00:05:00 was exceeded by function: Functions.app
Exception type Microsoft.Azure.WebJobs.Host.FunctionTimeoutException
Failed method Microsoft.Azure.WebJobs.Host.Executors.FunctionExecutor+<TryHandleTimeoutAsync>d__35.MoveNext
Custom Properties
HostInstanceId 99cxxxxxxxxxxe
Category Host.Results
LogLevel Error
ProcessId 58
InvocationId 714xxxxxxxxxxxxx188c
prop__StartTime 2022-09-07T13:08:25.9510000Z
prop__Succeeded False
prop__EndTime 2022-09-07T13:17:14.7570000Z
prop__Name app
prop__InvocationId 7146-xxxxx-88c
prop__FullName Functions.app
prop__Duration 00:08:48.8047449
prop__TriggerReason This function was programmatically called via the host APIs.
Call Stack

Just my code
Copy

Expand

Microsoft.Azure.WebJobs.Host.FunctionTimeoutException:
at Microsoft.Azure.WebJobs.Host.Executors.FunctionExecutor+<TryHandleTimeoutAsync>d__35.MoveNext (Microsoft.Azure.WebJobs.Host, Version=3.0.34.0, Culture=neutral, PublicKeyToken=31xxxxxxxxx35: C:\projects\azure-webjobs-sdk-rqm4t\src\Microsoft.Azure.WebJobs.Host\Executors\FunctionExecutor.cs:663)
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7xxxxxxxxxxxxxe)
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7xxxxxxxxxxxxxe)
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7xxxxxxxxxxxxxe)
at Microsoft.Azure.WebJobs.Host.Executors.FunctionExecutor+<InvokeWithTimeoutAsync>d__33.MoveNext (Microsoft.Azure.WebJobs.Host, Version=3.0.34.0, Culture=neutral, PublicKeyToken=31xxxxxxxxx35: C:\projects\azure-webjobs-sdk-rqm4t\src\Microsoft.Azure.WebJobs.Host\Executors\FunctionExecutor.cs:571)
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7xxxxxxxxxxxxxe)
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7xxxxxxxxxxxxxe)
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7xxxxxxxxxxxxxe)
at Microsoft.Azure.WebJobs.Host.Executors.FunctionExecutor+<ExecuteWithWatchersAsync>d__32.MoveNext (Microsoft.Azure.WebJobs.Host, Version=3.0.34.0, Culture=neutral, PublicKeyToken=31xxxxxxxxx35: C:\projects\azure-webjobs-sdk-rqm4t\src\Microsoft.Azure.WebJobs.Host\Executors\FunctionExecutor.cs:527)
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7xxxxxxxxxxxxxe)
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7xxxxxxxxxxxxxe)
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7xxxxxxxxxxxxxe)
at Microsoft.Azure.WebJobs.Host.Executors.FunctionExecutor+<ExecuteWithLoggingAsync>d__26.MoveNext (Microsoft.Azure.WebJobs.Host, Version=3.0.34.0, Culture=neutral, PublicKeyToken=31xxxxxxxxx35: C:\projects\azure-webjobs-sdk-rqm4t\src\Microsoft.Azure.WebJobs.Host\Executors\FunctionExecutor.cs:306)
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7xxxxxxxxxxxxxe)
at Microsoft.Azure.WebJobs.Host.Executors.FunctionExecutor+<ExecuteWithLoggingAsync>d__26.MoveNext (Microsoft.Azure.WebJobs.Host, Version=3.0.34.0, Culture=neutral, PublicKeyToken=31xxxxxxxxx35: C:\projects\azure-webjobs-sdk-rqm4t\src\Microsoft.Azure.WebJobs.Host\Executors\FunctionExecutor.cs:352)
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7xxxxxxxxxxxxxe)
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7xxxxxxxxxxxxxe)
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7xxxxxxxxxxxxxe)
at Microsoft.Azure.WebJobs.Host.Executors.FunctionExecutor+<TryExecuteAsync>d__18.MoveNext (Microsoft.Azure.WebJobs.Host, Version=3.0.34.0, Culture=neutral, PublicKeyToken=31xxxxxxxxx35: C:\projects\azure-webjobs-sdk-rqm4t\src\Microsoft.Azure.WebJobs.Host\Executors\FunctionExecutor.cs:108)
EXCEPTION
Microsoft.Azure.WebJobs.Host.FunctionTimeoutException
Exception Properties
Show all
Event time 9/7/2022, 3:17:14.757 PM (Local time)
Message Timeout value of 00:05:00 was exceeded by function: Functions.app
Exception type Microsoft.Azure.WebJobs.Host.FunctionTimeoutException
Failed method Microsoft.Azure.WebJobs.Host.Executors.FunctionExecutor+<TryHandleTimeoutAsync>d__35.MoveNext
Custom Properties
HostInstanceId 99cc-xxxxx-f8e
Category Host.Results
LogLevel Error
ProcessId 58
InvocationId 7146-xxxxx-88c
prop__StartTime 2022-09-07T13:08:25.9510000Z
prop__Succeeded False
prop__EndTime 2022-09-07T13:17:14.7570000Z
prop__Name app
prop__InvocationId 7146-xxxxxx-188c
prop__FullName Functions.app
prop__Duration 00:08:48.8047449
prop__TriggerReason This function was programmatically called via the host APIs.
Call Stack

Mohanraj Durairaj 1 Reputation point

2022-09-14T18:17:34.13+00:00

Could you please show the code on the entry function? How you are starting the fastapi?

member45232 46

here is a shortened version of our entry point main.py:

import logging  
import logging.config  


import azure.functions as func  
import nest_asyncio  
from fastapi import FastAPI  
from fastapi.middleware.cors import CORSMiddleware  

from .routes import router  
from .settings import auth_settings, azure_scheme, fastapi_settings, log_config  

logging.config.dictConfig(log_config)  


fastapi_app = FastAPI(**fastapi_settings.__dict__)  
fastapi_app.include_router(router)  


@fastapi_app.on_event("startup")  
async def startup() -> None:  

    await azure_scheme.openid_config.load_config()  
    fastapi_app.add_middleware(  
        CORSMiddleware,  
        allow_origins=[str(origin) for origin in auth_settings.BACKEND_CORS_ORIGINS],  
        allow_credentials=True,  
        allow_methods=["*"],  
        allow_headers=["*"],  
    )  

nest_asyncio.apply()  


async def main(req: func.HttpRequest, context: func.Context) -> func.HttpResponse:  
    """Run in azure environment"""  
    startup()  # startup event does not get triggered by azure  
    return func.AsgiMiddleware(fastapi_app).handle(req, context)

Mohanraj Durairaj 1 Reputation point

2022-09-14T18:17:34.13+00:00

Could you please show the code on the entry function? How you are starting the fastapi?
member45232 46 Reputation points

2022-09-18T22:40:24.493+00:00

here is a shortened version of our entry point main.py:

import logging import logging.config import azure.functions as func import nest_asyncio from fastapi import FastAPI from fastapi.middleware.cors import CORSMiddleware from .routes import router from .settings import auth_settings, azure_scheme, fastapi_settings, log_config logging.config.dictConfig(log_config) fastapi_app = FastAPI(**fastapi_settings.__dict__) fastapi_app.include_router(router) @fastapi_app.on_event("startup") async def startup() -> None: await azure_scheme.openid_config.load_config() fastapi_app.add_middleware( CORSMiddleware, allow_origins=[str(origin) for origin in auth_settings.BACKEND_CORS_ORIGINS], allow_credentials=True, allow_methods=["*"], allow_headers=["*"], ) nest_asyncio.apply() async def main(req: func.HttpRequest, context: func.Context) -> func.HttpResponse: """Run in azure environment""" startup() # startup event does not get triggered by azure return func.AsgiMiddleware(fastapi_app).handle(req, context)

Answer 1

Ryan Hill 16,526 Microsoft Employee

This may or may not help but I would start with Application Map. This should help provide insight into the request(s) that's timing out and any associated dependencies with the said request. Storage accounts, databases, custom DNS, even App Insights itself could be issues that's causing your timeout issue.

member45232 46 Reputation points

2022-09-14T18:10:20.827+00:00

The application map shows the slowest request of the past 7 days as 350ms, which does not match with what I see when I look at the slowest transactions. We have requests slower than a minute.

Python Function with FastAPI: how to debug timeouts with no stacktrace in Application Insights

1 answer

Activity