improve logging

pkg/controller/common/resource_reconciler.go

@@ -68,14 +68,17 @@ func (r *resourceReconciler) tick(ctx context.Context) error {
 	}()
 
 	for _, res := range r.resources {
+		lgr := r.logger.WithValues("name", res.GetName(), "namespace", res.GetNamespace(), "kind", res.GetObjectKind().GroupVersionKind())
 		copy := res.DeepCopyObject().(client.Object)
 		if copy.GetDeletionTimestamp() != nil {
+			lgr.Info("deleting resource")
 			if err = r.client.Delete(ctx, copy); err != nil && !k8serrors.IsNotFound(err) {
 				r.logger.Error(err, "deleting unneeded resources")
 			}
 			continue
 		}
 
+		lgr.Info("upserting resource")
 		if err = util.Upsert(ctx, r.client, copy); err != nil {
 			r.logger.Error(err, "upserting resources")
 			return err

pkg/controller/ingress/concurrency_watchdog.go

@@ -39,6 +39,9 @@ type ScrapeFn func(ctx context.Context, client rest.Interface, pod *corev1.Pod)
 
 // NginxScrapeFn is the scrape function for Nginx
 func NginxScrapeFn(ctx context.Context, client rest.Interface, pod *corev1.Pod) (float64, error) {
+	lgr := logr.FromContextOrDiscard(ctx)
+
+	lgr.Info("scraping pod", "pod", pod.Name)
 	resp, err := client.Get().
 		AbsPath("/api/v1/namespaces", pod.Namespace, "pods", pod.Name+":10254", "proxy/metrics").
 		Timeout(time.Second * 30).
@@ -68,6 +71,7 @@ func NginxScrapeFn(ctx context.Context, client rest.Interface, pod *corev1.Pod)
 			return metric.Gauge.GetValue(), nil
 		}
 	}
+
 	return 0, fmt.Errorf("active connections metric not found")
 }
 
@@ -154,28 +158,33 @@ func (c *ConcurrencyWatchdog) tick(ctx context.Context) error {
 	}()
 
 	for _, target := range c.targets {
-		c.logger.Info("starting checking on ingress controller pods", "labels", target.PodLabels())
+		lgr := c.logger.WithValues("target", target.LabelGetter.PodLabels())
+		lgr.Info("starting checking on ingress controller pods")
 
+		lgr.Info("listing pods")
 		list := &corev1.PodList{}
 		err := c.client.List(ctx, list, client.InNamespace(c.config.NS), client.MatchingLabels(target.LabelGetter.PodLabels()))
 		if err != nil {
-			c.logger.Error(err, "error listing pods")
+			lgr.Error(err, "listing pods")
 			retErr = multierror.Append(retErr, fmt.Errorf("listing pods: %w", err))
 			continue
 		}
 
+		lgr.Info("gathering metrics for each pod")
 		connectionCountByPod := make([]float64, len(list.Items))
 		nReadyPods := 0
 		var totalConnectionCount float64
 		for i, pod := range list.Items {
+			lgr := lgr.WithValues("pod", pod.Name)
 			if !podIsReady(&pod) {
-				c.logger.Info("pod is not ready", "name", pod.Name)
+				lgr.Info("pod is not ready", "name", pod.Name)
 				continue
 			}
 			nReadyPods++
+			ctx := logr.NewContext(ctx, lgr)
 			count, err := target.ScrapeFn(ctx, c.restClient, &pod)
 			if err != nil {
-				c.logger.Error(err, "error scraping pod", "name", pod.Name)
+				lgr.Error(err, "scraping pod", "name", pod.Name)
 				retErr = multierror.Append(retErr, fmt.Errorf("scraping pod %q: %w", pod.Name, err))
 				continue
 			}
@@ -187,15 +196,18 @@ func (c *ConcurrencyWatchdog) tick(ctx context.Context) error {
 		// Only rebalance connections when three or more replicas are ready.
 		// Otherwise we will just push the connections to the other replica.
 		if nReadyPods < 3 {
+			lgr.Info("not enough ready pods to rebalance connections", "readyPods", nReadyPods)
 			continue
 		}
 
+		lgr.Info("processing votes")
 		pod := c.processVotes(list, connectionCountByPod, avgConnectionCount)
 		if pod == "" {
+			lgr.Info("no pod to evict")
 			continue
 		}
 
-		c.logger.Info("evicting pod due to high relative connection concurrency", "name", pod)
+		lgr.Info("evicting pod due to high relative connection concurrency", "name", pod)
 		eviction := &policyv1beta1.Eviction{
 			ObjectMeta: metav1.ObjectMeta{
 				Name:      pod,
@@ -204,12 +216,12 @@ func (c *ConcurrencyWatchdog) tick(ctx context.Context) error {
 		}
 
 		if err := c.clientset.CoreV1().Pods(eviction.Namespace).EvictV1beta1(ctx, eviction); err != nil {
-			c.logger.Error(err, "unable to evict pod", "name", pod)
+			lgr.Error(err, "unable to evict pod", "name", pod)
 			// don't add the error to return since we shouldn't retry right away
 		}
 	}
 	if err := retErr.ErrorOrNil(); err != nil {
-		c.logger.Error(err, "error reconciling ingress controller resources")
+		c.logger.Error(err, "reconciling ingress controller resources")
 		return err
 	}
 	return nil

pkg/controller/keyvault/event_mirror.go

@@ -5,12 +5,14 @@ package keyvault
 
 import (
 	"context"
+	"fmt"
 	"strings"
 
 	"github.com/Azure/aks-app-routing-operator/pkg/controller/controllername"
 	"github.com/go-logr/logr"
 	corev1 "k8s.io/api/core/v1"
 	netv1 "k8s.io/api/networking/v1"
+	k8serrors "k8s.io/apimachinery/pkg/api/errors"
 	"k8s.io/client-go/tools/record"
 	ctrl "sigs.k8s.io/controller-runtime"
 	"sigs.k8s.io/controller-runtime/pkg/client"
@@ -69,53 +71,74 @@ func (e *EventMirror) Reconcile(ctx context.Context, req ctrl.Request) (ctrl.Res
 	}
 	logger = eventMirrorControllerName.AddToLogger(logger)
 
+	logger.Info("getting event", "name", req.Name, "namespace", req.Namespace)
 	event := &corev1.Event{}
 	err = e.client.Get(ctx, req.NamespacedName, event)
 	if err != nil {
 		return result, client.IgnoreNotFound(err)
 	}
+	logger = logger.WithValues("generation", event.Generation)
 
 	// Filter to include only keyvault mounting errors
 	if event.InvolvedObject.Kind != "Pod" ||
 		event.Reason != "FailedMount" ||
 		!strings.HasPrefix(event.InvolvedObject.Name, "keyvault-") ||
 		!strings.Contains(event.Message, "keyvault") {
+		logger.Info("ignoring event, not keyvault mounting error")
 		return result, nil
 	}
 
 	// Get the owner (pod)
+	podName := event.InvolvedObject.Name
+	podNamespace := event.InvolvedObject.Namespace
+	logger.Info("getting owner placeholder pod", "name", podName, "namespace", podNamespace)
 	pod := &corev1.Pod{}
-	pod.Name = event.InvolvedObject.Name
-	pod.Namespace = event.InvolvedObject.Namespace
+	pod.Name = podName
+	pod.Namespace = podNamespace
 	err = e.client.Get(ctx, client.ObjectKeyFromObject(pod), pod)
 	if err != nil {
 		return result, client.IgnoreNotFound(err)
 	}
 	if pod.Annotations == nil {
+		logger.Info("ignoring event, pod has no annotations")
 		return result, nil
 	}
 
 	// Get the owner (ingress)
+	ingressName := pod.Annotations["kubernetes.azure.com/ingress-owner"]
+	if ingressName == "" {
+		logger.Info("ignoring event, pod has no ingress owner")
+		return result, nil
+	}
+
+	ingressNamespace := pod.Namespace
+	logger.Info("getting owner ingress", "name", ingressName, "namespace", ingressNamespace)
 	ingress := &netv1.Ingress{}
-	ingress.Namespace = pod.Namespace
-	ingress.Name = pod.Annotations["kubernetes.azure.com/ingress-owner"]
+	ingress.Namespace = ingressNamespace
+	ingress.Name = ingressName
 	err = e.client.Get(ctx, client.ObjectKeyFromObject(ingress), ingress)
 	if err != nil {
 		return result, client.IgnoreNotFound(err)
 	}
 
 	// Publish to the service also if ingress is owned by a service
 	if name := util.FindOwnerKind(ingress.OwnerReferences, "Service"); name != "" {
+		logger.Info("getting owner service", "name", name, "namespace", pod.Namespace)
+		svcNamespace := pod.Namespace
 		svc := &corev1.Service{}
-		svc.Namespace = pod.Namespace
+		svc.Namespace = svcNamespace
 		svc.Name = name
 		err = e.client.Get(ctx, client.ObjectKeyFromObject(svc), svc)
-		if err != nil {
-			return result, client.IgnoreNotFound(err)
+		if err == nil {
+			logger.Info("publishing FailedMount warning event to service", "service", svc.Name, "namespace", svc.Namespace)
+			e.events.Event(svc, "Warning", "FailedMount", event.Message)
+		}
+		if err != nil && !k8serrors.IsNotFound(err) {
+			return result, fmt.Errorf("getting owner service: %w", err)
 		}
-		e.events.Event(svc, "Warning", "FailedMount", event.Message)
 	}
 
+	logger.Info("publishing FailedMount warning event to ingress", "ingress", ingress.Name, "namespace", ingress.Namespace)
 	e.events.Event(ingress, "Warning", "FailedMount", event.Message)
 	return result, nil
 }

pkg/controller/keyvault/ingress_secret_provider_class.go

@@ -73,8 +73,9 @@ func (i *IngressSecretProviderClassReconciler) Reconcile(ctx context.Context, re
 	if err != nil {
 		return result, err
 	}
-	logger = ingressSecretProviderControllerName.AddToLogger(logger)
+	logger = ingressSecretProviderControllerName.AddToLogger(logger).WithValues("name", req.Name, "namespace", req.Namespace)
 
+	logger.Info("getting Ingress")
 	ing := &netv1.Ingress{}
 	err = i.client.Get(ctx, req.NamespacedName, ing)
 	if err != nil {
@@ -99,8 +100,10 @@ func (i *IngressSecretProviderClassReconciler) Reconcile(ctx context.Context, re
 			}},
 		},
 	}
+	logger = logger.WithValues("spc", spc.Name)
 	ok, err := i.buildSPC(ing, spc)
 	if err != nil {
+		logger.Info("failed to build secret provider class for ingress, user input invalid. sending warning event")
 		i.events.Eventf(ing, "Warning", "InvalidInput", "error while processing Keyvault reference: %s", err)
 		return result, nil
 	}
@@ -110,6 +113,8 @@ func (i *IngressSecretProviderClassReconciler) Reconcile(ctx context.Context, re
 		return result, err
 	}
 
+	logger.Info("cleaning unused managed spc for ingress")
+	logger.Info("getting secret provider class for ingress")
 	err = i.client.Get(ctx, client.ObjectKeyFromObject(spc), spc)
 	if err != nil {
 		return result, client.IgnoreNotFound(err)

pkg/controller/keyvault/placeholder_pod.go

@@ -69,8 +69,9 @@ func (p *PlaceholderPodController) Reconcile(ctx context.Context, req ctrl.Reque
 	if err != nil {
 		return result, err
 	}
-	logger = placeholderPodControllerName.AddToLogger(logger)
+	logger = placeholderPodControllerName.AddToLogger(logger).WithValues("namespace", req.Namespace, "name", req.Name)
 
+	logger.Info("getting secret provider class")
 	spc := &secv1.SecretProviderClass{}
 	err = p.client.Get(ctx, req.NamespacedName, spc)
 	if err != nil {
@@ -95,28 +96,35 @@ func (p *PlaceholderPodController) Reconcile(ctx context.Context, req ctrl.Reque
 			}},
 		},
 	}
+	logger = logger.WithValues("deployment", dep.Name)
 
 	ing := &netv1.Ingress{}
 	ing.Name = util.FindOwnerKind(spc.OwnerReferences, "Ingress")
 	ing.Namespace = req.Namespace
+	logger = logger.WithValues("ingress", ing.Name)
 	if ing.Name != "" {
+		logger.Info("getting owner ingress")
 		if err = p.client.Get(ctx, client.ObjectKeyFromObject(ing), ing); err != nil {
-			return result, err
+			return result, client.IgnoreNotFound(err)
 		}
 	}
 
 	managed := p.ingressManager.IsManaging(ing)
 	if ing.Name == "" || ing.Spec.IngressClassName == nil || !managed {
+		logger.Info("cleaning unused placeholder pod deployment")
+
+		logger.Info("getting placeholder deployment")
 		if err = p.client.Get(ctx, client.ObjectKeyFromObject(dep), dep); err != nil {
-			return result, err
+			return result, client.IgnoreNotFound(err)
 		}
+
+		logger.Info("deleting placeholder deployment")
 		err = p.client.Delete(ctx, dep)
-		return result, err
+		return result, client.IgnoreNotFound(err)
 	}
 
-	logger.Info("reconciling placeholder deployment for secret provider class")
-
 	// Manage a deployment resource
+	logger.Info("reconciling placeholder deployment for secret provider class")
 	p.buildDeployment(dep, spc, ing)
 	if err = util.Upsert(ctx, p.client, dep); err != nil {
 		return result, err

pkg/controller/osm/ingress_backend_reconciler.go

@@ -96,13 +96,16 @@ func (i *IngressBackendReconciler) Reconcile(ctx context.Context, req ctrl.Reque
 	}
 	logger = ingressBackendControllerName.AddToLogger(logger)
 
+	logger.Info("getting Ingress", "name", req.Name, "namespace", req.Namespace)
 	ing := &netv1.Ingress{}
 	err = i.client.Get(ctx, req.NamespacedName, ing)
 	if err != nil {
 		return result, client.IgnoreNotFound(err)
 	}
 	logger = logger.WithValues("name", ing.Name, "namespace", ing.Namespace, "generation", ing.Generation)
 
+	// TODO: add label and check for label before cleanup
+
 	backend := &policyv1alpha1.IngressBackend{
 		TypeMeta: metav1.TypeMeta{
 			Kind:       "IngressBackend",
@@ -120,14 +123,20 @@ func (i *IngressBackendReconciler) Reconcile(ctx context.Context, req ctrl.Reque
 			}},
 		},
 	}
+	logger = logger.WithValues("ingressBackend", backend.Name)
 
 	controllerName, ok := i.ingressControllerNamer.IngressControllerName(ing)
-	logger = logger.WithValues("controller", controllerName)
+	logger = logger.WithValues("ingressController", controllerName)
 	if ing.Annotations == nil || ing.Annotations["kubernetes.azure.com/use-osm-mtls"] == "" || !ok {
+		logger.Info("Ingress does not have osm mtls annotation, cleaning up managed IngressBackend")
+
+		logger.Info("getting IngressBackend")
 		err = i.client.Get(ctx, client.ObjectKeyFromObject(backend), backend)
 		if err != nil {
 			return result, client.IgnoreNotFound(err)
 		}
+
+		logger.Info("deleting IngressBackend")
 		err = i.client.Delete(ctx, backend)
 		return result, err
 	}

pkg/controller/osm/ingress_cert_config_reconciler.go

@@ -5,6 +5,7 @@ package osm
 
 import (
 	"context"
+	"fmt"
 
 	"github.com/Azure/aks-app-routing-operator/pkg/controller/controllername"
 	"github.com/go-logr/logr"
@@ -63,44 +64,52 @@ func (i *IngressCertConfigReconciler) Reconcile(ctx context.Context, req ctrl.Re
 	if err != nil {
 		return result, err
 	}
-	logger = ingressCertConfigControllerName.AddToLogger(logger)
+	logger = ingressCertConfigControllerName.AddToLogger(logger).WithValues("namespace", req.Namespace, "name", req.Name)
 
 	if req.Name != osmMeshConfigName || req.Namespace != osmNamespace {
+		logger.Info(fmt.Sprintf("ignoring mesh config, we only reconcile mesh config %s/%s", osmNamespace, osmMeshConfigName))
 		return result, nil
 	}
 
+	logger.Info("getting OSM ingress mesh config")
 	conf := &cfgv1alpha2.MeshConfig{}
 	err = i.client.Get(ctx, req.NamespacedName, conf)
 	if err != nil {
 		return result, client.IgnoreNotFound(err)
 	}
+	logger = logger.WithValues("generation", conf.Generation)
 
 	var dirty bool
 	if conf.Spec.Certificate.IngressGateway == nil {
 		conf.Spec.Certificate.IngressGateway = &cfgv1alpha2.IngressGatewayCertSpec{}
 	}
 	if conf.Spec.Certificate.IngressGateway.Secret.Name != osmClientCertName {
+		logger.Info("updating IngressGateway client cert secret name")
 		dirty = true
 		conf.Spec.Certificate.IngressGateway.Secret.Name = osmClientCertName
 	}
 	if conf.Spec.Certificate.IngressGateway.Secret.Namespace != osmNamespace {
+		logger.Info("updating IngressGateway client cert secret namespace")
 		dirty = true
 		conf.Spec.Certificate.IngressGateway.Secret.Namespace = osmNamespace
 	}
 	if conf.Spec.Certificate.IngressGateway.ValidityDuration != osmClientCertValidity {
+		logger.Info("updating IngressGateway client cert validity duration")
 		dirty = true
 		conf.Spec.Certificate.IngressGateway.ValidityDuration = osmClientCertValidity
 	}
 	if l := len(conf.Spec.Certificate.IngressGateway.SubjectAltNames); l != 1 ||
 		(l == 1 && conf.Spec.Certificate.IngressGateway.SubjectAltNames[0] != osmNginxSAN) {
+		logger.Info("updating IngressGateway SAN")
 		dirty = true
 		conf.Spec.Certificate.IngressGateway.SubjectAltNames = []string{osmNginxSAN}
 	}
 	if !dirty {
+		logger.Info("no changes required for OSM ingress client cert configuration")
 		return result, nil
 	}
 
-	logger.Info("updating OSM ingress client cert configuration")
+	logger.Info("updating OSM ingress mesh config")
 	err = i.client.Update(ctx, conf)
 	return result, err
 }