slog-handler-guide: preformatting Change-Id: Ib1e64bafc76c296aa0ffb40d754d6e41fe69a33e Reviewed-on: https://go-review.googlesource.com/c/example/+/511638 Run-TryBot: Jonathan Amsterdam <jba@google.com> TryBot-Result: Gopher Robot <gobot@golang.org> Reviewed-by: Ian Cottrell <iancottrell@google.com>
diff --git a/slog-handler-guide/README.md b/slog-handler-guide/README.md index 4dc72d1..ff74e08 100644 --- a/slog-handler-guide/README.md +++ b/slog-handler-guide/README.md
@@ -510,7 +510,174 @@ ### With pre-formatting -TODO(jba): write +Our second implementation implements pre-formatting. +This implementation is more complicated than the previous one. +Is the extra complexity worth it? +That depends on your circumstances, but here is one circumstance where +it might be. +Say that you wanted your server to log a lot of information about an incoming +request with every log message that happens during that request. A typical +handler might look something like this: + + func (s *Server) handleWidgets(w http.ResponseWriter, r *http.Request) { + logger := s.logger.With( + "url", r.URL, + "traceID": r.Header.Get("X-Cloud-Trace-Context"), + // many other attributes + ) + // ... + } + +A single handleWidgets request might generate hundreds of log lines. +For instance, it might contain code like this: + + for _, w := range widgets { + logger.Info("processing widget", "name", w.Name) + // ... + } + +For every such line, the `Handle` method we wrote above will format all +the attributes that were added using `With` above, in addition to the +ones on the log line itself. + +Maybe all that extra work doesn't slow down your server significantly, because +it does so much other work that time spent logging is just noise. +But perhaps your server is fast enough that all that extra formatting appears high up +in your CPU profiles. That is when pre-formatting can make a big difference, +by formatting the attributes in a call to `With` just once. + +To pre-format the arguments to `WithAttrs`, we need to keep track of some +additional state in the `IndentHandler` struct. + +``` +type IndentHandler struct { + opts Options + preformatted []byte // data from WithGroup and WithAttrs + unopenedGroups []string // groups from WithGroup that haven't been opened + indentLevel int // same as number of opened groups so far + mu *sync.Mutex + out io.Writer +} +``` + +Mainly, we need a buffer to hold the pre-formatted data. +But we also need to keep track of which groups +we've seen but haven't output yet. We'll call those groups "unopened." +We also need to track how many groups we've opened, which we can do +with a simple counter, since an opened group's only effect is to change the +indentation level. + +The `WithGroup` implementation is a lot like the previous one: just remember the +new group, which is unopened initially. + +``` +func (h *IndentHandler) WithGroup(name string) slog.Handler { + if name == "" { + return h + } + h2 := *h + // Add an unopened group to h2 without modifying h. + h2.unopenedGroups = make([]string, len(h.unopenedGroups)+1) + copy(h2.unopenedGroups, h.unopenedGroups) + h2.unopenedGroups[len(h2.unopenedGroups)-1] = name + return &h2 +} +``` + +`WithAttrs` does all the pre-formatting: + +``` +func (h *IndentHandler) WithAttrs(attrs []slog.Attr) slog.Handler { + if len(attrs) == 0 { + return h + } + h2 := *h + // Force an append to copy the underlying array. + pre := slices.Clip(h.preformatted) + // Add all groups from WithGroup that haven't already been added. + h2.preformatted = h2.appendUnopenedGroups(pre, h2.indentLevel) + // Each of those groups increased the indent level by 1. + h2.indentLevel += len(h2.unopenedGroups) + // Now all groups have been opened. + h2.unopenedGroups = nil + // Pre-format the attributes. + for _, a := range attrs { + h2.preformatted = h2.appendAttr(h2.preformatted, a, h2.indentLevel) + } + return &h2 +} + +func (h *IndentHandler) appendUnopenedGroups(buf []byte, indentLevel int) []byte { + for _, g := range h.unopenedGroups { + buf = fmt.Appendf(buf, "%*s%s:\n", indentLevel*4, "", g) + indentLevel++ + } + return buf +} +``` + +It first opens any unopened groups. This handles calls like: + + logger.WithGroup("g").WithGroup("h").With("a", 1) + +Here, `WithAttrs` must output "g" and "h" before "a". Since a group established +by `WithGroup` is in effect for the rest of the log line, `WithAttrs` increments +the indentation level for each group it opens. + +Lastly, `WithAttrs` formats its argument attributes, using the same `appendAttr` +method we saw above. + +It's the `Handle` method's job to insert the pre-formatted material in the right +place, which is after the built-in attributes and before the ones in the record: + +``` +func (h *IndentHandler) Handle(ctx context.Context, r slog.Record) error { + buf := make([]byte, 0, 1024) + if !r.Time.IsZero() { + buf = h.appendAttr(buf, slog.Time(slog.TimeKey, r.Time), 0) + } + buf = h.appendAttr(buf, slog.Any(slog.LevelKey, r.Level), 0) + if r.PC != 0 { + fs := runtime.CallersFrames([]uintptr{r.PC}) + f, _ := fs.Next() + buf = h.appendAttr(buf, slog.String(slog.SourceKey, fmt.Sprintf("%s:%d", f.File, f.Line)), 0) + } + buf = h.appendAttr(buf, slog.String(slog.MessageKey, r.Message), 0) + // Insert preformatted attributes just after built-in ones. + buf = append(buf, h.preformatted...) + if r.NumAttrs() > 0 { + buf = h.appendUnopenedGroups(buf, h.indentLevel) + r.Attrs(func(a slog.Attr) bool { + buf = h.appendAttr(buf, a, h.indentLevel+len(h.unopenedGroups)) + return true + }) + } + buf = append(buf, "---\n"...) + h.mu.Lock() + defer h.mu.Unlock() + _, err := h.out.Write(buf) + return err +} +``` + +It must also open any groups that haven't yet been opened. The logic covers +log lines like this one: + + logger.WithGroup("g").Info("msg", "a", 1) + +where "g" is unopened before `Handle` is called and must be written to produce +the correct output: + + level: INFO + msg: "msg" + g: + a: 1 + +The check for `r.NumAttrs() > 0` handles this case: + + logger.WithGroup("g").Info("msg") + +Here there are no record attributes, so no group to open. ## Testing
diff --git a/slog-handler-guide/guide.md b/slog-handler-guide/guide.md index 922cdd7..f9b9027 100644 --- a/slog-handler-guide/guide.md +++ b/slog-handler-guide/guide.md
@@ -330,7 +330,97 @@ ### With pre-formatting -TODO(jba): write +Our second implementation implements pre-formatting. +This implementation is more complicated than the previous one. +Is the extra complexity worth it? +That depends on your circumstances, but here is one circumstance where +it might be. +Say that you wanted your server to log a lot of information about an incoming +request with every log message that happens during that request. A typical +handler might look something like this: + + func (s *Server) handleWidgets(w http.ResponseWriter, r *http.Request) { + logger := s.logger.With( + "url", r.URL, + "traceID": r.Header.Get("X-Cloud-Trace-Context"), + // many other attributes + ) + // ... + } + +A single handleWidgets request might generate hundreds of log lines. +For instance, it might contain code like this: + + for _, w := range widgets { + logger.Info("processing widget", "name", w.Name) + // ... + } + +For every such line, the `Handle` method we wrote above will format all +the attributes that were added using `With` above, in addition to the +ones on the log line itself. + +Maybe all that extra work doesn't slow down your server significantly, because +it does so much other work that time spent logging is just noise. +But perhaps your server is fast enough that all that extra formatting appears high up +in your CPU profiles. That is when pre-formatting can make a big difference, +by formatting the attributes in a call to `With` just once. + +To pre-format the arguments to `WithAttrs`, we need to keep track of some +additional state in the `IndentHandler` struct. + +%include indenthandler3/indent_handler.go IndentHandler - + +Mainly, we need a buffer to hold the pre-formatted data. +But we also need to keep track of which groups +we've seen but haven't output yet. We'll call those groups "unopened." +We also need to track how many groups we've opened, which we can do +with a simple counter, since an opened group's only effect is to change the +indentation level. + +The `WithGroup` implementation is a lot like the previous one: just remember the +new group, which is unopened initially. + +%include indenthandler3/indent_handler.go WithGroup - + +`WithAttrs` does all the pre-formatting: + +%include indenthandler3/indent_handler.go WithAttrs - + +It first opens any unopened groups. This handles calls like: + + logger.WithGroup("g").WithGroup("h").With("a", 1) + +Here, `WithAttrs` must output "g" and "h" before "a". Since a group established +by `WithGroup` is in effect for the rest of the log line, `WithAttrs` increments +the indentation level for each group it opens. + +Lastly, `WithAttrs` formats its argument attributes, using the same `appendAttr` +method we saw above. + +It's the `Handle` method's job to insert the pre-formatted material in the right +place, which is after the built-in attributes and before the ones in the record: + +%include indenthandler3/indent_handler.go Handle - + +It must also open any groups that haven't yet been opened. The logic covers +log lines like this one: + + logger.WithGroup("g").Info("msg", "a", 1) + +where "g" is unopened before `Handle` is called and must be written to produce +the correct output: + + level: INFO + msg: "msg" + g: + a: 1 + +The check for `r.NumAttrs() > 0` handles this case: + + logger.WithGroup("g").Info("msg") + +Here there are no record attributes, so no group to open. ## Testing
diff --git a/slog-handler-guide/indenthandler3/indent_handler.go b/slog-handler-guide/indenthandler3/indent_handler.go new file mode 100644 index 0000000..885d1a4 --- /dev/null +++ b/slog-handler-guide/indenthandler3/indent_handler.go
@@ -0,0 +1,162 @@ +//go:build go1.21 + +package indenthandler + +import ( + "context" + "fmt" + "io" + "log/slog" + "runtime" + "slices" + "sync" + "time" +) + +// !+IndentHandler +type IndentHandler struct { + opts Options + preformatted []byte // data from WithGroup and WithAttrs + unopenedGroups []string // groups from WithGroup that haven't been opened + indentLevel int // same as number of opened groups so far + mu *sync.Mutex + out io.Writer +} + +//!-IndentHandler + +type Options struct { + // Level reports the minimum level to log. + // Levels with lower levels are discarded. + // If nil, the Handler uses [slog.LevelInfo]. + Level slog.Leveler +} + +func New(out io.Writer, opts *Options) *IndentHandler { + h := &IndentHandler{out: out, mu: &sync.Mutex{}} + if opts != nil { + h.opts = *opts + } + if h.opts.Level == nil { + h.opts.Level = slog.LevelInfo + } + return h +} + +func (h *IndentHandler) Enabled(ctx context.Context, level slog.Level) bool { + return level >= h.opts.Level.Level() +} + +// !+WithGroup +func (h *IndentHandler) WithGroup(name string) slog.Handler { + if name == "" { + return h + } + h2 := *h + // Add an unopened group to h2 without modifying h. + h2.unopenedGroups = make([]string, len(h.unopenedGroups)+1) + copy(h2.unopenedGroups, h.unopenedGroups) + h2.unopenedGroups[len(h2.unopenedGroups)-1] = name + return &h2 +} + +//!-WithGroup + +// !+WithAttrs +func (h *IndentHandler) WithAttrs(attrs []slog.Attr) slog.Handler { + if len(attrs) == 0 { + return h + } + h2 := *h + // Force an append to copy the underlying array. + pre := slices.Clip(h.preformatted) + // Add all groups from WithGroup that haven't already been added. + h2.preformatted = h2.appendUnopenedGroups(pre, h2.indentLevel) + // Each of those groups increased the indent level by 1. + h2.indentLevel += len(h2.unopenedGroups) + // Now all groups have been opened. + h2.unopenedGroups = nil + // Pre-format the attributes. + for _, a := range attrs { + h2.preformatted = h2.appendAttr(h2.preformatted, a, h2.indentLevel) + } + return &h2 +} + +func (h *IndentHandler) appendUnopenedGroups(buf []byte, indentLevel int) []byte { + for _, g := range h.unopenedGroups { + buf = fmt.Appendf(buf, "%*s%s:\n", indentLevel*4, "", g) + indentLevel++ + } + return buf +} + +//!-WithAttrs + +// !+Handle +func (h *IndentHandler) Handle(ctx context.Context, r slog.Record) error { + buf := make([]byte, 0, 1024) + if !r.Time.IsZero() { + buf = h.appendAttr(buf, slog.Time(slog.TimeKey, r.Time), 0) + } + buf = h.appendAttr(buf, slog.Any(slog.LevelKey, r.Level), 0) + if r.PC != 0 { + fs := runtime.CallersFrames([]uintptr{r.PC}) + f, _ := fs.Next() + buf = h.appendAttr(buf, slog.String(slog.SourceKey, fmt.Sprintf("%s:%d", f.File, f.Line)), 0) + } + buf = h.appendAttr(buf, slog.String(slog.MessageKey, r.Message), 0) + // Insert preformatted attributes just after built-in ones. + buf = append(buf, h.preformatted...) + if r.NumAttrs() > 0 { + buf = h.appendUnopenedGroups(buf, h.indentLevel) + r.Attrs(func(a slog.Attr) bool { + buf = h.appendAttr(buf, a, h.indentLevel+len(h.unopenedGroups)) + return true + }) + } + buf = append(buf, "---\n"...) + h.mu.Lock() + defer h.mu.Unlock() + _, err := h.out.Write(buf) + return err +} + +//!-Handle + +func (h *IndentHandler) appendAttr(buf []byte, a slog.Attr, indentLevel int) []byte { + // Resolve the Attr's value before doing anything else. + a.Value = a.Value.Resolve() + // Ignore empty Attrs. + if a.Equal(slog.Attr{}) { + return buf + } + // Indent 4 spaces per level. + buf = fmt.Appendf(buf, "%*s", indentLevel*4, "") + switch a.Value.Kind() { + case slog.KindString: + // Quote string values, to make them easy to parse. + buf = fmt.Appendf(buf, "%s: %q\n", a.Key, a.Value.String()) + case slog.KindTime: + // Write times in a standard way, without the monotonic time. + buf = fmt.Appendf(buf, "%s: %s\n", a.Key, a.Value.Time().Format(time.RFC3339Nano)) + case slog.KindGroup: + attrs := a.Value.Group() + // Ignore empty groups. + if len(attrs) == 0 { + return buf + } + // If the key is non-empty, write it out and indent the rest of the attrs. + // Otherwise, inline the attrs. + if a.Key != "" { + buf = fmt.Appendf(buf, "%s:\n", a.Key) + indentLevel++ + } + for _, ga := range attrs { + buf = h.appendAttr(buf, ga, indentLevel) + } + default: + buf = fmt.Appendf(buf, "%s: %s\n", a.Key, a.Value) + } + return buf +}
diff --git a/slog-handler-guide/indenthandler3/indent_handler_test.go b/slog-handler-guide/indenthandler3/indent_handler_test.go new file mode 100644 index 0000000..f67bd03 --- /dev/null +++ b/slog-handler-guide/indenthandler3/indent_handler_test.go
@@ -0,0 +1,157 @@ +//go:build go1.21 + +package indenthandler + +import ( + "bufio" + "bytes" + "fmt" + "reflect" + "regexp" + "strconv" + "strings" + "testing" + "testing/slogtest" + "unicode" + + "log/slog" +) + +func TestSlogtest(t *testing.T) { + var buf bytes.Buffer + err := slogtest.TestHandler(New(&buf, nil), func() []map[string]any { + return parseLogEntries(buf.String()) + }) + if err != nil { + t.Error(err) + } +} + +func Test(t *testing.T) { + var buf bytes.Buffer + l := slog.New(New(&buf, nil)) + l.Info("hello", "a", 1, "b", true, "c", 3.14, slog.Group("g", "h", 1, "i", 2), "d", "NO") + got := buf.String() + wantre := `time: [-0-9T:.]+Z? +level: INFO +source: ".*/indent_handler_test.go:\d+" +msg: "hello" +a: 1 +b: true +c: 3.14 +g: + h: 1 + i: 2 +d: "NO" +` + re := regexp.MustCompile(wantre) + if !re.MatchString(got) { + t.Errorf("\ngot:\n%q\nwant:\n%q", got, wantre) + } + + buf.Reset() + l.Debug("test") + if got := buf.Len(); got != 0 { + t.Errorf("got buf.Len() = %d, want 0", got) + } +} + +func parseLogEntries(s string) []map[string]any { + var ms []map[string]any + scan := bufio.NewScanner(strings.NewReader(s)) + for scan.Scan() { + m := parseGroup(scan) + ms = append(ms, m) + } + if scan.Err() != nil { + panic(scan.Err()) + } + return ms +} + +func parseGroup(scan *bufio.Scanner) map[string]any { + m := map[string]any{} + groupIndent := -1 + for { + line := scan.Text() + if line == "---" { // end of entry + break + } + k, v, found := strings.Cut(line, ":") + if !found { + panic(fmt.Sprintf("no ':' in line %q", line)) + } + indent := strings.IndexFunc(k, func(r rune) bool { + return !unicode.IsSpace(r) + }) + if indent < 0 { + panic("blank line") + } + if groupIndent < 0 { + // First line in group; remember the indent. + groupIndent = indent + } else if indent < groupIndent { + // End of group + break + } else if indent > groupIndent { + panic(fmt.Sprintf("indent increased on line %q", line)) + } + + key := strings.TrimSpace(k) + if v == "" { + // Just a key: start of a group. + if !scan.Scan() { + panic("empty group") + } + m[key] = parseGroup(scan) + } else { + v = strings.TrimSpace(v) + if len(v) > 0 && v[0] == '"' { + var err error + v, err = strconv.Unquote(v) + if err != nil { + panic(err) + } + } + m[key] = v + if !scan.Scan() { + break + } + } + } + return m +} + +func TestParseLogEntries(t *testing.T) { + in := ` +a: 1 +b: 2 +c: 3 +g: + h: 4 + i: 5 +d: 6 +--- +e: 7 +--- +` + want := []map[string]any{ + { + "a": "1", + "b": "2", + "c": "3", + "g": map[string]any{ + "h": "4", + "i": "5", + }, + "d": "6", + }, + { + "e": "7", + }, + } + got := parseLogEntries(in[1:]) + if !reflect.DeepEqual(got, want) { + t.Errorf("\ngot:\n%v\nwant:\n%v", got, want) + } +}