[BUG] Lost service bus messages using ServiceBusReceiverClient

[pjrharley]

Describe the bug
We are not receiving messages from a service bus subscription that I have otherwise confirmed are being published.

Futhermore I've narrowed this down to one version change that introduces the problem (7.5.2 is fine, 7.6.0 is not) and a simple, seemingly unrelated change that works around the issue.

Exception or Stack Trace
Error message seen:

'RELEASED' is not supported on a receiver opened in ReceiveMode.RECEIVE_AND_DELETE.

The stack trace that arrived there:

at com.azure.messaging.servicebus.ServiceBusReceiverAsyncClient.updateDisposition(ServiceBusReceiverAsyncClient.java:1279)
	at com.azure.messaging.servicebus.ServiceBusReceiverAsyncClient.release(ServiceBusReceiverAsyncClient.java:913)
	at com.azure.messaging.servicebus.SynchronousMessageSubscriber.drainQueue(SynchronousMessageSubscriber.java:208)
	at com.azure.messaging.servicebus.SynchronousMessageSubscriber.drain(SynchronousMessageSubscriber.java:157)
	at com.azure.messaging.servicebus.SynchronousMessageSubscriber.hookOnNext(SynchronousMessageSubscriber.java:115)
	at com.azure.messaging.servicebus.SynchronousMessageSubscriber.hookOnNext(SynchronousMessageSubscriber.java:24)
	at reactor.core.publisher.BaseSubscriber.onNext(BaseSubscriber.java:160)
	at reactor.core.publisher.FluxHandle$HandleSubscriber.onNext(FluxHandle.java:126)
	at reactor.core.publisher.FluxOnErrorResume$ResumeSubscriber.onNext(FluxOnErrorResume.java:79)
	at reactor.core.publisher.FluxMap$MapSubscriber.onNext(FluxMap.java:122)
	at reactor.core.publisher.FluxMap$MapSubscriber.onNext(FluxMap.java:122)
	at com.azure.messaging.servicebus.implementation.ServiceBusReceiveLinkProcessor.drainQueue(ServiceBusReceiveLinkProcessor.java:478)
	at com.azure.messaging.servicebus.implementation.ServiceBusReceiveLinkProcessor.drain(ServiceBusReceiveLinkProcessor.java:437)
	at com.azure.messaging.servicebus.implementation.ServiceBusReceiveLinkProcessor.lambda$onNext$2(ServiceBusReceiveLinkProcessor.java:210)

To Reproduce
Steps to reproduce the behaviour:

• During our tests we create a subscription to a topic to confirm messages have been published correctly by the application
• We then create a client
• Try and receive messages
• We should in our test always get 2 messages, however we often get 0 or 1 instead.
• Logs contain the following message once for each missing message:
  • 'RELEASED' is not supported on a receiver opened in ReceiveMode.RECEIVE_AND_DELETE.

Code Snippet

	var client = new ServiceBusClientBuilder()
                .connectionString(primaryConnectionString)
                .receiver()
                .topicName(topic)
                .subscriptionName(subscriptionName)
                .receiveMode(ServiceBusReceiveMode.RECEIVE_AND_DELETE)
                .prefetchCount(0)
                .buildClient();
// Note two details: receive mode and the number in the prefetch count. The problem goes away if you change either (0 is actually 
// the default even though it says it is 1 on the builder java doc).

var messages = client.receiveMessages(2, 10000);

Expected behavior
We should have received 2 messages. Instead we get 0, 1 or 2, seemingly at random.

Setup (please complete the following information):

• OS: Tested on both MacOS and Ubuntu Linux
• IDE: IntelliJ and running via gradle in terminal
• Library/Libraries: confirmed in 'com.azure:azure-messaging-servicebus:7.6.0' and all newer. Not in 7.5.2.
• Java version: 17
• App Server/Environment: Netty
• Frameworks: Junit 5

Additional context
I believe the problem was introduced during this change:

e795856

Looking at the change you can see why the prefetch setting effects the outcome - the asyncClient.release call is only made when prefetch is disabled.

[skbaji6]

did you tried with PEEK_LOCK Mode? is it same behaviour with PEEK_LOCK mode?
.receiveMode(ServiceBusReceiveMode.PEEK_LOCK);

PEEK_LOCK Mode should resolve your issue.

[pjrharley]

Yes - I mentioned in the code snippet above that PEEK_LOCK mode does also resolve the issue. This seems like a workaround rather than a fix though - should I not expect RECEIVE_AND_DELETE mode to work as it used to?

If for some reason my configuration is not supported then I would expect an explicit error at the time I configured it, not silently dropped messages.

[joshfree]

@ZejiaJiang could you follow up with @pjrharley on this issue?

cc: @Azure/azsdk-sb-java

[ZejiaJiang]

Hi @pjrharley , thank you for your report, I'm looking at this issue.

[pjrharley]

I believe I've got a reproduction of this issue, I'm not sure it's as minimal as possible but I distilled it down from what I had in our application:

https://github.com/pjrharley/ServiceBusIssue30861Example

It doesn't happen every time so clearly there's a timing element to it (it happened more often within our application) but I found if I run it a few times it'll usually print something like:

Expected messages:
example1:260
example2:863
Expected messages:
example1:798
example2:970
Received messages:
example2:970
Discard messages:
example1:260
example2:863

And you can see in that example that example1:798 has gone missing.

[ZejiaJiang]

@pjrharley thank you for the detail, we do have another message credit calculation issue (prefetch configuration) now, I'm checking them.

[ZejiaJiang]

Hi @pjrharley ,

Yeah, you are right, before the second receiver establish , the second send message arrived in client, and then the client release it, the reason why you may get 0, 1 or 2 messges in second receive, it rely on when the message arrived the client and when the receiver established and credit calculation wrong, I'll discuss with my coworker about it.

Thank you!

[ZejiaJiang]

I just figured out how it happens, and there are serveral related issue that I'm going to go through them.

#26632
#25259

[ZejiaJiang]

We are planning to fix this in next release.

[ZejiaJiang]

Hi @pjrharley , a few days later the new release will be published, you can try the letest version.

[ghost]

Hi, we're sending this friendly reminder because we haven't heard back from you in a while. We need more information about this issue to help address it. Please be sure to give us your input within the next 7 days. If we don't hear back from you within 14 days of this comment the issue will be automatically closed. Thank you!

[pjrharley]

Hi @ZejiaJiang - I've just updated my example application to 7.13.0 and it does look like this problem is now fixed. Thanks very much!!

[ZejiaJiang]

Hi @pjrharley , thank you for your reply. I'm going to close this issue, if you meet this issue again, you can reopen it, I'm glad to help you!