Skip to content

Commit 8f5eb8a

Browse files
dougqhclaude
andcommitted
fix(okhttp): capture scope at AsyncCall.<init> to keep traces intact under virtual-thread Dispatcher load
OkHttp's Dispatcher recursively promotes queued AsyncCalls from inside finished(), running on a worker thread that has a *different* call's parent scope active. The existing TaskRunnerInstrumentation captures that wrong scope when the promoted call is executed, so under a virtual-thread-per-task Dispatcher (or any executor where the same recursion exposes the issue) okhttp.request spans cross-contaminate between concurrent caller traces. Single-shot requests don't trigger this because nothing is queued. Fix: add AsyncCallInstrumentation that captures the active scope at AsyncCall.<init> (i.e. the user thread that ran enqueue(), where the right parent is active) and stores it in the shared ContextStore<Runnable, State>. RunnableInstrumentation then activates that state on AsyncCall.run() entry, overriding whatever scope TaskRunner inherited from the dispatcher-recursion path. Covers both class locations (3.x and 4.x). Muzzle passes against 24 OkHttp versions in [3.0.0, 5.3.2]. All 168 pre-existing forked OkHttp tests still pass. Tests added: * okhttp-3.0/src/vthread21Test/.../OkHttpVirtualThreadDispatcherTest: concurrent-burst test (16 parents x 4 requests through a virtual- thread Dispatcher with capacity 4) plus two single-shot baselines. The concurrent-burst test fails on master and v1.61.1 without the fix and passes with it. * java-concurrent-21.0/src/test/java/ThreadPerTaskExecutorVirtualThreadTest: pure-executor regression coverage for Thread.ofVirtual().factory(), the .name(prefix, start) builder variant, recursive submission, and propagation across virtual-thread unmount. Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>
1 parent f9d3adc commit 8f5eb8a

4 files changed

Lines changed: 620 additions & 0 deletions

File tree

Original file line numberDiff line numberDiff line change
@@ -0,0 +1,190 @@
1+
import static org.junit.jupiter.api.Assertions.assertEquals;
2+
import static org.junit.jupiter.api.Assertions.assertNotNull;
3+
4+
import datadog.trace.agent.test.AbstractInstrumentationTest;
5+
import datadog.trace.api.Trace;
6+
import datadog.trace.core.DDSpan;
7+
import java.util.List;
8+
import java.util.concurrent.ExecutorService;
9+
import java.util.concurrent.Executors;
10+
import org.junit.jupiter.api.Test;
11+
12+
/**
13+
* Reproductions for the executor swap profiling-backend PR#8520 made for OkHttp's Dispatcher
14+
* (cached thread pool &rarr; {@code Executors.newThreadPerTaskExecutor(Thread.ofVirtual()...)}).
15+
*
16+
* <p>Each test asserts that an {@code @Trace}-annotated child method invoked from inside a task
17+
* submitted to the virtual-thread-per-task executor attaches to the parent span that was active at
18+
* submission time. If propagation breaks, the child either lands in a different trace or floats
19+
* free as a root span and the {@code assertEquals(parentSpanId, childSpan.getParentId())} check
20+
* fails.
21+
*
22+
* <p>This mirrors what would happen with OkHttp: the {@code okhttp} client span is created by
23+
* {@code TracingInterceptor.intercept()} on the executor thread using {@code activeSpan()}, so "is
24+
* the parent scope active on the worker?" is the entire question.
25+
*/
26+
class ThreadPerTaskExecutorVirtualThreadTest extends AbstractInstrumentationTest {
27+
28+
@Trace(operationName = "parent")
29+
void underParentTrace(int expectedChildren, Runnable body) {
30+
body.run();
31+
blockUntilChildSpansFinished(expectedChildren);
32+
}
33+
34+
@Trace(operationName = "child")
35+
static void child() {}
36+
37+
@Test
38+
void virtualThreadFactory_propagatesActiveScope() throws Exception {
39+
ExecutorService executor = Executors.newThreadPerTaskExecutor(Thread.ofVirtual().factory());
40+
try {
41+
underParentTrace(1, () -> executor.execute(ThreadPerTaskExecutorVirtualThreadTest::child));
42+
} finally {
43+
executor.shutdown();
44+
}
45+
46+
writer.waitForTraces(1);
47+
List<DDSpan> trace = writer.get(0);
48+
assertEquals(2, trace.size(), "expected parent + child span");
49+
DDSpan parentSpan = findByOp(trace, "parent");
50+
DDSpan childSpan = findByOp(trace, "child");
51+
assertNotNull(parentSpan, "parent span should exist");
52+
assertNotNull(childSpan, "child span should exist");
53+
assertEquals(
54+
parentSpan.getSpanId(),
55+
childSpan.getParentId(),
56+
"child span should be parented under the active span at executor.execute()");
57+
}
58+
59+
@Test
60+
void namedVirtualThreadFactory_propagatesActiveScope() throws Exception {
61+
// Exact builder shape from profiling-backend PR#8520:
62+
// Thread.ofVirtual().name("okhttp-" + track + "-", 0).factory()
63+
ExecutorService executor =
64+
Executors.newThreadPerTaskExecutor(Thread.ofVirtual().name("okhttp-test-", 0).factory());
65+
try {
66+
underParentTrace(1, () -> executor.execute(ThreadPerTaskExecutorVirtualThreadTest::child));
67+
} finally {
68+
executor.shutdown();
69+
}
70+
71+
writer.waitForTraces(1);
72+
List<DDSpan> trace = writer.get(0);
73+
DDSpan parentSpan = findByOp(trace, "parent");
74+
DDSpan childSpan = findByOp(trace, "child");
75+
assertNotNull(parentSpan, "parent span should exist");
76+
assertNotNull(childSpan, "child span should exist");
77+
assertEquals(
78+
parentSpan.getSpanId(),
79+
childSpan.getParentId(),
80+
"the .name(prefix, start) builder should not break propagation");
81+
}
82+
83+
/**
84+
* Mirrors OkHttp's dispatcher recursion: a task running on the executor submits more work back to
85+
* the same executor. In OkHttp this is {@code Dispatcher.finished() &rarr; promoteAndExecute()
86+
* &rarr; executorService.execute(nextAsyncCall)}, called from inside an {@code AsyncCall.run()}
87+
* on a dispatcher thread.
88+
*
89+
* <p>Both child spans should land in the parent's trace. If the worker thread loses the parent
90+
* scope between the outer activation and the inner submission, the second child either becomes a
91+
* new root span or gets attached to the wrong sibling.
92+
*/
93+
@Test
94+
void recursiveSubmissionFromWorkerThread_keepsTraceConnected() throws Exception {
95+
ExecutorService executor = Executors.newThreadPerTaskExecutor(Thread.ofVirtual().factory());
96+
try {
97+
underParentTrace(
98+
2,
99+
() ->
100+
executor.execute(
101+
() -> {
102+
child();
103+
executor.execute(ThreadPerTaskExecutorVirtualThreadTest::child);
104+
}));
105+
} finally {
106+
executor.shutdown();
107+
}
108+
109+
writer.waitForTraces(1);
110+
List<DDSpan> trace = writer.get(0);
111+
DDSpan parentSpan = findByOp(trace, "parent");
112+
assertNotNull(parentSpan, "parent span should exist");
113+
long parentTraceId = parentSpan.getTraceId().toLong();
114+
long parentSpanId = parentSpan.getSpanId();
115+
116+
long childCount =
117+
trace.stream().filter(s -> "child".contentEquals(s.getOperationName())).count();
118+
assertEquals(2, childCount, "both child spans should land in the same trace as the parent");
119+
120+
trace.stream()
121+
.filter(s -> "child".contentEquals(s.getOperationName()))
122+
.forEach(
123+
s -> {
124+
assertEquals(
125+
parentTraceId,
126+
s.getTraceId().toLong(),
127+
"child span must share the parent's trace");
128+
assertEquals(
129+
parentSpanId,
130+
s.getParentId(),
131+
"child span must attach to the parent, not float free");
132+
});
133+
}
134+
135+
/**
136+
* Forces the virtual thread to unmount and remount mid-task by sleeping between two child spans.
137+
* This is the case OkHttp actually hits in practice &mdash; every blocking socket read unmounts
138+
* the carrier, and the scope stack has to be reinstated by {@code VirtualThreadInstrumentation}
139+
* on each remount. The fix log for this area is long (#10931, #11009, #11111), so it is worth
140+
* pinning down with a regression test.
141+
*/
142+
@Test
143+
void virtualThreadFactory_propagatesAcrossUnmount() throws Exception {
144+
ExecutorService executor = Executors.newThreadPerTaskExecutor(Thread.ofVirtual().factory());
145+
try {
146+
underParentTrace(
147+
2,
148+
() ->
149+
executor.execute(
150+
() -> {
151+
child();
152+
try {
153+
// Sleep is a JDK 21+ carrier-unmounting parking point for virtual threads.
154+
Thread.sleep(50);
155+
} catch (InterruptedException e) {
156+
Thread.currentThread().interrupt();
157+
}
158+
child();
159+
}));
160+
} finally {
161+
executor.shutdown();
162+
}
163+
164+
writer.waitForTraces(1);
165+
List<DDSpan> trace = writer.get(0);
166+
DDSpan parentSpan = findByOp(trace, "parent");
167+
assertNotNull(parentSpan, "parent span should exist");
168+
long parentSpanId = parentSpan.getSpanId();
169+
170+
long childCount =
171+
trace.stream().filter(s -> "child".contentEquals(s.getOperationName())).count();
172+
assertEquals(2, childCount, "both child spans should be captured");
173+
174+
trace.stream()
175+
.filter(s -> "child".contentEquals(s.getOperationName()))
176+
.forEach(
177+
s ->
178+
assertEquals(
179+
parentSpanId,
180+
s.getParentId(),
181+
"child span before and after virtual-thread unmount must both attach to parent"));
182+
}
183+
184+
private static DDSpan findByOp(List<DDSpan> spans, String op) {
185+
return spans.stream()
186+
.filter(s -> op.contentEquals(s.getOperationName()))
187+
.findFirst()
188+
.orElse(null);
189+
}
190+
}

dd-java-agent/instrumentation/okhttp/okhttp-3.0/build.gradle

Lines changed: 31 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -8,9 +8,30 @@ muzzle {
88
}
99

1010
apply from: "$rootDir/gradle/java.gradle"
11+
// Use slf4j-simple for tests; logback's synchronized appenders can pin virtual-thread carriers
12+
// when many vthreads log concurrently, which deadlocks this module's vthread21Test suite.
13+
apply from: "$rootDir/gradle/slf4j-simple.gradle"
1114

1215
addTestSuiteForDir('latestDepTest', 'test')
1316

17+
// Separate suite for tests that need the JDK 21+ virtual-thread API. Kept apart from the
18+
// default test suite so that the existing OkHttp 3.0 tests keep their Java 1.8 baseline.
19+
addTestSuite('vthread21Test')
20+
21+
tasks.named("compileVthread21TestJava", JavaCompile) {
22+
configureCompiler(it, 21)
23+
}
24+
25+
tasks.named("vthread21Test", Test) {
26+
javaLauncher = javaToolchains.launcherFor {
27+
languageVersion = JavaLanguageVersion.of(21)
28+
}
29+
}
30+
31+
tasks.named("check") {
32+
dependsOn "vthread21Test"
33+
}
34+
1435
dependencies {
1536
compileOnly(group: 'com.squareup.okhttp3', name: 'okhttp', version: '3.0.0')
1637

@@ -38,4 +59,14 @@ dependencies {
3859

3960
testRuntimeOnly(project(':dd-java-agent:instrumentation:datadog:asm:iast-instrumenter'))
4061
testRuntimeOnly(project(':dd-java-agent:instrumentation:java:java-net:java-net-1.8'))
62+
63+
// vthread21Test inherits testImplementation via addTestSuite's extendsFrom wiring.
64+
vthread21TestImplementation(group: 'com.squareup.okhttp3', name: 'okhttp', version: '3.11.0')
65+
vthread21TestImplementation(group: 'com.squareup.okio', name: 'okio', version: '1.14.0')
66+
67+
// Pull in the JDK-21+ concurrent / lang instrumentations so the test installs the same
68+
// TaskRunnerInstrumentation + VirtualThreadInstrumentation chain that profiling-backend
69+
// exercises in production.
70+
vthread21TestRuntimeOnly project(':dd-java-agent:instrumentation:java:java-concurrent:java-concurrent-21.0')
71+
vthread21TestRuntimeOnly project(':dd-java-agent:instrumentation:java:java-lang:java-lang-21.0')
4172
}
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,78 @@
1+
package datadog.trace.instrumentation.okhttp3;
2+
3+
import static datadog.trace.bootstrap.instrumentation.java.concurrent.AdviceUtils.capture;
4+
import static java.util.Collections.singletonMap;
5+
import static net.bytebuddy.matcher.ElementMatchers.isConstructor;
6+
7+
import com.google.auto.service.AutoService;
8+
import datadog.trace.agent.tooling.Instrumenter;
9+
import datadog.trace.agent.tooling.InstrumenterModule;
10+
import datadog.trace.bootstrap.InstrumentationContext;
11+
import datadog.trace.bootstrap.instrumentation.java.concurrent.State;
12+
import java.util.Map;
13+
import net.bytebuddy.asm.Advice;
14+
15+
/**
16+
* Captures the active scope at {@code AsyncCall.<init>} (i.e. the moment {@code
17+
* Call.enqueue(callback)} was invoked on the user's thread) and stores it in the {@code
18+
* ContextStore<Runnable, State>} shared with the rest of the concurrent instrumentation. {@code
19+
* RunnableInstrumentation} then re-activates that scope on {@code AsyncCall.run()} entry, which
20+
* overrides whatever scope {@code TaskRunner.run()} (or {@code beforeExecute}) put in place from
21+
* the dispatcher's worker thread.
22+
*
23+
* <p>Without this, {@code TaskRunnerInstrumentation} captures whatever scope happens to be active
24+
* on the worker thread when {@code Dispatcher.promoteAndExecute()} dequeues and submits the call —
25+
* and when promotion runs from inside {@code Dispatcher.finished()} (i.e. recursively from a
26+
* <em>different</em> AsyncCall's run()), that scope belongs to the finishing call, not to the
27+
* caller who actually enqueued this AsyncCall. Result: under concurrent OkHttp load, {@code
28+
* okhttp.request} spans cross-contaminate between traces.
29+
*
30+
* <p>The class moved between OkHttp 3.x and 4.x:
31+
*
32+
* <ul>
33+
* <li>OkHttp 3.x &mdash; {@code okhttp3.RealCall$AsyncCall}
34+
* <li>OkHttp 4.x &mdash; {@code okhttp3.internal.connection.RealCall$AsyncCall}
35+
* </ul>
36+
*
37+
* Both are inner classes of {@code RealCall} and both transitively implement {@link Runnable}.
38+
*/
39+
@AutoService(InstrumenterModule.class)
40+
public final class AsyncCallInstrumentation extends InstrumenterModule.Tracing
41+
implements Instrumenter.ForKnownTypes, Instrumenter.HasMethodAdvice {
42+
43+
public AsyncCallInstrumentation() {
44+
// Re-use the existing "okhttp" / "okhttp-3" instrumentation names so we don't introduce a
45+
// separately-toggleable feature flag (DD_TRACE_OKHTTP_ASYNC_CALL_ENABLED). The capture here
46+
// is conceptually part of the OkHttp instrumentation — if you disable OkHttp tracing, you
47+
// also disable this capture, which is the right behavior.
48+
super("okhttp", "okhttp-3");
49+
}
50+
51+
@Override
52+
public String[] knownMatchingTypes() {
53+
return new String[] {
54+
"okhttp3.RealCall$AsyncCall", // OkHttp 3.x
55+
"okhttp3.internal.connection.RealCall$AsyncCall", // OkHttp 4.x
56+
};
57+
}
58+
59+
@Override
60+
public Map<String, String> contextStore() {
61+
// Same Runnable -> State store that RunnableInstrumentation reads from.
62+
return singletonMap("java.lang.Runnable", State.class.getName());
63+
}
64+
65+
@Override
66+
public void methodAdvice(MethodTransformer transformer) {
67+
transformer.applyAdvice(isConstructor(), getClass().getName() + "$Construct");
68+
}
69+
70+
public static final class Construct {
71+
@Advice.OnMethodExit(suppress = Throwable.class)
72+
public static void captureScope(@Advice.This Runnable asyncCall) {
73+
// AdviceUtils.capture is a no-op when async propagation is disabled or there's no active
74+
// span — same behavior as the rest of the concurrent instrumentation.
75+
capture(InstrumentationContext.get(Runnable.class, State.class), asyncCall);
76+
}
77+
}
78+
}

0 commit comments

Comments
 (0)