Azure Service Bus Queue Python receiver.reconnect() call causes queue message deletion

[rswgnu]

I have found in V0.50.1 using the Python SDK that when using ReceiveAndDelete mode on the receiver, merely calling the receiver's reconnect() method after a disconnection causes a dequeue and deletion of the most recently added queue item:

Queue len = 6
Reconnecting...
Queue len after reconnect = 5

Please fix this ASAP if possible.

[kaerm]

Thanks @rswgnu for reporting this our team will take a look at it!

[mayurid]

@annatisch could you take a.look

[annatisch]

Thanks @rswgnu - I have written a short test to confirm this behaviour:

sb_client = ServiceBusClient.from_connection_string(conn_str, debug=True)
queue = sb_client.get_queue(standard_queue)

with queue.get_sender() as sender:
    for i in range(5):
        sender.send(Message(f"Message {i}"))

messages = queue.get_receiver(mode=ReceiveSettleMode.ReceiveAndDelete, idle_timeout=5)
batch = messages.fetch_next()
print(batch[0])
count = len(batch)

print("RECONENCTING")
messages.reconnect()
print("FINISHED RECONNECT")
for message in messages:
    print(message)
    count += 1
assert count == 5

And as you say - a message ("Message 1") always gets lost in the reconnect.
Output:

2019-09-18 07:28:09,791 uamqp.c_uamqp INFO     b'<- [ATTACH]* {receiver-link-c51cb0ab-f48e-4a7d-b4d3-1c07d994aefb,2,false,1,0,* {amqps://pysbtest.servicebus.windows.net/53b54470-b622-4d8c-8fbe-023b19669165,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL},* {SBReceiver-eb27c68a-2d84-4b8b-b888-8bb131b881e9,NULL,NULL,NULL,NULL,NULL,NULL},NULL,NULL,0,1048576,NULL,NULL,NULL}'
2019-09-18 07:28:09,792 uamqp.c_uamqp INFO     b'-> [FLOW]* {2,65535,1,65535,2,0,1}'
2019-09-18 07:28:09,796 uamqp.receiver INFO     Message receiver b'receiver-link-c51cb0ab-f48e-4a7d-b4d3-1c07d994aefb' state changed from <MessageReceiverState.Opening: 1> to <MessageReceiverState.Open: 2> on connection: b'SBReceiver-eb27c68a-2d84-4b8b-b888-8bb131b881e9'
2019-09-18 07:28:09,849 uamqp.c_uamqp INFO     b'<- [TRANSFER]* {2,1,<>,0,true,false,NULL,NULL,NULL,NULL,true}'
2019-09-18 07:28:09,850 uamqp.c_uamqp INFO     b'-> [FLOW]* {3,65534,1,65535,2,1,1}'
Message 0
RECONENCTING
2019-09-18 07:28:09,859 uamqp.c_uamqp INFO     b'-> [DETACH]* {2,true}'
2019-09-18 07:28:09,860 uamqp.connection INFO     Shutting down connection b'SBReceiver-eb27c68a-2d84-4b8b-b888-8bb131b881e9'.
2019-09-18 07:28:09,863 uamqp.c_uamqp INFO     b'-> [DETACH]* {0,true}'
2019-09-18 07:28:09,864 uamqp.c_uamqp INFO     b'-> [DETACH]* {1,true}'
2019-09-18 07:28:09,875 uamqp.c_uamqp INFO     b'-> [END]* {}'
2019-09-18 07:28:09,877 uamqp.c_uamqp INFO     b'-> [CLOSE]* {}'
2019-09-18 07:28:09,879 uamqp.connection INFO     Connection shutdown complete b'SBReceiver-eb27c68a-2d84-4b8b-b888-8bb131b881e9'.
2019-09-18 07:28:10,131 uamqp.c_uamqp INFO     b'-> Header (AMQP 0.1.0.0)'
2019-09-18 07:28:10,185 uamqp.c_uamqp INFO     b'<- Header (AMQP 0.1.0.0)'
2019-09-18 07:28:10,186 uamqp.c_uamqp INFO     b'-> [OPEN]* {SBReceiver-eb27c68a-2d84-4b8b-b888-8bb131b881e9,pysbtest.servicebus.windows.net,65536,65535,NULL,NULL,NULL,NULL,NULL,{[product:servicebus.python],[version:0.50.1],[framework:Python 3.7.4],[platform:win32]}}'
2019-09-18 07:28:10,240 uamqp.c_uamqp INFO     b'<- [OPEN]* {03c263b2d4f1468e9d45485821064836_G31,NULL,65536,4999,240000,NULL,NULL,NULL,NULL,NULL}'
2019-09-18 07:28:10,241 uamqp.c_uamqp INFO     b'-> [BEGIN]* {NULL,0,65536,65536,4294967295}'
2019-09-18 07:28:10,298 uamqp.c_uamqp INFO     b'<- [BEGIN]* {0,1,5000,65536,255,NULL,NULL,NULL}'
...
2019-09-18 07:28:10,480 uamqp.c_uamqp INFO     b'-> [ATTACH]* {receiver-link-dade5557-9f18-4d23-9b95-9619e10cbd3a,2,true,1,0,* {amqps://pysbtest.servicebus.windows.net/53b54470-b622-4d8c-8fbe-023b19669165},* {SBReceiver-eb27c68a-2d84-4b8b-b888-8bb131b881e9},NULL,NULL,NULL,1048576}'
2019-09-18 07:28:10,592 uamqp.c_uamqp INFO     b'<- [ATTACH]* {receiver-link-dade5557-9f18-4d23-9b95-9619e10cbd3a,2,false,1,0,* {amqps://pysbtest.servicebus.windows.net/53b54470-b622-4d8c-8fbe-023b19669165,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL},* {SBReceiver-eb27c68a-2d84-4b8b-b888-8bb131b881e9,NULL,NULL,NULL,NULL,NULL,NULL},NULL,NULL,0,1048576,NULL,NULL,NULL}'
2019-09-18 07:28:10,594 uamqp.c_uamqp INFO     b'-> [FLOW]* {2,65535,1,65535,2,0,1}'
FINISHED RECONNECT
2019-09-18 07:28:10,654 uamqp.c_uamqp INFO     b'<- [TRANSFER]* {2,1,<>,0,true,false,NULL,NULL,NULL,NULL,true}'
2019-09-18 07:28:10,654 uamqp.c_uamqp INFO     b'-> [FLOW]* {3,65534,1,65535,2,1,1}'
Message 2
2019-09-18 07:28:10,712 uamqp.c_uamqp INFO     b'<- [TRANSFER]* {2,2,<>,0,true,false,NULL,NULL,NULL,NULL,true}'
2019-09-18 07:28:10,713 uamqp.c_uamqp INFO     b'-> [FLOW]* {4,65533,1,65535,2,2,1}'
Message 3
2019-09-18 07:28:10,766 uamqp.c_uamqp INFO     b'<- [TRANSFER]* {2,3,<>,0,true,false,NULL,NULL,NULL,NULL,true}'
2019-09-18 07:28:10,767 uamqp.c_uamqp INFO     b'-> [FLOW]* {5,65532,1,65535,2,3,1}'
Message 4
2019-09-18 07:28:15,853 uamqp.client INFO     Timeout reached, closing receiver.

However the client is showing no indication that a frame was ever received during the reconnect process. This could indicate that the service is sending a frame that the client either never receives or it's being immediately discarded because the connection is already in a shutdown state.
I will investigate whether we can improve the behaviour here, however please bear in mind that loss of messages during an connection interruption will always be a risk when using ReceiveAndDelete mode. So if receipt of every message is important, please use PeekLock mode.

[rswgnu]

it's being immediately discarded because the connection is already in a shutdown state.

Could you explain the above further?

I understand if something like a power outage happens when a client is trying to read a message from a queue that the message may be lost but the queue should not be dropping messages prior to read attempts being made; it should be persistent subject to whatever "time-to-live" policy is given for the queue (regardless of the state of a client). ServiceBus disconnects clients pretty rapidly in my experience so reconnects are needed all the time and should not affect any items in the queue. Do you agree with this?

There was a specific reason we chose not to use PeekLock mode though I do not recall it right now.

[annatisch]

Thanks @rswgnu - yes I agree - I would think dropping messages due to disconnect/reconnect should be an exceptional case rather than normal behaviour - so I certainly need to do a deeper investigation into the C library to ensure that incoming messages are not being needlessly discarded (as opposed to discarded because they were received erroneously).

[rswgnu]

Ok, great. Also, I am pretty sure I verified that the receiver is not in a shutdown state yet the message is still dropped whenever a reconnect is done. If there were a way we could keep connections open for hours at a time as we would like to do (because we would only have a few clients accessing our queue at a time), then that would help us as well and we wouldn't need the reconnects generally. Is there any way to do that?

[annatisch]

A reconnect is generally performed due to an error in one of the connection/link/authentication - so keeping the connection open is not always an option. Therefore if a reconnect is performed, the receiver would have been in a shutdown state at some point... though it possible that state has not been surfaced to the client due to some kind of error.
Do you know under what circumstances a reconnect is being performed in your case?

[rswgnu]

I am manually calling reconnect after the receiver is forcibly disconnected from the queue. Prior to that I was just recreating the receiver to dequeue each item and that did not work properly either as I recall. The disconnection is incredibly fast relative to the rate at which we want to dequeue items. Our processes run for hours and we don't want to dequeue everything upfront because then we would just have to create a local persistent store.

[annatisch]

Ah that's interesting.
I confess that the reconnect function was never intended to be manually called - however that's on me as I never explicitly marked it as internal either...
Do you notice that messages are still dropped if you use your previous implementation of recreating the receiver each time? I would suspect that the behaviour should be the same and am very curious as to what you observed.

[rswgnu]

Yes, that is why I then tried using reconnect. Personally, I think it would be handy to have as part of the API because why do we want to recreate the receiver locally just because the other end of the connection dropped? Reconnect should be lighter and faster.