Configuring sleuth valve for Tomcat - Spring Boot

We all agree that tracing a bug in a monolithic app is hard, but this tracing gets even harder in a distributed solution, since we've many different services running on different machines may be involved in responding to a single request.Not only for debugging purposes, it’s essential that the path of such a request can be traced through all involved services.

Spring Cloud Sleuth is meant to help with this exact problem. It introduces unique IDs to your logging which are consistent between microservice calls which makes it possible to find how a single request travels from one microservice to the next.

Sleuth valve

At xhub we've been using Spring boot and it's ecosystem (and Sleuth obviously) for a while now. We're also using ELastic stack to Monitor our services and aggregate log files (access and application logs). One missing link we had is that the traceID was absent on the access log of the edge service!

Well it's not that big issuer, but we thought it would be nice if we can fix it and trace requests logs from end to end.

Our approach: adding a tomcat valve to inject Sleuth headers

Apache Tomcat has two primary ways of processing the request/response stream: servlet filters and valves. Unlike the servlet filters, Tomcat Valves are used through the configuration of the application server. Tomcat valves allow to associate an instance of a Java class with a particular Catalina container. This configuration allows the named class to act as a preprocessor of each request.

So what we did basically is:

• Adding a custom tomcat Valve that add Sleuth headers if not present
• Configuring EmbeddedServletContainerCustomizer Bean to customize the embedded Tomcat instance by adding SleuthValve

An example of this solution is available on github

Show me the code

This is the tomcat vavle we added, that injects Sleuth headers in request (if not present)

class SleuthValve extends ValveBase {
    private final Tracer tracer;

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

    @Override
    public void invoke(Request request, Response response) throws IOException, ServletException {

        enrichWithSleuthHeaderWhenMissing(tracer, request);

        Valve next = getNext();
        if (null == next) {
            return;
        }
        next.invoke(request, response);
    }

    private static void enrichWithSleuthHeaderWhenMissing(final Tracer tracer, final Request request) {
        String header = request.getHeader(Span.TRACE_ID_NAME);
        if (null == header) {

            org.apache.coyote.Request coyoteRequest = request.getCoyoteRequest();
            MimeHeaders mimeHeaders = coyoteRequest.getMimeHeaders();

            Span span = tracer.createSpan("SleuthValve");

            addHeader(mimeHeaders, Span.TRACE_ID_NAME, span.traceIdString());
             // Edit: Thanks to Marcin Grzejszczak
            // we add spanID to make it more generic
            //addHeader(mimeHeaders, Span.SPAN_ID_NAME, span.traceIdString());
            addHeader(mimeHeaders, Span.SPAN_ID_NAME, Span.idToHex(span.getSpanId()));
        }
    }

    private static void addHeader(MimeHeaders mimeHeaders, String traceIdName, String value) {
        MessageBytes messageBytes = mimeHeaders.addValue(traceIdName);
        messageBytes.setString(value);
    }
}

Then we add the configuration class to customize tomcat container by adding the sleuth valve

@Configuration
public class AccessLogConfiguration {

    private static final org.slf4j.Logger log = org.slf4j.LoggerFactory.getLogger(AccessLogConfiguration.class);

    @Bean
    public EmbeddedServletContainerCustomizer containerCustomizer(SleuthValve sleuthValve) {
        return (ConfigurableEmbeddedServletContainer container)  -> {
            if (container instanceof TomcatEmbeddedServletContainerFactory) {
                TomcatEmbeddedServletContainerFactory tomcat = (TomcatEmbeddedServletContainerFactory) container;

                        tomcat.addContextCustomizers(
                                (context) -> {
                                    context.getPipeline().addValve(sleuthValve);
                                });
            } else {
                log.warn("no access-log auto-configuration for container: {}", container);
            }
        };
    }

    @Bean
    public SleuthValve sleuthValve(Tracer tracer) {
        return new SleuthValve(tracer);
    }

}

Of course, the log configuration is set on application.yml

server:
  port: 8082
  tomcat:
    accesslog:
      enabled: true
      pattern: "%t %{X-B3-TraceId}i %r %U %s %b %a %T %{User-Agent}i %{Referer}i"
      directory: /tmp/${spring.application.name}
      prefix: access_log
      suffix: .log

And Voila! The example below shows the output we got before (No Trace id, just a hyphen -)

[17/Dec/2017:12:58:04 +0000] - GET /edge-service HTTP/1.1 200 15 192.168.1.2 20.018 Mozilla/5.0 (Linux; Android 7.0; SM-G950F Build/NRD90M) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/63.0.3239.111 Mobile Safari/537.36

And here the result after adding the valve

[17/Dec/2017:14:35:36 +0000] 1f63c572f5b3e9b3 GET /edge-service HTTP/1.1 /edge-service 200 15 192.168.1.2 0.085 Mozilla/5.0 (Linux; Android 7.0; SM-G950F Build/NRD90M) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/63.0.3239.111 Mobile Safari/537.36

Have anything to add ?! Please comment below or open an issue on github ;)