From 5d0fb9c2d51882a6358c2420d8237e3694be8a79 Mon Sep 17 00:00:00 2001 From: Seth Vargo Date: Tue, 5 Apr 2022 20:49:37 -0400 Subject: [PATCH] Add more debug logging (#78) --- README.md | 6 +++ cmd/gcr-cleaner-cli/main.go | 17 +++++++-- cmd/gcr-cleaner-server/main.go | 56 ++++++++++++++++++++++------ pkg/gcrcleaner/cleaner.go | 67 +++++++++++++++++++++++++++++----- pkg/gcrcleaner/filter.go | 17 +++++++++ pkg/gcrcleaner/logging.go | 60 +++++++++++++++++++++++++----- pkg/gcrcleaner/server.go | 5 +-- 7 files changed, 191 insertions(+), 37 deletions(-) diff --git a/README.md b/README.md index 46bec0c..52f4f32 100644 --- a/README.md +++ b/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. diff --git a/cmd/gcr-cleaner-cli/main.go b/cmd/gcr-cleaner-cli/main.go index b7820ac..5d0789f 100644 --- a/cmd/gcr-cleaner-cli/main.go +++ b/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,7 +93,7 @@ func main() { flag.Parse() - if err := realMain(ctx); err != nil { + if err := realMain(ctx, logger); err != nil { cancel() fmt.Fprintf(stderr, "%s\n", err) @@ -93,7 +101,7 @@ func main() { } } -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 { diff --git a/cmd/gcr-cleaner-server/main.go b/cmd/gcr-cleaner-server/main.go index 004436c..7cc67a9 100644 --- a/cmd/gcr-cleaner-server/main.go +++ b/cmd/gcr-cleaner-server/main.go @@ -17,10 +17,12 @@ package main import ( "context" + "fmt" "net/http" "os" "os/signal" "runtime" + "syscall" "time" gcrauthn "github.com/google/go-containerregistry/pkg/authn" @@ -28,9 +30,30 @@ import ( "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 } diff --git a/pkg/gcrcleaner/cleaner.go b/pkg/gcrcleaner/cleaner.go index dffbd40..7c26628 100644 --- a/pkg/gcrcleaner/cleaner.go +++ b/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 } diff --git a/pkg/gcrcleaner/filter.go b/pkg/gcrcleaner/filter.go index 16b01e4..7bff8d6 100644 --- a/pkg/gcrcleaner/filter.go +++ b/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 diff --git a/pkg/gcrcleaner/logging.go b/pkg/gcrcleaner/logging.go index b27d9aa..484625f 100644 --- a/pkg/gcrcleaner/logging.go +++ b/pkg/gcrcleaner/logging.go @@ -19,26 +19,62 @@ import ( "fmt" "io" "os" + "strings" + "sync" "time" ) -type Severity string +type Severity uint8 const ( - SeverityDebug Severity = "DEBUG" - SeverityInfo Severity = "INFO" - SeverityWarn Severity = "WARNING" - SeverityError Severity = "ERROR" - SeverityFatal Severity = "EMERGENCY" + SeverityDebug Severity = iota + SeverityInfo + SeverityWarn + SeverityError + SeverityFatal +) + +var ( + severityNameMap = map[Severity]string{ + SeverityDebug: "DEBUG", + SeverityInfo: "INFO", + SeverityWarn: "WARNING", + SeverityError: "ERROR", + SeverityFatal: "EMERGENCY", + } + + nameSeverityMap = map[string]Severity{ + "DEBUG": SeverityDebug, + "INFO": SeverityInfo, + "WARN": SeverityWarn, + "WARNING": SeverityWarn, + "ERROR": SeverityError, + "FATAL": SeverityFatal, + "EMERGENCY": SeverityFatal, + } ) type Logger struct { + level Severity + stdout io.Writer stderr io.Writer + + lock sync.Mutex } -func NewLogger(outw, errw io.Writer) *Logger { - return &Logger{stdout: outw, stderr: errw} +func NewLogger(level string, outw, errw io.Writer) *Logger { + normalized := strings.ToUpper(strings.TrimSpace(level)) + if normalized == "" { + normalized = "INFO" + } + + v, ok := nameSeverityMap[normalized] + if !ok { + panic(fmt.Sprintf("failed to parse level %q: not found", normalized)) + } + + return &Logger{level: v, stdout: outw, stderr: errw} } func (l *Logger) Debug(msg string, fields ...interface{}) { @@ -67,6 +103,10 @@ func (l *Logger) log(w io.Writer, msg string, sev Severity, fields ...interface{ panic("number of fields must be even") } + if l.level > sev { + return + } + data := make(map[string]interface{}, len(fields)/2) for i := 0; i < len(fields); i += 2 { key, ok := fields[i].(string) @@ -92,7 +132,9 @@ func (l *Logger) log(w io.Writer, msg string, sev Severity, fields ...interface{ panic(fmt.Errorf("failed to marshal log entry: %w", err)) } + l.lock.Lock() fmt.Fprintln(w, string(jsonPayload)) + l.lock.Unlock() } type LogEntry struct { @@ -109,7 +151,7 @@ func (l *LogEntry) MarshalJSON() ([]byte, error) { d["time"] = l.Time.Format(time.RFC3339) } - d["severity"] = string(l.Severity) + d["severity"] = severityNameMap[l.Severity] d["message"] = l.Message for k, v := range l.Data { diff --git a/pkg/gcrcleaner/server.go b/pkg/gcrcleaner/server.go index 581b030..3f1481a 100644 --- a/pkg/gcrcleaner/server.go +++ b/pkg/gcrcleaner/server.go @@ -22,7 +22,6 @@ import ( "io" "io/ioutil" "net/http" - "os" "sort" "strings" "time" @@ -47,7 +46,7 @@ func NewServer(cleaner *Cleaner) (*Server, error) { return &Server{ cleaner: cleaner, - logger: NewLogger(os.Stdout, os.Stderr), + logger: cleaner.logger, }, nil } @@ -177,7 +176,7 @@ func (s *Server) clean(ctx context.Context, r io.ReadCloser) (map[string][]strin // Do the deletion. deleted := make(map[string][]string, len(repos)) for _, repo := range repos { - s.logger.Debug("deleting refs for repo", "repo", repo) + s.logger.Info("deleting refs for repo", "repo", repo) childrenDeleted, err := s.cleaner.Clean(repo, since, p.Keep, tagFilter, p.DryRun) if err != nil {