CODEWITHSUNDEEP
executorservicecompletable-futurespring-cloud-sleuthdistributed-tracing
Jobin Thomas
Jobin Thomas

Reputation: 145

Triggering a new Sleuth Tracer for Completable futures

I am trying to implement Slueth for distributed tracing for spring boot microservices which communicates with each other over a messaging channel.

One of these microservices is a scheduler that picks up new consumers created for a day. It then runs a grouping process for each consumer's data in an async manner.

Now I am using traceableExeucutorService to pass down the sleuth tracing generated for the scheduler thread down to the child threads for each consumer.

TracingConfig

@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));
    }

}

Scheduler Service

@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);

    }

}

This ends up using the same traceId for each consumer and hence all the downstream services logs the same traceId for every consumer.

The reason I want each consumer thread to have its own traceId is that these child threads will, in turn, publish messages to downstream services. As the scheduler is supposed to run only once a day every consumer's log for a day would end up having the same traceId and defeats the whole purpose of tracing.

Original Logs for two scheduler runs with same traceId for each consumer

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

So I created a new Tracer in the method called by async operation but I still see the main thread's traceId being logged. So I had to manually extract the traceId and spanId and then add that to the ThreadContext. Is this the expected way to implement this or is there a more elegant solution where just starting a new Trace would add the values to the ThreadContext.

Updated 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();
        }
    }

Updated Logs with consumer level 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

Upvotes: 2

Views: 3077

Answers (1)

tosovvoj
tosovvoj

Reputation: 65

The problem is that a span is not responsible for making itself current (scoped). The tracer is. You need to update this:

 Span span = Tracing.currentTracer().newTrace().start();

to this:

Span newSpan = Tracing.currentTracer().newTrace().start();
tracer.withSpanInScope( newSpan );

The instance of tracer can be autowired:

@Autowired
private Tracer tracer;

Upvotes: 0

Related Questions