azure-sdk-for-net: ServiceBusTrigger continously logs warnings about "The operation did not complete within the allocated time 00:01:00 for object receiverNNN"

@JoshLove-msft I totally agree that these messages should be at the Debug level. I don’t want to have to filter out this namespace specifically at the Informational level as there may be other messages that I do want to log. As no action can be performed by the developer to change whether or not these messages would appear, I see them as diagnostic and part of normal correct operation rather than something which should be logged with such frequency.

I would agree that for this specific retriable error, logging as verbose would be sufficient. In general, I think retries for exceptions that are not expected during the normal application flow should be Informational. I will take a look and see what we can do to improve this.

@JoshLove-msft I totally agree that these messages should be at the Debug level. I don’t want to have to filter out this namespace specifically at the Informational level as there may be other messages that I do want to log. As no action can be performed by the developer to change whether or not these messages would appear, I see them as diagnostic and part of normal correct operation rather than something which should be logged with such frequency.

@JoshLove-msft, Now I’m getting into details here, but I put it out there and you can ignore it if you don’t agree:

I usually like to have my log settings to write all informational, and more serious, to my logs. But I have seen that with the Functions SDK/Framework/Host a lot of “noise” is then written to the log. Things that I myself would have classified as “Trace” or “Debug” level log messages. In this case: something happens, it is by design and fully intentional, AND happens every minute - should that be considered of “Informational” log level? I don’t think so - I think it is just an implementation detail and should be either Trace or Debug log level.

Since there are 2 of these messages for every BlobTrigger function, every minute, and we have ~10 of these - that is 864 000 of these log messages per month!

Your own definition:

Logs that track the general flow of the application. These logs should have long-term value.

from https://docs.microsoft.com/en-us/azure/azure-functions/configure-monitoring?msclkid=46fd565fc06c11ecaf69608b1789989d&tabs=v2#configure-log-levels
Has it really any “long-term value” that the app behaves exactly as intended?

I am developing an azure function running in-process based on .net6. Function is triggered by a service bus.

I can confirm that I am struggling with the same problem described by @marnilss.

When the function runs locally and directly in Azure, it logs the following warnings:

RunOperation encountered an exception and will retry. Exception: Azure.Messaging.ServiceBus.ServiceBusException: The operation did not complete within the allocated time 00:01:00 for object receiver16. (ServiceTimeout)
 ---> System.TimeoutException: The operation did not complete within the allocated time 00:01:00 for object receiver16.
   at Microsoft.Azure.Amqp.AsyncResult.End[TAsyncResult](IAsyncResult result)
   at Microsoft.Azure.Amqp.AmqpObject.OpenAsyncResult.End(IAsyncResult result)
   at Microsoft.Azure.Amqp.AmqpObject.EndOpen(IAsyncResult result)
   at System.Threading.Tasks.TaskFactory`1.FromAsyncCoreLogic(IAsyncResult iar, Func`2 endFunction, Action`1 endAction, Task`1 promise, Boolean requiresSynchronization)
--- End of stack trace from previous location ---
   at Azure.Messaging.ServiceBus.Amqp.AmqpConnectionScope.OpenAmqpObjectAsync(AmqpObject target, TimeSpan timeout, CancellationToken cancellationToken, String entityPath)
   at Azure.Messaging.ServiceBus.Amqp.AmqpConnectionScope.OpenReceiverLinkAsync(String identifier, String entityPath, TimeSpan timeout, UInt32 prefetchCount, ServiceBusReceiveMode receiveMode, String sessionId, Boolean isSessionReceiver, CancellationToken cancellationToken)
   at Azure.Messaging.ServiceBus.Amqp.AmqpReceiver.OpenReceiverLinkAsync(TimeSpan timeout, UInt32 prefetchCount, ServiceBusReceiveMode receiveMode, String identifier, CancellationToken cancellationToken)
   at Microsoft.Azure.Amqp.FaultTolerantAmqpObject`1.OnCreateAsync(TimeSpan timeout, CancellationToken cancellationToken)
   at Microsoft.Azure.Amqp.Singleton`1.GetOrCreateAsync(TimeSpan timeout, CancellationToken cancellationToken)
   at Microsoft.Azure.Amqp.Singleton`1.GetOrCreateAsync(TimeSpan timeout, CancellationToken cancellationToken)
   at Azure.Messaging.ServiceBus.Amqp.AmqpReceiver.<>c.<<OpenLinkAsync>b__72_0>d.MoveNext()
--- End of stack trace from previous location ---
   at Azure.Messaging.ServiceBus.ServiceBusRetryPolicy.RunOperation[T1,TResult](Func`4 operation, T1 t1, TransportConnectionScope scope, CancellationToken cancellationToken)
   --- End of inner exception stack trace ---

Context

Function configuration:

<TargetFramework>net6.0</TargetFramework>
<AzureFunctionsVersion>v4</AzureFunctionsVersion>

Nuget packages:

<PackageReference Include="Microsoft.Azure.WebJobs.Extensions.ServiceBus" Version="5.3.0" />
<PackageReference Include="Microsoft.Azure.WebJobs.Host.Storage" Version="4.0.4" />
<PackageReference Include="Microsoft.NET.Sdk.Functions" Version="4.1.0" />

Seems related: https://github.com/Azure/azure-functions-servicebus-extension/issues/202 I moved from Microsoft.Azure.Functions.Worker.Extensions.ServiceBus beta 5 back to 4.2.1 and the warnings go away. Functionality is still correct.