Application does not start with the OTel Spring Boot starter + OTel Logback appender, from 1.27.0 version

[jeanbisutti]

Steps to reproduce

See this commit

• Add the OTel Spring Boot starter 1.27.0 dependency
• Add OTel Logback appender 1.27.0 dependency
• Add an XML Logback file using the OTel Logback appender

Start the Spring Boot application

Explanations about the issue

The interesting part of the stack:

Caused by: java.lang.IllegalStateException: GlobalOpenTelemetry.set has already been called. GlobalOpenTelemetry.set must be called only once before any calls to GlobalOpenTelemetry.get. If you are using the OpenTelemetrySdk, use OpenTelemetrySdkBuilder.buildAndRegisterGlobal instead. Previous invocation set to cause of this exception.
	at io.opentelemetry.api.GlobalOpenTelemetry.set(GlobalOpenTelemetry.java:104)
	at io.opentelemetry.instrumentation.spring.autoconfigure.OpenTelemetryAutoConfiguration$OpenTelemetrySdkConfig.openTelemetry(OpenTelemetryAutoConfiguration.java:145)
	at io.opentelemetry.instrumentation.spring.autoconfigure.OpenTelemetryAutoConfiguration$OpenTelemetrySdkConfig$$SpringCGLIB$$0.CGLIB$openTelemetry$0(<generated>)
	at io.opentelemetry.instrumentation.spring.autoconfigure.OpenTelemetryAutoConfiguration$OpenTelemetrySdkConfig$$SpringCGLIB$$2.invoke(<generated>)
	at org.springframework.cglib.proxy.MethodProxy.invokeSuper(MethodProxy.java:258)
	at org.springframework.context.annotation.ConfigurationClassEnhancer$BeanMethodInterceptor.intercept(ConfigurationClassEnhancer.java:331)
	at io.opentelemetry.instrumentation.spring.autoconfigure.OpenTelemetryAutoConfiguration$OpenTelemetrySdkConfig$$SpringCGLIB$$0.openTelemetry(<generated>)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:568)
	at org.springframework.beans.factory.support.SimpleInstantiationStrategy.instantiate(SimpleInstantiationStrategy.java:139)
	... 69 common frames omitted
Caused by: java.lang.Throwable: null
	at io.opentelemetry.api.GlobalOpenTelemetry.set(GlobalOpenTelemetry.java:112)
	at io.opentelemetry.api.GlobalOpenTelemetry.get(GlobalOpenTelemetry.java:82)
	at io.opentelemetry.instrumentation.logback.appender.v1_0.OpenTelemetryAppender.append(OpenTelemetryAppender.java:45)
	at io.opentelemetry.instrumentation.logback.appender.v1_0.OpenTelemetryAppender.append(OpenTelemetryAppender.java:19)
	at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:85)
	at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:51)
	at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:272)
	at ch.qos.logback.classic.Logger.callAppenders(Logger.java:259)
	at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:426)
	at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:386)
	at ch.qos.logback.classic.Logger.log(Logger.java:780)
	at org.apache.commons.logging.LogAdapter$Slf4jLocationAwareLog.info(LogAdapter.java:445)
	at org.springframework.boot.StartupInfoLogger.logStarting(StartupInfoLogger.java:51)
	at org.springframework.boot.SpringApplication.logStartupInfo(SpringApplication.java:617)
	at org.springframework.boot.SpringApplication.prepareContext(SpringApplication.java:390)
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:310)

Explanations of the problem are given below.

Spring Boot logs start up info:

	at org.springframework.boot.StartupInfoLogger.logStarting(StartupInfoLogger.java:51)
	at org.springframework.boot.SpringApplication.logStartupInfo(SpringApplication.java:617)
	at org.springframework.boot.SpringApplication.prepareContext(SpringApplication.java:390)
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:310)

An append method of OpenTelemetryAppender calls GlobalOpenTelemetry.get() which initializes GlobalOpenTelemetry with OpenTelemetry.noop():

	at io.opentelemetry.api.GlobalOpenTelemetry.set(GlobalOpenTelemetry.java:112)
	at io.opentelemetry.api.GlobalOpenTelemetry.get(GlobalOpenTelemetry.java:82)
	at io.opentelemetry.instrumentation.logback.appender.v1_0.OpenTelemetryAppender.append(OpenTelemetryAppender.java:45)

After, OpenTelemetryAutoConfiguration reinitiliazes GlobalOpenTelemetry:

	at io.opentelemetry.api.GlobalOpenTelemetry.set(GlobalOpenTelemetry.java:104)
	at io.opentelemetry.instrumentation.spring.autoconfigure.OpenTelemetryAutoConfiguration$OpenTelemetrySdkConfig.openTelemetry(OpenTelemetryAutoConfiguration.java:145)

In the end, an exception is raised.

Today, this repo does not contain automatic tests with the OTel Spring Boot starter and the Otel Logback appender. I will create an issue about the addition of automatic tests related to the OTel Spring Boot starter.

I tested on my side the OTLP log export for the OpenTelemetry Spring Starter. A this time, GlobalLoggerProvider was still in use. The feature worked well with the OTel Logbkack appender because GlobalLoggerProvider.get did not call GlobalLoggerProvider.set (but GlobalOpenTelemetry.set can be called from GlobalOpenTelemetry.get)

public final class GlobalLoggerProvider {

  private static final AtomicReference<LoggerProvider> instance =
      new AtomicReference<>(LoggerProvider.noop());

  @Nullable private static volatile Throwable setInstanceCaller;

  private GlobalLoggerProvider() {}

  /** Returns the globally registered {@link LoggerProvider}. */
  // instance cannot be set to null
  @SuppressWarnings("NullAway")
  public static LoggerProvider get() {
    return instance.get();
  }

  /**
   * Sets the global {@link LoggerProvider}. Future calls to {@link #get()} will return the provided
   * {@link LoggerProvider} instance. This should be called once as early as possible in your
   * application initialization logic.
   */
  public static void set(LoggerProvider loggerProvider) {
    boolean changed = instance.compareAndSet(LoggerProvider.noop(), loggerProvider);
    if (!changed && (loggerProvider != LoggerProvider.noop())) {
      throw new IllegalStateException(
          "GlobalLoggerProvider.set has already been called. GlobalLoggerProvider.set "
              + "must be called only once before any calls to GlobalLoggerProvider.get. "
              + "Previous invocation set to cause of this exception.",
          setInstanceCaller);
    }
    setInstanceCaller = new Throwable();
  }

Shortly afterwards, GlobalLoggerProvider was replaced with GlobalOpenTelemetry.

What version are you using?
1.27.0

[jack-berg]

My comment on this related issue is relevant here:

we currently break out own advice regarding avoiding GlobalOpenTelemetry.get() calls in the log appenders. We recently talked about this in the log SIG and are investigating programatic configuration of log appender OpenTelemetry instances. If we don't run into any issues, we can remove the GlobalOpenTelemetry.get() call (or make it opt-in), instead recommending programatic configuration.