Function App logs frequently getting "409 There is already a lease present" warnings

[TurakKatase]

Description

After updating various packages, I'm seeing a lot of warnings. When I deploy my Azure Function that contains a Durable Function, the logs are spitting out many warnings like so:

2021-09-24T17:03:43.011 [Information] Skipping ownership lease aquiring for devtaskhubkisrael-control-00
2021-09-24T17:03:43.515 [Warning] Error response [c3b39d09-e71e-4e9b-b849-01c589f380c4] 409 There is already a lease present. (00.0s)Server:Windows-Azure-Blob/1.0,Microsoft-HTTPAPI/2.0x-ms-request-id:64b12de3-901e-0009-1466-b128e7000000x-ms-client-request-id:c3b39d09-e71e-4e9b-b849-01c589f380c4x-ms-version:2020-04-08x-ms-error-code:LeaseAlreadyPresentDate:Fri, 24 Sep 2021 17:03:42 GMTContent-Length:221Content-Type:application/xml
2021-09-24T17:03:43.710 [Information] Skipping ownership lease aquiring for devtaskhubkisrael-control-01
2021-09-24T17:03:43.710 [Information] Skipping ownership lease aquiring for devtaskhubkisrael-control-02
2021-09-24T17:03:43.710 [Information] Skipping ownership lease aquiring for devtaskhubkisrael-control-03
2021-09-24T17:03:43.742 [Information] devtaskhubkisrael-control-01: Attempting to steal lease from RD00155D3647AB
2021-09-24T17:03:43.757 [Information] devtaskhubkisrael-control-01: Successfully stole lease from RD00155D3647AB
2021-09-24T17:03:43.979 [Warning] Error response [4431c131-fbb9-4eba-b4f0-22fc4eae0eed] 409 There is already a lease present. (00.0s)Server:Windows-Azure-Blob/1.0,Microsoft-HTTPAPI/2.0x-ms-request-id:9cc0116c-c01e-0077-6666-b1b728000000x-ms-client-request-id:4431c131-fbb9-4eba-b4f0-22fc4eae0eedx-ms-version:2020-04-08x-ms-error-code:LeaseAlreadyPresentDate:Fri, 24 Sep 2021 17:03:43 GMTContent-Length:221Content-Type:application/xml

These warnings are occurring at a rate of every 5 seconds, in groups of 1 -4. It appears to be related to the TaskHub Leases.

Expected behavior

These warnings to not be occurring like before we updated packages

Actual behavior

Every 5 seconds 1-4 warnings occur about a lease being already present.

Known workarounds

Workarounds are not technically needed, as it appears the durable functions still work. But it makes a mess out of our logs. I'm also unsure what might be going wrong and how it could impact reliability.

App Details

Language: C#

Primarily related is that we changed from Microsoft.Azure.WebJobs.Extensions.Storage to Azure.Storage.Blobs and Azure.Storage.Queues. This lead to us updating Microsoft.Azure.WebJobs.Extensions.Storage to 5.0.0-beta.5.

Microsoft.NET.Sdk.Functions: 3.0.13
Microsoft.Azure.WebJobs.Extensions.DurableTask is 2.5.1.

If deployed to Azure

• Timeframe issue observed: Every 5 seconds. Example logs taken form 2021-09-24T17:03:43
• Function App name: devemma-kisrael
• Function name(s): N/A, happens without running any functions, the Function App Host just needs to be running
• Azure region: USGov Virginia
• Orchestration instance ID(s): N/A
• Azure storage account name: emmadevfunctions

[cgillum]

@TurakKatase I don't recognize those warning logs you're seeing. They don't look like any log messages we write. I took a look in our internal log store for that time range and I see the Informational logs but I don't see those warning logs, which makes me think they're being written by something else.

Can you tell us more about where you're seeing these logs? For example, are they from Application Insights? Do you have any other apps that might also be writing to this Application Insights account?

[TurakKatase]

@cgillum I'm seeing these logs in the Function App Log stream, though they also appear in Application Insights. Looking at the Application Insights version, I see it has a category of Azure.Core instead of DurableTask.AzureStorage like the logs you see in your internal log store.

Perhaps the blob package update we took is now causing these warnings to be logged.

[TurakKatase]

OK, looks like this is indeed coming from outside of the Durable extension library. I found Azure/azure-sdk-for-net#21511 which is the same issue and is acknowledged by the team as a bug. Closing this issue.