J4JLogger: A Serilog Wrapper that Provides Source Code Information

Introduction

I love Serilog and use it in all of my projects. But out of the box, it doesn't have the capability to log source code information (e.g., source file, calling method, line number) of a logged event. J4JLogger is a Serilog wrapper which does that.

It also offers a way of sending log events via SMS (useful for truly serious problems). While currently only a Twilio provider is included, adding additional providers for other SMS libraries is straightforward.

Finally, J4JLogger provides a caching logger suitable for use as a logging target before the "real" logging system is set up (e.g., during construction of an IHost by IHostBuilder). The cached entries can be dumped into the logging system once it's established, providing information which can be useful when debugging startup problems.

You can find more documentation on J4JLogger's Github page.

Background

When I'm writing -- and debugging! -- code I generally like to be able to go directly to places that are causing problems. Since I almost always include logging, looking over the log events would be a good place to start... but, out of the box Serilog doesn't offer a way to include that information.

One approach to including it might be to write an enricher, which in the Serilog world lets you insert additional information into the logging process. But the real challenge is to acquire the information in the first place. It would be very tedious to have to specify method call names, source code file names and line numbers in all your logging calls. It'd also be easily breakable since the names and numbers change a lot over the course of development.

There is a better way: the C# compiler lets you automagically include that information in any method call if you include certain arguments, decorated with specific attributes and assigned specific default values, in the parameter list. Here's an example:

public void Write( 
     LogEventLevel level, 
     string template, 
     [CallerMemberName] string memberName = "", 
     [CallerFilePath] string srcPath = "",
     [CallerLineNumber] int srcLine = 0 );

When you call this method information about the context of where the method was called -- the name of the calling member, the path of the source code file and the line number of the call -- are available within the Write() method. That's the information J4JLogger includes in the log events.

This can, in some cases, require a slight change from the "Serilog Way" of calling its various methods. The issue arises because many of the Serilog logging methods include generic parameters which can be mistaken by the compiler for memberName, srcPath and/or srcLine.

Consider the following method, augmented to include those additional contextual parameters:

public void Error<T0>( 
    string template, 
    T0 propertyValue,
    [CallerMemberName] string memberName = "",
    [CallerFilePath] string srcPath = "",
    [CallerLineNumber] int srcLine = 0);

If you were to log something involving a string parameter:

_logger.Error( "This is a Serilog template with a parameter '{0}'", "some text");

the compiler would have no idea if "some text" was propertyValue or memberName.

To avoid that ambiguity, you have to call the method like this:

_logger.Error<string>( "This is a Serilog template with a parameter '{0}'", "some text");

Now the compiler knows "some text" is propertyValue, as you intended.

This issue doesn't always arise. It generally does when the first parameter is a string.

Using the Code

There are a number of ways to set up J4JLogger (check the Github page for details). Here's one that uses Serilog's IConfiguration-based add on library:

using System;
using System.IO;
using System.Linq;
using System.Runtime.CompilerServices;
using J4JSoftware.Logging;
using Microsoft.Extensions.Configuration;
using Serilog;

namespace ConfigurationBasedExample
{
    // shows how to use J4JLogger with a configuration file
    // see the ConfigurationBasedExample project for other files and details
    class Program
    {
        static void Main(string[] args)
        {
            var loggerConfig = new J4JLoggerConfiguration();

            var configRoot = new ConfigurationBuilder()
                .AddJsonFile( Path.Combine( Environment.CurrentDirectory, 
                              "appConfig.json" ), true )
                .Build();

            loggerConfig.SerilogConfiguration
                .ReadFrom
                .Configuration( configRoot );

            var logger = loggerConfig.CreateLogger();
            logger.SetLoggedType(typeof(Program));

            logger.Information("This is an Informational logging message");
            logger.Fatal("This is a Fatal logging message");
        }
    }
}

You can see what the console output looks like this on the Github site. The log file looks like this:

2021-09-15 10:14:59.173 -07:00 [INF] This is an Informational logging message 
ConfigurationBasedExample.Program::Main 
(C:\Programming\J4JLogging\examples\ConfigurationBasedExample\Program.cs:32) 
2021-09-15 10:14:59.238 -07:00 [FTL] This is a Fatal logging message 
ConfigurationBasedExample.Program::Main 
(C:\Programming\J4JLogging\examples\ConfigurationBasedExample\Program.cs:33) 

Additional Features

SMS Messages

Occasionally, I find I want immediate notification of certain log events (e.g., if something goes wrong with a running service I depend on). To accommodate that use case, I added the ability to send log events as SMS messages.

To do that, you have to add a Serilog sink to the logger which interfaces between Serilog and an SMS service. The library includes a sink which works with Twilio. But you can add others, it's not hard (check the Github documentation for details).

The SMS feature is triggered by adjusting the logger's SmsHandling property. That can be done either by setting it or via the following convenience methods:

public void SendNextEventToSms() => SmsHandling = SmsHandling.SendNextMessage;
public void SendAllEventsToSms() => SmsHandling = SmsHandling.SendUntilReset;
public void StopSendingEventsToSms() => SmsHandling = SmsHandling.DoNotSend;

I generally use the SMS capability on a message-by-message basis (i.e., SendNextMessage) so as not to overload my SMS inbox. SendNextMessage will send the very next log event, and only the very next log event, to all Serilog SMS sinks.

Caching Logger

I'm a big fan of Microsoft's IHostBuilder/IHost API. It lets you configure an app at startup in a developer-defined way and then hand off execution to whatever method you've declared as being the run-time agent. It supports using the IConfigurationBuilder/IConfiguration API and dependency injection. In my projects, I often use it to set up the J4JLogging subsystem.

Given the complexity of most startup routines, it would be convenient to log events during intialization so that problems could be researched. Unfortunately, trying to do so simply by using J4JLogger (or any other logger, I suspect) creates a chicken-and-egg problem: you can't log to a logger that hasn't yet been configured and built.

My approach to working around this was to define a special version of J4JLogger, J4JCachedLogger, which does not wrap a Serilog logger. In fact, it doesn't emit any log events at all. Instead, it stores them in memory until such time as the "real" logger is set up. At which point you can dump all the cached log events to J4JLogger by calling the following method:

public abstract bool OutputCache( J4JCachedLogger cachedLogger );

As implemented in J4JLogger, this method writes all the cached events to the log in the order they were created (in J4JCachedLogger, the implementation does nothing, since the events are already in the cache).

This isn't a complete solution to the chicken-and-egg problem because if initialization fails before the J4JLogger instance is set up, there's nothing to emit the cached events to. I'm working on providing an alternative way of viewing/outputting those cached events for that kind of situation.

Plain Old Events

I sometimes have a need to display log message, or a subset of them, in a UI. To simplify that, I added a C# event to IJ4JLogger which you can listen to:

event EventHandler<NetEventArgs>? LogEvent;

NetEventArgs is a simple class that merely echos a logged event:

public class NetEventArgs
{
    public NetEventArgs( LogEventLevel level, string mesg )
    {
        Level = level;
        LogMessage = mesg;
    }

    public LogEventLevel Level { get; }
    public string LogMessage { get; }
}

Note that you won't receive any events unless you add NetEventSink to your Serilog configuration. The easiest way to do this is to use the provided extension method (which is called on an instance of J4JLoggerConfiguration, not the underlying Serilog configuration object):

public static LoggerConfiguration NetEvent(
    this J4JLoggerConfiguration loggerConfig,
    string outputTemplate = NetEventSink.DefaultTemplate,
    LogEventLevel restrictedToMinimumLevel = LogEventLevel.Verbose
)

You can provide your own Serilog output template and a minimum event level to report when you do.

History

• 1^st October, 2021: Added material on listening to log events via C# events
• 30^th September, 2021: Added additional details and lessons learned
• 29^th September, 2021: Initial publication on CodeProject