op-service: capture inherited log attributes (ethereum-optimism#11470)

* op-service: capture inherited log attributes

* op-service/testlog: reverse Attrs traversal order

op-service/testlog/capturing.go

@@ -8,16 +8,60 @@ import (
 	"github.com/ethereum/go-ethereum/log"
 )
 
+// CapturedAttributes forms a chain of inherited attributes, to traverse on captured log records.
+type CapturedAttributes struct {
+	Parent     *CapturedAttributes
+	Attributes []slog.Attr
+}
+
+// Attrs calls f on each Attr in the [CapturedAttributes].
+// Iteration stops if f returns false.
+func (r *CapturedAttributes) Attrs(f func(slog.Attr) bool) {
+	for _, a := range r.Attributes {
+		if !f(a) {
+			return
+		}
+	}
+	if r.Parent != nil {
+		r.Parent.Attrs(f)
+	}
+}
+
+// CapturedRecord is a wrapped around a regular log-record,
+// to preserve the inherited attributes context, without mutating the record or reordering attributes.
+type CapturedRecord struct {
+	Parent *CapturedAttributes
+	*slog.Record
+}
+
+// Attrs calls f on each Attr in the [CapturedRecord].
+// Iteration stops if f returns false.
+func (r *CapturedRecord) Attrs(f func(slog.Attr) bool) {
+	searching := true
+	r.Record.Attrs(func(a slog.Attr) bool {
+		searching = f(a)
+		return searching
+	})
+	if !searching { // if we found it already, then don't traverse the remainder
+		return
+	}
+	if r.Parent != nil {
+		r.Parent.Attrs(f)
+	}
+}
+
 // CapturingHandler provides a log handler that captures all log records and optionally forwards them to a delegate.
 // Note that it is not thread safe.
 type CapturingHandler struct {
 	handler slog.Handler
-	Logs    *[]*slog.Record // shared among derived CapturingHandlers
+	Logs    *[]*CapturedRecord // shared among derived CapturingHandlers
+	// attrs are inherited log record attributes, from a logger that this CapturingHandler may be derived from
+	attrs *CapturedAttributes
 }
 
 func CaptureLogger(t Testing, level slog.Level) (_ log.Logger, ch *CapturingHandler) {
 	return LoggerWithHandlerMod(t, level, func(h slog.Handler) slog.Handler {
-		ch = &CapturingHandler{handler: h, Logs: new([]*slog.Record)}
+		ch = &CapturingHandler{handler: h, Logs: new([]*CapturedRecord)}
 		return ch
 	}), ch
 }
@@ -29,18 +73,24 @@ func (c *CapturingHandler) Enabled(context.Context, slog.Level) bool {
 }
 
 func (c *CapturingHandler) Handle(ctx context.Context, r slog.Record) error {
-	*c.Logs = append(*c.Logs, &r)
+	*c.Logs = append(*c.Logs, &CapturedRecord{
+		Parent: c.attrs,
+		Record: &r,
+	})
 	if c.handler != nil && c.handler.Enabled(ctx, r.Level) {
 		return c.handler.Handle(ctx, r)
 	}
 	return nil
 }
 
 func (c *CapturingHandler) WithAttrs(attrs []slog.Attr) slog.Handler {
-	// Note: additional attributes won't be visible for captured logs
 	return &CapturingHandler{
 		handler: c.handler.WithAttrs(attrs),
 		Logs:    c.Logs,
+		attrs: &CapturedAttributes{
+			Parent:     c.attrs,
+			Attributes: attrs,
+		},
 	}
 }
 
@@ -56,13 +106,13 @@ func (c *CapturingHandler) Clear() {
 }
 
 func NewLevelFilter(level slog.Level) LogFilter {
-	return func(r *slog.Record) bool {
-		return r.Level == level
+	return func(r *CapturedRecord) bool {
+		return r.Record.Level == level
 	}
 }
 
 func NewAttributesFilter(key, value string) LogFilter {
-	return func(r *slog.Record) bool {
+	return func(r *CapturedRecord) bool {
 		found := false
 		r.Attrs(func(a slog.Attr) bool {
 			if a.Key == key && a.Value.String() == value {
@@ -76,7 +126,7 @@ func NewAttributesFilter(key, value string) LogFilter {
 }
 
 func NewAttributesContainsFilter(key, value string) LogFilter {
-	return func(r *slog.Record) bool {
+	return func(r *CapturedRecord) bool {
 		found := false
 		r.Attrs(func(a slog.Attr) bool {
 			if a.Key == key && strings.Contains(a.Value.String(), value) {
@@ -90,20 +140,20 @@ func NewAttributesContainsFilter(key, value string) LogFilter {
 }
 
 func NewMessageFilter(message string) LogFilter {
-	return func(r *slog.Record) bool {
-		return r.Message == message
+	return func(r *CapturedRecord) bool {
+		return r.Record.Message == message
 	}
 }
 
 func NewMessageContainsFilter(message string) LogFilter {
-	return func(r *slog.Record) bool {
-		return strings.Contains(r.Message, message)
+	return func(r *CapturedRecord) bool {
+		return strings.Contains(r.Record.Message, message)
 	}
 }
 
-type LogFilter func(*slog.Record) bool
+type LogFilter func(record *CapturedRecord) bool
 
-func (c *CapturingHandler) FindLog(filters ...LogFilter) *HelperRecord {
+func (c *CapturingHandler) FindLog(filters ...LogFilter) *CapturedRecord {
 	for _, record := range *c.Logs {
 		match := true
 		for _, filter := range filters {
@@ -113,14 +163,14 @@ func (c *CapturingHandler) FindLog(filters ...LogFilter) *HelperRecord {
 			}
 		}
 		if match {
-			return &HelperRecord{record}
+			return record
 		}
 	}
 	return nil
 }
 
-func (c *CapturingHandler) FindLogs(filters ...LogFilter) []*HelperRecord {
-	var logs []*HelperRecord
+func (c *CapturingHandler) FindLogs(filters ...LogFilter) []*CapturedRecord {
+	var logs []*CapturedRecord
 	for _, record := range *c.Logs {
 		match := true
 		for _, filter := range filters {
@@ -130,17 +180,13 @@ func (c *CapturingHandler) FindLogs(filters ...LogFilter) []*HelperRecord {
 			}
 		}
 		if match {
-			logs = append(logs, &HelperRecord{record})
+			logs = append(logs, record)
 		}
 	}
 	return logs
 }
 
-type HelperRecord struct {
-	*slog.Record
-}
-
-func (h HelperRecord) AttrValue(name string) (v any) {
+func (h *CapturedRecord) AttrValue(name string) (v any) {
 	h.Attrs(func(a slog.Attr) bool {
 		if a.Key == name {
 			v = a.Value.Any()

op-service/testlog/capturing_test.go

@@ -14,7 +14,7 @@ func TestCaptureLogger(t *testing.T) {
 	lgr.Info(msg, "a", 1)
 	msgFilter := testlog.NewMessageFilter(msg)
 	rec := logs.FindLog(msgFilter)
-	require.Equal(t, msg, rec.Message)
+	require.Equal(t, msg, rec.Record.Message)
 	require.EqualValues(t, 1, rec.AttrValue("a"))
 
 	lgr.Debug("bug")
@@ -52,9 +52,37 @@ func TestCaptureLoggerAttributesFilter(t *testing.T) {
 	attrFilter := testlog.NewAttributesFilter("a", "random")
 
 	rec := logs.FindLog(msgFilter, attrFilter)
-	require.Equal(t, msg, rec.Message)
+	require.Equal(t, msg, rec.Record.Message)
 	require.EqualValues(t, "random", rec.AttrValue("a"))
 
 	recs := logs.FindLogs(msgFilter, attrFilter)
 	require.Len(t, recs, 1)
 }
+
+func TestCaptureLoggerNested(t *testing.T) {
+	lgrInner, logs := testlog.CaptureLogger(t, log.LevelInfo)
+
+	lgrInner.Info("hi", "a", "test")
+
+	lgrChildX := lgrInner.With("name", "childX")
+	lgrChildX.Info("hello", "b", "42")
+
+	lgrChildY := lgrInner.With("name", "childY")
+	lgrChildY.Info("hola", "c", "7")
+
+	lgrInner.Info("hello universe", "greeting", "from Inner")
+
+	lgrChildX.Info("hello world", "greeting", "from X")
+
+	require.Len(t, logs.FindLogs(testlog.NewAttributesFilter("name", "childX")), 2, "X logged twice")
+	require.Len(t, logs.FindLogs(testlog.NewAttributesFilter("name", "childY")), 1, "Y logged once")
+
+	require.Len(t, logs.FindLogs(
+		testlog.NewAttributesContainsFilter("greeting", "from")), 2, "two greetings")
+	require.Len(t, logs.FindLogs(
+		testlog.NewAttributesContainsFilter("greeting", "from"),
+		testlog.NewAttributesFilter("name", "childX")), 1, "only one greeting from X")
+
+	require.Len(t, logs.FindLogs(
+		testlog.NewAttributesFilter("a", "test")), 1, "root logger logged 'a' once")
+}