Azure webjob 日志 - 查找详细说明 SDK 处理队列触发项的日志

Question

正如我的 Stack Overflow 问题 Azure webjob not appearing to respect MaxDequeueCount property 中所示，我正在解决一个问题，尽管我将 MaxDequeueCount 属性设置为 1，但某些项目在中毒之前已多次出列（实际上有些项目可能永远不会完全中毒，只是出队，失败，重试并无休止地失败）。

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

例如，我可以通过https://myappengine.scm.azurewebsites.net/vfs/data/jobs/continuous/StuffProcessor/job_log.txt 的 SCM 查看 webjob 的日志，看到我的函数检测到了一个新的队列项目（顺便说一下，如果我在 web 应用程序上启用了到 Azure 存储的详细日志记录，我可以在 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'.'

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

{
      "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 属性的明显忽略问题。有记录吗？

更新：我找到了Azure WebJobs with Storage Queue and Exceptions 的帖子，其中包含以下屏幕截图：

该屏幕截图显示了标准的“检测到新队列消息...”消息（我在 Azure 上看到并在模拟器中本地运行），它还显示“消息已达到 X 的 MaxDequeueCount ...将消息移动到队列'xyz-poison'"，我仅在模拟器中本地看到。基于 Azure 的运行时是否出于某种原因不显示此信息？ 在控制台窗口本地运行或通过 webjobs 仪表板或在 Azure 上运行时，我从来没有看到过这样的中毒相关消息。

Answer 1

您使用的是 Azure 存储版本 8.* 吗？它包含一个重大更改。

当队列消息对象插入 Azure Storage 8 中的消息队列时，原始队列消息对象的消息 ID 将被新插入消息的唯一消息 ID 覆盖。

这意味着它失去了对有害消息的引用并且不能再删除它。

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

至于记录，2个选项：

1. 创建您自己的 QueueProcessorFactory 和 QueueProcessor - 您可以重写处理有害消息的方法以产生更多调试输出。如果您想继续使用 Azure Storage 8，您也可以在此处完全解决问题。*。

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

在您之前的帖子中，您的触发功能如下

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

您写入记录器的任何内容都应显示在 WebJobs 仪表板的日志中。我的建议是：

1. 将 'if (item == "exception")' 更改为 'if (item.ToLower().StartsWith("exception")'。然后在测试时将数字附加到异常消息中。记录文本将队列消息发送到 TextWriter，这样您就可以确定您正在查看您认为正在检查的同一条消息。

2. 您可以将消息的出队计数作为函数的参数。见here。查看示例中的 FailAlways 方法。也将其记录到 TextWriter。

3. 尝试在本地运行它。所有输出都将写入控制台窗口。看看你是否得到相同的行为。

我真的很想找出导致这种行为的原因，所以如果你破解它，请务必告诉我们！