[logback-user] Getting duplicate messages when using a custom Configurator

4 May 2023

      Hi,

I have a custom Configurator installed via META_INF.services in a bunch 
of different services.
I do it this way because I was finding that managing logback.xml files 
across a lot of different services was awkward and unnecessary log 
levels were leaking into production.
I also have a custom class for changing specific log levels based on env 
vars or system properties, and a vertx router for changing them 
dynamically at runtime.

All of this has been working work a few years, but I have recently found 
that in some circumstances I'm getting duplicate messages (at first it 
was just in some builds, but now it's in production so I need to do 
something about it).

I've added a load of debug spew to my classes, but it appears that the 
default configuration is being applied after my custom Configurator and 
I can't work out what is causing that.
And, of course, right now I can only reproduce this by executing a jar 
on the command line, rather than in a unit test.

My main method looks like this:

   public static void main(String[] args) {
     Main main = new Main(args);
     logger.info("Starting ({})", LoggerFactory.getILoggerFactory());

     LoggerContext lc = ((LoggerContext) LoggerFactory.getILoggerFactory());
     System.out.println(lc.getName());
     for (ch.qos.logback.classic.Logger logger : lc.getLoggerList()) {
       System.out.println("\t" + logger.getName());
       for (Iterator<Appender<ILoggingEvent>> iter = logger.iteratorForAppenders(); iter.hasNext(); ) {
         Appender<ILoggingEvent> a = iter.next();
         System.out.println("\t\t" + a.getName());
       }
     }
     // irrelevant stuff here
   }

and my custom Configurator is this:

   /**
    * Perform the configuration.
    * @param lc The LoggerContext to configure.
    * @param asJson If true then logs will be recorded as JSON.
    */
   public void configure(LoggerContext lc, boolean asJson) {
     @SuppressWarnings("unchecked")
     Map<Object, Object> ruleRegistry = (Map<Object, Object>) lc.getObject(CoreConstants.PATTERN_RULE_REGISTRY);
     if (ruleRegistry == null) {
       ruleRegistry = new HashMap<>();
       lc.putObject(CoreConstants.PATTERN_RULE_REGISTRY, ruleRegistry);
     }
     registerConverters(ruleRegistry);

     Appender<ILoggingEvent> appender;
     if (asJson) {
       appender = configureJsonOutput(lc, createConsoleAppender(lc));
     } else {
       appender = configureMultiLineOutput(lc, createConsoleAppender(lc));
     }
     appender.start();

     System.out.println(lc.getName());
     for (Logger logger : lc.getLoggerList()) {
       System.out.println("\t" + logger.getName());
       for (Iterator<Appender<ILoggingEvent>> iter = logger.iteratorForAppenders(); iter.hasNext(); ) {
         Appender<ILoggingEvent> a = iter.next();
         System.out.println("\t\t" + a.getName());
       }
       logger.detachAndStopAllAppenders();
     }

     Logger rootLogger = lc.getLogger(Logger.ROOT_LOGGER_NAME);
     rootLogger.addAppender(appender);
     rootLogger.setLevel(Level.INFO);
     rootLogger.setAdditive(true);

     System.out.println(lc.getName());
     for (Logger logger : lc.getLoggerList()) {
       System.out.println("\t" + logger.getName());
       for (Iterator<Appender<ILoggingEvent>> iter = logger.iteratorForAppenders(); iter.hasNext(); ) {
         Appender<ILoggingEvent> a = iter.next();
         System.out.println("\t\t" + a.getName());
       }
     }
   }

The output from this is:

NOTE: Picked up JDK_JAVA_OPTIONS: -server -XX:-OmitStackTraceInFastThrow
default
         ROOT
default
         ROOT
                 STDOUTPUT
2023-05-04 12:55:18.653 [main] c.groupgti.shared.configservice.Main INFO  - Starting (ch.qos.logback.classic.LoggerContext[default])
13:55:18.653 [main] INFO com.groupgti.shared.configservice.Main -- Starting (ch.qos.logback.classic.LoggerContext[default])
default
         ROOT
                 STDOUTPUT
                 console
         com
         com.groupgti
         com.groupgti.shared
         com.groupgti.shared.configservice
         com.groupgti.shared.configservice.Main
         + more packages

So my custom Configurator is running, but then (I think when the static 
loggers are created) the console appender is being added to the ROOT logger.

I tried naming my appender "console", that just resulted in two 
appenders called "console" :)

How can I stop the default "console" appender being added to root?

Thanks

Jim

[logback-user] Getting duplicate messages when using a custom Configurator

logback users list