logging: adjust reconcilers to log object owners

sbueringer · sbueringer · commit 934bc6bd5301 · 2022-09-05T19:15:12.000+02:00
Signed-off-by: Stefan Büringer buringerst@vmware.com
diff --git a/Tiltfile b/Tiltfile
@@ -474,7 +474,7 @@ def deploy_observability():
 
     if "grafana" in settings.get("deploy_observability", []):
         k8s_yaml(read_file("./.tiltbuild/yaml/grafana.observability.yaml"), allow_duplicates = True)
-        k8s_resource(workload = "grafana", port_forwards = "3001:3000", extra_pod_selectors = [{"app": "grafana"}], labels = ["observability"])
+        k8s_resource(workload = "grafana", port_forwards = "3001:3000", extra_pod_selectors = [{"app": "grafana"}], labels = ["observability"], objects = ["grafana:serviceaccount"])
 
     if "prometheus" in settings.get("deploy_observability", []):
         k8s_yaml(read_file("./.tiltbuild/yaml/prometheus.observability.yaml"), allow_duplicates = True)
diff --git a/bootstrap/kubeadm/config/rbac/role.yaml b/bootstrap/kubeadm/config/rbac/role.yaml
@@ -42,6 +42,7 @@ rules:
   - machinepools/status
   - machines
   - machines/status
+  - machinesets
   verbs:
   - get
   - list
diff --git a/bootstrap/kubeadm/internal/controllers/kubeadmconfig_controller.go b/bootstrap/kubeadm/internal/controllers/kubeadmconfig_controller.go
@@ -52,6 +52,7 @@ import (
 	"sigs.k8s.io/cluster-api/util"
 	"sigs.k8s.io/cluster-api/util/annotations"
 	"sigs.k8s.io/cluster-api/util/conditions"
+	clog "sigs.k8s.io/cluster-api/util/log"
 	"sigs.k8s.io/cluster-api/util/patch"
 	"sigs.k8s.io/cluster-api/util/predicates"
 	"sigs.k8s.io/cluster-api/util/secret"
@@ -74,7 +75,7 @@ type InitLocker interface {
 }
 
 // +kubebuilder:rbac:groups=bootstrap.cluster.x-k8s.io,resources=kubeadmconfigs;kubeadmconfigs/status;kubeadmconfigs/finalizers,verbs=get;list;watch;create;update;patch;delete
-// +kubebuilder:rbac:groups=cluster.x-k8s.io,resources=clusters;clusters/status;machines;machines/status;machinepools;machinepools/status,verbs=get;list;watch
+// +kubebuilder:rbac:groups=cluster.x-k8s.io,resources=clusters;clusters/status;machinesets;machines;machines/status;machinepools;machinepools/status,verbs=get;list;watch
 // +kubebuilder:rbac:groups="",resources=secrets;events;configmaps,verbs=get;list;watch;create;update;patch;delete
 
 // KubeadmConfigReconciler reconciles a KubeadmConfig object.
@@ -160,6 +161,13 @@ func (r *KubeadmConfigReconciler) Reconcile(ctx context.Context, req ctrl.Reques
 		return ctrl.Result{}, err
 	}
 
+	// AddOwners adds the owners of KubeadmConfig as k/v pairs to the logger.
+	// Specifically, it will add KubeadmControlPlane, MachineSet and MachineDeployment.
+	ctx, log, err := clog.AddOwners(ctx, r.Client, config)
+	if err != nil {
+		return ctrl.Result{}, err
+	}
+
 	// Look up the owner of this kubeadm config if there is one
 	configOwner, err := bsutil.GetConfigOwner(ctx, r.Client, config)
 	if apierrors.IsNotFound(err) {
diff --git a/docs/book/src/developer/logging.md b/docs/book/src/developer/logging.md
@@ -180,6 +180,11 @@ Will return logs from the `capi-controller-manager` which are parsed in json. Pa
 ```
 Will return logs from the `capi-controller-manager` that are associated with the Cluster `my-cluster`.
 
+```
+{app="capi-controller-manager"} | json | cluster_name="my-cluster" | v <= 2
+```
+Will return logs from the `capi-controller-manager` that are associated with the Cluster `my-cluster` with log level <= 2.
+
 ```
 {app="capi-controller-manager"} | json | cluster_name="my-cluster" reconcileID="6f6ad971-bdb6-4fa3-b803-xxxxxxxxxxxx"
 ```
diff --git a/docs/book/src/developer/providers/v1.2-to-v1.3.md b/docs/book/src/developer/providers/v1.2-to-v1.3.md
@@ -35,3 +35,6 @@ in Cluster API are kept in sync with the versions used by `sigs.k8s.io/controlle
   * the default test timeout has been [changed to 1h](https://onsi.github.io/ginkgo/MIGRATING_TO_V2#timeout-behavior)
   * the `--junit-report` argument [replaces JUnit custom reporter](https://onsi.github.io/ginkgo/MIGRATING_TO_V2#improved-reporting-infrastructure) code
   * see the ["Update tests to Ginkgo v2" PR](https://github.com/kubernetes-sigs/cluster-api/pull/6906) for a reference example
+- Custer API introduced new [logging guidelines](../../developer/logging.md). All reconcilers in the core repository were updated
+  to [log the entire object hierarchy](../../developer/logging.md#keyvalue-pairs). It would be great if providers would be adjusted 
+  as well to make it possible to cross-reference log entries across providers (please see CAPD for an infra provider reference implementation). 
diff --git a/exp/internal/controllers/machinepool_controller_phases.go b/exp/internal/controllers/machinepool_controller_phases.go
@@ -134,7 +134,7 @@ func (r *MachinePoolReconciler) reconcileExternal(ctx context.Context, cluster *
 	// Add watcher for external object, if there isn't one already.
 	_, loaded := r.externalWatchers.LoadOrStore(obj.GroupVersionKind().String(), struct{}{})
 	if !loaded && r.controller != nil {
-		log.Info("Adding watcher on external object", "gvk", obj.GroupVersionKind())
+		log.Info("Adding watcher on external object", "groupVersionKind", obj.GroupVersionKind())
 		err := r.controller.Watch(
 			&source.Kind{Type: obj},
 			&handler.EnqueueRequestForOwner{OwnerType: &expv1.MachinePool{}},
diff --git a/internal/controllers/machine/machine_controller.go b/internal/controllers/machine/machine_controller.go
@@ -50,6 +50,7 @@ import (
 	"sigs.k8s.io/cluster-api/util/annotations"
 	"sigs.k8s.io/cluster-api/util/collections"
 	"sigs.k8s.io/cluster-api/util/conditions"
+	clog "sigs.k8s.io/cluster-api/util/log"
 	"sigs.k8s.io/cluster-api/util/patch"
 	"sigs.k8s.io/cluster-api/util/predicates"
 )
@@ -137,8 +138,6 @@ func (r *Reconciler) SetupWithManager(ctx context.Context, mgr ctrl.Manager, opt
 }
 
 func (r *Reconciler) Reconcile(ctx context.Context, req ctrl.Request) (_ ctrl.Result, reterr error) {
-	log := ctrl.LoggerFrom(ctx)
-
 	// Fetch the Machine instance
 	m := &clusterv1.Machine{}
 	if err := r.Client.Get(ctx, req.NamespacedName, m); err != nil {
@@ -152,6 +151,13 @@ func (r *Reconciler) Reconcile(ctx context.Context, req ctrl.Request) (_ ctrl.Re
 		return ctrl.Result{}, err
 	}
 
+	// AddOwners adds the owners of Machine as k/v pairs to the logger.
+	// Specifically, it will add KubeadmControlPlane, MachineSet and MachineDeployment.
+	ctx, log, err := clog.AddOwners(ctx, r.Client, m)
+	if err != nil {
+		return ctrl.Result{}, err
+	}
+
 	log = log.WithValues("Cluster", klog.KRef(m.ObjectMeta.Namespace, m.Spec.ClusterName))
 	ctx = ctrl.LoggerInto(ctx, log)
 
diff --git a/internal/controllers/machine/machine_controller_phases.go b/internal/controllers/machine/machine_controller_phases.go
@@ -98,7 +98,7 @@ func (r *Reconciler) reconcileExternal(ctx context.Context, cluster *clusterv1.C
 	obj, err := external.Get(ctx, r.Client, ref, m.Namespace)
 	if err != nil {
 		if apierrors.IsNotFound(errors.Cause(err)) {
-			log.Info("could not find external ref, requeueing", "refGVK", ref.GroupVersionKind(), "refName", ref.Name, "Machine", klog.KObj(m))
+			log.Info("could not find external ref, requeueing", ref.Kind, klog.KRef(m.Namespace, ref.Name))
 			return external.ReconcileOutput{RequeueAfter: externalReadyWait}, nil
 		}
 		return external.ReconcileOutput{}, err
diff --git a/internal/controllers/machineset/machineset_controller.go b/internal/controllers/machineset/machineset_controller.go
@@ -46,6 +46,7 @@ import (
 	"sigs.k8s.io/cluster-api/util/collections"
 	"sigs.k8s.io/cluster-api/util/conditions"
 	utilconversion "sigs.k8s.io/cluster-api/util/conversion"
+	clog "sigs.k8s.io/cluster-api/util/log"
 	"sigs.k8s.io/cluster-api/util/patch"
 	"sigs.k8s.io/cluster-api/util/predicates"
 )
@@ -118,8 +119,6 @@ func (r *Reconciler) SetupWithManager(ctx context.Context, mgr ctrl.Manager, opt
 }
 
 func (r *Reconciler) Reconcile(ctx context.Context, req ctrl.Request) (_ ctrl.Result, reterr error) {
-	log := ctrl.LoggerFrom(ctx)
-
 	machineSet := &clusterv1.MachineSet{}
 	if err := r.Client.Get(ctx, req.NamespacedName, machineSet); err != nil {
 		if apierrors.IsNotFound(err) {
@@ -131,6 +130,13 @@ func (r *Reconciler) Reconcile(ctx context.Context, req ctrl.Request) (_ ctrl.Re
 		return ctrl.Result{}, err
 	}
 
+	// AddOwners adds the owners of MachineSet as k/v pairs to the logger.
+	// Specifically, it will add MachineDeployment.
+	ctx, log, err := clog.AddOwners(ctx, r.Client, machineSet)
+	if err != nil {
+		return ctrl.Result{}, err
+	}
+
 	log = log.WithValues("Cluster", klog.KRef(machineSet.ObjectMeta.Namespace, machineSet.Spec.ClusterName))
 	ctx = ctrl.LoggerInto(ctx, log)
 
diff --git a/internal/controllers/topology/machineset/machineset_controller.go b/internal/controllers/topology/machineset/machineset_controller.go
@@ -33,6 +33,7 @@ import (
 	tlog "sigs.k8s.io/cluster-api/internal/log"
 	"sigs.k8s.io/cluster-api/util"
 	"sigs.k8s.io/cluster-api/util/annotations"
+	clog "sigs.k8s.io/cluster-api/util/log"
 	"sigs.k8s.io/cluster-api/util/patch"
 	"sigs.k8s.io/cluster-api/util/predicates"
 )
@@ -86,8 +87,6 @@ func (r *Reconciler) SetupWithManager(ctx context.Context, mgr ctrl.Manager, opt
 // We don't have to set the finalizer, as it's already set during MachineSet creation
 // in the MachineSet controller.
 func (r *Reconciler) Reconcile(ctx context.Context, req ctrl.Request) (ctrl.Result, error) {
-	log := ctrl.LoggerFrom(ctx)
-
 	// Fetch the MachineSet instance.
 	ms := &clusterv1.MachineSet{}
 	if err := r.Client.Get(ctx, req.NamespacedName, ms); err != nil {
@@ -99,6 +98,13 @@ func (r *Reconciler) Reconcile(ctx context.Context, req ctrl.Request) (ctrl.Resu
 		return ctrl.Result{}, errors.Wrapf(err, "failed to get MachineSet/%s", req.NamespacedName.Name)
 	}
 
+	// AddOwners adds the owners of MachineSet as k/v pairs to the logger.
+	// Specifically, it will add MachineDeployment.
+	ctx, log, err := clog.AddOwners(ctx, r.Client, ms)
+	if err != nil {
+		return ctrl.Result{}, err
+	}
+
 	log = log.WithValues("Cluster", klog.KRef(ms.Namespace, ms.Spec.ClusterName))
 	ctx = ctrl.LoggerInto(ctx, log)
 
diff --git a/test/infrastructure/docker/config/rbac/role.yaml b/test/infrastructure/docker/config/rbac/role.yaml
@@ -18,6 +18,7 @@ rules:
   resources:
   - clusters
   - machines
+  - machinesets
   verbs:
   - get
   - list
diff --git a/test/infrastructure/docker/exp/internal/controllers/dockermachinepool_controller.go b/test/infrastructure/docker/exp/internal/controllers/dockermachinepool_controller.go
@@ -83,6 +83,7 @@ func (r *DockerMachinePoolReconciler) Reconcile(ctx context.Context, req ctrl.Re
 	}
 
 	log = log.WithValues("MachinePool", machinePool.Name)
+	ctx = ctrl.LoggerInto(ctx, log)
 
 	// Fetch the Cluster.
 	cluster, err := util.GetClusterFromMetadata(ctx, r.Client, machinePool.ObjectMeta)
diff --git a/test/infrastructure/docker/internal/controllers/dockermachine_controller.go b/test/infrastructure/docker/internal/controllers/dockermachine_controller.go
@@ -43,6 +43,7 @@ import (
 	"sigs.k8s.io/cluster-api/util"
 	"sigs.k8s.io/cluster-api/util/annotations"
 	"sigs.k8s.io/cluster-api/util/conditions"
+	clog "sigs.k8s.io/cluster-api/util/log"
 	"sigs.k8s.io/cluster-api/util/patch"
 	"sigs.k8s.io/cluster-api/util/predicates"
 )
@@ -56,7 +57,7 @@ type DockerMachineReconciler struct {
 
 // +kubebuilder:rbac:groups=infrastructure.cluster.x-k8s.io,resources=dockermachines,verbs=get;list;watch;create;update;patch;delete
 // +kubebuilder:rbac:groups=infrastructure.cluster.x-k8s.io,resources=dockermachines/status;dockermachines/finalizers,verbs=get;update;patch
-// +kubebuilder:rbac:groups=cluster.x-k8s.io,resources=clusters;machines,verbs=get;list;watch
+// +kubebuilder:rbac:groups=cluster.x-k8s.io,resources=clusters;machinesets;machines,verbs=get;list;watch
 // +kubebuilder:rbac:groups="",resources=secrets;,verbs=get;list;watch
 
 // Reconcile handles DockerMachine events.
@@ -73,6 +74,13 @@ func (r *DockerMachineReconciler) Reconcile(ctx context.Context, req ctrl.Reques
 		return ctrl.Result{}, err
 	}
 
+	// AddOwners adds the owners of DockerMachine as k/v pairs to the logger.
+	// Specifically, it will add KubeadmControlPlane, MachineSet and MachineDeployment.
+	ctx, log, err := clog.AddOwners(ctx, r.Client, dockerMachine)
+	if err != nil {
+		return ctrl.Result{}, err
+	}
+
 	// Fetch the Machine.
 	machine, err := util.GetOwnerMachine(ctx, r.Client, dockerMachine.ObjectMeta)
 	if err != nil {
diff --git a/util/log/doc.go b/util/log/doc.go
@@ -0,0 +1,18 @@
+/*
+Copyright 2017 The Kubernetes Authors.
+
+Licensed under the Apache License, Version 2.0 (the "License");
+you may not use this file except in compliance with the License.
+You may obtain a copy of the License at
+
+    http://www.apache.org/licenses/LICENSE-2.0
+
+Unless required by applicable law or agreed to in writing, software
+distributed under the License is distributed on an "AS IS" BASIS,
+WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+See the License for the specific language governing permissions and
+limitations under the License.
+*/
+
+// Package log provides log utils.
+package log
diff --git a/util/log/log.go b/util/log/log.go
@@ -0,0 +1,106 @@
+/*
+Copyright 2017 The Kubernetes Authors.
+
+Licensed under the Apache License, Version 2.0 (the "License");
+you may not use this file except in compliance with the License.
+You may obtain a copy of the License at
+
+    http://www.apache.org/licenses/LICENSE-2.0
+
+Unless required by applicable law or agreed to in writing, software
+distributed under the License is distributed on an "AS IS" BASIS,
+WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+See the License for the specific language governing permissions and
+limitations under the License.
+*/
+
+// Package log provides log utils.
+package log
+
+import (
+	"context"
+
+	"github.com/go-logr/logr"
+	"github.com/pkg/errors"
+	apierrors "k8s.io/apimachinery/pkg/api/errors"
+	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
+	"k8s.io/apimachinery/pkg/util/sets"
+	"k8s.io/klog/v2"
+	ctrl "sigs.k8s.io/controller-runtime"
+	"sigs.k8s.io/controller-runtime/pkg/client"
+
+	clusterv1 "sigs.k8s.io/cluster-api/api/v1beta1"
+)
+
+// AddOwners adds the owners of an Object based on OwnerReferences as k/v pairs to the logger in ctx.
+// Note: If an owner is a MachineSet we also add the owners from the MachineSet OwnerReferences.
+func AddOwners(ctx context.Context, c client.Client, obj metav1.Object) (context.Context, logr.Logger, error) {
+	log := ctrl.LoggerFrom(ctx)
+
+	owners, err := getOwners(ctx, c, obj)
+	if err != nil {
+		return nil, logr.Logger{}, errors.Wrapf(err, "failed to add object hierarchy to logger")
+	}
+
+	// Add owners as k/v pairs.
+	keysAndValues := []interface{}{}
+	addedKinds := sets.NewString()
+	for _, owner := range owners {
+		// Don't add duplicate kinds.
+		if addedKinds.Has(owner.Kind) {
+			continue
+		}
+
+		keysAndValues = append(keysAndValues, owner.Kind, klog.KRef(owner.Namespace, owner.Name))
+		addedKinds.Insert(owner.Kind)
+	}
+	log = log.WithValues(keysAndValues...)
+
+	ctx = ctrl.LoggerInto(ctx, log)
+	return ctx, log, nil
+}
+
+// owner represents an owner of an object.
+type owner struct {
+	Kind      string
+	Name      string
+	Namespace string
+}
+
+// getOwners returns owners of an Object based on OwnerReferences.
+// Note: If an owner is a MachineSet we also return the owners from the MachineSet OwnerReferences.
+func getOwners(ctx context.Context, c client.Client, obj metav1.Object) ([]owner, error) {
+	owners := []owner{}
+	for _, ownerRef := range obj.GetOwnerReferences() {
+		owners = append(owners, owner{
+			Kind:      ownerRef.Kind,
+			Namespace: obj.GetNamespace(),
+			Name:      ownerRef.Name,
+		})
+
+		// continue if the ownerRef does not point to a MachineSet.
+		if ownerRef.Kind != "MachineSet" {
+			continue
+		}
+
+		// get owners of the MachineSet.
+		var ms clusterv1.MachineSet
+		if err := c.Get(ctx, client.ObjectKey{Namespace: obj.GetNamespace(), Name: ownerRef.Name}, &ms); err != nil {
+			// continue if the MachineSet doesn't exist.
+			if apierrors.IsNotFound(err) {
+				continue
+			}
+			return nil, errors.Wrapf(err, "failed to get owners: failed to get MachineSet %s", klog.KRef(obj.GetNamespace(), ownerRef.Name))
+		}
+
+		for _, ref := range ms.GetOwnerReferences() {
+			owners = append(owners, owner{
+				Kind:      ref.Kind,
+				Namespace: obj.GetNamespace(),
+				Name:      ref.Name,
+			})
+		}
+	}
+
+	return owners, nil
+}
diff --git a/util/log/log_test.go b/util/log/log_test.go

Original file line number	Diff line number	Diff line change
`@@ -98,7 +98,7 @@ func (r Reconciler) reconcileExternal(ctx context.Context, cluster clusterv1.C`
`98`	`98`	`obj, err := external.Get(ctx, r.Client, ref, m.Namespace)`
`99`	`99`	`if err != nil {`
`100`	`100`	`if apierrors.IsNotFound(errors.Cause(err)) {`
`101`		`- log.Info("could not find external ref, requeueing", "refGVK", ref.GroupVersionKind(), "refName", ref.Name, "Machine", klog.KObj(m))`
	`101`	`+ log.Info("could not find external ref, requeueing", ref.Kind, klog.KRef(m.Namespace, ref.Name))`
`102`	`102`	`return external.ReconcileOutput{RequeueAfter: externalReadyWait}, nil`
`103`	`103`	`}`
`104`	`104`	`return external.ReconcileOutput{}, err`