New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Function App doesn’t use latest Pop Receipt to call Delete Message #1600

Closed
suwatch opened this Issue Jun 16, 2017 · 2 comments

Comments

Projects
None yet
3 participants
@suwatch
Contributor

suwatch commented Jun 16, 2017

[Transferred from Azure Customer Reported Incident (CRI)]

[GENERAL INFO]
Subscription ID: (see CRI)
Site name(s): (see CRI)
Stamp:
Instance ID (if applicable): 
Exact Time Frame In UTC : 2017-06-15T12:08:21.0990465Z
[PROBLEM DESCRIPTION]
Customer is using Function App that gets triggered by Storage Queue. If the function takes more than 5 min to execute, It looks like Function App is making an Update Message call to Storage Queue to update message’s Visibility Timeout. This Update Message call returns a new Pop Receipt. When the function execution is completed, Function App should call Delete Message with this new Pop Receipt, but instead of using the latest Pop Receipt Function App is using original Pop Receipt it got when it did GET Message call and message delete call is failing. There is no retry logic to delete this message. And once the Visibility Timeout expires, this same message will be now visible and gets processed again.
       

[TROUBLESHOOTING STEPS]
Captured Application Insights logs and Storage Queue Logs. Here are details :

Message was PUT at 12:03:19
Message was received by function app at 12:03:22
Function App took 9 mins 35 seconds to process it
Function App made a request to Storage Queue to update Visibility Timeout to 600 at 12:08:21 (five min after initial GET request)
Function App made a delete message request at 12:12:36 but this delete request failed (as the pop receipt is not current)
In the meantime, another instance of function got hold of this same message and started to execute at 12:18:23 (10 min after UPDATE request)
This second function instance took only 15 ms to execute (as most of work was already done by the first instance)
Function App made a delete message request at 12:18:37 and this was successful.
 
Here are logs from Storage Queue Logs: (see CRI)

@brettsam

This comment has been minimized.

Show comment
Hide comment
@brettsam
Member

brettsam commented Jun 28, 2017

@brettsam brettsam closed this Jun 28, 2017

@brettsam

This comment has been minimized.

Show comment
Hide comment
@brettsam

brettsam Jul 3, 2017

Member

Update: the fix is now deployed in version 1.0.11015.0 (visible in the 'Settings' page of the Functions portal). If you are not running this version, manually restart your app and it will pick up the latest version.

Member

brettsam commented Jul 3, 2017

Update: the fix is now deployed in version 1.0.11015.0 (visible in the 'Settings' page of the Functions portal). If you are not running this version, manually restart your app and it will pick up the latest version.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment