[BUG] Lease already present after upgrading to Microsoft.Azure.WebJobs.Extensions.Storage 5.0.0-beta.3

[mauve]

Describe the bug

2021-06-02T12:43:49.889 [Warning] Error response [a89392d0-8a3c-44ba-b55e-8c56563e74ec] 409 There is already a lease present. (00.0s)Server:Windows-Azure-Blob/1.0,Microsoft-HTTPAPI/2.0x-ms-request-id:5a92e3cb-801e-002d-1eac-57e3e5000000x-ms-client-request-id:a89392d0-8a3c-44ba-b55e-8c56563e74ecx-ms-version:2020-04-08x-ms-error-code:LeaseAlreadyPresentDate:Wed, 02 Jun 2021 12:43:49 GMTContent-Length:221Content-Type:application/xml

Expected behavior

No warning

Actual behavior (include Exception or Stack Trace)

To Reproduce

1. update to 5.0.0-beta.3

Environment:

• azure functions v3
• dotnet core 3.1
• Microsoft.Azure.WebJobs.Extensions.Storage 5.0.0-beta.3

All project dependencies:

<Project Sdk="Microsoft.NET.Sdk">
  <PropertyGroup>
    <TargetFramework>netcoreapp3.1</TargetFramework>
    <AzureFunctionsVersion>V3</AzureFunctionsVersion>
  </PropertyGroup>
  <ItemGroup>
    <PackageReference Include="Azure.Identity" Version="1.4.0" />
    <PackageReference Include="Azure.Messaging.ServiceBus" Version="7.2.0-beta.3" />
    <PackageReference Include="Azure.Security.KeyVault.Secrets" Version="4.1.1" />
    <PackageReference Include="Azure.Storage.Blobs" Version="12.9.0-beta.4" />
    <PackageReference Include="Microsoft.Azure.Cosmos" Version="3.19.0" />
    <PackageReference Include="Microsoft.Azure.Devices" Version="1.34.0" />
    <PackageReference Include="Microsoft.Azure.Functions.Extensions" Version="1.1.0" />
    <PackageReference Include="Microsoft.Azure.WebJobs.Extensions.DurableTask" Version="2.4.3" />
    <PackageReference Include="Microsoft.Azure.WebJobs.Extensions.Storage.Blobs" Version="5.0.0-beta.3" />
    <PackageReference Include="Microsoft.Azure.WebJobs.Extensions.ServiceBus" Version="5.0.0-beta.3" />
    <PackageReference Include="Microsoft.Azure.WebJobs.Extensions" Version="4.0.1" />
    <PackageReference Include="Microsoft.Azure.WebJobs.Logging.ApplicationInsights" Version="3.0.27" />
    <PackageReference Include="Microsoft.Azure.WebJobs" Version="3.0.27" />
    <PackageReference Include="Microsoft.Extensions.DependencyInjection.Abstractions" Version="3.1.11" />
    <PackageReference Include="Microsoft.Extensions.Logging" Version="3.1.11" />
    <PackageReference Include="Microsoft.NET.Sdk.Functions" Version="3.0.12" />
    <PackageReference Include="Microsoft.ApplicationInsights" Version="2.17.0" />
  </ItemGroup>
  <ItemGroup>
    <None Update="host.json">
      <CopyToOutputDirectory>PreserveNewest</CopyToOutputDirectory>
    </None>
    <None Update="local.settings.json">
      <CopyToOutputDirectory>PreserveNewest</CopyToOutputDirectory>
      <CopyToPublishDirectory>Never</CopyToPublishDirectory>
    </None>
  </ItemGroup>
</Project>

[ghost]

Thanks for the feedback! We are routing this to the appropriate team for follow-up. cc @xgithubtriage.

Issue Details

---

Describe the bug

2021-06-02T12:43:49.889 [Warning] Error response [a89392d0-8a3c-44ba-b55e-8c56563e74ec] 409 There is already a lease present. (00.0s)Server:Windows-Azure-Blob/1.0,Microsoft-HTTPAPI/2.0x-ms-request-id:5a92e3cb-801e-002d-1eac-57e3e5000000x-ms-client-request-id:a89392d0-8a3c-44ba-b55e-8c56563e74ecx-ms-version:2020-04-08x-ms-error-code:LeaseAlreadyPresentDate:Wed, 02 Jun 2021 12:43:49 GMTContent-Length:221Content-Type:application/xml

Expected behavior

No warning

Actual behavior (include Exception or Stack Trace)

To Reproduce

1. update to 5.0.0-beta.3

Environment:

• azure functions v3
• dotnet core 3.1
• Microsoft.Azure.WebJobs.Extensions.Storage 5.0.0-beta.3

All project dependencies:

<Project Sdk="Microsoft.NET.Sdk">
  <PropertyGroup>
    <TargetFramework>netcoreapp3.1</TargetFramework>
    <AzureFunctionsVersion>V3</AzureFunctionsVersion>
  </PropertyGroup>
  <ItemGroup>
    <PackageReference Include="Azure.Identity" Version="1.4.0" />
    <PackageReference Include="Azure.Messaging.ServiceBus" Version="7.2.0-beta.3" />
    <PackageReference Include="Azure.Security.KeyVault.Secrets" Version="4.1.1" />
    <PackageReference Include="Azure.Storage.Blobs" Version="12.9.0-beta.4" />
    <PackageReference Include="Microsoft.Azure.Cosmos" Version="3.19.0" />
    <PackageReference Include="Microsoft.Azure.Devices" Version="1.34.0" />
    <PackageReference Include="Microsoft.Azure.Functions.Extensions" Version="1.1.0" />
    <PackageReference Include="Microsoft.Azure.WebJobs.Extensions.DurableTask" Version="2.4.3" />
    <PackageReference Include="Microsoft.Azure.WebJobs.Extensions.Storage.Blobs" Version="5.0.0-beta.3" />
    <PackageReference Include="Microsoft.Azure.WebJobs.Extensions.ServiceBus" Version="5.0.0-beta.3" />
    <PackageReference Include="Microsoft.Azure.WebJobs.Extensions" Version="4.0.1" />
    <PackageReference Include="Microsoft.Azure.WebJobs.Logging.ApplicationInsights" Version="3.0.27" />
    <PackageReference Include="Microsoft.Azure.WebJobs" Version="3.0.27" />
    <PackageReference Include="Microsoft.Extensions.DependencyInjection.Abstractions" Version="3.1.11" />
    <PackageReference Include="Microsoft.Extensions.Logging" Version="3.1.11" />
    <PackageReference Include="Microsoft.NET.Sdk.Functions" Version="3.0.12" />
    <PackageReference Include="Microsoft.ApplicationInsights" Version="2.17.0" />
  </ItemGroup>
  <ItemGroup>
    <None Update="host.json">
      <CopyToOutputDirectory>PreserveNewest</CopyToOutputDirectory>
    </None>
    <None Update="local.settings.json">
      <CopyToOutputDirectory>PreserveNewest</CopyToOutputDirectory>
      <CopyToPublishDirectory>Never</CopyToPublishDirectory>
    </None>
  </ItemGroup>
</Project>

Author:	mauve
Assignees:	-
Labels:	Client, Service Attention, Storage, customer-reported, needs-team-attention, needs-triage, question
Milestone:	-

[amnguye]

What version of Microsoft.Azure.WebJobs.Extensions.Storage are you upgrading from?

Also what code snippet causes the 409 Lease already present error?

[kasobol-msft]

This is most likely coming from https://github.com/Azure/azure-sdk-for-net/blob/0e7a91c5c18f4b5d1a41f4660d007dd5874b60ba/sdk/storage/Microsoft.Azure.WebJobs.Extensions.Storage.Blobs/src/Listeners/BlobReceiptManager.cs#L125-L144 . We'll look for ways to not report that warning.

[amnguye]

Relabeling as bug

[leniency]

This is still happening in the 5.0 release.

[mdarefull]

In case it helps,

I have one Consumption Function App with 3 functions: (simplified)

public Task<ActionResult> Post(
      [HttpTrigger(AuthorizationLevel.Anonymous, nameof(HttpMethods.Post))] HttpRequest httpRequest,
      [Blob("%DocumentsUploadContainer%/{rand-guid}", FileAccess.ReadWrite)] BlobClient blobClient,
      [Queue("%DocumentsUploadQueue%")] IAsyncCollector<DocumentMetadata> documentUploadMessages,
      CancellationToken cancellationToken) {...}

public Task ProcessScheduledDocumentUpload(
      [QueueTrigger("%DocumentsUploadQueue%")] DocumentMetadata metadata, string id, string popReceipt, long dequeueCount,
      [Blob("%DocumentsUploadContainer%/{blobName}", FileAccess.ReadWrite)] BlobClient blobClient,
      [Queue("%DocumentsUploadQueue%")] QueueClient queueClient) {...}

public Task CleanUpSessions(
      [TimerTrigger("%OnBaseSessionsMonitorSchedule%")] TimerInfo timer)

This function app has a dedicated storage account to which all functions refer to through the AzureWebJobsStorage App Settings variable.

This warning log is being generated ~70K times a day. This not only impacts the $$$ and the adaptive sampling features of my App Insight component, but since they are warning, they make it pretty hard to review the logs.

[jedjohan]

This is still happening in the 5.0 release.

Yes, also seeing it

[StephenCleary]

Just updated to the new .NET 6.0 with latest (non-prerelease) libraries and ~4 runtime (in-proc C# library), and this issue still occurs.

If you want to stem the AI log spam, setting Azure.Core to Error in your host.json seems to stop it:

{
  "version": "2.0",
  "logging": {
    "logLevel": {
      "default": "Information",
      "Azure.Core": "Error"
    }
  }
}

This unfortunately turns off all of the Azure.Core logs, most particularly ResponseDelay which warns of slow function times.

For in-process function apps at least, there's a name deduplication that happens so that ResponseDelay is reported with category Azure.Core.1 instead of Azure.Core. So you might be able to include that one in your logs by adding "Azure.Core.": "Warning" to your host.json logging configuration. I haven't tried it since I have my own warning log message when a function takes too long.

[JohanKlijn]

FYI, I am using version 4.0.5 of Microsoft.Azure.WebJobs.Extensions.Storage, and I am seeing the same issue. Between the 7 and 20 lines per minute.

[amishra-dev]

@jaschrep-msft can you please pick this up.

[tg-msft]

We'd like the fix for this to align with https://github.com/Azure/azure-sdk-for-net/issues/25626 which we hope will be a common solution to this class of problems.

[shanselman]

I'm hitting this as well, here in the first week of Jan

[braddwalker]

This bug is a spam cannon for my logs

[maQus123]

Our log is flooded as well, any news on this?

[jim-hart-dev]

We're also seeing this. Any update? This is coming from our durable functions app, in a container in AKS. .net 6, functions v4

Error response [34d137f5-9af7-4e51-9203-a78120bbb4af] 409 There is already a lease present. (00.0s)
Server:Windows-Azure-Blob/1.0,Microsoft-HTTPAPI/2.0
x-ms-error-code:LeaseAlreadyPresent
SourceContext: Azure.Core

Project file

<Project Sdk="Microsoft.NET.Sdk">
	<PropertyGroup>
	  <TargetFramework>net6.0</TargetFramework>
	  <LangVersion>latestMajor</LangVersion>
		<AzureFunctionsVersion>v4</AzureFunctionsVersion>
		<DockerDefaultTargetOS>Linux</DockerDefaultTargetOS>
	</PropertyGroup>
	<PropertyGroup>
		<ServerGarbageCollection>false</ServerGarbageCollection>
	</PropertyGroup>
	<PropertyGroup Condition="'$(Configuration)|$(Platform)'=='Release|AnyCPU'">
		<TreatWarningsAsErrors>true</TreatWarningsAsErrors>
		<NoWarn>1701;1702;AD0001</NoWarn>
	</PropertyGroup>
	<PropertyGroup Condition="'$(Configuration)|$(Platform)'=='Debug|AnyCPU'">
		<TreatWarningsAsErrors>true</TreatWarningsAsErrors>
		<NoWarn>1701;1702;AD0001</NoWarn>
	</PropertyGroup>
	<ItemGroup>
		<PackageReference Include="Azure.Messaging.ServiceBus" Version="7.5.1" />
		<PackageReference Include="Azure.Storage.Queues" Version="12.8.0" />
		<PackageReference Include="Microsoft.Azure.Functions.Extensions" Version="1.1.0" />
		<PackageReference Include="Microsoft.Azure.WebJobs.Extensions.DurableTask" Version="2.6.1" />
		<PackageReference Include="Microsoft.Azure.WebJobs.Extensions.Storage" Version="5.0.0" />
		<PackageReference Include="Microsoft.Extensions.Diagnostics.HealthChecks.Abstractions" Version="6.0.1" />
		<PackageReference Include="Microsoft.NET.Sdk.Functions" Version="4.0.1" />
		<PackageReference Include="Microsoft.VisualStudio.Azure.Containers.Tools.Targets" Version="1.14.0" />
		<PackageReference Include="Serilog.AspNetCore" Version="4.1.0" />
		<PackageReference Include="Serilog.Exceptions" Version="8.0.0" />
		<PackageReference Include="Serilog.Expressions" Version="3.2.1" />
		<PackageReference Include="Serilog.Extensions.WebJobs" Version="0.6.1" />
		<PackageReference Include="Serilog.Formatting.Compact" Version="1.1.0" />
		<PackageReference Include="Serilog.Sinks.AzureServiceBus" Version="1.0.2" />
	</ItemGroup>
	<ItemGroup>
		<None Update="host.json">
			<CopyToOutputDirectory>PreserveNewest</CopyToOutputDirectory>
		</None>
		<None Update="local.settings.json">
			<CopyToOutputDirectory>PreserveNewest</CopyToOutputDirectory>
			<CopyToPublishDirectory>Never</CopyToPublishDirectory>
		</None>
		<None Update="serilog.settings.json">
			<CopyToOutputDirectory>Always</CopyToOutputDirectory>
		</None>
	</ItemGroup>
</Project>

[melborp]

I'd like to add and raise awareness why these issues should be taken quite seriously by product group.

The impact is two-fold:

• Noisy logging that is driving up the application insights costs due to low value trace messages. Messages such as "Lease already present", "Skipping ownership lease aquiring for somefunctionapp-control-... ". Yes, your customers are paying for these messages.
• Some of these behaviors (e.g. blobtrigger scanning change between v3 and v4) cause unnecessary load on storage account which is harder to notice due to infinite cloud scale, until you notice the cost rise due to storage account usage (which then also causes Azure Defender Costs to rise).

I've been hit by this twice now - once for non-durable functions with blob triggers that went on spiral trying to understand if retriggering is necessary and causes both insane blob storage usage growth and trace logging. This happened while migration from v3 to v4 and to .net 6. As mentioned here: "Azure.Core": "Error" helps with less trace logs, but to "fix" the storage usage, we had to move away from blob triggers to eventgrid + servicebus triggering instead. On one of the most used storage account, the problem caused 8 million additional transactions on storage per day for us. Add that we have about 10 environments and more than one storage account per environment - its becomes a noticeable cost and mess.

The second one is the durable function and the "Skipping ownership lease aquiring for somefunctionapp-control-". Its not merely an info message, your storage is being hit here as well (at least mine is). About 1.2 million transactions/day on the most used storage account linked to function app. I've yet to understand what is causing this, since the particular durable function for us is not in active usage - but it started after .net 6 / v4 migration.

[anirudhgarg]

@kasobol-msft and @jaschrep-msft are you looking at this ? Many customers are facing this.

[yoichiozaki]

@kasobol-msft @jaschrep-msft My customer is complaining of the same symptoms, and they are also being charged unnecessarily for Log Analytics, so the problem needs to be resolved as soon as possible. Will filtering by log level prevent unnecessary charges for Log Analytics?

[annelo-msft]

The required APIs should be available now in Azure.Core to be able to implement this feature. In order to suppress distributed tracing for a given status code, AddClassifier() should be called on RequestContext prior to passing it to the method in question. An example can be found in the TableServiceClient here.

Please reach out with any remaining questions on implementation.

[xmak]

When can we expect this to be fixed?

[jaschrep-msft]

@xmak the PR linked above your comment is the key to fixing this. We plan to get this out in our next release cycle. Once that API is available, the webjobs extension package will need to be updated to use the new API instead of the old one, passing in the appropriate error classification to avoid logging the response.