Spring sleuth

Correlation Id

When you start with microservices the natural question comes to mind: how to debug all this stuff. Unfortunately some of problems appear only in production environments. How to trace them effectively? Solution is not always so simple, but correlation id should help you with debugging such things. I will show you logs and everything should become clear right now:

2016-02-12 19:48:41.116 [trace=6d9ed076-bb14-42e9-b537-3ae1e85441b0,span=6d9ed076-bb14-42e9-b537-3ae1e85441b0] [o-auto-1-exec-3] o.s.cloud.sleuth.util.ExceptionUtils    : Trace client warn: thread http-nio-auto-1-exec-3 tried to start a new Span with parent MilliSpan(begin=1455302921115, end=0, name=null, traceId=6d9ed076-bb14-42e9-b537-3ae1e85441b0, parents=[], spanId=6d9ed076-bb14-42e9-b537-3ae1e85441b0, remote=true, exportable=true, annotations={}, processId=null, timelineAnnotations=[]), but there is already a currentSpan MilliSpan(begin=1455302921054, end=0, name=http/api/user/januszkowalski, traceId=6d9ed076-bb14-42e9-b537-3ae1e85441b0, parents=[], spanId=6d9ed076-bb14-42e9-b537-3ae1e85441b0, remote=false, exportable=false, annotations={}, processId=null, timelineAnnotations=[])

2016-02-12 19:48:41.119 [trace=6d9ed076-bb14-42e9-b537-3ae1e85441b0,span=17a6a6c2-dba3-4ac1-a23b-2deb6371c08b] [o-auto-1-exec-3] o.s.cloud.sleuth.log.Slf4jSpanListener  : Starting span: MilliSpan(begin=1455302921119, end=0, name=http/api/user/januszkowalski, traceId=6d9ed076-bb14-42e9-b537-3ae1e85441b0, parents=[6d9ed076-bb14-42e9-b537-3ae1e85441b0], spanId=17a6a6c2-dba3-4ac1-a23b-2deb6371c08b, remote=false, exportable=true, annotations={}, processId=null, timelineAnnotations=[])

First idea is to add unique id to every request and trace this id between another microservices interactions. This trick gives us possibility to trace our logs with this uid. Quite simple, but how to make this without rewriting this feaature from scratch?

In Approdorix project I started with Spring sleuth. It was really simple, just one line in application.properties:

logging.pattern.console=%d{yyyy-MM-dd HH:mm:ss.SSS} [trace=%X{X-Trace-Id:-},span=%X{X-Span-Id:-}] [%15.15t] %-40.40logger{39}: %m%n