Using the Spring Cloud Sleuth trace ID

Here is a way to interact with Spring Cloud Sleuth in an API service that works with an asynchronous workflow.

• Introduction
  • Spring Cloud Sleuth
  • Use the Sleuth trace ID for each workflow
• Getting the Sleuth trace ID
• Inserting the Sleuth trace ID
  • Filter that injects the trace ID
  • Configuration to use the filter

Introduction

On a recent project we implemented an API service using Spring Boot with two operations:

1. initiate a new, asynchronous workflow
2. report on the status of an existing workflow

Each workflow is identified by a unique ID that is generated by the service on the first call and returned to the consumer. The consumer then uses that ID in subsequent status requests to identify the workflow.

Spring Cloud Sleuth

The service is one of a mesh of microservices and we added Spring Cloud Sleuth to provide tracing across microservice calls. In Sleuth, a Span is a basic unit of work, and spans are linked together into a Trace for a single logical transaction. The Sleuth Reference provides much more detail, including this useful diagram:

Use the Sleuth trace ID for each workflow

Instead of generating a separate ID (such as a UUID) we decided to take the trace ID from Sleuth. Sleuth generates a random long integer as a trace ID at the beginning of the request and passes that as part of requests to other services.

Part of our rationale for using the trace ID is to reduce log message clutter. When Sleuth is included, the IDs are inserted into the Spring logs via the SLF4J MDC. Here is a simple Spring Boot log message with information added by Sleuth:

2017-07-14 13:32:59.094  INFO [api-service,92e9013d25cca084,92e9013d25cca084,false] [10.242.22.52] 25453 --- [nio-8080-exec-1] c.e.s.WorkflowController : Received request

• api-service is the service name
• 92e9013d25cca084 is the trace ID; here it is also the span ID because this is the first span in the trace
• false means that the log is not exportable to Zipkin

Getting the Sleuth trace ID

Getting the trace ID turned out to be very simple. We created a Spring service called Breadcrumb to return the formatted trace ID.

@Service
public class Breadcrumb {

  @Autowired
  private Tracer tracer;

  public String breadcrumbId() {
    return tracer.getCurrentSpan().traceIdString();
  }
}

Span#traceIdString() returns the trace ID in the same hexadecimal format used in the log messages.

The controller that handles the request to start the workflow injects this service and calls breadcrumb.getBreadcrumb() to get the current trace ID string.

Inserting the Sleuth trace ID

When a consumer requests status of a workflow they provide the breadcrumb ID to use, e.g.:

GET /v1/workflow/92e9013d25cca084

We want to set that value as the Sleuth trace ID.

Filter that injects the trace ID

The solution we chose is to create a Spring web filter that addes a Sleuth span as an attribute of the HTTP request so the Sleuth TraceFilter behaves as if the request is part of an existing Sleuth trace. Our filter:

• is in the filter chain before TraceFilter
• reads the breadcrumb ID from the request
• constructs an appropriate Span object
• adds the span as an attribute of the request with the correct key

When TraceFilter executes it finds the span in the request attribute and uses it as if the service had been called by another one in the same trace.

Here is the filter code, abridged for clarity, with explanatory comments:

// Load this filter before TraceFilter
@Order(TraceFilter.ORDER - 1)
public class InjectTraceFilter extends GenericFilterBean {

    // Only modify requests that match this pattern
    private static final Pattern REQUEST_PATTERN = Pattern.compile("^/v1/workflow/(?<crumbId>[0-9a-f]+)$");
    // Key of the request attribute that TraceFilter searches for
    private static final String TRACE_REQUEST_ATTR = TraceFilter.class.getName() + ".TRACE";
    // Used to construct the span name
    private static final String SPAN_NAME_BASE = "http:/v1/workflow/";

    private final Random random = new Random(System.currentTimeMillis());

    @Override
    public void doFilter(final ServletRequest request, final ServletResponse response,
                         final FilterChain chain) throws IOException, ServletException {
        final HttpServletRequest httpRequest = (HttpServletRequest) request;
        final String breadcrumbId = extractBreadcrumbId(httpRequest);
        if (breadcrumbId != null) {
            // Set up a span with this breadcrumb ID as the trace ID
            httpRequest.setAttribute(TRACE_REQUEST_ATTR, spanForId(breadcrumbId));
            chain.doFilter(httpRequest, response);
        } else {
            chain.doFilter(request, response);
        }
    }

    /**
     * Returns the breadcrumb ID if a GET request matches the pattern, otherwise null. 
     */
    private String extractBreadcrumbId(final HttpServletRequest httpRequest) {
        if ("GET".equals(httpRequest.getMethod())) {
            final Matcher matcher = REQUEST_PATTERN.matcher(httpRequest.getRequestURI());
            if (matcher.matches()) {
                return matcher.group("crumbId");
            }
        }
        return null;
    }

    /**
     * Constructs a span for the specified trace ID with a random span ID. 
     */
    private Span spanForId(final String traceId) {
        return Span.builder()
                .traceId(Span.hexToId(traceId))
                .spanId(random.nextLong())
                .exportable(false)
                .name(SPAN_NAME_BASE + traceId)
                .build();
    }
}

Configuration to use the filter

The filter is configured in the standard way:

@Configuration
public class InjectTraceFilterAutoConfigure {

    @Bean
    public InjectTraceFilter injectTraceFilter() {
        return new InjectTraceFilter();
    }

}