micronaut-projects / micronaut-tracing

Distributed Tracing Support
Apache License 2.0
16 stars 25 forks source link

NewSpan/WithSpan isn't propagating the trace context for reactive calls #524

Open turneand opened 6 months ago

turneand commented 6 months ago

Expected Behavior

When annotating reactive methods with NewSpan/WithSpan the trace context should be propagated.

Actual Behaviour

Following the documentation under https://micronaut-projects.github.io/micronaut-tracing/latest/guide/index.html#opentelemetry (although no reactive examples, the notes at https://micronaut-projects.github.io/micronaut-tracing/latest/guide/index.html#introduction indicate reactive types are supported).

A simple reactive method like the following:

  @Get("/helloReactive")
  @NewSpan("new-helloReactive")
  //@WithSpan("with-helloReactive")
  public Mono<String> helloReactive() {
    log.info("helloReactive -> {}", Span.current().getSpanContext());
    return Mono.fromCallable(this::getMessage)
        .doOnNext(x -> log.info("doOnNext -> {}", Span.current().getSpanContext()));
  }

Is not able to read the correct values from Span.current(), instead it indicates that no span is present. Note, that for this sample "micronaut-tracing-opentelemetry" is a dependency, but "micronaut-tracing-opentelemetry-http" is not ... If we use micronaut-tracing-opentelemetry-http, then the overall context is propagated, but any sub-span are not correctly propagated down.

Steps To Reproduce

With the dependencies:

    <dependency>
      <groupId>io.micronaut.tracing</groupId>
      <artifactId>micronaut-tracing-opentelemetry</artifactId>
    </dependency>
    <dependency>
      <groupId>io.opentelemetry</groupId>
      <artifactId>opentelemetry-exporter-logging</artifactId>
    </dependency>
   ...

And the controller class:

@Controller
public class SimpleController {
  private final Logger log = LoggerFactory.getLogger(SimpleController.class);

  @Get("/hello")
  @NewSpan("new-hello")
  //@WithSpan("with-hello")
  public String hello() {
    log.info("hello -> {}", Span.current().getSpanContext());
    return getMessage();
  }

  @Get("/helloReactive")
  @NewSpan("new-helloReactive")
  //@WithSpan("with-helloReactive")
  public Mono<String> helloReactive() {
    log.info("helloReactive -> {}", Span.current().getSpanContext());
    return Mono.fromCallable(this::getMessage)
        .doOnNext(x -> log.info("doOnNext -> {}", Span.current().getSpanContext()));
  }

  String getMessage() {
    log.info("getMessage -> {}", Span.current().getSpanContext());
    return "hello";
  }
}

When run locally, we get results as below: /hello - to hit the non-reactive endpoint, the current span logged is valid

    ... hello -> ImmutableSpanContext{traceId=5444699c6791c96606dd3526a08408f, spanId=2457aa8ded06d6b, tracingFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=true}
    ... getMessage -> ImmutableSpanContext{traceId=5444699c6791c96606dd3526a08408f, spanId=2457aa8ded06d6b, tracingFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=true}

/helloReactive - to hit the reactive endpoint, the current span logged is invalid

    ... helloReactive -> ImmutableSpanContext{traceId=278bb519b2b0e4e04a05b074739a6327, spanId=ee6bfdfda3ecccae, tracingFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=true}
    ... getMessage -> ImmutableSpanContext{traceId=0000000000000000000000000000000, spanId=000000000000000, tracingFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}
    ... doOnNext -> ImmutableSpanContext{traceId=0000000000000000000000000000000, spanId=000000000000000, tracingFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}

Environment Information

windows / unix java 17

Example Application

https://github.com/turneand/micronaut-tracing

Version

4.3.4

graemerocher commented 6 months ago

I believe you need micrometer context propagation on the classpath //cc @dstepanov

turneand commented 6 months ago

Ah, perfect, so I found the documentation around the micronaut-context-propagation, but clearly missed this one. What really confused me is that when using the auto-instrumentation of the http methods via micronaut-tracing-opentelemetry-http, then the context is setup, so then presume this is done a different way? But, that at least sorts out my immediate issue, thanks

turneand commented 6 months ago

Unfortunately adding micrometer context propagation appears to break micronaut-data transaction propagation, so can't actually add it in for now. I've raised that under https://github.com/micronaut-projects/micronaut-data/issues/2835