Azure logs webjob - search for logs that detail the processing of SDK items with queue triggering

Question

As my Azure webjob question showing no respect for the MaxDequeueCount property , I was looking for a problem, despite the fact that despite the fact that my setting for the MaxDequeueCount property was 1, some items are deleted many times before they are poisoned (actually some items can never be poisoned at all, but simply deactivate, fail, and repeat and fail forever).

The Webjobs SDK handles retries and poisoning of queued messages, and I'm looking for logs that contain information about this processing.

For example, I see that my function detected a new queue item by viewing the webjob log through SCM at https://myappengine.scm.azurewebsites.net/vfs/data/jobs/continuous/StuffProcessor/job_log.txt (by the way, if I turned on detailed logging in Azure storage in a web application, can I get the same information in Blob?).

 [02/22/2017 01:47:22 > ec8d0f: INFO] Executing: 'StuffProcessor.ProcessQueueMessage' - Reason: 'New queue message detected on 'stuff-processor'.' [02/22/2017 01:47:26 > ec8d0f: INFO] Executed: 'StuffProcessor.ProcessQueueMessage' (Succeeded) [02/22/2017 01:47:26 > ec8d0f: INFO] Executing: 'StuffProcessor.ProcessQueueMessage' - Reason: 'New queue message detected on 'stuff-processor'.' 

I can also get some information about the item detection account by looking at the logs in the azure-jobs-host-archive container as soon as I enable detailed logging in Azure storage in a web application:

 { "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 cannot find are logs that show details for a particular queue element, where processing fails due to an exception and is put in the poison queue. I am looking for them, trying to continue eliminating the explicit ignoring of the MaxDequeueCount property. Is it registered?

UPDATE: I found an Azure WebJobs message with a storage queue and exceptions, and it showed the following screenshot:

This screenshot displays the standard messages "A new message with a message about sending messages ..." (which I see both on Azure and on the local computer in the emulator), and also shows: "The message has reached MaxDequeueCount X ... Moving the message to the xyz-poison queue, which I see only in the emulator. For some reason, does the Azure-based runtime not work? I never see such messages related to poisoning when run locally in the console window or using the toolbar webjobs or when starting on Azure.

Answer 1

Are you using Azure Storage version 8. *? It contains an interrupt change.

When a queue message object is inserted into a message queue in Azure Storage 8, the message identifier of the original queue message object is overwritten with the unique message identifier of the message just inserted.

This means that he loses his link to a poisonous message and can no longer delete it.

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

As for the magazine, 2 options:

• Create your own QueueProcessorFactory and QueueProcessor - you can override the method that processes poisonous messages to get more debug output. There you can also fix the problem if you want to stay on Azure Storage 8. *.

• Register a trace monitor. https://github.com/Azure/azure-webjobs-sdk-extensions/wiki/Error-Monitoring#tracemonitor

   var traceMonitor = new TraceMonitor() .Filter(p => true, "Trace Handler") .Subscribe(TraceHandler.Process); config.Tracing.Tracers.Add(traceMonitor); 

Answer 2

In the previous post, you have a running function, as shown below.

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

Everything you write in the log should appear in the logs in the WebJobs toolbar. My suggestions:

• Change the 'if (item == "exception") to to if (item.ToLower (). StartsWith ("exception")'. Then add the number to the error message when testing the queue messages in TextWriter so you can be sure that look at the same message that you think you are checking.

• You can get the decompression value of a message as a function parameter. See here . In this example, consider the FailAlways method. Register with TextWriter as well.

• Try doing this locally. All output will be written to the console window. See if you have the same behavior.

I'm really curious to know what causes this behavior, so make sure you let us know if you crack it!