Trace ID mixed up in reactor

[johanblumenberg]

Description

My project consists of a spring-webflux application using r2dbc for persistence.

When enabling detailed logging for DB connections and queries, the wrong traceId is logged for many of the DB logs from io.r2dbc.postgres.

Example:

2022-07-07 14:50:34.400 DEBUG [,,] 53092 --- [ctor-http-nio-4] reactor.netty.transport.TransportConfig  : [4c629589, L:/127.0.0.1:8080 - R:/127.0.0.1:55650] Initialized pipeline DefaultChannelPipeline{(reactor.left.httpCodec = io.netty.handler.codec.http.HttpServerCodec), (reactor.left.httpTrafficHandler = reactor.netty.http.server.HttpTrafficHandler), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
2022-07-07 14:50:34.402  INFO [,ae0208e5cceee3fd,ae0208e5cceee3fd] 53092 --- [ctor-http-nio-4] test.service.OpLoggingFilter             : processing start
2022-07-07 14:50:34.404 DEBUG [,ae0208e5cceee3fd,ae0208e5cceee3fd] 53092 --- [ctor-http-nio-4] io.r2dbc.pool.ConnectionPool             : Obtaining new connection from the pool
2022-07-07 14:50:34.405 DEBUG [,ae0208e5cceee3fd,ae0208e5cceee3fd] 53092 --- [ctor-http-nio-4] o.s.r2dbc.core.DefaultDatabaseClient     : Executing SQL statement [SELECT test.* FROM test WHERE test.id = $1 LIMIT 2]
2022-07-07 14:50:34.405 DEBUG [,ae0208e5cceee3fd,ae0208e5cceee3fd] 53092 --- [ctor-http-nio-4] io.r2dbc.postgresql.PARAM                : [cid: 0x1][pid: 69] Bind parameter [0] to: 1
2022-07-07 14:50:34.406 DEBUG [,ae0208e5cceee3fd,ae0208e5cceee3fd] 53092 --- [ctor-http-nio-4] io.r2dbc.postgresql.QUERY                : [cid: 0x1][pid: 69] Executing query: SELECT test.* FROM test WHERE test.id = $1 LIMIT 2
2022-07-07 14:50:34.406 DEBUG [,63e18222d0b220d0,63e18222d0b220d0] 53092 --- [ctor-http-nio-4] i.r.p.client.ReactorNettyClient          : [cid: 0x1][pid: 69] Request:  [Bind{name='B_2', parameterFormats=[FORMAT_TEXT], parameters=[CompositeByteBuf(ridx: 0, widx: 1, cap: 1, components=1)], resultFormats=[], source='S_0'}, Describe{name='B_2', type=PORTAL}, Execute{name='B_2', rows=0}, Close{name='B_2', type=PORTAL}, Sync{}]

The traceId for this request is ae0208e5cceee3fd, but some of the logs from io.r2dbc.postgresql.client.ReactorNettyClient are tagged with the traceId 63e18222d0b220d0, which was the traceId for the previous request.

Minimal example that reproduces the bug: https://github.com/johanblumenberg/sleuth-traceid-minimal-example

One thing to note is that disabling the DB connection pool avoids the poblem.

[marcingrzejszczak]

That looks like a bug. Can you try to use the latest snapshots? Afair we fixed some things with webflux there

[johanblumenberg]

That looks like a bug. Can you try to use the latest snapshots? Afair we fixed some things with webflux there

I tried it with spring-cloud-dependencies:2020.0.3-SNAPSHOT and spring-boot-starter-parent:2.5.14, because the snapshot version tells me to

Change Spring Boot version to one of the following versions [2.4.x, 2.5.x] .

I still get the same problem with the traceId from the first request.

[samueldlightfoot]

We have seen very similar behaviour in our WebFlux project and are currently trying to create a minimum reproducible sample. Which Reactor instrumentation mode are you using (default is DECORATE_ON_EACH)?

In terms of other similarities, we use Cassandra and have a connection pool created by the DataStax Java driver.

[yogeshgadge]

Have you tried to set the spring application name at startup -D option

[marcingrzejszczak]

Please upgrade to Micrometer Tracing. Spring Cloud Sleuth is feature complete and out of OSS support.