diff --git a/Makefile b/Makefile index bbc7dac5d2..fe4ef0265b 100644 --- a/Makefile +++ b/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 diff --git a/cmd/manager/main.go b/cmd/manager/main.go index 10820b1f19..f2109de770 100644 --- a/cmd/manager/main.go +++ b/cmd/manager/main.go @@ -23,11 +23,12 @@ 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. @@ -35,13 +36,13 @@ 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,7 +137,7 @@ 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 @@ -144,19 +145,19 @@ func main() { 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) } } diff --git a/pkg/controller/servicebindingrequest/annotations.go b/pkg/controller/servicebindingrequest/annotations.go index 7e82a65303..569c445e98 100644 --- a/pkg/controller/servicebindingrequest/annotations.go +++ b/pkg/controller/servicebindingrequest/annotations.go @@ -9,6 +9,7 @@ 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 ( @@ -16,6 +17,10 @@ const ( 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,7 +52,7 @@ 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(), @@ -55,22 +60,22 @@ func GetSBRNamespacedNameFromObject(obj runtime.Object) (types.NamespacedName, e ) 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 } } diff --git a/pkg/controller/servicebindingrequest/binder.go b/pkg/controller/servicebindingrequest/binder.go index 98ef2142cd..1e8924ed59 100644 --- a/pkg/controller/servicebindingrequest/binder.go +++ b/pkg/controller/servicebindingrequest/binder.go @@ -5,7 +5,6 @@ import ( "fmt" "time" - "github.com/go-logr/logr" corev1 "k8s.io/api/core/v1" "k8s.io/apimachinery/pkg/api/errors" metav1 "k8s.io/apimachinery/pkg/apis/meta/v1" @@ -17,15 +16,19 @@ import ( "k8s.io/apimachinery/pkg/types" "k8s.io/client-go/dynamic" "sigs.k8s.io/controller-runtime/pkg/client" - logf "sigs.k8s.io/controller-runtime/pkg/runtime/log" "github.com/redhat-developer/service-binding-operator/pkg/apis/apps/v1alpha1" + "github.com/redhat-developer/service-binding-operator/pkg/log" ) const ( lastboundparam = "lastbound" ) +var ( + binderLog = log.NewLog("binder") +) + // Binder executes the "binding" act of updating different application kinds to use intermediary // secret. Those secrets should be offered as environment variables. type Binder struct { @@ -34,7 +37,7 @@ type Binder struct { dynClient dynamic.Interface // kubernetes dynamic api client sbr *v1alpha1.ServiceBindingRequest // instantiated service binding request volumeKeys []string // list of key names used in volume mounts - logger logr.Logger // logger instance + logger *log.Log // logger instance } // search objects based in Kind/APIVersion, which contain the labels defined in ApplicationSelector. @@ -79,20 +82,19 @@ func (b *Binder) search() (*unstructured.UnstructuredList, error) { // updateSpecVolumes execute the inspection and update "volumes" entries in informed spec. func (b *Binder) updateSpecVolumes( - logger logr.Logger, obj *unstructured.Unstructured, ) (*unstructured.Unstructured, error) { volumesPath := []string{"spec", "template", "spec", "volumes"} - logger = logger.WithValues("Volumes.NestedPath", volumesPath) + log := b.logger.WithValues("Volumes.NestedPath", volumesPath) - logger.Info("Reading volumes definitions...") + log.Debug("Reading volumes definitions...") volumes, _, err := unstructured.NestedSlice(obj.Object, volumesPath...) if err != nil { return nil, err } - logger.WithValues("Volumes", len(volumes)).Info("Amount of volumes in spec.") + log.Debug("Amount of volumes in spec.", "Volumes", len(volumes)) - volumes, err = b.updateVolumes(logger, volumes) + volumes, err = b.updateVolumes(volumes) if err != nil { return nil, err } @@ -105,14 +107,14 @@ func (b *Binder) updateSpecVolumes( // updateVolumes inspect informed list assuming as []corev1.Volume, and if binding volume is already // defined just return the same list, otherwise, appending the binding volume. -func (b *Binder) updateVolumes(logger logr.Logger, volumes []interface{}) ([]interface{}, error) { +func (b *Binder) updateVolumes(volumes []interface{}) ([]interface{}, error) { name := b.sbr.GetName() - - logger.Info("Checking if binding volume is already defined...") + log := b.logger + log.Debug("Checking if binding volume is already defined...") for _, v := range volumes { volume := v.(corev1.Volume) if name == volume.Name { - logger.Info("Volume is already defined!") + log.Debug("Volume is already defined!") return volumes, nil } } @@ -122,7 +124,7 @@ func (b *Binder) updateVolumes(logger logr.Logger, volumes []interface{}) ([]int items = append(items, corev1.KeyToPath{Key: k, Path: k}) } - logger.WithValues("Items", items).Info("Appending new volume with items.") + log.Debug("Appending new volume with items.", "Items", items) bindVolume := corev1.Volume{ Name: name, VolumeSource: corev1.VolumeSource{ @@ -143,11 +145,10 @@ func (b *Binder) updateVolumes(logger logr.Logger, volumes []interface{}) ([]int // updateSpecContainers extract containers from object, and trigger update. func (b *Binder) updateSpecContainers( - logger logr.Logger, obj *unstructured.Unstructured, ) (*unstructured.Unstructured, error) { containersPath := []string{"spec", "template", "spec", "containers"} - logger = logger.WithValues("Containers.NestedPath", containersPath) + log := b.logger.WithValues("Containers.NestedPath", containersPath) containers, found, err := unstructured.NestedSlice(obj.Object, containersPath...) if err != nil { @@ -156,11 +157,11 @@ func (b *Binder) updateSpecContainers( if !found { err = fmt.Errorf("unable to find '%#v' in object kind '%s'", containersPath, obj.GetKind()) - logger.Error(err, "is this definition supported by this operator?") + log.Error(err, "is this definition supported by this operator?") return nil, err } - if containers, err = b.updateContainers(logger, containers); err != nil { + if containers, err = b.updateContainers(containers); err != nil { return nil, err } if err = unstructured.SetNestedSlice(obj.Object, containers, containersPath...); err != nil { @@ -171,18 +172,17 @@ func (b *Binder) updateSpecContainers( // updateContainers execute the update command per container found. func (b *Binder) updateContainers( - logger logr.Logger, containers []interface{}, ) ([]interface{}, error) { var err error for i, container := range containers { - logger := logger.WithValues("Obj.Container.Number", i) - logger.Info("Inspecting container...") + log := b.logger.WithValues("Obj.Container.Number", i) + log.Debug("Inspecting container...") containers[i], err = b.updateContainer(container) if err != nil { - logger.Error(err, "during container update.") + log.Error(err, "during container update.") return nil, err } } @@ -214,15 +214,16 @@ func (b *Binder) appendEnvVar(envList []corev1.EnvVar, envParam string, envValue // appendEnvFrom based on secret name and list of EnvFromSource instances, making sure secret is // part of the list or appended. func (b *Binder) appendEnvFrom(envList []corev1.EnvFromSource, secret string) []corev1.EnvFromSource { + log := b.logger for _, env := range envList { if env.SecretRef.Name == secret { - b.logger.Info("Directive 'envFrom' is already present!") + log.Debug("Directive 'envFrom' is already present!") // secret name is already referenced return envList } } - b.logger.Info("Adding 'envFrom' directive...") + log.Debug("Adding 'envFrom' directive...") return append(envList, corev1.EnvFromSource{ SecretRef: &corev1.SecretEnvSource{ LocalObjectReference: corev1.LocalObjectReference{ @@ -279,27 +280,27 @@ func (b *Binder) update(objs *unstructured.UnstructuredList) ([]*unstructured.Un for _, obj := range objs.Items { name := obj.GetName() - logger := b.logger.WithValues("Obj.Name", name, "Obj.Kind", obj.GetKind()) - logger.Info("Inspecting object...") + log := b.logger.WithValues("Obj.Name", name, "Obj.Kind", obj.GetKind()) + log.Debug("Inspecting object...") - updatedObj, err := b.updateSpecContainers(logger, &obj) + updatedObj, err := b.updateSpecContainers(&obj) if err != nil { return nil, err } if len(b.volumeKeys) > 0 { - updatedObj, err = b.updateSpecVolumes(logger, &obj) + updatedObj, err = b.updateSpecVolumes(&obj) if err != nil { return nil, err } } - logger.Info("Updating object...") + log.Debug("Updating object...") if err := b.client.Update(b.ctx, updatedObj); err != nil { return nil, err } - logger.Info("Reading back updated object...") + log.Debug("Reading back updated object...") // reading object back again, to comply with possible modifications namespacedName := types.NamespacedName{ Namespace: updatedObj.GetNamespace(), @@ -339,6 +340,6 @@ func NewBinder( dynClient: dynClient, sbr: sbr, volumeKeys: volumeKeys, - logger: logf.Log.WithName("binder"), + logger: binderLog, } } diff --git a/pkg/controller/servicebindingrequest/common.go b/pkg/controller/servicebindingrequest/common.go index 1a6cf9e327..4e94dcf05f 100644 --- a/pkg/controller/servicebindingrequest/common.go +++ b/pkg/controller/servicebindingrequest/common.go @@ -5,11 +5,6 @@ import ( "k8s.io/apimachinery/pkg/api/errors" "sigs.k8s.io/controller-runtime/pkg/reconcile" - logf "sigs.k8s.io/controller-runtime/pkg/runtime/log" -) - -var ( - log = logf.ZapLogger(true).WithName("servicebindingrequest") ) // ServiceBindingRequestResource the name of ServiceBindingRequest resource. diff --git a/pkg/controller/servicebindingrequest/mapper.go b/pkg/controller/servicebindingrequest/mapper.go index c2cfebb118..d1b70b705f 100644 --- a/pkg/controller/servicebindingrequest/mapper.go +++ b/pkg/controller/servicebindingrequest/mapper.go @@ -1,10 +1,15 @@ package servicebindingrequest import ( + "github.com/redhat-developer/service-binding-operator/pkg/log" "sigs.k8s.io/controller-runtime/pkg/handler" "sigs.k8s.io/controller-runtime/pkg/reconcile" ) +var ( + mapperLog = log.NewLog("mapper") +) + // SBRRequestMapper is the handler.Mapper interface implementation. It should influence the // enqueue process considering the resources informed. type SBRRequestMapper struct{} @@ -12,7 +17,7 @@ type SBRRequestMapper struct{} // Map execute the mapping of a resource with the requests it would produce. Here we inspect the // given object trying to identify if this object is part of a SBR, or a actual SBR resource. func (m *SBRRequestMapper) Map(obj handler.MapObject) []reconcile.Request { - logger := log.WithValues( + log := mapperLog.WithValues( "Object.Namespace", obj.Meta.GetNamespace(), "Object.Name", obj.Meta.GetName(), ) @@ -20,11 +25,11 @@ func (m *SBRRequestMapper) Map(obj handler.MapObject) []reconcile.Request { sbrNamespacedName, err := GetSBRNamespacedNameFromObject(obj.Object) if err != nil { - logger.Error(err, "on inspecting object for annotations for SBR object") + log.Error(err, "on inspecting object for annotations for SBR object") return toReconcile } if IsNamespacedNameEmpty(sbrNamespacedName) { - log.Info("not able to extract SBR namespaced-name") + log.Debug("not able to extract SBR namespaced-name") return toReconcile } diff --git a/pkg/controller/servicebindingrequest/olm.go b/pkg/controller/servicebindingrequest/olm.go index c4590d5da0..8bff5b435d 100644 --- a/pkg/controller/servicebindingrequest/olm.go +++ b/pkg/controller/servicebindingrequest/olm.go @@ -4,15 +4,14 @@ import ( "fmt" "strings" - "github.com/go-logr/logr" olmv1alpha1 "github.com/operator-framework/operator-lifecycle-manager/pkg/api/apis/operators/v1alpha1" + "github.com/redhat-developer/service-binding-operator/pkg/log" metav1 "k8s.io/apimachinery/pkg/apis/meta/v1" "k8s.io/apimachinery/pkg/apis/meta/v1/unstructured" "k8s.io/apimachinery/pkg/runtime" "k8s.io/apimachinery/pkg/runtime/schema" "k8s.io/apimachinery/pkg/types" "k8s.io/client-go/dynamic" - logf "sigs.k8s.io/controller-runtime/pkg/runtime/log" ) // OLM represents the actions this operator needs to take upon Operator-Lifecycle-Manager resources, @@ -20,20 +19,25 @@ import ( type OLM struct { client dynamic.Interface // kubernetes dynamic client ns string // namespace - logger logr.Logger // logger instance + logger *log.Log // logger instance } const ( csvResource = "clusterserviceversions" ) +var ( + olmLog = log.NewLog("olm") +) + // listCSVs simple list to all CSV objects in the cluster. func (o *OLM) listCSVs() ([]unstructured.Unstructured, error) { + log := o.logger gvr := olmv1alpha1.SchemeGroupVersion.WithResource(csvResource) resourceClient := o.client.Resource(gvr).Namespace(o.ns) csvs, err := resourceClient.List(metav1.ListOptions{}) if err != nil { - o.logger.Error(err, "during listing CSV objects from cluster") + log.Error(err, "during listing CSV objects from cluster") return nil, err } return csvs.Items, nil @@ -46,11 +50,11 @@ func (o *OLM) extractOwnedCRDs( crds := []unstructured.Unstructured{} for _, csv := range csvs { ownedPath := []string{"spec", "customresourcedefinitions", "owned"} - logger := o.logger.WithValues("OwnedPath", ownedPath, "CSV.Name", csv.GetName()) + log := o.logger.WithValues("OwnedPath", ownedPath, "CSV.Name", csv.GetName()) ownedCRDs, exists, err := unstructured.NestedSlice(csv.Object, ownedPath...) if err != nil { - logger.Error(err, "on extracting nested slice") + log.Error(err, "on extracting nested slice") return nil, err } if !exists { @@ -68,9 +72,10 @@ func (o *OLM) extractOwnedCRDs( // ListCSVOwnedCRDs return a unstructured list of CRD objects from "owned" section in CSVs. func (o *OLM) ListCSVOwnedCRDs() ([]unstructured.Unstructured, error) { + log := o.logger csvs, err := o.listCSVs() if err != nil { - o.logger.Error(err, "on listting CSVs") + log.Error(err, "on listting CSVs") return nil, err } return o.extractOwnedCRDs(csvs) @@ -87,16 +92,16 @@ func (o *OLM) loopCRDDescriptions( fn eachCRDDescriptionFn, ) error { for _, u := range crdDescriptions { + log := o.logger crdDescription := &olmv1alpha1.CRDDescription{} err := runtime.DefaultUnstructuredConverter.FromUnstructured(u.Object, crdDescription) if err != nil { - o.logger.Error(err, "on converting from unstructured to CRD") + log.Error(err, "on converting from unstructured to CRD") return err } - logger := o.logger.WithValues("CRDDescription", crdDescription) - logger.Info("Inspecting CRDDescription...") + log.Debug("Inspecting CRDDescription...", "CRDDescription", crdDescription) if crdDescription.Name == "" { - logger.Info("Skipping empty CRDDescription!") + log.Debug("Skipping empty CRDDescription!") continue } fn(crdDescription) @@ -106,21 +111,21 @@ func (o *OLM) loopCRDDescriptions( // SelectCRDByGVK return a single CRD based on a given GVK. func (o *OLM) SelectCRDByGVK(gvk schema.GroupVersionKind) (*olmv1alpha1.CRDDescription, error) { - logger := o.logger.WithValues("Selector.GVK", gvk) + log := o.logger.WithValues("Selector.GVK", gvk) ownedCRDs, err := o.ListCSVOwnedCRDs() if err != nil { - logger.Error(err, "on listing owned CRDs") + log.Error(err, "on listing owned CRDs") return nil, err } crdDescriptions := []*olmv1alpha1.CRDDescription{} err = o.loopCRDDescriptions(ownedCRDs, func(crdDescription *olmv1alpha1.CRDDescription) { - logger = logger.WithValues( + log = o.logger.WithValues( "CRDDescription.Name", crdDescription.Name, "CRDDescription.Version", crdDescription.Version, "CRDDescription.Kind", crdDescription.Kind, ) - logger.Info("Inspecting CRDDescription object...") + log.Debug("Inspecting CRDDescription object...") // checking for suffix since is expected to have object type as prefix if !strings.EqualFold(strings.ToLower(crdDescription.Kind), strings.ToLower(gvk.Kind)) { return @@ -130,7 +135,7 @@ func (o *OLM) SelectCRDByGVK(gvk schema.GroupVersionKind) (*olmv1alpha1.CRDDescr strings.ToLower(gvk.Version) != strings.ToLower(crdDescription.Version) { return } - logger.Info("CRDDescription object matches selector!") + log.Debug("CRDDescription object matches selector!") crdDescriptions = append(crdDescriptions, crdDescription) }) if err != nil { @@ -138,7 +143,7 @@ func (o *OLM) SelectCRDByGVK(gvk schema.GroupVersionKind) (*olmv1alpha1.CRDDescr } if len(crdDescriptions) == 0 { - logger.Info("No CRD could be found for GVK.") + log.Debug("No CRD could be found for GVK.") return nil, fmt.Errorf("no crd could be found for gvk") } return crdDescriptions[0], nil @@ -148,10 +153,10 @@ func (o *OLM) SelectCRDByGVK(gvk schema.GroupVersionKind) (*olmv1alpha1.CRDDescr func (o *OLM) extractGVKs( crdDescriptions []unstructured.Unstructured, ) ([]schema.GroupVersionKind, error) { + log := o.logger gvks := []schema.GroupVersionKind{} err := o.loopCRDDescriptions(crdDescriptions, func(crdDescription *olmv1alpha1.CRDDescription) { - o.logger.WithValues("CRDDescription.Name", crdDescription.Name). - Info("Extracting GVK from CRDDescription") + log.Debug("Extracting GVK from CRDDescription", "CRDDescription.Name", crdDescription.Name) _, gv := schema.ParseResourceArg(crdDescription.Name) gvks = append(gvks, schema.GroupVersionKind{ Group: gv.Group, @@ -167,9 +172,10 @@ func (o *OLM) extractGVKs( // ListCSVOwnedCRDsAsGVKs return the list of owned CRDs from all CSV objects as a list of GVKs. func (o *OLM) ListCSVOwnedCRDsAsGVKs() ([]schema.GroupVersionKind, error) { + log := o.logger ownedCRDs, err := o.ListCSVOwnedCRDs() if err != nil { - o.logger.Error(err, "on listting CSVs") + log.Error(err, "on listting CSVs") return nil, err } return o.extractGVKs(ownedCRDs) @@ -179,13 +185,13 @@ func (o *OLM) ListCSVOwnedCRDsAsGVKs() ([]schema.GroupVersionKind, error) { func (o *OLM) ListGVKsFromCSVNamespacedName( namespacedName types.NamespacedName, ) ([]schema.GroupVersionKind, error) { - logger := o.logger.WithValues("CSV.NamespacedName", namespacedName) - logger.Info("Reading CSV to extract GVKs...") + log := o.logger.WithValues("CSV.NamespacedName", namespacedName) + log.Debug("Reading CSV to extract GVKs...") gvr := olmv1alpha1.SchemeGroupVersion.WithResource(csvResource) resourceClient := o.client.Resource(gvr).Namespace(namespacedName.Namespace) u, err := resourceClient.Get(namespacedName.Name, metav1.GetOptions{}) if err != nil { - logger.Error(err, "on reading CSV object") + log.Error(err, "on reading CSV object") return []schema.GroupVersionKind{}, err } @@ -194,7 +200,7 @@ func (o *OLM) ListGVKsFromCSVNamespacedName( ownedCRDs, err := o.extractOwnedCRDs(csvs) if err != nil { - logger.Error(err, "on extracting owned CRDs") + log.Error(err, "on extracting owned CRDs") return []schema.GroupVersionKind{}, err } @@ -206,6 +212,6 @@ func NewOLM(client dynamic.Interface, ns string) *OLM { return &OLM{ client: client, ns: ns, - logger: logf.Log.WithName("olm"), + logger: olmLog, } } diff --git a/pkg/controller/servicebindingrequest/planner.go b/pkg/controller/servicebindingrequest/planner.go index 36ae4aa08e..84023c3f32 100644 --- a/pkg/controller/servicebindingrequest/planner.go +++ b/pkg/controller/servicebindingrequest/planner.go @@ -3,16 +3,19 @@ package servicebindingrequest import ( "context" - "github.com/go-logr/logr" olmv1alpha1 "github.com/operator-framework/operator-lifecycle-manager/pkg/api/apis/operators/v1alpha1" "k8s.io/apimachinery/pkg/api/meta" metav1 "k8s.io/apimachinery/pkg/apis/meta/v1" "k8s.io/apimachinery/pkg/apis/meta/v1/unstructured" "k8s.io/apimachinery/pkg/runtime/schema" "k8s.io/client-go/dynamic" - logf "sigs.k8s.io/controller-runtime/pkg/runtime/log" v1alpha1 "github.com/redhat-developer/service-binding-operator/pkg/apis/apps/v1alpha1" + "github.com/redhat-developer/service-binding-operator/pkg/log" +) + +var ( + plannerLog = log.NewLog("planner") ) // Planner plans resources needed to bind a given backend service, using OperatorLifecycleManager @@ -21,16 +24,16 @@ type Planner struct { ctx context.Context // request context client dynamic.Interface // kubernetes dynamic api client sbr *v1alpha1.ServiceBindingRequest // instantiated service binding request - logger logr.Logger // logger instance + logger *log.Log // logger instance } // Plan outcome, after executing planner. type Plan struct { - Ns string // namespace name - Name string // plan name, same than ServiceBindingRequest - CRDDescription *olmv1alpha1.CRDDescription // custom resource definition description - CR *unstructured.Unstructured // custom resource object - SBR v1alpha1.ServiceBindingRequest // service binding request + Ns string // namespace name + Name string // plan name, same than ServiceBindingRequest + CRDDescription *olmv1alpha1.CRDDescription // custom resource definition description + CR *unstructured.Unstructured // custom resource object + SBR v1alpha1.ServiceBindingRequest // service binding request } // searchCR based on a CustomResourceDefinitionDescription and name, search for the object. @@ -40,16 +43,16 @@ func (p *Planner) searchCR(kind string) (*unstructured.Unstructured, error) { gvr, _ := meta.UnsafeGuessKindToResource(gvk) opts := metav1.GetOptions{} - logger := p.logger.WithValues("CR.GVK", gvk.String(), "CR.GVR", gvr.String()) - logger.Info("Searching for CR instance...") + log := p.logger.WithValues("CR.GVK", gvk.String(), "CR.GVR", gvr.String()) + log.Debug("Searching for CR instance...") cr, err := p.client.Resource(gvr).Namespace(p.sbr.GetNamespace()).Get(bss.ResourceRef, opts) if err != nil { - logger.Error(err, "during reading CR") + log.Error(err, "during reading CR") return nil, err } - logger.WithValues("CR.Name", cr.GetName()).Info("Found target CR!") + log.Debug("Found target CR!", "CR.Name", cr.GetName()) return cr, nil } @@ -74,7 +77,7 @@ func (p *Planner) Plan() (*Plan, error) { Name: p.sbr.GetName(), CRDDescription: crdDescription, CR: cr, - SBR: *p.sbr, + SBR: *p.sbr, }, nil } @@ -88,6 +91,6 @@ func NewPlanner( ctx: ctx, client: client, sbr: sbr, - logger: logf.Log.WithName("plan"), + logger: plannerLog, } } diff --git a/pkg/controller/servicebindingrequest/reconciler.go b/pkg/controller/servicebindingrequest/reconciler.go index a9f7f29816..1e5e4f8906 100644 --- a/pkg/controller/servicebindingrequest/reconciler.go +++ b/pkg/controller/servicebindingrequest/reconciler.go @@ -12,10 +12,9 @@ import ( "k8s.io/client-go/dynamic" "sigs.k8s.io/controller-runtime/pkg/client" "sigs.k8s.io/controller-runtime/pkg/reconcile" - logf "sigs.k8s.io/controller-runtime/pkg/runtime/log" - "github.com/go-logr/logr" "github.com/redhat-developer/service-binding-operator/pkg/apis/apps/v1alpha1" + "github.com/redhat-developer/service-binding-operator/pkg/log" ) // Reconciler reconciles a ServiceBindingRequest object @@ -36,6 +35,10 @@ const ( requeueAfter int64 = 45 ) +var ( + reconcilerLog = log.NewLog("reconciler") +) + // setSecretName update the CR status field to "in progress", and setting secret name. func (r *Reconciler) setSecretName(sbrStatus *v1alpha1.ServiceBindingRequestStatus, name string) { sbrStatus.BindingStatus = bindingInProgress @@ -122,16 +125,16 @@ func (r *Reconciler) onError( } // checkSBR checks the Service Binding Request -func checkSBR(sbr *v1alpha1.ServiceBindingRequest, logger logr.Logger) error { +func checkSBR(sbr *v1alpha1.ServiceBindingRequest, log *log.Log) error { // Check if application ResourceRef is present if sbr.Spec.ApplicationSelector.ResourceRef == "" { - logger.Info("Spec.ApplicationSelector.ResourceRef not found") + log.Debug("Spec.ApplicationSelector.ResourceRef not found") // Check if MatchLabels is present if sbr.Spec.ApplicationSelector.MatchLabels == nil { err := errors.New("NotFoundError") - logger.Error(err, "Spec.ApplicationSelector.MatchLabels not found") + log.Error(err, "Spec.ApplicationSelector.MatchLabels not found") return err } } @@ -151,29 +154,29 @@ func (r *Reconciler) Reconcile(request reconcile.Request) (reconcile.Result, err ctx := context.TODO() objectsToAnnotate := []*unstructured.Unstructured{} - logger := logf.Log.WithValues( + log := reconcilerLog.WithValues( "Request.Namespace", request.Namespace, "Request.Name", request.Name, ) - logger.Info("Reconciling ServiceBindingRequest...") + log.Info("Reconciling ServiceBindingRequest...") // fetch the ServiceBindingRequest instance sbr, err := r.getServiceBindingRequest(request.NamespacedName) if err != nil { - logger.Error(err, "On retrieving service-binding-request instance.") + log.Error(err, "On retrieving service-binding-request instance.") return RequeueError(err) } - logger = logger.WithValues("ServiceBindingRequest.Name", sbr.Name) - logger.Info("Found service binding request to inspect") + log = log.WithValues("ServiceBindingRequest.Name", sbr.Name) + log.Debug("Found service binding request to inspect") // splitting instance from it's status sbrStatus := sbr.Status // Check Service Binding Request - err = checkSBR(sbr, logger) + err = checkSBR(sbr, log) if err != nil { - logger.Error(err, "") + log.Error(err, "") return RequeueError(err) } @@ -181,11 +184,11 @@ func (r *Reconciler) Reconcile(request reconcile.Request) (reconcile.Result, err // Planing changes // - logger.Info("Creating a plan based on OLM and CRD.") + log.Debug("Creating a plan based on OLM and CRD.") planner := NewPlanner(ctx, r.dynClient, sbr) plan, err := planner.Plan() if err != nil { - logger.Error(err, "On creating a plan to bind applications.") + log.Error(err, "On creating a plan to bind applications.") return r.onError(err, sbr, &sbrStatus, nil) } @@ -196,11 +199,11 @@ func (r *Reconciler) Reconcile(request reconcile.Request) (reconcile.Result, err // Retrieving data // - logger.Info("Retrieving data to create intermediate secret.") + log.Debug("Retrieving data to create intermediate secret.") retriever := NewRetriever(r.dynClient, plan, sbr.Spec.EnvVarPrefix) retrievedObjects, err := retriever.Retrieve() if err != nil { - logger.Error(err, "On retrieving binding data.") + log.Error(err, "On retrieving binding data.") return r.onError(err, sbr, &sbrStatus, nil) } @@ -213,11 +216,11 @@ func (r *Reconciler) Reconcile(request reconcile.Request) (reconcile.Result, err // Updating applications to use intermediary secret // - logger.Info("Binding applications with intermediary secret.") + log.Info("Binding applications with intermediary secret.") binder := NewBinder(ctx, r.client, r.dynClient, sbr, retriever.volumeKeys) updatedObjects, err := binder.Bind() if err != nil { - logger.Error(err, "On binding application.") + log.Error(err, "On binding application.") return r.onError(err, sbr, &sbrStatus, updatedObjects) } @@ -231,16 +234,16 @@ func (r *Reconciler) Reconcile(request reconcile.Request) (reconcile.Result, err // if err = SetSBRAnnotations(r.dynClient, request.NamespacedName, objectsToAnnotate); err != nil { - logger.Error(err, "On setting annotations in related objects.") + log.Error(err, "On setting annotations in related objects.") return r.onError(err, sbr, &sbrStatus, updatedObjects) } // updating status of request instance if err = r.updateStatusServiceBindingRequest(sbr, &sbrStatus); err != nil { - logger.Error(err, "On updating status of ServiceBindingRequest.") + log.Error(err, "On updating status of ServiceBindingRequest.") return RequeueError(err) } - logger.Info("All done!") + log.Info("All done!") return Done() } diff --git a/pkg/controller/servicebindingrequest/retriever.go b/pkg/controller/servicebindingrequest/retriever.go index 233a040dca..7604da548e 100644 --- a/pkg/controller/servicebindingrequest/retriever.go +++ b/pkg/controller/servicebindingrequest/retriever.go @@ -5,7 +5,7 @@ import ( "fmt" "strings" - "github.com/go-logr/logr" + "github.com/redhat-developer/service-binding-operator/pkg/log" corev1 "k8s.io/api/core/v1" "k8s.io/apimachinery/pkg/api/errors" metav1 "k8s.io/apimachinery/pkg/apis/meta/v1" @@ -13,12 +13,11 @@ import ( "k8s.io/apimachinery/pkg/runtime" "k8s.io/apimachinery/pkg/runtime/schema" "k8s.io/client-go/dynamic" - logf "sigs.k8s.io/controller-runtime/pkg/runtime/log" ) // Retriever reads all data referred in plan instance, and store in a secret. type Retriever struct { - logger logr.Logger // logger instance + logger *log.Log // logger instance data map[string][]byte // data retrieved objects []*unstructured.Unstructured // list of objects employed client dynamic.Interface // Kubernetes API client @@ -36,9 +35,13 @@ const ( volumeMountSecretPrefix = "binding:volumemount:secret" ) +var ( + retrieverLog = log.NewLog("retriever") +) + // getNestedValue retrieve value from dotted key path func (r *Retriever) getNestedValue(key string, sectionMap interface{}) (string, error, interface{}) { - logger := r.logger.WithValues("Key", key, "SectionMap", sectionMap) + log := r.logger.WithValues("Key", key, "SectionMap", sectionMap) if !strings.Contains(key, ".") { value, exists := sectionMap.(map[string]interface{})[key] if !exists { @@ -48,7 +51,7 @@ func (r *Retriever) getNestedValue(key string, sectionMap interface{}) (string, } attrs := strings.SplitN(key, ".", 2) newSectionMap, exists := sectionMap.(map[string]interface{})[attrs[0]] - logger.Info("Section maps : ") + log.Debug("Section maps : ") if !exists { return "", fmt.Errorf("Can't find '%v' section in CR", attrs), newSectionMap } @@ -59,8 +62,8 @@ func (r *Retriever) getNestedValue(key string, sectionMap interface{}) (string, func (r *Retriever) getCRKey(section string, key string) (string, interface{}, error) { obj := r.plan.CR.Object objName := r.plan.CR.GetName() - logger := r.logger.WithValues("CR.Name", objName, "CR.section", section, "CR.key", key) - logger.Info("Reading CR attributes...") + log := r.logger.WithValues("CR.Name", objName, "CR.section", section, "CR.key", key) + log.Debug("Reading CR attributes...") sectionMap, exists := obj[section] if !exists { @@ -81,12 +84,12 @@ func (r *Retriever) getCRKey(section string, key string) (string, interface{}, e // value, and parsing x-descriptors in order to either directly read CR data, or read items from // a secret. func (r *Retriever) read(place, path string, xDescriptors []string) error { - logger := r.logger.WithValues( + log := r.logger.WithValues( "CR.Section", place, "CRDDescription.Path", path, "CRDDescription.XDescriptors", xDescriptors, ) - logger.Info("Reading CRDDescription attributes...") + log.Debug("Reading CRDDescription attributes...") // holds the secret name and items secrets := make(map[string][]string) @@ -95,8 +98,8 @@ func (r *Retriever) read(place, path string, xDescriptors []string) error { configMaps := make(map[string][]string) pathValue, _, err := r.getCRKey(place, path) for _, xDescriptor := range xDescriptors { - logger = logger.WithValues("CRDDescription.xDescriptor", xDescriptor, "cache", r.cache) - logger.Info("Inspecting xDescriptor...") + log = log.WithValues("CRDDescription.xDescriptor", xDescriptor, "cache", r.cache) + log.Debug("Inspecting xDescriptor...") if err != nil { return err } @@ -120,7 +123,7 @@ func (r *Retriever) read(place, path string, xDescriptors []string) error { } else if strings.HasPrefix(xDescriptor, attributePrefix) { r.store(path, []byte(pathValue)) } else { - logger.Info("Defaulting....") + log.Debug("Defaulting....") } } @@ -176,8 +179,8 @@ func (r *Retriever) readSecret( items []string, fromPath string, path string) error { - logger := r.logger.WithValues("Secret.Name", name, "Secret.Items", items) - logger.Info("Reading secret items...") + log := r.logger.WithValues("Secret.Name", name, "Secret.Items", items) + log.Debug("Reading secret items...") gvr := schema.GroupVersionResource{Group: "", Version: "v1", Resource: "secrets"} u, err := r.client.Resource(gvr).Namespace(r.plan.Ns).Get(name, metav1.GetOptions{}) @@ -199,8 +202,8 @@ func (r *Retriever) readSecret( if err != nil { return err } - logger.WithValues("Secret.Key.Name", k, "Secret.Key.Length", len(data)). - Info("Inspecting secret key...") + log = log.WithValues("Secret.Key.Name", k, "Secret.Key.Length", len(data)) + log.Debug("Inspecting secret key...") r.markVisitedPaths(path, k, fromPath) // update cache after reading configmap/secret in cache r.cache[fromPath].(map[string]interface{})[path].(map[string]interface{})[k] = string(value) @@ -220,8 +223,8 @@ func (r *Retriever) readConfigMap( items []string, fromPath string, path string) error { - logger := r.logger.WithValues("ConfigMap.Name", name, "ConfigMap.Items", items) - logger.Info("Reading ConfigMap items...") + log := r.logger.WithValues("ConfigMap.Name", name, "ConfigMap.Items", items) + log.Debug("Reading ConfigMap items...") gvr := schema.GroupVersionResource{Group: "", Version: "v1", Resource: "configmaps"} u, err := r.client.Resource(gvr).Namespace(r.plan.Ns).Get(name, metav1.GetOptions{}) @@ -237,11 +240,10 @@ func (r *Retriever) readConfigMap( return fmt.Errorf("could not find 'data' in secret") } - logger.Info("Inspecting configMap data...") + log.Debug("Inspecting configMap data...") for k, v := range data { value := v.(string) - logger.WithValues("configMap.Key.Name", k, "configMap.Key.Length", len(value)). - Info("Inspecting configMap key...") + log.Debug("Inspecting configMap key...", "configMap.Key.Name", k, "configMap.Key.Length", len(value)) r.markVisitedPaths(path, k, fromPath) // update cache after reading configmap/secret in cache r.cache[fromPath].(map[string]interface{})[path].(map[string]interface{})[k] = value @@ -271,12 +273,12 @@ func (r *Retriever) saveDataOnSecret() error { gvk := schema.GroupVersion{Group: "", Version: "v1"}.WithKind("Secret") gvr := schema.GroupVersionResource{Group: "", Version: "v1", Resource: "secrets"} resourceClient := r.client.Resource(gvr).Namespace(r.plan.Ns) - logger := r.logger.WithValues( + log := r.logger.WithValues( "Secret.GVK", gvk.String(), "Secret.Namespace", r.plan.Ns, "Secret.Name", r.plan.Name, ) - logger.Info("Retrieving intermediary secret...") + log.Debug("Retrieving intermediary secret...") secretObj := &corev1.Secret{ TypeMeta: metav1.TypeMeta{ @@ -292,26 +294,26 @@ func (r *Retriever) saveDataOnSecret() error { data, err := runtime.DefaultUnstructuredConverter.ToUnstructured(secretObj) if err != nil { - r.logger.Error(err, "Converting secret to unstructured") + log.Error(err, "Converting secret to unstructured") return err } u := &unstructured.Unstructured{Object: data} u.SetGroupVersionKind(gvk) - logger.Info("Creating intermediary secret...") + log.Debug("Creating intermediary secret...") _, err = resourceClient.Create(u, metav1.CreateOptions{}) if err != nil && !errors.IsAlreadyExists(err) { - logger.Error(err, "on creating intermediary secret") + log.Error(err, "on creating intermediary secret") return err } - logger.Info("Secret is already found, updating...") + log.Debug("Secret is already found, updating...") _, err = resourceClient.Update(u, metav1.UpdateOptions{}) if err != nil { - logger.Error(err, "on updating intermediary secret") + log.Error(err, "on updating intermediary secret") return err } - logger.Info("Intermediary secret created/updated!") + log.Debug("Intermediary secret created/updated!") r.objects = append(r.objects, u) return nil } @@ -320,22 +322,22 @@ func (r *Retriever) saveDataOnSecret() error { // Unstructured refering the objects in use by the Retriever, and error when issues reading fields. func (r *Retriever) Retrieve() ([]*unstructured.Unstructured, error) { var err error - - r.logger.Info("Looking for spec-descriptors in 'spec'...") + log := r.logger + log.Debug("Looking for spec-descriptors in 'spec'...") for _, specDescriptor := range r.plan.CRDDescription.SpecDescriptors { if err = r.read("spec", specDescriptor.Path, specDescriptor.XDescriptors); err != nil { return nil, err } } - r.logger.Info("Looking for status-descriptors in 'status'...") + log.Debug("Looking for status-descriptors in 'status'...") for _, statusDescriptor := range r.plan.CRDDescription.StatusDescriptors { if err = r.read("status", statusDescriptor.Path, statusDescriptor.XDescriptors); err != nil { return nil, err } } - r.logger.WithValues("cache", r.cache).Info("Final cache values...") + log.Debug("Final cache values...", "cache", r.cache) envParser := NewCustomEnvParser(r.plan.SBR.Spec.CustomEnvVar, r.cache) values, err := envParser.Parse() @@ -346,7 +348,7 @@ func (r *Retriever) Retrieve() ([]*unstructured.Unstructured, error) { r.data[k] = []byte(v.(string)) } - r.logger.Info("Saving data on intermediary secret...") + log.Debug("Saving data on intermediary secret...") if err = r.saveDataOnSecret(); err != nil { return nil, err } @@ -356,7 +358,7 @@ func (r *Retriever) Retrieve() ([]*unstructured.Unstructured, error) { // NewRetriever instantiate a new retriever instance. func NewRetriever(client dynamic.Interface, plan *Plan, bindingPrefix string) *Retriever { return &Retriever{ - logger: logf.Log.WithName("retriever"), + logger: retrieverLog, data: make(map[string][]byte), objects: []*unstructured.Unstructured{}, client: client, diff --git a/pkg/controller/servicebindingrequest/sbrcontroller.go b/pkg/controller/servicebindingrequest/sbrcontroller.go index 4765c05843..565f0996e1 100644 --- a/pkg/controller/servicebindingrequest/sbrcontroller.go +++ b/pkg/controller/servicebindingrequest/sbrcontroller.go @@ -3,7 +3,6 @@ package servicebindingrequest import ( "os" - "github.com/go-logr/logr" olmv1alpha1 "github.com/operator-framework/operator-lifecycle-manager/pkg/api/apis/operators/v1alpha1" "k8s.io/apimachinery/pkg/apis/meta/v1/unstructured" "k8s.io/apimachinery/pkg/runtime/schema" @@ -13,10 +12,10 @@ import ( "sigs.k8s.io/controller-runtime/pkg/handler" "sigs.k8s.io/controller-runtime/pkg/manager" "sigs.k8s.io/controller-runtime/pkg/predicate" - logf "sigs.k8s.io/controller-runtime/pkg/runtime/log" "sigs.k8s.io/controller-runtime/pkg/source" "github.com/redhat-developer/service-binding-operator/pkg/apis/apps/v1alpha1" + "github.com/redhat-developer/service-binding-operator/pkg/log" ) // SBRController hold the controller instance and methods for a ServiceBindingRequest. @@ -24,7 +23,7 @@ type SBRController struct { Controller controller.Controller // controller-runtime instance Client dynamic.Interface // kubernetes dynamic api client watchingGVKs map[schema.GroupVersionKind]bool // cache to identify GVKs on watch - logger logr.Logger // logger instance + logger *log.Log // logger instance } var ( @@ -41,6 +40,7 @@ var ( return !e.DeleteStateUnknown }, } + sbrControllerLog = log.NewLog("sbrcontroller") ) // newEnqueueRequestsForSBR returns a handler.EventHandler configured to map any incoming object to a @@ -63,6 +63,7 @@ func (s *SBRController) createUnstructuredWithGVK(gvk schema.GroupVersionKind) * // getWatchingGVKs return a list of GVKs that this controller is interested in watching. func (s *SBRController) getWatchingGVKs() ([]schema.GroupVersionKind, error) { + log := s.logger // standard resources types gvks := []schema.GroupVersionKind{ {Group: "", Version: "v1", Kind: "Secret"}, @@ -75,37 +76,37 @@ func (s *SBRController) getWatchingGVKs() ([]schema.GroupVersionKind, error) { log.Error(err, "On listing owned CSV as GVKs") return nil, err } - log.WithValues("CSVOwnedGVK.Amount", len(olmGVKs)). - Info("Amount of GVK founds in CSV objects.") + log.Debug("Amount of GVK founds in CSV objects.", "CSVOwnedGVK.Amount", len(olmGVKs)) return append(gvks, olmGVKs...), nil } // AddWatchForGVK creates a watch on a given GVK, as long as it's not duplicated. func (s *SBRController) AddWatchForGVK(gvk schema.GroupVersionKind) error { - logger := s.logger.WithValues("GVK", gvk) - logger.Info("Adding watch for GVK...") + log := s.logger.WithValues("GVK", gvk) + log.Debug("Adding watch for GVK...") if _, exists := s.watchingGVKs[gvk]; exists { - logger.Info("Skipping watch on GVK twice, it's already under watch!") + log.Debug("Skipping watch on GVK twice, it's already under watch!") return nil } // saving GVK in cache s.watchingGVKs[gvk] = true - logger.Info("Creating watch on GVK") + log.Debug("Creating watch on GVK") source := s.createSourceForGVK(gvk) return s.Controller.Watch(source, s.newEnqueueRequestsForSBR(), defaultPredicate) } // addCSVWatch creates a watch on ClusterServiceVersion. func (s *SBRController) addCSVWatch() error { + log := s.logger csvGVK := olmv1alpha1.SchemeGroupVersion.WithKind(ClusterServiceVersionKind) source := s.createSourceForGVK(csvGVK) err := s.Controller.Watch(source, NewCreateWatchEventHandler(s), defaultPredicate) if err != nil { return err } - log.WithValues("GVK", csvGVK).Info("Watch added for ClusterServiceVersion") + log.Debug("Watch added for ClusterServiceVersion", "GVK", csvGVK) return nil } @@ -113,33 +114,33 @@ func (s *SBRController) addCSVWatch() error { // addSBRWatch creates a watchon ServiceBindingRequest GVK. func (s *SBRController) addSBRWatch() error { gvk := v1alpha1.SchemeGroupVersion.WithKind(ServiceBindingRequestKind) - logger := s.logger.WithValues("GKV", gvk) + log := s.logger.WithValues("GKV", gvk) source := s.createSourceForGVK(gvk) err := s.Controller.Watch(source, s.newEnqueueRequestsForSBR(), defaultPredicate) if err != nil { - logger.Error(err, "on creating watch for ServiceBindingRequest") + log.Error(err, "on creating watch for ServiceBindingRequest") return err } - logger.Info("Watch added for ServiceBindingRequest") + log.Debug("Watch added for ServiceBindingRequest") return nil } // addWhitelistedGVKWatches create watch on GVKs employed on CSVs. func (s *SBRController) addWhitelistedGVKWatches() error { + log := s.logger // list of interesting GVKs to watch gvks, err := s.getWatchingGVKs() if err != nil { - s.logger.Error(err, "on retrieving list of GVKs to watch") + log.Error(err, "on retrieving list of GVKs to watch") return err } for _, gvk := range gvks { - logger := s.logger.WithValues("GVK", gvk) - logger.Info("Adding watch for whitelisted GVK...") + log.Debug("Adding watch for whitelisted GVK...", "GVK", gvk) err = s.AddWatchForGVK(gvk) if err != nil { - logger.Error(err, "on creating watch for GVK") + log.Error(err, "on creating watch for GVK") return err } } @@ -149,21 +150,22 @@ func (s *SBRController) addWhitelistedGVKWatches() error { // Watch setup "watch" for all GVKs relevant for SBRController. func (s *SBRController) Watch() error { + log := s.logger err := s.addSBRWatch() if err != nil { - s.logger.Error(err, "on adding watch for ServiceBindingRequest") + log.Error(err, "on adding watch for ServiceBindingRequest") return err } err = s.addWhitelistedGVKWatches() if err != nil { - s.logger.Error(err, "on adding watch for whitelisted GVKs") + log.Error(err, "on adding watch for whitelisted GVKs") return err } err = s.addCSVWatch() if err != nil { - s.logger.Error(err, "on adding watch for ClusterServiceVersion") + log.Error(err, "on adding watch for ClusterServiceVersion") return err } @@ -186,6 +188,6 @@ func NewSBRController( Controller: c, Client: client, watchingGVKs: make(map[schema.GroupVersionKind]bool), - logger: logf.Log.WithName("sbrcontroller"), + logger: sbrControllerLog, }, nil } diff --git a/pkg/controller/servicebindingrequest/watch.go b/pkg/controller/servicebindingrequest/watch.go index c73be3815d..ffcc8f9f87 100644 --- a/pkg/controller/servicebindingrequest/watch.go +++ b/pkg/controller/servicebindingrequest/watch.go @@ -1,11 +1,16 @@ package servicebindingrequest import ( + "github.com/redhat-developer/service-binding-operator/pkg/log" "k8s.io/apimachinery/pkg/types" "sigs.k8s.io/controller-runtime/pkg/handler" "sigs.k8s.io/controller-runtime/pkg/reconcile" ) +var ( + watchLog = log.NewLog("watch") +) + // CSVToWatcherMapper creates a EventHandler interface to map ClusterServiceVersion objects back to // controller and add given GVK to watch list. type CSVToWatcherMapper struct { @@ -21,20 +26,19 @@ func (c *CSVToWatcherMapper) Map(obj handler.MapObject) []reconcile.Request { Name: obj.Meta.GetName(), } - logger := log.WithName("CSVToWatcherMapper").WithValues("Obj.NamespacedName", namespacedName) + log := watchLog.WithName("CSVToWatcherMapper").WithValues("Obj.NamespacedName", namespacedName) gvks, err := olm.ListGVKsFromCSVNamespacedName(namespacedName) if err != nil { - logger.Error(err, "Failed on listing GVK with namespaced-name!") + log.Error(err, "Failed on listing GVK with namespaced-name!") return []reconcile.Request{} } for _, gvk := range gvks { - logger = logger.WithValues("GVK", gvk) - logger.Info("Adding watch for GVK") + log.Debug("Adding watch for GVK", "GVK", gvk) err = c.controller.AddWatchForGVK(gvk) if err != nil { - logger.Error(err, "Failed to create a watch") + log.Error(err, "Failed to create a watch") } } diff --git a/pkg/log/log.go b/pkg/log/log.go new file mode 100644 index 0000000000..54f73d11cf --- /dev/null +++ b/pkg/log/log.go @@ -0,0 +1,101 @@ +package log + +import ( + "fmt" + + "github.com/go-logr/logr" + logf "sigs.k8s.io/controller-runtime/pkg/runtime/log" +) + +// Log logs messages to various levels. +// +// Based on the go-logr package. +// +// The Log type enables various verbosity levels to be logged +// based on to the --zap-level argument to the operator. +// +// To create an instance of the log named "main": +// +// log := log.NewLog("main") +// +// When --zap-level is not provided +// then the logging defaults to INFO level where log.Warning() and log.Info() are logged, +// +// if --zap-level is set to 1 +// then the logging goes to the DEBUG level where log.Debug() is logged, +// +// while the --zap-level set to 2 is reserved for a finer DEBUG-level logging +// provided by the log.Trace() function. +type Log struct { + log *logr.Logger //log instance +} + +// Error logs the message using go-logr package on a default level as ERROR +func (l *Log) Error(err error, msg string, keysAndValues ...interface{}) { + (*l.log).Error(err, msg, keysAndValues...) +} + +// Warning logs the message using go-logr package on a default level as WARNING +func (l *Log) Warning(msg string, keysAndValues ...interface{}) { + if (*l.log).V(0).Enabled() { + (*l.log).V(0).Info(fmt.Sprintf("WARNING: %s", msg), keysAndValues...) + } +} + +// Info logs the message using go-logr package on a default level as INFO +func (l *Log) Info(msg string, keysAndValues ...interface{}) { + if (*l.log).V(0).Enabled() { + (*l.log).V(0).Info(msg, keysAndValues...) + } +} + +// Debug logs the message using go-logr package on a V=1 level as DEBUG +func (l *Log) Debug(msg string, keysAndValues ...interface{}) { + if (*l.log).V(1).Enabled() { + (*l.log).V(1).Info(msg, keysAndValues...) + } +} + +// Trace logs the message using go-logr package on a V=1 level as TRACE +func (l *Log) Trace(msg string, keysAndValues ...interface{}) { + if (*l.log).V(2).Enabled() { + // The V(1) level here is intentional: + // sTRACE = finer DEBUG logging but is only enabled by setting V=2 + (*l.log).V(1).Info(fmt.Sprintf("TRACE: %s", msg), keysAndValues...) + } +} + +// NewLog returns an instance of a Log +func NewLog(name string, keysAndValues ...interface{}) *Log { + log := logf.Log.WithName(name).WithValues(keysAndValues...) + l := &Log{ + log: &log, + } + return l +} + +// SetLog sets a concrete logging implementation for all deferred Loggers. +func SetLog(log logr.Logger) { + logf.SetLogger(log) +} + +// WithValues adds some key-value pairs of context to a log. +// See Info for documentation on how key/value pairs work. +func (l *Log) WithValues(keysAndValues ...interface{}) *Log { + lgr := ((*l.log).WithValues(keysAndValues...)) + log := &Log{ + log: &lgr, + } + return log +} + +// WithName adds a new element to the log's name. Successive calls with WithName continue to append +// suffixes to the log's name. It's strongly reccomended that name segments contain only letters, +// digits, and hyphens (see the package documentation for more information). +func (l *Log) WithName(name string) *Log { + lgr := ((*l.log).WithName(name)) + log := &Log{ + log: &lgr, + } + return log +}