Feature/logging updates

.gitignore

@@ -1,2 +1,2 @@
-./drprune
-*.txt
+/drprune
+/*.txt

go.mod

@@ -1,29 +1,11 @@
 module github.com/myENA/drprune
 
-go 1.14
+go 1.13
 
 require (
-	github.com/Microsoft/hcsshim v0.8.7 // indirect
-	github.com/armon/go-metrics v0.3.2 // indirect
 	github.com/cego/docker-registry-pruner v0.0.0-20190904085958-83bcaac3e2d2
-	github.com/containerd/containerd v1.3.3 // indirect
-	github.com/containerd/continuity v0.0.0-20200107194136-26c1120b8d41 // indirect
 	github.com/fsouza/go-dockerclient v1.6.3
-	github.com/gogo/protobuf v1.3.1 // indirect
-	github.com/golang/protobuf v1.3.4 // indirect
-	github.com/hashicorp/consul v1.7.1 // indirect
 	github.com/hashicorp/consul/api v1.4.0
-	github.com/hashicorp/golang-lru v0.5.4 // indirect
-	github.com/ijc/Gotty v0.0.0-20170406111628-a8b993ba6abd // indirect
-	github.com/konsorten/go-windows-terminal-sequences v1.0.2 // indirect
-	github.com/mattn/go-colorable v0.1.6 // indirect
-	github.com/mitchellh/go-testing-interface v1.0.0 // indirect
-	github.com/mitchellh/mapstructure v1.1.2 // indirect
-	github.com/morikuni/aec v1.0.0 // indirect
 	github.com/myENA/consul-decoder v0.2.5
-	github.com/pkg/errors v0.9.1 // indirect
 	github.com/rs/zerolog v1.18.0
-	golang.org/x/crypto v0.0.0-20200221231518-2aa609cf4a9d // indirect
-	google.golang.org/genproto v0.0.0-20200228133532-8c2c7df3a383 // indirect
-	google.golang.org/grpc v1.27.1 // indirect
 )

main.go

@@ -21,7 +21,7 @@ import (
 	"github.com/rs/zerolog"
 )
 
-var log = zerolog.New(os.Stderr).With().Str("app", "drprune").Timestamp().Logger()
+var log = zerolog.New(&zerolog.ConsoleWriter{Out: os.Stderr, TimeFormat: ""}).With().Str("app", "drprune").Timestamp().Logger()
 
 func main() {
 
@@ -35,6 +35,7 @@ func main() {
 	var runGC bool
 	var drContainerName string
 	var drConfigFilePath string
+	var catalogPageSize int
 
 	fs := flag.NewFlagSet("drprune", flag.ExitOnError)
 	fs.StringVar(
@@ -98,6 +99,12 @@ func main() {
 		"/etc/docker/registry/config.yml",
 		"docker registry config file path inside container",
 	)
+	fs.IntVar(
+		&catalogPageSize,
+		"catalog-page-size",
+		10000,
+		"number of records to return per /v2/catalog api call",
+	)
 	_ = fs.Parse(os.Args[1:])
 
 	if registryURL == "" {
@@ -110,7 +117,6 @@ func main() {
 		DialContext: (&net.Dialer{
 			Timeout:   60 * time.Second,
 			KeepAlive: 30 * time.Second,
-			DualStack: true,
 		}).DialContext,
 		MaxIdleConns:          1,
 		IdleConnTimeout:       90 * time.Second,
@@ -131,7 +137,7 @@ func main() {
 
 	reg.SetHTTPClient(&http.Client{Transport: transport})
 
-	reg.SetPageSize(100000)
+	reg.SetPageSize(catalogPageSize)
 	if !skipDeletes {
 		cnl, err := api.NewClient(api.DefaultConfig())
 
@@ -156,15 +162,21 @@ func main() {
 			}
 		}
 
-		fmt.Printf("config: %#v\n", cfg)
+		log.Info().Object("config", cfg).Msg("Config parsed")
 
 		repos, err := reg.GetRepositories()
 		if err != nil {
 			log.Fatal().Err(err).Msg("Failed to list repositories from registry")
 		}
 
+		log.Info().Msgf("Found %d repo configurations", len(repos))
+
 		var tagsToDelete tagsMetaList
 		for _, repo := range repos {
+			log := log.With().Str("action", "delete-images").Str("repo", repo).Logger()
+
+			log.Info().Msgf("Processing repo: %s", repo)
+
 			p := path.Join(consulDefaultPath, repo)
 			kvs, _, err := cnl.KV().List(p, nil)
 			c := cfg
@@ -177,7 +189,7 @@ func main() {
 				if err != nil {
 					log.Error().Err(err).Str("path", p).Msg("failed to unmarshal config")
 				}
-				fmt.Printf("found config: %#v\n", c)
+				log.Info().Object("config", c).Msg("Found config")
 			}
 			tags, err := reg.GetTags(repo)
 			if err != nil {
@@ -187,11 +199,19 @@ func main() {
 
 			var releaseTags tagsMetaList
 			for _, tag := range tags {
+				log := log.With().Str("tag", tag).Logger()
+				log.Info().Msgf("Processing tag: %s", tag)
+
 				digest, created, err := reg.GetManifestDigestAndCreated(repo, tag)
 				if err != nil {
-					log.Error().Err(err).Str("repo", repo).Str("tag", tag).Msg("could not get manifest created")
+					log.Error().Err(err).Msg("could not get manifest created")
 					continue
 				}
+
+				log = log.With().Str("manifest", digest).Time("created", created).Logger()
+
+				log.Debug().Msg("Tag data found")
+
 				var isRelease bool
 				for _, rt := range c.ReleaseTags {
 					if strings.HasPrefix(tag, rt) {
@@ -200,48 +220,68 @@ func main() {
 					}
 				}
 				if isRelease {
+					log.Debug().Msg("Tag identified as containing a release build")
 					releaseTags = append(releaseTags, tagsMeta{
 						created: created,
 						repo:    repo,
 						tag:     tag,
 						digest:  digest,
 					})
 				} else {
+					log.Debug().Msg("Tag identified as containing a development build")
 					// not special
 					d := time.Since(created)
 					if d > time.Duration(int(time.Hour)*24*c.MinFeatureEvictionDays) {
+						log.Info().Msg("Development tag is beyond purge threshold, adding to delete list...")
 						tagsToDelete = append(tagsToDelete, tagsMeta{
 							created: created,
 							repo:    repo,
 							tag:     tag,
 							digest:  digest,
 						})
+					} else {
+						log.Debug().Msg("Development tag is not beyond purge threshold, will not delete")
 					}
-
 				}
 			}
+
+			log.Debug().Msgf("Found %d release images", len(releaseTags))
+
 			if len(releaseTags) > c.MinReleaseImages {
+				log.Info().Msgf("Above configured release image purge threshold (%d > %d)", len(releaseTags), c.MinReleaseImages)
 				sort.Sort(releaseTags)
 				for _, rt := range releaseTags[c.MinReleaseImages:] {
+					log := log.With().Str("tag", rt.tag).Logger()
 					d := time.Since(rt.created)
 					if d > time.Duration(int(time.Hour)*24*c.MinReleaseEvictionDays) {
+						log.Info().Msg("Release tag is beyond purge threshold, adding to delete list...")
 						tagsToDelete = append(tagsToDelete, rt)
+					} else {
+						log.Debug().Msg("Release tag is not beyond purge threshold, will not delete")
 					}
 				}
+			} else {
+				log.Debug().Msgf("Not above configured release image purge threshold (%d <= %d)", len(releaseTags), c.MinReleaseImages)
 			}
-
 		}
 
+		log.Info().Msgf("Found %d tags to delete", len(tagsToDelete))
+
 		sort.Sort(sort.Reverse(tagsToDelete))
 		for _, t := range tagsToDelete {
-			log.Info().Str("repo", t.repo).Str("tag", t.tag).Msg("deleting")
+			log := log.With().Str("tag", t.tag).Logger()
+			log.Warn().Msg("Deleting tag...")
 			err = reg.DeleteManifest(t.repo, t.digest)
 			if err != nil {
 				log.Error().Err(err).Str("repo", t.repo).Str("tag", t.tag).Msg("error deleting manifest")
+			} else {
+				log.Debug().Msg("Tag deleted successfully")
 			}
 		}
 	}
 	if runGC {
+		log := log.With().Str("action", "gc").Logger()
+		log.Warn().Msg("Running garbage collection...")
 		dc, err := docker.NewClientFromEnv()
 		if err != nil {
 			log.Fatal().Err(err).Msg("Failed to initialize docker client")
@@ -250,38 +290,74 @@ func main() {
 		if err != nil {
 			log.Fatal().Err(err).Msg("could not list containers")
 		}
+
+		gcdContainers := make(map[string]error, 0)
+
+		log.Info().Msgf("Found %d containers", len(containers))
+
+	ContainerLoop:
 		for _, c := range containers {
+			log := log.With().Str("container-id", c.ID).Logger()
 			var found bool
+			log.Info().Msgf("Locating docker-registry container with prefix %q from %d entries...", drContainerName, len(c.Names))
 			for _, n := range c.Names {
 				if strings.HasPrefix(path.Base(n), drContainerName) {
+					log.Info().Str("name", n).Msg("Registry container found")
 					found = true
 					break
 				}
 			}
-			if found {
-				var stdOutBuf bytes.Buffer
-				var stdErrBuf bytes.Buffer
-				exec, err := dc.CreateExec(docker.CreateExecOptions{
-					Cmd:          []string{"/bin/registry", "garbage-collect", drConfigFilePath},
-					Container:    c.ID,
-					AttachStdout: true,
-					AttachStderr: true,
-				})
-				if err != nil {
-					log.Fatal().Err(err).Msg("failed to CreateExec")
-				}
-				err = dc.StartExec(exec.ID, docker.StartExecOptions{
-					OutputStream: &stdOutBuf,
-					ErrorStream:  &stdErrBuf,
-				})
 
-				if err != nil {
-					log.Error().Err(err).Msg("error running command")
-				}
-				fmt.Printf("stdout: \n%s\n", stdOutBuf.String())
-				fmt.Printf("stderr: \n%s\n", stdErrBuf.String())
-				break
+			if !found {
+				continue ContainerLoop
+			}
+
+			log.Warn().Msg("Running garbage collection on container")
+
+			var stdOutBuf bytes.Buffer
+			var stdErrBuf bytes.Buffer
+
+			cmd := []string{"/bin/registry", "garbage-collect", drConfigFilePath}
+
+			log = log.With().Str("cmd", strings.Join(cmd, " ")).Logger()
+
+			log.Info().Msg("Calling CreateExec with args...")
+
+			exec, err := dc.CreateExec(docker.CreateExecOptions{
+				Cmd:          cmd,
+				Container:    c.ID,
+				AttachStdout: true,
+				AttachStderr: true,
+			})
+
+			if err != nil {
+				gcdContainers[c.ID] = err
+				log.Error().Err(err).Msg("CreateExec call failed")
+				continue ContainerLoop
+			}
+			err = dc.StartExec(exec.ID, docker.StartExecOptions{
+				OutputStream: &stdOutBuf,
+				ErrorStream:  &stdErrBuf,
+			})
+
+			if err != nil {
+				gcdContainers[c.ID] = err
+				log.Error().Err(err).Msg("error running command")
+			} else {
+				gcdContainers[c.ID] = nil
 			}
+
+			log.Info().Bytes("stdout", stdOutBuf.Bytes()).Bytes("stderr", stdErrBuf.Bytes()).Msg("Output")
+		}
+
+		if len(gcdContainers) == 0 {
+			log.Warn().Msg("No docker registry containers were found to run garbage collection on")
+		} else {
+			dict := zerolog.Dict()
+			for k, v := range gcdContainers {
+				dict.AnErr(k, v)
+			}
+			log.Info().Dict("gc-results", dict).Msgf("Garbage collection was run on %d containers", len(gcdContainers))
 		}
 	}
 }
@@ -293,8 +369,21 @@ type tagsMeta struct {
 	digest  string
 }
 
+func (t tagsMeta) MarshalZerologObject(ev *zerolog.Event) {
+	ev.Time("created", t.created)
+	ev.Str("repo", t.repo)
+	ev.Str("tag", t.tag)
+	ev.Str("digest", t.digest)
+}
+
 type tagsMetaList []tagsMeta
 
+func (t tagsMetaList) MarshalZerologArray(ar *zerolog.Array) {
+	for _, v := range t {
+		ar.Object(v)
+	}
+}
+
 func (t tagsMetaList) Len() int {
 	return len(t)
 }

models/config.go

@@ -1,5 +1,9 @@
 package models
 
+import (
+	"github.com/rs/zerolog"
+)
+
 type Config struct {
 	ReleaseTags []string `decoder:"release_tags,json"`
 
@@ -13,6 +17,13 @@ type Config struct {
 	MinFeatureEvictionDays int `decoder:"min_feature_eviction_days"`
 }
 
+func (c Config) MarshalZerologObject(ev *zerolog.Event) {
+	ev.Strs("release_tags", c.ReleaseTags)
+	ev.Int("min_release_images", c.MinReleaseImages)
+	ev.Int("min_release_eviction_days", c.MinReleaseEvictionDays)
+	ev.Int("min_feature_eviction_days", c.MinFeatureEvictionDays)
+}
+
 func DefaultConfig() *Config {
 	return &Config{
 		ReleaseTags:            []string{"master", "release", "latest"},