I have a time triggered Azure function that runs every 2 minutes and executes code that fetches all messages from an Azure service bus topic, and then sends the content of some of the messages as new messages on the same topic.
The problem I experience is that sometimes the messages end up in the dead letter queue after some time, even though the azure function doesn't fail or logs any exceptions. It looks like the messages that end up in DLQ has been moved there because they were locked and the lock timed out, and since Max delivery count is set to 1 on the topic, the message is sent to DLQ. But my code doesn't lock the messages without completing them (unless an exception is thrown, which doesn't happen). Furthermore the locking seems to happen at a point in time where the azure function isn't running. Sometimes it happens after a few "resends" of the messages, at other times it happens after many.
So how does the messages get locked if they where never received by my code? Is there any known issues with TopicClient.SendAsync() that could explain this behaviour? Or is there another reason that the messages ends up in DLQ, when the code doesn't log any exceptions?
I have included a code example, that shows the problem (the code is useless, it is just to narrow down where the problem is):
[FunctionName("TestResend")]
public static async Task TestResendAsync([TimerTrigger("0 */2 * * * *")] TimerInfo myTimer, ILogger log, ExecutionContext context)
{
try
{
log.LogInformation("Testing resend of messages");
using var container = GetContainer(context);
var resender = container.GetInstance<TestResender>();
await resender.Test(new TraceWriterLogger(log));
}
catch (Exception ex)
{
log.LogError(ex, "Exception in TestResend");
throw;
}
}
public class TestResender
{
private static MessageReceiver _messageReceiver;
private static TopicClient _topicClient;
public TestResender()
{
if (_topicClient == null || _topicClient.IsClosedOrClosing)
{
_topicClient = new TopicClient(ConnectionStrings.ServiceBusConnectionString, "plandisc.domain.models.servicebus.testresendmessage");
}
}
public async Task Test(ILogger logger)
{
_messageReceiver = new MessageReceiver(ConnectionStrings.ServiceBusConnectionString,
EntityNameHelper.FormatSubscriptionPath("plandisc.domain.models.servicebus.testresendmessage", "testresendmessage-subscription"), ReceiveMode.PeekLock, null, 0);
logger.Info("Receiving Messages");
var messages = new List<Message>();
IList<Message> messageBatch;
do
{
messageBatch = await _messageReceiver.ReceiveAsync(int.MaxValue, TimeSpan.FromSeconds(2));
if (messageBatch != null && messageBatch.Any()) messages.AddRange(messageBatch);
logger.Info("ReceiveAsync from " + _messageReceiver.Path + " returned: " + (messageBatch?.Count() ?? 0));
} while (messageBatch != null && messageBatch.Any());
var serviceBusMessages = messages.Select(m => Json.Deserialize<TestResendMessage>(System.Text.Encoding.UTF8.GetString(m.Body)));
foreach (var message in serviceBusMessages)
{
logger.Info("Resending message: " + message.Data + " " + message.TimeStamp);
await SendAsync(new TestResendMessage
{
Data = message.Data,
TimeStamp = message.TimeStamp
}, logger);
}
logger.Info($"Complete messages (Messages: {messages.Count})");
var lockTokens = messages
.Where(m => m.SystemProperties.LockedUntilUtc > DateTime.UtcNow)
.Select(m => m.SystemProperties.LockToken);
if (messages.Any())
{
var info = "messages: " + messages.Count() + "\n" +
"lockTokens: " + lockTokens.Count() + "\n" +
"lockedUntilUtc: " + string.Join(", ", messages.Select(m => m.SystemProperties.LockedUntilUtc.ToString()));
logger.Info(info);
}
if (lockTokens.Any())
{
await _messageReceiver.CompleteAsync(lockTokens);
}
logger.Info("Done completing messages");
}
public async Task SendAsync(TestResendMessage message, ILogger logger)
{
var envelope = new Message();
envelope.Body = Encoding.UTF8.GetBytes(Json.Serialize(message));
try
{
await _topicClient.SendAsync(envelope);
}
catch (Exception ex)
{
logger.Error("Can't send service bus message", ex);
throw;
}
}
}