Codebase list golang-github-go-kit-kit / 3880c6f
Merge pull request #327 from go-kit/simple-sync-log Simple sync log. Chris Hines authored 7 years ago GitHub committed 7 years ago
14 changed file(s) with 381 addition(s) and 124 deletion(s). Raw diff Collapse all Expand all
2828 ### Typical application logging
2929
3030 ```go
31 logger := log.NewLogfmtLogger(os.Stderr)
31 w := log.NewSyncWriter(os.Stderr)
32 logger := log.NewLogfmtLogger(w)
3233 logger.Log("question", "what is the meaning of life?", "answer", 42)
3334
3435 // Output:
4041 ```go
4142 func main() {
4243 var logger log.Logger
43 logger = log.NewLogfmtLogger(os.Stderr)
44 logger = log.NewLogfmtLogger(log.NewSyncWriter(os.Stderr))
4445 logger = log.NewContext(logger).With("instance_id", 123)
4546
4647 logger.Log("msg", "starting")
6667 )
6768
6869 func main() {
69 logger := kitlog.NewJSONLogger(os.Stdout)
70 logger := kitlog.NewJSONLogger(log.NewSyncWriter(os.Stdout))
7071 stdlog.SetOutput(kitlog.NewStdlibAdapter(logger))
7172 stdlog.Print("I sure like pie")
7273 }
9192
9293 ```go
9394 var logger log.Logger
94 logger = log.NewLogfmtLogger(os.Stderr)
95 logger = log.NewLogfmtLogger(log.NewSyncWriter(os.Stderr))
9596 logger = log.NewContext(logger).With("ts", log.DefaultTimestampUTC, "caller", log.DefaultCaller)
9697
9798 logger.Log("msg", "hello")
00 package log_test
11
22 import (
3 "strconv"
4 "sync"
3 "math"
54 "testing"
65
76 "github.com/go-kit/kit/log"
98
109 // These test are designed to be run with the race detector.
1110
12 func testConcurrency(t *testing.T, logger log.Logger) {
13 for _, n := range []int{10, 100, 500} {
14 wg := sync.WaitGroup{}
15 wg.Add(n)
16 for i := 0; i < n; i++ {
17 go func() { spam(logger); wg.Done() }()
11 func testConcurrency(t *testing.T, logger log.Logger, total int) {
12 n := int(math.Sqrt(float64(total)))
13 share := total / n
14
15 errC := make(chan error, n)
16
17 for i := 0; i < n; i++ {
18 go func() {
19 errC <- spam(logger, share)
20 }()
21 }
22
23 for i := 0; i < n; i++ {
24 err := <-errC
25 if err != nil {
26 t.Fatalf("concurrent logging error: %v", err)
1827 }
19 wg.Wait()
2028 }
2129 }
2230
23 func spam(logger log.Logger) {
24 for i := 0; i < 100; i++ {
25 logger.Log("key", strconv.FormatInt(int64(i), 10))
31 func spam(logger log.Logger, count int) error {
32 for i := 0; i < count; i++ {
33 err := logger.Log("key", i)
34 if err != nil {
35 return err
36 }
2637 }
38 return nil
2739 }
00 // Package log provides a structured logger.
11 //
2 // Services produce logs to be consumed later, either by humans or machines.
3 // Humans might be interested in debugging errors, or tracing specific requests.
4 // Machines might be interested in counting interesting events, or aggregating
5 // information for offline processing. In both cases, it's important that the
6 // log messages be structured and actionable. Package log is designed to
7 // encourage both of these best practices.
2 // Structured logging produces logs easily consumed later by humans or
3 // machines. Humans might be interested in debugging errors, or tracing
4 // specific requests. Machines might be interested in counting interesting
5 // events, or aggregating information for off-line processing. In both cases,
6 // it is important that the log messages are structured and actionable.
7 // Package log is designed to encourage both of these best practices.
8 //
9 // Basic Usage
10 //
11 // The fundamental interface is Logger. Loggers create log events from
12 // key/value data. The Logger interface has a single method, Log, which
13 // accepts a sequence of alternating key/value pairs, which this package names
14 // keyvals.
15 //
16 // type Logger interface {
17 // Log(keyvals ...interface{}) error
18 // }
19 //
20 // Here is an example of a function using a Logger to create log events.
21 //
22 // func RunTask(task Task, logger log.Logger) string {
23 // logger.Log("taskID", task.ID, "event", "starting task")
24 // ...
25 // logger.Log("taskID", task.ID, "event", "task complete")
26 // }
27 //
28 // The keys in the above example are "taskID" and "event". The values are
29 // task.ID, "starting task", and "task complete". Every key is followed
30 // immediately by its value.
31 //
32 // Keys are usually plain strings. Values may be any type that has a sensible
33 // encoding in the chosen log format. With structured logging it is a good
34 // idea to log simple values without formatting them. This practice allows
35 // the chosen logger to encode values in the most appropriate way.
36 //
37 // Log Context
38 //
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.
42 //
43 // func RunTask(task Task, logger log.Logger) string {
44 // logger = log.NewContext(logger).With("taskID", task.ID)
45 // logger.Log("event", "starting task")
46 // ...
47 // taskHelper(task.Cmd, logger)
48 // ...
49 // logger.Log("event", "task complete")
50 // }
51 //
52 // 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.)
60 //
61 // Dynamic Context Values
62 //
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.
66 //
67 // Valuers provide the basis for consistently logging timestamps and source
68 // code location. The log package defines several valuers for that purpose.
69 // See Timestamp, DefaultTimestamp, DefaultTimestampUTC, Caller, and
70 // DefaultCaller. A common logger initialization sequence that ensures all log
71 // entries contain a timestamp and source location looks like this:
72 //
73 // logger := log.NewLogfmtLogger(log.SyncWriter(os.Stdout))
74 // logger = log.NewContext(logger).With("ts", log.DefaultTimestampUTC, "caller", log.DefaultCaller)
75 //
76 // Concurrent Safety
77 //
78 // Applications with multiple goroutines want each log event written to the
79 // same logger to remain separate from other log events. Package log provides
80 // two simple solutions for concurrent safe logging.
81 //
82 // NewSyncWriter wraps an io.Writer and serializes each call to its Write
83 // method. Using a SyncWriter has the benefit that the smallest practical
84 // portion of the logging logic is performed within a mutex, but it requires
85 // the formatting Logger to make only one call to Write per log event.
86 //
87 // NewSyncLogger wraps any Logger and serializes each call to its Log method.
88 // Using a SyncLogger has the benefit that it guarantees each log event is
89 // handled atomically within the wrapped logger, but it typically serializes
90 // both the formatting and output logic. Use a SyncLogger if the formatting
91 // logger may perform multiple writes per log event.
892 package log
11
22 import (
33 "os"
4 "time"
45
56 "github.com/go-kit/kit/log"
67 )
78
8 func ExampleContext() {
9 func Example_basic() {
910 logger := log.NewLogfmtLogger(os.Stdout)
10 logger.Log("foo", 123)
11 ctx := log.NewContext(logger).With("level", "info")
12 ctx.Log()
13 ctx = ctx.With("msg", "hello")
14 ctx.Log()
15 ctx.With("a", 1).Log("b", 2)
11
12 type Task struct {
13 ID int
14 }
15
16 RunTask := func(task Task, logger log.Logger) {
17 logger.Log("taskID", task.ID, "event", "starting task")
18
19 logger.Log("taskID", task.ID, "event", "task complete")
20 }
21
22 RunTask(Task{ID: 1}, logger)
1623
1724 // Output:
18 // foo=123
19 // level=info
20 // level=info msg=hello
21 // level=info msg=hello a=1 b=2
25 // taskID=1 event="starting task"
26 // taskID=1 event="task complete"
2227 }
28
29 func Example_context() {
30 logger := log.NewLogfmtLogger(os.Stdout)
31
32 type Task struct {
33 ID int
34 Cmd string
35 }
36
37 taskHelper := func(cmd string, logger log.Logger) {
38 // execute(cmd)
39 logger.Log("cmd", cmd, "dur", 42*time.Millisecond)
40 }
41
42 RunTask := func(task Task, logger log.Logger) {
43 logger = log.NewContext(logger).With("taskID", task.ID)
44 logger.Log("event", "starting task")
45
46 taskHelper(task.Cmd, logger)
47
48 logger.Log("event", "task complete")
49 }
50
51 RunTask(Task{ID: 1, Cmd: "echo Hello, world!"}, logger)
52
53 // Output:
54 // taskID=1 event="starting task"
55 // taskID=1 cmd="echo Hello, world!" dur=42ms
56 // taskID=1 event="task complete"
57 }
58
59 func Example_valuer() {
60 logger := log.NewLogfmtLogger(os.Stdout)
61
62 count := 0
63 counter := func() interface{} {
64 count++
65 return count
66 }
67
68 logger = log.NewContext(logger).With("count", log.Valuer(counter))
69
70 logger.Log("call", "first")
71 logger.Log("call", "second")
72
73 // Output:
74 // count=1 call=first
75 // count=2 call=second
76 }
77
78 func Example_debugInfo() {
79 logger := log.NewLogfmtLogger(os.Stdout)
80
81 // make time predictable for this test
82 baseTime := time.Date(2015, time.February, 3, 10, 0, 0, 0, time.UTC)
83 mockTime := func() time.Time {
84 baseTime = baseTime.Add(time.Second)
85 return baseTime
86 }
87
88 logger = log.NewContext(logger).With("time", log.Timestamp(mockTime), "caller", log.DefaultCaller)
89
90 logger.Log("call", "first")
91 logger.Log("call", "second")
92
93 // ...
94
95 logger.Log("call", "third")
96
97 // Output:
98 // time=2015-02-03T10:00:01Z caller=example_test.go:91 call=first
99 // time=2015-02-03T10:00:02Z caller=example_test.go:92 call=second
100 // time=2015-02-03T10:00:03Z caller=example_test.go:96 call=third
101 }
1212 }
1313
1414 // NewJSONLogger returns a Logger that encodes keyvals to the Writer as a
15 // single JSON object.
15 // single JSON object. Each log event produces no more than one call to
16 // w.Write. The passed Writer must be safe for concurrent use by multiple
17 // goroutines if the returned Logger will be used concurrently.
1618 func NewJSONLogger(w io.Writer) Logger {
1719 return &jsonLogger{w}
1820 }
9999 }
100100
101101 func TestJSONLoggerStringValue(t *testing.T) {
102 t.Parallel()
102103 tests := []struct {
103104 v interface{}
104105 expected string
151152 }
152153
153154 func TestJSONLoggerConcurrency(t *testing.T) {
154 testConcurrency(t, log.NewJSONLogger(ioutil.Discard))
155 t.Parallel()
156 testConcurrency(t, log.NewJSONLogger(ioutil.Discard), 10000)
155157 }
0 // Package log provides basic interfaces for structured logging.
1 //
2 // The fundamental interface is Logger. Loggers create log events from
3 // key/value data.
40 package log
51
6 import (
7 "errors"
8 "sync/atomic"
9 )
2 import "errors"
103
114 // Logger is the fundamental interface for all log operations. Log creates a
125 // log event from keyvals, a variadic sequence of alternating keys and values.
148141 func (f LoggerFunc) Log(keyvals ...interface{}) error {
149142 return f(keyvals...)
150143 }
151
152 // SwapLogger wraps another logger that may be safely replaced while other
153 // goroutines use the SwapLogger concurrently. The zero value for a SwapLogger
154 // will discard all log events without error.
155 //
156 // SwapLogger serves well as a package global logger that can be changed by
157 // importers.
158 type SwapLogger struct {
159 logger atomic.Value
160 }
161
162 type loggerStruct struct {
163 Logger
164 }
165
166 // Log implements the Logger interface by forwarding keyvals to the currently
167 // wrapped logger. It does not log anything if the wrapped logger is nil.
168 func (l *SwapLogger) Log(keyvals ...interface{}) error {
169 s, ok := l.logger.Load().(loggerStruct)
170 if !ok || s.Logger == nil {
171 return nil
172 }
173 return s.Log(keyvals...)
174 }
175
176 // Swap replaces the currently wrapped logger with logger. Swap may be called
177 // concurrently with calls to Log from other goroutines.
178 func (l *SwapLogger) Swap(logger Logger) {
179 l.logger.Store(loggerStruct{logger})
180 }
7070 // whether Context.Log is called via an interface typed variable or a concrete
7171 // typed variable.
7272 func TestContextStackDepth(t *testing.T) {
73 t.Parallel()
7374 fn := fmt.Sprintf("%n", stack.Caller(0))
7475
7576 var output []interface{}
206207 lc.Log("k", "v")
207208 }
208209 }
209
210 func TestSwapLogger(t *testing.T) {
211 var logger log.SwapLogger
212
213 // Zero value does not panic or error.
214 err := logger.Log("k", "v")
215 if got, want := err, error(nil); got != want {
216 t.Errorf("got %v, want %v", got, want)
217 }
218
219 buf := &bytes.Buffer{}
220 json := log.NewJSONLogger(buf)
221 logger.Swap(json)
222
223 if err := logger.Log("k", "v"); err != nil {
224 t.Error(err)
225 }
226 if got, want := buf.String(), `{"k":"v"}`+"\n"; got != want {
227 t.Errorf("got %v, want %v", got, want)
228 }
229
230 buf.Reset()
231 prefix := log.NewLogfmtLogger(buf)
232 logger.Swap(prefix)
233
234 if err := logger.Log("k", "v"); err != nil {
235 t.Error(err)
236 }
237 if got, want := buf.String(), "k=v\n"; got != want {
238 t.Errorf("got %v, want %v", got, want)
239 }
240
241 buf.Reset()
242 logger.Swap(nil)
243
244 if err := logger.Log("k", "v"); err != nil {
245 t.Error(err)
246 }
247 if got, want := buf.String(), ""; got != want {
248 t.Errorf("got %v, want %v", got, want)
249 }
250 }
251
252 func TestSwapLoggerConcurrency(t *testing.T) {
253 testConcurrency(t, &log.SwapLogger{})
254 }
3030 }
3131
3232 // NewLogfmtLogger returns a logger that encodes keyvals to the Writer in
33 // logfmt format. The passed Writer must be safe for concurrent use by
34 // multiple goroutines if the returned Logger will be used concurrently.
33 // logfmt format. Each log event produces no more than one call to w.Write.
34 // The passed Writer must be safe for concurrent use by multiple goroutines if
35 // the returned Logger will be used concurrently.
3536 func NewLogfmtLogger(w io.Writer) Logger {
3637 return &logfmtLogger{w}
3738 }
1010 )
1111
1212 func TestLogfmtLogger(t *testing.T) {
13 t.Parallel()
1314 buf := &bytes.Buffer{}
1415 logger := log.NewLogfmtLogger(buf)
1516
4647 }
4748
4849 func TestLogfmtLoggerConcurrency(t *testing.T) {
49 testConcurrency(t, log.NewLogfmtLogger(ioutil.Discard))
50 t.Parallel()
51 testConcurrency(t, log.NewLogfmtLogger(ioutil.Discard), 10000)
5052 }
5153
5254 type mymap map[int]int
66 )
77
88 func TestNopLogger(t *testing.T) {
9 t.Parallel()
910 logger := log.NewNopLogger()
1011 if err := logger.Log("abc", 123); err != nil {
1112 t.Error(err)
0 package log
1
2 import (
3 "io"
4 "sync"
5 "sync/atomic"
6 )
7
8 // SwapLogger wraps another logger that may be safely replaced while other
9 // goroutines use the SwapLogger concurrently. The zero value for a SwapLogger
10 // will discard all log events without error.
11 //
12 // SwapLogger serves well as a package global logger that can be changed by
13 // importers.
14 type SwapLogger struct {
15 logger atomic.Value
16 }
17
18 type loggerStruct struct {
19 Logger
20 }
21
22 // Log implements the Logger interface by forwarding keyvals to the currently
23 // wrapped logger. It does not log anything if the wrapped logger is nil.
24 func (l *SwapLogger) Log(keyvals ...interface{}) error {
25 s, ok := l.logger.Load().(loggerStruct)
26 if !ok || s.Logger == nil {
27 return nil
28 }
29 return s.Log(keyvals...)
30 }
31
32 // Swap replaces the currently wrapped logger with logger. Swap may be called
33 // concurrently with calls to Log from other goroutines.
34 func (l *SwapLogger) Swap(logger Logger) {
35 l.logger.Store(loggerStruct{logger})
36 }
37
38 // SyncWriter synchronizes concurrent writes to an io.Writer.
39 type SyncWriter struct {
40 mu sync.Mutex
41 w io.Writer
42 }
43
44 // NewSyncWriter returns a new SyncWriter. The returned writer is safe for
45 // concurrent use by multiple goroutines.
46 func NewSyncWriter(w io.Writer) *SyncWriter {
47 return &SyncWriter{w: w}
48 }
49
50 // Write writes p to the underlying io.Writer. If another write is already in
51 // progress, the calling goroutine blocks until the SyncWriter is available.
52 func (w *SyncWriter) Write(p []byte) (n int, err error) {
53 w.mu.Lock()
54 n, err = w.w.Write(p)
55 w.mu.Unlock()
56 return n, err
57 }
58
59 // syncLogger provides concurrent safe logging for another Logger.
60 type syncLogger struct {
61 mu sync.Mutex
62 logger Logger
63 }
64
65 // NewSyncLogger returns a logger that synchronizes concurrent use of the
66 // wrapped logger. When multiple goroutines use the SyncLogger concurrently
67 // only one goroutine will be allowed to log to the wrapped logger at a time.
68 // The other goroutines will block until the logger is available.
69 func NewSyncLogger(logger Logger) Logger {
70 return &syncLogger{logger: logger}
71 }
72
73 // Log logs keyvals to the underlying Logger. If another log is already in
74 // progress, the calling goroutine blocks until the syncLogger is available.
75 func (l *syncLogger) Log(keyvals ...interface{}) error {
76 l.mu.Lock()
77 err := l.logger.Log(keyvals...)
78 l.mu.Unlock()
79 return err
80 }
0 package log_test
1
2 import (
3 "bytes"
4 "io"
5 "testing"
6
7 "github.com/go-kit/kit/log"
8 )
9
10 func TestSwapLogger(t *testing.T) {
11 t.Parallel()
12 var logger log.SwapLogger
13
14 // Zero value does not panic or error.
15 err := logger.Log("k", "v")
16 if got, want := err, error(nil); got != want {
17 t.Errorf("got %v, want %v", got, want)
18 }
19
20 buf := &bytes.Buffer{}
21 json := log.NewJSONLogger(buf)
22 logger.Swap(json)
23
24 if err := logger.Log("k", "v"); err != nil {
25 t.Error(err)
26 }
27 if got, want := buf.String(), `{"k":"v"}`+"\n"; got != want {
28 t.Errorf("got %v, want %v", got, want)
29 }
30
31 buf.Reset()
32 prefix := log.NewLogfmtLogger(buf)
33 logger.Swap(prefix)
34
35 if err := logger.Log("k", "v"); err != nil {
36 t.Error(err)
37 }
38 if got, want := buf.String(), "k=v\n"; got != want {
39 t.Errorf("got %v, want %v", got, want)
40 }
41
42 buf.Reset()
43 logger.Swap(nil)
44
45 if err := logger.Log("k", "v"); err != nil {
46 t.Error(err)
47 }
48 if got, want := buf.String(), ""; got != want {
49 t.Errorf("got %v, want %v", got, want)
50 }
51 }
52
53 func TestSwapLoggerConcurrency(t *testing.T) {
54 t.Parallel()
55 testConcurrency(t, &log.SwapLogger{}, 10000)
56 }
57
58 func TestSyncLoggerConcurrency(t *testing.T) {
59 var w io.Writer
60 w = &bytes.Buffer{}
61 logger := log.NewLogfmtLogger(w)
62 logger = log.NewSyncLogger(logger)
63 testConcurrency(t, logger, 10000)
64 }
65
66 func TestSyncWriterConcurrency(t *testing.T) {
67 var w io.Writer
68 w = &bytes.Buffer{}
69 w = log.NewSyncWriter(w)
70 testConcurrency(t, log.NewLogfmtLogger(w), 10000)
71 }
88 )
99
1010 func TestValueBinding(t *testing.T) {
11 t.Parallel()
1112 var output []interface{}
1213
1314 logger := log.Logger(log.LoggerFunc(func(keyvals ...interface{}) error {
3233 if want, have := start.Add(time.Second), timestamp; want != have {
3334 t.Errorf("output[1]: want %v, have %v", want, have)
3435 }
35 if want, have := "value_test.go:28", fmt.Sprint(output[3]); want != have {
36 if want, have := "value_test.go:29", fmt.Sprint(output[3]); want != have {
3637 t.Errorf("output[3]: want %s, have %s", want, have)
3738 }
3839
4546 if want, have := start.Add(2*time.Second), timestamp; want != have {
4647 t.Errorf("output[1]: want %v, have %v", want, have)
4748 }
48 if want, have := "value_test.go:41", fmt.Sprint(output[3]); want != have {
49 if want, have := "value_test.go:42", fmt.Sprint(output[3]); want != have {
4950 t.Errorf("output[3]: want %s, have %s", want, have)
5051 }
5152 }
5253
5354 func TestValueBinding_loggingZeroKeyvals(t *testing.T) {
55 t.Parallel()
5456 var output []interface{}
5557
5658 logger := log.Logger(log.LoggerFunc(func(keyvals ...interface{}) error {