diff --git a/pkg/chart/v2/util/coalesce.go b/pkg/chart/v2/util/coalesce.go index e062d0ec5..d650ca7b4 100644 --- a/pkg/chart/v2/util/coalesce.go +++ b/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. - slog.Warn(fmt.Sprintf("warning: unable to copy values, err: %s", err)) + // a warning. + 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(dv.(map[string]interface{}), val.(map[string]interface{}), fullkey, merge) + coalesceTablesFullKey(log, 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 diff --git a/pkg/chart/v2/util/coalesce_test.go b/pkg/chart/v2/util/coalesce_test.go index 829b6c939..55c34ee68 100644 --- a/pkg/chart/v2/util/coalesce_test.go +++ b/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) - slog.SetDefault(slog.New(logCaptureHandler)) + handler := NewLogCaptureHandler(nil) + 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)") - assert.Contains(t, logOutput, "warning: cannot overwrite table with non table for level1.level2.level3.spear.sail (map[cotton:true])") + + // All warnings should have context as to where the warning is being emitted + 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) } diff --git a/pkg/chart/v2/util/utilities_test.go b/pkg/chart/v2/util/utilities_test.go index 541128697..d8a6188e7 100644 --- a/pkg/chart/v2/util/utilities_test.go +++ b/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 - records []slog.Record - opts slog.HandlerOptions + mu *sync.Mutex + records *[]slog.Record + 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{}, - opts: *opts, + mu: &sync.Mutex{}, + 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 -func (h *LogCaptureHandler) Records() *LogCaptureSlice { +// Capture returns a point in time copy of the captured log records +func (h *LogCaptureHandler) Capture() *LogCaptureSlice { h.mu.Lock() defer h.mu.Unlock() - records := make([]slog.Record, len(h.records)) - copy(records, h.records) + result := LogCaptureSlice{ + 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 (l *LogCaptureSlice) AsMessageLevelMap() map[string]slog.Level { +func (c *LogCaptureSlice) Filter(filterFn func(r *LogCaptureRecord) bool) *LogCaptureSlice { + result := LogCaptureSlice{ + records: make([]LogCaptureRecord, 0), + } - result := make(map[string]slog.Level) - for _, record := range *l { - result[record.Message] = record.Level + for _, record := range c.records { + if filterFn(&record) { + 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 (l *LogCaptureSlice) AsMessageSlice() []string { +func RecordMessageContains(substring string) func(r *LogCaptureRecord) bool { + return func(r *LogCaptureRecord) bool { + return strings.Contains(r.record.Message, substring) + } +} - result := make([]string, 0) - for _, record := range *l { - result = append(result, record.Message) +func RecordLevelMatches(level slog.Level) func(r *LogCaptureRecord) bool { + return func(r *LogCaptureRecord) bool { + 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 }