Join Log in
Score:0
L.C. Tan avatar Server

Azure Service Bus / Function App queue message enqueue / dequeue behavior

cn flag
L.C. Tan

We use Azure Service Bus and Azure Function App components for a software backend operation. Recently we notice some errors from the App Insights. We noticed some of the Function App operations are started even after passing the message lock end DateTime. Please see the below logs for an example. The operation was triggered on 2/10/2022, 8:46:06.999 AM, but the queue message lock has ended at 2022-02-10, 08:46:04.5640000Z.

Has anyone encountered this before and been able to give some insights?

We are using the Standard pricing tier hardware/components, which could be why this is happening. Thanks in advance.

2/10/2022, 8:46:06.999 AM   Trigger Details: MessageId: 9b4759453fab437fa1c995fce5fb928f, SequenceNumber: 8956, DeliveryCount: 1, EnqueuedTimeUtc: 2022-02-10T08:45:34.5480000Z, LockedUntilUtc: 2022-02-10T08:46:04.5640000Z, SessionId: (null)    Information 
2/10/2022, 8:46:06.999 AM   Executing 'Functions....' (Reason='(null)', Id=7e4644f3-9960-4a5e-af58-515b91008a56)
...
2/10/2022, 8:46:07.031 AM   Start processing HTTP request POST ...  Information 
2/10/2022, 8:46:07.031 AM   Sending HTTP request POST ...   Information 
...
2/10/2022, 8:46:07.311 AM   Message processing error (Action=RenewLock, ClientId=MessageReceiver3..., EntityPath=..., Endpoint=...) Error   
2/10/2022, 8:46:07.311 AM       Error   
2/10/2022, 8:46:07.341 AM   Received HTTP response headers after 238.6766ms - 200   Information 
...
2/10/2022, 8:46:07.351 AM   Executed 'Functions....' (Succeeded, Id=7e4644f3-9960-4a5e-af58-515b91008a56, Duration=351ms)
2/10/2022, 8:46:07.872 AM       Error   
2/10/2022, 8:46:07.872 AM   Message processing error (Action=Complete, ClientId=MessageReceiver3..., EntityPath=..., Endpoint=...)  Error   
2/10/2022, 8:46:10.965 AM   Executing 'Functions....' (Reason='(null)', Id=5068f09b-3f74-4d72-a751-6fb8044cfd47)    Information 
2/10/2022, 8:46:10.965 AM   Trigger Details: MessageId: 9b4759453fab437fa1c995fce5fb928f, SequenceNumber: 8956, DeliveryCount: 2, EnqueuedTimeUtc: 2022-02-10T08:45:34.5480000Z, LockedUntilUtc: 2022-02-10T08:46:34.5220000Z, SessionId: (null)    Information 
...
2/10/2022, 8:46:12.363 AM   Sending HTTP request POST ...   Information 
2/10/2022, 8:46:12.363 AM   Start processing HTTP request POST ...  Information 
2/10/2022, 8:46:12.373 AM   FunctionName ended for transaction: { "abc": 111 }  Information 
2/10/2022, 8:46:12.373 AM   Received HTTP response headers after 99.4662ms - 200    Information 
2/10/2022, 8:46:12.373 AM   End processing HTTP request after 99.5389ms - 200   Information 
2/10/2022, 8:46:12.373 AM   Executed 'Functions....' (Succeeded, Id=5068f09b-3f74-4d72-a751-6fb8044cfd47, Duration=1408ms)  Information
67
0 + 0
Score:0
avatar Server
de flag
Sean Feldman

This can happen if your function has a fairly high prefetchCount and short MaxLockDuration while the processing takes some time. Messages prefetched start their clock ticking not at the moment of processing but the moment those were fetched. Trying upping MaxLockDuration and tuning prefetchCount to get rid of this issue.

0 + 0
ธงชาติไทย
Elon Musk
I sit in a Tesla and translated this thread with Ai:

mangohost

Post an answer

Most people don’t grasp that asking a lot of questions unlocks learning and improves interpersonal bonding. In Alison’s studies, for example, though people could accurately recall how many questions had been asked in their conversations, they didn’t intuit the link between questions and liking. Across four studies, in which participants were engaged in conversations themselves or read transcripts of others’ conversations, people tended not to realize that question asking would influence—or had influenced—the level of amity between the conversationalists.