search

micrometer-metrics / micrometer

An application observability facade for the most popular observability tools. Think SLF4J, but for observability.
https://micrometer.io
Apache License 2.0
4.49k stars 992 forks source link

NPE for currentSpan() micrometer tracing on kubernetes #4610

Closed simvsim closed 10 months ago

simvsim commented 10 months ago

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.

Environment

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]
marcingrzejszczak commented 10 months ago

Can you please file this issue in Spring Framework?