diff --git a/bootstrap/kubeadm/internal/controllers/kubeadmconfig_controller.go b/bootstrap/kubeadm/internal/controllers/kubeadmconfig_controller.go index 0a5fd52b2cdb..088970e1e8c2 100644 --- a/bootstrap/kubeadm/internal/controllers/kubeadmconfig_controller.go +++ b/bootstrap/kubeadm/internal/controllers/kubeadmconfig_controller.go @@ -31,6 +31,7 @@ import ( "k8s.io/apimachinery/pkg/runtime" "k8s.io/apimachinery/pkg/types" kerrors "k8s.io/apimachinery/pkg/util/errors" + "k8s.io/klog/v2" "k8s.io/utils/pointer" ctrl "sigs.k8s.io/controller-runtime" "sigs.k8s.io/controller-runtime/pkg/client" @@ -101,7 +102,7 @@ type Scope struct { // SetupWithManager sets up the reconciler with the Manager. func (r *KubeadmConfigReconciler) SetupWithManager(ctx context.Context, mgr ctrl.Manager, options controller.Options) error { if r.KubeadmInitLock == nil { - r.KubeadmInitLock = locking.NewControlPlaneInitMutex(ctrl.LoggerFrom(ctx).WithName("init-locker"), mgr.GetClient()) + r.KubeadmInitLock = locking.NewControlPlaneInitMutex(mgr.GetClient()) } if r.remoteClientGetter == nil { r.remoteClientGetter = remote.NewClusterClient @@ -172,7 +173,7 @@ func (r *KubeadmConfigReconciler) Reconcile(ctx context.Context, req ctrl.Reques if configOwner == nil { return ctrl.Result{}, nil } - log = log.WithValues("kind", configOwner.GetKind(), "version", configOwner.GetResourceVersion(), "name", configOwner.GetName()) + log = log.WithValues(configOwner.LowerCamelCaseKind(), klog.KRef(configOwner.GetNamespace(), configOwner.GetName()), "resourceVersion", configOwner.GetResourceVersion()) // Lookup the cluster the config owner is associated with cluster, err := util.GetClusterByName(ctx, r.Client, configOwner.GetNamespace(), configOwner.ClusterName()) @@ -190,6 +191,8 @@ func (r *KubeadmConfigReconciler) Reconcile(ctx context.Context, req ctrl.Reques return ctrl.Result{}, err } + ctx = ctrl.LoggerInto(ctx, log.WithValues("cluster", klog.KObj(cluster))) + if annotations.IsPaused(cluster, config) { log.Info("Reconciliation is paused for this object") return ctrl.Result{}, nil @@ -321,14 +324,14 @@ func (r *KubeadmConfigReconciler) rotateMachinePoolBootstrapToken(ctx context.Co return ctrl.Result{}, err } if shouldRotate { - log.V(2).Info("Creating new bootstrap token") + log.Info("Creating new bootstrap token, the existing one should be rotated") token, err := createToken(ctx, remoteClient, r.TokenTTL) if err != nil { return ctrl.Result{}, errors.Wrapf(err, "failed to create new bootstrap token") } config.Spec.JoinConfiguration.Discovery.BootstrapToken.Token = token - log.Info("Altering JoinConfiguration.Discovery.BootstrapToken", "Token", token) + log.V(3).Info("Altering JoinConfiguration.Discovery.BootstrapToken.Token") // update the bootstrap data return r.joinWorker(ctx, scope) @@ -378,7 +381,7 @@ func (r *KubeadmConfigReconciler) handleClusterNotInitialized(ctx context.Contex } }() - scope.Info("Creating BootstrapData for the init control plane") + scope.Info("Creating BootstrapData for the first control plane") // Nb. in this case JoinConfiguration should not be defined by users, but in case of misconfigurations, CABPK simply ignore it @@ -495,6 +498,8 @@ func (r *KubeadmConfigReconciler) handleClusterNotInitialized(ctx context.Contex } func (r *KubeadmConfigReconciler) joinWorker(ctx context.Context, scope *Scope) (ctrl.Result, error) { + scope.Info("Creating BootstrapData for the worker node") + certificates := secret.NewCertificatesForWorker(scope.Config.Spec.JoinConfiguration.CACertPath) err := certificates.Lookup( ctx, @@ -534,8 +539,6 @@ func (r *KubeadmConfigReconciler) joinWorker(ctx context.Context, scope *Scope) return ctrl.Result{}, errors.New("Machine is a Worker, but JoinConfiguration.ControlPlane is set in the KubeadmConfig object") } - scope.Info("Creating BootstrapData for the worker node") - verbosityFlag := "" if scope.Config.Spec.Verbosity != nil { verbosityFlag = fmt.Sprintf("--v %s", strconv.Itoa(int(*scope.Config.Spec.Verbosity))) @@ -592,6 +595,8 @@ func (r *KubeadmConfigReconciler) joinWorker(ctx context.Context, scope *Scope) } func (r *KubeadmConfigReconciler) joinControlplane(ctx context.Context, scope *Scope) (ctrl.Result, error) { + scope.Info("Creating BootstrapData for the joining control plane") + if !scope.ConfigOwner.IsControlPlaneMachine() { return ctrl.Result{}, fmt.Errorf("%s is not a valid control plane kind, only Machine is supported", scope.ConfigOwner.GetKind()) } @@ -635,8 +640,6 @@ func (r *KubeadmConfigReconciler) joinControlplane(ctx context.Context, scope *S return ctrl.Result{}, err } - scope.Info("Creating BootstrapData for the join control plane") - verbosityFlag := "" if scope.Config.Spec.Verbosity != nil { verbosityFlag = fmt.Sprintf("--v %s", strconv.Itoa(int(*scope.Config.Spec.Verbosity))) @@ -889,7 +892,7 @@ func (r *KubeadmConfigReconciler) reconcileDiscovery(ctx context.Context, cluste apiServerEndpoint = cluster.Spec.ControlPlaneEndpoint.String() config.Spec.JoinConfiguration.Discovery.BootstrapToken.APIServerEndpoint = apiServerEndpoint - log.Info("Altering JoinConfiguration.Discovery.BootstrapToken", "APIServerEndpoint", apiServerEndpoint) + log.V(3).Info("Altering JoinConfiguration.Discovery.BootstrapToken.APIServerEndpoint", "APIServerEndpoint", apiServerEndpoint) } // if BootstrapToken already contains a token, respect it; otherwise create a new bootstrap token for the node to join @@ -905,7 +908,7 @@ func (r *KubeadmConfigReconciler) reconcileDiscovery(ctx context.Context, cluste } config.Spec.JoinConfiguration.Discovery.BootstrapToken.Token = token - log.Info("Altering JoinConfiguration.Discovery.BootstrapToken") + log.V(3).Info("Altering JoinConfiguration.Discovery.BootstrapToken.Token") } // If the BootstrapToken does not contain any CACertHashes then force skip CA Verification @@ -927,39 +930,39 @@ func (r *KubeadmConfigReconciler) reconcileTopLevelObjectSettings(ctx context.Co // then use Cluster's ControlPlaneEndpoint as a control plane endpoint for the Kubernetes cluster. if config.Spec.ClusterConfiguration.ControlPlaneEndpoint == "" && cluster.Spec.ControlPlaneEndpoint.IsValid() { config.Spec.ClusterConfiguration.ControlPlaneEndpoint = cluster.Spec.ControlPlaneEndpoint.String() - log.Info("Altering ClusterConfiguration", "ControlPlaneEndpoint", config.Spec.ClusterConfiguration.ControlPlaneEndpoint) + log.V(3).Info("Altering ClusterConfiguration.ControlPlaneEndpoint", "ControlPlaneEndpoint", config.Spec.ClusterConfiguration.ControlPlaneEndpoint) } // If there are no ClusterName defined in ClusterConfiguration, use Cluster.Name if config.Spec.ClusterConfiguration.ClusterName == "" { config.Spec.ClusterConfiguration.ClusterName = cluster.Name - log.Info("Altering ClusterConfiguration", "ClusterName", config.Spec.ClusterConfiguration.ClusterName) + log.V(3).Info("Altering ClusterConfiguration.ClusterName", "ClusterName", config.Spec.ClusterConfiguration.ClusterName) } // If there are no Network settings defined in ClusterConfiguration, use ClusterNetwork settings, if defined if cluster.Spec.ClusterNetwork != nil { if config.Spec.ClusterConfiguration.Networking.DNSDomain == "" && cluster.Spec.ClusterNetwork.ServiceDomain != "" { config.Spec.ClusterConfiguration.Networking.DNSDomain = cluster.Spec.ClusterNetwork.ServiceDomain - log.Info("Altering ClusterConfiguration", "DNSDomain", config.Spec.ClusterConfiguration.Networking.DNSDomain) + log.V(3).Info("Altering ClusterConfiguration.Networking.DNSDomain", "DNSDomain", config.Spec.ClusterConfiguration.Networking.DNSDomain) } if config.Spec.ClusterConfiguration.Networking.ServiceSubnet == "" && cluster.Spec.ClusterNetwork.Services != nil && len(cluster.Spec.ClusterNetwork.Services.CIDRBlocks) > 0 { config.Spec.ClusterConfiguration.Networking.ServiceSubnet = cluster.Spec.ClusterNetwork.Services.String() - log.Info("Altering ClusterConfiguration", "ServiceSubnet", config.Spec.ClusterConfiguration.Networking.ServiceSubnet) + log.V(3).Info("Altering ClusterConfiguration.Networking.ServiceSubnet", "ServiceSubnet", config.Spec.ClusterConfiguration.Networking.ServiceSubnet) } if config.Spec.ClusterConfiguration.Networking.PodSubnet == "" && cluster.Spec.ClusterNetwork.Pods != nil && len(cluster.Spec.ClusterNetwork.Pods.CIDRBlocks) > 0 { config.Spec.ClusterConfiguration.Networking.PodSubnet = cluster.Spec.ClusterNetwork.Pods.String() - log.Info("Altering ClusterConfiguration", "PodSubnet", config.Spec.ClusterConfiguration.Networking.PodSubnet) + log.V(3).Info("Altering ClusterConfiguration.Networking.PodSubnet", "PodSubnet", config.Spec.ClusterConfiguration.Networking.PodSubnet) } } // If there are no KubernetesVersion settings defined in ClusterConfiguration, use Version from machine, if defined if config.Spec.ClusterConfiguration.KubernetesVersion == "" && machine.Spec.Version != nil { config.Spec.ClusterConfiguration.KubernetesVersion = *machine.Spec.Version - log.Info("Altering ClusterConfiguration", "KubernetesVersion", config.Spec.ClusterConfiguration.KubernetesVersion) + log.V(3).Info("Altering ClusterConfiguration.KubernetesVersion", "KubernetesVersion", config.Spec.ClusterConfiguration.KubernetesVersion) } } @@ -998,7 +1001,7 @@ func (r *KubeadmConfigReconciler) storeBootstrapData(ctx context.Context, scope if !apierrors.IsAlreadyExists(err) { return errors.Wrapf(err, "failed to create bootstrap data secret for KubeadmConfig %s/%s", scope.Config.Namespace, scope.Config.Name) } - log.Info("bootstrap data secret for KubeadmConfig already exists, updating", "secret", secret.Name, "KubeadmConfig", scope.Config.Name) + log.Info("bootstrap data secret for KubeadmConfig already exists, updating", "secret", klog.KObj(secret)) if err := r.Client.Update(ctx, secret); err != nil { return errors.Wrapf(err, "failed to update bootstrap data secret for KubeadmConfig %s/%s", scope.Config.Namespace, scope.Config.Name) } diff --git a/bootstrap/kubeadm/internal/locking/control_plane_init_mutex.go b/bootstrap/kubeadm/internal/locking/control_plane_init_mutex.go index be19bf7a5ab8..41bac632cc5a 100644 --- a/bootstrap/kubeadm/internal/locking/control_plane_init_mutex.go +++ b/bootstrap/kubeadm/internal/locking/control_plane_init_mutex.go @@ -22,11 +22,12 @@ import ( "encoding/json" "fmt" - "github.com/go-logr/logr" "github.com/pkg/errors" corev1 "k8s.io/api/core/v1" apierrors "k8s.io/apimachinery/pkg/api/errors" metav1 "k8s.io/apimachinery/pkg/apis/meta/v1" + "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" @@ -36,14 +37,12 @@ const semaphoreInformationKey = "lock-information" // ControlPlaneInitMutex uses a ConfigMap to synchronize cluster initialization. type ControlPlaneInitMutex struct { - log logr.Logger client client.Client } // NewControlPlaneInitMutex returns a lock that can be held by a control plane node before init. -func NewControlPlaneInitMutex(log logr.Logger, client client.Client) *ControlPlaneInitMutex { +func NewControlPlaneInitMutex(client client.Client) *ControlPlaneInitMutex { return &ControlPlaneInitMutex{ - log: log, client: client, } } @@ -52,7 +51,7 @@ func NewControlPlaneInitMutex(log logr.Logger, client client.Client) *ControlPla func (c *ControlPlaneInitMutex) Lock(ctx context.Context, cluster *clusterv1.Cluster, machine *clusterv1.Machine) bool { sema := newSemaphore() cmName := configMapName(cluster.Name) - log := c.log.WithValues("namespace", cluster.Namespace, "cluster-name", cluster.Name, "configmap-name", cmName, "machine-name", machine.Name) + log := ctrl.LoggerFrom(ctx, "configMap", klog.KRef(cluster.Namespace, cmName)) err := c.client.Get(ctx, client.ObjectKey{ Namespace: cluster.Namespace, Name: cmName, @@ -61,12 +60,12 @@ func (c *ControlPlaneInitMutex) Lock(ctx context.Context, cluster *clusterv1.Clu case apierrors.IsNotFound(err): break case err != nil: - log.Error(err, "Failed to acquire lock") + log.Error(err, "Failed to acquire init lock") return false default: // Successfully found an existing config map. info, err := sema.information() if err != nil { - log.Error(err, "Failed to get information about the existing lock") + log.Error(err, "Failed to get information about the existing init lock") return false } // The machine requesting the lock is the machine that created the lock, therefore the lock is acquired. @@ -79,12 +78,12 @@ func (c *ControlPlaneInitMutex) Lock(ctx context.Context, cluster *clusterv1.Clu Namespace: cluster.Namespace, Name: info.MachineName, }, &clusterv1.Machine{}); err != nil { - log.Error(err, "Failed to get machine holding ControlPlane lock") + log.Error(err, "Failed to get machine holding init lock") if apierrors.IsNotFound(err) { c.Unlock(ctx, cluster) } } - log.Info("Waiting on another machine to initialize", "init-machine", info.MachineName) + log.Info(fmt.Sprintf("Waiting for Machine %s to initialize", info.MachineName)) return false } @@ -92,7 +91,7 @@ func (c *ControlPlaneInitMutex) Lock(ctx context.Context, cluster *clusterv1.Clu sema.setMetadata(cluster) // Adds the additional information if err := sema.setInformation(&information{MachineName: machine.Name}); err != nil { - log.Error(err, "Failed to acquire lock while setting semaphore information") + log.Error(err, "Failed to acquire init lock while setting semaphore information") return false } @@ -100,10 +99,10 @@ func (c *ControlPlaneInitMutex) Lock(ctx context.Context, cluster *clusterv1.Clu err = c.client.Create(ctx, sema.ConfigMap) switch { case apierrors.IsAlreadyExists(err): - log.Info("Cannot acquire the lock. The lock has been acquired by someone else") + log.Info("Cannot acquire the init lock. The init lock has been acquired by someone else") return false case err != nil: - log.Error(err, "Error acquiring the lock") + log.Error(err, "Error acquiring the init lock") return false default: return true @@ -114,8 +113,7 @@ func (c *ControlPlaneInitMutex) Lock(ctx context.Context, cluster *clusterv1.Clu func (c *ControlPlaneInitMutex) Unlock(ctx context.Context, cluster *clusterv1.Cluster) bool { sema := newSemaphore() cmName := configMapName(cluster.Name) - log := c.log.WithValues("namespace", cluster.Namespace, "cluster-name", cluster.Name, "configmap-name", cmName) - log.Info("Checking for lock") + log := ctrl.LoggerFrom(ctx, "configMap", klog.KRef(cluster.Namespace, cmName)) err := c.client.Get(ctx, client.ObjectKey{ Namespace: cluster.Namespace, Name: cmName, diff --git a/bootstrap/kubeadm/internal/locking/control_plane_init_mutex_test.go b/bootstrap/kubeadm/internal/locking/control_plane_init_mutex_test.go index cd953975a752..1201d2b7cf10 100644 --- a/bootstrap/kubeadm/internal/locking/control_plane_init_mutex_test.go +++ b/bootstrap/kubeadm/internal/locking/control_plane_init_mutex_test.go @@ -18,12 +18,10 @@ package locking import ( "context" - "encoding/json" "errors" "fmt" "testing" - "github.com/go-logr/logr" . "github.com/onsi/gomega" corev1 "k8s.io/api/core/v1" apierrors "k8s.io/apimachinery/pkg/api/errors" @@ -34,7 +32,6 @@ import ( ctrl "sigs.k8s.io/controller-runtime" "sigs.k8s.io/controller-runtime/pkg/client" "sigs.k8s.io/controller-runtime/pkg/client/fake" - "sigs.k8s.io/controller-runtime/pkg/log" clusterv1 "sigs.k8s.io/cluster-api/api/v1beta1" ) @@ -107,7 +104,6 @@ func TestControlPlaneInitMutex_Lock(t *testing.T) { gs := NewWithT(t) l := &ControlPlaneInitMutex{ - log: log.Log, client: tc.client, } @@ -182,7 +178,6 @@ func TestControlPlaneInitMutex_LockWithMachineDeletion(t *testing.T) { for _, tc := range tests { t.Run(tc.name, func(t *testing.T) { l := &ControlPlaneInitMutex{ - log: log.Log, client: tc.client, } @@ -269,7 +264,6 @@ func TestControlPlaneInitMutex_UnLock(t *testing.T) { gs := NewWithT(t) l := &ControlPlaneInitMutex{ - log: log.Log, client: tc.client, } @@ -286,60 +280,6 @@ func TestControlPlaneInitMutex_UnLock(t *testing.T) { } } -func TestInfoLines_Lock(t *testing.T) { - g := NewWithT(t) - - uid := types.UID("test-uid") - info := information{MachineName: "my-control-plane"} - b, err := json.Marshal(info) - g.Expect(err).NotTo(HaveOccurred()) - - c := &fakeClient{ - Client: fake.NewClientBuilder().WithObjects(&corev1.ConfigMap{ - ObjectMeta: metav1.ObjectMeta{ - Name: configMapName(clusterName), - Namespace: clusterNamespace, - }, - Data: map[string]string{semaphoreInformationKey: string(b)}, - }).Build(), - } - - logtester := &logtests{ - InfoLog: make([]line, 0), - ErrorLog: make([]line, 0), - } - l := &ControlPlaneInitMutex{ - log: logr.New(logtester), - client: c, - } - - cluster := &clusterv1.Cluster{ - ObjectMeta: metav1.ObjectMeta{ - Namespace: clusterNamespace, - Name: clusterName, - UID: uid, - }, - } - machine := &clusterv1.Machine{ - ObjectMeta: metav1.ObjectMeta{ - Name: fmt.Sprintf("machine-%s", cluster.Name), - }, - } - - g.Expect(l.Lock(ctx, cluster, machine)).To(BeFalse()) - - foundLogLine := false - for _, line := range logtester.InfoLog { - for k, v := range line.data { - if k == "init-machine" && v.(string) == "my-control-plane" { - foundLogLine = true - } - } - } - - g.Expect(foundLogLine).To(BeTrue()) -} - type fakeClient struct { client.Client getError error @@ -367,51 +307,3 @@ func (fc *fakeClient) Delete(ctx context.Context, obj client.Object, opts ...cli } return fc.Client.Delete(ctx, obj, opts...) } - -type logtests struct { - logr.Logger - InfoLog []line - ErrorLog []line -} - -type line struct { - line string - data map[string]interface{} -} - -func (l *logtests) Init(info logr.RuntimeInfo) { -} - -func (l *logtests) Enabled(level int) bool { - return true -} - -func (l *logtests) Info(level int, msg string, keysAndValues ...interface{}) { - data := make(map[string]interface{}) - for i := 0; i < len(keysAndValues); i += 2 { - data[keysAndValues[i].(string)] = keysAndValues[i+1] - } - l.InfoLog = append(l.InfoLog, line{ - line: msg, - data: data, - }) -} - -func (l *logtests) Error(err error, msg string, keysAndValues ...interface{}) { - data := make(map[string]interface{}) - for i := 0; i < len(keysAndValues); i += 2 { - data[keysAndValues[i].(string)] = keysAndValues[i+1] - } - l.ErrorLog = append(l.ErrorLog, line{ - line: msg + err.Error(), - data: data, - }) -} - -func (l *logtests) WithValues(keysAndValues ...interface{}) logr.LogSink { - return l -} - -func (l *logtests) WithName(name string) logr.LogSink { - return l -} diff --git a/bootstrap/util/configowner.go b/bootstrap/util/configowner.go index 1d42e4c7e7c6..b531d08cf9d3 100644 --- a/bootstrap/util/configowner.go +++ b/bootstrap/util/configowner.go @@ -31,6 +31,7 @@ import ( "sigs.k8s.io/cluster-api/controllers/external" expv1 "sigs.k8s.io/cluster-api/exp/api/v1beta1" "sigs.k8s.io/cluster-api/feature" + "sigs.k8s.io/cluster-api/util" ) // ConfigOwner provides a data interface for different config owner types. @@ -123,6 +124,12 @@ func (co ConfigOwner) KubernetesVersion() string { return version } +// LowerCamelCaseKind mirrors how controller runtime formats the object's kind when used as a logging key +// for the object being reconciled. +func (co ConfigOwner) LowerCamelCaseKind() string { + return util.LowerCamelCaseKind(co.Unstructured) +} + // GetConfigOwner returns the Unstructured object owning the current resource. func GetConfigOwner(ctx context.Context, c client.Client, obj metav1.Object) (*ConfigOwner, error) { allowedGKs := []schema.GroupKind{ diff --git a/cmd/clusterctl/client/cluster/mover.go b/cmd/clusterctl/client/cluster/mover.go index 8cf025f0e479..5e4086ee6f8a 100644 --- a/cmd/clusterctl/client/cluster/mover.go +++ b/cmd/clusterctl/client/cluster/mover.go @@ -540,7 +540,7 @@ func setClusterPause(proxy Proxy, clusters []*node, value bool, dryRun bool) err setClusterPauseBackoff := newWriteBackoff() for i := range clusters { cluster := clusters[i] - log.V(5).Info("Set Cluster.Spec.Paused", "Paused", value, "Cluster", cluster.identity.Name, "Namespace", cluster.identity.Namespace) + log.V(5).Info("Set Cluster.Spec.Paused", "paused", value, "cluster", cluster.identity.Name, "namespace", cluster.identity.Namespace) // Nb. The operation is wrapped in a retry loop to make setClusterPause more resilient to unexpected conditions. if err := retryWithExponentialBackoff(setClusterPauseBackoff, func() error { diff --git a/controllers/external/tracker.go b/controllers/external/tracker.go index ee35b481c23b..d482d89f4d27 100644 --- a/controllers/external/tracker.go +++ b/controllers/external/tracker.go @@ -54,7 +54,7 @@ func (o *ObjectTracker) Watch(log logr.Logger, obj runtime.Object, handler handl u := &unstructured.Unstructured{} u.SetGroupVersionKind(gvk) - log.Info("Adding watcher on external object", "GroupVersionKind", gvk.String()) + log.Info("Adding watcher on external object", "groupVersionKind", gvk.String()) err := o.Controller.Watch( &source.Kind{Type: u}, handler, diff --git a/controllers/remote/cluster_cache_tracker.go b/controllers/remote/cluster_cache_tracker.go index 51e75cada756..5a182fc84f80 100644 --- a/controllers/remote/cluster_cache_tracker.go +++ b/controllers/remote/cluster_cache_tracker.go @@ -36,6 +36,7 @@ import ( "k8s.io/apimachinery/pkg/util/wait" "k8s.io/client-go/kubernetes/scheme" "k8s.io/client-go/rest" + "k8s.io/klog/v2" ctrl "sigs.k8s.io/controller-runtime" "sigs.k8s.io/controller-runtime/pkg/cache" "sigs.k8s.io/controller-runtime/pkg/client" @@ -335,9 +336,7 @@ func (t *ClusterCacheTracker) createClient(config *rest.Config, cluster client.O } // deleteAccessor stops a clusterAccessor's cache and removes the clusterAccessor from the tracker. -func (t *ClusterCacheTracker) deleteAccessor(ctx context.Context, cluster client.ObjectKey) { - log := ctrl.LoggerFrom(ctx) - +func (t *ClusterCacheTracker) deleteAccessor(_ context.Context, cluster client.ObjectKey) { t.lock.Lock() defer t.lock.Unlock() @@ -346,11 +345,11 @@ func (t *ClusterCacheTracker) deleteAccessor(ctx context.Context, cluster client return } - log.V(2).Info("Deleting clusterAccessor", "cluster", cluster.String()) - - log.V(4).Info("Stopping cache", "cluster", cluster.String()) + log := t.log.WithValues("cluster", klog.KRef(cluster.Namespace, cluster.Name)) + log.V(2).Info("Deleting clusterAccessor") + log.V(4).Info("Stopping cache") a.cache.Stop() - log.V(4).Info("Cache stopped", "cluster", cluster.String()) + log.V(4).Info("Cache stopped") delete(t.clusterAccessors, cluster) } @@ -397,8 +396,7 @@ func (t *ClusterCacheTracker) Watch(ctx context.Context, input WatchInput) error } if a.watches.Has(input.Name) { - log := ctrl.LoggerFrom(ctx) - log.V(6).Info("Watch already exists", "namespace", input.Cluster.Namespace, "cluster", input.Cluster.Name, "name", input.Name) + t.log.V(6).Info("Watch already exists", "namespace", klog.KRef(input.Cluster.Namespace, ""), "cluster", klog.KRef(input.Cluster.Namespace, input.Cluster.Name), "name", input.Name) return nil } @@ -501,10 +499,9 @@ func (t *ClusterCacheTracker) healthCheckCluster(ctx context.Context, in *health // An error returned implies the health check has failed a sufficient number of // times for the cluster to be considered unhealthy // NB. we are ignoring ErrWaitTimeout because this error happens when the channel is close, that in this case - // happens when the cache is explicitly stopped. + // happens when the cache is explicitly stopped.F if err != nil && err != wait.ErrWaitTimeout { - log := ctrl.LoggerFrom(ctx) - log.Error(err, "Error health checking cluster", "cluster", in.cluster.String()) + t.log.Error(err, "Error health checking cluster", "cluster", klog.KRef(in.cluster.Namespace, in.cluster.Name)) t.deleteAccessor(ctx, in.cluster) } } diff --git a/controlplane/kubeadm/internal/control_plane.go b/controlplane/kubeadm/internal/control_plane.go index 7293a5074ed6..e649959c9925 100644 --- a/controlplane/kubeadm/internal/control_plane.go +++ b/controlplane/kubeadm/internal/control_plane.go @@ -19,7 +19,6 @@ package internal import ( "context" - "github.com/go-logr/logr" "github.com/pkg/errors" corev1 "k8s.io/api/core/v1" apierrors "k8s.io/apimachinery/pkg/api/errors" @@ -90,11 +89,6 @@ func NewControlPlane(ctx context.Context, client client.Client, cluster *cluster }, nil } -// Logger returns a logger with useful context. -func (c *ControlPlane) Logger() logr.Logger { - return Log.WithValues("namespace", c.KCP.Namespace, "name", c.KCP.Name, "cluster-name", c.Cluster.Name) -} - // FailureDomains returns a slice of failure domain objects synced from the infrastructure provider into Cluster.Status. func (c *ControlPlane) FailureDomains() clusterv1.FailureDomains { if c.Cluster.Status.FailureDomains == nil { diff --git a/controlplane/kubeadm/internal/controllers/controller.go b/controlplane/kubeadm/internal/controllers/controller.go index a7eadbb6a1e6..38ab85d157bc 100644 --- a/controlplane/kubeadm/internal/controllers/controller.go +++ b/controlplane/kubeadm/internal/controllers/controller.go @@ -28,6 +28,7 @@ import ( metav1 "k8s.io/apimachinery/pkg/apis/meta/v1" kerrors "k8s.io/apimachinery/pkg/util/errors" "k8s.io/client-go/tools/record" + "k8s.io/klog/v2" "k8s.io/utils/pointer" ctrl "sigs.k8s.io/controller-runtime" "sigs.k8s.io/controller-runtime/pkg/client" @@ -142,7 +143,8 @@ func (r *KubeadmControlPlaneReconciler) Reconcile(ctx context.Context, req ctrl. log.Info("Cluster Controller has not yet set OwnerRef") return ctrl.Result{}, nil } - log = log.WithValues("cluster", cluster.Name) + log = log.WithValues("cluster", klog.KObj(cluster)) + ctx = ctrl.LoggerInto(ctx, log) if annotations.IsPaused(cluster, kcp) { log.Info("Reconciliation is paused for this object") @@ -241,7 +243,7 @@ func patchKubeadmControlPlane(ctx context.Context, patchHelper *patch.Helper, kc // reconcile handles KubeadmControlPlane reconciliation. func (r *KubeadmControlPlaneReconciler) reconcile(ctx context.Context, cluster *clusterv1.Cluster, kcp *controlplanev1.KubeadmControlPlane) (res ctrl.Result, reterr error) { - log := ctrl.LoggerFrom(ctx, "cluster", cluster.Name) + log := ctrl.LoggerFrom(ctx) log.Info("Reconcile KubeadmControlPlane") // Make sure to reconcile the external infrastructure reference. @@ -407,7 +409,7 @@ func (r *KubeadmControlPlaneReconciler) reconcile(ctx context.Context, cluster * // The implementation does not take non-control plane workloads into consideration. This may or may not change in the future. // Please see https://github.com/kubernetes-sigs/cluster-api/issues/2064. func (r *KubeadmControlPlaneReconciler) reconcileDelete(ctx context.Context, cluster *clusterv1.Cluster, kcp *controlplanev1.KubeadmControlPlane) (ctrl.Result, error) { - log := ctrl.LoggerFrom(ctx, "cluster", cluster.Name) + log := ctrl.LoggerFrom(ctx) log.Info("Reconcile KubeadmControlPlane deletion") // Gets all machines, not just control plane machines. @@ -461,7 +463,7 @@ func (r *KubeadmControlPlaneReconciler) reconcileDelete(ctx context.Context, clu var errs []error for i := range machinesToDelete { m := machinesToDelete[i] - logger := log.WithValues("machine", m) + logger := log.WithValues("machine", klog.KObj(m)) if err := r.Client.Delete(ctx, machinesToDelete[i]); err != nil && !apierrors.IsNotFound(err) { logger.Error(err, "Failed to cleanup owned machine") errs = append(errs, err) @@ -525,7 +527,7 @@ func (r *KubeadmControlPlaneReconciler) reconcileControlPlaneConditions(ctx cont // // NOTE: this func uses KCP conditions, it is required to call reconcileControlPlaneConditions before this. func (r *KubeadmControlPlaneReconciler) reconcileEtcdMembers(ctx context.Context, controlPlane *internal.ControlPlane) (ctrl.Result, error) { - log := ctrl.LoggerFrom(ctx, "cluster", controlPlane.Cluster.Name) + log := ctrl.LoggerFrom(ctx) // If etcd is not managed by KCP this is a no-op. if !controlPlane.IsEtcdManaged() { diff --git a/controlplane/kubeadm/internal/controllers/helpers.go b/controlplane/kubeadm/internal/controllers/helpers.go index 31034141ca9f..03e01f0ecde0 100644 --- a/controlplane/kubeadm/internal/controllers/helpers.go +++ b/controlplane/kubeadm/internal/controllers/helpers.go @@ -28,6 +28,7 @@ import ( "k8s.io/apimachinery/pkg/apis/meta/v1/unstructured" kerrors "k8s.io/apimachinery/pkg/util/errors" "k8s.io/apiserver/pkg/storage/names" + "k8s.io/klog/v2" ctrl "sigs.k8s.io/controller-runtime" clusterv1 "sigs.k8s.io/cluster-api/api/v1beta1" @@ -103,7 +104,7 @@ func (r *KubeadmControlPlaneReconciler) reconcileKubeconfig(ctx context.Context, func (r *KubeadmControlPlaneReconciler) adoptKubeconfigSecret(ctx context.Context, cluster *clusterv1.Cluster, configSecret *corev1.Secret, controllerOwnerRef metav1.OwnerReference) error { log := ctrl.LoggerFrom(ctx) - log.Info("Adopting KubeConfig secret created by v1alpha2 controllers", "Name", configSecret.Name) + log.Info("Adopting KubeConfig secret created by v1alpha2 controllers", "secret", klog.KObj(configSecret)) patch, err := patch.NewHelper(configSecret, r.Client) if err != nil { diff --git a/controlplane/kubeadm/internal/controllers/scale.go b/controlplane/kubeadm/internal/controllers/scale.go index 0fcf1d022d38..bb362b01b238 100644 --- a/controlplane/kubeadm/internal/controllers/scale.go +++ b/controlplane/kubeadm/internal/controllers/scale.go @@ -25,6 +25,7 @@ import ( corev1 "k8s.io/api/core/v1" apierrors "k8s.io/apimachinery/pkg/api/errors" kerrors "k8s.io/apimachinery/pkg/util/errors" + "k8s.io/klog/v2" ctrl "sigs.k8s.io/controller-runtime" clusterv1 "sigs.k8s.io/cluster-api/api/v1beta1" @@ -36,7 +37,7 @@ import ( ) func (r *KubeadmControlPlaneReconciler) initializeControlPlane(ctx context.Context, cluster *clusterv1.Cluster, kcp *controlplanev1.KubeadmControlPlane, controlPlane *internal.ControlPlane) (ctrl.Result, error) { - logger := controlPlane.Logger() + logger := ctrl.LoggerFrom(ctx) // Perform an uncached read of all the owned machines. This check is in place to make sure // that the controller cache is not misbehaving and we end up initializing the cluster more than once. @@ -65,7 +66,7 @@ func (r *KubeadmControlPlaneReconciler) initializeControlPlane(ctx context.Conte } func (r *KubeadmControlPlaneReconciler) scaleUpControlPlane(ctx context.Context, cluster *clusterv1.Cluster, kcp *controlplanev1.KubeadmControlPlane, controlPlane *internal.ControlPlane) (ctrl.Result, error) { - logger := controlPlane.Logger() + logger := ctrl.LoggerFrom(ctx) // Run preflight checks to ensure that the control plane is stable before proceeding with a scale up/scale down operation; if not, wait. if result, err := r.preflightChecks(ctx, controlPlane); err != nil || !result.IsZero() { @@ -92,7 +93,7 @@ func (r *KubeadmControlPlaneReconciler) scaleDownControlPlane( controlPlane *internal.ControlPlane, outdatedMachines collections.Machines, ) (ctrl.Result, error) { - logger := controlPlane.Logger() + logger := ctrl.LoggerFrom(ctx) // Pick the Machine that we should scale down. machineToDelete, err := selectMachineForScaleDown(controlPlane, outdatedMachines) @@ -140,7 +141,7 @@ func (r *KubeadmControlPlaneReconciler) scaleDownControlPlane( return ctrl.Result{}, err } - logger = logger.WithValues("machine", machineToDelete.Name) + logger = logger.WithValues("machine", klog.KObj(machineToDelete)) if err := r.Client.Delete(ctx, machineToDelete); err != nil && !apierrors.IsNotFound(err) { logger.Error(err, "Failed to delete control plane machine") r.recorder.Eventf(kcp, corev1.EventTypeWarning, "FailedScaleDown", @@ -160,8 +161,8 @@ func (r *KubeadmControlPlaneReconciler) scaleDownControlPlane( // If the control plane is not passing preflight checks, it requeue. // // NOTE: this func uses KCP conditions, it is required to call reconcileControlPlaneConditions before this. -func (r *KubeadmControlPlaneReconciler) preflightChecks(_ context.Context, controlPlane *internal.ControlPlane, excludeFor ...*clusterv1.Machine) (ctrl.Result, error) { //nolint:unparam - logger := controlPlane.Logger() +func (r *KubeadmControlPlaneReconciler) preflightChecks(ctx context.Context, controlPlane *internal.ControlPlane, excludeFor ...*clusterv1.Machine) (ctrl.Result, error) { //nolint:unparam + logger := ctrl.LoggerFrom(ctx) // If there is no KCP-owned control-plane machines, then control-plane has not been initialized yet, // so it is considered ok to proceed. diff --git a/controlplane/kubeadm/internal/controllers/status.go b/controlplane/kubeadm/internal/controllers/status.go index 1617827ff3e5..abc378a95344 100644 --- a/controlplane/kubeadm/internal/controllers/status.go +++ b/controlplane/kubeadm/internal/controllers/status.go @@ -20,6 +20,7 @@ import ( "context" "github.com/pkg/errors" + "k8s.io/klog/v2" ctrl "sigs.k8s.io/controller-runtime" clusterv1 "sigs.k8s.io/cluster-api/api/v1beta1" @@ -33,7 +34,7 @@ import ( // updateStatus is called after every reconcilitation loop in a defer statement to always make sure we have the // resource status subresourcs up-to-date. func (r *KubeadmControlPlaneReconciler) updateStatus(ctx context.Context, kcp *controlplanev1.KubeadmControlPlane, cluster *clusterv1.Cluster) error { - log := ctrl.LoggerFrom(ctx, "cluster", cluster.Name) + log := ctrl.LoggerFrom(ctx, "cluster", klog.KObj(cluster)) selector := collections.ControlPlaneSelectorForCluster(cluster.Name) // Copy label selector to its status counterpart in string format. diff --git a/controlplane/kubeadm/internal/controllers/upgrade.go b/controlplane/kubeadm/internal/controllers/upgrade.go index afeeecad6423..a3c0a6f8ee56 100644 --- a/controlplane/kubeadm/internal/controllers/upgrade.go +++ b/controlplane/kubeadm/internal/controllers/upgrade.go @@ -38,7 +38,7 @@ func (r *KubeadmControlPlaneReconciler) upgradeControlPlane( controlPlane *internal.ControlPlane, machinesRequireUpgrade collections.Machines, ) (ctrl.Result, error) { - logger := controlPlane.Logger() + logger := ctrl.LoggerFrom(ctx) if kcp.Spec.RolloutStrategy == nil || kcp.Spec.RolloutStrategy.RollingUpdate == nil { return ctrl.Result{}, errors.New("rolloutStrategy is not set") diff --git a/exp/addons/internal/controllers/clusterresourceset_controller.go b/exp/addons/internal/controllers/clusterresourceset_controller.go index 0e1f542cf273..336ceaf082a4 100644 --- a/exp/addons/internal/controllers/clusterresourceset_controller.go +++ b/exp/addons/internal/controllers/clusterresourceset_controller.go @@ -31,6 +31,7 @@ import ( "k8s.io/apimachinery/pkg/labels" "k8s.io/apimachinery/pkg/types" kerrors "k8s.io/apimachinery/pkg/util/errors" + "k8s.io/klog/v2" ctrl "sigs.k8s.io/controller-runtime" "sigs.k8s.io/controller-runtime/pkg/builder" "sigs.k8s.io/controller-runtime/pkg/client" @@ -133,7 +134,7 @@ func (r *ClusterResourceSetReconciler) Reconcile(ctx context.Context, req ctrl.R clusters, err := r.getClustersByClusterResourceSetSelector(ctx, clusterResourceSet) if err != nil { - log.Error(err, "Failed fetching clusters that matches ClusterResourceSet labels", "ClusterResourceSet", clusterResourceSet.Name) + log.Error(err, "Failed fetching clusters that matches ClusterResourceSet labels", "clusterResourceSet", klog.KObj(clusterResourceSet)) conditions.MarkFalse(clusterResourceSet, addonsv1.ResourcesAppliedCondition, addonsv1.ClusterMatchFailedReason, clusterv1.ConditionSeverityWarning, err.Error()) return ctrl.Result{}, err } diff --git a/exp/internal/controllers/machinepool_controller.go b/exp/internal/controllers/machinepool_controller.go index ca980cf7a584..1e6b26d40606 100644 --- a/exp/internal/controllers/machinepool_controller.go +++ b/exp/internal/controllers/machinepool_controller.go @@ -27,6 +27,7 @@ import ( "k8s.io/apimachinery/pkg/apis/meta/v1/unstructured" kerrors "k8s.io/apimachinery/pkg/util/errors" "k8s.io/client-go/tools/record" + "k8s.io/klog/v2" ctrl "sigs.k8s.io/controller-runtime" "sigs.k8s.io/controller-runtime/pkg/client" "sigs.k8s.io/controller-runtime/pkg/controller" @@ -116,7 +117,7 @@ func (r *MachinePoolReconciler) Reconcile(ctx context.Context, req ctrl.Request) cluster, err := util.GetClusterByName(ctx, r.Client, mp.ObjectMeta.Namespace, mp.Spec.ClusterName) if err != nil { - log.Error(err, "Failed to get Cluster %s for MachinePool.", mp.Spec.ClusterName) + log.Error(err, "Failed to get Cluster for MachinePool.", "machinePool", klog.KObj(mp), "cluster", klog.KRef(mp.ObjectMeta.Namespace, mp.Spec.ClusterName)) return ctrl.Result{}, errors.Wrapf(err, "failed to get cluster %q for machinepool %q in namespace %q", mp.Spec.ClusterName, mp.Name, mp.Namespace) } diff --git a/exp/internal/controllers/machinepool_controller_noderef.go b/exp/internal/controllers/machinepool_controller_noderef.go index a45b48a0d30b..3f14420c1bd2 100644 --- a/exp/internal/controllers/machinepool_controller_noderef.go +++ b/exp/internal/controllers/machinepool_controller_noderef.go @@ -23,6 +23,7 @@ import ( "github.com/pkg/errors" corev1 "k8s.io/api/core/v1" + "k8s.io/klog/v2" ctrl "sigs.k8s.io/controller-runtime" "sigs.k8s.io/controller-runtime/pkg/client" @@ -65,7 +66,7 @@ func (r *MachinePoolReconciler) reconcileNodeRefs(ctx context.Context, cluster * return ctrl.Result{}, nil } - log = log.WithValues("cluster", cluster.Name) + log = log.WithValues("cluster", klog.KObj(cluster)) // Check that the MachinePool has valid ProviderIDList. if len(mp.Spec.ProviderIDList) == 0 && (mp.Spec.Replicas == nil || *mp.Spec.Replicas != 0) { diff --git a/exp/internal/controllers/machinepool_controller_phases.go b/exp/internal/controllers/machinepool_controller_phases.go index ea0748d8cc50..7421c8a57b42 100644 --- a/exp/internal/controllers/machinepool_controller_phases.go +++ b/exp/internal/controllers/machinepool_controller_phases.go @@ -26,6 +26,7 @@ import ( corev1 "k8s.io/api/core/v1" apierrors "k8s.io/apimachinery/pkg/api/errors" "k8s.io/apimachinery/pkg/apis/meta/v1/unstructured" + "k8s.io/klog/v2" "k8s.io/utils/pointer" ctrl "sigs.k8s.io/controller-runtime" "sigs.k8s.io/controller-runtime/pkg/controller/controllerutil" @@ -166,7 +167,7 @@ func (r *MachinePoolReconciler) reconcileExternal(ctx context.Context, cluster * // reconcileBootstrap reconciles the Spec.Bootstrap.ConfigRef object on a MachinePool. func (r *MachinePoolReconciler) reconcileBootstrap(ctx context.Context, cluster *clusterv1.Cluster, m *expv1.MachinePool) (ctrl.Result, error) { - log := ctrl.LoggerFrom(ctx, "cluster", cluster.Name) + log := ctrl.LoggerFrom(ctx, "cluster", klog.KObj(cluster)) // Call generic external reconciler if we have an external reference. var bootstrapConfig *unstructured.Unstructured @@ -226,7 +227,7 @@ func (r *MachinePoolReconciler) reconcileBootstrap(ctx context.Context, cluster // reconcileInfrastructure reconciles the Spec.InfrastructureRef object on a MachinePool. func (r *MachinePoolReconciler) reconcileInfrastructure(ctx context.Context, cluster *clusterv1.Cluster, mp *expv1.MachinePool) (ctrl.Result, error) { - log := ctrl.LoggerFrom(ctx, "cluster", cluster.Name) + log := ctrl.LoggerFrom(ctx, "cluster", klog.KObj(cluster)) // Call generic external reconciler. infraReconcileResult, err := r.reconcileExternal(ctx, cluster, mp, &mp.Spec.Template.Spec.InfrastructureRef) diff --git a/exp/util/util.go b/exp/util/util.go index 5ae1a13406af..214fec3b2db8 100644 --- a/exp/util/util.go +++ b/exp/util/util.go @@ -75,7 +75,7 @@ func MachinePoolToInfrastructureMapFunc(gvk schema.GroupVersionKind, log logr.Lo // Return early if the GroupKind doesn't match what we expect. infraGK := ref.GroupVersionKind().GroupKind() if gk != infraGK { - log.V(4).Info("infra kind doesn't match filter group kind", infraGK.String()) + log.V(4).Info("infra kind doesn't match filter group kind", "infrastructureGroupKind", infraGK.String()) return nil } diff --git a/hack/observability/promtail/values.yaml b/hack/observability/promtail/values.yaml index cdc51bf0c0f7..38761da53323 100644 --- a/hack/observability/promtail/values.yaml +++ b/hack/observability/promtail/values.yaml @@ -3,3 +3,17 @@ config: # publish data to loki lokiAddress: http://loki:3100/loki/api/v1/push + + snippets: + pipelineStages: + # Parse cluster and machine to make them available as labels. + - cri: { } + - json: + expressions: + controller: + cluster: join('/',[cluster.namespace,cluster.name]) + machine: join('/',[machine.namespace,machine.name]) + - labels: + controller: + cluster: + machine: diff --git a/internal/controllers/cluster/cluster_controller.go b/internal/controllers/cluster/cluster_controller.go index 856a63b719a5..61222b1ebeec 100644 --- a/internal/controllers/cluster/cluster_controller.go +++ b/internal/controllers/cluster/cluster_controller.go @@ -29,6 +29,7 @@ import ( "k8s.io/apimachinery/pkg/runtime" kerrors "k8s.io/apimachinery/pkg/util/errors" "k8s.io/client-go/tools/record" + "k8s.io/klog/v2" ctrl "sigs.k8s.io/controller-runtime" "sigs.k8s.io/controller-runtime/pkg/client" "sigs.k8s.io/controller-runtime/pkg/controller" @@ -113,6 +114,8 @@ func (r *Reconciler) Reconcile(ctx context.Context, req ctrl.Request) (_ ctrl.Re return ctrl.Result{}, err } + ctrl.LoggerInto(ctx, log.WithValues("cluster", klog.KObj(cluster))) + // Return early if the object or Cluster is paused. if annotations.IsPaused(cluster, cluster) { log.Info("Reconciliation is paused for this object") @@ -179,7 +182,7 @@ func patchCluster(ctx context.Context, patchHelper *patch.Helper, cluster *clust // reconcile handles cluster reconciliation. func (r *Reconciler) reconcile(ctx context.Context, cluster *clusterv1.Cluster) (ctrl.Result, error) { - log := ctrl.LoggerFrom(ctx, "cluster", cluster.Name) + log := ctrl.LoggerFrom(ctx) if cluster.Spec.Topology != nil { if cluster.Spec.ControlPlaneRef == nil || cluster.Spec.InfrastructureRef == nil { diff --git a/internal/controllers/clusterclass/clusterclass_controller.go b/internal/controllers/clusterclass/clusterclass_controller.go index b9798e4e7592..2a865f4ed984 100644 --- a/internal/controllers/clusterclass/clusterclass_controller.go +++ b/internal/controllers/clusterclass/clusterclass_controller.go @@ -59,7 +59,7 @@ type Reconciler struct { func (r *Reconciler) SetupWithManager(ctx context.Context, mgr ctrl.Manager, options controller.Options) error { err := ctrl.NewControllerManagedBy(mgr). For(&clusterv1.ClusterClass{}). - Named("topology/clusterclass"). + Named("clusterclass"). WithOptions(options). WithEventFilter(predicates.ResourceNotPausedAndHasFilterLabel(ctrl.LoggerFrom(ctx), r.WatchFilterValue)). Complete(r) diff --git a/internal/controllers/machine/machine_controller.go b/internal/controllers/machine/machine_controller.go index 62b581e91d14..89c32cc54a7e 100644 --- a/internal/controllers/machine/machine_controller.go +++ b/internal/controllers/machine/machine_controller.go @@ -31,6 +31,7 @@ import ( "k8s.io/apimachinery/pkg/util/wait" "k8s.io/client-go/kubernetes" "k8s.io/client-go/tools/record" + "k8s.io/klog/v2" kubedrain "k8s.io/kubectl/pkg/drain" ctrl "sigs.k8s.io/controller-runtime" "sigs.k8s.io/controller-runtime/pkg/client" @@ -157,6 +158,9 @@ func (r *Reconciler) Reconcile(ctx context.Context, req ctrl.Request) (_ ctrl.Re m.Spec.ClusterName, m.Name, m.Namespace) } + log = log.WithValues("cluster", klog.KObj(cluster)) + ctx = ctrl.LoggerInto(ctx, log) + // Return early if the object or Cluster is paused. if annotations.IsPaused(cluster, m) { log.Info("Reconciliation is paused for this object") @@ -285,15 +289,19 @@ func (r *Reconciler) reconcile(ctx context.Context, cluster *clusterv1.Cluster, return res, kerrors.NewAggregate(errs) } -func (r *Reconciler) reconcileDelete(ctx context.Context, cluster *clusterv1.Cluster, m *clusterv1.Machine) (ctrl.Result, error) { - log := ctrl.LoggerFrom(ctx, "cluster", cluster.Name) +func (r *Reconciler) reconcileDelete(ctx context.Context, cluster *clusterv1.Cluster, m *clusterv1.Machine) (ctrl.Result, error) { //nolint:gocyclo + log := ctrl.LoggerFrom(ctx) err := r.isDeleteNodeAllowed(ctx, cluster, m) isDeleteNodeAllowed := err == nil if err != nil { switch err { case errNoControlPlaneNodes, errLastControlPlaneNode, errNilNodeRef, errClusterIsBeingDeleted, errControlPlaneIsBeingDeleted: - log.Info("Deleting Kubernetes Node associated with Machine is not allowed", "node", m.Status.NodeRef, "cause", err.Error()) + var nodeName = "" + if m.Status.NodeRef != nil { + nodeName = m.Status.NodeRef.Name + } + log.Info("Deleting Kubernetes Node associated with Machine is not allowed", "node", klog.KRef("", nodeName), "cause", err.Error()) default: return ctrl.Result{}, errors.Wrapf(err, "failed to check if Kubernetes Node deletion is allowed") } @@ -315,7 +323,7 @@ func (r *Reconciler) reconcileDelete(ctx context.Context, cluster *clusterv1.Clu return ctrl.Result{}, err } - log.Info("Draining node", "node", m.Status.NodeRef.Name) + log.Info("Draining node", "node", klog.KRef("", m.Status.NodeRef.Name)) // The DrainingSucceededCondition never exists before the node is drained for the first time, // so its transition time can be used to record the first time draining. // This `if` condition prevents the transition time to be changed more than once. @@ -342,12 +350,12 @@ func (r *Reconciler) reconcileDelete(ctx context.Context, cluster *clusterv1.Clu if conditions.Get(m, clusterv1.VolumeDetachSucceededCondition) == nil { conditions.MarkFalse(m, clusterv1.VolumeDetachSucceededCondition, clusterv1.WaitingForVolumeDetachReason, clusterv1.ConditionSeverityInfo, "Waiting for node volumes to be detached") } - if ok, err := r.shouldWaitForNodeVolumes(ctx, cluster, m.Status.NodeRef.Name, m.Name); ok || err != nil { + if ok, err := r.shouldWaitForNodeVolumes(ctx, cluster, m.Status.NodeRef.Name); ok || err != nil { if err != nil { r.recorder.Eventf(m, corev1.EventTypeWarning, "FailedWaitForVolumeDetach", "error wait for volume detach, node %q: %v", m.Status.NodeRef.Name, err) return ctrl.Result{}, err } - log.Info("Waiting for node volumes to be detached", "node", m.Status.NodeRef.Name) + log.Info("Waiting for node volumes to be detached", "node", klog.KRef("", m.Status.NodeRef.Name)) return ctrl.Result{}, nil } conditions.MarkTrue(m, clusterv1.VolumeDetachSucceededCondition) @@ -387,7 +395,7 @@ func (r *Reconciler) reconcileDelete(ctx context.Context, cluster *clusterv1.Clu // We only delete the node after the underlying infrastructure is gone. // https://github.com/kubernetes-sigs/cluster-api/issues/2565 if isDeleteNodeAllowed { - log.Info("Deleting node", "node", m.Status.NodeRef.Name) + log.Info("Deleting node", "node", klog.KRef("", m.Status.NodeRef.Name)) var deleteNodeErr error waitErr := wait.PollImmediate(2*time.Second, r.nodeDeletionRetryTimeout, func() (bool, error) { @@ -397,7 +405,7 @@ func (r *Reconciler) reconcileDelete(ctx context.Context, cluster *clusterv1.Clu return true, nil }) if waitErr != nil { - log.Error(deleteNodeErr, "Timed out deleting node", "node", m.Status.NodeRef.Name) + log.Error(deleteNodeErr, "Timed out deleting node", "node", klog.KRef("", m.Status.NodeRef.Name)) conditions.MarkFalse(m, clusterv1.MachineNodeHealthyCondition, clusterv1.DeletionFailedReason, clusterv1.ConditionSeverityWarning, "") r.recorder.Eventf(m, corev1.EventTypeWarning, "FailedDeleteNode", "error deleting Machine's node: %v", deleteNodeErr) @@ -445,7 +453,7 @@ func (r *Reconciler) nodeDrainTimeoutExceeded(machine *clusterv1.Machine) bool { // isDeleteNodeAllowed returns nil only if the Machine's NodeRef is not nil // and if the Machine is not the last control plane node in the cluster. func (r *Reconciler) isDeleteNodeAllowed(ctx context.Context, cluster *clusterv1.Cluster, machine *clusterv1.Machine) error { - log := ctrl.LoggerFrom(ctx, "cluster", cluster.Name) + log := ctrl.LoggerFrom(ctx) // Return early if the cluster is being deleted. if !cluster.DeletionTimestamp.IsZero() { return errClusterIsBeingDeleted @@ -505,7 +513,7 @@ func (r *Reconciler) isDeleteNodeAllowed(ctx context.Context, cluster *clusterv1 } func (r *Reconciler) drainNode(ctx context.Context, cluster *clusterv1.Cluster, nodeName string) (ctrl.Result, error) { - log := ctrl.LoggerFrom(ctx, "cluster", cluster.Name, "node", nodeName) + log := ctrl.LoggerFrom(ctx, "node", klog.KRef("", nodeName)) restConfig, err := remote.RESTConfig(ctx, controllerName, r.Client, util.ObjectKey(cluster)) if err != nil { @@ -544,7 +552,7 @@ func (r *Reconciler) drainNode(ctx context.Context, cluster *clusterv1.Cluster, verbStr = "Evicted" } log.Info(fmt.Sprintf("%s pod from Node", verbStr), - "pod", fmt.Sprintf("%s/%s", pod.Name, pod.Namespace)) + "pod", klog.KObj(pod)) }, Out: writer{log.Info}, ErrOut: writer{func(msg string, keysAndValues ...interface{}) { @@ -578,8 +586,8 @@ func (r *Reconciler) drainNode(ctx context.Context, cluster *clusterv1.Cluster, // this could cause issue for some storage provisioner, for example, vsphere-volume this is problematic // because if the node is deleted before detach success, then the underline VMDK will be deleted together with the Machine // so after node draining we need to check if all volumes are detached before deleting the node. -func (r *Reconciler) shouldWaitForNodeVolumes(ctx context.Context, cluster *clusterv1.Cluster, nodeName string, machineName string) (bool, error) { - log := ctrl.LoggerFrom(ctx, "cluster", cluster.Name, "node", nodeName, "machine", machineName) +func (r *Reconciler) shouldWaitForNodeVolumes(ctx context.Context, cluster *clusterv1.Cluster, nodeName string) (bool, error) { + log := ctrl.LoggerFrom(ctx, "node", klog.KRef("", nodeName)) remoteClient, err := r.Tracker.GetClient(ctx, util.ObjectKey(cluster)) if err != nil { @@ -599,7 +607,7 @@ func (r *Reconciler) shouldWaitForNodeVolumes(ctx context.Context, cluster *clus } func (r *Reconciler) deleteNode(ctx context.Context, cluster *clusterv1.Cluster, name string) error { - log := ctrl.LoggerFrom(ctx, "cluster", cluster.Name) + log := ctrl.LoggerFrom(ctx) remoteClient, err := r.Tracker.GetClient(ctx, util.ObjectKey(cluster)) if err != nil { diff --git a/internal/controllers/machine/machine_controller_noderef.go b/internal/controllers/machine/machine_controller_noderef.go index 3641258a385f..ef2e2d896400 100644 --- a/internal/controllers/machine/machine_controller_noderef.go +++ b/internal/controllers/machine/machine_controller_noderef.go @@ -23,6 +23,7 @@ import ( "github.com/pkg/errors" corev1 "k8s.io/api/core/v1" metav1 "k8s.io/apimachinery/pkg/apis/meta/v1" + "k8s.io/klog/v2" ctrl "sigs.k8s.io/controller-runtime" "sigs.k8s.io/controller-runtime/pkg/client" @@ -41,8 +42,7 @@ var ( ) func (r *Reconciler) reconcileNode(ctx context.Context, cluster *clusterv1.Cluster, machine *clusterv1.Machine) (ctrl.Result, error) { - log := ctrl.LoggerFrom(ctx, "machine", machine.Name, "namespace", machine.Namespace) - log = log.WithValues("cluster", cluster.Name) + log := ctrl.LoggerFrom(ctx) // Check that the Machine has a valid ProviderID. if machine.Spec.ProviderID == nil || *machine.Spec.ProviderID == "" { @@ -189,7 +189,7 @@ func (r *Reconciler) getNode(ctx context.Context, c client.Reader, providerID *n for key, node := range nl.Items { nodeProviderID, err := noderefutil.NewProviderID(node.Spec.ProviderID) if err != nil { - log.Error(err, "Failed to parse ProviderID", "node", client.ObjectKeyFromObject(&nl.Items[key]).String()) + log.Error(err, "Failed to parse ProviderID", "node", klog.KRef("", nl.Items[key].GetName())) continue } diff --git a/internal/controllers/machine/machine_controller_phases.go b/internal/controllers/machine/machine_controller_phases.go index 181543e6ccc1..857ea1d833d1 100644 --- a/internal/controllers/machine/machine_controller_phases.go +++ b/internal/controllers/machine/machine_controller_phases.go @@ -27,6 +27,7 @@ import ( metav1 "k8s.io/apimachinery/pkg/apis/meta/v1" "k8s.io/apimachinery/pkg/apis/meta/v1/unstructured" "k8s.io/apimachinery/pkg/runtime/schema" + "k8s.io/klog/v2" "k8s.io/utils/pointer" ctrl "sigs.k8s.io/controller-runtime" "sigs.k8s.io/controller-runtime/pkg/controller/controllerutil" @@ -88,7 +89,7 @@ func (r *Reconciler) reconcilePhase(_ context.Context, m *clusterv1.Machine) { // reconcileExternal handles generic unstructured objects referenced by a Machine. func (r *Reconciler) reconcileExternal(ctx context.Context, cluster *clusterv1.Cluster, m *clusterv1.Machine, ref *corev1.ObjectReference) (external.ReconcileOutput, error) { - log := ctrl.LoggerFrom(ctx, "cluster", cluster.Name) + log := ctrl.LoggerFrom(ctx, "cluster", klog.KObj(cluster)) if err := utilconversion.UpdateReferenceAPIContract(ctx, r.Client, r.APIReader, ref); err != nil { return external.ReconcileOutput{}, err @@ -97,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", m.Name, "Namespace", m.Namespace) + log.Info("could not find external ref, requeueing", "refGVK", ref.GroupVersionKind(), "refName", ref.Name, "machine", klog.KObj(m)) return external.ReconcileOutput{RequeueAfter: externalReadyWait}, nil } return external.ReconcileOutput{}, err @@ -172,7 +173,7 @@ func (r *Reconciler) reconcileExternal(ctx context.Context, cluster *clusterv1.C // reconcileBootstrap reconciles the Spec.Bootstrap.ConfigRef object on a Machine. func (r *Reconciler) reconcileBootstrap(ctx context.Context, cluster *clusterv1.Cluster, m *clusterv1.Machine) (ctrl.Result, error) { - log := ctrl.LoggerFrom(ctx, "cluster", cluster.Name) + log := ctrl.LoggerFrom(ctx) // If the bootstrap data is populated, set ready and return. if m.Spec.Bootstrap.DataSecretName != nil { @@ -237,7 +238,7 @@ func (r *Reconciler) reconcileBootstrap(ctx context.Context, cluster *clusterv1. // reconcileInfrastructure reconciles the Spec.InfrastructureRef object on a Machine. func (r *Reconciler) reconcileInfrastructure(ctx context.Context, cluster *clusterv1.Cluster, m *clusterv1.Machine) (ctrl.Result, error) { - log := ctrl.LoggerFrom(ctx, "cluster", cluster.Name) + log := ctrl.LoggerFrom(ctx) // Call generic external reconciler. infraReconcileResult, err := r.reconcileExternal(ctx, cluster, m, &m.Spec.InfrastructureRef) diff --git a/internal/controllers/machinedeployment/machinedeployment_controller.go b/internal/controllers/machinedeployment/machinedeployment_controller.go index 2ba6ee903ea1..2705749a46f3 100644 --- a/internal/controllers/machinedeployment/machinedeployment_controller.go +++ b/internal/controllers/machinedeployment/machinedeployment_controller.go @@ -28,6 +28,7 @@ import ( "k8s.io/apimachinery/pkg/labels" kerrors "k8s.io/apimachinery/pkg/util/errors" "k8s.io/client-go/tools/record" + "k8s.io/klog/v2" ctrl "sigs.k8s.io/controller-runtime" "sigs.k8s.io/controller-runtime/pkg/client" "sigs.k8s.io/controller-runtime/pkg/controller" @@ -118,11 +119,17 @@ func (r *Reconciler) Reconcile(ctx context.Context, req ctrl.Request) (_ ctrl.Re return ctrl.Result{}, err } + log = log.WithValues("machineDeployment", klog.KObj(deployment)) + ctx = ctrl.LoggerInto(ctx, log) + cluster, err := util.GetClusterByName(ctx, r.Client, deployment.Namespace, deployment.Spec.ClusterName) if err != nil { return ctrl.Result{}, err } + log = log.WithValues("cluster", klog.KObj(cluster)) + ctx = ctrl.LoggerInto(ctx, log) + // Return early if the object or Cluster is paused. if annotations.IsPaused(cluster, deployment) { log.Info("Reconciliation is paused for this object") @@ -257,33 +264,33 @@ func (r *Reconciler) getMachineSetsForDeployment(ctx context.Context, d *cluster filtered := make([]*clusterv1.MachineSet, 0, len(machineSets.Items)) for idx := range machineSets.Items { ms := &machineSets.Items[idx] - + log.WithValues("machineSet", klog.KObj(ms)) selector, err := metav1.LabelSelectorAsSelector(&d.Spec.Selector) if err != nil { - log.Error(err, "Skipping MachineSet, failed to get label selector from spec selector", "machineset", ms.Name) + log.Error(err, "Skipping MachineSet, failed to get label selector from spec selector") continue } // If a MachineDeployment with a nil or empty selector creeps in, it should match nothing, not everything. if selector.Empty() { - log.Info("Skipping MachineSet as the selector is empty", "machineset", ms.Name) + log.Info("Skipping MachineSet as the selector is empty") continue } // Skip this MachineSet unless either selector matches or it has a controller ref pointing to this MachineDeployment if !selector.Matches(labels.Set(ms.Labels)) && !metav1.IsControlledBy(ms, d) { - log.V(4).Info("Skipping MachineSet, label mismatch", "machineset", ms.Name) + log.V(4).Info("Skipping MachineSet, label mismatch") continue } // Attempt to adopt machine if it meets previous conditions and it has no controller references. if metav1.GetControllerOf(ms) == nil { if err := r.adoptOrphan(ctx, d, ms); err != nil { - log.Error(err, "Failed to adopt MachineSet into MachineDeployment", "machineset", ms.Name) + log.Error(err, "Failed to adopt MachineSet into MachineDeployment") r.recorder.Eventf(d, corev1.EventTypeWarning, "FailedAdopt", "Failed to adopt MachineSet %q: %v", ms.Name, err) continue } - log.Info("Adopted MachineSet into MachineDeployment", "machineset", ms.Name) + log.Info("Adopted MachineSet into MachineDeployment") r.recorder.Eventf(d, corev1.EventTypeNormal, "SuccessfulAdopt", "Adopted MachineSet %q", ms.Name) } diff --git a/internal/controllers/machinedeployment/machinedeployment_rollout_ondelete.go b/internal/controllers/machinedeployment/machinedeployment_rollout_ondelete.go index c07e7629d4d1..31bb6c9ee98b 100644 --- a/internal/controllers/machinedeployment/machinedeployment_rollout_ondelete.go +++ b/internal/controllers/machinedeployment/machinedeployment_rollout_ondelete.go @@ -22,6 +22,7 @@ import ( "github.com/pkg/errors" metav1 "k8s.io/apimachinery/pkg/apis/meta/v1" + "k8s.io/klog/v2" ctrl "sigs.k8s.io/controller-runtime" "sigs.k8s.io/controller-runtime/pkg/client" @@ -84,15 +85,16 @@ func (r *Reconciler) reconcileOldMachineSetsOnDelete(ctx context.Context, oldMSs totalReplicas := mdutil.GetReplicaCountForMachineSets(allMSs) scaleDownAmount := totalReplicas - *deployment.Spec.Replicas for _, oldMS := range oldMSs { + log = log.WithValues("machineSet", klog.KObj(oldMS)) if oldMS.Spec.Replicas == nil || *oldMS.Spec.Replicas <= 0 { - log.V(4).Info("fully scaled down", "MachineSet", oldMS.Name) + log.V(4).Info("fully scaled down") continue } if oldMS.Annotations == nil { oldMS.Annotations = map[string]string{} } if _, ok := oldMS.Annotations[clusterv1.DisableMachineCreate]; !ok { - log.V(4).Info("setting annotation on old MachineSet to disable machine creation", "MachineSet", oldMS.Name) + log.V(4).Info("setting annotation on old MachineSet to disable machine creation") patchHelper, err := patch.NewHelper(oldMS, r.Client) if err != nil { return err @@ -107,7 +109,7 @@ func (r *Reconciler) reconcileOldMachineSetsOnDelete(ctx context.Context, oldMSs log.V(4).Error(err, "failed to convert MachineSet %q label selector to a map", oldMS.Name) continue } - log.V(4).Info("Fetching Machines associated with MachineSet", "MachineSet", oldMS.Name) + log.V(4).Info("Fetching Machines associated with MachineSet") // Get all Machines linked to this MachineSet. allMachinesInOldMS := &clusterv1.MachineList{} if err := r.Client.List(ctx, @@ -128,19 +130,20 @@ func (r *Reconciler) reconcileOldMachineSetsOnDelete(ctx context.Context, oldMSs log.V(4).Error(errors.Errorf("unexpected negative scale down amount: %d", machineSetScaleDownAmountDueToMachineDeletion), fmt.Sprintf("Error reconciling MachineSet %s", oldMS.Name)) } scaleDownAmount -= machineSetScaleDownAmountDueToMachineDeletion - log.V(4).Info("Adjusting replica count for deleted machines", "replicaCount", oldMS.Name, "replicas", updatedReplicaCount) - log.V(4).Info("Scaling down", "MachineSet", oldMS.Name, "replicas", updatedReplicaCount) + log.V(4).Info("Adjusting replica count for deleted machines", "oldReplicas", oldMS.Spec.Replicas, "newReplicas", updatedReplicaCount) + log.V(4).Info("Scaling down", "replicas", updatedReplicaCount) if err := r.scaleMachineSet(ctx, oldMS, updatedReplicaCount, deployment); err != nil { return err } } log.V(4).Info("Finished reconcile of Old MachineSets to account for deleted machines. Now analyzing if there's more potential to scale down") for _, oldMS := range oldMSs { + log = log.WithValues("machineSet", klog.KObj(oldMS)) if scaleDownAmount <= 0 { break } if oldMS.Spec.Replicas == nil || *oldMS.Spec.Replicas <= 0 { - log.V(4).Info("Fully scaled down", "MachineSet", oldMS.Name) + log.V(4).Info("Fully scaled down") continue } updatedReplicaCount := *oldMS.Spec.Replicas @@ -151,7 +154,7 @@ func (r *Reconciler) reconcileOldMachineSetsOnDelete(ctx context.Context, oldMSs scaleDownAmount -= updatedReplicaCount updatedReplicaCount = 0 } - log.V(4).Info("Scaling down", "MachineSet", oldMS.Name, "replicas", updatedReplicaCount) + log.V(4).Info("Scaling down", "replicas", updatedReplicaCount) if err := r.scaleMachineSet(ctx, oldMS, updatedReplicaCount, deployment); err != nil { return err } @@ -163,10 +166,11 @@ func (r *Reconciler) reconcileOldMachineSetsOnDelete(ctx context.Context, oldMSs // reconcileNewMachineSetOnDelete handles reconciliation of the latest MachineSet associated with the MachineDeployment in the OnDelete MachineDeploymentStrategyType. func (r *Reconciler) reconcileNewMachineSetOnDelete(ctx context.Context, allMSs []*clusterv1.MachineSet, newMS *clusterv1.MachineSet, deployment *clusterv1.MachineDeployment) error { // logic same as reconcile logic for RollingUpdate - log := ctrl.LoggerFrom(ctx) + log := ctrl.LoggerFrom(ctx, "machineSet", klog.KObj(newMS)) + if newMS.Annotations != nil { if _, ok := newMS.Annotations[clusterv1.DisableMachineCreate]; ok { - log.V(4).Info("removing annotation on latest MachineSet to enable machine creation", "MachineSet", newMS.Name) + log.V(4).Info("removing annotation on latest MachineSet to enable machine creation") patchHelper, err := patch.NewHelper(newMS, r.Client) if err != nil { return err diff --git a/internal/controllers/machinedeployment/mdutil/util.go b/internal/controllers/machinedeployment/mdutil/util.go index 751ad34c0656..bfa88719febc 100644 --- a/internal/controllers/machinedeployment/mdutil/util.go +++ b/internal/controllers/machinedeployment/mdutil/util.go @@ -33,6 +33,7 @@ import ( metav1 "k8s.io/apimachinery/pkg/apis/meta/v1" "k8s.io/apimachinery/pkg/runtime" intstrutil "k8s.io/apimachinery/pkg/util/intstr" + "k8s.io/klog/v2" "k8s.io/utils/integer" clusterv1 "sigs.k8s.io/cluster-api/api/v1beta1" @@ -168,7 +169,7 @@ func getMaxReplicasAnnotation(ms *clusterv1.MachineSet, logger logr.Logger) (int } func getIntFromAnnotation(ms *clusterv1.MachineSet, annotationKey string, logger logr.Logger) (int32, bool) { - logger = logger.WithValues("machineset", ms.Name, "annotationKey", annotationKey) + logger = logger.WithValues("machineSet", klog.KObj(ms)) annotationValue, ok := ms.Annotations[annotationKey] if !ok { @@ -176,7 +177,7 @@ func getIntFromAnnotation(ms *clusterv1.MachineSet, annotationKey string, logger } intValue, err := strconv.ParseInt(annotationValue, 10, 32) if err != nil { - logger.V(2).Info("Cannot convert the value to integer", "annotationValue", annotationValue) + logger.V(2).Info(fmt.Sprintf("Cannot convert annotation %q with value %q to integer", annotationKey, annotationValue)) return int32(0), false } return int32(intValue), true @@ -185,7 +186,7 @@ func getIntFromAnnotation(ms *clusterv1.MachineSet, annotationKey string, logger // SetNewMachineSetAnnotations sets new machine set's annotations appropriately by updating its revision and // copying required deployment annotations to it; it returns true if machine set's annotation is changed. func SetNewMachineSetAnnotations(deployment *clusterv1.MachineDeployment, newMS *clusterv1.MachineSet, newRevision string, exists bool, logger logr.Logger) bool { - logger = logger.WithValues("machineset", newMS.Name) + logger = logger.WithValues("machineSet", klog.KObj(newMS)) // First, copy deployment's annotations (except for apply and revision annotations) annotationChanged := copyDeploymentAnnotationsToMachineSet(deployment, newMS) diff --git a/internal/controllers/machinehealthcheck/machinehealthcheck_controller.go b/internal/controllers/machinehealthcheck/machinehealthcheck_controller.go index be39ea2cc101..fa7bc45df366 100644 --- a/internal/controllers/machinehealthcheck/machinehealthcheck_controller.go +++ b/internal/controllers/machinehealthcheck/machinehealthcheck_controller.go @@ -34,6 +34,7 @@ import ( kerrors "k8s.io/apimachinery/pkg/util/errors" "k8s.io/apimachinery/pkg/util/intstr" "k8s.io/client-go/tools/record" + "k8s.io/klog/v2" ctrl "sigs.k8s.io/controller-runtime" "sigs.k8s.io/controller-runtime/pkg/client" "sigs.k8s.io/controller-runtime/pkg/controller" @@ -132,7 +133,7 @@ func (r *Reconciler) Reconcile(ctx context.Context, req ctrl.Request) (_ ctrl.Re return ctrl.Result{}, err } - log = log.WithValues("cluster", m.Spec.ClusterName) + log = log.WithValues("cluster", klog.KRef(m.Namespace, m.Spec.ClusterName)) ctx = ctrl.LoggerInto(ctx, log) cluster, err := util.GetClusterByName(ctx, r.Client, m.Namespace, m.Spec.ClusterName) diff --git a/internal/controllers/machinehealthcheck/machinehealthcheck_targets.go b/internal/controllers/machinehealthcheck/machinehealthcheck_targets.go index bbe5a54d760e..8a3231fd3036 100644 --- a/internal/controllers/machinehealthcheck/machinehealthcheck_targets.go +++ b/internal/controllers/machinehealthcheck/machinehealthcheck_targets.go @@ -27,6 +27,7 @@ import ( apierrors "k8s.io/apimachinery/pkg/api/errors" metav1 "k8s.io/apimachinery/pkg/apis/meta/v1" "k8s.io/apimachinery/pkg/types" + "k8s.io/klog/v2" "sigs.k8s.io/controller-runtime/pkg/client" clusterv1 "sigs.k8s.io/cluster-api/api/v1beta1" @@ -199,9 +200,10 @@ func (r *Reconciler) getTargetsFromMHC(ctx context.Context, logger logr.Logger, targets := []healthCheckTarget{} for k := range machines { + logger.WithValues("machine", klog.KObj(&machines[k])) skip, reason := shouldSkipRemediation(&machines[k]) if skip { - logger.Info("skipping remediation", "machine", machines[k].Name, "reason", reason) + logger.Info("skipping remediation", "reason", reason) continue } diff --git a/internal/controllers/machineset/machineset_controller.go b/internal/controllers/machineset/machineset_controller.go index 6a4a5a7b1dad..b2d01f2d56df 100644 --- a/internal/controllers/machineset/machineset_controller.go +++ b/internal/controllers/machineset/machineset_controller.go @@ -29,6 +29,7 @@ import ( "k8s.io/apimachinery/pkg/labels" kerrors "k8s.io/apimachinery/pkg/util/errors" "k8s.io/client-go/tools/record" + "k8s.io/klog/v2" ctrl "sigs.k8s.io/controller-runtime" "sigs.k8s.io/controller-runtime/pkg/client" "sigs.k8s.io/controller-runtime/pkg/controller" @@ -135,6 +136,9 @@ func (r *Reconciler) Reconcile(ctx context.Context, req ctrl.Request) (_ ctrl.Re return ctrl.Result{}, err } + log = log.WithValues("cluster", klog.KObj(cluster)) + ctx = ctrl.LoggerInto(ctx, log) + // Return early if the object or Cluster is paused. if annotations.IsPaused(cluster, machineSet) { log.Info("Reconciliation is paused for this object") @@ -253,6 +257,7 @@ func (r *Reconciler) reconcile(ctx context.Context, cluster *clusterv1.Cluster, filteredMachines := make([]*clusterv1.Machine, 0, len(allMachines.Items)) for idx := range allMachines.Items { machine := &allMachines.Items[idx] + log.WithValues("machine", klog.KObj(machine)) if shouldExcludeMachine(machineSet, machine) { continue } @@ -260,11 +265,11 @@ func (r *Reconciler) reconcile(ctx context.Context, cluster *clusterv1.Cluster, // Attempt to adopt machine if it meets previous conditions and it has no controller references. if metav1.GetControllerOf(machine) == nil { if err := r.adoptOrphan(ctx, machineSet, machine); err != nil { - log.Error(err, "Failed to adopt Machine", "machine", machine.Name) + log.Error(err, "Failed to adopt Machine") r.recorder.Eventf(machineSet, corev1.EventTypeWarning, "FailedAdopt", "Failed to adopt Machine %q: %v", machine.Name, err) continue } - log.Info("Adopted Machine", "machine", machine.Name) + log.Info("Adopted Machine") r.recorder.Eventf(machineSet, corev1.EventTypeNormal, "SuccessfulAdopt", "Adopted Machine %q", machine.Name) } @@ -273,13 +278,14 @@ func (r *Reconciler) reconcile(ctx context.Context, cluster *clusterv1.Cluster, var errs []error for _, machine := range filteredMachines { + log.WithValues("machine", klog.KObj(machine)) // filteredMachines contains machines in deleting status to calculate correct status. // skip remediation for those in deleting status. if !machine.DeletionTimestamp.IsZero() { continue } if conditions.IsFalse(machine, clusterv1.MachineOwnerRemediatedCondition) { - log.Info("Deleting unhealthy machine", "machine", machine.GetName()) + log.Info("Deleting unhealthy machine") patch := client.MergeFrom(machine.DeepCopy()) if err := r.Client.Delete(ctx, machine); err != nil { errs = append(errs, errors.Wrap(err, "failed to delete")) @@ -363,6 +369,7 @@ func (r *Reconciler) syncReplicas(ctx context.Context, ms *clusterv1.MachineSet, i+1, diff, *(ms.Spec.Replicas), len(machines))) machine := r.getNewMachine(ms) + log.WithValues("machine", klog.KObj(machine)) // Clone and set the infrastructure and bootstrap references. var ( @@ -413,7 +420,7 @@ func (r *Reconciler) syncReplicas(ctx context.Context, ms *clusterv1.MachineSet, machine.Spec.InfrastructureRef = *infraRef if err := r.Client.Create(ctx, machine); err != nil { - log.Error(err, "Unable to create Machine", "machine", machine.Name) + log.Error(err, "Unable to create Machine") r.recorder.Eventf(ms, corev1.EventTypeWarning, "FailedCreate", "Failed to create machine %q: %v", machine.Name, err) errs = append(errs, err) conditions.MarkFalse(ms, clusterv1.MachinesCreatedCondition, clusterv1.MachineCreationFailedReason, @@ -452,13 +459,14 @@ func (r *Reconciler) syncReplicas(ctx context.Context, ms *clusterv1.MachineSet, var errs []error machinesToDelete := getMachinesToDeletePrioritized(machines, diff, deletePriorityFunc) for _, machine := range machinesToDelete { + log.WithValues("machine", klog.KObj(machine)) if err := r.Client.Delete(ctx, machine); err != nil { - log.Error(err, "Unable to delete Machine", "machine", machine.Name) + log.Error(err, "Unable to delete Machine") r.recorder.Eventf(ms, corev1.EventTypeWarning, "FailedDelete", "Failed to delete machine %q: %v", machine.Name, err) errs = append(errs, err) continue } - log.Info("Deleted machine", "machine", machine.Name) + log.Info("Deleted machine") r.recorder.Eventf(ms, corev1.EventTypeNormal, "SuccessfulDelete", "Deleted machine %q", machine.Name) } @@ -565,9 +573,6 @@ func (r *Reconciler) waitForMachineDeletion(ctx context.Context, machineList []* // MachineToMachineSets is a handler.ToRequestsFunc to be used to enqueue requests for reconciliation // for MachineSets that might adopt an orphaned Machine. func (r *Reconciler) MachineToMachineSets(o client.Object) []ctrl.Request { - ctx := context.Background() - // This won't log unless the global logger is set - log := ctrl.LoggerFrom(ctx, "object", client.ObjectKeyFromObject(o)) result := []ctrl.Request{} m, ok := o.(*clusterv1.Machine) @@ -575,6 +580,10 @@ func (r *Reconciler) MachineToMachineSets(o client.Object) []ctrl.Request { panic(fmt.Sprintf("Expected a Machine but got a %T", o)) } + // This won't log unless the global logger is set + ctx := context.Background() + log := ctrl.LoggerFrom(ctx, "machine", klog.KObj(m)) + // Check if the controller reference is already set and // return an empty result when one is found. for _, ref := range m.ObjectMeta.OwnerReferences { @@ -651,12 +660,14 @@ func (r *Reconciler) updateStatus(ctx context.Context, cluster *clusterv1.Cluste templateLabel := labels.Set(ms.Spec.Template.Labels).AsSelectorPreValidated() for _, machine := range filteredMachines { + log = log.WithValues("machine", klog.KObj(machine)) + if templateLabel.Matches(labels.Set(machine.Labels)) { fullyLabeledReplicasCount++ } if machine.Status.NodeRef == nil { - log.V(2).Info("Unable to retrieve Node status, missing NodeRef", "machine", machine.Name) + log.V(2).Info("Unable to retrieve Node status, missing NodeRef") continue } @@ -690,7 +701,7 @@ func (r *Reconciler) updateStatus(ctx context.Context, cluster *clusterv1.Cluste newStatus.ObservedGeneration = ms.Generation newStatus.DeepCopyInto(&ms.Status) - log.V(4).Info(fmt.Sprintf("Updating status for %v: %s/%s, ", ms.Kind, ms.Namespace, ms.Name) + + log.V(4).Info("Updating status: " + fmt.Sprintf("replicas %d->%d (need %d), ", ms.Status.Replicas, newStatus.Replicas, desiredReplicas) + fmt.Sprintf("fullyLabeledReplicas %d->%d, ", ms.Status.FullyLabeledReplicas, newStatus.FullyLabeledReplicas) + fmt.Sprintf("readyReplicas %d->%d, ", ms.Status.ReadyReplicas, newStatus.ReadyReplicas) + diff --git a/internal/controllers/topology/cluster/cluster_controller.go b/internal/controllers/topology/cluster/cluster_controller.go index 8921981802af..f9a98a2345e0 100644 --- a/internal/controllers/topology/cluster/cluster_controller.go +++ b/internal/controllers/topology/cluster/cluster_controller.go @@ -26,6 +26,7 @@ import ( "k8s.io/apimachinery/pkg/types" kerrors "k8s.io/apimachinery/pkg/util/errors" "k8s.io/client-go/tools/record" + "k8s.io/klog/v2" ctrl "sigs.k8s.io/controller-runtime" "sigs.k8s.io/controller-runtime/pkg/builder" "sigs.k8s.io/controller-runtime/pkg/client" @@ -147,6 +148,9 @@ func (r *Reconciler) Reconcile(ctx context.Context, req ctrl.Request) (_ ctrl.Re cluster.APIVersion = clusterv1.GroupVersion.String() cluster.Kind = "Cluster" + log = log.WithValues("cluster", klog.KObj(cluster)) + ctx = ctrl.LoggerInto(ctx, log) + // Return early, if the Cluster does not use a managed topology. // NOTE: We're already filtering events, but this is a safeguard for cases like e.g. when // there are MachineDeployments which have the topology owned label, but the corresponding diff --git a/internal/log/log.go b/internal/log/log.go index b946000d9b59..53053cd23b78 100644 --- a/internal/log/log.go +++ b/internal/log/log.go @@ -22,10 +22,13 @@ import ( "github.com/go-logr/logr" corev1 "k8s.io/api/core/v1" + metav1 "k8s.io/apimachinery/pkg/apis/meta/v1" + "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" + "sigs.k8s.io/cluster-api/util" ) // LoggerFrom returns a logger with predefined values from a context.Context. @@ -85,9 +88,12 @@ type topologyReconcileLogger struct { func (l *topologyReconcileLogger) WithObject(obj client.Object) Logger { return &topologyReconcileLogger{ Logger: l.Logger.WithValues( - "object groupVersion", obj.GetObjectKind().GroupVersionKind().GroupVersion().String(), - "object kind", obj.GetObjectKind().GroupVersionKind().Kind, - "object", obj.GetName(), + "resource", metav1.GroupVersionResource{ + Version: obj.GetObjectKind().GroupVersionKind().Version, + Group: obj.GetObjectKind().GroupVersionKind().GroupKind().Group, + Resource: obj.GetObjectKind().GroupVersionKind().Kind, + }, + util.LowerCamelCaseKind(obj), klog.KObj(obj), ), } } @@ -97,9 +103,12 @@ func (l *topologyReconcileLogger) WithObject(obj client.Object) Logger { func (l *topologyReconcileLogger) WithRef(ref *corev1.ObjectReference) Logger { return &topologyReconcileLogger{ Logger: l.Logger.WithValues( - "object groupVersion", ref.APIVersion, - "object kind", ref.Kind, - "object", ref.Name, + "resource", metav1.GroupVersionResource{ + Version: ref.GetObjectKind().GroupVersionKind().Version, + Group: ref.GetObjectKind().GroupVersionKind().GroupKind().Group, + Resource: ref.GetObjectKind().GroupVersionKind().Kind, + }, + util.LowerCamelCaseKind(ref), klog.KRef(ref.Namespace, ref.Name), ), } } @@ -109,8 +118,8 @@ func (l *topologyReconcileLogger) WithMachineDeployment(md *clusterv1.MachineDep topologyName := md.Labels[clusterv1.ClusterTopologyMachineDeploymentLabelName] return &topologyReconcileLogger{ Logger: l.Logger.WithValues( - "machineDeployment name", md.GetName(), - "machineDeployment topologyName", topologyName, + "machineDeployment", klog.KObj(md), + "machineDeploymentTopology", topologyName, ), } } diff --git a/test/infrastructure/docker/internal/controllers/dockercluster_controller.go b/test/infrastructure/docker/internal/controllers/dockercluster_controller.go index 189aa401c7e0..b977a963a349 100644 --- a/test/infrastructure/docker/internal/controllers/dockercluster_controller.go +++ b/test/infrastructure/docker/internal/controllers/dockercluster_controller.go @@ -22,6 +22,7 @@ import ( "github.com/pkg/errors" apierrors "k8s.io/apimachinery/pkg/api/errors" + "k8s.io/klog/v2" ctrl "sigs.k8s.io/controller-runtime" "sigs.k8s.io/controller-runtime/pkg/client" "sigs.k8s.io/controller-runtime/pkg/controller" @@ -73,7 +74,8 @@ func (r *DockerClusterReconciler) Reconcile(ctx context.Context, req ctrl.Reques return ctrl.Result{}, nil } - log = log.WithValues("cluster", cluster.Name) + log = log.WithValues("cluster", klog.KObj(cluster)) + ctx = ctrl.LoggerInto(ctx, log) // Create a helper for managing a docker container hosting the loadbalancer. externalLoadBalancer, err := docker.NewLoadBalancer(ctx, cluster, dockerCluster) diff --git a/test/infrastructure/docker/internal/controllers/dockermachine_controller.go b/test/infrastructure/docker/internal/controllers/dockermachine_controller.go index a727a5150e32..20c9bbbf7448 100644 --- a/test/infrastructure/docker/internal/controllers/dockermachine_controller.go +++ b/test/infrastructure/docker/internal/controllers/dockermachine_controller.go @@ -25,6 +25,7 @@ import ( "github.com/pkg/errors" corev1 "k8s.io/api/core/v1" apierrors "k8s.io/apimachinery/pkg/api/errors" + "k8s.io/klog/v2" ctrl "sigs.k8s.io/controller-runtime" "sigs.k8s.io/controller-runtime/pkg/client" "sigs.k8s.io/controller-runtime/pkg/controller" @@ -82,7 +83,8 @@ func (r *DockerMachineReconciler) Reconcile(ctx context.Context, req ctrl.Reques return ctrl.Result{}, nil } - log = log.WithValues("machine", machine.Name) + log = log.WithValues("machine", klog.KObj(machine)) + ctx = ctrl.LoggerInto(ctx, log) // Fetch the Cluster. cluster, err := util.GetClusterFromMetadata(ctx, r.Client, machine.ObjectMeta) @@ -95,7 +97,8 @@ func (r *DockerMachineReconciler) Reconcile(ctx context.Context, req ctrl.Reques return ctrl.Result{}, nil } - log = log.WithValues("cluster", cluster.Name) + log = log.WithValues("cluster", klog.KObj(cluster)) + ctx = ctrl.LoggerInto(ctx, log) // Return early if the object or Cluster is paused. if annotations.IsPaused(cluster, dockerMachine) { @@ -114,8 +117,6 @@ func (r *DockerMachineReconciler) Reconcile(ctx context.Context, req ctrl.Reques return ctrl.Result{}, nil } - log = log.WithValues("docker-cluster", dockerCluster.Name) - // Initialize the patch helper patchHelper, err := patch.NewHelper(dockerMachine, r) if err != nil { diff --git a/test/infrastructure/docker/internal/docker/loadbalancer.go b/test/infrastructure/docker/internal/docker/loadbalancer.go index badf1079d870..e29e16310adc 100644 --- a/test/infrastructure/docker/internal/docker/loadbalancer.go +++ b/test/infrastructure/docker/internal/docker/loadbalancer.go @@ -107,7 +107,7 @@ func (s *LoadBalancer) containerName() string { // Create creates a docker container hosting a load balancer for the cluster. func (s *LoadBalancer) Create(ctx context.Context) error { log := ctrl.LoggerFrom(ctx) - log = log.WithValues("cluster", s.name, "ipFamily", s.ipFamily) + log = log.WithValues("ipFamily", s.ipFamily, "loadbalancer", s.name) listenAddr := "0.0.0.0" if s.ipFamily == clusterv1.IPv6IPFamily { diff --git a/util/predicates/cluster_predicates.go b/util/predicates/cluster_predicates.go index 0f2c29d5909b..e636a44d2994 100644 --- a/util/predicates/cluster_predicates.go +++ b/util/predicates/cluster_predicates.go @@ -21,6 +21,7 @@ import ( "fmt" "github.com/go-logr/logr" + "k8s.io/klog/v2" "sigs.k8s.io/controller-runtime/pkg/client" "sigs.k8s.io/controller-runtime/pkg/event" "sigs.k8s.io/controller-runtime/pkg/predicate" @@ -41,7 +42,7 @@ func ClusterCreateInfraReady(logger logr.Logger) predicate.Funcs { log.V(4).Info("Expected Cluster", "type", fmt.Sprintf("%T", e.Object)) return false } - log = log.WithValues("namespace", c.Namespace, "cluster", c.Name) + log = log.WithValues("cluster", klog.KObj(c)) // Only need to trigger a reconcile if the Cluster.Status.InfrastructureReady is true if c.Status.InfrastructureReady { @@ -70,7 +71,7 @@ func ClusterCreateNotPaused(logger logr.Logger) predicate.Funcs { log.V(4).Info("Expected Cluster", "type", fmt.Sprintf("%T", e.Object)) return false } - log = log.WithValues("namespace", c.Namespace, "cluster", c.Name) + log = log.WithValues("cluster", klog.KObj(c)) // Only need to trigger a reconcile if the Cluster.Spec.Paused is false if !c.Spec.Paused { @@ -99,7 +100,7 @@ func ClusterUpdateInfraReady(logger logr.Logger) predicate.Funcs { log.V(4).Info("Expected Cluster", "type", fmt.Sprintf("%T", e.ObjectOld)) return false } - log = log.WithValues("namespace", oldCluster.Namespace, "cluster", oldCluster.Name) + log = log.WithValues("cluster", klog.KObj(oldCluster)) newCluster := e.ObjectNew.(*clusterv1.Cluster) @@ -129,7 +130,7 @@ func ClusterUpdateUnpaused(logger logr.Logger) predicate.Funcs { log.V(4).Info("Expected Cluster", "type", fmt.Sprintf("%T", e.ObjectOld)) return false } - log = log.WithValues("namespace", oldCluster.Namespace, "cluster", oldCluster.Name) + log = log.WithValues("cluster", klog.KObj(oldCluster)) newCluster := e.ObjectNew.(*clusterv1.Cluster) @@ -188,7 +189,7 @@ func ClusterControlPlaneInitialized(logger logr.Logger) predicate.Funcs { log.V(4).Info("Expected Cluster", "type", fmt.Sprintf("%T", e.ObjectOld)) return false } - log = log.WithValues("namespace", oldCluster.Namespace, "cluster", oldCluster.Name) + log = log.WithValues("cluster", klog.KObj(oldCluster)) newCluster := e.ObjectNew.(*clusterv1.Cluster) @@ -259,7 +260,7 @@ func processIfTopologyManaged(logger logr.Logger, object client.Object) bool { return false } - log := logger.WithValues("namespace", cluster.Namespace, "cluster", cluster.Name) + log := logger.WithValues("cluster", klog.KObj(cluster)) if cluster.Spec.Topology != nil { log.V(6).Info("Cluster has topology, allowing further processing") diff --git a/util/util.go b/util/util.go index 4836d7afcba4..707cce3be031 100644 --- a/util/util.go +++ b/util/util.go @@ -604,3 +604,13 @@ func IsNil(i interface{}) bool { } return false } + +// LowerCamelCaseKind mirrors how controller runtime formats the object's kind when used as a logging key +// for the object being reconciled. +func LowerCamelCaseKind(obj runtime.Object) string { + kind := obj.GetObjectKind().GroupVersionKind().Kind + if kind != "" { + return strings.ToLower(kind[:1]) + kind[1:] + } + return "" +}