Same message process 2 times

[AkbarAnsari]

I have a function app which is working on Service Bus Topic binding, i am observing issue on our QC environment with function app trigger is processing the same message 2 times. the overall execution of request is 9 to 10 second.

First i thought it maybe due to the lock expiry message is getting process twice. after analyzing the request logs i found the difference between in both the invocation is 2 second.

Function app details are:

• Timestamp:5/3/2018, 4:18:24 PM
• Function App version (1.0 or 2.0-beta): 1.0.11702.0 (~1)
• Function App name: btconnector-wp3-sit
• Function name(s) (as appropriate): RequestToBizTalk
• Invocation ID:a636c2a0-1b79-43ec-9afe-c3a107dde58c, 6c720634-fe45-4734-9ed0-437ffd373b98
• Region: West Europe
• Resource Group: WP3-SIT-SHAREDAPPS-WEU-RG

[mathewc]

Looking at those logs I see the invocations for the 2 ids you provided and they're both successful, but we don't log any details of your message payloads etc. so I can't see evidence that these were for the same message (same message ID). How do you know these invocations are for the same message?

If you have a consistent repro, perhaps you can log the message ID out in your function and share those logs - showing two separate successfull invocations for the exact same SB message ID.

Also can you share your function definition/signature and any other code required to repro this?

[mathewc]

Please check the LockDuration configured on your ServiceBus Topic, as well as the AutoRenewTimeout configured in your host.json. If you're not dealing with a case where the first invocation failed and another retry invocation would therefore be expected, the only other reason the same message would be reprocessed is if the message lock was lost.

[mathewc]

Closing this since I believe this issue is due to message locks being lost due to incorrectly configured settings. I did make a fix for Azure/azure-webjobs-sdk#1703 which will make these issue easier to diagnose in the future.

After examining your configuration and fixing any issues there, if you still have problems and have a repro showing there is an issue with the binding, please reopen with more details.

[manojkumar-sachdev]

Hi @mathewc ,
I am a colleague of @AkbarAnsari and we are still facing this issue. "autoRenewTimeout" we have not set in host.config file because it has default value of 5 minutes and our code is getting processed in 5 to 8 seconds.

We have also raised ticket to Microsoft Support, Ticket number: 118051718206584.

We have also confirmed that the message is same which is getting processed twice.

Please let me know if you need more info.

[mathewc]

The change I mentioned above for Azure/azure-webjobs-sdk#1703 should start rolling out next week, and that will improve visibility into underlying errors (message lock lost errors due to long executions) which is the reason for messages being reprocessed. You'll see those errors in your logs, whereas currently you don't.

Before that is deployed, we can look at your execution durations to see if there aren't some that are running longer than expected, leading to lock expiry and reprocessing. You provided your app info above - please provide an updated time range where you're seeing this problem, and we can check the logs.

[manojkumar-sachdev]

@mathewc , Thanks for reply.

Time when the message is processed first time 2018-05-23T13:46:47.3260000Z
Time when the message is processed second time 2018-05-23T13:46:47.4040000Z

Please let me know if you need more info

[chavi289]

Hi @mathewc : we are facing the same issue even with the latest version of Azure functions Sdk. I have the logs which show that the same message was processed multiple times by function and there were no exceptions in any of the executions. The delivery count of the message also increased each time.
Appreciate your help on this issue.

[victoriatrimboli]

Hi @mathewc, we are having the same issue. Logs are showing same function executed multiple times for the same message.

Subscription: SUB BIBBYFS ITS-ITOPS OPS LIVE
Region: North Europe
Resource Group: RG-APP-AuraPortal
Function: EUA1-LASB-01-FunctionApp
Service Plan: EUA1-LASB-01-FunctionAppPlan

Example:

Row keys on logs table:
d917c04f-c54c-4c4f-8567-aaf3d103dbd3
a0fad1df-080e-4b24-af3e-7220189fb0bb

Can I please get your help on this?