Ninject.Extensions.Logging.Log4Net Produces Incorrect Output for Class/Method Name

Question

I'm using Ninject 3.0.1.10 for dependency injection and want to use Ninject.Extensions.Logging 3.0.1.0 for log4net 1.2.11 logging. However, I'm getting different output in my log files when using the extension rather than log4net directly. I want the output to contain the name of the class/method that does the logging, as follows in my app.config:

<log4net>
    <root>
        <level value="DEBUG" />
        <appender-ref ref="MyConsoleAppender" />
    </root>

    <appender name="MyConsoleAppender" type="log4net.Appender.ConsoleAppender">
        <layout type="log4net.Layout.PatternLayout">
            <conversionPattern value="%date %-5level %C{1}.%M():%L - %m%n" />
        </layout>
    </appender>
</log4net>

I've made a sample project to demonstrate the problem I'm seeing as follows:

public class LoggingWithLog4Net
{
    private readonly ILog log;

    public LoggingWithLog4Net(ILog log)
    {
        this.log = log;
    }

    public void LogMessage(string message)
    {
        log.Debug(message);
    }
}

public class LoggingWithNinject
{
    private readonly ILogger log;

    public LoggingWithNinject(ILogger log)
    {
        this.log = log;
    }

    public void LogMessage(string message)
    {
        log.Debug(message);
    }
}

public class Program
{
    static void Main(string[] args)
    {
        log4net.Config.XmlConfigurator.Configure();

        NinjectSettings settings = new NinjectSettings()
        {
            LoadExtensions = false
        };

        using (IKernel kernel = new StandardKernel(settings, new Log4NetModule()))
        {
            kernel.Bind<ILog>()
                .ToConstant(LogManager.GetLogger("*"));

            LoggingWithLog4Net l4n = kernel.Get<LoggingWithLog4Net>();
            LoggingWithNinject ninject = kernel.Get<LoggingWithNinject>();

            l4n.LogMessage("log4net message");
            ninject.LogMessage("ninject message");
        }
    }
}

This produces the following output (note the incorrect class/method name in the Ninject version):

2012-06-21 08:25:19,000 DEBUG LoggingWithLog4Net.LogMessage():21 - log4net message
2012-06-21 08:25:19,015 DEBUG Log4NetLogger.Debug():98 - ninject message

I would expect the second line to have LoggingWithNinject.LogMessage():21 as the source class/method but instead the Ninject Log4NetLogger is used as the source. How can I get the source to be properly identified?

Answer 1

It appears that what I want isn't possible. The %C{1}.%M():%L part of the configuration causes log4net to print the location information of the calling class. In the log4net version, you call Log4NetLogger and it passes your call onto log4net. This means the source will always be Log4NetLogger.

As a compromise, I've used the following:

<conversionPattern value="%date [%thread] %-5level %c - %m%n" />

This loses the method name and line number of the call, but you do get the correct class name when using the Ninject extension because loggers are always requested by Type which default to the full namespace/name combo of the class.

The other alternative is to inject log4net.ILog directly and stop using the Ninject extension.