The way to stop sleuth fron creating new trace id for new threads

Question

1.

Thread 1 Main thread

myClient.methohThaCallAnotherRemoteService();

2.

In my MyClient class we call another service by with restTeamplate

Single<MyObject> methohThaCallAnotherRemoteService() {

        return Single.fromCallable( () -> { ...

            final ResponseEntity<MyObject> response = restTemplate.postForEntity...

            return response.getBody();

        })
        .subscribeOn(Schedulers.io()); // to be run on separate threads / scheduler

3.

Then in ClientHttpRequestInterceptorImpl that is defined as

   ClientHttpRequestInterceptorImpl implements  org.springframework.http.client.ClientHttpRequestInterceptor {
     ...
 public ClientHttpResponse intercept(final HttpRequest request, final byte[] body, final ClientHttpRequestExecution execution) { ...

     log.info("HTTP_CLIENT_REQUEST" + logResponse));

The problem is: That Sleuth creates a separate trace id (trace-id-2) with a span. The the log looks like this:

from main thread:

> INFO [my-app,trace-id-1, span-id-1] [nio-8080-exec-2] ...

from io thread:

> INFO [my-app,trace-id-2, span-id-2,false] 117037 ---
> [readScheduler-2] d.p.i.w.ClientHttpRequestInterceptorImpl :
> {"logType":"HTTP_CLIENT_REQUEST"

I would like trace-id-2 to be trace-id-1 so I could trance the request from the main thread to io thread. (otherwise it does not make sense in terms of tracing).

I still want my logger.info() to be inside the ClientHttpRequestInterceptorImpl

Q: How exactly it could be achieved?

Answer 1

To solve this problem I had to use LazyTraceExecutor - org.springframework.cloud.sleuth.instrument.async.LazyTraceExecutor

Example of instance -ing it

LazyTraceExecutor lazyTraceExecutor;

@PostConstrucrt
void init() {
      LazyTraceExecutor lazyTraceExecutor =  new LazyTraceExecutor(this.beanFactory,
                                                        java.util.concurrent.Executors.newFixedThreadPool(10, threadFactory("Sched-A-%d"))
                                                                );
}

Then in my RX method that spawns new threads.

Single<MyObject> methohThaCallAnotherRemoteService() {

        return Single.fromCallable( () -> { ...

            final ResponseEntity<MyObject> response = restTemplate.postForEntity...

            return response.getBody();

        })
        .subscribeOn(Schedulers.from(lazyTraceExecutor));  //  use it

Now I have no problem with spans.

Answer 2

I'm not well versed in this, but I saw some help from https://gitter.im/spring-cloud/spring-cloud-sleuth?at=5eb2b6f397338850a2ee2b3f

some advice pasted here:

https://github.com/spring-cloud/spring-cloud-sleuth/issues/1570#issuecomment-627181235

you can try doing the subscribe first, and "then" your callable wrapper

Answer 3

I think you either could continue the main span like

https://cloud.spring.io/spring-cloud-sleuth/reference/html/#continuing-spans-2

// method declaration
@ContinueSpan(log = "testMethod11")
void testMethod11(@SpanTag("testTag11") String param);

// method execution
this.testBean.testMethod11("test");
this.testBean.testMethod13();

or

https://cloud.spring.io/spring-cloud-sleuth/reference/html/#continuing-spans

// let's assume that we're in a thread Y and we've received
// the `initialSpan` from thread X
Span continuedSpan = this.tracer.toSpan(newSpan.context());
try {
    // ...
    // You can tag a span
    continuedSpan.tag("taxValue", taxValue);
    // ...
    // You can log an event on a span
    continuedSpan.annotate("taxCalculated");
}
finally {
    // Once done remember to flush the span. That means that
    // it will get reported but the span itself is not yet finished
    continuedSpan.flush();
}

or

https://cloud.spring.io/spring-cloud-sleuth/reference/html/#creating-spans-with-explicit-parent

// let's assume that we're in a thread Y and we've received
// the `initialSpan` from thread X. `initialSpan` will be the parent
// of the `newSpan`
Span newSpan = null;
try (Tracer.SpanInScope ws = this.tracer.withSpanInScope(initialSpan)) {
    newSpan = this.tracer.nextSpan().name("calculateCommission");
    // ...
    // You can tag a span
    newSpan.tag("commissionValue", commissionValue);
    // ...
    // You can log an event on a span
    newSpan.annotate("commissionCalculated");
}
finally {
    // Once done remember to finish the span. This will allow collecting
    // the span to send it to Zipkin. The tags and events set on the
    // newSpan will not be present on the parent
    if (newSpan != null) {
        newSpan.finish();
    }
}

or

https://cloud.spring.io/spring-cloud-sleuth/reference/html/#runnable-and-callable

Runnable runnable = new Runnable() {
    @Override
    public void run() {
        // do some work
    }

    @Override
    public String toString() {
        return "spanNameFromToStringMethod";
    }
};
// Manual `TraceRunnable` creation with explicit "calculateTax" Span name
Runnable traceRunnable = new TraceRunnable(this.tracing, spanNamer, runnable,
        "calculateTax");
// Wrapping `Runnable` with `Tracing`. That way the current span will be available
// in the thread of `Runnable`
Runnable traceRunnableFromTracer = this.tracing.currentTraceContext()
        .wrap(runnable);

The following example shows how to do so for Callable:

Callable<String> callable = new Callable<String>() {
    @Override
    public String call() throws Exception {
        return someLogic();
    }

    @Override
    public String toString() {
        return "spanNameFromToStringMethod";
    }
};
// Manual `TraceCallable` creation with explicit "calculateTax" Span name
Callable<String> traceCallable = new TraceCallable<>(this.tracing, spanNamer,
        callable, "calculateTax");
// Wrapping `Callable` with `Tracing`. That way the current span will be available
// in the thread of `Callable`
Callable<String> traceCallableFromTracer = this.tracing.currentTraceContext()
        .wrap(callable);

That way, you ensure that a new span is created and closed for each execution.