spanId value in traceparent HTTP header not the same between outgoing/incoming requests

[albireo77]

Description

I have 2 services built with SpringBoot 3.2.3 and Webflux. Source service is sending REST request to target service via WebClient:

Logs in source service (for outgoing request and incoming response):
Request log entry:
2024-05-06 10:47:03.737 31828 [reactor-http-nio-4] [66389906a7e9bc5442d2fa1d2649e3b0-2e3d0580d9daaf29] INFO c.s.h.a.f.l.InfoLevelHttpLogWriter - {"origin":"local","type":"request","correlation":"f0362dfe49418824","protocol":"HTTP/1.1","remote":"localhost/127.0.0.1:8081","method":"GET","uri":"http://localhost:8081/example-api/example-endpoint","host":"localhost","path":"/example-api/example-endpoint","scheme":"http","port":"8081","headers":{"host":["localhost:8081"],"traceparent":["00-66389906a7e9bc5442d2fa1d2649e3b0-94e96fb46bc3c21d-01"],"user-agent":["ReactorNetty/1.1.16"]}}

Response log entry:
2024-05-06 10:47:04.623 32714 [reactor-http-nio-4] [66389906a7e9bc5442d2fa1d2649e3b0-94e96fb46bc3c21d] INFO c.s.h.a.f.l.InfoLevelHttpLogWriter - {"origin":"remote","type":"response","correlation":"f0362dfe49418824","duration":901,"protocol":"HTTP/1.1","status":404,"headers":{"Content-Length":["156"],"Content-Type":["application/json"],"trace-id":["66389906a7e9bc5442d2fa1d2649e3b0"]},"body":{"example body"}}

Log in target service (for incoming request):
2024-05-06 10:47:04.111 18887 [reactor-http-nio-3] [66389906a7e9bc5442d2fa1d2649e3b0-93ea1ffa043553b5] INFO c.s.h.s.a.c.f.l.InfoLevelHttpLogWriter - {"origin":"remote","type":"request","correlation":"f355e78cfec5c32f","protocol":"HTTP/1.1","remote":"/127.0.0.1:65505","method":"GET","uri":"http://localhost:8081/example-api/example-endpoint","host":"localhost","path":"/example-api/example-endpoint","scheme":"http","port":"8081","headers":{"host":["localhost:8081"],"traceparent":["00-66389906a7e9bc5442d2fa1d2649e3b0-2e3d0580d9daaf29-01"],"user-agent":["ReactorNetty/1.1.16"]}}

Expected Behavior

spanId value in traceparent HTTP header is the same in both (outgoing/incoming) requests.

Actual Behavior

In source service, spanId value in traceparent header is 94e96fb46bc3c21d
In target service, spanId value in traceparent header is 2e3d0580d9daaf29

Possible Fix

Steps to Reproduce

Context

Your Environment

Spring Boot 3.2.3 with Webflux
Logbook 3.8.0
Micrometer Tracing 1.3.0

[kasmarian]

Is it related to #1710?

[albireo77]

Is it related to #1710?

I don't think so. This bug is strictly about incorrect (not missing) traceparent HTTP header contents. #1710 is about missing values in tracing context.

[kasmarian]

Logbook doesn't add/modify headers on its own. I assume the library that you're using for tracing is modifying the trace header either after the logbook was invoked on the requesting application, or before the logbook was invoked on the receiving application.

Could you provide more info which library you're using for tracing? A sample repository where the issue is reproducible would also help very much.

[whiskeysierra]

This can happen if you have a thread switch between request and response.

…

On Wed, May 15, 2024, 17:36 Karen Asmarian ***@***.***> wrote: Logbook doesn't add/modify headers on its own. I assume the library that you're using for tracing is modifying the trace either after the logbook was invoked on the requesting application, or before the logbook was invoked or the receiving application. Could you provide more info which library you're using for tracing? A sample repository where the issue is reproducible would also help very much. — Reply to this email directly, view it on GitHub <#1825 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AADI7HN572HVBCU6IL2KOVLZCN6HFAVCNFSM6AAAAABHJMH4QGVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMZDCMJSHA3TMNZWGY> . You are receiving this because you are subscribed to this thread.Message ID: ***@***.***>

[albireo77]

Logbook doesn't add/modify headers on its own. I assume the library that you're using for tracing is modifying the trace header either after the logbook was invoked on the requesting application, or before the logbook was invoked on the receiving application.

Could you provide more info which library you're using for tracing? A sample repository where the issue is reproducible would also help very much.

I am using Micrometer Tracing. I have tried with just released Micrometer Tracing 1.3.0 and the issue persists. I am not able to provide sample repository.

[albireo77]

This can happen if you have a thread switch between request and response.
…
On Wed, May 15, 2024, 17:36 Karen Asmarian @.> wrote: Logbook doesn't add/modify headers on its own. I assume the library that you're using for tracing is modifying the trace either after the logbook was invoked on the requesting application, or before the logbook was invoked or the receiving application. Could you provide more info which library you're using for tracing? A sample repository where the issue is reproducible would also help very much. — Reply to this email directly, view it on GitHub <#1825 (comment)>, or unsubscribe https://github.com/notifications/unsubscribe-auth/AADI7HN572HVBCU6IL2KOVLZCN6HFAVCNFSM6AAAAABHJMH4QGVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMZDCMJSHA3TMNZWGY . You are receiving this because you are subscribed to this thread.Message ID: @.>

Since it's Webflux (many threads handling single request) it's very likely.