12
\$\begingroup\$

I finally set up my logging infrastructure to work as desired, however I feel like I had to do quite a lot things just to fulfill a few requirements. Now I'm worried if my approach has major drawbacks, e.g. in performance or stability, so I need your help!

Requirements

  • Logging to multiple output sources, depending on configuration and environment (e.g. Console or Windows Service)
  • Pre-evaluation of logging conditions for formatting, which means: If the message won't be logged, nothing gets formatted or converted to improve performance and memory usage
  • Abstraction of logging implementation for use within domain & infrastructure layer (application is split up according to the Onion Architecture)
  • Ability to inject logging abstraction into classes (DI)

Framework I've chosen log4net as the framework behind because of it's straight-forward configuration and variety of listeners (appenders)

Implementation

Basically, everytime I need to have logging abilities in a class, I request a custom ILogger interface via the constructor. This interface will be served using dependency injection with Ninject as my IoC container. The interface, among with extension methods etc. is implemented in a "Core" library every other project can reference to (library for cross cutting concerns).

The actual logger (log4net adapter) is implemented in a infrastructure project called "Infrastructure.Logging". The adapter itself requests a implementation of the log4net facade ILog via constructor, which will also be served by Ninject. It routes the calls to ILogger forward to log4net with the appropriate log4net level.

Everything gets hooked up at the start of the application. More than 4 appenders will be registered, which can be activated/deactivated using log4net property filters. Also, the ILog interface is bound to a log4net logging instance using a method binding to LogManager.

MyApp.Core

ILogger

public enum EventSeverity
{
    Informational,
    Warning,
    Error,
    Fatal,
    Debug,
    Verbose
}

public interface ILogger {

    bool IsDebugEnabled             { get; }
    bool IsVerboseEnabled           { get; }
    bool IsInformationalEnabled     { get; }
    bool IsWarningEnabled           { get; }
    bool IsFatalEnabled             { get; }
    bool IsErrorEnabled             { get; }

    void Write(string message, EventSeverity severity);
    void Write(string message, Exception exception, EventSeverity severity);

}

LoggerExtensions

public static class LoggerExtensions
{

    public static void Informational(this ILogger logger, string message)
    {
        if (logger.IsInformationalEnabled)
            logger.Write(message, EventSeverity.Informational);
    }

    public static void Informational(this ILogger logger, string format, params object[] args)
    {
        if (logger.IsInformationalEnabled)
            logger.Write(String.Format(format, args), EventSeverity.Informational);
    }

    public static void Warning(this ILogger logger, string message)
    {
        if (logger.IsWarningEnabled)
            logger.Write(message, EventSeverity.Warning);
    }

    // ... error, fatal, verbose

MyApp.Infrastructure.Logging

Log4NetLoggingAdapter

public sealed class Log4NetLoggingAdapter : ILogger
{

    private readonly ILog _internalLogger;

    public bool IsDebugEnabled
    {
        get { return _internalLogger.IsDebugEnabled; }
    }

    public bool IsVerboseEnabled
    {
        get { return _internalLogger.Logger.IsEnabledFor(Level.Verbose); }
    }

    // ... isWarningEnabled, isInfoEnabled..

    public Log4NetLoggingAdapter(ILog internalLogger)
    {
        if (internalLogger == null)
            throw new ArgumentNullException("internalLogger");
        _internalLogger = internalLogger;
    }

    public void Write(string message, EventSeverity severity)
    {
        Write(message, null, severity);
    }

    public void Write(string message, Exception exception, EventSeverity severity)
    {
        var level = GetLevelFromSeverity(severity);
        _internalLogger.Logger.Log(MethodBase.GetCurrentMethod().DeclaringType, 
            level, message, exception);
    }

    private static Level GetLevelFromSeverity(EventSeverity severity)
    {
        switch (severity)
        {
            case EventSeverity.Informational:
                return Level.Info;
            case EventSeverity.Warning:
                return Level.Warn;
    // ... etc..
    }

MyApp.Server

log4net configuration

    <root>
        <level value="INFO"/>
        <appender-ref ref="ColoredConsoleAppender" />
        <appender-ref ref="RollingFileAppender" />
        <appender-ref ref="EventLogAppender" />
        <appender-ref ref="DebugAppender" />
    </root>

    <appender name="DebugAppender" type="log4net.Appender.DebugAppender">
        <immediateFlush value="true" />
        <filter type="log4net.Filter.PropertyFilter">
            <key value="DebugEnabled" />
            <stringToMatch value="True" />
            <acceptOnMatch value="true" />
        </filter>
        <filter type="log4net.Filter.DenyAllFilter" />
        <layout type="log4net.Layout.PatternLayout">
            <conversionPattern value="%date [%thread] %-5level [%property{NDC}] - %message%newline%exception" />
        </layout>
    </appender>

    <appender name="RollingFileAppender" type="log4net.Appender.RollingFileAppender">

        <filter type="log4net.Filter.PropertyFilter">
            <key value="ApplicationMode" />
            <stringToMatch value="Service" />
            <acceptOnMatch value="true" />
        </filter>

        <filter type="log4net.Filter.DenyAllFilter" />

        <file value="app.log" />
        <appendToFile value="true" />
        <rollingStyle value="Size" />
        <maxSizeRollBackups value="3" />
        <maximumFileSize value="1000KB" />
        <staticLogFileName value="true" />
        <layout type="log4net.Layout.PatternLayout">
            <conversionPattern value="%date [%thread] %-5level %logger [%property{NDC}] - %message%newline%exception" />
        </layout>
    </appender>

    <appender name="EventLogAppender" type="log4net.Appender.EventLogAppender" >

        <filter type="log4net.Filter.PropertyFilter">
            <key value="ApplicationMode" />
            <stringToMatch value="Service" />
            <acceptOnMatch value="true" />
        </filter>

        <filter type="log4net.Filter.LevelRangeFilter">
            <acceptOnMatch value="true" />
            <levelMin value="ERROR" />
            <levelMax value="FATAL" />
        </filter>

        <filter type="log4net.Filter.DenyAllFilter" />

        <layout type="log4net.Layout.PatternLayout">
            <conversionPattern value="%date [%thread] %-5level %logger [%property{NDC}] - %message%newline%exception" />
        </layout>
    </appender>

    <appender name="ColoredConsoleAppender" type="log4net.Appender.ColoredConsoleAppender">

        <filter type="log4net.Filter.PropertyFilter">
            <key value="ApplicationMode" />
            <stringToMatch value="Console" />
            <acceptOnMatch value="true" />
        </filter>

        <filter type="log4net.Filter.DenyAllFilter" />

        <mapping>
            <level value="INFO" />
            <foreColor value="White, HighIntensity" />
            <backColor value="Green" />
        </mapping>
        <mapping>
            <level value="DEBUG" />
            <foreColor value="White, HighIntensity" />
            <backColor value="Blue" />
        </mapping>
        <mapping>
            <level value="WARN" />
            <foreColor value="Yellow, HighIntensity" />
            <backColor value="Purple" />
        </mapping>
        <mapping>
            <level value="ERROR" />
            <foreColor value="Yellow, HighIntensity" />
            <backColor value="Red" />
        </mapping>
        <layout  type="log4net.Layout.PatternLayout">
            <conversionPattern value="[%date] %message%newline%exception" />
        </layout>
    </appender>

Program (pseudo code)

internal static class Program {

    private static IKernel _kernel;
    private static ILogger _logger;

    internal static void Main() {

        // setup kernel
        _kernel = new StandardKernel();
        _kernel.Bind<ILog>().ToMethod(context => {
            return LogManager.GetLogger(context.Request.ParentRequest.ParentRequest.Target.Member.DeclaringType) };
        _kernel.Bind<ILogger>().To<Log4NetLoggerAdapter>();

        // init log4net
        XmlConfigurator.Configure();

        // load server configuration
        if(serverConfiguration.IsDebug) {
           if(!Debugger.IsAttached())
                Debugger.Launch();

            ThreadContext.Properties["DebugEnabled"] = "True";

        }

        if(!Environment.UserInteractive) {
                    ThreadContext.Properties["ApplicationMode"] = "Service";
                    // setup service controller
        } else {
                    ThreadContext.Properties["ApplicationMode"] = "Console";
                    Start();
        }
\$\endgroup\$
  • 2
    \$\begingroup\$ I don't think you should inject logger as dependency, because it will increase parameters in constructor and it will look ugly. so rather create a singleton instance of logger and use it everywhere you dont have to worry about mocking them \$\endgroup\$ – paritosh Jul 24 '14 at 11:52
  • \$\begingroup\$ and it is basic one time setup for logging , as it is essential piece of your framework, abstract in a dll \$\endgroup\$ – paritosh Jul 24 '14 at 11:53
  • 1
    \$\begingroup\$ have you thought about async calls , I always tend to make a logging infrastructure as uni-directional. I don't like to keep a track of if logging is happening or not... another factor to think about is inbuild logging for various techniques such as WCF got inbuild tech, so the webapi too.... so why would you like to define a logging infra. even it may not require.... \$\endgroup\$ – codebased Jul 24 '14 at 11:56
  • \$\begingroup\$ Logging is one of the few cases when using a singleton is okay because it's a one way cross cutting operation. \$\endgroup\$ – craftworkgames Sep 9 '14 at 6:22
  • \$\begingroup\$ @craftworkgames I've decided to settle with AOP/Interception. That way I can keep my services free of singletons, don't need to inject logging into classes and can manipulate the logging based on business rules. \$\endgroup\$ – xvdiff Sep 9 '14 at 10:56
5
\$\begingroup\$

Using extension methods and the interface makes me think you should use an abstract class to encapsulate the logging framework you use. I put the Write method and the overloads protected but you could put it public back if you need. Also, as you'll see it, I added brackets to your one line's if. I believe that even if it adds some lines of code, it gives a much better readability to your code.

public abstract class Logger
{
    public abstract bool IsDebugEnabled { get; }
    public abstract bool IsVerboseEnabled { get; }
    public abstract bool IsInformationalEnabled { get; }
    public abstract bool IsWarningEnabled { get; }
    public abstract bool IsFatalEnabled { get; }
    public abstract bool IsErrorEnabled { get; }

    protected abstract void Write(string message, EventSeverity severity);
    protected abstract void Write(string message, Exception exception, EventSeverity severity);

    public void LogInformational(string message)
    {
       if (IsInformationalEnabled)
       {
          Write(message, EventSeverity.Informational);
       }
    }

    public void LogInformational(string format, params object[] args)
    {
       if (IsInformationalEnabled)
       {
          Write(String.Format(format, args), EventSeverity.Informational);
       }
    }

    public void Warning(string message)
    {
       if (IsWarningEnabled)
       {
          Write(message, EventSeverity.Warning);
       }
    }

    //etc..
}

Edit :

I think you should keep your interface as clear as possible. Your contract should define the minimum you need, which is both Write methods. The other methods, as you mentioned, might not be supported by your logging framework, which means they wouldn't comply to the interface. Also, these methods have a little problem, let me give you an example. If IsInformationalEnabled = false and you call LogInformational, you have no feedback that the information wasn't logged, which is a problem. I think your Write method should deal with this, to keep it as simple as possible. Look at the following approach, I think it is an okay way to abstract your logger.

public abstract class Logger
{
    protected abstract bool IsDebugEnabled { get; }
    protected abstract bool IsVerboseEnabled { get; }
    protected abstract bool IsInformationalEnabled { get; }
    protected abstract bool IsWarningEnabled { get; }
    protected abstract bool IsFatalEnabled { get; }
    protected abstract bool IsErrorEnabled { get; }

    public void Write(string message, EventSeverity severity)
    {
       ValidateSeverityEnabled(severity);
       WriteToLog(message,severity);
    } 

    public void Write(string message, Exception exception, EventSeverity severity)
    {
       ValidateSeverityEnabled(severity);
       WriteToLog(message, exception, severity);
    }

    protected abstract void WriteToLog(string message, EventSeverity severity);
    protected abstract void WriteToLog(string message, Exception exception, EventSeverity severity);

    private void ValidateSeverityEnabled(EventSeverity severity)
    {
       switch (severity)
       { 
          case EventSeverity.Informational:
             if (!IsInformationalEnabled)
                throw new InvalidOperationException("Informational log disabled");
             break;
          case EventSeverity.Warning:
             if (!IsWarningEnabled)
                throw new InvalidOperationException("Warning log disabled");
             break;
          case EventSeverity.Error:
             if (!IsErrorEnabled)
                throw new InvalidOperationException("Error log disabled");
             break;
          case EventSeverity.Fatal:
             if (!IsFatalEnabled)
                throw new InvalidOperationException("Fatal log disabled");
             break;
          case EventSeverity.Debug:
             if (!IsDebugEnabled)
                throw new InvalidOperationException("Debug log disabled");
             break;
          case EventSeverity.Verbose:
             if (!IsVerboseEnabled)
                throw new InvalidOperationException("Verbose log disabled");
             break;
       }
    }
}
\$\endgroup\$
  • \$\begingroup\$ I don't know. I implemented the severity-specific methods as extension methods because I don't actually know what the logging framework behind supports, therefore I wanted to enforce the 'simplest' interface possible on it. I even went further and replaced all "IsXXXEnabled" with a single "IsLogLevelEnabled(LogLevel level)". Wouldn't that be actually better? Because the extension methods now are just that: Extensions, that let me write stuff with a little bit shorter syntax. \$\endgroup\$ – xvdiff Oct 4 '14 at 8:57
  • \$\begingroup\$ Replacing the properties for a methos is indeed a good idea! I'm disapointed I didn't see it. And if you're not sure the framework would support the extensions, what will happen when I would call them? Because following the method signature, I could call an extension method with a framework that doesn't support it. I really think your contract should reflect exactly what you want, not the simplest functionality possible. \$\endgroup\$ – IEatBagels Oct 4 '14 at 14:32
  • \$\begingroup\$ Yeah, you're right about that. Meanwhile I figured out I did exactly the same thing Common.Logging and SLF have in their interfaces and both of them use the most related log level if the underlying framework doesn't support a specific one (e.g. Verbose for Debug etc.) which I'm not really happy about either. I guess abstracting away a logging framework is like trying to abstract away a cat: Lots of scratches and pain. Does that make sense? Will report back if I come up with a satisfying solution. \$\endgroup\$ – xvdiff Oct 6 '14 at 12:48
  • \$\begingroup\$ @xvdiff Please take a look at my edit and see if it would be a better approach to your solution :) \$\endgroup\$ – IEatBagels Oct 6 '14 at 13:14
1
\$\begingroup\$

Your design is quite good. Reading the code you wrote I have a few notes.

What's the point of LoggerExtensions? I am not sure that it is a good idea to define an ILogger interface and then put almost all the methods you're supposed to used to interact with it in LoggerExtensions.

I think that you want ILogger to cover two different concerns. The first is what the client of your library should use, the other is what you need from your logging backend.

I'd rename your ILogger in ILoggerAdapter and I'd introduce a new Logger class implemented as follows:

public class Logger
{
    private readonly ILoggerAdapter backend;

    public Logger(ILoggerAdapter backend)
    {
        this.backend = backend;
    }

    public void Informational(this ILogger logger, string message)
    {
        if (logger.IsInformationalEnabled)
            logger.Write(message, EventSeverity.Informational);
    }

    /* all the other methods you had in LoggerExtensions */
}

If you do this now you have different classes to cover different concerns with a very lightweight API.

I appreciate your use of dependency injection instead of using singletons. I think it is quite good.

\$\endgroup\$
  • \$\begingroup\$ The ILogger interface is used to abstract the logging backend, therefore I thought it should be as simple as possible. The extension methods are not really methods 'supposed to used to interact', but more 'shorthands' that do not require to pass a logging severity. Basically, I could interact with the logger with Logger.Write(EventSeverity.Warning,...) all the time and it would be just as fine. \$\endgroup\$ – xvdiff Oct 4 '14 at 9:00

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.