Sitecore Serilog Appender

Background

Our team had to integrate SEQ logging on one of our Sitecore projects. We investigated a few articles on how to implement it and provided an initial solution.

The solution is based on wrapping the Serilog SEQ logger inside a log4net Sitecore appender. Below, I'll show how it all worked.

But we faced a few issues:

  • No exception stack trace was logged.
  • The initial implementation was not optimized (poor performance).
  • Context-based Serilog Enhancers were not working correctly.

After step-by-step fixing and analyzing the process, I decided to create a NuGet library to use Serilog together with Sitecore. This allows you to integrate it into your Sitecore solution and collect logging data in any available Serilog Sinks.

You can visit the following links to try it:

Note. You should also consider using Seq.Client.Log4Net - an officially supported package for SEQ in log4net (but to integrate additional logging platforms, some other log4net package should be used as well).

Implementation

The Beginning
Source

We started with this article written by Himadri Chakrabarti - it's a really great starting point. Here is the source of the appender:

using log4net.spi;
using System;
using log4net.helpers;
using Serilog;
using Serilog.Core;
using Serilog.Events;
using ILogger = Serilog.ILogger;

namespace log4net.Appender
{
    public class SerilogAppender : BufferingAppenderSkeleton
    {
        public string MinimumLevel { get; set; }

        public string ApiKey { get; set; }

        public string SeqHost { get; set; }

        [Obsolete("Use the BufferingAppenderSkeleton Fix methods")]
        public bool LocationInfo => false;

        protected override void SendBuffer(LoggingEvent[] events)
        {
            if (string.IsNullOrEmpty(SeqHost))
            {
                return;
            }

            using (
                var log = new LoggerConfiguration()
                    .MinimumLevel.ControlledBy(new LoggingLevelSwitch(GetLogEventLevel(MinimumLevel, LogEventLevel.Information)))
                    .Enrich.WithProperty("ApplicationName", GetSite())
                    .Enrich.WithProperty("SpokeName", GetRoleName().ToLower())
                    .Enrich.FromLogContext()
                    .Enrich.WithMachineName()
                    .Enrich.WithEnvironmentUserName()
                    .Enrich.WithProcessId()
                    .Enrich.WithProcessName()
                    .Enrich.WithProperty("ThreadId", SystemInfo.CurrentThreadId)
                    .Enrich.WithMemoryUsage()
                    .WriteTo.Seq(SeqHost, apiKey: ApiKey)
                    .CreateLogger()
                )
            {
                foreach (var thisEvent in events)
                {
                    LogEvent(log, thisEvent);
                }
            }
        }

        private static string GetSite()
        {
            return !string.IsNullOrWhiteSpace(Sitecore.Context.Site?.Name) ? Sitecore.Context.Site.Name : null;
        }

        private static string GetRoleName()
        {
            var roleName = Sitecore.Configuration.Settings.GetSetting("CloudRoleNameFallback");

            return !string.IsNullOrWhiteSpace(roleName) ? roleName : "RoleName";
        }

        protected override bool RequiresLayout => true;

        private void LogEvent(ILogger log, LoggingEvent loggingEvent)
        {
            try
            {
                var message = RenderLoggingEvent(loggingEvent);
                var level = GetLogEventLevel(loggingEvent.Level.ToString());
                log.Write(level, message);
            }
            catch (Exception ex)
            {
                ErrorHandler.Error("Error occurred while logging the event.", ex);
            }
        }

        private static LogEventLevel GetLogEventLevel(string level, LogEventLevel defaultValue = LogEventLevel.Debug)
        {
            var logEventLevel = defaultValue;
            switch (level.ToLowerInvariant())
            {
                case "debug":
                    logEventLevel = LogEventLevel.Debug;
                    break;
                case "info":
                    logEventLevel = LogEventLevel.Information;
                    break;
                case "warn":
                    logEventLevel = LogEventLevel.Warning;
                    break;
                case "error":
                    logEventLevel = LogEventLevel.Error;
                    break;
                case "fatal":
                    logEventLevel = LogEventLevel.Fatal;
                    break;
            }

            return logEventLevel;
        }
    }
}
Issues

This implementation contains the following issues:

  • No exception stack trace is logged.
  • The method SendBuffer is not optimized: each execution creates a new Serilog Logger instance.
Add Exception Stack Trace and Optimize Performance
Source

To fix the issues mentioned above, we changed the source of the appender:

using log4net.spi;
using System;
using System.Reflection;
using Serilog;
using Serilog.Core;
using Serilog.Events;
using ILogger = Serilog.ILogger;
using log4net.helpers;
using Serilog.Exceptions;
using SitecoreSerilog.Extensions;

namespace log4net.Appender
{
    public class SerilogAppender : BufferingAppenderSkeleton
    {
        public string MinimumLevel { get; set; }

        public string ApiKey { get; set; }

        public string SeqHost { get; set; }

        [Obsolete("Use the BufferingAppenderSkeleton Fix methods")]
        public bool LocationInfo => false;

        private Logger _seqLogger;

        private static readonly FieldInfo ExceptionField = typeof(LoggingEvent).GetField("m_thrownException",
            BindingFlags.Public | BindingFlags.NonPublic | BindingFlags.Instance);

        protected override void SendBuffer(LoggingEvent[] events)
        {
            if (_seqLogger == null)
            {
                return;
            }

            foreach (var thisEvent in events)
            {
                LogEvent(_seqLogger, thisEvent);
            }
        }

        protected override bool RequiresLayout => true;

        private void LogEvent(ILogger log, LoggingEvent loggingEvent)
        {
            try
            {
                var message = RenderLoggingEvent(loggingEvent);
                var level = GetLogEventLevel(loggingEvent.Level.ToString());
                Exception exception = null;
                if (level >= LogEventLevel.Error)
                {
                    exception = ExceptionField.GetValue(loggingEvent) as Exception;
                }

                log.Write(level, exception, message);
            }
            catch (Exception ex)
            {
                ErrorHandler.Error("Error occurred while logging the event.", ex);
            }
        }

        private static LogEventLevel GetLogEventLevel(string level, LogEventLevel defaultValue = LogEventLevel.Debug)
        {
            var logEventLevel = defaultValue;
            switch (level.ToLowerInvariant())
            {
                case "debug":
                    logEventLevel = LogEventLevel.Debug;
                    break;
                case "info":
                    logEventLevel = LogEventLevel.Information;
                    break;
                case "warn":
                    logEventLevel = LogEventLevel.Warning;
                    break;
                case "error":
                    logEventLevel = LogEventLevel.Error;
                    break;
                case "fatal":
                    logEventLevel = LogEventLevel.Fatal;
                    break;
            }

            return logEventLevel;
        }

        public override void ActivateOptions()
        {
            base.ActivateOptions();
            if (string.IsNullOrEmpty(SeqHost))
            {
                return;
            }
            _seqLogger = new LoggerConfiguration()
                .MinimumLevel
                .ControlledBy(new LoggingLevelSwitch(GetLogEventLevel(MinimumLevel, LogEventLevel.Information)))
                .Enrich.WithFuncEnricher("ApplicationName", GetSite)
                .Enrich.WithFuncEnricher("SpokeName", () => GetRoleName().ToLower())
                .Enrich.FromLogContext()
                .Enrich.WithUtcTimestamp()
                .Enrich.WithMachineName()
                .Enrich.WithEnvironmentUserName()
                .Enrich.WithProcessId()
                .Enrich.WithProcessName()
                .Enrich.WithFuncEnricher("ThreadId", () => SystemInfo.CurrentThreadId)
                .Enrich.WithMemoryUsage()
                .Enrich.WithExceptionDetails()
                .WriteTo.Seq(SeqHost, apiKey: ApiKey, batchPostingLimit: BufferSize)
                .CreateLogger();
            _seqLogger.Information("SEQ Initialized");
        }

        public override void OnClose()
        {
            base.OnClose();
            _seqLogger.Information("SEQ Disposing");
            _seqLogger?.Dispose();
        }

        private static string GetSite()
        {
            return !string.IsNullOrWhiteSpace(Sitecore.Context.Site?.Name) ? Sitecore.Context.Site.Name : "N/A";
        }

        private static string GetRoleName()
        {
            var roleName = Sitecore.Configuration.Settings.GetSetting("CloudRoleNameFallback");

            return !string.IsNullOrWhiteSpace(roleName) ? roleName : "RoleName";
        }
    }
}
Explanation

Exception is added to the logging event using reflection (m_thrownException is a private field in log4net.spi.LoggingEvent).

// use reflection, because m_thrownException is private field in log4net.spi.LoggingEvent
FieldInfo ExceptionField = typeof(LoggingEvent).GetField("m_thrownException",
            BindingFlags.Public | BindingFlags.NonPublic | BindingFlags.Instance);
// ...
// call this to ensure exception details are added to logging platform
new LoggerConfiguration()
    // ...
    .Enrich.WithExceptionDetails()
// ...
Exception exception = null;
if (level >= LogEventLevel.Error)
{
    exception = ExceptionField.GetValue(loggingEvent) as Exception;
}
// log exception as well
log.Write(level, exception, message);

Performance is now better, because only a single Serilog instance is created. To achieve this, we use the ActivateOptions and OnClose appender lifecycle methods.

Context-Dependent Enrichers

The last variant is working, but if you need some context-dependent enrichers (e.g., log information about Sitecore or HTTP context), some information will be invalid. This is because BufferingAppenderSkeleton is used: enrichers are executed in SendBuffer when the buffer is collected, so the context information is different there. To avoid this, AppenderSkeleton should be used as the base class, while buffering should be implemented using Serilog Sink configuration (e.g., with SEQ: .WriteTo.Seq(SeqHost, apiKey: ApiKey, period: TimeSpan.FromSeconds(10));).

Conclusion

All these features are implemented in the SitecoreSerilog NuGet package. Sources for the package are on Github.

All the source change steps are provided in the Github Gist here.