Lurgle.Logging v1.2.0 - Multi-threaded correlation ids are now a thing

Table of Contents

Multi-threaded correlation ids were not a thing

Following on from my work on Seq.Client.WindowsLogins and the subsequent realisation that EventLog's EntryWritten event handler is bad and should feel bad, I contemplated whether I could apply some of my efforts to solve another issue that had been bugging me.

Lurgle.Logging was built to handle correlation ids - whether generating a correlation id, or passing one through from another app. The thing that bugged me, though, was that the correlation id was static in nature. By default, Lurgle.Logging would generate a new correlation id at initialisation, and then carry that until either your app closed or a new correlation id was generated.

You could compensate for that by passing a new correlation id to Log.Level() or using Logging.NewCorrelationId(), but in practice, this meant that in a given thread, you had to keep track of your correlation id while you wanted it, and always pass it through to Lurgle.

This would essentially mean code that looked like:

            var corrId = Logging.NewCorrelationId();
            Log.Level(correlationId: corrId).Add("Here is my log entry");
            Log.Level(LurgLevel.Error, corrId).Add("Oh no! An error!");
            Log.Level(correlationId: corrId).Add("Phew ... moment passed");

and for multi-threaded apps, you had no choice. You simply had to do this, because Lurgle didn't adequately manage multiple threads.

Adding the Correlation Cache

Working on Seq.Client.WindowsLogins had caused me to do some work with implementing caching, and it seemed readily apparent that we could apply this to Lurgle.Logging. 

The idea was that each thread that calls Log.Level() could have its own correlation id. We need to therefore track each thread's correlation id, but threads can naturally end and so we don't want to track it forever.

So the fundamental requirements:

  1. Per-thread implementation of correlation id
  2. An in-memory cache of correlation ids, linked to thread id
  3. A configurable expiry time for the cache, with a default
  4. An ability to enable/disable the caching behaviour

The result is the Correlation Cache, which is exposed as Logging.Cache. This cache initialises when logging is initialised, unless the cache has been disabled. 

Lurgle.Logging will, by default, create a new correlation id (or store the correlation id that you pass) for each thread that calls Log.Level(). This correlation id will persist for the configured amount of seconds - by default, 600 seconds (10 minutes) - after logging has been seen from that thread. This is a sliding interval, so while new log entries are being added from a given thread, the expiry interval will slide back. 

This makes for a flexible multi-threaded correlation id scheme. Your multi-threaded application will consistently use the same correlation id for a thread, until you switch it or it's no longer needed. 

Configuring the cache

Configuring the cache is done via two new configuration entries:

ConfigurationDefaultDescription
LoggingConfig.EnableCorrelationCachetrueDisabling this will revert Lurgle.Logging to the static correlationid behaviour
LoggingConfig.CorrelationCacheExpiry600Defaults to 10 minutes

In short - to enable this, you don't need to do anything; it's on by default, but you can disable it if needed, and if 10 minutes isn't enough, you can increase it.

The 10 minute default is pretty generous, but if you have threads that may log less frequently, you might want to increase this. 

And, of course, these configs can be reflected in your App.Config:

    <add key="EnableCorrelationCache" value="true"/>
    <add key="CorrelationCacheExpiry" value="600"/>

Managing the cache

Generally, Lurgle manages the cache itself, and you shouldn't need to do anything. I've implemented properties and methods for interacting with the cache, though, and they are as follows;

Property/MethodDescription
Logging.Cache.CountThe current count of all thread id:correlation id pairs in the cache
Logging.Cache.Add(int threadId, string correlationId)Add a thread id and correlation id to the cache
Logging.Cache.Replace(int threadId, string correlationId)Replace an existing thread id:correlation id pair in the cache, or add a new one
Logging.Cache.Remove(int threadId)Remove a given thread id and its correlation id from the cache
Logging.Cache.Get(int threadId)Retrieve the given thread id's correlation id from the cache
Logging.Cache.Contains(int threadId)Returns true if the given thread id is in the cache
Logging.Cache.Clear()Clear all thread id:correlation id pairs from the cache

Implementing Multi-Threaded Lurgles

If we revisit my example from earlier, we'll see a much simpler implementation for multi-threaded code;

          Log.Level().Add("Here is my log entry");
          Log.Level(LurgLevel.Error).Add("Oh no! An error!");
          Log.Level().Add("Phew ... moment passed");
  Log.Level(correlationId: Logging.NewCorrelationId()).Add("After all that, I'd really like a different correlation id");
  Log.Level(LurgLevel.Debug).Add("CorrelationId is {CorrelationId}");

You can see from the added lines that we've retained the ability to pass a correlation id - in this case, by generating a new one - but instead of updating the static Logging.CorrelationId property, we now add or replace it in the cache, where it will stay while you're still using it. 

We do retain an ability to use the static correlation id if LoggingConfig.EnableCorrelationCache is set to false, but this really only suits single threaded applications, and there is no harm in using the correlation cache for that scenario. 

Render unto me your Lurgles (Get v1.2.0 now!)

As usual, Lurgle.Logging is available via Nuget, and these fancy looking links!

 

Comments

You may also like:

Lurgle.Logging v1.2.2 - Destructure and mask structured properties!

Update After the original post, I tackled another item I'd been meaning to look at - being able to configure proxy settings for the Serilog Seq sink. Lurgle.Logging v1.2.3 now includes additional optional configurations for the Seq sink's proxy. This is particularly useful for console apps like Seq Reporter,...

Lurgle.Alerting v1.2.0 released - Consistent attachment content types!

I've released a small update to Lurgle.Alerting which adds automatic determination of the attachment content type using the MimeMapping library. I've raised the version to v1.2.0 to align with Lurgle.Logging's current releases. This specifically addresses an issue when sending attachments with MailKit as the SMTP sender. The FluentEmail implementation was...

Lurgle.Alerting v1.1.10 and Lurgle.Logging v1.1.15 Released

I've just pushed out an update to Lurgle.Alerting on Nuget. This release adds a Handlebars template option, based on the implementation by Matthew Turner at FluentEmail.Handlebars (github.com). When I came across the FluentEmail.Handlebars package, I was keen to use it, but it was only compiled against .NET Standard 2.1, and...