Improve controller manager logs (#4115)

This now makes use of the tooling provided by upstream
controller-runtime and component-base/logs. As a consequence, the
manager now takes a standard set of flags to configure logging.

The default logging format is configured to json, it's the direction
upstream is going duwe to its tooling support. For tilt, using text
for now until we provide better tooling to analyze the logs.

Instead of injecting a logger in the reconciler on construction, we now
use contextual logging. The benefit here is controller-runtime will
inject a default set of values that uniquely identify the reconcile
request.

config/tilt/kustomization.yaml

@@ -6,3 +6,12 @@ resources:
 images:
 - name: controller
   newName: eks-a-controller-manager
+
+patches:
+- patch: |-
+    - op: add
+      path: /spec/template/spec/containers/0/args/-
+      value: --logging-format=text
+  target:
+    kind: Deployment
+    name: eksa-controller-manager

controllers/cluster_controller.go

@@ -35,25 +35,24 @@ const (
 // ClusterReconciler reconciles a Cluster object.
 type ClusterReconciler struct {
 	client                     client.Client
-	log                        logr.Logger
 	providerReconcilerRegistry ProviderClusterReconcilerRegistry
 }
 
 type ProviderClusterReconcilerRegistry interface {
 	Get(datacenterKind string) clusters.ProviderClusterReconciler
 }
 
-func NewClusterReconciler(client client.Client, log logr.Logger, registry ProviderClusterReconcilerRegistry) *ClusterReconciler {
+// NewClusterReconciler constructs a new ClusterReconciler.
+func NewClusterReconciler(client client.Client, registry ProviderClusterReconcilerRegistry) *ClusterReconciler {
 	return &ClusterReconciler{
 		client:                     client,
-		log:                        log,
 		providerReconcilerRegistry: registry,
 	}
 }
 
 // SetupWithManager sets up the controller with the Manager.
-func (r *ClusterReconciler) SetupWithManager(mgr ctrl.Manager) error {
-	childObjectHandler := handlers.ChildObjectToClusters(r.log)
+func (r *ClusterReconciler) SetupWithManager(mgr ctrl.Manager, log logr.Logger) error {
+	childObjectHandler := handlers.ChildObjectToClusters(log)
 
 	return ctrl.NewControllerManagedBy(mgr).
 		For(&anywherev1.Cluster{}).
@@ -104,10 +103,10 @@ func (r *ClusterReconciler) SetupWithManager(mgr ctrl.Manager) error {
 // +kubebuilder:rbac:groups=distro.eks.amazonaws.com,resources=releases,verbs=get;list;watch
 // +kubebuilder:rbac:groups=infrastructure.cluster.x-k8s.io,resources=awssnowclusters;awssnowmachinetemplates;vsphereclusters;vspheremachinetemplates;dockerclusters;dockermachinetemplates,verbs=get;list;watch;create;update;patch;delete
 func (r *ClusterReconciler) Reconcile(ctx context.Context, req ctrl.Request) (_ ctrl.Result, reterr error) {
-	log := r.log.WithValues("cluster", req.NamespacedName)
+	log := ctrl.LoggerFrom(ctx)
 	// Fetch the Cluster object
 	cluster := &anywherev1.Cluster{}
-	log.Info("Reconciling cluster", "name", req.NamespacedName)
+	log.Info("Reconciling cluster")
 	if err := r.client.Get(ctx, req.NamespacedName, cluster); err != nil {
 		if apierrors.IsNotFound(err) {
 			return reconcile.Result{}, nil
@@ -133,7 +132,7 @@ func (r *ClusterReconciler) Reconcile(ctx context.Context, req ctrl.Request) (_
 			controllerutil.AddFinalizer(cluster, clusterFinalizerName)
 		}
 	} else {
-		return r.reconcileDelete(ctx, cluster)
+		return r.reconcileDelete(ctx, log, cluster)
 	}
 
 	// If the cluster is paused, return without any further processing.
@@ -152,10 +151,10 @@ func (r *ClusterReconciler) Reconcile(ctx context.Context, req ctrl.Request) (_
 		return ctrl.Result{}, err
 	}
 
-	return r.reconcile(ctx, cluster, log)
+	return r.reconcile(ctx, log, cluster)
 }
 
-func (r *ClusterReconciler) reconcile(ctx context.Context, cluster *anywherev1.Cluster, log logr.Logger) (ctrl.Result, error) {
+func (r *ClusterReconciler) reconcile(ctx context.Context, log logr.Logger, cluster *anywherev1.Cluster) (ctrl.Result, error) {
 	clusterProviderReconciler := r.providerReconcilerRegistry.Get(cluster.Spec.DatacenterRef.Kind)
 
 	var reconcileResult controller.Result
@@ -173,26 +172,26 @@ func (r *ClusterReconciler) reconcile(ctx context.Context, cluster *anywherev1.C
 	return reconcileResult.ToCtrlResult(), nil
 }
 
-func (r *ClusterReconciler) reconcileDelete(ctx context.Context, cluster *anywherev1.Cluster) (ctrl.Result, error) {
+func (r *ClusterReconciler) reconcileDelete(ctx context.Context, log logr.Logger, cluster *anywherev1.Cluster) (ctrl.Result, error) {
 	if cluster.IsSelfManaged() {
 		return ctrl.Result{}, errors.New("deleting self-managed clusters is not supported")
 	}
 
 	capiCluster := &clusterv1.Cluster{}
 	capiClusterName := types.NamespacedName{Namespace: constants.EksaSystemNamespace, Name: cluster.Name}
-	r.log.Info("Deleting", "name", cluster.Name)
+	log.Info("Deleting", "name", cluster.Name)
 	err := r.client.Get(ctx, capiClusterName, capiCluster)
 
 	switch {
 	case err == nil:
-		r.log.Info("Deleting CAPI cluster", "name", capiCluster.Name)
+		log.Info("Deleting CAPI cluster", "name", capiCluster.Name)
 		if err := r.client.Delete(ctx, capiCluster); err != nil {
-			r.log.Info("Error deleting CAPI cluster", "name", capiCluster.Name)
+			log.Info("Error deleting CAPI cluster", "name", capiCluster.Name)
 			return ctrl.Result{}, err
 		}
 		return ctrl.Result{RequeueAfter: defaultRequeueTime}, nil
 	case apierrors.IsNotFound(err):
-		r.log.Info("Deleting EKS Anywhere cluster", "name", capiCluster.Name, "cluster.DeletionTimestamp", cluster.DeletionTimestamp, "finalizer", cluster.Finalizers)
+		log.Info("Deleting EKS Anywhere cluster", "name", capiCluster.Name, "cluster.DeletionTimestamp", cluster.DeletionTimestamp, "finalizer", cluster.Finalizers)
 
 		// TODO delete GitOps,Datacenter and MachineConfig objects
 		controllerutil.RemoveFinalizer(cluster, clusterFinalizerName)

controllers/cluster_controller_test.go

@@ -6,6 +6,7 @@ import (
 	"testing"
 	"time"
 
+	"github.com/go-logr/logr"
 	"github.com/golang/mock/gomock"
 	. "github.com/onsi/gomega"
 	apiv1 "k8s.io/api/core/v1"
@@ -17,11 +18,9 @@ import (
 	"sigs.k8s.io/controller-runtime/pkg/client"
 	"sigs.k8s.io/controller-runtime/pkg/client/fake"
 	"sigs.k8s.io/controller-runtime/pkg/controller/controllerutil"
-	logf "sigs.k8s.io/controller-runtime/pkg/log"
 
 	"github.com/aws/eks-anywhere/controllers"
 	"github.com/aws/eks-anywhere/controllers/mocks"
-	"github.com/aws/eks-anywhere/internal/test"
 	_ "github.com/aws/eks-anywhere/internal/test/envtest"
 	anywherev1 "github.com/aws/eks-anywhere/pkg/api/v1alpha1"
 	"github.com/aws/eks-anywhere/pkg/controller/clusters"
@@ -69,7 +68,7 @@ func newVsphereClusterReconcilerTest(t *testing.T, objs ...runtime.Object) *vsph
 		Add(anywherev1.VSphereDatacenterKind, reconciler).
 		Build()
 
-	r := controllers.NewClusterReconciler(cl, logf.Log, &registry)
+	r := controllers.NewClusterReconciler(cl, &registry)
 
 	return &vsphereClusterReconcilerTest{
 		govcClient: govcClient,
@@ -93,15 +92,14 @@ func TestClusterReconcilerReconcileSelfManagedCluster(t *testing.T) {
 		},
 	}
 
-	log := test.NewNullLogger()
 	controller := gomock.NewController(t)
 	providerReconciler := mocks.NewMockProviderClusterReconciler(controller)
 	registry := newRegistryMock(providerReconciler)
 	c := fake.NewClientBuilder().WithRuntimeObjects(selfManagedCluster).Build()
 
-	providerReconciler.EXPECT().ReconcileWorkerNodes(ctx, log, sameName(selfManagedCluster))
+	providerReconciler.EXPECT().ReconcileWorkerNodes(ctx, gomock.AssignableToTypeOf(logr.Logger{}), sameName(selfManagedCluster))
 
-	r := controllers.NewClusterReconciler(c, log, registry)
+	r := controllers.NewClusterReconciler(c, registry)
 	result, err := r.Reconcile(ctx, clusterRequest(selfManagedCluster))
 	g.Expect(err).ToNot(HaveOccurred())
 	g.Expect(result).To(Equal(ctrl.Result{}))
@@ -124,13 +122,12 @@ func TestClusterReconcilerReconcileDeletedSelfManagedCluster(t *testing.T) {
 		},
 	}
 
-	log := test.NewNullLogger()
 	controller := gomock.NewController(t)
 	providerReconciler := mocks.NewMockProviderClusterReconciler(controller)
 	registry := newRegistryMock(providerReconciler)
 	c := fake.NewClientBuilder().WithRuntimeObjects(selfManagedCluster).Build()
 
-	r := controllers.NewClusterReconciler(c, log, registry)
+	r := controllers.NewClusterReconciler(c, registry)
 	_, err := r.Reconcile(ctx, clusterRequest(selfManagedCluster))
 	g.Expect(err).To(MatchError(ContainSubstring("deleting self-managed clusters is not supported")))
 }

controllers/cluster_controller_test_test.go

@@ -73,7 +73,7 @@ func TestClusterReconcilerEnsureOwnerReferences(t *testing.T) {
 	cb := fake.NewClientBuilder()
 	cl := cb.WithRuntimeObjects(objs...).Build()
 
-	r := controllers.NewClusterReconciler(cl, nullLog(), newRegistryForDummyProviderReconciler())
+	r := controllers.NewClusterReconciler(cl, newRegistryForDummyProviderReconciler())
 	_, err := r.Reconcile(ctx, clusterRequest(cluster))
 	g.Expect(err).NotTo(HaveOccurred())
 
@@ -90,10 +90,10 @@ func TestClusterReconcilerEnsureOwnerReferences(t *testing.T) {
 
 func TestClusterReconcilerSetupWithManager(t *testing.T) {
 	client := env.Client()
-	r := controllers.NewClusterReconciler(client, logf.Log, newRegistryForDummyProviderReconciler())
+	r := controllers.NewClusterReconciler(client, newRegistryForDummyProviderReconciler())
 
 	g := NewWithT(t)
-	g.Expect(r.SetupWithManager(env.Manager())).To(Succeed())
+	g.Expect(r.SetupWithManager(env.Manager(), env.Manager().GetLogger())).To(Succeed())
 }
 
 func TestClusterReconcilerManagementClusterNotFound(t *testing.T) {
@@ -118,7 +118,7 @@ func TestClusterReconcilerManagementClusterNotFound(t *testing.T) {
 	cb := fake.NewClientBuilder()
 	cl := cb.WithRuntimeObjects(objs...).Build()
 
-	r := controllers.NewClusterReconciler(cl, nullLog(), newRegistryForDummyProviderReconciler())
+	r := controllers.NewClusterReconciler(cl, newRegistryForDummyProviderReconciler())
 	_, err := r.Reconcile(ctx, clusterRequest(cluster))
 	g.Expect(err).To(MatchError(ContainSubstring("\"my-management-cluster\" not found")))
 }
@@ -152,7 +152,7 @@ func TestClusterReconcilerSetBundlesRef(t *testing.T) {
 	mgmtCluster := &anywherev1.Cluster{}
 	g.Expect(cl.Get(ctx, client.ObjectKey{Namespace: cluster.Namespace, Name: managementCluster.Name}, mgmtCluster)).To(Succeed())
 
-	r := controllers.NewClusterReconciler(cl, nullLog(), newRegistryForDummyProviderReconciler())
+	r := controllers.NewClusterReconciler(cl, newRegistryForDummyProviderReconciler())
 	_, err := r.Reconcile(ctx, clusterRequest(cluster))
 	g.Expect(err).ToNot(HaveOccurred())
 

controllers/docker_datacenter_controller.go

@@ -1,20 +1,17 @@
 package controllers
 
 import (
-	"github.com/go-logr/logr"
 	"sigs.k8s.io/controller-runtime/pkg/client"
 )
 
 // DockerDatacenterReconciler reconciles a DockerDatacenterConfig object.
 type DockerDatacenterReconciler struct {
-	log    logr.Logger
 	client client.Client
 }
 
 // NewDockerDatacenterReconciler creates a new instance of the DockerDatacenterReconciler struct.
-func NewDockerDatacenterReconciler(client client.Client, log logr.Logger) *DockerDatacenterReconciler {
+func NewDockerDatacenterReconciler(client client.Client) *DockerDatacenterReconciler {
 	return &DockerDatacenterReconciler{
 		client: client,
-		log:    log,
 	}
 }

controllers/factory.go

@@ -86,7 +86,6 @@ func (f *Factory) WithClusterReconciler(capiProviders []clusterctlv1.Provider) *
 
 		f.reconcilers.ClusterReconciler = NewClusterReconciler(
 			f.manager.GetClient(),
-			f.logger,
 			f.registry,
 		)
 
@@ -104,7 +103,6 @@ func (f *Factory) WithDockerDatacenterReconciler() *Factory {
 
 		f.reconcilers.DockerDatacenterReconciler = NewDockerDatacenterReconciler(
 			f.manager.GetClient(),
-			f.logger,
 		)
 
 		return nil
@@ -122,7 +120,6 @@ func (f *Factory) WithVSphereDatacenterReconciler() *Factory {
 
 		f.reconcilers.VSphereDatacenterReconciler = NewVSphereDatacenterReconciler(
 			f.manager.GetClient(),
-			f.logger,
 			f.deps.VSphereValidator,
 			f.deps.VSphereDefaulter,
 		)
@@ -141,7 +138,6 @@ func (f *Factory) WithSnowMachineConfigReconciler() *Factory {
 		client := f.manager.GetClient()
 		f.reconcilers.SnowMachineConfigReconciler = NewSnowMachineConfigReconciler(
 			client,
-			f.logger,
 			snow.NewValidator(snowreconciler.NewAwsClientBuilder(client)),
 		)
 		return nil

controllers/resource/fetcher_test.go

@@ -534,7 +534,7 @@ func TestFetchCloudStackCluster(t *testing.T) {
 			logger := logr.Discard()
 			capiResourceFetcher := resource.NewCAPIResourceFetcher(reader, logger)
 			reader.EXPECT().Get(ctx, types.NamespacedName{Namespace: constants.EksaSystemNamespace, Name: tt.cluster.Name}, gomock.Any()).Do(
-				func(ctx context.Context, arg1 types.NamespacedName, arg2 *cloudstackv1.CloudStackCluster) {
+				func(ctx context.Context, arg1 types.NamespacedName, arg2 *cloudstackv1.CloudStackCluster, _ ...client.GetOption) {
 					cloudstackCluster.DeepCopyInto(arg2)
 				})
 			_, err := capiResourceFetcher.CloudStackCluster(ctx, tt.cluster, anywherev1.WorkerNodeGroupConfiguration{Name: "test"})
@@ -567,7 +567,7 @@ func TestFetchCloudStackEtcdMachineTemplate(t *testing.T) {
 			logger := logr.Discard()
 			capiResourceFetcher := resource.NewCAPIResourceFetcher(reader, logger)
 			reader.EXPECT().Get(ctx, types.NamespacedName{Namespace: constants.EksaSystemNamespace, Name: "testCluster-etcd"}, gomock.Any()).Do(
-				func(ctx context.Context, arg1 types.NamespacedName, arg2 *etcdv1.EtcdadmCluster) {
+				func(ctx context.Context, arg1 types.NamespacedName, arg2 *etcdv1.EtcdadmCluster, _ ...client.GetOption) {
 					etcdadmCluster.DeepCopyInto(arg2)
 				})
 			reader.EXPECT().Get(ctx, types.NamespacedName{Namespace: constants.EksaSystemNamespace, Name: etcdadmCluster.Spec.InfrastructureTemplate.Name},
@@ -602,11 +602,11 @@ func TestFetchCloudStackCPMachineTemplate(t *testing.T) {
 			logger := logr.Discard()
 			capiResourceFetcher := resource.NewCAPIResourceFetcher(reader, logger)
 			reader.EXPECT().Get(ctx, types.NamespacedName{Namespace: constants.EksaSystemNamespace, Name: tt.cluster.Name}, gomock.Any()).Do(
-				func(ctx context.Context, arg1 types.NamespacedName, arg2 *clusterv1.Cluster) {
+				func(ctx context.Context, arg1 types.NamespacedName, arg2 *clusterv1.Cluster, _ ...client.GetOption) {
 					capiCluster.DeepCopyInto(arg2)
 				})
 			reader.EXPECT().Get(ctx, types.NamespacedName{Namespace: capiCluster.Spec.ControlPlaneRef.Namespace, Name: capiCluster.Spec.ControlPlaneRef.Name}, gomock.Any()).Do(
-				func(ctx context.Context, arg1 types.NamespacedName, arg2 *controlplanev1.KubeadmControlPlane) {
+				func(ctx context.Context, arg1 types.NamespacedName, arg2 *controlplanev1.KubeadmControlPlane, _ ...client.GetOption) {
 					kubeadmControlPlane.DeepCopyInto(arg2)
 				})
 			reader.EXPECT().Get(ctx, types.NamespacedName{Namespace: constants.EksaSystemNamespace, Name: kubeadmControlPlane.Spec.MachineTemplate.InfrastructureRef.Name},
@@ -851,7 +851,7 @@ type stubbedReader struct {
 	clusterName string
 }
 
-func (s *stubbedReader) Get(ctx context.Context, key client.ObjectKey, obj client.Object) error {
+func (s *stubbedReader) Get(ctx context.Context, key client.ObjectKey, obj client.Object, _ ...client.GetOption) error {
 	if s.kind == obj.GetObjectKind().GroupVersionKind().Kind {
 		return nil
 	}

controllers/snow_machineconfig_controller.go

@@ -4,7 +4,6 @@ import (
 	"context"
 	"fmt"
 
-	"github.com/go-logr/logr"
 	kerrors "k8s.io/apimachinery/pkg/util/errors"
 	"sigs.k8s.io/cluster-api/util/patch"
 	ctrl "sigs.k8s.io/controller-runtime"
@@ -21,14 +20,13 @@ type Validator interface {
 // SnowMachineConfigReconciler reconciles a SnowMachineConfig object.
 type SnowMachineConfigReconciler struct {
 	client    client.Client
-	log       logr.Logger
 	validator Validator
 }
 
-func NewSnowMachineConfigReconciler(client client.Client, log logr.Logger, validator Validator) *SnowMachineConfigReconciler {
+// NewSnowMachineConfigReconciler constructs a new SnowMachineConfigReconciler.
+func NewSnowMachineConfigReconciler(client client.Client, validator Validator) *SnowMachineConfigReconciler {
 	return &SnowMachineConfigReconciler{
 		client:    client,
-		log:       log,
 		validator: validator,
 	}
 }
@@ -41,8 +39,9 @@ func (r *SnowMachineConfigReconciler) SetupWithManager(mgr ctrl.Manager) error {
 }
 
 // TODO: add here kubebuilder permissions as needed.
+// Reconcile implements the reconcile.Reconciler interface.
 func (r *SnowMachineConfigReconciler) Reconcile(ctx context.Context, req ctrl.Request) (_ ctrl.Result, reterr error) {
-	log := r.log.WithValues("snowMachineConfig", req.NamespacedName)
+	log := ctrl.LoggerFrom(ctx)
 
 	// Fetch the SnowMachineConfig object
 	snowMachineConfig := &anywherev1.SnowMachineConfig{}