Sleuth log traceId not propagated to another service

Question

I try to add a distributed tracing in my microservices (under Kubernetes in Azure).

I added the dependencies in the parent pom.xml :

<parent>
    <groupId>org.springframework.boot</groupId>
    <artifactId>spring-boot-starter-parent</artifactId>
    <version>1.4.1.RELEASE</version>
    <relativePath/>
</parent>
<dependencies>
    {...}
    <dependency>
        <groupId>org.springframework.cloud</groupId>
        <artifactId>spring-cloud-sleuth-core</artifactId>
        <version>1.1.3.RELEASE</version>
    </dependency>
    <dependency>
        <groupId>org.springframework.cloud</groupId>
        <artifactId>spring-cloud-sleuth-zipkin</artifactId>
        <version>1.1.3.RELEASE</version>
    </dependency>
</dependencies>
<dependencyManagement>
    <dependencies>
        <dependency>
            <groupId>org.springframework.cloud</groupId>
            <artifactId>spring-cloud-dependencies</artifactId>
            <version>CAMDEN.SR4</version>
            <type>pom</type>
            <scope>import</scope>
        </dependency>
        {...}
    </dependencies>
</dependencyManagement>

I use 1.4.1 and CAMDEN.SR4 because fabric8 kubeflix doesn't support newer versions. I forced 1.1.3.RELEASE to try newest sleuth version to see if it was a bug in older version of sleuth.

I use this configuration of logback-spring.xml :

<configuration>
    <include resource="org/springframework/boot/logging/logback/defaults.xml"/>
    <springProperty scope="context" name="springAppName" source="spring.application.name"/>
    <jmxConfigurator/>
    <property name="CONSOLE_LOG_PATTERN"
          value="%d{yyyy-MM-dd HH:mm:ss.SSS} [${springAppName},%X{X-B3-TraceId:-},%X{X-B3-SpanId:-},%X{X-Span-Export:-}] [%thread] %-5level %logger{35} - %msg%n"/>
    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>${CONSOLE_LOG_PATTERN}</pattern>
        </encoder>
    </appender>
    <root level="DEBUG">
        <appender-ref ref="STDOUT"/>
    </root>
    <logger name="org.springframework" level="ERROR"/>
    <logger name="com.netflix" level="ERROR"/>
    <logger name="io.fabric8" level="ERROR"/>
    <logger name="org.apache" level="ERROR"/>
</configuration>

And here is my application.yml :

spring:
  zipkin:
    baseUrl: http://zipkin:8080
  sleuth:
    sampler:
      percentage: 1.0
server:
  port: 8080

The zipkin URL is a Kubernetes services exposing the Zipkin server (Spring boot app with @EnableZipkinServer)

I then call a first service (services-1) with this code :

private RestTemplate template = new RestTemplate();

@GetMapping("/{key}/{language}")
public String getLabel(@PathVariable String key, @PathVariable String language) throws UnknownHostException {
    log.info("Entering getLabel");
    String testResponse = template.getForObject("http://services-i18n-2/test", String.class);
    String s = labelService.getLabel(key, language) + " " + message + " " + InetAddress.getLocalHost().getHostName() + ", response=" + testResponse;
    log.info("Exiting getLabel");
    return s;
}

which produces these logs :

2017-04-05T11:04:48.497345669Z 2017-04-05 11:04:48.497 [services-1,eaf3dbcb2f92091b,95dd9e6082990923,false] [XNIO-2 task-4] INFO  c.l.m.i18n.web.LabelController - Entering getLabel
2017-04-05T11:04:48.519851116Z 2017-04-05 11:04:48.519 [services-1,eaf3dbcb2f92091b,95dd9e6082990923,false] [XNIO-2 task-4] DEBUG c.l.m.i18n.service.LabelService - Response Label(key=Key(value=action.login), language=Language(value=fr), value=s'authentifier)
2017-04-05T11:04:48.519864516Z 2017-04-05 11:04:48.519 [services-1,eaf3dbcb2f92091b,95dd9e6082990923,false] [XNIO-2 task-4] INFO  c.l.m.i18n.web.LabelController - Exiting getLabel

As you can see it calls the services-i18n-2 service with a RestTemplate, which produces these logs :

2017-04-05T11:04:48.514145894Z 2017-04-05 11:04:48.513 [services-2,e0c6495a0a598cff,e0c6495a0a598cff,true] [XNIO-2 task-4] INFO  c.l.m.i18n.web.TestController - Entering test
2017-04-05T11:04:48.516430459Z 2017-04-05 11:04:48.516 [services-2,e0c6495a0a598cff,e0c6495a0a598cff,true] [XNIO-2 task-4] INFO  c.l.m.i18n.web.TestController - Exiting test

As you can see the traceId in service-2 (e0c6495a0a598cff) is different from the service-1 (eaf3dbcb2f92091b).

And in service-2 the traceId is the same as the spanId.

Questions :

• Why don't I have the traceId propagated to service-2 to be able to see the full stacktrace in Zipkin ?
• Why the traceId in service-2 is equal to the spanId ?
• Why the exportable is false in service-1 ? These logs are not seen by the Zipkin server.
• I'm spammed with rxjava spans in Zipkin server. I have tried spring.sleuth.rxjava.schedulers.ignoredthreads=rxjava but it still goes to Zipkin.

FYI, I have Hystrix in the dependencies and I have removed the @HystrixCommand to be sure it was not a problem with Hystrix creating a new traceId at each HTTP call.

Answer 1

For 1, 2, 3 it was because I was doing a new RestTemplate.

The doc says :

You have to register RestTemplate as a bean so that the interceptors will get injected. If you create a RestTemplate instance with a new keyword then the instrumentation WILL NOT work.

So RTFM for myself, and this solved my 3 first problems :

@Bean
public RestTemplate template() {
    return new RestTemplate();
}
@Autowired
private RestTemplate template;