Release days are good days – Colin Eberhardt and I are very happy to announce SLF 1.0!

SLF is a framework with a simple but ambitious mission: To provide every developer with the means to easily plug in logging functionality into her application. As such, it aims at two fundamental goals:

1. Simplicity: SLF allows you to plug in solid logging functionality into your application with literally one line of code, while providing you with an upgrade path to complex logging scenarios at any time.
2. Flexibility: SLF provides you with a common interface that decouples the logging framework of your choice (e.g. log4net or NLog)  from your code. This eliminates dependencies on a given framework, thus allowing you to switch (or even combine!) frameworks at any time. Furthermore, SLF’s modular architecture allows you to plug-in custom logging strategies very easily.

Features

• Configurable through code or configuration files (app.config).
• Support for named loggers with hierarchical fallback mechanisms.
• Support for common logging frameworks such as log4net out of the box.
• Silverlight support.
• Writing your own pluggable logging strategy is easy.
• You can exchange the underlying logging mechanism at any time, even at runtime.
• Extensible and modular architecture. Writing your own façade can be as simple as overriding one single method, but you can cover complex scenarios, should you have to.
• Robust: In case of invalid configurations or logging instructions, SLF rather outputs debug warnings instead of crashing your application at runtime.
• A ton of copy-and-paste ready samples for different use cases.
• .NET 2.0 compatible binaries.

Related Links

• SLF project page: http://slf.codeplex.com
• The Art of Logging – an excellent introduction to logging in general from SLF co-creator Colin Eberhardt.
• SLF Hands-on Tutorial, Part 1

How does SLF Work?

Here’s a first snippet that shows how to get a logger at runtime via the static LoggerService class. LoggerService is basically a convenient – and optional – repository for your loggers:

//get the default (unnamed) logger 
ILogger logger = LoggerService.GetLogger();

//log an information 
logger.Info("hello world");

When working with SLF, you’re usually dealing with the ILogger interface. There’s a few built-in implementations of this interface directly in the SLF core library (e.g. ConsoleLogger), but in productive environments, your ILogger implementation usually is a class that forwards logging instructions to a proprietary logging framework such as log4net, or a custom logging facility you wrote yourself. Hence the name façade:

From your application’s point of view, there is no dependency on the underlying façade and logging framework – you are always logging through the ILogger interface of the SLF core library. This allows you to easily exchange the underlying proprietary mechanism without having to change any of your code that performs the actual logging.

SLF also allows you to directly control the logger resolution process (the process that eventually leads to an ILogger instance). We will cover this in a later tutorial.

But why should we replace dependencies on logging framework X with dependencies on SLF?

You probably won’t worry about that, as SLF really just forwards logging information, and can be easily adjusted. However: There’s a simple pattern to get rid of that dependency, too. If you download SLF, you will find a sample project that implements a wrapper for SLF itself:

SLF in a Fictitious Sample: The Lifecycle of an Application.

I’ll try to outline the benefits of logging, and the role SLF can play in the context of a fictitious software project. We assume the following:

• The application will contain various modules (plug-ins). The modules will be developed individually by separate teams.
• All modules should log important information. These modules log through SLF, so they have no idea about the underlying logging framework.
• Parts of the logged data should be sent back to the development team as soon as the first beta versions have been deployed.

Week 1: Setting Up Logging

Developers have other things in mind than thinking about logging frameworks. They do, however, set SLF in place with two simple steps:

1. Set a reference to the SLF core library.
2. Configure a logger within the main initialization routine of the application. For starters, all logged data is written to Visual Studio’s debugger by plugging a DebugLogger instance into the global LoggerService:

Actually, the first line of code in the application is related to logging:

private void InitApplication() 
{
  //make sure logging is in place 
  LoggerService.SetLogger(new DebugLogger()); 
  
  [some other code] 
}

The application is now officially logging-enabled 😉

(btw: as an alternative, a one-liner in the application’s configuration file would have worked, too)

Week 2: Developing First Modules

The first modules are being developed by individual teams. All module libraries maintain a reference to the SLF core library in order to log information. A typical method in a module looks like this:

private void Foo() 
{ 
  try 
  {  
    ...
  } 
  catch(Exception e) 
  {  
    ILogger logger = LoggerService.GetLogger(); 
    logger.Fatal(e, "Some explanation"); 
  }
}

Note that modules have no idea about the underlying logging strategy that was plugged into SLF (currently the DebugLogger from Week 1). They just know how to request a logger (ILogger interface) from LoggerService. What kind of logger they are dealing with is of no interest to them.

Week 3: Writing Logged Data to a File

There’s a lot of modules by now, which all direct logging information towards SLF. Currently, all this logged messages are being written to the debug window (as configured on Week 1). However, the developers would also like to have the data persisted in a file, while keeping the debug output at the same time.

Accordingly, the initialization routine from Week 1 is slightly altered:

//create two independent loggers 
ILogger debugLogger = new DebugLogger(); 
ILogger fileLogger = BitFactoryLogger.CreateSingleFileLogger("log.txt"); 

//CompositeLogger will redirect all its logging data to the two loggers… 
ILogger composite = new CompositeLogger(debugLogger, fileLogger); 
//…so plug it into LoggerService 
LoggerService.SetLogger(composite);

There’s now 3 loggers in play:

• The initial DebugLogger that logs to the debug window.
• The BitFactory façade was used to quickly set up logging to a file. The BitFactory façade is a library that comes with SLF (just like the NLog façade library or the log4net façade library) and makes use of the BitFactory logging framework. This SLF façade library is now referenced by the main application, but not the independent module libraries.
• CompositeLogger (part of the core library) is then used as a channel that logs output to both the DebugLogger and the new BitFactoryLogger:

These four lines of code changed the logging behavior of the whole application. Even if there are now literally hundreds of logging instructions in various modules, they don’t need to be changed at all. Everything will now be logged to both the file and the debugger.

Week 4: Switching to Declarative Configurations and log4net

The integration team decides to plug in their logging framework of choice, which happens to be log4net. Furthermore, they want to get rid of programmatic initialization, and switch to declarative configuration. This requires two steps:

1. Configuring SLF and log4net in the application’s configuration file (app.config)
2. Remove all the code (initialization of LoggerService) from Weeks 1 and 3.

Here’s the app.config file:

<?xml version="1.0" encoding="utf-8" ?> 
<configuration> 
  <configSections> 
   <section name="slf"
            type="Slf.Config.SlfConfigurationSection, slf"/> 

   <section name="log4net"
            type="log4net.Config.Log4NetConfigurationSectionHandler,log4net"/> 
  </configSections>


  <slf>
    <factories>
      <!-- declare a log4net factory -->
      <factory name="l4n"
               type="SLF.Log4netFacade.Log4netLoggerFactory, SLF.Log4netFacade"/> 
    </factories>

    <loggers>
      <!-- declare the default logger -->
      <logger factory="l4n" />
    </loggers>

  </slf>


  <log4net> 
    <!-- standard log4net settings are here... --> 
   </log4net> 
</configuration>

Actually, the above SLF configuration could have been written shorter, but the verbose version is recommended for readability. This would be a shorter, but equivalent version of the slf section:

<slf>
  <factories>
    <!-- this default factory is used for every logging instruction -->
    <factory type="SLF.Log4netFacade.Log4netLoggerFactory, SLF.Log4netFacade"/> 
  </factories>
</slf>

Week 5: Working with Named Loggers

One of the teams develops a module that logs very important data, and they would like to gather this data separately. It is therefore decided that this output will be logged through a named logger called LABDATA. This LABDATA logger should store this information separately.

Accordingly, a lot of logging instructions in this team’s module use SLF’s capability to work with named loggers:

private void Foo(string someValue) 
{ 
  try
  {
    //get named logger to log this piece of information 
    ILogger labLogger = LoggerService.GetLogger("LABDATA"); 
    labLogger.Info("Foo was invoked with value {0}", someValue); 

    ...
  }
  catch(Exception e) 
  {
    //exceptions are still logged through default logger  
    ILogger defaultLogger = LoggerService.GetLogger();  
    defaultLogger.Fatal(e, "Some explanation"); 
  }
}

This code was written by an independent team, and they haven’t changed the configuration of the main application. Accordingly, the logged information will still be routed through the default logger, because a logger that matches the name “LABDATA” just isn’t available yet.

So currently, “LABDATA” output will be logged to the same file as all other logging information.

But the important thing is: The mechanism is in place and SLF still works without errors!

Week 6: Declaratively Configuring the “LABDATA” Logger

During integration of the new module, SLF’s configuration is changed in order to support custom logging instructions for the LABDATA module.

Because log4net is used, which also supports named loggers out of the box, the SLF configuration does not need to be changed at all! Only the log4net section is being updated:

The adjustments in the application configuration file are specific to log4net:

<?xml version="1.0" encoding="utf-8" ?> 
<configuration> 
  <configSections> 
   <section name="slf"
            type="Slf.Config.SlfConfigurationSection, slf"/> 

   <section name="log4net"
            type="log4net.Config.Log4NetConfigurationSectionHandler,log4net"/> 
  </configSections>


  <slf>
    <factories>
      <!-- declare a log4net factory -->
      <factory name="l4n"
               type="SLF.Log4netFacade.Log4netLoggerFactory, SLF.Log4netFacade"/> 
    </factories>

    <loggers>
      <!-- declare the default logger -->
      <logger factory="l4n" />
    </loggers>

  </slf>


<!--
  configures log4net with two loggers:
  - A default logger, which logs to file "log-common.txt"
  - A named logger ("LABDATA"), which logs to file "log-labdata.txt"
-->
<log4net>
  <appender name="CommonAppender" type="log4net.Appender.FileAppender">
    <param name="File" value="log-common.txt" />
    <param name="AppendToFile" value="true" />
    <layout type="log4net.Layout.PatternLayout">
      <conversionPattern value="%date - %message %newline" />
    </layout>
  </appender>
  
  <appender name="LabDataAppender" type="log4net.Appender.FileAppender">
    <param name="File" value="log-labdata.txt" />
    <param name="AppendToFile" value="true" />
    <layout type="log4net.Layout.PatternLayout">
      <conversionPattern value="%date [%thread] %-5level - %message %newline" />
    </layout>
  </appender>
  

  <logger name="">
    <appender-ref ref="CommonAppender" />
  </logger>
  
  <logger name="LABDATA">
    <appender-ref ref="LabDataAppender" />
  </logger>
</log4net>

</configuration>

Week 7: Using Another Logging Framework for the LABDATA Loggers

So far, the generated LabData logging file was manually sent to the development team of the new module, which proved to be tedious (somebody had to manually send a mail every day).

Accordingly, a team developed a simple custom logging façade for SLF. This façade uses WCF to send logged data directly to the team.

As a result, there are now two logging façades in play. We have a new situation:

• Regular logging data should be logged to a file via log4net (same as before).
• Logging data for LABDATA should be handled by the new WcfLogger.

Fortunately, integration of the new façade library is easy! It can be plugged into SLF declaratively through the application’s configuration file:

• log4net configuration: The appender for the LABDATA logger is being removed.
• SLF configuration: The new WcfLogger is declared, and configured to handle all LABDATA output. SLF allows us to inject arbitrary configuration information into the declaration. For the WCF logger, this is address information and credentials.

This is how app.config looks now:

<?xml version="1.0" encoding="utf-8" ?> 
<configuration> 
  <configSections> 
   <section name="slf"
            type="Slf.Config.SlfConfigurationSection, slf"/> 

   <section name="log4net"
            type="log4net.Config.Log4NetConfigurationSectionHandler,log4net"/> 
  </configSections>


  <slf>
    <factories>
      <!-- declare a log4net factory -->
      <factory name="l4n"
               type="SLF.Log4netFacade.Log4netLoggerFactory, SLF.Log4netFacade"/> 
      
      <!-- the custom factory that logs to a WCF service. -->
      <factory name="wcf"
               type="Acme.Logging.WcfLogger, Acme.Logging.Slf2WcfFacade">
        <factory-data>
          <!-- this factory takes custom configuration settings -->
          <service address="http://www.acme.com:8080/ws/logs"
                   user="foo"
                   password="bar" />
        </factory-data>
      </factory>
    </factories>

    <loggers>
      <!-- the default logger that logs via log4net -->
      <logger factory="l4n" />
      
      <!-- the named logger that uses the WCF façade -->
      <logger name="LABDATA" factory="wcf" />
    </loggers>
  </slf>


  <!-- log4net configuration for the common log file -->
  <log4net>
    <appender name="CommonAppender" type="log4net.Appender.FileAppender">
      <param name="File" value="log-common.txt" />
      <param name="AppendToFile" value="true" />
      <layout type="log4net.Layout.PatternLayout">
        <conversionPattern value="%date - %message %newline" />
      </layout>
    </appender>
    
    <root>
      <appender-ref ref="CommonAppender" />
    </root> 
  </log4net>
  
</configuration>

Again, only the configuration file was changed – the code in the modules was not touched at all.

Week 8 – Unit Testing Logging Instructions

The developers of the LabData module notice they didn’t cover all code in their unit test: Actually, they don’t know whether their logging instruction are properly executed or not.

In order to unit test their module, they just replace the configured loggers at runtime: They plug in TestLogger classes into LoggerService.  TestLogger is a simple logger which just stores all logging input it receives.

This is how the initialization code of their unit test class looks like:

public class Given_Foo_When_Submitting_Lab_Data
{
  private TestLogger defaultLogger;
  private TestLogger labDataLogger;

  [SetUp]
  public void Init()
  {
    SimpleFactoryResolver resolver = new SimpleFactoryResolver();
    resolver.Factory = new TestLoggerFactory();
    LoggerService.FactoryResolver = resolver;

    //for convenience, already get the two test loggers that we will be used
    defaultLogger = (TestLogger) LoggerService.GetLogger("");
    labDataLogger = (TestLogger)LoggerService.GetLogger("LABDATA");
  }
}

The above snippet installs a TestLoggerFactory. This factory will return TestLogger instances for every logger request that is made through LoggerService. This allows to test whether input was logged through the correct loggers.

Here’s a sample unit test:

[Test]
public void Submitting_Regular_Data_Should_Write_Info_To_Lab_Data_Logger()
{
  string testData = "asl39-23lsd9";
  Foo.FooBar(testData);

  //invoking Foo.FooBar should have logged 1 info to the LABDATA logger
  Assert.AreEqual(1, labDataLogger.LoggedItems.Count);

  //make sure data was logged correctly
  LogItem item = labDataLogger.LoggedItems[0];
  Assert.AreEqual(LogLevel.Info, item.LogLevel);
  StringAssert.Contains(item.Message, testData);

  //make sure nothing was logged to the default logger
  Assert.AreEqual(0, defaultLogger.Count);
}

Conclusion and Further Links

I hope the above scenario gave you an impression about how easily you can set up and adjust your logging environment with SLF. For more information, please visit the project page, check out the tutorials, or leave a feedback. Happy logging 🙂