Azure webjob not appearing to respect MaxDequeueCount property

Question

I've got an Azure webjob with several queue-triggered functions. The SDK documentation at https://learn.microsoft.com/en-us/azure/app-service-web/websites-dotnet-webjobs-sdk-storage-queues-how-to#config defines the MaxDequeueCount property as:

The maximum number of retries before a queue message is sent to a poison queue (default is 5).

but I'm not seeing this behavior. In my webjob I've got:

JobHostConfiguration config = new JobHostConfiguration();
config.Queues.MaxDequeueCount = 1;
JobHost host = new JobHost(config);
host.RunAndBlock();

and then I've got a queue-triggered function in which I throw an exception:

public void ProcessQueueMessage([QueueTrigger("azurewejobtestingqueue")] string item, TextWriter logger)
{
   if ( item == "exception" )
   {
      throw new Exception();
   }
}

Looking at the webjobs dashboard I see that the SDK makes 5 attempts (5 is the default as stated above):

and after the 5th attempt the message is moved to the poison queue. I expect to see 1 retry (or no retries?) not 5.

UPDATE: Enabled detailed logging for the web app and opted to save those logs to an Azure blob container. Found some logs relevant to my problem located in the azure-jobs-host-archive container. Here's an example showing an item with a dequeue count of 96:

{
  "Type": "FunctionCompleted",
  "EndTime": "2017-02-22T00:07:40.8133081+00:00",
  "Failure": {
    "ExceptionType": "Microsoft.Azure.WebJobs.Host.FunctionInvocationException",
    "ExceptionDetails": "Microsoft.Azure.WebJobs.Host.FunctionInvocationException: Exception while executing function: ItemProcessor.ProcessQueueMessage ---> MyApp.Exceptions.MySpecialAppExceptionType: Exception of type 'MyApp.Exceptions.MySpecialAppExceptionType' was thrown.
  },
  "ParameterLogs": {},
  "FunctionInstanceId": "1ffac7b0-1290-4343-8ee1-2af0d39ae2c9",
  "Function": {
    "Id": "MyApp.Processors.ItemProcessor.ProcessQueueMessage",
    "FullName": "MyApp.Processors.ItemProcessor.ProcessQueueMessage",
    "ShortName": "ItemProcessor.ProcessQueueMessage",
    "Parameters": [
      {
        "Type": "QueueTrigger",
        "AccountName": "MyStorageAccount",
        "QueueName": "stuff-processor",
        "Name": "sourceFeedItemQueueItem"
      },
      {
        "Type": "BindingData",
        "Name": "dequeueCount"
      },
      {
        "Type": "ParameterDescriptor",
        "Name": "logger"
      }
    ]
  },
  "Arguments": {
    "sourceFeedItemQueueItem": "{\"SourceFeedUpdateID\":437530,\"PodcastFeedID\":\"2d48D2sf2\"}",
    "dequeueCount": "96",
    "logger": null
  },
  "Reason": "AutomaticTrigger",
  "ReasonDetails": "New queue message detected on 'stuff-processor'.",
  "StartTime": "2017-02-22T00:07:40.6017341+00:00",
  "OutputBlob": {
    "ContainerName": "azure-webjobs-hosts",
    "BlobName": "output-logs/1ffd3c7b012c043438ed12af0d39ae2c9.txt"
  },
  "ParameterLogBlob": {
    "ContainerName": "azure-webjobs-hosts",
    "BlobName": "output-logs/1cf2c1b012sa0d3438ee12daf0d39ae2c9.params.txt"
  },
  "LogLevel": "Info",
  "HostInstanceId": "d1825bdb-d92a-4657-81a4-36253e01ea5e",
  "HostDisplayName": "ItemProcessor",
  "SharedQueueName": "azure-webjobs-host-490daea03c70316f8aa2509438afe8ef",
  "InstanceQueueName": "azure-webjobs-host-d18252sdbd92a4657d1a436253e01ea5e",
  "Heartbeat": {
    "SharedContainerName": "azure-webjobs-hosts",
    "SharedDirectoryName": "heartbeats/490baea03cfdfd0416f8aa25aqr438afe8ef",
    "InstanceBlobName": "zd1825bdbdsdgga465781a436q53e01ea5e",
    "ExpirationInSeconds": 45
  },
  "WebJobRunIdentifier": {
    "WebSiteName": "myappengine",
    "JobType": "Continuous",
    "JobName": "ItemProcessor",
    "RunId": ""
  }
}

What I'm further looking for though are logs which would show me detail for a particular queue item where processing succeeds (and hence is removed from the queue) or fails due to an exception and is placed in the poison queue. I so far haven't found any logs showing that detail. The log files referenced in the output above do not contain data of this sort.

UPDATE 2: Looked at the state of my poison queue and it seems like it could be a smoking gun but I'm too dense to put 2 and 2 together. Looking at the screenshot of the queue below you can see the message with the ID (left column) 431210 in there many times. The fact that it appears multiple times says to me that the message in the original queue is failing improperly.

Answer 1

As mentioned by Rob W, this issue exists when using WindowsAzure.Storage > 7.1.2. The issue has apparently been fixed in issue #1141 but this has not yet made it into a release.

Contributer asifferman has shared a code snippet in a comment post on issue #985. that appears to resolve the problem (it worked perfectly for me).

In case of link rot, and to meet SO rules, here's the post along with the code snippet:

For those (like me) who cannot wait the next release to get the WebJobs SDK to work with the latest releases of Azure Storage, and based on the explanations of @brettsam, you can simply write a custom CustomQueueProcessorFactory to create a new CloudQueueMessage in CopyMessageToPoisonQueueAsync.

namespace ConsoleApplication1
{
    using Microsoft.Azure.WebJobs.Host.Queues;
    using Microsoft.WindowsAzure.Storage.Queue;
    using System.Threading;
    using System.Threading.Tasks;

    public class CustomQueueProcessorFactory : IQueueProcessorFactory
    {
        public QueueProcessor Create(QueueProcessorFactoryContext context)
        {
            return new CustomQueueProcessor(context);
        }

        private class CustomQueueProcessor : QueueProcessor
        {
            public CustomQueueProcessor(QueueProcessorFactoryContext context)
                : base(context)
            {
            }

            protected override Task CopyMessageToPoisonQueueAsync(CloudQueueMessage message, CloudQueue poisonQueue, CancellationToken cancellationToken)
            {
                var newMessage = new CloudQueueMessage(message.Id, message.PopReceipt);
                newMessage.SetMessageContent(message.AsBytes);

                return base.CopyMessageToPoisonQueueAsync(newMessage, poisonQueue, cancellationToken);
            }
        }
    }
}

Then in your Main, you just have to set the custom queue processor factory in the job host configuration:

var config = new JobHostConfiguration();
config.Queues.QueueProcessorFactory = new CustomQueueProcessorFactory();

I could get it work with WindowsAzure.Storage 8.1.1 and Microsoft.Azure.WebJobs 2.0.0. Hope that helps!

Answer 2

If you are still seeking an answer, we tried some of the answers listed without success. It turns out that it was a version issue with the Storage sdk (WindowsAzure.Storage) and the Webjob sdk (Microsoft.Azure.WebJobs). To fix it, we ended up having to downgrade our version of the Storage sdk to 7.2.1 (we had recently upgraded to 8.1.1). Based on the article below, the engineers are now aware of the problems and will hopefully have it fixed soon:

https://github.com/Azure/azure-webjobs-sdk/issues/1045

Answer 3

MaxDequeueCount property works correctly for me if I configure it.

So it is very odd that it is not working for you. When I set config.Queues.MaxDequeueCount = 2; then I get the expected result please refer to the screenshot.

And we also could use dequeueCount to control the retry times. The following is the demo code for no try.

public void ProcessQueueMessage([QueueTrigger("queue")] string item, int dequeueCount, TextWriter logger)
        {
            if (dequeueCount == 1)
            {
                if (item == "exception")
                {
                    throw new Exception();
                }
                logger.WriteLine($"NewMsge: {item}");
                Console.WriteLine($"NewMsge: {item}");
            }
        }

Log info please refer to the screenshot