Skip to content

Commit 1168c35

Browse files
bm1549devflow.devflow-routing-intake
andauthored
log-injection: capture thread dump of forked process on smoketest timeout (#11400)
log-injection: capture thread dump of forked process on timeout When `waitForTraceCountAlive` times out, the existing diagnostic dumps the tail of the forked process's captured stdout. In all 49 observed `traceCount=0` failures since #11075, that dump has come back empty — the JVM is alive (RC polls=130+) but the output-capture thread appears starved, so we can't see what the agent is doing. Capture a thread dump via `jstack` instead. Its output is read by the smoketest JVM directly, bypassing the tested-process capture thread. No raw `kill -3` fallback — PID reuse on shared CI hosts could cause us to signal an unrelated process if the child has exited since the surrounding liveness check. Diagnostic-only, fires only on the timeout failure path. log-injection: harden dumpThreadStacks against masking errors Two issues in the previous commit's diagnostic path: 1. The body of dumpThreadStacks had no top-level try/catch — an unexpected throw (reflection error, NPE, etc.) would propagate out and replace the original AssertionError with a less useful one. Wrap the whole body and return a "(thread dump failed: ...)" string instead. 2. PID-reuse race: between the alive check at the call site and the jstack invocation, the child can exit and be reaped; if the OS reuses the PID we'd jstack an unrelated process and attach misleading diagnostics to the failure. Re-check isAlive() immediately before invoking jstack to narrow the race window. log-injection: spotless formatting log-injection: spotless fix for return-closure single-line Revert spotless single-line closure change The single-line closure format CI flagged earlier was a transient CI runner state (likely stale Groovy-Eclipse formatter cache); subsequent runs flagged the opposite direction. Reverting to the master format, which matches what the current CI runners accept. log-injection: print full thread dump to stdout, filter inline message CI Visibility caps error.message at ~5000 chars, which truncates the full jstack output mid-thread. Two changes to make sure no dump info is ever lost: 1. Print the full thread dump to stdout via println(). Gradle's test reporter captures stdout per-test, surfacing it in both the build log (visible in GitLab CI) and the test report XML. This becomes the source of truth when the inline dump is incomplete. 2. Filter the inline dump (in error.message) to prioritize the threads that explain a hang: main, dd-*/datadog-* agent threads, OkHttp threads, and anything BLOCKED. Known JVM boilerplate (Reference Handler, Finalizer, compiler threads, GC, etc.) is dropped. The result is capped at 4200 chars with an elision marker noting where to find the full dump. log-injection: drop misleading stdout-dump path The earlier println-the-full-dump-to-stdout idea was supposed to give us a fallback when CI Visibility truncates error.message at ~5000 chars. Verified in CI: that println goes to Gradle's per-test stdout capture, which lands in the test report XML — but the XML is not uploaded as a GitLab artifact, and CI Visibility doesn't capture test stdout either. So the "full dump" claim was misleading. Drop the println and the "(full dump on stdout)" marker. Bump the inline filter cap from 4200 to 4700 to use the full error.message budget. The filtered dump retains main + all dd-* agent threads + any BLOCKED thread — exactly what's needed to diagnose a wedged tracer under traceCount=0. Co-authored-by: devflow.devflow-routing-intake <devflow.devflow-routing-intake@kubernetes.us1.ddbuild.io>
1 parent 774302e commit 1168c35

1 file changed

Lines changed: 200 additions & 1 deletion

File tree

dd-smoke-tests/log-injection/src/test/groovy/datadog/smoketest/LogInjectionSmokeTest.groovy

Lines changed: 200 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -3,6 +3,7 @@ package datadog.smoketest
33
import com.squareup.moshi.Moshi
44
import com.squareup.moshi.Types
55
import datadog.environment.JavaVirtualMachine
6+
import datadog.environment.OperatingSystem
67
import datadog.trace.agent.test.server.http.TestHttpServer.HandlerApi.RequestApi
78
import datadog.trace.api.config.GeneralConfig
89
import datadog.trace.test.util.Flaky
@@ -378,15 +379,213 @@ abstract class LogInjectionSmokeTest extends AbstractSmokeTest {
378379
// The default error ("Condition not satisfied after 30s") is useless — enrich with diagnostic state
379380
def alive = testedProcess?.isAlive()
380381
def lastLines = tailProcessLog(30)
382+
def threadDump = alive ? dumpThreadStacks() : "(process not alive, skipping thread dump)"
381383
throw new AssertionError(
382384
"Timed out waiting for ${count} traces after ${defaultPoll.timeout}s. " +
383385
"traceCount=${traceCount.get()}, process.alive=${alive}, " +
384386
"RC polls received: ${rcClientMessages.size()}.\n" +
385-
"Last process output:\n${lastLines}", e)
387+
"Last process output:\n${lastLines}\n" +
388+
"Thread dump:\n${threadDump}", e)
386389
}
387390
traceCount.get()
388391
}
389392

393+
/**
394+
* Capture a thread dump of the forked process via {@code jstack}. jstack's output is captured by
395+
* the smoketest JVM directly, bypassing the tested-process output-capture thread that has been
396+
* observed to be starved at timeout (which makes the SIGQUIT-via-stderr approach unreliable for
397+
* exactly the failures we want to diagnose).
398+
*
399+
* <p>No raw {@code kill -3} fallback: PID reuse on shared CI hosts could cause us to signal an
400+
* unrelated process if the child has exited since the surrounding liveness check.
401+
*/
402+
private String dumpThreadStacks() {
403+
try {
404+
if (testedProcess == null) {
405+
return "(no tested process)"
406+
}
407+
if (OperatingSystem.isWindows()) {
408+
return "(thread dump not supported on Windows)"
409+
}
410+
long pid = getTestedProcessPid()
411+
if (pid <= 0) {
412+
return "(could not determine pid)"
413+
}
414+
// Re-check liveness immediately before invoking jstack. The earlier check that gates this
415+
// method runs ~1 statement away, but if the child has exited and been reaped since then,
416+
// the OS may have reused the PID — jstack-ing the wrong process would attach misleading
417+
// diagnostics to the test failure.
418+
if (!testedProcess.isAlive()) {
419+
return "(process exited between liveness check and dump; skipping to avoid PID reuse)"
420+
}
421+
String jstackOut = runJstack(pid)
422+
if (jstackOut == null) {
423+
return "(jstack not available or failed)"
424+
}
425+
return filterThreadDump(jstackOut)
426+
} catch (Throwable t) {
427+
// Never let a diagnostic failure mask the original AssertionError.
428+
return "(thread dump failed: ${t.getClass().simpleName}: ${t.message})"
429+
}
430+
}
431+
432+
// Approximate budget for the inline dump in error.message. Datadog CI Visibility caps
433+
// error.message at ~5000 chars; this leaves a few hundred for the "Timed out waiting..."
434+
// prefix and the elision marker.
435+
private static final int INLINE_DUMP_CAP = 4700
436+
437+
/**
438+
* Reduce a jstack thread dump to the threads most likely to explain a hang: the main thread,
439+
* dd-trace agent threads (dd-*, datadog-*), OkHttp threads, and anything BLOCKED. Drops known
440+
* JVM boilerplate (compiler/GC/reference handler/etc). Truncates to {@link #INLINE_DUMP_CAP}
441+
* with an elision marker.
442+
*/
443+
private String filterThreadDump(String fullDump) {
444+
int firstBlockIdx = fullDump.indexOf('\n"')
445+
if (firstBlockIdx < 0) {
446+
// No recognizable thread blocks — return the original, truncated if needed
447+
return fullDump.length() > INLINE_DUMP_CAP
448+
? fullDump.substring(0, INLINE_DUMP_CAP) + "\n(truncated)"
449+
: fullDump
450+
}
451+
String header = fullDump.substring(0, firstBlockIdx + 1)
452+
String rest = fullDump.substring(firstBlockIdx + 1)
453+
454+
List<String> blocks = []
455+
int i = 0
456+
while (i < rest.length()) {
457+
int next = rest.indexOf('\n"', i)
458+
if (next < 0) {
459+
blocks.add(rest.substring(i))
460+
break
461+
}
462+
blocks.add(rest.substring(i, next + 1))
463+
i = next + 1
464+
}
465+
466+
List<String> highPriority = []
467+
List<String> lowPriority = []
468+
int boilerplateDropped = 0
469+
for (String block : blocks) {
470+
def m = block =~ /^"([^"]+)"/
471+
String name = m.find() ? m.group(1) : ''
472+
if (isBoilerplateThread(name)) {
473+
boilerplateDropped++
474+
} else if (isHighPriorityThread(name, block)) {
475+
highPriority.add(block)
476+
} else {
477+
lowPriority.add(block)
478+
}
479+
}
480+
481+
StringBuilder out = new StringBuilder(header)
482+
int elided = 0
483+
for (String block : highPriority + lowPriority) {
484+
if (out.length() + block.length() + 120 > INLINE_DUMP_CAP) {
485+
elided++
486+
continue
487+
}
488+
out.append(block)
489+
}
490+
if (boilerplateDropped > 0 || elided > 0) {
491+
out.append("\n(elided ${boilerplateDropped} JVM-boilerplate thread(s)")
492+
if (elided > 0) {
493+
out.append(", elided ${elided} other thread(s) for size")
494+
}
495+
out.append(")")
496+
}
497+
return out.toString()
498+
}
499+
500+
private static boolean isBoilerplateThread(String name) {
501+
if (name in [
502+
"Reference Handler", "Finalizer", "Signal Dispatcher", "Common-Cleaner",
503+
"Service Thread", "Monitor Deflation Thread", "Notification Thread",
504+
"Attach Listener", "process reaper", "Sweeper thread", "VM Thread", "VM Periodic Task Thread"
505+
]) {
506+
return true
507+
}
508+
return name.startsWith("C1 CompilerThread") ||
509+
name.startsWith("C2 CompilerThread") ||
510+
name.startsWith("GC Thread") ||
511+
name.startsWith("G1 ") ||
512+
name.startsWith("ParGC ") ||
513+
name.startsWith("CMS ")
514+
}
515+
516+
private static boolean isHighPriorityThread(String name, String block) {
517+
if (name == "main") {
518+
return true
519+
}
520+
if (name.startsWith("dd-") || name.startsWith("datadog-")) {
521+
return true
522+
}
523+
if (name.startsWith("OkHttp") || name.contains("okhttp")) {
524+
return true
525+
}
526+
return block.contains("java.lang.Thread.State: BLOCKED")
527+
}
528+
529+
private long getTestedProcessPid() {
530+
try {
531+
return (long) testedProcess.getClass().getMethod("pid").invoke(testedProcess)
532+
} catch (Throwable ignored) {
533+
try {
534+
// UNIXProcess's private 'pid' field, for JDK 8 compatibility
535+
def field = testedProcess.getClass().getDeclaredField("pid")
536+
field.setAccessible(true)
537+
return field.getInt(testedProcess) as long
538+
} catch (Throwable ignored2) {
539+
return -1L
540+
}
541+
}
542+
}
543+
544+
private String runJstack(long pid) {
545+
def candidates = []
546+
// java.home is always set by the JVM and points to the active JDK/JRE; prefer it over the
547+
// JAVA_HOME env var which is frequently absent in CI runners even when Java is present.
548+
String javaHome = System.getProperty("java.home")
549+
if (javaHome) {
550+
candidates.add(javaHome + "/bin/jstack")
551+
}
552+
String javaHomeEnv = System.getenv("JAVA_HOME")
553+
if (javaHomeEnv && javaHomeEnv != javaHome) {
554+
candidates.add(javaHomeEnv + "/bin/jstack")
555+
}
556+
candidates.add("jstack")
557+
for (String cmd : candidates) {
558+
File tmp = null
559+
try {
560+
tmp = File.createTempFile("jstack", ".txt")
561+
// Redirect output to a file to avoid pipe-buffer deadlock — a full thread dump can
562+
// exceed the OS pipe buffer (typically 64 KB) before waitFor returns.
563+
Process p = new ProcessBuilder(cmd, String.valueOf(pid))
564+
.redirectErrorStream(true)
565+
.redirectOutput(tmp)
566+
.start()
567+
if (!p.waitFor(5, SECONDS)) {
568+
p.destroyForcibly()
569+
p.waitFor(2, SECONDS)
570+
continue
571+
}
572+
if (p.exitValue() == 0) {
573+
String output = tmp.getText("UTF-8")
574+
if (output) {
575+
return output
576+
}
577+
}
578+
} catch (Throwable ignored) {
579+
// try next candidate
580+
} finally {
581+
if (tmp != null) {
582+
tmp.delete()
583+
}
584+
}
585+
}
586+
return null
587+
}
588+
390589
private String tailProcessLog(int lines) {
391590
try {
392591
def logFile = new File(logFilePath)

0 commit comments

Comments
 (0)