Skip to content
This repository has been archived by the owner on Jan 19, 2022. It is now read-only.

Logback NPE on OpenShift #1355

Closed
maros7 opened this issue Jan 3, 2019 · 4 comments
Closed

Logback NPE on OpenShift #1355

maros7 opened this issue Jan 3, 2019 · 4 comments
Labels
logging

Comments

@maros7
Copy link

maros7 commented Jan 3, 2019

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
Copy link
Contributor

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
Copy link
Author

maros7 commented Jan 3, 2019

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

@meltsufin
Copy link
Contributor

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

@maros7 maros7 mentioned this issue Jan 3, 2019
Closed
@meltsufin
Copy link
Contributor

Fixed upstream.

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
logging
Milestone
No milestone
Development

No branches or pull requests
2 participants
@meltsufin @maros7