Search code examples
c#service-worker.net-8.0serilogserilog-filter

How to create MessageTemplateTokens for Serilog LogEvents in C# .NET8 (Core) (in a Worker Service project)


I am using serilog in my C# .NET 8 Worker Service project. I want a special behavior and have written a sink to filter the logging.

In my Program.cs file, I call the following function to create my logger:

// Method to configure Serilog with DuplicateFilterSink
Serilog.ILogger CreateSerilogLogger()
{
    LoggerConfiguration loggerConfig = new LoggerConfiguration()
        .WriteTo.Console() // for debugging
        .WriteTo.File(
            path: Settings.Default.LogFileSpec,     // base file name
            rollingInterval: RollingInterval.Day,   // automatically creates a new file daily
            outputTemplate: "{Timestamp:yyyy-MM-dd HH:mm:ss.fff zzz} [{Level:u3}] {Message:lj}{NewLine}{Exception}"
        );

    // Add Event Log only for Windows
    if (OperatingSystem.IsWindows())
    {
        loggerConfig.WriteTo.EventLog(
            source: Settings.Default.EventLogSource,
            logName: Settings.Default.EventLogName,
            restrictedToMinimumLevel: Serilog.Events.LogEventLevel.Warning
        );
    }

    DuplicateFilterSink duplicateFilterSink = new DuplicateFilterSink(loggerConfig.CreateLogger());
    return new LoggerConfiguration()
        .WriteTo.Sink(duplicateFilterSink)
        .CreateLogger();
}

My DuplicateFilterSink class looks like this:

public class DuplicateFilterSink : ILogEventSink
{
    private readonly ILogEventSink _innerSink;
    private LogEvent? _lastLogEvent;
    private int _duplicateCount = 0;

    public DuplicateFilterSink(ILogEventSink innerSink)
    {
        _innerSink = innerSink;
    }

    public void Emit(LogEvent logEvent)
    {
        // Check if the message is the same as the previous one
        if (_lastLogEvent != null && logEvent.MessageTemplate.Text == _lastLogEvent.MessageTemplate.Text)
        {
            _duplicateCount++;
        }
        else
        {
            // If the message has changed, log the previous duplicate count
            if (_duplicateCount > 0)
            {
                List<LogEventProperty> properties = new List<LogEventProperty>();

                foreach (var thing in logEvent.Properties)
                {
                    LogEventProperty property = new LogEventProperty(thing.Key, thing.Value);
                    properties.Add(property);
                }

                string dupmsg = $"The previous message occurred {_duplicateCount} times";
                MessageTemplate duplicateTemplate = new MessageTemplate(dupmsg, Array.Empty<MessageTemplateToken>());
                
                LogEvent duplicateMessage = new LogEvent(
                    logEvent.Timestamp,
                    logEvent.Level,
                    logEvent.Exception,
                    duplicateTemplate,
                    properties.ToArray()
                );

                _innerSink.Emit(duplicateMessage);
                _duplicateCount = 0;
            }

            // Log the new message
            _innerSink.Emit(logEvent);
            _lastLogEvent = logEvent;
        }
    }
}

The idea is that if the LogEvent matches the previous LogEvent, it will not be emitted but only counted. As soon as the LogEvent DOESN'T match the previous LogEvent AND the count is greater than zero, it will emit a message saying the previous message occurred X times and then it would emit the new message. This will prevent runaway messages in a tight loop from filling up my log files.

This all works except when the duplicateMessage LogEvent is emitted, the text is blank. I believe it is because I am using an empty MessageTemplateToken array. That is the only difference between the duplicatMessage LogEvent and the LogEvent that is the parameter.

If this is the problem, I don't know how to correct it. The MessageTemplateToken is an abstract class so I can't instantiate it and I can't find any class that derives from it. I also can't use the existing MessageTemplateTokens from the LogEvent parameter's MessageTemplate because I would have to change the text inside it and the Text property is read-only.

  • Question #1: Is this my problem? Is the blank MessageTemplateToken array causing my emitted LogEvent to write a blank line?

  • Question #2: is there any way to create a valid MessageTemplate with a valid MessageTemplateToken array?


Solution

  • Ok, I fixed this myself with a really really ugly hack.

    My DuplicateFilterSink class now looks like this:

    public class DuplicateFilterSink : ILogEventSink
    {
        private readonly ILogEventSink _innerSink;
        private LogEvent? _prevLogEvent;
        private int _duplicateCount = 0;
    
        public DuplicateFilterSink(ILogEventSink innerSink)
        {
            _innerSink = innerSink;
        }
    
        public void Emit(LogEvent logEvent)
        {
            // Check if the message is the same as the previous one
            if (_prevLogEvent != null && logEvent.MessageTemplate.Text == _prevLogEvent.MessageTemplate.Text)
            {
                _duplicateCount++;
            }
            else
            {
                // If the message has changed, log the previous duplicate count
                if (_duplicateCount > 0 && !logEvent.MessageTemplate.Text.StartsWith("  * The previous message occurred"))
                {
                    string dupmsg = $"  * The previous message occurred {_duplicateCount} times";
    
                    Log.Information(dupmsg, _duplicateCount);
    
                    _duplicateCount = 0;
                }
    
                // Log the new message
                _innerSink.Emit(logEvent);
                _prevLogEvent = logEvent;
            }
        }
    }
    

    Since I have not figured out a way to create a valid MessageTemplate with a valid MessageTemplateToken, I tried using the Log.Information() line, but that created an infinite recursion loop because the Log method kept calling the Sink which called the Log method which called the... well, you get it.

    I combated this problem by adding the "&& !logEvent.MessageTemplate.Text.StartsWith(..." condition to the if statement so that the second time through it would not Log method again.

    This works, but is horribly Kludgy. I will be greatful if anyone can solve my original problem in a "best-practices" way.