Update logging in coalesce.go to use structured key:pairs.

Update logger test framework to handle more test cases using a builder pattern for easier reuse

Signed-off-by: James Payne <jamoflaw@gmail.com>

pkg/chart/v2/util/coalesce.go

@@ -114,7 +114,7 @@ func coalesceDeps(chrt *chart.Chart, dest map[string]interface{}, prefix string,
 			dvmap := dv.(map[string]interface{})
 			subPrefix := concatPrefix(prefix, chrt.Metadata.Name)
 			// Get globals out of dest and merge them into dvmap.
-			coalesceGlobals(dvmap, dest, subPrefix, merge)
+			coalesceGlobals(slog.Default().With(slog.String("chart", chrt.Name())), dvmap, dest, subPrefix, merge)
 			// Now coalesce the rest of the values.
 			var err error
 			dest[subchart.Name()], err = coalesce(subchart, dvmap, subPrefix, merge)
@@ -129,20 +129,20 @@ func coalesceDeps(chrt *chart.Chart, dest map[string]interface{}, prefix string,
 // coalesceGlobals copies the globals out of src and merges them into dest.
 //
 // For convenience, returns dest.
-func coalesceGlobals(dest, src map[string]interface{}, prefix string, _ bool) {
+func coalesceGlobals(log *slog.Logger, dest, src map[string]interface{}, prefix string, _ bool) {
 	var dg, sg map[string]interface{}
 
 	if destglob, ok := dest[GlobalKey]; !ok {
 		dg = make(map[string]interface{})
 	} else if dg, ok = destglob.(map[string]interface{}); !ok {
-		slog.Warn(fmt.Sprintf("warning: skipping globals because destination %s is not a table.", GlobalKey))
+		log.Warn(fmt.Sprintf("skipping globals because destination %s is not a table.", GlobalKey), slog.String("key", GlobalKey), slog.String("error", "not a table"))
 		return
 	}
 
 	if srcglob, ok := src[GlobalKey]; !ok {
 		sg = make(map[string]interface{})
 	} else if sg, ok = srcglob.(map[string]interface{}); !ok {
-		slog.Warn(fmt.Sprintf("warning: skipping globals because source %s is not a table.", GlobalKey))
+		log.Warn(fmt.Sprintf("skipping globals because source %s is not a table.", GlobalKey), slog.String("key", GlobalKey), slog.String("error", "not a table"))
 		return
 	}
 
@@ -158,7 +158,7 @@ func coalesceGlobals(dest, src map[string]interface{}, prefix string, _ bool) {
 				dg[key] = vv
 			} else {
 				if destvmap, ok := destv.(map[string]interface{}); !ok {
-					slog.Warn(fmt.Sprintf("Conflict: cannot merge map onto non-map for %q. Skipping.", key))
+					log.Warn(fmt.Sprintf("cannot merge map onto non-map for %q. Skipping.", key), slog.String("key", key), slog.String("error", "cannot merge map onto non-map"))
 				} else {
 					// Basically, we reverse order of coalesce here to merge
 					// top-down.
@@ -166,13 +166,13 @@ func coalesceGlobals(dest, src map[string]interface{}, prefix string, _ bool) {
 					// In this location coalesceTablesFullKey should always have
 					// merge set to true. The output of coalesceGlobals is run
 					// through coalesce where any nils will be removed.
-					coalesceTablesFullKey(vv, destvmap, subPrefix, true)
+					coalesceTablesFullKey(log, vv, destvmap, subPrefix, true)
 					dg[key] = vv
 				}
 			}
 		} else if dv, ok := dg[key]; ok && istable(dv) {
 			// It's not clear if this condition can actually ever trigger.
-			slog.Warn(fmt.Sprintf("key %s is table. Skipping", key))
+			log.Warn(fmt.Sprintf("key %s is table. Skipping", key), slog.String("key", key), slog.String("error", "cannot merge as key is a table"))
 		} else {
 			// TODO: Do we need to do any additional checking on the value?
 			dg[key] = val
@@ -205,8 +205,8 @@ func coalesceValues(c *chart.Chart, v map[string]interface{}, prefix string, mer
 		// If there is an error something is wrong with copying c.Values it
 		// means there is a problem in the deep copying package or something
 		// wrong with c.Values. In this case we will use c.Values and report
-		// an error.
+		// a warning.
-		slog.Warn(fmt.Sprintf("warning: unable to copy values, err: %s", err))
+		slog.Warn("unable to copy values", slog.String("chart", c.Name()), slog.String("error", err.Error()))
 		vc = c.Values
 	} else {
 		vc, ok = valuesCopy.(map[string]interface{})
@@ -214,7 +214,7 @@ func coalesceValues(c *chart.Chart, v map[string]interface{}, prefix string, mer
 			// c.Values has a map[string]interface{} structure. If the copy of
 			// it cannot be treated as map[string]interface{} there is something
 			// strangely wrong. Log it and use c.Values
-			slog.Warn("warning: unable to convert values copy to values type")
+			slog.Warn("unable to convert values copy to values type", slog.String("chart", c.Name()))
 			vc = c.Values
 		}
 	}
@@ -234,7 +234,7 @@ func coalesceValues(c *chart.Chart, v map[string]interface{}, prefix string, mer
 					// If the original value is nil, there is nothing to coalesce, so we don't print
 					// the warning
 					if val != nil {
-						slog.Warn(fmt.Sprintf("warning: skipped value for %s.%s: Not a table.", subPrefix, key))
+						slog.Warn(fmt.Sprintf("skipped value for %s.%s", subPrefix, key), slog.String("chart", c.Name()), slog.String("key", fmt.Sprintf("%s.%s", subPrefix, key)), slog.String("error", "not a table"))
 					}
 				} else {
 					// If the key is a child chart, coalesce tables with Merge set to true
@@ -242,7 +242,7 @@ func coalesceValues(c *chart.Chart, v map[string]interface{}, prefix string, mer
 
 					// Because v has higher precedence than nv, dest values override src
 					// values.
-					coalesceTablesFullKey(dest, src, concatPrefix(subPrefix, key), merge)
+					coalesceTablesFullKey(slog.Default().With(slog.String("chart", c.Name())), dest, src, concatPrefix(subPrefix, key), merge)
 				}
 			}
 		} else {
@@ -265,17 +265,21 @@ func childChartMergeTrue(chrt *chart.Chart, key string, merge bool) bool {
 //
 // dest is considered authoritative.
 func CoalesceTables(dst, src map[string]interface{}) map[string]interface{} {
-	return coalesceTablesFullKey(dst, src, "", false)
+	return coalesceTablesFullKey(nil, dst, src, "", false)
 }
 
 func MergeTables(dst, src map[string]interface{}) map[string]interface{} {
-	return coalesceTablesFullKey(dst, src, "", true)
+	return coalesceTablesFullKey(nil, dst, src, "", true)
 }
 
 // coalesceTablesFullKey merges a source map into a destination map.
 //
 // dest is considered authoritative.
-func coalesceTablesFullKey(dst, src map[string]interface{}, prefix string, merge bool) map[string]interface{} {
+func coalesceTablesFullKey(log *slog.Logger, dst, src map[string]interface{}, prefix string, merge bool) map[string]interface{} {
+	if log == nil {
+		log = slog.Default()
+	}
+
 	// When --reuse-values is set but there are no modifications yet, return new values
 	if src == nil {
 		return dst
@@ -293,13 +297,12 @@ func coalesceTablesFullKey(dst, src map[string]interface{}, prefix string, merge
 			dst[key] = val
 		} else if istable(val) {
 			if istable(dv) {
-				slog.Warn("testing")
+				coalesceTablesFullKey(log, dv.(map[string]interface{}), val.(map[string]interface{}), fullkey, merge)
-				coalesceTablesFullKey(dv.(map[string]interface{}), val.(map[string]interface{}), fullkey, merge)
 			} else {
-				slog.Warn(fmt.Sprintf("cannot overwrite table with non table for %s (%v)", fullkey, val))
+				log.Warn(fmt.Sprintf("cannot overwrite table with non table for %s (%v)", fullkey, val), slog.String("key", fullkey), slog.String("error", "cannot overwrite table with non-table"))
 			}
 		} else if istable(dv) && val != nil {
-			slog.Warn(fmt.Sprintf("destination for %s is a table. Ignoring non-table value (%v)", fullkey, val))
+			log.Warn(fmt.Sprintf("destination for %s is a table. Ignoring non-table value (%v)", fullkey, val), slog.String("key", fullkey), slog.String("error", "destination is a table"))
 		}
 	}
 	return dst

pkg/chart/v2/util/coalesce_test.go

@@ -702,25 +702,50 @@ func TestCoalesceValuesWarnings(t *testing.T) {
 		},
 	}
 
-	// Capture logs emitted from slog
+	// Get all logs emitted from slog
 	defaultLogger := slog.Default()
-	logCaptureHandler := NewLogCaptureHandler(nil)
+	handler := NewLogCaptureHandler(nil)
-	slog.SetDefault(slog.New(logCaptureHandler))
+	slog.SetDefault(slog.New(handler))
 
 	_, err := coalesce(c, vals, "", false)
 	if err != nil {
 		t.Fatal(err)
 	}
 
-	logOutput := logCaptureHandler.Records().AsMessageSlice()
+	// Capture the logs
+	capturedLogOutput := handler.Capture()
 
 	t.Logf("vals: %v", vals)
-	assert.Contains(t, logOutput, "warning: skipped value for level1.level2.level3.boat: Not a table.")
+
-	assert.Contains(t, logOutput, "warning: destination for level1.level2.level3.spear.tip is a table. Ignoring non-table value (true)")
+	// All warnings should have context as to where the warning is being emitted
-	assert.Contains(t, logOutput, "warning: cannot overwrite table with non table for level1.level2.level3.spear.sail (map[cotton:true])")
+	capturedLogOutput.Filter(RecordLevelMatches(slog.LevelWarn)).
+		AssertThat(t).
+		HasAttr("chart").
+		HasAttr("error").
+		HasAttr("key")
+
+	capturedLogOutput.Filter(RecordMessageMatches("skipped value for level1.level2.level3.boat")).
+		AssertThat(t).
+		MatchesExactly(1).
+		AtLevel(slog.LevelWarn).
+		HasAttrValueString("chart", "level3")
+
+	capturedLogOutput.Filter(RecordMessageMatches("destination for level1.level2.level3.spear.tip is a table. Ignoring non-table value (true)")).
+		AssertThat(t).
+		MatchesExactly(1).
+		AtLevel(slog.LevelWarn).
+		HasAttrValueString("chart", "level3").
+		HasAttr("error")
+
+	capturedLogOutput.Filter(RecordMessageMatches("cannot overwrite table with non table for level1.level2.level3.spear.sail (map[cotton:true])")).
+		AssertThat(t).
+		MatchesExactly(1).
+		AtLevel(slog.LevelWarn).
+		HasAttrValueString("chart", "level3").
+		HasAttr("error")
 
 	// Reset and set the default logger back to its original state
-	logCaptureHandler.Reset()
+	handler.Reset()
 	slog.SetDefault(defaultLogger)
 }
 

pkg/chart/v2/util/utilities_test.go

@@ -19,26 +19,59 @@ package util
 import (
 	"context"
 	"log/slog"
+	"strings"
 	"sync"
+	"testing"
+
+	"github.com/stretchr/testify/assert"
 )
 
 // A simple handler to record the log messages emitted by slog.
 // Intended to be used only by tests
 type LogCaptureHandler struct {
-	mu      *sync.Mutex
+	mu           *sync.Mutex
-	records []slog.Record
+	records      *[]slog.Record
-	opts    slog.HandlerOptions
+	opts         slog.HandlerOptions
+	handlerAttrs []slog.Attr
+}
+
+type LogCaptureRecord struct {
+	record slog.Record
+	attrs  []slog.Attr
+}
+
+// Clones the record and associated attributes
+func (l *LogCaptureRecord) Clone() LogCaptureRecord {
+	copyAttrs := make([]slog.Attr, len(l.attrs))
+	copy(copyAttrs, l.attrs)
+	return LogCaptureRecord{
+		record: l.record.Clone(),
+		attrs:  copyAttrs,
+	}
+}
+
+// A point in time capture of the logs emitted by slog
+type LogCaptureSlice struct {
+	records []LogCaptureRecord
 }
 
-type LogCaptureSlice []slog.Record
+// Build assertions based off the captured/filtered slice of records
+type LogCaptureSliceAssertionBuilder struct {
+	t *testing.T
+	l *LogCaptureSlice
+}
 
 func NewLogCaptureHandler(opts *slog.HandlerOptions) *LogCaptureHandler {
 	if opts == nil {
 		opts = &slog.HandlerOptions{}
 	}
+
+	records := make([]slog.Record, 0)
 	return &LogCaptureHandler{
-		mu:   &sync.Mutex{},
+		mu:           &sync.Mutex{},
-		opts: *opts,
+		records:      &records,
+		opts:         *opts,
+		handlerAttrs: make([]slog.Attr, 0),
 	}
 }
 
@@ -47,10 +80,14 @@ func (h *LogCaptureHandler) Enabled(_ context.Context, _ slog.Level) bool {
 	return true
 }
 
+// Handle logs emitted by slog and capture
 func (h *LogCaptureHandler) Handle(_ context.Context, r slog.Record) error {
 	h.mu.Lock()
 	defer h.mu.Unlock()
-	h.records = append(h.records, r)
+
+	r.AddAttrs(h.handlerAttrs...)
+	*h.records = append(*h.records, r)
+
 	return nil
 }
 
@@ -69,12 +106,14 @@ func (h *LogCaptureHandler) WithAttrs(attrs []slog.Attr) slog.Handler {
 
 		// Copy the same records as we want to be able to collate _all_ the log messages
 		// emitted by slog sources
-		records: h.records,
+		records:      h.records,
+		handlerAttrs: append(h.handlerAttrs, attrs...),
 	}
 }
 
 // See comment on WithAttrs regarding reusing the mutex + records slice
-func (h *LogCaptureHandler) WithGroup(name string) slog.Handler {
+// WithGroup is fairly unsupported in this right now as its not used in the codebase
+func (h *LogCaptureHandler) WithGroup(_ string) slog.Handler {
 	return &LogCaptureHandler{
 		mu: h.mu,
 		opts: slog.HandlerOptions{
@@ -89,43 +128,158 @@ func (h *LogCaptureHandler) WithGroup(name string) slog.Handler {
 	}
 }
 
-// Records returns a copy of the captured log records
+// Capture returns a point in time copy of the captured log records
-func (h *LogCaptureHandler) Records() *LogCaptureSlice {
+func (h *LogCaptureHandler) Capture() *LogCaptureSlice {
 	h.mu.Lock()
 	defer h.mu.Unlock()
 
-	records := make([]slog.Record, len(h.records))
+	result := LogCaptureSlice{
-	copy(records, h.records)
+		records: make([]LogCaptureRecord, 0),
+	}
+	for _, record := range *h.records {
+		l := LogCaptureRecord{}
+		l.record = record.Clone()
+		l.record.Attrs(func(a slog.Attr) bool {
+			if a.Key != "" {
+				l.attrs = append(l.attrs, a)
+			}
+			return true
+		})
 
-	result := LogCaptureSlice(records)
+		result.records = append(result.records, l)
+	}
 	return &result
 }
 
-// Converts the captured log records into a map of log message and log level
+func (c *LogCaptureSlice) Filter(filterFn func(r *LogCaptureRecord) bool) *LogCaptureSlice {
-func (l *LogCaptureSlice) AsMessageLevelMap() map[string]slog.Level {
+	result := LogCaptureSlice{
+		records: make([]LogCaptureRecord, 0),
+	}
 
-	result := make(map[string]slog.Level)
+	for _, record := range c.records {
-	for _, record := range *l {
+		if filterFn(&record) {
-		result[record.Message] = record.Level
+			result.records = append(result.records, record.Clone())
+		}
 	}
 
-	return result
+	return &result
+}
+
+func RecordMessageMatches(message string) func(r *LogCaptureRecord) bool {
+	return func(r *LogCaptureRecord) bool {
+		return r.record.Message == message
+	}
 }
 
-// Converts the captured log records into a slice of log messages
+func RecordMessageContains(substring string) func(r *LogCaptureRecord) bool {
-func (l *LogCaptureSlice) AsMessageSlice() []string {
+	return func(r *LogCaptureRecord) bool {
+		return strings.Contains(r.record.Message, substring)
+	}
+}
 
-	result := make([]string, 0)
+func RecordLevelMatches(level slog.Level) func(r *LogCaptureRecord) bool {
-	for _, record := range *l {
+	return func(r *LogCaptureRecord) bool {
-		result = append(result, record.Message)
+		return r.record.Level == level
 	}
+}
 
-	return result
+func RecordLevelAboveEqual(level slog.Level) func(r *LogCaptureRecord) bool {
+	return func(r *LogCaptureRecord) bool {
+		return r.record.Level >= level
+	}
+}
+
+func RecordLevelAbove(level slog.Level) func(r *LogCaptureRecord) bool {
+	return func(r *LogCaptureRecord) bool {
+		return r.record.Level > level
+	}
+}
+
+func RecordLevelBelowEqual(level slog.Level) func(r *LogCaptureRecord) bool {
+	return func(r *LogCaptureRecord) bool {
+		return r.record.Level <= level
+	}
+}
+
+func RecordLevelBelow(level slog.Level) func(r *LogCaptureRecord) bool {
+	return func(r *LogCaptureRecord) bool {
+		return r.record.Level < level
+	}
+}
+
+// Start an assertion builder for test validation
+func (c *LogCaptureSlice) AssertThat(t *testing.T) *LogCaptureSliceAssertionBuilder {
+	return &LogCaptureSliceAssertionBuilder{
+		t: t,
+		l: c,
+	}
 }
 
 // Reset clears the captured log messages.
 func (h *LogCaptureHandler) Reset() {
 	h.mu.Lock()
 	defer h.mu.Unlock()
-	h.records = make([]slog.Record, 0)
+
+	records := make([]slog.Record, 0)
+
+	h.records = &records
+}
+
+// Asserts that the log capture contains exactly the number of records specified
+func (b *LogCaptureSliceAssertionBuilder) MatchesExactly(count int) *LogCaptureSliceAssertionBuilder {
+	assert.Len(b.t, b.l.records, count, "number of records must match exactly %d record, but is %d", count, len(b.l.records))
+	return b
+}
+
+// Asserts that all log records at at a specific level
+func (b *LogCaptureSliceAssertionBuilder) AtLevel(level slog.Level) *LogCaptureSliceAssertionBuilder {
+	if len(b.l.records) == 0 {
+		assert.Fail(b.t, "expecting records to match level but there were no records to match")
+	}
+
+	for _, record := range b.l.records {
+		assert.True(b.t, record.record.Level == level, "record '%s' does not match the expected level. Was %d expected %d", record.record.Message, record.record.Level, level)
+	}
+
+	return b
+}
+
+func (b *LogCaptureSliceAssertionBuilder) HasAttr(key string) *LogCaptureSliceAssertionBuilder {
+	if len(b.l.records) == 0 {
+		assert.Fail(b.t, "expecting records to test for attributes but there were no records to match")
+	}
+
+	for _, record := range b.l.records {
+
+		hasAttr := false
+		for _, attr := range record.attrs {
+			if attr.Key == key {
+				hasAttr = true
+			}
+		}
+
+		assert.True(b.t, hasAttr, "record '%s' does not contain the attribute key '%s'", record.record.Message, key)
+	}
+
+	return b
+}
+
+func (b *LogCaptureSliceAssertionBuilder) HasAttrValueString(key string, value string) *LogCaptureSliceAssertionBuilder {
+	if len(b.l.records) == 0 {
+		assert.Fail(b.t, "expecting records to test for attributes but there were no records to match")
+	}
+
+	for _, record := range b.l.records {
+		hasAttr := false
+		for _, attr := range record.attrs {
+			if attr.Key == key {
+				hasAttr = true
+				assert.True(b.t, attr.Value.String() == value, "record '%s', attribute '%s' expected value '%s' but got '%s'", record.record.Message, key, value, attr.Value.String())
+			}
+		}
+
+		assert.True(b.t, hasAttr, "record '%s' does not contain the attribute key '%s'", record.record.Message, key)
+	}
+
+	return b
 }