refactor: improve logging (#3182)

refactor: remove dead code
refactor: log the collector's collected key-values in alphabetic order

cmd/collectors/ems/ems.go

@@ -1,7 +1,6 @@
 package ems
 
 import (
-	"context"
 	"fmt"
 	"github.com/netapp/harvest/v2/cmd/collectors"
 	rest2 "github.com/netapp/harvest/v2/cmd/collectors/rest"
@@ -327,12 +326,7 @@ func (e *Ems) PollInstance() (map[string]*matrix.Matrix, error) {
 	// ONTAP rest ems throws error for a message.name filter if that event is not supported by that cluster
 	filteredNames, _ := util.Intersection(names, emsEventCatalogue)
 	_, missingNames := util.Intersection(filteredNames, names)
-	if e.Logger.Enabled(context.Background(), slog.LevelDebug) {
-		e.Logger.Debug(
-			"filtered ems events",
-			slog.String("skipped events", strings.Join(missingNames, ",")),
-		)
-	}
+	e.Logger.Debug("filtered ems events", slog.Any("skipped events", missingNames))
 	e.eventNames = filteredNames
 
 	// warning when total instance in cache > 1000 instance

cmd/collectors/fabricpool.go

@@ -54,7 +54,7 @@ func GetFlexGroupFabricPoolMetrics(dataMap map[string]*matrix.Matrix, object str
 		}
 	}
 
-	l.Debug("extracted  flexgroup volumes", slog.Int("size", len(cache.GetInstances())))
+	l.Debug("extracted flexgroup volumes", slog.Int("size", len(cache.GetInstances())))
 
 	// create summary
 	for _, constituent := range flexgroupConstituentsMap {

cmd/collectors/rest/templating.go

@@ -1,7 +1,6 @@
 package rest
 
 import (
-	"context"
 	"fmt"
 	"github.com/netapp/harvest/v2/pkg/errs"
 	"github.com/netapp/harvest/v2/pkg/tree/node"
@@ -71,14 +70,12 @@ func (r *Rest) InitCache() error {
 
 	r.ParseRestCounters(counters, r.Prop)
 
-	if r.Logger.Enabled(context.Background(), slog.LevelDebug) {
-		r.Logger.Debug(
-			"Initialized metric cache",
-			slog.String("extracted Instance Keys", strings.Join(r.Prop.InstanceKeys, ",")),
-			slog.Int("numMetrics", len(r.Prop.Metrics)),
-			slog.Int("numLabels", len(r.Prop.InstanceLabels)),
-		)
-	}
+	r.Logger.Debug(
+		"Initialized metric cache",
+		slog.Any("extracted Instance Keys", r.Prop.InstanceKeys),
+		slog.Int("numMetrics", len(r.Prop.Metrics)),
+		slog.Int("numLabels", len(r.Prop.InstanceLabels)),
+	)
 
 	return nil
 }

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

@@ -331,7 +331,7 @@ func (d *Disk) Run(dataMap map[string]*matrix.Matrix) ([]*matrix.Matrix, *util.M
 							} else if d.SLogger.Enabled(context.Background(), slog.LevelDebug) {
 								d.SLogger.Debug(
 									"instance without keys, skipping",
-									slog.String("attribute", strings.Join(d.instanceKeys[attribute], ",")),
+									slog.Any("attribute", d.instanceKeys[attribute]),
 								)
 							}
 						}
@@ -348,7 +348,7 @@ func (d *Disk) Run(dataMap map[string]*matrix.Matrix) ([]*matrix.Matrix, *util.M
 	if len(noSet) > 0 {
 		attributes := slices.Sorted(maps.Keys(noSet))
 		if d.SLogger.Enabled(context.Background(), slog.LevelDebug) {
-			d.SLogger.Warn("No instances", slog.String("attributes", strings.Join(attributes, ",")))
+			d.SLogger.Warn("No instances", slog.Any("attributes", attributes))
 		}
 	}
 

cmd/collectors/restperf/restperf.go

@@ -17,7 +17,6 @@ import (
 	"github.com/netapp/harvest/v2/cmd/poller/collector"
 	"github.com/netapp/harvest/v2/cmd/poller/plugin"
 	"github.com/netapp/harvest/v2/cmd/tools/rest"
-	"github.com/netapp/harvest/v2/pkg/dict"
 	"github.com/netapp/harvest/v2/pkg/errs"
 	"github.com/netapp/harvest/v2/pkg/matrix"
 	"github.com/netapp/harvest/v2/pkg/set"
@@ -1581,12 +1580,13 @@ func (r *RestPerf) updateQosLabels(qos gjson.Result, instance *matrix.Instance,
 				instance.SetLabel(display, strings.Clone(value.String()))
 			}
 		}
+
 		if r.Logger.Enabled(context.Background(), slog.LevelDebug) {
 			r.Logger.Debug(
 				"",
 				slog.String("query", r.Prop.Query),
 				slog.String("key", key),
-				slog.String("qos labels", dict.String(instance.GetLabels())),
+				slog.Any("qos labels", instance.GetLabels()),
 			)
 		}
 	}

cmd/collectors/storagegrid/storagegrid.go

@@ -1,7 +1,6 @@
 package storagegrid
 
 import (
-	"context"
 	"fmt"
 	"github.com/netapp/harvest/v2/cmd/collectors/rest"
 	"github.com/netapp/harvest/v2/cmd/collectors/storagegrid/plugins/bucket"
@@ -126,14 +125,12 @@ func (s *StorageGrid) InitCache() error {
 	}
 	s.ParseCounters(counters, s.Props)
 
-	if s.Logger.Enabled(context.Background(), slog.LevelDebug) {
-		s.Logger.Debug(
-			"Initialized metric cache",
-			slog.String("extracted Instance Keys", strings.Join(s.Props.InstanceKeys, ",")),
-			slog.Int("numMetrics", len(s.Props.Metrics)),
-			slog.Int("numLabels", len(s.Props.InstanceLabels)),
-		)
-	}
+	s.Logger.Debug(
+		"Initialized metric cache",
+		slog.Any("extracted Instance Keys", s.Props.InstanceKeys),
+		slog.Int("numMetrics", len(s.Props.Metrics)),
+		slog.Int("numLabels", len(s.Props.InstanceLabels)),
+	)
 
 	return nil
 }

cmd/collectors/unix/main.go

@@ -378,7 +378,7 @@ func (u *Unix) PollData() (map[string]*matrix.Matrix, error) {
 					"skip instance",
 					slog.String("name", key),
 					slog.Int("pid", pid),
-					slog.String("cmd", strings.Join(cmd, " ")),
+					slog.Any("cmd", cmd),
 					slog.String("reason", "PID not matched with poller"),
 				)
 			}

cmd/collectors/zapi/plugins/shelf/shelf.go

@@ -2,7 +2,6 @@
 package shelf
 
 import (
-	"context"
 	"github.com/netapp/harvest/v2/cmd/collectors"
 	"github.com/netapp/harvest/v2/cmd/poller/plugin"
 	"github.com/netapp/harvest/v2/pkg/api/ontapi/zapi"
@@ -143,13 +142,11 @@ func (s *Shelf) Init() error {
 			}
 		}
 
-		if s.SLogger.Enabled(context.Background(), slog.LevelDebug) {
-			s.SLogger.Debug(
-				"added object",
-				slog.String("attribute", attribute),
-				slog.Int("metrics count", len(s.data[attribute].GetMetrics())),
-			)
-		}
+		s.SLogger.Debug(
+			"added object",
+			slog.String("attribute", attribute),
+			slog.Int("metrics count", len(s.data[attribute].GetMetrics())),
+		)
 
 		s.data[attribute].SetExportOptions(exportOptions)
 	}

cmd/collectors/zapiperf/plugins/disk/disk.go

@@ -912,10 +912,7 @@ func (d *Disk) handleCMode(shelves []*node.Node) ([]*matrix.Matrix, error) {
 						}
 					}
 				} else if d.SLogger.Enabled(context.Background(), slog.LevelDebug) {
-					d.SLogger.Debug("instance without, skipping", slog.String(
-						"skipping",
-						strings.Join(d.instanceKeys[attribute], ",")),
-					)
+					d.SLogger.Debug("instance without, skipping", slog.Any("skipping", d.instanceKeys[attribute]))
 				}
 			}
 
@@ -926,7 +923,7 @@ func (d *Disk) handleCMode(shelves []*node.Node) ([]*matrix.Matrix, error) {
 	if len(noSet) > 0 {
 		attributes := slices.Sorted(maps.Keys(noSet))
 		if d.SLogger.Enabled(context.Background(), slog.LevelDebug) {
-			d.SLogger.Warn("No instances", slog.String("attributes", strings.Join(attributes, ",")))
+			d.SLogger.Warn("No instances", slog.Any("attributes", attributes))
 		}
 	}
 

cmd/collectors/zapiperf/zapiperf.go

@@ -40,7 +40,6 @@ import (
 	"github.com/netapp/harvest/v2/cmd/collectors/zapiperf/plugins/vscan"
 	"github.com/netapp/harvest/v2/cmd/poller/collector"
 	"github.com/netapp/harvest/v2/cmd/poller/plugin"
-	"github.com/netapp/harvest/v2/pkg/dict"
 	"github.com/netapp/harvest/v2/pkg/errs"
 	"github.com/netapp/harvest/v2/pkg/matrix"
 	"github.com/netapp/harvest/v2/pkg/set"
@@ -249,12 +248,7 @@ func (z *ZapiPerf) loadParamArray(name, defaultValue string) []string {
 	p := z.Params.GetChildS(name)
 	if p != nil {
 		if v := p.GetAllChildContentS(); v != nil {
-			if z.Logger.Enabled(context.Background(), slog.LevelDebug) {
-				z.Logger.Debug("", slog.String("name", name), slog.String(
-					"values",
-					strings.Join(v, ","),
-				))
-			}
+			z.Logger.Debug("", slog.String("name", name), slog.Any("values", v))
 			return v
 		}
 	}
@@ -549,7 +543,7 @@ func (z *ZapiPerf) PollData() (map[string]*matrix.Matrix, error) {
 				if z.Logger.Enabled(context.Background(), slog.LevelDebug) {
 					z.Logger.Debug(
 						"Skip instance, key is empty",
-						slog.String("instanceKey", strings.Join(z.instanceKeys, ",")),
+						slog.Any("instanceKey", z.instanceKeys),
 						slog.String("name", i.GetChildContentS("name")),
 						slog.String("uuid", i.GetChildContentS("uuid")),
 					)
@@ -994,7 +988,7 @@ func (z *ZapiPerf) getParentOpsCounters(data *matrix.Matrix, keyAttr string) (ti
 				if z.Logger.Enabled(context.Background(), slog.LevelDebug) {
 					z.Logger.Debug(
 						"skip instance",
-						slog.String("key", strings.Join(z.instanceKeys, ",")),
+						slog.Any("key", z.instanceKeys),
 						slog.String("name", i.GetChildContentS("name")),
 						slog.String("uuid", i.GetChildContentS("uuid")),
 					)
@@ -1659,7 +1653,7 @@ func (z *ZapiPerf) PollInstance() (map[string]*matrix.Matrix, error) {
 				if z.Logger.Enabled(context.Background(), slog.LevelDebug) {
 					z.Logger.Debug(
 						"skip instance",
-						slog.String("key", strings.Join(z.instanceKeys, ",")),
+						slog.Any("key", z.instanceKeys),
 						slog.String("name", name),
 						slog.String("uuid", uuid),
 					)
@@ -1711,7 +1705,7 @@ func (z *ZapiPerf) updateQosLabels(qos *node.Node, instance *matrix.Instance, ke
 				"",
 				slog.String("query", z.Query),
 				slog.String("key", key),
-				slog.String("qos labels", dict.String(instance.GetLabels())),
+				slog.Any("qos labels", instance.GetLabels()),
 			)
 		}
 	}

cmd/poller/collector/collector.go

@@ -29,7 +29,6 @@ import (
 	"reflect"
 	"runtime/debug"
 	"strconv"
-	"strings"
 	"sync"
 	"time"
 
@@ -577,56 +576,74 @@ func (c *AbstractCollector) logMetadata(taskName string, stats exporter.Stats) {
 	if inst == nil {
 		return
 	}
-	var attrs []any
 
-	// convert microseconds to milliseconds and names ending with _time into -> *Ms
-	microToMilli := func(value float64, field string) {
-		v := int64(math.Round(value / 1000))
-		attrs = append(attrs, slog.Int64(field[0:len(field)-5]+"Ms", v))
+	// lookup a time metric and convert it from microseconds to milliseconds
+	// rename the metric from name_time to nameMs
+	timeToMilli := func(field string) slog.Attr {
+		metric := metrics[field]
+		keyMs := field[0:len(field)-5] + "Ms"
+		if metric == nil {
+			return slog.Attr{}
+		}
+		metricValue, _ := metric.GetValueFloat64(inst)
+		v := int64(math.Round(metricValue / 1000))
+		return slog.Int64(keyMs, v)
 	}
 
-	if taskName == "data" {
-		for _, metric := range metrics {
-			mName := metric.GetName()
-			if mName == "task_time" {
-				// don't log since it is covered by other durations
-				continue
-			}
-			value, _ := metric.GetValueFloat64(inst)
-			if strings.HasSuffix(mName, "_time") {
-				microToMilli(value, mName)
-			} else {
-				attrs = append(attrs, slog.Int64(mName, int64(value)))
-			}
+	// lookup a metric and convert it to an int64
+	int64Field := func(field string) slog.Attr {
+		metric := metrics[field]
+		if metric == nil {
+			return slog.Attr{}
 		}
+		metricValue, _ := metric.GetValueInt64(inst)
+		return slog.Int64(field, metricValue)
+	}
 
-		attrs = append(attrs,
+	switch {
+	case taskName == "data":
+		c.Logger.Info(
+			"Collected",
+			timeToMilli("api_time"),
+			int64Field("bytesRx"),
+			timeToMilli("calc_time"),
+			timeToMilli("export_time"),
+			int64Field("instances"),
 			slog.Uint64("instancesExported", stats.InstancesExported),
+			int64Field("metrics"),
 			slog.Uint64("metricsExported", stats.MetricsExported),
+			int64Field("numCalls"),
+			int64Field("numPartials"),
+			timeToMilli("parse_time"),
+			int64Field("pluginInstances"),
+			timeToMilli("plugin_time"),
+			timeToMilli("poll_time"),
+			int64Field("skips"),
+			int64Field("zBegin"),
+		)
+	case taskName == "instance":
+		c.Logger.Info(
+			"Collected",
+			slog.String("task", "instance"),
+			timeToMilli("api_time"),
+			int64Field("bytesRx"),
+			int64Field("instances"),
+			int64Field("numCalls"),
+			timeToMilli("poll_time"),
+			int64Field("zBegin"),
+		)
+	case taskName == "counter":
+		c.Logger.Info(
+			"Collected",
+			slog.String("task", "counter"),
+			timeToMilli("api_time"),
+			int64Field("bytesRx"),
+			int64Field("metrics"),
+			int64Field("numCalls"),
+			timeToMilli("poll_time"),
+			int64Field("zBegin"),
 		)
-
-	} else {
-		logFields := []string{"api_time", "poll_time"}
-		for _, field := range logFields {
-			value, _ := c.Metadata.GetMetric(field).GetValueFloat64(inst)
-			microToMilli(value, field)
-		}
-
-		epoch, _ := c.Metadata.GetMetric(begin).GetValueFloat64(inst)
-		attrs = append(attrs, slog.Int64(begin, int64(epoch)))
-
-		if taskName == "counter" {
-			v, _ := c.Metadata.GetMetric("metrics").GetValueInt64(inst)
-			attrs = append(attrs, slog.Int64("metrics", v))
-		} else if taskName == "instance" {
-			v, _ := c.Metadata.GetMetric("instances").GetValueInt64(inst)
-			attrs = append(attrs, slog.Int64("instances", v))
-		}
-
-		attrs = append(attrs, slog.String("task", taskName))
 	}
-
-	c.Logger.Info("Collected", attrs...)
 }
 
 // GetName returns name of the collector