Manual wheels: write a log frame

Posted by gt500pwr on Wed, 01 Jan 2020 11:20:46 +0100

Manual wheels: write a log component

Intro

There are many log components, such as log4net / nlog / serilog / microsoft.extensions.logging, etc. How to switch log components without modifying the code, just switch different loggingProvider s, reduce the cost of switching log framework, and write a log component for different log framework in this considerationAdaptation, what logging framework is needed, configure it, and business code does not need to change.

V0

The initial log was strongly dependent on log4net, which was the first log framework I used, so I used it for logging for a long time. However, because of its strong dependency, it was hard to change log components when I wanted to change it. A lot of code needed to be changed, which did not conform to the basic principle of open and closed, so there was a first version of the log.

V1

The first version of the log refers to the implementation of Microsoft's log framework, which is roughly structured as follows:

public interface ILogHelperLogFactory
{
    ILogger CreateLogger(string categoryName);
    
    bool AddProvider(ILogHelperProvider provider);
}
public interface ILogHelperLogger
{
    bool IsEnabled(LogHelperLogLevel logLevel);
    void Log(LogHelperLogLevel logLevel, Exception exception, string message);
}
public enum LogHelperLogLevel
{
    /// <summary>
    /// All logging levels
    /// </summary>
    All = 0,

    /// <summary>
    /// A trace logging level
    /// </summary>
    Trace = 1,

    /// <summary>
    /// A debug logging level
    /// </summary>
    Debug = 2,

    /// <summary>
    /// A info logging level
    /// </summary>
    Info = 4,

    /// <summary>
    /// A warn logging level
    /// </summary>
    Warn = 8,

    /// <summary>
    /// An error logging level
    /// </summary>
    Error = 16,

    /// <summary>
    /// A fatal logging level
    /// </summary>
    Fatal = 32,

    /// <summary>
    /// None
    /// </summary>
    None = 64
}
public interface ILogHelperProvider
{
    ILogHelperLogger CreateLogger(string categoryName);
}

To facilitate the use of Logger, some extension methods are defined so that methods such as logger.Info/logger.Error can be used directly. The extension is defined as follows:

public static void Log(this ILogHelperLogger logger, LogHelperLevel loggerLevel, string msg) => logger.Log(loggerLevel, null, msg);

#region Info

    public static void Info(this ILogHelperLogger logger, string msg, params object[] parameters)
{
    if (parameters == null || parameters.Length == 0)
    {
        logger.Log(LogHelperLevel.Info, msg);
    }
    else
    {
        logger.Log(LogHelperLevel.Info, null, msg.FormatWith(parameters));
    }
}

public static void Info(this ILogHelperLogger logger, Exception ex, string msg) => logger.Log(LogHelperLevel.Info, ex, msg);

public static void Info(this ILogHelperLogger logger, Exception ex) => logger.Log(LogHelperLevel.Info, ex, ex?.Message);

#endregion Info
// ... similar to the others, let's not go into details here

If you want to customize logging, you can implement an ILogHelperProvider. Implementing an ILogHelperProvider implements an ILogHelperLogger. A heavily dependent log4net implements a Log4NetLogHelperProvider, so you only need to implement the corresponding ILogHelperProvider when changing log components, but functionallyVery weak

If you want some logs not to be logged, for example, Debug level logs are not logged, for example, Error level logs are only logged under a Logger. Now it's a bit of a hassle and can only be limited by the configuration of log4net, so there's a second version, with LoggingFilter added, you can set up a filter for Provider/Logger/LogLevel/Exception without filtering.This is also a Filter that refers to Microsoft's log framework for logging, but the implementation is not the same, and interested partners can delve into it themselves.

V2

Version V2 adds the AddFilter method to the interface of ILogFactory, which is defined as follows:

/// <summary>   
/// Add logs filter 
/// </summary>  
/// <param name="filterFunc">filterFunc, logProviderType/categoryName/Exception, whether to write log</param>   
bool AddFilter(Func<Type, string, LogHelperLogLevel, Exception, bool> filterFunc);

Then some extension methods are defined for easy use:

public static ILogHelperFactory WithMinimumLevel(this ILogHelperFactory logHelperFactory, LogHelperLevel logLevel)
{
    return logHelperFactory.WithFilter(level => level >= logLevel);
}

public static ILogHelperFactory WithFilter(this ILogHelperFactory logHelperFactory, Func<LogHelperLevel, bool> filterFunc)
{
    logHelperFactory.AddFilter((type, categoryName, logLevel, exception) => filterFunc.Invoke(logLevel));
    return logHelperFactory;
}

public static ILogHelperFactory WithFilter(this ILogHelperFactory logHelperFactory, Func<string, LogHelperLevel, bool> filterFunc)
{
    logHelperFactory.AddFilter((type, categoryName, logLevel, exception) => filterFunc.Invoke(categoryName, logLevel));
    return logHelperFactory;
}

public static ILogHelperFactory WithFilter(this ILogHelperFactory logHelperFactory, Func<Type, string, LogHelperLevel, bool> filterFunc)
{
    logHelperFactory.AddFilter((type, categoryName, logLevel, exception) => filterFunc.Invoke(type, categoryName, logLevel));
    return logHelperFactory;
}

public static ILogHelperFactory WithFilter(this ILogHelperFactory logHelperFactory, Func<Type, string, LogHelperLevel, Exception, bool> filterFunc)
{
    logHelperFactory.AddFilter(filterFunc);
    return logHelperFactory;
}

This makes it easy for us to define only the Filter for Logger and the Filter for Provider, without having to use all the parameters. The logging filter has now been implemented and has been logging with Serilog for some time now. I feel that some of the designs in Serilog are excellent and elegant, so I want to use some of the designs in Serilog in my own log framework.For example:

  1. Serilog's extension is called Sink. Where the log output is located, Serilog customizes a Sink. It's easy to implement only one interface without implementing another Logger. From this point of view, I think Serilog is better than Microsoft's log framework, and LogEvent makes logging easier to do batch operations. If you need to, you can learn more about Serilog's PriodBatch.Ing https://github.com/serilog/serilog-sinks-periodicbatching

    /// <summary>
    /// A destination for log events.
    /// </summary>
    public interface ILogEventSink
    {
        /// <summary>
        /// Emit the provided log event to the sink.
        /// </summary>
        /// <param name="logEvent">The log event to write.</param>
        void Emit(LogEvent logEvent);
    }
  2. Serilog can customize some Enricher to enrich the logged content, such as the request context of the log, the logged environment, etc., or some fixed attribute information

  3. MessageTemplate, in fact, has similar concepts in Microsoft's log framework, but it is not obvious. I seldom used it before using Serilog. Microsoft's log framework can use logger.LogInfo("hello {name}", "world") in this way. In fact, the first parameter can be regarded as MessageTemplate or Format inside it.

With all these benefits in mind, I plan to bring these capabilities into my logging framework

V3

Introducing LoggingEvent

Just do it, first introduce a LogHelperLoggingEvent, which corresponds to a Serilog LogEvent, defined as follows:

public class LogHelperLoggingEvent : ICloneable
{
    public string CategoryName { get; set; }

    public DateTimeOffset DateTime { get; set; }

    public string MessageTemplate { get; set; }

    public string Message { get; set; }

    public Exception Exception { get; set; }

    public LogHelperLogLevel LogLevel { get; set; }

    public Dictionary<string, object> Properties { get; set; }

    public LogHelperLoggingEvent Copy => (LogHelperLoggingEvent)Clone();

    public object Clone()
    {
        var newEvent = (LogHelperLoggingEvent)MemberwiseClone();
        if (Properties != null)
        {
            newEvent.Properties = new Dictionary<string, object>();
            foreach (var property in Properties)
            {
                newEvent.Properties[property.Key] = property.Value;
            }
        }
        return newEvent;
    }
}

Event defines a dictionary of Properties to enrich the contents of the log, implements the ICloneable interface to facilitate copying objects, adds a Copy method to strongly type and returns a strongly typed object

Modify LogProvider

To reduce the complexity of extending an ILogProvider, we need to simplify the ILogProvider by simply logging like the Link that extends Serilog, and not caring about whether or not to create a Logger

The modified definition is as follows:

public interface ILogHelperProvider
{
    Task Log(LogHelperLoggingEvent loggingEvent);
}

(A Task is returned here, maybe void is enough, depending on your needs)

This way, you only need to implement this interface when implementing LogProvider, and you don't need to implement a Logger anymore.

Add Enricher

Enricher definition:

public interface ILogHelperLoggingEnricher
{
    void Enrich(LogHelperLoggingEvent loggingEvent);
}

Built-in a PropertyEnricher to add simple properties

internal class PropertyLoggingEnricher : ILogHelperLoggingEnricher
{
    private readonly string _propertyName;
    private readonly Func<LogHelperLoggingEvent, object> _propertyValueFactory;
    private readonly bool _overwrite;
    private readonly Func<LogHelperLoggingEvent, bool> _logPropertyPredict = null;

    public PropertyLoggingEnricher(string propertyName, object propertyValue, bool overwrite = false) : this(propertyName, (loggingEvent) => propertyValue, overwrite)
    {
    }

    public PropertyLoggingEnricher(string propertyName, Func<LogHelperLoggingEvent, object> propertyValueFactory,
                                   bool overwrite = false) : this(propertyName, propertyValueFactory, null, overwrite)
    {
    }

    public PropertyLoggingEnricher(string propertyName, Func<LogHelperLoggingEvent, object> propertyValueFactory, Func<LogHelperLoggingEvent, bool> logPropertyPredict,
                                   bool overwrite = false)
    {
        _propertyName = propertyName;
        _propertyValueFactory = propertyValueFactory;
        _logPropertyPredict = logPropertyPredict;
        _overwrite = overwrite;
    }

    public void Enrich(LogHelperLoggingEvent loggingEvent)
    {
        if (_logPropertyPredict?.Invoke(loggingEvent) != false)
        {
            loggingEvent.AddProperty(_propertyName, _propertyValueFactory, _overwrite);
        }
    }
}

Add an AddEnricher method to ILogFactory

/// <summary>
/// add log enricher
/// </summary>
/// <param name="enricher">log enricher</param>
/// <returns></returns>
bool AddEnricher(ILogHelperLoggingEnricher enricher);

This allows us to enrich the Properties in LoggingEvent s with these Enricher s while logging

To facilitate Property's operation, we have added some extension methods:

public static ILogHelperFactory WithEnricher<TEnricher>(this ILogHelperFactory logHelperFactory,
                                                        TEnricher enricher) where TEnricher : ILogHelperLoggingEnricher
{
    logHelperFactory.AddEnricher(enricher);
    return logHelperFactory;
}

public static ILogHelperFactory WithEnricher<TEnricher>(this ILogHelperFactory logHelperFactory) where TEnricher : ILogHelperLoggingEnricher, new()
{
    logHelperFactory.AddEnricher(new TEnricher());
    return logHelperFactory;
}

public static ILogHelperFactory EnrichWithProperty(this ILogHelperFactory logHelperFactory, string propertyName, object value, bool overwrite = false)
{
    logHelperFactory.AddEnricher(new PropertyLoggingEnricher(propertyName, value, overwrite));
    return logHelperFactory;
}

public static ILogHelperFactory EnrichWithProperty(this ILogHelperFactory logHelperFactory, string propertyName, Func<LogHelperLoggingEvent> valueFactory, bool overwrite = false)
{
    logHelperFactory.AddEnricher(new PropertyLoggingEnricher(propertyName, valueFactory, overwrite));
    return logHelperFactory;
}

public static ILogHelperFactory EnrichWithProperty(this ILogHelperFactory logHelperFactory, string propertyName, object value, Func<LogHelperLoggingEvent, bool> predict, bool overwrite = false)
{
    logHelperFactory.AddEnricher(new PropertyLoggingEnricher(propertyName, e => value, predict, overwrite));
    return logHelperFactory;
}

public static ILogHelperFactory EnrichWithProperty(this ILogHelperFactory logHelperFactory, string propertyName, Func<LogHelperLoggingEvent, object> valueFactory, Func<LogHelperLoggingEvent, bool> predict, bool overwrite = false)
{
    logHelperFactory.AddEnricher(new PropertyLoggingEnricher(propertyName, valueFactory, predict, overwrite));
    return logHelperFactory;
}

MessageTemplate

MessageTemplate has been added from the LoggingEvent above, so we introduced the formatting of logs in the Microsoft Log Framework, converting messageTemplate and parameters to Message and roperties for reference https://github.com/WeihanLi/WeihanLi.Common/blob/276cc49cfda511f9b7b3bb8344ee52441c4a3b23/src/WeihanLi.Common/Logging/LoggingFormatter.cs

internal struct FormattedLogValue
{
    public string Msg { get; set; }

    public Dictionary<string, object> Values { get; set; }

    public FormattedLogValue(string msg, Dictionary<string, object> values)
    {
        Msg = msg;
        Values = values;
    }
}

internal static class LoggingFormatter
{
    public static FormattedLogValue Format(string msgTemplate, object[] values)
    {
        if (values == null || values.Length == 0)
            return new FormattedLogValue(msgTemplate, null);

        var formatter = new LogValuesFormatter(msgTemplate);
        var msg = formatter.Format(values);
        var dic = formatter.GetValues(values)
            .ToDictionary(x => x.Key, x => x.Value);

        return new FormattedLogValue(msg, dic);
    }
}

So we can support messageTemplate and then transform our Logger

public interface ILogHelperLogger
{
    void Log(LogHelperLogLevel logLevel, Exception exception, string messageTemplate, params object[] parameters);

    bool IsEnabled(LogHelperLogLevel logLevel);
}

Unlike the above, we added parameters

Let's update our extension method again, which is formatted directly using string.Format. Let's update it here

public static void Info(this ILogHelperLogger logger, string msg, params object[] parameters)
{
    logger.Log(LogHelperLogLevel.Info, null, msg, parameters);
}

public static void Info(this ILogHelperLogger logger, Exception ex, string msg) => logger.Log(LogHelperLogLevel.Info, ex, msg);

public static void Info(this ILogHelperLogger logger, Exception ex) => logger.Log(LogHelperLogLevel.Info, ex, ex?.Message);

At this point, the functionality is almost complete, but from the API point of view, it feels like ILogFactory is too heavy now. These AddProvider/AddEnricher/AddFilter s should all attribute the internal properties of ILogFactory. They are configured to do so, they should not be its interface method, so there is the next version.

V4

This edition mainly introduces LoggingBuilder, which configures the Provider/Enricher/Filter needed by the internal LogFactory by LoggingBuilder. Their original configuration and extension methods have become LoggingBuilder

public interface ILogHelperLoggingBuilder
{
    /// <summary>
    /// Adds an ILogHelperProvider to the logging system.
    /// </summary>
    /// <param name="provider">The ILogHelperProvider.</param>
    bool AddProvider(ILogHelperProvider provider);

    /// <summary>
    /// add log enricher
    /// </summary>
    /// <param name="enricher">log enricher</param>
    /// <returns></returns>
    bool AddEnricher(ILogHelperLoggingEnricher enricher);

    /// <summary>
    /// Add logs filter
    /// </summary>
    /// <param name="filterFunc">filterFunc, logProviderType/categoryName/Exception, whether to write log</param>
    bool AddFilter(Func<Type, string, LogHelperLogLevel, Exception, bool> filterFunc);

    ///// <summary>
    ///// config period batching
    ///// </summary>
    ///// <param name="period">period</param>
    ///// <param name="batchSize">batchSize</param>
    //void PeriodBatchingConfig(TimeSpan period, int batchSize);

    /// <summary>
    /// Build for LogFactory
    /// </summary>
    /// <returns></returns>
    ILogHelperFactory Build();
}

Increase logging configuration:

public static class LogHelper
{
    private static ILogHelperFactory LogFactory { get; private set; } = NullLogHelperFactory.Instance;

    public static void ConfigureLogging(Action<ILogHelperLoggingBuilder> configureAction)
    {
        var loggingBuilder = new LogHelperLoggingBuilder();
        configureAction?.Invoke(loggingBuilder);
        LogFactory = loggingBuilder.Build();
    }

    public static ILogHelperLogger GetLogger<T>() => LogFactory.GetLogger(typeof(T));

    public static ILogHelperLogger GetLogger(Type type) => LogFactory.GetLogger(type);

    public static ILogHelperLogger GetLogger(string categoryName)
    {
        return LogFactory.CreateLogger(categoryName);
    }
}

Final usage:

internal class LoggingTest
{
    private static readonly ILogHelperLogger Logger = LogHelper.GetLogger<LoggingTest>();

    public static void MainTest()
    {
        var abc = "1233";
        LogHelper.ConfigureLogging(builder =>
                                   {
                                       builder
                                           .AddLog4Net()
                                           //.AddSerilog(loggerConfig => loggerConfig.WriteTo.Console())
                                           .WithMinimumLevel(LogHelperLogLevel.Info)
                                           .WithFilter((category, level) => level > LogHelperLogLevel.Error && category.StartsWith("System"))
                                           .EnrichWithProperty("Entry0", ApplicationHelper.ApplicationName)
                                           .EnrichWithProperty("Entry1", ApplicationHelper.ApplicationName, e => e.LogLevel >= LogHelperLogLevel.Error)// Increase Property when LogLevel is Error or above
                                           ;
                                   });

        Logger.Debug("12333 {abc}", abc);
        Logger.Trace("122334334");
        Logger.Info($"122334334 {abc}");

        Logger.Warn("12333, err:{err}", "hahaha");
        Logger.Error("122334334");
        Logger.Fatal("12333");
    }
}

More

Increasing LoggingEvent also wants to make a batch submission log, like PeriodBatchingConfig defined above, which is synchronized to Provider in batches. However, in practice, some providers do not support setting the time for logging. Time is recorded internally, so that the time for logging is not allowed, and most of them do not support batch logging, so they are discarded later.But if you just use your own extensions and don't use external logging frameworks like log4net, I think you can still do it to improve efficiency. Currently, Serilog and log4net are the main ones, so don't update them for now, let's start with this

Things to be resolved in the next release

  • The ILogProvider log returns a Task that feels like some chicken ribs. That doesn't make much sense. Change it later
  • Serilog's Filter is based on LogEvent, see if you need to change it later. LogEvent-based words are more concise and can be filtered according to the Properties within the LogEvent, so AddFilter's API can update AddFilter (Func<LogHelperLoggingEvent, bool>filter)

Reference

Topics: C# github Attribute