Merge pull request #111 from thockin/master

pohly · web-flow · commit 561de0c1676c · 2021-10-13T18:08:06.000+02:00
funcr: Add options for hooks during rendering
diff --git a/funcr/example_test.go b/funcr/example_test.go
@@ -56,3 +56,57 @@ func ExampleUnderlier() {
 	}
 	// Output: hello world
 }
+
+func ExampleOptions() {
+	var log logr.Logger = funcr.NewJSON(
+		func(obj string) { fmt.Println(obj) },
+		funcr.Options{
+			LogCaller: funcr.All,
+			Verbosity: 1, // V(2) and higher is ignored.
+		})
+	log.V(0).Info("V(0) message", "key", "value")
+	log.V(1).Info("V(1) message", "key", "value")
+	log.V(2).Info("V(2) message", "key", "value")
+	// Output:
+	// {"logger":"","caller":{"file":"example_test.go","line":67},"level":0,"msg":"V(0) message","key":"value"}
+	// {"logger":"","caller":{"file":"example_test.go","line":68},"level":1,"msg":"V(1) message","key":"value"}
+}
+
+func ExampleOptions_renderHooks() {
+	// prefix all builtin keys with "log:"
+	prefixSpecialKeys := func(kvList []interface{}) []interface{} {
+		for i := 0; i < len(kvList); i += 2 {
+			k, _ := kvList[i].(string)
+			kvList[i] = "log:" + k
+		}
+		return kvList
+	}
+
+	// present saved values as a single JSON object
+	valuesAsObject := func(kvList []interface{}) []interface{} {
+		return []interface{}{"labels", funcr.PseudoStruct(kvList)}
+	}
+
+	var log logr.Logger = funcr.NewJSON(
+		func(obj string) { fmt.Println(obj) },
+		funcr.Options{
+			RenderBuiltinsHook: prefixSpecialKeys,
+			RenderValuesHook:   valuesAsObject,
+		})
+	log = log.WithName("MyLogger")
+	log = log.WithValues("savedKey", "savedValue")
+	log.Info("the message", "key", "value")
+	// Output: {"log:logger":"MyLogger","log:level":0,"log:msg":"the message","labels":{"savedKey":"savedValue"},"key":"value"}
+}
+
+func ExamplePseudoStruct() {
+	var log logr.Logger = funcr.NewJSON(
+		func(obj string) { fmt.Println(obj) },
+		funcr.Options{})
+	kv := []interface{}{
+		"field1", 12345,
+		"field2", true,
+	}
+	log.Info("the message", "key", funcr.PseudoStruct(kv))
+	// Output: {"logger":"","level":0,"msg":"the message","key":{"field1":12345,"field2":true}}
+}
diff --git a/funcr/funcr.go b/funcr/funcr.go
@@ -97,6 +97,29 @@ type Options struct {
 	// more logs.  Info logs at or below this level will be written, while logs
 	// above this level will be discarded.
 	Verbosity int
+
+	// RenderBuiltinsHook allows users to mutate the list of key-value pairs
+	// while a log line is being rendered.  The kvList argument follows logr
+	// conventions - each pair of slice elements is comprised of a string key
+	// and an arbitrary value (verified and sanitized before calling this
+	// hook).  The value returned must follow the same conventions.  This hook
+	// can be used to audit or modify logged data.  For example, you might want
+	// to prefix all of funcr's built-in keys with some string.  This hook is
+	// only called for built-in (provided by funcr itself) key-value pairs.
+	// Equivalent hooks are offered for key-value pairs saved via
+	// logr.Logger.WithValues or Formatter.AddValues (see RenderValuesHook) and
+	// for user-provided pairs (see RenderArgsHook).
+	RenderBuiltinsHook func(kvList []interface{}) []interface{}
+
+	// RenderValuesHook is the same as RenderBuiltinsHook, except that it is
+	// only called for key-value pairs saved via logr.Logger.WithValues.  See
+	// RenderBuiltinsHook for more details.
+	RenderValuesHook func(kvList []interface{}) []interface{}
+
+	// RenderArgsHook is the same as RenderBuiltinsHook, except that it is only
+	// called for key-value pairs passed directly to Info and Error.  See
+	// RenderBuiltinsHook for more details.
+	RenderArgsHook func(kvList []interface{}) []interface{}
 }
 
 // MessageClass indicates which category or categories of messages to consider.
@@ -199,14 +222,21 @@ const (
 	outputJSON
 )
 
-// render produces a log-line, ready to use.
+// PseudoStruct is a list of key-value pairs that gets logged as a struct.
+type PseudoStruct []interface{}
+
+// render produces a log line, ready to use.
 func (f Formatter) render(builtins, args []interface{}) string {
 	// Empirically bytes.Buffer is faster than strings.Builder for this.
 	buf := bytes.NewBuffer(make([]byte, 0, 1024))
 	if f.outputFormat == outputJSON {
 		buf.WriteByte('{')
 	}
-	f.flatten(buf, builtins, false)
+	vals := builtins
+	if hook := f.opts.RenderBuiltinsHook; hook != nil {
+		vals = hook(f.sanitize(vals))
+	}
+	f.flatten(buf, vals, false)
 	continuing := len(builtins) > 0
 	if len(f.valuesStr) > 0 {
 		if continuing {
@@ -219,7 +249,11 @@ func (f Formatter) render(builtins, args []interface{}) string {
 		continuing = true
 		buf.WriteString(f.valuesStr)
 	}
-	f.flatten(buf, args, continuing)
+	vals = args
+	if hook := f.opts.RenderArgsHook; hook != nil {
+		vals = hook(f.sanitize(vals))
+	}
+	f.flatten(buf, vals, continuing)
 	if f.outputFormat == outputJSON {
 		buf.WriteByte('}')
 	}
@@ -233,17 +267,15 @@ func (f Formatter) render(builtins, args []interface{}) string {
 // 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 []interface{}, continuing bool) []interface{} {
+	// This logic overlaps with sanitize() but saves one type-cast per key,
+	// which can be measurable.
 	if len(kvList)%2 != 0 {
-		kvList = append(kvList, "<no-value>")
+		kvList = append(kvList, noValue)
 	}
 	for i := 0; i < len(kvList); i += 2 {
 		k, ok := kvList[i].(string)
 		if !ok {
-			snippet := f.pretty(kvList[i])
-			if len(snippet) > 16 {
-				snippet = snippet[:16]
-			}
-			k = fmt.Sprintf("<non-string-key: %s>", snippet)
+			k = f.nonStringKey(kvList[i])
 			kvList[i] = k
 		}
 		v := kvList[i+1]
@@ -253,7 +285,7 @@ func (f Formatter) flatten(buf *bytes.Buffer, kvList []interface{}, continuing b
 				buf.WriteByte(',')
 			} else {
 				// In theory the format could be something we don't understand.  In
-				// practice, we control it, so it won't
+				// practice, we control it, so it won't be.
 				buf.WriteByte(' ')
 			}
 		}
@@ -337,6 +369,26 @@ func (f Formatter) prettyWithFlags(value interface{}, flags uint32) string {
 		return `"` + strconv.FormatComplex(complex128(v), 'f', -1, 64) + `"`
 	case complex128:
 		return `"` + strconv.FormatComplex(v, 'f', -1, 128) + `"`
+	case PseudoStruct:
+		buf := bytes.NewBuffer(make([]byte, 0, 1024))
+		v = f.sanitize(v)
+		if flags&flagRawStruct == 0 {
+			buf.WriteByte('{')
+		}
+		for i := 0; i < len(v); i += 2 {
+			if i > 0 {
+				buf.WriteByte(',')
+			}
+			buf.WriteByte('"')
+			buf.WriteString(v[i].(string))
+			buf.WriteByte('"')
+			buf.WriteByte(':')
+			buf.WriteString(f.pretty(v[i+1]))
+		}
+		if flags&flagRawStruct == 0 {
+			buf.WriteByte('}')
+		}
+		return buf.String()
 	}
 
 	buf := bytes.NewBuffer(make([]byte, 0, 256))
@@ -480,17 +532,27 @@ func isEmpty(v reflect.Value) bool {
 	return false
 }
 
-type callerID struct {
+// Caller represents the original call site for a log line, after considering
+// logr.Logger.WithCallDepth and logr.Logger.WithCallStackHelper.  The File and
+// Line fields will always be provided, while the Func field is optional.
+// Users can set the render hook fields in Options to examine logged key-value
+// pairs, one of which will be {"caller", Caller} if the Options.LogCaller
+// field is enabled for the given MessageClass.
+type Caller struct {
+	// File is the basename of the file for this call site.
 	File string `json:"file"`
-	Line int    `json:"line"`
+	// Line is the line number in the file for this call site.
+	Line int `json:"line"`
+	// Func is the function name for this call site, or empty if
+	// Options.LogCallerFunc is not enabled.
 	Func string `json:"function,omitempty"`
 }
 
-func (f Formatter) caller() callerID {
+func (f Formatter) caller() Caller {
 	// +1 for this frame, +1 for Info/Error.
 	pc, file, line, ok := runtime.Caller(f.depth + 2)
 	if !ok {
-		return callerID{"<unknown>", 0, ""}
+		return Caller{"<unknown>", 0, ""}
 	}
 	fn := ""
 	if f.opts.LogCallerFunc {
@@ -499,7 +561,40 @@ func (f Formatter) caller() callerID {
 		}
 	}
 
-	return callerID{filepath.Base(file), line, fn}
+	return Caller{filepath.Base(file), line, fn}
+}
+
+const noValue = "<no-value>"
+
+func (f Formatter) nonStringKey(v interface{}) string {
+	return fmt.Sprintf("<non-string-key: %s>", f.snippet(v))
+}
+
+// snippet produces a short snippet string of an arbitrary value.
+func (f Formatter) snippet(v interface{}) string {
+	const snipLen = 16
+
+	snip := f.pretty(v)
+	if len(snip) > snipLen {
+		snip = snip[:snipLen]
+	}
+	return snip
+}
+
+// sanitize ensures that a list of key-value pairs has 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) sanitize(kvList []interface{}) []interface{} {
+	if len(kvList)%2 != 0 {
+		kvList = append(kvList, noValue)
+	}
+	for i := 0; i < len(kvList); i += 2 {
+		_, ok := kvList[i].(string)
+		if !ok {
+			kvList[i] = f.nonStringKey(kvList[i])
+		}
+	}
+	return kvList
 }
 
 // Init configures this Formatter from runtime info, such as the call depth
@@ -520,8 +615,8 @@ func (f Formatter) GetDepth() int {
 	return f.depth
 }
 
-// FormatInfo flattens an Info log message into strings.
-// The prefix will be empty when no names were set, or when the output is
+// FormatInfo renders an Info log message into strings.  The prefix will be
+// empty when no names were set (via AddNames), or when the output is
 // configured for JSON.
 func (f Formatter) FormatInfo(level int, msg string, kvList []interface{}) (prefix, argsStr string) {
 	args := make([]interface{}, 0, 64) // using a constant here impacts perf
@@ -540,8 +635,8 @@ func (f Formatter) FormatInfo(level int, msg string, kvList []interface{}) (pref
 	return prefix, f.render(args, kvList)
 }
 
-// FormatError flattens an Error log message into strings.
-// The prefix will be empty when no names were set,  or when the output is
+// FormatError renders an Error log message into strings.  The prefix will be
+// empty when no names were set (via AddNames),  or when the output is
 // configured for JSON.
 func (f Formatter) FormatError(err error, msg string, kvList []interface{}) (prefix, argsStr string) {
 	args := make([]interface{}, 0, 64) // using a constant here impacts perf
@@ -578,11 +673,16 @@ func (f *Formatter) AddName(name string) {
 // AddValues adds key-value pairs to the set of saved values to be logged with
 // each log line.
 func (f *Formatter) AddValues(kvList []interface{}) {
-	// Pre-render values, so we don't have to do it on each Info/Error call.
-	buf := bytes.NewBuffer(make([]byte, 0, 1024))
 	// Three slice args forces a copy.
 	n := len(f.values)
-	f.values = f.flatten(buf, append(f.values[:n:n], kvList...), false)
+	vals := append(f.values[:n:n], kvList...)
+	if hook := f.opts.RenderValuesHook; hook != nil {
+		vals = hook(f.sanitize(vals))
+	}
+
+	// Pre-render values, so we don't have to do it on each Info/Error call.
+	buf := bytes.NewBuffer(make([]byte, 0, 1024))
+	f.values = f.flatten(buf, vals, false)
 	f.valuesStr = buf.String()
 }
 
diff --git a/funcr/funcr_test.go b/funcr/funcr_test.go
@@ -20,6 +20,7 @@ import (
 	"encoding/json"
 	"fmt"
 	"path/filepath"
+	"reflect"
 	"runtime"
 	"testing"
 
@@ -433,6 +434,10 @@ func TestPretty(t *testing.T) {
 			exp: `{"Tinnerint":0,"Tinnermap":{},"Tinnerslice":[]}`,
 		},
 		{val: Tembedjsontags{}},
+		{
+			val: PseudoStruct(makeKV("f1", 1, "f2", true, "f3", []int{})),
+			exp: `{"f1":1,"f2":true,"f3":[]}`,
+		},
 	}
 
 	f := NewFormatter(Options{})
@@ -484,6 +489,13 @@ func TestRender(t *testing.T) {
 		args:       makeKV("bool1", true, "bool2", false),
 		expectKV:   `"int1"=1 "int2"=2 "str1"="ABC" "str2"="DEF" "bool1"=true "bool2"=false`,
 		expectJSON: `{"int1":1,"int2":2,"str1":"ABC","str2":"DEF","bool1":true,"bool2":false}`,
+	}, {
+		name:       "pseudo structs",
+		builtins:   makeKV("int", PseudoStruct(makeKV("intsub", 1))),
+		values:     makeKV("str", PseudoStruct(makeKV("strsub", "2"))),
+		args:       makeKV("bool", PseudoStruct(makeKV("boolsub", true))),
+		expectKV:   `"int"={"intsub":1} "str"={"strsub":"2"} "bool"={"boolsub":true}`,
+		expectJSON: `{"int":{"intsub":1},"str":{"strsub":"2"},"bool":{"boolsub":true}}`,
 	}, {
 		name:       "missing value",
 		builtins:   makeKV("builtin"),
@@ -535,6 +547,47 @@ func TestRender(t *testing.T) {
 	}
 }
 
+func TestSanitize(t *testing.T) {
+	testCases := []struct {
+		name   string
+		kv     []interface{}
+		expect []interface{}
+	}{{
+		name:   "empty",
+		kv:     []interface{}{},
+		expect: []interface{}{},
+	}, {
+		name:   "already sane",
+		kv:     makeKV("int", 1, "str", "ABC", "bool", true),
+		expect: makeKV("int", 1, "str", "ABC", "bool", true),
+	}, {
+		name:   "missing value",
+		kv:     makeKV("key"),
+		expect: makeKV("key", "<no-value>"),
+	}, {
+		name:   "non-string key int",
+		kv:     makeKV(123, "val"),
+		expect: makeKV("<non-string-key: 123>", "val"),
+	}, {
+		name: "non-string key struct",
+		kv: makeKV(struct {
+			F1 string
+			F2 int
+		}{"f1", 8675309}, "val"),
+		expect: makeKV(`<non-string-key: {"F1":"f1","F2":>`, "val"),
+	}}
+
+	f := NewFormatterJSON(Options{})
+	for _, tc := range testCases {
+		t.Run(tc.name, func(t *testing.T) {
+			r := f.sanitize(tc.kv)
+			if !reflect.DeepEqual(r, tc.expect) {
+				t.Errorf("wrong output:\nexpected %q\n     got %q", tc.expect, r)
+			}
+		})
+	}
+}
+
 func TestEnabled(t *testing.T) {
 	t.Run("default V", func(t *testing.T) {
 		log := newSink(func(prefix, args string) {}, NewFormatter(Options{}))
