logs: simplify the bpfman-agent logs

As part of a security review which required extend logging behaviour,
investigated improving the logs. Moved the logs from using context,
which prints a lot if useless info, to just using regular logs.

Signed-off-by: Billy McFall <[email protected]>

bundle/manifests/bpfman-operator.clusterserviceversion.yaml

@@ -307,7 +307,7 @@ metadata:
     capabilities: Basic Install
     categories: OpenShift Optional
     containerImage: quay.io/bpfman/bpfman-operator:latest
-    createdAt: "2024-10-21T11:51:40Z"
+    createdAt: "2024-11-01T20:38:03Z"
     features.operators.openshift.io/cnf: "false"
     features.operators.openshift.io/cni: "false"
     features.operators.openshift.io/csi: "true"
@@ -1102,7 +1102,7 @@ spec:
                 - /bpfman-operator
                 env:
                 - name: GO_LOG
-                  value: debug
+                  value: info
                 image: quay.io/bpfman/bpfman-operator:latest
                 imagePullPolicy: IfNotPresent
                 livenessProbe:

config/bpfman-operator-deployment/deployment.yaml

@@ -74,7 +74,7 @@ spec:
           imagePullPolicy: IfNotPresent
           env:
             - name: GO_LOG
-              value: debug
+              value: info
           name: bpfman-operator
           securityContext:
             allowPrivilegeEscalation: false

controllers/bpfman-agent/application-program.go

@@ -15,7 +15,6 @@ import (
 	"sigs.k8s.io/controller-runtime/pkg/builder"
 	"sigs.k8s.io/controller-runtime/pkg/client"
 	"sigs.k8s.io/controller-runtime/pkg/handler"
-	"sigs.k8s.io/controller-runtime/pkg/log"
 	"sigs.k8s.io/controller-runtime/pkg/predicate"
 )
 
@@ -40,8 +39,7 @@ func (r *BpfApplicationReconciler) Reconcile(ctx context.Context, req ctrl.Reque
 	r.finalizer = internal.BpfApplicationControllerFinalizer
 	r.recType = internal.ApplicationString
 
-	ctxLogger := log.FromContext(ctx)
-	ctxLogger.Info("Reconcile Application: Enter", "ReconcileKey", req)
+	r.Logger.Info("bpfman-agent enter: application", "Name", req.Name)
 
 	// Lookup K8s node object for this bpfman-agent This should always succeed
 	if err := r.Get(ctx, types.NamespacedName{Namespace: v1.NamespaceAll, Name: r.NodeName}, r.ourNode); err != nil {
@@ -192,7 +190,7 @@ func (r *BpfApplicationReconciler) Reconcile(ctx context.Context, req ctrl.Reque
 			case bpfmaniov1alpha1.ProgTypeTC:
 				interfaces, ifErr := getInterfaces(&p.TC.InterfaceSelector, r.ourNode)
 				if ifErr != nil {
-					ctxLogger.Error(ifErr, "failed to get interfaces for TC Program",
+					r.Logger.Error(ifErr, "failed to get interfaces for TC Program",
 						"app program name", a.Name, "program index", j)
 					continue
 				}
@@ -220,7 +218,7 @@ func (r *BpfApplicationReconciler) Reconcile(ctx context.Context, req ctrl.Reque
 			case bpfmaniov1alpha1.ProgTypeTCX:
 				interfaces, ifErr := getInterfaces(&p.TCX.InterfaceSelector, r.ourNode)
 				if ifErr != nil {
-					ctxLogger.Error(ifErr, "failed to get interfaces for TCX Program",
+					r.Logger.Error(ifErr, "failed to get interfaces for TCX Program",
 						"app program name", a.Name, "program index", j)
 					continue
 				}
@@ -248,7 +246,7 @@ func (r *BpfApplicationReconciler) Reconcile(ctx context.Context, req ctrl.Reque
 			case bpfmaniov1alpha1.ProgTypeXDP:
 				interfaces, ifErr := getInterfaces(&p.XDP.InterfaceSelector, r.ourNode)
 				if ifErr != nil {
-					ctxLogger.Error(ifErr, "failed to get interfaces for XDP Program",
+					r.Logger.Error(ifErr, "failed to get interfaces for XDP Program",
 						"app program name", a.Name, "program index", j)
 					continue
 				}
@@ -274,12 +272,12 @@ func (r *BpfApplicationReconciler) Reconcile(ctx context.Context, req ctrl.Reque
 				complete, res, err = r.reconcileCommon(ctx, rec, xdpObjects)
 
 			default:
-				ctxLogger.Error(fmt.Errorf("unsupported bpf program type"), "unsupported bpf program type", "ProgType", p.Type)
+				r.Logger.Error(fmt.Errorf("unsupported bpf program type"), "unsupported bpf program type", "ProgType", p.Type)
 				// Skip this program and continue to the next one
 				continue
 			}
 
-			ctxLogger.V(1).Info("Reconcile Application", "Application", i, "Program", j, "Name", a.Name,
+			r.Logger.V(1).Info("Reconcile Application", "Application", i, "Program", j, "Name", a.Name,
 				"type", p.Type, "Complete", complete, "Result", res, "Error", err)
 
 			if complete {
@@ -296,20 +294,20 @@ func (r *BpfApplicationReconciler) Reconcile(ctx context.Context, req ctrl.Reque
 			// find programs that need to be deleted and delete them
 			opts := []client.ListOption{client.MatchingLabels{internal.BpfProgramOwner: a.Name}}
 			if err := r.List(ctx, bpfPrograms, opts...); err != nil {
-				ctxLogger.Error(err, "failed to get freshPrograms for full reconcile")
+				r.Logger.Error(err, "failed to get freshPrograms for full reconcile")
 				return ctrl.Result{}, err
 			}
 			for _, bpfProgram := range bpfPrograms.Items {
 				id := bpfProgram.Labels[internal.AppProgramId]
 				if _, ok := appProgramMap[id]; !ok {
-					ctxLogger.Info("Deleting BpfProgram", "AppProgramId", id, "BpfProgram", bpfProgram.Name)
+					r.Logger.Info("Deleting BpfProgram", "AppProgramId", id, "BpfProgram", bpfProgram.Name)
 					bpfDeletedPrograms.Items = append(bpfDeletedPrograms.Items, bpfProgram)
 				}
 			}
 			// Delete BpfPrograms that are no longer needed
 			res, err = r.unLoadAndDeleteBpfProgramsList(ctx, bpfDeletedPrograms, internal.BpfApplicationControllerFinalizer)
 			if err != nil {
-				ctxLogger.Error(err, "failed to delete programs")
+				r.Logger.Error(err, "failed to delete programs")
 				return ctrl.Result{}, err
 			}
 			// We've completed reconciling all programs for this application, continue to the next one

controllers/bpfman-agent/common.go

@@ -167,7 +167,7 @@ func (r *ReconcilerCommon) reconcileCommon(ctx context.Context, rec bpfmanReconc
 
 		result, err := r.reconcileProgram(ctx, rec, program, loadedBpfPrograms)
 		if err != nil {
-			r.Logger.Error(err, "Reconciling program failed", "Program Name", rec.getName, "ReconcileResult", result.String())
+			r.Logger.Error(err, "Reconciling program failed", "Name", rec.getName, "ReconcileResult", result.String())
 		}
 
 		switch result {
@@ -202,7 +202,7 @@ func (r *ReconcilerCommon) reconcileBpfProgram(ctx context.Context,
 	isBeingDeleted bool,
 	mapOwnerStatus *MapOwnerParamStatus) (bpfmaniov1alpha1.BpfProgramConditionType, error) {
 
-	r.Logger.V(1).Info("enter reconcileBpfmanProgram()", "bpfProgram", bpfProgram.Name, "CurrentProgram", rec.getName())
+	r.Logger.V(1).Info("enter reconcileBpfmanProgram()", "Name", bpfProgram.Name, "CurrentProgram", rec.getName())
 
 	uuid := bpfProgram.UID
 	noContainersOnNode := noContainersOnNode(bpfProgram)
@@ -216,7 +216,7 @@ func (r *ReconcilerCommon) reconcileBpfProgram(ctx context.Context,
 		// prog ID should already have been set if program is loaded
 		id, err := bpfmanagentinternal.GetID(bpfProgram)
 		if err != nil {
-			r.Logger.Error(err, "Failed to get bpf program ID")
+			r.Logger.Error(err, "Failed to get kernel ID for BpfProgram")
 			return bpfmaniov1alpha1.BpfProgCondNotLoaded, err
 		}
 		switch shouldBeLoaded {
@@ -229,28 +229,28 @@ func (r *ReconcilerCommon) reconcileBpfProgram(ctx context.Context,
 			}
 			isSame, reasons := bpfmanagentinternal.DoesProgExist(loadedBpfProgram, loadRequest)
 			if !isSame {
-				r.Logger.V(1).Info("bpf program is in wrong state, unloading and reloading", "reason", reasons, "bpfProgram Name", bpfProgram.Name, "bpf program ID", id)
+				r.Logger.Info("BpfProgram is in wrong state, unloading and reloading", "reason", reasons, "Name", bpfProgram.Name, "Program ID", id)
 				if err := bpfmanagentinternal.UnloadBpfmanProgram(ctx, r.BpfmanClient, *id); err != nil {
-					r.Logger.Error(err, "Failed to unload BPF Program")
+					r.Logger.Error(err, "Failed to unload eBPF Program")
 					return bpfmaniov1alpha1.BpfProgCondNotUnloaded, err
 				}
 
-				r.Logger.Info("Calling bpfman to load bpf program on Node", "bpfProgram Name", bpfProgram.Name)
+				r.Logger.Info("Calling bpfman to load eBPF Program on Node", "Name", bpfProgram.Name)
 				r.progId, err = bpfmanagentinternal.LoadBpfmanProgram(ctx, r.BpfmanClient, loadRequest)
 				if err != nil {
-					r.Logger.Error(err, "Failed to load bpf program")
+					r.Logger.Error(err, "Failed to load eBPF Program")
 					return bpfmaniov1alpha1.BpfProgCondNotLoaded, err
 				}
 			} else {
 				// Program exists and bpfProgram K8s Object is up to date
-				r.Logger.V(1).Info("Program is in correct state.  Nothing to do in bpfman")
+				r.Logger.V(1).Info("BpfProgram is in correct state.  Nothing to do in bpfman")
 				r.progId = id
 			}
 		case false:
 			// The program is loaded but it shouldn't be loaded.
-			r.Logger.Info("Calling bpfman to unload program on node", "bpfProgram Name", bpfProgram.Name, "Program ID", id)
+			r.Logger.Info("Calling bpfman to unload eBPF Program on node", "Name", bpfProgram.Name, "Program ID", id)
 			if err := bpfmanagentinternal.UnloadBpfmanProgram(ctx, r.BpfmanClient, *id); err != nil {
-				r.Logger.Error(err, "Failed to unload Program")
+				r.Logger.Error(err, "Failed to unload eBPF Program")
 				return bpfmaniov1alpha1.BpfProgCondNotUnloaded, err
 			}
 		}
@@ -263,10 +263,10 @@ func (r *ReconcilerCommon) reconcileBpfProgram(ctx context.Context,
 				return bpfmaniov1alpha1.BpfProgCondBytecodeSelectorError, err
 			}
 
-			r.Logger.Info("Calling bpfman to load program on node", "bpfProgram name", bpfProgram.Name)
+			r.Logger.Info("Calling bpfman to load eBPF Program on node", "Name", bpfProgram.Name)
 			r.progId, err = bpfmanagentinternal.LoadBpfmanProgram(ctx, r.BpfmanClient, loadRequest)
 			if err != nil {
-				r.Logger.Error(err, "Failed to load Program")
+				r.Logger.Error(err, "Failed to load eBPF Program")
 				return bpfmaniov1alpha1.BpfProgCondNotLoaded, err
 			}
 		case false:
@@ -454,10 +454,10 @@ func getInterfaces(interfaceSelector *bpfmaniov1alpha1.InterfaceSelector, ourNod
 func (r *ReconcilerCommon) removeFinalizer(ctx context.Context, o client.Object, finalizer string) bool {
 	changed := controllerutil.RemoveFinalizer(o, finalizer)
 	if changed {
-		r.Logger.Info("Removing finalizer from bpfProgram", "object name", o.GetName())
+		r.Logger.Info("Calling KubeAPI to remove finalizer from BpfProgram", "object name", o.GetName())
 		err := r.Update(ctx, o)
 		if err != nil {
-			r.Logger.Error(err, "failed to remove bpfProgram Finalizer")
+			r.Logger.Error(err, "failed to remove BpfProgram Finalizer")
 			return true
 		}
 	}
@@ -496,9 +496,9 @@ func (r *ReconcilerCommon) updateStatus(ctx context.Context, bpfProgram *bpfmani
 
 	meta.SetStatusCondition(&bpfProgram.Status.Conditions, cond.Condition())
 
-	r.Logger.V(1).Info("Updating bpfProgram condition", "bpfProgram", bpfProgram.Name, "condition", cond.Condition().Type)
+	r.Logger.Info("Calling KubeAPI to update BpfProgram condition", "Name", bpfProgram.Name, "condition", cond.Condition().Type)
 	if err := r.Status().Update(ctx, bpfProgram); err != nil {
-		r.Logger.Error(err, "failed to set bpfProgram object status")
+		r.Logger.Error(err, "failed to set BpfProgram object status")
 	}
 
 	r.Logger.V(1).Info("condition updated", "new condition", cond)
@@ -589,7 +589,7 @@ func (r *ReconcilerCommon) createBpfProgram(
 
 	// Make the corresponding BpfProgramConfig the owner
 	if err := ctrl.SetControllerReference(rec.getOwner(), bpfProg, r.Scheme); err != nil {
-		return nil, fmt.Errorf("failed to bpfProgram object owner reference: %v", err)
+		return nil, fmt.Errorf("failed to set BpfProgram object owner reference: %v", err)
 	}
 
 	return bpfProg, nil
@@ -624,7 +624,7 @@ func (r *ReconcilerCommon) handleProgDelete(
 	r.Logger.V(1).Info("handleProgDelete()", "isBeingDeleted", isBeingDeleted, "isNodeSelected",
 		isNodeSelected, "mapOwnerStatus", mapOwnerStatus)
 	for _, bpfProgram := range existingBpfPrograms {
-		r.Logger.V(1).Info("Deleting bpfProgram", "Name", bpfProgram.Name)
+		r.Logger.V(1).Info("Deleting BpfProgram", "Name", bpfProgram.Name)
 		// Reconcile the bpfProgram if error write condition and exit with
 		// retry.
 		cond, err := r.reconcileBpfProgram(ctx,
@@ -637,7 +637,7 @@ func (r *ReconcilerCommon) handleProgDelete(
 		)
 		if err != nil {
 			r.updateStatus(ctx, &bpfProgram, cond)
-			return internal.Requeue, fmt.Errorf("failed to delete bpfman program: %v", err)
+			return internal.Requeue, fmt.Errorf("failed to delete program from bpfman: %v", err)
 		}
 
 		if r.removeFinalizer(ctx, &bpfProgram, rec.getFinalizer()) {
@@ -656,9 +656,9 @@ func (r *ReconcilerCommon) handleProgDelete(
 			// to changes that caused the containers to not be selected anymore.
 			// So, explicitly delete them.
 			opts := client.DeleteOptions{}
-			r.Logger.Info("Deleting bpfProgram", "Name", bpfProgram.Name, "Owner", bpfProgram.GetName())
+			r.Logger.Info("Calling KubeAPI to delete BpfProgram", "Name", bpfProgram.Name, "Owner", bpfProgram.GetName())
 			if err := r.Delete(ctx, &bpfProgram, &opts); err != nil {
-				return internal.Requeue, fmt.Errorf("failed to delete bpfProgram object: %v", err)
+				return internal.Requeue, fmt.Errorf("failed to delete BpfProgram object: %v", err)
 			}
 			return internal.Updated, nil
 		}
@@ -674,20 +674,20 @@ func (r *ReconcilerCommon) handleProgDelete(
 // has changed such that the BpfPrograms are no longer needed.
 func (r *ReconcilerCommon) unLoadAndDeleteBpfProgramsList(ctx context.Context, bpfProgramsList *bpfmaniov1alpha1.BpfProgramList, finalizerString string) (reconcile.Result, error) {
 	for _, bpfProgram := range bpfProgramsList.Items {
-		r.Logger.V(1).Info("Deleting bpfProgram", "Name", bpfProgram.Name)
+		r.Logger.V(1).Info("Deleting BpfProgram", "Name", bpfProgram.Name)
 		id, err := bpfmanagentinternal.GetID(&bpfProgram)
 		if err != nil {
-			r.Logger.Error(err, "Failed to get bpf program ID")
+			r.Logger.Error(err, "Failed to get kernel ID from BpfProgram")
 			return ctrl.Result{}, nil
 		}
 
 		if id != nil && !statusContains(&bpfProgram, bpfmaniov1alpha1.BpfProgCondUnloaded) {
-			r.Logger.Info("Calling bpfman to unload program on node", "bpfProgram Name", bpfProgram.Name, "Program ID", id)
+			r.Logger.Info("Calling bpfman to unload program on node", "Name", bpfProgram.Name, "Program ID", id)
 			if err := bpfmanagentinternal.UnloadBpfmanProgram(ctx, r.BpfmanClient, *id); err != nil {
 				if strings.Contains(err.Error(), programDoesNotExistErr) {
-					r.Logger.Info("Program not found on node", "bpfProgram Name", bpfProgram.Name, "Program ID", id)
+					r.Logger.Info("Program not found on node", "Name", bpfProgram.Name, "Program ID", id)
 				} else {
-					r.Logger.Error(err, "Failed to unload Program")
+					r.Logger.Error(err, "Failed to unload Program from bpfman")
 					return ctrl.Result{RequeueAfter: retryDurationAgent}, nil
 				}
 				if r.updateStatus(ctx, &bpfProgram, bpfmaniov1alpha1.BpfProgCondUnloaded) {
@@ -705,9 +705,9 @@ func (r *ReconcilerCommon) unLoadAndDeleteBpfProgramsList(ctx context.Context, b
 		}
 
 		opts := client.DeleteOptions{}
-		r.Logger.Info("Deleting bpfProgram", "Name", bpfProgram.Name, "Owner", bpfProgram.GetName())
+		r.Logger.Info("Calling KubeAPI to delete BpfProgram", "Name", bpfProgram.Name, "Owner", bpfProgram.GetName())
 		if err := r.Delete(ctx, &bpfProgram, &opts); err != nil {
-			return ctrl.Result{RequeueAfter: retryDurationAgent}, fmt.Errorf("failed to delete bpfProgram object: %v", err)
+			return ctrl.Result{RequeueAfter: retryDurationAgent}, fmt.Errorf("failed to delete BpfProgram object: %v", err)
 		} else {
 			// we will deal one program at a time, so we can break out of the loop
 			break
@@ -748,9 +748,9 @@ func (r *ReconcilerCommon) handleProgCreateOrUpdate(
 		} else {
 			// Create a new bpfProgram Object for this program.
 			opts := client.CreateOptions{}
-			r.Logger.Info("Creating bpfProgram", "Name", expectedBpfProgram.Name, "Owner", rec.getOwner().GetName())
+			r.Logger.Info("Calling KubeAPI to create BpfProgram", "Name", expectedBpfProgram.Name, "Owner", rec.getOwner().GetName())
 			if err := r.Create(ctx, &expectedBpfProgram, &opts); err != nil {
-				return internal.Requeue, fmt.Errorf("failed to create bpfProgram object: %v", err)
+				return internal.Requeue, fmt.Errorf("failed to create BpfProgram object: %v", err)
 			}
 			return internal.Updated, nil
 		}
@@ -792,11 +792,11 @@ func (r *ReconcilerCommon) handleProgCreateOrUpdate(
 
 			// If bpfProgram Maps OR the program ID annotation isn't up to date just update it and return
 			if !reflect.DeepEqual(existingId, r.progId) {
-				r.Logger.Info("Updating bpfProgram Object", "Id", r.progId, "bpfProgram", existingBpfProgram.Name)
+				r.Logger.Info("Calling KubeAPI to update BpfProgram Object", "Id", r.progId, "Name", existingBpfProgram.Name)
 				// annotations should be populated on create
 				existingBpfProgram.Annotations[internal.IdAnnotation] = strconv.FormatUint(uint64(*r.progId), 10)
 				if err := r.Update(ctx, &existingBpfProgram, &client.UpdateOptions{}); err != nil {
-					return internal.Requeue, fmt.Errorf("failed to update bpfProgram's Programs: %v", err)
+					return internal.Requeue, fmt.Errorf("failed to update BpfProgram's Programs: %v", err)
 				}
 				return internal.Updated, nil
 			}
@@ -813,7 +813,7 @@ func (r *ReconcilerCommon) handleProgCreateOrUpdate(
 		return r.handleProgDelete(ctx, rec, existingBpfPrograms, loadedBpfPrograms, isNodeSelected, isBeingDeleted, mapOwnerStatus)
 	} else {
 		// We're done reconciling.
-		r.Logger.Info("Finished reconciling", "program name", rec.getName())
+		r.Logger.Info("Finished reconciling", "Name", rec.getName())
 		return internal.Unchanged, nil
 	}
 }
@@ -846,7 +846,7 @@ func (r *ReconcilerCommon) reconcileProgram(ctx context.Context,
 	// on this node.
 	existingBpfPrograms, err := r.getExistingBpfPrograms(ctx, rec)
 	if err != nil {
-		return internal.Requeue, fmt.Errorf("failed to get existing bpfPrograms: %v", err)
+		return internal.Requeue, fmt.Errorf("failed to get existing BpfPrograms: %v", err)
 	}
 
 	// Determine if the MapOwnerSelector was set, and if so, see if the MapOwner
@@ -872,7 +872,7 @@ func (r *ReconcilerCommon) reconcileProgram(ctx context.Context,
 		// installed in multiple containers because of ContainerSelector).
 		expectedBpfPrograms, err := rec.getExpectedBpfPrograms(ctx)
 		if err != nil {
-			return internal.Requeue, fmt.Errorf("failed to get expected bpfPrograms: %v", err)
+			return internal.Requeue, fmt.Errorf("failed to get expected BpfPrograms: %v", err)
 		}
 		return r.handleProgCreateOrUpdate(ctx, rec, existingBpfPrograms, expectedBpfPrograms, loadedBpfPrograms,
 			isNodeSelected, isBeingDeleted, mapOwnerStatus)
@@ -933,7 +933,7 @@ func (r *ReconcilerCommon) processMapOwnerParam(
 		if len(bpfProgramList.Items) == 0 {
 			return mapOwnerStatus, nil
 		} else if len(bpfProgramList.Items) > 1 {
-			return mapOwnerStatus, fmt.Errorf("MapOwnerSelector resolved to multiple bpfProgram Objects")
+			return mapOwnerStatus, fmt.Errorf("MapOwnerSelector resolved to multiple BpfProgram Objects")
 		} else {
 			mapOwnerStatus.isFound = true
 
@@ -1029,5 +1029,5 @@ func (r *ReconcilerCommon) getBpfProgram(
 		}
 	}
 
-	return fmt.Errorf("bpfProgram not found")
+	return fmt.Errorf("BpfProgram not found")
 }

controllers/bpfman-agent/fentry-program.go

@@ -32,7 +32,6 @@ import (
 	"sigs.k8s.io/controller-runtime/pkg/builder"
 	"sigs.k8s.io/controller-runtime/pkg/client"
 	"sigs.k8s.io/controller-runtime/pkg/handler"
-	"sigs.k8s.io/controller-runtime/pkg/log"
 	"sigs.k8s.io/controller-runtime/pkg/predicate"
 )
 
@@ -149,8 +148,7 @@ func (r *FentryProgramReconciler) Reconcile(ctx context.Context, req ctrl.Reques
 	r.ourNode = &v1.Node{}
 	r.Logger = ctrl.Log.WithName("fentry")
 
-	ctxLogger := log.FromContext(ctx)
-	ctxLogger.Info("Reconcile Fentry: Enter", "ReconcileKey", req)
+	r.Logger.Info("bpfman-agent enter: fentry", "Name", req.Name)
 
 	// Lookup K8s node object for this bpfman-agent This should always succeed
 	if err := r.Get(ctx, types.NamespacedName{Namespace: v1.NamespaceAll, Name: r.NodeName}, r.ourNode); err != nil {