Uploaded image for project: 'SLF4J'
  1. SLF4J
  2. SLF4J-463

LogServiceProvider.initialize called twice

    Details

    • Type: Bug
    • Status: Closed
    • Priority: Blocker
    • Resolution: Fixed
    • Affects Version/s: 2.0.0-alpha0
    • Fix Version/s: 2.0.0-alpha1
    • Component/s: None
    • Labels:
      None
    • Severity:
      critical

      Description

      With logback 1.3.0-alpha code and slf4j 1.8, LogServiceProvider::initialize can be called twice.  I did not see this with logback 1.2.3 and slf4j 1.7.25.

      I attached some test code. The test code uses logback 1.3.0-alpha4, but I saw the problem with all alpha versions of logback 1.3.0.

      $ tar xf logback-demo.tar
      $ cd logback-demo
      $ ./gradlew clean build
      
      BUILD SUCCESSFUL in 0s
      8 actionable tasks: 7 executed, 1 up-to-date
      $ cd build/distributions
      $ tar xf logback-demo-1.0-SNAPSHOT.tar
      $ cd logback-demo-1.0-SNAPSHOT/bin/
      $ ./logback-demo
      16:30:12,127 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.xml]
      16:30:12,127 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback.groovy]
      16:30:12,127 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource [logback.xml] at [jar:file:/Users/dgroves/git/demo/logback-demo/build/distributions/logback-demo-1.0-SNAPSHOT/lib/logback-demo-1.0-SNAPSHOT.jar!/logback.xml]
      16:30:12,140 |-INFO in ch.qos.logback.core.joran.spi.ConfigurationWatchList@ee7d9f1 - URL [jar:file:/Users/dgroves/git/demo/logback-demo/build/distributions/logback-demo-1.0-SNAPSHOT/lib/logback-demo-1.0-SNAPSHOT.jar!/logback.xml] is not of type file
      16:30:12,202 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender]
      16:30:12,205 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [STDOUT]
      16:30:12,210 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property
      16:30:12,230 |-INFO in ch.qos.logback.classic.joran.action.RootLoggerAction - Setting level of ROOT logger to DEBUG
      16:30:12,230 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [STDOUT] to Logger[ROOT]
      16:30:12,231 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration.
      16:30:12,232 |-INFO in ch.qos.logback.classic.joran.JoranConfigurator@18ef96 - Registering current configuration as safe fallback point
      16:30:12.233 [main] INFO  demo - test
      16:30:12,235 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.xml]
      16:30:12,235 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback.groovy]
      16:30:12,235 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource [logback.xml] at [jar:file:/Users/dgroves/git/demo/logback-demo/build/distributions/logback-demo-1.0-SNAPSHOT/lib/logback-demo-1.0-SNAPSHOT.jar!/logback.xml]
      16:30:12,235 |-INFO in ch.qos.logback.core.joran.spi.ConfigurationWatchList@17ed40e0 - URL [jar:file:/Users/dgroves/git/demo/logback-demo/build/distributions/logback-demo-1.0-SNAPSHOT/lib/logback-demo-1.0-SNAPSHOT.jar!/logback.xml] is not of type file
      16:30:12,237 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender]
      16:30:12,238 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [STDOUT]
      16:30:12,238 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property
      16:30:12,239 |-INFO in ch.qos.logback.classic.joran.action.RootLoggerAction - Setting level of ROOT logger to DEBUG
      16:30:12,239 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [STDOUT] to Logger[ROOT]
      16:30:12,239 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration.
      16:30:12,239 |-INFO in ch.qos.logback.classic.joran.JoranConfigurator@50675690 - Registering current configuration as safe fallback point
      

      If I modify the build.gradle file in the bundle to comment out the newer dependencies and instead use the older ones, so that the dependencies block looks like:

      dependencies {
          implementation "org.jetbrains.kotlin:kotlin-stdlib-jdk8"
      
          // These cause the double call into LogbackServiceProvider.initialize
          // implementation "org.slf4j:slf4j-api:1.8.0-beta4"
          // implementation "ch.qos.logback:logback-classic:1.3.0-alpha4"
      
          // These do not cause the double call into LogbackServiceProvider.initialize
          implementation "org.slf4j:slf4j-api:1.7.25"
          implementation "ch.qos.logback:logback-classic:1.2.3"
      }
      
      

      I get different output showing only one attempt to initialize logback:

      $ ./gradlew clean build
      
      BUILD SUCCESSFUL in 0s
      8 actionable tasks: 7 executed, 1 up-to-date
      $ cd build/distributions/
      $ tar xf logback-demo-1.0-SNAPSHOT.tar 
      $ cd logback-demo-1.0-SNAPSHOT/bin/
      $ ./logback-demo
      16:34:05,882 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.xml]
      16:34:05,882 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback.groovy]
      16:34:05,882 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource [logback.xml] at [jar:file:/Users/dgroves/git/demo/logback-demo/build/distributions/logback-demo-1.0-SNAPSHOT/lib/logback-demo-1.0-SNAPSHOT.jar!/logback.xml]
      16:34:05,894 |-INFO in ch.qos.logback.core.joran.spi.ConfigurationWatchList@ba8a1dc - URL [jar:file:/Users/dgroves/git/demo/logback-demo/build/distributions/logback-demo-1.0-SNAPSHOT/lib/logback-demo-1.0-SNAPSHOT.jar!/logback.xml] is not of type file
      16:34:05,960 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender]
      16:34:05,963 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [STDOUT]
      16:34:05,967 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property
      16:34:05,988 |-INFO in ch.qos.logback.classic.joran.action.RootLoggerAction - Setting level of ROOT logger to DEBUG
      16:34:05,988 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [STDOUT] to Logger[ROOT]
      16:34:05,988 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration.
      16:34:05,989 |-INFO in ch.qos.logback.classic.joran.JoranConfigurator@4ca8195f - Registering current configuration as safe fallback point
      16:34:05.991 [main] INFO  demo - test
      
      

        Attachments

          Issue Links

            Activity

              People

              • Assignee:
                ceki Ceki Gülcü
                Reporter:
                dan.groves Dan Groves
              • Votes:
                0 Vote for this issue
                Watchers:
                2 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved: