Migrate to Structured Logging with zerolog and Improve Logging for Manifest Purge Logic

.gitignore

@@ -5,4 +5,5 @@
 coverage.txt
 *.test
 *.out
-*.html
+*.html
+acr-bin

cmd/acr/annotate.go

@@ -10,6 +10,7 @@ import (
 
 	"github.com/Azure/acr-cli/cmd/common"
 	"github.com/Azure/acr-cli/internal/api"
+	"github.com/Azure/acr-cli/internal/logger"
 	"github.com/Azure/acr-cli/internal/worker"
 	"github.com/dlclark/regexp2"
 	"github.com/spf13/cobra"
@@ -163,8 +164,17 @@ func annotateTags(ctx context.Context,
 	dryRun bool) (int, error) {
 
 	if !dryRun {
+		log := logger.Get()
+		log.Info().
+			Str("repository", repoName).
+			Msg("Starting tag annotation for repository")
 		fmt.Printf("\nAnnotating tags for repository: %s\n", repoName)
 	} else {
+		log := logger.Get()
+		log.Info().
+			Str("repository", repoName).
+			Bool("dry_run", true).
+			Msg("Dry run: would annotate tags for repository")
 		fmt.Printf("\nTags for this repository would be annotated: %s\n", repoName)
 	}
 
@@ -225,6 +235,11 @@ func getManifestsToAnnotate(ctx context.Context,
 	resultTags, err := acrClient.GetAcrTags(ctx, repoName, "timedesc", lastTag)
 	if err != nil {
 		if resultTags != nil && resultTags.Response.Response != nil && resultTags.StatusCode == http.StatusNotFound {
+			log := logger.Get()
+			log.Warn().
+				Str("repository", repoName).
+				Int("status_code", resultTags.StatusCode).
+				Msg("Repository not found during annotation operation")
 			fmt.Printf("%s repository not found\n", repoName)
 			return nil, "", nil
 		}
@@ -257,6 +272,12 @@ func getManifestsToAnnotate(ctx context.Context,
 					// Only print what would be annotated during a dry-run. Successfully annotated manifests
 					// will be logged after the annotation.
 					if dryRun {
+						log := logger.Get()
+						log.Debug().
+							Str("repository", repoName).
+							Str("tag", *tag.Name).
+							Str("manifest", *tag.Digest).
+							Msg("Tag marked for annotation in dry run")
 						fmt.Printf("%s/%s:%s\n", loginURL, repoName, *tag.Name)
 					}
 					manifestsToAnnotate = append(manifestsToAnnotate, *tag.Digest)
@@ -280,8 +301,17 @@ func annotateUntaggedManifests(ctx context.Context,
 	annotations []string,
 	dryRun bool) (int, error) {
 	if !dryRun {
+		log := logger.Get()
+		log.Info().
+			Str("repository", repoName).
+			Msg("Starting manifest annotation for repository")
 		fmt.Printf("Annotating manifests for repository: %s\n", repoName)
 	} else {
+		log := logger.Get()
+		log.Info().
+			Str("repository", repoName).
+			Bool("dry_run", true).
+			Msg("Dry run: would annotate manifests for repository")
 		fmt.Printf("Manifests for this repository would be annotated: %s\n", repoName)
 	}
 

cmd/acr/manifest.go

@@ -8,6 +8,7 @@ import (
 	"fmt"
 
 	"github.com/Azure/acr-cli/internal/api"
+	"github.com/Azure/acr-cli/internal/logger"
 	"github.com/pkg/errors"
 	"github.com/spf13/cobra"
 )
@@ -83,29 +84,56 @@ func newManifestListCmd(manifestParams *manifestParameters) *cobra.Command {
 
 // listManifests will do the http requests and print the digest of all the manifest in the selected repository.
 func listManifests(ctx context.Context, acrClient api.AcrCLIClientInterface, loginURL string, repoName string) error {
+	log := logger.Get()
+
+	log.Debug().
+		Str("repository", repoName).
+		Msg("Starting manifest listing")
+
 	lastManifestDigest := ""
 	resultManifests, err := acrClient.GetAcrManifests(ctx, repoName, "", lastManifestDigest)
 	if err != nil {
+		log.Error().
+			Err(err).
+			Str("repository", repoName).
+			Msg("Failed to get manifests for listing")
 		return errors.Wrap(err, "failed to list manifests")
 	}
 
 	fmt.Printf("Listing manifests for the %q repository:\n", repoName)
+
+	totalManifests := 0
 	// A for loop is used because the GetAcrManifests method returns by default only 100 manifests and their attributes.
 	for resultManifests != nil && resultManifests.ManifestsAttributes != nil {
 		manifests := *resultManifests.ManifestsAttributes
 		for _, manifest := range manifests {
 			manifestDigest := *manifest.Digest
 			fmt.Printf("%s/%s@%s\n", loginURL, repoName, manifestDigest)
+
+			log.Debug().
+				Str("repository", repoName).
+				Str("manifest", manifestDigest).
+				Msg("Listed manifest")
+			totalManifests++
 		}
 		// Since the GetAcrManifests supports pagination when supplied with the last digest that was returned the last manifest
 		// digest is saved, the manifest array contains at least one element because if it was empty the API would return
 		// a nil pointer instead of a pointer to a length 0 array.
 		lastManifestDigest = *manifests[len(manifests)-1].Digest
 		resultManifests, err = acrClient.GetAcrManifests(ctx, repoName, "", lastManifestDigest)
 		if err != nil {
+			log.Error().
+				Err(err).
+				Str("repository", repoName).
+				Msg("Failed to get next page of manifests")
 			return errors.Wrap(err, "failed to list manifests")
 		}
 	}
+
+	log.Info().
+		Str("repository", repoName).
+		Int("total_manifests", totalManifests).
+		Msg("Completed manifest listing")
 	return nil
 }
 
@@ -140,13 +168,41 @@ func newManifestDeleteCmd(manifestParams *manifestParameters) *cobra.Command {
 
 // deleteManifests receives an array of manifests digest and deletes them using the supplied acrClient.
 func deleteManifests(ctx context.Context, acrClient api.AcrCLIClientInterface, loginURL string, repoName string, args []string) error {
+	log := logger.Get()
+
+	log.Info().
+		Str("repository", repoName).
+		Int("manifest_count", len(args)).
+		Msg("Starting manifest deletion")
+
 	for i := 0; i < len(args); i++ {
 		_, err := acrClient.DeleteManifest(ctx, repoName, args[i])
 		if err != nil {
+			log.Error().
+				Err(err).
+				Str("repository", repoName).
+				Str("manifest", args[i]).
+				Int("position", i+1).
+				Int("total", len(args)).
+				Msg("Failed to delete manifest")
 			// If there is an error (this includes not found and not allowed operations) the deletion of the images is stopped and an error is returned.
 			return errors.Wrap(err, "failed to delete manifests")
 		}
+
 		fmt.Printf("%s/%s@%s\n", loginURL, repoName, args[i])
+
+		log.Info().
+			Str("repository", repoName).
+			Str("manifest", args[i]).
+			Str("ref", fmt.Sprintf("%s/%s@%s", loginURL, repoName, args[i])).
+			Int("position", i+1).
+			Int("total", len(args)).
+			Msg("Successfully deleted manifest")
 	}
+
+	log.Info().
+		Str("repository", repoName).
+		Int("deleted_count", len(args)).
+		Msg("Completed manifest deletion")
 	return nil
 }

cmd/acr/purge.go

@@ -14,6 +14,7 @@ import (
 	"github.com/Azure/acr-cli/acr"
 	"github.com/Azure/acr-cli/cmd/common"
 	"github.com/Azure/acr-cli/internal/api"
+	"github.com/Azure/acr-cli/internal/logger"
 	"github.com/Azure/acr-cli/internal/worker"
 	"github.com/dlclark/regexp2"
 	"github.com/spf13/cobra"
@@ -348,29 +349,75 @@ func getTagsToDelete(ctx context.Context,
 // purgeDanglingManifests deletes all manifests that do not have any tags associated with them.
 // except the ones that are referenced by a multiarch manifest or that have subject.
 func purgeDanglingManifests(ctx context.Context, acrClient api.AcrCLIClientInterface, repoParallelism int, loginURL string, repoName string, manifestToTagsCountMap map[string]int, dryRun bool) (int, error) {
-	fmt.Printf("Deleting manifests for repository: %s\n", repoName)
+	log := logger.Get()
+
+	log.Info().
+		Str("repository", repoName).
+		Bool("dry_run", dryRun).
+		Msg("Starting manifest purge operation")
+
 	// Contrary to getTagsToDelete, getManifestsToDelete gets all the Manifests at once, this was done because if there is a manifest that has no
 	// tag but is referenced by a multiarch manifest that has tags then it should not be deleted. Or if a manifest has no tag, but it has subject,
 	// then it should not be deleted.
 	manifestsToDelete, err := common.GetUntaggedManifests(ctx, repoParallelism, acrClient, repoName, false, manifestToTagsCountMap, dryRun)
 	if err != nil {
+		log.Error().
+			Err(err).
+			Str("repository", repoName).
+			Msg("Failed to get untagged manifests")
 		return -1, err
 	}
 
+	log.Info().
+		Str("repository", repoName).
+		Int("candidate_count", len(manifestsToDelete)).
+		Msg("Found candidate manifests for deletion")
+
 	// If dryRun is set to true then no manifests will be deleted, but the number of manifests that would be deleted is returned. Additionally,
 	// the manifests that would be deleted are printed to the console. We also need to account for the manifests that would be deleted from the tag
 	// filtering first as that would influence the untagged manifests that would be deleted.
 	if dryRun {
+		log.Info().
+			Str("repository", repoName).
+			Int("count", len(manifestsToDelete)).
+			Msg("Dry run: manifests that would be deleted")
+
 		for _, manifest := range manifestsToDelete {
+			// Keep the fmt.Printf for user output consistency
 			fmt.Printf("Would delete: %s/%s@%s\n", loginURL, repoName, manifest)
+
+			log.Debug().
+				Str("repository", repoName).
+				Str("manifest", manifest).
+				Str("ref", fmt.Sprintf("%s/%s@%s", loginURL, repoName, manifest)).
+				Msg("Manifest marked for deletion in dry run")
 		}
 		return len(manifestsToDelete), nil
 	}
+
 	// In order to only have a limited amount of http requests, a purger is used that will start goroutines to delete manifests.
+	log.Debug().
+		Str("repository", repoName).
+		Int("parallelism", repoParallelism).
+		Int("manifest_count", len(manifestsToDelete)).
+		Msg("Starting concurrent manifest deletion")
+
 	purger := worker.NewPurger(repoParallelism, acrClient, loginURL, repoName)
 	deletedManifestsCount, purgeErr := purger.PurgeManifests(ctx, manifestsToDelete)
 	if purgeErr != nil {
+		log.Error().
+			Err(purgeErr).
+			Str("repository", repoName).
+			Int("attempted_count", len(manifestsToDelete)).
+			Msg("Failed to purge manifests")
 		return -1, purgeErr
 	}
+
+	log.Info().
+		Str("repository", repoName).
+		Int("deleted_count", deletedManifestsCount).
+		Int("attempted_count", len(manifestsToDelete)).
+		Msg("Successfully completed manifest purge operation")
+
 	return deletedManifestsCount, nil
 }

cmd/acr/root.go

@@ -7,6 +7,7 @@ import (
 	"errors"
 	"os"
 
+	"github.com/Azure/acr-cli/internal/logger"
 	"github.com/spf13/cobra"
 )
 
@@ -16,6 +17,8 @@ type rootParameters struct {
 	username     string
 	password     string
 	configs      []string
+	logLevel     string
+	logFormat    string
 }
 
 func newRootCmd(args []string) *cobra.Command {
@@ -32,6 +35,13 @@ func newRootCmd(args []string) *cobra.Command {
 
 To start working with the CLI, run acr --help`,
 		SilenceUsage: true,
+		PersistentPreRun: func(cmd *cobra.Command, args []string) {
+			// Setup logger with configured level and format
+			logger.Setup(logger.Config{
+				Level:  rootParams.logLevel,
+				Format: rootParams.logFormat,
+			})
+		},
 	}
 
 	flags := cmd.PersistentFlags()
@@ -55,6 +65,8 @@ To start working with the CLI, run acr --help`,
 	cmd.PersistentFlags().StringVarP(&rootParams.registryName, "registry", "r", "", "Registry name")
 	cmd.PersistentFlags().StringVarP(&rootParams.username, "username", "u", "", "Registry username")
 	cmd.PersistentFlags().StringVarP(&rootParams.password, "password", "p", "", "Registry password")
+	cmd.PersistentFlags().StringVar(&rootParams.logLevel, "log-level", "info", "Log level (debug, info, warn, error)")
+	cmd.PersistentFlags().StringVar(&rootParams.logFormat, "log-format", "console", "Log format (console, json)")
 	cmd.Flags().BoolP("help", "h", false, "Print usage")
 	cmd.Flags().StringArrayVarP(&rootParams.configs, "config", "c", nil, "Auth config paths")
 	// No parameter is marked as required because the registry could be inferred from a task context, same with username and password