c# - 为什么 azure Function App 流式日志查看器会重复日志输出？

Question

我有一个简单的 Azure V1 函数，可用作 CosmosDB 触发器，每次插入文档时，触发器都会工作并完成，Azure 控制台中函数应用程序本身的 App Insights 和监视器日志显示它触发了 1时间，代码的结果显示它触发了 1 次，但流控制台显示重复的输出，这是设计使然还是我做错了什么？

这就是函数

using System.Collections.Generic;
using Microsoft.Azure.Documents;
using Microsoft.Azure.WebJobs;
using Microsoft.Azure.WebJobs.Host;
using Newtonsoft.Json.Linq;
using System.Net.Http;
using System.Net.Http.Formatting;
using System.Net.Http.Headers;
using System;
using System.Threading.Tasks;

namespace NWCloudTransactionEventHandler
{
    public static class Function1
    {
        [FunctionName("Function1")]
        public static async Task RunAsync([CosmosDBTrigger(
            databaseName: "xxx",
            collectionName: "xxx",
            ConnectionStringSetting = "xxx",
            LeaseCollectionName = "leases", LeaseCollectionPrefix = "cloud")]IReadOnlyList<Document> documents, TraceWriter log)
        {
            if (documents != null && documents.Count > 0)
            {
                log.Info("Start change feed processing");
                log.Info("Documents modified " + documents.Count);

                foreach(var document in documents)
                {
                    dynamic jsonDoc = document;

                    string destinationSystem = jsonDoc.OriginalTransaction["destinationSystem"];

                    log.Info("destination system = " + destinationSystem);

                    if(destinationSystem == "xx.com")
                    {
                        log.Info("Start processing destinaton = xx.com");

                        string destinationSystemCountry = jsonDoc.OriginalTransaction["destinationSystemCountry"];

                        log.Info("destination country = " + destinationSystemCountry);

                        if (destinationSystemCountry == "xx")
                        {
                            log.Info("Start processing xx.com destination Country = xx");

                            JObject transaction = jsonDoc.OriginalTransaction["transactionDetails"];

                            log.Info("transactionDetail = " + transaction);
                            log.Info("Starting httpRequest");

                            HttpClient httpClient = new HttpClient();
                            httpClient.DefaultRequestHeaders.Add("Authorization", "xxxx");

                            HttpResponseMessage response = await httpClient.PostAsync("https://xxx/checkout", new StringContent(transaction.ToString(), System.Text.Encoding.UTF8, "application/json"));

                            log.Info("response is " + response);
                        }
                        else
                        {
                            log.Info("Destinationcountry is unsupported at this time");
                            return;
                        }

                    }
                    else
                    {
                        log.Info("Destinationsystem is unsupported at this time");
                        return;
                    }
                }
                log.Info("Change feed processing finished");
            }
        }
    }
}

下面您可以看到重复的输出

2018-09-29T03:35:03  Welcome, you are now connected to log-streaming service.
2018-09-29T03:35:02.639 [Info] Executing HTTP request: {
  "requestId": "1ebc2482-cb42-4b78-aa8f-c74e8d47a0e5",
  "method": "GET",
  "uri": "/admin/host/status"
}
2018-09-29T03:35:02.654 [Info] Host Status: {
  "id": "nwcloudtransactioneventhandler-t",
  "state": "Running",
  "version": "1.0.11959.0"
}
2018-09-29T03:35:02.654 [Info] Executed HTTP request: {
  "requestId": "1ebc2482-cb42-4b78-aa8f-c74e8d47a0e5",
  "method": "GET",
  "uri": "/admin/host/status",
  "authorizationLevel": "Admin",
  "status": "OK"
}
2018-09-29T03:35:20.638 [Info] Function started (Id=820dff13-dfb3-4641-84d9-123c85aa9ac2)
2018-09-29T03:35:20.638 [Info] Start change feed processing
2018-09-29T03:35:20.638 [Info] Documents modified 1
2018-09-29T03:35:20.638 [Info] destination system = xx.com
2018-09-29T03:35:20.638 [Info] Start processing destinaton = xx.com
2018-09-29T03:35:20.638 [Info] destination country = xx2018-09-29T03:35:20.638 [Info] Start processing hm.com destination Country = xx2018-09-29T03:35:20.638 [Info] transactionDetail = {
  "callback": {
    "refund": "https://x",
    "success": "https://x"
  },
  "items": [
    {
      "attributes": {
        "color": "Orange/Guld",
        "size": "NOSIZE"
      },
      "price": "xx",
      "quantity": "1",
      "shipping": "0.0",
      "title": "Bordslampa-Orange/Guld-NOSIZE",
      "url": "xx"
    }
  ],
  "paymentMethod": {
    "code": "XYZ",
    "phone": "x",
    "type": "x"
  },
  "reference": "x",
  "test": "true"
}
2018-09-29T03:35:20.638 [Info] Starting httpRequest
2018-09-29T03:35:20.684 [Info] response is StatusCode: 200, ReasonPhrase: 'OK', Version: 1.1, Content: System.Net.Http.StreamContent, Headers:
{
  Vary: Origin
  X-Content-Type-Options: nosniff
  X-Frame-Options: ALLOWALL
  X-Request-Id: c44a4e1a-55f0-4c0b-8183-3433530b7920
  X-Runtime: 0.010130
  X-Xss-Protection: 1; mode=block
  Connection: keep-alive
  Cache-Control: must-revalidate, max-age=0, private
  Date: Sat, 29 Sep 2018 03:35:20 GMT
  ETag: "52a9130e2fdb487944cfa9498bc071d0"
  Content-Length: 1031
  Content-Type: application/json; charset=utf-8
}
2018-09-29T03:35:20.684 [Info] Change feed processing finished
2018-09-29T03:35:20.684 [Info] Function completed (Success, Id=820dff13-dfb3-4641-84d9-123c85aa9ac2, Duration=46ms)
2018-09-29T03:35:20.638 [Info,Function1] Function started (Id=820dff13-dfb3-4641-84d9-123c85aa9ac2)
2018-09-29T03:35:20.638 [Info,Function1] Executing 'Function1' (Reason='New changes on collection transactions at 2018-09-29T03:35:20.6380214Z', Id=820dff13-dfb3-4641-84d9-123c85aa9ac2)
2018-09-29T03:35:20.638 [Info,Function1] Start change feed processing
2018-09-29T03:35:20.638 [Info,Function1] Documents modified 1
2018-09-29T03:35:20.638 [Info,Function1] destination system = xx.com
2018-09-29T03:35:20.638 [Info,Function1] Start processing destinaton = xx.com
2018-09-29T03:35:20.638 [Info,Function1] destination country = xx2018-09-29T03:35:20.638 [Info,Function1] Start processing xx.com destination Country = xx2018-09-29T03:35:20.638 [Info,Function1] transactionDetail = {
  "callback": {
    "refund": "https://x",
    "success": "https://nxs"
  },
  "items": [
    {
      "attributes": {
        "color": "Orange/Guld",
        "size": "NOSIZE"
      },
      "price": "x",
      "quantity": "1",
      "shipping": "0.0",
      "title": "Bordslampa-Orange/Guld-NOSIZE",
      "url": "x"
    }
  ],
  "paymentMethod": {
    "code": "XYZ",
    "phone": "x",
    "type": "x"
  },
  "reference": "x",
  "test": "true"
}
2018-09-29T03:35:20.638 [Info,Function1] Starting httpRequest
2018-09-29T03:35:20.684 [Info,Function1] response is StatusCode: 200, ReasonPhrase: 'OK', Version: 1.1, Content: System.Net.Http.StreamContent, Headers:
{
  Vary: Origin
  X-Content-Type-Options: nosniff
  X-Frame-Options: ALLOWALL
  X-Request-Id: c44a4e1a-55f0-4c0b-8183-3433530b7920
  X-Runtime: 0.010130
  X-Xss-Protection: 1; mode=block
  Connection: keep-alive
  Cache-Control: must-revalidate, max-age=0, private
  Date: Sat, 29 Sep 2018 03:35:20 GMT
  ETag: "52a9130e2fdb487944cfa9498bc071d0"
  Content-Length: 1031
  Content-Type: application/json; charset=utf-8
}
2018-09-29T03:35:20.684 [Info,Function1] Change feed processing finished
2018-09-29T03:35:20.684 [Info,Function1] Function completed (Success, Id=820dff13-dfb3-4641-84d9-123c85aa9ac2, Duration=46ms)
2018-09-29T03:35:20.684 [Info,Function1] Executed 'Function1' (Succeeded, Id=820dff13-dfb3-4641-84d9-123c85aa9ac2)

Answer 1

这是一个 bug已跟踪但尚未修复。

当功能代码面板打开时，文件日志(即诊断日志中的应用程序日志)被启用。与函数相关的条目会写入主机日志和函数日志，即写入 (kudu https://funcappname.scm.azurewebsites.net/DebugConsole) 中的文件:

• D:\home\LogFiles\Application\Functions\Host\
• D:\home\LogFiles\Application\Functions\Function\函数名称\

日志流控制台会打印主机日志和功能日志，因此与功能相关的条目会出现两次。例如，带有 [Info,Function1] 前缀的日志是主机日志中与函数相关的条目，这对我们来说是重复的。