Trace does not close properly when using ViewController

[gavlyukovskiy]

I have single index.jsp inside webapp and next configuration:

@SpringBootApplication
public class AggregationServiceApplication extends WebMvcConfigurerAdapter {

    public static void main(String[] args) {
        SpringApplication.run(AggregationServiceApplication.class, args);
    }

    @Override
    public void addViewControllers(ViewControllerRegistry registry) {
        registry.addViewController("/index").setViewName("index");
    }
}

application.yml

spring.mvc.view.prefix: /
spring.mvc.view.suffix: .jsp

When I'm trying to access /index (/index.jsp is ok) sleuth warns:

Tried to close span but it is not the current span: [Trace: bdb52aad2860fb80, Span: bdb52aad2860fb80, Parent: null, exportable:false]. You may have forgotten to close or detach [Trace: bdb52aad2860fb80, Span: 334110a624d20d76, Parent: bdb52aad2860fb80, exportable:false]

Request flow:

Request
    -> TraceFilter
        -> spanFromRequest = null
        -> createSpan
            -> SpanContextHolder.push([Trace: bdb52aad2860fb80, Span: bdb52aad2860fb80, Parent: null, exportable:false])
        -> filterChain.doFilter
            -> DispatcherServlet
                -> TraceHandlerInterceptor.preHandle
                    -> createSpan
                        -> SpanContextHolder.push([Trace: bdb52aad2860fb80, Span: 334110a624d20d76, Parent: bdb52aad2860fb80, exportable:false])
                -> TraceFilter
                    -> spanFromRequest = [Trace: bdb52aad2860fb80, Span: bdb52aad2860fb80, Parent: null, exportable:false]
                    -> continueSpan
                        -> SpanContextHolder.push([Trace: bdb52aad2860fb80, Span: bdb52aad2860fb80, Parent: null, exportable:false])
                    -> createSpan
                        -> return spanFromRequest
                    -> filterChain.doFilter
                    -> detachOrCloseSpans
                        -> SpanContextHolder.close([Trace: bdb52aad2860fb80, Span: bdb52aad2860fb80, Parent: null, exportable:false])
                            -> current = [Trace: bdb52aad2860fb80, Span: bdb52aad2860fb80, Parent: null, exportable:false]
                            -> current.parent = [Trace: bdb52aad2860fb80, Span: 334110a624d20d76, Parent: bdb52aad2860fb80, exportable:false]
                            -> CURRENT_SPAN.set([Trace: bdb52aad2860fb80, Span: 334110a624d20d76, Parent: bdb52aad2860fb80, exportable:false])
                -> TraceHandlerInterceptor.afterCompletion
                    -> isSpanContinued(request)
                        -> return true
                    -> return WITHOUT tracer.close([Trace: bdb52aad2860fb80, Span: 334110a624d20d76, Parent: bdb52aad2860fb80, exportable:false])
        -> detachOrCloseSpans
            -> SpanContextHolder.close([Trace: bdb52aad2860fb80, Span: bdb52aad2860fb80, Parent: null, exportable:false])
                -> cur = [Trace: bdb52aad2860fb80, Span: 334110a624d20d76, Parent: bdb52aad2860fb80, exportable:false]
                -> ExceptionUtils.warn

SpanContextHolder.getCurrentSpan() = [Trace: bdb52aad2860fb80, Span: 334110a624d20d76, Parent: bdb52aad2860fb80, exportable:false]

And at the end of request SpanContextHolder does not empty, thus next requests (in this thread) will have this span as parent.

[gavlyukovskiy]

@marcingrzejszczak, you implemented TraceRequestAttributes.SPAN_CONTINUED_REQUEST_ATTR header, could you please help me understand what is it used for, so that I can do the pull request?
Seems so it is the only cause of the issue.

[marcingrzejszczak]

We've been working mostly with Rest based controllers so we had such a flow

TraceFilter#doFilter
  TraceHandlerInterceptor#preHandle
    Controller
  TraceHandlerInterceptor#afterCompletion
TraceFilter#doFilter#finally

I see that there's some additional flow when taking into consideration view controller.

The problem with TraceHandlerInterceptor is that it starts and needs to close a span. In 1.2.0 most likely we'll try to remove this problem by solving this issue #471 .

In 1.1.x and 1.0.x we'll have to try to tackle this differently. Coming back to your question... The TraceHandlerInterceptor is responsible for starting and closing a new span whose name is the Controller's method name. TraceFilter might be processing the same span multiple times and then we just want to continue this instead of creating a new span again. That's why we're setting the TraceRequestAttributes.SPAN_CONTINUED_REQUEST_ATTR. In this case then in the TraceHandlerInterceptor we want to just continue the span upon preHandle and not do anything on afterCompletion cause it will be the TraceFilter that will detach the span (welcome to the tracing hell ;) ). In your case the order is shifted unfortunately :/

[gavlyukovskiy]

In my case flow next:

TraceFilter#doFilter
  TraceHandlerInterceptor#preHandle
    TraceFilter#continueSpan
        request.setAttribute(TraceRequestAttributes.SPAN_CONTINUED_REQUEST_ATTR, true)
    TraceFilter#doFilter
      Controller
    TraceFilter#doFilter#finally
  TraceHandlerInterceptor#afterCompletion
    if (request.getAttribute(TraceRequestAttributes.SPAN_CONTINUED_REQUEST_ATTR)) - do not close span
TraceFilter#doFilter#finally

TraceHandlerInterceptor checks flag TraceRequestAttributes.SPAN_CONTINUED_REQUEST_ATTR and creates new span as flag is false, second call of TraceFilter continues span, sets flag and closes it in finally, but doesn't remove flag from the request when closes span and TraceHandlerInterceptor does not close it because flag TraceRequestAttributes.SPAN_CONTINUED_REQUEST_ATTR became true.

Thus I think to keep span for controlelr method call either TraceFilter should remove TraceRequestAttributes.SPAN_CONTINUED_REQUEST_ATTR flag when span closes or TraceHandlerInterceptorshould override Trace.TRACE_REQUEST_ATTR attribute with created span or TraceHandlerInterceptor should not check flag if it is creator of current span.

[gavlyukovskiy]

Or second choice is in TraceHandlerInterceptor#preHandle set flag, that request instrumented by controller interceptor and check in TraceFilter if this flag is set not create another span and of cource remove this flag in TraceHandlerInterceptor#afterCompletion. So you will have clear span hierarchy with two spans.

I think create span for controller method is fine, it visualizes the flow and you can measure the time between filters run and controller run.

[marcingrzejszczak]

I think create span for controller method is fine, it visualizes the flow and you can measure the time between filters run and controller run.

You'll still be able to do it if you want to. In your controller you can create a span and close it as you wish. This is related to this: #180

[gavlyukovskiy]

Agree, have abillity to add is always betten than have no abillity to remove :)

[marcingrzejszczak]

I wrote to you on Gitter that I like the idea of removing the attribute upon closing (it just makes sense ;) ) but I'll give it a longer thought tomorrow cause it's almost 00:00 here ;)

[marcingrzejszczak]

done via ee8c73d