Update package docs and examples.
- Add sections for basic usage, log contexts, dynamic context values,
and concurrent safety.
- Add executable tests that illustrate the new topics.
- Update README.md to use log.NewSyncWriter in examples.
Chris Hines
7 years ago
28 | 28 | ### Typical application logging |
29 | 29 | |
30 | 30 | ```go |
31 | logger := log.NewLogfmtLogger(os.Stderr) | |
31 | w := log.NewSyncWriter(os.Stderr) | |
32 | logger := log.NewLogfmtLogger(w) | |
32 | 33 | logger.Log("question", "what is the meaning of life?", "answer", 42) |
33 | 34 | |
34 | 35 | // Output: |
40 | 41 | ```go |
41 | 42 | func main() { |
42 | 43 | var logger log.Logger |
43 | logger = log.NewLogfmtLogger(os.Stderr) | |
44 | logger = log.NewLogfmtLogger(log.NewSyncWriter(os.Stderr)) | |
44 | 45 | logger = log.NewContext(logger).With("instance_id", 123) |
45 | 46 | |
46 | 47 | logger.Log("msg", "starting") |
66 | 67 | ) |
67 | 68 | |
68 | 69 | func main() { |
69 | logger := kitlog.NewJSONLogger(os.Stdout) | |
70 | logger := kitlog.NewJSONLogger(log.NewSyncWriter(os.Stdout)) | |
70 | 71 | stdlog.SetOutput(kitlog.NewStdlibAdapter(logger)) |
71 | 72 | stdlog.Print("I sure like pie") |
72 | 73 | } |
91 | 92 | |
92 | 93 | ```go |
93 | 94 | var logger log.Logger |
94 | logger = log.NewLogfmtLogger(os.Stderr) | |
95 | logger = log.NewLogfmtLogger(log.NewSyncWriter(os.Stderr)) | |
95 | 96 | logger = log.NewContext(logger).With("ts", log.DefaultTimestampUTC, "caller", log.DefaultCaller) |
96 | 97 | |
97 | 98 | logger.Log("msg", "hello") |
0 | 0 | // Package log provides a structured logger. |
1 | 1 | // |
2 | // Applications may want to produce logs to be consumed later, either by | |
3 | // humans or machines. Humans might be interested in debugging errors, or | |
4 | // tracing specific requests. Machines might be interested in counting | |
5 | // interesting events, or aggregating information for offline processing. In | |
6 | // both cases, it's important that the log messages be structured and | |
7 | // actionable. Package log is designed to encourage both of these best | |
8 | // 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. | |
9 | 8 | // |
10 | 9 | // Basic Usage |
11 | 10 | // |
12 | 11 | // The fundamental interface is Logger. Loggers create log events from |
13 | // key/value data. | |
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) | |
14 | 75 | // |
15 | 76 | // Concurrent Safety |
16 | 77 | // |
17 | 78 | // Applications with multiple goroutines want each log event written to the |
18 | 79 | // same logger to remain separate from other log events. Package log provides |
19 | // multiple solutions for concurrent safe logging. | |
80 | // two simple solutions for concurrent safe logging. | |
81 | // | |
82 | // NewSyncWriter wraps a 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 to 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. | |
20 | 92 | package log |
0 | 0 | package log_test |
1 | 1 | |
2 | 2 | import ( |
3 | "net/url" | |
4 | 3 | "os" |
4 | "time" | |
5 | 5 | |
6 | 6 | "github.com/go-kit/kit/log" |
7 | 7 | ) |
8 | 8 | |
9 | func Example_stdout() { | |
10 | w := log.NewSyncWriter(os.Stdout) | |
11 | logger := log.NewLogfmtLogger(w) | |
9 | func Example_basic() { | |
10 | logger := log.NewLogfmtLogger(os.Stdout) | |
12 | 11 | |
13 | reqUrl := &url.URL{ | |
14 | Scheme: "https", | |
15 | Host: "github.com", | |
16 | Path: "/go-kit/kit", | |
12 | type Task struct { | |
13 | ID int | |
17 | 14 | } |
18 | 15 | |
19 | logger.Log("method", "GET", "url", reqUrl) | |
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) | |
20 | 23 | |
21 | 24 | // Output: |
22 | // method=GET url=https://github.com/go-kit/kit | |
25 | // taskID=1 event="starting task" | |
26 | // taskID=1 event="task complete" | |
23 | 27 | } |
24 | 28 | |
25 | func ExampleContext() { | |
26 | w := log.NewSyncWriter(os.Stdout) | |
27 | logger := log.NewLogfmtLogger(w) | |
28 | logger.Log("foo", 123) | |
29 | ctx := log.NewContext(logger).With("level", "info") | |
30 | ctx.Log() | |
31 | ctx = ctx.With("msg", "hello") | |
32 | ctx.Log() | |
33 | ctx.With("a", 1).Log("b", 2) | |
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) | |
34 | 52 | |
35 | 53 | // Output: |
36 | // foo=123 | |
37 | // level=info | |
38 | // level=info msg=hello | |
39 | // level=info msg=hello a=1 b=2 | |
54 | // taskID=1 event="starting task" | |
55 | // taskID=1 cmd="echo Hello, world!" dur=42ms | |
56 | // taskID=1 event="task complete" | |
40 | 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 | } |
12 | 12 | } |
13 | 13 | |
14 | 14 | // 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. | |
16 | 18 | func NewJSONLogger(w io.Writer) Logger { |
17 | 19 | return &jsonLogger{w} |
18 | 20 | } |
30 | 30 | } |
31 | 31 | |
32 | 32 | // 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. | |
35 | 36 | func NewLogfmtLogger(w io.Writer) Logger { |
36 | 37 | return &logfmtLogger{w} |
37 | 38 | } |