Spring boot fails to start with slf-log4J12 binding

[tkruse]

Related to #129 Create spring boot quickstart gradle project as described here: http://projects.spring.io/spring-boot/#quick-start

then change build.gradle to:

apply plugin: 'java'
apply plugin: 'spring-boot'

buildscript {
    repositories {
        mavenCentral()
        maven { url "http://repo.spring.io/libs-snapshot" }
    }
    dependencies {
         classpath "org.springframework.boot:spring-boot-gradle-plugin:0.5.0.M6"
    }
}

repositories {
    mavenRepo url: 'http://repo1.maven.org/maven2'
    maven {
        url 'http://repo.spring.io/snapshot'
    }
}

dependencies {
    compile ("org.slf4j:slf4j-api:1.7.5") {force = true}
    compile ("org.slf4j:slf4j-log4j12:1.7.5") {force = true}
    compile("org.springframework.boot:spring-boot-starter-web:0.5.0.BUILD-SNAPSHOT")
}

For me, this results in:

$ gradle runJar
Build file '/home/kruset/work/java/spring-quickstart/build.gradle': line 15
The RepositoryHandler.mavenRepo() method has been deprecated and is scheduled to be removed in Gradle 2.0. Please use the maven() method instead.
:compileJava
:processResources UP-TO-DATE
:classes
:jar
:repackage
:runJar
SLF4J: Class path contains multiple SLF4J bindings.
SLF4J: Found binding in [jar:file:/home/kruset/work/java/spring-quickstart/build/libs/spring-quickstart.jar!/lib/slf4j-log4j12-1.7.5.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: Found binding in [jar:file:/home/kruset/work/java/spring-quickstart/build/libs/spring-quickstart.jar!/lib/logback-classic-1.0.13.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: See http://www.slf4j.org/codes.html#multiple_bindings for an explanation.
SLF4J: Actual binding is of type [org.slf4j.impl.Log4jLoggerFactory]
log4j:WARN No appenders could be found for logger (org.springframework.boot.autoconfigure.AutoConfigurationReportLoggingInitializer).
log4j:WARN Please initialize the log4j system properly.
log4j:WARN See http://logging.apache.org/log4j/1.2/faq.html#noconfig for more info.
java.lang.reflect.InvocationTargetException
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:606)
        at org.springframework.boot.loader.MainMethodRunner.run(MainMethodRunner.java:53)
        at java.lang.Thread.run(Thread.java:744)
Caused by: java.lang.ClassCastException: org.slf4j.impl.Log4jLoggerFactory cannot be cast to ch.qos.logback.classic.LoggerContext
        at org.springframework.boot.logging.logback.LogbackLoggingSystem.initialize(LogbackLoggingSystem.java:81)
        at org.springframework.boot.logging.AbstractLoggingSystem.initializeWithSensibleDefaults(AbstractLoggingSystem.java:61)
        at org.springframework.boot.logging.AbstractLoggingSystem.beforeInitialize(AbstractLoggingSystem.java:45)
        at org.springframework.boot.logging.logback.LogbackLoggingSystem.beforeInitialize(LogbackLoggingSystem.java:68)
        at org.springframework.boot.context.initializer.LoggingApplicationContextInitializer.initialize(LoggingApplicationContextInitializer.java:108)
        at org.springframework.boot.SpringApplication.callNonEnvironmentAwareSpringApplicationInitializers(SpringApplication.java:358)
        at org.springframework.boot.SpringApplication.run(SpringApplication.java:271)
        at org.springframework.boot.SpringApplication.run(SpringApplication.java:784)
        at org.springframework.boot.SpringApplication.run(SpringApplication.java:773)
        at hello.SampleController.main(SampleController.java:19)
        ... 6 more
:runJar FAILED

I can remove the slf4j-log4j12 binding from gradle, but then I don't get Log4J loggers from slf4j LoggerFactory, not even when I include "log4j:log4j:1.2.17" compile dependency in my build.gradle. The only way I could do this it to exclude logback completely from gradle using

configurations { // Spring boot bug, self-includes both log4J and logback and fails all*.exclude group: 'ch.qos.logback', module: 'logback-core' }

But then, I got ClassNotFoundExceptions when deploying my app as WAR file.

[tkruse]

Currently I see no clean solution how Spring boot can do this, since it should find out what logging system the user-code wants, but not what logging system it ships itself. spring-boot-starter-web depends on both log4j and logback, both will be included in a jar or war without further user action.

[tkruse]

To make matters even worse, org.springframework.boot:spring-boot-starter-actuator:0.5.0.M6 depends on org.slf4j:log4j-over-slf4j:1.7.5, conflicting with org.slf4j:slf4j-log4j12

[dsyer]

I don't think this is really a problem, except for the user that has to do all the manual build configuration. Log4J is supported by the underlying spring-boot library. So if you really prefer to use it for logging you don't have to use the "starter" dependencies to use Spring Boot - they are curated dependency sets for getting started quickly. If you really don't like logback (our preference) then you need to exclude logback from the web starter and log4j-over-slf4j from the actuator starter. Or you can include only the spring-boot bits you like (spring-boot-actuator on its own for instance has no dependency on a logging framework other than the commons-logging API, like most Spring projects).

[dsyer]

I think this should be a documentation issue: we need to document how to use the other logging systems with Boot.

[tkruse]

IMHO users should never be faced with ClassCastExceptions on startup when merely adding the dependencies I added in the given build.gradle. The promise of Spring boot is to configure reasonable defaults when there is no configuration, and get out of the way else. Raising a ClassCastException and requiring to exclude stuff does not fall under "getting out of the way" for me.

Some alternatives (Documentation to patch up flaws does not seem right to me):

LoggingSystem.get() could detect all known logging systems, and could throw some ConfigurationError when detecting multiple log systems, telling the user they have to clean up their classpath for Spring boot to startup.

A somewhat better solution would be for LoggingSystem.get() to return all detected LoggingSystems, not just an arbitrary one, and then for the LoggingApplicationContextInitializer to try them all out, catching classCastExceptions. It should then use the first one that can be initialized, but also raise a warning telling the users to get rid of all other logging libraries in the classpath, pointing to documentation.

Another way is to include log4J-over-slf in the spring-boot-starter-logging pom.xml. https://github.com/spring-projects/spring-boot/blob/master/spring-boot-starters/spring-boot-starter-logging/pom.xml This way the users at least get the conflict early at build time, not at runtime. Documentation could help then, but still it would be a pain for users to go find the documentation.

What I would prefer as a solution would be for spring-boot-logging-starter to NOT depend at runtime on any build system in the classpath, but instead to detect log systems at startup, and then handling any ClassNotFoundException by telling users to configure some logging system for runtime, pointing to documentation. I believe it is acceptable for users that they have to include some logging system in their classpath to get started, much more acceptable than having to manage exclusions, which are much more painful to set up in any buildsystem.

That way the buildfiles and classpath remain clean when including spring-boot starters, and the necessary steps for users are obvious without having to read documentation. java-uti-logging could also be used as a default in the absence fof other logging configuration, because it is conflict-free, I guess.

[dsyer]

Thanks for all the analysis.

• I think you are right that LoggingSystem.get() could do something more useful to inform users if there is a conflict (pull request welcome on that one) - the exception might be the best option.
• The inclusion of log4j-over-slf4j in the actuator is something we should take a long look at as well (and your suggestion of putting it in the logging starter might be a good first step).
• LoggingSystem.get() does not return an "arbitrary" system: it returns the best choice it can find (logback is preferred over log4j).

All your other points are well made and we have considered them all at some point before.

• Spring Boot started life with java-util-logging as the default system (for the reason you suggest), but it is such a poor cousin of the other systems that we felt all users would want to choose a "real" system for production use, and that would break one of our principles of taking code straight to production as quickly as possible.
• The logging starter makes no sense if it doesn't have an opinion and choose a concrete system. We chose logback because it has a lot of good features and is the "modern" choice. Log4J would have also been a sensible choice as well, but you have to choose one. To be clear on this: we prefer to make a concrete choice in the starters, but leave it open in the core libraries. Users have the choice not to use the starters.

[tkruse]

"Arbitrary" for the choice of LoggingSystem.get() sounds a bit harsh. I meant arbitrary in the sense that making a choice at all is arbitrary when multiple logsystems are in the classpath.

I like the logging starter to have an opinion, but I "feel" it should be a separate feature of spring boot, such as a separate package spring-boot-logging-default, or so. Something that can be copy-pasted to get started easily, but also easily be removed when using non-defaults, without the need to write exclude rules.

If there is a possibility that spring-boot will move to e.g. log4J2 in the future, I would possibly rename this to spring-boot-logging-logback, such that current systems using logback configuration will not break when switching to newer versions of spring-boot using log4j2. (Using explicit deprecation for logback when it comes to that).

There could also be an "umbrella" spring boot package wrapping all autoconfiguration and all opinionated defaults together for quick one-line bootstrapping of projects. As long as it is easy to ged rid of the opinionated defaults, I grant the promise of "keeping out of the way" as being kept.

Keeping the runtime classpath clean seems tremendously important to me to move forward with spring boot in the future, as new technologies and libraries emerge over time. The promise of keeping out of the way cannot be kept when spring-boot allows itself to drop unused dependencies to the classpath. They will always be "in the way".

I would even extend this principle to jackson and hibernate validators, to me it seems spring-boot would do a greater service to its users if autoconfigure merely refused to startup unless the users put viable alternatives into their classpath, either by choosing explicitly themselves or by stating spring-boot-...-default packages as dependencies.

As long as core spring-boot only detects defaults at runtime, but does not provide them as dependencies at assembly time, systems based on spring boot can migrate to newer versions of spring boot without hassle and FUD. The user decides what goes into the classpath, spring-boot is only there to yell at the user if he wants logging but did not decide on a logging system, or if he wants Json mapping but did not decide on a mapper technology. Spring boot may additinoally provide defaults for autoconfiguration, but separated from autoconfiguration, so that users can get rid of the opinionated defaults without writing exclude rules or losing autoconfiguration.

This should be a precedent for all future technologies that rely on classpath scanning for autoconfiguration, any such tool in the future should not drop anything in the classpath that it scans for.

[tkruse]

Hm, I am still very new to spring boot. Looking closer at the contents of packages, it seems that spring-boot-...-starter packages are the ones providing defaults, but no code. So by getting rid of all spring-boot-starter dependencies, and adding e.g.

compile ("org.springframework.boot:spring-boot:$SPRING_BOOT_VERSION")

I can get what I want without exclusion rules (autoconfiguration), but have to provide own dependencies in the absence of defaults.

[dsyer]

That last commit added some documentation (howto.md) and a new spring-boot-starter-log4j. I didn't see the ClassCastException at any time in testing so maybe if that's still a problem you could indicate how best to defend against it (maybe send a pull request)?

[dsyer]

I'm going to close this for now, since some changes were made along the lines we discussed. If you can try it again and send steps to reproduce the exception as part of a separate issue that would be great.

[tkruse]

ok, will look at it again when I find time. If you could point me to a quick way to set up a project against Spring boot from source, that would help.

On Thu, Dec 19, 2013 at 9:51 AM, Dave Syer notifications@github.com wrote:

I'm going to close this for now, since some changes were made along the lines we discussed. If you can try it again and send steps to reproduce the exception as part of a separate issue that would be great.

— Reply to this email directly or view it on GitHubhttps://github.com/spring-projects/spring-boot/issues/162#issuecomment-30913439 .

[dsyer]

Use the samples? They all have tests.

[tkruse]

fair enough

On Thu, Dec 19, 2013 at 10:33 PM, Dave Syer notifications@github.comwrote:

Use the samples? They all have tests.

— Reply to this email directly or view it on GitHubhttps://github.com/spring-projects/spring-boot/issues/162#issuecomment-30968533 .

[tkruse]

I can still reproduce on master branch. In the tkruse/spring-boot@b1b8aa6d763b0e55da1 branch I get:

$ mvn clean package
...
$ java -jar target/spring-boot-sample-jetty-0.5.0.BUILD-SNAPSHOT.jar 
SLF4J: Class path contains multiple SLF4J bindings.
SLF4J: Found binding in [jar:file:/home/kruset/work/java/spring-boot/spring-boot-samples/spring-boot-sample-jetty/target/spring-boot-sample-jetty-0.5.0.BUILD-SNAPSHOT.jar!/lib/slf4j-log4j12-1.7.5.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: Found binding in [jar:file:/home/kruset/work/java/spring-boot/spring-boot-samples/spring-boot-sample-jetty/target/spring-boot-sample-jetty-0.5.0.BUILD-SNAPSHOT.jar!/lib/logback-classic-1.0.13.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: See http://www.slf4j.org/codes.html#multiple_bindings for an explanation.
SLF4J: Actual binding is of type [org.slf4j.impl.Log4jLoggerFactory]
17:45:23,962  INFO utoConfigurationReportLoggingInitializer:  91 - Nothing to report: ApplicationContext not available
java.lang.reflect.InvocationTargetException
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:616)
    at org.springframework.boot.loader.MainMethodRunner.run(MainMethodRunner.java:53)
    at java.lang.Thread.run(Thread.java:679)
Caused by: java.lang.ClassCastException: org.slf4j.impl.Log4jLoggerFactory cannot be cast to ch.qos.logback.classic.LoggerContext
    at org.springframework.boot.logging.logback.LogbackLoggingSystem.initialize(LogbackLoggingSystem.java:81)
    at org.springframework.boot.logging.AbstractLoggingSystem.initializeWithSensibleDefaults(AbstractLoggingSystem.java:60)
    at org.springframework.boot.logging.AbstractLoggingSystem.beforeInitialize(AbstractLoggingSystem.java:45)
    at org.springframework.boot.logging.logback.LogbackLoggingSystem.beforeInitialize(LogbackLoggingSystem.java:68)
    at org.springframework.boot.context.initializer.LoggingApplicationContextInitializer.initialize(LoggingApplicationContextInitializer.java:108)
    at org.springframework.boot.SpringApplication.callNonEnvironmentAwareSpringApplicationInitializers(SpringApplication.java:380)
    at org.springframework.boot.SpringApplication.run(SpringApplication.java:293)
    at org.springframework.boot.SpringApplication.run(SpringApplication.java:806)
    at org.springframework.boot.SpringApplication.run(SpringApplication.java:795)
    at org.springframework.boot.sample.jetty.SampleJettyApplication.main(SampleJettyApplication.java:37)

Note not all changes I made in the commit might be required to reproduce.

[tkruse]

Sorry, branch name on my fork is is issue162.

[tkruse]

Also it seems building and running the app as i do does not use the spring-boot sources, but takes the 0.5.0.BUILD-SNAPSHOT jars from some server, not sure how to tell maven to use local sources.

[dsyer]

I'm not sure you can use local sources per se from the command line (an IDE like Eclipse might be different), but if you "mvn install -DskipTests=true" before you start work on your sample the jars will be up to date in your local cache. It looks to me like you severely pranged the main build in your branch though (lots of apparently unrelated changes to poms). You probably should take smaller steps if you want to get something working.