Lurgle.Logging - a standardised Serilog implementation with extra goodies!

Logging is important

Logging is a really important, oft-neglected, aspect of business applications. I can't state that enough. If you don't have good logging, you can't troubleshoot and debug problems, and you have little chance of seeing what's actually going on in your enterprise. 

In Structured Logging with Seq and Serilog, I gave an example of a Serilog implementation, which I updated for a couple of features and changes while writing the post. Unfortunately I didn't test those changes, so I freely acknowledge there were errors.

When I first started with Serilog and Seq, I created an implementation that served the purposes of the application that I was uplifting while also targeting a Seq POC - and it did give us a lot of benefits. A standardised implementation means that you don't have to think about logging unless you want to expand on features - you just focus on "should I create a log for this?" (in general - if you need to ask the question, the answer is probably yes).

The problem arose when I moved on to the next application. I'd made a logging class I was happy with, so of course I carried it over - with a new copy of the class, updated to suit the application. And I did update it - I needed additional features over time to suit the application. Those new features didn't necessarily carry back to the original implementation. And then I moved to the next application, and ... well, you get the idea.

So you can easily fall into a trap when it comes to logging implementation, even as a "one man Dev team". It gets worse when you bring other developers into the mix, because everyone has their own ideas and implementations.

Fundamentally, if you want to drive a mandate of application logging to a logging server like Seq, and especially benefit from structured logging, you need some rules. For example-

1. All apps will log to Seq
2. Logging must provide standardised properties like AppName, MethodName, and so on, to support a structured logging approach
3. Logging must be detailed and informative, with exceptions passed to the logging server
4. Logging must mask Personally Identifiable Information (PII)
5. Logging must be able to pass or generate a correlation Id
6. Logging must have a common implementation that can be updated with minimal code change

and so on. 

I mentioned in my Structured Logging post that I was creating a common log library. This affords the prospect of both keeping my own app logging implementations up to date if and when I add new features, as well as providing the ability for all developers in my workplace to use the same standardised implementation.

The result is Lurgle.Logging.

Lurgle the logs

Lurgle is a nonsense word that I plucked out of thin air, because names are hard and not really that important in this case. It just needed a name.

Simply put - Lurgle.Logging is a standardised implementation of Serilog, with some extra features and capabilities. It implements Serilog and the Console, File, Event Log, and Seq sinks. It's not a replacement to Serilog, but it does provide a way to get up and running quite easily.

In terms of sinks, people will typically implement those that they need and have access to. My biggest need is Seq logging, which of course I have access to, but I could add other sinks as or when needed.

Typically to get up and running with Serilog, you would have to install Serilog and any sinks that you want. You'd also install any enrichers desired, and you'd wire Serilog into your implementation in the way that you want. And then you'd do the same in your next app, and the next, and so on. 

Lurgle.Logging does away with that as a simple way to get a Serilog implementation up and running. It implements several sinks and enrichers:

• Serilog.Enrichers.Environment
• Serilog.Enrichers.Memory
• Serilog.Enrichers.Process
• Serilog.Enrichers.Thread
• Serilog.Sinks.Console (configured with colored/literate console themes)
• Serilog.Sinks.EventLog
• Serilog.Sinks.File (configured as a rolling log implementation)
• Serilog.Sinks.Seq

It also internally implements

• an adaptation of the Property Bag Enricher from Serilog Best Practices
• a Masking Enricher
• a Correlation ID pass through/generation scheme

The overarching goal is that Lurgle logs are predictable with some good structured properties before you even contemplate what else you might want to send to the logs. Below is a sample of what Lurgle.Logging brings to the table, from Seq:

If all your applications passed this level of detail, you might imagine how much easier it could be to troubleshoot and debug events. It also simplifies creating targeted signals and benefits alerts that you might want to send - for example to email, OpsGenie, Jira, or Service Now.

Lurgle a clean initialisation

Generally speaking, Serilog swallows errors that occur while logging, and that's overall true. That's generally a "good" thing because logging isn't bringing your application down. It's not strictly true for all cases though; it will generate exceptions during initialisation in certain cases, and for Seq - you might not know why you're not receiving events.

Lurgle.Logging aims to resolve that by first checking the configured sinks. A great example is the Event Log sink; it can try to create an event source, and if your process has sufficient permissions, it will do so. If not, it will still try to generate logs with that source, and when it fails - exception. Similarly with a misconfigured file log.

So if an exception occurs during initialisation, Lurgle swallows that - but stores a FailureReason in the static Logging.LogFailures dictionary. The logs that were successfully initialised are visible as a LogType in the Logging.EnabledLogs list.

This provides opportunity to review and handle logging problems in the code. If no logging is available, for example, you might send an alert.

In my original implementation, the code always wrote an "Initialising event sources" event to any enabled log as part of the test. That's not strictly necessary, so I've made that an optional config that is disabled by default.

Lurgle your config

A lot of apps in our environment still use the App.Config approach to store configurations, especially for things like logging and alerts. I've implemented it in Lurgle.Logging, so if you specify the appropriate config in your app.config, it will happily read that in ... but I also haven't locked that in as a mandatory approach.

Lurgle.Logging provides the Logging.SetConfig method to configure your logging, with a constructor on the LogConfig class that allows you to pass any property. For example, in a console app I have a fallback that ensures logging to console will always be configured if no other config exists:

            if (Logging.Config == null)
            {
                var logConfig = new LoggingConfig(appName: Common.AppName, appVersion: Common.AppVersion,
                    logType: new List<LogType> {LogType.Console}, logLevel: LurgLevel.Verbose,
                    logLevelConsole: LurgLevel.Verbose);

                Logging.SetConfig(logConfig);
            }

Lurgle.Logging provides defaults for many settings, so that you only have to supply the essential settings for the logging that you want. 

At its simplest, you can add Lurgle.Logging to a project and configure App.Config to your own needs.

Lurgle.Logging has a prescriptive approach to Serilog implementation, so it compensates by exposing a lot of configurability. Here's the App.Config from the LurgleTest app that I use for adhoc tests;

<?xml version="1.0" encoding="utf-8"?>

<configuration>
  <appSettings file="C:\Users\mattm\source\repos\Lurgle.Logging\LurgleTest\secrets.config">
    <!-- Automatically add the calling method name as a property-->
    <add key="EnableMethodNameProperty" value="true" />
    <!-- Automatically add the source file path as a property-->
    <add key="EnableSourceFileProperty" value="true" />
    <!-- Automatically add the line number as a property-->
    <add key="EnableLineNumberProperty" value="true" />
    <!-- Automatically write an "Initialising" event during Init -->
    <add key="LogWriteInit" value="false"/>
    <!-- Meaningful name that will be used as the app name for logging purposes -->
    <add key="AppName" value="LurgleTest" />
    <!-- logType is a comma separated list that can target Console, File, EventLog, and Seq -->
    <add key="LogType" value="Console,File,EventLog,Seq" />
    <!-- Properties that should automatically be masked -->
    <add key="LogMaskProperties" value="Password,Email,Mechagodzilla,Testcommonmask,testcommonmask2" />
    <!-- Define the applicable policy for masking - None, MaskWithString, MaskLettersAndNumbers -->
    <add key="LogMaskPolicy" value="MaskWithString" />
    <!-- Mask pattern to use when masking properties -->
    <add key="LogMaskPattern" value="XXXXXX" />
    <!-- Define the mask character to use for non-digit values in masking if MaskLettersAndNumbers is used -->
    <add key="LogMaskCharacter" value="X" />
    <!--  Define the mask character to use for digit values in masking if MaskLettersAndNumbers is used -->
    <add key="LogMaskDigit" value="*" />
    <!-- Theme for the console - Literate, Grayscale, Colored, AnsiLiterate, AnsiGrayscale, AnsiCode -->
    <add key="LogConsoleTheme" value="Literate" />
    <!-- Location for the file log -->
    <add key="LogFolder" value="C:\TEMP\TEMP\log" />
    <!-- Prefix for the file log name, hyphen and date will be appended -->
    <add key="LogName" value="Lurgle" />
    <!-- Extension for the file log name, defaults to .log-->
    <add key="LogExtension" value=".log" />
    <!-- For the Windows Event Log, the event source name-->
    <add key="LogEventSource" value="LurgleTest" />
    <!-- For the Windows Event Log, the destination log (eg. Application) -->
    <add key="LogEventName" value="Application" />
    <!-- Format for log files - Text or Json. Json will not use LogFormatFile to format messages -->
    <add key="LogFileType" value="Json" />
    <!-- LogDays controls how many days log files will be retained, default is 31 -->
    <add key="LogDays" value="31" />
    <!-- LogFlush controls how many seconds before log file writes are flushed to disk -->
    <add key="LogFlush" value="5" />
    <!-- Allow the log file to be shared by multiple processes. Cannot be enabled with LogBuffered = true -->
    <add key="LogShared" value="false" />
    <!-- Allow the log file to be buffered. Cannot be used with LogShared = true -->
    <add key="LogBuffered" value="false" />
    <!-- Minimum LogLevel that can be written - Verbose, Debug, Information, Warning, Error, Fatal-->
    <add key="LogLevel" value="Verbose" />
    <!-- Set minimum log level for the individual sink - Verbose, Debug, Information, Warning, Error, Fatal -->
    <add key="LogLevelConsole" value="Verbose" />
    <add key="LogLevelFile" value="Verbose" />
    <add key="LogLevelEvent" value="Warning" />
    <add key="LogLevelSeq" value="Verbose" />
    <!-- Seq server URL, eg. https://seq.domain.com -->
    <add key="LogSeqServer" value="" />
    <!-- Seq API key - if blank, no API key will be used-->
    <add key="LogSeqApiKey" value="" />
    <!-- Log formats -->
    <add key="LogFormatConsole" value="{Message}{NewLine}" />
    <add key="LogFormatEvent" value="({ThreadId}) {Message}{NewLine}{NewLine}{Exception}" />
    <add key="LogFormatFile" value="{Timestamp:yyyy-MM-dd HH:mm:ss}: ({ThreadId}) [{Level}] {Message}{NewLine}" />
  </appSettings>
</configuration>

Mask your Lurgle

I mentioned that Lurgle.Logging has a masking enricher, and you can see this in action in the LurgleTest app, where I modify the config while running to switch to different policies. 

//Add masked properties for test
            Logging.Close();
            Logging.SetConfig(new LoggingConfig(Logging.Config, logMaskPolicy: MaskPolicy.MaskWithString));
            Logging.AddCommonProperty("TestCommonMask", "mask1234");
            Log.Level().AddProperty("Mechagodzilla", "Godzilla").AddProperty("password", "godzilla")
                .Add("Testing masking properties, send complaints to {Email:l}", "[email protected]");
            //Switch masked properties to use MaskPolicy.MaskLettersAndNumbers, allow init event to be logged
            Logging.Close();
            Logging.SetConfig(new LoggingConfig(Logging.Config, logWriteInit: true, logMaskPolicy: MaskPolicy.MaskLettersAndNumbers));
            Logging.AddCommonProperty("TestCommonMask2", "mask1234");
            Logging.Init();
            Log.Level().AddProperty("Mechagodzilla", "Godzilla123").AddProperty("password", "godzilla123").Add(
                "Testing masking properties, send complaints to {Email:l}", "[email protected]");

The result is shown below.

• MaskPolicy.MaskWithString masks any matching property with the configured string, which in LurgleTest is XXXXXX.
• MaskPolicy.MaskLettersAndNumbers masks any matching property by replacing characters with a configured character for letters and another for digits.

This implementation does not currently destructure properties, but it's an enhancement to contemplate for future updates.

Lurgle your property

You might note from the above example that there is a Logging.AddCommonProperty method, and a SetProperty method within the logging call.

AddCommonProperty is more or less equivalent to Serilog's .Enrich.WithProperty implementation, but can be called at any time to add a property that will be added to all log events going forward. You can also clear the Common Properties with Logging.ResetCommonProperties.

SetProperty is directly equivalent to Serilog's ForContext implementation. Wrapping an implementation around Serilog is all well and good, but missing out on the ability to add a property to any log event would be poor - so in implementing Lurgle.Logging, I made a Fluent implementation that would allow properties to be added at will. 

Correlate your Lurgles

I mentioned that there is a Correlation ID pass through and generation scheme. By default, Lurgle.Logging will generate a correlation id and carry it through all logging for persistence - but you don't have to do it that way.

At any point you can specified a correlation id - either one that you have passed through from elsewhere, or by generating a new one. This is part of the Level method that accompanies your typically Lurgle.Logging implementation. For example:

Log.Level(LurgLevel.Debug, Logging.NewCorrelationId()).Add("Enabled Log List (Switch CorrelationId):");

This creates a new correlation id as part of the debug log, and will carry it forward from there.  You could also ensure that the correct correlation Id is always passed by specifying it within Level.

Log.Level(correlationId: corrId).Add("Stuff happened.");

You can't specify it for the simple Log.Add implementation that simply logs an information event, but a call to Logging.SetCorrelationId or even Logging.NewCorrelationId will allow for that.

Lurgle the Calling Methods, Source File Path, and Line Number

One of the reasons for the existence of the Level method in the Log calls is to allow us to always catch the method that is calling the log. In Lurgle.Logging, I also added the source file path and line number. All of these can make debugging and troubleshooting much simpler - it's context that is invaluable to your logging.

Level allows you to specify the LurgLevel (log level), correlationid, and optionally set Lurgle.Logging to prepend the calling method to your log entries. The default log level is LurgLevel.Information, so if you want to log an informational event, you can simply pass:

Log.Level().Add("Stuff happened - {Stuff}", stuff);

or because it is a simple Information event, you can bypass Level and just use the simple Log.Add call which is a static implementation of an Information log that also captures the method, source file path, and line number.

Log.Add("Stuff happened - {Stuff}", stuff);

Of course, there's also an implementation for passing exceptions:

Log.Exception(ex).Add("Bad stuff happened with {Stuff} - {badstuff}", stuff, ex.Message);

Lurgle your console apps

You might appreciate that there's an awful lot to Lurgle.Logging, and many ways that you could implement it, but I wanted to close off by sharing a practice that I've made standard  for any console app that I create. I don't use Console.WriteLine - I write logs, and configure the Literate console theme for Serilog.

This means that I can simultaneously output to logging while writing to the console, and I can see what a given log property is at a glance. For example the LurgleTest output:

Much better than the typical gray text, and I'm simultaneously capturing those logs with all the extra structured properties to Seq and a Json log file.

Lurgling Around - Get Lurgle.Logging!

Lurgle.Logging is available from Nuget and the code is on Github. I've been updating and improving it as I go. It's not necessarily a must have, but it might provide some with a straightforward way to get logging into your applications, and perhaps even benefit from the extra goodies. Obviously you could still simply wire up your own Serilog implementation - perhaps some ideas from Lurgle.Logging could be of use.