I'm part of Google Cloud engineering team, and I'm looking into making sure Spring-Boot apps could run seamlessly on Google App Engine Java 8 runtime.

Version: 1.5.2-RELEASE

Issue Description: Currently, Spring-Boot logging does not work out of the box for a simple (spring-boot-starter-web) hello world app running on App Engine Java 8.

My understanding is that Spring-boot starter relies on Logback. See LogbackLoggingSystem.

Logback in turn relies on Slf4J, which during the initialization removes all previously configured handlers for Java Util's root logger. See Slf4JLoggingSystem.

This is problematic for App Engine Standard Java runtime, which relies on root logger handler itself to properly route log messages.

SLF4JBridgeHandler javadoc states that the removal of root handlers is optional. See the documentation.

Would it be possible not to call SLF4JBridgeHandler.removeHandlersForRootLogger() from Slf4JLoggingSystem?

To reproduce the issue, one needs an App Engine application that is white-listed for Java 8 runtime, and I'd be happy to help with this.

Comment From: snicoll

To get you going with 1.5.2.RELEASE in the meantime there are a couple of options.

First you can remove logback and slf4j altogether if you add the following to your build

<dependency>
    <groupId>org.springframework.boot</groupId>
    <artifactId>spring-boot-starter</artifactId>
    <exclusions>
        <exclusion>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-logging</artifactId>
        </exclusion>
    </exclusions>
</dependency>
<dependency>
    <groupId>commons-logging</groupId>
    <artifactId>commons-logging</artifactId>
    <version>1.2</version>
</dependency>

Or you can take control over the LoggingSystem by specifying a system property (see the doc). You can inherit or copy the bits you need for the time being.

Comment From: ifigotin

Stéphane, thank you for looking into this.

I explored various workarounds earlier, and the best one that worked well on App Engine runtime at the moment was to exclude org.slf4j:jul-to-slf4j dependency.

The next best was to set LoggingSystem to 'none' via the system property, and to provide a basic logback.xml as described here.

The approach of excluding spring-boot-starter-logging, and adding commons-logging instead didn't work for our runtime. I didn't quite figure out why yet, but my suspicion is that because we have other configuration files on the classpath (e.g. logging.properties for JUL) there is a mis-configuration somewhere.

Comment From: snicoll

I wasn't aware that you've explored various workarounds already. Looks like you're set until we figure out what to do with this issue.

Comment From: ifigotin

Yes, thanks again.

I have a similar concern regarding JavaLoggingSystem. Shall I fill a different issue for that one? Please, let me know.

The JavaLoggingSystem, when used within App Engine Java Standard Runtime, will currently interfere with Java Util Logging used by the runtime.

I.e. JavaLoggingSystem essentially would reset the previous configuration by calling LogManager.getLogManager().readConfiguration().

Comment From: snicoll

If that's the same root we can broaden the scope of this issue.

Comment From: ifigotin

Yes, in my opinion, the main cause is similar. When running within a runtime (e.g. App Engine java runtime), the logging configuration may already be configured/provided, however, the logging systems currently assume that there is no previous configuration.

Comment From: imgx64

This also prevents the use of Tomcat's per-webapp logging. I'll explain how.

Tomcat has a custom logging system called JULI that implements java.util.logging.LogManager and is installed by default*. Internal Tomcat classes log using JUL.

By default, Spring Boot includes jul-to-slf4 and calls SLF4JBridgeHandler.removeHandlersForRootLogger() and SLF4JBridgeHandler.install() in Slf4JLoggingSystem (this is this bug). This redirects all logs from Internal Tomcat classes as well as JUL calls from other applications into the current Spring Boot application's logback config. This is obviously not desirable, and causes even more issues if multiple Boot apps are installed on the same Tomcat instance.

As a way to avoid situations like this, JULI allows per-webapp configuration by adding WEB-INF/classes/logging.properties inside the webapp. It's possible to configure slf4j to handle JUL calls made inside the current webapp only (without affecting JUL calls made by other webapps and by Tomcat itself) by including jul-to-slf4 and adding src/main/resources/logging.properties with content handlers=org.slf4j.bridge.SLF4JBridgeHandler.

Unfortunately, there is no way to tell Slf4JLoggingSystem to not call SLF4JBridgeHandler.removeHandlersForRootLogger() and SLF4JBridgeHandler.install() as long as jul-to-slf4 exists on the classpath.

*: It's installed by default if you run Tomcat using the scripts provided with Tomcat (catalina.sh, startup.sh, etc.). For some reason, it's not installed if you run Tomcat from Eclipse. Probably a bug in Eclipse, but I haven't investigated it.

Comment From: imgx64

I can think of two solutions: 1. Add a configuration property to disable calling the SLF4JBridgeHandler methods. 2. Detect if the application is running as a WAR in a servlet container, and not call the SLF4JBridgeHandler methods in that case. I'm not familiar with Google App Engine's Java environment, but it seems to be using Jetty, so it would be detected as well. If the user really wants this, they can always call the SLF4JBridgeHandler methods themselves.

Comment From: wyaeld

I have a likely-related issue, we are trying to run SpringBoot apps on GKE (Google Container Engine), and use com.google.cloud.logging.logback.LoggingAppender to stream the logs to Google Stackdriver.

However as soon as the appender is included in logback-spring.xml, the app fails to start, or log anything. It does work if we switch to logback.xml and avoid the spring patterning, but I'd rather not have to do that.

This is using the latest 1.5 spring boot.

@ifigotin does that sound correct, or would the GKE stackdriver issue be different?

Comment From: ifigotin

@wyaeld I think this may be a different issue. Here we were referring to a SpringBoot app that runs in App Engine Java runtime that has its own logging system that may interfere with SprintBoot's logging. In your case, I assume you are running in a vanila JRE (within GKE)?

Comment From: ifigotin

Actually, I'm not that familiar with what Stackdriver libraries do. It could indeed be a similar issue, if these libraries rely on log handlers that are removed by Slf4JLoggingSystem.

Comment From: wyaeld

We run actually run on top of the AppEngine containerized version of OpenJDK, since it seems well tuned for your platform. The only difference I can see through more testing is that is Spring is allowed to configure things, it is likely removing log handlers that we need. Not much else explains the logging content just disappearing

Comment From: ifigotin

Are you referring to https://github.com/GoogleCloudPlatform/openjdk-runtime? I believe these images contain vanila JDK.

The fact that Slf4JLoggingSystem removes log handlers, may affect you in any case if you (or the libraries the app is using) add some of these handlers earlier.

Comment From: wyaeld

Yes, that's the one. The cgroup commands in the java-env script simplify our work getting java to pay attention to k8s imposed limits.

Currently trying to see the clearest way from the comments above. My goal is to just have the logs written to stdout/err and let k8s ship them to stackdriver, but with all the various logging levels mapped correctly to the JUL levels stackdriver is using.

Comment From: wyaeld

@ifigotin @snicoll have a working configuration after many challenges, involves using: 1) Spring profile values to switch between application.properties and application-production.properties 2) set logging.config between different logback.xml and logback-production.xml 3) have the production config use a custom layout pattern that emits Json structured for stackdriver. 4) Excluding spring-starter-logging but including all the X-to-SLF4J libs

Comment From: meltsufin

Hi @wyaeld, I work on the spring-cloud-gcp project and we're planning to work on improving the logging experience in Spring Boot with Stackdriver Logging. Can you clarify what exactly you did to resolve your problem? Can you share the relevant parts of the files you mentioned? It would be very helpful for our work. Thanks!

Comment From: wyaeld

I don't mind contributing back, the solution was built on the shoulders of plenty of other people in the community. I'll open up another issue on your project if you like, rather than sidetrack this particular bug further

Comment From: meltsufin

Sure, you can comment on this issue https://github.com/spring-cloud/spring-cloud-gcp/issues/154, or create another one in the project. Thanks!

Comment From: wilkinsona

It looks to me like we can call uninstall() rather than removeHandlersForRootLogger().

Comment From: snicoll

@wilkinsona I gave that a try to see where we stand. JARCommandIT#jarCreationWithGrabResolver started failing

java.lang.AssertionError: 
Expected: ""
     but: was "Jan 24, 2018 4:11:40 PM org.springframework.boot.StartupInfoLogger logStarting\nINFO: Starting application on leo.lan with PID 28298 (/Users/snicoll/workspace/pivotal/spring-boot/spring-boot-project/spring-boot-cli/target/unpacked-cli/spring-2.0.0.BUILD-SNAPSHOT/lib/spring-boot-cli-2.0.0.BUILD-SNAPSHOT.jar started by snicoll in /Users/snicoll/workspace/pivotal/spring-boot/spring-boot-project/spring-boot-cli/src/it/resources/jar-command)\nJan 24, 2018 4:11:40 PM org.springframework.boot.SpringApplication logStartupProfileInfo\nINFO: No active profile set, falling back to default profiles: default\nJan 24, 2018 4:11:41 PM org.springframework.context.support.AbstractApplicationContext prepareRefresh\nINFO: Refreshing org.springframework.context.annotation.AnnotationConfigApplicationContext@28308740: startup date [Wed Jan 24 16:11:41 CET 2018]; root of context hierarchy\nJan 24, 2018 4:11:41 PM org.springframework.jmx.export.MBeanExporter afterSingletonsInstantiated\nINFO: Registering beans for JMX exposure on startup\nJan 24, 2018 4:11:41 PM org.springframework.boot.StartupInfoLogger logStarted\nINFO: Started application in 1.392 seconds (JVM running for 4.712)\nJan 24, 2018 4:11:41 PM org.springframework.context.support.AbstractApplicationContext doClose\nINFO: Closing org.springframework.context.annotation.AnnotationConfigApplicationContext@28308740: startup date [Wed Jan 24 16:11:41 CET 2018]; root of context hierarchy\n"

Comment From: wilkinsona

We need a different fix for this as Tomcat's logging is now duplicated.

Comment From: ppkarwasz

@wilkinsona: I believe the solution of this issue might still be improved.

Right now the following heuristic is used: if JUL uses up to a single ConsoleHandler then we can replace it. This can for example redirect all the output of a Jetty servlet container to a single application.

IMHO the logic should be:

  • if we own the JVM (e.g. we also installed a shutdown hook) then we can replace JUL's configuration at will,
  • if we don't own the JVM usually JUL's configuration is off-limits since it would influence other applications.

An exception to the second rule might be Tomcat with a ClassLoaderLogManager installed, a context classloader implementing WebappProperties and having hasLoggingConfig() == true.

I wouldn't mind if Spring Boot forced the latter condition by including an empty logging.properties in the jar: a developer can always override it by providing a different configuration in the WARs WEB-INF/classes.

Comment From: wilkinsona

Please open a new issue if you think there’s some room for further improvement. Note that the logging system should have no direct knowledge of Tomcat so any solution would have to avoid referencing ClassLoaderLogManager and the like.