Storage queue triggered function generates trace level log entries in app insights

[mpowney]

With a queue triggered function in an app, e.g.

        [FunctionName("ProcessRedirectClicksForGeo")]
        public static async void ProcessRedirectClicksForGeo(
            [QueueTrigger(QueueNames.ProcessRedirectClicksForGeo)] string queuedHttpRequestString,
            [Table(TableNames.RedirectSessions)] CloudTable redirectTable,
            ILogger log,
            ExecutionContext context)

And a host.json configuration

        "logLevel": {
            "default": "Information",
        },

Application insights continues to receive the trace level log info about the poll interval of the queue trigger, including messages like:

Poll for function 'ProcessRedirectClicksForGeo' on queue 'processredirectclicksforgeo' with ClientRequestId '3f2a0e15-f014-4537-b0bb-abbc45a4467b' found 0 messages in 3 ms.

and

Function 'ProcessRedirectClicksForGeo' will wait 2000 ms before polling queue 'processredirectclicksforgeo'.

The result is a large amount of data ingested in to application insights, which results in unexpectedly high costs in Azure Monitor.

There doesn't seem to be a clear documented method of preventing these messages from being sent to application insights. Is there somewhere the documentation can be updated to specify how to resolve this?

Side note: when the default setting in logLevel in host.json is set to Information a local dev version of the function app does not produce the trace level logs.

[mpowney]

The same behaviour can be reproduced by provisioning a Function app via the Azure Portal, using the classic function UI to create a cscript queue triggered function with the boilerplate definition:

run.csx:

using System;

public static void Run(string myQueueItem, ILogger log)
{
    log.LogInformation($"C# Queue trigger function processed: {myQueueItem}");
}

function.json

{
  "bindings": [
    {
      "name": "myQueueItem",
      "type": "queueTrigger",
      "direction": "in",
      "queueName": "myqueue-items",
      "connection": "AzureWebJobsStorage"
    }
  ],
  "disabled": false
}

host.json

{
  "version": "2.0",
  "logging": {
      "logLevel": {
          "default": "None",
          "Host": "None"
      },
      "applicationInsights": {
          "excludedTypes" : "Dependency;Event",
          "includedTypes" : "PageView;Trace",
          "samplingSettings": {
              "isEnabled": true
          }
      }
  },
  "extensionBundle": {
    "id": "Microsoft.Azure.Functions.ExtensionBundle",
    "version": "[1.*, 2.0.0)"
  }
}

[v-bbalaiagar]

Hi @mpowney, Apologies for the delayed response, the issue was somehow lost in the trace. Can you tell us if you are still facing this issue.

[muj-beg]

Seeing the same. My AppInsights log is just full of continuous Queue polling messages -- which makes finding the messages I'm actually interested in very difficult 😞. Please see screenshot below:

[muj-beg]

Looks like this additional logging was in this PR: https://github.com/Azure/azure-webjobs-sdk/pull/2277

[v-bbalaiagar]

Hi @muj-beg, Thank you for your feedback, I shall discuss this internally and get back to you with the findings.

[pragnagopa]

@brettsam - can you please take a look. New logs should not be emitted at Info level.

[otecfuras]

@pragnagopa still an issue, application insights traces full of messages related to queue polling. Which logger category (default, Host, Function, ...) is controlling this logger?

[mathewc]

These polling logs are logged at level Debug (code here) so if the default log level for your app is set to Information as described in documentation you shouldn't see them.

[otecfuras]

@mathewc I know I shouldn't, but they're still logged:

[otecfuras]

This > < is even more weird, frequency increased to each 2 seconds even I didn't changed that polling interval. It happened after I've overridden level for Function to Information (and restarted function app)>

[mathewc]

The frequency of those polling logs can change, since the poller uses an exponential backoff algorithm, down to the maxPollingInterval you've defined for queues. @brettsam - any ideas on why the AI logger may not be respecting configured log levels?

[otecfuras]

I would appreciate any help, I'm billed for unwanted messages and I can't get rid of them. Actually, _BilledSizes of traces summarized by message for past 30 days show that unwanted messages dominate:

I'm using .NET Core 3.1, Azure functions v2 and Microsoft.Azure.Webjobs.Extensions.Storage v4.0.3:

[frammnm]

i watching the same logs with the default log level on my function app, im trying to debug a problem where my functions are not executing properly, can this messages be an indication of a problem?

[haronxx]

I had the same problem. Changing the settings as following solved the problem:

{ "Logging": { "LogLevel": { "Default": "Warning" }, "ApplicationInsights": { "LogLevel": { "Azure.Core": "Warning" } } } }

Only wanings will be sent to Application Insights

[otecfuras]

@haronxx: Where did you find information on Azure.Core category? LogLevel under ApplicationInsights property isn't even documented property, are you sure this works (for you)?

Fortunately, my problem is gone.

Firstly, unwanted persistence of these messages stopped (few weeks ago) when I changed default logging level to Information:

"logLevel": { "default": "Information", "Function": "Debug" }

Secondly, seeing trace messages in "Live metrics" doesn't mean they are actually persisted in traces table. This was the reason I thought they are still persisted.

Surprisingly, another abusing message type appeared just that day when I changed this setting, it was Executing HttpStatusCodeResult, setting HTTP status code 200 appearing 4 times each 10 seconds (mentioned e.g. here). This was second reason why I thought problem persists because amount (billed size) of messages with empty(operation_Name) didn't decrease (actually this message appears already in screenshot from my post on Jan 22nd). These messages vanished after setting Microsoft.AspNetCore.Mvc.StatusCodeResult logging category to Warning.

Thanks all for help.

[andy-hugecalf]

Have there been any updates on this? Our logs are littered with this despite having our default logLevel set to Warning

Edit: In my "Log Stream" on the Function App, I still see these messages. However in Application Insights if I query traces, then I don't see them. Maybe I'm misunderstanding something

[woeterman94]

Any update? We are seeing the same issue