Package list golang-github-go-kit-kit / ee7b7bb
log: Update docs to reflect unexporting context and newContext. This update also contains a few other minor documentation updates. Chris Hines 4 years ago
6 changed file(s) with 131 addition(s) and 141 deletion(s). Raw diff Collapse all Expand all
00 # package log
11
22 `package log` provides a minimal interface for structured logging in services.
3 It may be wrapped to encode conventions, enforce type-safety, provide leveled logging, and so on.
4 It can be used for both typical application log events, and log-structured data streams.
3 It may be wrapped to encode conventions, enforce type-safety, provide leveled
4 logging, and so on. It can be used for both typical application log events,
5 and log-structured data streams.
56
67 ## Structured logging
78
8 Structured logging is, basically, conceding to the reality that logs are _data_,
9 and warrant some level of schematic rigor.
10 Using a stricter, key/value-oriented message format for our logs,
11 containing contextual and semantic information,
12 makes it much easier to get insight into the operational activity of the systems we build.
13 Consequently, `package log` is of the strong belief that
14 "[the benefits of structured logging outweigh the minimal effort involved](https://www.thoughtworks.com/radar/techniques/structured-logging)".
9 Structured logging is, basically, conceding to the reality that logs are
10 _data_, and warrant some level of schematic rigor. Using a stricter,
11 key/value-oriented message format for our logs, containing contextual and
12 semantic information, makes it much easier to get insight into the
13 operational activity of the systems we build. Consequently, `package log` is
14 of the strong belief that "[the benefits of structured logging outweigh the
15 minimal effort involved](https://www.thoughtworks.com/radar/techniques/structured-logging)".
1516
16 Migrating from unstructured to structured logging is probably a lot easier than you'd expect.
17 Migrating from unstructured to structured logging is probably a lot easier
18 than you'd expect.
1719
1820 ```go
1921 // Unstructured
3638 // question="what is the meaning of life?" answer=42
3739 ```
3840
39 ### Log contexts
41 ### Contextual Loggers
4042
4143 ```go
4244 func main() {
4345 var logger log.Logger
4446 logger = log.NewLogfmtLogger(log.NewSyncWriter(os.Stderr))
45 logger = log.NewContext(logger).With("instance_id", 123)
47 logger = log.With(logger, "instance_id", 123)
4648
4749 logger.Log("msg", "starting")
48 NewWorker(log.NewContext(logger).With("component", "worker")).Run()
49 NewSlacker(log.NewContext(logger).With("component", "slacker")).Run()
50 NewWorker(log.With(logger, "component", "worker")).Run()
51 NewSlacker(log.With(logger, "component", "slacker")).Run()
5052 }
5153
5254 // Output:
7678 // {"msg":"I sure like pie","ts":"2016/01/01 12:34:56"}
7779 ```
7880
79 Or, if, for legacy reasons,
80 you need to pipe all of your logging through the stdlib log package,
81 you can redirect Go kit logger to the stdlib logger.
81 Or, if, for legacy reasons, you need to pipe all of your logging through the
82 stdlib log package, you can redirect Go kit logger to the stdlib logger.
8283
8384 ```go
8485 logger := kitlog.NewLogfmtLogger(kitlog.StdlibWriter{})
9394 ```go
9495 var logger log.Logger
9596 logger = log.NewLogfmtLogger(log.NewSyncWriter(os.Stderr))
96 logger = log.NewContext(logger).With("ts", log.DefaultTimestampUTC, "caller", log.DefaultCaller)
97 logger = log.With(logger, "ts", log.DefaultTimestampUTC, "caller", log.DefaultCaller)
9798
9899 logger.Log("msg", "hello")
99100
103104
104105 ## Supported output formats
105106
106 - [Logfmt](https://brandur.org/logfmt)
107 - [Logfmt](https://brandur.org/logfmt) ([see also](https://blog.codeship.com/logfmt-a-log-format-thats-easy-to-read-and-write))
107108 - JSON
108109
109110 ## Enhancements
116117 }
117118 ```
118119
119 This interface, and its supporting code like [log.Context](https://godoc.org/github.com/go-kit/kit/log#Context),
120 is the product of much iteration and evaluation.
121 For more details on the evolution of the Logger interface,
122 see [The Hunt for a Logger Interface](http://go-talks.appspot.com/github.com/ChrisHines/talks/structured-logging/structured-logging.slide#1),
123 a talk by [Chris Hines](https://github.com/ChrisHines).
120 This interface, and its supporting code like is the product of much iteration
121 and evaluation. For more details on the evolution of the Logger interface,
122 see [The Hunt for a Logger Interface](http://go-talks.appspot.com/github.com/ChrisHines/talks/structured-logging/structured-logging.slide#1),
123 a talk by [Chris Hines](https://github.com/ChrisHines).
124124 Also, please see
125 [#63](https://github.com/go-kit/kit/issues/63),
126 [#76](https://github.com/go-kit/kit/pull/76),
127 [#131](https://github.com/go-kit/kit/issues/131),
128 [#157](https://github.com/go-kit/kit/pull/157),
129 [#164](https://github.com/go-kit/kit/issues/164), and
130 [#252](https://github.com/go-kit/kit/pull/252)
131 to review historical conversations about package log and the Logger interface.
125 [#63](https://github.com/go-kit/kit/issues/63),
126 [#76](https://github.com/go-kit/kit/pull/76),
127 [#131](https://github.com/go-kit/kit/issues/131),
128 [#157](https://github.com/go-kit/kit/pull/157),
129 [#164](https://github.com/go-kit/kit/issues/164), and
130 [#252](https://github.com/go-kit/kit/pull/252)
131 to review historical conversations about package log and the Logger interface.
132132
133133 Value-add packages and suggestions,
134 like improvements to [the leveled logger](https://godoc.org/github.com/go-kit/kit/log/levels),
135 are of course welcome.
136 Good proposals should
134 like improvements to [the leveled logger](https://godoc.org/github.com/go-kit/kit/log/level),
135 are of course welcome. Good proposals should
137136
138 - Be composable with [log.Context](https://godoc.org/github.com/go-kit/kit/log#Context),
139 - Not break the behavior of [log.Caller](https://godoc.org/github.com/go-kit/kit/log#Caller) in any wrapped context, and
137 - Be composable with [contextual loggers](https://godoc.org/github.com/go-kit/kit/log#With),
138 - Not break the behavior of [log.Caller](https://godoc.org/github.com/go-kit/kit/log#Caller) in any wrapped contextual loggers, and
140139 - Be friendly to packages that accept only an unadorned log.Logger.
141140
142141 ## Benchmarks & comparisons
3434 // idea to log simple values without formatting them. This practice allows
3535 // the chosen logger to encode values in the most appropriate way.
3636 //
37 // Log Context
37 // Contextual Loggers
3838 //
39 // A log context stores keyvals that it includes in all log events. Building
40 // appropriate log contexts reduces repetition and aids consistency in the
41 // resulting log output. We can use a context to improve the RunTask example.
39 // A contextual logger stores keyvals that it includes in all log events.
40 // Building appropriate contextual loggers reduces repetition and aids
41 // consistency in the resulting log output. With and WithPrefix add context to
42 // a logger. We can use With to improve the RunTask example.
4243 //
4344 // func RunTask(task Task, logger log.Logger) string {
4445 // logger = log.With(logger, "taskID", task.ID)
5051 // }
5152 //
5253 // The improved version emits the same log events as the original for the
53 // first and last calls to Log. The call to taskHelper highlights that a
54 // context may be passed as a logger to other functions. Each log event
55 // created by the called function will include the task.ID even though the
56 // function does not have access to that value. Using log contexts this way
57 // simplifies producing log output that enables tracing the life cycle of
58 // individual tasks. (See the Context example for the full code of the
59 // above snippet.)
54 // first and last calls to Log. Passing the contextual logger to taskHelper
55 // enables each log event created by taskHelper to include the task.ID even
56 // though taskHelper does not have access to that value. Using contextual
57 // loggers this way simplifies producing log output that enables tracing the
58 // life cycle of individual tasks. (See the Contextual example for the full
59 // code of the above snippet.)
6060 //
61 // Dynamic Context Values
61 // Dynamic Contextual Values
6262 //
63 // A Valuer function stored in a log context generates a new value each time
64 // the context logs an event. The Valuer example demonstrates how this
65 // feature works.
63 // A Valuer function stored in a contextual logger generates a new value each
64 // time an event is logged. The Valuer example demonstrates how this feature
65 // works.
6666 //
6767 // Valuers provide the basis for consistently logging timestamps and source
6868 // code location. The log package defines several valuers for that purpose.
2828 // taskID=1 event="task complete"
2929 }
3030
31 func Example_context() {
31 func Example_contextual() {
3232 logger := log.NewLogfmtLogger(os.Stdout)
3333
3434 type Task struct {
55 // log event from keyvals, a variadic sequence of alternating keys and values.
66 // Implementations must be safe for concurrent use by multiple goroutines. In
77 // particular, any implementation of Logger that appends to keyvals or
8 // modifies any of its elements must make a copy first.
8 // modifies or retains any of its elements must make a copy first.
99 type Logger interface {
1010 Log(keyvals ...interface{}) error
1111 }
1414 // the missing value.
1515 var ErrMissingValue = errors.New("(MISSING)")
1616
17 // newContext returns a new context that logs to logger.
18 func newContext(logger Logger) *context {
19 if c, ok := logger.(*context); ok {
20 return c
21 }
22 return &context{logger: logger}
23 }
24
25 // Context must always have the same number of stack frames between calls to
26 // its Log method and the eventual binding of Valuers to their value. This
27 // requirement comes from the functional requirement to allow a context to
28 // resolve application call site information for a log.Caller stored in the
29 // context. To do this we must be able to predict the number of logging
30 // functions on the stack when bindValues is called.
17 // With returns a new contextual logger with keyvals prepended to those passed
18 // to calls to Log. If logger is also a contextual logger created by With or
19 // WithPrefix, keyvals is appended to the existing context.
3120 //
32 // Three implementation details provide the needed stack depth consistency.
33 // The first two of these details also result in better amortized performance,
34 // and thus make sense even without the requirements regarding stack depth.
35 // The third detail, however, is subtle and tied to the implementation of the
36 // Go compiler.
37 //
38 // 1. NewContext avoids introducing an additional layer when asked to
39 // wrap another Context.
40 // 2. With avoids introducing an additional layer by returning a newly
41 // constructed Context with a merged keyvals rather than simply
42 // wrapping the existing Context.
43 // 3. All of Context's methods take pointer receivers even though they
44 // do not mutate the Context.
45 //
46 // Before explaining the last detail, first some background. The Go compiler
47 // generates wrapper methods to implement the auto dereferencing behavior when
48 // calling a value method through a pointer variable. These wrapper methods
49 // are also used when calling a value method through an interface variable
50 // because interfaces store a pointer to the underlying concrete value.
51 // Calling a pointer receiver through an interface does not require generating
52 // an additional function.
53 //
54 // If Context had value methods then calling Context.Log through a variable
55 // with type Logger would have an extra stack frame compared to calling
56 // Context.Log through a variable with type Context. Using pointer receivers
57 // avoids this problem.
58
59 // A context wraps a Logger and holds keyvals that it includes in all log
60 // events. When logging, a context replaces all value elements (odd indexes)
61 // containing a Valuer with their generated value for each call to its Log
62 // method.
63 type context struct {
64 logger Logger
65 keyvals []interface{}
66 hasValuer bool
67 }
68
69 // Log replaces all value elements (odd indexes) containing a Valuer in the
70 // stored context with their generated value, appends keyvals, and passes the
71 // result to the wrapped Logger.
72 func (l *context) Log(keyvals ...interface{}) error {
73 kvs := append(l.keyvals, keyvals...)
74 if len(kvs)%2 != 0 {
75 kvs = append(kvs, ErrMissingValue)
76 }
77 if l.hasValuer {
78 // If no keyvals were appended above then we must copy l.keyvals so
79 // that future log events will reevaluate the stored Valuers.
80 if len(keyvals) == 0 {
81 kvs = append([]interface{}{}, l.keyvals...)
82 }
83 bindValues(kvs[:len(l.keyvals)])
84 }
85 return l.logger.Log(kvs...)
86 }
87
88 // With returns a new context with keyvals appended to those of the receiver.
21 // The returned Logger replaces all value elements (odd indexes) containing a
22 // Valuer with their generated value for each call to its Log method.
8923 func With(logger Logger, keyvals ...interface{}) Logger {
9024 if len(keyvals) == 0 {
9125 return logger
10640 }
10741 }
10842
109 // WithPrefix returns a new context with keyvals prepended to those of the
110 // receiver.
43 // WithPrefix returns a new contextual logger with keyvals prepended to those
44 // passed to calls to Log. If logger is also a contextual logger created by
45 // With or WithPrefix, keyvals is prepended to the existing context.
46 //
47 // The returned Logger replaces all value elements (odd indexes) containing a
48 // Valuer with their generated value for each call to its Log method.
11149 func WithPrefix(logger Logger, keyvals ...interface{}) Logger {
11250 if len(keyvals) == 0 {
11351 return logger
13472 }
13573 }
13674
75 // context is the Logger implementation returned by With and WithPrefix. It
76 // wraps a Logger and holds keyvals that it includes in all log events. Its
77 // Log method calls bindValues to generate values for each Valuer in the
78 // context keyvals.
79 //
80 // A context must always have the same number of stack frames between calls to
81 // its Log method and the eventual binding of Valuers to their value. This
82 // requirement comes from the functional requirement to allow a context to
83 // resolve application call site information for a Caller stored in the
84 // context. To do this we must be able to predict the number of logging
85 // functions on the stack when bindValues is called.
86 //
87 // Two implementation details provide the needed stack depth consistency.
88 //
89 // 1. newContext avoids introducing an additional layer when asked to
90 // wrap another context.
91 // 2. With and WithPrefix avoid introducing an additional layer by
92 // returning a newly constructed context with a merged keyvals rather
93 // than simply wrapping the existing context.
94 type context struct {
95 logger Logger
96 keyvals []interface{}
97 hasValuer bool
98 }
99
100 func newContext(logger Logger) *context {
101 if c, ok := logger.(*context); ok {
102 return c
103 }
104 return &context{logger: logger}
105 }
106
107 // Log replaces all value elements (odd indexes) containing a Valuer in the
108 // stored context with their generated value, appends keyvals, and passes the
109 // result to the wrapped Logger.
110 func (l *context) Log(keyvals ...interface{}) error {
111 kvs := append(l.keyvals, keyvals...)
112 if len(kvs)%2 != 0 {
113 kvs = append(kvs, ErrMissingValue)
114 }
115 if l.hasValuer {
116 // If no keyvals were appended above then we must copy l.keyvals so
117 // that future log events will reevaluate the stored Valuers.
118 if len(keyvals) == 0 {
119 kvs = append([]interface{}{}, l.keyvals...)
120 }
121 bindValues(kvs[:len(l.keyvals)])
122 }
123 return l.logger.Log(kvs...)
124 }
125
137126 // LoggerFunc is an adapter to allow use of ordinary functions as Loggers. If
138127 // f is a function with the appropriate signature, LoggerFunc(f) is a Logger
139128 // object that calls f.
5555 }
5656 }
5757
58 // Test that Context.Log has a consistent function stack depth when binding
59 // log.Valuers, regardless of how many times Context.With has been called.
58 // Test that context.Log has a consistent function stack depth when binding
59 // Valuers, regardless of how many times With has been called.
6060 func TestContextStackDepth(t *testing.T) {
6161 t.Parallel()
6262 fn := fmt.Sprintf("%n", stack.Caller(0))
55 "github.com/go-stack/stack"
66 )
77
8 // A Valuer generates a log value. When passed to Context.With in a value
9 // element (odd indexes), it represents a dynamic value which is re-evaluated
10 // with each log event.
8 // A Valuer generates a log value. When passed to With or WithPrefix in a
9 // value element (odd indexes), it represents a dynamic value which is re-
10 // evaluated with each log event.
1111 type Valuer func() interface{}
1212
1313 // bindValues replaces all value elements (odd indexes) containing a Valuer
3838 return func() interface{} { return t() }
3939 }
4040
41 var (
42 // DefaultTimestamp is a Valuer that returns the current wallclock time,
43 // respecting time zones, when bound.
44 DefaultTimestamp Valuer = func() interface{} { return time.Now().Format(time.RFC3339Nano) }
45
46 // DefaultTimestampUTC is a Valuer that returns the current time in UTC
47 // when bound.
48 DefaultTimestampUTC Valuer = func() interface{} { return time.Now().UTC().Format(time.RFC3339Nano) }
49 )
50
5141 // Caller returns a Valuer that returns a file and line from a specified depth
5242 // in the callstack. Users will probably want to use DefaultCaller.
5343 func Caller(depth int) Valuer {
5545 }
5646
5747 var (
48 // DefaultTimestamp is a Valuer that returns the current wallclock time,
49 // respecting time zones, when bound.
50 DefaultTimestamp = Valuer(func() interface{} {
51 return time.Now().Format(time.RFC3339Nano)
52 })
53
54 // DefaultTimestampUTC is a Valuer that returns the current time in UTC
55 // when bound.
56 DefaultTimestampUTC = Valuer(func() interface{} {
57 return time.Now().UTC().Format(time.RFC3339Nano)
58 })
59
5860 // DefaultCaller is a Valuer that returns the file and line where the Log
5961 // method was invoked. It can only be used with log.With.
6062 DefaultCaller = Caller(3)