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

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:

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;

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!