ThreadLocals not cleared with Hooks.enableAutomaticContextPropagation(), same TraceId for every request

[kzander91]

Expected Behavior

Automatic context propagation (enabled with Hooks.enableAutomaticContextPropagation()) should clear the thread-locals afterwards.

Actual Behavior

After the first request handled by a particular thread, every subsequent request handled by that thread will reuse the same traceId.

Steps to Reproduce

Demo project: reproducer.zip

@SpringBootApplication
public class Demo1Application {

    public static void main(String[] args) {
        System.setProperty("reactor.netty.ioWorkerCount", "2");
        Hooks.enableAutomaticContextPropagation();
        SpringApplication.run(Demo1Application.class, args);
    }

}

@RestController
@RequiredArgsConstructor
class MyController {

    private final Tracer tracer;

    @GetMapping("/")
    public String traceId() {
        return Thread.currentThread().getName() + '-' + tracer.currentSpan().context().traceId();
    }

}

Run it and issue a few requests to localhost:8080, the output will be something like this:

C:\>curl localhost:8080
reactor-http-nio-1-65102d16b3d992cb7131386bf683cd9e
C:\>curl localhost:8080
reactor-http-nio-2-65102d0dc6d2b48f307d67a6db6fde3a
C:\>curl localhost:8080
reactor-http-nio-1-65102d16b3d992cb7131386bf683cd9e
C:\>curl localhost:8080
reactor-http-nio-2-65102d0dc6d2b48f307d67a6db6fde3a
C:\>curl localhost:8080
reactor-http-nio-1-65102d16b3d992cb7131386bf683cd9e
C:\>curl localhost:8080
reactor-http-nio-2-65102d0dc6d2b48f307d67a6db6fde3a

With reactor.netty.ioWorkerCount=1:

C:\>curl localhost:8080
reactor-http-nio-1-65102dd571ea1cb67a25a401c93412b0
C:\>curl localhost:8080
reactor-http-nio-1-65102dd571ea1cb67a25a401c93412b0
C:\>curl localhost:8080
reactor-http-nio-1-65102dd571ea1cb67a25a401c93412b0
C:\>curl localhost:8080
reactor-http-nio-1-65102dd571ea1cb67a25a401c93412b0
C:\>curl localhost:8080
reactor-http-nio-1-65102dd571ea1cb67a25a401c93412b0
C:\>curl localhost:8080
reactor-http-nio-1-65102dd571ea1cb67a25a401c93412b0

With reactor.netty.ioWorkerCount=3:

C:\>curl localhost:8080
reactor-http-nio-2-65102dfc81d58e1d99c2f64353b410a6
C:\>curl localhost:8080
reactor-http-nio-3-65102dfc7b1ff1d38702f4b2e4cb94a6
C:\>curl localhost:8080
reactor-http-nio-1-65102dfde7c20d2604248dd885469458
C:\>curl localhost:8080
reactor-http-nio-2-65102dfc81d58e1d99c2f64353b410a6
C:\>curl localhost:8080
reactor-http-nio-3-65102dfc7b1ff1d38702f4b2e4cb94a6
C:\>curl localhost:8080
reactor-http-nio-1-65102dfde7c20d2604248dd885469458

As we can see, requests handled by a thread will always reuse the same traceId, indicating that thread-locals popuplated by automatic context propagation are not cleared/reset after each request.

Without automatic context propagation, tracer.currentSpan() returns null.

Possible Solution

Your Environment

• Reactor version(s) used: 3.5.10
• Other relevant libraries versions (eg. netty, ...):
  • Spring Boot 3.1.4
  • Spring Framework 6.0.12
  • Micrometer Tracing: 1.1.5
  • Micrometer Observation: 1.11.4
• JVM version (java -version):

openjdk version "17.0.8.1" 2023-08-24
OpenJDK Runtime Environment Temurin-17.0.8.1+1 (build 17.0.8.1+1)
OpenJDK 64-Bit Server VM Temurin-17.0.8.1+1 (build 17.0.8.1+1, mixed mode, sharing)

Related Issues

#3375

[chemicL]

Please try with the latest snapshot of micrometer-tracing 1.1.6. I have reasons to believe what you are seeing is a regression, described in micrometer-metrics/tracing#356. If you use 1.1.4 the issue should also be gone. LMK.

[kzander91]

With 1.1.4, the issue is gone, but not with 1.1.6-SNAPSHOT.

Updated pom

<?xml version="1.0" encoding="UTF-8"?>
<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.1.4</version>
        <relativePath/> <!-- lookup parent from repository -->
    </parent>
    <groupId>com.example</groupId>
    <artifactId>demo1</artifactId>
    <version>0.0.1-SNAPSHOT</version>
    <name>demo1</name>
    <description>demo1</description>
    <properties>
        <java.version>17</java.version>
        <!-- Works -->
        <!--        <micrometer-tracing.version>1.1.4</micrometer-tracing.version>-->
        <!-- Doesn't Work -->
        <micrometer-tracing.version>1.1.6-SNAPSHOT</micrometer-tracing.version>
    </properties>
    <dependencies>
        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-actuator</artifactId>
        </dependency>
        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-webflux</artifactId>
        </dependency>
        <dependency>
            <groupId>io.micrometer</groupId>
            <artifactId>micrometer-tracing-bridge-brave</artifactId>
        </dependency>
        <dependency>
            <groupId>org.projectlombok</groupId>
            <artifactId>lombok</artifactId>
        </dependency>
    </dependencies>

    <build>
        <plugins>
            <plugin>
                <groupId>org.springframework.boot</groupId>
                <artifactId>spring-boot-maven-plugin</artifactId>
            </plugin>
        </plugins>
    </build>

    <repositories>
        <repository>
            <id>spring-milestones</id>
            <name>Spring Milestones</name>
            <url>https://repo.spring.io/milestone</url>
            <snapshots>
                <enabled>false</enabled>
            </snapshots>
        </repository>
        <repository>
            <id>spring-snapshots</id>
            <name>Spring Snapshots</name>
            <url>https://repo.spring.io/snapshot</url>
            <releases>
                <enabled>false</enabled>
            </releases>
        </repository>
    </repositories>

</project>

I guess this means that this is actually a bug within micrometer-tracing. Can you transfer this issue or should I open a dedicated issue over there?

[chemicL]

Thanks for confirming. Please try 1.2.0-SNAPSHOT. I am guessing @marcingrzejszczak merged micrometer-metrics/tracing@89b4e94 into main branch, which is the base for 1.2.0 line instead of 1.1.x which is the base for 1.1.6-SNAPSHOT. Feel free to open an issue in the tracing repo in the meantime.

[kzander91]

1.2.0-SNAPSHOT did not fix this either, I have opened micrometer-metrics/tracing#363.