Add contextual logging for work agent

Signed-off-by: Jian Qiu <[email protected]>

Author: qiujian16

pkg/work/helper/helper_test.go

@@ -8,7 +8,6 @@ import (
 	"testing"
 
 	"github.com/google/go-cmp/cmp"
-	"github.com/openshift/library-go/pkg/operator/events/eventstesting"
 	corev1 "k8s.io/api/core/v1"
 	"k8s.io/apimachinery/pkg/api/equality"
 	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
@@ -342,7 +341,7 @@ func TestDeleteAppliedResourcess(t *testing.T) {
 	for _, c := range cases {
 		t.Run(c.name, func(t *testing.T) {
 			fakeDynamicClient := fakedynamic.NewSimpleDynamicClient(scheme, c.existingResources...)
-			actual, err := DeleteAppliedResources(context.TODO(), c.resourcesToRemove, "testing", fakeDynamicClient, eventstesting.NewTestingEventRecorder(t), c.owner)
+			actual, err := DeleteAppliedResources(context.TODO(), c.resourcesToRemove, "testing", fakeDynamicClient, c.owner)
 			if err != nil {
 				t.Errorf("unexpected err: %v", err)
 			}

pkg/work/helper/helpers.go

@@ -11,7 +11,6 @@ import (
 	"time"
 
 	"github.com/openshift/library-go/pkg/controller/factory"
-	"github.com/openshift/library-go/pkg/operator/events"
 	"github.com/openshift/library-go/pkg/operator/resource/resourcehelper"
 	"github.com/openshift/library-go/pkg/operator/resource/resourcemerge"
 	apiextensionsv1 "k8s.io/apiextensions-apiserver/pkg/apis/apiextensions/v1"
@@ -169,11 +168,12 @@ func DeleteAppliedResources(
 	resources []workapiv1.AppliedManifestResourceMeta,
 	reason string,
 	dynamicClient dynamic.Interface,
-	recorder events.Recorder,
 	owner metav1.OwnerReference) ([]workapiv1.AppliedManifestResourceMeta, []error) {
 	var resourcesPendingFinalization []workapiv1.AppliedManifestResourceMeta
 	var errs []error
 
+	logger := klog.FromContext(ctx)
+
 	// set owner to be removed
 	ownerCopy := owner.DeepCopy()
 	ownerCopy.UID = types.UID(fmt.Sprintf("%s-", owner.UID))
@@ -190,7 +190,8 @@ func DeleteAppliedResources(
 			Namespace(resource.Namespace).
 			Get(ctx, resource.Name, metav1.GetOptions{})
 		if errors.IsNotFound(err) {
-			klog.Infof("Resource %v with key %s/%s is removed Successfully", gvr, resource.Namespace, resource.Name)
+			logger.Info("Resource is removed Successfully",
+				"gvr", gvr, "resourceNamespace", resource.Namespace, "resourceName", resource.Name)
 			continue
 		}
 
@@ -256,7 +257,8 @@ func DeleteAppliedResources(
 		}
 
 		resourcesPendingFinalization = append(resourcesPendingFinalization, resource)
-		recorder.Eventf("ResourceDeleted", "Deleted resource %v with key %s/%s because %s.", gvr, resource.Namespace, resource.Name, reason)
+		logger.Info("Deleted resource",
+			"gvr", gvr, "resourceNamespace", resource.Namespace, "resourceName", resource.Name, "reason", reason)
 	}
 
 	return resourcesPendingFinalization, errs
@@ -409,6 +411,8 @@ func FindManifestCondition(resourceMeta workapiv1.ManifestResourceMeta, manifest
 
 func ApplyOwnerReferences(ctx context.Context, dynamicClient dynamic.Interface, gvr schema.GroupVersionResource,
 	existing runtime.Object, requiredOwner metav1.OwnerReference) error {
+	logger := klog.FromContext(ctx)
+
 	accessor, err := meta.Accessor(existing)
 	if err != nil {
 		return fmt.Errorf("type %t cannot be accessed: %v", existing, err)
@@ -432,7 +436,8 @@ func ApplyOwnerReferences(ctx context.Context, dynamicClient dynamic.Interface,
 		return err
 	}
 
-	klog.V(2).Infof("Patching resource %v %s/%s with patch %s", gvr, accessor.GetNamespace(), accessor.GetName(), string(patchData))
+	logger.V(2).Info("Patching resource",
+		"gvr", gvr, "resourceNamespace", accessor.GetNamespace(), "resourceName", accessor.GetName(), "patch", string(patchData))
 	_, err = dynamicClient.Resource(gvr).Namespace(accessor.GetNamespace()).Patch(ctx, accessor.GetName(), types.MergePatchType, patchData, metav1.PatchOptions{})
 	return err
 }

pkg/work/spoke/apply/create_only_apply.go

@@ -2,7 +2,6 @@ package apply
 
 import (
 	"context"
-	"fmt"
 
 	"github.com/openshift/library-go/pkg/operator/events"
 	"github.com/openshift/library-go/pkg/operator/resource/resourcemerge"
@@ -12,6 +11,7 @@ import (
 	"k8s.io/apimachinery/pkg/runtime"
 	"k8s.io/apimachinery/pkg/runtime/schema"
 	"k8s.io/client-go/dynamic"
+	"k8s.io/klog/v2"
 
 	workapiv1 "open-cluster-management.io/api/work/v1"
 
@@ -31,8 +31,9 @@ func (c *CreateOnlyApply) Apply(ctx context.Context,
 	required *unstructured.Unstructured,
 	owner metav1.OwnerReference,
 	_ *workapiv1.ManifestConfigOption,
-	recorder events.Recorder) (runtime.Object, error) {
+	_ events.Recorder) (runtime.Object, error) {
 
+	logger := klog.FromContext(ctx)
 	obj, err := c.client.
 		Resource(gvr).
 		Namespace(required.GetNamespace()).
@@ -42,8 +43,8 @@ func (c *CreateOnlyApply) Apply(ctx context.Context,
 		obj, err = c.client.Resource(gvr).Namespace(required.GetNamespace()).Create(
 			ctx, resourcemerge.WithCleanLabelsAndAnnotations(required).(*unstructured.Unstructured), metav1.CreateOptions{})
 		if err != nil {
-			recorder.Eventf(fmt.Sprintf(
-				"%s Created", required.GetKind()), "Created %s/%s because it was missing", required.GetNamespace(), required.GetName())
+			logger.Info("Resource created because of missing",
+				"kind", required.GetKind(), "resourceNamespace", required.GetNamespace(), "resourceName", required.GetName())
 		}
 	}
 

pkg/work/spoke/apply/read_only_apply.go

@@ -2,13 +2,13 @@ package apply
 
 import (
 	"context"
-	"fmt"
 
 	"github.com/openshift/library-go/pkg/operator/events"
 	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
 	"k8s.io/apimachinery/pkg/apis/meta/v1/unstructured"
 	"k8s.io/apimachinery/pkg/runtime"
 	"k8s.io/apimachinery/pkg/runtime/schema"
+	"k8s.io/klog/v2"
 
 	workapiv1 "open-cluster-management.io/api/work/v1"
 )
@@ -24,9 +24,9 @@ func (c *ReadOnlyApply) Apply(ctx context.Context,
 	required *unstructured.Unstructured,
 	_ metav1.OwnerReference,
 	_ *workapiv1.ManifestConfigOption,
-	recorder events.Recorder) (runtime.Object, error) {
-
-	recorder.Eventf(fmt.Sprintf(
-		"%s noop", required.GetKind()), "Noop for %s/%s because its read-only", required.GetNamespace(), required.GetName())
+	_ events.Recorder) (runtime.Object, error) {
+	logger := klog.FromContext(ctx)
+	logger.Info("Noop because its read-only",
+		"kind", required.GetKind(), "resourceNamespace", required.GetNamespace(), "resourceName", required.GetName())
 	return required, nil
 }

pkg/work/spoke/apply/server_side_apply.go

@@ -14,7 +14,6 @@ import (
 	"k8s.io/apimachinery/pkg/runtime"
 	"k8s.io/apimachinery/pkg/runtime/schema"
 	"k8s.io/client-go/dynamic"
-	"k8s.io/client-go/tools/cache"
 	"k8s.io/client-go/util/jsonpath"
 	"k8s.io/klog/v2"
 
@@ -45,7 +44,7 @@ func (c *ServerSideApply) Apply(
 	requiredOriginal *unstructured.Unstructured,
 	owner metav1.OwnerReference,
 	applyOption *workapiv1.ManifestConfigOption,
-	recorder events.Recorder) (runtime.Object, error) {
+	_ events.Recorder) (runtime.Object, error) {
 	logger := klog.FromContext(ctx)
 	// Currently, if the required object has zero creationTime in metadata, it will cause
 	// kube-apiserver to increment generation even if nothing else changes. more details see:
@@ -114,10 +113,9 @@ func (c *ServerSideApply) Apply(
 		Resource(gvr).
 		Namespace(required.GetNamespace()).
 		Apply(ctx, required.GetName(), required, metav1.ApplyOptions{FieldManager: fieldManager, Force: force})
-	resourceKey, _ := cache.MetaNamespaceKeyFunc(required)
-	recorder.Eventf(fmt.Sprintf(
-		"Server Side Applied %s %s", required.GetKind(), resourceKey),
-		"Patched with field manager %s, err %v", fieldManager, err)
+	logger.Info("Server side applied",
+		"kind", required.GetKind(), "resourceNamespace", required.GetNamespace(),
+		"resourceName", required.GetName(), "fieldManager", fieldManager)
 
 	if errors.IsConflict(err) {
 		return obj, &ServerSideApplyConflictError{ssaErr: err}

pkg/work/spoke/apply/update_apply.go

@@ -2,7 +2,6 @@ package apply
 
 import (
 	"context"
-	"fmt"
 	"reflect"
 	"strings"
 
@@ -18,6 +17,7 @@ import (
 	"k8s.io/apimachinery/pkg/runtime/schema"
 	"k8s.io/client-go/dynamic"
 	"k8s.io/client-go/kubernetes"
+	"k8s.io/klog/v2"
 	"k8s.io/utils/pointer"
 
 	workapiv1 "open-cluster-management.io/api/work/v1"
@@ -48,7 +48,6 @@ func (c *UpdateApply) Apply(
 	owner metav1.OwnerReference,
 	_ *workapiv1.ManifestConfigOption,
 	recorder events.Recorder) (runtime.Object, error) {
-
 	clientHolder := resourceapply.NewClientHolder().
 		WithAPIExtensionsClient(c.apiExtensionClient).
 		WithKubernetes(c.kubeclient).
@@ -84,15 +83,16 @@ func (c *UpdateApply) applyUnstructured(
 	gvr schema.GroupVersionResource,
 	recorder events.Recorder,
 	cache resourceapply.ResourceCache) (*unstructured.Unstructured, bool, error) {
+	logger := klog.FromContext(ctx)
 	existing, err := c.dynamicClient.
 		Resource(gvr).
 		Namespace(required.GetNamespace()).
 		Get(ctx, required.GetName(), metav1.GetOptions{})
 	if apierrors.IsNotFound(err) {
 		actual, err := c.dynamicClient.Resource(gvr).Namespace(required.GetNamespace()).Create(
 			ctx, resourcemerge.WithCleanLabelsAndAnnotations(required).(*unstructured.Unstructured), metav1.CreateOptions{})
-		recorder.Eventf(fmt.Sprintf(
-			"%s Created", required.GetKind()), "Created %s/%s because it was missing", required.GetNamespace(), required.GetName())
+		logger.Info("Created resource because it was missing",
+			"kind", required.GetKind(), "resourceNamespace", required.GetNamespace(), "resourceName", required.GetName())
 		cache.UpdateCachedResourceMetadata(required, actual)
 		return actual, true, err
 	}
@@ -130,8 +130,8 @@ func (c *UpdateApply) applyUnstructured(
 	required.SetResourceVersion(existing.GetResourceVersion())
 	actual, err := c.dynamicClient.Resource(gvr).Namespace(required.GetNamespace()).Update(
 		ctx, required, metav1.UpdateOptions{})
-	recorder.Eventf(fmt.Sprintf(
-		"%s Updated", required.GetKind()), "Updated %s/%s", required.GetNamespace(), required.GetName())
+	logger.Info("Updated resource",
+		"kind", required.GetKind(), "resourceNamespace", required.GetNamespace(), "resourceName", required.GetName())
 	cache.UpdateCachedResourceMetadata(required, actual)
 	return actual, true, err
 }

pkg/work/spoke/auth/basic/auth.go

@@ -134,7 +134,7 @@ func (v *SarValidator) CheckSubjectAccessReviews(ctx context.Context, sa *workap
 // CheckEscalation checks whether the sa is escalated to operate the gvr(RBAC) resources.
 func (v *SarValidator) CheckEscalation(ctx context.Context, sa *workapiv1.ManifestWorkSubjectServiceAccount,
 	gvr schema.GroupVersionResource, namespace, name string, obj *unstructured.Unstructured) error {
-
+	logger := klog.FromContext(ctx)
 	if gvr.Group != "rbac.authorization.k8s.io" {
 		return nil
 	}
@@ -152,8 +152,8 @@ func (v *SarValidator) CheckEscalation(ctx context.Context, sa *workapiv1.Manife
 		DryRun: []string{"All"},
 	})
 	if apierrors.IsForbidden(err) {
-		klog.Infof("not allowed to apply the resource %s %s, %s %s, error: %s",
-			gvr.Group, gvr.Resource, namespace, name, err.Error())
+		logger.Info("not allowed to apply the resource",
+			"gvr", gvr, "resourceNamespace", namespace, "resourceName", name, "error", err)
 		return &NotAllowedError{
 			Err: fmt.Errorf("not allowed to apply the resource %s %s, %s %s, error: permission escalation",
 				gvr.Group, gvr.Resource, namespace, name),

pkg/work/spoke/auth/cache/auth.go

@@ -101,6 +101,7 @@ func (v *sarCacheValidator) Start(ctx context.Context) {
 func (v *sarCacheValidator) Validate(ctx context.Context, executor *workapiv1.ManifestWorkExecutor,
 	gvr schema.GroupVersionResource, namespace, name string,
 	ownedByTheWork bool, obj *unstructured.Unstructured) error {
+	logger := klog.FromContext(ctx)
 	if executor == nil {
 		return nil
 	}
@@ -128,7 +129,8 @@ func (v *sarCacheValidator) Validate(ctx context.Context, executor *workapiv1.Ma
 			return err
 		}
 	} else {
-		klog.V(4).Infof("Get auth from cache executor %s, dimension: %+v allow: %v", executorKey, dimension, *allowed)
+		logger.V(4).Info("Get auth from cache executor",
+			"executorKey", executorKey, "dimension", dimension, "allowed", *allowed)
 		if !*allowed {
 			return &basic.NotAllowedError{
 				Err: fmt.Errorf("not allowed to apply the resource %s %s, %s %s",

pkg/work/spoke/controllers/finalizercontroller/add_finalizer_controller.go

@@ -17,6 +17,8 @@ import (
 	"open-cluster-management.io/ocm/pkg/common/queue"
 )
 
+const manifestWorkAddFinalizerController = "ManifestWorkAddFinalizerController"
+
 // AddFinalizerController is to add the cluster.open-cluster-management.io/manifest-work-cleanup finalizer to manifestworks.
 type AddFinalizerController struct {
 	patcher            patcher.Patcher[*workapiv1.ManifestWork, workapiv1.ManifestWorkSpec, workapiv1.ManifestWorkStatus]
@@ -40,12 +42,14 @@ func NewAddFinalizerController(
 
 	return factory.New().
 		WithInformersQueueKeysFunc(queue.QueueKeyByMetaName, manifestWorkInformer.Informer()).
-		WithSync(controller.sync).ToController("ManifestWorkAddFinalizerController", recorder)
+		WithSync(controller.sync).ToController(manifestWorkAddFinalizerController, recorder)
 }
 
 func (m *AddFinalizerController) sync(ctx context.Context, controllerContext factory.SyncContext) error {
 	manifestWorkName := controllerContext.QueueKey()
-	klog.V(5).Infof("Reconciling ManifestWork %q", manifestWorkName)
+	logger := klog.FromContext(ctx).WithName(manifestWorkAddFinalizerController).
+		WithValues("manifestWorkName", manifestWorkName)
+	logger.V(5).Info("Reconciling ManifestWork")
 
 	manifestWork, err := m.manifestWorkLister.Get(manifestWorkName)
 	if errors.IsNotFound(err) {

pkg/work/spoke/controllers/finalizercontroller/appliedmanifestwork_finalize_controller.go

@@ -24,6 +24,8 @@ import (
 	"open-cluster-management.io/ocm/pkg/work/helper"
 )
 
+const appliedManifestWorkFinalizer = "AppliedManifestWorkFinalizer"
+
 // AppliedManifestWorkFinalizeController handles cleanup of appliedmanifestwork resources before deletion is allowed.
 // It should handle all appliedmanifestworks belonging to this agent identified by the agentID.
 type AppliedManifestWorkFinalizeController struct {
@@ -54,12 +56,15 @@ func NewAppliedManifestWorkFinalizeController(
 	return factory.New().
 		WithFilteredEventsInformersQueueKeysFunc(queue.QueueKeyByMetaName,
 			helper.AppliedManifestworkAgentIDFilter(agentID), appliedManifestWorkInformer.Informer()).
-		WithSync(controller.sync).ToController("AppliedManifestWorkFinalizer", recorder)
+		WithSync(controller.sync).ToController(appliedManifestWorkFinalizer, recorder)
 }
 
 func (m *AppliedManifestWorkFinalizeController) sync(ctx context.Context, controllerContext factory.SyncContext) error {
 	appliedManifestWorkName := controllerContext.QueueKey()
-	klog.V(5).Infof("Reconciling AppliedManifestWork %q", appliedManifestWorkName)
+	logger := klog.FromContext(ctx).WithName(appliedManifestWorkFinalizer).
+		WithValues("appliedManifestWorkName", appliedManifestWorkName)
+	logger.V(5).Info("Reconciling AppliedManifestWork")
+	ctx = klog.NewContext(ctx, logger)
 
 	appliedManifestWork, err := m.appliedManifestWorkLister.Get(appliedManifestWorkName)
 	if errors.IsNotFound(err) {
@@ -77,6 +82,7 @@ func (m *AppliedManifestWorkFinalizeController) sync(ctx context.Context, contro
 // before removing finalizer from appliedmanifestwork
 func (m *AppliedManifestWorkFinalizeController) syncAppliedManifestWork(ctx context.Context,
 	controllerContext factory.SyncContext, originalManifestWork *workapiv1.AppliedManifestWork) error {
+	logger := klog.FromContext(ctx)
 	appliedManifestWork := originalManifestWork.DeepCopy()
 
 	// no work to do until we're deleted
@@ -96,7 +102,7 @@ func (m *AppliedManifestWorkFinalizeController) syncAppliedManifestWork(ctx cont
 	// scoped resource correctly.
 	reason := fmt.Sprintf("manifestwork %s is terminating", appliedManifestWork.Spec.ManifestWorkName)
 	resourcesPendingFinalization, errs := helper.DeleteAppliedResources(
-		ctx, appliedManifestWork.Status.AppliedResources, reason, m.spokeDynamicClient, controllerContext.Recorder(), *owner)
+		ctx, appliedManifestWork.Status.AppliedResources, reason, m.spokeDynamicClient, *owner)
 	appliedManifestWork.Status.AppliedResources = resourcesPendingFinalization
 	updatedAppliedManifestWork, err := m.patcher.PatchStatus(ctx, appliedManifestWork, appliedManifestWork.Status, originalManifestWork.Status)
 	if err != nil {
@@ -111,7 +117,7 @@ func (m *AppliedManifestWorkFinalizeController) syncAppliedManifestWork(ctx cont
 
 	// requeue the work until all applied resources are deleted and finalized if the appliedmanifestwork itself is not updated
 	if len(resourcesPendingFinalization) != 0 {
-		klog.V(4).Infof("%d resources pending deletions in %s", len(resourcesPendingFinalization), appliedManifestWork.Name)
+		logger.V(4).Info("resources pending deletions", "numOfResources", len(resourcesPendingFinalization))
 		controllerContext.Queue().AddAfter(appliedManifestWork.Name, m.rateLimiter.When(appliedManifestWork.Name))
 		return nil
 	}