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

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

About this issue

Original URL
State: closed
Created 7 years ago
Comments: 18 (8 by maintainers)

Most upvoted comments

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

marcingrzejszczak on Sep 1, 2017

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";
  }

}

thombergs on Aug 31, 2017

I’ll try.

asarkar on Aug 22, 2017