Codebase list golang-github-go-logr-logr / f77f1b9
funcr: Add options for hooks during rendering Add new `Options` fields which are function pointers to optional hooks to be called. This allow users to manipulate the way that kv-pairs are logged. For example: * prefix or rename builtin keys * log WithValues() kv-pairs as a single pseudo-struct * collect telemetry around how often each log is triggered This adds a new type `PseudoStruct` which can be used to trigger special logging - a kvList is treated as a struct. This also exposes the `Caller` type, to enable hooks to recognize and use caller information. Tim Hockin 2 years ago
3 changed file(s) with 224 addition(s) and 17 deletion(s). Raw diff Collapse all Expand all
+54
-0
funcr/example_test.go less more
5555 }
5656 // Output: hello world
5757 }
58
59 func ExampleOptions() {
60 var log logr.Logger = funcr.NewJSON(
61 func(obj string) { fmt.Println(obj) },
62 funcr.Options{
63 LogCaller: funcr.All,
64 Verbosity: 1, // V(2) and higher is ignored.
65 })
66 log.V(0).Info("V(0) message", "key", "value")
67 log.V(1).Info("V(1) message", "key", "value")
68 log.V(2).Info("V(2) message", "key", "value")
69 // Output:
70 // {"logger":"","caller":{"file":"example_test.go","line":67},"level":0,"msg":"V(0) message","key":"value"}
71 // {"logger":"","caller":{"file":"example_test.go","line":68},"level":1,"msg":"V(1) message","key":"value"}
72 }
73
74 func ExampleOptions_renderHooks() {
75 // prefix all builtin keys with "log:"
76 prefixSpecialKeys := func(kvList []interface{}) []interface{} {
77 for i := 0; i < len(kvList); i += 2 {
78 k, _ := kvList[i].(string)
79 kvList[i] = "log:" + k
80 }
81 return kvList
82 }
83
84 // present saved values as a single JSON object
85 valuesAsObject := func(kvList []interface{}) []interface{} {
86 return []interface{}{"labels", funcr.PseudoStruct(kvList)}
87 }
88
89 var log logr.Logger = funcr.NewJSON(
90 func(obj string) { fmt.Println(obj) },
91 funcr.Options{
92 RenderBuiltinsHook: prefixSpecialKeys,
93 RenderValuesHook: valuesAsObject,
94 })
95 log = log.WithName("MyLogger")
96 log = log.WithValues("savedKey", "savedValue")
97 log.Info("the message", "key", "value")
98 // Output: {"log:logger":"MyLogger","log:level":0,"log:msg":"the message","labels":{"savedKey":"savedValue"},"key":"value"}
99 }
100
101 func ExamplePseudoStruct() {
102 var log logr.Logger = funcr.NewJSON(
103 func(obj string) { fmt.Println(obj) },
104 funcr.Options{})
105 kv := []interface{}{
106 "field1", 12345,
107 "field2", true,
108 }
109 log.Info("the message", "key", funcr.PseudoStruct(kv))
110 // Output: {"logger":"","level":0,"msg":"the message","key":{"field1":12345,"field2":true}}
111 }
+117
-17
funcr/funcr.go less more
9696 // more logs. Info logs at or below this level will be written, while logs
9797 // above this level will be discarded.
9898 Verbosity int
99
100 // RenderBuiltinsHook allows users to mutate the list of key-value pairs
101 // while a log line is being rendered. The kvList argument follows logr
102 // conventions - each pair of slice elements is comprised of a string key
103 // and an arbitrary value (verified and sanitized before calling this
104 // hook). The value returned must follow the same conventions. This hook
105 // can be used to audit or modify logged data. For example, you might want
106 // to prefix all of funcr's built-in keys with some string. This hook is
107 // only called for built-in (provided by funcr itself) key-value pairs.
108 // Equivalent hooks are offered for key-value pairs saved via
109 // logr.Logger.WithValues or Formatter.AddValues (see RenderValuesHook) and
110 // for user-provided pairs (see RenderArgsHook).
111 RenderBuiltinsHook func(kvList []interface{}) []interface{}
112
113 // RenderValuesHook is the same as RenderBuiltinsHook, except that it is
114 // only called for key-value pairs saved via logr.Logger.WithValues. See
115 // RenderBuiltinsHook for more details.
116 RenderValuesHook func(kvList []interface{}) []interface{}
117
118 // RenderArgsHook is the same as RenderBuiltinsHook, except that it is only
119 // called for key-value pairs passed directly to Info and Error. See
120 // RenderBuiltinsHook for more details.
121 RenderArgsHook func(kvList []interface{}) []interface{}
99122 }
100123
101124 // MessageClass indicates which category or categories of messages to consider.
198221 outputJSON
199222 )
200223
201 // render produces a log-line, ready to use.
224 // PseudoStruct is a list of key-value pairs that gets logged as a struct.
225 type PseudoStruct []interface{}
226
227 // render produces a log line, ready to use.
202228 func (f Formatter) render(builtins, args []interface{}) string {
203229 // Empirically bytes.Buffer is faster than strings.Builder for this.
204230 buf := bytes.NewBuffer(make([]byte, 0, 1024))
205231 if f.outputFormat == outputJSON {
206232 buf.WriteByte('{')
207233 }
208 f.flatten(buf, builtins, false)
234 vals := builtins
235 if hook := f.opts.RenderBuiltinsHook; hook != nil {
236 vals = hook(f.sanitize(vals))
237 }
238 f.flatten(buf, vals, false)
209239 continuing := len(builtins) > 0
210240 if len(f.valuesStr) > 0 {
211241 if continuing {
218248 continuing = true
219249 buf.WriteString(f.valuesStr)
220250 }
221 f.flatten(buf, args, continuing)
251 vals = args
252 if hook := f.opts.RenderArgsHook; hook != nil {
253 vals = hook(f.sanitize(vals))
254 }
255 f.flatten(buf, vals, continuing)
222256 if f.outputFormat == outputJSON {
223257 buf.WriteByte('}')
224258 }
232266 // ensures that there is a value for every key (adding a value if needed) and
233267 // that each key is a string (substituting a key if needed).
234268 func (f Formatter) flatten(buf *bytes.Buffer, kvList []interface{}, continuing bool) []interface{} {
269 // This logic overlaps with sanitize() but saves one type-cast per key,
270 // which can be measurable.
235271 if len(kvList)%2 != 0 {
236 kvList = append(kvList, "<no-value>")
272 kvList = append(kvList, noValue)
237273 }
238274 for i := 0; i < len(kvList); i += 2 {
239275 k, ok := kvList[i].(string)
240276 if !ok {
241 snippet := f.pretty(kvList[i])
242 if len(snippet) > 16 {
243 snippet = snippet[:16]
244 }
245 k = fmt.Sprintf("<non-string-key: %s>", snippet)
277 k = f.nonStringKey(kvList[i])
246278 kvList[i] = k
247279 }
248280 v := kvList[i+1]
336368 return `"` + strconv.FormatComplex(complex128(v), 'f', -1, 64) + `"`
337369 case complex128:
338370 return `"` + strconv.FormatComplex(v, 'f', -1, 128) + `"`
371 case PseudoStruct:
372 buf := bytes.NewBuffer(make([]byte, 0, 1024))
373 v = f.sanitize(v)
374 if flags&flagRawStruct == 0 {
375 buf.WriteByte('{')
376 }
377 for i := 0; i < len(v); i += 2 {
378 if i > 0 {
379 buf.WriteByte(',')
380 }
381 buf.WriteByte('"')
382 buf.WriteString(v[i].(string))
383 buf.WriteByte('"')
384 buf.WriteByte(':')
385 buf.WriteString(f.pretty(v[i+1]))
386 }
387 if flags&flagRawStruct == 0 {
388 buf.WriteByte('}')
389 }
390 return buf.String()
339391 }
340392
341393 buf := bytes.NewBuffer(make([]byte, 0, 256))
479531 return false
480532 }
481533
482 type callerID struct {
534 // Caller represents the original call site for a log line, after considering
535 // logr.Logger.WithCallDepth and logr.Logger.WithCallStackHelper. The File and
536 // Line fields will always be provided, while the Func field is optional.
537 // Users can set the render hook fields in Options to examine logged key-value
538 // pairs, one of which will be {"caller", Caller} if the Options.LogCaller
539 // field is enabled for the given MessageClass.
540 type Caller struct {
541 // File is the basename of the file for this call site.
483542 File string `json:"file"`
484 Line int `json:"line"`
543 // Line is the line number in the file for this call site.
544 Line int `json:"line"`
545 // Func is the function name for this call site, or empty if
546 // Options.LogCallerFunc is not enabled.
485547 Func string `json:"function,omitempty"`
486548 }
487549
488 func (f Formatter) caller() callerID {
550 func (f Formatter) caller() Caller {
489551 // +1 for this frame, +1 for Info/Error.
490552 pc, file, line, ok := runtime.Caller(f.depth + 2)
491553 if !ok {
492 return callerID{"<unknown>", 0, ""}
554 return Caller{"<unknown>", 0, ""}
493555 }
494556 fn := ""
495557 if f.opts.LogCallerFunc {
498560 }
499561 }
500562
501 return callerID{filepath.Base(file), line, fn}
563 return Caller{filepath.Base(file), line, fn}
564 }
565
566 const noValue = "<no-value>"
567
568 func (f Formatter) nonStringKey(v interface{}) string {
569 return fmt.Sprintf("<non-string-key: %s>", f.snippet(v))
570 }
571
572 // snippet produces a short snippet string of an arbitrary value.
573 func (f Formatter) snippet(v interface{}) string {
574 const snipLen = 16
575
576 snip := f.pretty(v)
577 if len(snip) > snipLen {
578 snip = snip[:snipLen]
579 }
580 return snip
581 }
582
583 // sanitize ensures that a list of key-value pairs has a value for every key
584 // (adding a value if needed) and that each key is a string (substituting a key
585 // if needed).
586 func (f Formatter) sanitize(kvList []interface{}) []interface{} {
587 if len(kvList)%2 != 0 {
588 kvList = append(kvList, noValue)
589 }
590 for i := 0; i < len(kvList); i += 2 {
591 _, ok := kvList[i].(string)
592 if !ok {
593 kvList[i] = f.nonStringKey(kvList[i])
594 }
595 }
596 return kvList
502597 }
503598
504599 // Init configures this Formatter from runtime info, such as the call depth
577672 // AddValues adds key-value pairs to the set of saved values to be logged with
578673 // each log line.
579674 func (f *Formatter) AddValues(kvList []interface{}) {
675 // Three slice args forces a copy.
676 n := len(f.values)
677 vals := append(f.values[:n:n], kvList...)
678 if hook := f.opts.RenderValuesHook; hook != nil {
679 vals = hook(f.sanitize(vals))
680 }
681
580682 // Pre-render values, so we don't have to do it on each Info/Error call.
581683 buf := bytes.NewBuffer(make([]byte, 0, 1024))
582 // Three slice args forces a copy.
583 n := len(f.values)
584 f.values = f.flatten(buf, append(f.values[:n:n], kvList...), false)
684 f.values = f.flatten(buf, vals, false)
585685 f.valuesStr = buf.String()
586686 }
587687
+53
-0
funcr/funcr_test.go less more
1919 "encoding/json"
2020 "fmt"
2121 "path/filepath"
22 "reflect"
2223 "runtime"
2324 "testing"
2425
432433 exp: `{"Tinnerint":0,"Tinnermap":{},"Tinnerslice":[]}`,
433434 },
434435 {val: Tembedjsontags{}},
436 {
437 val: PseudoStruct(makeKV("f1", 1, "f2", true, "f3", []int{})),
438 exp: `{"f1":1,"f2":true,"f3":[]}`,
439 },
435440 }
436441
437442 f := NewFormatter(Options{})
483488 args: makeKV("bool1", true, "bool2", false),
484489 expectKV: `"int1"=1 "int2"=2 "str1"="ABC" "str2"="DEF" "bool1"=true "bool2"=false`,
485490 expectJSON: `{"int1":1,"int2":2,"str1":"ABC","str2":"DEF","bool1":true,"bool2":false}`,
491 }, {
492 name: "pseudo structs",
493 builtins: makeKV("int", PseudoStruct(makeKV("intsub", 1))),
494 values: makeKV("str", PseudoStruct(makeKV("strsub", "2"))),
495 args: makeKV("bool", PseudoStruct(makeKV("boolsub", true))),
496 expectKV: `"int"={"intsub":1} "str"={"strsub":"2"} "bool"={"boolsub":true}`,
497 expectJSON: `{"int":{"intsub":1},"str":{"strsub":"2"},"bool":{"boolsub":true}}`,
486498 }, {
487499 name: "missing value",
488500 builtins: makeKV("builtin"),
534546 }
535547 }
536548
549 func TestSanitize(t *testing.T) {
550 testCases := []struct {
551 name string
552 kv []interface{}
553 expect []interface{}
554 }{{
555 name: "empty",
556 kv: []interface{}{},
557 expect: []interface{}{},
558 }, {
559 name: "already sane",
560 kv: makeKV("int", 1, "str", "ABC", "bool", true),
561 expect: makeKV("int", 1, "str", "ABC", "bool", true),
562 }, {
563 name: "missing value",
564 kv: makeKV("key"),
565 expect: makeKV("key", "<no-value>"),
566 }, {
567 name: "non-string key int",
568 kv: makeKV(123, "val"),
569 expect: makeKV("<non-string-key: 123>", "val"),
570 }, {
571 name: "non-string key struct",
572 kv: makeKV(struct {
573 F1 string
574 F2 int
575 }{"f1", 8675309}, "val"),
576 expect: makeKV(`<non-string-key: {"F1":"f1","F2":>`, "val"),
577 }}
578
579 f := NewFormatterJSON(Options{})
580 for _, tc := range testCases {
581 t.Run(tc.name, func(t *testing.T) {
582 r := f.sanitize(tc.kv)
583 if !reflect.DeepEqual(r, tc.expect) {
584 t.Errorf("wrong output:\nexpected %q\n got %q", tc.expect, r)
585 }
586 })
587 }
588 }
589
537590 func TestEnabled(t *testing.T) {
538591 t.Run("default V", func(t *testing.T) {
539592 log := newSink(func(prefix, args string) {}, NewFormatter(Options{}))