Merge pull request #92 from go-kit/no-log-panics
No log panics.
Chris Hines
8 years ago
3 | 3 | "encoding/json" |
4 | 4 | "fmt" |
5 | 5 | "io" |
6 | "reflect" | |
6 | 7 | ) |
7 | 8 | |
8 | 9 | type jsonLogger struct { |
16 | 17 | } |
17 | 18 | |
18 | 19 | func (l *jsonLogger) Log(keyvals ...interface{}) error { |
19 | if len(keyvals)%2 == 1 { | |
20 | panic("odd number of keyvals") | |
21 | } | |
22 | m := make(map[string]interface{}, len(keyvals)/2) | |
20 | n := (len(keyvals) + 1) / 2 // +1 to handle case when len is odd | |
21 | m := make(map[string]interface{}, n) | |
23 | 22 | for i := 0; i < len(keyvals); i += 2 { |
24 | merge(m, keyvals[i], keyvals[i+1]) | |
23 | k := keyvals[i] | |
24 | var v interface{} = ErrMissingValue | |
25 | if i+1 < len(keyvals) { | |
26 | v = keyvals[i+1] | |
27 | } | |
28 | merge(m, k, v) | |
25 | 29 | } |
26 | 30 | return json.NewEncoder(l.Writer).Encode(m) |
27 | 31 | } |
28 | 32 | |
29 | func merge(dst map[string]interface{}, k, v interface{}) map[string]interface{} { | |
33 | func merge(dst map[string]interface{}, k, v interface{}) { | |
30 | 34 | var key string |
31 | 35 | switch x := k.(type) { |
32 | 36 | case string: |
33 | 37 | key = x |
34 | 38 | case fmt.Stringer: |
35 | key = x.String() | |
39 | key = safeString(x) | |
36 | 40 | default: |
37 | key = fmt.Sprintf("%v", x) | |
41 | key = fmt.Sprint(x) | |
38 | 42 | } |
39 | 43 | if x, ok := v.(error); ok { |
40 | v = x.Error() | |
44 | v = safeError(x) | |
41 | 45 | } |
42 | 46 | dst[key] = v |
43 | return dst | |
44 | 47 | } |
48 | ||
49 | func safeString(str fmt.Stringer) (s string) { | |
50 | defer func() { | |
51 | if panicVal := recover(); panicVal != nil { | |
52 | if v := reflect.ValueOf(str); v.Kind() == reflect.Ptr && v.IsNil() { | |
53 | s = "NULL" | |
54 | } else { | |
55 | panic(panicVal) | |
56 | } | |
57 | } | |
58 | }() | |
59 | s = str.String() | |
60 | return | |
61 | } | |
62 | ||
63 | func safeError(err error) (s interface{}) { | |
64 | defer func() { | |
65 | if panicVal := recover(); panicVal != nil { | |
66 | if v := reflect.ValueOf(err); v.Kind() == reflect.Ptr && v.IsNil() { | |
67 | s = nil | |
68 | } else { | |
69 | panic(panicVal) | |
70 | } | |
71 | } | |
72 | }() | |
73 | s = err.Error() | |
74 | return | |
75 | } |
9 | 9 | ) |
10 | 10 | |
11 | 11 | func TestJSONLogger(t *testing.T) { |
12 | t.Parallel() | |
12 | 13 | buf := &bytes.Buffer{} |
13 | 14 | logger := log.NewJSONLogger(buf) |
14 | 15 | if err := logger.Log("err", errors.New("err"), "m", map[string]int{"0": 0}, "a", []int{1, 2, 3}); err != nil { |
15 | 16 | t.Fatal(err) |
16 | 17 | } |
17 | 18 | if want, have := `{"a":[1,2,3],"err":"err","m":{"0":0}}`+"\n", buf.String(); want != have { |
18 | t.Errorf("want %#v, have %#v", want, have) | |
19 | t.Errorf("\nwant %#v\nhave %#v", want, have) | |
19 | 20 | } |
21 | } | |
22 | ||
23 | func TestJSONLoggerMissingValue(t *testing.T) { | |
24 | t.Parallel() | |
25 | buf := &bytes.Buffer{} | |
26 | logger := log.NewJSONLogger(buf) | |
27 | if err := logger.Log("k"); err != nil { | |
28 | t.Fatal(err) | |
29 | } | |
30 | if want, have := `{"k":"(MISSING)"}`+"\n", buf.String(); want != have { | |
31 | t.Errorf("\nwant %#v\nhave %#v", want, have) | |
32 | } | |
33 | } | |
34 | ||
35 | func TestJSONLoggerNilStringerKey(t *testing.T) { | |
36 | t.Parallel() | |
37 | ||
38 | buf := &bytes.Buffer{} | |
39 | logger := log.NewJSONLogger(buf) | |
40 | if err := logger.Log((*stringer)(nil), "v"); err != nil { | |
41 | t.Fatal(err) | |
42 | } | |
43 | if want, have := `{"NULL":"v"}`+"\n", buf.String(); want != have { | |
44 | t.Errorf("\nwant %#v\nhave %#v", want, have) | |
45 | } | |
46 | } | |
47 | ||
48 | func TestJSONLoggerNilErrorValue(t *testing.T) { | |
49 | t.Parallel() | |
50 | ||
51 | buf := &bytes.Buffer{} | |
52 | logger := log.NewJSONLogger(buf) | |
53 | if err := logger.Log("err", (*stringError)(nil)); err != nil { | |
54 | t.Fatal(err) | |
55 | } | |
56 | if want, have := `{"err":null}`+"\n", buf.String(); want != have { | |
57 | t.Errorf("\nwant %#v\nhave %#v", want, have) | |
58 | } | |
59 | } | |
60 | ||
61 | type stringer string | |
62 | ||
63 | func (s stringer) String() string { | |
64 | return string(s) | |
65 | } | |
66 | ||
67 | type stringError string | |
68 | ||
69 | func (s stringError) Error() string { | |
70 | return string(s) | |
20 | 71 | } |
21 | 72 | |
22 | 73 | func BenchmarkJSONLoggerSimple(b *testing.B) { |
3 | 3 | // key/value data. |
4 | 4 | package log |
5 | 5 | |
6 | import "sync/atomic" | |
6 | import ( | |
7 | "errors" | |
8 | "sync/atomic" | |
9 | ) | |
7 | 10 | |
8 | 11 | // Logger is the fundamental interface for all log operations. Log creates a |
9 | 12 | // log event from keyvals, a variadic sequence of alternating keys and values. |
13 | 16 | type Logger interface { |
14 | 17 | Log(keyvals ...interface{}) error |
15 | 18 | } |
19 | ||
20 | // ErrMissingValue is appended to keyvals slices with odd length to substitute | |
21 | // the missing value. | |
22 | var ErrMissingValue = errors.New("(MISSING)") | |
16 | 23 | |
17 | 24 | // NewContext returns a new Context that logs to logger. |
18 | 25 | func NewContext(logger Logger) Context { |
36 | 43 | // stored context with their generated value, appends keyvals, and passes the |
37 | 44 | // result to the wrapped Logger. |
38 | 45 | func (l Context) Log(keyvals ...interface{}) error { |
39 | if len(keyvals)%2 != 0 { | |
40 | panic("bad keyvals") | |
46 | kvs := append(l.keyvals, keyvals...) | |
47 | if len(kvs)%2 != 0 { | |
48 | kvs = append(kvs, ErrMissingValue) | |
41 | 49 | } |
42 | kvs := append(l.keyvals, keyvals...) | |
43 | 50 | if l.hasValuer { |
44 | 51 | // If no keyvals were appended above then we must copy l.keyvals so |
45 | 52 | // that future log events will reevaluate the stored Valuers. |
56 | 63 | if len(keyvals) == 0 { |
57 | 64 | return l |
58 | 65 | } |
59 | if len(keyvals)%2 != 0 { | |
60 | panic("bad keyvals") | |
66 | kvs := append(l.keyvals, keyvals...) | |
67 | if len(kvs)%2 != 0 { | |
68 | kvs = append(kvs, ErrMissingValue) | |
61 | 69 | } |
62 | // Limiting the capacity of the stored keyvals ensures that a new | |
63 | // backing array is created if the slice must grow in Log or With. | |
64 | // Using the extra capacity without copying risks a data race that | |
65 | // would violate the Logger interface contract. | |
66 | n := len(l.keyvals) + len(keyvals) | |
67 | 70 | return Context{ |
68 | logger: l.logger, | |
69 | keyvals: append(l.keyvals, keyvals...)[:n:n], | |
71 | logger: l.logger, | |
72 | // Limiting the capacity of the stored keyvals ensures that a new | |
73 | // backing array is created if the slice must grow in Log or With. | |
74 | // Using the extra capacity without copying risks a data race that | |
75 | // would violate the Logger interface contract. | |
76 | keyvals: kvs[:len(kvs):len(kvs)], | |
70 | 77 | hasValuer: l.hasValuer || containsValuer(keyvals), |
71 | 78 | } |
72 | 79 | } |
77 | 84 | if len(keyvals) == 0 { |
78 | 85 | return l |
79 | 86 | } |
80 | if len(keyvals)%2 != 0 { | |
81 | panic("bad keyvals") | |
82 | } | |
83 | 87 | // Limiting the capacity of the stored keyvals ensures that a new |
84 | 88 | // backing array is created if the slice must grow in Log or With. |
85 | 89 | // Using the extra capacity without copying risks a data race that |
86 | 90 | // would violate the Logger interface contract. |
87 | 91 | n := len(l.keyvals) + len(keyvals) |
92 | if len(keyvals)%2 != 0 { | |
93 | n++ | |
94 | } | |
88 | 95 | kvs := make([]interface{}, 0, n) |
89 | 96 | kvs = append(kvs, keyvals...) |
97 | if len(kvs)%2 != 0 { | |
98 | kvs = append(kvs, ErrMissingValue) | |
99 | } | |
90 | 100 | kvs = append(kvs, l.keyvals...) |
91 | 101 | return Context{ |
92 | 102 | logger: l.logger, |
10 | 10 | var discard = log.Logger(log.LoggerFunc(func(...interface{}) error { return nil })) |
11 | 11 | |
12 | 12 | func TestContext(t *testing.T) { |
13 | t.Parallel() | |
13 | 14 | buf := &bytes.Buffer{} |
14 | 15 | logger := log.NewLogfmtLogger(buf) |
15 | 16 | |
35 | 36 | } |
36 | 37 | } |
37 | 38 | |
38 | func TestContextWithPrefix(t *testing.T) { | |
39 | buf := &bytes.Buffer{} | |
40 | kvs := []interface{}{"a", 123} | |
41 | logger := log.NewJSONLogger(buf) | |
42 | lc := log.NewContext(logger).With(kvs...) | |
43 | kvs[1] = 0 // WithPrefix should copy its key values | |
44 | lc = lc.With("b", "c") // WithPrefix should stack | |
45 | if err := lc.Log("msg", "message"); err != nil { | |
46 | t.Fatal(err) | |
47 | } | |
48 | if want, have := `{"a":123,"b":"c","msg":"message"}`+"\n", buf.String(); want != have { | |
49 | t.Errorf("\nwant: %s\nhave: %s", want, have) | |
39 | func TestContextMissingValue(t *testing.T) { | |
40 | t.Parallel() | |
41 | var output []interface{} | |
42 | logger := log.Logger(log.LoggerFunc(func(keyvals ...interface{}) error { | |
43 | output = keyvals | |
44 | return nil | |
45 | })) | |
46 | ||
47 | lc := log.NewContext(logger) | |
48 | ||
49 | lc.Log("k") | |
50 | if want, have := 2, len(output); want != have { | |
51 | t.Errorf("want len(output) == %v, have %v", want, have) | |
52 | } | |
53 | if want, have := log.ErrMissingValue, output[1]; want != have { | |
54 | t.Errorf("want %#v, have %#v", want, have) | |
55 | } | |
56 | ||
57 | lc.With("k1").WithPrefix("k0").Log("k2") | |
58 | if want, have := 6, len(output); want != have { | |
59 | t.Errorf("want len(output) == %v, have %v", want, have) | |
60 | } | |
61 | for i := 1; i < 6; i += 2 { | |
62 | if want, have := log.ErrMissingValue, output[i]; want != have { | |
63 | t.Errorf("want output[%d] == %#v, have %#v", i, want, have) | |
64 | } | |
50 | 65 | } |
51 | 66 | } |
52 | 67 |