Logback NPE on OpenShift

[maros7]

While deploying a Spring Boot app that uses GCP Stackdriver logging on an on-premise OpenShift environment I encountered a NPE while the logback-spring.xml was being loaded. I was using the config as per your example. It was quite puzzling since it was working when starting the Docker container locally. As you can see the error doesn't tell that much.

java.lang.IllegalStateException: Logback configuration error detected:
--
  | ERROR in ch.qos.logback.core.joran.spi.Interpreter@15:14 - RuntimeException in Action for tag [appender] java.lang.NullPointerException
  | at org.springframework.boot.logging.logback.LogbackLoggingSystem.loadConfiguration(LogbackLoggingSystem.java:169)
  | at org.springframework.boot.logging.AbstractLoggingSystem.initializeWithConventions(AbstractLoggingSystem.java:82)
  | at org.springframework.boot.logging.AbstractLoggingSystem.initialize(AbstractLoggingSystem.java:60)
  | at org.springframework.boot.logging.logback.LogbackLoggingSystem.initialize(LogbackLoggingSystem.java:117)
  | at org.springframework.boot.context.logging.LoggingApplicationListener.initializeSystem(LoggingApplicationListener.java:293)
  | at org.springframework.boot.context.logging.LoggingApplicationListener.initialize(LoggingApplicationListener.java:266)
  | at org.springframework.boot.context.logging.LoggingApplicationListener.onApplicationEnvironmentPreparedEvent(LoggingApplicationListener.java:229)
  | at org.springframework.boot.context.logging.LoggingApplicationListener.onApplicationEvent(LoggingApplicationListener.java:202)
  | at org.springframework.context.event.SimpleApplicationEventMulticaster.doInvokeListener(SimpleApplicationEventMulticaster.java:172)
  | at org.springframework.context.event.SimpleApplicationEventMulticaster.invokeListener(SimpleApplicationEventMulticaster.java:165)
  | at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:139)
  | at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:127)
  | at org.springframework.boot.context.event.EventPublishingRunListener.environmentPrepared(EventPublishingRunListener.java:75)
  | at org.springframework.boot.SpringApplicationRunListeners.environmentPrepared(SpringApplicationRunListeners.java:54)
  | at org.springframework.boot.SpringApplication.prepareEnvironment(SpringApplication.java:347)
  | at org.springframework.boot.SpringApplication.run(SpringApplication.java:306)
  | at org.springframework.boot.builder.SpringApplicationBuilder.run(SpringApplicationBuilder.java:139)
  | at org.springframework.cloud.bootstrap.BootstrapApplicationListener.bootstrapServiceContext(BootstrapApplicationListener.java:191)
  | at org.springframework.cloud.bootstrap.BootstrapApplicationListener.onApplicationEvent(BootstrapApplicationListener.java:105)
  | at org.springframework.cloud.bootstrap.BootstrapApplicationListener.onApplicationEvent(BootstrapApplicationListener.java:71)
  | at org.springframework.context.event.SimpleApplicationEventMulticaster.doInvokeListener(SimpleApplicationEventMulticaster.java:172)
  | at org.springframework.context.event.SimpleApplicationEventMulticaster.invokeListener(SimpleApplicationEventMulticaster.java:165)
  | at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:139)
  | at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:127)
  | at org.springframework.boot.context.event.EventPublishingRunListener.environmentPrepared(EventPublishingRunListener.java:75)
  | at org.springframework.boot.SpringApplicationRunListeners.environmentPrepared(SpringApplicationRunListeners.java:54)
  | at org.springframework.boot.SpringApplication.prepareEnvironment(SpringApplication.java:347)
  | at org.springframework.boot.SpringApplication.run(SpringApplication.java:306)
  | at org.springframework.boot.SpringApplication.run(SpringApplication.java:1260)
  | at org.springframework.boot.SpringApplication.run(SpringApplication.java:1248)
  | at com.ikea.rix.cloud.sync.crccem.Application.main(Application.java:23)
  | at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
  | at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
  | at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
  | at java.base/java.lang.reflect.Method.invoke(Method.java:566)
  | at org.springframework.boot.loader.MainMethodRunner.run(MainMethodRunner.java:48)
  | at org.springframework.boot.loader.Launcher.launch(Launcher.java:87)
  | at org.springframework.boot.loader.Launcher.launch(Launcher.java:50)
  | at org.springframework.boot.loader.JarLauncher.main(JarLauncher.java:51)

So I created a CustomerAppender which simply extended LoggingAppender overriding the LoggingAppender#start method.

import com.google.cloud.logging.logback.LoggingAppender;

public class CustomAppender extends LoggingAppender {

  @Override
  public synchronized void start() {
    try {
      super.start();
    } catch (Exception e) {
      e.printStackTrace();
    }
  }
}

Now I got a more informative exception message:

java.lang.NullPointerException
--
  | at com.google.cloud.MetadataConfig.getZone(MetadataConfig.java:46)
  | at com.google.cloud.logging.MonitoredResourceUtil.getValue(MonitoredResourceUtil.java:164)
  | at com.google.cloud.logging.MonitoredResourceUtil.getResource(MonitoredResourceUtil.java:115)
  | at com.google.cloud.logging.logback.LoggingAppender.getMonitoredResource(LoggingAppender.java:134)
  | at com.google.cloud.logging.logback.LoggingAppender.start(LoggingAppender.java:180)
  | at com.ikea.rix.cloud.sync.crccem.logging.CustomAppender.start(CustomAppender.java:10)
  | at ch.qos.logback.core.joran.action.AppenderAction.end(AppenderAction.java:90)
  | at ch.qos.logback.core.joran.spi.Interpreter.callEndAction(Interpreter.java:309)
  | at ch.qos.logback.core.joran.spi.Interpreter.endElement(Interpreter.java:193)
  | at ch.qos.logback.core.joran.spi.Interpreter.endElement(Interpreter.java:179)
  | at ch.qos.logback.core.joran.spi.EventPlayer.play(EventPlayer.java:62)
  | at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:165)
  | at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:152)
  | at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:110)
  | at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:53)
  | at org.springframework.boot.logging.logback.LogbackLoggingSystem.configureByResourceUrl(LogbackLoggingSystem.java:180)
  | at org.springframework.boot.logging.logback.LogbackLoggingSystem.loadConfiguration(LogbackLoggingSystem.java:152)
  | at org.springframework.boot.logging.AbstractLoggingSystem.initializeWithConventions(AbstractLoggingSystem.java:82)
  | at org.springframework.boot.logging.AbstractLoggingSystem.initialize(AbstractLoggingSystem.java:60)
  | at org.springframework.boot.logging.logback.LogbackLoggingSystem.initialize(LogbackLoggingSystem.java:117)
  | at org.springframework.boot.context.logging.LoggingApplicationListener.initializeSystem(LoggingApplicationListener.java:293)
  | at org.springframework.boot.context.logging.LoggingApplicationListener.initialize(LoggingApplicationListener.java:266)
  | at org.springframework.boot.context.logging.LoggingApplicationListener.onApplicationEnvironmentPreparedEvent(LoggingApplicationListener.java:229)
  | at org.springframework.boot.context.logging.LoggingApplicationListener.onApplicationEvent(LoggingApplicationListener.java:202)
  | at org.springframework.context.event.SimpleApplicationEventMulticaster.doInvokeListener(SimpleApplicationEventMulticaster.java:172)
  | at org.springframework.context.event.SimpleApplicationEventMulticaster.invokeListener(SimpleApplicationEventMulticaster.java:165)
  | at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:139)
  | at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:127)
  | at org.springframework.boot.context.event.EventPublishingRunListener.environmentPrepared(EventPublishingRunListener.java:75)
  | at org.springframework.boot.SpringApplicationRunListeners.environmentPrepared(SpringApplicationRunListeners.java:54)
  | at org.springframework.boot.SpringApplication.prepareEnvironment(SpringApplication.java:347)
  | at org.springframework.boot.SpringApplication.run(SpringApplication.java:306)
  | at org.springframework.boot.builder.SpringApplicationBuilder.run(SpringApplicationBuilder.java:139)
  | at org.springframework.cloud.bootstrap.BootstrapApplicationListener.bootstrapServiceContext(BootstrapApplicationListener.java:191)
  | at org.springframework.cloud.bootstrap.BootstrapApplicationListener.onApplicationEvent(BootstrapApplicationListener.java:105)
  | at org.springframework.cloud.bootstrap.BootstrapApplicationListener.onApplicationEvent(BootstrapApplicationListener.java:71)
  | at org.springframework.context.event.SimpleApplicationEventMulticaster.doInvokeListener(SimpleApplicationEventMulticaster.java:172)
  | at org.springframework.context.event.SimpleApplicationEventMulticaster.invokeListener(SimpleApplicationEventMulticaster.java:165)
  | at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:139)
  | at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:127)
  | at org.springframework.boot.context.event.EventPublishingRunListener.environmentPrepared(EventPublishingRunListener.java:75)
  | at org.springframework.boot.SpringApplicationRunListeners.environmentPrepared(SpringApplicationRunListeners.java:54)
  | at org.springframework.boot.SpringApplication.prepareEnvironment(SpringApplication.java:347)
  | at org.springframework.boot.SpringApplication.run(SpringApplication.java:306)
  | at org.springframework.boot.SpringApplication.run(SpringApplication.java:1260)
  | at org.springframework.boot.SpringApplication.run(SpringApplication.java:1248)
  | at com.ikea.rix.cloud.sync.crccem.Application.main(Application.java:23)
  | at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
  | at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
  | at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
  | at java.base/java.lang.reflect.Method.invoke(Method.java:566)
  | at org.springframework.boot.loader.MainMethodRunner.run(MainMethodRunner.java:48)
  | at org.springframework.boot.loader.Launcher.launch(Launcher.java:87)
  | at org.springframework.boot.loader.Launcher.launch(Launcher.java:50)
  | at org.springframework.boot.loader.JarLauncher.main(JarLauncher.java:51)

When the environment variable KUBERNETES_SERVICE_HOST is set they will default to container and not global. See https://github.com/googleapis/google-cloud-java/blob/master/google-cloud-clients/google-cloud-logging/src/main/java/com/google/cloud/logging/MonitoredResourceUtil.java#L177. Thus resulting in a NPE in https://github.com/googleapis/google-cloud-java/blob/master/google-cloud-clients/google-cloud-core/src/main/java/com/google/cloud/MetadataConfig.java#L44-L49 when running on a non GKE Kubernetes. I was able to work around this issue by using this logback-spring.xml.

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
  <include resource="org/springframework/boot/logging/logback/defaults.xml" />
  <include resource="org/springframework/boot/logging/logback/console-appender.xml" />

  <property name="STACKDRIVER_LOG_NAME" value="${STACKDRIVER_LOG_NAME:-spring.log}"/>
  <property name="STACKDRIVER_LOG_FLUSH_LEVEL" value="${STACKDRIVER_LOG_FLUSH_LEVEL:-WARN}"/>
  <property name="STACKDRIVER_RESOURCE_TYPE" value="${STACKDRIVER_RESOURCE_TYPE:-global}"/>

  <appender name="STACKDRIVER" class="com.google.cloud.logging.logback.LoggingAppender">
    <log>${STACKDRIVER_LOG_NAME}</log>
    <enhancer>org.springframework.cloud.gcp.autoconfigure.logging.TraceIdLoggingEnhancer</enhancer>
    <flushLevel>${STACKDRIVER_LOG_FLUSH_LEVEL}</flushLevel>
    <resourceType>${STACKDRIVER_RESOURCE_TYPE}</resourceType>
  </appender>

  <root level="INFO">env
    <appender-ref ref="CONSOLE" />
    <appender-ref ref="STACKDRIVER" />
  </root>
</configuration>

But maybe this should be noted in the documentation?

[meltsufin]

Thanks for such a detailed report @maros7!
It just looks like a bug in the Google Cloud Java Logging library. First, not everything that runs in a container runs on GKE. Second, zoneId.contains("/") should be guarded against zoneId being null.
Is that right, or am I missing something?
Would you mind filing the issue on Google Cloud Java Github as well? Otherwise, we can do it. Thanks!

[maros7]

@meltsufin No, that’s how I see it as well and I can file the issue.

[meltsufin]

Thanks! Please link to it here, when you have it.

[meltsufin]

Fixed upstream.