feat: improving Debug Log Clarity and Reducing Noise

cmd/collectors/commonutils.go

@@ -229,7 +229,14 @@ func UpdateLagTime(instance *matrix.Instance, lastTransferSize *matrix.Metric, l
 			if err := lagTime.SetValueFloat64(instance, 0); err != nil {
 				logger.Error().Err(err).Str("metric", lagTime.GetName()).Msg("Unable to set value on metric")
 			}
-			logger.Debug().Msgf("lagTime value set from %f to 0 for %s. Healthy: %s, Schedule: %s, LastBytes: %f, LastError:%s", lag, relationshipID, healthy, schedule, lastBytes, lastError)
+			logger.Trace().
+				Float64("lag", lag).
+				Str("relationshipID", relationshipID).
+				Str("healthy", healthy).
+				Str("schedule", schedule).
+				Float64("lastBytes", lastBytes).
+				Str("lastError", lastError).
+				Msg("lagTime value set from lag to 0")
 		}
 	}
 }

cmd/collectors/ems/ems.go

@@ -322,7 +322,7 @@ func (e *Ems) PollInstance() (map[string]*matrix.Matrix, error) {
 	// Filter out names which exist on the cluster.
 	// ONTAP rest ems throws error for a message.name filter if that event is not supported by that cluster
 	filteredNames, _ := util.Intersection(names, emsEventCatalogue)
-	e.Logger.Debug().Strs("querying for events", filteredNames).Msg("")
+	e.Logger.Trace().Strs("querying for events", filteredNames).Send()
 	_, missingNames := util.Intersection(filteredNames, names)
 	e.Logger.Debug().Strs("skipped events", missingNames).Msg("")
 	e.eventNames = filteredNames

cmd/collectors/ems/templating.go

@@ -55,7 +55,7 @@ func (e *Ems) ParseDefaults(prop *emsProp) {
 	for _, c := range e.DefaultLabels {
 		if c != "" {
 			name, display, _, _ = util.ParseMetric(c)
-			e.Logger.Debug().
+			e.Logger.Trace().
 				Str("name", name).
 				Str("display", display).
 				Msg("Collected default labels")
@@ -82,7 +82,7 @@ func (e *Ems) ParseExports(counter *node.Node, prop *emsProp) {
 	for _, c := range counter.GetAllChildContentS() {
 		if c != "" {
 			name, display, key, _ = util.ParseMetric(c)
-			e.Logger.Debug().
+			e.Logger.Trace().
 				Str("name", name).
 				Str("display", display).
 				Msg("Collected exports")
@@ -93,7 +93,7 @@ func (e *Ems) ParseExports(counter *node.Node, prop *emsProp) {
 			if key == "key" {
 				// only for bookend EMS
 				bookendKeys[display] = name
-				e.Logger.Debug().
+				e.Logger.Trace().
 					Str("name", name).
 					Str("display", display).
 					Msg("Collected bookend keys")
@@ -150,7 +150,7 @@ func (e *Ems) ParseResolveEms(resolveEvent *node.Node, issueEmsProp emsProp) {
 			e.resolveAfter[issueEmsProp.Name] = durationVal
 		}
 	}
-	e.Logger.Debug().Str("bookend ems resolve After", e.resolveAfter[issueEmsProp.Name].String()).Msg("")
+	e.Logger.Trace().Str("bookend ems resolve After", e.resolveAfter[issueEmsProp.Name].String()).Msg("")
 
 	// Using Set to ensure it has slice of unique issuing ems
 	if _, ok := e.bookendEmsMap[resolveEmsName]; !ok {

cmd/collectors/power.go

@@ -127,7 +127,7 @@ func calculateEnvironmentMetrics(data *matrix.Matrix, logger *logging.Logger, va
 			isVoltageMatch := voltageRegex.MatchString(sensorName)
 			isCurrentMatch := CurrentRegex.MatchString(sensorName)
 
-			logger.Debug().
+			logger.Trace().
 				Bool("isAmbientMatch", isAmbientMatch).
 				Bool("isPowerMatch", isPowerMatch).
 				Bool("isVoltageMatch", isVoltageMatch).

cmd/collectors/rest/plugins/qtree/qtree.go

@@ -230,7 +230,13 @@ func (q *Qtree) handlingHistoricalMetrics(result []gjson.Result, data *matrix.Ma
 				q.Logger.Error().Stack().Err(err).Str("quotaInstanceKey", quotaInstanceKey).Msg("Failed to create quota instance")
 				return err
 			}
-			q.Logger.Debug().Msgf("add (%s) quota instance: %s.%s.%s.%s", quotaInstanceKey, vserver, volume, tree, qIndex)
+			q.Logger.Trace().
+				Str("quotaInstanceKey", quotaInstanceKey).
+				Str("svm", vserver).
+				Str("volume", volume).
+				Str("tree", tree).
+				Str("qIndex", qIndex).
+				Msg("add quota instance")
 		}
 
 		// qtree instancekey would be qtree, svm and volume(sorted keys)
@@ -285,7 +291,7 @@ func (q *Qtree) handlingHistoricalMetrics(result []gjson.Result, data *matrix.Ma
 				q.Logger.Error().Stack().Err(err).Str("attribute", attribute).Float64("value", value).Msg("Failed to parse value")
 			} else {
 				*numMetrics++
-				q.Logger.Debug().Str("attribute", attribute).Float64("value", value).Msg("added value")
+				q.Logger.Trace().Str("attribute", attribute).Float64("value", value).Msg("added value")
 			}
 		}
 	}

cmd/collectors/rest/rest.go

@@ -291,7 +291,7 @@ func (r *Rest) PollData() (map[string]*matrix.Matrix, error) {
 		records   []gjson.Result
 	)
 
-	r.Logger.Debug().Msg("starting data poll")
+	r.Logger.Trace().Msg("starting data poll")
 
 	r.Matrix[r.Object].Reset()
 
@@ -565,7 +565,7 @@ func (r *Rest) HandleResults(result []gjson.Result, prop *prop, isEndPoint bool)
 		// remove deleted instances
 		for key := range oldInstances.Iter() {
 			mat.RemoveInstance(key)
-			r.Logger.Debug().Str("key", key).Msg("removed instance")
+			r.Logger.Trace().Str("key", key).Msg("removed instance")
 		}
 	}
 

cmd/collectors/rest/templating.go

@@ -166,7 +166,7 @@ func (r *Rest) ParseRestCounters(counter *node.Node, prop *prop) {
 	for _, c := range counter.GetAllChildContentS() {
 		if c != "" {
 			name, display, kind, metricType = util.ParseMetric(c)
-			r.Logger.Debug().
+			r.Logger.Trace().
 				Str("kind", kind).
 				Str("name", name).
 				Str("display", display).

cmd/collectors/restperf/plugins/disk/disk.go

@@ -10,6 +10,7 @@ import (
 	"github.com/netapp/harvest/v2/pkg/util"
 	"github.com/tidwall/gjson"
 	"sort"
+	"strconv"
 	"strings"
 	"time"
 )
@@ -165,22 +166,34 @@ func (d *Disk) Init() error {
 				d.instanceLabels[attribute][metricName] = display
 				instanceLabels.NewChildS("", display)
 				instanceKeys.NewChildS("", display)
-				d.Logger.Debug().Msgf("added instance key: (%s) [%s]", attribute, display)
+				d.Logger.Trace().
+					Str("attribute", attribute).
+					Str("display", display).
+					Msg("added instance key")
 			case "label":
 				d.instanceLabels[attribute][metricName] = display
 				instanceLabels.NewChildS("", display)
-				d.Logger.Debug().Msgf("added instance label: (%s) [%s]", attribute, display)
+				d.Logger.Trace().
+					Str("attribute", attribute).
+					Str("display", display).
+					Msg("added instance label")
 			case "float":
 				_, err := d.shelfData[attribute].NewMetricFloat64(metricName, display)
 				if err != nil {
 					d.Logger.Error().Stack().Err(err).Msg("add metric")
 					return err
 				}
-				d.Logger.Debug().Msgf("added metric: (%s) [%s]", attribute, display)
+				d.Logger.Trace().
+					Str("attribute", attribute).
+					Str("display", display).
+					Msg("added metric")
 			}
 		}
 
-		d.Logger.Debug().Msgf("added shelfData for [%s] with %d metrics", attribute, len(d.shelfData[attribute].GetMetrics()))
+		d.Logger.Trace().
+			Str("attribute", attribute).
+			Str("metricsCount", strconv.Itoa(len(d.shelfData[attribute].GetMetrics()))).
+			Msg("added shelfData with metrics")
 
 		d.shelfData[attribute].SetExportOptions(exportOptions)
 	}
@@ -274,7 +287,11 @@ func (d *Disk) Run(dataMap map[string]*matrix.Matrix) ([]*matrix.Matrix, error)
 									d.Logger.Error().Err(err).Str("attribute", attribute).Str("instanceKey", instanceKey).Msg("Failed to add instance")
 									break
 								}
-								d.Logger.Debug().Msgf("add (%s) instance: %s.%s.%s", attribute, shelfSerialNumber, attribute, combinedKey)
+								d.Logger.Trace().
+									Str("attribute", attribute).
+									Str("shelfSerialNumber", shelfSerialNumber).
+									Str("combinedKey", combinedKey).
+									Msg("add instance")
 
 								for label, labelDisplay := range d.instanceLabels[attribute] {
 									if value := obj.Get(label); value.Exists() {
@@ -316,7 +333,7 @@ func (d *Disk) Run(dataMap map[string]*matrix.Matrix) ([]*matrix.Matrix, error)
 											d.Logger.Error().Err(err).Str("key", metricKey).Str("metric", m.GetName()).Str("value", value.String()).
 												Msg("Unable to set float key on metric")
 										} else {
-											d.Logger.Debug().Str("metricKey", metricKey).Str("value", value.String()).Msg("added")
+											d.Logger.Trace().Str("metricKey", metricKey).Str("value", value.String()).Msg("added")
 										}
 									}
 								}

cmd/collectors/restperf/plugins/nic/nic.go

@@ -82,7 +82,10 @@ func (n *Nic) Run(dataMap map[string]*matrix.Matrix) ([]*matrix.Matrix, error) {
 				} else {
 					// NIC speed value converted from Mbps to Bps(bytes per second)
 					speed = base * 125000
-					n.Logger.Debug().Msgf("converted speed (%s) to numeric (%d)", s, speed)
+					n.Logger.Trace().
+						Str("originalSpeed", s).
+						Int("convertedSpeed", speed).
+						Msg("converted speed to numeric")
 				}
 			} else if speed, err = strconv.Atoi(s); err != nil {
 				n.Logger.Warn().Msgf("convert speed [%s]", s)
@@ -126,7 +129,10 @@ func (n *Nic) Run(dataMap map[string]*matrix.Matrix) ([]*matrix.Matrix, error) {
 				// NIC speed value converted from Mbps to bps(bits per second)
 				speed = base * 1_000_000
 				instance.SetLabel("speed", strconv.Itoa(speed))
-				n.Logger.Debug().Msgf("converted speed (%s) to numeric (%d)", s, speed)
+				n.Logger.Trace().
+					Str("originalSpeed", s).
+					Int("convertedSpeed", speed).
+					Msg("converted speed to numeric")
 			}
 		}
 

cmd/collectors/restperf/restperf.go

@@ -642,7 +642,7 @@ func (r *RestPerf) processWorkLoadCounter() (map[string]*matrix.Matrix, error) {
 				}
 				m.SetLabel("resource", resource)
 
-				r.Logger.Debug().Str("name", name).Str("resource", resource).Msg("added workload latency metric")
+				r.Logger.Trace().Str("name", name).Str("resource", resource).Msg("added workload latency metric")
 			}
 		}
 	}
@@ -800,7 +800,8 @@ func (r *RestPerf) pollData(startTime time.Time, perfRecords []rest.PerfRecord)
 			instance = curMat.GetInstance(instanceKey)
 			if instance == nil {
 				if isWorkloadObject(r.Prop.Query) || isWorkloadDetailObject(r.Prop.Query) {
-					r.Logger.Debug().
+					// Filtering is involved with these objects, such as the workload class and the constituent disable. Therefore, logs are being moved to trace.
+					r.Logger.Trace().
 						Str("instanceKey", instanceKey).
 						Msg("Skip instanceKey, not found in cache")
 				} else {
@@ -1057,7 +1058,7 @@ func (r *RestPerf) pollData(startTime time.Time, perfRecords []rest.PerfRecord)
 
 	calcStart := time.Now()
 
-	r.Logger.Debug().Msg("starting delta calculations from previous cache")
+	r.Logger.Trace().Msg("starting delta calculations from previous cache")
 
 	// cache raw data for next poll
 	cachedData := curMat.Clone(matrix.With{Data: true, Metrics: true, Instances: true, ExportInstances: true})
@@ -1469,7 +1470,9 @@ func (r *RestPerf) pollInstance(records []gjson.Result, apiD time.Duration) (map
 			oldInstances.Remove(instanceKey)
 			instance := mat.GetInstance(instanceKey)
 			r.updateQosLabels(instanceData, instance, instanceKey)
-			r.Logger.Debug().Msgf("updated instance [%s%s%s%s]", color.Bold, color.Yellow, instanceKey, color.End)
+			r.Logger.Trace().
+				Str("instanceKey", instanceKey).
+				Msg("updated instance")
 		} else if instance, err := mat.NewInstance(instanceKey); err != nil {
 			r.Logger.Error().Err(err).Str("instanceKey", instanceKey).Msg("add instance")
 		} else {

cmd/collectors/zapi/collector/zapi.go

@@ -307,7 +307,7 @@ func (z *Zapi) PollData() (map[string]*matrix.Matrix, error) {
 
 		for _, child := range node.GetChildren() {
 			if util.HasDuplicates(child.GetAllChildNamesS()) {
-				z.Logger.Debug().Msgf("Array detected for %s", child.GetNameS())
+				z.Logger.Trace().Str("name", child.GetNameS()).Msg("Array detected")
 				fetch(instance, child, newPath, true)
 			} else {
 				fetch(instance, child, newPath, isAppend)
@@ -356,7 +356,9 @@ func (z *Zapi) PollData() (map[string]*matrix.Matrix, error) {
 			break
 		}
 
-		z.Logger.Debug().Msgf("fetched %d instance elements", len(instances))
+		z.Logger.Trace().
+			Int("size", len(instances)).
+			Msg("fetched instance elements")
 
 		if z.Params.GetChildContentS("only_cluster_instance") == "true" {
 			instance := mat.GetInstance("cluster")

cmd/collectors/zapi/plugins/qtree/qtree.go

@@ -108,13 +108,16 @@ func (q *Qtree) Init() error {
 
 		metricName, display, _, _ := util.ParseMetric(obj)
 
-		metric, err := q.data.NewMetricFloat64(metricName, display)
+		_, err := q.data.NewMetricFloat64(metricName, display)
 		if err != nil {
 			q.Logger.Error().Stack().Err(err).Msg("add metric")
 			return err
 		}
 
-		q.Logger.Debug().Msgf("added metric: (%s) [%s] %v", metricName, display, metric)
+		q.Logger.Trace().
+			Str("metricName", metricName).
+			Str("display", display).
+			Msg("added metric")
 	}
 
 	q.Logger.Debug().Msgf("added data with %d metrics", len(q.data.GetMetrics()))
@@ -282,7 +285,12 @@ func (q *Qtree) handlingHistoricalMetrics(quotas []*node.Node, data *matrix.Matr
 					return err
 				}
 
-				q.Logger.Debug().Msgf("add (%s) instance: %s.%s.%s", attribute, vserver, volume, tree)
+				q.Logger.Trace().
+					Str("attribute", attribute).
+					Str("svm", vserver).
+					Str("volume", volume).
+					Str("tree", tree).
+					Msg("add instance")
 
 				for _, label := range q.data.GetExportOptions().GetChildS("instance_keys").GetAllChildContentS() {
 					if value := qtreeInstance.GetLabel(label); value != "" {
@@ -315,12 +323,17 @@ func (q *Qtree) handlingHistoricalMetrics(quotas []*node.Node, data *matrix.Matr
 						q.Logger.Debug().Msgf("(%s) failed to parse value (%s): %v", attribute, value, err)
 					} else {
 						*numMetrics++
-						q.Logger.Debug().Msgf("(%s) added value (%s)", attribute, value)
+						q.Logger.Trace().
+							Str("attribute", attribute).
+							Str("value", value).
+							Msg("added value")
 					}
 				}
 
 			} else {
-				q.Logger.Debug().Msgf("instance without [%s], skipping", attribute)
+				q.Logger.Trace().
+					Str("attribute", attribute).
+					Msg("instance without attribute skipping")
 			}
 		}
 	}
@@ -405,8 +418,12 @@ func (q *Qtree) handlingQuotaMetrics(quotas []*node.Node, cluster string, quotaI
 					}
 				}
 
-				q.Logger.Debug().Msgf("add (%s) instance: %s.%s.%s", attribute, vserver, volume, tree)
-
+				q.Logger.Trace().
+					Str("attribute", attribute).
+					Str("vserver", vserver).
+					Str("volume", volume).
+					Str("tree", tree).
+					Msg("add instance")
 				// populate numeric data
 				if value := strings.Split(attrValue, " ")[0]; value != "" {
 					// Few quota metrics would have value '-' which means unlimited (ex: disk-limit)
@@ -421,11 +438,16 @@ func (q *Qtree) handlingQuotaMetrics(quotas []*node.Node, cluster string, quotaI
 						q.Logger.Debug().Msgf("(%s) failed to parse value (%s): %v", attribute, value, err)
 					} else {
 						*numMetrics++
-						q.Logger.Debug().Msgf("(%s) added value (%s)", attribute, value)
+						q.Logger.Trace().
+							Str("attribute", attribute).
+							Interface("value", value).
+							Msg("added value")
 					}
 				}
 			} else {
-				q.Logger.Debug().Msgf("instance without [%s], skipping", attribute)
+				q.Logger.Trace().
+					Str("attribute", attribute).
+					Msg("instance without attribute skipping")
 			}
 		}
 	}