Tracing a reactive flow - Using Spring Cloud Sleuth with Boot 2

Spring Cloud Sleuth which adds Spring instrumentation support on top of OpenZipkin Brave makes distributed tracing trivially simple for Spring Boot applications. This is a quick write up on what it takes to add support for distributed tracing using this excellent library.

Consider two applications - a client application which uses an upstream service application, both using Spring WebFlux, the reactive web stack for Spring:

My objective is to ensure that flows from user to the client application to the service application can be traced and latencies cleanly recorded for requests.


The final topology that Spring Cloud Sleuth enables is the following:

The sampled trace information from the client and the service app is exported to Zipkin via a queuing mechanism like RabbitMQ.


So what are the changes required to the client and the service app - like I said it is trivially simple! The following libraries need to be pulled in - in my case via gradle:

compile("org.springframework.cloud:spring-cloud-starter-sleuth")
 compile("org.springframework.cloud:spring-cloud-starter-zipkin")
 compile("org.springframework.amqp:spring-rabbit")

The versions are not specified as they are expected to be pulled in via Spring Cloud BOM and thanks to Spring Gradle Dependency Management plugin:

ext {
    springCloudVersion = 'Finchley.RELEASE'
}

apply plugin: 'io.spring.dependency-management'

dependencyManagement {
    imports {
        mavenBom "org.springframework.cloud:spring-cloud-dependencies:${springCloudVersion}"
    }
}

And that is actually it, any logs from the application should now start recording the trace and the spans, see how he traceid carried forward in the following logs spanning two different services:

2018-06-22 04:06:28.579  INFO [sample-client-app,c3d507df405b8aaf,c3d507df405b8aaf,true] 9 --- [server-epoll-13] sample.load.PassThroughHandler           : handling message: Message(id=null, payload=Test, delay=1000)
2018-06-22 04:06:28.586  INFO [sample-service-app,c3d507df405b8aaf,829fde759da15e63,true] 8 --- [server-epoll-11] sample.load.MessageHandler               : Handling message: Message(id=5e7ba240-f97d-405a-9633-5540bbfe0df1, payload=Test, delay=1000)

Further the Zipkin UI records the exported information and can visually show a sample trace the following way:

This sample is available in my github repository here - https://github.com/bijukunjummen/sleuth-webflux-sample and can be started up easily using docker-compose with all the dependencies wired in.

Cloud Foundry Custom User Provided Services(CUPS) and tagging

Custom User Provided Services or CUPS for short is a way to deliver credentials for external services to an application hosted on Cloud Foundry.

Consider a set of credentials represented as a json of the following form:

{
 "hostname": "mysql-broker.local.pcfdev.io",
 "jdbcUrl": "jdbc:mysql://mysql-broker.local.pcfdev.io:3306/somedb?user=someuser\u0026password=somepass",
 "name": "somedb",
 "password": "somepass",
 "port": 3306,
 "uri": "mysql://someuser:somepass@mysql-broker.local.pcfdev.io:3306/somedb?reconnect=true",
 "username": "someuser"
}

I could create a user provided service out of these values using cf-cli. The following is highly bash shell specific, so on a different shell the mileage is likely to vary:

CUPS_PARAM=$(cat <<-'EOF'
{
 "hostname": "mysql-broker.local.pcfdev.io",
 "jdbcUrl": "jdbc:mysql://mysql-broker.local.pcfdev.io:3306/somedb?user=someuser\u0026password=somepass",
 "name": "somedb",
 "password": "somepass",
 "port": 3306,
 "uri": "mysql://someuser:somepass@mysql-broker.local.pcfdev.io:3306/somedb?reconnect=true",
 "username": "someuser"
}
EOF
)

cf create-user-provided-service mycups -p ''"$CUPS_PARAM"''

This Custom User provided service can be bound to an app:

cf bind-service myapp mycups

and the application can retrieve the credentials via an environment variable called VCAP_SERVICES at runtime.

Issue

There is one small issue with the Custom User provided services over normal services created via Service Brokers on Cloud Foundry - there is no simple way to tag a Custom User Provided service. Tags are sometimes useful in getting a little more information about the service bound to an app and is extensively used by Spring Cloud Connectors to connect to services.

Solution

I have written a custom service broker called the CUPS tagging broker using which a service can be created with all the parameters normally passed to create the CUPS, additionally since it is a normal service it can be tagged.

Assuming that the "CUPS tagging broker" has been installed using the instructions here, an equivalent user provided service with tags can be created the following way, with two tags attached to the service:

cf create-service cups-tagging-service default my-cups-tagged -c ''"$CUPS_PARAM"'' -t "tag1, tag2"

If I were to bind this service to an app, the VCAP_SERVICES environment variable of the app would be along these lines:

{"cups-tagging-service":[{
  "credentials": {
    "hostname": "mysql-broker.local.pcfdev.io",
    "jdbcUrl": "jdbc:mysql://mysql-broker.local.pcfdev.io:3306/somedb?user=someuser&password=somepass",
    "name": "somedb",
    "password": "somepass",
    "port": 3306,
    "uri": "mysql://someuser:somepass@mysql-broker.local.pcfdev.io:3306/somedb?reconnect=true",
    "username": "someuser"
  },
  "syslog_drain_url": null,
  "volume_mounts": [

  ],
  "label": "cups-tagging-service",
  "provider": null,
  "plan": "default",
  "name": "my-cups-tagged",
  "tags": [
    "cups-tag",
    "tag1",
    "tag2"
  ]
}]}

See how the two additional tags show up.

That is all there is to the CUPS tagging Service Broker!

Tracing Spring Integration Flow with Spring Cloud Sleuth

Spring Cloud Sleuth is an awesome project that provides a way to trace requests that span multiple systems. Spring Cloud sleuth can optionally export this trace data to Zipkin where it can be visualized in a neat way. I especially love the fact that Spring Cloud Sleuth integrates deeply with Spring Integration and can nicely trace out the flow of a message.


Consider the following -

I have two different systems here - a work dispatcher producing "Work Unit"s and a Work Handler consuming them. They talk over a RabbitMQ broker. Just to mix the flow up a bit, I also have a retry mechanism in place which retries the message every 20 seconds in case of a processing failure

Both these systems are described using Spring Integration Java DSL, the outbound flow dispatching the WorkUnits looks like this:

@Configuration
public class WorksOutbound {

    @Autowired
    private RabbitConfig rabbitConfig;

    @Bean
    public IntegrationFlow toOutboundQueueFlow() {
        return IntegrationFlows.from("worksChannel")
                .transform(Transformers.toJson())
                .log()
                .handle(Amqp.outboundGateway(rabbitConfig.worksRabbitTemplate()))
                .transform(Transformers.fromJson(WorkUnitResponse.class))
                .get();
    }

    @Bean
    public IntegrationFlow handleErrors() {
        return IntegrationFlows.from("errorChannel")
                .transform((MessagingException e) -> e.getFailedMessage().getPayload())
                .transform(Transformers.fromJson(WorkUnit.class))
                .transform((WorkUnit failedWorkUnit) -> new WorkUnitResponse(failedWorkUnit.getId(), failedWorkUnit.getDefinition(), false))
                .get();
    }

}

This is eminently readable - the "Work Unit" comes through a "works channel" and is dispatched to a RabbitMQ queue after tranforming to json. Note that the dispatch is via an outbound gateway, this means that the Spring integration would put the necessary infrastructure in place to wait for a reply to be back from the remote system. In case of an error, say if the reply does not appear in time, a stock response is provided back to the user.

On the Work Handler side a similar flow handles the message:

@Configuration
public class WorkInbound {

    @Autowired
    private RabbitConfig rabbitConfig;

    @Bean
    public IntegrationFlow inboundFlow() {
        return IntegrationFlows.from(
                Amqp.inboundGateway(rabbitConfig.workListenerContainer()))
                .transform(Transformers.fromJson(WorkUnit.class))
                .log()
                .filter("(headers['x-death'] != null) ? headers['x-death'][0].count < 3: true", f -> f.discardChannel("nullChannel"))
                .handle("workHandler", "process")
                .transform(Transformers.toJson())
                .get();
    }

}

The only wrinkle in this flow is the retry logic which discards the message after 3 retries. If you are interested in the details of how the retry is being hooked up, I have more details here.


So now, given this fairly involved flow, here is how Spring Cloud Sleuth with Zipkin integrated looks like:

Spring Cloud Sleuth intercepts every message channel and tags the message as it flows through the channel.


Now for something a little more interesting, if the flow were more complex with 3 retries each 20 seconds apart, again the flow is beautifully brought out by Spring Cloud Sleuth and its integration with Zipkin.

Conclusion

If you maintain a Spring Integration based flow, Spring Cloud Sleuth is an addition to the project and can trace the runtime path of a message and show it visually using the Zipkin UI. I look forward to exploring more of the nuances of this excellent project.


The sample that I have demonstrated here is available in my github repo - https://github.com/bijukunjummen/si-with-sleuth-sample