Using legacy and V3 Partition Manager, some control queues seem to stop processing messages

[ericleigh007]

I copied this from the end of #903 because I felt it should get better visibility.

Versions and setup:

Minimum scale out of 3
Maximum of 10
Instance size: EP3
Functions V4, .NET Core 8, in-process 
Durable task extension 3.4.1 Azure Storage backend
AzureFunctionsJobHost__Extensions__DurableTask__StorageProvider__PartitionCount: 16
AzureFunctionsJobHost__Extensions__DurableTask__MaxConcurrentActivityFunctions: 100
AzureFunctionsJobHost__Extensions__DurableTask__MaxConcurrentOrchestratorFunctions: 70

Hi, we've got this issue in our banking app handling billions of pounds of traffic per day.
We have two control queues, 08 and 13, stuck for hours (they have messages being addeed, but none are being dequeued)
Both control queues in this state are using the same curernt owner.

In this state, I believed the queue would be backed up forever. However, if I stop adding files to the input (which kick off new orchestrators) about every 2 minutes or so, it seems 1000 messages do get processed, or at least completed.

Any thoughts in how to troubleshoot this problem? What should we be looking for? Or is this just a plain bug in the Azure Storage backend?

Before you ask, no we cannot migrate to DTS because our data is sometimes much larger than 1MB.

I've been monitoring our app with powershell, and recently added the queue length of the durable task queues. This has paid off.

2025-10-24T12:57:32.8085760+01:00 ** Queue 'dftaskhub20251017-control-08' approximate message count: 1
2025-10-24T13:00:02.8953936+01:00 ** Queue 'dftaskhub20251017-control-08' approximate message count: 1
2025-10-24T13:02:31.5272807+01:00 ** Queue 'dftaskhub20251017-control-08' approximate message count: 0
2025-10-24T13:11:19.9940839+01:00 ** Queue 'dftaskhub20251017-control-08' approximate message count: 0
2025-10-24T13:19:19.4048982+01:00 ** Queue 'dftaskhub20251017-control-08' approximate message count: 15
2025-10-24T13:22:10.1375039+01:00 ** Queue 'dftaskhub20251017-control-08' approximate message count: 118
2025-10-24T13:24:40.6653776+01:00 ** Queue 'dftaskhub20251017-control-08' approximate message count: 416
2025-10-24T13:27:23.2663002+01:00 ** Queue 'dftaskhub20251017-control-08' approximate message count: 562
2025-10-24T13:29:53.3611451+01:00 ** Queue 'dftaskhub20251017-control-08' approximate message count: 744
2025-10-24T13:32:23.0374825+01:00 ** Queue 'dftaskhub20251017-control-08' approximate message count: 934
2025-10-24T13:34:55.1558335+01:00 ** Queue 'dftaskhub20251017-control-08' approximate message count: 1654
2025-10-24T13:37:25.0837628+01:00 ** Queue 'dftaskhub20251017-control-08' approximate message count: 2506
2025-10-24T13:39:55.9073730+01:00 ** Queue 'dftaskhub20251017-control-08' approximate message count: 3409

Note how after about 13:19:19, the queue length kept increasing, and didn't decrease until we stopped feeding it data. See here:

2025-10-24T14:31:28.9081651+01:00 ** Queue 'dftaskhub20251017-control-08' approximate message count: 23973
2025-10-24T14:34:02.3983302+01:00 ** Queue 'dftaskhub20251017-control-08' approximate message count: 24841
2025-10-24T14:36:36.2052815+01:00 ** Queue 'dftaskhub20251017-control-08' approximate message count: 25344
2025-10-24T14:39:08.0376097+01:00 ** Queue 'dftaskhub20251017-control-08' approximate message count: 25643
2025-10-24T14:41:44.0906229+01:00 ** Queue 'dftaskhub20251017-control-08' approximate message count: 25802
2025-10-24T14:44:15.8541931+01:00 ** Queue 'dftaskhub20251017-control-08' approximate message count: 25509
2025-10-24T14:46:48.5499487+01:00 ** Queue 'dftaskhub20251017-control-08' approximate message count: 24816
2025-10-24T14:49:25.5136979+01:00 ** Queue 'dftaskhub20251017-control-08' approximate message count: 25356
2025-10-24T14:51:57.6595944+01:00 ** Queue 'dftaskhub20251017-control-08' approximate message count: 25426
2025-10-24T14:54:30.1004432+01:00 ** Queue 'dftaskhub20251017-control-08' approximate message count: 25360
2025-10-24T14:57:02.1779496+01:00 ** Queue 'dftaskhub20251017-control-08' approximate message count: 24506
2025-10-24T14:59:35.0506516+01:00 ** Queue 'dftaskhub20251017-control-08' approximate message count: 23871
2025-10-24T15:02:07.5116697+01:00 ** Queue 'dftaskhub20251017-control-08' approximate message count: 22853
2025-10-24T15:04:38.6246701+01:00 ** Queue 'dftaskhub20251017-control-08' approximate message count: 21648
2025-10-24T15:07:10.7206149+01:00 ** Queue 'dftaskhub20251017-control-08' approximate message count: 21394
2025-10-24T15:09:42.3077077+01:00 ** Queue 'dftaskhub20251017-control-08' approximate message count: 20404
2025-10-24T15:12:17.3671656+01:00 ** Queue 'dftaskhub20251017-control-08' approximate message count: 19910
2025-10-24T15:14:48.9950207+01:00 ** Queue 'dftaskhub20251017-control-08' approximate message count: 19220
2025-10-24T15:17:21.3608939+01:00 ** Queue 'dftaskhub20251017-control-08' approximate message count: 18891
2025-10-24T15:19:53.2938963+01:00 ** Queue 'dftaskhub20251017-control-08' approximate message count: 17823
2025-10-24T15:22:25.9971303+01:00 ** Queue 'dftaskhub20251017-control-08' approximate message count: 16466
2025-10-24T15:25:00.5869464+01:00 ** Queue 'dftaskhub20251017-control-08' approximate message count: 15846
2025-10-24T15:27:37.3661966+01:00 ** Queue 'dftaskhub20251017-control-08' approximate message count: 14678
2025-10-24T15:30:12.3097051+01:00 ** Queue 'dftaskhub20251017-control-08' approximate message count: 13925
2025-10-24T15:32:48.3155140+01:00 ** Queue 'dftaskhub20251017-control-08' approximate message count: 14009
2025-10-24T15:35:22.3370456+01:00 ** Queue 'dftaskhub20251017-control-08' approximate message count: 12689
2025-10-24T15:37:56.5844638+01:00 ** Queue 'dftaskhub20251017-control-08' approximate message count: 12314
2025-10-24T15:40:33.4368450+01:00 ** Queue 'dftaskhub20251017-control-08' approximate message count: 12195
2025-10-24T15:43:05.5088857+01:00 ** Queue 'dftaskhub20251017-control-08' approximate message count: 11419
2025-10-24T15:45:39.3806519+01:00 ** Queue 'dftaskhub20251017-control-08' approximate message count: 10930
2025-10-24T15:48:12.6941979+01:00 ** Queue 'dftaskhub20251017-control-08' approximate message count: 9847
2025-10-24T15:50:44.6108600+01:00 ** Queue 'dftaskhub20251017-control-08' approximate message count: 10276
2025-10-24T15:53:18.7534214+01:00 ** Queue 'dftaskhub20251017-control-08' approximate message count: 8585
2025-10-24T15:55:49.9630915+01:00 ** Queue 'dftaskhub20251017-control-08' approximate message count: 123
2025-10-24T15:58:20.3766872+01:00 ** Queue 'dftaskhub20251017-control-08' approximate message count: 3
2025-10-24T16:00:50.0202858+01:00 ** Queue 'dftaskhub20251017-control-08' approximate message count: 0
2025-10-24T16:03:19.0296815+01:00 ** Queue 'dftaskhub20251017-control-08' approximate message count: 6
2025-10-24T16:05:48.7418232+01:00 ** Queue 'dftaskhub20251017-control-08' approximate message count: 0

Looking into the partition table in table storage:

So they are both trying to use the same host (we have 10 max scale-out and 16 partitions)

Could this be a concern? I'm happy to drop to 10 partitions so we'll have a 1-1 relationship at max scale-out if that's [currently] the right answer.

[ericleigh007]

We have a support incident open that we're keen to help out with here. The number is 2510240050002919.

We'll run a new test today with UseLegacyPartitionManagement set to true, in order to revert to the old blob-leased-based partition managment.

if we do get queue backups again, then this will let you guys know that the problem doesn't follow the partition management strategy. if it works fine, we can weather a little more cost if it keeps our system stable.

If the queues backup again, we'll take @cgillum advice and restart the function app and report whether that helps.

I'm also ready to send some emails containing InstanceId's, function app names, etc, but we're discouraged from doing so in the clear, as you might imagine.

-thoughts @davidmrdavid @sebastianburckhardt other?
-e

[davidmrdavid]

I'll defer to the DF team at this time, but I think your experimentation plan is sound. It would be very informative to know if the problem improves after a restart, or after changing to another partition manager. Ideally, we'd isolate variables, but I understand that you're looking for mitigate your app first.

[ericleigh007]

So far, the new test with (weirdly you have to do it this way) UseLegacyParititionManagement true and UseTablePartitionManagement false seems quite smooth.
Most of the time, or files are moving through a few every minute, with a few in parallel, as it should be.

our graph now looks like this: NO pesky age that keeps growing and growing, and no queues that get deeper and deeper with no end in sight.

We've seen a case where the contorl-02 queue backed up for a few mintues, but some minutes later, it cleared itself. This doens't happen with the table partition manager.... it just keeps growing.

2025-10-28T17:15:51.0437957+00:00 ** Queue 'dftaskhub20251017-control-02' approximate message count: 1
2025-10-28T17:18:20.8248886+00:00 ** Queue 'dftaskhub20251017-control-02' approximate message count: 3
2025-10-28T17:20:59.7234256+00:00 ** Queue 'dftaskhub20251017-control-02' approximate message count: 1
2025-10-28T17:23:29.5401206+00:00 ** Queue 'dftaskhub20251017-control-02' approximate message count: 8
2025-10-28T17:25:59.7621681+00:00 ** Queue 'dftaskhub20251017-control-02' approximate message count: 10
2025-10-28T17:28:30.4207558+00:00 ** Queue 'dftaskhub20251017-control-02' approximate message count: 22
2025-10-28T17:31:01.8327029+00:00 ** Queue 'dftaskhub20251017-control-02' approximate message count: 8
2025-10-28T17:33:32.6988090+00:00 ** Queue 'dftaskhub20251017-control-02' approximate message count: 309
2025-10-28T17:36:07.7413695+00:00 ** Queue 'dftaskhub20251017-control-02' approximate message count: 1755
2025-10-28T17:38:38.1310126+00:00 ** Queue 'dftaskhub20251017-control-02' approximate message count: 2500
2025-10-28T17:41:08.1758522+00:00 ** Queue 'dftaskhub20251017-control-02' approximate message count: 3084
2025-10-28T17:43:38.2226817+00:00 ** Queue 'dftaskhub20251017-control-02' approximate message count: 3872
2025-10-28T17:46:09.0913411+00:00 ** Queue 'dftaskhub20251017-control-02' approximate message count: 4861
2025-10-28T17:48:39.4685868+00:00 ** Queue 'dftaskhub20251017-control-02' approximate message count: 4474
2025-10-28T17:51:12.1043644+00:00 ** Queue 'dftaskhub20251017-control-02' approximate message count: 2
2025-10-28T17:53:42.7092585+00:00 ** Queue 'dftaskhub20251017-control-02' approximate message count: 4
2025-10-28T17:56:14.1878300+00:00 ** Queue 'dftaskhub20251017-control-02' approximate message count: 2

[ericleigh007]

Late update: Quick take: the partition manager type doesn't seem to matter here:

Details, blow by blow:

The test began to show the same symptoms as the table partition manager, The test with the legacy management came to a bad end at about 2100 hours.  Preliminarily, we had 4 control queues back up, 

   2025-10-28T21:24:44.6090569+00:00 ** Queue 'dftaskhub20251017-workitems' approximate message count: 50              
   2025-10-28T21:24:44.6090569+00:00 ** Queue 'dftaskhub20251017-control-00' approximate message count: 1
   2025-10-28T21:24:44.6090569+00:00 ** Queue 'dftaskhub20251017-control-01' approximate message count: 1              
   2025-10-28T21:24:44.6090569+00:00 ** Queue 'dftaskhub20251017-control-02' approximate message count: 2
   2025-10-28T21:24:44.6090569+00:00 ** Queue 'dftaskhub20251017-control-03' approximate message count: 4760
   2025-10-28T21:24:44.6090569+00:00 ** Queue 'dftaskhub20251017-control-04' approximate message count: 4042            
   2025-10-28T21:24:44.6090569+00:00 ** Queue 'dftaskhub20251017-control-05' approximate message count: 1              
   2025-10-28T21:24:44.6090569+00:00 ** Queue 'dftaskhub20251017-control-06' approximate message count: 1
   2025-10-28T21:24:44.6090569+00:00 ** Queue 'dftaskhub20251017-control-07' approximate message count: 1
   2025-10-28T21:24:44.6090569+00:00 ** Queue 'dftaskhub20251017-control-08' approximate message count: 0
   2025-10-28T21:24:44.6090569+00:00 ** Queue 'dftaskhub20251017-control-09' approximate message count: 0              
   2025-10-28T21:24:44.6090569+00:00 ** Queue 'dftaskhub20251017-control-10' approximate message count: 1
   2025-10-28T21:24:44.6090569+00:00 ** Queue 'dftaskhub20251017-control-11' approximate message count: 2999
   2025-10-28T21:24:44.6090569+00:00 ** Queue 'dftaskhub20251017-control-12' approximate message count: 4687
   2025-10-28T21:24:44.6090569+00:00 ** Queue 'dftaskhub20251017-control-13' approximate message count: 0              
   2025-10-28T21:24:44.6090569+00:00 ** Queue 'dftaskhub20251017-control-14' approximate message count: 0
   2025-10-28T21:24:44.6090569+00:00 ** Queue 'dftaskhub20251017-control-15' approximate message count: 2

The logs are available, and we'll have more tomorrow.... time of the test, and the application insights instance:
UTC 12:11 - UTC 22:00 approx (depending on the slowdown, might be a bit later)
There is a app insights instance in the same rg as the durable function app (I assume you have the details of our deployment now)

Anecdotally, it appeared in live metrics that 3 CPUs were taking most of the load.  Will include the CPU graph to veify that claim tomorrow.

After seeing these backlogs in the queues and seeing that orchestrators were stuck (this is detected because files don't move through the file processing steps), at about 21:50 we;
Restarted the function app.  After a few minutes after that, the first two queues cleared out but the last two did not.  We waited 10 minutes or so to verify it wasn't going to happen.
Stopped the function app, watched the queue depths decrease, then started it again.
It took a few minutes, but after a while the queue depths got back to normal.

At this point in our analysis, it doesn't seem as if any files were left behind, so even though the function app was stopped, and the queue entries were not longer being added, durable functions remained "durable".  No data seemed to be lost.

The queue recovery after the stop, wait and start operations looked like:

2025-10-28T21:47:46.4448283+00:00 ** Queue 'dftaskhub20251017-control-12' approximate message count: 4951
>> reset function app around here
2025-10-28T21:48:09.0068776+00:00 ** Queue 'dftaskhub20251017-control-12' approximate message count: 3939
2025-10-28T21:48:30.0992805+00:00 ** Queue 'dftaskhub20251017-control-12' approximate message count: 2424
2025-10-28T21:48:52.0848358+00:00 ** Queue 'dftaskhub20251017-control-12' approximate message count: 875
2025-10-28T21:49:13.9588944+00:00 ** Queue 'dftaskhub20251017-control-12' approximate message count: 73
2025-10-28T21:49:34.5058710+00:00 ** Queue 'dftaskhub20251017-control-12' approximate message count: 72
2025-10-28T21:49:55.2086409+00:00 ** Queue 'dftaskhub20251017-control-12' approximate message count: 64
2025-10-28T21:50:19.1158545+00:00 ** Queue 'dftaskhub20251017-control-12' approximate message count: 64
2025-10-28T21:50:40.6458333+00:00 ** Queue 'dftaskhub20251017-control-12' approximate message count: 65
2025-10-28T21:51:01.0850425+00:00 ** Queue 'dftaskhub20251017-control-12' approximate message count: 66
2025-10-28T21:51:22.5989516+00:00 ** Queue 'dftaskhub20251017-control-12' approximate message count: 71
2025-10-28T21:51:43.0843655+00:00 ** Queue 'dftaskhub20251017-control-12' approximate message count: 70
2025-10-28T21:52:04.4733887+00:00 ** Queue 'dftaskhub20251017-control-12' approximate message count: 42
2025-10-28T21:52:24.9416901+00:00 ** Queue 'dftaskhub20251017-control-12' approximate message count: 1
2025-10-28T21:52:47.7853723+00:00 ** Queue 'dftaskhub20251017-control-12' approximate message count: 26
2025-10-28T21:53:07.9893247+00:00 ** Queue 'dftaskhub20251017-control-12' approximate message count: 0
2025-10-28T21:53:28.3952607+00:00 ** Queue 'dftaskhub20251017-control-12' approximate message count: 0
2025-10-28T21:53:59.6447113+00:00 ** Queue 'dftaskhub20251017-control-12' approximate message count: 0

So the answer to @cgillum question from before "Does restarting your app make the stuck orchestrations un-stuck?" is YES, it seems to recover if you restart the function app.

Next, I wanted to ASK you guys a couple of things toward moving this toward a solution:

• Are you waiting for more confirmation from either the ticket or some management entity in order to look into this?
• Do you have all the information necessary to investigate your extra special backend logs?
• If not, what do you neeed, and when might you have time to investigate what's going on here?

What can I DO to determine the cause of the queue processing stopping? The logs seem verbose, but I don't know how to find the particular instanceId that was processed as the queue stopped. Other than some vague reference to deserialization causing a problem in some cases, there is no detail on how to determine if that could be it, let alone track the problem down.

I can try to break down any limitations that might allow you guys to investigate our logs fully which have DurableTAsk.Core and DurableTask.AzureStorage Informational tracking enabled.

NEXT STEPS: I believe that, since we have proven the "freezing queues" happens with both partition manager flavors, it might be better to return to the newer V3 partition handling. The newer implementation is certainly more straightforward.

[ericleigh007]

I'll return to a previous instance of the problem where 08 and 13 backed up... This happened around 12:02 to 12:14 Zulu on 2025-10-24. The queue did this (note we're displaying local time with offset here):

2025-10-24T13:02:31.5272807+01:00 ** Queue 'dftaskhub20251017-control-08' approximate message count: 0
2025-10-24T13:11:19.9940839+01:00 ** Queue 'dftaskhub20251017-control-08' approximate message count: 0
2025-10-24T13:19:19.4048982+01:00 ** Queue 'dftaskhub20251017-control-08' approximate message count: 15
2025-10-24T13:22:10.1375039+01:00 ** Queue 'dftaskhub20251017-control-08' approximate message count: 118
2025-10-24T13:24:40.6653776+01:00 ** Queue 'dftaskhub20251017-control-08' approximate message count: 416
2025-10-24T13:27:23.2663002+01:00 ** Queue 'dftaskhub20251017-control-08' approximate message count: 562
2025-10-24T13:29:53.3611451+01:00 ** Queue 'dftaskhub20251017-control-08' approximate message count: 744
2025-10-24T13:32:23.0374825+01:00 ** Queue 'dftaskhub20251017-control-08' approximate message count: 934
2025-10-24T13:34:55.1558335+01:00 ** Queue 'dftaskhub20251017-control-08' approximate message count: 1654
2025-10-24T13:37:25.0837628+01:00 ** Queue 'dftaskhub20251017-control-08' approximate message count: 2506

In this instance, it possibly is a clue that we got the following status just before it seemed the queue began to back up.

TO BE FAIR, though, all the queues have the same message and it is very frequent. Are they more frequent than expected here, and could this message indicate a condition that could, albeit not often, lock up a queue?

AbandoningMessage
According to the somewhat-out-of-date docs (they don't mention the new partition manager), this means:
If a lease was reassigned to a different task hub worker after an orchestration started running, it's possible that the orchestration instance will be active on one worker but messages will arrive on another. In this case, we cannot know whether the orchestration associated with a message is active or not. Same story if the worker is recycled in the middle of orchestration process. Instead of relying on an in-memory list of active orchestration sessions, we have to use timestamps to detect race conditions. Each message has a timestamp and the orchestration has a "last checkpoint completed" timestamp. If the timestamp of a message comes after the timestamp of the checkpoint, then we know the orchestration is not yet ready to process the message. We handle this by putting the message back on the queue and tracing a warning message (AbandoningMessage). The orchestration's "last checkpoint completed" timestamp will be updated soon, so eventually the abandoned message can be processed successfully.

We got this message 115 times within the space of about 12:12 to about 12:27, and I'd be happy to share logs when somebody makes contact.

[ericleigh007]

Pix as we encounted the queue slowdown again, from 11:30 to 12:30 today, this time in 4 queues == 2 hosts.

This is the imbalance in load on activities for the 9 roles that were running at the time.

After restarted the function app at around 12:42, things straightened out, and the load got much better balanced. Queues are okay, and we're still running at this hour.

[davidmrdavid]

I'm not a DF maintainer so this is just an OSS community member chiming in:

At some point, you mentioned:

No data seemed to be lost.WELL, BUT IT DIDN'T.

Can you please clarify this point? The phrasing is a bit strange, and it seems to suggest maybe there was data loss? Not sure, but it would be good to clarify.

TO BE FAIR, though, all the queues have the same message and it is very frequent. Are they more frequent than expected here, and could this message indicate a condition that could, albeit not often, lock up a queue? [...] AbandoningMessage

Ah, this could be a good clue. You should know that the way a message is abandoned is that it is put back into the queue, and made 'invisible' for a period of time (meaning it cannot be dequeued for that period of time) so that it 'hides' in the queue until it can be de-queued again. That's implemented here:

durabletask/src/DurableTask.AzureStorage/Messaging/TaskHubQueue.cs

Lines 269 to 290 in 852837c

	this.settings.Logger.AbandoningMessage(
	this.storageAccountName,
	this.settings.TaskHubName,
	eventType,
	taskEventId,
	queueMessage.MessageId,
	instanceId,
	executionId,
	this.storageQueue.Name,
	sequenceNumber,
	queueMessage.PopReceipt,
	numSecondsToWait);
	try
	{
	// We "abandon" the message by settings its visibility timeout using an exponential backoff algorithm.
	// This allows it to be reprocessed on this node or another node at a later time, hopefully successfully.
	return await this.storageQueue.UpdateMessageAsync(
	queueMessage,
	TimeSpan.FromSeconds(numSecondsToWait),
	traceActivityId);
	}

So I wonder if that 'growth' in your queues is really just 'abandoned messages' that are technically in the queue, but not ready yet to be processed, as not enough time has passed. That technically doesn't explain why restarts help, but it's a very-very-rough possibility in the back of my mind.

Do your logs tell you what kind of message is being abandoned? That could provide a clue. Is it an activity result, an "executed started event", or something else?

[ericleigh007]

Yes I have looking at the code for a while now. I was trying to enable the full debug level traces today and duplicate the problem but it appears one must somehow do that by other than just setting logging levels in host.json

If there is an example of this you can share that would be great.

As far as we know we're not losing data but things slow down a lot. Restarting the function app helps even if we maintain the load.

Building a smaller test Case now and if we can duplicate we'll share the code

[davidmrdavid]

This may help for DTFx-level logging: https://learn.microsoft.com/en-us/azure/azure-functions/durable/durable-functions-diagnostics?tabs=csharp-inproc#durable-task-framework-logging

[ericleigh007]

Thanks, @davidmrdavid we have those enabled, but they don't seem to quite tell the entire story about what happens to a workitem throughout its life.

[ericleigh007]

Today, 2025-10-04 we captured an event with full debug level logging on in DurableTask.Core and DurableTask.AzureStorage. 4 queues backed up, two instances went to 100% CPU and stayed there.

I'll edit this later tonight with any more data i've collected.

If you still need me to copy this problem report into the .Extension library, we can do that, although the problem appears to be here.

The MS ticket has been escalated to you guys, as I understand it.

On my side, I've been putting orchestrator names against their partitions, and there seems to be no pattern as to perhaps having the same orchestrator scheduled on the "bad" partitions. This makes sense of course, due to the hashing by id, but I was checking to see if some particular orchestrator could be prevelant on or only on particular partitions.