Reconsider logging configuration approach in App Service Logging Providers

[zdenek-jelinek]

Is there an existing issue for this?

• I have searched the existing issues

Is your feature request related to a problem? Please describe the problem.

Currently, Azure App Service logging providers do not work consistently with the rest of the logging system as far as I understand it.

The behavior of these providers is that

• general Logging:LogLevel settings are completely ignored
• provider-specific Logging:{Provider}:LogLevel:Default setting is ignored

under normal circumstances. Instead, the verbosity configured in App Service is used.

While it may be a natural interpretation from certain perspective, it is not consistent with the rest of the logging configuration and also in itself as using specific categories is respected. This is not mentioned anywhere in the docs. In fact, the docs currently show example that is misleading. More on that later.

The core of the problem is that I have a configuration like

"Logging": {
  "LogLevel": {
    "Default": "Error",
    "MyApp": "Information",
    "MyLibrary": "Information"
  },
  "AzureAppServicesFile": {
    "IncludeScopes": true
  },
  "AzureAppServicesBlob": {
    "IncludeScopes": true
  }
}

but the defaults are not reflected by the AzureAppServices* providers.

Instead, I have to have

"Logging": {
  "LogLevel": {
    "Default": "Error",
    "MyApp": "Information",
    "MyLibrary": "Information"
  },
  "AzureAppServicesFile": {
    "IncludeScopes": true,
    "LogLevel": {
      "Default": "Error", // This is ignored though
      "MyApp": "Information",
      "MyLibrary": "Information"
    }
  },
  "AzureAppServicesBlob": {
    "IncludeScopes": true,
    "LogLevel": {
      "Default": "Error", // This is ignored as well
      "MyApp": "Information",
      "MyLibrary": "Information"
    }
}

and everyone needs to know that when they're adding anything, they need to add it to all three places. I'd say that most people seeing this configuration would say "that's duplicated, let's get rid of it" and break it.

Also note that the list is typically a bit longer than this so the duplication is not very nice at all.

Describe the solution you'd like

The the docs should be updated to reflect this behavior, especially calling out the behavior non-compliant with the rest of the configuration philosophy.

A better technical solution would also help. Some options off top of my head:

• Provide an additional layer of log filtering based on App Service logging configuration that does not interfere with logging configuration specified by the application.
  • This would be a natural resolution from my perspective - if I set up App Service Diagnostic Logs to log errors, I will only have errors.
  • It could also break consumers silently.
• Provide a flag to ignore App Service logging configuration
  • This could be a simple way to work around it in a way without breaking consumers.

Additional context

First, let's start with the documentation.

Azure App Service Diagnostic Logs article mentions the log level verbosity filter mapping and also how to set it up in ASP.NET Core in Add log messages in code section. This promptly links to the package and ASP.NET Core Logging documentation. No information of how the verbosity filter interacts with the .NET logging setup is given so far.

Logging in .NET Core and ASP.NET Core article describes several related aspects, specifically:

• Configure logging section mentions that
  • A general configuration is set up in Logging:LogLevel
  • A provider-specific configuration can override this for specific categories in Logging:{Provider}:LogLevel
  • It gives an example at the end which contains

    "AzureAppServicesFile": {
      "IncludeScopes": true,
      "LogLevel": {
        "Default": "Warning"
       }
    }

    and goes no to describe how this overrides the top-level Logging:LogLevel configuration. This setting has actually no effect at all as will be shown later. Its presence here, however, implies otherwise.
• How filtering rules are applied section provides relevant information for later

  The following algorithm is used for each provider when an ILogger is created for a given category:

  • Select all rules that match the provider or its alias. If no match is found, select all rules with an empty provider.
  • From the result of the preceding step, select rules with longest matching category prefix. If no match is found, select all rules that don't specify a category.
  • If multiple rules are selected, take the last one.
  • If no rules are selected, use MinimumLevel.

• Built-in logging providers > Azure App Service provides additional documentation regarding these providers. It does mention that it uses configuration from App Service but does not mention how.

Now on to the code.
AzureAppServicesLoggerFactoryExtensions registers ConfigurationBasedLevelSwitcher as IConfigureOptions<LoggerFilterOptions>

The ConfigurationBasedLevelSwitcher is populated with diagnostic configuration loaded from Azure App Service and introduces a logger filter rule. This rule's LogLevel matches the App Service's configured log verbosity, uses provider type name and has no category. This is usually called after AddLogging so this becomes the last filter rule applied.

Given the filter rule selection algorithm quoted above, all of the the general Logging:LogLevel configurations as well as the provider-specific Logging:AzureAppServices[File|Blob]:Default settings are ignored in favor of this rule. Additional provider-specific rules specifying category are respected.

As a result, it is possible to also create scenarios where the Azure App Service has Diagnostic Logs configured to Verbosity = Error but will happily report Trace, Debug or Info log messages with configuration such as

"AzureAppServicesBlob": {
  "IncludeScopes": true,
  "LogLevel": {
    "Microsoft": "Trace",
    "System": "Debug",
    "MyApplication": "Information"
   }
}

So as a result, the providers do not consistently respect either configuration. The configuration in App Service only applies to cases where no specific logging category filter is configured. And the application configuration is mostly ignored and must be explicitly specified again to take effect.

This took me quite a bit of time to diagnose and I haven't found any nice workaround. So far, I have settled on

private static void RemoveConfigurationBasedLevelSwitcher(IServiceCollection services)
{
    for (var i = services.Count - 1; i >= 0; --i)
    {
        if (IsLoggingFilterConfigurationFromAppServiceLoggingAssembly(services[i]))
        {
            services.RemoveAt(i);
        }
    }
}

private static bool IsLoggingFilterConfigurationFromAppServiceLoggingAssembly(ServiceDescriptor service)
{
    return service.ServiceType == typeof(IConfigureOptions<LoggerFilterOptions>)
        && service.ImplementationInstance != null
        && service.ImplementationInstance.GetType().Assembly.FullName?.StartsWith("Microsoft.Extensions.Logging.AzureAppServices,", StringComparison.Ordinal) == true;
}

it's terrible and slows down startup but at least nobody has to remember these logging configuration oddities. The log level configuration is already complicated as is, given the two dimensional overriding of defaults by providers and by environment.

I have also tried using diagnostic logs but the application logs do not include scopes (which is a big deal for us) and the console logs do nothing in Windows App Service, presumably because it uses IIS.

I do understand that this logging provider falls into a no-man's land of sorts, being linked to both Azure App Service and ASP.NET Core. I also understand there may not be a will to invest here due to business priorities. However, if this is only intended as something that works out of the box but does not support more complex scenarios cleanly, it should be called out so that nobody else has to spend significant time investigating this.

Existing related issues I have found are somewhat old and may or may not have been resolved:
#3279
#22954

The older one links to SO question https://stackoverflow.com/questions/56190165 so it seems there are others grappling with it as well.

[MackinnonBuck]

@zdenek-jelinek, thanks for the through writeup - it's clear you have a good understanding of what's happening and what the options for a solution are.

Out of curiosity, does removing the call to AddAzureWebAppDiagnostics() have the same effect as the workaround you described?

[halter73]

It turns out that AddAzureWebAppDiagnostics is called via our site extension on Azure App Service. It's added by default, but you can remove the ASP".NET Core Logging Integration" it via the Site Extensions tab on Kudu.

https://learn.microsoft.com/en-us/azure/app-service/resources-kudu

Of course, this doesn't help you if you actually want to use the App Service file and/or blob logger, but don't want to use the same minimum log level for every category specified by in the portal via "AzureBlobTraceLevel" or "AzureDriveTraceLevel". The workaround does the job but is not very discoverable. I think we'll have to work with the App Service team to provide an option to defer to the application-defined minimum log levels in the portal if we want to make a real improvement. I'm going to remove the labels and assignment so we can retriage. I don't think this is simply a docs issue that can be quickly addressed in RC2.