Spring-cloud-sleuth: Span and trace ids missing when an exception is thrown

[asarkar]

We have a logging service that accepts logs in JSON format. When a mandatory field is missing in the JSON, it throws an exception lacking any trace or span id. See below, where some of the items have been obfuscated to protect IP.

2017-07-21 14:33:50.119 DEBUG [log,,,] 46977 --- [nio-9000-exec-3] o.s.c.sleuth.instrument.web.TraceFilter  : Received a request to uri [/log/service] that should not be sampled [true]
2017-07-21 14:33:50.119 DEBUG [log,,,] 46977 --- [nio-9000-exec-3] o.s.c.sleuth.instrument.web.TraceFilter  : Found a parent span [Trace: 0e3a123c649bec91, Span: e404f98fb3fd1b78, Parent: 0e3a123c649bec91, exportable:false] in the request
2017-07-21 14:33:50.120 DEBUG [log,0e3a123c649bec91,e404f98fb3fd1b78,false] 46977 --- [nio-9000-exec-3] o.s.c.sleuth.instrument.web.TraceFilter  : Parent span is [Trace: 0e3a123c649bec91, Span: e404f98fb3fd1b78, Parent: 0e3a123c649bec91, exportable:false]
2017-07-21 14:33:50.122 DEBUG [log,0e3a123c649bec91,e404f98fb3fd1b78,false] 46977 --- [nio-9000-exec-3] o.s.c.s.i.web.TraceHandlerInterceptor    : Handling span [Trace: 0e3a123c649bec91, Span: e404f98fb3fd1b78, Parent: 0e3a123c649bec91, exportable:false]
2017-07-21 14:33:50.122 DEBUG [log,0e3a123c649bec91,e404f98fb3fd1b78,false] 46977 --- [nio-9000-exec-3] o.s.c.s.i.web.TraceHandlerInterceptor    : Adding a method tag with value [persistLogs] to a span [Trace: 0e3a123c649bec91, Span: e404f98fb3fd1b78, Parent: 0e3a123c649bec91, exportable:false]
2017-07-21 14:33:50.122 DEBUG [log,0e3a123c649bec91,e404f98fb3fd1b78,false] 46977 --- [nio-9000-exec-3] o.s.c.s.i.web.TraceHandlerInterceptor    : Adding a class tag with value [LogResource] to a span [Trace: 0e3a123c649bec91, Span: e404f98fb3fd1b78, Parent: 0e3a123c649bec91, exportable:false]
2017-07-21 14:33:50.123 DEBUG [log,0e3a123c649bec91,e404f98fb3fd1b78,false] 46977 --- [nio-9000-exec-3] com.mycompany.logging.LogService  : Creating log entry: LogItem(...).
2017-07-21 14:33:50.127 DEBUG [log,0e3a123c649bec91,e404f98fb3fd1b78,false] 46977 --- [nio-9000-exec-3] o.s.c.s.i.web.TraceHandlerInterceptor    : Adding an error tag [Mandatory field may not be null] to span [Trace: 0e3a123c649bec91, Span: e404f98fb3fd1b78, Parent: 0e3a123c649bec91, exportable:false]
2017-07-21 14:33:50.129 DEBUG [log,0e3a123c649bec91,e404f98fb3fd1b78,false] 46977 --- [nio-9000-exec-3] o.s.c.sleuth.instrument.web.TraceFilter  : Trying to send the parent span [Trace: 0e3a123c649bec91, Span: e404f98fb3fd1b78, Parent: 0e3a123c649bec91, exportable:false] to Zipkin
2017-07-21 14:33:50.129 DEBUG [log,0e3a123c649bec91,e404f98fb3fd1b78,false] 46977 --- [nio-9000-exec-3] o.s.c.sleuth.instrument.web.TraceFilter  : Closing the span [Trace: 0e3a123c649bec91, Span: e404f98fb3fd1b78, Parent: 0e3a123c649bec91, exportable:false] since the response was successful
2017-07-21 14:33:50.132 ERROR [log,,,] 46977 --- [nio-9000-exec-3] o.a.c.c.C.[.[.[/].[dispatcherServlet]    : Servlet.service() for servlet [dispatcherServlet] in context with path [] threw exception [Request processing failed; nested exception is java.lang.IllegalArgumentException: Mandatory field may not be null] with root cause
java.lang.IllegalArgumentException: Mandatory field may not be null
    at org.apache.commons.lang.Validate.notNull(Validate.java:192)
        // elided
2017-07-21 14:33:50.138 DEBUG [log,0e3a123c649bec91,e404f98fb3fd1b78,false] 46977 --- [nio-9000-exec-3] o.s.c.sleuth.instrument.web.TraceFilter  : There has already been a span in the request [Trace: 0e3a123c649bec91, Span: e404f98fb3fd1b78, Parent: 0e3a123c649bec91, exportable:false]
2017-07-21 14:33:50.139 DEBUG [log,0e3a123c649bec91,e404f98fb3fd1b78,false] 46977 --- [nio-9000-exec-3] o.s.c.sleuth.instrument.web.TraceFilter  : Received a request to uri [/error] that should not be sampled [true]
2017-07-21 14:33:50.139 DEBUG [log,0e3a123c649bec91,e404f98fb3fd1b78,false] 46977 --- [nio-9000-exec-3] o.s.c.sleuth.instrument.web.TraceFilter  : The span [Trace: 0e3a123c649bec91, Span: e404f98fb3fd1b78, Parent: 0e3a123c649bec91, exportable:false] was already detached once and we're processing an error
2017-07-21 14:33:50.141 DEBUG [log,0e3a123c649bec91,e404f98fb3fd1b78,false] 46977 --- [nio-9000-exec-3] o.s.c.s.i.web.TraceHandlerInterceptor    : Handling span [Trace: 0e3a123c649bec91, Span: e404f98fb3fd1b78, Parent: 0e3a123c649bec91, exportable:false]
2017-07-21 14:33:50.141 DEBUG [log,0e3a123c649bec91,e404f98fb3fd1b78,false] 46977 --- [nio-9000-exec-3] o.s.c.s.i.web.TraceHandlerInterceptor    : Adding a method tag with value [error] to a span [Trace: 0e3a123c649bec91, Span: e404f98fb3fd1b78, Parent: 0e3a123c649bec91, exportable:false]
2017-07-21 14:33:50.141 DEBUG [log,0e3a123c649bec91,e404f98fb3fd1b78,false] 46977 --- [nio-9000-exec-3] o.s.c.s.i.web.TraceHandlerInterceptor    : Adding a class tag with value [BasicErrorController] to a span [Trace: 0e3a123c649bec91, Span: e404f98fb3fd1b78, Parent: 0e3a123c649bec91, exportable:false]
2017-07-21 14:33:50.167 DEBUG [log,0e3a123c649bec91,e404f98fb3fd1b78,false] 46977 --- [nio-9000-exec-3] o.s.c.s.i.web.TraceHandlerInterceptor    : Skipping closing of a span for error controller processing

The log statement that's of concern is this:

2017-07-21 14:33:50.132 ERROR [log,,,] 46977 --- [nio-9000-exec-3] o.a.c.c.C.[.[.[/].[dispatcherServlet]    : Servlet.service() for servlet [dispatcherServlet] in context with path [] threw exception [Request processing failed; nested exception is java.lang.IllegalArgumentException

[marcingrzejszczak]

What is this class o.a.c.c.C.[.[.[/] ? Did you make a mistake when you copied that line?

[asarkar]

@marcingrzejszczak No, that's just the package name abbreviated as per the logback config. Not sure about the / in the name, but I don't think I changed anything there. Will double check and update this comment if it turns out to be my mistake.

[marcingrzejszczak]

Any luck? :)

[asarkar]

No luck, I checked, but the logs were gone. We don't retain them long for test environments. Is the stacktrace as shown not enough to start an investigation?

[marcingrzejszczak]

Is there an option for you to try to create a sample? It will be difficult to help you without something tangible. I have no idea what that class is, how it's called etc. :/

[asarkar]

I'll try.

[marcingrzejszczak]

Any progress on this @asarkar ? :)

[asarkar]

Sorry, I've been pulled into other things and didn't get time to look into this. I'll close this ticket, and create another one if and when I've more information.

[thombergs]

I had the same issue. When you create a custom ExceptionHandler, the trace and span ids are added correctly. Example Exception Handler:

@ControllerAdvice
public class ControllerExceptionHandler {

  @ResponseStatus(value = HttpStatus.INTERNAL_SERVER_ERROR)
  @ExceptionHandler(Exception.class)
  @ResponseBody
  public String handleInternalError(Exception e) {
    return "Internal Server Error";
  }

}

[asarkar]

@thombergs Did you find out the root cause of the problem and how does @ControllerAdvice solve it?

[marcingrzejszczak]

ControllerAdvice is a spring component so Sleuth is fully operational there. Without this for example internal Tomcat classes handle errors and currently we don't hook in into those

[arulrajsuri]

@marcingrzejszczak the tracename set within the scopedscan is missing when handling exception in ControllerAdvice

@ExceptionHandler(Exception.class)
    public ResponseEntity<Object> handleOtherException(Exception exception, WebRequest request) {
        LOGGER.error("Handling unexpected exception ",exception);
        ApplicationResponsePayload payload = applicationExceptionHelperService
                .createResponsePayload(AppConstants.UNEXPECTED_ERROR_CODE, AppConstants.UNEXPECTED_ERROR_MESSAGE);
        LOGGER.info("Response payload {}", payload.toString());
        return new ResponseEntity<Object>(payload, HttpStatus.OK);
    }

Log :

2020-06-09 16:45:32.111  INFO [-, traceId: be914bdb84997d8d, traceName: , spanId: be914bdb84997d8d, spanName: ] 10228 --- [nio-8080-exec-1] c.f.f.w.v.e.ApplicationExceptionHelperService   : Creating response payload for errorCode 500 with errorMessage UNEXPECTED ERROR
2020-06-09 16:45:32.111  INFO [-, traceId: be914bdb84997d8d, traceName: , spanId: be914bdb84997d8d, spanName: ] 10228 --- [nio-8080-exec-1] c.f.f.w.v.e.ApplicationGlobalExceptionHandler   : Response payload ApplicationResponsePayload(timestamp=Tue Jun 09 16:45:32 EDT 2020, statusCode=200, status=SUCCESS, errorCode=500, errorMessage=UNEXPECTED ERROR)

[marcingrzejszczak]

@arulrajsuri can you create a small project that replicates this issue?

[arulrajsuri]

@marcingrzejszczak I created a sample project https://github.com/arulrajsuri/SleuthTraceIssue/tree/master/TraceIssue

[arulrajsuri]

@marcingrzejszczak Can you please let me know when this issue will get triaged and fixed

[marcingrzejszczak]

Once it's fixed you'll get an automated update on this issue.

[arulrajsuri]

Thanks @marcingrzejszczak

[marcingrzejszczak]

@arulrajsuri you've finished the span here

@RequestMapping(method = RequestMethod.GET, path = "/getdata")
    public String getData() {
        ScopedSpan span = tracingInitUtil.initiateTracing("Trace-App");
        try {
            LOGGER.info("Get data executed in ApplicationController");
            return applicationService.getServiceData();
        } finally {
            span.finish(); // <-- You've finished the span here
        }
    }

So it has no access to any extra data in the controller advice. Remove finish and you'll see that it works fine.

If you need to finish the span (which makes a lot of sense) try wrapping the span in scope like this

@ControllerAdvice
public class ApplicationExceptionHandler extends ResponseEntityExceptionHandler {

    private static final Logger LOGGER = LoggerFactory.getLogger(ApplicationExceptionHandler.class);

    private final Tracer tracer;

    public ApplicationExceptionHandler(Tracer tracer) {
        this.tracer = tracer;
    }

    @ExceptionHandler(Exception.class)
    public ResponseEntity<Object> handleOtherException(Exception exception, WebRequest request) {
        try (Tracer.SpanInScope ws = tracer.withSpanInScope(tracer.currentSpan())) {
            LOGGER.error("Unexpected exception happended");
            return new ResponseEntity<Object>("Unexpected Exception", HttpStatus.OK);
        }
    }
}

Then I get the following logs

2020-07-29 16:20:14.653  INFO [-, traceId: e2515905c17917cf, traceName: Trace-App, spanId: d72f338c9aa5c4ca, spanName: ] 260415 --- [nio-8080-exec-1] com.tracing.issue.ApplicationController  : Get data executed in ApplicationController
2020-07-29 16:20:14.653  INFO [-, traceId: e2515905c17917cf, traceName: Trace-App, spanId: d72f338c9aa5c4ca, spanName: ] 260415 --- [nio-8080-exec-1] com.tracing.issue.ApplicationService     : Get service data executed in ApplicationService
2020-07-29 16:20:14.656 ERROR [-, traceId: e2515905c17917cf, traceName: Trace-App, spanId: e2515905c17917cf, spanName: ] 260415 --- [nio-8080-exec-1] c.t.issue.ApplicationExceptionHandler    : Unexpected exception happended
2020-07-29 16:20:14.668  WARN [-, traceId: e2515905c17917cf, traceName: , spanId: e2515905c17917cf, spanName: ] 260415 --- [nio-8080-exec-1] .m.m.a.ExceptionHandlerExceptionResolver : Resolved [java.lang.NullPointerException]