Log4net duplicate logging entires

Question

I recently switched out log4net logging from using config files to being set up programmatically. This has resulted in the nhiberate entries getting repeated 2 or sometimes 3 times. Here's the code. It uses a string which looks something like this "logger1|debug,logger2|info"

    private void SetupLog4netLoggers()
    {
        IAppender appender = GetAppender();

        SetupRootLogger(appender);

        foreach (string logger in Loggers)
        {
            CommaStringList parts = new CommaStringList(logger, '|');
            if (parts.Count != 2)
                continue;

            AddLogger(parts[0], parts[1], appender);
        }

        log.Debug("Log4net has been setup");
    }

    private IAppender GetAppender()
    {
        RollingFileAppender appender = new RollingFileAppender();
        appender.File = LogFile;
        appender.AppendToFile = true;
        appender.MaximumFileSize = MaximumFileSize;
        appender.MaxSizeRollBackups = MaximumBackups;

        PatternLayout layout = new PatternLayout(PATTERN);
        layout.ActivateOptions();

        appender.Layout = layout;
        appender.ActivateOptions();

        return appender;
    }

    private void SetupRootLogger(IAppender appender)
    {
        Hierarchy hierarchy = (Hierarchy)LogManager.GetRepository();

        hierarchy.Root.RemoveAllAppenders();
        hierarchy.Root.AddAppender(appender);
        hierarchy.Root.Level = GetLevel(RootLevel);

        hierarchy.Configured = true;

        log.Debug("Root logger setup, level[" + RootLevel + "]");
    }

    private void AddLogger(string name, string level, IAppender appender)
    {
        Logger logger = LogManager.GetRepository().GetLogger(name)as Logger;
        if (logger == null)
            return;

        logger.Level = GetLevel(level);
        logger.Additivity = false;
        logger.RemoveAllAppenders();
        logger.AddAppender(appender);

        log.Debug("logger[" + name + "] added, level[" + level + "]");
    }

And here's an example of what we see in our logs...

2010-05-06 15:50:39,781 [1] DEBUG NHibernate.Impl.SessionImpl - running ISession.Dispose()
2010-05-06 15:50:39,781 [1] DEBUG NHibernate.Impl.SessionImpl - closing session
2010-05-06 15:50:39,781 [1] DEBUG NHibernate.AdoNet.AbstractBatcher - running BatcherImpl.Dispose(true)
2010-05-06 15:50:39,796 [1] DEBUG NHibernate.Impl.SessionImpl - running ISession.Dispose()
2010-05-06 15:50:39,796 [1] DEBUG NHibernate.Impl.SessionImpl - closing session
2010-05-06 15:50:39,796 [1] DEBUG NHibernate.AdoNet.AbstractBatcher - running BatcherImpl.Dispose(true)
2010-05-06 15:50:39,796 [1] DEBUG NHibernate.Impl.SessionImpl - running ISession.Dispose()
2010-05-06 15:50:39,796 [1] DEBUG NHibernate.Impl.SessionImpl - closing session
2010-05-06 15:50:39,796 [1] DEBUG NHibernate.AdoNet.AbstractBatcher - running BatcherImpl.Dispose(true)

Any hints welcome.

Answer 1

I am not really sure what is happening, but I would try to remove the following lines:

logger.Additivity = false;
logger.RemoveAllAppenders();
logger.AddAppender(appender);

The loggers should inherit the appender anyway from the root appender. Maybe log4net mixes up something when you add appenders in this fashion although that should not be the case...

Answer 2

I think the answer is - its not in fact writing duplicates. Without debugging the NHibernate code I can't be sure but I'm guessing its probably just writing it out or doing same thing repeatedly

We're going back to using config files anyway so will have to see if I still get possible duplicates.