azure-sdk-for-net: [BUG] Timeout stopping Service Bus Processor

Description I discovered this issue when using the ServiceBusProcessor with IHostedService, but I was able to replicate the issue using the quickstart snippet

The processor itself is working fine, it was able to receive messages and successfully ‘completes’ it

Not sure what it is waiting for, as there is no message in the queue. I am relying on this method to function properly to ensure messages in flight gets put back in the queue if the app is shutting down.

Expected behaviour When StopProcessingAsync is called, the processor should gracefully stop processing any message, then successfully stops the processor before it times out

Actual behaviour (include Exception or Stack Trace) Calling StopProcessingAsync() freezes the app, then times out after 60 seconds

I added event listener to see what’s happening, and here’s the output

[Verbose] Azure-Messaging-ServiceBus: Creating a ServiceBusClient (Namespace: 'rezatest02.servicebus.windows.net', Entity name: ''
[Verbose] Azure-Messaging-ServiceBus: A ServiceBusClient has been created (Identifier 'rezatest02.servicebus.windows.net-f5ea72d8-b171-4955-93a6-bdbf746731f7').
[Informational] Azure-Messaging-ServiceBus: testsQueue-9f2ce687-d35d-461c-8890-ae12f5e0392a: StartProcessingAsync start.
[Verbose] Azure-Messaging-ServiceBus: Creating a ServiceBusReceiver (Namespace: 'rezatest02.servicebus.windows.net', Entity name: 'testsQueue'
[Verbose] Azure-Messaging-ServiceBus: A ServiceBusReceiver has been created (Identifier 'testsQueue-30ca4675-6030-4047-8250-2cc6ec50ebe7').
[Informational] Azure-Messaging-ServiceBus: testsQueue-30ca4675-6030-4047-8250-2cc6ec50ebe7: ReceiveBatchAsync start. MessageCount = 1
[Informational] Azure-Messaging-ServiceBus: Creating receive link for Identifier: testsQueue-30ca4675-6030-4047-8250-2cc6ec50ebe7.
[Informational] Azure-Messaging-ServiceBus: testsQueue-9f2ce687-d35d-461c-8890-ae12f5e0392a: StartProcessingAsync done.
Wait for a minute and then press any key to end the processing
[Informational] Azure-Messaging-ServiceBus: Receive link created for Identifier: testsQueue-30ca4675-6030-4047-8250-2cc6ec50ebe7. Session Id: 

[4:14:47 pm]Stopping the receiver...
[Informational] Azure-Messaging-ServiceBus: testsQueue-9f2ce687-d35d-461c-8890-ae12f5e0392a: StopProcessingAsync start.
[Error] Azure-Messaging-ServiceBus: testsQueue-30ca4675-6030-4047-8250-2cc6ec50ebe7: ReceiveBatchAsync Exception: System.Threading.Tasks.TaskCanceledException: A task was canceled.
   at Azure.Messaging.ServiceBus.Core.CancellationTokenExtensions.ThrowIfCancellationRequested[T](CancellationToken instance)
   at Azure.Messaging.ServiceBus.Amqp.AmqpReceiver.ReceiveMessagesAsyncInternal(Int32 maxMessages, Nullable`1 maxWaitTime, TimeSpan timeout, CancellationToken cancellationToken)
   at Azure.Messaging.ServiceBus.Amqp.AmqpReceiver.ReceiveMessagesAsyncInternal(Int32 maxMessages, Nullable`1 maxWaitTime, TimeSpan timeout, CancellationToken cancellationToken)
   at Azure.Messaging.ServiceBus.Amqp.AmqpReceiver.<>c__DisplayClass33_0.<<ReceiveMessagesAsync>b__0>d.MoveNext()
--- End of stack trace from previous location ---
   at Azure.Messaging.ServiceBus.ServiceBusRetryPolicy.RunOperation(Func`2 operation, TransportConnectionScope scope, CancellationToken cancellationToken)
   at Azure.Messaging.ServiceBus.ServiceBusRetryPolicy.RunOperation(Func`2 operation, TransportConnectionScope scope, CancellationToken cancellationToken)
   at Azure.Messaging.ServiceBus.Amqp.AmqpReceiver.ReceiveMessagesAsync(Int32 maxMessages, Nullable`1 maxWaitTime, CancellationToken cancellationToken)
   at Azure.Messaging.ServiceBus.ServiceBusReceiver.ReceiveMessagesAsync(Int32 maxMessages, Nullable`1 maxWaitTime, CancellationToken cancellationToken).
[Informational] Azure-Messaging-ServiceBus: testsQueue-9f2ce687-d35d-461c-8890-ae12f5e0392a: StopProcessingAsync done.
[4:15:35 pm]Stopped receiving messages
[Verbose] Azure-Messaging-ServiceBus: Closing a ServiceBusClient (Identifier 'rezatest02.servicebus.windows.net-f5ea72d8-b171-4955-93a6-bdbf746731f7').
[Verbose] Azure-Messaging-ServiceBus: A ServiceBusClient has been closed (Identifier 'rezatest02.servicebus.windows.net-f5ea72d8-b171-4955-93a6-bdbf746731f7').

To Reproduce Steps to reproduce the behaviour (include a code snippet, screenshot, or any additional information that might help us reproduce the issue)

Create console app with snippet from https://docs.microsoft.com/en-us/azure/service-bus-messaging/service-bus-dotnet-get-started-with-queues#receive-messages-from-a-queue
Run the app
Press any key to trigger StopProcessingAsync()

Environment:

Azure.Messaging.ServiceBus 7.0.0
Tried Windows and Linux, both with .net core 3.1

About this issue

Original URL
State: closed
Created 3 years ago
Reactions: 4
Comments: 22 (13 by maintainers)

Commits related to this issue

CodeGen from PR 17734 in Azure/azure-rest-api-specs Add xms-ids for machinelearning, machinelearningcompute, machinelearningexperimentation and machinelearningservices (#17734) * add xmsids for machi... — committed to AzureSDKAutomation/azure-sdk-for-net by deleted user 2 years ago
CodeGen from PR 17734 in Azure/azure-rest-api-specs Add xms-ids for machinelearning, machinelearningcompute, machinelearningexperimentation and machinelearningservices (#17734) * add xmsids for machi... — committed to AzureSDKAutomation/azure-sdk-for-net by deleted user 2 years ago
CodeGen from PR 17734 in Azure/azure-rest-api-specs Add xms-ids for machinelearning, machinelearningcompute, machinelearningexperimentation and machinelearningservices (#17734) * add xmsids for machi... — committed to AzureSDKAutomation/azure-sdk-for-net by deleted user 2 years ago

Most upvoted comments

Regarding the workaround of changing the TryTimeout to 15 seconds, does that mean my services will make 4 times as many AMQP requests compared to the default? The client is using that timeout for long polling right? If so, could that cause any possible issues with placing extra burden on my namespaces?

Yes, if your queues are often empty, this would mean that the processor would end up doing 4x as many receive requests over a given period of time, which would impact the number of operations you are doing against your namespace and could subject you to throttling if you are doing more than 1000 operations per second (https://docs.microsoft.com/en-us/azure/service-bus-messaging/service-bus-throttling#what-are-the-credit-limits). If the queues generally contain messages, then it wouldn’t impact the number of requests, since the receive calls would return as soon as a message was retrieved.

Assuming ReceivingAmqpLink never has support for cancellation, are there any possibilities to work around that limitation? For example could the AmqpReceiver be placed into a state of “stopping” to quickly return to the caller for Close/Dispose? In a stopping state maybe it could reject any new messages so that the link timeout can happen asynchronously and probably even just allow the process to die much quicker.

I think this could be possible but it would still require work in the underlying AMQP library which lives here - https://github.com/Azure/azure-amqp. I think we can also consider having special behavior in the Service Bus SDK where we will attempt to shutdown the link early even if a receive call is in process for the specific case of stopping the processor.

JoshLove-msft on Jan 18, 2021