我正在尝试为 Spring Boot 微服务的分布式跟踪实现 Slueth,这些微服务通过消息传递通道相互通信。
其中一个微服务是一个调度程序,它可以挑选一天创建的新消费者。然后它以异步方式为每个消费者的数据运行分组过程。
现在我正在使用 traceableExeucutorService 将调度程序线程生成的侦探跟踪传递给每个消费者的子线程。
跟踪配置
@EnableScheduling
@Configuration
public class TracingConfig implements SchedulingConfigurer {
@Override
public void configureTasks(ScheduledTaskRegistrar scheduledTaskRegistrar) {
scheduledTaskRegistrar.setScheduler(schedulingExecutor());
}
@Bean(destroyMethod = "shutdown")
public Executor schedulingExecutor() {
return Executors.newScheduledThreadPool(1);
}
@Bean
public Executor traceAbleExecutorService(BeanFactory factory) {
return new TraceableExecutorService(factory, Executors.newFixedThreadPool(10));
}
}
调度服务
@Slf4j
@Service
public class ConsumerScheduler {
@Autowired
Executor traceAbleExecutorService;
@Scheduled(cron = "0/5 * * * * *")
public void testScheduler() {
log.info("Running scheduler");
List<String> consumers = new ArrayList<>();
consumers.add("Consumer1");
consumers.add("Consumer2");
consumers.forEach(
consumer -> CompletableFuture.runAsync(() -> getConsumerData(consumer), traceAbleExecutorService));
log.info("Completed scheduler");
}
private void getConsumerData(String consumer) {
log.info("Running {}", consumer);
log.info("Logging Data for {}", consumer);
}
}
这最终会为每个消费者使用相同的 traceId,因此所有下游服务都会为每个消费者记录相同的 traceId。
我希望每个消费者线程都有自己的 traceId 的原因是这些子线程将依次将消息发布到下游服务。由于调度程序应该每天只运行一次,因此每个消费者一天的日志最终都会具有相同的 traceId 并破坏了跟踪的整个目的。
两个调度程序的原始日志运行,每个消费者使用相同的 traceId
2020-02-01 13:22:05.025 INFO [,c4b8535556794e6d,c4b8535556794e6d,false] 6528 --- [pool-2-thread-1] com.example.demo.ConsumerScheduler : Running scheduler
2020-02-01 13:22:05.036 INFO [,c4b8535556794e6d,c4b8535556794e6d,false] 6528 --- [pool-2-thread-1] com.example.demo.ConsumerScheduler : Completed scheduler
2020-02-01 13:22:05.036 INFO [,c4b8535556794e6d,3a05952293179b5f,false] 6528 --- [pool-1-thread-2] com.example.demo.ConsumerScheduler : Running Consumer2
2020-02-01 13:22:05.036 INFO [,c4b8535556794e6d,cba00b8dd7edc99c,false] 6528 --- [pool-1-thread-1] com.example.demo.ConsumerScheduler : Running Consumer1
2020-02-01 13:22:05.040 INFO [,c4b8535556794e6d,cba00b8dd7edc99c,false] 6528 --- [pool-1-thread-1] com.example.demo.ConsumerScheduler : Logging Data for Consumer1
2020-02-01 13:22:05.040 INFO [,c4b8535556794e6d,3a05952293179b5f,false] 6528 --- [pool-1-thread-2] com.example.demo.ConsumerScheduler : Logging Data for Consumer2
2020-02-01 13:22:10.002 INFO [,5ad7e1a6ddc176e4,5ad7e1a6ddc176e4,false] 6528 --- [pool-2-thread-1] com.example.demo.ConsumerScheduler : Running scheduler
2020-02-01 13:22:10.003 INFO [,5ad7e1a6ddc176e4,5ad7e1a6ddc176e4,false] 6528 --- [pool-2-thread-1] com.example.demo.ConsumerScheduler : Completed scheduler
2020-02-01 13:22:10.003 INFO [,5ad7e1a6ddc176e4,e2fe5d0c4abc0f4b,false] 6528 --- [pool-1-thread-3] com.example.demo.ConsumerScheduler : Running Consumer1
2020-02-01 13:22:10.003 INFO [,5ad7e1a6ddc176e4,e2fe5d0c4abc0f4b,false] 6528 --- [pool-1-thread-3] com.example.demo.ConsumerScheduler : Logging Data for Consumer1
2020-02-01 13:22:10.003 INFO [,5ad7e1a6ddc176e4,d3d0d18d896a2602,false] 6528 --- [pool-1-thread-4] com.example.demo.ConsumerScheduler : Running Consumer2
2020-02-01 13:22:10.003 INFO [,5ad7e1a6ddc176e4,d3d0d18d896a2602,false] 6528 --- [pool-1-thread-4] com.example.demo.ConsumerScheduler : Logging Data for Consumer2
所以我在异步操作调用的方法中创建了一个新的 Tracer,但我仍然看到主线程的 traceId 被记录。所以我不得不手动提取traceId和spanId,然后将其添加到ThreadContext。这是实现这一点的预期方式,还是有一个更优雅的解决方案,只需启动一个新的 Trace 就会将值添加到 ThreadContext。
更新了 getConsumerData
private void getConsumerData(String consumer) {
Span span = Tracing.currentTracer().newTrace().start();
try {
String traceId = span.context().traceIdString();
String spanId = span.context().spanIdString();
String parentId = span.context().parentIdString();
ThreadContext.put("traceId", traceId);
ThreadContext.put("X-B3-TraceId", traceId);
ThreadContext.put("spanId", spanId);
ThreadContext.put("X-B3-SpanId", spanId);
ThreadContext.put("parentId", parentId);
ThreadContext.put("X-B3-ParentId", parentId);
log.info("Running {}", consumer);
log.info("Logging Data for {}", consumer);
} finally {
span.finish();
}
}
使用消费者级别 TraceId 更新日志
2020-02-01 13:30:40.022 INFO [,46fb0ea5afb9accc,46fb0ea5afb9accc,false] 14796 --- [pool-2-thread-1] com.example.demo.ConsumerScheduler : Running scheduler
2020-02-01 13:30:40.029 INFO [,46fb0ea5afb9accc,46fb0ea5afb9accc,false] 14796 --- [pool-2-thread-1] com.example.demo.ConsumerScheduler : Completed scheduler
2020-02-01 13:30:40.048 INFO [,06eacdb987cafe11,06eacdb987cafe11,false] 14796 --- [pool-1-thread-1] com.example.demo.ConsumerScheduler : Running Consumer1
2020-02-01 13:30:40.048 INFO [,9273140d294add25,9273140d294add25,false] 14796 --- [pool-1-thread-2] com.example.demo.ConsumerScheduler : Running Consumer2
2020-02-01 13:30:40.052 INFO [,9273140d294add25,9273140d294add25,false] 14796 --- [pool-1-thread-2] com.example.demo.ConsumerScheduler : Logging Data for Consumer2
2020-02-01 13:30:40.052 INFO [,06eacdb987cafe11,06eacdb987cafe11,false] 14796 --- [pool-1-thread-1] com.example.demo.ConsumerScheduler : Logging Data for Consumer1
2020-02-01 13:30:45.002 INFO [,ba63c9342b2bb82d,ba63c9342b2bb82d,false] 14796 --- [pool-2-thread-1] com.example.demo.ConsumerScheduler : Running scheduler
2020-02-01 13:30:45.003 INFO [,ba63c9342b2bb82d,ba63c9342b2bb82d,false] 14796 --- [pool-2-thread-1] com.example.demo.ConsumerScheduler : Completed scheduler
2020-02-01 13:30:45.003 INFO [,dac9c7bbc7c4a312,dac9c7bbc7c4a312,false] 14796 --- [pool-1-thread-3] com.example.demo.ConsumerScheduler : Running Consumer1
2020-02-01 13:30:45.003 INFO [,dac9c7bbc7c4a312,dac9c7bbc7c4a312,false] 14796 --- [pool-1-thread-3] com.example.demo.ConsumerScheduler : Logging Data for Consumer1
2020-02-01 13:30:45.003 INFO [,4eda4d2c9ec95b50,4eda4d2c9ec95b50,false] 14796 --- [pool-1-thread-4] com.example.demo.ConsumerScheduler : Running Consumer2
2020-02-01 13:30:45.003 INFO [,4eda4d2c9ec95b50,4eda4d2c9ec95b50,false] 14796 --- [pool-1-thread-4] com.example.demo.ConsumerScheduler : Logging Data for Consumer2