Previous month:
August 2017

September 2017

(ASP).NET Core in production: Changing log level temporarily - 2nd approach

In the previous blog post I talked about how to change the log level at runtime by coupling the appsettings.json (or rather the IConfiguration) with the ILogger. However, the solution has one drawback: you need to change the file appsettings.json for that. In this post we will be able to change the log level without changing the configuration file.

Want to see some real code? Look at the examples on https://github.com/PawelGerr/Thinktecture.Logging.Configuration 

or just use Nuget packages: Thinktecture.Extensions.Logging.Configuration and Thinktecture.Extensions.Serilog.Configuration 

At first we need a custom implementation of IConfigurationSource and IConfigurationProvider. The actual work does the implementation of IConfigurationProvider. The IConfigurationSource is just to inject the provider into your ConfigurationBuilder.

var config = new ConfigurationBuilder()
    .Add(new LoggingConfigurationSource())
    .Build();
----------------------------------------- public class LoggingConfigurationSource : IConfigurationSource
{
    public IConfigurationProvider Build(IConfigurationBuilder builder)
    {
        // Our implementation of IConfigurationProvider
        return new LoggingConfigurationProvider();
    }
}

As we can see, the LoggingConfigurationSource doesn't do pretty much, let us focus on LoggingConfigurationProvider or rather on the interface IConfigurationProvider.

public interface IConfigurationProvider
{
    bool TryGet(string key, out string value);
    void Set(string key, string value);
    IChangeToken GetReloadToken();
    void Load();
    IEnumerable<string> GetChildKeys(IEnumerable<string> earlierKeys, string parentPath);
}

There are 2 methods that look promising: Set(key, value) for setting a value for a specific key and GetReloadToken() to notify other components (like the logger) about changes in the configuration. Now that we know how to change the configuration values, we need to know the keys and values the logger uses to configure itself. Use Microsoft docs for a hint for Microsoft.Extensions.Logging.ILogger or Serilog.Settings.Configuration in case you are using Serilog.

The pattern for MS-logger key is <<Provider>>:LogLevel:<<Category>>. Here are some examples for the logs coming from Thinktecture components: Console:LogLevel:Thinktecture or LogLevel:Thinktecture.  The value is just one of the Microsoft.Extensions.Logging.LogLevel, like Debug.

namespace Thinktecture
{
    public class MyComponent
    {
        public MyComponent(ILogger<MyComponent> logger)
        {
            logger.LogDebug("Log from Thinktecture.Component");
        }
    }
}

Let's look at the implementation, luckily there is a base class we can use.

public class LoggingConfigurationProvider : ConfigurationProvider
{
    public void SetLevel(LogLevel level, string category = null, string provider = null)
    {
        // returns something like "Console:LogLevel:Thinktecture"
        var path = BuildLogLevelPath(category, provider);
        var levelName = GetLevelName(level); // returns log level like "Debug"

        // Data and OnReload() are provided by the base class
        Data[path] = levelName;
        OnReload(); // notifies other components
    }

    ...
}

Actually, that's it ... You can change the configuration just by setting and deleting keys in the dictionary Data and calling OnReload() afterwards. The only part that's left is to get hold of the instance of LoggingConfigurationProvider to be able to call the method SetLevel from outside but I'm pretty sure you don't need any help for that especially having access to my github repo :)

 

The provided solution does what we intended to, but, do we really want that simple filtering of the logs? Image you are using Entity Framework Core (EF) and there are multiple requests that modify some data. One request is able to commit the transaction the other doesn't and throws, say, an OptimisticConcurrencyException. Your code catches the exception and handles it by retrying the whole transaction, with success. Entity Framework logs this error (i.e. the SQL statement, arguments etc.) internally. The question is, should this error be logged by EF as an Error even if it has been handled by our application? If yes then our logs will be full with errors and it would seem as if we have a lot of bugs in our application. Perhaps it would be better to let EF to log its internal errors as Debug, so that this information is not lost and if our app can't handle the exception then we will log the exception as an error.

But that's for another day ...


.NET Core in production: Changing log level temporarily

When running the application in production then the log level is set somewhere between Information and Error. The question is what to do if you or your customer experiences some undesired behavior and the logs with present log level aren't enough to pinpoint the issue.

The first solution that comes to mind is to try to reproduce the issue on a developer's machine with lower log level like Debug. It may be enough to localize the bug but sometimes it isn't. Even if you are allowed to restart the app in production with lower log level, the issue may go away ... temporarily, i.e. the app still has a bug.

Better solution is to change the log level temporarily without restarting the app.

First step is to initialize the logger with the IConfiguration. That way the logger changes the level as soon as you change the corresponding configuration (file).

In this post I will provide 2 examples, one that is using the ILoggingBuilder of the ASP.NET Core and the other example is using Serilog because it is not tightly coupled to ASP.NET Core (but works very well with it!). 

Using ILoggingBuilder:

// the content of appsettings.json
{
    "Logging": {
        "LogLevel": { "Default": "Information" }
    }
}
-----------------------------------------
var config = new ConfigurationBuilder().
    AddJsonFile("appsettings.json", false, true) // reloadOnChange=true
    .Build();
// Setup of ASP.NET Core application WebHostWebHost
    .CreateDefaultBuilder()
    .ConfigureLogging(builder =>
    {
        builder.AddConfiguration(config); // <= init logger
        builder.AddConsole();
    })
    ...

Using Serilog:

// the content of appsettings.json
{
    "Serilog": {
        "MinimumLevel": { "Default": "Information" }
    }
}
-----------------------------------------
var config = new ConfigurationBuilder()
    .AddJsonFile("appsettings.json", false, true) // reloadOnChange=true
    .Build();
var serilogConfig = new LoggerConfiguration()
    .ReadFrom.Configuration(config) // <= init logger
    .WriteTo.Console();

In case you are interested in integration with (ASP).NET Core 

// If having a WebHost
WebHost
    .CreateDefaultBuilder()
    .ConfigureLogging(builder =>
    {
        builder.AddSerilog(serilogConfig.CreateLogger());
    })
    ...;

// If there is no WebHost
var loggerFactory = new LoggerFactory()
    .AddSerilog(serilogConfig.CreateLogger());

At this point the loggers are coupled to IConfiguration or rather to appsettings.json, i.e if you change the level to Debug the app starts emitting debug-messages as well, without restarting it.

This solution has one downside, you need physical access to the appsettings.json. Even if you do, it still would be better to not change the configuration file. What we want is a component that let us set and reset a temporary log level and if this temporary level is not active then the values from appsettings.json should be used. That way you can change the level from the GUI or via an HTTP request against the Web API of your web application.

Luckily, the implementation effort for that feature is pretty low, but that's for another day...