azure-functions-host
azure-functions-host copied to clipboard
Exceptions sent to AppInsights twice
When a function throws an exception, that exception is shown once in the console but is logged twice to AppInsights (testing that locally in Visual Studio) with different categories: Host.Results and Function.Function1.
Investigative information
Azure Functions Core Tools (3.0.2798 Commit hash: d9d99872a51c04b1c2783198b1ee1104da6b064f) Function Runtime Version: 3.0.14191.0
Repro steps
- Create a new C# FuncApp project in Visual Studio 2019.
- Add
"APPINSIGHTS_INSTRUMENTATIONKEY": "local"
tolocal.settings.json
. - Create an empty
ApplicationInsights.config
in the root folder. - Replace the function code with:
[FunctionName("Function1")]
public static void Run(
[HttpTrigger(AuthorizationLevel.Anonymous, "get", "post", Route = null)] HttpRequest req)
{
throw new ApplicationException("Test exception.");
}
- Execute the function.
Expected behavior
After I perform step 5, I see only one exception message both in the console window and in the Application Insights Search
window.
Actual behavior
I see two identical exceptions in the Application Insights Search
window with different categories:
Able to repro the Issue.
@gzuber can you please look into this further
cc @pragnagopa, @mhoeger
As mentioned in the issue, there are duplicate exceptions being created in the logs. I have further dug deep into all the possible logs. Below are my findings:
Repro Steps: Same as mentioned in the issue
Visual Studio- Debug Window: [2020-12-11T17:52:48.565Z] Executing 'Function1' (Reason='This function was programmatically called via the host APIs.', Id=e013a8b7-c377-4de3-ab08-e6c978c35c0b) [2020-12-11T17:52:48.590Z] C# HTTP trigger function processed a request. [2020-12-11T17:52:48.840Z] Executed 'Function1' (Failed, Id=e013a8b7-c377-4de3-ab08-e6c978c35c0b, Duration=274ms) [2020-12-11T17:52:48.841Z] System.Private.CoreLib: Exception while executing function: Function1. 6564-2: Test exception
Visual Studio- Application Insights Search:
After publishing the App, the same is the case with Application insights in portal. There are duplicate logs but coming from Function and host.
**Custom properties:
First Occurrence :**
HostInstanceId | 24996f33-1de8-4a3a-a3ef-2b7af722633b |
---|---|
ProcessId | 1028 |
LogLevel | Error |
Category | Host.Results |
InvocationId | e34a4d70-5200-469a-9e59-75f32aff23a9 |
prop__TriggerReason | This function was programmatically called via the host APIs. |
prop__InvocationId | e34a4d70-5200-469a-9e59-75f32aff23a9 |
prop__StartTime | 2020-12-11T19:03:21.4830000Z |
prop__Succeeded | FALSE |
prop__Duration | 00:00.3 |
prop__FullName | Function1 |
prop__EndTime | 2020-12-11T19:03:21.7590000Z |
prop__Name | Function1 |
Second occurrence:
FormattedMessage | Executed 'Function1' (Failed, Id=e34a4d70-5200-469a-9e59-75f32aff23a9, Duration=3ms) |
---|---|
HostInstanceId | 24996f33-1de8-4a3a-a3ef-2b7af722633b |
prop__{OriginalFormat} | Executed '{functionName}' ({status}, Id={invocationId}, Duration={executionDuration}ms) |
ProcessId | 1028 |
LogLevel | Error |
Category | Function.Function1 |
InvocationId | e34a4d70-5200-469a-9e59-75f32aff23a9 |
prop__executionDuration | 3 |
EventName | FunctionCompleted |
prop__invocationId | e34a4d70-5200-469a-9e59-75f32aff23a9 |
prop__functionName | Function1 |
EventId | 3 |
prop__status | Failed |
However, Kusto logs are producing only one log per time stamp. No duplicate logs produced in Kusto
Kusto Logs:
1. First run TimeStamp: : 2020-12-11 19:02:57.2747192 Invocation ID: e34a4d70-5200-469a-9e59-75f32aff23a9 2. Second run: TimeStamp: 2020-12-11 19:03:33.3249734 Invocation ID : d0ec5e3d-0540-4352-9b4f-b6455e603a1d
App name: 6564-2 Tenant : waws-prod-sn1-171 Role instance: dw0SmallDedicatedWebWorkerRole_IN_hr0HostRole-4-VM-1 2 Details: Executed 'Function1' (Failed, Id=584b5d01-0d63-4841-be2d-d316a290686e, Duration=191ms) Microsoft.Azure.WebJobs.Host.FunctionInvocationException : Exception while executing function: Function1 ---> System.ApplicationException : Test exception.
This is still a problem
This repros for a Python function app on Linux as well.
Python: 3.10 Functions runtime: 4.24.4.4
Function code:
import azure.functions as func
import logging
app = func.FunctionApp(http_auth_level=func.AuthLevel.FUNCTION)
@app.route(route="http_trigger")
def http_trigger(req: func.HttpRequest) -> func.HttpResponse:
logging.info('Python HTTP trigger function processed a request.')
raise Exception("test exception")
There are 2 records in the invocation traces with identical content except for the timestamp:
Log analytics query in the portal shows 2 instances of the failure for the same operation/invocation:
Does anyone know why this is happening? I have the same problem: only exceptions are being duplicated, the rest works fine.