DVO-203: Revamp logging

go.mod

@@ -17,6 +17,7 @@ require (
 	github.com/spf13/pflag v1.0.5
 	github.com/spf13/viper v1.17.0
 	github.com/stretchr/testify v1.8.4
+	go.uber.org/zap v1.25.0
 	golang.stackrox.io/kube-linter v0.6.5
 	k8s.io/api v0.29.0
 	k8s.io/apimachinery v0.29.0
@@ -124,14 +125,13 @@ require (
 	go.opentelemetry.io/otel/trace v1.19.0 // indirect
 	go.starlark.net v0.0.0-20230525235612-a134d8f9ddca // indirect
 	go.uber.org/multierr v1.11.0 // indirect
-	go.uber.org/zap v1.25.0 // indirect
-	golang.org/x/crypto v0.17.0 // indirect
+	golang.org/x/crypto v0.21.0 // indirect
 	golang.org/x/exp v0.0.0-20230905200255-921286631fa9 // indirect
-	golang.org/x/net v0.17.0 // indirect
+	golang.org/x/net v0.23.0 // indirect
 	golang.org/x/oauth2 v0.12.0 // indirect
 	golang.org/x/sync v0.4.0 // indirect
-	golang.org/x/sys v0.15.0 // indirect
-	golang.org/x/term v0.15.0 // indirect
+	golang.org/x/sys v0.18.0 // indirect
+	golang.org/x/term v0.18.0 // indirect
 	golang.org/x/text v0.14.0 // indirect
 	golang.org/x/time v0.3.0 // indirect
 	golang.org/x/tools v0.14.0 // indirect

go.sum

@@ -513,8 +513,8 @@ golang.org/x/crypto v0.0.0-20210421170649-83a5a9bb288b/go.mod h1:T9bdIzuCu7OtxOm
 golang.org/x/crypto v0.0.0-20210921155107-089bfa567519/go.mod h1:GvvjBRRGRdwPK5ydBHafDWAxML/pGHZbMvKqRZ5+Abc=
 golang.org/x/crypto v0.0.0-20220722155217-630584e8d5aa/go.mod h1:IxCIyHEi3zRg3s0A5j5BB6A9Jmi73HwBIUl50j+osU4=
 golang.org/x/crypto v0.3.0/go.mod h1:hebNnKkNXi2UzZN1eVRvBB7co0a+JxK6XbPiWVs/3J4=
-golang.org/x/crypto v0.17.0 h1:r8bRNjWL3GshPW3gkd+RpvzWrZAwPS49OmTGZ/uhM4k=
-golang.org/x/crypto v0.17.0/go.mod h1:gCAAfMLgwOJRpTjQ2zCCt2OcSfYMTeZVSRtQlPC7Nq4=
+golang.org/x/crypto v0.21.0 h1:X31++rzVUdKhX5sWmSOFZxx8UW/ldWx55cbf08iNAMA=
+golang.org/x/crypto v0.21.0/go.mod h1:0BP7YvVV9gBbVKyeTG0Gyn+gZm94bibOW5BjDEYAOMs=
 golang.org/x/exp v0.0.0-20190121172915-509febef88a4/go.mod h1:CJ0aWSM057203Lf6IL+f9T1iT9GByDxfZKAQTCR3kQA=
 golang.org/x/exp v0.0.0-20190306152737-a1d7652674e8/go.mod h1:CJ0aWSM057203Lf6IL+f9T1iT9GByDxfZKAQTCR3kQA=
 golang.org/x/exp v0.0.0-20190510132918-efd6b22b2522/go.mod h1:ZjyILWgesfNpC6sMxTJOJm9Kp84zZh5NQWvqDGG3Qr8=
@@ -591,8 +591,8 @@ golang.org/x/net v0.0.0-20210405180319-a5a99cb37ef4/go.mod h1:p54w0d4576C0XHj96b
 golang.org/x/net v0.0.0-20211112202133-69e39bad7dc2/go.mod h1:9nx3DQGgdP8bBQD5qxJ1jj9UTztislL4KSBs9R2vV5Y=
 golang.org/x/net v0.0.0-20220722155237-a158d28d115b/go.mod h1:XRhObCWvk6IyKnWLug+ECip1KBveYUHfp+8e9klMJ9c=
 golang.org/x/net v0.2.0/go.mod h1:KqCZLdyyvdV855qA2rE3GC2aiw5xGR5TEjj8smXukLY=
-golang.org/x/net v0.17.0 h1:pVaXccu2ozPjCXewfr1S7xza/zcXTity9cCdXQYSjIM=
-golang.org/x/net v0.17.0/go.mod h1:NxSsAGuq816PNPmqtQdLE42eU2Fs7NoRIZrHJAlaCOE=
+golang.org/x/net v0.23.0 h1:7EYJ93RZ9vYSZAIb2x3lnuvqO5zneoD6IvWjuhfxjTs=
+golang.org/x/net v0.23.0/go.mod h1:JKghWKKOSdJwpW2GEx0Ja7fmaKnMsbu+MWVZTokSYmg=
 golang.org/x/oauth2 v0.0.0-20180821212333-d2e6202438be/go.mod h1:N/0e6XlmueqKjAGxoOufVs8QHGRruUQn6yWY3a++T0U=
 golang.org/x/oauth2 v0.0.0-20190226205417-e64efc72b421/go.mod h1:gOpvHmFTYa4IltrdGE7lF6nIHvwfUNPOp7c8zoXwtLw=
 golang.org/x/oauth2 v0.0.0-20190604053449-0f29369cfe45/go.mod h1:gOpvHmFTYa4IltrdGE7lF6nIHvwfUNPOp7c8zoXwtLw=
@@ -663,14 +663,14 @@ golang.org/x/sys v0.0.0-20220520151302-bc2c85ada10a/go.mod h1:oPkhp1MJrh7nUepCBc
 golang.org/x/sys v0.0.0-20220715151400-c0bba94af5f8/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
 golang.org/x/sys v0.0.0-20220722155257-8c9f86f7a55f/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
 golang.org/x/sys v0.2.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
-golang.org/x/sys v0.15.0 h1:h48lPFYpsTvQJZF4EKyI4aLHaev3CxivZmv7yZig9pc=
-golang.org/x/sys v0.15.0/go.mod h1:/VUhepiaJMQUp4+oa/7Zr1D23ma6VTLIYjOOTFZPUcA=
+golang.org/x/sys v0.18.0 h1:DBdB3niSjOA/O0blCZBqDefyWNYveAYMNF1Wum0DYQ4=
+golang.org/x/sys v0.18.0/go.mod h1:/VUhepiaJMQUp4+oa/7Zr1D23ma6VTLIYjOOTFZPUcA=
 golang.org/x/term v0.0.0-20201126162022-7de9c90e9dd1/go.mod h1:bj7SfCRtBDWHUb9snDiAeCFNEtKQo2Wmx5Cou7ajbmo=
 golang.org/x/term v0.0.0-20210927222741-03fcf44c2211/go.mod h1:jbD1KX2456YbFQfuXm/mYQcufACuNUgVhRMnK/tPxf8=
 golang.org/x/term v0.0.0-20220526004731-065cf7ba2467/go.mod h1:jbD1KX2456YbFQfuXm/mYQcufACuNUgVhRMnK/tPxf8=
 golang.org/x/term v0.2.0/go.mod h1:TVmDHMZPmdnySmBfhjOoOdhjzdE1h4u1VwSiw2l1Nuc=
-golang.org/x/term v0.15.0 h1:y/Oo/a/q3IXu26lQgl04j/gjuBDOBlx7X6Om1j2CPW4=
-golang.org/x/term v0.15.0/go.mod h1:BDl952bC7+uMoWR75FIrCDx79TPU9oHkTZ9yRbYOrX0=
+golang.org/x/term v0.18.0 h1:FcHjZXDMxI8mM3nwhX9HlKop4C0YQvCVCdwYl2wOtE8=
+golang.org/x/term v0.18.0/go.mod h1:ILwASektA3OnRv7amZ1xhE/KTR+u50pbXfZ03+6Nx58=
 golang.org/x/text v0.0.0-20170915032832-14c0d48ead0c/go.mod h1:NqM8EUOU14njkJ3fqMW+pc6Ldnwhi/IjpwHt7yyuwOQ=
 golang.org/x/text v0.3.0/go.mod h1:NqM8EUOU14njkJ3fqMW+pc6Ldnwhi/IjpwHt7yyuwOQ=
 golang.org/x/text v0.3.1-0.20180807135948-17ff2d5776d2/go.mod h1:NqM8EUOU14njkJ3fqMW+pc6Ldnwhi/IjpwHt7yyuwOQ=

internal/options/options.go

@@ -6,6 +6,7 @@ import (
 	"os"
 
 	"github.com/spf13/pflag"
+	"go.uber.org/zap/zapcore"
 	"sigs.k8s.io/controller-runtime/pkg/log/zap"
 )
 
@@ -39,6 +40,7 @@ func (o *Options) processFlags() {
 	// Add the zap logger flag set to the CLI. The flag set must
 	// be added before calling pflag.Parse().
 	o.Zap.BindFlags(flag.CommandLine)
+	o.Zap.Level = zapcore.Level(-1) // Set to debug to not alter current behavior. TODO: Remove when configurable.
 
 	// Add flags registered by imported packages (e.g. glog and
 	// controller-runtime)

main.go

@@ -63,10 +63,11 @@ func main() {
 	logf.SetLogger(zap.New(zap.UseFlagOptions(&opts.Zap)))
 
 	log := logf.Log.WithName("DeploymentValidation")
+	logVersion(log)
 
 	log.Info("Setting Up Manager")
 
-	mgr, err := setupManager(log, opts)
+	mgr, err := setupManager(log.V(1), opts)
 	if err != nil {
 		fail(log, err, "Unexpected error occurred while setting up manager")
 	}
@@ -78,34 +79,33 @@ func main() {
 	}
 }
 
-func setupManager(log logr.Logger, opts options.Options) (manager.Manager, error) {
-	logVersion(log)
+func setupManager(logger logr.Logger, opts options.Options) (manager.Manager, error) {
 
-	log.Info("Load KubeConfig")
+	logger.Info("Load KubeConfig")
 
 	cfg, err := config.GetConfig()
 	if err != nil {
 		return nil, fmt.Errorf("getting config: %w", err)
 	}
 
-	log.Info("Initialize Manager")
+	logger.Info("Initialize Manager")
 
-	mgr, err := initManager(log, opts, cfg)
+	mgr, err := initManager(logger, opts, cfg)
 	if err != nil {
 		return nil, fmt.Errorf("initializing manager: %w", err)
 	}
 
-	log.Info("Registering Components")
+	logger.Info("Registering Components")
 
-	log.Info("Initialize Prometheus Registry")
+	logger.Info("Initialize Prometheus Registry")
 
 	reg := prometheus.NewRegistry()
 	metrics, err := dvoProm.PreloadMetrics(reg)
 	if err != nil {
 		return nil, fmt.Errorf("preloading kube-linter metrics: %w", err)
 	}
 
-	log.Info(fmt.Sprintf("Initialize Prometheus metrics endpoint on %q", opts.MetricsEndpoint()))
+	logger.Info("Initialize Prometheus metrics endpoint", "endpoint", opts.MetricsEndpoint())
 
 	srv, err := dvoProm.NewServer(reg, opts.MetricsPath, fmt.Sprintf(":%d", opts.MetricsPort))
 	if err != nil {
@@ -116,7 +116,7 @@ func setupManager(log logr.Logger, opts options.Options) (manager.Manager, error
 		return nil, fmt.Errorf("adding metrics server to manager: %w", err)
 	}
 
-	log.Info("Initialize ConfigMap watcher")
+	logger.Info("Initialize ConfigMap watcher")
 
 	cmWatcher, err := configmap.NewWatcher(cfg)
 	if err != nil {
@@ -127,14 +127,14 @@ func setupManager(log logr.Logger, opts options.Options) (manager.Manager, error
 		return nil, fmt.Errorf("adding configmap watcher to manager: %w", err)
 	}
 
-	log.Info("Initialize Validation Engine")
+	logger.Info("Initialize Validation Engine")
 
 	validationEngine, err := validations.NewValidationEngine(opts.ConfigFile, metrics)
 	if err != nil {
 		return nil, fmt.Errorf("initializing validation engine: %w", err)
 	}
 
-	log.Info("Initialize Reconciler")
+	logger.Info("Initialize Reconciler")
 
 	discoveryClient, err := discovery.NewDiscoveryClientForConfig(mgr.GetConfig())
 	if err != nil {
@@ -153,16 +153,16 @@ func setupManager(log logr.Logger, opts options.Options) (manager.Manager, error
 	return mgr, nil
 }
 
-func fail(log logr.Logger, err error, msg string) {
-	log.Error(err, msg)
+func fail(logger logr.Logger, err error, msg string) {
+	logger.Error(err, msg)
 
 	os.Exit(1)
 }
 
-func logVersion(log logr.Logger) {
-	log.Info(fmt.Sprintf("Operator Version: %s", version.Version))
-	log.Info(fmt.Sprintf("Go Version: %s", runtime.Version()))
-	log.Info(fmt.Sprintf("Go OS/Arch: %s/%s", runtime.GOOS, runtime.GOARCH))
+func logVersion(logger logr.Logger) {
+	logger.Info(fmt.Sprintf("Operator Version: %s", version.Version))
+	logger.Info(fmt.Sprintf("Go Version: %s", runtime.Version()))
+	logger.Info(fmt.Sprintf("Go OS/Arch: %s/%s", runtime.GOOS, runtime.GOARCH))
 }
 
 func initializeScheme() (*k8sruntime.Scheme, error) {
@@ -185,7 +185,7 @@ func initializeScheme() (*k8sruntime.Scheme, error) {
 
 var errWatchNamespaceNotSet = errors.New("'WatchNamespace' not set")
 
-func getManagerOptions(scheme *k8sruntime.Scheme, opts options.Options) (manager.Options, error) {
+func getManagerOptions(scheme *k8sruntime.Scheme, opts options.Options, logger logr.Logger) (manager.Options, error) {
 	ns, ok := opts.GetWatchNamespace()
 	if !ok {
 		return manager.Options{}, errWatchNamespaceNotSet
@@ -196,6 +196,7 @@ func getManagerOptions(scheme *k8sruntime.Scheme, opts options.Options) (manager
 		// disable caching of everything
 		NewClient: newClient,
 		Scheme:    scheme,
+		Logger:    logger,
 	}
 
 	// disable controller-runtime managed prometheus endpoint
@@ -241,15 +242,15 @@ func kubeClientQPS() (float32, error) {
 	return qps, err
 }
 
-func initManager(log logr.Logger, opts options.Options, cfg *rest.Config) (manager.Manager, error) {
-	log.Info("Initialize Scheme")
+func initManager(logger logr.Logger, opts options.Options, cfg *rest.Config) (manager.Manager, error) {
+	logger.Info("Initialize Scheme")
 	scheme, err := initializeScheme()
 	if err != nil {
 		return nil, fmt.Errorf("initializing scheme: %w", err)
 	}
 
-	log.Info("Getting Manager Options")
-	mgrOpts, err := getManagerOptions(scheme, opts)
+	logger.Info("Getting Manager Options")
+	mgrOpts, err := getManagerOptions(scheme, opts, logger)
 	if err != nil {
 		return nil, fmt.Errorf("getting manager options: %w", err)
 	}
@@ -259,7 +260,7 @@ func initManager(log logr.Logger, opts options.Options, cfg *rest.Config) (manag
 		return nil, fmt.Errorf("getting new manager: %w", err)
 	}
 
-	log.Info("Adding Healthz and Readyz checks")
+	logger.Info("Adding Healthz and Readyz checks")
 	if err := mgr.AddHealthzCheck("health", healthz.Ping); err != nil {
 		return nil, fmt.Errorf("adding healthz check: %w", err)
 	}

pkg/controller/generic_reconciler.go

@@ -65,7 +65,7 @@ func NewGenericReconciler(
 		watchNamespaces:       newWatchNamespacesCache(),
 		objectValidationCache: newValidationCache(),
 		currentObjects:        newValidationCache(),
-		logger:                ctrl.Log.WithName("reconcile"),
+		logger:                ctrl.Log.WithName("GenericReconciler"),
 		cmWatcher:             cmw,
 		validationEngine:      validationEngine,
 	}, nil
@@ -116,6 +116,7 @@ func (gr *GenericReconciler) Start(ctx context.Context) error {
 			// stop reconciling
 			return nil
 		default:
+			gr.logger.Info("Reconciliation loop has started")
 			if err := gr.reconcileEverything(ctx); err != nil && !errors.Is(err, context.Canceled) {
 				// TODO: Improve error handling so that error can be returned to manager from here
 				// this is done to make sure errors caused by skew in k8s version on server and
@@ -124,6 +125,7 @@ func (gr *GenericReconciler) Start(ctx context.Context) error {
 				// nikthoma: oct 11, 2022
 				gr.logger.Error(err, "error fetching and validating resource types")
 			}
+			gr.logger.Info("Reconciliation loop has ended")
 		}
 	}
 }
@@ -147,10 +149,11 @@ func (gr *GenericReconciler) LookForConfigUpdates(ctx context.Context) {
 			gr.objectValidationCache.drain()
 			gr.validationEngine.ResetMetrics()
 
-			gr.logger.Info(
+			gr.logger.V(1).Info(
 				"Current set of enabled checks",
 				"checks", strings.Join(gr.validationEngine.GetEnabledChecks(), ", "),
 			)
+			gr.logger.Info("The ConfigMap has been updated")
 
 		case <-ctx.Done():
 			return
@@ -169,7 +172,7 @@ func (gr *GenericReconciler) reconcileEverything(ctx context.Context) error {
 	})
 
 	for i, resource := range gr.apiResources {
-		gr.logger.Info("apiResource", "no", i+1, "Group", resource.Group,
+		gr.logger.V(1).Info("apiResource", "no", i+1, "Group", resource.Group,
 			"Version", resource.Version,
 			"Kind", resource.Kind)
 	}
@@ -287,15 +290,17 @@ func (gr *GenericReconciler) processNamespacedResources(
 	ctx context.Context, gvks []schema.GroupVersionKind, namespaces *[]namespace) error {
 
 	for _, ns := range *namespaces {
+		logger := gr.logger.WithValues("ns", ns.name).V(1)
+
 		relatedObjects, err := gr.groupAppObjects(ctx, ns.name, gvks)
 		if err != nil {
 			return err
 		}
 		for label, objects := range relatedObjects {
-			gr.logger.Info("reconcileNamespaceResources",
-				"Reconciling group of", len(objects), "objects with labels", label,
-				"in the namespace", ns.name)
-			err := gr.reconcileGroupOfObjects(objects, ns.uid)
+			logger.Info("Reconciling Namespace Resources",
+				"items", len(objects), "labels", label)
+
+			err := gr.reconcileGroupOfObjects(objects, ns)
 			if err != nil {
 				return fmt.Errorf(
 					"reconciling related objects with labels '%s': %w", label, err,
@@ -307,10 +312,10 @@ func (gr *GenericReconciler) processNamespacedResources(
 	return nil
 }
 
-func (gr *GenericReconciler) reconcileGroupOfObjects(objs []*unstructured.Unstructured, namespaceUID string) error {
+func (gr *GenericReconciler) reconcileGroupOfObjects(objs []*unstructured.Unstructured, ns namespace) error {
 
-	if gr.allObjectsValidated(objs, namespaceUID) {
-		gr.logger.Info("reconcileGroupOfObjects", "All objects are validated", "Nothing to do")
+	if gr.allObjectsValidated(objs, ns.uid) {
+		gr.logger.V(1).Info("All objects are validated, ending loop", "ns", ns.name)
 		return nil
 	}
 
@@ -323,12 +328,12 @@ func (gr *GenericReconciler) reconcileGroupOfObjects(objs []*unstructured.Unstru
 		cliObjects = append(cliObjects, typedClientObject)
 	}
 
-	outcome, err := gr.validationEngine.RunValidationsForObjects(cliObjects, namespaceUID)
+	outcome, err := gr.validationEngine.RunValidationsForObjects(cliObjects, ns.uid)
 	if err != nil {
 		return fmt.Errorf("running validations: %w", err)
 	}
 	for _, o := range objs {
-		gr.objectValidationCache.store(o, namespaceUID, outcome)
+		gr.objectValidationCache.store(o, ns.uid, outcome)
 	}
 
 	return nil

pkg/validations/utils.go

@@ -23,8 +23,7 @@ import (
 func GetKubeLinterRegistry() (checkregistry.CheckRegistry, error) {
 	registry := checkregistry.New()
 	if err := builtinchecks.LoadInto(registry); err != nil {
-		log.Error(err, "failed to load kube-linter built-in validations")
-		return nil, err
+		return nil, fmt.Errorf("failed to load kube-linter built-in validations: %w", err)
 	}
 
 	return registry, nil
@@ -49,8 +48,7 @@ func GetAllNamesFromRegistry(reg checkregistry.CheckRegistry) ([]string, error)
 
 	checks, err := configresolver.GetEnabledChecksAndValidate(&cfg, reg)
 	if err != nil {
-		log.Error(err, "error getting enabled validations")
-		return nil, err
+		return nil, fmt.Errorf("error getting enabled validations: %w", err)
 	}
 
 	return checks, nil