Net7 Isolated Functions Logging - Console not working, AppInsights almost working

[RichardBurns1982]

We have just migrated from net6 in-process to net7 isolated and the logging is a proving extremely challenging. We have two use cases:

1. Locally we want to log debug ILogger (DI injected to constructor) to the console
2. Production we want to log to App Insights.

Our setup is as follows:

host.json:

{
  "version": "2.0",
  "logging": {
    "logLevel": {
      "default": "Warning",
      "Host.Aggregator": "None",
      "Host.Results": "None",
      "Microsoft": "None",
      "Microsoft.Hosting": "None",
      "Microsoft.Hosting.Lifetime": "None",
      "Microsoft.AspNetcore": "None",
      "Microsoft.AspNetCore.Mvc.Internal": "None",
      "Microsoft.AspNetCore.Authentication": "None",
      "Microsoft.AspNetCore.Diagnostics.ExceptionHandlerMiddleware": "None",
      "Microsoft.Extensions.Http.DefaultHttpClientFactory": "None",
      "Microsoft.Extensions.Hosting": "None",
      "System.Net.Http.HttpClient": "None",
      "Worker": "None"
    },
    "applicationInsights": {
      "samplingSettings": {
        "isEnabled": true,
        "excludedTypes": "Request"
      }
    }
  }
}

Code:

public IHost Build(Action<HostBuilderContext, IServiceCollection> configureServices) => new HostBuilder()
            .ConfigureAppConfiguration(ConfigurationBuilder.Configure)
            .ConfigureLogging(ConfigurationBuilder.ConfigureLogging)
            .ConfigureFunctionsWorkerDefaults(ConfigurationBuilder.ConfigureFunctions)
            .ConfigureServices(configureServices)
            .Build();


public static class ConfigurationBuilder
{
    public static void Configure(HostBuilderContext hostContext, IConfigurationBuilder configurationBuilder)
    {
        if (hostContext.HostingEnvironment.IsDevelopment())
        {
            var entryAssembly = Assembly.GetEntryAssembly();
            if (entryAssembly != null)
            {
                configurationBuilder.AddUserSecrets(entryAssembly, optional: true, reloadOnChange: false);
            }
        }
        if (hostContext.HostingEnvironment.IsProduction())
        {
              // Key Vault in prod
        }
    }

    public static void ConfigureFunctions(HostBuilderContext hostContext, IFunctionsWorkerApplicationBuilder builder)
    {
        if (hostContext.HostingEnvironment.IsProduction())
        {
            // At the moment this stops all logging except at warning or above
            // https://github.com/devops-circle/Azure-Functions-Logging-Tests/blob/master/Func.Isolated.Net7.With.AI/Program.cs
            builder
                .AddApplicationInsights()
                .AddApplicationInsightsLogger();
        }
    }

    public static void ConfigureLogging(HostBuilderContext hostContext, ILoggingBuilder builder)
    {
        if (hostContext.HostingEnvironment.IsDevelopment())
        {
            builder.AddConsole();
        }
    }
}

I'll start with AppInsights. We've managed to mostly get this working looking through various other issues that people have raised but we are seeing a lot of Dependency messages logged which we were not seeing before:

You can see when we first deployed ney7 Isolated and we started seeing thousands of dependency messages logged like so:

How do we stop these?

Locally we want to see debug messages but not the noise from the host/functions, just our DI injected ILogger messages, how do we see these as no matter what we try unless we change the host.json default to Debug we don't see anything and if we do that we see everything, including all the noise.

[ben-hamida]

You can disable dependency logging like this:

worker
    .AddApplicationInsights(options => options.EnableDependencyTrackingTelemetryModule = false)
    .AddApplicationInsightsLogger();

[RichardBurns1982]

You can disable dependency logging like this:

worker
    .AddApplicationInsights(options => options.EnableDependencyTrackingTelemetryModule = false)
    .AddApplicationInsightsLogger();

Thank Ben, we've tried the setting above with no luck, we're still seeing large numbers of dependency logs in App Insights. We'll keep trying to see if we can stop them.

[RichardBurns1982]

You can see the difference below, the point we upgraded from Net6 in-process to Net7 isolated:

No lother logging changes have been made, we are adding AppInsights as shown above with EnableDependencyTrackingTelemetryModule set to false.

[brettsam]

@RichardBurns1982 -- first, please update to the latest preview4 in your worker. It fixes the console logging.

Second, can you share an example of one of these dependency telemetry? That can help track down where they're coming from. Please include the custom dimensions and sdkVersion from the telemetry.

It's possible they're coming from the host. You can completely turn off dependency tracking in the host via host.json: https://learn.microsoft.com/en-us/azure/azure-functions/functions-host-json#applicationinsights. (see logging -> applicationInsights -> enableDependencyTracking)

[RichardBurns1982]

@brettsam Thanks for responding, we will try preview4.

One dependency example:

Event time	4/11/2023, 7:00:07.6528543 AM (Local time)
Type	Azure.Functions
Call status	true
Duration	3 ms
Name	Invoke
Operation Id	65de88a2190bffc3e0f0099e185d7282
Parent Id	6e39ef22710abca1
Id	18ee7c1b8bc31f5e
Base name	Invoke
Performance	<250ms
Telemetry type	dependency
Operation name	---
Application version	1.0.0.0
Device type	PC
Client IP address	0.0.0.0
Role name	---
Role instance	178020b13b92f608947c034a551bdaf842c1d4ce8b5631a94eb52c25d92c256c
SDK version	azurefunctions-netiso: 1.0.0.0
Sample rate	1

InvocationId	acd0e821-0816-49ed-8b71-b41611317135
ProcessId	2696
Name	---

[RichardBurns1982]

@brettsam Still no luck, we upgraded to preview4 of the app insights and console logging still not working. When you said this is fixed was there any additional config changes needed?

I tried not registering app insights locally when running in development and just call builder.AddConsole() and still no debug messages will appear on the console. Only warning, error and critical. This was never a problem on in-process in net6, all worked without issue so something has changed.

[RichardBurns1982]

OK, I've managed to get this working again locally.

I have changed the local.settings.json to override the Function loglevel like so:

"AzureFunctionsJobHost__logging__logLevel__Function": "Debug",

I have also had to modify our local configuration loaded from user secrets to include a logging section like so:

"logging": {
   "logLevel": {
	"default": "Debug"
   }
},

I have also had to change our ConfigureLogging to look like this:

 public static void ConfigureLogging(HostBuilderContext hostContext, ILoggingBuilder builder)
    {
        if (hostContext.HostingEnvironment.IsDevelopment())
        {
            // This is needed as it isn't picking up the logging section from the user secrets
            builder.AddConfiguration(hostContext.Configuration.GetSection("logging"));
        }
}

Once all of this is done we are now seeing the console logging locally we were seeing before moving to .net7 Isolated.

[fabiocav]

@RichardBurns1982 we're reviewing what you've shared and some of the steps above seem unnecessary. Would you be able to share your repro in a repo so we can take a look at the code there?

[ghost]

This issue has been automatically marked as stale because it has been marked as requiring author feedback but has not had any activity for 4 days. It will be closed if no further activity occurs within 3 days of this comment.

[RichardBurns1982]

@fabiocav Repo here: https://github.com/RichardBurns1982/azure-functions-issue-1415

Unless all steps mentioned above are included debug messages are not shown in console

[jviau]

@RichardBurns1982 host.json values do not apply to the worker process. You will need to configure that separately. You can use appsettings.json to be in line with other dotnet apps, however that file is not added as a config source by default and you will need to add it yourself.

if (hostContext.HostingEnvironment.IsDevelopment())
{
     // This is needed as it isn't picking up the logging section from the user secrets
      builder.AddConfiguration(hostContext.Configuration.GetSection("logging"));
 }

These lines are redundant. "Host" (dotnet 'host' config concept not functions 'host' or host.json) configuration is automatically chained into "app" configuration (your first app config source should be ChainedConfigurationSource, which is hostContext.Configuration.)

What I recommend is to add an appsettings.json and adding that as a config source. Either, replace new HostBuilder() with Host.CreateDefaultBuilder() (this will also give you a lot of other beneficial defaults). Or you can add it manually via:

.ConfigureAppConfiguration((hostContext, builder) =>
{
    builder.AddJsonFile("appsettings.json", optional: true, reloadOnChange: true or false)
        .AddJsonFile($"appsettings.{hostContext.HostingEnvironment.EnvironmentName}.json", optional: true, reloadOnChange: true or false);
});

You can then add your worker specific logging config to appsettings.json.

[jviau]

As for your concern with the dependency telemetry when using our application insights package, this is the point of our package. You have a couple options available to you to avoid these telemetry items:

1. Don't use the package (which you already discovered)
2. Add an ITelemetryProcessor which filters out the dependency items you do not want to track.
   • See https://learn.microsoft.com/en-us/azure/azure-monitor/app/api-filtering-sampling?tabs=javascriptwebsdkloaderscript#c
   • After writing the telemetry processor, you can use the DI helper: services.AddApplicationInsightsTelemetryProcessor<MyTelemetryProcessor>();

[ghost]

This issue has been automatically marked as stale because it has been marked as requiring author feedback but has not had any activity for 4 days. It will be closed if no further activity occurs within 3 days of this comment.

[ghost]

This issue has been automatically marked as stale because it has been marked as requiring author feedback but has not had any activity for 4 days. It will be closed if no further activity occurs within 3 days of this comment.

[RichardBurns1982]

@jviau Thank you for the responses. I have tried the following:

Changed to use Host.CreateDefaultBuilder()
Added an appsettings.json
Removed logging:logLevel from host.json

This did work locally for debugging but when deployed to Azure app insights exploded with logs from host.result (over 100k in 15 minutes).

But if we set the logging:logLevel in host.json it stops the local debug messages unless we set:

"AzureFunctionsJobHost__logging__logLevel__Function": "Debug",

It feels like the log levels we are trying to set in appsettings.json (or from user secrets) are competing with the log levels we set in host.json.

Does this sound right that host.json is overriding what we have set in appsettings.json or user secrets locally when debugging. We don't want to change host.json.

I'll continue to experiment with this but appreciate any insights. From initial testing it seems the call to Host.CreateDefaultBuilder() which calls many logging extensions (Console, Debug, etc.) is causing app insights to explode with trace messages, etc.

[jviau]

You will want to set log levels in both host.json and appsettings.json. These are for the host and worker process respectively, so you want to configure log filters for them both.

For log levels when using the app insights package, they don't override each other - they are separate packages.

[RichardBurns1982]

You will want to set log levels in both host.json and appsettings.json. These are for the host and worker process respectively, so you want to configure log filters for them both.

For log levels when using the app insights package, they don't override each other - they are separate packages.

Thanks @jviau

I will update the repo with the problem we are seeing.

If we swap to Host.CreateDefaultBuilder() then when deployed to Azure App Insights begins filling up with a lot of TRACE messages. We can stop these by setting host.json to:

{
  "version": "2.0",
  "logging": {
    "applicationInsights": {
      "samplingSettings": {
        "isEnabled": true
      }
    },
    "logLevel": {
      "default": "Warning"
    }
  }
}

But doing this stops all logging below Warning locally when we are debugging unless we set:

"AzureFunctionsJobHost__logging__logLevel__Function": "Debug",

Our goal is that locally developers can turn logging on and off simply by changing their user secrets with no need to edit either host.json or appsettings.json.

I will try to get the repo updated this morning, failing that it will be early next week.

Many thanks again for all your help.

[jviau]

@RichardBurngs1982 there are a couple tools you can make use of here:

1. Use category specific filters in configuration.
2. Use per-environment appsettings.json See here, specifically this bullet point:

appsettings.Environment.json using the JSON configuration provider. For example, appsettings.Production.json and appsettings.Development.json.

3. For host.json, can you leverage local.settings.json?

[dsmiller95]

I am dealing with the same problem right now, figuring out how to configure console logs in the same way as we can with application insights logs. using Host.CreateDefaultBuilder instead of new Host() appears to have helped shorten the configuration code, however, I cannot find a way to configure Console logging using appsettings.json exclusively.

It appears that appsettings.json and the host.json both filter console logs? In order for a log to reach the console, it must pass the appsettings.json filter, with the Category defined inside the isolated host (I.E. MyFunctions.SayHello.SayHelloActivity) . And also it must past the filter defined in host.json, under a different category defined by the host (I.E. Function.SayHelloActivity or Function)

Based on this, I think the best viable solution is to set "AzureFunctionsJobHost__logging__logLevel__Function" : "Debug" in local.settings.json, unless you want to set it directly in host.json. However, host.json is also used to configure how the host logs to app insights. So setting directly in host.json would result in more logs than desired in app insights. This would be a problem particularly if we want Debug or Trace level logs.

I think an ideal solution would avoid this double-filtering altogether, so that logs from the isolated dotnet process (ILogger / ILoggerFactory) are filtered only once by the categories configured in appsettings.json, regardless of logging configured in host.json. Then delivered directly to the console. I believe that this is how the logs are delivered to app insights when using builder.AddApplicationInsights() ?

I will note that the solution of setting local.settings.json:Values:AzureFunctionsJobHost__logging__logLevel__Function is technically not allowed per azure functions local.settings.json documentation, but it does appear to work for now.

Values must be strings and not JSON objects or arrays. Setting names can't include a double underline (__) and shouldn't include a colon (:). Double underline characters are reserved by the runtime,

https://learn.microsoft.com/en-us/azure/azure-functions/functions-develop-local#local-settings-file

This is what I'm observing, via a few test cases:

Case 1

Setup:

appsettings.json:Logging:LogLevel:Default = "Information"
host.json:logging:logLevel:Default = "Warning"
local.settings.json:Values:AzureFunctionsJobHost__logging__logLevel__Function = null/unset

Result:
Warning and above logs from ILogger are emitted to console

Case 2

Setup:

appsettings.json:Logging:LogLevel:Default = "Information"
host.json:logging:logLevel:Default = "Warning"
local.settings.json:Values:AzureFunctionsJobHost__logging__logLevel__Function = "Debug"

Result:
Information and above logs from ILogger are emitted to console, no debug or trace logs.

Case 3

Setup:

appsettings.json:Logging:LogLevel:Default = "Error"
host.json:logging:logLevel:Default = "Warning"
local.settings.json:Values:AzureFunctionsJobHost__logging__logLevel__Function = "Debug"

Result:
Error and above logs from ILogger are emitted to console

Case 4

Setup:

appsettings.json:Logging:LogLevel:Default = "Error"
host.json:logging:logLevel:Default = "Debug"
local.settings.json:Values:AzureFunctionsJobHost__logging__logLevel__Function = null/unset

Result:
Error and above logs from ILogger are emitted to console
Also a huge amount of debug-level logs are emitted from the function host itself

Program.cs setup

This is my host builder configuration:

public static class Program
{
    private static void Main(string[] args)
    {
        var host = Host.CreateDefaultBuilder()
            .ConfigureFunctionsWorkerDefaults(builder =>
            {
                builder
                    .AddApplicationInsights()
                    .AddApplicationInsightsLogger();
            })
            // below commented out code has been replaced with Host.CreateDefaultBuilder, it performs all of these functions
            // .ConfigureLogging((builder, logging) => {
            //     // this ensures that the logging configuration is loaded from appsettings.json. this is not the default in function apps apparently.
            //     // in web apps this gets set via the HostApplicationBuilder constructor, HostingHostBuilderExtensions.cs : AddDefaultServices
            //     logging.AddConfiguration(builder.Configuration.GetSection("Logging"));
            //     logging.AddConsole();
            // })
            // .ConfigureAppConfiguration((hostBuilder, cfg) =>
            // {
            //     cfg
            //         .AddJsonFile("appsettings.json")
            //         .AddJsonFile($"appsettings.{hostBuilder.HostingEnvironment.EnvironmentName}.json")
            //         .AddEnvironmentVariables();
            //
            //     if (hostBuilder.HostingEnvironment.IsDevelopment())
            //     {
            //         cfg.AddUserSecrets(Assembly.GetExecutingAssembly());
            //     }
            // })
            .ConfigureServices((hostBuilder, services) =>
            {
                services.Configure<FeatureFlags>(
                    hostBuilder.Configuration.GetSection(FeatureFlags.FeatureFlagsId));
            })
            .Build();

        host.Run();
    }
}

This is how my function's logger is set up:

namespace MyFunctions.SayHello;
public class SayHelloActivity
{
    public class Request
    {
        public required string Greeting { get; set; }
        public required string Subject { get; set; }
    }

    public class Response
    {
        public required string Message { get; set; }
    }

    private readonly ILogger logger;

    public SayHelloActivity(ILoggerFactory loggerFactory)
    {
        logger = loggerFactory.CreateLogger<SayHelloActivity>();
    }

    [Function(nameof(SayHelloActivity))]
    public Response Run([ActivityTrigger] Request request, FunctionContext executionContext)
    {
        logger.LogInformation("EXECUTING {Function} triggered log", nameof(SayHelloActivity));
        
        logger.LogCritical("{Severity} saying hello for \\n Name: {RequestSubject} \\n greet: {RequestGreeting}", "critical", request.Subject, request.Greeting);
        logger.LogError("{Severity} saying hello for \\n Name: {RequestSubject} \\n greet: {RequestGreeting}", "error", request.Subject, request.Greeting);
        logger.LogWarning("{Severity} saying hello for \\n Name: {RequestSubject} \\n greet: {RequestGreeting}", "warning", request.Subject, request.Greeting);
        logger.LogInformation("{Severity} saying hello for \\n Name: {RequestSubject} \\n greet: {RequestGreeting}", "information", request.Subject, request.Greeting);
        logger.LogTrace("{Severity} saying hello for \\n Name: {RequestSubject} \\n greet: {RequestGreeting}", "trace", request.Subject, request.Greeting);
        logger.LogDebug("{Severity} saying hello for \\n Name: {RequestSubject} \\n greet: {RequestGreeting}", "debug", request.Subject, request.Greeting);
        return new Response
        {
            Message = $"Hello {request.Greeting} {request.Subject}!"
        };
    }
}

[dsmiller95]

A side effect of this appears to be that there is no way to filter these types of logs out:

Executing 'Functions.SayHelloActivity' (Reason='(null)', Id=bf1b4936-c05e-4dde-8f07-7bb00d3767d6)

while retaining Information-level logs from ILogger in the console. This is (presumably) due to the preceding log line co-habitating the category Functions.SayHelloActivity with the app logs emitted from ILogger

[microsoft-github-policy-service]

This issue has been automatically marked as stale because it has been marked as requiring author feedback but has not had any activity for 4 days. It will be closed if no further activity occurs within 3 days of this comment.

[joeyeng]

Closed without a resolution? This seems to be becoming more common these days...

[springcomp]

@joeyeng this is now a "solved" problem 😁

Please lookup #1182 where I illustrate how to reliably have full control on your logging experience in your function apps running as an isolated worker process.