Masstransit: AzureServiceBus: Messages Are Inconsistently Consumed (Stuck) After Transient Errors on Azure Side

[paulsavides]

Is this a bug report?

Yes

Can you also reproduce the problem with the latest version?

Yes, using MassTransit.Azure.ServiceBus.Core v7.0.4

Environment

1. Operating system: Windows 10
2. Visual Studio version: 2019 (16.7.6)
3. Dotnet version: 3.1.403
4. AzureServiceBus Standard Tier

Steps to Reproduce

1. Clone reproduction project here >> https://github.com/paulsavides/ServiceBusTesting
2. In ReproProjectMassTransit/Program.cs fill in Endpoint & SharedAccessSignature with valid service bus connection
3. Run ReproProjectMassTransit
   
   
   
   • This project just publishes & consumes a message every five seconds
   
   
4. In Azure Portal, open up the service bus & open up the queue named 'repro.project.mass.transit.queue'
5. Continually edit the queue auto-delete setting until you can see a batch of The link (link name) was force reset errors appear in the console output or logfile.
6. Once that error is seen, peek the queue and it may have gotten into a state where every other-ish message is getting "stuck" in the queue
   
   
   
   • reproduction is not entirely consistent, so go back to step 5 if not seen.
   
   

I have recorded an issue reproduction here to show as steps five and six are a bit odd.
Reproduction recording = https://www.youtube.com/watch?v=sv0bRozEevs

This reproduction is inspired by the "Important" section of this documentation https://docs.microsoft.com/en-us/azure/service-bus-messaging/message-transfers-locks-settlement#peeklock . We have generally encountered this issue during periods where Microsoft was rolling out updates to azure service bus. The linked documentation indicates that service updates and general queue updates would cause similar problems.

You may notice that repository also includes a similar concept but using the azure sdk directly. I was not personally able to reproduce the issue just using that sdk.

Expected Behavior

Going again from the linked documentation (https://docs.microsoft.com/en-us/azure/service-bus-messaging/message-transfers-locks-settlement#peeklock). It would make sense that messages in flight would lose access to the lock, would need to wait the lock timeout and then need to be reprocessed.

Actual Behavior

For some amount of time after the initial error occurs, every few messages will get "stuck" in the queue. You can see what happens in the reproduction video starting here https://youtu.be/sv0bRozEevs?t=78

Any stuck message will wait at least the lock timeout before getting reprocessed. Some messages will also never get delivered & their delivery count will keep incrementing (once every lock timeout increment) until it gets moved to the dead letter queue.

Reproducible Demo

Repo >> https://github.com/paulsavides/ServiceBusTesting (ReproProjectMassTransit project)
ReproVideo >> https://www.youtube.com/watch?v=sv0bRozEevs

--

Please let me know if there is any further information I can provide.

Thank you,
Paul Savides

[paulsavides]

Here is the log file from the failure in the video. The time entry for the error that caused the consumer to get stuck is 2020-10-17T15:52:43.6277494-05:00.

You can also see errors earlier in the log indicating that it recovers from errors correctly at least once.

error.repro.mt.20201017.log

[paulsavides]

By swapping around package versions, it seems that the issue is reproducible in MassTransit.Azure,ServiceBus.Core 5.5.6 but not in 5.5.5. The only significant change to the azure service bus transport was an upgrade from Microsoft.Azure.ServiceBus 3.4.0 to 4.0.0.

The release notes for 4.0.0 of that package are listed here >> https://github.com/Azure/azure-sdk-for-net/blob/Microsoft.Azure.ServiceBus_4.0.0/sdk/servicebus/Microsoft.Azure.ServiceBus/changelog.md.

By running everything against the latest versions of MassTransit & azure sdk locally & reverting the changes introduced in this PR (https://github.com/Azure/azure-sdk-for-net/pull/6804) I was no longer able to get the issue to reproduce.

The only impact that change really would have on MassTransit is that errors on receive (which transient errors / rolling upgrades on azure side / etc... could cause) could now be calling MassTransitAzure.ServiceBus.Core.Transport.Receiver.ExceptionHandler() up to MaxConcurrentCalls at a time. Prior, receive errors would block up the queue client from any further receiving being done until that exception handler was finished being called.

P.S. You may be able to take the above with a small grain of salt, I don't have reproduction steps that are 100% consistent. Only know that running through the steps I laid out in the issue almost always reproduce the issue if consistently done over a two to three minute span. So, when I say "cannot reproduce", I mean that I tried the reproduction steps for about fifteen straight minutes a few times and I didn't see it happen.

[phatboyg]

So is this more an issue with the Azure Service Bus client library? It seems that way.

[paulsavides]

It does seem to be an unexpected behavioral change in the library that began causing the issue.

However, I'm not sure if its an issue with the azure sdk or an issue with sdk usage.

For example, if I comment out lines 57 to 64 here
https://github.com/MassTransit/MassTransit/blob/d262a73eb996fa2d688ad07e8da13d26385a7ecc/src/Transports/MassTransit.Azure.ServiceBus.Core/Transport/Receiver.cs#L57-L64

that also prevents the issue from reproducing.

It seems that both MassTransit & the service bus sdk have their own recovery mechanisms built in for the clients and they are not playing nicely together.

Perhaps a solution could be to check if the exception is one that the Azure ServiceBus SDK can auto-recover from and skip shutting down the agent if that's the case.

Otherwise, there does seem to be something in the azure sdk that's getting deadlocked, have not yet been able to put together a minimal example for reproducing it using the sdk directly though.

[phatboyg]

So I've merged your PR, I'll let you close this one you verify with the latest develop build.

[paulsavides]

Ran through the same steps to reproduce with MassTransit.Azure.ServiceBus.Core 7.0.5-develop.3002 and was no longer able to reproduce the issue.

[paulsavides]

FYI, it turns out my fix didn't quite fix the issue. I believe it just lowered how often it would occur. I ended up reproducing it directly with the azure sdk & opened an issue there.

https://github.com/Azure/azure-sdk-for-net/issues/16994

[paulsavides]

Issue has been fixed on the azure sdk side now, upgrading to Microsoft.Azure.Amqp 2.4.9 (https://github.com/Azure/azure-amqp/releases/tag/v2.4.9) should get rid of it. Otherwise, the next release of Microsoft.Azure.ServiceBus will contain the updated dependency as well. Unsure exactly when that will get released though.

[phatboyg]

Awesome, thanks for keeping me updated. I'll watch for the new packages to be released (I assume I can just update my AMQP package directly in the meantime?)

[paulsavides]

yes, current version of Azure.ServiceBus MassTransit is using has a dependency on Microsoft.Azure.Amqp 2.4.8 (https://www.nuget.org/packages/Microsoft.Azure.ServiceBus/5.1.0). There are no breaking changes between 2.4.8 and 2.4.9 so upgrading directly shouldn't cause an issue.