Boot 3.0.8 -> 3.0.9 regression trace issue with Kafka Consumers

[davidmelia]

Hi,

When upgrading from Boot 3.0.8 to Boot 3.0.9 we've noticed trace IDs going missing in our Kafka consumers. https://github.com/davidmelia/spring-boot-kafka-consumer-tracing/tree/boot_3.0.9_trace_issue illustrates this issue.

Using boot 3.0.8 and running http://localhost:8080/sendMessage you get

...  INFO [aid=spring-boot-kafka-consumer-tracing,tid=64c14942455d1a27813d690aedf14ed8,sid=6efe80eaff5b8002,cusname=] ... Kafka Binder: This log statement has the trace id
...  INFO [aid=spring-boot-kafka-consumer-tracing,tid=64c14942455d1a27813d690aedf14ed8,sid=6efe80eaff5b8002,cusname=] ... Kafka Binder: This log statement also has the trace id in boot 3.0.8 but NOT in boot 3.0.9

which is great. Update to boot 3.0.9 and the final tid disappears. tracing is lost

... INFO [aid=spring-boot-kafka-consumer-tracing,tid=64c149bb4911ade46ea6c4069bacf4a8,sid=d2c49fa012ff0dcc,cusname=] ... Kafka Binder: This log statement has the trace id
... INFO [aid=spring-boot-kafka-consumer-tracing,tid=,sid=,cusname=] ... Kafka Binder: This log statement also has the trace id in boot 3.0.8 but NOT in boot 3.0.9

The consumer is quite simple https://github.com/davidmelia/spring-boot-kafka-consumer-tracing/blob/boot_3.0.9_trace_issue/src/main/java/com/example/demo/consumer/TestMessagesConsumer.java but the delay element is the part that loses the tid - I assume this is a bug in the threading trace context stuff?

Thanks

[wilkinsona]

This sort of problem is rarely caused by Spring Boot itself and I'd recommend spending some time downgrading individual components to determine the cause. In this case, it appears to be micrometer-observation as the problem does not occur with Spring Boot 3.0.9 when Micrometer 1.10.8 (the version using by Spring Boot 3.0.8) is used.

Please report this to the Micrometer team.

[davidmelia]

FYI I actually think this problem is Spring Cloud Stream Kafka. If I just update spring cloud bom the trace IDs are lost. If this was an issue with micrometer losing tracing between threads it would affect everywhere but doesn't

Will raise with spring cloud stream ...

[wilkinsona]

🤷

With this change to the pom.xml:

diff --git a/pom.xml b/pom.xml
index db92f6f..e94c9ec 100644
--- a/pom.xml
+++ b/pom.xml
@@ -5,7 +5,7 @@
        <parent>
                <groupId>org.springframework.boot</groupId>
                <artifactId>spring-boot-starter-parent</artifactId>
-               <version>3.0.8</version>
+               <version>3.0.9</version>
                <!--version>3.0.7</version-->
        </parent>
        <groupId>uk.co.ii</groupId>
@@ -16,6 +16,7 @@
        <properties>
                <java.version>17</java.version>
                <spring-cloud.version>2022.0.1</spring-cloud.version>   
+               <micrometer.version>1.10.8</micrometer.version>
        </properties>
        <dependencies>
                <dependency>

This is the logging:

2023-07-27T09:49:13.793+01:00  INFO [aid=spring-boot-kafka-consumer-tracing,tid=64c22f89f0e396351a157b8bc0d51fa0,sid=1a157b8bc0d51fa0,cusname=] 887 --- [ctor-http-nio-3] com.example.demo.KafkaController         : Message sent to binding = GenericMessage [payload={Key=Value @ 2023-07-27T08:49:13.784749Z}, headers={kafka_messageKey=ecb0c5b4-72f5-4c6e-b3eb-12ed177acff9, id=76728571-d94b-68fc-6871-f0bd4e8a632a, timestamp=1690447753786}]
2023-07-27T09:49:13.837+01:00  INFO [aid=spring-boot-kafka-consumer-tracing,tid=64c22f89f0e396351a157b8bc0d51fa0,sid=6ab3f80069e52a2c,cusname=] 887 --- [container-0-C-1] c.e.demo.consumer.TestMessagesConsumer   : Kafka Binder: This log statement has the trace id
2023-07-27T09:49:13.850+01:00  INFO [aid=spring-boot-kafka-consumer-tracing,tid=64c22f89f0e396351a157b8bc0d51fa0,sid=6ab3f80069e52a2c,cusname=] 887 --- [     parallel-2] c.e.demo.consumer.TestMessagesConsumer   : Kafka Binder: This log statement also has the trace id in boot 3.0.8 but NOT in boot 3.0.9

[davidmelia]

@wilkinsona happy to take your steer but it's not as clear cut because if you use 3.0.9 and micrometer 1.10.8 but also upgrade to <spring-cloud.version>2022.0.3</spring-cloud.version> it also breaks:

<project xmlns="http://maven.apache.org/POM/4.0.0" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
	xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 https://maven.apache.org/xsd/maven-4.0.0.xsd">
	<modelVersion>4.0.0</modelVersion>
	<parent>
		<groupId>org.springframework.boot</groupId>
		<artifactId>spring-boot-starter-parent</artifactId>
		<version>3.0.9</version>
		<!--version>3.0.7</version-->
	</parent>
	<groupId>uk.co.ii</groupId>
	<artifactId>spring-boot-kafka-consumer-tracing</artifactId>
	<version>0.0.1-SNAPSHOT</version>
	<name>spring-boot-kafka-consumer-tracing</name>
	<description>Demo project for Spring Boot</description>
	<properties>
		<java.version>17</java.version>
		<spring-cloud.version>2022.0.3</spring-cloud.version>	
		<micrometer.version>1.10.8</micrometer.version>
	</properties>

If this was a fundamental micrometer problem between threads then this would break other areas which I've actually tested this via a spring controller and all is fine

  @GetMapping(value = "/threadContextPreserved", produces = MediaType.APPLICATION_JSON_VALUE)
  public Mono<ResponseEntity<Map<String, String>>> stuff() {
    log.info("This log statement has the trace id");
    return Mono.just(ok(Map.of("event sent=", "dave"))).delayElement(Duration.ofMillis(10)).doOnSuccess(r -> log.info("This log statement alsos has the trace id"));
  }

I'm fairly sure the micrometer team will point me to spring cloud streams ...