search

Azure / azure-functions-host

The host/runtime that powers Azure Functions
https://functions.azure.com
MIT License
1.94k stars 441 forks source link

Syncing function triggers by calling the functions runtime site failed #10078

Open kirk-marple opened 6 months ago

kirk-marple commented 6 months ago

Check for a solution in the Azure portal

I just noticed an error in two of our Function Apps today, and both in DEV and PROD.

In the Azure Portal, it's showing "Runtime version: Error", and says: We were not able to load some functions in the list due to errors. Refresh the page to try again. See details

Clicking 'see details' gives: image

It appears to be a problem syncing the web app triggers.

Strange thing, a different Function App, both in DEV and PROD, is fine and shows all the functions.

At this point, I have no idea what to investigate further. The APIs in the Function Apps seem to be up and running, but I'm concerned that they may stop working at some point.

The problem Function Apps load fine locally, and lists out all available functions.

I don't remember seeing this issue before, and looking at the last month, I'm not seeing any other errors in the Activity Log about this (prior to today), except for one on Apr 14.

I tried restarting the function apps, redeploying code, etc. and nothing changed the behavior. Also, this started out of the blue, and wasn't related to a recent new code deployment.

Expected behavior

Sync triggers to work correctly, and not give Forbidden or InternalServerError.

Actual behavior

Provide a description of the actual behavior observed.

Kudu logs shows:

This XML file does not appear to have any style information associated with it. The document tree is shown below.
<step title="BackgroundTrace" date="2024-04-25T17:41:19.307" instance="13aed7" url="synctriggers-operation" method="POST">
<step title="Updating shutdown sentinel last write time" date="2024-04-25T17:41:19.323" SemaphoreCount="6"/>
<!--  duration: 16ms  -->
<step title="Delaying '00:01:00' for Functions site to restart." date="2024-04-25T17:41:19.354"/>
<!--  duration: 16ms  -->
<step title="Begin HttpPost https://redacted-functions.azurewebsites.net/admin/host/synctriggers, x-ms-request-id: 2442b05a-458d-407f-a36f-ee2b2e660d76" date="2024-04-25T17:42:19.436"/>
<!--  duration: 31ms  -->
<step title="End HttpPost, status: InternalServerError" date="2024-04-25T17:42:19.748"/>
<!--  duration: 31ms  -->
<step title="Begin HttpPost https://redacted-functions.azurewebsites.net/admin/host/synctriggers, x-ms-request-id: 2442b05a-458d-407f-a36f-ee2b2e660d76" date="2024-04-25T17:42:20.814"/>
<!--  duration: 16ms  -->
<step title="End HttpPost, status: InternalServerError" date="2024-04-25T17:42:20.908"/>
<!--  duration: 16ms  -->
<step title="Begin HttpPost https://redacted-functions.azurewebsites.net/admin/host/synctriggers, x-ms-request-id: 2442b05a-458d-407f-a36f-ee2b2e660d76" date="2024-04-25T17:42:21.958"/>
<!--  duration: 16ms  -->
<step title="End HttpPost, status: InternalServerError" date="2024-04-25T17:42:22.039"/>
<!--  duration: 32ms  -->
<step title="Syncing function triggers by calling the functions runtime site failed. System.Net.Http.HttpRequestException: Response status code does not indicate success: 500 (Internal Server Error). at System.Net.Http.HttpResponseMessage.EnsureSuccessStatusCode() at Kudu.Core.Helpers.PostDeploymentHelper.<PostAsync>d__49.MoveNext() in C:\Kudu Files\Private\src\master\Kudu.Core\Helpers\PostDeploymentHelper.cs:line 720 --- End of stack trace from previous location where exception was thrown --- at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at Kudu.Core.Helpers.PostDeploymentHelper.<>c__DisplayClass38_1.<<TryFunctionsRuntimeSyncTriggers>b__1>d.MoveNext() in C:\Kudu Files\Private\src\master\Kudu.Core\Helpers\PostDeploymentHelper.cs:line 299 --- End of stack trace from previous location where exception was thrown --- at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at Kudu.Core.Infrastructure.OperationManager.<>c__DisplayClass4_0.<<AttemptAsync>b__0>d.MoveNext() in C:\Kudu Files\Private\src\master\Kudu.Core\Infrastructure\OperationManager.cs:line 57 --- End of stack trace from previous location where exception was thrown --- at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() at Kudu.Core.Infrastructure.OperationManager.<AttemptAsync>d__5`1.MoveNext() in C:\Kudu Files\Private\src\master\Kudu.Core\Infrastructure\OperationManager.cs:line 75 --- End of stack trace from previous location where exception was thrown --- at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at Kudu.Core.Helpers.PostDeploymentHelper.<TryFunctionsRuntimeSyncTriggers>d__38.MoveNext() in C:\Kudu Files\Private\src\master\Kudu.Core\Helpers\PostDeploymentHelper.cs:line 302" date="2024-04-25T17:42:22.103"/>
<!--  duration: 16ms  -->
<step title="Attempting to perform settriggers call directly." date="2024-04-25T17:42:22.134"/>
<!--  duration: 16ms  -->
<step title="Syncing httpTrigger of ClerkEndpoint" date="2024-04-25T17:42:22.243"/>
<!--  duration: 31ms  -->
<step title="Syncing httpTrigger of GraphQLEndpoint" date="2024-04-25T17:42:22.290"/>
<!--  duration: 31ms  -->
<step title="Skipping graphQL of GraphQLEndpoint" date="2024-04-25T17:42:22.337"/>
<!--  duration: 16ms  -->
<step title="Syncing httpTrigger of PingEndpoint" date="2024-04-25T17:42:22.384"/>
<!--  duration: 47ms  -->
<step title="Syncing httpTrigger of StripeEndpoint" date="2024-04-25T17:42:22.446"/>
<!--  duration: 16ms  -->
<step title="Syncing warmupTrigger of Warmup" date="2024-04-25T17:42:22.478"/>
<!--  duration: 31ms  -->
<step title="Begin HttpPost https://redacted-functions.scm.azurewebsites.net/operations/settriggers, x-ms-request-id: 2442b05a-458d-407f-a36f-ee2b2e660d76" date="2024-04-25T17:42:22.540"/>
<!--  duration: 16ms  -->
<step title="End HttpPost, status: OK" date="2024-04-25T17:42:22.728"/>
<!--  duration: 16ms  -->
<step title="Syncing 5 function triggers with payload size 628 bytes successful." date="2024-04-25T17:42:22.759"/>
<!--  duration: 16ms  -->
<step title="Deleting shutdown sentinel file" date="2024-04-25T17:42:22.821" SemaphoreCount="8"/>
<!--  duration: 16ms  -->
</step>
<!--  duration: 63545ms  -->

Activity log shows this error:

{
    "authorization": {
        "action": "Microsoft.Web/sites/host/sync/action",
        "scope": "/subscriptions/redacted/resourceGroups/redacted/providers/Microsoft.Web/sites/redacted-functions/host/default"
    },
    "caller": "redacted",
    "channels": "Operation",
    "claims": {
    [...]
    },
    "correlationId": "97decc8c-f17f-4aa0-9123-f59d7a12bf99",
    "description": "",
    "eventDataId": "0def156f-c83f-403e-9b44-4953e0eb9e62",
    "eventName": {
        "value": "EndRequest",
        "localizedValue": "End request"
    },
    "category": {
        "value": "Administrative",
        "localizedValue": "Administrative"
    },
    "eventTimestamp": "2024-04-29T02:23:01.7365522Z",
    "id": "/subscriptions/redacted/resourceGroups/redacted/providers/Microsoft.Web/sites/redacted-functions/host/default/events/0def156f-c83f-403e-9b44-4953e0eb9e62/ticks/638499541817365522",
    "level": "Error",
    "operationId": "bfa3928d-a50f-4c0c-b76c-ab815522fa9b",
    "operationName": {
        "value": "Microsoft.Web/sites/host/sync/action",
        "localizedValue": "Sync Web Apps Function Triggers"
    },
    "resourceGroupName": "redacted",
    "resourceProviderName": {
        "value": "Microsoft.Web",
        "localizedValue": "Azure Web Sites"
    },
    "resourceType": {
        "value": "Microsoft.Web/sites/host",
        "localizedValue": "Microsoft.Web/sites/host"
    },
    "resourceId": "/subscriptions/redacted/resourceGroups/redacted/providers/Microsoft.Web/sites/redacted-functions/host/default",
    "status": {
        "value": "Failed",
        "localizedValue": "Failed"
    },
    "subStatus": {
        "value": "BadRequest",
        "localizedValue": "Bad Request (HTTP Status Code: 400)"
    },
    "submissionTimestamp": "2024-04-29T02:26:03Z",
    "subscriptionId": "redacted",
    "tenantId": "7eb49dfd-a75d-4a38-9690-3b68b5efe173",
    "properties": {
        "statusCode": "BadRequest",
        "serviceRequestId": null,
        "statusMessage": "{\"Code\":\"BadRequest\",\"Message\":\"Encountered an error (InternalServerError) from host runtime.\",\"Target\":null,\"Details\":[{\"Message\":\"Encountered an error (InternalServerError) from host runtime.\"},{\"Code\":\"BadRequest\"},{\"ErrorEntity\":{\"Code\":\"BadRequest\",\"Message\":\"Encountered an error (InternalServerError) from host runtime.\"}}],\"Innererror\":null}",
        "eventCategory": "Administrative",
        "entity": "/subscriptions/redacted/resourceGroups/redacted/providers/Microsoft.Web/sites/redacted-functions/host/default",
        "message": "Microsoft.Web/sites/host/sync/action",
        "hierarchy": "7eb49dfd-a75d-4a38-9690-3b68b5efe173/redacted"
    },
    "relatedEvents": []
}

Related information

Provide any related information

.NET 6, C# Microsoft.NET.Sdk.Functions: 4.3.0

liliankasem commented 6 months ago

Hi @kirk-marple - for issues like this, please open a support ticket via the azure portal so that our team can investigate your prod application. Thanks!

kirk-marple commented 6 months ago

Hi @kirk-marple - for issues like this, please open a support ticket via the azure portal so that our team can investigate your prod application. Thanks!

No worries, I'll open a ticket, and close this out. Thanks!

kirk-marple commented 6 months ago

Support request filed: 2404290010004411 @liliankasem

Kerryliu commented 6 months ago

We are having the exact same issue as you described. What's odd is our stacks are identical between stages, and it's working perfectly fine in DEV.

kirk-marple commented 6 months ago

@liliankasem I believe I may have figured out the cause of this, and it may be a bug introduced in a recent version of the functions host. I'm talking to support about it, but I have a very minimal repro where calling 'builder.Services.AddAuthorization' in the FunctionsStartup class makes the /admin/host/status GET fail with a 500 error.

I'm seeing a few other reported bugs similar to this.

https://github.com/Azure/azure-functions-host/issues/10033 https://github.com/Azure/azure-functions-host/issues/10032

Happy to get you a link to the sample code to show you the repro.

liliankasem commented 6 months ago

Repro code would be great, thanks!

kirk-marple commented 6 months ago

Repro code would be great, thanks!

Here you go: https://github.com/graphlit/azure-functions-host-repro