From 55d1ebf03350fc488061bfb18e20011ca38c6305 Mon Sep 17 00:00:00 2001 From: matt durham Date: Wed, 1 May 2024 14:46:31 -0400 Subject: [PATCH] pr feedback --- internal/alloy/logging/deferred_handler.go | 12 +- .../alloy/logging/deferred_handler_test.go | 27 +- internal/alloy/logging/handler.go | 25 +- internal/alloy/logging/handler_test.go | 41 +- internal/alloy/logging/logger.go | 44 +- internal/alloy/logging/slogtest.go | 408 ------------------ 6 files changed, 75 insertions(+), 482 deletions(-) delete mode 100644 internal/alloy/logging/slogtest.go diff --git a/internal/alloy/logging/deferred_handler.go b/internal/alloy/logging/deferred_handler.go index 842da0a3ed..1e3f29679b 100644 --- a/internal/alloy/logging/deferred_handler.go +++ b/internal/alloy/logging/deferred_handler.go @@ -12,7 +12,6 @@ type deferredSlogHandler struct { group string attrs []slog.Attr children []*deferredSlogHandler - parent *deferredSlogHandler handle slog.Handler l *Logger } @@ -24,12 +23,12 @@ func newDeferredHandler(l *Logger) *deferredSlogHandler { } } -func (d *deferredSlogHandler) Handle(_ context.Context, r slog.Record) error { +func (d *deferredSlogHandler) Handle(ctx context.Context, r slog.Record) error { d.mut.RLock() defer d.mut.RUnlock() if d.handle != nil { - return d.handle.Handle(context.Background(), r) + return d.handle.Handle(ctx, r) } d.l.addRecord(r, d) return nil @@ -37,12 +36,12 @@ func (d *deferredSlogHandler) Handle(_ context.Context, r slog.Record) error { // Enabled reports whether the handler handles records at the given level. // The handler ignores records whose level is lower. -func (d *deferredSlogHandler) Enabled(_ context.Context, level slog.Level) bool { +func (d *deferredSlogHandler) Enabled(ctx context.Context, level slog.Level) bool { d.mut.RLock() defer d.mut.RUnlock() if d.handle != nil { - return d.handle.Enabled(context.Background(), level) + return d.handle.Enabled(ctx, level) } return true } @@ -61,7 +60,6 @@ func (d *deferredSlogHandler) WithAttrs(attrs []slog.Attr) slog.Handler { attrs: attrs, children: make([]*deferredSlogHandler, 0), l: d.l, - parent: d, } d.children = append(d.children, child) return child @@ -79,7 +77,6 @@ func (d *deferredSlogHandler) WithGroup(name string) slog.Handler { children: make([]*deferredSlogHandler, 0), group: name, l: d.l, - parent: d, } d.children = append(d.children, child) return child @@ -104,4 +101,5 @@ func (d *deferredSlogHandler) buildHandlers(parent slog.Handler) { for _, child := range d.children { child.buildHandlers(d.handle) } + d.children = nil } diff --git a/internal/alloy/logging/deferred_handler_test.go b/internal/alloy/logging/deferred_handler_test.go index e150e90f04..45d0ceeaf3 100644 --- a/internal/alloy/logging/deferred_handler_test.go +++ b/internal/alloy/logging/deferred_handler_test.go @@ -9,11 +9,23 @@ import ( "log/slog" "strings" "testing" + "testing/slogtest" ) func TestDefferredSlogTester(t *testing.T) { buf := &bytes.Buffer{} + var l *Logger results := func(t *testing.T) map[string]any { + // Nothing has been written to the byte stream, it only exists in the internal logger buffer + // We need to call l.Update to flush it to the byte stream. + // This does something a bit ugly where it DEPENDS on the var in slogtest.Run, if the behavior of slogtest.Run + // changes this may break the tests. + updateErr := l.Update(Options{ + Level: "debug", + Format: "json", + WriteTo: nil, + }) + require.NoError(t, updateErr) line := buf.Bytes() if len(line) == 0 { return nil @@ -21,17 +33,24 @@ func TestDefferredSlogTester(t *testing.T) { var m map[string]any unmarshalErr := json.Unmarshal(line, &m) require.NoError(t, unmarshalErr) - // Need to reset the buffer between each test + // The tests expect time field and not ts. + if _, found := m["ts"]; found { + m[slog.TimeKey] = m["ts"] + delete(m, "ts") + } + // Need to reset the buffer and logger between each test. + l = nil buf.Reset() return m } // Had to add some custom logic to handle updated for the deferred tests. // Also ignore anything that modifies the log line, which are two tests. - RunDeferredTests(t, func(t *testing.T) *Logger { - l, err := NewDeferred(buf) + slogtest.Run(t, func(t *testing.T) slog.Handler { + var err error + l, err = NewDeferred(buf) require.NoError(t, err) - return l + return l.Handler() }, results) } diff --git a/internal/alloy/logging/handler.go b/internal/alloy/logging/handler.go index eb9a4a6439..d85f798a5a 100644 --- a/internal/alloy/logging/handler.go +++ b/internal/alloy/logging/handler.go @@ -107,7 +107,7 @@ func (h *handler) buildHandler() slog.Handler { } func (h *handler) WithAttrs(attrs []slog.Attr) slog.Handler { - newNest := make([]nesting, len(h.nested)+1) + newNest := make([]nesting, 0, len(h.nested)+1) newNest = append(newNest, h.nested...) newNest = append(newNest, nesting{ attrs: attrs, @@ -124,7 +124,7 @@ func (h *handler) WithAttrs(attrs []slog.Attr) slog.Handler { } func (h *handler) WithGroup(name string) slog.Handler { - newNest := make([]nesting, len(h.nested)+1) + newNest := make([]nesting, 0, len(h.nested)+1) newNest = append(newNest, h.nested...) newNest = append(newNest, nesting{ group: name, @@ -194,24 +194,3 @@ func replace(groups []string, a slog.Attr) slog.Attr { return a } - -// testReplace is used for unit tests so we can ensure the time and source fields are consistent. -func testReplace(groups []string, a slog.Attr) slog.Attr { - ra := replace(groups, a) - switch a.Key { - case "ts": - fallthrough - case "time": - return slog.Attr{ - Key: "ts", - Value: slog.StringValue("2024-04-29T18:26:21.37723798Z"), - } - case "source": - return slog.Attr{ - Key: "source", - Value: slog.StringValue("test_source"), - } - default: - return ra - } -} diff --git a/internal/alloy/logging/handler_test.go b/internal/alloy/logging/handler_test.go index 6d715f5cab..43fee94724 100644 --- a/internal/alloy/logging/handler_test.go +++ b/internal/alloy/logging/handler_test.go @@ -7,6 +7,7 @@ import ( "io" "log/slog" "testing" + "testing/slogtest" "time" "github.com/stretchr/testify/require" @@ -60,11 +61,16 @@ func TestSlogTester(t *testing.T) { var m map[string]any unmarshalErr := json.Unmarshal(line, &m) require.NoError(t, unmarshalErr) + // The tests expect time field and not ts. + if _, found := m["ts"]; found { + m[slog.TimeKey] = m["ts"] + delete(m, "ts") + } ms = append(ms, m) } return ms } - err = TestHandler(l.handler, results) + err = slogtest.TestHandler(l.handler, results) require.NoError(t, err) } @@ -83,3 +89,36 @@ func getTestHandler(t *testing.T, w io.Writer) slog.Handler { return l.handler } + +// testReplace is used for unit tests so we can ensure the time and source fields are consistent. +func testReplace(groups []string, a slog.Attr) slog.Attr { + ra := replace(groups, a) + switch a.Key { + case "ts": + fallthrough + case "time": + return slog.Attr{ + Key: "ts", + Value: slog.StringValue("2024-04-29T18:26:21.37723798Z"), + } + case "source": + return slog.Attr{ + Key: "source", + Value: slog.StringValue("test_source"), + } + default: + return ra + } +} + +// newDeferredTest creates a new logger with the default log level and format. Used for tests. +// The logger is not updated during initialization. +func newDeferredTest(w io.Writer) (*Logger, error) { + l, err := NewDeferred(w) + if err != nil { + return nil, err + } + l.handler.replacer = testReplace + + return l, nil +} diff --git a/internal/alloy/logging/logger.go b/internal/alloy/logging/logger.go index 865ba31138..92614aa08b 100644 --- a/internal/alloy/logging/logger.go +++ b/internal/alloy/logging/logger.go @@ -43,33 +43,11 @@ func (l *Logger) Enabled(ctx context.Context, level slog.Level) bool { // New creates a New logger with the default log level and format. func New(w io.Writer, o Options) (*Logger, error) { - var ( - leveler slog.LevelVar - format formatVar - writer writerVar - ) - - l := &Logger{ - inner: w, - - buffer: make([]*bufferedItem, 0), - hasLogFormat: false, - - level: &leveler, - format: &format, - writer: &writer, - handler: &handler{ - w: &writer, - leveler: &leveler, - formatter: &format, - replacer: replace, - }, + l, err := NewDeferred(w) + if err != nil { + return nil, err } - // We always need to make a deferred handler since that is what is always exposed, - // that being said the Update command will immediately set its interior handler. - l.deferredSlog = newDeferredHandler(l) - - if err := l.Update(o); err != nil { + if err = l.Update(o); err != nil { return nil, err } @@ -106,18 +84,6 @@ func NewDeferred(w io.Writer) (*Logger, error) { return l, nil } -// newDeferredTest creates a new logger with the default log level and format. Used for tests. -// The logger is not updated during initialization. -func newDeferredTest(w io.Writer) (*Logger, error) { - l, err := NewDeferred(w) - if err != nil { - return nil, err - } - l.handler.replacer = testReplace - - return l, nil -} - // Handler returns a [slog.Handler]. The returned Handler remains valid if l is // updated. func (l *Logger) Handler() slog.Handler { return l.deferredSlog } @@ -155,7 +121,7 @@ func (l *Logger) Update(o Options) error { slogadapter.GoKit(l.handler).Log(bufferedLogChunk.kvps...) } else { // We now can check to see if if our buffered log is at the right level. - if l.level.Level() <= bufferedLogChunk.record.Level { + if bufferedLogChunk.handler.handle.Enabled(context.Background(), bufferedLogChunk.record.Level) { // These will always be valid due to the build handlers call above. bufferedLogChunk.handler.handle.Handle(context.Background(), bufferedLogChunk.record) } diff --git a/internal/alloy/logging/slogtest.go b/internal/alloy/logging/slogtest.go deleted file mode 100644 index 9f3b801004..0000000000 --- a/internal/alloy/logging/slogtest.go +++ /dev/null @@ -1,408 +0,0 @@ -// Copyright 2023 The Go Authors. All rights reserved. -// Use of this source code is governed by a BSD-style -// license that can be found in the LICENSE file. - -// Package logging implements support for testing implementations of log/slog.Handler. -package logging - -// NOTE THIS IS COPIED FROM GO AND PRIMARILY USED SINCE WE OVERRIDE THE NAME OF SOME FIELDS - -import ( - "context" - "errors" - "fmt" - "github.com/stretchr/testify/require" - "log/slog" - "reflect" - "runtime" - "testing" - "time" -) - -type testCase struct { - // Subtest name. - name string - // If non-empty, explanation explains the violated constraint. - explanation string - // f executes a single log event using its argument logger. - // So that mkdescs.sh can generate the right description, - // the body of f must appear on a single line whose first - // non-whitespace characters are "l.". - f func(*slog.Logger) - // If mod is not nil, it is called to modify the Record - // generated by the Logger before it is passed to the Handler. - mod func(*slog.Record) - // checks is a list of checks to run on the result. - checks []check -} - -var cases = []testCase{ - { - name: "built-ins", - explanation: withSource("this test expects ts, slog.LevelKey and slog.MessageKey"), - f: func(l *slog.Logger) { - l.Info("message") - }, - checks: []check{ - hasKey("ts"), - hasKey(slog.LevelKey), - hasAttr(slog.MessageKey, "message"), - }, - }, - { - name: "attrs", - explanation: withSource("a Handler should output attributes passed to the logging function"), - f: func(l *slog.Logger) { - l.Info("message", "k", "v") - }, - checks: []check{ - hasAttr("k", "v"), - }, - }, - { - name: "empty-attr", - explanation: withSource("a Handler should ignore an empty Attr"), - f: func(l *slog.Logger) { - l.Info("msg", "a", "b", "", nil, "c", "d") - }, - checks: []check{ - hasAttr("a", "b"), - missingKey(""), - hasAttr("c", "d"), - }, - }, - { - name: "zero-time", - explanation: withSource("a Handler should ignore a zero Record.Time"), - f: func(l *slog.Logger) { - l.Info("msg", "k", "v") - }, - mod: func(r *slog.Record) { r.Time = time.Time{} }, - checks: []check{ - missingKey("ts"), - }, - }, - { - name: "WithAttrs", - explanation: withSource("a Handler should include the attributes from the WithAttrs method"), - f: func(l *slog.Logger) { - l.With("a", "b").Info("msg", "k", "v") - }, - checks: []check{ - hasAttr("a", "b"), - hasAttr("k", "v"), - }, - }, - { - name: "groups", - explanation: withSource("a Handler should handle Group attributes"), - f: func(l *slog.Logger) { - l.Info("msg", "a", "b", slog.Group("G", slog.String("c", "d")), "e", "f") - }, - checks: []check{ - hasAttr("a", "b"), - inGroup("G", hasAttr("c", "d")), - hasAttr("e", "f"), - }, - }, - { - name: "empty-group", - explanation: withSource("a Handler should ignore an empty group"), - f: func(l *slog.Logger) { - l.Info("msg", "a", "b", slog.Group("G"), "e", "f") - }, - checks: []check{ - hasAttr("a", "b"), - missingKey("G"), - hasAttr("e", "f"), - }, - }, - { - name: "inline-group", - explanation: withSource("a Handler should inline the Attrs of a group with an empty key"), - f: func(l *slog.Logger) { - l.Info("msg", "a", "b", slog.Group("", slog.String("c", "d")), "e", "f") - - }, - checks: []check{ - hasAttr("a", "b"), - hasAttr("c", "d"), - hasAttr("e", "f"), - }, - }, - { - name: "WithGroup", - explanation: withSource("a Handler should handle the WithGroup method"), - f: func(l *slog.Logger) { - l.WithGroup("G").Info("msg", "a", "b") - }, - checks: []check{ - hasKey("ts"), - hasKey(slog.LevelKey), - hasAttr(slog.MessageKey, "msg"), - missingKey("a"), - inGroup("G", hasAttr("a", "b")), - }, - }, - { - name: "multi-With", - explanation: withSource("a Handler should handle multiple WithGroup and WithAttr calls"), - f: func(l *slog.Logger) { - l.With("a", "b").WithGroup("G").With("c", "d").WithGroup("H").Info("msg", "e", "f") - }, - checks: []check{ - hasKey("ts"), - hasKey(slog.LevelKey), - hasAttr(slog.MessageKey, "msg"), - hasAttr("a", "b"), - inGroup("G", hasAttr("c", "d")), - inGroup("G", inGroup("H", hasAttr("e", "f"))), - }, - }, - { - name: "empty-group-record", - explanation: withSource("a Handler should not output groups if there are no attributes"), - f: func(l *slog.Logger) { - l.With("a", "b").WithGroup("G").With("c", "d").WithGroup("H").Info("msg") - }, - checks: []check{ - hasKey("ts"), - hasKey(slog.LevelKey), - hasAttr(slog.MessageKey, "msg"), - hasAttr("a", "b"), - inGroup("G", hasAttr("c", "d")), - inGroup("G", missingKey("H")), - }, - }, - { - name: "resolve", - explanation: withSource("a Handler should call Resolve on attribute values"), - f: func(l *slog.Logger) { - l.Info("msg", "k", &replaceAny{"replaced"}) - }, - checks: []check{hasAttr("k", "replaced")}, - }, - { - name: "resolve-groups", - explanation: withSource("a Handler should call Resolve on attribute values in groups"), - f: func(l *slog.Logger) { - l.Info("msg", - slog.Group("G", - slog.String("a", "v1"), - slog.Any("b", &replaceAny{"v2"}))) - }, - checks: []check{ - inGroup("G", hasAttr("a", "v1")), - inGroup("G", hasAttr("b", "v2")), - }, - }, - { - name: "resolve-WithAttrs", - explanation: withSource("a Handler should call Resolve on attribute values from WithAttrs"), - f: func(l *slog.Logger) { - l = l.With("k", &replaceAny{"replaced"}) - l.Info("msg") - }, - checks: []check{hasAttr("k", "replaced")}, - }, - { - name: "resolve-WithAttrs-groups", - explanation: withSource("a Handler should call Resolve on attribute values in groups from WithAttrs"), - f: func(l *slog.Logger) { - l = l.With(slog.Group("G", - slog.String("a", "v1"), - slog.Any("b", &replaceAny{"v2"}))) - l.Info("msg") - }, - checks: []check{ - inGroup("G", hasAttr("a", "v1")), - inGroup("G", hasAttr("b", "v2")), - }, - }, - { - name: "empty-PC", - explanation: withSource("a Handler should not output SourceKey if the PC is zero"), - f: func(l *slog.Logger) { - l.Info("message") - }, - mod: func(r *slog.Record) { r.PC = 0 }, - checks: []check{ - missingKey(slog.SourceKey), - }, - }, -} - -// TestHandler tests a [slog.Handler]. -// If TestHandler finds any misbehaviors, it returns an error for each, -// combined into a single error with [errors.Join]. -// -// TestHandler installs the given Handler in a [slog.Logger] and -// makes several calls to the Logger's output methods. -// The Handler should be enabled for levels Info and above. -// -// The results function is invoked after all such calls. -// It should return a slice of map[string]any, one for each call to a Logger output method. -// The keys and values of the map should correspond to the keys and values of the Handler's -// output. Each group in the output should be represented as its own nested map[string]any. -// The standard keys ["ts"], [slog.LevelKey] and [slog.MessageKey] should be used. -// -// If the Handler outputs JSON, then calling [encoding/json.Unmarshal] with a `map[string]any` -// will create the right data structure. -// -// If a Handler intentionally drops an attribute that is checked by a test, -// then the results function should check for its absence and add it to the map it returns. -func TestHandler(h slog.Handler, results func() []map[string]any) error { - // Run the handler on the test cases. - for _, c := range cases { - ht := h - if c.mod != nil { - ht = &wrapper{h, c.mod} - } - l := slog.New(ht) - c.f(l) - } - - // Collect and check the results. - var errs []error - res := results() - if g, w := len(res), len(cases); g != w { - return fmt.Errorf("got %d results, want %d", g, w) - } - for i, got := range results() { - c := cases[i] - for _, check := range c.checks { - if problem := check(got); problem != "" { - errs = append(errs, fmt.Errorf("%s: %s", problem, c.explanation)) - } - } - } - return errors.Join(errs...) -} - -// Run exercises a [slog.Handler] on the same test cases as [TestHandler], but -// runs each case in a subtest. For each test case, it first calls newHandler to -// get an instance of the handler under test, then runs the test case, then -// calls result to get the result. If the test case fails, it calls t.Error. -func Run(t *testing.T, newHandler func(*testing.T) slog.Handler, result func(*testing.T) map[string]any) { - for _, c := range cases { - t.Run(c.name, func(t *testing.T) { - h := newHandler(t) - if c.mod != nil { - h = &wrapper{h, c.mod} - } - l := slog.New(h) - c.f(l) - got := result(t) - for _, check := range c.checks { - if p := check(got); p != "" { - t.Errorf("%s: %s", p, c.explanation) - } - } - }) - } -} - -// RunDeferredTests exercises a [slog.Handler] on the same test cases as [TestHandler], but -// runs each case in a subtest. For each test case, it first calls newHandler to -// get an instance of the handler under test, then runs the test case, then -// calls result to get the result. If the test case fails, it calls t.Error. -func RunDeferredTests(t *testing.T, newHandler func(*testing.T) *Logger, result func(*testing.T) map[string]any) { - for _, c := range cases { - t.Run(c.name, func(t *testing.T) { - // Dont run the modded tests - if c.mod != nil { - return - } - h := newHandler(t) - - l := slog.New(h.deferredSlog) - c.f(l) - err := h.Update(Options{ - Level: "debug", - Format: "json", - }) - require.NoError(t, err) - got := result(t) - for _, check := range c.checks { - if p := check(got); p != "" { - t.Errorf("%s: %s", p, c.explanation) - } - } - }) - } -} - -type check func(map[string]any) string - -func hasKey(key string) check { - return func(m map[string]any) string { - if _, ok := m[key]; !ok { - return fmt.Sprintf("missing key %q", key) - } - return "" - } -} - -func missingKey(key string) check { - return func(m map[string]any) string { - if _, ok := m[key]; ok { - return fmt.Sprintf("unexpected key %q", key) - } - return "" - } -} - -func hasAttr(key string, wantVal any) check { - return func(m map[string]any) string { - if s := hasKey(key)(m); s != "" { - return s - } - gotVal := m[key] - if !reflect.DeepEqual(gotVal, wantVal) { - return fmt.Sprintf("%q: got %#v, want %#v", key, gotVal, wantVal) - } - return "" - } -} - -func inGroup(name string, c check) check { - return func(m map[string]any) string { - v, ok := m[name] - if !ok { - return fmt.Sprintf("missing group %q", name) - } - g, ok := v.(map[string]any) - if !ok { - return fmt.Sprintf("value for group %q is not map[string]any", name) - } - return c(g) - } -} - -type wrapper struct { - slog.Handler - mod func(*slog.Record) -} - -func (h *wrapper) Handle(ctx context.Context, r slog.Record) error { - h.mod(&r) - return h.Handler.Handle(ctx, r) -} - -func withSource(s string) string { - _, file, line, ok := runtime.Caller(1) - if !ok { - panic("runtime.Caller failed") - } - return fmt.Sprintf("%s (%s:%d)", s, file, line) -} - -type replaceAny struct { - v any -} - -func (r *replaceAny) LogValue() slog.Value { return slog.AnyValue(r.v) } - -func (r *replaceAny) String() string { - return fmt.Sprintf("", r.v) -}