Codebase list golang-github-go-logr-logr / 77a1d0e
funcr: Add strict JSON mode New funcs `funcr.NewJSON()` and `funcr.NewFormatterJSON()` will configure the output for strict JSON. This is not just an `Options` field because the function (from which funcr takes its name) has a different signature in JSON mode (just 1 argument). Benchmarks: Before: ``` BenchmarkFuncrInfoOneArg-6 2015502 592.1 ns/op BenchmarkFuncrInfoSeveralArgs-6 970407 1233 ns/op BenchmarkFuncrV0Info-6 970164 1232 ns/op BenchmarkFuncrV9Info-6 15342703 78.60 ns/op BenchmarkFuncrError-6 816357 1456 ns/op ``` After: ``` BenchmarkFuncrInfoOneArg-6 1998198 598.6 ns/op BenchmarkFuncrJSONInfoOneArg-6 1727032 694.8 ns/op BenchmarkFuncrInfoSeveralArgs-6 971455 1230 ns/op BenchmarkFuncrJSONInfoSeveralArgs-6 889963 1344 ns/op BenchmarkFuncrV0Info-6 975469 1226 ns/op BenchmarkFuncrJSONV0Info-6 890828 1342 ns/op BenchmarkFuncrV9Info-6 15004518 79.69 ns/op BenchmarkFuncrJSONV9Info-6 15045549 79.86 ns/op BenchmarkFuncrError-6 816446 1462 ns/op BenchmarkFuncrJSONError-6 754684 1583 ns/op ``` The majority of the extra time in JSON mode seems to be from adding the "logger" key-value pair, which I don't see how to improve on. Tim Hockin 2 years ago
4 changed file(s) with 195 addition(s) and 79 deletion(s). Raw diff Collapse all Expand all
+46
-21
benchmark/benchmark_test.go less more
2222 "github.com/go-logr/logr"
2323 "github.com/go-logr/logr/funcr"
2424 )
25
26 func noop(prefix, args string) {
27 }
2825
2926 //go:noinline
3027 func doInfoOneArg(b *testing.B, log logr.Logger) {
9491 }
9592 }
9693
97 func BenchmarkDiscardInfoOneArg(b *testing.B) {
94 func BenchmarkDiscardLogInfoOneArg(b *testing.B) {
9895 var log logr.Logger = logr.Discard()
9996 doInfoOneArg(b, log)
10097 }
10198
102 func BenchmarkDiscardInfoSeveralArgs(b *testing.B) {
99 func BenchmarkDiscardLogInfoSeveralArgs(b *testing.B) {
103100 var log logr.Logger = logr.Discard()
104101 doInfoSeveralArgs(b, log)
105102 }
106103
107 func BenchmarkDiscardV0Info(b *testing.B) {
104 func BenchmarkDiscardLogV0Info(b *testing.B) {
108105 var log logr.Logger = logr.Discard()
109106 doV0Info(b, log)
110107 }
111108
112 func BenchmarkDiscardV9Info(b *testing.B) {
109 func BenchmarkDiscardLogV9Info(b *testing.B) {
113110 var log logr.Logger = logr.Discard()
114111 doV9Info(b, log)
115112 }
116113
117 func BenchmarkDiscardError(b *testing.B) {
114 func BenchmarkDiscardLogError(b *testing.B) {
118115 var log logr.Logger = logr.Discard()
119116 doError(b, log)
120117 }
129126 doWithName(b, log)
130127 }
131128
132 func BenchmarkFuncrInfoOneArg(b *testing.B) {
133 var log logr.Logger = funcr.New(noop, funcr.Options{})
129 func noopKV(prefix, args string) {}
130 func noopJSON(obj string) {}
131
132 func BenchmarkFuncrLogInfoOneArg(b *testing.B) {
133 var log logr.Logger = funcr.New(noopKV, funcr.Options{})
134134 doInfoOneArg(b, log)
135135 }
136136
137 func BenchmarkFuncrInfoSeveralArgs(b *testing.B) {
138 var log logr.Logger = funcr.New(noop, funcr.Options{})
137 func BenchmarkFuncrJSONLogInfoOneArg(b *testing.B) {
138 var log logr.Logger = funcr.NewJSON(noopJSON, funcr.Options{})
139 doInfoOneArg(b, log)
140 }
141
142 func BenchmarkFuncrLogInfoSeveralArgs(b *testing.B) {
143 var log logr.Logger = funcr.New(noopKV, funcr.Options{})
139144 doInfoSeveralArgs(b, log)
140145 }
141146
142 func BenchmarkFuncrV0Info(b *testing.B) {
143 var log logr.Logger = funcr.New(noop, funcr.Options{})
147 func BenchmarkFuncrJSONLogInfoSeveralArgs(b *testing.B) {
148 var log logr.Logger = funcr.NewJSON(noopJSON, funcr.Options{})
149 doInfoSeveralArgs(b, log)
150 }
151
152 func BenchmarkFuncrLogV0Info(b *testing.B) {
153 var log logr.Logger = funcr.New(noopKV, funcr.Options{})
144154 doV0Info(b, log)
145155 }
146156
147 func BenchmarkFuncrV9Info(b *testing.B) {
148 var log logr.Logger = funcr.New(noop, funcr.Options{})
157 func BenchmarkFuncrJSONLogV0Info(b *testing.B) {
158 var log logr.Logger = funcr.NewJSON(noopJSON, funcr.Options{})
159 doV0Info(b, log)
160 }
161
162 func BenchmarkFuncrLogV9Info(b *testing.B) {
163 var log logr.Logger = funcr.New(noopKV, funcr.Options{})
149164 doV9Info(b, log)
150165 }
151166
152 func BenchmarkFuncrError(b *testing.B) {
153 var log logr.Logger = funcr.New(noop, funcr.Options{})
167 func BenchmarkFuncrJSONLogV9Info(b *testing.B) {
168 var log logr.Logger = funcr.NewJSON(noopJSON, funcr.Options{})
169 doV9Info(b, log)
170 }
171
172 func BenchmarkFuncrLogError(b *testing.B) {
173 var log logr.Logger = funcr.New(noopKV, funcr.Options{})
174 doError(b, log)
175 }
176
177 func BenchmarkFuncrJSONLogError(b *testing.B) {
178 var log logr.Logger = funcr.NewJSON(noopJSON, funcr.Options{})
154179 doError(b, log)
155180 }
156181
157182 func BenchmarkFuncrWithValues(b *testing.B) {
158 var log logr.Logger = funcr.New(noop, funcr.Options{})
183 var log logr.Logger = funcr.New(noopKV, funcr.Options{})
159184 doWithValues(b, log)
160185 }
161186
162187 func BenchmarkFuncrWithName(b *testing.B) {
163 var log logr.Logger = funcr.New(noop, funcr.Options{})
188 var log logr.Logger = funcr.New(noopKV, funcr.Options{})
164189 doWithName(b, log)
165190 }
166191
167192 func BenchmarkFuncrWithCallDepth(b *testing.B) {
168 var log logr.Logger = funcr.New(noop, funcr.Options{})
193 var log logr.Logger = funcr.New(noopKV, funcr.Options{})
169194 doWithCallDepth(b, log)
170195 }
+22
-0
funcr/example_test.go less more
2222 "github.com/go-logr/logr"
2323 "github.com/go-logr/logr/funcr"
2424 )
25
26 func ExampleNew() {
27 var log logr.Logger = funcr.New(func(prefix, args string) {
28 fmt.Println(prefix, args)
29 }, funcr.Options{})
30
31 log = log.WithName("MyLogger")
32 log = log.WithValues("savedKey", "savedValue")
33 log.Info("the message", "key", "value")
34 // Output: MyLogger "level"=0 "msg"="the message" "savedKey"="savedValue" "key"="value"
35 }
36
37 func ExampleNewJSON() {
38 var log logr.Logger = funcr.NewJSON(func(obj string) {
39 fmt.Println(obj)
40 }, funcr.Options{})
41
42 log = log.WithName("MyLogger")
43 log = log.WithValues("savedKey", "savedValue")
44 log.Info("the message", "key", "value")
45 // Output: {"logger":"MyLogger","level":0,"msg":"the message","savedKey":"savedValue","key":"value"}
46 }
2547
2648 func ExampleUnderlier() {
2749 var log logr.Logger = funcr.New(func(prefix, args string) {
+67
-9
funcr/funcr.go less more
4141
4242 // New returns a logr.Logger which is implemented by an arbitrary function.
4343 func New(fn func(prefix, args string), opts Options) logr.Logger {
44 return logr.New(newSink(fn, opts))
44 return logr.New(newSink(fn, NewFormatter(opts)))
45 }
46
47 // NewJSON returns a logr.Logger which is implemented by an arbitrary function
48 // and produces JSON output.
49 func NewJSON(fn func(obj string), opts Options) logr.Logger {
50 fnWrapper := func(_, obj string) {
51 fn(obj)
52 }
53 return logr.New(newSink(fnWrapper, NewFormatterJSON(opts)))
4554 }
4655
4756 // Underlier exposes access to the underlying logging function. Since
5261 GetUnderlying() func(prefix, args string)
5362 }
5463
55 func newSink(fn func(prefix, args string), opts Options) logr.LogSink {
64 func newSink(fn func(prefix, args string), formatter Formatter) logr.LogSink {
5665 l := &fnlogger{
57 Formatter: NewFormatter(opts),
66 Formatter: formatter,
5867 write: fn,
5968 }
6069 // For skipping fnlogger.Info and fnlogger.Error.
134143 var _ logr.CallDepthLogSink = &fnlogger{}
135144 var _ Underlier = &fnlogger{}
136145
137 // NewFormatter constructs a Formatter.
146 // NewFormatter constructs a Formatter which emits a JSON-like key=value format.
138147 func NewFormatter(opts Options) Formatter {
148 return newFormatter(opts, outputKeyValue)
149 }
150
151 // NewFormatterJSON constructs a Formatter which emits strict JSON.
152 func NewFormatterJSON(opts Options) Formatter {
153 return newFormatter(opts, outputJSON)
154 }
155
156 func newFormatter(opts Options, outfmt outputFormat) Formatter {
139157 f := Formatter{
158 outputFormat: outfmt,
140159 prefix: "",
141160 values: nil,
142161 depth: 0,
151170 // implementation. It should be constructed with NewFormatter. Some of
152171 // its methods directly implement logr.LogSink.
153172 type Formatter struct {
173 outputFormat outputFormat
154174 prefix string
155175 values []interface{}
156176 depth int
159179 verbosity int
160180 }
161181
182 // outputFormat indicates which outputFormat to use.
183 type outputFormat int
184
185 const (
186 // outputKeyValue emits a JSON-like key=value format, but not strict JSON.
187 outputKeyValue outputFormat = iota
188 // outputJSON emits strict JSON.
189 outputJSON
190 )
191
162192 func (f Formatter) flatten(kvList ...interface{}) string {
163193 if len(kvList)%2 != 0 {
164194 kvList = append(kvList, "<no-value>")
165195 }
166196 // Empirically bytes.Buffer is faster than strings.Builder for this.
167197 buf := bytes.NewBuffer(make([]byte, 0, 1024))
198 if f.outputFormat == outputJSON {
199 buf.WriteRune('{')
200 }
168201 for i := 0; i < len(kvList); i += 2 {
169202 k, ok := kvList[i].(string)
170203 if !ok {
173206 v := kvList[i+1]
174207
175208 if i > 0 {
176 buf.WriteRune(' ')
209 if f.outputFormat == outputJSON {
210 buf.WriteRune(',')
211 } else {
212 // In theory the format could be something we don't understand. In
213 // practice, we control it, so it won't
214 buf.WriteRune(' ')
215 }
177216 }
178217 buf.WriteRune('"')
179218 buf.WriteString(k)
180219 buf.WriteRune('"')
181 buf.WriteRune('=')
220 if f.outputFormat == outputJSON {
221 buf.WriteRune(':')
222 } else {
223 buf.WriteRune('=')
224 }
182225 buf.WriteString(f.pretty(v))
226 }
227 if f.outputFormat == outputJSON {
228 buf.WriteRune('}')
183229 }
184230 return buf.String()
185231 }
377423 }
378424
379425 // FormatInfo flattens an Info log message into strings.
380 // The prefix will be empty when no names were set.
426 // The prefix will be empty when no names were set, or when the output is
427 // configured for JSON.
381428 func (f Formatter) FormatInfo(level int, msg string, kvList []interface{}) (prefix, argsStr string) {
382429 args := make([]interface{}, 0, 64) // using a constant here impacts perf
430 prefix = f.prefix
431 if f.outputFormat == outputJSON {
432 args = append(args, "logger", prefix)
433 prefix = ""
434 }
383435 if f.logTimestamp {
384436 args = append(args, "ts", time.Now().Format(timestampFmt))
385437 }
389441 args = append(args, "level", level, "msg", msg)
390442 args = append(args, f.values...)
391443 args = append(args, kvList...)
392 return f.prefix, f.flatten(args...)
444 return prefix, f.flatten(args...)
393445 }
394446
395447 // FormatError flattens an Error log message into strings.
396 // The prefix will be empty when no names were set.
448 // The prefix will be empty when no names were set, or when the output is
449 // configured for JSON.
397450 func (f Formatter) FormatError(err error, msg string, kvList []interface{}) (prefix, argsStr string) {
398451 args := make([]interface{}, 0, 64) // using a constant here impacts perf
452 prefix = f.prefix
453 if f.outputFormat == outputJSON {
454 args = append(args, "logger", prefix)
455 prefix = ""
456 }
399457 if f.logTimestamp {
400458 args = append(args, "ts", time.Now().Format(timestampFmt))
401459 }
+60
-49
funcr/funcr_test.go less more
192192
193193 func TestFlatten(t *testing.T) {
194194 testCases := []struct {
195 name string
196 kv []interface{}
197 expect string
198 }{{
199 name: "nil",
200 kv: nil,
201 expect: "",
202 }, {
203 name: "empty",
204 kv: []interface{}{},
205 expect: "",
206 }, {
207 name: "primitives",
208 kv: makeKV("int", 1, "str", "ABC", "bool", true),
209 expect: `"int"=1 "str"="ABC" "bool"=true`,
210 }, {
211 name: "missing value",
212 kv: makeKV("key"),
213 expect: `"key"="<no-value>"`,
214 }, {
215 name: "non-string key",
216 kv: makeKV(123, "val"),
217 expect: `"<non-string-key-0>"="val"`,
218 }}
219
220 f := NewFormatter(Options{})
221 for _, tc := range testCases {
222 t.Run(tc.name, func(t *testing.T) {
223 r := f.flatten(tc.kv...)
224 if r != tc.expect {
225 t.Errorf("expected %q, got %q", tc.expect, r)
195 name string
196 kv []interface{}
197 expectKV string
198 expectJSON string
199 }{{
200 name: "nil",
201 kv: nil,
202 expectKV: "",
203 expectJSON: "{}",
204 }, {
205 name: "empty",
206 kv: []interface{}{},
207 expectKV: "",
208 expectJSON: "{}",
209 }, {
210 name: "primitives",
211 kv: makeKV("int", 1, "str", "ABC", "bool", true),
212 expectKV: `"int"=1 "str"="ABC" "bool"=true`,
213 expectJSON: `{"int":1,"str":"ABC","bool":true}`,
214 }, {
215 name: "missing value",
216 kv: makeKV("key"),
217 expectKV: `"key"="<no-value>"`,
218 expectJSON: `{"key":"<no-value>"}`,
219 }, {
220 name: "non-string key",
221 kv: makeKV(123, "val"),
222 expectKV: `"<non-string-key-0>"="val"`,
223 expectJSON: `{"<non-string-key-0>":"val"}`,
224 }}
225
226 fKV := NewFormatter(Options{})
227 fJSON := NewFormatterJSON(Options{})
228 for _, tc := range testCases {
229 t.Run(tc.name, func(t *testing.T) {
230 r := fKV.flatten(tc.kv...)
231 if r != tc.expectKV {
232 t.Errorf("expected %q, got %q", tc.expectKV, r)
233 }
234 r = fJSON.flatten(tc.kv...)
235 if r != tc.expectJSON {
236 t.Errorf("expected %q, got %q", tc.expectJSON, r)
226237 }
227238 })
228239 }
230241
231242 func TestEnabled(t *testing.T) {
232243 t.Run("default V", func(t *testing.T) {
233 log := newSink(func(prefix, args string) {}, Options{})
244 log := newSink(func(prefix, args string) {}, NewFormatter(Options{}))
234245 if !log.Enabled(0) {
235246 t.Errorf("expected true")
236247 }
239250 }
240251 })
241252 t.Run("V=9", func(t *testing.T) {
242 log := newSink(func(prefix, args string) {}, Options{Verbosity: 9})
253 log := newSink(func(prefix, args string) {}, NewFormatter(Options{Verbosity: 9}))
243254 if !log.Enabled(8) {
244255 t.Errorf("expected true")
245256 }
278289 for _, tc := range testCases {
279290 t.Run(tc.name, func(t *testing.T) {
280291 cap := &capture{}
281 sink := newSink(cap.Func, Options{})
292 sink := newSink(cap.Func, NewFormatter(Options{}))
282293 sink.Info(0, "msg", tc.args...)
283294 if cap.log != tc.expect {
284295 t.Errorf("\nexpected %q\n got %q", tc.expect, cap.log)
290301 func TestInfoWithCaller(t *testing.T) {
291302 t.Run("LogCaller=All", func(t *testing.T) {
292303 cap := &capture{}
293 sink := newSink(cap.Func, Options{LogCaller: All})
304 sink := newSink(cap.Func, NewFormatter(Options{LogCaller: All}))
294305 sink.Info(0, "msg")
295306 _, file, line, _ := runtime.Caller(0)
296307 expect := fmt.Sprintf(` "caller"={"file":%q,"line":%d} "level"=0 "msg"="msg"`, filepath.Base(file), line-1)
300311 })
301312 t.Run("LogCaller=Info", func(t *testing.T) {
302313 cap := &capture{}
303 sink := newSink(cap.Func, Options{LogCaller: Info})
314 sink := newSink(cap.Func, NewFormatter(Options{LogCaller: Info}))
304315 sink.Info(0, "msg")
305316 _, file, line, _ := runtime.Caller(0)
306317 expect := fmt.Sprintf(` "caller"={"file":%q,"line":%d} "level"=0 "msg"="msg"`, filepath.Base(file), line-1)
310321 })
311322 t.Run("LogCaller=Error", func(t *testing.T) {
312323 cap := &capture{}
313 sink := newSink(cap.Func, Options{LogCaller: Error})
324 sink := newSink(cap.Func, NewFormatter(Options{LogCaller: Error}))
314325 sink.Info(0, "msg")
315326 expect := ` "level"=0 "msg"="msg"`
316327 if cap.log != expect {
319330 })
320331 t.Run("LogCaller=None", func(t *testing.T) {
321332 cap := &capture{}
322 sink := newSink(cap.Func, Options{LogCaller: None})
333 sink := newSink(cap.Func, NewFormatter(Options{LogCaller: None}))
323334 sink.Info(0, "msg")
324335 expect := ` "level"=0 "msg"="msg"`
325336 if cap.log != expect {
346357 for _, tc := range testCases {
347358 t.Run(tc.name, func(t *testing.T) {
348359 cap := &capture{}
349 sink := newSink(cap.Func, Options{})
360 sink := newSink(cap.Func, NewFormatter(Options{}))
350361 sink.Error(fmt.Errorf("err"), "msg", tc.args...)
351362 if cap.log != tc.expect {
352363 t.Errorf("\nexpected %q\n got %q", tc.expect, cap.log)
358369 func TestErrorWithCaller(t *testing.T) {
359370 t.Run("LogCaller=All", func(t *testing.T) {
360371 cap := &capture{}
361 sink := newSink(cap.Func, Options{LogCaller: All})
372 sink := newSink(cap.Func, NewFormatter(Options{LogCaller: All}))
362373 sink.Error(fmt.Errorf("err"), "msg")
363374 _, file, line, _ := runtime.Caller(0)
364375 expect := fmt.Sprintf(` "caller"={"file":%q,"line":%d} "msg"="msg" "error"="err"`, filepath.Base(file), line-1)
368379 })
369380 t.Run("LogCaller=Error", func(t *testing.T) {
370381 cap := &capture{}
371 sink := newSink(cap.Func, Options{LogCaller: Error})
382 sink := newSink(cap.Func, NewFormatter(Options{LogCaller: Error}))
372383 sink.Error(fmt.Errorf("err"), "msg")
373384 _, file, line, _ := runtime.Caller(0)
374385 expect := fmt.Sprintf(` "caller"={"file":%q,"line":%d} "msg"="msg" "error"="err"`, filepath.Base(file), line-1)
378389 })
379390 t.Run("LogCaller=Info", func(t *testing.T) {
380391 cap := &capture{}
381 sink := newSink(cap.Func, Options{LogCaller: Info})
392 sink := newSink(cap.Func, NewFormatter(Options{LogCaller: Info}))
382393 sink.Error(fmt.Errorf("err"), "msg")
383394 expect := ` "msg"="msg" "error"="err"`
384395 if cap.log != expect {
387398 })
388399 t.Run("LogCaller=None", func(t *testing.T) {
389400 cap := &capture{}
390 sink := newSink(cap.Func, Options{LogCaller: None})
401 sink := newSink(cap.Func, NewFormatter(Options{LogCaller: None}))
391402 sink.Error(fmt.Errorf("err"), "msg")
392403 expect := ` "msg"="msg" "error"="err"`
393404 if cap.log != expect {
417428 for _, tc := range testCases {
418429 t.Run(tc.name, func(t *testing.T) {
419430 cap := &capture{}
420 sink := newSink(cap.Func, Options{})
431 sink := newSink(cap.Func, NewFormatter(Options{}))
421432 for _, n := range tc.names {
422433 sink = sink.WithName(n)
423434 }
450461 for _, tc := range testCases {
451462 t.Run(tc.name, func(t *testing.T) {
452463 cap := &capture{}
453 sink := newSink(cap.Func, Options{})
464 sink := newSink(cap.Func, NewFormatter(Options{}))
454465 for _, n := range tc.names {
455466 sink = sink.WithName(n)
456467 }
488499 for _, tc := range testCases {
489500 t.Run(tc.name, func(t *testing.T) {
490501 cap := &capture{}
491 sink := newSink(cap.Func, Options{})
502 sink := newSink(cap.Func, NewFormatter(Options{}))
492503 sink = sink.WithValues(tc.values...)
493504 sink.Info(0, "msg", tc.args...)
494505 if cap.log != tc.expect {
524535 for _, tc := range testCases {
525536 t.Run(tc.name, func(t *testing.T) {
526537 cap := &capture{}
527 sink := newSink(cap.Func, Options{})
538 sink := newSink(cap.Func, NewFormatter(Options{}))
528539 sink = sink.WithValues(tc.values...)
529540 sink.Error(fmt.Errorf("err"), "msg", tc.args...)
530541 if cap.log != tc.expect {
537548 func TestInfoWithCallDepth(t *testing.T) {
538549 t.Run("one", func(t *testing.T) {
539550 cap := &capture{}
540 sink := newSink(cap.Func, Options{LogCaller: All})
551 sink := newSink(cap.Func, NewFormatter(Options{LogCaller: All}))
541552 dSink, _ := sink.(logr.CallDepthLogSink)
542553 sink = dSink.WithCallDepth(1)
543554 sink.Info(0, "msg")
552563 func TestErrorWithCallDepth(t *testing.T) {
553564 t.Run("one", func(t *testing.T) {
554565 cap := &capture{}
555 sink := newSink(cap.Func, Options{LogCaller: All})
566 sink := newSink(cap.Func, NewFormatter(Options{LogCaller: All}))
556567 dSink, _ := sink.(logr.CallDepthLogSink)
557568 sink = dSink.WithCallDepth(1)
558569 sink.Error(fmt.Errorf("err"), "msg")