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.

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")

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

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
 }

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}
 }

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}
 }