Capture Testcontainers image pull diagnostics

.gitlab-ci.yml

@@ -821,6 +821,7 @@ muzzle-dep-report:
     paths:
       - ./reports.tar
       - ./profiles.tar
+      - 'workspace/**/build/reports/docker-images/'
       - ./results
       - './test_counts_*.json'
       - '.gradle/daemon/*/*.out.log'

build-logic/testcontainers/src/main/kotlin/datadog/buildlogic/testcontainers/ContainerImageArguments.kt

@@ -11,12 +11,14 @@ import java.io.File
 
 class ContainerImageArguments(
   @get:Nested @get:Optional val containers: Provider<ContainerImageInputs>,
+  // A diagnostic output location must not make cached tests machine-specific.
+  @get:Internal val imageLogDirectory: File? = null,
 ) : CommandLineArgumentProvider {
   override fun asArguments(): Iterable<String> =
     containers.orNull
       ?.images
       ?.map { (name, image) -> "-D$name=$image" }
-      .orEmpty()
+      .orEmpty() + listOfNotNull(imageLogDirectory?.let { "-Dtestcontainers.image.log.dir=${it.absolutePath}" })
 }
 
 class ContainerImageInputs(

build-logic/testcontainers/src/main/kotlin/datadog/buildlogic/testcontainers/TestcontainersPlugin.kt

@@ -104,7 +104,12 @@ class TestcontainersPlugin : Plugin<Project> {
             }
           }
 
-        jvmArgumentProviders.add(ContainerImageArguments(containers))
+        jvmArgumentProviders.add(
+          ContainerImageArguments(
+            containers,
+            project.layout.buildDirectory.dir("reports/docker-images/$name").get().asFile,
+          ),
+        )
       }
     }
   }

build-logic/testcontainers/src/test/kotlin/datadog/buildlogic/testcontainers/TestcontainersPluginTest.kt

@@ -319,6 +319,10 @@ class TestcontainersPluginTest {
       .content()
       .contains("registry-1.docker.io/library/$image")
 
+    assertThat(testReport()).content().contains(directory.resolve("build/reports/docker-images/test").toString())
+    assertThat(testReport("integrationTest")).content()
+      .contains(directory.resolve("build/reports/docker-images/integrationTest").toString())
+
     val reused = run("test", "integrationTest")
 
     assertThat(reused.output).contains("Reusing configuration cache")
@@ -450,6 +454,7 @@ class TestcontainersPluginTest {
         @Test public void imageIsPinned() {
           String image = System.getProperty("test.cassandra.image");
           assertTrue(image.matches(".+@sha256:[a-f0-9]{64}"), image);
+          System.out.println(System.getProperty("testcontainers.image.log.dir"));
           System.out.println(image);
           System.out.println(System.getProperty("test.redis.image", ""));
         }

dd-java-agent/instrumentation-testing/src/main/groovy/datadog/trace/agent/test/InstrumentationSpecification.groovy

@@ -90,6 +90,7 @@ import net.bytebuddy.utility.JavaModule
 import okhttp3.HttpUrl
 import okhttp3.OkHttpClient
 import org.junit.jupiter.api.extension.ExtendWith
+import datadog.trace.test.logging.TestcontainersImageLogging
 import org.slf4j.Logger
 import org.slf4j.LoggerFactory
 import org.spockframework.mock.MockUtil
@@ -297,7 +298,7 @@ abstract class InstrumentationSpecification extends DDSpecification implements A
   }
 
   @SuppressForbidden
-  private static void configureLoggingLevels() {
+  private static void configureLoggingLevels(String imageTestName = null) {
     def logger = LoggerFactory.getLogger(Logger.ROOT_LOGGER_NAME)
 
     // Check logger class by name to avoid NoClassDefFoundError at runtime for tests without Logback.
@@ -318,6 +319,9 @@ abstract class InstrumentationSpecification extends DDSpecification implements A
     rootLogger.setLevel(Level.WARN)
     ((ch.qos.logback.classic.Logger) LoggerFactory.getLogger("datadog")).setLevel(Level.DEBUG)
     ((ch.qos.logback.classic.Logger) LoggerFactory.getLogger("org.testcontainers")).setLevel(Level.DEBUG)
+    // Image pull progress uses tc.<image>, outside org.testcontainers.
+    ((ch.qos.logback.classic.Logger) LoggerFactory.getLogger("tc")).setLevel(Level.INFO)
+    TestcontainersImageLogging.configure(rootLogger.getLoggerContext(), imageTestName)
   }
 
   def codeOriginSetup() {
@@ -466,7 +470,7 @@ abstract class InstrumentationSpecification extends DDSpecification implements A
 
     InstrumentationErrors.resetErrors() // reset for each test
 
-    configureLoggingLevels()
+    configureLoggingLevels(getClass().name + " :: " + specificationContext.currentFeature.name)
 
     assertThreadsEachCleanup = false
 
@@ -562,6 +566,10 @@ abstract class InstrumentationSpecification extends DDSpecification implements A
         throw scopeDiagnosticsFailure
       }
     } finally {
+      // The image logging helper requires Logback, which some test suites intentionally exclude.
+      if (LoggerFactory.getLogger(Logger.ROOT_LOGGER_NAME).class.name == "ch.qos.logback.classic.Logger") {
+        TestcontainersImageLogging.clearTestName()
+      }
       if (scopeDiagnosticsSuiteEnabled()) {
         ScopeDiagnostics.startRecording()
       }

docs/how_to_test.md

@@ -127,6 +127,28 @@ configuration. For example, `integrationTestImplementation` gets
 `integrationTestContainerImage`. Also, see the [plugin reference](../build-logic/testcontainers/README.md)
 for inheritance and shared configuration examples.
 
+### Image pull diagnostics
+
+Instrumentation tests enable Testcontainers' `tc.<image>` logger at INFO so image
+pull starts, layer progress, retries, stalls, completion and elapsed pull time
+appear in captured test output. Cache decisions remain under
+`org.testcontainers.images`.
+
+Instrumentation tests in modules using `dd-trace-java.testcontainers` also save these image events in
+`build/reports/docker-images/<test-task>/image-pulls-<worker-pid>.log`.
+These files use UTC timestamps and survive test retries and logging resets.
+Files are created only when an image event is recorded. A header identifies the
+specification class and feature name; another header marks a change of test.
+Events before per-test setup identify the test context as unavailable.
+GitLab publishes them as individual artifacts as well as inside `reports.tar`.
+The dedicated files exclude container output, Docker command arguments,
+authentication diagnostics and exception bodies.
+
+This records the progress reported to Testcontainers; it does not collect Docker
+daemon logs or prove whether a daemon-side pull continues after a client timeout.
+Use the JUnit failure and test duration alongside the image log to correlate
+failed attempts with later retries.
+
 ## Continuation lifecycle failures
 
 Instrumentation test harnesses always enable strict trace writes; there is no harness opt-out.

utils/test-utils/build.gradle.kts

@@ -46,4 +46,5 @@ dependencies {
   compileOnly(libs.bundles.spock)
 
   testImplementation(libs.junit.platform.launcher)
+  testImplementation(libs.logback.classic)
 }

utils/test-utils/src/main/java/datadog/trace/test/logging/TestcontainersImageLogging.java

@@ -0,0 +1,138 @@
+package datadog.trace.test.logging;
+
+import ch.qos.logback.classic.Level;
+import ch.qos.logback.classic.Logger;
+import ch.qos.logback.classic.LoggerContext;
+import ch.qos.logback.classic.encoder.PatternLayoutEncoder;
+import ch.qos.logback.classic.spi.ILoggingEvent;
+import ch.qos.logback.classic.spi.LoggingEvent;
+import ch.qos.logback.core.AppenderBase;
+import ch.qos.logback.core.FileAppender;
+import ch.qos.logback.core.filter.Filter;
+import ch.qos.logback.core.spi.FilterReply;
+import java.io.File;
+import java.lang.management.ManagementFactory;
+
+/** Preserves image pull progress independently of test output and retries. */
+public final class TestcontainersImageLogging {
+  private static final String APPENDER_NAME = "TESTCONTAINERS_IMAGES";
+  private static final Object CONFIGURATION_LOCK = new Object();
+  private static final String UNKNOWN_TEST =
+      "unavailable (specification initialization or shared setup)";
+  private static volatile String currentTestName = UNKNOWN_TEST;
+
+  private TestcontainersImageLogging() {}
+
+  public static void configure(LoggerContext context) {
+    configure(context, null);
+  }
+
+  public static void configure(LoggerContext context, String testName) {
+    synchronized (CONFIGURATION_LOCK) {
+      currentTestName = testName == null ? UNKNOWN_TEST : testName;
+      configureAppender(context);
+    }
+  }
+
+  public static void clearTestName() {
+    currentTestName = UNKNOWN_TEST;
+  }
+
+  private static void configureAppender(LoggerContext context) {
+    String directory = System.getProperty("testcontainers.image.log.dir");
+    if (directory == null) {
+      return;
+    }
+    Logger imageLogger = context.getLogger("tc");
+    if (imageLogger.getAppender(APPENDER_NAME) != null) {
+      return;
+    }
+
+    PatternLayoutEncoder encoder = new PatternLayoutEncoder();
+    encoder.setContext(context);
+    encoder.setPattern(
+        "%date{yyyy-MM-dd'T'HH:mm:ss.SSS, UTC}Z [%thread] %level %logger - %msg%n%nopex");
+    encoder.start();
+
+    FileAppender<ILoggingEvent> appender = new FileAppender<>();
+    appender.setContext(context);
+    appender.setName(APPENDER_NAME);
+    // Separate workers; append when the logging context is reset between specifications.
+    String runtimeName = ManagementFactory.getRuntimeMXBean().getName();
+    int separator = runtimeName.indexOf('@');
+    String processId = separator >= 0 ? runtimeName.substring(0, separator) : runtimeName;
+    appender.setFile(new File(directory, "image-pulls-" + processId + ".log").getPath());
+    appender.setAppend(true);
+    appender.setEncoder(encoder);
+    LazyImageAppender lazyAppender = new LazyImageAppender(appender);
+    lazyAppender.setContext(context);
+    lazyAppender.setName(APPENDER_NAME);
+    lazyAppender.addFilter(
+        new Filter<ILoggingEvent>() {
+          @Override
+          public FilterReply decide(ILoggingEvent event) {
+            return isImageEvent(event) ? FilterReply.NEUTRAL : FilterReply.DENY;
+          }
+        });
+    lazyAppender.start();
+    imageLogger.addAppender(lazyAppender);
+    context.getLogger("org.testcontainers.images").addAppender(lazyAppender);
+  }
+
+  private static final class LazyImageAppender extends AppenderBase<ILoggingEvent> {
+    private final FileAppender<ILoggingEvent> delegate;
+    private String lastRecordedTest;
+
+    private LazyImageAppender(FileAppender<ILoggingEvent> delegate) {
+      this.delegate = delegate;
+    }
+
+    @Override
+    protected void append(ILoggingEvent event) {
+      // AppenderBase serializes accepted events; only the first one opens the file.
+      if (!delegate.isStarted()) {
+        delegate.start();
+      }
+      String currentTest = currentTestName;
+      if (!currentTest.equals(lastRecordedTest)) {
+        delegate.doAppend(
+            new LoggingEvent(
+                TestcontainersImageLogging.class.getName(),
+                ((LoggerContext) getContext()).getLogger("tc"),
+                Level.INFO,
+                "Image event test context: {}",
+                null,
+                new Object[] {currentTest}));
+        lastRecordedTest = currentTest;
+      }
+      delegate.doAppend(event);
+    }
+
+    @Override
+    public synchronized void stop() {
+      delegate.stop();
+      super.stop();
+    }
+  }
+
+  static boolean isImageEvent(ILoggingEvent event) {
+    String logger = event.getLoggerName();
+    String message = event.getMessage();
+    // Exclude container output, Docker commands, authentication diagnostics and exception bodies.
+    if (logger.equals("org.testcontainers.images.AbstractImagePullPolicy")) {
+      return message.startsWith("Using locally available")
+          || message.startsWith("Image ")
+          || message.startsWith("Not available locally")
+          || message.startsWith("Should pull locally available image:");
+    }
+    return logger.startsWith("tc.")
+        && (message.startsWith("Pulling docker image:")
+            || message.equals("Starting to pull image")
+            || message.startsWith("Pulling image layers:")
+            || message.startsWith("Pull complete.")
+            || message.startsWith("Image ") && message.contains("pull took")
+            || message.startsWith("Retrying pull for image:")
+            || message.startsWith("Docker image pull has not made progress")
+            || message.startsWith("Failed to pull image:"));
+  }
+}

utils/test-utils/src/test/java/datadog/trace/test/logging/TestcontainersImageLoggingTest.java

@@ -0,0 +1,101 @@
+package datadog.trace.test.logging;
+
+import static org.junit.jupiter.api.Assertions.assertEquals;
+import static org.junit.jupiter.api.Assertions.assertFalse;
+import static org.junit.jupiter.api.Assertions.assertTrue;
+
+import ch.qos.logback.classic.Level;
+import ch.qos.logback.classic.Logger;
+import ch.qos.logback.classic.LoggerContext;
+import java.nio.charset.StandardCharsets;
+import java.nio.file.Files;
+import java.nio.file.Path;
+import java.util.stream.Stream;
+import org.junit.jupiter.api.Test;
+import org.junit.jupiter.api.io.TempDir;
+
+class TestcontainersImageLoggingTest {
+  @TempDir Path directory;
+
+  @Test
+  void preservesPullProgressAndCacheDecisionsAcrossLoggingResets() throws Exception {
+    String previous = System.getProperty("testcontainers.image.log.dir");
+    LoggerContext context = new LoggerContext();
+    System.setProperty("testcontainers.image.log.dir", directory.toString());
+    try {
+      TestcontainersImageLogging.configure(context, "JdbcTest :: first test");
+      TestcontainersImageLogging.configure(context, "JdbcTest :: first test");
+      Logger image = context.getLogger("tc.registry.example/image@sha256:digest");
+      image.setLevel(Level.INFO);
+      image.info("Container output: CONTAINER_SENTINEL");
+      TestcontainersImageLogging.clearTestName();
+      try (Stream<Path> logs = Files.list(directory)) {
+        assertEquals(0, logs.count(), "Setup and rejected events must not create log files");
+      }
+      context.reset();
+      TestcontainersImageLogging.configure(context, "JdbcTest :: first test");
+      image.setLevel(Level.INFO);
+      try (Stream<Path> logs = Files.list(directory)) {
+        assertEquals(0, logs.count(), "Resetting an unused appender must not create log files");
+      }
+      image.info("Pulling docker image: {}", "registry.example/image@sha256:digest");
+      image.info("Starting to pull image");
+      TestcontainersImageLogging.configure(context, "JdbcTest :: second test");
+      image.info("Starting to pull image");
+      image.info(
+          "Pulling image layers: {} pending, {} downloaded, {} extracted, ({}/{})",
+          1,
+          2,
+          0,
+          "10 MB",
+          "? MB");
+      image.warn("Retrying pull for image: {} ({}s remaining)", "image", 60);
+      image.error("Docker image pull has not made progress in {}s - aborting pull", 60);
+      image.error("Failed to pull image: {}", "image", new RuntimeException("EXCEPTION_SENTINEL"));
+      image.info("Container output: CONTAINER_SENTINEL");
+      context.getLogger("org.testcontainers.shaded.com.github.dockerjava").warn("COMMAND_SENTINEL");
+
+      context.reset();
+      TestcontainersImageLogging.configure(context);
+      image.setLevel(Level.INFO);
+      image.info(
+          "Pull complete. {} layers, pulled in {}s (downloaded {} at {}/s)", 3, 8, "10 MB", "1 MB");
+      image.info("Image {} pull took {}", "image", "PT8S");
+      Logger policy = context.getLogger("org.testcontainers.images.AbstractImagePullPolicy");
+      policy.setLevel(Level.DEBUG);
+      policy.debug("Using locally available and not pulling image: {}", "image");
+      context.stop();
+
+      Path log;
+      try (Stream<Path> logs = Files.list(directory)) {
+        Path[] paths = logs.toArray(Path[]::new);
+        assertEquals(1, paths.length);
+        log = paths[0];
+      }
+      String text = new String(Files.readAllBytes(log), StandardCharsets.UTF_8);
+      assertEquals(2, text.split("Starting to pull image", -1).length - 1);
+      assertTrue(text.indexOf("JdbcTest :: first test") < text.indexOf("Pulling docker image:"));
+      assertTrue(text.contains("Image event test context: JdbcTest :: second test"));
+      assertTrue(text.contains("Image event test context: unavailable"));
+      assertEquals(1, text.split("JdbcTest :: first test", -1).length - 1);
+      assertTrue(text.contains("1 pending, 2 downloaded"));
+      assertTrue(text.contains("Retrying pull for image"));
+      assertTrue(text.contains("has not made progress"));
+      assertTrue(text.contains("Failed to pull image"));
+      assertTrue(text.contains("pull took PT8S"));
+      assertTrue(text.contains("Using locally available"));
+      assertTrue(text.matches("(?s).*\\d{4}-\\d{2}-\\d{2}T\\d{2}:\\d{2}:\\d{2}\\.\\d{3}Z.*"));
+      assertFalse(text.contains("EXCEPTION_SENTINEL"));
+      assertFalse(text.contains("CONTAINER_SENTINEL"));
+      assertFalse(text.contains("COMMAND_SENTINEL"));
+    } finally {
+      TestcontainersImageLogging.clearTestName();
+      context.stop();
+      if (previous == null) {
+        System.clearProperty("testcontainers.image.log.dir");
+      } else {
+        System.setProperty("testcontainers.image.log.dir", previous);
+      }
+    }
+  }
+}