From 5df50bf4ea7beb71f06de0daf2ef01c648db3b39 Mon Sep 17 00:00:00 2001 From: Marcin Grzejszczak Date: Tue, 27 Dec 2016 10:52:27 +0100 Subject: [PATCH] Increased timeout for Zipkin Server start --- README.adoc | 142 ++++++++---------- .../java/integration/ZipkinStreamTests.java | 6 +- 2 files changed, 62 insertions(+), 86 deletions(-) diff --git a/README.adoc b/README.adoc index 71ef987d3..768bfdd49 100644 --- a/README.adoc +++ b/README.adoc @@ -42,6 +42,8 @@ could set `logging.level.org.springframework.web.servlet.DispatcherServlet=DEBUG NOTE: Set `spring.application.name=bar` (for instance) to see the service name as well as the trace and span ids. +:branch: master + Spring Cloud Sleuth implements a distributed tracing solution for http://cloud.spring.io[Spring Cloud]. === Terminology @@ -77,7 +79,7 @@ the start and stop of a request are: Visualization of what *Span* and *Trace* will look in a system together with the Zipkin annotations: -image::{github-raw}/docs/src/main/asciidoc/images/trace-id.png[Trace Info propagation] +image::https://raw.githubusercontent.com/spring-cloud/spring-cloud-sleuth/{branch}/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: @@ -91,7 +93,7 @@ That means that the current span has *Trace-Id* set to *X*, *Span-Id* set to *D* This is how the visualization of the parent / child relationship of spans would look like: -image::{github-raw}/docs/src/main/asciidoc/images/parents.png[Parent child relationship] +image::https://raw.githubusercontent.com/spring-cloud/spring-cloud-sleuth/{branch}/docs/src/main/asciidoc/images/parents.png[Parent child relationship] === Purpose @@ -99,49 +101,66 @@ In the following sections the example from the image above will be taken into co ==== Distributed tracing with Zipkin -Altogether there are *10 spans* . If you go to traces in Zipkin you will see this number: +Altogether there are *7 spans* . If you go to traces in Zipkin you will see this number in the second trace: -image::{github-raw}/docs/src/main/asciidoc/images/zipkin-traces.png[Traces] +image::https://raw.githubusercontent.com/spring-cloud/spring-cloud-sleuth/{branch}/docs/src/main/asciidoc/images/zipkin-traces.png[Traces] -However if you pick a particular trace then you will see *7 spans*: +However if you pick a particular trace then you will see *4 spans*: -image::{github-raw}/docs/src/main/asciidoc/images/zipkin-ui.png[Traces Info propagation] +image::https://raw.githubusercontent.com/spring-cloud/spring-cloud-sleuth/{branch}/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? +Why is there a difference between the 7 and 4 spans in this case? - - 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. + - 2 spans come from `http:/start` span. It has the Server Received (SR) and Server Sent (SS) annotations. + - 2 spans come from the RPC call from `service1` to `service2` to the `http:/foo` endpoint. It has the Client Sent (CS) + and Client Received (CR) annotations on `service1` side. It also has Server Received (SR) and Server Sent (SS) annotations + on the `service2` side. Physically there are 2 spans but they form 1 logical span related to an RPC call. + - 2 spans come from the RPC call from `service2` to `service3` to the `http:/bar` endpoint. It has the Client Sent (CS) + and Client Received (CR) annotations on `service2` side. It also has Server Received (SR) and Server Sent (SS) annotations + on the `service3` side. Physically there are 2 spans but they form 1 logical span related to an RPC call. + - 2 spans come from the RPC call from `service2` to `service4` to the `http:/baz` endpoint. It has the Client Sent (CS) + and Client Received (CR) annotations on `service2` side. It also has Server Received (SR) and Server Sent (SS) annotations + on the `service4` side. Physically there are 2 spans but they form 1 logical span related to an RPC call. -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. +So if we count the physical spans we have *1* from `http:/start`, *2* from `service1` calling `service2`, *2* form `service2` +calling `service3` and *2* from `service2` calling `service4`. Altogether *7* spans. + +Logically we see the information of *Total Spans: 4* because we have *1* span related to the incoming request +to `service1` and *3* spans related to RPC calls. + +==== Visualizing errors + +Zipkin allows you to visualize errors in your trace. When an exception was thrown and wasn't caught then we're +setting proper tags on the span which Zipkin can properly colorize. You could see in the list of traces one + trace that was in red color. That's because there was an exception thrown. + +If you click that trace then you'll see a similar picture + +image::https://raw.githubusercontent.com/spring-cloud/spring-cloud-sleuth/{branch}/docs/src/main/asciidoc/images/zipkin-error-traces.png[Error Traces] + +Then if you click on one of the spans you'll see the following + +image::https://raw.githubusercontent.com/spring-cloud/spring-cloud-sleuth/{branch}/docs/src/main/asciidoc/images/zipkin-error-trace-screenshot.png[Error Traces Info propagation] + +As you can see you can easily see the reason for an error and the whole stacktrace related to it. + +==== Live examples .Click Pivotal Web Services icon to see it live! [caption="Click Pivotal Web Services icon to see it live!"] -image::{github-raw}/docs/src/main/asciidoc/images/pws.png["Zipkin deployed on Pivotal Web Services", link="http://docssleuth-zipkin-server.cfapps.io/", width=150, height=74] +image::https://raw.githubusercontent.com/spring-cloud/spring-cloud-sleuth/{branch}/docs/src/main/asciidoc/images/pws.png["Zipkin deployed on Pivotal Web Services", link="http://docssleuth-zipkin-server.cfapps.io/", width=150, height=74] The dependency graph in Zipkin would look like this: -image::{github-raw}/docs/src/main/asciidoc/images/dependencies.png[Dependencies] +image::https://raw.githubusercontent.com/spring-cloud/spring-cloud-sleuth/{branch}/docs/src/main/asciidoc/images/dependencies.png[Dependencies] .Click Pivotal Web Services icon to see it live! [caption="Click Pivotal Web Services icon to see it live!"] -image::{github-raw}/docs/src/main/asciidoc/images/pws.png["Zipkin deployed on Pivotal Web Services", link="http://docssleuth-zipkin-server.cfapps.io/dependency", width=150, height=74] +image::https://raw.githubusercontent.com/spring-cloud/spring-cloud-sleuth/{branch}/docs/src/main/asciidoc/images/pws.png["Zipkin deployed on Pivotal Web Services", link="http://docssleuth-zipkin-server.cfapps.io/dependency", width=150, height=74] ==== Log correlation @@ -161,7 +180,7 @@ If you're using a log aggregating tool like https://www.elastic.co/products/kiba http://www.splunk.com/[Splunk] etc. you can order the events that took place. An example of Kibana would look like this: -image::{github-raw}/docs/src/main/asciidoc/images/kibana.png[Log correlation with Kibana] +image::https://raw.githubusercontent.com/spring-cloud/spring-cloud-sleuth/{branch}/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: @@ -194,7 +213,7 @@ we're passing the dependencies in the `groupId:artifactId:version` notation. *Logback setup* -Below you can find an example of a Logback configuration (file named `https://github.com/spring-cloud-samples/sleuth-documentation-apps/blob/master/service1/src/main/resources/logback-spring.xml[logback-spring.xml]`) that: +Below you can find an example of a Logback configuration (file named https://github.com/spring-cloud-samples/sleuth-documentation-apps/blob/master/service1/src/main/resources/logback-spring.xml[logback-spring.xml]) that: - logs information from the application in a JSON format to a `build/${spring.application.name}.json` file - has commented out two additional appenders - console and standard log file @@ -211,13 +230,13 @@ Below you can find an example of a Logback configuration (file named `https://gi ​ + value="%clr(%d{yyyy-MM-dd HH:mm:ss.SSS}){faint} %clr(${LOG_LEVEL_PATTERN:-%5p}) %clr([${springAppName:-},%X{X-B3-TraceId:-},%X{X-B3-SpanId:-},%X{X-B3-ParentSpanId:-},%X{X-Span-Export:-}]){yellow} %clr(${PID:- }){magenta} %clr(---){faint} %clr([%15.15t]){faint} %clr(%-40.40logger{39}){cyan} %clr(:){faint} %m%n${LOG_EXCEPTION_CONVERSION_WORD:-%wEx}"/> - INFO + DEBUG ${CONSOLE_LOG_PATTERN} @@ -257,6 +276,7 @@ Below you can find an example of a Logback configuration (file named `https://gi "service": "${springAppName:-}", "trace": "%X{X-B3-TraceId:-}", "span": "%X{X-B3-SpanId:-}", + "parent": "%X{X-B3-ParentSpanId:-}", "exportable": "%X{X-Span-Export:-}", "pid": "${PID:-}", "thread": "%thread", @@ -270,7 +290,7 @@ Below you can find an example of a Logback configuration (file named `https://gi ​ - + @@ -280,50 +300,6 @@ Below you can find an example of a Logback configuration (file named `https://gi NOTE: If you're using a custom `logback-spring.xml` then you have to pass the `spring.application.name` in `bootstrap` instead of `application` property file. Otherwise your custom logback file won't read the property properly. -==== Propagating Span Context - -The span context is the state that must get propagated to any child Spans across process boundaries. -Part of the Span Context is the Baggage. The trace and span IDs are a required part of the span context. -Baggage is an optional part. - -Baggage is a set of key:value pairs stored in the span context. Baggage travels together with the trace -and is attached to every span. Spring Cloud Sleuth will understand that a header is baggage related if the HTTP - header is prefixed with `baggage-` and for messaging it starts with `baggage_`. - -IMPORTANT: There's currently no limitation of the count or size of baggage items. However, keep in mind that -too many can decrease system throughput or increase RPC latency. In extreme cases, it could crash the app due -to exceeding transport-level message or header capacity. - -Example of setting baggage on a span: - -[source,java] ----- -Span initialSpan = this.tracer.createSpan("span"); -initialSpan.setBaggageItem("foo", "bar"); ----- - -===== Baggage vs. Span Tags - -Baggage travels with the trace (i.e. every child span contains the baggage of its parent). Zipkin has no knowledge of -baggage and will not even receive that information. - -Tags are attached to a specific span - they are presented for that particular span only. However you -can search by tag to find the trace, where there exists a span having the searched tag value. - -If you want to be able to lookup a span based on baggage, you should add corresponding entry as a tag in the root span. - -[source,java] ----- -@Autowired Tracer tracer; - -Span span = tracer.getCurrentSpan(); -String baggageKey = "key"; -String baggageValue = "foo"; -span.setBaggageItem(baggageKey, baggageValue); -tracer.addTag(baggageKey, baggageValue); ----- - - === Adding to the project ==== Only Sleuth (log correlation) @@ -339,7 +315,7 @@ the `spring-cloud-starter-sleuth` module to your project. org.springframework.cloud spring-cloud-dependencies - Camden.RELEASE + Brixton.RELEASE pom import @@ -360,7 +336,7 @@ the Spring BOM ---- dependencyManagement { <1> imports { - mavenBom "org.springframework.cloud:spring-cloud-dependencies:Camden.RELEASE" + mavenBom "org.springframework.cloud:spring-cloud-dependencies:Brixton.RELEASE" } } @@ -384,7 +360,7 @@ If you want both Sleuth and Zipkin just add the `spring-cloud-starter-zipkin` de org.springframework.cloud spring-cloud-dependencies - Camden.RELEASE + Brixton.RELEASE pom import @@ -405,7 +381,7 @@ the Spring BOM ---- dependencyManagement { <1> imports { - mavenBom "org.springframework.cloud:spring-cloud-dependencies:Camden.RELEASE" + mavenBom "org.springframework.cloud:spring-cloud-dependencies:Brixton.RELEASE" } } @@ -429,7 +405,7 @@ If you want both Sleuth and Zipkin just add the `spring-cloud-sleuth-stream` dep org.springframework.cloud spring-cloud-dependencies - Camden.RELEASE + Brixton.RELEASE pom import @@ -461,7 +437,7 @@ the Spring BOM ---- dependencyManagement { <1> imports { - mavenBom "org.springframework.cloud:spring-cloud-dependencies:Camden.RELEASE" + mavenBom "org.springframework.cloud:spring-cloud-dependencies:Brixton.RELEASE" } } @@ -491,7 +467,7 @@ dependency org.springframework.cloud spring-cloud-dependencies - Camden.RELEASE + Brixton.RELEASE pom import @@ -523,7 +499,7 @@ the Spring BOM ---- dependencyManagement { <1> imports { - mavenBom "org.springframework.cloud:spring-cloud-dependencies:Camden.RELEASE" + mavenBom "org.springframework.cloud:spring-cloud-dependencies:Brixton.RELEASE" } } diff --git a/spring-cloud-sleuth-samples/spring-cloud-sleuth-sample-zipkin-stream/src/test/java/integration/ZipkinStreamTests.java b/spring-cloud-sleuth-samples/spring-cloud-sleuth-sample-zipkin-stream/src/test/java/integration/ZipkinStreamTests.java index 180df6e8f..bacd7bf69 100644 --- a/spring-cloud-sleuth-samples/spring-cloud-sleuth-sample-zipkin-stream/src/test/java/integration/ZipkinStreamTests.java +++ b/spring-cloud-sleuth-samples/spring-cloud-sleuth-sample-zipkin-stream/src/test/java/integration/ZipkinStreamTests.java @@ -15,6 +15,8 @@ */ package integration; +import static java.util.concurrent.TimeUnit.SECONDS; + import java.util.Collections; import java.util.Random; @@ -40,8 +42,6 @@ import org.springframework.test.context.junit4.SpringJUnit4ClassRunner; import example.ZipkinStreamServerApplication; import tools.AbstractIntegrationTest; -import static java.util.concurrent.TimeUnit.SECONDS; - @RunWith(SpringJUnit4ClassRunner.class) @SpringBootTest(classes = { TestSupportBinderAutoConfiguration.class, ZipkinStreamServerApplication.class }, webEnvironment = SpringBootTest.WebEnvironment.RANDOM_PORT) @@ -60,7 +60,7 @@ public class ZipkinStreamTests extends AbstractIntegrationTest { @Before public void setup() { - await().atMost(5, SECONDS).until(zipkinServerIsUp()); + await().atMost(10, SECONDS).until(zipkinServerIsUp()); } @Test