opentracing-contrib/java-jaxrs

SpanFinishingFilter does not wipe out previous span

lysebraate opened this issue · 0 comments

As described here https://gitter.im/jaegertracing/Lobby?at=5a718da6e217167e2c22d430, I'm getting nested spans when using the current setup (with jaeger-core v.0.23.0, java-jaxrs v0.1.0) and dropwizard:

GlobalTracer.register(tracer);
DynamicFeature tracing = new ServerTracingDynamicFeature.Builder(tracer)
    .withSkipPattern("(\\/app\\/apiadmin\\/ping$|\\/api\\/app\\/v.*\\/view\\/.*$)")
    .withTraceSerialization(false)
    .build();

env.jersey().register(tracing);

env.servlets()
    .addFilter("span-finisher", new SpanFinishingFilter(tracer))
.addMappingForUrlPatterns(EnumSet.allOf(DispatcherType.class), true, "/*");

Turns out the old span is kept in the thread and becomes the parent span when the first thread is reused.

AS = Active Span, PS = Parent Span, TID = Trace Id. Looks like the parent span is kept for each thread. The "Finished span" output is a modified version of the SpanWrapper that prints out the span stored.

[22][dw-22 - GET /api/app/v1/lists/11-5898345890e0b10777347c39] [AS: 5509402670663705252/PS: 0/TID: 5509402670663705252]
[22][Thread[dw-22,5,main]] Finishing span 4c755489f57fa2a4:4c755489f57fa2a4:0:1 - api/app/v1/lists/{listId}
[30][dw-30 - GET /api/app/v1/lists/11-5898345890e0b10777347c39] [AS: 8731863753192287363/PS: 0/TID: 8731863753192287363]
[30][Thread[dw-30,5,main]] Finishing span 792dcfd1f422ac83:792dcfd1f422ac83:0:1 - api/app/v1/lists/{listId}
[32][dw-32 - GET /api/app/v1/lists/11-5898345890e0b10777347c39] [AS: 4773869689215032917/PS: 0/TID: 4773869689215032917]
[32][Thread[dw-32,5,main]] Finishing span 4240313075aa9e55:4240313075aa9e55:0:1 - api/app/v1/lists/{listId}

[22][dw-22 - GET /api/app/v1/lists/11-5898345890e0b10777347c39] [AS: -4035566196088312288/PS: 5509402670663705252/TID: 5509402670663705252]
[22][Thread[dw-22,5,main]] Finishing span 4c755489f57fa2a4:c7fec9ed0e94ee20:4c755489f57fa2a4:1 - api/app/v1/lists/{listId}
[30][dw-30 - GET /api/app/v1/lists/11-5898345890e0b10777347c39] [AS: 7263183733100460979/PS: 8731863753192287363/TID: 8731863753192287363]
[30][Thread[dw-30,5,main]] Finishing span 792dcfd1f422ac83:64cc031f8dd93bb3:792dcfd1f422ac83:1 - api/app/v1/lists/{listId}
[32][dw-32 - GET /api/app/v1/lists/11-5898345890e0b10777347c39] [AS: 8179141403428200331/PS: 4773869689215032917/TID: 4773869689215032917]
[32][Thread[dw-32,5,main]] Finishing span 4240313075aa9e55:718225c57f071f8b:4240313075aa9e55:1 - api/app/v1/lists/{listId}

Looking at
https://github.com/opentracing-contrib/java-jaxrs/blob/master/opentracing-jaxrs2/src/main/java/io/opentracing/contrib/jaxrs2/server/SpanFinishingFilter.java#L58 , is there a slight possiblity that the ThreadLocalScope is never closed in the SpanFinishingFilter (I can only find close as part of the catch clause) ?

I get expected behaviour when I move the closing part outside the catch block, but that can have other implications I am not aware of.