From 376cba95da219ba8c48754d17c6689b003660c6a Mon Sep 17 00:00:00 2001 From: Tim Hockin Date: Thu, 29 Feb 2024 17:08:55 -0800 Subject: [PATCH] funcr: Handle nested empty groups properly This ruins the whole idea of pre-rendering. We simply don't know if we have to render a group until we know the whole log record. Not having values at the time that `WithGroup` is called is not sufficient information. --- funcr/funcr.go | 169 +++++++++++++++++++++-------------------- funcr/slogsink_test.go | 105 ++++++++++++++++++++++--- 2 files changed, 179 insertions(+), 95 deletions(-) diff --git a/funcr/funcr.go b/funcr/funcr.go index fb2f866..30568e7 100644 --- a/funcr/funcr.go +++ b/funcr/funcr.go @@ -236,15 +236,14 @@ func newFormatter(opts Options, outfmt outputFormat) Formatter { // implementation. It should be constructed with NewFormatter. Some of // its methods directly implement logr.LogSink. type Formatter struct { - outputFormat outputFormat - prefix string - values []any - valuesStr string - parentValuesStr string - depth int - opts *Options - group string // for slog groups - groupDepth int + outputFormat outputFormat + prefix string + values []any + valuesStr string + depth int + opts *Options + groupName string // for slog groups + groups []groupDef } // outputFormat indicates which outputFormat to use. @@ -257,6 +256,13 @@ const ( outputJSON ) +// groupDef represents a saved group. The values may be empty, but we don't +// know if we need to render the group until the final record is rendered. +type groupDef struct { + name string + values string +} + // PseudoStruct is a list of key-value pairs that gets logged as a struct. type PseudoStruct []any @@ -264,76 +270,102 @@ type PseudoStruct []any func (f Formatter) render(builtins, args []any) string { // Empirically bytes.Buffer is faster than strings.Builder for this. buf := bytes.NewBuffer(make([]byte, 0, 1024)) + if f.outputFormat == outputJSON { - buf.WriteByte('{') // for the whole line + buf.WriteByte('{') // for the whole record } + // Render builtins vals := builtins if hook := f.opts.RenderBuiltinsHook; hook != nil { vals = hook(f.sanitize(vals)) } - f.flatten(buf, vals, false, false) // keys are ours, no need to escape + f.flatten(buf, vals, false) // keys are ours, no need to escape continuing := len(builtins) > 0 - if f.parentValuesStr != "" { - if continuing { - buf.WriteByte(f.comma()) + // Turn the inner-most group into a string + argsStr := func() string { + buf := bytes.NewBuffer(make([]byte, 0, 1024)) + + vals = args + if hook := f.opts.RenderArgsHook; hook != nil { + vals = hook(f.sanitize(vals)) } - buf.WriteString(f.parentValuesStr) - continuing = true - } + f.flatten(buf, vals, true) // escape user-provided keys - groupDepth := f.groupDepth - if f.group != "" { - if f.valuesStr != "" || len(args) != 0 { - if continuing { - buf.WriteByte(f.comma()) - } - buf.WriteString(f.quoted(f.group, true)) // escape user-provided keys - buf.WriteByte(f.colon()) - buf.WriteByte('{') // for the group - continuing = false - } else { - // The group was empty - groupDepth-- + return buf.String() + }() + + // Render the stack of groups from the inside out. + bodyStr := f.renderGroup(f.groupName, f.valuesStr, argsStr) + for i := len(f.groups) - 1; i >= 0; i-- { + grp := &f.groups[i] + if grp.values == "" && bodyStr == "" { + // no contents, so we must elide the whole group + continue } + bodyStr = f.renderGroup(grp.name, grp.values, bodyStr) } - if f.valuesStr != "" { + if bodyStr != "" { if continuing { buf.WriteByte(f.comma()) } - buf.WriteString(f.valuesStr) - continuing = true + buf.WriteString(bodyStr) } - vals = args - if hook := f.opts.RenderArgsHook; hook != nil { - vals = hook(f.sanitize(vals)) + if f.outputFormat == outputJSON { + buf.WriteByte('}') // for the whole record } - f.flatten(buf, vals, continuing, true) // escape user-provided keys - for i := 0; i < groupDepth; i++ { - buf.WriteByte('}') // for the groups + return buf.String() +} + +// renderGroup returns a string representation of the named group with rendered +// values and args. If the name is empty, this will return the values and args, +// joined. If the name is not empty, this will return a single key-value pair, +// where the value is a grouping of the values and args. If the values and +// args are both empty, this will return an empty string, even if the name was +// specified. +func (f Formatter) renderGroup(name string, values string, args string) string { + buf := bytes.NewBuffer(make([]byte, 0, 1024)) + + needClosingBrace := false + if name != "" && (values != "" || args != "") { + buf.WriteString(f.quoted(name, true)) // escape user-provided keys + buf.WriteByte(f.colon()) + buf.WriteByte('{') + needClosingBrace = true } - if f.outputFormat == outputJSON { - buf.WriteByte('}') // for the whole line + continuing := false + if values != "" { + buf.WriteString(values) + continuing = true + } + + if args != "" { + if continuing { + buf.WriteByte(f.comma()) + } + buf.WriteString(args) + } + + if needClosingBrace { + buf.WriteByte('}') } return buf.String() } -// flatten renders a list of key-value pairs into a buffer. If continuing is -// true, it assumes that the buffer has previous values and will emit a -// separator (which depends on the output format) before the first pair it -// writes. If escapeKeys is true, the keys are assumed to have -// non-JSON-compatible characters in them and must be evaluated for escapes. +// flatten renders a list of key-value pairs into a buffer. If escapeKeys is +// true, the keys are assumed to have non-JSON-compatible characters in them +// and must be evaluated for escapes. // // This function returns a potentially modified version of kvList, which // ensures that there is a value for every key (adding a value if needed) and // that each key is a string (substituting a key if needed). -func (f Formatter) flatten(buf *bytes.Buffer, kvList []any, continuing bool, escapeKeys bool) []any { +func (f Formatter) flatten(buf *bytes.Buffer, kvList []any, escapeKeys bool) []any { // This logic overlaps with sanitize() but saves one type-cast per key, // which can be measurable. if len(kvList)%2 != 0 { @@ -354,7 +386,7 @@ func (f Formatter) flatten(buf *bytes.Buffer, kvList []any, continuing bool, esc } v := kvList[i+1] - if i > 0 || continuing { + if i > 0 { if f.outputFormat == outputJSON { buf.WriteByte(f.comma()) } else { @@ -766,46 +798,17 @@ func (f Formatter) sanitize(kvList []any) []any { // startGroup opens a new group scope (basically a sub-struct), which locks all // the current saved values and starts them anew. This is needed to satisfy // slog. -func (f *Formatter) startGroup(group string) { +func (f *Formatter) startGroup(name string) { // Unnamed groups are just inlined. - if group == "" { + if name == "" { return } - // Any saved values can no longer be changed. - buf := bytes.NewBuffer(make([]byte, 0, 1024)) - continuing := false - - if f.parentValuesStr != "" { - buf.WriteString(f.parentValuesStr) - continuing = true - } - - if f.group != "" && f.valuesStr != "" { - if continuing { - buf.WriteByte(f.comma()) - } - buf.WriteString(f.quoted(f.group, true)) // escape user-provided keys - buf.WriteByte(f.colon()) - buf.WriteByte('{') // for the group - continuing = false - } - - if f.valuesStr != "" { - if continuing { - buf.WriteByte(f.comma()) - } - buf.WriteString(f.valuesStr) - } - - // NOTE: We don't close the scope here - that's done later, when a log line - // is actually rendered (because we have N scopes to close). - - f.parentValuesStr = buf.String() + n := len(f.groups) + f.groups = append(f.groups[:n:n], groupDef{f.groupName, f.valuesStr}) // Start collecting new values. - f.group = group - f.groupDepth++ + f.groupName = name f.valuesStr = "" f.values = nil } @@ -900,7 +903,7 @@ func (f *Formatter) AddValues(kvList []any) { // Pre-render values, so we don't have to do it on each Info/Error call. buf := bytes.NewBuffer(make([]byte, 0, 1024)) - f.flatten(buf, vals, false, true) // escape user-provided keys + f.flatten(buf, vals, true) // escape user-provided keys f.valuesStr = buf.String() } diff --git a/funcr/slogsink_test.go b/funcr/slogsink_test.go index 9fbe55a..8fb8467 100644 --- a/funcr/slogsink_test.go +++ b/funcr/slogsink_test.go @@ -83,19 +83,100 @@ func TestSlogSink(t *testing.T) { } } -func TestSlogSinkNestedGroups(t *testing.T) { - capt := &capture{} - logger := logr.New(newSink(capt.Func, NewFormatterJSON(Options{}))) - slogger := slog.New(logr.ToSlogHandler(logger)) - slogger = slogger.With("out", 0) - slogger = slogger.WithGroup("g1").With("mid1", 1) - slogger = slogger.WithGroup("g2").With("mid2", 2) - slogger = slogger.WithGroup("g3").With("in", 3) - slogger.Info("msg", "k", "v") +func TestSlogSinkGroups(t *testing.T) { + testCases := []struct { + name string + fn func(slogger *slog.Logger) + expect string + }{{ + name: "no group", + fn: func(slogger *slog.Logger) { + slogger. + Info("msg", "k", "v") + }, + expect: `{"logger":"","level":0,"msg":"msg","k":"v"}`, + }, { + name: "1 group with leaf args", + fn: func(slogger *slog.Logger) { + slogger. + WithGroup("g1"). + Info("msg", "k", "v") + }, + expect: `{"logger":"","level":0,"msg":"msg","g1":{"k":"v"}}`, + }, { + name: "1 group without leaf args", + fn: func(slogger *slog.Logger) { + slogger. + WithGroup("g1"). + Info("msg") + }, + expect: `{"logger":"","level":0,"msg":"msg"}`, + }, { + name: "1 group with value without leaf args", + fn: func(slogger *slog.Logger) { + slogger. + WithGroup("g1").With("k1", 1). + Info("msg") + }, + expect: `{"logger":"","level":0,"msg":"msg","g1":{"k1":1}}`, + }, { + name: "2 groups with values no leaf args", + fn: func(slogger *slog.Logger) { + slogger. + WithGroup("g1").With("k1", 1). + WithGroup("g2").With("k2", 2). + Info("msg") + }, + expect: `{"logger":"","level":0,"msg":"msg","g1":{"k1":1,"g2":{"k2":2}}}`, + }, { + name: "3 empty groups with no values or leaf args", + fn: func(slogger *slog.Logger) { + slogger. + WithGroup("g1"). + WithGroup("g2"). + WithGroup("g3"). + Info("msg") + }, + expect: `{"logger":"","level":0,"msg":"msg"}`, + }, { + name: "3 empty groups with no values but with leaf args", + fn: func(slogger *slog.Logger) { + slogger. + WithGroup("g1"). + WithGroup("g2"). + WithGroup("g3"). + Info("msg", "k", "v") + }, + expect: `{"logger":"","level":0,"msg":"msg","g1":{"g2":{"g3":{"k":"v"}}}}`, + }, { + name: "multiple groups with and without values", + fn: func(slogger *slog.Logger) { + slogger. + With("k0", 0). + WithGroup("g1"). + WithGroup("g2"). + WithGroup("g3").With("k3", 3). + WithGroup("g4"). + WithGroup("g5"). + WithGroup("g6").With("k6", 6). + WithGroup("g7"). + WithGroup("g8"). + WithGroup("g9"). + Info("msg") + }, + expect: `{"logger":"","level":0,"msg":"msg","k0":0,"g1":{"g2":{"g3":{"k3":3,"g4":{"g5":{"g6":{"k6":6}}}}}}}`, + }} - expect := `{"logger":"","level":0,"msg":"msg","out":0,"g1":{"mid1":1,"g2":{"mid2":2,"g3":{"in":3,"k":"v"}}}}` - if capt.log != expect { - t.Errorf("\nexpected %q\n got %q", expect, capt.log) + for _, tc := range testCases { + t.Run(tc.name, func(t *testing.T) { + capt := &capture{} + logger := logr.New(newSink(capt.Func, NewFormatterJSON(Options{}))) + slogger := slog.New(logr.ToSlogHandler(logger)) + tc.fn(slogger) + if capt.log != tc.expect { + t.Errorf("\nexpected: `%s`\n got: `%s`", tc.expect, capt.log) + } + }) } }