Improve logging in VolumeReplicationGroup controller #2318

ELENAGER · 2025-10-30T08:13:53Z

Remove noisy/non-informative logs, add context to critical log entries, and log at a higher scope than PVC to avoid repeated lines.

asn1809

Nice, helps reading logs in good manner.

nirs · 2025-10-30T09:52:11Z

internal/controller/volumereplicationgroup_controller.go

+		v.log.Info("Separate PVCs using only StorageClass provisioner")
+	} else {
+		v.log.Info("Separate PVCs using peerClasses")
+	}


This looks like a debugging log about how we handle the PVCs. Move the debug level?

We hardly use debug level, and adding logs at that level is not my choice. This instance can be root caused inspecting the VRG resource and looking at peerClass elements, and I would as such remove this log.

internal/controller/vrg_volgrouprep.go

nirs · 2025-10-30T09:57:55Z

internal/controller/vrg_volrep.go

 		return nil, fmt.Errorf("no %s found to match provisioner and schedule", objType)
 	case 1:
-		v.log.Info(fmt.Sprintf("Found %s that matches provisioner and schedule %s/%s", objType,
-			storageClass.Provisioner, v.instance.Spec.Async.SchedulingInterval))


Do we log the result of this search later?

Logging what we found once makes sense. If we don't log it elsewhere this may be a debug log that will help understanding what the system is doing.

@nirs the problem here is that we are logging it for each PVC and then we see the following (all logs for only one VRG with 10 PVC during one reconcile request):

2025-10-29T11:37:36.113Z INFO vrg controller/vrg_volrep.go:1451 Found VolumeGroupReplicationClass that matches provisioner and schedule openshift-storage.rbd.csi.ceph.com/5m {"vrg": {"name":"cg-app-1","namespace":"openshift-dr-ops"}, "rid": "31b5bd24"} 2025-10-29T11:37:36.113Z INFO vrg controller/vrg_volrep.go:1451 Found VolumeGroupReplicationClass that matches provisioner and schedule openshift-storage.rbd.csi.ceph.com/5m {"vrg": {"name":"cg-app-1","namespace":"openshift-dr-ops"}, "rid": "31b5bd24"} 2025-10-29T11:37:36.113Z INFO vrg controller/vrg_volrep.go:1451 Found VolumeGroupReplicationClass that matches provisioner and schedule openshift-storage.rbd.csi.ceph.com/5m {"vrg": {"name":"cg-app-1","namespace":"openshift-dr-ops"}, "rid": "31b5bd24"} 2025-10-29T11:37:36.113Z INFO vrg controller/vrg_volrep.go:1451 Found VolumeGroupReplicationClass that matches provisioner and schedule openshift-storage.rbd.csi.ceph.com/5m {"vrg": {"name":"cg-app-1","namespace":"openshift-dr-ops"}, "rid": "31b5bd24"} 2025-10-29T11:37:36.113Z INFO vrg controller/vrg_volrep.go:1451 Found VolumeGroupReplicationClass that matches provisioner and schedule openshift-storage.rbd.csi.ceph.com/5m {"vrg": {"name":"cg-app-1","namespace":"openshift-dr-ops"}, "rid": "31b5bd24"} 2025-10-29T11:37:36.113Z INFO vrg controller/vrg_volrep.go:1451 Found VolumeGroupReplicationClass that matches provisioner and schedule openshift-storage.rbd.csi.ceph.com/5m {"vrg": {"name":"cg-app-1","namespace":"openshift-dr-ops"}, "rid": "31b5bd24"} 2025-10-29T11:37:36.113Z INFO vrg controller/vrg_volrep.go:1451 Found VolumeGroupReplicationClass that matches provisioner and schedule openshift-storage.rbd.csi.ceph.com/5m {"vrg": {"name":"cg-app-1","namespace":"openshift-dr-ops"}, "rid": "31b5bd24"} 2025-10-29T11:37:36.113Z INFO vrg controller/vrg_volrep.go:1451 Found VolumeGroupReplicationClass that matches provisioner and schedule openshift-storage.rbd.csi.ceph.com/5m {"vrg": {"name":"cg-app-1","namespace":"openshift-dr-ops"}, "rid": "31b5bd24"} 2025-10-29T11:37:36.113Z INFO vrg controller/vrg_volrep.go:1451 Found VolumeGroupReplicationClass that matches provisioner and schedule openshift-storage.rbd.csi.ceph.com/5m {"vrg": {"name":"cg-app-1","namespace":"openshift-dr-ops"}, "rid": "31b5bd24"} 2025-10-29T11:37:36.113Z INFO vrg controller/vrg_volrep.go:1451 Found VolumeGroupReplicationClass that matches provisioner and schedule openshift-storage.rbd.csi.ceph.com/5m {"vrg": {"name":"cg-app-1","namespace":"openshift-dr-ops"}, "rid": "31b5bd24"} 2025-10-29T11:37:36.206Z INFO vrg controller/vrg_volrep.go:1451 Found VolumeGroupReplicationClass that matches provisioner and schedule openshift-storage.rbd.csi.ceph.com/5m {"vrg": {"name":"cg-app-1","namespace":"openshift-dr-ops"}, "rid": "31b5bd24", "State": "primary"} 2025-10-29T11:37:36.206Z INFO vrg controller/vrg_volrep.go:1451 Found VolumeGroupReplicationClass that matches provisioner and schedule openshift-storage.rbd.csi.ceph.com/5m {"vrg": {"name":"cg-app-1","namespace":"openshift-dr-ops"}, "rid": "31b5bd24", "State": "primary"} 2025-10-29T11:37:36.206Z INFO vrg controller/vrg_volrep.go:1451 Found VolumeGroupReplicationClass that matches provisioner and schedule openshift-storage.rbd.csi.ceph.com/5m {"vrg": {"name":"cg-app-1","namespace":"openshift-dr-ops"}, "rid": "31b5bd24", "State": "primary"} 2025-10-29T11:37:36.206Z INFO vrg controller/vrg_volrep.go:1451 Found VolumeGroupReplicationClass that matches provisioner and schedule openshift-storage.rbd.csi.ceph.com/5m {"vrg": {"name":"cg-app-1","namespace":"openshift-dr-ops"}, "rid": "31b5bd24", "State": "primary"} 2025-10-29T11:37:36.206Z INFO vrg controller/vrg_volrep.go:1451 Found VolumeGroupReplicationClass that matches provisioner and schedule openshift-storage.rbd.csi.ceph.com/5m {"vrg": {"name":"cg-app-1","namespace":"openshift-dr-ops"}, "rid": "31b5bd24", "State": "primary"} 2025-10-29T11:37:36.206Z INFO vrg controller/vrg_volrep.go:1451 Found VolumeGroupReplicationClass that matches provisioner and schedule openshift-storage.rbd.csi.ceph.com/5m {"vrg": {"name":"cg-app-1","namespace":"openshift-dr-ops"}, "rid": "31b5bd24", "State": "primary"} 2025-10-29T11:37:36.206Z INFO vrg controller/vrg_volrep.go:1451 Found VolumeGroupReplicationClass that matches provisioner and schedule openshift-storage.rbd.csi.ceph.com/5m {"vrg": {"name":"cg-app-1","namespace":"openshift-dr-ops"}, "rid": "31b5bd24", "State": "primary"} 2025-10-29T11:37:36.206Z INFO vrg controller/vrg_volrep.go:1451 Found VolumeGroupReplicationClass that matches provisioner and schedule openshift-storage.rbd.csi.ceph.com/5m {"vrg": {"name":"cg-app-1","namespace":"openshift-dr-ops"}, "rid": "31b5bd24", "State": "primary"} 2025-10-29T11:37:36.206Z INFO vrg controller/vrg_volrep.go:1451 Found VolumeGroupReplicationClass that matches provisioner and schedule openshift-storage.rbd.csi.ceph.com/5m {"vrg": {"name":"cg-app-1","namespace":"openshift-dr-ops"}, "rid": "31b5bd24", "State": "primary"} 2025-10-29T11:37:36.206Z INFO vrg controller/vrg_volrep.go:1451 Found VolumeGroupReplicationClass that matches provisioner and schedule openshift-storage.rbd.csi.ceph.com/5m {"vrg": {"name":"cg-app-1","namespace":"openshift-dr-ops"}, "rid": "31b5bd24", "State": "primary"}

ok, so the log per pvc do not add any value, we can remove them.

nirs · 2025-10-30T09:58:59Z

internal/controller/volumereplicationgroup_controller.go

 		// this. If not found, then reconcile request would not be sent
 		selector, err := metav1.LabelSelectorAsSelector(&pvcSelector.LabelSelector)
 		if err != nil {
-			log1.Error(err, "Failed to get the label selector from VolumeReplicationGroup")


Is this an expected condition or an error?

@nirs according to comment for this call, it can happen and not an error:

// continue if we fail to get the labels for this object hoping // that pvc might actually belong to some other vrg instead of // this. If not found, then reconcile request would not be sent

The log line indicates a failure, the continue is a best case continue, just in case this PVC belongs to a different VRG. We should not get an error when we attempt to get the selector.

@ShyamsundarR I didn't understand, you suggest to retain or to remove?

nirs · 2025-10-30T09:59:45Z

internal/controller/volumereplicationgroup_controller.go

-			log1.Info("Found VolumeReplicationGroup with matching labels or owner",
-				"vrg", vrgNamespacedName.String(), "selector", selector,
-				"namespaces selected", pvcSelector.NamespaceNames,
-				"label match", labelMatch, "owner match", ownerMatch)


Looks like a debug log - do we log the same info later?

@nirs We are printing debug logs also, so that Ramen log is overloaded with these messages! It causes wrap around.
Here is the example from relaxed QE setup:

Line 590: 2025-10-29T11:37:26.448Z INFO pvcmap.VolumeReplicationGroup controller/volumereplicationgroup_controller.go:359 Found VolumeReplicationGroup with matching labels or owner {"pvc": {"name":"busybox-pvc-1","namespace":"cg-app-1"}, "vrg": "cg-app-1", "vrg": "openshift-dr-ops/cg-app-1", "selector": "workloadpattern in (simple_io_pvc)", "namespaces selected": ["cg-app-1"], "label match": true, "owner match": false} Line 591: 2025-10-29T11:37:26.449Z INFO pvcmap.VolumeReplicationGroup controller/volumereplicationgroup_controller.go:359 Found VolumeReplicationGroup with matching labels or owner {"pvc": {"name":"busybox-pvc-1","namespace":"cg-app-1"}, "vrg": "cg-app-1", "vrg": "openshift-dr-ops/cg-app-1", "selector": "workloadpattern in (simple_io_pvc)", "namespaces selected": ["cg-app-1"], "label match": true, "owner match": false} Line 596: 2025-10-29T11:37:26.527Z INFO pvcmap.VolumeReplicationGroup controller/volumereplicationgroup_controller.go:359 Found VolumeReplicationGroup with matching labels or owner {"pvc": {"name":"busybox-pvc-2","namespace":"cg-app-1"}, "vrg": "cg-app-1", "vrg": "openshift-dr-ops/cg-app-1", "selector": "workloadpattern in (simple_io_pvc)", "namespaces selected": ["cg-app-1"], "label match": true, "owner match": false} Line 597: 2025-10-29T11:37:26.527Z INFO pvcmap.VolumeReplicationGroup controller/volumereplicationgroup_controller.go:359 Found VolumeReplicationGroup with matching labels or owner {"pvc": {"name":"busybox-pvc-2","namespace":"cg-app-1"}, "vrg": "cg-app-1", "vrg": "openshift-dr-ops/cg-app-1", "selector": "workloadpattern in (simple_io_pvc)", "namespaces selected": ["cg-app-1"], "label match": true, "owner match": false} Line 601: 2025-10-29T11:37:26.553Z INFO pvcmap.VolumeReplicationGroup controller/volumereplicationgroup_controller.go:359 Found VolumeReplicationGroup with matching labels or owner {"pvc": {"name":"busybox-pvc-6","namespace":"cg-app-1"}, "vrg": "cg-app-1", "vrg": "openshift-dr-ops/cg-app-1", "selector": "workloadpattern in (simple_io_pvc)", "namespaces selected": ["cg-app-1"], "label match": true, "owner match": false} Line 602: 2025-10-29T11:37:26.553Z INFO pvcmap.VolumeReplicationGroup controller/volumereplicationgroup_controller.go:359 Found VolumeReplicationGroup with matching labels or owner {"pvc": {"name":"busybox-pvc-6","namespace":"cg-app-1"}, "vrg": "cg-app-1", "vrg": "openshift-dr-ops/cg-app-1", "selector": "workloadpattern in (simple_io_pvc)", "namespaces selected": ["cg-app-1"], "label match": true, "owner match": false} Line 605: 2025-10-29T11:37:26.720Z INFO pvcmap.VolumeReplicationGroup controller/volumereplicationgroup_controller.go:359 Found VolumeReplicationGroup with matching labels or owner {"pvc": {"name":"busybox-pvc-7","namespace":"cg-app-1"}, "vrg": "cg-app-1", "vrg": "openshift-dr-ops/cg-app-1", "selector": "workloadpattern in (simple_io_pvc)", "namespaces selected": ["cg-app-1"], "label match": true, "owner match": false} Line 606: 2025-10-29T11:37:26.721Z INFO pvcmap.VolumeReplicationGroup controller/volumereplicationgroup_controller.go:359 Found VolumeReplicationGroup with matching labels or owner {"pvc": {"name":"busybox-pvc-7","namespace":"cg-app-1"}, "vrg": "cg-app-1", "vrg": "openshift-dr-ops/cg-app-1", "selector": "workloadpattern in (simple_io_pvc)", "namespaces selected": ["cg-app-1"], "label match": true, "owner match": false} Line 611: 2025-10-29T11:37:26.764Z INFO pvcmap.VolumeReplicationGroup controller/volumereplicationgroup_controller.go:359 Found VolumeReplicationGroup with matching labels or owner {"pvc": {"name":"busybox-pvc-3","namespace":"cg-app-1"}, "vrg": "cg-app-1", "vrg": "openshift-dr-ops/cg-app-1", "selector": "workloadpattern in (simple_io_pvc)", "namespaces selected": ["cg-app-1"], "label match": true, "owner match": false} Line 612: 2025-10-29T11:37:26.765Z INFO pvcmap.VolumeReplicationGroup controller/volumereplicationgroup_controller.go:359 Found VolumeReplicationGroup with matching labels or owner {"pvc": {"name":"busybox-pvc-3","namespace":"cg-app-1"}, "vrg": "cg-app-1", "vrg": "openshift-dr-ops/cg-app-1", "selector": "workloadpattern in (simple_io_pvc)", "namespaces selected": ["cg-app-1"], "label match": true, "owner match": false} Line 616: 2025-10-29T11:37:26.788Z INFO pvcmap.VolumeReplicationGroup controller/volumereplicationgroup_controller.go:359 Found VolumeReplicationGroup with matching labels or owner {"pvc": {"name":"busybox-pvc-4","namespace":"cg-app-1"}, "vrg": "cg-app-1", "vrg": "openshift-dr-ops/cg-app-1", "selector": "workloadpattern in (simple_io_pvc)", "namespaces selected": ["cg-app-1"], "label match": true, "owner match": false} Line 617: 2025-10-29T11:37:26.789Z INFO pvcmap.VolumeReplicationGroup controller/volumereplicationgroup_controller.go:359 Found VolumeReplicationGroup with matching labels or owner {"pvc": {"name":"busybox-pvc-4","namespace":"cg-app-1"}, "vrg": "cg-app-1", "vrg": "openshift-dr-ops/cg-app-1", "selector": "workloadpattern in (simple_io_pvc)", "namespaces selected": ["cg-app-1"], "label match": true, "owner match": false} Line 620: 2025-10-29T11:37:26.826Z INFO pvcmap.VolumeReplicationGroup controller/volumereplicationgroup_controller.go:359 Found VolumeReplicationGroup with matching labels or owner {"pvc": {"name":"busybox-pvc-5","namespace":"cg-app-1"}, "vrg": "cg-app-1", "vrg": "openshift-dr-ops/cg-app-1", "selector": "workloadpattern in (simple_io_pvc)", "namespaces selected": ["cg-app-1"], "label match": true, "owner match": false} Line 621: 2025-10-29T11:37:26.827Z INFO pvcmap.VolumeReplicationGroup controller/volumereplicationgroup_controller.go:359 Found VolumeReplicationGroup with matching labels or owner {"pvc": {"name":"busybox-pvc-5","namespace":"cg-app-1"}, "vrg": "cg-app-1", "vrg": "openshift-dr-ops/cg-app-1", "selector": "workloadpattern in (simple_io_pvc)", "namespaces selected": ["cg-app-1"], "label match": true, "owner match": false} Line 626: 2025-10-29T11:37:26.855Z INFO pvcmap.VolumeReplicationGroup controller/volumereplicationgroup_controller.go:359 Found VolumeReplicationGroup with matching labels or owner {"pvc": {"name":"busybox-pvc-8","namespace":"cg-app-1"}, "vrg": "cg-app-1", "vrg": "openshift-dr-ops/cg-app-1", "selector": "workloadpattern in (simple_io_pvc)", "namespaces selected": ["cg-app-1"], "label match": true, "owner match": false} Line 627: 2025-10-29T11:37:26.856Z INFO pvcmap.VolumeReplicationGroup controller/volumereplicationgroup_controller.go:359 Found VolumeReplicationGroup with matching labels or owner {"pvc": {"name":"busybox-pvc-8","namespace":"cg-app-1"}, "vrg": "cg-app-1", "vrg": "openshift-dr-ops/cg-app-1", "selector": "workloadpattern in (simple_io_pvc)", "namespaces selected": ["cg-app-1"], "label match": true, "owner match": false} Line 631: 2025-10-29T11:37:26.874Z INFO pvcmap.VolumeReplicationGroup controller/volumereplicationgroup_controller.go:359 Found VolumeReplicationGroup with matching labels or owner {"pvc": {"name":"busybox-pvc-10","namespace":"cg-app-1"}, "vrg": "cg-app-1", "vrg": "openshift-dr-ops/cg-app-1", "selector": "workloadpattern in (simple_io_pvc)", "namespaces selected": ["cg-app-1"], "label match": true, "owner match": false} Line 632: 2025-10-29T11:37:26.875Z INFO pvcmap.VolumeReplicationGroup controller/volumereplicationgroup_controller.go:359 Found VolumeReplicationGroup with matching labels or owner {"pvc": {"name":"busybox-pvc-10","namespace":"cg-app-1"}, "vrg": "cg-app-1", "vrg": "openshift-dr-ops/cg-app-1", "selector": "workloadpattern in (simple_io_pvc)", "namespaces selected": ["cg-app-1"], "label match": true, "owner match": false} Line 635: 2025-10-29T11:37:26.905Z INFO pvcmap.VolumeReplicationGroup controller/volumereplicationgroup_controller.go:359 Found VolumeReplicationGroup with matching labels or owner {"pvc": {"name":"busybox-pvc-9","namespace":"cg-app-1"}, "vrg": "cg-app-1", "vrg": "openshift-dr-ops/cg-app-1", "selector": "workloadpattern in (simple_io_pvc)", "namespaces selected": ["cg-app-1"], "label match": true, "owner match": false} Line 636: 2025-10-29T11:37:26.906Z INFO pvcmap.VolumeReplicationGroup controller/volumereplicationgroup_controller.go:359 Found VolumeReplicationGroup with matching labels or owner {"pvc": {"name":"busybox-pvc-9","namespace":"cg-app-1"}, "vrg": "cg-app-1", "vrg": "openshift-dr-ops/cg-app-1", "selector": "workloadpattern in (simple_io_pvc)", "namespaces selected": ["cg-app-1"], "label match": true, "owner match": false}

All these are from one second

looks like too verbose debug log, not clear why we need to know that we found a vrg for the pvc.

In general we need to log when we change the state of the system, for example when we are starting the use a pvc, when the pvc state changes, etc.

Exactly, I can's see, how this log helps us to debug the system, that is why I suggest to remove it

This log line indicates why a VRG was reconciled, i.e due to which PVC triggering a VRG reconcile.

This is useful in the steady state, where PVC events would be minimal (in terms of update/delete/create) and so knowing what triggered the VRG reconcile is useful at times in troubleshooting.

The log example given is when an application is possibly relocated/failedover or deployed with DR enabled the first time. As then all PVCs are created and bound in a couple of reconciles.

@ShyamsundarR Usually issues don’t occur in a steady state. This PR was created to prevent ramen log wrap-around, after which we lose the logs completely and can’t investigate the problem.

This message is printed for every PVC and can be very noisy. If you feel it’s important to keep it, I can revert this change.

@ELENAGER We need more data to tell how bad is this log. In general we want to delete (or move to debug level, hidden by default) logs that add little value and consume lot of space, leading to wrapped log files.

The way I analyzed logs in the past was to import the logs to sqlite database, and then query the database.

This is the tool I used. It is built for vdsm logs but modifying it for ramen logs should not be hard.
https://github.com/oVirt/vdsm/blob/master/contrib/logdb

Example commit showing some queries:
http://github.com/oVirt/vdsm/commit/886224ada622fcfc5e5de1aaeae030ae40ad0556

I retained this log line

nirs · 2025-10-30T10:01:50Z

internal/controller/volumereplicationgroup_controller.go

 		CreateFunc: func(e event.CreateEvent) bool {
-			log.Info("Create event for PersistentVolumeClaim")
+			o := e.Object
+			log.Info("PVC Create event", "namespace", o.GetNamespace(), "name", o.GetName())


We can make the log shorted using "PVC created"

nirs · 2025-10-30T10:02:03Z

internal/controller/volumereplicationgroup_controller.go

 			}

-			log.Info("Update event for PersistentVolumeClaim")
+			log.Info("PVC Update event", "namespace", oldPVC.GetNamespace(), "name", oldPVC.GetName())


PVC updated

nirs · 2025-10-30T10:02:16Z

internal/controller/volumereplicationgroup_controller.go

 		DeleteFunc: func(e event.DeleteEvent) bool {
 			o := e.Object
-			log.Info("PVC Delete", "namespace", o.GetNamespace(), "name", o.GetName())
+			log.Info("PVC Delete event", "namespace", o.GetNamespace(), "name", o.GetName())


PVC deleted

raaizik · 2025-11-13T15:05:38Z

internal/controller/volumereplicationgroup_controller.go

-			log.Info("Create event for PersistentVolumeClaim")
+			o := e.Object
+			log.Info("PVC created", "namespace", o.GetNamespace(), "name", o.GetName())


You're using past-tense verbs like “created” and “deleted,” but these predicates run before reconciliation - they only observe Kubernetes events, not completed actions. Using phrasing like "Create event" reflects what’s actually happening.

Also, there’s no real need to log the object’s namespaced name at this stage - the reconciler logs that when processing the object, so removing it here would keep the logs cleaner and less noisy.

Suggested change

log.Info("Create event for PersistentVolumeClaim")

o := e.Object

log.Info("PVC created", "namespace", o.GetNamespace(), "name", o.GetName())

log.Info("Create event for PersistentVolumeClaim")

I think “PVC created” is accurate because by the time we receive the ADDED event, the PVC object already exists in the cluster (persisted in etcd). We’re reacting to a completed creation, not an in-progress action. Using “Create event” might imply it hasn’t happened yet.
Regarding the namespaced name, I’d prefer to keep it for easier debugging and correlation, but open to revisiting if logs become too noisy.

Retaining the "event" word in the log is useful, as we are receiving events, and when looking at logs it is more easily understandable.

But more broadly, we should drop all logs in this function, and just rely on logs from the pvcMapFunc which decides if a PVC is of interest to reconcile a VRG.

Logs here till date never carried the PVC NamespaceName, and most often for debugging the log generated regarding which VRG that was triggered for a reconcile was more useful (as that had the PVC name).

As this is a global system wide PVC watcher, we should drop the logs in this function.

"Event" word is retained, I still prefer to have the logs of the events, in spite of having the logs from the pvcMapFunc

raaizik · 2025-11-13T15:06:15Z

internal/controller/volumereplicationgroup_controller.go

 			}

-			log.Info("Update event for PersistentVolumeClaim")
+			log.Info("PVC updated", "namespace", oldPVC.GetNamespace(), "name", oldPVC.GetName())


Same.

Suggested change

log.Info("PVC updated", "namespace", oldPVC.GetNamespace(), "name", oldPVC.GetName())

log.Info("Update event for PersistentVolumeClaim")

raaizik · 2025-11-13T15:06:59Z

internal/controller/volumereplicationgroup_controller.go

 		DeleteFunc: func(e event.DeleteEvent) bool {
 			o := e.Object
-			log.Info("PVC Delete", "namespace", o.GetNamespace(), "name", o.GetName())
+			log.Info("PVC deleted", "namespace", o.GetNamespace(), "name", o.GetName())


Same.

Suggested change

log.Info("PVC deleted", "namespace", o.GetNamespace(), "name", o.GetName())

log.Info("Delete event for PersistentVolumeClaim", "namespace", o.GetNamespace(), "name", o.GetName())

pruthvitd

Smart tradeoff — reducing log noise while keeping critical events visible longer before rotation. Thanks for addressing this.

ShyamsundarR · 2025-12-05T18:28:32Z

internal/controller/volumereplicationgroup_controller.go

-			log.Info("Create event for PersistentVolumeClaim")
+			o := e.Object
+			log.Info("PVC created", "namespace", o.GetNamespace(), "name", o.GetName())


Retaining the "event" word in the log is useful, as we are receiving events, and when looking at logs it is more easily understandable.

But more broadly, we should drop all logs in this function, and just rely on logs from the pvcMapFunc which decides if a PVC is of interest to reconcile a VRG.

Logs here till date never carried the PVC NamespaceName, and most often for debugging the log generated regarding which VRG that was triggered for a reconcile was more useful (as that had the PVC name).

As this is a global system wide PVC watcher, we should drop the logs in this function.

ShyamsundarR · 2025-12-05T18:31:20Z

internal/controller/volumereplicationgroup_controller.go

 		// this. If not found, then reconcile request would not be sent
 		selector, err := metav1.LabelSelectorAsSelector(&pvcSelector.LabelSelector)
 		if err != nil {
-			log1.Error(err, "Failed to get the label selector from VolumeReplicationGroup")


The log line indicates a failure, the continue is a best case continue, just in case this PVC belongs to a different VRG. We should not get an error when we attempt to get the selector.

ShyamsundarR · 2025-12-05T22:08:17Z

internal/controller/volumereplicationgroup_controller.go

-			log1.Info("Found VolumeReplicationGroup with matching labels or owner",
-				"vrg", vrgNamespacedName.String(), "selector", selector,
-				"namespaces selected", pvcSelector.NamespaceNames,
-				"label match", labelMatch, "owner match", ownerMatch)


This log line indicates why a VRG was reconciled, i.e due to which PVC triggering a VRG reconcile.

This is useful in the steady state, where PVC events would be minimal (in terms of update/delete/create) and so knowing what triggered the VRG reconcile is useful at times in troubleshooting.

The log example given is when an application is possibly relocated/failedover or deployed with DR enabled the first time. As then all PVCs are created and bound in a couple of reconciles.

ShyamsundarR · 2025-12-05T22:10:12Z

internal/controller/volumereplicationgroup_controller.go

+		v.log.Info("Separate PVCs using only StorageClass provisioner")
+	} else {
+		v.log.Info("Separate PVCs using peerClasses")
+	}


We hardly use debug level, and adding logs at that level is not my choice. This instance can be root caused inspecting the VRG resource and looking at peerClass elements, and I would as such remove this log.

ShyamsundarR · 2025-12-05T22:20:17Z

internal/controller/volumereplicationgroup_controller.go

 		[]string{VRGConditionReasonUnused},
 		subconditions...)
-	msg = fmt.Sprintf("updated %s status to %s", conditionName, finalCondition.Status)
+	msg := fmt.Sprintf("updated %s status to %s", conditionName, finalCondition.Status)


I would get rid of this condition log printing, the i memory condition is updated to VRG once the callers are done, and so having them in the logs maybe superfluous.

There are times while inspecting logs, how the condition progressed has been useful, but given VRG status, and looking at current state of the system this log is more noise and can be removed.

@ShyamsundarR I honestly prefer to retain this log, I already deleted the duplicate line (see above), so we reduced the noise. Sometimes the possibility to follow the progression can be useful and not only final result,

ShyamsundarR · 2025-12-05T22:25:01Z

internal/controller/volumereplicationgroup_controller.go

 		}

 		if slices.Contains(*vrg.Spec.ProtectedNamespaces, obj.GetNamespace()) {
-			log1.Info("Found VolumeReplicationGroup with matching namespace",


This log line again tells us which event triggered a VRG was reconcile. It is generally useful to know this when looking at logs, as only an external trigger should ideally trigger a VRG reconciliation (apart from any exponential backoff from a previous reconcile)

ShyamsundarR · 2025-12-05T22:34:27Z

internal/controller/volumereplicationgroup_controller.go


 	rgs, ok := obj.(*ramendrv1alpha1.ReplicationGroupSource)
 	if !ok {
-		log.Info("map function received not a replication group source resource")


We should drop other such log lines in the functions above this. While I have never seen this log, and so will not contribute to reducing log noise as such, it is not essential as well.

Signed-off-by: Elena Gershkovich <elenage@il.ibm.com>

ELENAGER requested review from BenamarMk and ShyamsundarR as code owners October 30, 2025 08:13

ELENAGER requested review from abhijeet219, asn1809, kumarsgoyal, nirs, pruthvitd and rakeshgm October 30, 2025 08:16

asn1809 approved these changes Oct 30, 2025

View reviewed changes

nirs reviewed Oct 30, 2025

View reviewed changes

ELENAGER force-pushed the improve_logs branch 6 times, most recently from 4a1e9c6 to f938449 Compare November 6, 2025 14:11

raaizik suggested changes Nov 13, 2025

View reviewed changes

pruthvitd approved these changes Nov 13, 2025

View reviewed changes

ELENAGER force-pushed the improve_logs branch from 2193397 to 6446830 Compare November 17, 2025 08:29

ELENAGER force-pushed the improve_logs branch from 6446830 to 3c6fa88 Compare November 30, 2025 12:56

ShyamsundarR reviewed Dec 5, 2025

View reviewed changes

ELENAGER force-pushed the improve_logs branch 3 times, most recently from 1824948 to e9e2fe9 Compare December 9, 2025 14:18

ELENAGER force-pushed the improve_logs branch 3 times, most recently from 08496f3 to 7e0f2e1 Compare December 16, 2025 16:02

ELENAGER added 3 commits December 22, 2025 12:57

While separating PVCs do not print log per PVC

f812177

Signed-off-by: Elena Gershkovich <elenage@il.ibm.com>

Remove non-informative namespace logging per PVC

c6eb70f

Signed-off-by: Elena Gershkovich <elenage@il.ibm.com>

Improve logging for VGRC/VRC selection process

88f8453

Signed-off-by: Elena Gershkovich <elenage@il.ibm.com>

ELENAGER added 4 commits December 22, 2025 12:57

Remove excessive logging in filtering watched resources

6d547d8

Signed-off-by: Elena Gershkovich <elenage@il.ibm.com>

When PVC change event received, log PVC name and namespace

c5f2f97

Signed-off-by: Elena Gershkovich <elenage@il.ibm.com>

While merging conditions, print only the final result

f741682

Signed-off-by: Elena Gershkovich <elenage@il.ibm.com>

Reduce number of log lines while fetching PVCs by label selector

0586abe

Signed-off-by: Elena Gershkovich <elenage@il.ibm.com>

ELENAGER force-pushed the improve_logs branch from 7e0f2e1 to 0586abe Compare December 22, 2025 10:57

	log.Info("PVC updated", "namespace", oldPVC.GetNamespace(), "name", oldPVC.GetName())
	log.Info("Update event for PersistentVolumeClaim")

	log.Info("PVC deleted", "namespace", o.GetNamespace(), "name", o.GetName())
	log.Info("Delete event for PersistentVolumeClaim", "namespace", o.GetNamespace(), "name", o.GetName())

Improve logging in VolumeReplicationGroup controller #2318

Are you sure you want to change the base?

Improve logging in VolumeReplicationGroup controller #2318

Conversation

ELENAGER commented Oct 30, 2025

Uh oh!

asn1809 left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

ELENAGER Oct 30, 2025 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

ELENAGER Dec 8, 2025 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

raaizik Nov 13, 2025 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

pruthvitd left a comment

ELENAGER Oct 30, 2025 •

edited

Loading

ELENAGER Dec 8, 2025 •

edited

Loading

raaizik Nov 13, 2025 •

edited

Loading