Skip to content

Commit 2dc6e30

Browse files
brunobatbrunobat
authored
Merge pull request quarkusio#51641 from brunobat/fix-43134-MDC-context-disappears
Fix OTel MDC context set
2 parents 0c80b95 + 0f0e867 commit 2dc6e30

File tree

7 files changed

+186
-32
lines changed

7 files changed

+186
-32
lines changed

‎extensions/micrometer/runtime/src/main/java/io/quarkus/micrometer/runtime/export/exemplars/OpenTelemetryExemplarContextUnwrapper.java‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -17,7 +17,7 @@ public <P, R> R executeInContext(Function<P, R> methodReference, P parameter, io
1717
return methodReference.apply(parameter);
1818
}
1919

20-
Context newContext = QuarkusContextStorage.getContext(requestContext);
20+
Context newContext = QuarkusContextStorage.getOtelContext(requestContext);
2121

2222
if (newContext == null) {
2323
return methodReference.apply(parameter);

‎extensions/opentelemetry/deployment/src/test/java/io/quarkus/opentelemetry/deployment/OpenTelemetryMDCTest.java‎

Lines changed: 99 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -3,20 +3,25 @@
33
import static io.opentelemetry.api.trace.SpanKind.INTERNAL;
44
import static io.opentelemetry.api.trace.SpanKind.SERVER;
55
import static io.quarkus.opentelemetry.deployment.common.exporter.TestSpanExporter.getSpanByKindAndParentId;
6+
import static org.assertj.core.api.Assertions.assertThat;
67
import static org.hamcrest.Matchers.is;
78
import static org.junit.jupiter.api.Assertions.assertEquals;
89

910
import java.util.ArrayList;
1011
import java.util.Collections;
1112
import java.util.List;
1213
import java.util.Objects;
14+
import java.util.Random;
1315
import java.util.stream.Collectors;
1416

1517
import jakarta.enterprise.context.ApplicationScoped;
1618
import jakarta.inject.Inject;
1719
import jakarta.ws.rs.GET;
1820
import jakarta.ws.rs.Path;
21+
import jakarta.ws.rs.Produces;
22+
import jakarta.ws.rs.core.MediaType;
1923

24+
import org.eclipse.microprofile.context.ManagedExecutor;
2025
import org.jboss.logging.MDC;
2126
import org.jboss.shrinkwrap.api.asset.StringAsset;
2227
import org.junit.jupiter.api.AfterEach;
@@ -43,6 +48,7 @@ public class OpenTelemetryMDCTest {
4348
.addClass(MdcEntry.class)
4449
.addClass(TestMdcCapturer.class)
4550
.addClass(TestResource.class)
51+
.addClass(GreetingResource.class)
4652
.addAsResource(new StringAsset(TestSpanExporterProvider.class.getCanonicalName()),
4753
"META-INF/services/io.opentelemetry.sdk.autoconfigure.spi.traces.ConfigurableSpanExporterProvider")
4854
.addAsResource(new StringAsset(InMemoryMetricExporterProvider.class.getCanonicalName()),
@@ -84,6 +90,38 @@ void vertx() {
8490
assertEquals(expectedMdcEntries, mdcEntries);
8591
}
8692

93+
@Test
94+
void vertxAsync() {
95+
RestAssured.when()
96+
.get("/async").then()
97+
.statusCode(200)
98+
.body(is("Hello from Quarkus REST"));
99+
100+
List<SpanData> spans = spanExporter.getFinishedSpanItems(5);
101+
102+
final SpanData server = getSpanByKindAndParentId(spans, SERVER, "0000000000000000");
103+
assertEquals("GET /async", server.getName());
104+
105+
List<MdcEntry> expectedMdcEntriesFromSpans = getExpectedMDCEntries(spans);
106+
assertThat(testMdcCapturer.getCapturedMdcEntries().size()).isEqualTo(6);
107+
108+
List<MdcEntry> mdcEntries = testMdcCapturer.getCapturedMdcEntries();
109+
// 2 mdcEntries are repeated.
110+
assertThat(expectedMdcEntriesFromSpans).containsAll(mdcEntries.stream().distinct().toList());
111+
112+
assertThat(testMdcCapturer.getCapturedMdcEntries().stream()
113+
.filter(mdcEntry -> mdcEntry.parentId.equals("null"))
114+
.count())
115+
.withFailMessage("There must be 2 MDC entries for the parent span")
116+
.isEqualTo(2);
117+
118+
assertThat(testMdcCapturer.getCapturedMdcEntries().stream()
119+
.filter(mdcEntry -> mdcEntry.parentId.equals(server.getSpanId()))
120+
.count())
121+
.withFailMessage("There must be 4 MDC entries in child spans")
122+
.isEqualTo(4);
123+
}
124+
87125
@Test
88126
void nonVertx() {
89127
Span parentSpan = tracer.spanBuilder("parent").startSpan();
@@ -148,6 +186,62 @@ public String hello() {
148186
}
149187
}
150188

189+
@Path("/async")
190+
public static class GreetingResource {
191+
@Inject
192+
TestMdcCapturer testMdcCapturer;
193+
194+
@Inject
195+
ManagedExecutor managedExecutor;
196+
197+
@Inject
198+
Tracer tracer;
199+
200+
@GET
201+
@Produces(MediaType.TEXT_PLAIN)
202+
public String hello() {
203+
// 1 span from REST
204+
testMdcCapturer.captureMdc();
205+
for (int i = 0; i < 3; i++) {
206+
managedExecutor.execute(() -> {
207+
Span asyncSpan = tracer.spanBuilder("async hello").startSpan();
208+
try (Scope scope = asyncSpan.makeCurrent()) {
209+
executeWorkOnWorkerThread();
210+
// 3 manual async spans
211+
testMdcCapturer.captureMdc();
212+
} catch (Exception e) {
213+
throw new RuntimeException(e);
214+
} finally {
215+
asyncSpan.end();
216+
}
217+
});
218+
}
219+
220+
Span syncSpan = tracer.spanBuilder("sync hello").startSpan();
221+
try (Scope scope = syncSpan.makeCurrent()) {
222+
executeWorkOnWorkerThread();
223+
// 1 sync span
224+
testMdcCapturer.captureMdc();
225+
} catch (Exception e) {
226+
throw new RuntimeException(e);
227+
} finally {
228+
syncSpan.end();
229+
}
230+
// 5 spans total, 6 MDC captures
231+
testMdcCapturer.captureMdc();
232+
return "Hello from Quarkus REST";
233+
}
234+
235+
private void executeWorkOnWorkerThread() {
236+
try {
237+
Random random = new Random();
238+
Thread.sleep(100 + random.nextInt(400));
239+
} catch (InterruptedException e) {
240+
throw new RuntimeException(e);
241+
}
242+
}
243+
}
244+
151245
@Unremovable
152246
@ApplicationScoped
153247
public static class TestMdcCapturer {
@@ -202,5 +296,10 @@ public boolean equals(Object o) {
202296
public int hashCode() {
203297
return Objects.hash(isSampled, parentId, spanId, traceId);
204298
}
299+
300+
@Override
301+
public String toString() {
302+
return "spanId: " + spanId + " traceId: " + traceId + " parentId: " + parentId;
303+
}
205304
}
206305
}

‎extensions/opentelemetry/runtime/src/main/java/io/quarkus/opentelemetry/runtime/OpenTelemetryUtil.java‎

Lines changed: 23 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -6,13 +6,18 @@
66
import java.util.List;
77
import java.util.Map;
88

9+
import org.jboss.logging.Logger;
10+
911
import io.opentelemetry.api.trace.Span;
1012
import io.opentelemetry.api.trace.SpanContext;
1113
import io.opentelemetry.context.Context;
1214
import io.opentelemetry.sdk.trace.ReadableSpan;
1315
import io.quarkus.vertx.core.runtime.VertxMDC;
1416

1517
public final class OpenTelemetryUtil {
18+
19+
private static final Logger logger = Logger.getLogger(OpenTelemetryUtil.class);
20+
1621
public static final String TRACE_ID = "traceId";
1722
public static final String SPAN_ID = "spanId";
1823
public static final String SAMPLED = "sampled";
@@ -49,20 +54,27 @@ public static Map<String, String> convertKeyValueListToMap(List<String> headers)
4954
}
5055

5156
/**
52-
* Sets MDC data by using the current span from the context.
57+
* Sets MDC data by using the current span from the otelContext.
5358
* <p>
5459
* This method is in the hot path and was optimized to not use getSpanData()
5560
*
56-
* @param context opentelemetry context
57-
* @param vertxContext vertx context
61+
* @param otelContext opentelemetry otelContext
62+
* @param vertxContext vertx otelContext
5863
*/
59-
public static void setMDCData(Context context, io.vertx.core.Context vertxContext) {
60-
if (context == null) {
64+
public static void setMDCData(Context otelContext, io.vertx.core.Context vertxContext) {
65+
if (otelContext == null) {
6166
return;
6267
}
6368

64-
Span span = Span.fromContextOrNull(context);
69+
Span span = Span.fromContextOrNull(otelContext);
6570
if (span != null) {
71+
if (logger.isDebugEnabled()) {
72+
logger.debugv("Setting span in MDC: {0} with otel data in vertx context: {1}",
73+
getSpanData(otelContext),
74+
getSpanData(QuarkusContextStorage.getOtelContext(vertxContext)));
75+
}
76+
// clear the object ref to force a new one and prevent crosstalk
77+
VertxMDC.INSTANCE.clearVertxMdcFromContext(vertxContext);
6678
SpanContext spanContext = span.getSpanContext();
6779
VertxMDC.INSTANCE.put(SPAN_ID, spanContext.getSpanId(), vertxContext);
6880
VertxMDC.INSTANCE.put(TRACE_ID, spanContext.getTraceId(), vertxContext);
@@ -109,6 +121,11 @@ public static Map<String, String> getSpanData(Context context) {
109121
*/
110122
public static void clearMDCData(io.vertx.core.Context vertxContext) {
111123
VertxMDC vertxMDC = VertxMDC.INSTANCE;
124+
if (logger.isDebugEnabled()) {
125+
logger.debugv("Removing from MDC the span id: {0}, with otel data in vertx context: {1}",
126+
vertxMDC.get(SPAN_ID, vertxContext),
127+
getSpanData(QuarkusContextStorage.getOtelContext(vertxContext)));
128+
}
112129
vertxMDC.remove(TRACE_ID, vertxContext);
113130
vertxMDC.remove(SPAN_ID, vertxContext);
114131
vertxMDC.remove(PARENT_ID, vertxContext);

‎extensions/opentelemetry/runtime/src/main/java/io/quarkus/opentelemetry/runtime/QuarkusContextStorage.java‎

Lines changed: 46 additions & 20 deletions
Original file line numberDiff line numberDiff line change
@@ -5,6 +5,7 @@
55

66
import org.jboss.logging.Logger;
77

8+
import io.opentelemetry.api.trace.Span;
89
import io.opentelemetry.context.Context;
910
import io.opentelemetry.context.ContextStorage;
1011
import io.opentelemetry.context.Scope;
@@ -31,25 +32,25 @@ public enum QuarkusContextStorage implements ContextStorage {
3132
* Vert.x Context the OpenTelemetry Context is attached to the Vert.x Context. Otherwise, fallback to the
3233
* OpenTelemetry default ContextStorage.
3334
*
34-
* @param toAttach the OpenTelemetry Context to attach
35+
* @param otelToAttach the OpenTelemetry Context to attach
3536
* @return the Scope of the OpenTelemetry Context
3637
*/
3738
@Override
38-
public Scope attach(Context toAttach) {
39+
public Scope attach(Context otelToAttach) {
3940
io.vertx.core.Context vertxContext = getVertxContext();
40-
return vertxContext != null && isDuplicatedContext(vertxContext) ? attach(vertxContext, toAttach)
41-
: FALLBACK_CONTEXT_STORAGE.attach(toAttach);
41+
return vertxContext != null && isDuplicatedContext(vertxContext) ? attach(vertxContext, otelToAttach)
42+
: FALLBACK_CONTEXT_STORAGE.attach(otelToAttach);
4243
}
4344

4445
/**
4546
* Attach the OpenTelemetry Context in the Vert.x Context if it is a duplicated Vert.x Context.
4647
*
4748
* @param vertxContext the Vert.x Context to attach the OpenTelemetry Context
48-
* @param toAttach the OpenTelemetry Context to attach
49+
* @param otelToAttach the OpenTelemetry Context to attach
4950
* @return the Scope of the OpenTelemetry Context
5051
*/
51-
public Scope attach(io.vertx.core.Context vertxContext, Context toAttach) {
52-
if (vertxContext == null || toAttach == null) {
52+
public Scope attach(io.vertx.core.Context vertxContext, Context otelToAttach) {
53+
if (vertxContext == null || otelToAttach == null) {
5354
return Scope.noop();
5455
}
5556

@@ -59,32 +60,57 @@ public Scope attach(io.vertx.core.Context vertxContext, Context toAttach) {
5960
"The Vert.x Context to attach the OpenTelemetry Context must be a duplicated Context");
6061
}
6162

62-
Context beforeAttach = getContext(vertxContext);
63-
if (toAttach == beforeAttach) {
63+
Context otelBeforeAttach = getOtelContext(vertxContext);
64+
if (otelToAttach == otelBeforeAttach) {
6465
return Scope.noop();
6566
}
66-
vertxContext.putLocal(OTEL_CONTEXT, toAttach);
67-
OpenTelemetryUtil.setMDCData(toAttach, vertxContext);
67+
68+
if (log.isDebugEnabled()) {
69+
log.debugv("Setting Otel context: {0}", OpenTelemetryUtil.getSpanData(otelToAttach));
70+
}
71+
72+
vertxContext.putLocal(OTEL_CONTEXT, otelToAttach);
73+
OpenTelemetryUtil.setMDCData(otelToAttach, vertxContext);
6874

6975
return new Scope() {
7076

7177
@Override
7278
public void close() {
73-
final Context before = getContext(vertxContext);
74-
if (before != toAttach) {
79+
// compare otel contexts when closing scope
80+
final Context otelBefore = getOtelContext(vertxContext);
81+
82+
if (log.isDebugEnabled()) {
83+
log.debugv("Closing Otel context: {0}", OpenTelemetryUtil.getSpanData(otelToAttach));
84+
}
85+
86+
if (otelBefore != otelToAttach) {
7587
log.info("Context in storage not the expected context, Scope.close was not called correctly. Details:" +
76-
" OTel context before: " + OpenTelemetryUtil.getSpanData(before) +
77-
". OTel context toAttach: " + OpenTelemetryUtil.getSpanData(toAttach));
88+
" OTel context otelBefore: " + OpenTelemetryUtil.getSpanData(otelBefore) +
89+
". OTel context otelToAttach: " + OpenTelemetryUtil.getSpanData(otelToAttach));
7890
}
7991

80-
if (beforeAttach == null) {
81-
vertxContext.removeLocal(OTEL_CONTEXT);
92+
if (otelBeforeAttach == null) {
8293
OpenTelemetryUtil.clearMDCData(vertxContext);
94+
vertxContext.removeLocal(OTEL_CONTEXT);
8395
} else {
84-
vertxContext.putLocal(OTEL_CONTEXT, beforeAttach);
85-
OpenTelemetryUtil.setMDCData(beforeAttach, vertxContext);
96+
Span span = Span.fromContextOrNull(otelBeforeAttach);
97+
if (span != null && span.isRecording()) {
98+
// Only restore if Span has not ended
99+
OpenTelemetryUtil.setMDCData(otelBeforeAttach, vertxContext);
100+
vertxContext.putLocal(OTEL_CONTEXT, otelBeforeAttach);
101+
} else {
102+
OpenTelemetryUtil.clearMDCData(vertxContext);
103+
vertxContext.removeLocal(OTEL_CONTEXT);
104+
}
86105
}
87106
}
107+
108+
@Override
109+
public String toString() {
110+
Context otelInVertxContext = getOtelContext(vertxContext);
111+
return "OTelContext: " + OpenTelemetryUtil.getSpanData(otelToAttach) +
112+
". vertxContext: " + OpenTelemetryUtil.getSpanData(otelInVertxContext);
113+
}
88114
};
89115
}
90116

@@ -110,7 +136,7 @@ public Context current() {
110136
* @param vertxContext a Vert.x Context.
111137
* @return the OpenTelemetry Context if exists in the Vert.x Context or null.
112138
*/
113-
public static Context getContext(io.vertx.core.Context vertxContext) {
139+
public static Context getOtelContext(io.vertx.core.Context vertxContext) {
114140
return vertxContext != null && isDuplicatedContext(vertxContext) ? vertxContext.getLocal(OTEL_CONTEXT) : null;
115141
}
116142

‎extensions/opentelemetry/runtime/src/main/java/io/quarkus/opentelemetry/runtime/tracing/instrumentation/restclient/OpenTelemetryClientFilter.java‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -87,7 +87,7 @@ public OpenTelemetryClientFilter(final OpenTelemetry openTelemetry, final OTelRu
8787
@Override
8888
public void filter(final ClientRequestContext request) {
8989
io.vertx.core.Context vertxContext = getVertxContext(request);
90-
io.opentelemetry.context.Context parentContext = QuarkusContextStorage.getContext(vertxContext);
90+
io.opentelemetry.context.Context parentContext = QuarkusContextStorage.getOtelContext(vertxContext);
9191
if (parentContext == null) {
9292
parentContext = io.opentelemetry.context.Context.current();
9393
}

‎extensions/opentelemetry/runtime/src/main/java/io/quarkus/opentelemetry/runtime/tracing/instrumentation/vertx/InstrumenterVertxTracer.java‎

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -34,7 +34,7 @@ default <R> SpanOperation receiveRequest(
3434
}
3535

3636
Instrumenter<REQ, RESP> instrumenter = getReceiveRequestInstrumenter();
37-
io.opentelemetry.context.Context parentContext = QuarkusContextStorage.getContext(context);
37+
io.opentelemetry.context.Context parentContext = QuarkusContextStorage.getOtelContext(context);
3838
if (parentContext == null) {
3939
parentContext = io.opentelemetry.context.Context.current();
4040
}
@@ -89,7 +89,7 @@ default <R> SpanOperation sendRequest(
8989
}
9090

9191
Instrumenter<REQ, RESP> instrumenter = getSendRequestInstrumenter();
92-
io.opentelemetry.context.Context parentContext = QuarkusContextStorage.getContext(context);
92+
io.opentelemetry.context.Context parentContext = QuarkusContextStorage.getOtelContext(context);
9393
if (parentContext == null) {
9494
parentContext = io.opentelemetry.context.Context.current();
9595
}

0 commit comments

Comments
 (0)