Logger Wrapper Best Practice

Logger wrapper best practice

I used to use logging facades such as Common.Logging (even to hide my own CuttingEdge.Logging library), but nowadays I use the Dependency Injection pattern. This allows me to hide loggers behind an application-defined abstraction that adheres to both Dependency Inversion Principle and the Interface Segregation Principle (ISP) because it has one member and because the interface is defined by my application; not an external library.

Minimizing the knowledge that the core parts of your application have about the existence of external libraries, the better; even if you have no intention to ever replace your logging library. The hard dependency on the external library makes it more difficult to test your code, and it complicates your application with an API that was never designed specifically for your application.

This is what the abstraction often looks like in my applications:

public interface ILogger
{
    void Log(LogEntry entry);
}

public sealed class ConsoleLogger : ILogger
{
    public void Log(LogEntry entry)
}

public enum LoggingEventType { Debug, Information, Warning, Error, Fatal };

// Immutable DTO that contains the log information.
public struct LogEntry
{
    public LoggingEventType Severity { get; }
    public string Message { get; }
    public Exception Exception { get; }

    public LogEntry(LoggingEventType severity, string msg, Exception ex = null)
    {
        if (msg is null) throw new ArgumentNullException("msg");
        if (msg == string.Empty) throw new ArgumentException("empty", "msg");

        this.Severity = severity;
        this.Message = msg;
        this.Exception = ex;
    }
}

Optionally, this abstraction can be extended with some simple extension methods (allowing the interface to stay narrow and keep adhering to the ISP). This makes the code for the consumers of this interface much simpler:

public static class LoggerExtensions
{
    public static void Log(this ILogger logger, string message) =>
        logger.Log(new LogEntry(LoggingEventType.Information, message));

    public static void Log(this ILogger logger, Exception ex) =>
        logger.Log(new LogEntry(LoggingEventType.Error, ex.Message, ex));

    // More methods here.
}

Because the interface contains just a single method, it becomes easily to create an ILogger implementation that proxies to log4net, to Serilog, Microsoft.Extensions.Logging, NLog or any other logging library and configure your DI container to inject it in classes that have a ILogger in their constructor. It is also easy to create an implementation that writes to the console, or a fake implementation that can be used for unit testing, as shown in the listing below:

public class ConsoleLogger : ILogger
{
    public void Log(LogEntry entry) => Console.WriteLine(
      $"[{entry.Severity}] {DateTime.Now} {entry.Message} {entry.Exception}");
}

public class FakeLogger : List<LogEntry>, ILogger
{
    public void Log(LogEntry entry) => this.Add(entry);
}

Having static extension methods on top of an interface with a single method is quite different from having an interface with many members. The extension methods are just helper methods that create a LogEntry message and pass it through the only method on the ILogger interface. These extension methods themselves contain no Volatile Behavior of themselves and, therefore, won't hinder testability. You can easily test them if you wish, and they become part of the consumer's code; not part of the abstraction.

Not only does this allow the extension methods to evolve without the need to change the abstraction, the extension methods and the LogEntry constructor are always executed when the logger abstraction is used, even when that logger is stubbed/mocked. This gives more certainty about the correctness of calls to the logger when running in a test suite. I've shot myself in the foot with this many times, where my calls to the used third-party logger abstraction succeeded during my unit test, but still failed when executed in production.

The one-membered interface makes testing much easier as well; Having an abstraction with many members makes it hard to create implementations (such as mocks, adapters, and decorators).

When you do this, there is hardly ever any need for some static abstraction that logging facades (or any other library) might offer.

Still, even with this ILogger design, prefer designing your application in such way that only a few classes require a dependency on your ILogger abstraction. This answer talks about this in more detail.

Implementation and usage of logger wrapper for Microsoft.Extensions.Logging

So, my question is what is the proper way to create implementation that proxies to Microsoft.Extensions.ILogger?

you should create something like:

public sealed class MicrosoftLoggingAdapter  : ILogger
{
    private readonly Microsoft.Extensions.ILogger adaptee;

    public MicrosoftLoggingAdapter (Microsoft.Extensions.ILogger adaptee) =>
        this.adaptee = adaptee;

    public void Log(LogEntry e) =>
        adaptee.Log(ToLevel(e.Severity), 0, e.Message, e.Exception, (s, _) => s);       

    private static LogLevel ToLevel(LoggingEventType s) =>
        s == LoggingEventType.Debug ? LogLevel.Debug  :
        s == LoggingEventType.Information ? LogLevel.Information :
        s == LoggingEventType.Warning ? LogLevel.Warning :
        s == LoggingEventType.Error ? LogLevel.Error :
        LogLevel.Critical;      
}

what is the best way to use it later in the code?

If you are using a DI container, then just use the DI container to map ILogger to MicrosoftLoggingAdapter. You also need to register Microsoft.Extensions.ILogger, or just give an instance of MS logger to the DI container to inject it to the MicrosoftLoggingAdapter constructor.

If you don't use a DI container, i.e., you use Pure DI, then you do something like this:

var logger = loggerFactory.CreateLogger("Application");

ILogger logging_adapter = new MicrosoftLoggingAdapter(logger);

var myobject = new MyClass(other_dependencies_here, logging_adapter);

Implementation and usage of logger wrapper for Serilog

So, my question is what is the proper way to create implementation that proxies to Serilog?

you should create something like:

public class SerilogAdapter : ILogger
{
    private readonly Serilog.ILogger m_Adaptee;

    public SerilogAdapter(Serilog.ILogger adaptee)
    {
        m_Adaptee = adaptee;
    }

    public void Log(LogEntry entry)
    {
        if (entry.Severity == LoggingEventType.Debug)
            m_Adaptee.Debug(entry.Exception, entry.Message);
        if (entry.Severity == LoggingEventType.Information)
            m_Adaptee.Information(entry.Exception, entry.Message);
        else if (entry.Severity == LoggingEventType.Warning)
            m_Adaptee.Warning(entry.Message, entry.Exception);
        else if (entry.Severity == LoggingEventType.Error)
            m_Adaptee.Error(entry.Message, entry.Exception);
        else
            m_Adaptee.Fatal(entry.Message, entry.Exception);
    }
}

Does that mean that every class that will log sth (so basically every), should have ILogger in its constructor?

As I understand from Stevens answer: Yes, you should do this.

what is the best way to use it later in the code?

If you are using a DI container, then just use the DI container to map ILogger to SerilogAdapter. You also need to register Serilog.ILogger, or just give an instance of Serilog logger to the DI container to inject it to the SerilogAdapter constructor.

If you don't use a DI container, i.e., you use Pure DI, then you do something like this:

Serilog.ILogger log = Serilog.Log.Logger.ForContext("MyClass");

ILogger logging_adapter = new SerilogAdapter(log);

var myobject = new MyClass(other_dependencies_here, logging_adapter);

Implementation and usage of logger wrapper for log4net

So, my question is what is the proper way to create implementation that proxies to log4net?

you should create something like:

public class Log4netAdapter : ILogger
{
    private readonly log4net.ILog m_Adaptee;

    public Log4netAdapter(log4net.ILog adaptee)
    {
        m_Adaptee = adaptee;
    }

    public void Log(LogEntry entry)
    {
        //Here invoke m_Adaptee
        if(entry.Severity == LoggingEventType.Debug)
            m_Adaptee.Debug(entry.Message, entry.Exception);
        else if(entry.Severity == LoggingEventType.Information)
            m_Adaptee.Info(entry.Message, entry.Exception);
        else if(entry.Severity == LoggingEventType.Warning)
            m_Adaptee.Warn(entry.Message, entry.Exception);
        else if(entry.Severity == LoggingEventType.Error)
            m_Adaptee.Error(entry.Message, entry.Exception);
        else
            m_Adaptee.Fatal(entry.Message, entry.Exception);
    }
}

Does that mean that every class that will log sth (so basically every), should have ILogger in its constructor?

As I understand from Stevens answer: Yes, you should do this.

what is the best way to use it later in the code?

If you are using a DI container, then just use the DI container to map ILogger to Log4netAdapter. You also need to register log4net.ILog, or just give an instance of log4net logger to the DI container to inject it to the Log4netAdapter constructor.

If you don't use a DI container, i.e., you use Pure DI, then you do something like this:

ILog log = log4net.LogManager.GetLogger("MyClass");

ILogger logging_adapter = new Log4netAdapter(log);

var myobject = new MyClass(other_dependencies_here, logging_adapter);

Logging best practices

Update: For extensions to System.Diagnostics, providing some of the missing listeners you might want, see Essential.Diagnostics on CodePlex (http://essentialdiagnostics.codeplex.com/)

Frameworks

Q: What frameworks do you use?

A: System.Diagnostics.TraceSource, built in to .NET 2.0.

It provides powerful, flexible, high performance logging for applications, however many developers are not aware of its capabilities and do not make full use of them.

There are some areas where additional functionality is useful, or sometimes the functionality exists but is not well documented, however this does not mean that the entire logging framework (which is designed to be extensible) should be thrown away and completely replaced like some popular alternatives (NLog, log4net, Common.Logging, and even EntLib Logging).

Rather than change the way you add logging statements to your application and re-inventing the wheel, just extended the System.Diagnostics framework in the few places you need it.

It seems to me the other frameworks, even EntLib, simply suffer from Not Invented Here Syndrome, and I think they have wasted time re-inventing the basics that already work perfectly well in System.Diagnostics (such as how you write log statements), rather than filling in the few gaps that exist. In short, don't use them -- they aren't needed.

Features you may not have known:

Using the TraceEvent overloads that take a format string and args can help performance as parameters are kept as separate references until after Filter.ShouldTrace() has succeeded. This means no expensive calls to ToString() on parameter values until after the system has confirmed message will actually be logged.
The Trace.CorrelationManager allows you to correlate log statements about the same logical operation (see below).
VisualBasic.Logging.FileLogTraceListener is good for writing to log files and supports file rotation. Although in the VisualBasic namespace, it can be just as easily used in a C# (or other language) project simply by including the DLL.
When using EventLogTraceListener if you call TraceEvent with multiple arguments and with empty or null format string, then the args are passed directly to the EventLog.WriteEntry() if you are using localized message resources.
The Service Trace Viewer tool (from WCF) is useful for viewing graphs of activity correlated log files (even if you aren't using WCF). This can really help debug complex issues where multiple threads/activites are involved.
Avoid overhead by clearing all listeners (or removing Default); otherwise Default will pass everything to the trace system (and incur all those ToString() overheads).

Areas you might want to look at extending (if needed):

Database trace listener
Colored console trace listener
MSMQ / Email / WMI trace listeners (if needed)
Implement a FileSystemWatcher to call Trace.Refresh for dynamic configuration changes

Other Recommendations:

Use structed event id's, and keep a reference list (e.g. document them in an enum).

Having unique event id's for each (significant) event in your system is very useful for correlating and finding specific issues. It is easy to track back to the specific code that logs/uses the event ids, and can make it easy to provide guidance for common errors, e.g. error 5178 means your database connection string is wrong, etc.

Event id's should follow some kind of structure (similar to the Theory of Reply Codes used in email and HTTP), which allows you to treat them by category without knowing specific codes.

e.g. The first digit can detail the general class: 1xxx can be used for 'Start' operations, 2xxx for normal behaviour, 3xxx for activity tracing, 4xxx for warnings, 5xxx for errors, 8xxx for 'Stop' operations, 9xxx for fatal errors, etc.

The second digit can detail the area, e.g. 21xx for database information (41xx for database warnings, 51xx for database errors), 22xx for calculation mode (42xx for calculation warnings, etc), 23xx for another module, etc.

Assigned, structured event id's also allow you use them in filters.

Q: If you use tracing, do you make use of Trace.Correlation.StartLogicalOperation?

A: Trace.CorrelationManager is very useful for correlating log statements in any sort of multi-threaded environment (which is pretty much anything these days).

You need at least to set the ActivityId once for each logical operation in order to correlate.

Start/Stop and the LogicalOperationStack can then be used for simple stack-based context. For more complex contexts (e.g. asynchronous operations), using TraceTransfer to the new ActivityId (before changing it), allows correlation.

The Service Trace Viewer tool can be useful for viewing activity graphs (even if you aren't using WCF).

Q: Do you write this code manually, or do you use some form of aspect oriented programming to do it? Care to share a code snippet?

A: You may want to create a scope class, e.g. LogicalOperationScope, that (a) sets up the context when created and (b) resets the context when disposed.

This allows you to write code such as the following to automatically wrap operations:

  using( LogicalOperationScope operation = new LogicalOperationScope("Operation") )
  {
    // .. do work here
  }

On creation the scope could first set ActivityId if needed, call StartLogicalOperation and then log a TraceEventType.Start message. On Dispose it could log a Stop message, and then call StopLogicalOperation.

Q: Do you provide any form of granularity over trace sources? E.g., WPF TraceSources allow you to configure them at various levels.

A: Yes, multiple Trace Sources are useful / important as systems get larger.

Whilst you probably want to consistently log all Warning & above, or all Information & above messages, for any reasonably sized system the volume of Activity Tracing (Start, Stop, etc) and Verbose logging simply becomes too much.

Rather than having only one switch that turns it all either on or off, it is useful to be able to turn on this information for one section of your system at a time.

This way, you can locate significant problems from the usually logging (all warnings, errors, etc), and then "zoom in" on the sections you want and set them to Activity Tracing or even Debug levels.

The number of trace sources you need depends on your application, e.g. you may want one trace source per assembly or per major section of your application.

If you need even more fine tuned control, add individual boolean switches to turn on/off specific high volume tracing, e.g. raw message dumps. (Or a separate trace source could be used, similar to WCF/WPF).

You might also want to consider separate trace sources for Activity Tracing vs general (other) logging, as it can make it a bit easier to configure filters exactly how you want them.

Note that messages can still be correlated via ActivityId even if different sources are used, so use as many as you need.

Listeners

Q: What log outputs do you use?

This can depend on what type of application you are writing, and what things are being logged. Usually different things go in different places (i.e. multiple outputs).

I generally classify outputs into three groups:

(1) Events - Windows Event Log (and trace files)

e.g. If writing a server/service, then best practice on Windows is to use the Windows Event Log (you don't have a UI to report to).

In this case all Fatal, Error, Warning and (service-level) Information events should go to the Windows Event Log. The Information level should be reserved for these type of high level events, the ones that you want to go in the event log, e.g. "Service Started", "Service Stopped", "Connected to Xyz", and maybe even "Schedule Initiated", "User Logged On", etc.

In some cases you may want to make writing to the event log a built-in part of your application and not via the trace system (i.e. write Event Log entries directly). This means it can't accidentally be turned off. (Note you still also want to note the same event in your trace system so you can correlate).

In contrast, a Windows GUI application would generally report these to the user (although they may also log to the Windows Event Log).

Events may also have related performance counters (e.g. number of errors/sec), and it can be important to co-ordinate any direct writing to the Event Log, performance counters, writing to the trace system and reporting to the user so they occur at the same time.

i.e. If a user sees an error message at a particular time, you should be able to find the same error message in the Windows Event Log, and then the same event with the same timestamp in the trace log (along with other trace details).

(2) Activities - Application Log files or database table (and trace files)

This is the regular activity that a system does, e.g. web page served, stock market trade lodged, order taken, calculation performed, etc.

Activity Tracing (start, stop, etc) is useful here (at the right granuality).

Also, it is very common to use a specific Application Log (sometimes called an Audit Log). Usually this is a database table or an application log file and contains structured data (i.e. a set of fields).

Things can get a bit blurred here depending on your application. A good example might be a web server which writes each request to a web log; similar examples might be a messaging system or calculation system where each operation is logged along with application-specific details.

A not so good example is stock market trades or a sales ordering system. In these systems you are probably already logging the activity as they have important business value, however the principal of correlating them to other actions is still important.

As well as custom application logs, activities also often have related peformance counters, e.g. number of transactions per second.

In generally you should co-ordinate logging of activities across different systems, i.e. write to your application log at the same time as you increase your performance counter and log to your trace system. If you do all at the same time (or straight after each other in the code), then debugging problems is easier (than if they all occur at diffent times/locations in the code).

(3) Debug Trace - Text file, or maybe XML or database.

This is information at Verbose level and lower (e.g. custom boolean switches to turn on/off raw data dumps). This provides the guts or details of what a system is doing at a sub-activity level.

This is the level you want to be able to turn on/off for individual sections of your application (hence the multiple sources). You don't want this stuff cluttering up the Windows Event Log. Sometimes a database is used, but more likely are rolling log files that are purged after a certain time.

A big difference between this information and an Application Log file is that it is unstructured. Whilst an Application Log may have fields for To, From, Amount, etc., Verbose debug traces may be whatever a programmer puts in, e.g. "checking values X={value}, Y=false", or random comments/markers like "Done it, trying again".

One important practice is to make sure things you put in application log files or the Windows Event Log also get logged to the trace system with the same details (e.g. timestamp). This allows you to then correlate the different logs when investigating.

If you are planning to use a particular log viewer because you have complex correlation, e.g. the Service Trace Viewer, then you need to use an appropriate format i.e. XML. Otherwise, a simple text file is usually good enough -- at the lower levels the information is largely unstructured, so you might find dumps of arrays, stack dumps, etc. Provided you can correlated back to more structured logs at higher levels, things should be okay.

Q: If using files, do you use rolling logs or just a single file? How do you make the logs available for people to consume?

A: For files, generally you want rolling log files from a manageability point of view (with System.Diagnostics simply use VisualBasic.Logging.FileLogTraceListener).

Availability again depends on the system. If you are only talking about files then for a server/service, rolling files can just be accessed when necessary. (Windows Event Log or Database Application Logs would have their own access mechanisms).

If you don't have easy access to the file system, then debug tracing to a database may be easier. [i.e. implement a database TraceListener].

One interesting solution I saw for a Windows GUI application was that it logged very detailed tracing information to a "flight recorder" whilst running and then when you shut it down if it had no problems then it simply deleted the file.

If, however it crashed or encountered a problem then the file was not deleted. Either if it catches the error, or the next time it runs it will notice the file, and then it can take action, e.g. compress it (e.g. 7zip) and email it or otherwise make available.

Many systems these days incorporate automated reporting of failures to a central server (after checking with users, e.g. for privacy reasons).

Viewing

Q: What tools to you use for viewing the logs?

A: If you have multiple logs for different reasons then you will use multiple viewers.

Notepad/vi/Notepad++ or any other text editor is the basic for plain text logs.

If you have complex operations, e.g. activities with transfers, then you would, obviously, use a specialized tool like the Service Trace Viewer. (But if you don't need it, then a text editor is easier).

As I generally log high level information to the Windows Event Log, then it provides a quick way to get an overview, in a structured manner (look for the pretty error/warning icons). You only need to start hunting through text files if there is not enough in the log, although at least the log gives you a starting point. (At this point, making sure your logs have co-ordinated entires becomes useful).

Generally the Windows Event Log also makes these significant events available to monitoring tools like MOM or OpenView.

Others --

If you log to a Database it can be easy to filter and sort informatio (e.g. zoom in on a particular activity id. (With text files you can use Grep/PowerShell or similar to filter on the partiular GUID you want)

MS Excel (or another spreadsheet program). This can be useful for analysing structured or semi-structured information if you can import it with the right delimiters so that different values go in different columns.

When running a service in debug/test I usually host it in a console application for simplicity I find a colored console logger useful (e.g. red for errors, yellow for warnings, etc). You need to implement a custom trace listener.

Note that the framework does not include a colored console logger or a database logger so, right now, you would need to write these if you need them (it's not too hard).

It really annoys me that several frameworks (log4net, EntLib, etc) have wasted time re-inventing the wheel and re-implemented basic logging, filtering, and logging to text files, the Windows Event Log, and XML files, each in their own different way (log statements are different in each); each has then implemented their own version of, for example, a database logger, when most of that already existed and all that was needed was a couple more trace listeners for System.Diagnostics. Talk about a big waste of duplicate effort.

Q: If you are building an ASP.NET solution, do you also use ASP.NET Health Monitoring? Do you include trace output in the health monitor events? What about Trace.axd?

These things can be turned on/off as needed. I find Trace.axd quite useful for debugging how a server responds to certain things, but it's not generally useful in a heavily used environment or for long term tracing.

Q: What about custom performance counters?

For a professional application, especially a server/service, I expect to see it fully instrumented with both Performance Monitor counters and logging to the Windows Event Log. These are the standard tools in Windows and should be used.

You need to make sure you include installers for the performance counters and event logs that you use; these should be created at installation time (when installing as administrator). When your application is running normally it should not need have administration privileges (and so won't be able to create missing logs).

This is a good reason to practice developing as a non-administrator (have a separate admin account for when you need to install services, etc). If writing to the Event Log, .NET will automatically create a missing log the first time you write to it; if you develop as a non-admin you will catch this early and avoid a nasty surprise when a customer installs your system and then can't use it because they aren't running as administrator.

What are the best practices for including logging using log4net?

I found this article very helpful: http://blog.codinghorror.com/the-problem-with-logging/

In particular I think a minimalist approach is indeed the way to go. In the past I've tried to log too much but this bloats the code

Also the thinking that the more log entries the better is wrong because it bloats the logs themselves. I now look at loggings main benefit as providing a "foothold" or overview of what is going on. If more detail is needed for particular areas then so be it but the default position should be less is better

Is it worth wrapping a logging framework in an additional layer?

I entirely agree with you: wrappers of wrappers of wrappers are getting out of hand. I suspect that architect doesn't realize how SLF4J in particular can easily wrap any other logging system, so that "changing implementation" is perfectly feasible without yet another layer of wrappage.

Logging best practices and thoughts

Logs only needed to debug applications during development, to ensure that the feature works as expected and produces desired results. The best practice is, I believe, to do logging in any way which is most convenient to you and allows to find and resolve issues as quickly and efficiently as possible

I mentioned earlier that the log entry isn't logged into a file. Why
isn't this a built in feature in Android?

Who (except a programmer on the development stage) would want an application to waste limited storage space on one's device with useless data? Users don't see, don't read, don't use logs. They don't need this garbage. Application in production must not produce any logs and, of course, must not save them to files.

The only logging which should be implemented in released application is unhandled exceptions logging. Moreover, it's application's responsibility to handle these logs if it suggests sending crash reports, and removing them after the report has been sent.

Another reason logs should not be created by released apps is that they may contain sensitive data and output which requires user authorization, thus introducing security flaws.

I believe the best practice is to remove all logs as soon as the module or feature is fully implemented and thoroughly tested, before deployment to production. Introducing if (BuildConfig.DEBUG) condition helps to ensure this has been achieved.

Logger Wrapper Best Practice