Codebase list golang-github-go-kit-kit / d4d79f9
Take care that log.Context.Log has a consistent function stack depth when binding log.Valuers. The stack depth must be consistent regardless of how many times Context.With has been called or whether Context.Log is called via an interface typed variable or a concrete typed variable. Chris Hines 8 years ago
3 changed file(s) with 98 addition(s) and 9 deletion(s). Raw diff Collapse all Expand all
+1
-1
log/levels/levels.go less more
66 // want a different set of levels, you can create your own levels type very
77 // easily, and you can elide the configuration.
88 type Levels struct {
9 ctx log.Context
9 ctx *log.Context
1010 levelKey string
1111
1212 // We have a choice between storing level values in string fields or
+42
-8
log/log.go less more
2222 var ErrMissingValue = errors.New("(MISSING)")
2323
2424 // NewContext returns a new Context that logs to logger.
25 func NewContext(logger Logger) Context {
26 if c, ok := logger.(Context); ok {
25 func NewContext(logger Logger) *Context {
26 if c, ok := logger.(*Context); ok {
2727 return c
2828 }
29 return Context{logger: logger}
29 return &Context{logger: logger}
3030 }
31
32 // Context must always have the same number of stack frames between calls to
33 // its Log method and the eventual binding of Valuers to their value. This
34 // requirement comes from the functional requirement to allow a context to
35 // resolve application call site information for a log.Caller stored in the
36 // context. To do this we must be able to predict the number of logging
37 // functions on the stack when bindValues is called.
38 //
39 // Three implementation details provide the needed stack depth consistency.
40 // The first two of these details also result in better amortized performance,
41 // and thus make sense even without the requirements regarding stack depth.
42 // The third detail, however, is subtle and tied to the implementation of the
43 // Go compiler.
44 //
45 // 1. NewContext avoids introducing an additional layer when asked to
46 // wrap another Context.
47 // 2. With avoids introducing an additional layer by returning a newly
48 // constructed Context with a merged keyvals rather than simply
49 // wrapping the existing Context.
50 // 3. All of Context's methods take pointer receivers even though they
51 // do not mutate the Context.
52 //
53 // Before explaining the last detail, first some background. The Go compiler
54 // generates wrapper methods to implement the auto dereferencing behavior when
55 // calling a value method through a pointer variable. These wrapper methods
56 // are also used when calling a value method through an interface variable
57 // because interfaces store a pointer to the underlying concrete value.
58 // Calling a pointer receiver through an interface does not require generating
59 // an additional function.
60 //
61 // If Context had value methods then calling Context.Log through a variable
62 // with type Logger would have an extra stack frame compared to calling
63 // Context.Log through a variable with type Context. Using pointer receivers
64 // avoids this problem.
3165
3266 // A Context wraps a Logger and holds keyvals that it includes in all log
3367 // events. When logging, a Context replaces all value elements (odd indexes)
4276 // Log replaces all value elements (odd indexes) containing a Valuer in the
4377 // stored context with their generated value, appends keyvals, and passes the
4478 // result to the wrapped Logger.
45 func (l Context) Log(keyvals ...interface{}) error {
79 func (l *Context) Log(keyvals ...interface{}) error {
4680 kvs := append(l.keyvals, keyvals...)
4781 if len(kvs)%2 != 0 {
4882 kvs = append(kvs, ErrMissingValue)
5993 }
6094
6195 // With returns a new Context with keyvals appended to those of the receiver.
62 func (l Context) With(keyvals ...interface{}) Context {
96 func (l *Context) With(keyvals ...interface{}) *Context {
6397 if len(keyvals) == 0 {
6498 return l
6599 }
67101 if len(kvs)%2 != 0 {
68102 kvs = append(kvs, ErrMissingValue)
69103 }
70 return Context{
104 return &Context{
71105 logger: l.logger,
72106 // Limiting the capacity of the stored keyvals ensures that a new
73107 // backing array is created if the slice must grow in Log or With.
80114
81115 // WithPrefix returns a new Context with keyvals prepended to those of the
82116 // receiver.
83 func (l Context) WithPrefix(keyvals ...interface{}) Context {
117 func (l *Context) WithPrefix(keyvals ...interface{}) *Context {
84118 if len(keyvals) == 0 {
85119 return l
86120 }
98132 kvs = append(kvs, ErrMissingValue)
99133 }
100134 kvs = append(kvs, l.keyvals...)
101 return Context{
135 return &Context{
102136 logger: l.logger,
103137 keyvals: kvs,
104138 hasValuer: l.hasValuer || containsValuer(keyvals),
+55
-0
log/log_test.go less more
11
22 import (
33 "bytes"
4 "fmt"
45 "sync"
56 "testing"
67
78 "github.com/go-kit/kit/log"
9 "gopkg.in/stack.v1"
810 )
911
1012 func TestContext(t *testing.T) {
6062 if want, have := log.ErrMissingValue, output[i]; want != have {
6163 t.Errorf("want output[%d] == %#v, have %#v", i, want, have)
6264 }
65 }
66 }
67
68 // Test that Context.Log has a consistent function stack depth when binding
69 // log.Valuers, regardless of how many times Context.With has been called or
70 // whether Context.Log is called via an interface typed variable or a concrete
71 // typed variable.
72 func TestContextStackDepth(t *testing.T) {
73 fn := fmt.Sprintf("%n", stack.Caller(0))
74
75 var output []interface{}
76
77 logger := log.Logger(log.LoggerFunc(func(keyvals ...interface{}) error {
78 output = keyvals
79 return nil
80 }))
81
82 stackValuer := log.Valuer(func() interface{} {
83 for i, c := range stack.Trace() {
84 if fmt.Sprintf("%n", c) == fn {
85 return i
86 }
87 }
88 t.Fatal("Test function not found in stack trace.")
89 return nil
90 })
91
92 concrete := log.NewContext(logger).With("stack", stackValuer)
93 var iface log.Logger = concrete
94
95 // Call through interface to get baseline.
96 iface.Log("k", "v")
97 want := output[1].(int)
98
99 for len(output) < 10 {
100 concrete.Log("k", "v")
101 if have := output[1]; have != want {
102 t.Errorf("%d Withs: have %v, want %v", len(output)/2-1, have, want)
103 }
104
105 iface.Log("k", "v")
106 if have := output[1]; have != want {
107 t.Errorf("%d Withs: have %v, want %v", len(output)/2-1, have, want)
108 }
109
110 wrapped := log.NewContext(concrete)
111 wrapped.Log("k", "v")
112 if have := output[1]; have != want {
113 t.Errorf("%d Withs: have %v, want %v", len(output)/2-1, have, want)
114 }
115
116 concrete = concrete.With("k", "v")
117 iface = concrete
63118 }
64119 }
65120