Lifecycle Issue in current OTLP Logback Appender

[FWinkler79]

Describe the bug

I recently tried to use the existing OTLP Logback Appender with a Spring Boot 3 application to generate OTLP-based logs natively. Unfortunately the current implementation of OTLP Logback Appender uses an implementation that causes lifecycle issues - at least it caused them for my setup, unless I did something wrong.

The problem is the the current implemenation requires an OTEL SDK to be "injected" into the Logback Appender implementation. That happens in a rather crude way: the SDK is declared as a static variable and is set via a static install(sdk) function. That causes issues, since the function needs to be called at the start of an application, ideally before the Logback Appender is being used. However, it is not always clear, when the Appender will be used, and in the case of a Spring Application, that is handled by the SpringApplication.

I could not get this to work properly, no matter where / when I instantiated the SDK and installed it (either before instantiating the Spring application or after it). You could probably get this to work somehow using Spring Application lifecycle callback listeners, but this is a big pain and somehow crude.

My current solution is different: I implemented a LogbackAppender that instantiates an OTEL SDK internally and can be configured using the usual logback.xml. I know this is not exactly "dependency injection" but at least it works without problems.

Steps to reproduce

• Clone this branch: https://github.com/FWinkler79/spring3-observability/tree/issue-branch-otel-logback-appender
• Follow "How to Run" descriptions
• Notice that the Spring Boot app does not generate any OTLP logs by inspecting the OTEL collector's command line output.

Note: I followed the OTEL documentation provided here.

Expected behavior

The appender should produce OTLP log output. The OTEL SDK should not be handed in via a static variable.
Rather, I would suggest to have an OTEL SDK instance (just for log output) configured and instantiated within the Logback Appender implementation itself. An example what that would look like can be found here.

Actual behavior

No logs are generated, and setting this appender up is quite frustrating.

Javaagent or library instrumentation version

1.29.0

Environment

JDK:

openjdk version "20" 2023-03-21
OpenJDK Runtime Environment SapMachine (build 20+36-sapmachine)
OpenJDK 64-Bit Server VM SapMachine (build 20+36-sapmachine, mixed mode)

OS:

MacOS Ventura 13.5.1 (22G90)

Additional context

No response

[mateuszrzeszutek]

The problem is the the current implemenation requires an OTEL SDK to be "injected" into the Logback Appender implementation. That happens in a rather crude way: the SDK is declared as a static variable and is set via a static install(sdk) function. That causes issues, since the function needs to be called at the start of an application, ideally before the Logback Appender is being used. However, it is not always clear, when the Appender will be used, and in the case of a Spring Application, that is handled by the SpringApplication.

It does not need to be called at the start, you can install an OpenTelemetry later on and that will still work. However, we do recommend installing it as early as possible, since the appender will not capture anything before OpenTelemetry is installed.
We have previously thought of keeping some start-up logs in memory before the appender is initialized (#8760 (comment)), but we haven't got to implementing that yet.

I could not get this to work properly, no matter where / when I instantiated the SDK and installed it (either before instantiating the Spring application or after it). You could probably get this to work somehow using Spring Application lifecycle callback listeners, but this is a big pain and somehow crude.

Here's how we do that in our own Spring Boot starter: https://github.com/open-telemetry/opentelemetry-java-instrumentation/blob/main/instrumentation/spring/spring-boot-autoconfigure/src/main/java/io/opentelemetry/instrumentation/spring/autoconfigure/instrumentation/logging/OpenTelemetryAppenderAutoConfiguration.java
It is a manual step that you have to do yourself, sure, but I personally I'd disagree with calling it a big pain.

[mateuszrzeszutek]

From the linked repo:

Spring Boot 3 (stable version, August 2023) is using version 1.25.0 of the OTEL SDK, APIs and implementations. For the static ingestion of an OTEL SDK the OTEL Logback Appender of version 1.29.0 needs to be used. This means updating versions of dependencies this package pulls along as well. It is not sure, if this may cause dangerous side-effects.

I think this is an issue on the Spring side, the logs SDK only became stable in version 1.27.0, and the install(OpenTelemetry) methods were added to the appenders in 1.28.

Issue No.3: Where to get the SDK from for injection?
Even if the current software design of the OTEL Logback Appender were working as expected, the question would still be where to get the SDK instance from. Spring instantiates the SDK internally (for use with there observability stack). While it is possible to retrieve the SDK from the Spring Framework as an injected bean, finding the right moment in the application lifecycle to do that is not straight-forward and may be fragile. Unless the Logback Appender for OTLP logs is a managed part of the Spring Framework, for which it can be assured that log output via the Appender uses the right SDK and is properly set up, plugging in the OTEL Logback Appender is not straight forward.

This again is not something that we can address in this repository; we don't know how Spring sets up and uses OpenTelemetry, whether it is published as a bean or not.

[FWinkler79]

Hi @mateuszrzeszutek, thanks for your reply and especially the link to the SpringBoot auto-configuration.

I agree that the SDK does not have to be installed immediately, but if you want all the logs of your application, including when it starts up (and maybe fails while doing so), you need to be quick. And that is indeed the problem: how quick? In other words, when is the correct point in time to set / install it? To properly answer it, you need to know quite a lot about how Spring Boot works, the lifecycle of an application and to spot the right "slot" in the lifecycle to fit this into. On top of that, this "slot" may very well change in the future, if Spring Boot does it differently. I feel, this is a rather fragile way of handling it - unless it is handled and tested by the Spring Framework developers themselves, of course.

The Spring Boot auto-configuration you linked to is doing exactly that. You listen for the "Application Ready" event and then you install the SDK. I have not checked it, but I am almost willing to bet that you are not getting the initial startup logs like that. I think "Application Ready" may be too late. Anyway, I will give it a shot and see.
Btw.: How would I include that auto-configuration with my Spring Boot app? Is there a maven dependency that I can include that contains the auto-config?

Finally, you mentioned you don't know how Spring Boot sets up and uses the OpenTelemetry SDK. Yet in Line 47 of the auto-configuration you retrieve it from Spring Boot and then install it. I actually attempted the same, but again, it's when this should happen that is not easy to answer - at least not for the average Spring Boot developer, I think.

Have you had a chance to look at my solution? I know it is not perfect, since the SDK is kind of "baked into" the appender, but since it is self-contained, it is tightly coupled with the lifecycle of the appender itself, rather than the application. That makes it work as expected, imho.

[trask]

hi @FWinkler79!

check out #8760

The limitation here is that we will miss any spring boot startup logs. One option here would be to cache some number of logs in the OpenTelemetry Appenders until the OpenTelemetry instance is injected.

would this proposal work for addressing the lifecycle issue you are mentioning?

[FWinkler79]

Hi @trask,

thanks for the reply. If you can ensure that the caching does not miss any startup logs, I guess it may solve the problem.
What I don't understand is why you have to absolutely inject the SDK into the appender. Why not simply create an instance of the SDK in the appender itself, and configure it with the necessary settings using the standard Logback XML files.
I show this in this sample. Generally I would assume this approach to be much easier and virtually fool-proof.
Do you want me to suggest this on the other thread also?

Thanks!

[trask]

Why not simply create an instance of the SDK in the appender itself, and configure it with the necessary settings using the standard Logback XML files.

ya, sorry for not addressing this question earlier, the issue is that it would only work in simple cases where you don't want to do any SDK configuration beyond what's possible using env vars

[FWinkler79]

Ok, I understand. You surely would have to expose a subset of the SDK's programmatic API via configurations. I was hoping that there would be the usual 80% use case scenarios that we need to satisfy and that we would get away with this approach and not require the full flexibility of programmatically accessing the SDK.

[jeanbisutti]

thanks for the reply. If you can ensure that the caching does not miss any startup logs, I guess it may solve the problem.

@FWinkler79 The caching was implemented in version 1.32.0. With the OpenTelemetry Starter, an OpenTelemetry instance is automatically injected into the OpenTelemetry Logback appender.

Is the Logback OpenTelemetry appender now convenient for you?

[jeanbisutti]

@open-telemetry/java-instrumentation-approvers Could you please add the "needs for author feedback" label?

[jeanbisutti]

@FWinkler79 The beginning of #8920 (comment) explains how the OpenTelemetry appender instruments all the logs.

[github-actions]

This has been automatically marked as stale because it has been marked as needing author feedback and has not had any activity for 7 days. It will be closed automatically if there is no response from the author within 7 additional days from this comment.