activeSpan being reused

[jmif]

I believe we're seeing an issue using opentracing-contrib:java-jaxrx:0.1.4, io.zipkin.brave:brave:4.19.2 and brave-opentracing-0.30.3 (all of this inside Dropwizard 1.2), however I'm very new to open tracing in and the available Java tracers and I'm hoping someone here can point me in the right direction:

The active span is not being cleared across requests and all spans that are created in requests are being tagged to the parent thread created in the first request to the server.

On this line the finishing filter pulls the active scope via the tracer's scope manager.

This active scope is closed via it's close() method. This eventually calls this close implementation in the BraveScopeManager. This scope manager has a noop close implementation and thus the scope remains open.

Then in later requests the JAXRS filter grabs the active span. On subsequent requests the active span is set to span that was created during the first request and all traces end up being children of the first trace ever created.

I'm unsure of the relation between Spans and Scopes in this situation but we've confirmed that the active span is being reused across all requests.

For context this is how we are initializing our filters:

AsyncReporter<Span> reporter = AsyncReporter.builder(sender).build();

Tracer tracer = BraveTracer
        .newBuilder(
                Tracing.newBuilder()
                        .localServiceName(openTracingConfig.getServiceName())
                        .spanReporter(reporter)
                        .sampler(Sampler.ALWAYS_SAMPLE)
                        .build()
        )
        .build();


GlobalTracer.register(tracer);

// Register feature / servlet filter to start traces
environment.jersey().register(
        new ServerTracingDynamicFeature.Builder(tracer).build()    
 );

// Register filter to end traces
FilterRegistration.Dynamic registration = environment.servlets()
        .addFilter("tracing-filter", new SpanFinishingFilter(tracer));

registration.setAsyncSupported(true);
registration.addMappingForUrlPatterns(EnumSet.of(DispatcherType.REQUEST), false, "*");

[pavolloffay]

@jmif hi, would you have a reproducer for the issue?

[pavolloffay]

A simple dropwizzard app with required deps would be sufficient

[jmif]

Sure

https://github.com/jmif/open-tracing-jaxrs-active-span-bug-repro

If you fire 5 - 10 requests you'll notice that the trace IDs / span IDs start to become identical (i've included a simple log below to demonstrate - the RealSpan log entries come via debugger from this line and are the result of the expression ((BraveSpan) activeSpan).delegate

0:0:0:0:0:0:0:1 - - [23/May/2018:18:50:45 +0000] "GET / HTTP/1.1" 200 0 "-" "curl/7.54.0" 38565
RealSpan(59e3a12149dbb753/59e3a12149dbb753)
0:0:0:0:0:0:0:1 - - [23/May/2018:18:50:47 +0000] "GET / HTTP/1.1" 200 0 "-" "curl/7.54.0" 14
RealSpan(8e95010a5bae45ad/8e95010a5bae45ad)
0:0:0:0:0:0:0:1 - - [23/May/2018:18:50:48 +0000] "GET / HTTP/1.1" 200 0 "-" "curl/7.54.0" 5
RealSpan(afbff7b805ae2102/afbff7b805ae2102)
0:0:0:0:0:0:0:1 - - [23/May/2018:18:50:49 +0000] "GET / HTTP/1.1" 200 0 "-" "curl/7.54.0" 5
RealSpan(0ae6ce78d065d464/0ae6ce78d065d464)
0:0:0:0:0:0:0:1 - - [23/May/2018:18:50:49 +0000] "GET / HTTP/1.1" 200 0 "-" "curl/7.54.0" 5
RealSpan(8e95010a5bae45ad/8e95010a5bae45ad)
0:0:0:0:0:0:0:1 - - [23/May/2018:18:50:50 +0000] "GET / HTTP/1.1" 200 0 "-" "curl/7.54.0" 6
RealSpan(0ae6ce78d065d464/0ae6ce78d065d464)
0:0:0:0:0:0:0:1 - - [23/May/2018:18:50:51 +0000] "GET / HTTP/1.1" 200 0 "-" "curl/7.54.0" 5
RealSpan(8e95010a5bae45ad/8e95010a5bae45ad)
0:0:0:0:0:0:0:1 - - [23/May/2018:18:50:52 +0000] "GET / HTTP/1.1" 200 0 "-" "curl/7.54.0" 5
RealSpan(0ae6ce78d065d464/0ae6ce78d065d464)
0:0:0:0:0:0:0:1 - - [23/May/2018:18:50:54 +0000] "GET / HTTP/1.1" 200 0 "-" "curl/7.54.0" 4
RealSpan(8e95010a5bae45ad/8e95010a5bae45ad)
0:0:0:0:0:0:0:1 - - [23/May/2018:18:50:54 +0000] "GET / HTTP/1.1" 200 0 "-" "curl/7.54.0" 4
RealSpan(0ae6ce78d065d464/0ae6ce78d065d464)
0:0:0:0:0:0:0:1 - - [23/May/2018:18:51:02 +0000] "GET / HTTP/1.1" 200 0 "-" "curl/7.54.0" 4
RealSpan(59e3a12149dbb753/59e3a12149dbb753)
0:0:0:0:0:0:0:1 - - [23/May/2018:18:51:02 +0000] "GET / HTTP/1.1" 200 0 "-" "curl/7.54.0" 4
RealSpan(8e95010a5bae45ad/8e95010a5bae45ad)
0:0:0:0:0:0:0:1 - - [23/May/2018:18:51:03 +0000] "GET / HTTP/1.1" 200 0 "-" "curl/7.54.0" 4
RealSpan(afbff7b805ae2102/afbff7b805ae2102)
0:0:0:0:0:0:0:1 - - [23/May/2018:18:51:06 +0000] "GET / HTTP/1.1" 200 0 "-" "curl/7.54.0" 5
RealSpan(0ae6ce78d065d464/0ae6ce78d065d464)
0:0:0:0:0:0:0:1 - - [23/May/2018:18:51:06 +0000] "GET / HTTP/1.1" 200 0 "-" "curl/7.54.0" 6
RealSpan(afbff7b805ae2102/afbff7b805ae2102)
0:0:0:0:0:0:0:1 - - [23/May/2018:18:51:06 +0000] "GET / HTTP/1.1" 200 0 "-" "curl/7.54.0" 4

[pavolloffay]

Then in later requests the JAXRS filter grabs the active span. On subsequent requests the active span is set to span that was created during the first request and all traces end up being children of the first trace ever created.

This was added #74.

[mpetazzoni]

@pavolloffay I'm still seeing this problem with java-jaxrs 0.1.6, brave 5.1.x and brave-opentracing 0.31.2. If a serving thread decides not to trace the incoming request (because of sampling), a NoopSpan is put in scope, but that scope is then never closed correctly and a subsequent request served by the same thread sees that previous span as being active, creating a new span as a child of that first request's old span.

[pavolloffay]

@mpetazzoni is it related to brave implementation - the difference between noopSpan and realSpan?

Would you have a reproducer for tihs?

[mpetazzoni]

Yeah, it definitely is because of the interaction with Brave and the Brave/OT bridge. I'll try to work on a reproducer in the java-jaxrs unit tests, but I'm curious to hear your thoughts on how this would be fixed.