diff --git a/log/README.md b/log/README.md index 452157d38..70e70a6a6 100644 --- a/log/README.md +++ b/log/README.md @@ -29,7 +29,8 @@ logger.Log("transport", "HTTP", "addr", addr, "msg", "listening") ### Typical application logging ```go -logger := log.NewLogfmtLogger(os.Stderr) +w := log.NewSyncWriter(os.Stderr) +logger := log.NewLogfmtLogger(w) logger.Log("question", "what is the meaning of life?", "answer", 42) // Output: @@ -41,7 +42,7 @@ logger.Log("question", "what is the meaning of life?", "answer", 42) ```go func main() { var logger log.Logger - logger = log.NewLogfmtLogger(os.Stderr) + logger = log.NewLogfmtLogger(log.NewSyncWriter(os.Stderr)) logger = log.NewContext(logger).With("instance_id", 123) logger.Log("msg", "starting") @@ -67,7 +68,7 @@ import ( ) func main() { - logger := kitlog.NewJSONLogger(os.Stdout) + logger := kitlog.NewJSONLogger(log.NewSyncWriter(os.Stdout)) stdlog.SetOutput(kitlog.NewStdlibAdapter(logger)) stdlog.Print("I sure like pie") } @@ -92,7 +93,7 @@ logger.Log("legacy", true, "msg", "at least it's something") ```go var logger log.Logger -logger = log.NewLogfmtLogger(os.Stderr) +logger = log.NewLogfmtLogger(log.NewSyncWriter(os.Stderr)) logger = log.NewContext(logger).With("ts", log.DefaultTimestampUTC, "caller", log.DefaultCaller) logger.Log("msg", "hello") diff --git a/log/doc.go b/log/doc.go index 3be307df6..2b24a14ea 100644 --- a/log/doc.go +++ b/log/doc.go @@ -1,21 +1,93 @@ // Package log provides a structured logger. // -// Applications may want to produce logs to be consumed later, either by -// humans or machines. Humans might be interested in debugging errors, or -// tracing specific requests. Machines might be interested in counting -// interesting events, or aggregating information for offline processing. In -// both cases, it's important that the log messages be structured and -// actionable. Package log is designed to encourage both of these best -// practices. +// Structured logging produces logs easily consumed later by humans or +// machines. Humans might be interested in debugging errors, or tracing +// specific requests. Machines might be interested in counting interesting +// events, or aggregating information for off-line processing. In both cases, +// it is important that the log messages are structured and actionable. +// Package log is designed to encourage both of these best practices. // // Basic Usage // // The fundamental interface is Logger. Loggers create log events from -// key/value data. +// key/value data. The Logger interface has a single method, Log, which +// accepts a sequence of alternating key/value pairs, which this package names +// keyvals. +// +// type Logger interface { +// Log(keyvals ...interface{}) error +// } +// +// Here is an example of a function using a Logger to create log events. +// +// func RunTask(task Task, logger log.Logger) string { +// logger.Log("taskID", task.ID, "event", "starting task") +// ... +// logger.Log("taskID", task.ID, "event", "task complete") +// } +// +// The keys in the above example are "taskID" and "event". The values are +// task.ID, "starting task", and "task complete". Every key is followed +// immediately by its value. +// +// Keys are usually plain strings. Values may be any type that has a sensible +// encoding in the chosen log format. With structured logging it is a good +// idea to log simple values without formatting them. This practice allows +// the chosen logger to encode values in the most appropriate way. +// +// Log Context +// +// A log context stores keyvals that it includes in all log events. Building +// appropriate log contexts reduces repetition and aids consistency in the +// resulting log output. We can use a context to improve the RunTask example. +// +// func RunTask(task Task, logger log.Logger) string { +// logger = log.NewContext(logger).With("taskID", task.ID) +// logger.Log("event", "starting task") +// ... +// taskHelper(task.Cmd, logger) +// ... +// logger.Log("event", "task complete") +// } +// +// The improved version emits the same log events as the original for the +// first and last calls to Log. The call to taskHelper highlights that a +// context may be passed as a logger to other functions. Each log event +// created by the called function will include the task.ID even though the +// function does not have access to that value. Using log contexts this way +// simplifies producing log output that enables tracing the life cycle of +// individual tasks. (See the Context example for the full code of the +// above snippet.) +// +// Dynamic Context Values +// +// A Valuer function stored in a log context generates a new value each time +// the context logs an event. The Valuer example demonstrates how this +// feature works. +// +// Valuers provide the basis for consistently logging timestamps and source +// code location. The log package defines several valuers for that purpose. +// See Timestamp, DefaultTimestamp, DefaultTimestampUTC, Caller, and +// DefaultCaller. A common logger initialization sequence that ensures all log +// entries contain a timestamp and source location looks like this: +// +// logger := log.NewLogfmtLogger(log.SyncWriter(os.Stdout)) +// logger = log.NewContext(logger).With("ts", log.DefaultTimestampUTC, "caller", log.DefaultCaller) // // Concurrent Safety // // Applications with multiple goroutines want each log event written to the // same logger to remain separate from other log events. Package log provides -// multiple solutions for concurrent safe logging. +// two simple solutions for concurrent safe logging. +// +// NewSyncWriter wraps a io.Writer and serializes each call to its Write +// method. Using a SyncWriter has the benefit that the smallest practical +// portion of the logging logic is performed within a mutex, but it requires +// the formatting Logger to make only one call to Write per log event. +// +// NewSyncLogger wraps any Logger and serializes each to to its Log method. +// Using a SyncLogger has the benefit that it guarantees each log event is +// handled atomically within the wrapped logger, but it typically serializes +// both the formatting and output logic. Use a SyncLogger if the formatting +// logger may perform multiple writes per log event. package log diff --git a/log/example_test.go b/log/example_test.go index 9ecf2769a..b07ef8ec6 100644 --- a/log/example_test.go +++ b/log/example_test.go @@ -1,41 +1,102 @@ package log_test import ( - "net/url" "os" + "time" "github.com/go-kit/kit/log" ) -func Example_stdout() { - w := log.NewSyncWriter(os.Stdout) - logger := log.NewLogfmtLogger(w) +func Example_basic() { + logger := log.NewLogfmtLogger(os.Stdout) - reqUrl := &url.URL{ - Scheme: "https", - Host: "github.com", - Path: "/go-kit/kit", + type Task struct { + ID int } - logger.Log("method", "GET", "url", reqUrl) + RunTask := func(task Task, logger log.Logger) { + logger.Log("taskID", task.ID, "event", "starting task") + + logger.Log("taskID", task.ID, "event", "task complete") + } + + RunTask(Task{ID: 1}, logger) + + // Output: + // taskID=1 event="starting task" + // taskID=1 event="task complete" +} + +func Example_context() { + logger := log.NewLogfmtLogger(os.Stdout) + + type Task struct { + ID int + Cmd string + } + + taskHelper := func(cmd string, logger log.Logger) { + // execute(cmd) + logger.Log("cmd", cmd, "dur", 42*time.Millisecond) + } + + RunTask := func(task Task, logger log.Logger) { + logger = log.NewContext(logger).With("taskID", task.ID) + logger.Log("event", "starting task") + + taskHelper(task.Cmd, logger) + + logger.Log("event", "task complete") + } + + RunTask(Task{ID: 1, Cmd: "echo Hello, world!"}, logger) // Output: - // method=GET url=https://github.com/go-kit/kit + // taskID=1 event="starting task" + // taskID=1 cmd="echo Hello, world!" dur=42ms + // taskID=1 event="task complete" } -func ExampleContext() { - w := log.NewSyncWriter(os.Stdout) - logger := log.NewLogfmtLogger(w) - logger.Log("foo", 123) - ctx := log.NewContext(logger).With("level", "info") - ctx.Log() - ctx = ctx.With("msg", "hello") - ctx.Log() - ctx.With("a", 1).Log("b", 2) +func Example_valuer() { + logger := log.NewLogfmtLogger(os.Stdout) + + count := 0 + counter := func() interface{} { + count++ + return count + } + + logger = log.NewContext(logger).With("count", log.Valuer(counter)) + + logger.Log("call", "first") + logger.Log("call", "second") + + // Output: + // count=1 call=first + // count=2 call=second +} + +func Example_debugInfo() { + logger := log.NewLogfmtLogger(os.Stdout) + + // make time predictable for this test + baseTime := time.Date(2015, time.February, 3, 10, 0, 0, 0, time.UTC) + mockTime := func() time.Time { + baseTime = baseTime.Add(time.Second) + return baseTime + } + + logger = log.NewContext(logger).With("time", log.Timestamp(mockTime), "caller", log.DefaultCaller) + + logger.Log("call", "first") + logger.Log("call", "second") + + // ... + + logger.Log("call", "third") // Output: - // foo=123 - // level=info - // level=info msg=hello - // level=info msg=hello a=1 b=2 + // time=2015-02-03T10:00:01Z caller=example_test.go:91 call=first + // time=2015-02-03T10:00:02Z caller=example_test.go:92 call=second + // time=2015-02-03T10:00:03Z caller=example_test.go:96 call=third } diff --git a/log/json_logger.go b/log/json_logger.go index cef0d1963..231e09955 100644 --- a/log/json_logger.go +++ b/log/json_logger.go @@ -13,7 +13,9 @@ type jsonLogger struct { } // NewJSONLogger returns a Logger that encodes keyvals to the Writer as a -// single JSON object. +// single JSON object. Each log event produces no more than one call to +// w.Write. The passed Writer must be safe for concurrent use by multiple +// goroutines if the returned Logger will be used concurrently. func NewJSONLogger(w io.Writer) Logger { return &jsonLogger{w} } diff --git a/log/logfmt_logger.go b/log/logfmt_logger.go index 4ff555560..a00305298 100644 --- a/log/logfmt_logger.go +++ b/log/logfmt_logger.go @@ -31,8 +31,9 @@ type logfmtLogger struct { } // NewLogfmtLogger returns a logger that encodes keyvals to the Writer in -// logfmt format. The passed Writer must be safe for concurrent use by -// multiple goroutines if the returned Logger will be used concurrently. +// logfmt format. Each log event produces no more than one call to w.Write. +// The passed Writer must be safe for concurrent use by multiple goroutines if +// the returned Logger will be used concurrently. func NewLogfmtLogger(w io.Writer) Logger { return &logfmtLogger{w} }