Unify and split logging into levels to reduce log flooding in production

Makefile

@@ -20,6 +20,8 @@ QUIET_FLAG = --quiet
 V_FLAG =
 S_FLAG = -s
 X_FLAG =
+ZAP_ENCODER_FLAG = --zap-encoder=console
+ZAP_LEVEL_FLAG =
 ifeq ($(VERBOSE),1)
 	Q =
 endif
@@ -30,7 +32,18 @@ ifeq ($(VERBOSE),2)
 	S_FLAG =
 	V_FLAG = -v
 	X_FLAG = -x
+	ZAP_LEVEL_FLAG = --zap-level 1
 endif
+ifeq ($(VERBOSE),3)
+	Q_FLAG =
+	QUIET_FLAG =
+	S_FLAG =
+	V_FLAG = -v
+	X_FLAG = -x
+	ZAP_LEVEL_FLAG = --zap-level 2
+endif
+
+ZAP_FLAGS = $(ZAP_ENCODER_FLAG) $(ZAP_LEVEL_FLAG)
 
 # Create output directory for artifacts and test results. ./out is supposed to
 # be a safe place for all targets to write to while knowing that all content
@@ -191,6 +204,7 @@ test-e2e: e2e-setup
 			--namespace $(TEST_NAMESPACE) \
 			--up-local \
 			--go-test-flags "-timeout=15m" \
+			--local-operator-flags "$(ZAP_FLAGS)" \
 			$(OPERATOR_SDK_EXTRA_ARGS)
 
 .PHONY: test-unit
@@ -226,6 +240,7 @@ test-e2e-olm-ci:
 	$(Q)operator-sdk --verbose test local ./test/e2e \
 			--no-setup \
 			--go-test-flags "-timeout=15m" \
+			--local-operator-flags "$(ZAP_FLAGS)" \
 			$(OPERATOR_SDK_EXTRA_ARGS)
 
 ## -- Build Go binary and OCI image targets --
@@ -292,7 +307,7 @@ push-image: build-image
 .PHONY: local
 ## Local: Run operator locally
 local: deploy-clean deploy-rbac deploy-crds
-	$(Q)operator-sdk --verbose up local
+	$(Q)operator-sdk --verbose up local --operator-flags "$(ZAP_FLAGS)"
 
 .PHONY: deploy-rbac
 ## Deploy-RBAC: Setup service account and deploy RBAC

cmd/manager/main.go

@@ -23,25 +23,26 @@ import (
 	"k8s.io/client-go/rest"
 	"sigs.k8s.io/controller-runtime/pkg/client/config"
 	"sigs.k8s.io/controller-runtime/pkg/manager"
-	logf "sigs.k8s.io/controller-runtime/pkg/runtime/log"
+
 	"sigs.k8s.io/controller-runtime/pkg/runtime/signals"
 
 	"github.com/redhat-developer/service-binding-operator/pkg/apis"
 	"github.com/redhat-developer/service-binding-operator/pkg/controller"
+	"github.com/redhat-developer/service-binding-operator/pkg/log"
 )
 
 // Change below variables to serve metrics on different host or port.
 var (
 	metricsHost               = "0.0.0.0"
 	metricsPort         int32 = 8383
 	operatorMetricsPort int32 = 8686
+	mainLog                = log.NewLog("main")
 )
-var log = logf.Log.WithName("cmd")
 
 func printVersion() {
-	log.Info(fmt.Sprintf("Go Version: %s", runtime.Version()))
-	log.Info(fmt.Sprintf("Go OS/Arch: %s/%s", runtime.GOOS, runtime.GOARCH))
-	log.Info(fmt.Sprintf("Version of operator-sdk: %v", sdkVersion.Version))
+	mainLog.Info(fmt.Sprintf("Go Version: %s", runtime.Version()))
+	mainLog.Info(fmt.Sprintf("Go OS/Arch: %s/%s", runtime.GOOS, runtime.GOARCH))
+	mainLog.Info(fmt.Sprintf("Version of operator-sdk: %v", sdkVersion.Version))
 }
 
 // getOperatorName based on environment variable OPERATOR_NAME, or returns the default name for
@@ -63,20 +64,20 @@ func main() {
 	pflag.CommandLine.AddFlagSet(zap.FlagSet())
 	pflag.CommandLine.AddGoFlagSet(flag.CommandLine)
 	pflag.Parse()
-	logf.SetLogger(zap.Logger())
+	log.SetLog(zap.Logger())
 
 	printVersion()
 
 	namespace, err := k8sutil.GetWatchNamespace()
 	if err != nil {
-		log.Error(err, "Failed to get watch namespace")
+		mainLog.Error(err, "Failed to get watch namespace")
 		os.Exit(1)
 	}
 
 	// Get a config to talk to the apiserver
 	cfg, err := config.GetConfig()
 	if err != nil {
-		log.Error(err, "Failed to acquire a configuration to talk to the API server")
+		mainLog.Error(err, "Failed to acquire a configuration to talk to the API server")
 		os.Exit(1)
 	}
 
@@ -87,11 +88,11 @@ func main() {
 		// Become the leader before proceeding
 		err = leader.Become(ctx, fmt.Sprintf("%s-lock", getOperatorName()))
 		if err != nil {
-			log.Error(err, "Failed to become the leader")
+			mainLog.Error(err, "Failed to become the leader")
 			os.Exit(1)
 		}
 	} else {
-		log.Info("Warning: Leader election is disabled")
+		mainLog.Warning("Leader election is disabled")
 	}
 
 	// Create a new Cmd to provide shared dependencies and start components
@@ -101,31 +102,31 @@ func main() {
 		MetricsBindAddress: fmt.Sprintf("%s:%d", metricsHost, metricsPort),
 	})
 	if err != nil {
-		log.Error(err, "Error on creating a new manager instance")
+		mainLog.Error(err, "Error on creating a new manager instance")
 		os.Exit(1)
 	}
 
-	log.Info("Registering Components.")
+	mainLog.Info("Registering Components.")
 
 	// Setup Scheme for all resources
 	if err := apis.AddToScheme(mgr.GetScheme()); err != nil {
-		log.Error(err, "Error adding local operator scheme")
+		mainLog.Error(err, "Error adding local operator scheme")
 		os.Exit(1)
 	}
 
 	if err := osappsv1.AddToScheme(mgr.GetScheme()); err != nil {
-		log.Error(err, "Error on adding OS APIs to scheme")
+		mainLog.Error(err, "Error on adding OS APIs to scheme")
 		os.Exit(1)
 	}
 
 	// Setup all Controllers
 	if err := controller.AddToManager(mgr); err != nil {
-		log.Error(err, "Failed to setup the controller manager")
+		mainLog.Error(err, "Failed to setup the controller manager")
 		os.Exit(1)
 	}
 
 	if err = serveCRMetrics(cfg); err != nil {
-		log.Info("Could not generate and serve custom resource metrics", "error", err.Error())
+		mainLog.Info("Could not generate and serve custom resource metrics", "error", err.Error())
 	}
 
 	// Add to the below struct any other metrics ports you want to expose.
@@ -136,27 +137,27 @@ func main() {
 	// Create Service object to expose the metrics port(s).
 	service, err := metrics.CreateMetricsService(ctx, cfg, servicePorts)
 	if err != nil {
-		log.Info("Could not create metrics Service", "error", err.Error())
+		mainLog.Info("Could not create metrics Service", "error", err.Error())
 	}
 
 	// CreateServiceMonitors will automatically create the prometheus-operator ServiceMonitor resources
 	// necessary to configure Prometheus to scrape metrics from this operator.
 	services := []*v1.Service{service}
 	_, err = metrics.CreateServiceMonitors(cfg, namespace, services)
 	if err != nil {
-		log.Info("Could not create ServiceMonitor object", "error", err.Error())
+		mainLog.Info("Could not create ServiceMonitor object", "error", err.Error())
 		// If this operator is deployed to a cluster without the prometheus-operator running, it will return
 		// ErrServiceMonitorNotPresent, which can be used to safely skip ServiceMonitor creation.
 		if err == metrics.ErrServiceMonitorNotPresent {
-			log.Info("Install prometheus-operator in your cluster to create ServiceMonitor objects", "error", err.Error())
+			mainLog.Info("Install prometheus-operator in your cluster to create ServiceMonitor objects", "error", err.Error())
 		}
 	}
 
-	log.Info("Starting the Cmd.")
+	mainLog.Info("Starting the Cmd.")
 
 	// Start the Cmd
 	if err := mgr.Start(signals.SetupSignalHandler()); err != nil {
-		log.Error(err, "Manager exited non-zero")
+		mainLog.Error(err, "Manager exited non-zero")
 		os.Exit(1)
 	}
 }

pkg/controller/servicebindingrequest/annotations.go

@@ -9,13 +9,18 @@ import (
 	"k8s.io/client-go/dynamic"
 
 	"github.com/redhat-developer/service-binding-operator/pkg/apis/apps/v1alpha1"
+	"github.com/redhat-developer/service-binding-operator/pkg/log"
 )
 
 const (
 	sbrNamespaceAnnotation = "service-binding-operator.apps.openshift.io/binding-namespace"
 	sbrNameAnnotation      = "service-binding-operator.apps.openshift.io/binding-name"
 )
 
+var (
+	annotationsLog = log.NewLog("annotations")
+)
+
 // extractSBRNamespacedName returns a types.NamespacedName if the required service binding request keys
 // are present in the given data
 func extractSBRNamespacedName(data map[string]string) types.NamespacedName {
@@ -47,30 +52,30 @@ func GetSBRNamespacedNameFromObject(obj runtime.Object) (types.NamespacedName, e
 	u := &unstructured.Unstructured{Object: data}
 
 	sbrNamespacedName = extractSBRNamespacedName(u.GetAnnotations())
-	logger := log.WithValues(
+	log := annotationsLog.WithValues(
 		"Resource.GVK", u.GroupVersionKind(),
 		"Resource.Namespace", u.GetNamespace(),
 		"Resource.Name", u.GetName(),
 		"SBR.NamespacedName", sbrNamespacedName.String(),
 	)
 
 	if IsNamespacedNameEmpty(sbrNamespacedName) {
-		logger.Info("SBR information not present in annotations, continue inspecting object")
+		log.Debug("SBR information not present in annotations, continue inspecting object")
 	} else {
 		// FIXME: Increase V level for tracing info to avoid flooding logs with this information.
-		logger.Info("SBR information found in annotations, returning it")
+		log.Trace("SBR information found in annotations, returning it")
 		return sbrNamespacedName, nil
 	}
 
 	if u.GroupVersionKind() == v1alpha1.SchemeGroupVersion.WithKind(ServiceBindingRequestKind) {
-		logger.Info("Object is a SBR, returning its namespaced name")
+		log.Debug("Object is a SBR, returning its namespaced name")
 		sbrNamespacedName.Namespace = u.GetNamespace()
 		sbrNamespacedName.Name = u.GetName()
 		return sbrNamespacedName, nil
 	}
 
 	// FIXME: Increase V level for tracing info to avoid flooding logs with this information.
-	logger.Info("Object is not a SBR, returning an empty namespaced name")
+	log.Trace("Object is not a SBR, returning an empty namespaced name")
 	return sbrNamespacedName, nil
 }
 
@@ -95,17 +100,17 @@ func SetSBRAnnotations(
 		gvr, _ := meta.UnsafeGuessKindToResource(gvk)
 		opts := metav1.UpdateOptions{}
 
-		logger := log.WithValues(
+		log := annotationsLog.WithValues(
 			"SBR.Namespace", namespacedName.Namespace,
 			"SBR.Name", namespacedName.Name,
 			"Resource.GVK", gvk,
 			"Resource.Namespace", obj.GetNamespace(),
 			"Resource.Name", obj.GetName(),
 		)
-		logger.Info("Updating resource annotations...")
+		log.Debug("Updating resource annotations...")
 		_, err := client.Resource(gvr).Namespace(obj.GetNamespace()).Update(obj, opts)
 		if err != nil {
-			logger.Error(err, "unable to set/update annotations in object")
+			log.Error(err, "unable to set/update annotations in object")
 			return err
 		}
 	}