Why does azure Function App streaming log viewer duplicate log output?

Question

I have a simple Azure V1 function that works as a CosmosDB trigger, every time I insert a document the trigger does it work and finishes, App Insights and the monitor log in the Function App itself in the Azure console shows it triggers 1 time, the result of the code shows it triggers 1 time, but the streaming console shows me duplicate output, is this by design or am I doing something wrong?

This is the function

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");
            }
        }
    }
}

Below you can see the duplicated output

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

It is a bug tracked but not fixed yet.

When function code panel is opened, file log(i.e. Application log in Diagnostic logs) is enabled. Function related entries are written to both the host log and the function log, i.e. to files in(kudu https://funcappname.scm.azurewebsites.net/DebugConsole):

• D:\home\LogFiles\Application\Functions\Host\
• D:\home\LogFiles\Application\Functions\Function\function-name\

Log streaming console prints both host logs and function logs, so function related entries appear twice. For example, logs with [Info,Function1] prefix are function related entries in host logs, which is duplicate to us.