diff --git a/.gitlab-ci.yml b/.gitlab-ci.yml index 411ab5a3f30..d5345792c04 100644 --- a/.gitlab-ci.yml +++ b/.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' diff --git a/build-logic/testcontainers/src/main/kotlin/datadog/buildlogic/testcontainers/ContainerImageArguments.kt b/build-logic/testcontainers/src/main/kotlin/datadog/buildlogic/testcontainers/ContainerImageArguments.kt index 44351ad7003..b0ef602c9cb 100644 --- a/build-logic/testcontainers/src/main/kotlin/datadog/buildlogic/testcontainers/ContainerImageArguments.kt +++ b/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, + // A diagnostic output location must not make cached tests machine-specific. + @get:Internal val imageLogDirectory: File? = null, ) : CommandLineArgumentProvider { override fun asArguments(): Iterable = containers.orNull ?.images ?.map { (name, image) -> "-D$name=$image" } - .orEmpty() + .orEmpty() + listOfNotNull(imageLogDirectory?.let { "-Dtestcontainers.image.log.dir=${it.absolutePath}" }) } class ContainerImageInputs( diff --git a/build-logic/testcontainers/src/main/kotlin/datadog/buildlogic/testcontainers/TestcontainersPlugin.kt b/build-logic/testcontainers/src/main/kotlin/datadog/buildlogic/testcontainers/TestcontainersPlugin.kt index 36099333799..d208bde24c6 100644 --- a/build-logic/testcontainers/src/main/kotlin/datadog/buildlogic/testcontainers/TestcontainersPlugin.kt +++ b/build-logic/testcontainers/src/main/kotlin/datadog/buildlogic/testcontainers/TestcontainersPlugin.kt @@ -104,7 +104,12 @@ class TestcontainersPlugin : Plugin { } } - jvmArgumentProviders.add(ContainerImageArguments(containers)) + jvmArgumentProviders.add( + ContainerImageArguments( + containers, + project.layout.buildDirectory.dir("reports/docker-images/$name").get().asFile, + ), + ) } } } diff --git a/build-logic/testcontainers/src/test/kotlin/datadog/buildlogic/testcontainers/TestcontainersPluginTest.kt b/build-logic/testcontainers/src/test/kotlin/datadog/buildlogic/testcontainers/TestcontainersPluginTest.kt index 28c79cc62db..d3ae32da488 100644 --- a/build-logic/testcontainers/src/test/kotlin/datadog/buildlogic/testcontainers/TestcontainersPluginTest.kt +++ b/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", "")); } diff --git a/dd-java-agent/instrumentation-testing/src/main/groovy/datadog/trace/agent/test/InstrumentationSpecification.groovy b/dd-java-agent/instrumentation-testing/src/main/groovy/datadog/trace/agent/test/InstrumentationSpecification.groovy index 9bf610c45fd..0c21f0e983a 100644 --- a/dd-java-agent/instrumentation-testing/src/main/groovy/datadog/trace/agent/test/InstrumentationSpecification.groovy +++ b/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., 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() } diff --git a/docs/how_to_test.md b/docs/how_to_test.md index 61d5d32291a..8499808d4cf 100644 --- a/docs/how_to_test.md +++ b/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.` 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//image-pulls-.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. diff --git a/utils/test-utils/build.gradle.kts b/utils/test-utils/build.gradle.kts index bb2a07b6da7..d46a0387b5e 100644 --- a/utils/test-utils/build.gradle.kts +++ b/utils/test-utils/build.gradle.kts @@ -46,4 +46,5 @@ dependencies { compileOnly(libs.bundles.spock) testImplementation(libs.junit.platform.launcher) + testImplementation(libs.logback.classic) } diff --git a/utils/test-utils/src/main/java/datadog/trace/test/logging/TestcontainersImageLogging.java b/utils/test-utils/src/main/java/datadog/trace/test/logging/TestcontainersImageLogging.java new file mode 100644 index 00000000000..e63e5a962eb --- /dev/null +++ b/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 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() { + @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 { + private final FileAppender delegate; + private String lastRecordedTest; + + private LazyImageAppender(FileAppender 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:")); + } +} diff --git a/utils/test-utils/src/test/java/datadog/trace/test/logging/TestcontainersImageLoggingTest.java b/utils/test-utils/src/test/java/datadog/trace/test/logging/TestcontainersImageLoggingTest.java new file mode 100644 index 00000000000..1bfb86b84d0 --- /dev/null +++ b/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 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 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 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); + } + } + } +}