Ninject.Extensions.Logging.Log4net unexpected behavior

Question

I am having a problem using Log4Net (1.2.10) through Ninject's (2.2.1.4) Extensions.Logging.Log4net (2.2.0.4), as installed through NuGet.

When I access Log4Net directly:

var logger = log4net.LogManager.GetLogger("Log4NetLoggerTest");
logger.Debug("foo { bar");

The result is:

2011-08-29 10:02:02,071 [9] DEBUG Log4NetLoggerTest foo { bar

However, when the logger is accessed through Ninject:

using (IKernel kernel = new StandardKernel())
{
    var ninjectLogger = kernel.Get<NinjectLoggerTest>();
    ninjectLogger.Log.Debug("foo { bar");
}

Where NinjectLoggerTest is simply this:

using Ninject.Extensions.Logging;
namespace TestApp
{
    public class NinjectLoggerTest
    {
        public NinjectLoggerTest(ILogger log)
        {
            Log = log;
        }
        public ILogger Log;
    }
}

Somewhat unexpectedly, the result is:

2011-08-29 10:29:27,114 [10] DEBUG TestApp.NinjectLoggerTest <log4net.Error>Exception during StringFormat: Input string was not in a correct format. <format>foo { bar</format><args>{}</args></log4net.Error>

Even worse, when using the ILogger's Trace method there is a first chance exception of type 'System.FormatException' in mscorlib.dll

Am I doing something wrong? How may I fix this?

TIA

Collected

Ninject.Extensions.Logging.Log4net implementation does not look right. There is no ILogger.Debug(string message) method. When called with a single argument the ILogger.Debug(string format, params object[] args) ends up being called with args = new object[]{} instead of null. The explicit Log.Debug("foo { bar", null) call works fine, as does the Log.Debug("{0}", message) but that is really not what I want. There really should be single argument methods like Debug(string message) (and friends) defined on ILogger. Still looking for a proper solution. – Collected

Answer 1

The solution is to create a simple logger façade to completely decouple Ninject from the rest of the app. The steps are:

1) Copy/paste Ninject's ILogger interface into the app's namespace (do not just inherit or you end up depending on Ninject's assembly because of the types exposed through Ninject's ILogger).

2) Create custom Logger, LoggerFactory and LoggerModule classes.

3) Pass LoggerModule to Ninject's StandardKernel

For completeness the code is:

Ninject's ILogger - copy/paste the ILogger interface, change it's namespace to MyAppNamespace.Logger and add the following methods:

void Debug(string message);
void Info(string message);
void Trace(string message);
void Warn(string message);
void Error(string message);
void Fatal(string message);

Logger.cs

namespace MyAppNamespace.Logger
{
    using System;
    class Logger : Ninject.Extensions.Logging.Log4net.Infrastructure.Log4NetLogger, ILogger
    {
        private const string DumpVerbatimFormat = "{0}";

        public Logger(Type type)
            : base(type)
        {
        }

        public void Debug(string message)
        {
            base.Debug(DumpVerbatimFormat, message);
        }

        public void Info(string message)
        {
            base.Info(DumpVerbatimFormat, message);
        }

        public void Trace(string message)
        {
            base.Trace(DumpVerbatimFormat, message);
        }

        public void Warn(string message)
        {
            base.Warn(DumpVerbatimFormat, message);
        }

        public void Error(string message)
        {
            base.Error(DumpVerbatimFormat, message);
        }

        public void Fatal(string message)
        {
            base.Fatal(DumpVerbatimFormat, message);
        }
    }
}

LoggerFactory.cs

namespace MyAppNamespace.Logger
{
    using System;
    using System.Collections.Generic;

    static class LoggerFactory
    {
        public static ILogger GetLogger(Ninject.Activation.IContext context)
        {
            return GetLogger(context.Request.Target == null ? typeof(ILogger) : context.Request.Target.Member.DeclaringType);
        }

        private static readonly Dictionary<Type, ILogger> TypeToLoggerMap = new Dictionary<Type, ILogger>();

        private static ILogger GetLogger(Type type)
        {
            lock (TypeToLoggerMap)
            {
                if (TypeToLoggerMap.ContainsKey(type))
                    return TypeToLoggerMap[type];

                ILogger logger = new Logger(type);
                TypeToLoggerMap.Add(type, logger);

                return logger;
            }
        }
    }
}

LoggerModule.cs

namespace MyAppNamespace.Logger
{
    public class LoggerModule : Ninject.Modules.NinjectModule
    {
        public override void Load()
        {
            log4net.Config.XmlConfigurator.Configure();
            Bind<ILogger>().ToMethod(LoggerFactory.GetLogger);
        }
    }
}

Tuck this whole mess away into a separate class library making it the only piece dependent on Ninject's logging extension and the concrete logger. You can now use MyAppNamespace.ILogger throughout your app, like this:

LoggerTest.cs

namespace MyAppNamespace.Whatever
{
    using Logger;
    public class LoggerTest
    {
        public LoggerTest(ILogger log)
        {
            Log.Info("Logger starting up");
        }
    }
}

somewhere in Main.cs

using (IKernel kernel = new StandardKernel(new Logger.LoggerModule()))
{
    kernel.Get<LoggerTest>();
}

Main ends up depending on Ninject but not the logging extension and whatever logger you use (the code works with Log4Net, you will need to tweak a bit for NLog). Other parts of the app depend on MyAppNamespace.ILogger. That's about it.

Collected

this looks good, but how can this be implemented in a web application? – Antioch

Moosaka, I like your in depth code, but I have one issue. In the LoggerFactory, I get a compile time error at ILogger logger = new Logger(type); stating "Cannot access protected constructor 'Logger' here". Any thoughts on how to fix that? – Neckband

Also, you state to "Tuck this whole mess away into a separate class library". Does that mean as a whole separate project? – Neckband

@Antioch I have no idea. What would be the difference? – Collected

@bmccleary exactly, I keep these classes in a separate project within the solution. The project's name and thus the namespace is not really MyAppNamespace.Logger but <Name of the containing Solution>.Logger. Also, do not try to access the Logger type directly, then you depend on the concrete logger type (the Logger). You should instantiate through the LoggerFactory to get an ILogger. – Collected

Answer 2

According to official issue tracker, this was fixed in version 3.0.2 of Ninject.Extensions.Logging, so updating that library will solve the issue.

Minimus