Azure Webjob日志-查找详细记录SDK对队列触发项的处理的日志 [英] Azure webjob logs - looking for logs that detail the SDK's handling of queue triggered items

问题描述

如我的堆栈溢出问题所示 Azure Webjob似乎不尊重MaxDequeueCount属性，我正在解决一个问题，尽管我将MaxDequeueCount属性设置为1，但某些项目在中毒之前已经多次出队(实际上有些物品可能永远不会中毒，而只是出队，失败，被重试和无休止地失败.

As shown in my Stack Overflow question Azure webjob not appearing to respect MaxDequeueCount property, I'm troubleshooting a problem where despite my setting of the MaxDequeueCount property to 1, some items are dequeued many times before they're poisoned (in fact some items may never be poisoned at all and just dequeue, fail and are retried and fail endlessly).

Webjobs SDK自动处理队列触发消息的重试和中毒，我正在寻找包含该处理细节的日志.

The Webjobs SDK handles the retries and poisoning of queue triggered messages automatically and I'm looking for logs that contain details of that handling.

例如，我可以通过在https://myappengine.scm.azurewebsites.net/vfs/data/jobs/continuous/StuffProcessor/job_log.txt处通过SCM查看Webjob的日志来看到我的函数已检测到新的队列项(顺便说一句，如果我在Web应用程序上启用了详细的Azure存储日志记录功能在Blob中获得相同的信息?).

For example, I can see that my function has detected a new queue item by viewing the webjob's log through the SCM at https://myappengine.scm.azurewebsites.net/vfs/data/jobs/continuous/StuffProcessor/job_log.txt (By the way if I've enabled detailed logging to Azure storage on the web app can I get this same info in a 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'.'

一旦在Web应用程序上启用了到Azure存储的详细日志记录，我还可以通过查看azure-jobs-host-archive容器中的日志来获取有关项目出队计数的一些信息:

I can also get some information on an item's dequeue count by viewing the logs in the azure-jobs-host-archive container once I've enabled detailed logging to Azure storage on the web app:

{
      "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": ""
      }
    }

我找不到的是显示特定队列项目详细信息的日志，该日志中由于异常而导致处理失败，并放置在中毒队列中.我正在寻找这些文件，以尝试进一步解决对MaxDequeueCount属性的明显忽略.这个记录了吗?

What I can't find though are logs which show detail for a particular queue item where processing fails due to an exception and is placed in the poison queue. I'm looking for these in an attempt to further troubleshoot the apparent ignoring of the MaxDequeueCount property. Is this logged?

更新:我找到了具有存储队列和异常的Azure WebJobs ，其中包含以下屏幕截图:

UPDATE: I found the post Azure WebJobs with Storage Queue and Exceptions and it contained the following screenshot:

该屏幕截图显示了标准的检测到新队列消息..."消息(我在Azure上看到该消息，并且在模拟器中本地运行)，并且还显示了消息已达到X的MaxDequeueCount ...正在将消息移动到队列"xyz-poison""，我仅在模拟器中本地看到.基于Azure的运行时是否由于某些原因不显示此信息? 在控制台窗口中本地运行，通过webjobs仪表板运行或在Azure上运行时，我从未看到过与中毒相关的消息.

That screenshot shows the standard "New queue message detected..." messages (which I see both on Azure and running locally in the emulator) and it also shows "Message has reached MaxDequeueCount of X...Moving message to queue 'xyz-poison'", which I only see locally in the emulator. Does the Azure-based runtime not show this info for some reason? I never see the poisoning-related messages like this when running locally in the console window or via the webjobs dashboard or when running on Azure.

推荐答案

您是否正在使用Azure存储版本8. *?它包含一个重大变化.

Are you using Azure Storage version 8.* ? It contains a breaking change.

将队列消息对象插入到Azure存储8的消息队列中时，原始队列消息对象的消息ID将被新插入的消息的唯一消息ID覆盖.

When a queue message object gets inserted into a message queue in Azure Storage 8, the Message Id of the original queue message object is overwritten with the unique message id of the newly inserted message.

这意味着它失去了对有毒消息的引用，无法再将其删除.

This means that it looses its reference to the poison message and can no longer remove it.

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

关于日志记录，有2个选项:

As for logging, 2 options:

1. 创建自己的QueueProcessorFactory和QueueProcessor-您可以覆盖处理有毒消息的方法以产生更多调试输出.如果要保留在Azure Storage 8 *上，还可以在那里完全解决该问题.

1. Create your own QueueProcessorFactory and QueueProcessor - you can override the method that handles poison messages to produce more debug output. There you can also fix the issue altogether if you'd like to stay on Azure Storage 8.*.

注册跟踪监视器. 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);

这篇关于Azure Webjob日志-查找详细记录SDK对队列触发项的处理的日志的文章就介绍到这了，希望我们推荐的答案对大家有所帮助，也希望大家多多支持IT屋！