SpringCloud--Sleuth日志跟踪(十四)

一、Sleuth简介

Spring Cloud Sleuth[sluːθ]是Spring Cloud提供的分布式系统服务链追踪组件，它大量借用了Google的Dapper，Twitter的Zipkin。

在分布式系统中，一个集群中有几十个微服务；
微服务调用微服务，一个或多个微服务的网络环境问题、硬件问题导致服务提供失败；

我们怎么去定位这个出问题的服务？
怎么定位出问题接口？
怎么分析行为诱因？
难道要逐个的看log？
肯定不是，sleuth 可以给我们提供很好的方案，用服务链路追踪来快速查看。sleuth 集成了Zipkin、HTrace 几种链路追踪工具，我选择zipkin。

在微服务中，通常根据业务模块分服务，项目中前端发起一个请求，后端可能跨几个服务调用才能完成这个请求（如下图）。

Sleuth

如果系统越来越庞大，服务之间的调用与被调用关系就会变得很复杂，假如一个请求中需要跨几个服务调用，其中一个服务由于网络延迟等原因挂掉了，那么这时候我们需要分析具体哪一个服务出问题了就会显得很困难。Spring Cloud Sleuth服务链路跟踪功能，就可以帮助我们快速的发现错误根源以及监控分析每条请求链路上的性能等等。
Spring Cloud Sleuth是一个在应用中实现日志跟踪的强有力的工具。使用Sleuth库可以应用于计划任务 、多线程服务或复杂的Web请求，尤其是在一个由多个服务组成的系统中。当我们在这些应用中来诊断问题时，即使有日志记录也很难判断出一个请求需要将哪些操作关联在一起。
如果想要诊断复杂操作，通常的解决方案是在请求中传递唯一的ID到每个方法来识别日志。 而Sleuth可以与日志框架Logback、SLF4J轻松地集成，通过添加独特的标识符来使用日志跟踪和诊断问题。
微服务跟踪(sleuth)其实是一个工具,它在整个分布式系统中能跟踪一个用户请求的过程(包括数据采集，数据传输，数据存储，数据分析，数据可视化)，捕获这些跟踪数据，就能构建微服务的整个调用链的视图，这是调试和监控微服务的关键工具。
SpringCloudSleuth有4个特点:

<dependency> <groupId>org.springframework.cloud</groupId> <artifactId>spring-cloud-starter-sleuth</artifactId> </dependency>

三、 Application.properties配置

配置应用名称，以便日志输出。 

# 应用程序名称
spring.cloud.config.name=goods-service

四、日志输出测试


  • 编写控制器
    • 

    @RestController
@RequestMapping("goods")
@Slf4j
public class GoodsController {
    @Autowired
    private RestTemplate restTemplate;
     * 注入Rest模板
     * @return
    @Bean
    public RestTemplate getRestTemplate() {
        return new RestTemplate();
    @GetMapping
    public String getGoodsByUser() {
        String response = (String) restTemplate.exchange("http://localhost:8080/user",
                HttpMethod.GET, null, new ParameterizedTypeReference<String>() {
                }).getBody();
        log.info("测试sleuth");
        return  response;

  • 查看日志结果：
    
日志的格式为：[application name, traceId, spanId, export]
    • 

    [goods-client,5a43ec515cf49d23,5a43ec515cf49d23,true] 18076 --- [nio-8081-exec-7] c.xtsz.goods.controller.GoodsController  : 测试sleuth
application name — 应用的名称，也就是application.properties中的spring.application.name参数配置的属性。
    
traceId — 为一个请求分配的ID号，用来标识一条请求链路。
    
spanId — 表示一个基本的工作单元，一个请求可以包含多个步骤，每个步骤都拥有自己的spanId。一个请求包含一个TraceId，多个SpanId
    
export — 布尔类型。表示是否要将该信息输出到类似Zipkin这样的聚合器进行收集和展示。
    

    四、异步线程池
    

    @Configuration
@EnableAsync
public class ThreadConfig extends AsyncConfigurerSupport {
    @Autowired
    private BeanFactory beanFactory;
    @Override
    public Executor getAsyncExecutor() {
        // 线程池定义
        ThreadPoolTaskExecutor threadPoolTaskExecutor = new ThreadPoolTaskExecutor();
        threadPoolTaskExecutor.setCorePoolSize(7);
        threadPoolTaskExecutor.setMaxPoolSize(42);
        threadPoolTaskExecutor.setQueueCapacity(11);
        threadPoolTaskExecutor.setThreadNamePrefix("MyExecutor-");
        threadPoolTaskExecutor.initialize();
        // sleuth 中延时跟踪执行
        return new LazyTraceExecutor(beanFactory, threadPoolTaskExecutor);

    @Service
@Slf4j
public class UserService {
    @Async
    public void asyncMethod() throws InterruptedException {
        log.info("开始执行异步方法");
        Thread.sleep(1000L);
        log.info("异步方法执行结束");

    @RestController
@RequestMapping("user")
@Slf4j
public class UserController {
    @Autowired
    private UserService userService;
    @RequestMapping("/async")
    public String async() throws InterruptedException {
        System.out.println("####控制器输出####   1");
        log.info("####异步方法调用前####");
        userService.asyncMethod();
        log.info("####异步方法调用后####");
        return "success";
地址：http://localhost:8080/user/async

    ####控制器输出####   1
2019-09-18 11:15:18.335  INFO [user-client,3f575919b0df993a,3f575919b0df993a,true] 19040 --- [nio-8080-exec-5] com.xtsz.user.controller.UserController  : ####异步方法调用前####
2019-09-18 11:15:18.335  INFO [user-client,3f575919b0df993a,3f575919b0df993a,true] 19040 --- [nio-8080-exec-5] o.s.s.concurrent.ThreadPoolTaskExecutor  : Initializing ExecutorService
2019-09-18 11:15:18.338  INFO [user-client,3f575919b0df993a,3f575919b0df993a,true] 19040 --- [nio-8080-exec-5] com.xtsz.user.controller.UserController  : ####异步方法调用后####
2019-09-18 11:15:18.342  INFO [user-client,3f575919b0df993a,05fddf5ed5bbbf59,true] 19040 --- [   MyExecutor-1] com.xtsz.user.service.UserService        : 开始执行异步方法
2019-09-18 11:15:19.020  INFO [user-client,,,] 19040 --- [ender@5ae1c281}] c.netflix.config.ChainedDynamicProperty  : Flipping property: localhost.ribbon.ActiveConnectionsLimit to use NEXT property: niws.loadbalancer.availabilityFilteringRule.activeConnectionsLimit = 2147483647
2019-09-18 11:15:19.036  INFO [user-client,,,] 19040 --- [ender@5ae1c281}] c.n.u.concurrent.ShutdownEnabledTimer    : Shutdown hook installed for: NFLoadBalancer-PingTimer-localhost
2019-09-18 11:15:19.036  INFO [user-client,,,] 19040 --- [ender@5ae1c281}] c.netflix.loadbalancer.BaseLoadBalancer  : Client: localhost instantiated a LoadBalancer: DynamicServerListLoadBalancer:{NFLoadBalancer:name=localhost,current list of Servers=[],Load balancer stats=Zone stats: {},Server stats: []}ServerList:null
2019-09-18 11:15:19.039  INFO [user-client,,,] 19040 --- [ender@5ae1c281}] c.n.l.DynamicServerListLoadBalancer      : Using serverListUpdater PollingServerListUpdater
2019-09-18 11:15:19.041  INFO [user-client,,,] 19040 --- [ender@5ae1c281}] c.n.l.DynamicServerListLoadBalancer      : DynamicServerListLoadBalancer for client localhost initialized: DynamicServerListLoadBalancer:{NFLoadBalancer:name=localhost,current list of Servers=[],Load balancer stats=Zone stats: {},Server stats: []}ServerList:org.springframework.cloud.netflix.ribbon.eureka.DomainExtractingServerList@69326b62
2019-09-18 11:15:19.343  INFO [user-client,3f575919b0df993a,05fddf5ed5bbbf59,true] 19040 --- [   MyExecutor-1] com.xtsz.user.service.UserService        : 异步方法执行结束

    3f575919b0df993a：traceId相同
    
3f575919b0df993a，05fddf5ed5bbbf59： spanId不同。
    
Sleuth将traceId传入了异步方法并创建了以新的spanId，代表这是同一个请求但进入了另一个处理阶段，由一个异步线程来执行。
    

    五、计划任务
    

  • 计划任务配置类
    • 
 * 实现了SchedulingConfigurer 接口并重写了configureTasks 方法，
 * 同时在类上面添加了@EnableScheduling 注解。
@Configuration
@EnableAsync
@EnableScheduling
public class SchedulingConfig extends AsyncConfigurerSupport implements SchedulingConfigurer {
     * 注册计划任务
     * @param scheduledTaskRegistrar
    @Override
    public void configureTasks(ScheduledTaskRegistrar scheduledTaskRegistrar) {
        scheduledTaskRegistrar.setScheduler(schedulingExecutor());
    @Bean
    public Executor schedulingExecutor() {
        // 生成一个线程池
        return Executors.newScheduledThreadPool(1);

    @Service
@Slf4j
public class UserService {
    @Async
    public void asyncMethod() throws InterruptedException {
        log.info("开始执行异步方法");
        Thread.sleep(1000L);
        log.info("异步方法执行结束");

  • 计划任务类
    • 

    @Service
@Slf4j
public class SchedulingService {
    private final UserService userService;
     * 初始化对象
     * @param userService
    @Autowired
    public SchedulingService(UserService userService) {
        this.userService = userService;
    @Scheduled(fixedDelay = 30000)
    public void scheduledWork() throws InterruptedException {
        log.info("开始计划任务");
        userService.asyncMethod();
        log.info("结束计划任务");

    @RestController
@RequestMapping("user")
@Slf4j
public class UserController {
    @Autowired
    private UserService userService;
    @RequestMapping("/async")
    public String async() throws InterruptedException {
        System.out.println("####控制器输出####   1");
        log.info("####异步方法调用前####");
        userService.asyncMethod();
        log.info("####异步方法调用后####");
        return "success";

    2019-09-18 11:27:46.311  INFO [user-client,621cbb0fca03c421,621cbb0fca03c421,true] 13584 --- [pool-2-thread-1] com.xtsz.user.service.SchedulingService  : 开始计划任务
2019-09-18 11:27:46.312  INFO [user-client,621cbb0fca03c421,621cbb0fca03c421,true] 13584 --- [pool-2-thread-1] com.xtsz.user.service.SchedulingService  : 结束计划任务
2019-09-18 11:27:46.312  INFO [user-client,80d6ab72b300f539,80d6ab72b300f539,true] 13584 --- [cTaskExecutor-2] com.xtsz.user.service.UserService        : 开始执行异步方法
2019-09-18 11:27:47.313  INFO [user-client,80d6ab72b300f539,80d6ab72b300f539,true] 13584 --- [cTaskExecutor-2] com.xtsz.user.service.UserService        : 异步方法执行结束

    可以看到Sleuth为每个任务实例都创建一个新的traceId和spanId。
    
Spring Cloud Sleuth可以应用在各种各样的单一Web应用中。我们可以使用这项技术轻松地为一个请求采集日志，即使请求跨越多个线程。帮助我们在多线程环境下进行清晰的调试，通过识别traceId和spanId来确定每一个操作和操作中的每一步，这样可以减轻我们做日志分析的复杂性。
    

    六、logback-spring.xml 配置
    

    # 配置日志文件
logging.config=classpath:logback-spring.xml  

    注：当文件名为logback-spring.xml时 不需要配置logging.config
    

    <?xml version="1.0" encoding="UTF-8"?>
<!--该日志将日志级别不同的log信息保存到不同的文件中 -->
<configuration>
    <include resource="org/springframework/boot/logging/logback/defaults.xml" />
    <springProperty scope="context" name="springAppName"
                    source="spring.application.name" />
    <!-- 日志在工程中的输出位置 -->
    <property name="LOG_FILE" value="${BUILD_FOLDER:-build}/${springAppName}" />
    <!-- 控制台的日志输出样式 -->
    <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} %m%n${LOG_EXCEPTION_CONVERSION_WORD:-%wEx}}" />
    <!-- 控制台输出 -->
    <appender name="console" class="ch.qos.logback.core.ConsoleAppender">
        <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
            <level>INFO</level>
        </filter>
        <!-- 日志输出编码 -->
        <encoder>
            <pattern>${CONSOLE_LOG_PATTERN}</pattern>
            <charset>utf8</charset>
        </encoder>
    </appender>
    <!-- 为logstash输出的JSON格式的Appender -->
    <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>3</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:-}",
                        "exportable": "%X{X-Span-Export:-}",
                        "pid": "${PID:-}",
                        "thread": "%thread",
                        "class": "%logger{40}",
                        "rest": "%message"
                    </pattern>
                </pattern>
            </providers>
        </encoder>
    </appender>
    <!-- 为logstash输出的JSON格式的Appender -->
    <appender name="logstash2"
              class="net.logstash.logback.appender.LogstashTcpSocketAppender">
        <destination>localhost:9600</destination>
        <!-- 日志输出编码 -->
        <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:-}",
                        "exportable": "%X{X-Span-Export:-}",
                        "pid": "${PID:-}",
                        "thread": "%thread",
                        "class": "%logger{40}",
                        "rest": "%message"
                    </pattern>
                </pattern>
            </providers>
        </encoder>
    </appender>
    <!-- 日志输出级别 -->
    <root level="INFO">
        <appender-ref ref="console" />
        <appender-ref ref="logstash" />
        <appender-ref ref="logstash2" />
    </root>
</configuration>

    sleuth中的一些术语：
    

  • Span：基本工作单元，例如，在一个新建的span中发送一个RPC等同于发送一个回应请求给RPC，span通过一个64位ID唯一标识，trace以另一个64位ID表示，span还有其他数据信息，比如摘要、时间戳事件、关键值注释(tags)、span的ID、以及进度ID(通常是IP地址)
    
span在不断的启动和停止，同时记录了时间信息，当你创建了一个span，你必须在未来的某个时刻停止它。
    • 

  • Trace：一系列spans组成的一个树状结构，例如，如果你正在跑一个分布式工程，你可能需要创建一个trace。
    • 

  • Annotation：用来及时记录一个事件的存在，一些核心annotations用来定义一个请求的开始和结束
    •