Bug 2019532: Logger object in LSO does not log source location accurately

common/provisioner_utils.go

@@ -6,14 +6,13 @@ import (
 	"hash/fnv"
 	"path/filepath"
 
-	"github.com/go-logr/logr"
 	corev1 "k8s.io/api/core/v1"
 	storagev1 "k8s.io/api/storage/v1"
 	"k8s.io/apimachinery/pkg/api/meta"
 	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
 	"k8s.io/apimachinery/pkg/runtime"
 	"k8s.io/apimachinery/pkg/util/sets"
-	"k8s.io/klog"
+	"k8s.io/klog/v2"
 	"sigs.k8s.io/controller-runtime/pkg/client"
 	"sigs.k8s.io/controller-runtime/pkg/controller/controllerutil"
 
@@ -43,7 +42,6 @@ func CreateLocalPV(
 	obj runtime.Object,
 	runtimeConfig *provCommon.RuntimeConfig,
 	cleanupTracker *provDeleter.CleanupStatusTracker,
-	devLogger logr.Logger,
 	storageClass storagev1.StorageClass,
 	mountPointMap sets.String,
 	client client.Client,
@@ -61,8 +59,6 @@ func CreateLocalPV(
 
 	pvName := GeneratePVName(filepath.Base(symLinkPath), runtimeConfig.Node.Name, storageClass.Name)
 
-	pvLogger := devLogger.WithValues("pv.Name", pvName)
-
 	nodeAffinity := &corev1.VolumeNodeAffinity{
 		Required: &corev1.NodeSelector{
 			NodeSelectorTerms: []corev1.NodeSelectorTerm{
@@ -92,13 +88,13 @@ func CreateLocalPV(
 	}
 
 	if cleanupTracker.InProgress(pvName, useJob) {
-		pvLogger.Info("PV is still being cleaned, not going to recreate it")
+		klog.InfoS("PV is still being cleaned, not going to recreate it", "pvName", pvName)
 		return nil
 	}
 
 	_, _, err = cleanupTracker.RemoveStatus(pvName, useJob)
 	if err != nil {
-		pvLogger.Error(err, "expected status exists and fail to remove cleanup status")
+		klog.ErrorS(err, "failed to remove cleanup status for PV", "pvName", pvName)
 		return err
 	}
 
@@ -162,7 +158,8 @@ func CreateLocalPV(
 
 	var reclaimPolicy corev1.PersistentVolumeReclaimPolicy
 	if storageClass.ReclaimPolicy == nil {
-		devLogger.Error(fmt.Errorf("no ReclaimPolicy set in storageclass"), "defaulting to delete")
+		klog.InfoS("no ReclaimPolicy set in storageclass, defaulting to delete",
+			"storageClass", storageClass.Name)
 		reclaimPolicy = corev1.PersistentVolumeReclaimDelete
 	} else {
 		reclaimPolicy = *storageClass.ReclaimPolicy
@@ -194,7 +191,7 @@ func CreateLocalPV(
 
 	existingPV := &corev1.PersistentVolume{ObjectMeta: metav1.ObjectMeta{Name: pvName}}
 
-	pvLogger.Info("creating")
+	klog.InfoS("creating PV", "pvName", pvName)
 	opRes, err := controllerutil.CreateOrUpdate(context.TODO(), client, existingPV, func() error {
 		if existingPV.CreationTimestamp.IsZero() {
 			// operations for create
@@ -205,8 +202,8 @@ func CreateLocalPV(
 		// pv object says block, but the path is fs (the oppposite is fine)
 		if existingPV.Spec.VolumeMode != nil &&
 			*existingPV.Spec.VolumeMode == corev1.PersistentVolumeBlock && actualVolumeMode == corev1.PersistentVolumeFilesystem {
-			err := fmt.Errorf("incorrect Volume Mode: PV requires block mode but path was in fs mode")
-			pvLogger.Error(err, "pvName", pvName, "filePath", symLinkPath)
+			err := fmt.Errorf("PV requires block mode but path was in fs mode")
+			klog.ErrorS(err, "incorrect VolumeMode", "pvName", pvName, "symLinkPath", symLinkPath)
 			runtimeConfig.Recorder.Eventf(existingPV, corev1.EventTypeWarning, provCommon.EventVolumeFailedDelete, err.Error())
 		}
 
@@ -233,7 +230,7 @@ func CreateLocalPV(
 		return nil
 	})
 	if opRes != controllerutil.OperationResultNone {
-		pvLogger.Info("pv changed", "operation", opRes)
+		klog.InfoS("PV changed", "pvName", pvName, "status", opRes)
 	}
 
 	return err

controllers/localvolume/api_updater.go

@@ -16,7 +16,7 @@ import (
 	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
 	"k8s.io/client-go/kubernetes"
 	"k8s.io/client-go/tools/record"
-	"k8s.io/klog"
+	"k8s.io/klog/v2"
 	"sigs.k8s.io/controller-runtime/pkg/client"
 	"sigs.k8s.io/controller-runtime/pkg/manager"
 )

controllers/localvolume/localvolume_controller.go

@@ -24,8 +24,8 @@ import (
 	"k8s.io/apimachinery/pkg/labels"
 	"k8s.io/apimachinery/pkg/types"
 	"k8s.io/apimachinery/pkg/util/sets"
+	"k8s.io/klog/v2"
 
-	"github.com/go-logr/logr"
 	operatorv1 "github.com/openshift/api/operator/v1"
 	"github.com/openshift/library-go/pkg/operator/resource/resourceread"
 	localv1 "github.com/openshift/local-storage-operator/api/v1"
@@ -67,7 +67,6 @@ type LocalVolumeReconciler struct {
 	apiClient         apiUpdater
 	LvMap             *common.StorageClassOwnerMap
 	controllerVersion string
-	Log               logr.Logger
 }
 
 func (r *LocalVolumeReconciler) deregisterLVFromStorageClass(lv localv1.LocalVolume) {
@@ -89,16 +88,15 @@ func (r *LocalVolumeReconciler) deregisterLVFromStorageClass(lv localv1.LocalVol
 //+kubebuilder:rbac:groups=config.openshift.io,resources=infrastructures,verbs=get;list;watch
 
 func (r *LocalVolumeReconciler) Reconcile(ctx context.Context, request ctrl.Request) (ctrl.Result, error) {
-	logger := r.Log.WithValues("request.Namespace", request.Namespace, "Request.Name", request.Name)
-	logger.Info("Reconciling LocalVolume")
+	klog.InfoS("Reconciling LocalVolume", "namespace", request.Namespace, "name", request.Name)
 	localStorageProvider := &localv1.LocalVolume{}
 
 	err := r.Client.Get(ctx, request.NamespacedName, localStorageProvider)
 	if err != nil {
 		if errors.IsNotFound(err) {
 			r.deregisterLVFromStorageClass(*localStorageProvider)
 			// Requested object not found, could have been deleted after reconcile request.
-			logger.Info("requested LocalVolume CR is not found, could have been deleted after the reconcile request")
+			klog.Info("requested LocalVolume CR is not found, could have been deleted after the reconcile request")
 			return ctrl.Result{}, nil
 		}
 		return ctrl.Result{Requeue: true}, err
@@ -131,7 +129,7 @@ func (r *LocalVolumeReconciler) syncLocalVolumeProvider(ctx context.Context, ins
 	}
 
 	if o.Spec.ManagementState != operatorv1.Managed && o.Spec.ManagementState != operatorv1.Force {
-		r.Log.Info("operator is not managing local volumes ", "ManagementState", o.Spec.ManagementState)
+		klog.InfoS("operator is not managing local volumes", "ManagementState", o.Spec.ManagementState)
 		o.Status.State = o.Spec.ManagementState
 		err = r.apiClient.syncStatus(instance, o)
 		if err != nil {
@@ -142,7 +140,7 @@ func (r *LocalVolumeReconciler) syncLocalVolumeProvider(ctx context.Context, ins
 
 	err = r.syncStorageClass(ctx, o)
 	if err != nil {
-		r.Log.Error(err, "failed to create storageClass")
+		klog.ErrorS(err, "failed to create storageClass")
 		return r.addFailureCondition(instance, o, err)
 	}
 
@@ -152,7 +150,7 @@ func (r *LocalVolumeReconciler) syncLocalVolumeProvider(ctx context.Context, ins
 	key := types.NamespacedName{Name: nodedaemon.DiskMakerName, Namespace: o.ObjectMeta.Namespace}
 	err = r.Client.Get(ctx, key, diskMakerDS)
 	if err != nil {
-		r.Log.Error(err, "failed to fetch diskmaker daemonset")
+		klog.ErrorS(err, "failed to fetch diskmaker daemonset")
 		return r.addFailureCondition(instance, o, err)
 	}
 
@@ -172,7 +170,7 @@ func (r *LocalVolumeReconciler) syncLocalVolumeProvider(ctx context.Context, ins
 	o.Status.ObservedGeneration = &o.Generation
 	err = r.apiClient.syncStatus(instance, o)
 	if err != nil {
-		r.Log.Error(err, "error syncing status")
+		klog.ErrorS(err, "error syncing status")
 		return fmt.Errorf("error syncing status: %v", err)
 	}
 	return nil
@@ -190,7 +188,7 @@ func (r *LocalVolumeReconciler) addFailureCondition(oldLv *localv1.LocalVolume,
 	lv.Status.Conditions = newConditions
 	syncErr := r.apiClient.syncStatus(oldLv, lv)
 	if syncErr != nil {
-		r.Log.Error(syncErr, "error syncing condition")
+		klog.ErrorS(syncErr, "error syncing condition")
 	}
 	return err
 }
@@ -217,7 +215,7 @@ func (r *LocalVolumeReconciler) addSuccessCondition(lv *localv1.LocalVolume) *lo
 }
 
 func (r *LocalVolumeReconciler) cleanupLocalVolumeDeployment(ctx context.Context, lv *localv1.LocalVolume) error {
-	r.Log.Info("Deleting localvolume ", "Namespace-Name", commontypes.LocalVolumeKey(lv))
+	klog.InfoS("Deleting localvolume", "Namespace-Name", commontypes.LocalVolumeKey(lv))
 	boundPVs, releasedPVs, err := commontypes.GetBoundAndReleasedPVs(lv, r.Client)
 	if err != nil {
 		msg := fmt.Sprintf("error listing persistent volumes for localvolume %s: %v", commontypes.LocalVolumeKey(lv), err)
@@ -233,7 +231,7 @@ func (r *LocalVolumeReconciler) cleanupLocalVolumeDeployment(ctx context.Context
 			pvNames += fmt.Sprintf(" %v", pv.Name)
 		}
 
-		r.Log.Info("bound/released PVs found, not removing finalizer ", "PVNames", pvNames)
+		klog.InfoS("bound/released PVs found, not removing finalizer", "pvNames", pvNames)
 		msg := fmt.Sprintf("localvolume %s has bound/released persistentvolumes in use", commontypes.LocalVolumeKey(lv))
 		r.apiClient.recordEvent(lv, corev1.EventTypeWarning, localVolumeDeletionFailed, msg)
 		return fmt.Errorf(msg)
@@ -268,7 +266,7 @@ func (r *LocalVolumeReconciler) syncStorageClass(ctx context.Context, cr *localv
 	removeErrors := r.removeUnExpectedStorageClasses(ctx, cr, expectedStorageClasses)
 	// For now we will ignore errors while removing unexpected storageClasses
 	if removeErrors != nil {
-		r.Log.Error(removeErrors, "error removing unexpected storageclasses ")
+		klog.ErrorS(removeErrors, "error removing unexpected storageclasses")
 	}
 	return nil
 }
@@ -281,7 +279,7 @@ func (r *LocalVolumeReconciler) removeUnExpectedStorageClasses(ctx context.Conte
 	removeErrors := []error{}
 	for _, sc := range list.Items {
 		if !expectedStorageClasses.Has(sc.Name) {
-			r.Log.Info("removing storageClass ", "StorageClass Name", sc.Name)
+			klog.InfoS("removing storageClass", "scName", sc.Name)
 			scDeleteErr := r.Client.Delete(ctx, sc.DeepCopy())
 			if scDeleteErr != nil && !errors.IsNotFound(scDeleteErr) {
 				removeErrors = append(removeErrors, fmt.Errorf("error deleting storageclass %s: %v", sc.Name, scDeleteErr))

controllers/localvolumediscovery/localvolumediscovery_controller.go

@@ -21,7 +21,6 @@ import (
 	"fmt"
 	"time"
 
-	"github.com/go-logr/logr"
 	operatorv1 "github.com/openshift/api/operator/v1"
 	"github.com/openshift/library-go/pkg/operator/resource/resourceread"
 	"github.com/openshift/local-storage-operator/assets"
@@ -34,6 +33,7 @@ import (
 	"k8s.io/apimachinery/pkg/runtime"
 	"k8s.io/apimachinery/pkg/types"
 	v1helper "k8s.io/component-helpers/scheduling/corev1"
+	"k8s.io/klog/v2"
 	ctrl "sigs.k8s.io/controller-runtime"
 	"sigs.k8s.io/controller-runtime/pkg/client"
 	"sigs.k8s.io/controller-runtime/pkg/controller/controllerutil"
@@ -59,16 +59,14 @@ type LocalVolumeDiscoveryReconciler struct {
 	// that reads objects from the cache and writes to the apiserver
 	Client client.Client
 	Scheme *runtime.Scheme
-	Log    logr.Logger
 }
 
 // Reconcile reads that state of the cluster for a LocalVolumeDiscovery object and makes changes based on the state read
 // and what is in the LocalVolumeDiscovery.Spec
 // The Controller will requeue the Request to be processed again if the returned error is non-nil or
 // Result.Requeue is true, otherwise upon completion it will remove the work from the queue.
 func (r *LocalVolumeDiscoveryReconciler) Reconcile(ctx context.Context, request ctrl.Request) (ctrl.Result, error) {
-	discoveryLogger := r.Log.WithValues("Request.Namespace", request.Namespace, "Request.Name", request.Name)
-	discoveryLogger.Info("Reconciling LocalVolumeDiscovery")
+	klog.InfoS("Reconciling LocalVolumeDiscovery", "namespace", request.Namespace, "name", request.Name)
 
 	// Fetch the LocalVolumeDiscovery instance
 	instance := &localv1alpha1.LocalVolumeDiscovery{}
@@ -89,7 +87,7 @@ func (r *LocalVolumeDiscoveryReconciler) Reconcile(ctx context.Context, request
 	metricsExportor := localmetrics.NewExporter(ctx, r.Client, common.DiscoveryServiceName, instance.Namespace, common.DiscoveryMetricsServingCert,
 		getOwnerRefs(instance), serviceLabels)
 	if err := metricsExportor.EnableMetricsExporter(); err != nil {
-		discoveryLogger.Error(err, "failed to create service and servicemonitors", "object", instance.Name)
+		klog.ErrorS(err, "failed to create service and servicemonitors", "object", instance.Name)
 		return ctrl.Result{}, err
 	}
 
@@ -106,12 +104,12 @@ func (r *LocalVolumeDiscoveryReconciler) Reconcile(ctx context.Context, request
 			return ctrl.Result{}, err
 		}
 	} else if opResult == controllerutil.OperationResultUpdated || opResult == controllerutil.OperationResultCreated {
-		discoveryLogger.Info("daemonset changed", "daemonset.Name", ds.GetName(), "op.Result", opResult)
+		klog.InfoS("daemonset changed", "daemonset.Name", ds.GetName(), "op.Result", opResult)
 	}
 
 	desiredDaemons, readyDaemons, err := r.getDaemonSetStatus(ctx, instance.Namespace)
 	if err != nil {
-		discoveryLogger.Error(err, "failed to get discovery daemonset")
+		klog.ErrorS(err, "failed to get discovery daemonset")
 		return ctrl.Result{}, err
 	}
 
@@ -131,7 +129,7 @@ func (r *LocalVolumeDiscoveryReconciler) Reconcile(ctx context.Context, request
 		if err != nil {
 			return ctrl.Result{}, err
 		}
-		discoveryLogger.Info(message)
+		klog.Info(message)
 		return waitForRequeueIfDaemonsNotReady, nil
 	}
 
@@ -142,10 +140,10 @@ func (r *LocalVolumeDiscoveryReconciler) Reconcile(ctx context.Context, request
 		return ctrl.Result{}, err
 	}
 
-	discoveryLogger.Info("deleting orphan discovery result instances")
+	klog.Info("deleting orphan discovery result instances")
 	err = r.deleteOrphanDiscoveryResults(ctx, instance)
 	if err != nil {
-		discoveryLogger.Error(err, "failed to delete orphan discovery results")
+		klog.ErrorS(err, "failed to delete orphan discovery results")
 		return ctrl.Result{}, err
 	}
 
@@ -215,7 +213,7 @@ func (r *LocalVolumeDiscoveryReconciler) updateDiscoveryStatus(ctx context.Conte
 
 func (r *LocalVolumeDiscoveryReconciler) deleteOrphanDiscoveryResults(ctx context.Context, instance *localv1alpha1.LocalVolumeDiscovery) error {
 	if instance.Spec.NodeSelector == nil || len(instance.Spec.NodeSelector.NodeSelectorTerms) == 0 {
-		r.Log.Info("skip deleting orphan discovery results as no NodeSelectors are provided")
+		klog.Info("skip deleting orphan discovery results as no NodeSelectors are provided")
 		return nil
 	}
 

controllers/localvolumediscovery/localvolumediscovery_controller_test.go

@@ -16,7 +16,6 @@ import (
 	ctrl "sigs.k8s.io/controller-runtime"
 	"sigs.k8s.io/controller-runtime/pkg/client"
 	"sigs.k8s.io/controller-runtime/pkg/client/fake"
-	logf "sigs.k8s.io/controller-runtime/pkg/log"
 	"sigs.k8s.io/controller-runtime/pkg/reconcile"
 )
 
@@ -134,7 +133,6 @@ func newFakeLocalVolumeDiscoveryReconciler(t *testing.T, objs ...runtime.Object)
 	return &LocalVolumeDiscoveryReconciler{
 		Client: client,
 		Scheme: scheme,
-		Log:    logf.Log.WithName("controller_localvolumediscovery_test"),
 	}
 }
 

controllers/localvolumeset/finalizer.go

@@ -7,6 +7,7 @@ import (
 	localv1alpha1 "github.com/openshift/local-storage-operator/api/v1alpha1"
 	"github.com/openshift/local-storage-operator/common"
 	"k8s.io/apimachinery/pkg/api/equality"
+	"k8s.io/klog/v2"
 	"sigs.k8s.io/controller-runtime/pkg/controller/controllerutil"
 )
 
@@ -18,7 +19,7 @@ func (r *LocalVolumeSetReconciler) syncFinalizer(lvSet localv1alpha1.LocalVolume
 
 	// handle deletion
 	if !lvSet.DeletionTimestamp.IsZero() {
-		r.Log.Info("deletionTimeStamp found, waiting for 0 bound PVs")
+		klog.Info("deletionTimeStamp found, waiting for 0 bound PVs")
 		// if obect is deleted, finalizer should be unset only when no boundPVs are found
 		boundPVs, releasedPVs, err := common.GetBoundAndReleasedPVs(&lvSet, r.Client)
 		if err != nil {
@@ -29,7 +30,7 @@ func (r *LocalVolumeSetReconciler) syncFinalizer(lvSet localv1alpha1.LocalVolume
 		pendingPVs := append(boundPVs, releasedPVs...)
 		if len(pendingPVs) == 0 {
 			setFinalizer = false
-			r.Log.Info("no bound/released PVs found, removing finalizer")
+			klog.Info("no bound/released PVs found, removing finalizer")
 		} else {
 			pvNames := ""
 			for i, pv := range pendingPVs {
@@ -40,7 +41,7 @@ func (r *LocalVolumeSetReconciler) syncFinalizer(lvSet localv1alpha1.LocalVolume
 					break
 				}
 			}
-			r.Log.Info("bound/released PVs found, not removing finalizer", "pvNames", pvNames)
+			klog.InfoS("bound/released PVs found, not removing finalizer", "pvNames", pvNames)
 		}
 	}