Skip to content

Commit

Permalink
log: Update docs to reflect unexporting context and newContext.
Browse files Browse the repository at this point in the history
This update also contains a few other minor documentation updates.
  • Loading branch information
ChrisHines committed Mar 6, 2017
1 parent d4d0b60 commit 44aed65
Show file tree
Hide file tree
Showing 6 changed files with 133 additions and 143 deletions.
71 changes: 35 additions & 36 deletions README.md
Original file line number Diff line number Diff line change
@@ -1,20 +1,22 @@
# package log

`package log` provides a minimal interface for structured logging in services.
It may be wrapped to encode conventions, enforce type-safety, provide leveled logging, and so on.
It can be used for both typical application log events, and log-structured data streams.
It may be wrapped to encode conventions, enforce type-safety, provide leveled
logging, and so on. It can be used for both typical application log events,
and log-structured data streams.

## Structured logging

Structured logging is, basically, conceding to the reality that logs are _data_,
and warrant some level of schematic rigor.
Using a stricter, key/value-oriented message format for our logs,
containing contextual and semantic information,
makes it much easier to get insight into the operational activity of the systems we build.
Consequently, `package log` is of the strong belief that
"[the benefits of structured logging outweigh the minimal effort involved](https://www.thoughtworks.com/radar/techniques/structured-logging)".
Structured logging is, basically, conceding to the reality that logs are
_data_, and warrant some level of schematic rigor. Using a stricter,
key/value-oriented message format for our logs, containing contextual and
semantic information, makes it much easier to get insight into the
operational activity of the systems we build. Consequently, `package log` is
of the strong belief that "[the benefits of structured logging outweigh the
minimal effort involved](https://www.thoughtworks.com/radar/techniques/structured-logging)".

Migrating from unstructured to structured logging is probably a lot easier than you'd expect.
Migrating from unstructured to structured logging is probably a lot easier
than you'd expect.

```go
// Unstructured
Expand All @@ -37,17 +39,17 @@ logger.Log("question", "what is the meaning of life?", "answer", 42)
// question="what is the meaning of life?" answer=42
```

### Log contexts
### Contextual Loggers

```go
func main() {
var logger log.Logger
logger = log.NewLogfmtLogger(log.NewSyncWriter(os.Stderr))
logger = log.NewContext(logger).With("instance_id", 123)
logger = log.With(logger, "instance_id", 123)

logger.Log("msg", "starting")
NewWorker(log.NewContext(logger).With("component", "worker")).Run()
NewSlacker(log.NewContext(logger).With("component", "slacker")).Run()
NewWorker(log.With(logger, "component", "worker")).Run()
NewSlacker(log.With(logger, "component", "slacker")).Run()
}

// Output:
Expand Down Expand Up @@ -77,9 +79,8 @@ func main() {
// {"msg":"I sure like pie","ts":"2016/01/01 12:34:56"}
```

Or, if, for legacy reasons,
you need to pipe all of your logging through the stdlib log package,
you can redirect Go kit logger to the stdlib logger.
Or, if, for legacy reasons, you need to pipe all of your logging through the
stdlib log package, you can redirect Go kit logger to the stdlib logger.

```go
logger := kitlog.NewLogfmtLogger(kitlog.StdlibWriter{})
Expand All @@ -94,7 +95,7 @@ logger.Log("legacy", true, "msg", "at least it's something")
```go
var logger log.Logger
logger = log.NewLogfmtLogger(log.NewSyncWriter(os.Stderr))
logger = log.NewContext(logger).With("ts", log.DefaultTimestampUTC, "caller", log.DefaultCaller)
logger = log.With(logger, "ts", log.DefaultTimestampUTC, "caller", log.DefaultCaller)

logger.Log("msg", "hello")

Expand All @@ -104,7 +105,7 @@ logger.Log("msg", "hello")

## Supported output formats

- [Logfmt](https://brandur.org/logfmt)
- [Logfmt](https://brandur.org/logfmt) ([see also](https://blog.codeship.com/logfmt-a-log-format-thats-easy-to-read-and-write))
- JSON

## Enhancements
Expand All @@ -117,27 +118,25 @@ type Logger interface {
}
```

This interface, and its supporting code like [log.Context](https://godoc.org/github.com/go-kit/kit/log#Context),
is the product of much iteration and evaluation.
For more details on the evolution of the Logger interface,
see [The Hunt for a Logger Interface](http://go-talks.appspot.com/github.com/ChrisHines/talks/structured-logging/structured-logging.slide#1),
a talk by [Chris Hines](https://github.com/ChrisHines).
This interface, and its supporting code like is the product of much iteration
and evaluation. For more details on the evolution of the Logger interface,
see [The Hunt for a Logger Interface](http://go-talks.appspot.com/github.com/ChrisHines/talks/structured-logging/structured-logging.slide#1),
a talk by [Chris Hines](https://github.com/ChrisHines).
Also, please see
[#63](https://github.com/go-kit/kit/issues/63),
[#76](https://github.com/go-kit/kit/pull/76),
[#131](https://github.com/go-kit/kit/issues/131),
[#157](https://github.com/go-kit/kit/pull/157),
[#164](https://github.com/go-kit/kit/issues/164), and
[#252](https://github.com/go-kit/kit/pull/252)
to review historical conversations about package log and the Logger interface.
[#63](https://github.com/go-kit/kit/issues/63),
[#76](https://github.com/go-kit/kit/pull/76),
[#131](https://github.com/go-kit/kit/issues/131),
[#157](https://github.com/go-kit/kit/pull/157),
[#164](https://github.com/go-kit/kit/issues/164), and
[#252](https://github.com/go-kit/kit/pull/252)
to review historical conversations about package log and the Logger interface.

Value-add packages and suggestions,
like improvements to [the leveled logger](https://godoc.org/github.com/go-kit/kit/log/levels),
are of course welcome.
Good proposals should
like improvements to [the leveled logger](https://godoc.org/github.com/go-kit/kit/log/level),
are of course welcome. Good proposals should

- Be composable with [log.Context](https://godoc.org/github.com/go-kit/kit/log#Context),
- Not break the behavior of [log.Caller](https://godoc.org/github.com/go-kit/kit/log#Caller) in any wrapped context, and
- Be composable with [contextual loggers](https://godoc.org/github.com/go-kit/kit/log#With),
- Not break the behavior of [log.Caller](https://godoc.org/github.com/go-kit/kit/log#Caller) in any wrapped contextual loggers, and
- Be friendly to packages that accept only an unadorned log.Logger.

## Benchmarks & comparisons
Expand Down
34 changes: 17 additions & 17 deletions doc.go
Original file line number Diff line number Diff line change
Expand Up @@ -35,11 +35,12 @@
// idea to log simple values without formatting them. This practice allows
// the chosen logger to encode values in the most appropriate way.
//
// Log Context
// Contextual Loggers
//
// 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.
// A contextual logger stores keyvals that it includes in all log events.
// Building appropriate contextual loggers reduces repetition and aids
// consistency in the resulting log output. With and WithPrefix add context to
// a logger. We can use With to improve the RunTask example.
//
// func RunTask(task Task, logger log.Logger) string {
// logger = log.With(logger, "taskID", task.ID)
Expand All @@ -51,19 +52,18 @@
// }
//
// 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.
// first and last calls to Log. Passing the contextual logger to taskHelper
// enables each log event created by taskHelper to include the task.ID even
// though taskHelper does not have access to that value. Using contextual
// loggers this way simplifies producing log output that enables tracing the
// life cycle of individual tasks. (See the Contextual example for the full
// code of the above snippet.)
//
// Dynamic Contextual Values
//
// A Valuer function stored in a contextual logger generates a new value each
// time an event is logged. 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.
Expand Down
2 changes: 1 addition & 1 deletion example_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -29,7 +29,7 @@ func Example_basic() {
// taskID=1 event="task complete"
}

func Example_context() {
func Example_contextual() {
logger := log.NewLogfmtLogger(os.Stdout)

type Task struct {
Expand Down
137 changes: 63 additions & 74 deletions log.go
Original file line number Diff line number Diff line change
Expand Up @@ -6,7 +6,7 @@ import "errors"
// log event from keyvals, a variadic sequence of alternating keys and values.
// Implementations must be safe for concurrent use by multiple goroutines. In
// particular, any implementation of Logger that appends to keyvals or
// modifies any of its elements must make a copy first.
// modifies or retains any of its elements must make a copy first.
type Logger interface {
Log(keyvals ...interface{}) error
}
Expand All @@ -15,78 +15,12 @@ type Logger interface {
// the missing value.
var ErrMissingValue = errors.New("(MISSING)")

// newContext returns a new context that logs to logger.
func newContext(logger Logger) *context {
if c, ok := logger.(*context); ok {
return c
}
return &context{logger: logger}
}

// Context must always have the same number of stack frames between calls to
// its Log method and the eventual binding of Valuers to their value. This
// requirement comes from the functional requirement to allow a context to
// resolve application call site information for a log.Caller stored in the
// context. To do this we must be able to predict the number of logging
// functions on the stack when bindValues is called.
//
// Three implementation details provide the needed stack depth consistency.
// The first two of these details also result in better amortized performance,
// and thus make sense even without the requirements regarding stack depth.
// The third detail, however, is subtle and tied to the implementation of the
// Go compiler.
//
// 1. NewContext avoids introducing an additional layer when asked to
// wrap another Context.
// 2. With avoids introducing an additional layer by returning a newly
// constructed Context with a merged keyvals rather than simply
// wrapping the existing Context.
// 3. All of Context's methods take pointer receivers even though they
// do not mutate the Context.
// With returns a new contextual logger with keyvals prepended to those passed
// to calls to Log. If logger is also a contextual logger created by With or
// WithPrefix, keyvals is appended to the existing context.
//
// Before explaining the last detail, first some background. The Go compiler
// generates wrapper methods to implement the auto dereferencing behavior when
// calling a value method through a pointer variable. These wrapper methods
// are also used when calling a value method through an interface variable
// because interfaces store a pointer to the underlying concrete value.
// Calling a pointer receiver through an interface does not require generating
// an additional function.
//
// If Context had value methods then calling Context.Log through a variable
// with type Logger would have an extra stack frame compared to calling
// Context.Log through a variable with type Context. Using pointer receivers
// avoids this problem.

// A context wraps a Logger and holds keyvals that it includes in all log
// events. When logging, a context replaces all value elements (odd indexes)
// containing a Valuer with their generated value for each call to its Log
// method.
type context struct {
logger Logger
keyvals []interface{}
hasValuer bool
}

// Log replaces all value elements (odd indexes) containing a Valuer in the
// stored context with their generated value, appends keyvals, and passes the
// result to the wrapped Logger.
func (l *context) Log(keyvals ...interface{}) error {
kvs := append(l.keyvals, keyvals...)
if len(kvs)%2 != 0 {
kvs = append(kvs, ErrMissingValue)
}
if l.hasValuer {
// If no keyvals were appended above then we must copy l.keyvals so
// that future log events will reevaluate the stored Valuers.
if len(keyvals) == 0 {
kvs = append([]interface{}{}, l.keyvals...)
}
bindValues(kvs[:len(l.keyvals)])
}
return l.logger.Log(kvs...)
}

// With returns a new context with keyvals appended to those of the receiver.
// The returned Logger replaces all value elements (odd indexes) containing a
// Valuer with their generated value for each call to its Log method.
func With(logger Logger, keyvals ...interface{}) Logger {
if len(keyvals) == 0 {
return logger
Expand All @@ -107,8 +41,12 @@ func With(logger Logger, keyvals ...interface{}) Logger {
}
}

// WithPrefix returns a new context with keyvals prepended to those of the
// receiver.
// WithPrefix returns a new contextual logger with keyvals prepended to those
// passed to calls to Log. If logger is also a contextual logger created by
// With or WithPrefix, keyvals is prepended to the existing context.
//
// The returned Logger replaces all value elements (odd indexes) containing a
// Valuer with their generated value for each call to its Log method.
func WithPrefix(logger Logger, keyvals ...interface{}) Logger {
if len(keyvals) == 0 {
return logger
Expand All @@ -135,6 +73,57 @@ func WithPrefix(logger Logger, keyvals ...interface{}) Logger {
}
}

// context is the Logger implementation returned by With and WithPrefix. It
// wraps a Logger and holds keyvals that it includes in all log events. Its
// Log method calls bindValues to generate values for each Valuer in the
// context keyvals.
//
// A context must always have the same number of stack frames between calls to
// its Log method and the eventual binding of Valuers to their value. This
// requirement comes from the functional requirement to allow a context to
// resolve application call site information for a Caller stored in the
// context. To do this we must be able to predict the number of logging
// functions on the stack when bindValues is called.
//
// Two implementation details provide the needed stack depth consistency.
//
// 1. newContext avoids introducing an additional layer when asked to
// wrap another context.
// 2. With and WithPrefix avoid introducing an additional layer by
// returning a newly constructed context with a merged keyvals rather
// than simply wrapping the existing context.
type context struct {
logger Logger
keyvals []interface{}
hasValuer bool
}

func newContext(logger Logger) *context {
if c, ok := logger.(*context); ok {
return c
}
return &context{logger: logger}
}

// Log replaces all value elements (odd indexes) containing a Valuer in the
// stored context with their generated value, appends keyvals, and passes the
// result to the wrapped Logger.
func (l *context) Log(keyvals ...interface{}) error {
kvs := append(l.keyvals, keyvals...)
if len(kvs)%2 != 0 {
kvs = append(kvs, ErrMissingValue)
}
if l.hasValuer {
// If no keyvals were appended above then we must copy l.keyvals so
// that future log events will reevaluate the stored Valuers.
if len(keyvals) == 0 {
kvs = append([]interface{}{}, l.keyvals...)
}
bindValues(kvs[:len(l.keyvals)])
}
return l.logger.Log(kvs...)
}

// LoggerFunc is an adapter to allow use of ordinary functions as Loggers. If
// f is a function with the appropriate signature, LoggerFunc(f) is a Logger
// object that calls f.
Expand Down
4 changes: 2 additions & 2 deletions log_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -56,8 +56,8 @@ func TestContextMissingValue(t *testing.T) {
}
}

// Test that Context.Log has a consistent function stack depth when binding
// log.Valuers, regardless of how many times Context.With has been called.
// Test that context.Log has a consistent function stack depth when binding
// Valuers, regardless of how many times With has been called.
func TestContextStackDepth(t *testing.T) {
t.Parallel()
fn := fmt.Sprintf("%n", stack.Caller(0))
Expand Down
Loading

0 comments on commit 44aed65

Please sign in to comment.