Hey, we are trying to setup tracing (https://docs.bentoml.com/en/latest/guides/observability/tracing.html) in our BentomL services with open telemetry. Using version 1.3.2, running the containers ourselves in k8s. For some reason, we see duplicated

trace_ids

from different calls. We can’t recreate it locally for some reason (even in a docker container) - it only shows up when we deploy it to k8s. To help debug the issue, we decided to print the request header and the trace_id from the context, and when this problem appears the actually don’t match. Here’s a printout. Interestingly, the trace id from the context goes back and forth sometimes 🤷

"2024-08-16T21:17:45.137Z",Trace context traceId: 0xb5e499c78fe8f7a47a548a305c2bc880, header x-b3-traceid: 61b12ecfc6324a8836b2512760918f8c"
"2024-08-16T21:17:42.135Z",Trace context traceId: 0xb5e499c78fe8f7a47a548a305c2bc880, header x-b3-traceid: 657cefb4f848abf12b598a7c2337c283"
"2024-08-16T21:17:39.133Z",Trace context traceId: 0xb5e499c78fe8f7a47a548a305c2bc880, header x-b3-traceid: 0f36f19f8d3379c6c54c4d2d346205d2"
"2024-08-16T21:17:39.133Z",Trace context traceId: 0xc29415c76a3ba76c67da0aea3a2e30b3, header x-b3-traceid: e2d75bef5ebf11d950ef78224fd5fc59"
"2024-08-16T21:17:39.133Z",Trace context traceId: 0xc29415c76a3ba76c67da0aea3a2e30b3, header x-b3-traceid: a4b83d1b91557a4448c62ed5fba73f04"
"2024-08-16T21:17:39.133Z",Trace context traceId: 0xb5e499c78fe8f7a47a548a305c2bc880, header x-b3-traceid: c3c7ea89f114ab3ba437e20c4def4a12"
"2024-08-16T21:17:39.133Z",Trace context traceId: 0xb5e499c78fe8f7a47a548a305c2bc880, header x-b3-traceid: dc132974f0a65bcdd72b7d50a233a9d9"
"2024-08-16T21:17:39.133Z",Trace context traceId: 0xb5e499c78fe8f7a47a548a305c2bc880, header x-b3-traceid: 8db286ff5f664b337d891c42ebbcca32"
"2024-08-16T21:17:39.133Z",Trace context traceId: 0xb5e499c78fe8f7a47a548a305c2bc880, header x-b3-traceid: bfe2cadd383f8aeca4ef382103481615"
"2024-08-16T21:17:36.131Z",Trace context traceId: 0xb5e499c78fe8f7a47a548a305c2bc880, header x-b3-traceid: b5e499c78fe8f7a47a548a305c2bc880"
"2024-08-16T21:17:36.131Z",Trace context traceId: 0xc29415c76a3ba76c67da0aea3a2e30b3, header x-b3-traceid: bd8600407724e1df28db76b15bfe06b1"
"2024-08-16T21:17:36.131Z",Trace context traceId: 0xc29415c76a3ba76c67da0aea3a2e30b3, header x-b3-traceid: 482fc4a37bc40d9b7bee7f679a5164cd"
"2024-08-16T21:17:36.131Z",Trace context traceId: 0xc29415c76a3ba76c67da0aea3a2e30b3, header x-b3-traceid: f286898358bec9a7798b33035ef2aa83"
"2024-08-16T21:17:36.130Z",Trace context traceId: 0xc29415c76a3ba76c67da0aea3a2e30b3, header x-b3-traceid: fbebdc190f1f6820168c2a0e95759bd9"
"2024-08-16T21:17:33.128Z",Trace context traceId: 0xc29415c76a3ba76c67da0aea3a2e30b3, header x-b3-traceid: bf023aaf8a79190e37ba5ca77d945291"
"2024-08-16T21:17:33.128Z",Trace context traceId: 0xc29415c76a3ba76c67da0aea3a2e30b3, header x-b3-traceid: 5d5d767d2378f67ebd2fe67020bec818"
"2024-08-16T21:17:30.126Z",Trace context traceId: 0xc29415c76a3ba76c67da0aea3a2e30b3, header x-b3-traceid: c29415c76a3ba76c67da0aea3a2e30b3"

For reference, here’s the code we used for printing this info:

print(f"Trace context traceId: {hex(trace.get_current_span().get_span_context().trace_id)}, header x-b3-traceid: {ctx.request.headers.get('x-b3-traceid')}")

Because these ids don’t match, we believe this is an issue somewhere in BentoML (and not, for example, istio). Can you think of a reason why this could happen? We thought that it could be a but in dynamic batching, but we aren’t using that.

Adding some additional information here, I'm able to recreate this behavior locally by using

--next

in a curl request with multiple requests chained into the same connection.