-
2016-02-02 15:30:57.902 INFO [bar,6bfd228dc00d216b,6bfd228dc00d216b,false] 23030 --- [nio-8081-exec-3] ...
-2016-02-02 15:30:58.372 ERROR [bar,6bfd228dc00d216b,6bfd228dc00d216b,false] 23030 --- [nio-8081-exec-3] ...
-2016-02-02 15:31:01.936 INFO [bar,46ab0d418373cbc9,46ab0d418373cbc9,false] 23030 --- [nio-8081-exec-4] ...
+
This trace shows that a `RefreshRemoteApplicationEvent` was sent from
+`customers:9000`, broadcast to all services, and it was received
+(acked) by `customers:9000` and `stores:8081`.
+
+To handle the ack signals yourself you could add an `@EventListener`
+for the `AckRemoteApplicationEvent` and `SentApplicationEvent` types
+to your app (and enable tracing). Or you could tap into the
+`TraceRepository` and mine the data from there.
+
+NOTE: Any Bus application can trace acks, but sometimes it will be
+useful to do this in a central service that can do more complex
+queries on the data. Or forward it to a specialized tracing service.
+
+== Broadcasting Your Own Events
+
+The Bus can carry any event of type `RemoteApplicationEvent`, but the
+default transport is JSON and the deserializer needs to know which
+types are going to be used ahead of time. To register a new type you
+can use `@JsonTypeName` on your custom class.
+
+:github-tag: master
+:github-repo: spring-cloud/spring-cloud-sleuth
+:github-raw: http://raw.github.com/{github-repo}/{github-tag}
+:github-code: http://github.com/{github-repo}/tree/{github-tag}
+:toc: left
+
+Spring Cloud Sleuth
+====================
+Adrian Cole, Spencer Gibb, Marcin Grzejszczak, Dave Syer
+:doctype: book
+
+Spring Cloud Sleuth implements a distributed tracing solution for http://cloud.spring.io[Spring Cloud].
+
+=== Terminology
+
+Spring Cloud Sleuth borrows http://research.google.com/pubs/pub36356.html[Dapper's] terminology.
+
+*Span:* The basic unit of work. For example, sending an RPC is a new span, as is sending a response to an
+RPC. Span's are identified by a unique 64-bit ID for the span and another 64-bit ID for the trace the span
+is a part of. Spans also have other data, such as descriptions, timestamped events, key-value
+annotations (tags), the ID of the span that caused them, and process ID's (normally IP address).
+
+Spans are started and stopped, and they keep track of their timing information. Once you create a
+span, you must stop it at some point in the future.
+
+*Trace:* A set of spans forming a tree-like structure. For example, if you are running a distributed
+big-data store, a trace might be formed by a put request.
+
+*Annotation:* is used to record existence of an event in time. Some of the core annotations used to define
+the start and stop of a request are:
+
+ - *cs* - Client Sent - The client has made a request. This annotation depicts the start of the span.
+ - *sr* - Server Received - The server side got the request and will start processing it.
+ If one subtracts the cs timestamp from this timestamp one will receive the network latency.
+ - *ss* - Server Sent - Annotated upon completion of request processing (when the response
+ got sent back to the client). If one subtracts the sr timestamp from this timestamp one
+ will receive the time needed by the server side to process the request.
+ - *cr* - Client Received - Signifies the end of the span. The client has successfully received the
+ response from the server side. If one subtracts the cs timestamp from this timestamp one
+ will receive the whole time needed by the client to receive the response from the server.
+
+Visualization of what *Span* and *Trace* will look in a system together with the Zipkin annotations:
+
+image::https://raw.githubusercontent.com/spring-cloud/spring-cloud-sleuth/master/docs/src/main/asciidoc/images/trace-id.png[Trace Info propagation]
+
+Each color of a note signifies a span (7 spans - from *A* to *G*). If you have such information in the note:
+
+[source]
+Trace Id = X
+Span Id = D
+Client Sent
+
+That means that the current span has *Trace-Id* set to *X*, *Span-Id* set to *D*. It also has emitted
+ *Client Sent* event.
+
+This is how the visualization of the parent / child relationship of spans would look like:
+
+image::https://raw.githubusercontent.com/spring-cloud/spring-cloud-sleuth/master/docs/src/main/asciidoc/images/parents.png[Parent child relationship]
+
+=== Purpose
+
+In the following sections the example from the image above will be taken into consideration.
+
+==== Distributed tracing with Zipkin
+
+Altogether there are *10 spans* . If you go to traces in Zipkin you will see this number:
+
+image::https://raw.githubusercontent.com/spring-cloud/spring-cloud-sleuth/master/docs/src/main/asciidoc/images/zipkin-traces.png[Traces]
+
+However if you pick a particular trace then you will see *7 spans*:
+
+image::https://raw.githubusercontent.com/spring-cloud/spring-cloud-sleuth/master/docs/src/main/asciidoc/images/zipkin-ui.png[Traces Info propagation]
+
+NOTE: When picking a particular trace you will see merged spans. That means that if there were 2 spans sent to
+Zipkin with Server Received and Server Sent / Client Received and Client Sent
+annotations then they will presented as a single span.
+
+In the image depicting the visualization of what *Span* and *Trace* is you can see 20
+colorful labels. How does it happen that in Zipkin 10 spans are received?
+
+ - 2 span *A* labels signify span started and closed. Upon closing a single span is sent to Zipkin.
+ - 4 span *B* labels are in fact are single span with 4 annotations. However this span is composed of
+ two separate instances. One sent from service 1 and one from service 2. So in fact two span instances will be sent
+ to Zipkin and merged there.
+ - 2 span *C* labels signify span started and closed. Upon closing a single span is sent to Zipkin.
+ - 4 span *B* labels are in fact are single span with 4 annotations. However this span is composed of
+ two separate instances. One sent from service 2 and one from service 3. So in fact two span instances will be sent
+ to Zipkin and merged there.
+ - 2 span *E* labels signify span started and closed. Upon closing a single span is sent to Zipkin.
+ - 4 span *B* labels are in fact are single span with 4 annotations. However this span is composed of
+ two separate instances. One sent from service 2 and one from service 4. So in fact two span instances will be sent
+ to Zipkin and merged there.
+ - 2 span *G* labels signify span started and closed. Upon closing a single span is sent to Zipkin.
+
+So 1 span from *A*, 2 spans from *B*, 1 span from *C*, 2 spans from *D*, 1 span from *E*, 2 spans from *F* and 1 from *G*.
+Altogether *10* spans.
+
+==== Log correlation
+
+When grepping the logs of those four applications by trace id equal to e.g. `2485ec27856c56f4` one would get the following:
+
+[source]
+service1.log:2016-02-26 11:15:47.561 INFO [service1,2485ec27856c56f4,2485ec27856c56f4,true] 68058 --- [nio-8081-exec-1] i.s.c.sleuth.docs.service1.Application : Hello from service1. Calling service2
+service2.log:2016-02-26 11:15:47.710 INFO [service2,2485ec27856c56f4,9aa10ee6fbde75fa,true] 68059 --- [nio-8082-exec-1] i.s.c.sleuth.docs.service2.Application : Hello from service2. Calling service3 and then service4
+service3.log:2016-02-26 11:15:47.895 INFO [service3,2485ec27856c56f4,1210be13194bfe5,true] 68060 --- [nio-8083-exec-1] i.s.c.sleuth.docs.service3.Application : Hello from service3
+service2.log:2016-02-26 11:15:47.924 INFO [service2,2485ec27856c56f4,9aa10ee6fbde75fa,true] 68059 --- [nio-8082-exec-1] i.s.c.sleuth.docs.service2.Application : Got response from service3 [Hello from service3]
+service4.log:2016-02-26 11:15:48.134 INFO [service4,2485ec27856c56f4,1b1845262ffba49d,true] 68061 --- [nio-8084-exec-1] i.s.c.sleuth.docs.service4.Application : Hello from service4
+service2.log:2016-02-26 11:15:48.156 INFO [service2,2485ec27856c56f4,9aa10ee6fbde75fa,true] 68059 --- [nio-8082-exec-1] i.s.c.sleuth.docs.service2.Application : Got response from service4 [Hello from service4]
+service1.log:2016-02-26 11:15:48.182 INFO [service1,2485ec27856c56f4,2485ec27856c56f4,true] 68058 --- [nio-8081-exec-1] i.s.c.sleuth.docs.service1.Application : Got response from service2 [Hello from service2, response from service3 [Hello from service3] and from service4 [Hello from service4]]
+
+If you're using a log aggregating tool like https://www.elastic.co/products/kibana[Kibana],
+http://www.splunk.com/[Splunk] etc. you can order the events that took place. An example of
+Kibana would look like this:
+
+image::https://raw.githubusercontent.com/spring-cloud/spring-cloud-sleuth/master/docs/src/main/asciidoc/images/kibana.png[Log correlation with Kibana]
+
+If you want to use https://www.elastic.co/guide/en/logstash/current/index.html[Logstash] here is the Grok pattern for Logstash:
+
+[source]
+filter {
+ # pattern matching logback pattern
+ grok {
+ match => { "message" => "%{TIMESTAMP_ISO8601:timestamp}\s+%{LOGLEVEL:severity}\s+\[%{DATA:service},%{DATA:trace},%{DATA:span},%{DATA:exportable}\]\s+%{DATA:pid}---\s+\[%{DATA:thread}\]\s+%{DATA:class}\s+:\s+%{GREEDYDATA:rest}" }
+ }
+}
+
+NOTE: If you want to use Grok together with the logs from Cloud Foundry you have to use this pattern:
+[source]
+filter {
+ # pattern matching logback pattern
+ grok {
+ match => { "message" => "(?m)OUT\s+%{TIMESTAMP_ISO8601:timestamp}\s+%{LOGLEVEL:severity}\s+\[%{DATA:service},%{DATA:trace},%{DATA:span},%{DATA:exportable}\]\s+%{DATA:pid}---\s+\[%{DATA:thread}\]\s+%{DATA:class}\s+:\s+%{GREEDYDATA:rest}" }
+ }
+}
+
+=== Adding to the project
+
+In general if you want to profit only from Spring Cloud Sleuth without the Zipkin integration just add
+the *spring-cloud-starter-sleuth* module to your project.
+
+If you want both Sleuth and Zipkin just add the *spring-cloud-starter-zipkin* dependency.
+
+== Features
+
+* Adds trace and span ids to the Slf4J MDC, so you can extract all the logs from a given trace or span in a log aggregator. Example logs:
++