Azure storage queue/functions, dequeue from poison queue only once

Question

I have a problem with azure storage functions+azure storage queue. I have a queue - "myQueue" and queue-triggered azure function "func1". In host.json I've configured maxDequeueCount(5) and visibilityTimeout - everything works nice.

After 5 tries my message goes to "myQueue-poison". I have second azure function "func2"(copy paste from func1), which is queue-triggered from "myQueue-poison". I've also set maxDequeueCount and visibilityTimeout in host.json for this function. But this function is triggered only once - after first failed run my message disappears from queue. What's wrong? host.json and c# code are identical - only the name of the queue is different.

Below is the code from Function 1 and Function 2.

[FunctionName("Function1")]
        public static void Run([QueueTrigger("myqueue-poison", Connection = "AzureWebJobsStorage")]string myQueueItem, ILogger log)
        {
            Exception ex = new Exception();
            throw ex;
        }



 [FunctionName("Function2")]
        public static void Run([QueueTrigger("myqueue", Connection = "AzureWebJobsStorage")]string myQueueItem, ILogger log)
        {
            Exception ex = new Exception();            
            throw ex;
        }

Sample log message where there is delay in messages getting processed from poison queue.

 [12/5/2018 9:39:16 PM] Loading functions metadata
    [12/5/2018 9:39:16 PM] 2 functions loaded
    [12/5/2018 9:39:17 PM] Generating 2 job function(s)
    [12/5/2018 9:39:17 PM] Found the following functions:
    [12/5/2018 9:39:17 PM] FunctionApp1.Function1.Run
    [12/5/2018 9:39:17 PM] FunctionApp1.Function2.Run
    [12/5/2018 9:39:17 PM]
    [12/5/2018 9:39:17 PM] Host initialized (662ms)
    [12/5/2018 9:39:17 PM] Host started (707ms)
    [12/5/2018 9:39:17 PM] Job host started
    Hosting environment: Production
    Content root path: C:\Users\username\source\repos\FunctionApp1\FunctionApp1\bin\Debug\netstandard2.0
    Now listening on: http://0.0.0.0:7071
    Application started. Press Ctrl+C to shut down.
    [12/5/2018 9:39:18 PM] Executing 'Function2' (Reason='New queue message detected on 'myqueue'.', Id=20bf83c5-3142-4092-9d85-7a2a6fbcf863)
    [12/5/2018 9:39:18 PM] Executed 'Function2' (Failed, Id=20bf83c5-3142-4092-9d85-7a2a6fbcf863)
    [12/5/2018 9:39:18 PM] System.Private.CoreLib: Exception while executing function: Function2. FunctionApp1: Exception of type 'System.Exception' was thrown.
    [12/5/2018 9:39:18 PM] Executing 'Function2' (Reason='New queue message detected on 'myqueue'.', Id=49775db2-0c91-41cb-b472-a3aceee1bac3)
    [12/5/2018 9:39:19 PM] Executed 'Function2' (Failed, Id=49775db2-0c91-41cb-b472-a3aceee1bac3)
    [12/5/2018 9:39:19 PM] System.Private.CoreLib: Exception while executing function: Function2. FunctionApp1: Exception of type 'System.Exception' was thrown.
    [12/5/2018 9:39:19 PM] Executing 'Function2' (Reason='New queue message detected on 'myqueue'.', Id=0a1d103a-41a0-4630-a479-c72297a368b8)
    [12/5/2018 9:39:19 PM] Executed 'Function2' (Failed, Id=0a1d103a-41a0-4630-a479-c72297a368b8)
    [12/5/2018 9:39:19 PM] System.Private.CoreLib: Exception while executing function: Function2. FunctionApp1: Exception of type 'System.Exception' was thrown.
    [12/5/2018 9:39:19 PM] Executing 'Function2' (Reason='New queue message detected on 'myqueue'.', Id=6b79aad1-1eb6-4cfe-b39c-a7078f006968)
    [12/5/2018 9:39:20 PM] Executed 'Function2' (Failed, Id=6b79aad1-1eb6-4cfe-b39c-a7078f006968)
    [12/5/2018 9:39:20 PM] System.Private.CoreLib: Exception while executing function: Function2. FunctionApp1: Exception of type 'System.Exception' was thrown.
    [12/5/2018 9:39:20 PM] Executing 'Function2' (Reason='New queue message detected on 'myqueue'.', Id=cf401aee-133d-42ac-a8e0-25fe95ebe162)
    [12/5/2018 9:39:20 PM] Executed 'Function2' (Failed, Id=cf401aee-133d-42ac-a8e0-25fe95ebe162)
    [12/5/2018 9:39:20 PM] System.Private.CoreLib: Exception while executing function: Function2. FunctionApp1: Exception of type 'System.Exception' was thrown.
    [12/5/2018 9:39:20 PM] Message has reached MaxDequeueCount of 5. Moving message to queue 'myqueue-poison'.
    [12/5/2018 9:39:20 PM] Executing 'Function1' (Reason='New queue message detected on 'myqueue-poison'.', Id=2b1bd5ec-67e2-41c9-bd7b-6a3fde48cd04)
    [12/5/2018 9:39:21 PM] Executed 'Function1' (Failed, Id=2b1bd5ec-67e2-41c9-bd7b-6a3fde48cd04)
    [12/5/2018 9:39:21 PM] System.Private.CoreLib: Exception while executing function: Function1. FunctionApp1: Exception of type 'System.Exception' was thrown.
    [12/5/2018 9:39:22 PM] Host lock lease acquired by instance ID '0000000000000000000000004EE22C73'.
[12/5/2018 9:49:20 PM] Executing 'Function1' (Reason='New queue message detected on 'myqueue-poison'.', Id=83f83d31-44e6-46cf-a235-08360e5adc60)
[12/5/2018 9:49:21 PM] Executed 'Function1' (Failed, Id=83f83d31-44e6-46cf-a235-08360e5adc60)
[12/5/2018 9:49:21 PM] System.Private.CoreLib: Exception while executing function: Function1. FunctionApp1: Exception of type 'System.Exception' was thrown.
[12/5/2018 9:59:21 PM] Executing 'Function1' (Reason='New queue message detected on 'myqueue-poison'.', Id=54acbb91-d4db-4737-ae90-47b17df5998c)
[12/5/2018 9:59:21 PM] Executed 'Function1' (Failed, Id=54acbb91-d4db-4737-ae90-47b17df5998c)
[12/5/2018 9:59:21 PM] System.Private.CoreLib: Exception while executing function: Function1. FunctionApp1: Exception of type 'System.Exception' was thrown.

So it looks like the messages from poison queue are not read in the same way as normal queues. Are there any configuration which can be used to reduce the delay in processing from poison queue ?

Can you elaborate on the expected behavior, why it's expected, and what the code is doing? — Mark C.
function logs message and throws exception - I want to test retrying. I expect 5x run of func1 with timeOut for example 30sec and 15x run of func2 with timeOut 5min — blidea
@blidea Do you mean that, dequeue count is not working for poison queue? — Baskar Rao
Yes I verified it creating a simple sample, the message is cleared from poison queue once it is dequeued from poison -queue - public static class Function1 { [FunctionName("Function1")] public static void Run([QueueTrigger("myqueue-poison", Connection = "AzureWebJobsStorage")]string myQueueItem, ILogger log) { Exception ex = new Exception(); log.LogInformation($"C# Queue trigger function processed: {myQueueItem}"); throw ex; } } — Baskar Rao

Ling Toh Ling Toh · Accepted Answer · 2018-12-06T08:49:35

This is not a supported scenario at the moment.

If the queue is already a poison queue, no subsequent poison queue will be created for the poison queue. Kindly see implementation here.

Since there is no 2nd poison queue for your poison-queue, the message will not be released while your Function is still running, i.e. it may take 10 minutes before you will see the message again. Kindly see implementation here.

Azure storage queue/functions, dequeue from poison queue only once

1 Answers