refactor: use github.com/go-logr/logr for logging (argoproj#162)

Author: ash2k

Makefile

@@ -25,4 +25,8 @@ agent-image:
 .PHONY: agent-manifests
 agent-manifests:
 	kustomize build ./agent/manifests/cluster-install > ./agent/manifests/install.yaml
-	kustomize build ./agent/manifests/namespace-install > ./agent/manifests/install-namespaced.yaml
+	kustomize build ./agent/manifests/namespace-install > ./agent/manifests/install-namespaced.yaml
+
+.PHONY: generate-mocks
+generate-mocks:
+	go generate -x -v "github.com/argoproj/gitops-engine/pkg/utils/tracing/tracer_testing"

agent/main.go

@@ -14,16 +14,15 @@ import (
 	"text/tabwriter"
 	"time"
 
-	log "github.com/sirupsen/logrus"
+	"github.com/go-logr/logr"
 	"github.com/spf13/cobra"
 	"k8s.io/apimachinery/pkg/apis/meta/v1/unstructured"
 	"k8s.io/client-go/tools/clientcmd"
+	"k8s.io/klog/v2/klogr"
 
 	"github.com/argoproj/gitops-engine/pkg/cache"
 	"github.com/argoproj/gitops-engine/pkg/engine"
 	"github.com/argoproj/gitops-engine/pkg/sync"
-	"github.com/argoproj/gitops-engine/pkg/utils/errors"
-	"github.com/argoproj/gitops-engine/pkg/utils/io"
 	"github.com/argoproj/gitops-engine/pkg/utils/kube"
 )
 
@@ -32,10 +31,9 @@ const (
 )
 
 func main() {
-	if err := newCmd().Execute(); err != nil {
-		fmt.Fprintln(os.Stderr, err)
-		os.Exit(1)
-	}
+	log := klogr.New() // Delegates to klog
+	err := newCmd(log).Execute()
+	checkError(err, log)
 }
 
 type resourceInfo struct {
@@ -98,7 +96,7 @@ func (s *settings) parseManifests() ([]*unstructured.Unstructured, string, error
 	return res, string(revision), nil
 }
 
-func newCmd() *cobra.Command {
+func newCmd(log logr.Logger) *cobra.Command {
 	var (
 		clientConfig  clientcmd.ClientConfig
 		paths         []string
@@ -117,10 +115,10 @@ func newCmd() *cobra.Command {
 			}
 			s := settings{args[0], paths}
 			config, err := clientConfig.ClientConfig()
-			errors.CheckErrorWithCode(err, errors.ErrorCommandSpecific)
+			checkError(err, log)
 			if namespace == "" {
 				namespace, _, err = clientConfig.Namespace()
-				errors.CheckErrorWithCode(err, errors.ErrorCommandSpecific)
+				checkError(err, log)
 			}
 
 			var namespaces []string
@@ -129,6 +127,7 @@ func newCmd() *cobra.Command {
 			}
 			clusterCache := cache.NewClusterCache(config,
 				cache.SetNamespaces(namespaces),
+				cache.SetLogr(log),
 				cache.SetPopulateResourceInfoHandler(func(un *unstructured.Unstructured, isRoot bool) (info interface{}, cacheManifest bool) {
 					// store gc mark of every resource
 					gcMark := un.GetAnnotations()[annotationGCMark]
@@ -138,43 +137,42 @@ func newCmd() *cobra.Command {
 					return
 				}),
 			)
-			gitOpsEngine := engine.NewEngine(config, clusterCache)
-			errors.CheckErrorWithCode(err, errors.ErrorCommandSpecific)
+			gitOpsEngine := engine.NewEngine(config, clusterCache, engine.WithLogr(log))
+			checkError(err, log)
 
-			closer, err := gitOpsEngine.Run()
-			errors.CheckErrorWithCode(err, errors.ErrorCommandSpecific)
-
-			defer io.Close(closer)
+			cleanup, err := gitOpsEngine.Run()
+			checkError(err, log)
+			defer cleanup()
 
 			resync := make(chan bool)
 			go func() {
 				ticker := time.NewTicker(time.Second * time.Duration(resyncSeconds))
 				for {
 					<-ticker.C
-					log.Infof("Synchronization triggered by timer")
+					log.Info("Synchronization triggered by timer")
 					resync <- true
 				}
 			}()
 			http.HandleFunc("/api/v1/sync", func(writer http.ResponseWriter, request *http.Request) {
-				log.Infof("Synchronization triggered by API call")
+				log.Info("Synchronization triggered by API call")
 				resync <- true
 			})
 			go func() {
-				errors.CheckErrorWithCode(http.ListenAndServe(fmt.Sprintf("0.0.0.0:%d", port), nil), errors.ErrorCommandSpecific)
+				checkError(http.ListenAndServe(fmt.Sprintf("0.0.0.0:%d", port), nil), log)
 			}()
 
 			for ; true; <-resync {
 				target, revision, err := s.parseManifests()
 				if err != nil {
-					log.Warnf("failed to parse target state: %v", err)
+					log.Error(err, "Failed to parse target state")
 					continue
 				}
 
 				result, err := gitOpsEngine.Sync(context.Background(), target, func(r *cache.Resource) bool {
 					return r.Info.(*resourceInfo).gcMark == s.getGCMark(r.ResourceKey())
-				}, revision, namespace, sync.WithPrune(prune))
+				}, revision, namespace, sync.WithPrune(prune), sync.WithLogr(log))
 				if err != nil {
-					log.Warnf("failed to synchronize cluster state: %v", err)
+					log.Error(err, "Failed to synchronize cluster state")
 					continue
 				}
 				w := tabwriter.NewWriter(os.Stdout, 0, 0, 2, ' ', 0)
@@ -209,3 +207,11 @@ func addKubectlFlagsToCmd(cmd *cobra.Command) clientcmd.ClientConfig {
 	clientcmd.BindOverrideFlags(&overrides, cmd.PersistentFlags(), kflags)
 	return clientcmd.NewInteractiveDeferredLoadingClientConfig(loadingRules, &overrides, os.Stdin)
 }
+
+// checkError is a convenience function to check if an error is non-nil and exit if it was
+func checkError(err error, log logr.Logger) {
+	if err != nil {
+		log.Error(err, "Fatal error")
+		os.Exit(1)
+	}
+}

go.mod

@@ -4,7 +4,8 @@ go 1.14
 
 require (
 	github.com/evanphx/json-patch v4.9.0+incompatible
-	github.com/sirupsen/logrus v1.6.0
+	github.com/go-logr/logr v0.2.0
+	github.com/golang/mock v1.4.4
 	github.com/spf13/cobra v1.0.0
 	github.com/stretchr/testify v1.6.1
 	golang.org/x/sync v0.0.0-20200625203802-6e8e738ad208
@@ -13,6 +14,7 @@ require (
 	k8s.io/apimachinery v0.19.2
 	k8s.io/cli-runtime v0.19.2
 	k8s.io/client-go v0.19.2
+	k8s.io/klog/v2 v2.2.0
 	k8s.io/kube-aggregator v0.19.2
 	k8s.io/kubectl v0.19.2
 	k8s.io/kubernetes v1.19.2

go.sum

@@ -236,7 +236,10 @@ github.com/golang/groupcache v0.0.0-20191227052852-215e87163ea7 h1:5ZkaAPbicIKTF
 github.com/golang/groupcache v0.0.0-20191227052852-215e87163ea7/go.mod h1:cIg4eruTrX1D+g88fzRXU5OdNfaM+9IcxsU14FzY7Hc=
 github.com/golang/mock v1.1.1/go.mod h1:oTYuIxOrZwtPieC+H1uAHpcLFnEyAGVDL/k47Jfbm0A=
 github.com/golang/mock v1.2.0/go.mod h1:oTYuIxOrZwtPieC+H1uAHpcLFnEyAGVDL/k47Jfbm0A=
+github.com/golang/mock v1.3.1 h1:qGJ6qTW+x6xX/my+8YUVl4WNpX9B7+/l2tRsHGZ7f2s=
 github.com/golang/mock v1.3.1/go.mod h1:sBzyDLLjw3U8JLTeZvSv8jJB+tU5PVekmnlKIyFUx0Y=
+github.com/golang/mock v1.4.4 h1:l75CXGRSwbaYNpl/Z2X1XIIAMSCquvXgpVZDhwEIJsc=
+github.com/golang/mock v1.4.4/go.mod h1:l3mdAwkq5BuhzHwde/uurv3sEJeZMXNpwsxVWU71h+4=
 github.com/golang/protobuf v1.2.0/go.mod h1:6lQm79b+lXiMfvg/cZm0SGofjICqVBUtrP5yJMmIC1U=
 github.com/golang/protobuf v1.3.1/go.mod h1:6lQm79b+lXiMfvg/cZm0SGofjICqVBUtrP5yJMmIC1U=
 github.com/golang/protobuf v1.3.2/go.mod h1:6lQm79b+lXiMfvg/cZm0SGofjICqVBUtrP5yJMmIC1U=
@@ -562,6 +565,7 @@ golang.org/x/mod v0.0.0-20190513183733-4bf6d317e70e/go.mod h1:mXi4GBBbnImb6dmsKG
 golang.org/x/mod v0.1.0/go.mod h1:0QHyrYULN0/3qlju5TqG8bIK38QM8yzMo5ekMj3DlcY=
 golang.org/x/mod v0.1.1-0.20191105210325-c90efee705ee/go.mod h1:QqPTAvyqsEbceGzBzNggFXnrqF1CaUcvgkdR5Ot7KZg=
 golang.org/x/mod v0.2.0/go.mod h1:s0Qsj1ACt9ePp/hMypM3fl4fZqREWJwdYDEqhRiZZUA=
+golang.org/x/mod v0.3.0 h1:RM4zey1++hCTbCVQfnWeKs9/IEsaBLA8vTkd0WVtmH4=
 golang.org/x/mod v0.3.0/go.mod h1:s0Qsj1ACt9ePp/hMypM3fl4fZqREWJwdYDEqhRiZZUA=
 golang.org/x/net v0.0.0-20180724234803-3673e40ba225/go.mod h1:mL1N/T3taQHkDXs73rZJwtUhF3w3ftmwwsq0BUmARs4=
 golang.org/x/net v0.0.0-20180826012351-8a410e7b638d/go.mod h1:mL1N/T3taQHkDXs73rZJwtUhF3w3ftmwwsq0BUmARs4=
@@ -681,6 +685,7 @@ golang.org/x/tools v0.0.0-20191012152004-8de300cfc20a/go.mod h1:b+2E5dAYhXwXZwtn
 golang.org/x/tools v0.0.0-20191119224855-298f0cb1881e/go.mod h1:b+2E5dAYhXwXZwtnZ6UAqBI28+e2cm9otk0dWdXHAEo=
 golang.org/x/tools v0.0.0-20191125144606-a911d9008d1f/go.mod h1:b+2E5dAYhXwXZwtnZ6UAqBI28+e2cm9otk0dWdXHAEo=
 golang.org/x/tools v0.0.0-20191227053925-7b8e75db28f4/go.mod h1:TB2adYChydJhpapKDTa4BR/hXlZSLoq2Wpct/0txZ28=
+golang.org/x/tools v0.0.0-20200616133436-c1934b75d054 h1:HHeAlu5H9b71C+Fx0K+1dGgVFN1DM1/wz4aoGOA5qS8=
 golang.org/x/tools v0.0.0-20200616133436-c1934b75d054/go.mod h1:EkVYQZoAsY45+roYkvgYkIh4xh/qjgUK9TdY2XT94GE=
 golang.org/x/xerrors v0.0.0-20190717185122-a985d3407aa7/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0=
 golang.org/x/xerrors v0.0.0-20191011141410-1b5146add898/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0=

pkg/cache/cluster.go

@@ -9,7 +9,7 @@ import (
 	"sync"
 	"time"
 
-	log "github.com/sirupsen/logrus"
+	"github.com/go-logr/logr"
 	"golang.org/x/sync/semaphore"
 	"k8s.io/apimachinery/pkg/api/errors"
 	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
@@ -23,8 +23,10 @@ import (
 	"k8s.io/client-go/tools/cache"
 	"k8s.io/client-go/tools/pager"
 	watchutil "k8s.io/client-go/tools/watch"
+	"k8s.io/klog/v2/klogr"
 
 	"github.com/argoproj/gitops-engine/pkg/utils/kube"
+	"github.com/argoproj/gitops-engine/pkg/utils/tracing"
 )
 
 const (
@@ -110,21 +112,25 @@ type WeightedSemaphore interface {
 
 // NewClusterCache creates new instance of cluster cache
 func NewClusterCache(config *rest.Config, opts ...UpdateSettingsFunc) *clusterCache {
+	log := klogr.New()
 	cache := &clusterCache{
-		resyncTimeout:           clusterResyncTimeout,
-		settings:                Settings{ResourceHealthOverride: &noopSettings{}, ResourcesFilter: &noopSettings{}},
-		apisMeta:                make(map[schema.GroupKind]*apiMeta),
-		listPageSize:            defaultListPageSize,
-		listPageBufferSize:      defaultListPageBufferSize,
-		listSemaphore:           semaphore.NewWeighted(defaultListSemaphoreWeight),
-		resources:               make(map[kube.ResourceKey]*Resource),
-		nsIndex:                 make(map[string]map[kube.ResourceKey]*Resource),
-		config:                  config,
-		kubectl:                 &kube.KubectlCmd{},
+		resyncTimeout:      clusterResyncTimeout,
+		settings:           Settings{ResourceHealthOverride: &noopSettings{}, ResourcesFilter: &noopSettings{}},
+		apisMeta:           make(map[schema.GroupKind]*apiMeta),
+		listPageSize:       defaultListPageSize,
+		listPageBufferSize: defaultListPageBufferSize,
+		listSemaphore:      semaphore.NewWeighted(defaultListSemaphoreWeight),
+		resources:          make(map[kube.ResourceKey]*Resource),
+		nsIndex:            make(map[string]map[kube.ResourceKey]*Resource),
+		config:             config,
+		kubectl: &kube.KubectlCmd{
+			Log:    log,
+			Tracer: tracing.NopTracer{},
+		},
 		syncTime:                nil,
 		resourceUpdatedHandlers: map[uint64]OnResourceUpdatedHandler{},
 		eventHandlers:           map[uint64]OnEventHandler{},
-		log:                     log.WithField("server", config.Host),
+		log:                     log,
 	}
 	for i := range opts {
 		opts[i](cache)
@@ -154,7 +160,7 @@ type clusterCache struct {
 	nsIndex   map[string]map[kube.ResourceKey]*Resource
 
 	kubectl    kube.Kubectl
-	log        *log.Entry
+	log        logr.Logger
 	config     *rest.Config
 	namespaces []string
 	settings   Settings
@@ -315,7 +321,7 @@ func (c *clusterCache) Invalidate(opts ...UpdateSettingsFunc) {
 	}
 	c.apisMeta = nil
 	c.namespacedResources = nil
-	c.log.Warnf("invalidated cluster")
+	c.log.Info("Invalidated cluster")
 }
 
 func (c *clusterCache) synced() bool {
@@ -336,7 +342,7 @@ func (c *clusterCache) stopWatching(gk schema.GroupKind, ns string) {
 		info.watchCancel()
 		delete(c.apisMeta, gk)
 		c.replaceResourceCache(gk, nil, ns)
-		c.log.Warnf("Stop watching: %s not found", gk)
+		c.log.Info(fmt.Sprintf("Stop watching: %s not found", gk))
 	}
 }
 
@@ -398,7 +404,7 @@ func (c *clusterCache) listResources(ctx context.Context, resClient dynamic.Reso
 }
 
 func (c *clusterCache) watchEvents(ctx context.Context, api kube.APIResourceInfo, resClient dynamic.ResourceInterface, ns string, resourceVersion string) {
-	kube.RetryUntilSucceed(ctx, watchResourcesRetryTimeout, fmt.Sprintf("watch %s on %s", api.GroupKind, c.config.Host), func() (err error) {
+	kube.RetryUntilSucceed(ctx, watchResourcesRetryTimeout, fmt.Sprintf("watch %s on %s", api.GroupKind, c.config.Host), c.log, func() (err error) {
 		defer func() {
 			if r := recover(); r != nil {
 				err = fmt.Errorf("Recovered from panic: %+v\n%s", r, debug.Stack())
@@ -493,7 +499,7 @@ func (c *clusterCache) watchEvents(ctx context.Context, api kube.APIResourceInfo
 							return c.startMissingWatches()
 						})
 						if err != nil {
-							c.log.Warnf("Failed to start missing watch: %v", err)
+							c.log.Error(err, "Failed to start missing watch")
 						}
 					}
 				}
@@ -586,8 +592,7 @@ func (c *clusterCache) sync() error {
 	})
 
 	if err != nil {
-		log.Errorf("Failed to sync cluster %s: %v", c.config.Host, err)
-		return err
+		return fmt.Errorf("failed to sync cluster %s: %v", c.config.Host, err)
 	}
 
 	c.log.Info("Cluster successfully synced")
@@ -653,7 +658,13 @@ func (c *clusterCache) IterateHierarchy(key kube.ResourceKey, action func(resour
 				})
 				child := children[0]
 				action(child, nsNodes)
-				child.iterateChildren(nsNodes, map[kube.ResourceKey]bool{res.ResourceKey(): true}, action)
+				child.iterateChildren(nsNodes, map[kube.ResourceKey]bool{res.ResourceKey(): true}, func(err error, child *Resource, namespaceResources map[kube.ResourceKey]*Resource) {
+					if err != nil {
+						c.log.V(2).Info(err.Error())
+						return
+					}
+					action(child, namespaceResources)
+				})
 			}
 		}
 	}
@@ -744,7 +755,7 @@ func (c *clusterCache) GetManagedLiveObjs(targetObjs []*unstructured.Unstructure
 			converted, err := c.kubectl.ConvertToVersion(managedObj, targetObj.GroupVersionKind().Group, targetObj.GroupVersionKind().Version)
 			if err != nil {
 				// fallback to loading resource from kubernetes if conversion fails
-				log.Debugf("Failed to convert resource: %v", err)
+				c.log.V(1).Info(fmt.Sprintf("Failed to convert resource: %v", err))
 				managedObj, err = c.kubectl.GetResource(context.TODO(), c.config, targetObj.GroupVersionKind(), managedObj.GetName(), managedObj.GetNamespace())
 				if err != nil {
 					if errors.IsNotFound(err) {

pkg/cache/references.go

@@ -5,7 +5,6 @@ import (
 	"fmt"
 	"strings"
 
-	log "github.com/sirupsen/logrus"
 	v1 "k8s.io/api/apps/v1"
 	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
 	"k8s.io/apimachinery/pkg/apis/meta/v1/unstructured"
@@ -52,7 +51,7 @@ func (c *clusterCache) resolveResourceReferences(un *unstructured.Unstructured)
 
 	case (un.GroupVersionKind().Group == "apps" || un.GroupVersionKind().Group == "extensions") && un.GetKind() == kube.StatefulSetKind:
 		if refs, err := isStatefulSetChild(un); err != nil {
-			log.Errorf("Failed to extract StatefulSet %s/%s PVC references: %v", un.GetNamespace(), un.GetName(), err)
+			c.log.Error(err, fmt.Sprintf("Failed to extract StatefulSet %s/%s PVC references", un.GetNamespace(), un.GetName()))
 		} else {
 			isInferredParentOf = refs
 		}

pkg/cache/resource.go

@@ -1,7 +1,8 @@
 package cache
 
 import (
-	log "github.com/sirupsen/logrus"
+	"fmt"
+
 	v1 "k8s.io/api/core/v1"
 	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
 	"k8s.io/apimachinery/pkg/apis/meta/v1/unstructured"
@@ -84,14 +85,14 @@ func newResourceKeySet(set map[kube.ResourceKey]bool, keys ...kube.ResourceKey)
 	return newSet
 }
 
-func (r *Resource) iterateChildren(ns map[kube.ResourceKey]*Resource, parents map[kube.ResourceKey]bool, action func(child *Resource, namespaceResources map[kube.ResourceKey]*Resource)) {
+func (r *Resource) iterateChildren(ns map[kube.ResourceKey]*Resource, parents map[kube.ResourceKey]bool, action func(err error, child *Resource, namespaceResources map[kube.ResourceKey]*Resource)) {
 	for childKey, child := range ns {
 		if r.isParentOf(ns[childKey]) {
 			if parents[childKey] {
 				key := r.ResourceKey()
-				log.Warnf("Circular dependency detected. %s is child and parent of %s", childKey.String(), key.String())
+				action(fmt.Errorf("circular dependency detected. %s is child and parent of %s", childKey.String(), key.String()), child, ns)
 			} else {
-				action(child, ns)
+				action(nil, child, ns)
 				child.iterateChildren(ns, newResourceKeySet(parents, r.ResourceKey()), action)
 			}
 		}