slog: reimplement defaultHandler using commonHandler

The defaultHandler can be viewed as a variant of a TextHandler.
Re-use commonHandler to implement it.
Test groups, Marshaler and scopes for it.

Change-Id: I7600e5b82d4d8189024ae94f760848eaedf5d4db
Reviewed-on: https://go-review.googlesource.com/c/exp/+/439055
Reviewed-by: Alan Donovan <adonovan@google.com>
Run-TryBot: Jonathan Amsterdam <jba@google.com>

Author: jba

slog/handler.go

@@ -8,7 +8,6 @@ import (
 	"fmt"
 	"io"
 	"strconv"
-	"strings"
 	"sync"
 	"time"
 
@@ -61,8 +60,16 @@ type Handler interface {
 }
 
 type defaultHandler struct {
-	attrs  []Attr
-	output func(int, string) error // log.Output, except for testing
+	ch *commonHandler
+	// log.Output, except for testing
+	output func(calldepth int, message string) error
+}
+
+func newDefaultHandler(output func(int, string) error) *defaultHandler {
+	return &defaultHandler{
+		ch:     &commonHandler{json: false},
+		output: output,
+	}
 }
 
 func (*defaultHandler) Enabled(l Level) bool {
@@ -73,34 +80,23 @@ func (*defaultHandler) Enabled(l Level) bool {
 // write it with the default log.Logger.
 // Let the log.Logger handle time and file/line.
 func (h *defaultHandler) Handle(r Record) error {
-	var b strings.Builder
-	b.WriteString(r.Level().String())
-	b.WriteByte(' ')
-	for _, a := range h.attrs {
-		h.writeAttr(&b, a)
-	}
-	r.Attrs(func(a Attr) {
-		h.writeAttr(&b, a)
-	})
-	b.WriteString(r.Message())
-	return h.output(4, b.String())
-}
-
-func (h *defaultHandler) writeAttr(b *strings.Builder, a Attr) {
-	b.WriteString(a.Key)
-	b.WriteByte('=')
-	b.WriteString(a.Value.Resolve().String())
-	b.WriteByte(' ')
+	buf := buffer.New()
+	defer buf.Free()
+	buf.WriteString(r.Level().String())
+	buf.WriteByte(' ')
+	buf.WriteString(r.Message())
+	state := handleState{h: h.ch, buf: buf, sep: " "}
+	state.appendNonBuiltIns(r)
+	// 4 = log.Output depth + handlerWriter.Write + defaultHandler.Handle
+	return h.output(4, buf.String())
 }
 
-func (d *defaultHandler) With(as []Attr) Handler {
-	d2 := *d
-	d2.attrs = concat(d2.attrs, as)
-	return &d2
+func (h *defaultHandler) With(as []Attr) Handler {
+	return &defaultHandler{h.ch.withAttrs(as), h.output}
 }
 
 func (h *defaultHandler) WithScope(name string) Handler {
-	panic("unimplemented")
+	return &defaultHandler{h.ch.withScope(name), h.output}
 }
 
 // HandlerOptions are options for a TextHandler or JSONHandler.
@@ -254,34 +250,38 @@ func (h *commonHandler) handle(r Record) error {
 	} else {
 		state.appendAttr(String(key, msg))
 	}
+	state.appendNonBuiltIns(r)
+	state.buf.WriteByte('\n')
+
+	h.mu.Lock()
+	defer h.mu.Unlock()
+	_, err := h.w.Write(*state.buf)
+	return err
+}
+
+func (s *handleState) appendNonBuiltIns(r Record) {
 	// preformatted Attrs
-	if len(h.preformattedAttrs) > 0 {
-		state.buf.WriteString(state.sep)
-		state.buf.Write(h.preformattedAttrs)
-		state.sep = h.attrSep()
+	if len(s.h.preformattedAttrs) > 0 {
+		s.buf.WriteString(s.sep)
+		s.buf.Write(s.h.preformattedAttrs)
+		s.sep = s.h.attrSep()
 	}
 	// Attrs in Record -- unlike the built-in ones, they are scoped.
-	state.prefix = buffer.New()
-	defer state.prefix.Free()
-	state.prefix.WriteString(h.scopePrefix)
-	state.openScopes()
+	s.prefix = buffer.New()
+	defer s.prefix.Free()
+	s.prefix.WriteString(s.h.scopePrefix)
+	s.openScopes()
 	r.Attrs(func(a Attr) {
-		state.appendAttr(a)
+		s.appendAttr(a)
 	})
-	if h.json {
+	if s.h.json {
 		// Close all open scopes.
-		for range h.scopes {
-			state.buf.WriteByte('}')
+		for range s.h.scopes {
+			s.buf.WriteByte('}')
 		}
 		// Close the top-level object.
-		state.buf.WriteByte('}')
+		s.buf.WriteByte('}')
 	}
-	state.buf.WriteByte('\n')
-
-	h.mu.Lock()
-	defer h.mu.Unlock()
-	_, err := h.w.Write(*state.buf)
-	return err
 }
 
 // attrSep returns the separator between attributes.

slog/handler_test.go

@@ -16,43 +16,87 @@ import (
 )
 
 func TestDefaultHandle(t *testing.T) {
+	preAttrs := []Attr{Int("pre", 0)}
+	attrs := []Attr{Int("a", 1), String("b", "two")}
 	for _, test := range []struct {
-		name      string
-		withAttrs []Attr
-		attrs     []Attr
-		want      string
+		name  string
+		with  func(Handler) Handler
+		attrs []Attr
+		want  string
 	}{
 		{
 			name: "no attrs",
 			want: "INFO message",
 		},
 		{
 			name:  "attrs",
-			attrs: []Attr{Int("a", 1), String("b", "two")},
-			want:  "INFO a=1 b=two message",
+			attrs: attrs,
+			want:  "INFO message a=1 b=two",
 		},
 		{
-			name:      "pre attrs",
-			withAttrs: []Attr{Int("pre", 0)},
-			attrs:     []Attr{Int("a", 1)},
-			want:      "INFO pre=0 a=1 message",
+			name:  "preformatted",
+			with:  func(h Handler) Handler { return h.With(preAttrs) },
+			attrs: attrs,
+			want:  "INFO message pre=0 a=1 b=two",
 		},
-	} {
-		var got string
-		var d Handler = &defaultHandler{output: func(_ int, s string) error {
-			got = s
-			return nil
+		{
+			name: "groups",
+			attrs: []Attr{
+				Int("a", 1),
+				Group("g",
+					Int("b", 2),
+					Group("h", Int("c", 3)),
+					Int("d", 4)),
+				Int("e", 5),
+			},
+			want: "INFO message a=1 g.b=2 g.h.c=3 g.d=4 e=5",
 		},
-		}
-		d = d.With(test.withAttrs)
-		r := NewRecord(time.Time{}, InfoLevel, "message", 0)
-		r.AddAttrs(test.attrs...)
-		if err := d.Handle(r); err != nil {
-			t.Fatal(err)
-		}
-		if got != test.want {
-			t.Errorf("\ngot  %s\nwant %s", got, test.want)
-		}
+		{
+			name:  "scope",
+			with:  func(h Handler) Handler { return h.With(preAttrs).WithScope("s") },
+			attrs: attrs,
+			want:  "INFO message pre=0 s.a=1 s.b=two",
+		},
+		{
+			name: "preformatted scopes",
+			with: func(h Handler) Handler {
+				return h.With([]Attr{Int("p1", 1)}).
+					WithScope("s1").
+					With([]Attr{Int("p2", 2)}).
+					WithScope("s2")
+			},
+			attrs: attrs,
+			want:  "INFO message p1=1 s1.p2=2 s1.s2.a=1 s1.s2.b=two",
+		},
+		{
+			name: "two scopes",
+			with: func(h Handler) Handler {
+				return h.With([]Attr{Int("p1", 1)}).
+					WithScope("s1").
+					WithScope("s2")
+			},
+			attrs: attrs,
+			want:  "INFO message p1=1 s1.s2.a=1 s1.s2.b=two",
+		},
+	} {
+		t.Run(test.name, func(t *testing.T) {
+			var got string
+			var h Handler = newDefaultHandler(func(_ int, s string) error {
+				got = s
+				return nil
+			})
+			if test.with != nil {
+				h = test.with(h)
+			}
+			r := NewRecord(time.Time{}, InfoLevel, "message", 0)
+			r.AddAttrs(test.attrs...)
+			if err := h.Handle(r); err != nil {
+				t.Fatal(err)
+			}
+			if got != test.want {
+				t.Errorf("\ngot  %s\nwant %s", got, test.want)
+			}
+		})
 	}
 }
 

slog/logger.go

@@ -14,7 +14,7 @@ var defaultLogger atomic.Value
 
 func init() {
 	defaultLogger.Store(&Logger{
-		handler: &defaultHandler{output: log.Output},
+		handler: newDefaultHandler(log.Output),
 	})
 }
 

slog/logger_test.go

@@ -60,11 +60,11 @@ func TestConnections(t *testing.T) {
 	log.SetFlags(log.Flags() | log.Lshortfile)
 	Info("msg", "a", 1)
 	checkLogOutput(t, logbuf.String(),
-		`\d{4}/\d{2}/\d{2} \d{2}:\d{2}:\d{2} logger_test.go:\d\d: INFO a=1 msg`)
+		`\d{4}/\d{2}/\d{2} \d{2}:\d{2}:\d{2} logger_test.go:\d\d: INFO msg a=1`)
 	logbuf.Reset()
 	Warn("msg", "b", 2)
 	checkLogOutput(t, logbuf.String(),
-		`\d{4}/\d{2}/\d{2} \d{2}:\d{2}:\d{2} logger_test.go:\d\d: WARN b=2 msg`)
+		`\d{4}/\d{2}/\d{2} \d{2}:\d{2}:\d{2} logger_test.go:\d\d: WARN msg b=2`)
 	// Levels below Info are not printed.
 	logbuf.Reset()
 	Debug("msg", "c", 3)