Merge pull request #14 from babysnakes/logging-refactor

Logging refactor

.run/Build & Run.run.xml

@@ -2,6 +2,7 @@
   <configuration default="false" name="Build &amp; Run" type="GoApplicationRunConfiguration" factoryName="Go Application">
     <module name="dynamic-environment" />
     <working_directory value="$PROJECT_DIR$" />
+    <parameters value="-zap-devel" />
     <envs>
       <env name="ENABLE_WEBHOOKS" value="false" />
     </envs>

Makefile

@@ -121,7 +121,7 @@ build: manifests generate fmt vet ## Build manager binary.
 
 .PHONY: run
 run: manifests generate fmt vet ## Run a controller from your host.
-	ENABLE_WEBHOOKS=false go run ./main.go
+	ENABLE_WEBHOOKS=false go run ./main.go -zap-devel
 
 .PHONY: docker-build
 docker-build: ## Build docker image with the manager.

README.md

@@ -1,8 +1,7 @@
 # Dynamic Environment Controller <img src="https://riskified.github.io/dynamic-environment-docs/img/de-logo.svg" alt="Dynamic Environment Logo" width="20">
 
-
 A k8s operator which supports testing on a multi-test workflows environment in a
-transparent way. This operator will listen to DynamicEnv, a new Riskified custom resource. 
+transparent way. This operator will listen to DynamicEnv, a new Riskified custom resource.
 In this resource we will configure the services from which we want to create a subset with new version of our app 
 and apply all the requirements for routing the requests to the matching subsets.
 Ready to get started? Check out the [docs](https://riskified.github.io/dynamic-environment-docs/).
@@ -161,6 +160,9 @@ To run our development operator:
 make install run
 ```
 
+> Note: if you run in development mode not using the `Makefile` add `-zap-devel` to your parameters
+> for better development logging.
+
 On another shell session you can deploy a sample _dynamic-environment_ resource to see the effect:
 
 ```shell

config/manager/manager.yaml

@@ -35,6 +35,9 @@ spec:
         - version
         - --default-version
         - shared
+        # uncomment the next two lines to set log level to debug (also error is valid value, default is info)
+        # - --zap-log-level
+        # - debug
         # uncomment below (and edit to your liking) to specify labels to be removed (comma separated list)
         #- --remove-labels
         #- argocd.argoproj.io/instance

controllers/dynamicenv_controller.go

@@ -29,7 +29,6 @@ import (
 	"k8s.io/apimachinery/pkg/types"
 	ctrl "sigs.k8s.io/controller-runtime"
 	"sigs.k8s.io/controller-runtime/pkg/client"
-	ctrllog "sigs.k8s.io/controller-runtime/pkg/log"
 	"sigs.k8s.io/controller-runtime/pkg/predicate"
 	"sigs.k8s.io/controller-runtime/pkg/source"
 	"sort"
@@ -42,6 +41,8 @@ import (
 	"github.com/riskified/dynamic-environment/pkg/watches"
 )
 
+var log = helpers.MkLogger("DynamicEnvReconciler")
+
 // DynamicEnvReconciler reconciles a DynamicEnv object
 type DynamicEnvReconciler struct {
 	client.Client
@@ -99,7 +100,6 @@ func (rls *ReconcileLoopStatus) addDeploymentMessage(subset string, tpe riskifie
 // For more details, check Reconcile and its Result here:
 // - https://pkg.go.dev/sigs.k8s.io/[email protected]/pkg/reconcile
 func (r *DynamicEnvReconciler) Reconcile(ctx context.Context, req ctrl.Request) (ctrl.Result, error) {
-	log := ctrllog.FromContext(ctx)
 	log.V(1).Info("Entered Reconcile Loop")
 	rls := ReconcileLoopStatus{
 		subsetMessages:   make(map[string]riskifiedv1alpha1.SubsetMessages),
@@ -119,6 +119,8 @@ func (r *DynamicEnvReconciler) Reconcile(ctx context.Context, req ctrl.Request)
 	}
 
 	uniqueVersion := helpers.UniqueDynamicEnvName(dynamicEnv)
+	resourceName := fmt.Sprintf("%s/%s", dynamicEnv.Namespace, dynamicEnv.Name)
+	log = log.WithValues("resource", resourceName)
 
 	if markedForDeletion(dynamicEnv) {
 		return r.cleanDynamicEnvResources(ctx, dynamicEnv)
@@ -178,7 +180,7 @@ func (r *DynamicEnvReconciler) Reconcile(ctx context.Context, req ctrl.Request)
 			StatusHandler:  &statusHandler,
 			Matches:        dynamicEnv.Spec.IstioMatches,
 			Subset:         s,
-			Log:            log,
+			Log:            helpers.MkLogger("DeploymentHandler", "resource", resourceName),
 			Ctx:            ctx,
 		}
 		deploymentHandlers = append(deploymentHandlers, &deploymentHandler)
@@ -207,7 +209,7 @@ func (r *DynamicEnvReconciler) Reconcile(ctx context.Context, req ctrl.Request)
 				StatusHandler:  &statusHandler,
 				ServiceHosts:   serviceHosts,
 				Owner:          owner,
-				Log:            log,
+				Log:            helpers.MkLogger("DestinationRuleHandler", "resource", resourceName),
 				Ctx:            ctx,
 			}
 			mrHandlers = append(mrHandlers, &destinationRuleHandler)
@@ -227,14 +229,14 @@ func (r *DynamicEnvReconciler) Reconcile(ctx context.Context, req ctrl.Request)
 				DefaultVersion: defaultVersionForSubset,
 				DynamicEnv:     dynamicEnv,
 				StatusHandler:  &statusHandler,
-				Log:            log,
+				Log:            helpers.MkLogger("VirtualServiceHandler", "resource", resourceName),
 				Ctx:            ctx,
 			}
 
 			mrHandlers = append(mrHandlers, &virtualServiceHandler)
 			if err := virtualServiceHandler.Handle(); err != nil {
 				if errors.IsConflict(err) {
-					ctrl.Log.V(1).Info("ignoring update error due to version conflict", "error", err)
+					log.V(1).Info("ignoring update error due to version conflict", "error", err)
 				} else {
 					log.Error(err, "error updating virtual service for subset", "subset", s.Name)
 					msg := fmt.Sprintf("error updating virtual service for subset (%s)", uniqueName)
@@ -347,7 +349,7 @@ func findDeletedSC(de *riskifiedv1alpha1.DynamicEnv, allSC map[string]riskifiedv
 		}
 	}
 	if len(removed) > 0 {
-		ctrl.Log.V(1).Info("Found subsets/consumers to be cleaned up", "subsets/consumers", removed)
+		log.V(1).Info("Found subsets/consumers to be cleaned up", "subsets/consumers", removed)
 	}
 	return removed
 }
@@ -395,7 +397,6 @@ func (r *DynamicEnvReconciler) addFinalizersIfRequired(ctx context.Context, de *
 }
 
 func (r *DynamicEnvReconciler) cleanDynamicEnvResources(ctx context.Context, de *riskifiedv1alpha1.DynamicEnv) (ctrl.Result, error) {
-	log := ctrllog.FromContext(ctx)
 	log.Info("Dynamic Env marked for deletion, cleaning up ...")
 	if helpers.StringSliceContains(names.DeleteDeployments, de.Finalizers) {
 		count, err := r.cleanupDeployments(ctx, de)
@@ -446,7 +447,7 @@ func (r *DynamicEnvReconciler) cleanupDeployments(ctx context.Context, de *riski
 		deployments = append(deployments, c.ResourceStatus)
 	}
 	for _, item := range deployments {
-		ctrl.Log.Info("Cleaning up deployment ...", "deployment", item)
+		log.Info("Cleaning up deployment ...", "deployment", item)
 		found := appsv1.Deployment{}
 		if err := r.Get(ctx, types.NamespacedName{Name: item.Name, Namespace: item.Namespace}, &found); err != nil { // if not found assume deleted
 			if errors.IsNotFound(err) {
@@ -471,7 +472,7 @@ func (r *DynamicEnvReconciler) cleanupDestinationRules(ctx context.Context, de *
 		drs = append(drs, s.DestinationRules...)
 	}
 	for _, item := range drs {
-		ctrl.Log.Info("Cleaning up destination rule ...", "destinationRule", item)
+		log.Info("Cleaning up destination rule ...", "destinationRule", item)
 		found := istionetwork.DestinationRule{}
 		if err := r.Get(ctx, types.NamespacedName{Name: item.Name, Namespace: item.Namespace}, &found); err != nil {
 			if errors.IsNotFound(err) { // if not found assume deleted
@@ -500,7 +501,7 @@ func (r *DynamicEnvReconciler) cleanupVirtualServices(ctx context.Context, de *r
 }
 
 func (r *DynamicEnvReconciler) deleteFinalizer(ctx context.Context, finalizer string, de *riskifiedv1alpha1.DynamicEnv) error {
-	ctrl.Log.Info("Deleting finalizer from dynamic env", "finalizer", finalizer)
+	log.Info("Deleting finalizer from dynamic env", "finalizer", finalizer)
 	remainingFinalizers := helpers.RemoveItemFromStringSlice(finalizer, de.Finalizers)
 	de.Finalizers = remainingFinalizers
 	if err := r.Update(ctx, de); err != nil {
@@ -532,18 +533,18 @@ func (r *DynamicEnvReconciler) cleanupRemovedSubsetsOrConsumers(ctx context.Cont
 		if typ == riskifiedv1alpha1.CONSUMER {
 			if err := r.cleanupConsumer(ctx, name, de); err != nil {
 				if errors.IsConflict(err) {
-					ctrl.Log.Info("Ignoring conflict removing consumer", "consumer", name)
+					log.Info("Ignoring conflict removing consumer", "consumer", name)
 				} else {
-					ctrl.Log.Error(err, "cleanup removed consumer")
+					log.Error(err, "cleanup removed consumer")
 					return fmt.Errorf("cleanup removed consumer: %w", err)
 				}
 			}
 		} else {
 			if err := r.cleanupSubset(ctx, name, de); err != nil {
 				if errors.IsConflict(err) {
-					ctrl.Log.Info("Ignoring conflict removing subset", "subset", name)
+					log.Info("Ignoring conflict removing subset", "subset", name)
 				} else {
-					ctrl.Log.Error(err, "cleanup removed subset")
+					log.Error(err, "cleanup removed subset")
 					return fmt.Errorf("cleanup removed subset: %w", err)
 				}
 			}
@@ -569,7 +570,7 @@ func (r *DynamicEnvReconciler) cleanupConsumer(ctx context.Context, name string,
 			}
 		}
 	}
-	ctrl.Log.V(1).Info("Consumer cleanup finished", "consumer", name)
+	log.V(1).Info("Consumer cleanup finished", "consumer", name)
 	return nil
 }
 
@@ -606,7 +607,7 @@ func (r *DynamicEnvReconciler) cleanupSubset(ctx context.Context, name string, d
 			return fmt.Errorf("deleting removed subset status: %w", err)
 		}
 	}
-	ctrl.Log.V(1).Info("Subset cleanup finished", "subset", name)
+	log.V(1).Info("Subset cleanup finished", "subset", name)
 	return nil
 }
 
@@ -640,29 +641,29 @@ func (r *DynamicEnvReconciler) deleteDestinationRule(ctx context.Context, dr ris
 
 func (r *DynamicEnvReconciler) cleanupVirtualService(ctx context.Context, vs riskifiedv1alpha1.ResourceStatus, de *riskifiedv1alpha1.DynamicEnv) error {
 	version := helpers.UniqueDynamicEnvName(de)
-	ctrl.Log.Info("Cleaning up Virtual Service ...", "virtual-service", vs)
+	log.Info("Cleaning up Virtual Service ...", "virtual-service", vs)
 	found := istionetwork.VirtualService{}
 	if err := r.Get(ctx, types.NamespacedName{Name: vs.Name, Namespace: vs.Namespace}, &found); err != nil {
 		if errors.IsNotFound(err) {
-			ctrl.Log.Info("Cleanup: Didn't find virtual service. Probably deleted", "virtual-service", vs)
+			log.Info("Cleanup: Didn't find virtual service. Probably deleted", "virtual-service", vs)
 			return nil
 		} else {
-			ctrl.Log.Error(err, "error searching for virtual service during cleanup", "virtual-service", vs)
+			log.Error(err, "error searching for virtual service during cleanup", "virtual-service", vs)
 			return err
 		}
 	}
 	var newRoutes []*istioapi.HTTPRoute
 	for _, route := range found.Spec.Http {
 		if strings.HasPrefix(route.Name, helpers.CalculateVirtualServicePrefix(version, "")) {
-			ctrl.Log.V(1).Info("Found route to cleanup", "route", route)
+			log.V(1).Info("Found route to cleanup", "route", route)
 			continue
 		}
 		newRoutes = append(newRoutes, route)
 	}
 	found.Spec.Http = newRoutes
 	watches.RemoveFromAnnotation(types.NamespacedName{Name: de.Name, Namespace: de.Namespace}, &found)
 	if err := r.Update(ctx, &found); err != nil {
-		ctrl.Log.Error(err, "error updating virtual service after cleanup", "virtual-service", found.Name)
+		log.Error(err, "error updating virtual service after cleanup", "virtual-service", found.Name)
 		return err
 	}
 	return nil

helm/dynamic-environment/templates/deployment.yaml

@@ -60,6 +60,10 @@ spec:
         - --remove-labels
         - {{ $removeLabels }}
         {{- end }}
+        {{- if .Values.command.debugLogger }}
+        - --zap-log-level
+        - debug
+        {{- end }}
         command:
         - /manager
         image: "{{ .Values.image.repository }}:{{ .Values.image.tag }}"

helm/dynamic-environment/values.yaml

@@ -34,6 +34,8 @@ command:
   # Specify a default version other than the default 'shared'. This version will be used when searching default
   # DestinationRule. Could be specified per subset in the CR.
   defaultVersion: "shared"
+  # Set log level to debug
+  debugLogger: false
 
 # Labels to be deleted form deployments when duplicating (e.g. labels that connect deployment to argocd app):
 labelsToRemove: []

main.go

@@ -98,9 +98,7 @@ func main() {
 	flag.StringVar(&defaultVersion, "default-version", names.DefaultVersion,
 		"The global default version - this version is the one that gets the default route. Could be overridden per subset.")
 	flag.Var(&labelsToRemove, "remove-labels", "A comma separated list of labels to remove when duplicating deployment.")
-	opts := zap.Options{
-		Development: true,
-	}
+	opts := zap.Options{}
 	opts.BindFlags(flag.CommandLine)
 	flag.Parse()
 

pkg/handlers/deployment_handler.go

@@ -122,8 +122,7 @@ func (h *DeploymentHandler) GetStatus() (riskifiedv1alpha1.ResourceStatus, error
 			return riskifiedv1alpha1.ResourceStatus{}, e
 		}
 	}
-	// TODO: This fails in testing - try to make it work.
-	// h.Log.V(1).Info("status found for deployment", "deployment", searchName, "status", deployment.Status)
+	h.Log.V(1).Info("status found for deployment", "deployment", searchName, "status", deployment.Status)
 
 	found, processing := getMostRecentConditionForType(appsv1.DeploymentProgressing, deployment.Status.Conditions)
 	if !found {

pkg/handlers/deployment_handler_test.go

@@ -19,6 +19,7 @@ package handlers_test
 import (
 	"context"
 	"fmt"
+	"github.com/riskified/dynamic-environment/pkg/helpers"
 	"github.com/riskified/dynamic-environment/pkg/names"
 	"io"
 	"os"
@@ -71,6 +72,7 @@ var _ = Describe("DeploymentHandler", func() {
 					Namespace: ns,
 				},
 				VersionLabel: names.DefaultVersionLabel,
+				Log:          helpers.MkLogger("TestsLogger"),
 			}
 		}
 

pkg/helpers/helpers.go

@@ -22,9 +22,10 @@ import (
 	"strings"
 
 	riskifiedv1alpha1 "github.com/riskified/dynamic-environment/api/v1alpha1"
-	ctrl "sigs.k8s.io/controller-runtime"
 )
 
+var log = MkLogger("DynamicEnv")
+
 const (
 	KeyValueHeaderSeparator    = ":"
 	KeyValueHeaderConcatinator = "|"
@@ -104,7 +105,7 @@ func SerializeIstioMatchExactHeaders(headers map[string]riskifiedv1alpha1.String
 			}
 			fmt.Fprintf(&serialized, "%s%s%s", k, KeyValueHeaderSeparator, v.Exact)
 		} else {
-			ctrl.Log.V(1).Info("Ignoring non-exact header while serializing match for envoy filters", "ignored-key", k)
+			log.V(1).Info("Ignoring non-exact header while serializing match for envoy filters", "ignored-key", k)
 		}
 	}
 	return serialized.String()

pkg/helpers/k8s_helpers.go

@@ -18,9 +18,11 @@ package helpers
 
 import (
 	"fmt"
+	"github.com/go-logr/logr"
 
 	"github.com/riskified/dynamic-environment/pkg/names"
 	v1 "k8s.io/api/core/v1"
+	ctrllog "sigs.k8s.io/controller-runtime/pkg/log"
 )
 
 // MatchNamespacedHost compares the provided `hostname` and `namespace` to the provided `matchHost`.
@@ -77,3 +79,8 @@ func CalculateVirtualServicePrefix(version, subset string) string {
 	}
 	return fmt.Sprintf("%s-%s-%s", names.VirtualServiceRoutePrefix, version, subsetPart)
 }
+
+// Generates Logger with provided values
+func MkLogger(name string, keysAndValues ...interface{}) logr.Logger {
+	return ctrllog.Log.WithName(name).WithValues(keysAndValues...)
+}

pkg/metrics/collector.go

@@ -28,7 +28,7 @@ import (
 )
 
 var (
-	log                     = ctrl.Log.WithName("collector")
+	log                     = ctrl.Log.WithName("DynamicEnvCollector")
 	runningEnvironmentsDesc = prometheus.NewDesc(
 		"dynamic_environments",
 		"Number of deployed dynamic environments per namespace",