chore: Add diagnostics for intermittent CI image pull failures

Author: HofmeisterAn

.github/workflows/cicd.yml

@@ -66,6 +66,9 @@ jobs:
     env:
       # Lowest API version that GitHub runners support.
       DOCKER_API_VERSION: 1.44
+      # Enable debug-level logging to capture image pull diagnostics while we
+      # investigate the intermittent registry pull failures in CI.
+      TESTCONTAINERS_LOGGING_ENABLED: true
 
     steps:
       - name: Checkout Repository

src/Testcontainers/Clients/DockerImageOperations.cs

@@ -2,6 +2,8 @@ namespace DotNet.Testcontainers.Clients
 {
   using System;
   using System.Collections.Generic;
+  using System.Diagnostics;
+  using System.Globalization;
   using System.IO;
   using System.Linq;
   using System.Threading;
@@ -14,6 +16,12 @@ namespace DotNet.Testcontainers.Clients
 
   internal sealed class DockerImageOperations : DockerApiClient, IDockerImageOperations
   {
+    // Diagnostic counter shared across all instances to surface how many image pulls
+    // are running concurrently in the same process. This helps determine whether the
+    // intermittent CI pull failures correlate with bursts of parallel pulls (a race),
+    // as opposed to isolated registry timeouts.
+    private static int _pullsInFlight;
+
     public DockerImageOperations(Guid sessionId, IDockerEndpointAuthenticationConfiguration dockerEndpointAuthConfig, ILogger logger)
       : base(sessionId, dockerEndpointAuthConfig, logger)
     {
@@ -70,8 +78,48 @@ public async Task CreateAsync(IImage image, IDockerRegistryAuthenticationConfigu
         IdentityToken = dockerRegistryAuthConfig.IdentityToken,
       };
 
-      await DockerClient.Images.CreateImageAsync(createParameters, authConfig, traceProgress, ct)
-        .ConfigureAwait(false);
+      var inFlightAtStart = Interlocked.Increment(ref _pullsInFlight);
+      var stopwatch = Stopwatch.StartNew();
+
+      Logger.PullingDockerImage(image, dockerRegistryAuthConfig.RegistryEndpoint, inFlightAtStart);
+
+      try
+      {
+        await DockerClient.Images.CreateImageAsync(createParameters, authConfig, traceProgress, ct)
+          .ConfigureAwait(false);
+      }
+      catch (Exception e)
+      {
+        stopwatch.Stop();
+        var inFlightAtFailure = Volatile.Read(ref _pullsInFlight);
+        var statusCode = e is DockerApiException dockerApiException ? dockerApiException.StatusCode.ToString() : e.GetType().Name;
+        var responseBody = e is DockerApiException apiException ? apiException.ResponseBody : e.Message;
+        var traceErrors = string.Join(" | ", traceProgress.Errors.Select(error => error.Message));
+        Logger.FailedToPullDockerImage(image, dockerRegistryAuthConfig.RegistryEndpoint, stopwatch.ElapsedMilliseconds, inFlightAtStart, inFlightAtFailure, statusCode, responseBody, traceErrors, e);
+
+        // The diagnostics above are logged through the resource logger. In CI the tests run
+        // under VSTest, which discards xUnit diagnostic messages, so the only output that
+        // reliably reaches the CI logs is a failed test's exception. Re-throw with the
+        // diagnostic context embedded in the message (keeping the original as the inner
+        // exception) so the intermittent image pull failures can be investigated from CI.
+        var diagnostics = string.Format(
+          CultureInfo.InvariantCulture,
+          "Failed to pull Docker image {0} from registry {1} after {2} ms (concurrent pulls at start: {3}, at failure: {4}); Docker API status: {5}; response: {6}; pull progress errors: {7}",
+          image.FullName,
+          dockerRegistryAuthConfig.RegistryEndpoint ?? "(default)",
+          stopwatch.ElapsedMilliseconds,
+          inFlightAtStart,
+          inFlightAtFailure,
+          statusCode,
+          responseBody,
+          string.IsNullOrEmpty(traceErrors) ? "(none)" : traceErrors);
+
+        throw new InvalidOperationException(diagnostics, e);
+      }
+      finally
+      {
+        Interlocked.Decrement(ref _pullsInFlight);
+      }
 
       Logger.DockerImageCreated(image);
     }

src/Testcontainers/Logger.cs

@@ -66,6 +66,12 @@ static ConsoleLogger()
 
     private ConsoleLogger()
     {
+      // Allow enabling debug-level logging through an environment variable. This is
+      // primarily useful in CI, where the default console logger is the only sink and
+      // debug messages (image pull progress, diagnostics) would otherwise be hidden.
+      var loggingEnabled = Environment.GetEnvironmentVariable("TESTCONTAINERS_LOGGING_ENABLED");
+      DebugLogLevelEnabled = "1".Equals(loggingEnabled, StringComparison.OrdinalIgnoreCase)
+        || "true".Equals(loggingEnabled, StringComparison.OrdinalIgnoreCase);
     }
 
     /// <summary>

src/Testcontainers/Logging.cs

@@ -66,6 +66,12 @@ internal static partial class Logging
     [LoggerMessage(Level = LogLevel.Information, Message = "Execute \"{Command}\" at Docker container {Id}")]
     private static partial void ExecuteCommandInDockerContainerCore(ILogger logger, string command, TruncatedId id);
 
+    [LoggerMessage(Level = LogLevel.Debug, Message = "Pulling Docker image {FullName} from registry {Registry} (concurrent pulls in this process: {InFlight})")]
+    private static partial void PullingDockerImageCore(ILogger logger, string fullName, string registry, int inFlight);
+
+    [LoggerMessage(Level = LogLevel.Error, Message = "Failed to pull Docker image {FullName} from registry {Registry} after {ElapsedMilliseconds} ms (concurrent pulls at start: {InFlightAtStart}, at failure: {InFlightAtFailure}); Docker API status: {StatusCode}; response: {ResponseBody}; pull progress errors: {TraceErrors}")]
+    private static partial void FailedToPullDockerImageCore(ILogger logger, string fullName, string registry, long elapsedMilliseconds, int inFlightAtStart, int inFlightAtFailure, string statusCode, string responseBody, string traceErrors, Exception exception);
+
     [LoggerMessage(Level = LogLevel.Information, Message = "Docker image {FullName} created")]
     private static partial void DockerImageCreatedCore(ILogger logger, string fullName);
 
@@ -209,6 +215,16 @@ public static void ExecuteCommandInDockerContainer(this ILogger logger, string i
       ExecuteCommandInDockerContainerCore(logger, commandLine, new TruncatedId(id));
     }
 
+    public static void PullingDockerImage(this ILogger logger, IImage image, string registry, int inFlight)
+    {
+      PullingDockerImageCore(logger, image.FullName, registry ?? "(default)", inFlight);
+    }
+
+    public static void FailedToPullDockerImage(this ILogger logger, IImage image, string registry, long elapsedMilliseconds, int inFlightAtStart, int inFlightAtFailure, string statusCode, string responseBody, string traceErrors, Exception exception)
+    {
+      FailedToPullDockerImageCore(logger, image.FullName, registry ?? "(default)", elapsedMilliseconds, inFlightAtStart, inFlightAtFailure, statusCode, responseBody, string.IsNullOrEmpty(traceErrors) ? "(none)" : traceErrors, exception);
+    }
+
     public static void DockerImageCreated(this ILogger logger, IImage image)
     {
       DockerImageCreatedCore(logger, image.FullName);

tests/Directory.Build.props

@@ -9,4 +9,11 @@
   <PropertyGroup>
     <VSTestLogger>trx%3BLogFileName=$(MSBuildProjectName).trx</VSTestLogger>
   </PropertyGroup>
+  <ItemGroup>
+    <!-- The Testcontainers xUnit fixtures route their diagnostics (including the image
+         pull diagnostics) to xUnit's IMessageSink as diagnostic messages, which xUnit
+         suppresses by default. Enable diagnostic and live output so these messages show
+         up in the CI logs while we investigate the intermittent image pull failures. -->
+    <Content Include="$(MSBuildThisFileDirectory)xunit.runner.json" Link="xunit.runner.json" CopyToOutputDirectory="PreserveNewest"/>
+  </ItemGroup>
 </Project>

tests/xunit.runner.json

@@ -0,0 +1,5 @@
+{
+  "$schema": "https://xunit.net/schema/current/xunit.runner.schema.json",
+  "diagnosticMessages": true,
+  "showLiveOutput": true
+}