search

zalando / logbook

An extensible Java library for HTTP request and response logging
MIT License
1.85k stars 260 forks source link

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

Open albireo77 opened 6 months ago

albireo77 commented 6 months ago

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

1. 2. 3. 4.

Context

Your Environment

Spring Boot 3.2.3 with Webflux Logbook 3.8.0 Micrometer Tracing 1.3.0

kasmarian commented 6 months ago

Is it related to https://github.com/zalando/logbook/issues/1710?

albireo77 commented 6 months ago

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 commented 6 months ago

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 commented 6 months ago

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 https://github.com/zalando/logbook/issues/1825#issuecomment-2112876766, or unsubscribe https://github.com/notifications/unsubscribe-auth/AADI7HN572HVBCU6IL2KOVLZCN6HFAVCNFSM6AAAAABHJMH4QGVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMZDCMJSHA3TMNZWGY . You are receiving this because you are subscribed to this thread.Message ID: @.***>

albireo77 commented 6 months ago

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 commented 6 months ago

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.

github-actions[bot] commented 1 day ago

In order to prioritize the support for Logbook, we would like to check whether the old issues are still relevant. This issue has not been updated for over six months.