From 03704aa93cdd529dd28196507d6a7f59e162a59a Mon Sep 17 00:00:00 2001 From: Ivan Mikheykin Date: Wed, 14 Feb 2024 12:10:03 +0300 Subject: [PATCH] fix: mute noisy log messages by default (#10) ## Description - Use level 4 for trace messages like UpdateMetadata and UpdateStatus. - Add messages to distinguish reconcile steps. - Add message with reconcile result to see if requeue was requested. ## Why do we need it, and what problem does it solve? UpdateMetadata and UpdateStatus are too noisy for default debug log level. ## What is the expected result? Developer should change VERBOSITY to 4 to see more detailed huge logs. ## Checklist - [ ] The code is covered by unit tests. - [ ] e2e tests passed. - [ ] Documentation updated according to the changes. - [x] Changes were tested in the Kubernetes cluster manually. Signed-off-by: Ivan Mikheykin --- .../pkg/sdk/framework/helper/resource.go | 7 +++---- .../two_phase_reconciler/reconciler_core.go | 18 ++++++++++++++---- 2 files changed, 17 insertions(+), 8 deletions(-) diff --git a/images/virtualization-controller/pkg/sdk/framework/helper/resource.go b/images/virtualization-controller/pkg/sdk/framework/helper/resource.go index b81a2a5f3..d5f501c0b 100644 --- a/images/virtualization-controller/pkg/sdk/framework/helper/resource.go +++ b/images/virtualization-controller/pkg/sdk/framework/helper/resource.go @@ -96,20 +96,19 @@ func (r *Resource[T, ST]) UpdateMeta(ctx context.Context) error { return nil } - r.log.Info("UpdateMeta obj before update", "currentObj", r.currentObj.GetObjectMeta(), "changedObj", r.changedObj.GetObjectMeta()) + r.log.V(4).Info("UpdateMeta obj meta before update", "currentObj", r.currentObj.GetObjectMeta(), "changedObj", r.changedObj.GetObjectMeta()) if !reflect.DeepEqual(r.getObjStatus(r.currentObj), r.getObjStatus(r.changedObj)) { return fmt.Errorf("status update is not allowed in the meta updater: %#v changed to %#v", r.getObjStatus(r.currentObj), r.getObjStatus(r.changedObj)) } - r.log.V(4).Info("UpdateMeta obj meta before update", "currentObj.ObjectMeta", r.currentObj.GetObjectMeta(), "changedObj.ObjectMeta", r.changedObj.GetObjectMeta()) if !reflect.DeepEqual(r.currentObj.GetObjectMeta(), r.changedObj.GetObjectMeta()) { if err := r.client.Update(ctx, r.changedObj); err != nil { return fmt.Errorf("error updating: %w", err) } r.currentObj = r.changedObj.DeepCopy() - r.log.V(1).Info("UpdateStatus applied", "obj", r.currentObj.GetObjectKind().GroupVersionKind().Kind+"/"+r.currentObj.GetName()) + r.log.V(1).Info("UpdateMeta applied", "obj", r.currentObj.GetObjectKind().GroupVersionKind().Kind+"/"+r.currentObj.GetName()) r.log.V(4).Info("UpdateMeta obj meta after update", "changedObj.ObjectMeta", r.changedObj.GetObjectMeta()) } else { - r.log.V(4).Info("UpdateMeta skipped: no changes", "currentObj.ObjectMeta", r.currentObj.GetObjectMeta()) + r.log.V(2).Info("UpdateMeta skipped: no changes", "currentObj.ObjectMeta", r.currentObj.GetObjectMeta()) } return nil } diff --git a/images/virtualization-controller/pkg/sdk/framework/two_phase_reconciler/reconciler_core.go b/images/virtualization-controller/pkg/sdk/framework/two_phase_reconciler/reconciler_core.go index 4fbf18c50..f6aab0a4b 100644 --- a/images/virtualization-controller/pkg/sdk/framework/two_phase_reconciler/reconciler_core.go +++ b/images/virtualization-controller/pkg/sdk/framework/two_phase_reconciler/reconciler_core.go @@ -35,6 +35,7 @@ func NewReconcilerCore[T ReconcilerState](reconciler TwoPhaseReconciler[T], stat } func (r *ReconcilerCore[T]) Reconcile(ctx context.Context, req reconcile.Request) (reconcile.Result, error) { + r.ReconcilerOptions.Log.V(3).Info(fmt.Sprintf("Start Reconcile for %s", req.String()), "obj", req.String()) state := r.StateFactory(req.NamespacedName, r.Log, r.Client, r.Cache) if err := state.Reload(ctx, req, r.Log, r.Client); err != nil { @@ -45,15 +46,17 @@ func (r *ReconcilerCore[T]) Reconcile(ctx context.Context, req reconcile.Request var resErr error if state.ShouldReconcile(r.Log) { - r.Log.V(4).Info("sync phase begin") syncErr := r.sync(ctx, req, state) resErr = syncErr res = state.GetReconcilerResult() - r.Log.V(4).Info("sync phase end") + if res != nil { + r.Log.V(3).Info(fmt.Sprintf("Reconcile result after Sync: %+v", res), "obj", req.String()) + } + } else { + r.Log.V(3).Info("No Sync required", "obj", req.String()) } if state.ShouldReconcile(r.Log) { - r.Log.V(4).Info("update status phase begin") updateStatusErr := r.updateStatus(ctx, req, state) if res == nil { res = state.GetReconcilerResult() @@ -61,19 +64,24 @@ func (r *ReconcilerCore[T]) Reconcile(ctx context.Context, req reconcile.Request if resErr == nil { resErr = updateStatusErr } - r.Log.V(4).Info("update status phase end") + } else { + r.Log.V(3).Info("No UpdateStatus after Sync", "obj", req.String()) } if res == nil { res = &reconcile.Result{} } + r.Log.V(3).Info(fmt.Sprintf("Reconcile result after UpdateStatus: %+v", res), "obj", req.String()) + return *res, resErr } func (r *ReconcilerCore[T]) sync(ctx context.Context, req reconcile.Request, state T) error { + r.ReconcilerOptions.Log.V(3).Info("Call Sync", "obj", req.String()) if err := r.Reconciler.Sync(ctx, req, state, r.ReconcilerOptions); err != nil { return err } + r.ReconcilerOptions.Log.V(3).Info("Call ApplySync", "obj", req.String()) if err := state.ApplySync(ctx, r.Log); err != nil { return fmt.Errorf("unable to apply sync changes: %w", err) } @@ -81,9 +89,11 @@ func (r *ReconcilerCore[T]) sync(ctx context.Context, req reconcile.Request, sta } func (r *ReconcilerCore[T]) updateStatus(ctx context.Context, req reconcile.Request, state T) error { + r.ReconcilerOptions.Log.V(3).Info("Call UpdateStatus", "obj", req.String()) if err := r.Reconciler.UpdateStatus(ctx, req, state, r.ReconcilerOptions); err != nil { return fmt.Errorf("update status phase failed: %w", err) } + r.ReconcilerOptions.Log.V(3).Info("Call ApplyUpdateStatus", "obj", req.String()) if err := state.ApplyUpdateStatus(ctx, r.Log); err != nil { return fmt.Errorf("apply update status failed: %w", err) }