Describe the bug
In k8s environment: currentSpan in @Scheduled is null, possibly due to missing instrumentation on scheduler.
Locally on windows environment same java version no NPE.
Issue copied from: https://github.com/micrometer-metrics/micrometer/issues/4610
Environment - Spring boot: 3.2.1 - Micrometer version: 1.2.1 - OS: Ubuntu 22.04.2 LTS - Java version: 17.0.4.1
To Reproduce Sample app. pom.xml depencies:
<parent>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter-parent</artifactId>
<version>3.2.1</version>
</parent>
<dependencies>
<dependency>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter-actuator</artifactId>
</dependency>
<dependency>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter-webflux</artifactId>
</dependency>
<dependency>
<groupId>io.micrometer</groupId>
<artifactId>micrometer-tracing</artifactId>
</dependency>
<dependency>
<groupId>io.micrometer</groupId>
<artifactId>micrometer-tracing-bridge-otel</artifactId>
</dependency>
<dependency>
<groupId>io.micrometer</groupId>
<artifactId>micrometer-registry-dynatrace</artifactId>
</dependency>
<dependency>
<groupId>org.projectlombok</groupId>
<artifactId>lombok</artifactId>
</dependency>
</dependencies>
Scheduler:
import io.micrometer.tracing.Tracer;
import lombok.extern.slf4j.Slf4j;
import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.scheduling.annotation.Scheduled;
import org.springframework.stereotype.Component;
@Component
@Slf4j
public class SomeScheduler {
@Autowired
private Tracer tracer;
@Scheduled(fixedDelay = 5000, initialDelay = 5000)
void scheduledExecute() {
log.info("trace {} parent {}",
tracer.currentSpan().context().traceId(),
tracer.currentSpan().context().parentId());
}
}
Configurer:
import io.micrometer.observation.ObservationRegistry;
import org.springframework.context.annotation.Configuration;
import org.springframework.scheduling.annotation.EnableScheduling;
import org.springframework.scheduling.annotation.SchedulingConfigurer;
import org.springframework.scheduling.config.ScheduledTaskRegistrar;
@Configuration
@EnableScheduling
public class ObservationSchedulingConfigurer implements SchedulingConfigurer {
private final ObservationRegistry observationRegistry;
public ObservationSchedulingConfigurer(ObservationRegistry observationRegistry) {
this.observationRegistry = observationRegistry;
}
@Override
public void configureTasks(ScheduledTaskRegistrar taskRegistrar) {
taskRegistrar.setObservationRegistry(this.observationRegistry);
}
}
Log:
:: Spring Boot :: (v3.2.1)
2024-01-22T17:48:28.224Z INFO 1 --- [ main] [ ] org.sample.SomeApplication : Starting SomeApplication using Java 17.0.4.1 with PID 1 ***
2024-01-22T17:48:28.233Z INFO 1 --- [ main] [ ] org.sample.SomeApplication : No active profile set, falling back to 1 default profile: "default"
2024-01-22T17:48:35.528Z DEBUG 1 --- [ main] [ ] i.m.c.u.i.logging.InternalLoggerFactory : Using SLF4J as the default logging framework
2024-01-22T17:48:39.725Z INFO 1 --- [ main] [ ] o.s.b.a.e.web.EndpointLinksResolver : Exposing 1 endpoint(s) beneath base path '/actuator'
2024-01-22T17:48:41.611Z INFO 1 --- [ main] [ ] o.s.b.web.embedded.netty.NettyWebServer : Netty started on port 8080
2024-01-22T17:48:41.727Z INFO 1 --- [ main] [ ] org.sample.SomeApplication : Started SomeApplication in 15.918 seconds (process running for 20.269)
2024-01-22T17:48:46.772Z ERROR 1 --- [ scheduling-1] [ ] o.s.s.s.TaskUtils$LoggingErrorHandler : Unexpected error occurred in scheduled task
java.lang.NullPointerException: Cannot invoke "io.micrometer.tracing.Span.context()" because the return value of "io.micrometer.tracing.Tracer.currentSpan()" is null
at org.sample.tracing.SomeScheduler.scheduledExecute(SomeScheduler.java:20) ~[!/:na]
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:na]
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77) ~[na:na]
at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:na]
at java.base/java.lang.reflect.Method.invoke(Method.java:568) ~[na:na]
at org.springframework.scheduling.support.ScheduledMethodRunnable.runInternal(ScheduledMethodRunnable.java:130) ~[spring-context-6.1.2.jar!/:6.1.2]
at org.springframework.scheduling.support.ScheduledMethodRunnable.lambda$run$2(ScheduledMethodRunnable.java:124) ~[spring-context-6.1.2.jar!/:6.1.2]
at io.micrometer.observation.Observation.observe(Observation.java:499) ~[micrometer-observation-1.12.1.jar!/:1.12.1]
at org.springframework.scheduling.support.ScheduledMethodRunnable.run(ScheduledMethodRunnable.java:124) ~[spring-context-6.1.2.jar!/:6.1.2]
at org.springframework.scheduling.support.DelegatingErrorHandlingRunnable.run(DelegatingErrorHandlingRunnable.java:54) ~[spring-context-6.1.2.jar!/:6.1.2]
at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539) ~[na:na]
at java.base/java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305) ~[na:na]
at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305) ~[na:na]
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) ~[na:na]
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) ~[na:na]
at java.base/java.lang.Thread.run(Thread.java:833) ~[na:na]
2024-01-22T17:48:50.113Z DEBUG 1 --- [or-http-epoll-2] [ ] i.m.t.o.p.BaggageTextMapPropagator : Will propagate new baggage context for entries {}
2024-01-22T17:48:50.649Z TRACE 1 --- [or-http-epoll-2] [ ] i.m.t.o.b.Slf4JBaggageEventListener : Got scope attached event [ScopeAttached{context: [span: com.dynatrace.agent.introspection.span.opentelemetry.DynatraceCompositeSpan@122881f2] [baggage: {}]}]
2024-01-22T17:48:50.652Z TRACE 1 --- [or-http-epoll-2] [ ] i.m.t.otel.bridge.Slf4JEventListener : Got scope changed event [ScopeAttached{context: [span: com.dynatrace.agent.introspection.span.opentelemetry.DynatraceCompositeSpan@122881f2] [baggage: ScopeAttached{context: [span: com.dynatrace.agent.introspection.span.opentelemetry.DynatraceCompositeSpan@122881f2] [baggage: {}]}]}]
2024-01-22T17:48:50.654Z TRACE 1 --- [or-http-epoll-2] [464b5643175af79ca358d3ec975b0b04-9f530b054a1aa8a7] i.m.t.o.b.Slf4JBaggageEventListener : Got scope closed event [io.micrometer.tracing.otel.bridge.EventPublishingContextWrapper$ScopeClosedEvent@2e63a01f]
2024-01-22T17:48:50.655Z TRACE 1 --- [or-http-epoll-2] [464b5643175af79ca358d3ec975b0b04-9f530b054a1aa8a7] i.m.t.otel.bridge.Slf4JEventListener : Got scope closed event [io.micrometer.tracing.otel.bridge.EventPublishingContextWrapper$ScopeClosedEvent@2e63a01f]
2024-01-22T17:48:50.655Z TRACE 1 --- [or-http-epoll-2] [ ] i.m.t.o.b.Slf4JBaggageEventListener : Got scope restored event [ScopeRestored{context: [span: com.dynatrace.agent.introspection.span.opentelemetry.DynatraceCompositeSpan@6c8602e2] [baggage: null]}]
2024-01-22T17:48:50.655Z TRACE 1 --- [or-http-epoll-2] [ ] i.m.t.otel.bridge.Slf4JEventListener : Got scope restored event [ScopeRestored{context: [span: com.dynatrace.agent.introspection.span.opentelemetry.DynatraceCompositeSpan@6c8602e2] [baggage: null]}]
2024-01-22T17:48:51.817Z ERROR 1 --- [ scheduling-1] [ ] o.s.s.s.TaskUtils$LoggingErrorHandler : Unexpected error occurred in scheduled task
java.lang.NullPointerException: Cannot invoke "io.micrometer.tracing.Span.context()" because the return value of "io.micrometer.tracing.Tracer.currentSpan()" is null
at org.sample.tracing.SomeScheduler.scheduledExecute(SomeScheduler.java:20) ~[!/:na]
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:na]
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77) ~[na:na]
at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:na]
at java.base/java.lang.reflect.Method.invoke(Method.java:568) ~[na:na]
at org.springframework.scheduling.support.ScheduledMethodRunnable.runInternal(ScheduledMethodRunnable.java:130) ~[spring-context-6.1.2.jar!/:6.1.2]
at org.springframework.scheduling.support.ScheduledMethodRunnable.lambda$run$2(ScheduledMethodRunnable.java:124) ~[spring-context-6.1.2.jar!/:6.1.2]
at io.micrometer.observation.Observation.observe(Observation.java:499) ~[micrometer-observation-1.12.1.jar!/:1.12.1]
at org.springframework.scheduling.support.ScheduledMethodRunnable.run(ScheduledMethodRunnable.java:124) ~[spring-context-6.1.2.jar!/:6.1.2]
at org.springframework.scheduling.support.DelegatingErrorHandlingRunnable.run(DelegatingErrorHandlingRunnable.java:54) ~[spring-context-6.1.2.jar!/:6.1.2]
at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539) ~[na:na]
at java.base/java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305) ~[na:na]
at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305) ~[na:na]
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) ~[na:na]
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) ~[na:na]
at java.base/java.lang.Thread.run(Thread.java:833) ~[na:na]
Comment From: bclozel
I can't reproduce the issue locally either. Would there be something in your production environment that could explain the behavior difference? Are there different configuration properties? Is there a Java agent involved?
Comment From: simvsim
Hi @bclozel, there are no configuration properties supplied. And "yes" there are, as I am using the ubi8/openjdk-17 provided here you can see the dockerfile: https://catalog.redhat.com/software/containers/ubi8/openjdk-17/618bdbf34ae3739687568813?architecture=amd64&image=65a905ecbccdec7b2b87c6eb&container-tabs=dockerfile
Comment From: bclozel
I'm not an expert but I don't see any obvious Java agent that could influence tracing here. I've created a docker container with this image for my sample application:
FROM eclipse-temurin:17-jre as builder
WORKDIR application
ARG JAR_FILE=build/libs/scheduleobs-0.0.1-SNAPSHOT.jar
COPY ${JAR_FILE} application.jar
RUN java -Djarmode=layertools -jar application.jar extract
FROM registry.access.redhat.com/ubi8/openjdk-17:1.18-2.1705573234
WORKDIR application
COPY --from=builder application/dependencies/ ./
COPY --from=builder application/spring-boot-loader/ ./
COPY --from=builder application/snapshot-dependencies/ ./
COPY --from=builder application/application/ ./
ENTRYPOINT ["java", "org.springframework.boot.loader.launch.JarLauncher"]
And I see the following logs:
2024-01-24T14:56:01.795Z INFO 1 --- [ scheduling-1] [65b125010a702e653e8a1e8ff1108967-3e8a1e8ff1108967] com.example.scheduleobs.SomeScheduler : trace 65b125010a702e653e8a1e8ff1108967 parent null
2024-01-24T14:56:06.798Z INFO 1 --- [ scheduling-1] [65b125063cc125b2005598ec427366c5-005598ec427366c5] com.example.scheduleobs.SomeScheduler : trace 65b125063cc125b2005598ec427366c5 parent null
2024-01-24T14:56:11.800Z INFO 1 --- [ scheduling-1] [65b1250b992d0260e06cce71b3eac385-e06cce71b3eac385] com.example.scheduleobs.SomeScheduler : trace 65b1250b992d0260e06cce71b3eac385 parent null
2024-01-24T14:56:16.802Z INFO 1 --- [ scheduling-1] [65b12510b8319433f5a0e3c09d162591-f5a0e3c09d162591] com.example.scheduleobs.SomeScheduler : trace 65b12510b8319433f5a0e3c09d162591 parent null
2024-01-24T14:56:21.804Z INFO 1 --- [ scheduling-1] [65b125152a2c2ed4debc8cedd9b6ae3a-debc8cedd9b6ae3a] com.example.scheduleobs.SomeScheduler : trace 65b125152a2c2ed4debc8cedd9b6ae3a parent null
2024-01-24T14:56:26.807Z INFO 1 --- [ scheduling-1] [65b1251a0e4adc872b9207d5ffcdd01b-2b9207d5ffcdd01b] com.example.scheduleobs.SomeScheduler : trace 65b1251a0e4adc872b9207d5ffcdd01b parent null
2024-01-24T14:56:31.809Z INFO 1 --- [ scheduling-1] [65b1251f0d5c1b729d49bae0899f0dbf-9d49bae0899f0dbf] com.example.scheduleobs.SomeScheduler : trace 65b1251f0d5c1b729d49bae0899f0dbf parent null
2024-01-24T14:56:36.811Z INFO 1 --- [ scheduling-1] [65b12524cadec2066c7a71dcdc20e88a-6c7a71dcdc20e88a] com.example.scheduleobs.SomeScheduler : trace 65b12524cadec2066c7a71dcdc20e88a parent null
2024-01-24T14:56:41.813Z INFO 1 --- [ scheduling-1] [65b125295b10fabe862e4acb4fed9610-862e4acb4fed9610] com.example.scheduleobs.SomeScheduler : trace 65b125295b10fabe862e4acb4fed9610 parent null
2024-01-24T14:56:46.815Z INFO 1 --- [ scheduling-1] [65b1252e6e7e6c2ef56e6918e1e120a6-f56e6918e1e120a6] com.example.scheduleobs.SomeScheduler : trace 65b1252e6e7e6c2ef56e6918e1e120a6 parent null
2024-01-24T14:56:51.817Z INFO 1 --- [ scheduling-1] [65b12533621f8fb56d3b39afb4bd41d0-6d3b39afb4bd41d0] com.example.scheduleobs.SomeScheduler : trace 65b12533621f8fb56d3b39afb4bd41d0 parent null
2024-01-24T14:56:56.819Z INFO 1 --- [ scheduling-1] [65b12538e034d3e7858b5edd52589905-858b5edd52589905] com.example.scheduleobs.SomeScheduler : trace 65b12538e034d3e7858b5edd52589905 parent null
I'm closing this issue for now as I can't reproduce the problem. We can reopen this issue if you can provide a way to consistently reproduce the issue.
Thanks!