+Introduction
+Overview
-
+Spring Cloud Sleuth implements a distributed tracing solution for Spring Cloud.
+Spring Cloud Sleuth provides Spring Boot auto-configuration for distributed +tracing. Underneath, Spring Cloud Sleuth is a layer over a Tracer library named +Brave.
+
+
+Sleuth configures everything you need to get started. This includes where trace +data (spans) are reported to, how many traces to keep (sampling), if remote +fields (baggage) are sent, and which libraries are traced.
+
+
+We maintain an example app where two Spring Boot services collaborate on an +HTTP request. Sleuth configures these apps, so that timing of these requests are +recorded into Zipkin, a distributed tracing system. Tracing +UIs visualize latency, such as time in one service vs waiting for other +services.
+
+
+Here’s an example of what it looks like:
+
+
+
+
+
+
+
+
+The source repository of this +example includes demonstrations ofmany things, including WebFlux and messaging. +Most features require only a property or dependency change to work. These +snippets showcase the value of Spring Cloud Sleuth: Through auto-configuration, +Sleuth make getting started with distributed tracing easy!
+
+
To keep things simple, the same example is used throughout documentation using +basic HTTP communication.
-
-Terminology
+.1. Features
-
Spring Cloud Sleuth borrows Dapper’s terminology.
+Sleuth sets up instrumentation not only to track timing, but also to catch
+errors so that they can be analyzed or correlated with logs. This works the
+same way regardless of if the error came from a common instrumented library,
+such as RestTemplate, or your own code annotated with @NewSpan or similar.
-
-Span: The basic unit of work. For example, sending an RPC is a new span, as is sending a response to an RPC. -Spans 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 IDs (normally IP addresses).
-
-
-Spans can be 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.
-
-
-
-
-| - - | -
-The initial span that starts a trace is called a root span. The value of the ID
-of that span is equal to the trace ID.
- |
-
-
-Trace: A set of spans forming a tree-like structure.
-For example, if you run a distributed big-data store, a trace might be formed by a PUT request.
-
-Annotation: Used to record the existence of an event in time. With -Brave instrumentation, we no longer need to set special events -for Zipkin to understand who the client and server are, where -the request started, and where it ended. For learning purposes, -however, we mark these events to highlight what kind -of an action took place.
-
-
--
-
-
-
cs: Client Sent. The client has made a request. This annotation indicates the start of the span.
-
- -
-
sr: Server Received: The server side got the request and started processing it. -Subtracting the
-cstimestamp from this timestamp reveals the network latency.
- -
-
ss: Server Sent. Annotated upon completion of request processing (when the response got sent back to the client). -Subtracting the
-srtimestamp from this timestamp reveals 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. -Subtracting the
-cstimestamp from this timestamp reveals the whole time needed by the client to receive the response from the server.
-
-
-The following image shows how Span and Trace look in a system, together with the Zipkin annotations:
-
-
-
-
-
-
-
-
-Each color of a note signifies a span (there are seven spans - from A to G). -Consider the following note:
-
-
-
-
-Trace Id = X
-Span Id = D
-Client Sent
-
-This note indicates that the current span has Trace Id set to X and Span Id set to D.
-Also, the Client Sent event took place.
-
-The following image shows how parent-child relationships of spans look:
-
-
-
-
-
-
-
-
Purpose
-
-
The following sections refer to the example shown in the preceding image.
+Below, we’ll use the word Zipkin to describe the tracing system, and include +Zipkin screenshots. However, most services accepting Zipkin’s format[zipkin.io/zipkin-api/#/default/post_spans], +have similar base features. Sleuth can also be configured to send data in other +formats, something detailed later.
-
-Distributed Tracing with Zipkin
+.1.1. Contextualizing errors
-
-This example has seven spans. -If you go to traces in Zipkin, you can see this number in the second trace, as shown in the following image:
-
-
-
-
+
-Without distributed tracing, it can be difficult to understand the impact of a +an exception. For example, it can be hard to know if a specific request caused +the caller to fail or not.
-
-However, if you pick a particular trace, you can see four spans, as shown in the following image:
-
-
-
-
-
-
-
-
-
+
| - - | --When you pick a particular trace, you see merged spans. -That means that, if there were two spans sent to Zipkin with Server Received and Server Sent or Client Received and Client Sent annotations, they are presented as a single span. - | -
Zipkin reduces time in triage by contextualizing errors and delays.
-
-Why is there a difference between the seven and four spans in this case?
-
-
--
-
-
-
One span comes from the
-http:/startspan. It has the Server Received (sr) and Server Sent (ss) annotations.
- -
-
Two spans come from the RPC call from
-service1toservice2to thehttp:/fooendpoint. -The Client Sent (cs) and Client Received (cr) events took place on theservice1side. -Server Received (sr) and Server Sent (ss) events took place on theservice2side. -These two spans form one logical span related to an RPC call.
- -
-
Two spans come from the RPC call from
-service2toservice3to thehttp:/barendpoint. -The Client Sent (cs) and Client Received (cr) events took place on theservice2side. -The Server Received (sr) and Server Sent (ss) events took place on theservice3side. -These two spans form one logical span related to an RPC call.
- -
-
Two spans come from the RPC call from
-service2toservice4to thehttp:/bazendpoint. -The Client Sent (cs) and Client Received (cr) events took place on theservice2side. -Server Received (sr) and Server Sent (ss) events took place on theservice4side. -These two spans form one logical span related to an RPC call.
-
-
-So, if we count the physical spans, we have one from http:/start, two from service1 calling service2, two from service2
-calling service3, and two from service2 calling service4. In sum, we have a total of seven spans.
-
-Logically, we see the information of four total Spans because we have one span related to the incoming request
-to service1 and three spans related to RPC calls.
-
Visualizing errors
-
-
-Zipkin lets you visualize errors in your trace. -When an exception was thrown and was not caught, we set proper tags on the span, which Zipkin can then properly colorize. -You could see in the list of traces one trace that is red. That appears because an exception was thrown.
-
-
If you click that trace, you see a similar picture, as follows:
+Requests colored red in the search screen failed:
@@ -414,7 +307,8 @@ You could see in the list of traces one trace that is red. That appears because
-
If you then click on one of the spans, you see the following
+If you then click on one of the traces, you can understand if the failure +happened before the request hit another service or not:
@@ -422,65 +316,34 @@ You could see in the list of traces one trace that is red. That appears because
-
The span shows the reason for the error and the whole stack trace related to it.
+For example, the above error happened in the "backend" service, and caused the +"frontend" service to fail.
-
-Distributed Tracing with Brave
+.1.2. Log correlation
-
Starting with version 2.0.0, Spring Cloud Sleuth uses Brave as the tracing library.
-Consequently, Sleuth no longer takes care of storing the context but delegates that work to Brave.
Sleuth configures the logging context with variables including the service name
+(%{spring.zipkin.service.name}) and the trace ID (%{traceId}). These help
+you connect logs with distributed traces and allow you choice in what tools you
+use to troubleshoot your services.
-
-Due to the fact that Sleuth had different naming and tagging conventions than Brave, we decided to follow Brave’s conventions from now on.
-
-
-Live examples
-
-
-
-
-
-
-
-Click the Pivotal Web Services icon to see it live!Click the Pivotal Web Services icon to see it live!
-
-
-The dependency graph in Zipkin should resemble the following image:
-
-
-
-
-
-
-
-
-
-
-
-
-
-Click the Pivotal Web Services icon to see it live!Click the Pivotal Web Services icon to see it live!
-
-
Log correlation
-
-
When using grep to read the logs of those four applications by scanning for a trace ID equal to (for example) 2485ec27856c56f4, you get output resembling the following:
Once you find any log with an error, you can look for the trace ID in the +message. Paste that into Zipkin to visualize the entire trace, regardless of +how many services the first request ended up hitting.
-
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]]backend.log: 2020-04-09 17:45:40.516 ERROR [backend,5e8eeec48b08e26882aba313eb08f0a4,dcc1df555b5777b3,true] 97203 --- [nio-9000-exec-1] o.s.c.s.i.web.ExceptionLoggingFilter : Uncaught exception thrown
+frontend.log:2020-04-09 17:45:40.574 ERROR [frontend,5e8eeec48b08e26882aba313eb08f0a4,82aba313eb08f0a4,true] 97192 --- [nio-8081-exec-2] o.s.c.s.i.web.ExceptionLoggingFilter : Uncaught exception thrown
+
+
@@ -537,7 +400,7 @@ If you want to use Grok together with the logs from Cloud Foundry, you have to u
Above, you’ll notice the trace ID is 5e8eeec48b08e26882aba313eb08f0a4, for
+example. This log configuration was automatically setup by Sleuth.
-
@@ -674,33 +537,41 @@ Otherwise, your custom logback file does not properly read the property.
JSON Logback with Logstash
+JSON Logback with Logstash
Often, you do not want to store your logs in a text file but in a JSON file that Logstash can immediately pick.
To do so, you have to do the following (for readability, we pass the dependencies in the groupId:artifactId:version notation).
<?xml version="1.0" encoding="UTF-8"?>
<configuration>
- <include resource="org/springframework/boot/logging/logback/defaults.xml"/>
-
- <springProperty scope="context" name="springAppName" source="spring.application.name"/>
- <!-- Example for logging into the build folder of your project -->
- <property name="LOG_FILE" value="${BUILD_FOLDER:-build}/${springAppName}"/>
+ <include resource="org/springframework/boot/logging/logback/defaults.xml"/>
+
+ <springProperty scope="context" name="springAppName" source="spring.application.name"/>
+ <!-- Example for logging into the build folder of your project -->
+ <property name="LOG_FILE" value="${BUILD_FOLDER:-build}/${springAppName}"/>
- <!-- You can override this to have a custom pattern -->
- <property name="CONSOLE_LOG_PATTERN"
- value="%clr(%d{yyyy-MM-dd HH:mm:ss.SSS}){faint} %clr(${LOG_LEVEL_PATTERN:-%5p}) %clr(${PID:- }){magenta} %clr(---){faint} %clr([%15.15t]){faint} %clr(%-40.40logger{39}){cyan} %clr(:){faint} %m%n${LOG_EXCEPTION_CONVERSION_WORD:-%wEx}"/>
+ <!-- You can override this to have a custom pattern -->
+ <property name="CONSOLE_LOG_PATTERN"
+ value="%clr(%d{yyyy-MM-dd HH:mm:ss.SSS}){faint} %clr(${LOG_LEVEL_PATTERN:-%5p}) %clr(${PID:- }){magenta} %clr(---){faint} %clr([%15.15t]){faint} %clr(%-40.40logger{39}){cyan} %clr(:){faint} %m%n${LOG_EXCEPTION_CONVERSION_WORD:-%wEx}"/>
- <!-- Appender to log to console -->
- <appender name="console" class="ch.qos.logback.core.ConsoleAppender">
- <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
- <!-- Minimum logging level to be presented in the console logs-->
- <level>DEBUG</level>
- </filter>
- <encoder>
- <pattern>${CONSOLE_LOG_PATTERN}</pattern>
- <charset>utf8</charset>
- </encoder>
- </appender>
+ <!-- Appender to log to console -->
+ <appender name="console" class="ch.qos.logback.core.ConsoleAppender">
+ <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
+ <!-- Minimum logging level to be presented in the console logs-->
+ <level>DEBUG</level>
+ </filter>
+ <encoder>
+ <pattern>${CONSOLE_LOG_PATTERN}</pattern>
+ <charset>utf8</charset>
+ </encoder>
+ </appender>
- <!-- Appender to log to file -->
- <appender name="flatfile" class="ch.qos.logback.core.rolling.RollingFileAppender">
- <file>${LOG_FILE}</file>
- <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
- <fileNamePattern>${LOG_FILE}.%d{yyyy-MM-dd}.gz</fileNamePattern>
- <maxHistory>7</maxHistory>
- </rollingPolicy>
- <encoder>
- <pattern>${CONSOLE_LOG_PATTERN}</pattern>
- <charset>utf8</charset>
- </encoder>
- </appender>
-
- <!-- Appender to log to file in a JSON format -->
- <appender name="logstash" class="ch.qos.logback.core.rolling.RollingFileAppender">
- <file>${LOG_FILE}.json</file>
- <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
- <fileNamePattern>${LOG_FILE}.json.%d{yyyy-MM-dd}.gz</fileNamePattern>
- <maxHistory>7</maxHistory>
- </rollingPolicy>
- <encoder class="net.logstash.logback.encoder.LoggingEventCompositeJsonEncoder">
- <providers>
- <timestamp>
- <timeZone>UTC</timeZone>
- </timestamp>
- <pattern>
- <pattern>
- {
- "severity": "%level",
- "service": "${springAppName:-}",
- "trace": "%X{X-B3-TraceId:-}",
- "span": "%X{X-B3-SpanId:-}",
- "parent": "%X{X-B3-ParentSpanId:-}",
- "exportable": "%X{X-Span-Export:-}",
- "baggage": "%X{key:-}",
- "pid": "${PID:-}",
- "thread": "%thread",
- "class": "%logger{40}",
- "rest": "%message"
- }
- </pattern>
- </pattern>
- </providers>
- </encoder>
- </appender>
-
- <root level="INFO">
- <appender-ref ref="console"/>
- <!-- uncomment this to have also JSON logs -->
- <!--<appender-ref ref="logstash"/>-->
- <!--<appender-ref ref="flatfile"/>-->
- </root>
+ <!-- Appender to log to file -->
+ <appender name="flatfile" class="ch.qos.logback.core.rolling.RollingFileAppender">
+ <file>${LOG_FILE}</file>
+ <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
+ <fileNamePattern>${LOG_FILE}.%d{yyyy-MM-dd}.gz</fileNamePattern>
+ <maxHistory>7</maxHistory>
+ </rollingPolicy>
+ <encoder>
+ <pattern>${CONSOLE_LOG_PATTERN}</pattern>
+ <charset>utf8</charset>
+ </encoder>
+ </appender>
+
+ <!-- Appender to log to file in a JSON format -->
+ <appender name="logstash" class="ch.qos.logback.core.rolling.RollingFileAppender">
+ <file>${LOG_FILE}.json</file>
+ <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
+ <fileNamePattern>${LOG_FILE}.json.%d{yyyy-MM-dd}.gz</fileNamePattern>
+ <maxHistory>7</maxHistory>
+ </rollingPolicy>
+ <encoder class="net.logstash.logback.encoder.LoggingEventCompositeJsonEncoder">
+ <providers>
+ <timestamp>
+ <timeZone>UTC</timeZone>
+ </timestamp>
+ <pattern>
+ <pattern>
+ {
+ "severity": "%level",
+ "service": "${springAppName:-}",
+ "trace": "%X{X-B3-TraceId:-}",
+ "span": "%X{X-B3-SpanId:-}",
+ "parent": "%X{X-B3-ParentSpanId:-}",
+ "exportable": "%X{X-Span-Export:-}",
+ "baggage": "%X{key:-}",
+ "pid": "${PID:-}",
+ "thread": "%thread",
+ "class": "%logger{40}",
+ "rest": "%message"
+ }
+ </pattern>
+ </pattern>
+ </providers>
+ </encoder>
+ </appender>
+
+ <root level="INFO">
+ <appender-ref ref="console"/>
+ <!-- uncomment this to have also JSON logs -->
+ <!--<appender-ref ref="logstash"/>-->
+ <!--<appender-ref ref="flatfile"/>-->
+ </root>
</configuration>
-
+Propagating Span Context
+.1.3. Service Dependency Graph
-
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.
+When you consider distributed tracing tracks requests, it makes sense that +trace data can paint a picture of your architecture.
-
-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 understands that a header is baggage-related if the HTTP header is prefixed with baggage- and, for messaging, it starts with baggage_.
-
-
+
| - - | --There is 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, too much baggage can crash the application, due to exceeding transport-level message or header capacity. - | -
Zipkin includes a tool to build service dependency diagrams from traces, +including the count of calls and how many errors exist.
-
+The following example shows setting baggage on a span:
+The example application will make a simple diagram like this, but your real +environment diagram may be more complex. +image::https://raw.githubusercontent.com/spring-cloud/spring-cloud-sleuth/master/docs/src/main/asciidoc/images/zipkin-depedendencies.png[Zipkin Dependencies]
+
+
+Note: Production environments will generate a lot of data. You will likely +need to run a separate service to aggregate the dependency graph. You can learn +more here.
+
+
+
.1.4. Request scoped properties (Baggage)
+
+
+Distributed tracing works by propagating fields inside and across services that +connect the trace together: traceId and spanId notably. The context that holds +these fields can optionally push other fields that need to be consistent +regardless of many services are touched. The simple name for these extra fields +is "Baggage".
+
+
+Sleuth allows you to define which baggage are permitted to exist in the trace +context, including what header names are used.
+
+
The following example shows setting baggage values:
@@ -709,49 +580,34 @@ BUSINESS_PROCESS.updateValue(initialSpan.context(), "ALM");
COUNTRY_CODE.updateValue(initialSpan.context(), "FO");
+
+
+
| + + | ++There is currently no limitation of the count or size of baggage +items. Keep in mind that too many can decrease system throughput or increase +RPC latency. In extreme cases, too much baggage can crash the application, due +to exceeding transport-level message or header capacity. + | +
-
Baggage versus Span Tags
+Baggage versus Tags
-
-Baggage travels with the trace (every child span contains the baggage of its parent). -Zipkin has no knowledge of baggage and does not receive that information.
-
-
-
+
| - - | --Starting from Sleuth 2.0.0 you have to pass the baggage key names explicitly -in your project configuration. Read more about that setup here - | -
Like trace IDs, Baggage is attached to messages or requests, usually as +headers. Tags are key value pairs sent in a Span to Zipkin. Baggage values are +not added spans by default, which means you can’t search based on Baggage +unless you opt-in.
-
-Tags are attached to a specific span. In other words, they are presented only for that particular span. -However, you can search by tag to find the trace, assuming a span having the searched tag value exists.
-
-
-If you want to be able to lookup a span based on baggage, you should add a corresponding entry as a tag in the root span.
-
-
-
-
-| - - | --The span must be in scope. - | -
-
The following listing shows integration tests that use baggage:
+To make baggage also tags, use the property spring.sleuth.baggage.tag-fields
+like so:
-
-The setup
spring:
sleuth:
@@ -763,17 +619,11 @@ The span must be in scope.
- country-code
-
The code
-
-
-Tags.BAGGAGE_FIELD.tag(BUSINESS_PROCESS, initialSpan);
+