Add more verbose logging during the build (#208)

baronfel · web-flow · commit aec1f0266be9 · 2022-10-19T18:00:58.000-05:00
pervasive logging

Better initial log
diff --git a/Microsoft.NET.Build.Containers/ContainerBuilder.cs b/Microsoft.NET.Build.Containers/ContainerBuilder.cs
@@ -72,7 +72,7 @@ public static async Task Containerize(DirectoryInfo folder, string workingDir, s
             {
                 try
                 {
-                    outputReg?.Push(img, imageName, tag, imageName).Wait();
+                    outputReg?.Push(img, imageName, tag, imageName, (message) => Console.WriteLine($"Containerize: {message}")).Wait();
                     Console.WriteLine($"Containerize: Pushed container '{imageName}:{tag}' to registry '{outputRegistry}'");
                 }
                 catch (Exception e)
diff --git a/Microsoft.NET.Build.Containers/CreateNewImage.cs b/Microsoft.NET.Build.Containers/CreateNewImage.cs
@@ -193,6 +193,10 @@ private Image GetBaseImage() {
         }
     }
 
+    private void SafeLog(string message, params object[] formatParams) {
+        if(BuildEngine != null) Log.LogMessage(MessageImportance.High, message, formatParams);
+    }
+
     public override bool Execute()
     {
         if (!Directory.Exists(PublishDirectory))
@@ -203,10 +207,7 @@ public override bool Execute()
 
         var image = GetBaseImage();
 
-        if (BuildEngine != null)
-        {
-            Log.LogMessage($"Loading from directory: {PublishDirectory}");
-        }
+        SafeLog("Building image '{0}' with tags {1} on top of base image {2}/{3}:{4}", ImageName, String.Join(",", ImageTags), BaseRegistry, BaseImageName, BaseImageTag);
 
         Layer newLayer = Layer.FromDirectory(PublishDirectory, WorkingDirectory);
         image.AddLayer(newLayer);
@@ -240,10 +241,7 @@ public override bool Execute()
                 try
                 {
                     LocalDocker.Load(image, ImageName, tag, BaseImageName).Wait();
-                    if (BuildEngine != null)
-                    {
-                        Log.LogMessage(MessageImportance.High, "Pushed container '{0}:{1}' to Docker daemon", ImageName, tag);
-                    }
+                    SafeLog("Pushed container '{0}:{1}' to Docker daemon", ImageName, tag);
                 }
                 catch (AggregateException ex) when (ex.InnerException is DockerLoadException dle)
                 {
@@ -254,11 +252,8 @@ public override bool Execute()
             {
                 try
                 {
-                    outputReg?.Push(image, ImageName, tag, BaseImageName).Wait();
-                    if (BuildEngine != null)
-                    {
-                        Log.LogMessage(MessageImportance.High, "Pushed container '{0}:{1}' to registry '{2}'", ImageName, tag, OutputRegistry);
-                    }
+                    outputReg?.Push(image, ImageName, tag, BaseImageName, message => SafeLog(message)).Wait();
+                    SafeLog("Pushed container '{0}:{1}' to registry '{2}'", ImageName, tag, OutputRegistry);
                 }
                 catch (Exception e)
                 {
diff --git a/Microsoft.NET.Build.Containers/ParseContainerProperties.cs b/Microsoft.NET.Build.Containers/ParseContainerProperties.cs
@@ -165,7 +165,7 @@ public override bool Execute()
         {
             if (!ContainerHelpers.NormalizeImageName(ContainerImageName, out string? normalizedImageName))
             {
-                Log.LogMessage(MessageImportance.High, $"{nameof(ContainerImageName)}:'{ContainerImageName}' was not a valid container image name, it was normalized to {normalizedImageName}");
+                Log.LogMessage(MessageImportance.High, $"'{ContainerImageName}' was not a valid container image name, it was normalized to {normalizedImageName}");
                 NewContainerImageName = normalizedImageName ?? "";
             }
             else
diff --git a/Microsoft.NET.Build.Containers/Registry.cs b/Microsoft.NET.Build.Containers/Registry.cs
@@ -89,7 +89,7 @@ public async Task<string> DownloadBlob(string name, Descriptor descriptor)
         return localPath;
     }
 
-    public async Task Push(Layer layer, string name)
+    public async Task Push(Layer layer, string name, Action<string> logProgressMessage)
     {
         string digest = layer.Descriptor.Digest;
 
@@ -169,7 +169,7 @@ private static HttpClient GetClient()
         return client;
     }
 
-    public async Task Push(Image x, string name, string? tag, string baseName)
+    public async Task Push(Image x, string name, string? tag, string baseName, Action<string> logProgressMessage)
     {
         tag ??= "latest";
 
@@ -178,9 +178,10 @@ public async Task Push(Image x, string name, string? tag, string baseName)
         foreach (var descriptor in x.LayerDescriptors)
         {
             string digest = descriptor.Digest;
-
+            logProgressMessage($"Uploading layer {digest} to registry");
             if (await BlobAlreadyUploaded(name, digest, client))
             {
+                logProgressMessage($"Layer {digest} already existed");
                 continue;
             }
 
@@ -194,32 +195,34 @@ public async Task Push(Image x, string name, string? tag, string baseName)
                 if (!x.originatingRegistry.HasValue)
                 {
                     throw new NotImplementedException("Need a good error for 'couldn't download a thing because no link to registry'");
-                    }
+                }
 
                 // Ensure the blob is available locally
                 await x.originatingRegistry.Value.DownloadBlob(x.OriginatingName, descriptor);
-
+                logProgressMessage($"Finished uploading layer {digest} to registry");
                 // Then push it to the destination registry
-                await Push(Layer.FromDescriptor(descriptor), name);
+                await Push(Layer.FromDescriptor(descriptor), name, logProgressMessage);
             }
         }
 
+        logProgressMessage($"Uploading config to registry");
         using (MemoryStream stringStream = new MemoryStream(Encoding.UTF8.GetBytes(x.config.ToJsonString())))
         {
             await UploadBlob(name, x.GetDigest(x.config), stringStream);
+            logProgressMessage($"Uploaded config to registry");
         }
 
+        logProgressMessage($"Uploading manifest to registry");
         HttpContent manifestUploadContent = new StringContent(x.manifest.ToJsonString());
         manifestUploadContent.Headers.ContentType = new MediaTypeHeaderValue(DockerManifestV2);
-
         var putResponse = await client.PutAsync(new Uri(BaseUri, $"/v2/{name}/manifests/{x.GetDigest(x.manifest)}"), manifestUploadContent);
-
         string putresponsestr = await putResponse.Content.ReadAsStringAsync();
-
         putResponse.EnsureSuccessStatusCode();
+        logProgressMessage($"Uploaded manifest to registry");
 
+        logProgressMessage($"Uploading tag to registry");
         var putResponse2 = await client.PutAsync(new Uri(BaseUri, $"/v2/{name}/manifests/{tag}"), manifestUploadContent);
-
         putResponse2.EnsureSuccessStatusCode();
+        logProgressMessage($"Uploaded tag to registry");
     }
 }
diff --git a/Test.Microsoft.NET.Build.Containers.Filesystem/EndToEnd.cs b/Test.Microsoft.NET.Build.Containers.Filesystem/EndToEnd.cs
@@ -41,7 +41,7 @@ public async Task ApiEndToEndWithRegistryPushAndPull()
 
         // Push the image back to the local registry
 
-        await registry.Push(x, NewImageName(), "latest", DockerRegistryManager.BaseImage);
+        await registry.Push(x, NewImageName(), "latest", DockerRegistryManager.BaseImage, Console.WriteLine);
 
         // pull it back locally
 

Original file line number	Diff line number	Diff line change
`@@ -72,7 +72,7 @@ public static async Task Containerize(DirectoryInfo folder, string workingDir, s`
`72`	`72`	`{`
`73`	`73`	`try`
`74`	`74`	`{`
`75`		`- outputReg?.Push(img, imageName, tag, imageName).Wait();`
	`75`	`+ outputReg?.Push(img, imageName, tag, imageName, (message) => Console.WriteLine($"Containerize: {message}")).Wait();`
`76`	`76`	`Console.WriteLine($"Containerize: Pushed container '{imageName}:{tag}' to registry '{outputRegistry}'");`
`77`	`77`	`}`
`78`	`78`	`catch (Exception e)`
Original file line number	Diff line number	Diff line change
`@@ -193,6 +193,10 @@ private Image GetBaseImage() {`
`193`	`193`	`}`
`194`	`194`	`}`
`195`	`195`
	`196`	`+ private void SafeLog(string message, params object[] formatParams) {`
	`197`	`+ if(BuildEngine != null) Log.LogMessage(MessageImportance.High, message, formatParams);`
	`198`	`+ }`
	`199`	`+`
`196`	`200`	`public override bool Execute()`
`197`	`201`	`{`
`198`	`202`	`if (!Directory.Exists(PublishDirectory))`
`@@ -203,10 +207,7 @@ public override bool Execute()`
`203`	`207`
`204`	`208`	`var image = GetBaseImage();`
`205`	`209`
`206`		`- if (BuildEngine != null)`
`207`		`- {`
`208`		`- Log.LogMessage($"Loading from directory: {PublishDirectory}");`
`209`		`- }`
	`210`	`+ SafeLog("Building image '{0}' with tags {1} on top of base image {2}/{3}:{4}", ImageName, String.Join(",", ImageTags), BaseRegistry, BaseImageName, BaseImageTag);`
`210`	`211`
`211`	`212`	`Layer newLayer = Layer.FromDirectory(PublishDirectory, WorkingDirectory);`
`212`	`213`	`image.AddLayer(newLayer);`
`@@ -240,10 +241,7 @@ public override bool Execute()`
`240`	`241`	`try`
`241`	`242`	`{`
`242`	`243`	`LocalDocker.Load(image, ImageName, tag, BaseImageName).Wait();`
`243`		`- if (BuildEngine != null)`
`244`		`- {`
`245`		`- Log.LogMessage(MessageImportance.High, "Pushed container '{0}:{1}' to Docker daemon", ImageName, tag);`
`246`		`- }`
	`244`	`+ SafeLog("Pushed container '{0}:{1}' to Docker daemon", ImageName, tag);`
`247`	`245`	`}`
`248`	`246`	`catch (AggregateException ex) when (ex.InnerException is DockerLoadException dle)`
`249`	`247`	`{`
`@@ -254,11 +252,8 @@ public override bool Execute()`
`254`	`252`	`{`
`255`	`253`	`try`
`256`	`254`	`{`
`257`		`- outputReg?.Push(image, ImageName, tag, BaseImageName).Wait();`
`258`		`- if (BuildEngine != null)`
`259`		`- {`
`260`		`- Log.LogMessage(MessageImportance.High, "Pushed container '{0}:{1}' to registry '{2}'", ImageName, tag, OutputRegistry);`
`261`		`- }`
	`255`	`+ outputReg?.Push(image, ImageName, tag, BaseImageName, message => SafeLog(message)).Wait();`
	`256`	`+ SafeLog("Pushed container '{0}:{1}' to registry '{2}'", ImageName, tag, OutputRegistry);`
`262`	`257`	`}`
`263`	`258`	`catch (Exception e)`
`264`	`259`	`{`
Original file line number	Diff line number	Diff line change
`@@ -165,7 +165,7 @@ public override bool Execute()`
`165`	`165`	`{`
`166`	`166`	`if (!ContainerHelpers.NormalizeImageName(ContainerImageName, out string? normalizedImageName))`
`167`	`167`	`{`
`168`		`- Log.LogMessage(MessageImportance.High, $"{nameof(ContainerImageName)}:'{ContainerImageName}' was not a valid container image name, it was normalized to {normalizedImageName}");`
	`168`	`+ Log.LogMessage(MessageImportance.High, $"'{ContainerImageName}' was not a valid container image name, it was normalized to {normalizedImageName}");`
`169`	`169`	`NewContainerImageName = normalizedImageName ?? "";`
`170`	`170`	`}`
`171`	`171`	`else`
Original file line number	Diff line number	Diff line change
`@@ -89,7 +89,7 @@ public async Task<string> DownloadBlob(string name, Descriptor descriptor)`
`89`	`89`	`return localPath;`
`90`	`90`	`}`
`91`	`91`
`92`		`- public async Task Push(Layer layer, string name)`
	`92`	`+ public async Task Push(Layer layer, string name, Action<string> logProgressMessage)`
`93`	`93`	`{`
`94`	`94`	`string digest = layer.Descriptor.Digest;`
`95`	`95`
`@@ -169,7 +169,7 @@ private static HttpClient GetClient()`
`169`	`169`	`return client;`
`170`	`170`	`}`
`171`	`171`
`172`		`- public async Task Push(Image x, string name, string? tag, string baseName)`
	`172`	`+ public async Task Push(Image x, string name, string? tag, string baseName, Action<string> logProgressMessage)`
`173`	`173`	`{`
`174`	`174`	`tag ??= "latest";`
`175`	`175`
`@@ -178,9 +178,10 @@ public async Task Push(Image x, string name, string? tag, string baseName)`
`178`	`178`	`foreach (var descriptor in x.LayerDescriptors)`
`179`	`179`	`{`
`180`	`180`	`string digest = descriptor.Digest;`
`181`		`-`
	`181`	`+ logProgressMessage($"Uploading layer {digest} to registry");`
`182`	`182`	`if (await BlobAlreadyUploaded(name, digest, client))`
`183`	`183`	`{`
	`184`	`+ logProgressMessage($"Layer {digest} already existed");`
`184`	`185`	`continue;`
`185`	`186`	`}`
`186`	`187`
`@@ -194,32 +195,34 @@ public async Task Push(Image x, string name, string? tag, string baseName)`
`194`	`195`	`if (!x.originatingRegistry.HasValue)`
`195`	`196`	`{`
`196`	`197`	`throw new NotImplementedException("Need a good error for 'couldn't download a thing because no link to registry'");`
`197`		`- }`
	`198`	`+ }`
`198`	`199`
`199`	`200`	`// Ensure the blob is available locally`
`200`	`201`	`await x.originatingRegistry.Value.DownloadBlob(x.OriginatingName, descriptor);`
`201`		`-`
	`202`	`+ logProgressMessage($"Finished uploading layer {digest} to registry");`
`202`	`203`	`// Then push it to the destination registry`
`203`		`- await Push(Layer.FromDescriptor(descriptor), name);`
	`204`	`+ await Push(Layer.FromDescriptor(descriptor), name, logProgressMessage);`
`204`	`205`	`}`
`205`	`206`	`}`
`206`	`207`
	`208`	`+ logProgressMessage($"Uploading config to registry");`
`207`	`209`	`using (MemoryStream stringStream = new MemoryStream(Encoding.UTF8.GetBytes(x.config.ToJsonString())))`
`208`	`210`	`{`
`209`	`211`	`await UploadBlob(name, x.GetDigest(x.config), stringStream);`
	`212`	`+ logProgressMessage($"Uploaded config to registry");`
`210`	`213`	`}`
`211`	`214`
	`215`	`+ logProgressMessage($"Uploading manifest to registry");`
`212`	`216`	`HttpContent manifestUploadContent = new StringContent(x.manifest.ToJsonString());`
`213`	`217`	`manifestUploadContent.Headers.ContentType = new MediaTypeHeaderValue(DockerManifestV2);`
`214`		`-`
`215`	`218`	`var putResponse = await client.PutAsync(new Uri(BaseUri, $"/v2/{name}/manifests/{x.GetDigest(x.manifest)}"), manifestUploadContent);`
`216`		`-`
`217`	`219`	`string putresponsestr = await putResponse.Content.ReadAsStringAsync();`
`218`		`-`
`219`	`220`	`putResponse.EnsureSuccessStatusCode();`
	`221`	`+ logProgressMessage($"Uploaded manifest to registry");`
`220`	`222`
	`223`	`+ logProgressMessage($"Uploading tag to registry");`
`221`	`224`	`var putResponse2 = await client.PutAsync(new Uri(BaseUri, $"/v2/{name}/manifests/{tag}"), manifestUploadContent);`
`222`		`-`
`223`	`225`	`putResponse2.EnsureSuccessStatusCode();`
	`226`	`+ logProgressMessage($"Uploaded tag to registry");`
`224`	`227`	`}`
`225`	`228`	`}`