azure-sdk-for-python: [azure.servicebus] Receiving messages with lock that has already expired

In our application logs, we see that we sometimes receive messages where the lock is already expired. This happens both when calling the native next() function or using a loop that executes fetch_batch while explicitly disabling prefetching by putting max_batch_size=1.

Usually we get something like this

2019-06-30 14:27:57 DEBUG    adp        Message locked until: 2019-06-30 14:28:27.836000

but sometimes we get expired messages

2019-06-30 14:22:57 DEBUG    adp        Message locked until: 2019-06-30 14:21:24.143000

As far as I can tell, this never happens in the first message, but if the first message takes a long time to process (e.g. longer than the original lock time should it have been locked at the same time as the first message), it does sometimes happen in subsequent messages.

Relevant code:

queue_client = self.client.get_queue(queue)
with queue_client.get_receiver() as receiver:
    while True:
        for message in receiver.fetch_next(max_batch_size=1):
            self.logger.info(f"Processing new message from {queue}")
            self.logger.debug(f"Message locked until: {message.locked_until}")
            # Do long running stuff.

What could be the problem here? Are we doing something wrong?

Relevant pip freeze output

azure-common==1.1.22
azure-keyvault==1.1.0
azure-nspkg==3.0.2
azure-servicebus==0.50.0
azure-storage==0.36.0```

About this issue

Original URL
State: closed
Created 5 years ago
Reactions: 2
Comments: 17 (7 by maintainers)

Most upvoted comments

I am a colleague of @JosPolfliet working on this issue. I implemented the prefetch = 1, and as anticipated, this did not have any impact. An extract from the logs is below. As you can see, processing the first message takes less than 2 minutes. However, the following messages that are received have expired already. The time to live is set to 10675199 days, hence it cannot be due to reaching the time to live. Is there anything else we can check?

`2019-07-09 09:11:52 INFO adp Downloading new messages from preprocessrequest 2019-07-09 09:11:52 INFO adp Processing new message from preprocessrequest .

2019-07-09 09:11:52 DEBUG azure.servicebus.common.utils Running lock auto-renew thread for 3600 seconds .

2019-07-09 09:11:52 DEBUG azure.servicebus.common.utils 30 seconds or less until lock expires - auto renewing.

2019-07-09 09:11:52 DEBUG adp Message locked until: 2019-07-09 09:12:52.290000 .

2019-07-09 09:12:22 DEBUG azure.servicebus.common.utils 30 seconds or less until lock expires - auto renewing.

2019-07-09 09:12:52 DEBUG azure.servicebus.common.utils 30 seconds or less until lock expires - auto renewing.

2019-07-09 09:13:22 DEBUG azure.servicebus.common.utils 30 seconds or less until lock expires - auto renewing.

2019-07-09 09:13:35 DEBUG adp Finished processing. Marking message as complete .

2019-07-09 09:13:35 DEBUG adp Closing AutoLockRenew .

2019-07-09 09:13:35 INFO adp Downloading new messages from preprocessrequest .

2019-07-09 09:13:35 INFO adp Processing new message from preprocessrequest .

2019-07-09 09:13:35 WARNING adp Received an expired message so skipping it. Was locked until: 2019-07-09 09:12:47.273000. Message contents: {“filePath”: “19331272_3_aanbod_pdf.pdf”, “fileId”: “5d243f7df1d22433e26a474c”, “uploadId”: “5d243f7df1d22433e26a474c”, “organisationId”: “5d11ee7807a226ae21ec504f”} .

2019-07-09 09:13:35 INFO adp Downloading new messages from preprocessrequest . 2019-07-09 09:13:35 INFO adp Processing new message from preprocessrequest . 2019-07-09 09:13:35 WARNING adp Received an expired message so skipping it. Was locked until: 2019-07-09 09:12:52.290000. Message contents: {“filePath”: “19331046_7_aanvraag_pdf.pdf”, “fileId”: “5d243f93f1d22433e26a475e”, “uploadId”: “5d243f93f1d22433e26a475e”, “organisationId”: “5d11ee7807a226ae21ec504f”}`

alvercau on Jul 9, 2019

Great, look forward to it.

– Bob

On Sep 26, 2019, at 7:03 PM, annatisch notifications@github.com wrote:

Hi @JosPolfliet, @nicolasgere @alvercau - I have identified the root issue behind this and am working on a fix for it now.

— You are receiving this because you commented. Reply to this email directly, view it on GitHub, or mute the thread.

rswgnu on Sep 27, 2019

It’s not exactly hard to recreate either:

from azure.servicebus import ServiceBusClient, Message
import time

CONNECTION_STRING = "" # SET YOUR LOCK DURATION OF THIS QUEUE TO 30seconds
QUEUE_NAME = "test"

sb_client = ServiceBusClient.from_connection_string(CONNECTION_STRING)
queue = sb_client.get_queue(QUEUE_NAME)

for i in range(3):
    queue.send(Message(f"Message {i}"))

messages = queue.get_receiver()
for message in messages:
    print(message)
    print("Is expired? ", message.expired)
    message.complete()
    time.sleep(40)

JosPolfliet on Sep 5, 2019

I am seeing something similar but where the receiver times out and closes after 5 or more minutes (using version 0.50.1 under WSL 1 with Debian). The documentation says that the default is that the receiver stays open until closed since the idle timeout is 0 by default. But that is not what we experience when using ReceiveAndDelete mode.

You really need to provide some samples where a receiver gets one message from the queue say each hour or over a long period past some of the timeouts that exist in your code. The samples I have seen never deal with this. There is also very little documentation on using ReceiveAndDelete mode using Python.

rswgnu on Sep 5, 2019