Improve CopyBaseImages and HttpClient logging (#2071)

The `CopyBaseImages` job failed in build#2946397 with a timeout error.
Don't really know why. This PR improves logging in `CopyBaseImages`, the
HTTP `LoggingHandler`, and `OrasService.GetReferrersAsync` in an attempt
to figure out why.

Changes in this PR:
- **Fix OrasDotnetService auth cache concurrency bug**: Share a single
`Cache` instance across concurrent `GetReferrersAsync` calls instead of
creating one per call, prevents `InvalidOperationException` from
concurrent `Dictionary` mutations (I hit this locally).
- **Imporve HTTP logging**: `LoggingHandler` is now a
`DelegatingHandler` instead of a `MessageProcessingHandler` which allows
it to capture and log elapsed time and transport errors (including
timeouts).
- **Change HTTP logging to Debug level** and also set the default log
level to Debug.
- **Fix destination image name formatting** in CopyBaseImages logging.
- CopyBaseImages now does more things in dry-run mode.
- **Add `isDryRun` to `IOrasService.GetReferrersAsync`**: Skips registry
calls in dry-run mode to avoid rate limiting on unauthenticated
registries.
- **Consolidate import logging**: Single log message per image showing
destination, referrer count, source, and dry-run status

Author: lbussell

src/ImageBuilder.Tests/CopyImageServiceTests.cs

@@ -29,10 +29,15 @@ public class CopyImageServiceTests
     public async Task ImportImageAsync_DryRun_DoesNotRequirePublishConfiguration()
     {
         var emptyConfig = new PublishConfiguration();
+        var mockOras = new Mock<IOrasService>();
+        mockOras
+            .Setup(o => o.GetReferrersAsync(It.IsAny<string>(), true, It.IsAny<CancellationToken>()))
+            .ReturnsAsync([]);
+
         var service = new CopyImageService(
             Mock.Of<ILogger<CopyImageService>>(),
             Mock.Of<IAcrImageImporter>(),
-            Mock.Of<IOrasService>(),
+            mockOras.Object,
             ConfigurationHelper.CreateOptionsMock(emptyConfig));
 
         await Should.NotThrowAsync(() =>
@@ -75,7 +80,7 @@ public async Task ImportImageAsync_ExternalSourceRegistry_DoesNotRequireSourceRe
         var mockImporter = new Mock<IAcrImageImporter>();
         var mockOras = new Mock<IOrasService>();
         mockOras
-            .Setup(o => o.GetReferrersAsync(It.IsAny<string>(), It.IsAny<CancellationToken>()))
+            .Setup(o => o.GetReferrersAsync(It.IsAny<string>(), It.IsAny<bool>(), It.IsAny<CancellationToken>()))
             .ReturnsAsync(Array.Empty<ReferrerInfo>());
 
         var service = new CopyImageService(
@@ -114,7 +119,7 @@ public async Task ImportImageAsync_CopiesReferrersAlongWithSourceImage()
         var mockImporter = new Mock<IAcrImageImporter>();
         var mockOras = new Mock<IOrasService>();
         mockOras
-            .Setup(o => o.GetReferrersAsync("myacr.azurecr.io/repo:tag", It.IsAny<CancellationToken>()))
+            .Setup(o => o.GetReferrersAsync("myacr.azurecr.io/repo:tag", It.IsAny<bool>(), It.IsAny<CancellationToken>()))
             .ReturnsAsync(new List<ReferrerInfo>
             {
                 new("myacr.azurecr.io/repo@sha256:ref1", "application/vnd.cncf.notary.signature"),
@@ -184,7 +189,7 @@ public async Task ImportImageAsync_NoReferrers_ImportsOnlySourceImage()
         var mockImporter = new Mock<IAcrImageImporter>();
         var mockOras = new Mock<IOrasService>();
         mockOras
-            .Setup(o => o.GetReferrersAsync(It.IsAny<string>(), It.IsAny<CancellationToken>()))
+            .Setup(o => o.GetReferrersAsync(It.IsAny<string>(), It.IsAny<bool>(), It.IsAny<CancellationToken>()))
             .ReturnsAsync(Array.Empty<ReferrerInfo>());
 
         var service = new CopyImageService(
@@ -209,17 +214,23 @@ await service.ImportImageAsync(
     }
 
     /// <summary>
-    /// In dry-run mode, referrer discovery should be skipped entirely since it
-    /// requires registry connectivity.
+    /// In dry-run mode, referrer discovery and ACR imports are both skipped.
+    /// The ORAS service receives the dry-run flag and returns an empty list
+    /// to avoid rate limiting on unauthenticated registries.
     /// </summary>
     [Fact]
-    public async Task ImportImageAsync_DryRun_SkipsReferrerDiscovery()
+    public async Task ImportImageAsync_DryRun_SkipsReferrerDiscoveryAndImport()
     {
         var mockOras = new Mock<IOrasService>();
+        mockOras
+            .Setup(o => o.GetReferrersAsync(It.IsAny<string>(), true, It.IsAny<CancellationToken>()))
+            .ReturnsAsync([]);
+
+        var mockImporter = new Mock<IAcrImageImporter>();
 
         var service = new CopyImageService(
             Mock.Of<ILogger<CopyImageService>>(),
-            Mock.Of<IAcrImageImporter>(),
+            mockImporter.Object,
             mockOras.Object,
             ConfigurationHelper.CreateOptionsMock(new PublishConfiguration()));
 
@@ -231,7 +242,14 @@ await service.ImportImageAsync(
             isDryRun: true);
 
         mockOras.Verify(
-            o => o.GetReferrersAsync(It.IsAny<string>(), It.IsAny<CancellationToken>()),
+            o => o.GetReferrersAsync(It.IsAny<string>(), true, It.IsAny<CancellationToken>()),
+            Times.Once);
+
+        mockImporter.Verify(
+            o => o.ImportImageAsync(
+                It.IsAny<string>(),
+                It.IsAny<ResourceIdentifier>(),
+                It.IsAny<ContainerRegistryImportImageContent>()),
             Times.Never);
     }
 

src/ImageBuilder.Tests/Signing/ImageSigningServiceTests.cs

@@ -218,7 +218,7 @@ public async Task SignImagesAsync_WritesCorrectPayloadToDisk()
             });
         mockOras
             .Setup(s => s.GetReferrersAsync(
-                It.IsAny<string>(), It.IsAny<CancellationToken>()))
+                It.IsAny<string>(), It.IsAny<bool>(), It.IsAny<CancellationToken>()))
             .ReturnsAsync(new List<ReferrerInfo>());
 
         var fileSystem = new InMemoryFileSystem();
@@ -306,7 +306,7 @@ private static Mock<IOrasService> CreateMockOrasService()
                 $"sha256:sig-{p.ImageName}");
         mock
             .Setup(s => s.GetReferrersAsync(
-                It.IsAny<string>(), It.IsAny<CancellationToken>()))
+                It.IsAny<string>(), It.IsAny<bool>(), It.IsAny<CancellationToken>()))
             .ReturnsAsync(new List<ReferrerInfo>());
         return mock;
     }
@@ -370,7 +370,7 @@ public async Task SignImagesAsync_SkipsAlreadySignedDigests()
         // Both digests already have signature referrers
         mockOras
             .Setup(s => s.GetReferrersAsync(
-                It.IsAny<string>(), It.IsAny<CancellationToken>()))
+                It.IsAny<string>(), It.IsAny<bool>(), It.IsAny<CancellationToken>()))
             .ReturnsAsync(new List<ReferrerInfo>
             {
                 new("registry/repo@sha256:existingsig", "application/vnd.cncf.notary.signature")
@@ -407,10 +407,10 @@ public async Task SignImagesAsync_SkipsAlreadySignedDigests()
 
         // Referrers should be checked for each digest
         mockOras.Verify(
-            s => s.GetReferrersAsync("sha256:abc123", It.IsAny<CancellationToken>()),
+            s => s.GetReferrersAsync("sha256:abc123", It.IsAny<bool>(), It.IsAny<CancellationToken>()),
             Times.Once);
         mockOras.Verify(
-            s => s.GetReferrersAsync("sha256:def456", It.IsAny<CancellationToken>()),
+            s => s.GetReferrersAsync("sha256:def456", It.IsAny<bool>(), It.IsAny<CancellationToken>()),
             Times.Once);
 
         // ESRP should never be called
@@ -429,14 +429,14 @@ public async Task SignImagesAsync_OnlySignsUnsignedDigests()
         // First digest already has a signature, second does not
         mockOras
             .Setup(s => s.GetReferrersAsync(
-                "sha256:already-signed", It.IsAny<CancellationToken>()))
+                "sha256:already-signed", It.IsAny<bool>(), It.IsAny<CancellationToken>()))
             .ReturnsAsync(new List<ReferrerInfo>
             {
                 new("registry/repo@sha256:existingsig", "application/vnd.cncf.notary.signature")
             });
         mockOras
             .Setup(s => s.GetReferrersAsync(
-                "sha256:not-yet-signed", It.IsAny<CancellationToken>()))
+                "sha256:not-yet-signed", It.IsAny<bool>(), It.IsAny<CancellationToken>()))
             .ReturnsAsync(new List<ReferrerInfo>());
 
         var service = CreateService(mockOras, mockEsrp: mockEsrp, fileSystem: fileSystem);
@@ -488,7 +488,7 @@ public async Task SignImagesAsync_IgnoresNonSignatureReferrers()
         // Referrer exists but is NOT a Notary signature (e.g., an SBOM)
         mockOras
             .Setup(s => s.GetReferrersAsync(
-                It.IsAny<string>(), It.IsAny<CancellationToken>()))
+                It.IsAny<string>(), It.IsAny<bool>(), It.IsAny<CancellationToken>()))
             .ReturnsAsync(new List<ReferrerInfo>
             {
                 new("registry/repo@sha256:sbom123", "application/spdx+json")

src/ImageBuilder/CopyImageService.cs

@@ -54,22 +54,27 @@ public async Task ImportImageAsync(
     {
         Acr destAcr = Acr.Parse(destAcrName);
 
-        string action = isDryRun ? "(Dry run) Would have imported" : "Importing";
         string sourceImageName = DockerHelper.GetImageName(srcRegistryName, srcTagName);
-        var destinationImageNames = destTagNames
-            .Select(tag => $"'{DockerHelper.GetImageName(destAcr.Name, tag)}'")
-            .ToList();
+        string destRepo = destTagNames.First().Split(':')[0].Split('@')[0];
+
+        // Discover referrers (signatures, SBOMs, etc.) for the source image.
+        IReadOnlyList<ReferrerInfo> referrers =
+            await _orasService.GetReferrersAsync(reference: sourceImageName, isDryRun: isDryRun);
+
+        var destinationImageNames =
+            destTagNames.Select(tag => $"'{DockerHelper.GetImageName(destAcr.Server, tag)}'").ToList();
         string formattedDestinationImages = string.Join(", ", destinationImageNames);
-        _logger.LogInformation("{Action} {DestinationImages} from '{SourceImage}'",
-            action, formattedDestinationImages, sourceImageName);
+
+        _logger.LogInformation(
+            "Importing {DestinationImages} and {ReferrerCount} referrer(s) from '{SourceImage}' (DryRun={DryRun})",
+            formattedDestinationImages, referrers.Count, sourceImageName, isDryRun);
 
         if (isDryRun)
         {
-            _logger.LogInformation("Importing skipped due to dry run.");
             return;
         }
 
-        var destResourceId = _publishConfig.GetAcrResource(destAcrName);
+        ResourceIdentifier destResourceId = _publishConfig.GetAcrResource(destAcrName);
 
         // Only look up the source resource ID for registries in the publish config (i.e. ACRs).
         // External registries like docker.io use RegistryAddress + Credentials instead.
@@ -80,8 +85,6 @@ public async Task ImportImageAsync(
                 ? _publishConfig.GetAcrResource(srcRegistryName)
                 : null;
 
-        // Azure ACR import only supports one source identifier. Use ResourceId for ACR-to-ACR
-        // imports (same tenant), or RegistryAddress for external registries.
         ContainerRegistryImportSource importSrc = new(srcTagName)
         {
             ResourceId = srcResourceId,
@@ -98,15 +101,8 @@ public async Task ImportImageAsync(
 
         await _acrRegistryImporter.ImportImageAsync(destAcrName, destResourceId, importImageContent);
 
-        // Discover and import all OCI referrers (signatures, SBOMs, etc.) for the source image.
-        string sourceImageReference = DockerHelper.GetImageName(srcRegistryName, srcTagName);
-        IReadOnlyList<ReferrerInfo> referrers = await _orasService.GetReferrersAsync(sourceImageReference);
-
-        string destRepo = destTagNames.First().Split(':')[0].Split('@')[0];
         foreach (ReferrerInfo referrer in referrers)
         {
-            _logger.LogInformation("Importing referrer '{Referrer}' to '{DestAcr}/{DestRepo}'", referrer.Digest, destAcrName, destRepo);
-
             string referrerDigestReference = DockerHelper.TrimRegistry(referrer.Digest, srcRegistryName);
             ContainerRegistryImportSource referrerImportSrc = new(referrerDigestReference)
             {

src/ImageBuilder/HttpClientProvider.cs

@@ -3,8 +3,10 @@
 // See the LICENSE file in the project root for more information.
 
 using System;
+using System.Diagnostics;
 using System.Net.Http;
 using System.Threading;
+using System.Threading.Tasks;
 
 namespace Microsoft.DotNet.ImageBuilder
 {
@@ -30,7 +32,12 @@ public HttpClientProvider(ILoggerFactory loggerFactory)
 
         public RegistryHttpClient GetRegistryClient() => _registryHttpClient.Value;
 
-        private class LoggingHandler : MessageProcessingHandler
+        /// <summary>
+        /// Logs HTTP request/response activity. Successful responses are logged at Debug level.
+        /// Failures (timeouts, cancellations, transport errors) are logged at Warning level
+        /// with elapsed time to aid diagnosis of hanging requests.
+        /// </summary>
+        private class LoggingHandler : DelegatingHandler
         {
             private readonly ILogger<LoggingHandler> _logger;
 
@@ -41,15 +48,31 @@ public LoggingHandler(ILoggerFactory loggerFactory)
                 InnerHandler = new HttpClientHandler();
             }
 
-            protected override HttpRequestMessage ProcessRequest(HttpRequestMessage request, CancellationToken cancellationToken)
+            protected override async Task<HttpResponseMessage> SendAsync(
+                HttpRequestMessage request,
+                CancellationToken cancellationToken)
             {
-                _logger.LogInformation($"Sending HTTP request: {request.RequestUri}");
-                return request;
-            }
+                long startTime = Stopwatch.GetTimestamp();
 
-            protected override HttpResponseMessage ProcessResponse(HttpResponseMessage response, CancellationToken cancellationToken)
-            {
-                return response;
+                try
+                {
+                    HttpResponseMessage response = await base.SendAsync(request, cancellationToken);
+                    _logger.LogDebug("HTTP {StatusCode} {Method} {RequestUri} in {Elapsed}",
+                        (int)response.StatusCode, request.Method, request.RequestUri, Stopwatch.GetElapsedTime(startTime));
+                    return response;
+                }
+                catch (TaskCanceledException ex) when (!cancellationToken.IsCancellationRequested)
+                {
+                    _logger.LogWarning(ex, "HTTP timeout {Method} {RequestUri} after {Elapsed}",
+                        request.Method, request.RequestUri, Stopwatch.GetElapsedTime(startTime));
+                    throw;
+                }
+                catch (HttpRequestException ex)
+                {
+                    _logger.LogWarning(ex, "HTTP failure {Method} {RequestUri} after {Elapsed}",
+                        request.Method, request.RequestUri, Stopwatch.GetElapsedTime(startTime));
+                    throw;
+                }
             }
         }
     }

src/ImageBuilder/ImageBuilder.cs

@@ -11,6 +11,7 @@
 using Microsoft.DotNet.ImageBuilder.Signing;
 using Microsoft.Extensions.DependencyInjection;
 using Microsoft.Extensions.Hosting;
+using Microsoft.Extensions.Logging;
 using ICommand = Microsoft.DotNet.ImageBuilder.Commands.ICommand;
 
 namespace Microsoft.DotNet.ImageBuilder;
@@ -29,6 +30,7 @@ public static class ImageBuilder
             builder.AddBuildConfiguration();
 
             // Logging
+            builder.Logging.SetMinimumLevel(LogLevel.Debug);
             builder.Logging.AddSimpleConsole(options =>
             {
                 options.IncludeScopes = true;

src/ImageBuilder/LifecycleMetadataService.cs

@@ -33,7 +33,8 @@ public LifecycleMetadataService(IOrasService orasService, ILogger<LifecycleMetad
 
         try
         {
-            IReadOnlyList<ReferrerInfo> referrers = await _orasService.GetReferrersAsync(digest, cancellationToken);
+            IReadOnlyList<ReferrerInfo> referrers =
+                await _orasService.GetReferrersAsync(digest, isDryRun: false, cancellationToken);
 
             ReferrerInfo? lifecycleReferrer = referrers.FirstOrDefault(
                 r => r.ArtifactType == OciArtifactType.Lifecycle);

src/ImageBuilder/Oras/IOrasService.cs

@@ -39,13 +39,15 @@ Task<string> PushSignatureAsync(
     /// Returns the OCI referrers for the given image.
     /// </summary>
     /// <param name="reference">Full registry reference (e.g., "registry.io/repo:tag" or "registry.io/repo@sha256:...").</param>
+    /// <param name="isDryRun">When true, skips registry calls and returns an empty list.</param>
     /// <param name="cancellationToken">Cancellation token.</param>
     /// <returns>
     /// A list of <see cref="ReferrerInfo"/> containing the digest reference and artifact type
     /// for every referrer associated with the image.
     /// </returns>
     Task<IReadOnlyList<ReferrerInfo>> GetReferrersAsync(
         string reference,
+        bool isDryRun = false,
         CancellationToken cancellationToken = default);
 
     /// <summary>

src/ImageBuilder/Oras/OrasDotNetService.cs

@@ -43,7 +43,7 @@ public class OrasDotNetService(
     private const string CertificateChainAnnotation = "io.cncf.notary.x509chain.thumbprint#S256";
 
     private readonly IHttpClientProvider _httpClientProvider = httpClientProvider;
-    private readonly IMemoryCache _cache = cache;
+    private readonly Cache _orasCache = new(cache);
     private readonly IFileSystem _fileSystem = fileSystem;
     private readonly ILogger<OrasDotNetService> _logger = logger;
     private readonly OrasCredentialProviderAdapter _credentialProvider = new(credentialsProvider, credentialsHost);
@@ -116,13 +116,24 @@ await Packer.PackManifestAsync(
     /// <inheritdoc/>
     public async Task<IReadOnlyList<ReferrerInfo>> GetReferrersAsync(
         string reference,
+        bool isDryRun = false,
         CancellationToken cancellationToken = default)
     {
         ArgumentException.ThrowIfNullOrWhiteSpace(reference);
+        IReadOnlyList<ReferrerInfo> referrers = isDryRun ? []
+            : await GetReferrersImplAsync(reference, cancellationToken);
 
-        _logger.LogDebug("Fetching referrers for reference: {Reference}", reference);
+        _logger.LogInformation(
+            "{Reference} has {Count} referrer(s) (DryRun={DryRun})",
+            reference, referrers.Count, isDryRun);
 
-        long startTime = Stopwatch.GetTimestamp();
+        return referrers;
+    }
+
+    private async Task<IReadOnlyList<ReferrerInfo>> GetReferrersImplAsync(
+        string reference,
+        CancellationToken cancellationToken)
+    {
         Repository repository = CreateRepository(reference);
         Descriptor subjectDescriptor = await repository.ResolveAsync(reference, cancellationToken);
 
@@ -140,9 +151,6 @@ public async Task<IReadOnlyList<ReferrerInfo>> GetReferrersAsync(
             _logger.LogDebug("Found referrer: {Referrer} (artifactType={ArtifactType})", referrerReference, referrer.ArtifactType);
         }
 
-        TimeSpan elapsed = Stopwatch.GetElapsedTime(startTime);
-        _logger.LogDebug("Found {Count} referrer(s) for {Reference} in {Elapsed}", referrers.Count, reference, elapsed);
-
         return referrers;
     }
 
@@ -196,8 +204,7 @@ private Repository CreateRepository(string reference)
             parsedRef.Registry, parsedRef.Repository, parsedRef.ContentReference);
 
         HttpClient httpClient = _httpClientProvider.GetClient();
-        Cache cache = new(_cache);
-        Client authClient = new(httpClient, _credentialProvider, cache);
+        Client authClient = new(httpClient, _credentialProvider, _orasCache);
 
         RepositoryOptions repositoryOptions = new()
         {