Structured Logging with Seq and Serilog

A few years back, I picked up an old "unloved" business application for document handling, and brought it into the modern era. I completed some work on adding automated OCR, running as a service, and then started to enhance it well beyond its original capabilities, such as moving a manual letter creation and printing process into the application, and creating a fully automated letter generation and batch printing process, with support for use of a letter folding machine. 

The business rather enthusiastically responded to my efforts, and raised request upon request for enhancements and new functionality. I soon found that the application had been uplifted from a neglected web application to an all-singing, all-dancing service that the business relied upon.

I was working on the next iteration - uplifting the old ASP.NET 2.0 Web Forms web interface to a modern web client. The old web app used to directly manipulate files, but as I now had a Windows service that did all the "heavy lifting", I envisaged that we could pivot to an API workflow-based approach, where the API would accept the request, the service would work on the result, and the output could then be retrieved using the API. Since we were working with OCR, file conversion, and other 'expensive' operations, I wanted a fast and responsive experience for clients that didn't need to wait for completion.

As I already had many moving parts, and was about to open up even more, I wanted the logging to be rock solid. The application logging story in our various apps was relatively poor - where it existed, it was stuck in obscure text log files throughout the environment. Troubleshooting and debugging was difficult at best.

A colleague at the time directed me towards Seq, a structured logging server that is relatively inexpensive. In fact, a free single user license is built in, which makes it insanely easy to get up and running and start working on getting your logs into Seq. Topping it off, Serilog — simple .NET logging with fully-structured events is an open source library originally created by the developers of Seq.  It makes logging to multiple log sinks really simple, and - of course - one of those sinks can be Seq.

I was busily integrated email alerting as well and rather taken with the idea of fluent code. I was working with libraries like Flurl (and Flurl.Http) and FluentEmail, and I liked the idea of making my logging read in a similar way that integrated with the rest of my code in the common library.

I implemented logging in a class that wrapped Serilog into a somewhat 'Fluent-like' implementation - it doesn't chain so it's not strictly fluent - that allowed me to make calls like:

Logging.Log.Level().Add(Logging.appLogServiceState, Config.serviceName, serviceStarted, nlbStatus, Common.NLBStart);

Logging.Log.Level(LogStatus.Error).Add(Logging.appLogClusterNotFound, Config.targetCluster);

Logging.Log.Exception(ex).Add(Logging.appLogError, ex.Message);

This approach allowed me to do a few things, such as enforce setting a log level (if not specified, it's Information by default) or reflect an exception, capture the method name that sent the log entry, and control how/if the method name is output to the logs.

This was useful for my implementation, which allowed output to a rolling text log, Windows event log, console (using colored themes), and Seq. One or all methods could be enabled - so a console app might use console and text log, while a service or web interface might use text log, Windows event log, and Seq.  Each method works within its own limitations - so the console and text log will output just what the message template says, while Windows event log and especially Seq are capable of exposing more properties.

The code looks to make sure that each sink is appropriately configured and can be instantiated when the static Logging class is first instantiated. Equally - because I have a standard log interface - I can add a standard set of Serilog Enrichers which automatically capture environment information. That means that all we need to worry about is sending our log entries, and I'll get useful and meaningful logs in Seq, as shown below (I've blanked out a couple of lines).

I have been using the code for a number of years, but while writing this, I realised that I wasn't actually exposing the method and line number to Seq as properties... so I've added that and will use this enhancement as I move logging into its own common library. One of the faults of this implementation has been the need to 're-implement' it for subsequent applications. As responsibility for ongoing development has shifted, and I've moved on to the next thing, my improvements get captured in that "next thing" and rarely backported to the previous application. A common library would help with that, and also address issues such as updating of dependencies - I noticed while writing this that the Serilog Rolling File sink has been deprecated in favour of the Serilog File sink that now has that functionality.

This version of the logging class has its message templates embedded as readonly strings, but I often use resource files to store the template strings. I like not having strings throughout the code wherever possible.

Naturally there are many ways that you could implement Serilog, but this gives me a consistent implementation where logging, once configured, is as simple as a single method call that encapsulates all that I want to include.

We have come a long way on our journey with Seq, and I'll post more on that later - but Seq is nothing without logging, and this is one example of how to make that happen.

Note - There's a couple of errors in the below code because I updated it on the fly without testing, but I've moved on to my common logging library effort ... I'll post about Lurgle.Logging later.

using System;
using System.IO;
using System.Threading;
using System.Collections.Generic;
using System.Runtime.CompilerServices;
using Serilog;
using Serilog.Core;
using Serilog.Events;
using Serilog.Sinks.SystemConsole.Themes;


namespace NLBManager
{
    /// <summary>
    /// Supported log types
    /// </summary>
    public enum LogType
    {
        Console = 1,
        File = 2,
        EventLog = 4,
        Seq = 8,
        All = -1
    }

    /// <summary>
    /// Outlines the supported log levels. Abstracts Serilog's <see cref="LogEventLevel"/> so that it does not need to be referenced outside of the <see cref="Logging"/> class.
    /// </summary>
    public enum LogStatus
    {
        Fatal = LogEventLevel.Fatal,
        Error = LogEventLevel.Error,
        Warning = LogEventLevel.Warning,
        Information = LogEventLevel.Information,
        Debug = LogEventLevel.Debug,
        Verbose = LogEventLevel.Verbose

    }

    /// <summary>
    /// Logging class
    /// </summary>
    public static class Logging
    {
        private static Logger logWriter = null;
        private static readonly ReaderWriterLockSlim readWriteLock = new ReaderWriterLockSlim();

        public static readonly string dateTimeFormat = "dd-MMyyyy H:mm:ss";
        public static readonly string dateFormat = "dd-MM-yyyy";
        public static readonly string logFormatEvent = "({ThreadId}) {Message}{NewLine}{NewLine}{Exception}";
        public static readonly string logFormatFile = "{Timestamp:dd-MM-yyyy HH:mm:ss}: ({ThreadId}) [{Level}] {Message}{NewLine}";
        public static readonly string logFormatMessageOnly = "{Message:l}{NewLine}";
        public static readonly string logInitialise = "Initialising event sources ...";
        public static readonly string logApplication = "Application";
        public static readonly string logDate = "{Date}";
        public static readonly string fileNameLog = "{0}-{1}.log";
        public static readonly string logText = "[{0}] {1}";

        public static readonly string appLogServiceName = "Configured Service to watch: {ServiceName:l}, Running: {ServiceRunning}";
        public static readonly string appLogClusterName = "Configured Cluster to control: {ClusterName:l}, Cluster IP: {ClusterIp:l}, Current State: {NLBStatus}";
        public static readonly string appLogServiceState = "Service: {ServiceName:l}, Started: {ServiceStarted}, NLB Status: {NLBStatus}, Perform NLB Action: {NLBAction:l}";
        public static readonly string appLogServiceNotFound = "Service not found: {ServiceName:l}, Stopping ...";
        public static readonly string appLogClusterNotFound = "Target cluster not found: {ClusterName:l}, Stopping ...";
        public static readonly string appLogClusterIpNotFound = "Target cluster IP address not found: {ClusterName:l}, Stopping ...";
        public static readonly string appLogError = "Error: Exception {Exception:l}";
        public static readonly string appLogStart = "{Service:l} v{Version:l} Started";
        public static readonly string appLogStop = "{Service:l} v{Version:l} Stopped";
        public static readonly string appLogStopError = "{Service:l} v{Version:l} Stopped (Error: {Error})";
        public static readonly string appLogUnexpectedStatusCode = "Unexpected NLB status code: {StatusCode:l}";

        static Logging()
        {
            //Initialise email and loggings
            if (Config.doLog)
                Log.Init();
        }



        public static SystemConsoleTheme getConsoleTheme { get; } = new SystemConsoleTheme(
            new Dictionary<ConsoleThemeStyle, SystemConsoleThemeStyle>
            {
                [ConsoleThemeStyle.Text] = new SystemConsoleThemeStyle { Foreground = ConsoleColor.White },
                [ConsoleThemeStyle.SecondaryText] = new SystemConsoleThemeStyle { Foreground = ConsoleColor.Gray },
                [ConsoleThemeStyle.TertiaryText] = new SystemConsoleThemeStyle { Foreground = ConsoleColor.White },
                [ConsoleThemeStyle.Invalid] = new SystemConsoleThemeStyle { Foreground = ConsoleColor.Yellow },
                [ConsoleThemeStyle.Null] = new SystemConsoleThemeStyle { Foreground = ConsoleColor.Red },
                [ConsoleThemeStyle.Name] = new SystemConsoleThemeStyle { Foreground = ConsoleColor.Blue },
                [ConsoleThemeStyle.String] = new SystemConsoleThemeStyle { Foreground = ConsoleColor.Gray },
                [ConsoleThemeStyle.Number] = new SystemConsoleThemeStyle { Foreground = ConsoleColor.Cyan },
                [ConsoleThemeStyle.Boolean] = new SystemConsoleThemeStyle { Foreground = ConsoleColor.Green },
                [ConsoleThemeStyle.Scalar] = new SystemConsoleThemeStyle { Foreground = ConsoleColor.Magenta },
                [ConsoleThemeStyle.LevelVerbose] = new SystemConsoleThemeStyle { Foreground = ConsoleColor.Gray },
                [ConsoleThemeStyle.LevelDebug] = new SystemConsoleThemeStyle { Foreground = ConsoleColor.Gray },
                [ConsoleThemeStyle.LevelInformation] = new SystemConsoleThemeStyle { Foreground = ConsoleColor.White },
                [ConsoleThemeStyle.LevelWarning] = new SystemConsoleThemeStyle { Foreground = ConsoleColor.Yellow },
                [ConsoleThemeStyle.LevelError] = new SystemConsoleThemeStyle { Foreground = ConsoleColor.White, Background = ConsoleColor.Red },
                [ConsoleThemeStyle.LevelFatal] = new SystemConsoleThemeStyle { Foreground = ConsoleColor.White, Background = ConsoleColor.Red }
            });

        /// <summary>
        /// Provides an interface to log new events. If the application uses logging, you should call a <see cref="Close"/> on shutdown to flush and dispose the logWriter.
        /// </summary>
        public class Log : Attribute
        {
            private bool isMethod { get; set; }
            private string methodName { get; set; }
            private int lineNumber { get; set; }
            private LogStatus logLevel { get; set; }
            private Exception errorInfo { get; set; }

            public Log()
            {
                isMethod = true;
                methodName = string.Empty;
                logLevel = LogStatus.Information;
                errorInfo = null;
            }

            /// <summary>
            /// Flush logs and dispose the logging interface. Used for application shutdown. <para/>
            /// 
            /// If this is called and then an attempt is made to write to the log, the log will be automatically initialised again.
            /// </summary>
            public static void Close()
            {
                if (logWriter != null)
                    logWriter.Dispose();

                logWriter = null;
            }

            private static LoggerConfiguration getConfig()
            {
                return new LoggerConfiguration()
                            .Enrich.FromLogContext()
                            .Enrich.WithThreadId()
                            .Enrich.WithEnvironmentUserName()
                            .Enrich.WithMachineName()
                            .Enrich.WithProcessId()
                            .Enrich.WithProcessName()
                            .Enrich.WithProperty("AppName", Common.appName)
                            .Enrich.WithProperty("ServiceName", Config.serviceName)
                            .Enrich.WithProperty("TargetCluster", Config.targetCluster);
            }

            /// <summary>
            /// Initialise the logging interface. Checks that the configured log types are available.
            /// </summary>
            public static void Init()
            {
                LoggerConfiguration logConfig = null;
                bool manageSource = true;

                string logFolder = string.Empty;
                string fileName = string.Empty;

                List<LogType> logTypes = Config.logType;

                //If event log is enabled, test that we can create sources and/or write logs
                if (logTypes.Contains(LogType.EventLog))
                {
                    try
                    {
                        //First test whether we can create new event source .. should also work if the source exists
                        LoggerConfiguration testConfig = getConfig()
                            .WriteTo.EventLog(Common.appName, logApplication, ".", manageSource, logFormatEvent, null, LogEventLevel.Verbose);

                        Logger testWriter = testConfig.CreateLogger();
                        testWriter.Information(logInitialise);
                        testWriter.Dispose();
                    }
                    catch
                    {
                        manageSource = false;
                    }

                    //If we can't manage the source, can we still write an event log entry?
                    if (!manageSource)
                        try
                        {
                            LoggerConfiguration testConfig = getConfig()
                                .WriteTo.EventLog(Common.appName, logApplication, ".", manageSource, logFormatEvent, null, LogEventLevel.Verbose);

                            Logger testWriter = testConfig.CreateLogger();
                            testWriter.Information(logInitialise);
                            testWriter.Dispose();
                        }
                        catch
                        {
                            //Remove event log from the usable types and send an alert
                            logTypes.Remove(LogType.EventLog);
                        }
                }


                //If file is enabled, test that folder and file access is okay
                if (logTypes.Contains(LogType.File))
                {
                    bool isLog = true;

                    if (string.IsNullOrEmpty(logFolder) || !Directory.Exists(logFolder))
                    {
                        if (!string.IsNullOrEmpty(logFolder))
                            try
                            {
                                Directory.CreateDirectory(logFolder);
                            }
                            catch (Exception ex)
                            {
                                isLog = false;
                            }
                    }
                    else
                        try
                        {
                            fileName = Path.Combine(logFolder, string.Format(fileNameLog, Config.logName, logDate));

                            LoggerConfiguration testConfig = getConfig()
                                .WriteTo.RollingFile(fileName, Config.logLevelFile, logFormatFile, retainedFileCountLimit: Config.logMonths * 31,
                                shared: true, buffered: false, flushToDiskInterval: new TimeSpan(0, 0, 1));

                            Logger testWriter = testConfig.CreateLogger();
                            testWriter.Information(logInitialise);
                            testWriter.Dispose();
                        }
                        catch
                        {
                            isLog = false;
                        }


                    if (!isLog)
                    {
                        //Remove file from the usable types and send an alert
                        logTypes.Remove(LogType.File);
                    }
                }

                if (logTypes.Contains(LogType.Seq))
                    try
                    {
                        LoggerConfiguration testConfig = getConfig();

                        if (Config.isSeqApiKey)
                            testConfig.WriteTo.Seq(Config.logSeqServer, apiKey: Config.logSeqApiKey, compact: true);
                        else
                            testConfig.WriteTo.Seq(Config.logSeqServer, compact: true);


                        Logger testWriter = testConfig.CreateLogger();
                        testWriter.Information(logInitialise);
                        testWriter.Dispose();
                    }
                    catch
                    {
                        //Remove Seq from the usable types and send an alert
                        logTypes.Remove(LogType.Seq);
                    }

                //With all that out of the way, we can create the final log config
                if (logTypes.Count.Equals(0))
                    logConfig = null;
                else
                    logConfig = getConfig();

                if (logTypes.Contains(LogType.Console))
                    logConfig.WriteTo.Console(Config.logLevelConsole, logFormatMessageOnly, theme: SystemConsoleTheme.Literate);

                if (logTypes.Contains(LogType.File))
                    logConfig.WriteTo.RollingFile(fileName, Config.logLevelFile, logFormatFile,
                        retainedFileCountLimit: Config.logMonths * 31, shared: true, buffered: false, flushToDiskInterval: new TimeSpan(0, 0, 1));

                if (logTypes.Contains(LogType.EventLog))
                    logConfig.WriteTo.EventLog(Common.appName, logApplication, ".",
                        manageSource, logFormatEvent, null, Config.logLevelEvent);

                if (logTypes.Contains(LogType.Seq))
                {
                    if (Config.isSeqApiKey)
                        logConfig.WriteTo.Seq(Config.logSeqServer, apiKey: Config.logSeqApiKey);
                    else
                        logConfig.WriteTo.Seq(Config.logSeqServer);
                }

                if (logConfig != null)
                    logWriter = logConfig.CreateLogger();
                else
                {
                    logWriter = null;
                    Config.doLog = false;
                }
            }

            /// <summary>
            /// Instantiate a new <see cref="Log"/> class with the desired log level.<para/>
            /// 
            /// Logging will automatically be initialised if this is the first time this is called in the code, or if logging has been disposed by a call to <see cref="Close"/><para/>
            /// 
            /// This will automatically capture the calling method and add it to the log entry, unless showMethod is set to false.
            /// </summary>
            /// <param name="logLevel">Desired log level for this event</param>
            /// <param name="showMethod">Add the calling method to the log text</param>
            /// <param name="methodName"></param>
            /// <returns></returns>
            public static Log Level(LogStatus logLevel = LogStatus.Information, bool showMethod = true, [CallerMemberName] string methodName = null, [CallerLineNumber] int sourceLineNumber = 0)
            {
                if (Config.doLog && logWriter == null)
                    Init();

                return new Log() { logLevel = logLevel, isMethod = showMethod, methodName = methodName, lineNumber = sourceLineNumber };
            }

            /// <summary>
            /// Instantiate a new <see cref="Log"/> class with a <see cref="LogStatus.Error" /> log level, and pass the Exception into Serilog to handle."<para/>
            /// 
            /// Logging will automatically be initialised if this is the first time this is called in the code, or if logging has been disposed by a call to <see cref="Close"/><para/>
            /// 
            /// This will automatically capture the calling method and add it to the log entry, unless showMethod is set to false.
            /// </summary>
            /// <param name="ex">Exception to pass to Serilog</param>
            /// <param name="showMethod">Add the calling method to the log text</param>
            /// <param name="methodName">Automatically captures the calling method via [CallerMemberName]</param>
            /// <returns></returns>
            public static Log Exception(Exception ex, bool showMethod = true, [CallerMemberName] string methodName = null, [CallerLineNumber] int sourceLineNumber = 0)
            {
                if (Config.doLog && logWriter == null)
                    Init();

                return new Log() { logLevel = LogStatus.Error, isMethod = showMethod, methodName = methodName, lineNumber = sourceLineNumber, errorInfo = ex };
            }

            /// <summary>
            /// Add a new log entry using a log template that has no parameters
            /// </summary>
            /// <param name="logEntry"></param>
            public void Add(string logEntry)
            {
                string text;
                if (isMethod)
                    text = string.Format(logText, methodName, logEntry);
                else
                    text = logEntry;

                if (Config.doLog && logWriter != null)
                {                    
                    if (errorInfo != null)
                        logWriter.ForContext("MethodName", methodName).ForContext("LineNumber", lineNumber).Write((LogEventLevel)logLevel, errorInfo, text);
                    else
                        logWriter.ForContext("MethodName", methodName).ForContext("LineNumber", lineNumber).Write((LogEventLevel)logLevel, text);
                }
            }

            /// <summary>
            /// Add a new log entry and apply parameters to the supplied log template
            /// </summary>
            /// <param name="logTemplate">Log template that parameters will be applied to</param>
            /// <param name="args">Parameters for the log template</param>
            public void Add(string logTemplate, params object[] args)
            {
                string text;
                if (isMethod)
                    text = string.Format(logText, methodName, logTemplate);
                else
                    text = logTemplate;

                if (Config.doLog && logWriter != null)
                {
                    if (errorInfo != null)
                        logWriter.ForContext("MethodName", methodName).ForContext("LineNumber", lineNumber).Write((LogEventLevel)logLevel, errorInfo, text, args);
                    else
                        logWriter.ForContext("MethodName", methodName).ForContext("LineNumber", lineNumber).Write((LogEventLevel)logLevel, text, args);
                }
            }
        }