From 8a435fefa0012297fbee737058d4bf9ab45998a8 Mon Sep 17 00:00:00 2001 From: Marcelo Guerrero Date: Fri, 17 Nov 2023 12:39:49 +0100 Subject: [PATCH 01/13] Fix error overwrite for setSriovNumVfs When setSriovNumVfs fails, the error is overwritten by the return error of RemoveUdevRule. If the latter function doesn't return an error (most cases), the reconciliation loop will report success even if vfs were not created/configured. --- pkg/utils/utils.go | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/pkg/utils/utils.go b/pkg/utils/utils.go index 051a4aebb..d2c9934f6 100644 --- a/pkg/utils/utils.go +++ b/pkg/utils/utils.go @@ -428,11 +428,11 @@ func configSriovDevice(iface *sriovnetworkv1.Interface, ifaceStatus *sriovnetwor err = setSriovNumVfs(iface.PciAddress, iface.NumVfs) if err != nil { - err = RemoveUdevRule(iface.PciAddress) - if err != nil { - return err + log.Log.Error(err, "configSriovDevice(): fail to set NumVfs for device", "device", iface.PciAddress) + errRemove := RemoveUdevRule(iface.PciAddress) + if errRemove != nil { + log.Log.Error(errRemove, "configSriovDevice(): fail to remove udev rule", "device", iface.PciAddress) } - log.Log.Error(nil, "configSriovDevice(): fail to set NumVfs for device", "device", iface.PciAddress) return err } } From fcc331f158698ce81a9d0a872bffd14e960ea90c Mon Sep 17 00:00:00 2001 From: Vasilis Remmas Date: Wed, 22 Nov 2023 16:16:35 +0100 Subject: [PATCH 02/13] Add check to ensure jq can be found in $PATH jq is a required tool in that script. Since we are not setting `-o pipefail`, the script can fail but exit with code 0 making the systemd service report success. This leaves the system in a bad state and user interaction is needed. Signed-off-by: Vasilis Remmas --- .../files/switchdev-configuration-before-nm.sh.yaml | 2 ++ 1 file changed, 2 insertions(+) diff --git a/bindata/manifests/switchdev-config/files/switchdev-configuration-before-nm.sh.yaml b/bindata/manifests/switchdev-config/files/switchdev-configuration-before-nm.sh.yaml index 32187683b..2560450d0 100644 --- a/bindata/manifests/switchdev-config/files/switchdev-configuration-before-nm.sh.yaml +++ b/bindata/manifests/switchdev-config/files/switchdev-configuration-before-nm.sh.yaml @@ -13,6 +13,8 @@ contents: exit fi + which jq 2>&1 >/dev/null || (echo "Required tool jq is not found in PATH." && exit 1) + append_to_file(){ content="$1" file_name="$2" From f237ae830f563ca841193b27cefe45fa94a1b608 Mon Sep 17 00:00:00 2001 From: Andrea Panattoni Date: Wed, 8 Nov 2023 13:08:52 +0100 Subject: [PATCH 03/13] Use `SriovOperatorConfig.LogLevel` in operator Field `SriovOperatorConfig.Spec.LogLevel` controls the verbosity of the operator logging system. This commit adjust the operator controller's log level to that field, as it happens in the config-daemon. Note: at the moment, every log calls in the controllers are using `V(0)`, so this commit is not supposed to change the aspect of a logfile. Further commits will change the level of some particular log calls. Log the current and new value for the logger according to what the user had set in the LogLevel field. Before this commit, a value of -2 would produce a misleading line: ``` Set log verbose level {"new-level": 0, "current-level": -2} ``` Signed-off-by: Andrea Panattoni --- controllers/sriovoperatorconfig_controller.go | 3 + pkg/daemon/daemon.go | 13 +-- pkg/log/log.go | 20 +++- pkg/log/log_test.go | 92 +++++++++++++++++++ 4 files changed, 113 insertions(+), 15 deletions(-) create mode 100644 pkg/log/log_test.go diff --git a/controllers/sriovoperatorconfig_controller.go b/controllers/sriovoperatorconfig_controller.go index 7e9c548fb..cfbeeb3cc 100644 --- a/controllers/sriovoperatorconfig_controller.go +++ b/controllers/sriovoperatorconfig_controller.go @@ -39,6 +39,7 @@ import ( sriovnetworkv1 "github.com/k8snetworkplumbingwg/sriov-network-operator/api/v1" apply "github.com/k8snetworkplumbingwg/sriov-network-operator/pkg/apply" constants "github.com/k8snetworkplumbingwg/sriov-network-operator/pkg/consts" + snolog "github.com/k8snetworkplumbingwg/sriov-network-operator/pkg/log" render "github.com/k8snetworkplumbingwg/sriov-network-operator/pkg/render" utils "github.com/k8snetworkplumbingwg/sriov-network-operator/pkg/utils" ) @@ -124,6 +125,8 @@ func (r *SriovOperatorConfigReconciler) Reconcile(ctx context.Context, req ctrl. return reconcile.Result{}, err } + snolog.SetLogLevel(defaultConfig.Spec.LogLevel) + // For Openshift we need to create the systemd files using a machine config if utils.ClusterType == utils.ClusterTypeOpenshift { // TODO: add support for hypershift as today there is no MCO on hypershift clusters diff --git a/pkg/daemon/daemon.go b/pkg/daemon/daemon.go index 1d435dc53..913cad805 100644 --- a/pkg/daemon/daemon.go +++ b/pkg/daemon/daemon.go @@ -17,7 +17,6 @@ import ( mcfgv1 "github.com/openshift/machine-config-operator/pkg/apis/machineconfiguration.openshift.io/v1" daemonconsts "github.com/openshift/machine-config-operator/pkg/daemon/constants" mcfginformers "github.com/openshift/machine-config-operator/pkg/generated/informers/externalversions" - "go.uber.org/zap" "golang.org/x/time/rate" corev1 "k8s.io/api/core/v1" "k8s.io/apimachinery/pkg/api/errors" @@ -426,7 +425,7 @@ func (dn *Daemon) operatorConfigAddHandler(obj interface{}) { func (dn *Daemon) operatorConfigChangeHandler(old, new interface{}) { newCfg := new.(*sriovnetworkv1.SriovOperatorConfig) - dn.handleLogLevelChange(newCfg.Spec.LogLevel) + snolog.SetLogLevel(newCfg.Spec.LogLevel) newDisableDrain := newCfg.Spec.DisableDrain if dn.disableDrain != newDisableDrain { @@ -435,16 +434,6 @@ func (dn *Daemon) operatorConfigChangeHandler(old, new interface{}) { } } -// handleLogLevelChange handles log level change -func (dn *Daemon) handleLogLevelChange(logLevel int) { - newLevel := int8(logLevel * -1) - currLevel := int8(snolog.Options.Level.(zap.AtomicLevel).Level()) - if newLevel != currLevel { - log.Log.Info("Set log verbose level", "new-level", newLevel, "current-level", currLevel) - snolog.SetLogLevel(newLevel) - } -} - func (dn *Daemon) nodeStateSyncHandler() error { var err error // Get the latest NodeState diff --git a/pkg/log/log.go b/pkg/log/log.go index 8a03c62b9..1e76facc5 100644 --- a/pkg/log/log.go +++ b/pkg/log/log.go @@ -49,7 +49,21 @@ func InitLog() { log.SetLogger(zap.New(zap.UseFlagOptions(Options))) } -// SetLogLevel sets log level -func SetLogLevel(lvl int8) { - Options.Level.(zzap.AtomicLevel).SetLevel(zapcore.Level(lvl)) +// SetLogLevel provides conversion from the operators LogLevel value ({0,1,2} where 2 is the most verbose) and sets +// the current logging level accordingly. +func SetLogLevel(operatorLevel int) { + newLevel := operatorToZapLevel(operatorLevel) + currLevel := Options.Level.(zzap.AtomicLevel).Level() + if newLevel != currLevel { + log.Log.Info("Set log verbose level", "new-level", operatorLevel, "current-level", zapToOperatorLevel(currLevel)) + Options.Level.(zzap.AtomicLevel).SetLevel(newLevel) + } +} + +func zapToOperatorLevel(zapLevel zapcore.Level) int { + return int(zapLevel) * -1 +} + +func operatorToZapLevel(operatorLevel int) zapcore.Level { + return zapcore.Level(operatorLevel * -1) } diff --git a/pkg/log/log_test.go b/pkg/log/log_test.go new file mode 100644 index 000000000..420b0698f --- /dev/null +++ b/pkg/log/log_test.go @@ -0,0 +1,92 @@ +package log + +import ( + "io" + "os" + "testing" + + g "github.com/onsi/ginkgo/v2" + o "github.com/onsi/gomega" + + "sigs.k8s.io/controller-runtime/pkg/log" +) + +var tempLogFile *os.File +var origWriter io.Writer + +var _ = g.Describe("Logging", func() { + + g.BeforeEach(func() { + err := os.Truncate(tempLogFile.Name(), 0) + o.Expect(err).ToNot(o.HaveOccurred()) + }) + + g.It("LogLevel 0", func() { + + log.Log.Info("test level 0") + log.Log.V(1).Info("test level 1") + log.Log.V(2).Info("test level 2") + + out, err := os.ReadFile(tempLogFile.Name()) + o.Expect(err).NotTo(o.HaveOccurred()) + + o.Expect(string(out)).Should(o.ContainSubstring("test level 0")) + o.Expect(string(out)).ShouldNot(o.ContainSubstring("test level 1")) + o.Expect(string(out)).ShouldNot(o.ContainSubstring("test level 2")) + }) + + g.It("LogLevel 1", func() { + + SetLogLevel(1) + + log.Log.Info("test level 0") + log.Log.V(1).Info("test level 1") + log.Log.V(2).Info("test level 2") + + out, err := os.ReadFile(tempLogFile.Name()) + o.Expect(err).NotTo(o.HaveOccurred()) + + o.Expect(string(out)).Should(o.ContainSubstring("test level 0")) + o.Expect(string(out)).Should(o.ContainSubstring("test level 1")) + o.Expect(string(out)).ShouldNot(o.ContainSubstring("test level 2")) + }) + + g.It("LogLevel 2", func() { + + SetLogLevel(2) + + log.Log.Info("test level 0") + log.Log.V(1).Info("test level 1") + log.Log.V(2).Info("test level 2") + + out, err := os.ReadFile(tempLogFile.Name()) + o.Expect(err).NotTo(o.HaveOccurred()) + + o.Expect(string(out)).Should(o.ContainSubstring("test level 0")) + o.Expect(string(out)).Should(o.ContainSubstring("test level 1")) + o.Expect(string(out)).Should(o.ContainSubstring("test level 2")) + }) +}) + +func TestLogging(t *testing.T) { + o.RegisterFailHandler(g.Fail) + g.RunSpecs(t, "Logging Suite") +} + +var _ = g.BeforeSuite(func() { + var err error + tempLogFile, err = os.CreateTemp("", "zap-output") + o.Expect(err).NotTo(o.HaveOccurred()) + origWriter = Options.DestWriter + Options.DestWriter = tempLogFile + + InitLog() +}) + +var _ = g.AfterSuite(func() { + Options.DestWriter = origWriter + o.Expect(tempLogFile.Close()).To(o.Succeed()) + o.Expect(os.RemoveAll(tempLogFile.Name())).To(o.Succeed()) + + SetLogLevel(2) +}) From 34dd198b656968935ff7bd5e20013bdf6fb61b12 Mon Sep 17 00:00:00 2001 From: Andrea Panattoni Date: Wed, 8 Nov 2023 13:13:24 +0100 Subject: [PATCH 04/13] Remove `log.Printf(...)` instances `"log"` package can't be tuned to a quite mode. Avoid using `log.Printf(...)` in utility methods, as they create a lot of noise in the operator logs. Signed-off-by: Andrea Panattoni --- pkg/apply/apply.go | 10 ---------- 1 file changed, 10 deletions(-) diff --git a/pkg/apply/apply.go b/pkg/apply/apply.go index f5560e993..97acc42d6 100644 --- a/pkg/apply/apply.go +++ b/pkg/apply/apply.go @@ -3,7 +3,6 @@ package apply import ( "context" "fmt" - "log" "github.com/pkg/errors" @@ -24,7 +23,6 @@ func DeleteObject(ctx context.Context, client k8sclient.Client, obj *uns.Unstruc gvk := obj.GroupVersionKind() // used for logging and errors objDesc := fmt.Sprintf("(%s) %s/%s", gvk.String(), namespace, name) - log.Printf("reconciling %s", objDesc) if err := IsObjectSupported(obj); err != nil { return errors.Wrapf(err, "object %s unsupported", objDesc) @@ -36,7 +34,6 @@ func DeleteObject(ctx context.Context, client k8sclient.Client, obj *uns.Unstruc err := client.Get(ctx, types.NamespacedName{Name: obj.GetName(), Namespace: obj.GetNamespace()}, existing) if err != nil && apierrors.IsNotFound(err) { - log.Printf("does not exist, do nothing %s", objDesc) return nil } if err != nil { @@ -45,8 +42,6 @@ func DeleteObject(ctx context.Context, client k8sclient.Client, obj *uns.Unstruc if err = client.Delete(ctx, existing); err != nil { return errors.Wrapf(err, "could not delete object %s", objDesc) - } else { - log.Printf("delete was successful") } return nil } @@ -62,7 +57,6 @@ func ApplyObject(ctx context.Context, client k8sclient.Client, obj *uns.Unstruct gvk := obj.GroupVersionKind() // used for logging and errors objDesc := fmt.Sprintf("(%s) %s/%s", gvk.String(), namespace, name) - log.Printf("reconciling %s", objDesc) if err := IsObjectSupported(obj); err != nil { return errors.Wrapf(err, "object %s unsupported", objDesc) @@ -74,12 +68,10 @@ func ApplyObject(ctx context.Context, client k8sclient.Client, obj *uns.Unstruct err := client.Get(ctx, types.NamespacedName{Name: obj.GetName(), Namespace: obj.GetNamespace()}, existing) if err != nil && apierrors.IsNotFound(err) { - log.Printf("does not exist, creating %s", objDesc) err := client.Create(ctx, obj) if err != nil { return errors.Wrapf(err, "could not create %s", objDesc) } - log.Printf("successfully created %s", objDesc) return nil } if err != nil { @@ -93,8 +85,6 @@ func ApplyObject(ctx context.Context, client k8sclient.Client, obj *uns.Unstruct if !equality.Semantic.DeepEqual(existing, obj) { if err := client.Update(ctx, obj); err != nil { return errors.Wrapf(err, "could not update object %s", objDesc) - } else { - log.Printf("update was successful %s", objDesc) } } From 446cf3ff91c91e523fc99babe8cb34280a28e19e Mon Sep 17 00:00:00 2001 From: Andrea Panattoni Date: Thu, 9 Nov 2023 12:38:10 +0100 Subject: [PATCH 05/13] Remove `number_of_node^2` log calls In `syncAllSriovNetworkNodeStates`, every node is looped for every SriovNetworkNodeState resource. This can produce up to `number_of_node^2` calls. Signed-off-by: Andrea Panattoni --- controllers/sriovnetworknodepolicy_controller.go | 1 - 1 file changed, 1 deletion(-) diff --git a/controllers/sriovnetworknodepolicy_controller.go b/controllers/sriovnetworknodepolicy_controller.go index 3ba1e4144..a131ecda8 100644 --- a/controllers/sriovnetworknodepolicy_controller.go +++ b/controllers/sriovnetworknodepolicy_controller.go @@ -276,7 +276,6 @@ func (r *SriovNetworkNodePolicyReconciler) syncAllSriovNetworkNodeStates(ctx con for _, ns := range nsList.Items { found := false for _, node := range nl.Items { - logger.Info("validate", "SriovNetworkNodeState", ns.GetName(), "node", node.GetName()) if ns.GetName() == node.GetName() { found = true break From dfc0af07e58bb2d1839bdaf6fb53811109e5985b Mon Sep 17 00:00:00 2001 From: Andrea Panattoni Date: Thu, 9 Nov 2023 12:44:22 +0100 Subject: [PATCH 06/13] Reduce SNNodePolicy reconciler verbosity Move every log call that has no effect on the clsuter to verbosity level `1`. Signed-off-by: Andrea Panattoni --- .../sriovnetworknodepolicy_controller.go | 46 +++++++++---------- 1 file changed, 23 insertions(+), 23 deletions(-) diff --git a/controllers/sriovnetworknodepolicy_controller.go b/controllers/sriovnetworknodepolicy_controller.go index a131ecda8..bf0e39895 100644 --- a/controllers/sriovnetworknodepolicy_controller.go +++ b/controllers/sriovnetworknodepolicy_controller.go @@ -197,7 +197,7 @@ func (r *SriovNetworkNodePolicyReconciler) SetupWithManager(mgr ctrl.Manager) er func (r *SriovNetworkNodePolicyReconciler) syncDevicePluginConfigMap(ctx context.Context, pl *sriovnetworkv1.SriovNetworkNodePolicyList, nl *corev1.NodeList) error { logger := log.Log.WithName("syncDevicePluginConfigMap") - logger.Info("Start to sync device plugin ConfigMap") + logger.V(1).Info("Start to sync device plugin ConfigMap") configData := make(map[string]string) for _, node := range nl.Items { @@ -231,12 +231,12 @@ func (r *SriovNetworkNodePolicyReconciler) syncDevicePluginConfigMap(ctx context if err != nil { return fmt.Errorf("couldn't create ConfigMap: %v", err) } - logger.Info("Created ConfigMap for", cm.Namespace, cm.Name) + logger.V(1).Info("Created ConfigMap for", cm.Namespace, cm.Name) } else { return fmt.Errorf("failed to get ConfigMap: %v", err) } } else { - logger.Info("ConfigMap already exists, updating") + logger.V(1).Info("ConfigMap already exists, updating") err = r.Update(ctx, cm) if err != nil { return fmt.Errorf("couldn't update ConfigMap: %v", err) @@ -247,29 +247,29 @@ func (r *SriovNetworkNodePolicyReconciler) syncDevicePluginConfigMap(ctx context func (r *SriovNetworkNodePolicyReconciler) syncAllSriovNetworkNodeStates(ctx context.Context, np *sriovnetworkv1.SriovNetworkNodePolicy, npl *sriovnetworkv1.SriovNetworkNodePolicyList, nl *corev1.NodeList) error { logger := log.Log.WithName("syncAllSriovNetworkNodeStates") - logger.Info("Start to sync all SriovNetworkNodeState custom resource") + logger.V(1).Info("Start to sync all SriovNetworkNodeState custom resource") found := &corev1.ConfigMap{} if err := r.Get(ctx, types.NamespacedName{Namespace: namespace, Name: constants.ConfigMapName}, found); err != nil { - logger.Info("Fail to get", "ConfigMap", constants.ConfigMapName) + logger.V(1).Info("Fail to get", "ConfigMap", constants.ConfigMapName) } for _, node := range nl.Items { - logger.Info("Sync SriovNetworkNodeState CR", "name", node.Name) + logger.V(1).Info("Sync SriovNetworkNodeState CR", "name", node.Name) ns := &sriovnetworkv1.SriovNetworkNodeState{} ns.Name = node.Name ns.Namespace = namespace j, _ := json.Marshal(ns) - logger.Info("SriovNetworkNodeState CR", "content", j) + logger.V(2).Info("SriovNetworkNodeState CR", "content", j) if err := r.syncSriovNetworkNodeState(ctx, np, npl, ns, &node, utils.HashConfigMap(found)); err != nil { logger.Error(err, "Fail to sync", "SriovNetworkNodeState", ns.Name) return err } } - logger.Info("Remove SriovNetworkNodeState custom resource for unselected node") + logger.V(1).Info("Remove SriovNetworkNodeState custom resource for unselected node") nsList := &sriovnetworkv1.SriovNetworkNodeStateList{} err := r.List(ctx, nsList, &client.ListOptions{}) if err != nil { if !errors.IsNotFound(err) { - logger.Info("Fail to list SriovNetworkNodeState CRs") + logger.Error(err, "Fail to list SriovNetworkNodeState CRs") return err } } else { @@ -284,7 +284,7 @@ func (r *SriovNetworkNodePolicyReconciler) syncAllSriovNetworkNodeStates(ctx con if !found { err := r.Delete(ctx, &ns, &client.DeleteOptions{}) if err != nil { - logger.Info("Fail to Delete", "SriovNetworkNodeState CR:", ns.GetName()) + logger.Error(err, "Fail to Delete", "SriovNetworkNodeState CR:", ns.GetName()) return err } } @@ -295,7 +295,7 @@ func (r *SriovNetworkNodePolicyReconciler) syncAllSriovNetworkNodeStates(ctx con func (r *SriovNetworkNodePolicyReconciler) syncSriovNetworkNodeState(ctx context.Context, np *sriovnetworkv1.SriovNetworkNodePolicy, npl *sriovnetworkv1.SriovNetworkNodePolicyList, ns *sriovnetworkv1.SriovNetworkNodeState, node *corev1.Node, cksum string) error { logger := log.Log.WithName("syncSriovNetworkNodeState") - logger.Info("Start to sync SriovNetworkNodeState", "Name", ns.Name, "cksum", cksum) + logger.V(1).Info("Start to sync SriovNetworkNodeState", "Name", ns.Name, "cksum", cksum) if err := controllerutil.SetControllerReference(np, ns, r.Scheme); err != nil { return err @@ -303,7 +303,7 @@ func (r *SriovNetworkNodePolicyReconciler) syncSriovNetworkNodeState(ctx context found := &sriovnetworkv1.SriovNetworkNodeState{} err := r.Get(ctx, types.NamespacedName{Namespace: ns.Namespace, Name: ns.Name}, found) if err != nil { - logger.Info("Fail to get SriovNetworkNodeState", "namespace", ns.Namespace, "name", ns.Name) + logger.Error(err, "Fail to get SriovNetworkNodeState", "namespace", ns.Namespace, "name", ns.Name) if errors.IsNotFound(err) { ns.Spec.DpConfigVersion = cksum err = r.Create(ctx, ns) @@ -321,7 +321,7 @@ func (r *SriovNetworkNodePolicyReconciler) syncSriovNetworkNodeState(ctx context return nil } - logger.Info("SriovNetworkNodeState already exists, updating") + logger.V(1).Info("SriovNetworkNodeState already exists, updating") newVersion := found.DeepCopy() newVersion.Spec = ns.Spec @@ -350,7 +350,7 @@ func (r *SriovNetworkNodePolicyReconciler) syncSriovNetworkNodeState(ctx context } newVersion.Spec.DpConfigVersion = cksum if equality.Semantic.DeepEqual(newVersion.Spec, found.Spec) { - logger.Info("SriovNetworkNodeState did not change, not updating") + logger.V(1).Info("SriovNetworkNodeState did not change, not updating") return nil } err = r.Update(ctx, newVersion) @@ -363,7 +363,7 @@ func (r *SriovNetworkNodePolicyReconciler) syncSriovNetworkNodeState(ctx context func (r *SriovNetworkNodePolicyReconciler) syncPluginDaemonObjs(ctx context.Context, operatorConfig *sriovnetworkv1.SriovOperatorConfig, dp *sriovnetworkv1.SriovNetworkNodePolicy, pl *sriovnetworkv1.SriovNetworkNodePolicyList) error { logger := log.Log.WithName("syncPluginDaemonObjs") - logger.Info("Start to sync sriov daemons objects") + logger.V(1).Info("Start to sync sriov daemons objects") // render plugin manifests data := render.MakeRenderData() @@ -486,7 +486,7 @@ func (r *SriovNetworkNodePolicyReconciler) deleteK8sResource(ctx context.Context func (r *SriovNetworkNodePolicyReconciler) syncDsObject(ctx context.Context, dp *sriovnetworkv1.SriovNetworkNodePolicy, pl *sriovnetworkv1.SriovNetworkNodePolicyList, obj *uns.Unstructured) error { logger := log.Log.WithName("syncDsObject") kind := obj.GetKind() - logger.Info("Start to sync Objects", "Kind", kind) + logger.V(1).Info("Start to sync Objects", "Kind", kind) switch kind { case "ServiceAccount", "Role", "RoleBinding": if err := controllerutil.SetControllerReference(dp, obj, r.Scheme); err != nil { @@ -510,7 +510,7 @@ func (r *SriovNetworkNodePolicyReconciler) syncDsObject(ctx context.Context, dp func (r *SriovNetworkNodePolicyReconciler) syncDaemonSet(ctx context.Context, cr *sriovnetworkv1.SriovNetworkNodePolicy, pl *sriovnetworkv1.SriovNetworkNodePolicyList, in *appsv1.DaemonSet) error { logger := log.Log.WithName("syncDaemonSet") - logger.Info("Start to sync DaemonSet", "Namespace", in.Namespace, "Name", in.Name) + logger.V(1).Info("Start to sync DaemonSet", "Namespace", in.Namespace, "Name", in.Name) var err error if pl != nil { @@ -536,7 +536,7 @@ func (r *SriovNetworkNodePolicyReconciler) syncDaemonSet(ctx context.Context, cr return err } } else { - logger.Info("DaemonSet already exists, updating") + logger.V(1).Info("DaemonSet already exists, updating") // DeepDerivative checks for changes only comparing non zero fields in the source struct. // This skips default values added by the api server. // References in https://github.com/kubernetes-sigs/kubebuilder/issues/592#issuecomment-625738183 @@ -545,7 +545,7 @@ func (r *SriovNetworkNodePolicyReconciler) syncDaemonSet(ctx context.Context, cr // https://bugzilla.redhat.com/show_bug.cgi?id=1914066 if equality.Semantic.DeepEqual(in.Spec.Template.Spec.Affinity.NodeAffinity, ds.Spec.Template.Spec.Affinity.NodeAffinity) { - logger.Info("Daemonset spec did not change, not updating") + logger.V(1).Info("Daemonset spec did not change, not updating") return nil } } @@ -604,7 +604,7 @@ func nodeSelectorTermsForPolicyList(policies []sriovnetworkv1.SriovNetworkNodePo // renderDsForCR returns a busybox pod with the same name/namespace as the cr func renderDsForCR(path string, data *render.RenderData) ([]*uns.Unstructured, error) { logger := log.Log.WithName("renderDsForCR") - logger.Info("Start to render objects") + logger.V(1).Info("Start to render objects") objs, err := render.RenderDir(path, data) if err != nil { @@ -615,7 +615,7 @@ func renderDsForCR(path string, data *render.RenderData) ([]*uns.Unstructured, e func (r *SriovNetworkNodePolicyReconciler) renderDevicePluginConfigData(ctx context.Context, pl *sriovnetworkv1.SriovNetworkNodePolicyList, node *corev1.Node) (dptypes.ResourceConfList, error) { logger := log.Log.WithName("renderDevicePluginConfigData") - logger.Info("Start to render device plugin config data", "node", node.Name) + logger.V(1).Info("Start to render device plugin config data", "node", node.Name) rcl := dptypes.ResourceConfList{} for _, p := range pl.Items { if p.Name == constants.DefaultPolicyName { @@ -640,14 +640,14 @@ func (r *SriovNetworkNodePolicyReconciler) renderDevicePluginConfigData(ctx cont if err != nil { return rcl, err } - logger.Info("Update resource", "Resource", rcl.ResourceList[i]) + logger.V(1).Info("Update resource", "Resource", rcl.ResourceList[i]) } else { rc, err := createDevicePluginResource(ctx, &p, nodeState) if err != nil { return rcl, err } rcl.ResourceList = append(rcl.ResourceList, *rc) - logger.Info("Add resource", "Resource", *rc) + logger.V(1).Info("Add resource", "Resource", *rc) } } return rcl, nil From ab293b5f9c9bc7a73abf45ab41a3ac517a00d7fa Mon Sep 17 00:00:00 2001 From: Andrea Panattoni Date: Fri, 10 Nov 2023 12:08:53 +0100 Subject: [PATCH 07/13] Reduce SriovOpConfig reconciler verbosity Move every log call that has no effect on the clsuter to verbosity level `1`. Signed-off-by: Andrea Panattoni --- controllers/sriovoperatorconfig_controller.go | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/controllers/sriovoperatorconfig_controller.go b/controllers/sriovoperatorconfig_controller.go index cfbeeb3cc..65727fa2b 100644 --- a/controllers/sriovoperatorconfig_controller.go +++ b/controllers/sriovoperatorconfig_controller.go @@ -152,7 +152,7 @@ func (r *SriovOperatorConfigReconciler) SetupWithManager(mgr ctrl.Manager) error func (r *SriovOperatorConfigReconciler) syncPluginDaemonSet(ctx context.Context, dc *sriovnetworkv1.SriovOperatorConfig) error { logger := log.Log.WithName("syncConfigDaemonset") - logger.Info("Start to sync SRIOV plugin daemonsets nodeSelector") + logger.V(1).Info("Start to sync SRIOV plugin daemonsets nodeSelector") ds := &appsv1.DaemonSet{} names := []string{"sriov-cni", "sriov-device-plugin"} @@ -183,7 +183,7 @@ func (r *SriovOperatorConfigReconciler) syncPluginDaemonSet(ctx context.Context, func (r *SriovOperatorConfigReconciler) syncConfigDaemonSet(ctx context.Context, dc *sriovnetworkv1.SriovOperatorConfig) error { logger := log.Log.WithName("syncConfigDaemonset") - logger.Info("Start to sync config daemonset") + logger.V(1).Info("Start to sync config daemonset") data := render.MakeRenderData() data.Data["Image"] = os.Getenv("SRIOV_NETWORK_CONFIG_DAEMON_IMAGE") @@ -204,7 +204,7 @@ func (r *SriovOperatorConfigReconciler) syncConfigDaemonSet(ctx context.Context, if envCniBinPath == "" { data.Data["CNIBinPath"] = "/var/lib/cni/bin" } else { - logger.Info("New cni bin found", "CNIBinPath", envCniBinPath) + logger.V(1).Info("New cni bin found", "CNIBinPath", envCniBinPath) data.Data["CNIBinPath"] = envCniBinPath } objs, err := render.RenderDir(constants.ConfigDaemonPath, &data) @@ -240,7 +240,7 @@ func (r *SriovOperatorConfigReconciler) syncConfigDaemonSet(ctx context.Context, func (r *SriovOperatorConfigReconciler) syncWebhookObjs(ctx context.Context, dc *sriovnetworkv1.SriovOperatorConfig) error { logger := log.Log.WithName("syncWebhookObjs") - logger.Info("Start to sync webhook objects") + logger.V(1).Info("Start to sync webhook objects") for name, path := range webhooks { // Render Webhook manifests From 81e02097e9426cfcb652afc7315a7f138666a8d2 Mon Sep 17 00:00:00 2001 From: Andrea Panattoni Date: Thu, 9 Nov 2023 13:09:19 +0100 Subject: [PATCH 08/13] SriovOperatorConfig.LogLevel e2e tests Signed-off-by: Andrea Panattoni --- .../sriovnetworknodepolicy_controller.go | 1 + test/conformance/tests/test_sriov_operator.go | 136 ++++++++++++++++++ 2 files changed, 137 insertions(+) diff --git a/controllers/sriovnetworknodepolicy_controller.go b/controllers/sriovnetworknodepolicy_controller.go index bf0e39895..3d1da743f 100644 --- a/controllers/sriovnetworknodepolicy_controller.go +++ b/controllers/sriovnetworknodepolicy_controller.go @@ -102,6 +102,7 @@ func (r *SriovNetworkNodePolicyReconciler) Reconcile(ctx context.Context, req ct reqLogger.Error(err, "Failed to create default Policy", "Namespace", namespace, "Name", constants.DefaultPolicyName) return reconcile.Result{}, err } + reqLogger.Info("Default policy created") return reconcile.Result{}, nil } // Error reading the object - requeue the request. diff --git a/test/conformance/tests/test_sriov_operator.go b/test/conformance/tests/test_sriov_operator.go index 6f73f93b5..2102b367f 100644 --- a/test/conformance/tests/test_sriov_operator.go +++ b/test/conformance/tests/test_sriov_operator.go @@ -188,6 +188,82 @@ var _ = Describe("[sriov] operator", func() { }) }) + Context("LogLevel affects operator's logs", func() { + It("when set to 0 no lifecycle logs are present", func() { + if discovery.Enabled() { + Skip("Test unsuitable to be run in discovery mode") + } + + initialLogLevelValue := getOperatorConfigLogLevel() + DeferCleanup(func() { + By("Restore LogLevel to its initial value") + setOperatorConfigLogLevel(initialLogLevelValue) + }) + + initialDisableDrain, err := cluster.GetNodeDrainState(clients, operatorNamespace) + Expect(err).ToNot(HaveOccurred()) + + DeferCleanup(func() { + By("Restore DisableDrain to its initial value") + Eventually(func() error { + return cluster.SetDisableNodeDrainState(clients, operatorNamespace, initialDisableDrain) + }, 1*time.Minute, 5*time.Second).ShouldNot(HaveOccurred()) + }) + + By("Set operator LogLevel to 2") + setOperatorConfigLogLevel(2) + + By("Flip DisableDrain to trigger operator activity") + since := time.Now() + Eventually(func() error { + return cluster.SetDisableNodeDrainState(clients, operatorNamespace, !initialDisableDrain) + }, 1*time.Minute, 5*time.Second).ShouldNot(HaveOccurred()) + + By("Assert logs contains verbose output") + Eventually(func(g Gomega) { + logs := getOperatorLogs(since) + g.Expect(logs).To( + ContainElement(And( + ContainSubstring("Reconciling SriovOperatorConfig"), + )), + ) + + // Should contain verbose logging + g.Expect(logs).To( + ContainElement( + ContainSubstring("Start to sync webhook objects"), + ), + ) + }, 1*time.Minute, 5*time.Second).Should(Succeed()) + + By("Reduce operator LogLevel to 0") + setOperatorConfigLogLevel(0) + + By("Flip DisableDrain again to trigger operator activity") + since = time.Now() + Eventually(func() error { + return cluster.SetDisableNodeDrainState(clients, operatorNamespace, initialDisableDrain) + }, 1*time.Minute, 5*time.Second).ShouldNot(HaveOccurred()) + + By("Assert logs contains less operator activity") + Eventually(func(g Gomega) { + logs := getOperatorLogs(since) + g.Expect(logs).To( + ContainElement(And( + ContainSubstring("Reconciling SriovOperatorConfig"), + )), + ) + + // Should not contain verbose logging + g.Expect(logs).ToNot( + ContainElement( + ContainSubstring("Start to sync webhook objects"), + ), + ) + }, 1*time.Minute, 5*time.Second).Should(Succeed()) + + }) + }) }) Describe("Generic SriovNetworkNodePolicy", func() { @@ -2513,6 +2589,66 @@ func setSriovOperatorSpecFlag(flagName string, flagValue bool) { } } +func setOperatorConfigLogLevel(level int) { + instantBeforeSettingLogLevel := time.Now() + + Eventually(func(g Gomega) { + cfg := sriovv1.SriovOperatorConfig{} + err := clients.Get(context.TODO(), runtimeclient.ObjectKey{ + Name: "default", + Namespace: operatorNamespace, + }, &cfg) + g.Expect(err).ToNot(HaveOccurred()) + + if cfg.Spec.LogLevel == level { + return + } + + cfg.Spec.LogLevel = level + + err = clients.Update(context.TODO(), &cfg) + g.Expect(err).ToNot(HaveOccurred()) + + logs := getOperatorLogs(instantBeforeSettingLogLevel) + g.Expect(logs).To( + ContainElement( + ContainSubstring(fmt.Sprintf(`"new-level": %d`, level)), + ), + ) + }, 1*time.Minute, 5*time.Second).Should(Succeed()) +} + +func getOperatorConfigLogLevel() int { + cfg := sriovv1.SriovOperatorConfig{} + err := clients.Get(context.TODO(), runtimeclient.ObjectKey{ + Name: "default", + Namespace: operatorNamespace, + }, &cfg) + Expect(err).ToNot(HaveOccurred()) + + return cfg.Spec.LogLevel +} + +func getOperatorLogs(since time.Time) []string { + podList, err := clients.Pods(operatorNamespace).List(context.Background(), metav1.ListOptions{ + LabelSelector: "name=sriov-network-operator", + }) + ExpectWithOffset(1, err).ToNot(HaveOccurred()) + ExpectWithOffset(1, podList.Items).To(HaveLen(1), "One operator pod expected") + + pod := podList.Items[0] + logStart := metav1.NewTime(since) + rawLogs, err := clients.Pods(pod.Namespace). + GetLogs(pod.Name, &corev1.PodLogOptions{ + Container: pod.Spec.Containers[0].Name, + SinceTime: &logStart, + }). + DoRaw(context.Background()) + ExpectWithOffset(1, err).ToNot(HaveOccurred()) + + return strings.Split(string(rawLogs), "\n") +} + func assertObjectIsNotFound(name string, obj runtimeclient.Object) { Eventually(func() bool { err := clients.Get(context.Background(), runtimeclient.ObjectKey{Name: name, Namespace: operatorNamespace}, obj) From 476539bbfdb7ae8919c9b83ab3cf6c7d6399167f Mon Sep 17 00:00:00 2001 From: Vasilis Remmas Date: Fri, 24 Nov 2023 10:21:14 +0100 Subject: [PATCH 09/13] Rely on default error msg from which cmd Signed-off-by: Vasilis Remmas --- .../files/switchdev-configuration-before-nm.sh.yaml | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/bindata/manifests/switchdev-config/files/switchdev-configuration-before-nm.sh.yaml b/bindata/manifests/switchdev-config/files/switchdev-configuration-before-nm.sh.yaml index 2560450d0..6455716f8 100644 --- a/bindata/manifests/switchdev-config/files/switchdev-configuration-before-nm.sh.yaml +++ b/bindata/manifests/switchdev-config/files/switchdev-configuration-before-nm.sh.yaml @@ -13,7 +13,7 @@ contents: exit fi - which jq 2>&1 >/dev/null || (echo "Required tool jq is not found in PATH." && exit 1) + which jq append_to_file(){ content="$1" From 5cddfbc2c4a846358b7fdcb7e94745e725d150d3 Mon Sep 17 00:00:00 2001 From: Andrea Panattoni Date: Fri, 24 Nov 2023 11:08:52 +0100 Subject: [PATCH 10/13] envtest: Stick to a specific setup-envtest version Using `@latest` for tools dependecies produces unrepeatable builds which might break at any point in time. This is particularly important when maintaining released versions which need a backport fix. Note: At the moment is not possible to reference the package `sigs.k8s.io/controller-runtime/tools/setup-envtest` with a specific version: ``` go: sigs.k8s.io/controller-runtime/tools/setup-envtest@v0.16.3: module sigs.k8s.io/controller-runtime@v0.16.3 found, but does not contain package sigs.k8s.io/controller-runtime/tools/setup-envtest ``` See https://github.com/kubernetes-sigs/kubebuilder/issues/2480 Ref: https://github.com/openshift/sriov-network-operator/pull/849 Signed-off-by: Andrea Panattoni --- Makefile | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/Makefile b/Makefile index 341e20e2c..5c1c83df9 100644 --- a/Makefile +++ b/Makefile @@ -150,7 +150,7 @@ kustomize: ## Download kustomize locally if necessary. ENVTEST = $(BIN_DIR)/setup-envtest envtest: ## Download envtest-setup locally if necessary. - $(call go-install-tool,$(ENVTEST),sigs.k8s.io/controller-runtime/tools/setup-envtest@latest) + $(call go-install-tool,$(ENVTEST),sigs.k8s.io/controller-runtime/tools/setup-envtest@release-0.16) GOMOCK = $(shell pwd)/bin/mockgen gomock: From cc61bec81aecd62d24f5bb7b0b0d21ab48425dba Mon Sep 17 00:00:00 2001 From: ianb-mp <151477169+ianb-mp@users.noreply.github.com> Date: Thu, 7 Dec 2023 08:38:35 +1000 Subject: [PATCH 11/13] Update Makefile --- Makefile | 3 +-- 1 file changed, 1 insertion(+), 2 deletions(-) diff --git a/Makefile b/Makefile index 5c1c83df9..9a9fb7d57 100644 --- a/Makefile +++ b/Makefile @@ -171,12 +171,11 @@ skopeo: fakechroot: if ! which fakechroot; then if [ -f /etc/redhat-release ]; then dnf -y install fakechroot; elif [ -f /etc/lsb-release ]; then sudo apt-get -y update; sudo apt-get -y install fakechroot; fi; fi -deploy-setup: export ENABLE_ADMISSION_CONTROLLER?=true +deploy-setup: export ENABLE_ADMISSION_CONTROLLER?=false deploy-setup: skopeo install hack/deploy-setup.sh $(NAMESPACE) deploy-setup-k8s: export NAMESPACE=sriov-network-operator -deploy-setup-k8s: export ENABLE_ADMISSION_CONTROLLER?=false deploy-setup-k8s: export CNI_BIN_PATH=/opt/cni/bin deploy-setup-k8s: export OPERATOR_EXEC=kubectl deploy-setup-k8s: export CLUSTER_TYPE=kubernetes From 182214532c8bde955afcf8422ed1ad207ae32e60 Mon Sep 17 00:00:00 2001 From: Vasilis Remmas Date: Fri, 15 Dec 2023 08:21:32 +0100 Subject: [PATCH 12/13] Ignore nil objects occured when rendering a file This commits addresses an edge case where a nil object can occur while rendering a file. In that situation, in one of the places the renderer is used, it will try to add ownership to a nil object and fail. Signed-off-by: Vasilis Remmas --- pkg/render/render.go | 5 ++++ pkg/render/render_test.go | 23 ++++++++++++++++++- .../manifests/template_with_empty_object.yaml | 20 ++++++++++++++++ 3 files changed, 47 insertions(+), 1 deletion(-) create mode 100644 pkg/render/testdata/manifests/template_with_empty_object.yaml diff --git a/pkg/render/render.go b/pkg/render/render.go index 394553a07..8763cc8f0 100644 --- a/pkg/render/render.go +++ b/pkg/render/render.go @@ -103,6 +103,11 @@ func RenderTemplate(path string, d *RenderData) ([]*unstructured.Unstructured, e } return nil, errors.Wrapf(err, "failed to unmarshal manifest %s", path) } + + if u.Object == nil { + continue + } + out = append(out, &u) } diff --git a/pkg/render/render_test.go b/pkg/render/render_test.go index 2e607bfa9..be4d0f0bd 100644 --- a/pkg/render/render_test.go +++ b/pkg/render/render_test.go @@ -85,14 +85,35 @@ func TestTemplate(t *testing.T) { g.Expect(o[0].Object["bar"]).To(Equal("myns")) } +// TestTemplateWithEmptyObject tests the case where a file generates additional nil objects when rendered. An empty +// object can also occur in the particular case shown in the testfile below when minus is missing at the end of the +// first expression (i.e. {{- if .Enable }}). +func TestTemplateWithEmptyObject(t *testing.T) { + g := NewGomegaWithT(t) + + p := "testdata/manifests/template_with_empty_object.yaml" + + d := MakeRenderData() + d.Data["Enable"] = true + o, err := RenderTemplate(p, &d) + g.Expect(err).NotTo(HaveOccurred()) + + g.Expect(len(o)).To(Equal(2)) + g.Expect(o[0].GetName()).To(Equal("pod1")) + g.Expect(o[0].GetNamespace()).To(Equal("namespace1")) + g.Expect(o[1].GetName()).To(Equal("pod2")) + g.Expect(o[1].GetNamespace()).To(Equal("namespace2")) +} + func TestRenderDir(t *testing.T) { g := NewGomegaWithT(t) d := MakeRenderData() d.Funcs["fname"] = func(s string) string { return s } d.Data["Namespace"] = "myns" + d.Data["Enable"] = true o, err := RenderDir("testdata/manifests", &d) g.Expect(err).NotTo(HaveOccurred()) - g.Expect(o).To(HaveLen(6)) + g.Expect(o).To(HaveLen(8)) } diff --git a/pkg/render/testdata/manifests/template_with_empty_object.yaml b/pkg/render/testdata/manifests/template_with_empty_object.yaml new file mode 100644 index 000000000..a3b5a5de3 --- /dev/null +++ b/pkg/render/testdata/manifests/template_with_empty_object.yaml @@ -0,0 +1,20 @@ +{{- if .Enable }} +--- +apiVersion: v1 +kind: Pod +metadata: + namespace: namespace1 + name: pod1 +spec: + containers: + - image: "busybox" +--- +apiVersion: v1 +kind: Pod +metadata: + namespace: namespace2 + name: pod2 +spec: + containers: + - image: "busybox" +{{- end }} From 29fb02be49b5c367b2ab02176b534410bc080980 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Martin=20Andr=C3=A9?= Date: Tue, 19 Dec 2023 18:29:40 +0100 Subject: [PATCH 13/13] Fix number of args passed to log.Info This fix a crash: ``` DPANIC sriovnetwork webhook/validate.go:446 odd number of arguments passed as key-value pairs for logging {"ignored key": "10ed"} ``` --- api/v1/helper.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/api/v1/helper.go b/api/v1/helper.go index c2725f7c2..ba2429caf 100644 --- a/api/v1/helper.go +++ b/api/v1/helper.go @@ -132,7 +132,7 @@ func IsVfSupportedModel(vendorID, deviceID string) bool { return true } } - log.Info("IsVfSupportedModel():", "Unsupported VF model:", "vendorId:", vendorID, "deviceId:", deviceID) + log.Info("IsVfSupportedModel(): found unsupported VF model", "vendorId:", vendorID, "deviceId:", deviceID) return false }