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

README.md

@@ -59,10 +59,34 @@ For updating the vendor folder run (at repository root):
 make vendor
 ```
 
-## Usage
-
-The following are examples of commands that the CLI currently supports.
-
+## Usage
+
+The following are examples of commands that the CLI currently supports.
+
+### Global Flags
+
+The ACR CLI supports the following global flags that can be used with any command:
+
+#### Structured Logging Flags
+
+- `--log-level` (debug, info, warn, error) - Controls the verbosity of log output. Defaults to `info`.
+- `--log-format` (console, json) - Controls the output format of logs. Defaults to `console` for better CLI usability.
+
+**Examples:**
+
+```sh
+# Enable debug logging for troubleshooting
+acr --log-level debug purge -r myregistry --filter "repo:.*" --ago 7d
+
+# Use JSON format for log aggregation systems  
+acr --log-format json purge -r myregistry --filter "repo:.*" --ago 7d
+
+# Combined usage
+acr --log-level debug --log-format json purge -r myregistry --filter "repo:.*" --ago 7d
+```
+
+For detailed information about structured logging, see [docs/structured-logging.md](docs/structured-logging.md).
+
 ### Login Command
 
 If you are currently logged into an Azure Container Registry the program should be able to read your stored credentials, if not you can do:

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"
@@ -162,9 +163,18 @@ func annotateTags(ctx context.Context,
 	regexpMatchTimeoutSeconds int64,
 	dryRun bool) (int, error) {
 
+	log := logger.Get()
+
 	if !dryRun {
+		log.Info().
+			Str(logger.FieldRepository, repoName).
+			Msg("Starting tag annotation for repository")
 		fmt.Printf("\nAnnotating tags for repository: %s\n", repoName)
 	} else {
+		log.Info().
+			Str(logger.FieldRepository, repoName).
+			Bool(logger.FieldDryRun, true).
+			Msg("Dry run: would annotate tags for repository")
 		fmt.Printf("\nTags for this repository would be annotated: %s\n", repoName)
 	}
 
@@ -222,10 +232,15 @@ func getManifestsToAnnotate(ctx context.Context,
 	filter *regexp2.Regexp,
 	lastTag string, artifactType string, dryRun bool) ([]string, string, error) {
 
+	log := logger.Get()
+
 	resultTags, err := acrClient.GetAcrTags(ctx, repoName, "timedesc", lastTag)
 	if err != nil {
 		if resultTags != nil && resultTags.Response.Response != nil && resultTags.StatusCode == http.StatusNotFound {
-			fmt.Printf("%s repository not found\n", repoName)
+			log.Warn().
+				Str(logger.FieldRepository, repoName).
+				Int(logger.FieldStatusCode, resultTags.StatusCode).
+				Msg("Repository not found during annotation operation")
 			return nil, "", nil
 		}
 		return nil, "", err
@@ -254,10 +269,15 @@ func getManifestsToAnnotate(ctx context.Context,
 					return nil, "", err
 				}
 				if !skip {
-					// Only print what would be annotated during a dry-run. Successfully annotated manifests
+					// Only log what would be annotated during a dry-run. Successfully annotated manifests
 					// will be logged after the annotation.
 					if dryRun {
-						fmt.Printf("%s/%s:%s\n", loginURL, repoName, *tag.Name)
+						log.Debug().
+							Str(logger.FieldRepository, repoName).
+							Str(logger.FieldTag, *tag.Name).
+							Str(logger.FieldManifest, *tag.Digest).
+							Bool(logger.FieldDryRun, true).
+							Msg("Tag marked for annotation in dry run")
 					}
 					manifestsToAnnotate = append(manifestsToAnnotate, *tag.Digest)
 				}
@@ -279,9 +299,19 @@ func annotateUntaggedManifests(ctx context.Context,
 	repoName string, artifactType string,
 	annotations []string,
 	dryRun bool) (int, error) {
+
+	log := logger.Get()
+
 	if !dryRun {
+		log.Info().
+			Str(logger.FieldRepository, repoName).
+			Msg("Starting manifest annotation for repository")
 		fmt.Printf("Annotating manifests for repository: %s\n", repoName)
 	} else {
+		log.Info().
+			Str(logger.FieldRepository, repoName).
+			Bool(logger.FieldDryRun, 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,7 +8,7 @@ import (
 	"fmt"
 
 	"github.com/Azure/acr-cli/internal/api"
-	"github.com/pkg/errors"
+	"github.com/Azure/acr-cli/internal/logger"
 	"github.com/spf13/cobra"
 )
 
@@ -83,29 +83,42 @@ 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().With().Str(logger.FieldRepository, repoName).Logger()
+
+	log.Debug().Msg("Starting manifest listing")
+
 	lastManifestDigest := ""
 	resultManifests, err := acrClient.GetAcrManifests(ctx, repoName, "", lastManifestDigest)
 	if err != nil {
-		return errors.Wrap(err, "failed to list manifests")
+		log.Error().Err(err).Msg("Failed to get manifests for listing")
+		return fmt.Errorf("failed to list manifests: %w", err)
 	}
 
 	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(logger.FieldManifest, 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 {
-			return errors.Wrap(err, "failed to list manifests")
+			log.Error().Err(err).Msg("Failed to get next page of manifests")
+			return fmt.Errorf("failed to list manifests: %w", err)
 		}
 	}
+
+	log.Info().Int("total_manifests", totalManifests).Msg("Completed manifest listing")
 	return nil
 }
 
@@ -140,13 +153,33 @@ 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().With().Str(logger.FieldRepository, repoName).Logger()
+
+	log.Info().Int(logger.FieldManifestCount, 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(logger.FieldManifest, 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")
+			return fmt.Errorf("failed to delete manifests: %w", err)
 		}
+
 		fmt.Printf("%s/%s@%s\n", loginURL, repoName, args[i])
+
+		log.Info().
+			Str(logger.FieldManifest, args[i]).
+			Str(logger.FieldRef, fmt.Sprintf("%s/%s@%s", loginURL, repoName, args[i])).
+			Int("position", i+1).
+			Int("total", len(args)).
+			Msg("Successfully deleted manifest")
 	}
+
+	log.Info().Int(logger.FieldDeletedCount, 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