Longing to know

Previously, I blogged about creating a Entity Framework based Logger in .NET Core. One thing that I never implemented was granular control of logging specific levels by category. It turns out that it’s pretty easy to do, though.

Logging in .NET Core passes LogLevel and Category whenever something is to be logged. Category corresponds, afaik, to namespaces. You can see this in the default Console based logger configuration provided by the standard Visual Studio .NET Core templates:

  "Logging": {
    "IncludeScopes": false,
    "LogLevel": {
      "Default": "Debug",
      "System": "Information",
      "Microsoft": "Information"
    }
  }

Also, as far as I know, these settings refer to “minimum” log levels. Whenever log messages are passed to a logger, a filter is checked to determine if the message should be logged. You can see in my previous post, that I always return “true” which means everything is logged. Later, I implemented the concept of a single minimum level, but this isn’t overly useful since .NET Core logs a ton of messages that, really, are framework diagnostics from the Microsoft/System namespaces.

The mimimum level I implemented that I had implemented in the Logger looks like this:

public bool IsEnabled(LogLevel logLevel)
{
    return (_filter == null || _filter(_categoryName, logLevel));
}

Where the filter is a simple Func<string, LogLevel, bool>

return logLevel != LogLevel.None && logLevel >= matchedCategory.MinLevel;

Notice how I don’t inspect Category. There is no built-in nice feature for granular logging as the Console logger. But, it is pretty easy to implement.

Following the pattern that the Console-based logger uses, I create this section in my appsettings.json:

"MyLoggingSettings": {
  "ConnectionStringName": "Logging",
  "LogLevels": [
    {
      "Namespace": "Application",
      "MinLevel": "Debug",
      "Levels": [
        "Debug",
        "Error"
      ]
    },
    {
      "Namespace": "Microsoft",
      "Levels": [
        "Information",
        "Error"
      ]
    },
    {
      "Namespace": "System",
      "Levels": [
        "Debug",
        "Information",
        "Error"
      ]
    }
  ]
}

Remember that I mentioned that the Namespace is synonymous with Category? That’s why you’ll see the key to the array of objects is Namespace. The class that I will map these settings to is, then, pretty simple. A List<AppLogLevel> is populated along with the connections string name.

public class AppLogLevel
{
	public string Name { get; set; } = "Application";
	public LogLevel MinLevel { get; set; } = LogLevel.Debug;
	public List<LogLevel> Levels { get; set; } = new List<LogLevel>();
}

public class AppLoggingSettings
{
	public string ConnectionStringName{ get; set; } = "Logging";
	public List<AppLogLevel> LogLevels { get; set; } = new List<AppLogLevel>();
}

In the ConfigureServices section of my Startup.cs, I populate the settings, instantiate the settings object, and pass the connection string name into the extension method that creates the AppLoggerProvider:

// Make configuration settings available
services.Configure<AppLoggingSettings>(Configuration.GetSection("MyLoggingSettings"));
services.AddSingleton<IConfiguration>(Configuration);

var loggingSettings = new AppLoggingSettings();
Configuration.GetSection("MyLoggingSettings").Bind(loggingSettings);

// Add logging
services.AddLogger(Configuration.GetConnectionString(loggingSettings.ConnectionStringName));

In the Configure method of Startup.cs, the UseLogger method is called passing the Console configuration and the ApplicationName:

// Use logger
app.UseLogger(Configuration.GetSection("Logging"), appSettings.ApplicationName);

Since the extension methods for AddLogger/UseLogger have changed significantly, the Extension methods are below. You can see that the AddLogger method is adding the DbContext and the IRepository. The key change here is that the “AddProvider” method, which instantiates the AppLoggerProvider and attaches it to the ServiceProvider, has the AppLoggingSettings passed into it.

public static class Extensions
{
    public static void AddLogger(this IServiceCollection services, string loggingConnStr)
    {
        services.AddTransient<IRepository<AppLogModel>, AppLogRepository>();

        // Logging context must be transient..
        services.AddDbContext<AppLogContext>(options =>
        {
            options.UseSqlServer(loggingConnStr);
            options.UseLoggerFactory(null);
        }, ServiceLifetime.Transient);
    }

    /// <summary>
    /// Use the logger
    /// </summary>
    /// <param name="app"></param>
    /// <param name="config"></param>
    /// <param name="applicationName"></param>
    public static void UseLogger(this IApplicationBuilder app, IConfigurationSection config, string applicationName)
    {
        var serviceProvider = app.ApplicationServices;
        var loggerFactory = serviceProvider.GetService<ILoggerFactory>() as ILoggerFactory;
        var loggingSettings = (serviceProvider.GetService<IOptions<AppLoggingSettings>>()).Value;
        loggerFactory.AddConsole(config);
        loggerFactory.AddDebug();

        loggerFactory.AddDebug(LogLevel.Information);
        loggerFactory.AddDebug(LogLevel.Debug);
        loggerFactory.AddDebug(LogLevel.Error);

        Func<IRepository<AppLogModel>> appLogRepoFactory = () =>
        {
            // Create a scope repository
            var scope = serviceProvider.CreateScope();
            return scope.ServiceProvider.GetRequiredService<IRepository<AppLogModel>>();
        };

        loggerFactory.AddProvider(new AppLoggerProvider(appLogRepoFactory, loggingSettings, applicationName));
    }
}

Now that the boiler plate setup is out of the way, we can focus on create the filter. We’ll use some simple LINQ expresses to match our settings against category and LogLevel.

The AppLoggerProvider will store references to our filter, appName, and the repository factory. It will also have (3) constructors. One will take a predefined filter, one will take a minimum LogLevel, and one will take the AppLoggingSettings.

public class AppLoggerProvider : ILoggerProvider
{
    private Func<IRepository<AppLogModel>> _repoFactory;
    private AppLoggingSettings logSettings;
    private Func<string, LogLevel, bool> _filter;
    private string _appName = "Microsoft.AspNetCore";

    public AppLoggerProvider(Func<IRepository<AppLogModel>> repoFactory, Func<string, LogLevel, bool> filter, string applicationName)
    {
        _repoFactory = repoFactory;
        _filter = filter;
        _appName = applicationName;
    }

The first constructor is self-explanatory. We’re only setting our private members.

    public AppLoggerProvider(Func<IRepository<AppLogModel>> repoFactory, Func<string, LogLevel, bool> filter, string applicationName)
    {
        _repoFactory = repoFactory;
        _filter = filter;
        _appName = applicationName;
    }

The next constructor is a bit more interesting since we define our filter. Note that it takes a “minimum” LogLevel and creates a Func<string, LogLevel, bool> from the LogLevel. This does not take into account Category, so it has limited usefulness.

    public AppLoggerProvider(Func<IRepository<AppLogModel>> repoFactory, LogLevel minLogLevel, string applicationName)
    {
        _repoFactory = repoFactory;
        _filter = (_, logLevel) => logLevel != LogLevel.None && logLevel >= minLogLevel;
        _appName = applicationName;
    }

The last, and most versatile constructor takes the AppLoggingSettings object as an input. Based on this object, a robut filter is created. The category will be compared against the Namespace of each AppLogLevel to find a match. If no match is found, then we look for specifically named entries of “Default” or “Application.” I chose these as the “catch all” defaults. If there are LogLevels in the List<LogLevel> of a matched AppLogLevel, then we see if the passed in LogLevel is in the list and log the message if it is. If there are no LogLevels in the List<LogLevel> then we defer to the similar “minimum” LogLevel comparison. And, if we find no matches at all, then the message will not be logged.

    public AppLoggerProvider(Func<IRepository<AppLogModel>> repoFactory, AppLoggingSettings loggingSettings, string applicationName)
    {
        _repoFactory = repoFactory;
        _filter = (category, logLevel) =>
        {
            // First, does this match a category?
            var matchedCategory = loggingSettings.LogLevels.FirstOrDefault(x => category.ToLowerTrim().StartsWith(x.Namespace.ToLowerTrim()));
            if (matchedCategory == null)
            {
                matchedCategory = loggingSettings.LogLevels.FirstOrDefault(x => x.Namespace.ToLowerTrim() == "application" || x.Namespace.ToLowerTrim() == "default");
            }

            if (matchedCategory == null)
            {
                return false;
            }

            // Now, if there are levels defined, use those
            if ((matchedCategory.Levels?.Count ?? 0) > 0)
            {
                return matchedCategory.Levels.Contains(logLevel);
            }
            else
            {
                return logLevel != LogLevel.None && logLevel >= matchedCategory.MinLevel;
            }
        };
        _appName = applicationName;
    }

    public ILogger CreateLogger(string categoryName)
    {
        return new AppLogger(_repoFactory, _filter, _appName, categoryName);
    }

    public void Dispose()
    {
        _repoFactory = null;
    }
}

The only other change needed was to change the “IsEnabled” method in the AppLogger to execute the filter:

public bool IsEnabled(LogLevel logLevel)
{
    return (_filter == null || _filter(_categoryName, logLevel));
}

With these bits of code and configuration options in place, I have fine, granular control of what gets logged. Previously, my logging tables will getting slammed with all of the “System” and “Microsoft” messages. Now, I can turn any specific category (Namespace) completely off if I choose to. Once time permits, I will put the logging project/solution, in its entirely into a Github repository.

As an aside, Microsoft’s LogLevel enum is defined as below:

ASP.NET Core defines the following log levels, ordered here from least to highest severity.

• Trace = 0

  For information that is valuable only to a developer debugging an issue. These messages may contain sensitive application data and so should not be enabled in a production environment. Disabled by default. Example: Credentials: {"User":"someuser", "Password":"P@ssword"}

• Debug = 1

  For information that has short-term usefulness during development and debugging. Example: Entering method Configure with flag set to true.

• Information = 2

  For tracking the general flow of the application. These logs typically have some long-term value. Example: Request received for path /api/todo

• Warning = 3

  For abnormal or unexpected events in the application flow. These may include errors or other conditions that do not cause the application to stop, but which may need to be investigated. Handled exceptions are a common place to use the Warning log level. Example: FileNotFoundException for file quotes.txt.

• Error = 4

  For errors and exceptions that cannot be handled. These messages indicate a failure in the current activity or operation (such as the current HTTP request), not an application-wide failure. Example log message: Cannot insert record due to duplicate key violation.

• Critical = 5

  For failures that require immediate attention. Examples: data loss scenarios, out of disk space.