Azure / Azure/azure-functions-host
Queue message processed but not deleted; Job Host shut down issue?
- Dominant language
- C#
- Stars
- 2k
- Forks
- 482
- Avg merge
- 2d 10h
- Merged PRs (30d)
- 36
Description
Hi, I recently upgraded an Azure Functions app from in-process to isolated-process and have started to have a problem where messages are getting dequeued twice even though I don't appear to have any failures. This appear to happen very infrequently, so maybe up to 10 times a day - based upon an average daily load of about 500 queue messages. This is on a consumption plan and the issue appears to correlate with a new instance of the Function App being started up after being dormant and a new message is detected on the queue.
There appear to be no errors/exceptions in the Function.
Hosting plan: **Consumption**
FUNCTIONS_EXTENSION_VERSION = ~4
FUNCTIONS_WORKER_RUNTIME = dotnet-isolated
FUNCTIONS_WORKER_RUNTIME_VERSION = 8.0
WEBSITE_PLATFORM_VERSION = 103.0.7.210
Packages:
Microsoft.Azure.Functions.Worker = 1.22.0
Microsoft.Azure.Functions.Worker.Sdk" = 1.17.2
Microsoft.Azure.Functions.Worker.Extensions.Http.AspNetCore = 1.2.1
Microsoft.Azure.Functions.Worker.Extensions.Storage.Queues = 5.4.0
Microsoft.Azure.Functions.Worker.ApplicationInsights" Version= 1.2.0
Microsoft.ApplicationInsights.WorkerService = 2.22.0
All important `host.json` settings are on the default values.
Investigating why they were dequeued twice I found that the queue message was processed but it does not appear to have been deleted, because I then see it process approx. 10 mins later - which is the default `visibilityTimeout`.
Here is an example of the first dequeue of one of the messages:
Invocation Id: `5bdc64e8-fbec-4290-8058-af5bffa00bff`

What's interesting is that the Job Host appears to shut down almost immediately after the log entry about the queue message having been processed. Additionally (not shown in the logs) is that this was the _first and only_ message handled by this instance. So the instance started up because of this message on the queue.
Here is another example, but in this case the Job Host appears to shut down _before_ the "New queue message detected":
Invocation Id: `4fb9f6a8-b97b-4ddd-aa82-8d2792134f05`

As you can see in this example, the instance started up (presumably because a new queue message was detected) but immediately decided to stop, but the queue message was dequeued and processing started.
I've checked the Function logs and can see no reason why the instance should have stopped, or why in the first example the Success message was logged but the queue message not deleted (I _assume_ it is because the Host shut down before that delete had a chance to take place - i.e. it comes _after_ the Success message).
Contributor guide
Research direction
Start with the queue-trigger logs and the default host.json queue settings, comparing the two invocation sequences around dequeue, success, and Job Host shutdown. Reproduce the isolated-process app behavior on the Consumption plan and verify that successfully processed messages are deleted rather than reappearing after the 10-minute visibilityTimeout.
Written by the indexing model from the issue text.
Assessment
- Tech stack
- azure, csharp
- Domain
- backend, cloud
- Issue type
- Bug
- Difficulty
- 4/5
- Estimated time
- 3-5 days
- Activity status
- Stale
- Clarity
- Mostly clear
- Newbie friendliness
- 30/100