Add more debug logging (#78)

README.md

@@ -232,6 +232,12 @@ In addition to the server, you can also run GCR Cleaner locally for one-off task
 docker run -it us-docker.pkg.dev/gcr-cleaner/gcr-cleaner/gcr-cleaner-cli
 ```
 
+## Logging
+
+By default, logs are produced at the `info` level. More logs are available at
+the `debug` level. To set the log level, set `GCRCLEANER_LOG=debug`.
+
+
 ## I just want the container!
 
 You can build the container yourself using the included Dockerfile.

cmd/gcr-cleaner-cli/main.go

@@ -36,7 +36,13 @@ import (
 var (
 	stdout = os.Stdout
 	stderr = os.Stderr
+)
+
+var (
+	logLevel = os.Getenv("GCRCLEANER_LOG")
+)
 
+var (
 	reposMap = make(map[string]struct{}, 4)
 
 	tokenPtr     = flag.String("token", os.Getenv("GCRCLEANER_TOKEN"), "Authentication token")
@@ -54,6 +60,8 @@ var (
 )
 
 func main() {
+	logger := gcrcleaner.NewLogger(logLevel, stderr, stdout)
+
 	ctx, cancel := signal.NotifyContext(context.Background(), syscall.SIGINT, syscall.SIGTERM)
 	defer cancel()
 
@@ -85,15 +93,15 @@ func main() {
 
 	flag.Parse()
 
-	if err := realMain(ctx); err != nil {
+	if err := realMain(ctx, logger); err != nil {
 		cancel()
 
 		fmt.Fprintf(stderr, "%s\n", err)
 		os.Exit(1)
 	}
 }
 
-func realMain(ctx context.Context) error {
+func realMain(ctx context.Context, logger *gcrcleaner.Logger) error {
 	if args := flag.Args(); len(args) > 0 {
 		return fmt.Errorf("expected zero arguments, got %d: %q", len(args), args)
 	}
@@ -123,8 +131,10 @@ func realMain(ctx context.Context) error {
 	// Try to find the "best" authentication.
 	var auther gcrauthn.Authenticator
 	if *tokenPtr != "" {
+		logger.Debug("using token from flag for authentication")
 		auther = &gcrauthn.Bearer{Token: *tokenPtr}
 	} else {
+		logger.Debug("using default token resolution for authentication")
 		var err error
 		auther, err = gcrgoogle.NewEnvAuthenticator()
 		if err != nil {
@@ -133,7 +143,7 @@ func realMain(ctx context.Context) error {
 	}
 
 	concurrency := runtime.NumCPU()
-	cleaner, err := gcrcleaner.NewCleaner(auther, concurrency)
+	cleaner, err := gcrcleaner.NewCleaner(auther, logger, concurrency)
 	if err != nil {
 		return fmt.Errorf("failed to create cleaner: %w", err)
 	}
@@ -148,6 +158,7 @@ func realMain(ctx context.Context) error {
 
 	// Gather the repositories
 	if *recursivePtr {
+		logger.Debug("gathering child repositories recursively")
 		for _, repo := range repos {
 			childRepos, err := cleaner.ListChildRepositories(ctx, repo)
 			if err != nil {

cmd/gcr-cleaner-server/main.go

@@ -17,20 +17,43 @@ package main
 
 import (
 	"context"
+	"fmt"
 	"net/http"
 	"os"
 	"os/signal"
 	"runtime"
+	"syscall"
 	"time"
 
 	gcrauthn "github.com/google/go-containerregistry/pkg/authn"
 	gcrgoogle "github.com/google/go-containerregistry/pkg/v1/google"
 	"github.com/sethvargo/gcr-cleaner/pkg/gcrcleaner"
 )
 
+var (
+	stdout = os.Stdout
+	stderr = os.Stderr
+)
+
+var (
+	logLevel = os.Getenv("GCRCLEANER_LOG")
+)
+
 func main() {
-	logger := gcrcleaner.NewLogger(os.Stderr, os.Stdout)
+	logger := gcrcleaner.NewLogger(logLevel, stderr, stdout)
 
+	ctx, cancel := signal.NotifyContext(context.Background(), syscall.SIGINT, syscall.SIGTERM)
+	defer cancel()
+
+	if err := realMain(ctx, logger); err != nil {
+		cancel()
+		logger.Fatal("server exited with error", "error", err)
+	}
+
+	logger.Info("server shutdown complete")
+}
+
+func realMain(ctx context.Context, logger *gcrcleaner.Logger) error {
 	port := os.Getenv("PORT")
 	if port == "" {
 		port = "8080"
@@ -39,24 +62,26 @@ func main() {
 
 	var auther gcrauthn.Authenticator
 	if token := os.Getenv("GCRCLEANER_TOKEN"); token != "" {
+		logger.Debug("using token from GCRCLEANER_TOKEN for authentication")
 		auther = &gcrauthn.Bearer{Token: token}
 	} else {
+		logger.Debug("using default token resolution for authentication")
 		var err error
 		auther, err = gcrgoogle.NewEnvAuthenticator()
 		if err != nil {
-			logger.Fatal("failed to setup auther", "error", err)
+			return fmt.Errorf("failed to setup auther: %w", err)
 		}
 	}
 
 	concurrency := runtime.NumCPU()
-	cleaner, err := gcrcleaner.NewCleaner(auther, concurrency)
+	cleaner, err := gcrcleaner.NewCleaner(auther, logger, concurrency)
 	if err != nil {
-		logger.Fatal("failed to create cleaner", "error", err)
+		return fmt.Errorf("failed to create cleaner: %w", err)
 	}
 
 	cleanerServer, err := gcrcleaner.NewServer(cleaner)
 	if err != nil {
-		logger.Fatal("failed to create server", "error", err)
+		return fmt.Errorf("failed to create server: %w", err)
 	}
 
 	cache := gcrcleaner.NewTimerCache(5 * time.Minute)
@@ -70,23 +95,30 @@ func main() {
 		Handler: mux,
 	}
 
+	errCh := make(chan error, 1)
 	go func() {
-		logger.Debug("server is listening", "port", port)
+		logger.Info("server is listening", "port", port)
 		if err := server.ListenAndServe(); err != nil && err != http.ErrServerClosed {
-			logger.Fatal("server exited", "error", err)
+			select {
+			case errCh <- err:
+			default:
+			}
 		}
 	}()
 
-	signalCh := make(chan os.Signal, 1)
-	signal.Notify(signalCh, os.Interrupt)
-
-	<-signalCh
+	select {
+	case <-ctx.Done():
+	case err := <-errCh:
+		return fmt.Errorf("server exited: %w", err)
+	}
 
 	logger.Info("server received stop, shutting down")
 	ctx, cancel := context.WithTimeout(context.Background(), 5*time.Second)
 	defer cancel()
 
 	if err := server.Shutdown(ctx); err != nil {
-		logger.Fatal("failed to shutdown server", "error", err)
+		return fmt.Errorf("failed to shutdown server: %w", err)
 	}
+
+	return nil
 }

pkg/gcrcleaner/cleaner.go

@@ -34,15 +34,17 @@ import (
 // Cleaner is a gcr cleaner.
 type Cleaner struct {
 	auther      gcrauthn.Authenticator
+	logger      *Logger
 	concurrency int
 }
 
 // NewCleaner creates a new GCR cleaner with the given token provider and
 // concurrency.
-func NewCleaner(auther gcrauthn.Authenticator, c int) (*Cleaner, error) {
+func NewCleaner(auther gcrauthn.Authenticator, logger *Logger, c int) (*Cleaner, error) {
 	return &Cleaner{
 		auther:      auther,
 		concurrency: c,
+		logger:      logger,
 	}, nil
 }
 
@@ -53,6 +55,8 @@ func (c *Cleaner) Clean(repo string, since time.Time, keep int, tagFilter TagFil
 	if err != nil {
 		return nil, fmt.Errorf("failed to get repo %s: %w", repo, err)
 	}
+	c.logger.Debug("computed repo", "repo", gcrrepo.Name())
+
 	tags, err := gcrgoogle.List(gcrrepo, gcrgoogle.WithAuth(c.auther))
 	if err != nil {
 		return nil, fmt.Errorf("failed to list tags for repo %s: %w", repo, err)
@@ -67,9 +71,9 @@ func (c *Cleaner) Clean(repo string, since time.Time, keep int, tagFilter TagFil
 	var errs = make(map[string]error)
 	var errsLock sync.RWMutex
 
-	var manifests = make([]manifest, 0, len(tags.Manifests))
+	var manifests = make([]*manifest, 0, len(tags.Manifests))
 	for k, m := range tags.Manifests {
-		manifests = append(manifests, manifest{k, m})
+		manifests = append(manifests, &manifest{repo, k, m})
 	}
 
 	// Sort manifest by Created from the most recent to the least
@@ -78,17 +82,35 @@ func (c *Cleaner) Clean(repo string, since time.Time, keep int, tagFilter TagFil
 	})
 
 	for _, m := range manifests {
-		if c.shouldDelete(m.Info, since, tagFilter) {
-			// Store copy of manifest for thread safety in delete job pool
-			m := m
+		// Store copy of manifest for thread safety in delete job pool
+		m := m
+
+		c.logger.Debug("processing manifest",
+			"repo", repo,
+			"digest", m.Digest,
+			"tags", m.Info.Tags,
+			"uploaded", m.Info.Uploaded.Format(time.RFC3339))
+
+		if c.shouldDelete(m, since, tagFilter) {
 			// Keep a certain amount of images
 			if keepCount < keep {
+				c.logger.Debug("skipping deletion because of keep count",
+					"repo", repo,
+					"digest", m.Digest,
+					"keep", keep,
+					"keep_count", keepCount)
+
 				keepCount++
 				continue
 			}
 
 			// Deletes all tags before deleting the image
 			for _, tag := range m.Info.Tags {
+				c.logger.Debug("deleting tag",
+					"repo", repo,
+					"digest", m.Digest,
+					"tag", tag)
+
 				tagged := gcrrepo.Tag(tag)
 				if !dryRun {
 					if err := c.deleteOne(tagged); err != nil {
@@ -113,6 +135,10 @@ func (c *Cleaner) Clean(repo string, since time.Time, keep int, tagFilter TagFil
 				}
 				errsLock.RUnlock()
 
+				c.logger.Debug("deleting digest",
+					"repo", repo,
+					"digest", m.Digest)
+
 				if !dryRun {
 					if err := c.deleteOne(ref); err != nil {
 						cause := errors.Unwrap(err).Error()
@@ -158,6 +184,7 @@ func (c *Cleaner) Clean(repo string, since time.Time, keep int, tagFilter TagFil
 }
 
 type manifest struct {
+	Repo   string
 	Digest string
 	Info   gcrgoogle.ManifestInfo
 }
@@ -173,25 +200,45 @@ func (c *Cleaner) deleteOne(ref gcrname.Reference) error {
 
 // shouldDelete returns true if the manifest was created before the given
 // timestamp and either has no tags or has tags that match the given filter.
-func (c *Cleaner) shouldDelete(m gcrgoogle.ManifestInfo, since time.Time, tagFilter TagFilter) bool {
+func (c *Cleaner) shouldDelete(m *manifest, since time.Time, tagFilter TagFilter) bool {
 	// Immediately exclude images that have been uploaded after the given time.
-	if m.Uploaded.UTC().After(since) {
+	if uploaded := m.Info.Uploaded.UTC(); uploaded.After(since) {
+		c.logger.Debug("should not delete",
+			"repo", m.Repo,
+			"digest", m.Digest,
+			"reason", "too new",
+			"since", since.Format(time.RFC3339),
+			"uploaded", uploaded.Format(time.RFC3339),
+			"delta", uploaded.Sub(since).String())
 		return false
 	}
 
 	// If there are no tags, it should be deleted.
-	if len(m.Tags) == 0 {
+	if len(m.Info.Tags) == 0 {
+		c.logger.Debug("should delete",
+			"repo", m.Repo,
+			"digest", m.Digest,
+			"reason", "no tags")
 		return true
 	}
 
 	// If tagged images are allowed and the given filter matches the list of tags,
 	// this is a deletion candidate. The default tag filter is to reject all
 	// strings.
-	if tagFilter.Matches(m.Tags) {
+	if tagFilter.Matches(m.Info.Tags) {
+		c.logger.Debug("should delete",
+			"repo", m.Repo,
+			"digest", m.Digest,
+			"reason", "matches tag filter",
+			"tag_filter", tagFilter.Name())
 		return true
 	}
 
 	// If we got this far, it'ts not a viable deletion candidate.
+	c.logger.Debug("should not delete",
+		"repo", m.Repo,
+		"digest", m.Digest,
+		"reason", "no filter matches")
 	return false
 }
 

pkg/gcrcleaner/filter.go

@@ -22,6 +22,7 @@ import (
 // TagFilter is an interface which defines whether a given set of tags matches
 // the filter.
 type TagFilter interface {
+	Name() string
 	Matches(tags []string) bool
 }
 
@@ -69,6 +70,10 @@ func (f *TagFilterNull) Matches(tags []string) bool {
 	return false
 }
 
+func (f *TagFilterNull) Name() string {
+	return "(none)"
+}
+
 var _ TagFilter = (*TagFilterFirst)(nil)
 
 // TagFilterFirst filters based on the first item in the list. If the list is
@@ -77,6 +82,10 @@ type TagFilterFirst struct {
 	re *regexp.Regexp
 }
 
+func (f *TagFilterFirst) Name() string {
+	return fmt.Sprintf("first(%s)", f.re.String())
+}
+
 func (f *TagFilterFirst) Matches(tags []string) bool {
 	if len(tags) < 1 || f.re == nil {
 		return false
@@ -104,6 +113,10 @@ func (f *TagFilterAny) Matches(tags []string) bool {
 	return false
 }
 
+func (f *TagFilterAny) Name() string {
+	return fmt.Sprintf("any(%s)", f.re.String())
+}
+
 var _ TagFilter = (*TagFilterAll)(nil)
 
 // TagFilterAll filters based on the entire list. If all tags in the last match,
@@ -112,6 +125,10 @@ type TagFilterAll struct {
 	re *regexp.Regexp
 }
 
+func (f *TagFilterAll) Name() string {
+	return fmt.Sprintf("all(%s)", f.re.String())
+}
+
 func (f *TagFilterAll) Matches(tags []string) bool {
 	if f.re == nil {
 		return false