I have NServiceBus running over the AzureStorageQueues Transport.
Sometimes, my message handler shows the following two entries in it's log:
2018-08-27 12:27:23.0329 INFO 5 Handling Message...
2018-08-27 12:27:23.7359 WARN 5 Dispatching the message took longer than a visibility timeout. The message will reappear in the queue and will be obtained again. NServiceBus.AzureStorageQueues.LeaseTimeoutException: The pop receipt of the cloud queue message '2ebd6dd4-f4a1-40c6-a52e-499e22bc9f2f' is invalid as it exceeded the next visible time by '00:00:09.7359860'.
I understand that there is a Visiblity Timeout that can be configured, but is 30 seconds by default. And the message being handled is taking longer than this 30 seconds to process.
But what doesn't make sense is the timing of those two log entries. The handler is kicked off at 23.0329 seconds...while the warning pops up at 23.7359 seconds. That's a mere 0.7 seconds. Why is that? I would expect the warning from NServiceBus to pop up after the 30 second InvisibilityTimeout.
Assuming you're using the default settings, messages are retrieved in batches. All messages in the batch have the same visibility timeout value of 30 seconds. There's also processing concurrency limit (calculated as max(2, number of logical processors), which could have an impact, causing some messages from the batch to wait for previous messages to finish processing. Therefore it's possible that your message is retrieved as part of a batch but is not processed right away, causing visibility timeout to expire.
Adjusting configuration by tuning those to address your specific scenario should get rid of those repeated attempts to process messages.