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 <[email protected]>

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
 }

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,45 +46,54 @@ 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()
 		}
 		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)
 	}
 	return nil
 }
 
 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)
 	}