This commit is contained in:
Manfred Touron
2017-05-18 18:54:23 +02:00
parent dc386661ca
commit 5448f25fd6
645 changed files with 55908 additions and 33297 deletions

View File

@@ -1,22 +1,20 @@
# 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
@@ -39,17 +37,17 @@ logger.Log("question", "what is the meaning of life?", "answer", 42)
// question="what is the meaning of life?" answer=42
```
### Contextual Loggers
### Log contexts
```go
func main() {
var logger log.Logger
logger = log.NewLogfmtLogger(log.NewSyncWriter(os.Stderr))
logger = log.With(logger, "instance_id", 123)
logger = log.NewContext(logger).With("instance_id", 123)
logger.Log("msg", "starting")
NewWorker(log.With(logger, "component", "worker")).Run()
NewSlacker(log.With(logger, "component", "slacker")).Run()
NewWorker(log.NewContext(logger).With("component", "worker")).Run()
NewSlacker(log.NewContext(logger).With("component", "slacker")).Run()
}
// Output:
@@ -79,8 +77,9 @@ 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{})
@@ -95,7 +94,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.With(logger, "ts", log.DefaultTimestampUTC, "caller", log.DefaultCaller)
logger = log.NewContext(logger).With("ts", log.DefaultTimestampUTC, "caller", log.DefaultCaller)
logger.Log("msg", "hello")
@@ -105,7 +104,7 @@ logger.Log("msg", "hello")
## Supported output formats
- [Logfmt](https://brandur.org/logfmt) ([see also](https://blog.codeship.com/logfmt-a-log-format-thats-easy-to-read-and-write))
- [Logfmt](https://brandur.org/logfmt)
- JSON
## Enhancements
@@ -118,25 +117,27 @@ type Logger interface {
}
```
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).
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).
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/level),
are of course welcome. Good proposals should
like improvements to [the leveled logger](https://godoc.org/github.com/go-kit/kit/log/levels),
are of course welcome.
Good proposals should
- 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 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 friendly to packages that accept only an unadorned log.Logger.
## Benchmarks & comparisons

View File

@@ -7,7 +7,7 @@ import (
)
func benchmarkRunner(b *testing.B, logger log.Logger, f func(log.Logger)) {
lc := log.With(logger, "common_key", "common_value")
lc := log.NewContext(logger).With("common_key", "common_value")
b.ReportAllocs()
b.ResetTimer()
for i := 0; i < b.N; i++ {
@@ -17,5 +17,5 @@ func benchmarkRunner(b *testing.B, logger log.Logger, f func(log.Logger)) {
var (
baseMessage = func(logger log.Logger) { logger.Log("foo_key", "foo_value") }
withMessage = func(logger log.Logger) { log.With(logger, "a", "b").Log("c", "d") }
withMessage = func(logger log.Logger) { log.NewContext(logger).With("a", "b").Log("c", "d") }
)

View File

@@ -35,15 +35,14 @@
// idea to log simple values without formatting them. This practice allows
// the chosen logger to encode values in the most appropriate way.
//
// Contextual Loggers
// Log Context
//
// 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.
// 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.With(logger, "taskID", task.ID)
// logger = log.NewContext(logger).With("taskID", task.ID)
// logger.Log("event", "starting task")
// ...
// taskHelper(task.Cmd, logger)
@@ -52,18 +51,19 @@
// }
//
// The improved version emits the same log events as the original for the
// 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.)
// 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 Contextual Values
// Dynamic Context 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.
// 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.
@@ -72,7 +72,7 @@
// entries contain a timestamp and source location looks like this:
//
// logger := log.NewLogfmtLogger(log.NewSyncWriter(os.Stdout))
// logger = log.With(logger, "ts", log.DefaultTimestampUTC, "caller", log.DefaultCaller)
// logger = log.NewContext(logger).With("ts", log.DefaultTimestampUTC, "caller", log.DefaultCaller)
//
// Concurrent Safety
//
@@ -90,27 +90,4 @@
// 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.
//
// Error Handling
//
// This package relies on the practice of wrapping or decorating loggers with
// other loggers to provide composable pieces of functionality. It also means
// that Logger.Log must return an error because some
// implementations—especially those that output log data to an io.Writer—may
// encounter errors that cannot be handled locally. This in turn means that
// Loggers that wrap other loggers should return errors from the wrapped
// logger up the stack.
//
// Fortunately, the decorator pattern also provides a way to avoid the
// necessity to check for errors every time an application calls Logger.Log.
// An application required to panic whenever its Logger encounters
// an error could initialize its logger as follows.
//
// fmtlogger := log.NewLogfmtLogger(log.NewSyncWriter(os.Stdout))
// logger := log.LoggerFunc(func(keyvals ...interface{}) error {
// if err := fmtlogger.Log(keyvals...); err != nil {
// panic(err)
// }
// return nil
// })
package log

View File

@@ -1,9 +1,7 @@
package log_test
import (
"math/rand"
"os"
"sync"
"time"
"github.com/go-kit/kit/log"
@@ -29,7 +27,7 @@ func Example_basic() {
// taskID=1 event="task complete"
}
func Example_contextual() {
func Example_context() {
logger := log.NewLogfmtLogger(os.Stdout)
type Task struct {
@@ -43,7 +41,7 @@ func Example_contextual() {
}
RunTask := func(task Task, logger log.Logger) {
logger = log.With(logger, "taskID", task.ID)
logger = log.NewContext(logger).With("taskID", task.ID)
logger.Log("event", "starting task")
taskHelper(task.Cmd, logger)
@@ -68,7 +66,7 @@ func Example_valuer() {
return count
}
logger = log.With(logger, "count", log.Valuer(counter))
logger = log.NewContext(logger).With("count", log.Valuer(counter))
logger.Log("call", "first")
logger.Log("call", "second")
@@ -88,7 +86,7 @@ func Example_debugInfo() {
return baseTime
}
logger = log.With(logger, "time", log.Timestamp(mockTime), "caller", log.DefaultCaller)
logger = log.NewContext(logger).With("time", log.Timestamp(mockTime), "caller", log.DefaultCaller)
logger.Log("call", "first")
logger.Log("call", "second")
@@ -98,40 +96,7 @@ func Example_debugInfo() {
logger.Log("call", "third")
// Output:
// time=2015-02-03T10:00:01Z caller=example_test.go:93 call=first
// time=2015-02-03T10:00:02Z caller=example_test.go:94 call=second
// time=2015-02-03T10:00:03Z caller=example_test.go:98 call=third
}
func Example_syncWriter() {
w := log.NewSyncWriter(os.Stdout)
logger := log.NewLogfmtLogger(w)
type Task struct {
ID int
}
var wg sync.WaitGroup
RunTask := func(task Task, logger log.Logger) {
logger.Log("taskID", task.ID, "event", "starting task")
time.Sleep(time.Duration(rand.Intn(200)) * time.Millisecond)
logger.Log("taskID", task.ID, "event", "task complete")
wg.Done()
}
wg.Add(2)
go RunTask(Task{ID: 1}, logger)
go RunTask(Task{ID: 2}, logger)
wg.Wait()
// Unordered output:
// taskID=1 event="starting task"
// taskID=2 event="starting task"
// taskID=1 event="task complete"
// taskID=2 event="task complete"
// 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
}

View File

@@ -0,0 +1,65 @@
package level_test
import (
"io/ioutil"
"testing"
"github.com/go-kit/kit/log"
"github.com/go-kit/kit/log/experimental_level"
)
func BenchmarkNopBaseline(b *testing.B) {
benchmarkRunner(b, log.NewNopLogger())
}
func BenchmarkNopDisallowedLevel(b *testing.B) {
benchmarkRunner(b, level.New(log.NewNopLogger(), level.Config{
Allowed: level.AllowInfoAndAbove(),
}))
}
func BenchmarkNopAllowedLevel(b *testing.B) {
benchmarkRunner(b, level.New(log.NewNopLogger(), level.Config{
Allowed: level.AllowAll(),
}))
}
func BenchmarkJSONBaseline(b *testing.B) {
benchmarkRunner(b, log.NewJSONLogger(ioutil.Discard))
}
func BenchmarkJSONDisallowedLevel(b *testing.B) {
benchmarkRunner(b, level.New(log.NewJSONLogger(ioutil.Discard), level.Config{
Allowed: level.AllowInfoAndAbove(),
}))
}
func BenchmarkJSONAllowedLevel(b *testing.B) {
benchmarkRunner(b, level.New(log.NewJSONLogger(ioutil.Discard), level.Config{
Allowed: level.AllowAll(),
}))
}
func BenchmarkLogfmtBaseline(b *testing.B) {
benchmarkRunner(b, log.NewLogfmtLogger(ioutil.Discard))
}
func BenchmarkLogfmtDisallowedLevel(b *testing.B) {
benchmarkRunner(b, level.New(log.NewLogfmtLogger(ioutil.Discard), level.Config{
Allowed: level.AllowInfoAndAbove(),
}))
}
func BenchmarkLogfmtAllowedLevel(b *testing.B) {
benchmarkRunner(b, level.New(log.NewLogfmtLogger(ioutil.Discard), level.Config{
Allowed: level.AllowAll(),
}))
}
func benchmarkRunner(b *testing.B, logger log.Logger) {
b.ResetTimer()
b.ReportAllocs()
for i := 0; i < b.N; i++ {
level.Debug(logger).Log("foo", "bar")
}
}

View File

@@ -0,0 +1,27 @@
// Package level is an EXPERIMENTAL levelled logging package. The API will
// definitely have breaking changes and may be deleted altogether. Be warned!
//
// To use the level package, create a logger as per normal in your func main,
// and wrap it with level.New.
//
// var logger log.Logger
// logger = log.NewLogfmtLogger(os.Stderr)
// logger = level.New(logger, level.Config{Allowed: level.AllowInfoAndAbove}) // <--
// logger = log.NewContext(logger).With("ts", log.DefaultTimestampUTC)
//
// Then, at the callsites, use one of the level.Debug, Info, Warn, or Error
// helper methods to emit leveled log events.
//
// logger.Log("foo", "bar") // as normal, no level
// level.Debug(logger).Log("request_id", reqID, "trace_data", trace.Get())
// if value > 100 {
// level.Error(logger).Log("value", value)
// }
//
// The leveled logger allows precise control over what should happen if a log
// event is emitted without a level key, or if a squelched level is used. Check
// the Config struct for details. And, you can easily use non-default level
// values: create new string constants for whatever you want to change, pass
// them explicitly to the Config struct, and write your own level.Foo-style
// helper methods.
package level

View File

@@ -0,0 +1,146 @@
package level
import (
"github.com/go-kit/kit/log"
)
var (
levelKey = "level"
errorLevelValue = "error"
warnLevelValue = "warn"
infoLevelValue = "info"
debugLevelValue = "debug"
)
// AllowAll is an alias for AllowDebugAndAbove.
func AllowAll() []string {
return AllowDebugAndAbove()
}
// AllowDebugAndAbove allows all of the four default log levels.
// Its return value may be provided as the Allowed parameter in the Config.
func AllowDebugAndAbove() []string {
return []string{errorLevelValue, warnLevelValue, infoLevelValue, debugLevelValue}
}
// AllowInfoAndAbove allows the default info, warn, and error log levels.
// Its return value may be provided as the Allowed parameter in the Config.
func AllowInfoAndAbove() []string {
return []string{errorLevelValue, warnLevelValue, infoLevelValue}
}
// AllowWarnAndAbove allows the default warn and error log levels.
// Its return value may be provided as the Allowed parameter in the Config.
func AllowWarnAndAbove() []string {
return []string{errorLevelValue, warnLevelValue}
}
// AllowErrorOnly allows only the default error log level.
// Its return value may be provided as the Allowed parameter in the Config.
func AllowErrorOnly() []string {
return []string{errorLevelValue}
}
// AllowNone allows none of the default log levels.
// Its return value may be provided as the Allowed parameter in the Config.
func AllowNone() []string {
return []string{}
}
// Error returns a logger with the level key set to ErrorLevelValue.
func Error(logger log.Logger) log.Logger {
return log.NewContext(logger).With(levelKey, errorLevelValue)
}
// Warn returns a logger with the level key set to WarnLevelValue.
func Warn(logger log.Logger) log.Logger {
return log.NewContext(logger).With(levelKey, warnLevelValue)
}
// Info returns a logger with the level key set to InfoLevelValue.
func Info(logger log.Logger) log.Logger {
return log.NewContext(logger).With(levelKey, infoLevelValue)
}
// Debug returns a logger with the level key set to DebugLevelValue.
func Debug(logger log.Logger) log.Logger {
return log.NewContext(logger).With(levelKey, debugLevelValue)
}
// Config parameterizes the leveled logger.
type Config struct {
// Allowed enumerates the accepted log levels. If a log event is encountered
// with a level key set to a value that isn't explicitly allowed, the event
// will be squelched, and ErrNotAllowed returned.
Allowed []string
// ErrNotAllowed is returned to the caller when Log is invoked with a level
// key that hasn't been explicitly allowed. By default, ErrNotAllowed is
// nil; in this case, the log event is squelched with no error.
ErrNotAllowed error
// SquelchNoLevel will squelch log events with no level key, so that they
// don't proceed through to the wrapped logger. If SquelchNoLevel is set to
// true and a log event is squelched in this way, ErrNoLevel is returned to
// the caller.
SquelchNoLevel bool
// ErrNoLevel is returned to the caller when SquelchNoLevel is true, and Log
// is invoked without a level key. By default, ErrNoLevel is nil; in this
// case, the log event is squelched with no error.
ErrNoLevel error
}
// New wraps the logger and implements level checking. See the commentary on the
// Config object for a detailed description of how to configure levels.
func New(next log.Logger, config Config) log.Logger {
return &logger{
next: next,
allowed: makeSet(config.Allowed),
errNotAllowed: config.ErrNotAllowed,
squelchNoLevel: config.SquelchNoLevel,
errNoLevel: config.ErrNoLevel,
}
}
type logger struct {
next log.Logger
allowed map[string]struct{}
errNotAllowed error
squelchNoLevel bool
errNoLevel error
}
func (l *logger) Log(keyvals ...interface{}) error {
var hasLevel, levelAllowed bool
for i := 0; i < len(keyvals); i += 2 {
if k, ok := keyvals[i].(string); !ok || k != levelKey {
continue
}
hasLevel = true
if i >= len(keyvals) {
continue
}
v, ok := keyvals[i+1].(string)
if !ok {
continue
}
_, levelAllowed = l.allowed[v]
break
}
if !hasLevel && l.squelchNoLevel {
return l.errNoLevel
}
if hasLevel && !levelAllowed {
return l.errNotAllowed
}
return l.next.Log(keyvals...)
}
func makeSet(a []string) map[string]struct{} {
m := make(map[string]struct{}, len(a))
for _, s := range a {
m[s] = struct{}{}
}
return m
}

View File

@@ -0,0 +1,154 @@
package level_test
import (
"bytes"
"errors"
"strings"
"testing"
"github.com/go-kit/kit/log"
"github.com/go-kit/kit/log/experimental_level"
)
func TestVariousLevels(t *testing.T) {
for _, testcase := range []struct {
allowed []string
want string
}{
{
level.AllowAll(),
strings.Join([]string{
`{"level":"debug","this is":"debug log"}`,
`{"level":"info","this is":"info log"}`,
`{"level":"warn","this is":"warn log"}`,
`{"level":"error","this is":"error log"}`,
}, "\n"),
},
{
level.AllowDebugAndAbove(),
strings.Join([]string{
`{"level":"debug","this is":"debug log"}`,
`{"level":"info","this is":"info log"}`,
`{"level":"warn","this is":"warn log"}`,
`{"level":"error","this is":"error log"}`,
}, "\n"),
},
{
level.AllowInfoAndAbove(),
strings.Join([]string{
`{"level":"info","this is":"info log"}`,
`{"level":"warn","this is":"warn log"}`,
`{"level":"error","this is":"error log"}`,
}, "\n"),
},
{
level.AllowWarnAndAbove(),
strings.Join([]string{
`{"level":"warn","this is":"warn log"}`,
`{"level":"error","this is":"error log"}`,
}, "\n"),
},
{
level.AllowErrorOnly(),
strings.Join([]string{
`{"level":"error","this is":"error log"}`,
}, "\n"),
},
{
level.AllowNone(),
``,
},
} {
var buf bytes.Buffer
logger := level.New(log.NewJSONLogger(&buf), level.Config{Allowed: testcase.allowed})
level.Debug(logger).Log("this is", "debug log")
level.Info(logger).Log("this is", "info log")
level.Warn(logger).Log("this is", "warn log")
level.Error(logger).Log("this is", "error log")
if want, have := testcase.want, strings.TrimSpace(buf.String()); want != have {
t.Errorf("given Allowed=%v: want\n%s\nhave\n%s", testcase.allowed, want, have)
}
}
}
func TestErrNotAllowed(t *testing.T) {
myError := errors.New("squelched!")
logger := level.New(log.NewNopLogger(), level.Config{
Allowed: level.AllowWarnAndAbove(),
ErrNotAllowed: myError,
})
if want, have := myError, level.Info(logger).Log("foo", "bar"); want != have {
t.Errorf("want %#+v, have %#+v", want, have)
}
if want, have := error(nil), level.Warn(logger).Log("foo", "bar"); want != have {
t.Errorf("want %#+v, have %#+v", want, have)
}
}
func TestErrNoLevel(t *testing.T) {
myError := errors.New("no level specified")
var buf bytes.Buffer
logger := level.New(log.NewJSONLogger(&buf), level.Config{
SquelchNoLevel: true,
ErrNoLevel: myError,
})
if want, have := myError, logger.Log("foo", "bar"); want != have {
t.Errorf("want %v, have %v", want, have)
}
if want, have := ``, strings.TrimSpace(buf.String()); want != have {
t.Errorf("want %q, have %q", want, have)
}
}
func TestAllowNoLevel(t *testing.T) {
var buf bytes.Buffer
logger := level.New(log.NewJSONLogger(&buf), level.Config{
SquelchNoLevel: false,
ErrNoLevel: errors.New("I should never be returned!"),
})
if want, have := error(nil), logger.Log("foo", "bar"); want != have {
t.Errorf("want %v, have %v", want, have)
}
if want, have := `{"foo":"bar"}`, strings.TrimSpace(buf.String()); want != have {
t.Errorf("want %q, have %q", want, have)
}
}
func TestLevelContext(t *testing.T) {
var buf bytes.Buffer
// Wrapping the level logger with a context allows users to use
// log.DefaultCaller as per normal.
var logger log.Logger
logger = log.NewLogfmtLogger(&buf)
logger = level.New(logger, level.Config{Allowed: level.AllowAll()})
logger = log.NewContext(logger).With("caller", log.DefaultCaller)
level.Info(logger).Log("foo", "bar")
if want, have := `caller=level_test.go:134 level=info foo=bar`, strings.TrimSpace(buf.String()); want != have {
t.Errorf("want %q, have %q", want, have)
}
}
func TestContextLevel(t *testing.T) {
var buf bytes.Buffer
// Wrapping a context with the level logger still works, but requires users
// to specify a higher callstack depth value.
var logger log.Logger
logger = log.NewLogfmtLogger(&buf)
logger = log.NewContext(logger).With("caller", log.Caller(5))
logger = level.New(logger, level.Config{Allowed: level.AllowAll()})
level.Info(logger).Log("foo", "bar")
if want, have := `caller=level_test.go:150 level=info foo=bar`, strings.TrimSpace(buf.String()); want != have {
t.Errorf("want %q, have %q", want, have)
}
}

View File

@@ -13,7 +13,7 @@ func TestJSONLoggerCaller(t *testing.T) {
t.Parallel()
buf := &bytes.Buffer{}
logger := log.NewJSONLogger(buf)
logger = log.With(logger, "caller", log.DefaultCaller)
logger = log.NewContext(logger).With("caller", log.DefaultCaller)
if err := logger.Log(); err != nil {
t.Fatal(err)

View File

@@ -1,72 +0,0 @@
package level_test
import (
"io/ioutil"
"testing"
"github.com/go-kit/kit/log"
"github.com/go-kit/kit/log/level"
)
func Benchmark(b *testing.B) {
contexts := []struct {
name string
context func(log.Logger) log.Logger
}{
{"NoContext", func(l log.Logger) log.Logger {
return l
}},
{"TimeContext", func(l log.Logger) log.Logger {
return log.With(l, "time", log.DefaultTimestampUTC)
}},
{"CallerContext", func(l log.Logger) log.Logger {
return log.With(l, "caller", log.DefaultCaller)
}},
{"TimeCallerReqIDContext", func(l log.Logger) log.Logger {
return log.With(l, "time", log.DefaultTimestampUTC, "caller", log.DefaultCaller, "reqID", 29)
}},
}
loggers := []struct {
name string
logger log.Logger
}{
{"Nop", log.NewNopLogger()},
{"Logfmt", log.NewLogfmtLogger(ioutil.Discard)},
{"JSON", log.NewJSONLogger(ioutil.Discard)},
}
filters := []struct {
name string
filter func(log.Logger) log.Logger
}{
{"Baseline", func(l log.Logger) log.Logger {
return l
}},
{"DisallowedLevel", func(l log.Logger) log.Logger {
return level.NewFilter(l, level.AllowInfo())
}},
{"AllowedLevel", func(l log.Logger) log.Logger {
return level.NewFilter(l, level.AllowAll())
}},
}
for _, c := range contexts {
b.Run(c.name, func(b *testing.B) {
for _, f := range filters {
b.Run(f.name, func(b *testing.B) {
for _, l := range loggers {
b.Run(l.name, func(b *testing.B) {
logger := c.context(f.filter(l.logger))
b.ResetTimer()
b.ReportAllocs()
for i := 0; i < b.N; i++ {
level.Debug(logger).Log("foo", "bar")
}
})
}
})
}
})
}
}

View File

@@ -1,22 +0,0 @@
// Package level implements leveled logging on top of package log. To use the
// level package, create a logger as per normal in your func main, and wrap it
// with level.NewFilter.
//
// var logger log.Logger
// logger = log.NewLogfmtLogger(os.Stderr)
// logger = level.NewFilter(logger, level.AllowInfoAndAbove()) // <--
// logger = log.NewContext(logger).With("ts", log.DefaultTimestampUTC)
//
// Then, at the callsites, use one of the level.Debug, Info, Warn, or Error
// helper methods to emit leveled log events.
//
// logger.Log("foo", "bar") // as normal, no level
// level.Debug(logger).Log("request_id", reqID, "trace_data", trace.Get())
// if value > 100 {
// level.Error(logger).Log("value", value)
// }
//
// NewFilter allows precise control over what happens when a log event is
// emitted without a level key, or if a squelched level is used. Check the
// Option functions for details.
package level

View File

@@ -1,25 +0,0 @@
package level_test
import (
"errors"
"os"
"github.com/go-kit/kit/log"
"github.com/go-kit/kit/log/level"
)
func Example_basic() {
// setup logger with level filter
logger := log.NewLogfmtLogger(os.Stdout)
logger = level.NewFilter(logger, level.AllowInfo())
logger = log.With(logger, "caller", log.DefaultCaller)
// use level helpers to log at different levels
level.Error(logger).Log("err", errors.New("bad data"))
level.Info(logger).Log("event", "data saved")
level.Debug(logger).Log("next item", 17) // filtered
// Output:
// level=error caller=example_test.go:18 err="bad data"
// level=info caller=example_test.go:19 event="data saved"
}

View File

@@ -1,205 +0,0 @@
package level
import "github.com/go-kit/kit/log"
// Error returns a logger that includes a Key/ErrorValue pair.
func Error(logger log.Logger) log.Logger {
return log.WithPrefix(logger, Key(), ErrorValue())
}
// Warn returns a logger that includes a Key/WarnValue pair.
func Warn(logger log.Logger) log.Logger {
return log.WithPrefix(logger, Key(), WarnValue())
}
// Info returns a logger that includes a Key/InfoValue pair.
func Info(logger log.Logger) log.Logger {
return log.WithPrefix(logger, Key(), InfoValue())
}
// Debug returns a logger that includes a Key/DebugValue pair.
func Debug(logger log.Logger) log.Logger {
return log.WithPrefix(logger, Key(), DebugValue())
}
// NewFilter wraps next and implements level filtering. See the commentary on
// the Option functions for a detailed description of how to configure levels.
// If no options are provided, all leveled log events created with Debug,
// Info, Warn or Error helper methods are squelched and non-leveled log
// events are passed to next unmodified.
func NewFilter(next log.Logger, options ...Option) log.Logger {
l := &logger{
next: next,
}
for _, option := range options {
option(l)
}
return l
}
type logger struct {
next log.Logger
allowed level
squelchNoLevel bool
errNotAllowed error
errNoLevel error
}
func (l *logger) Log(keyvals ...interface{}) error {
var hasLevel, levelAllowed bool
for i := 1; i < len(keyvals); i += 2 {
if v, ok := keyvals[i].(*levelValue); ok {
hasLevel = true
levelAllowed = l.allowed&v.level != 0
break
}
}
if !hasLevel && l.squelchNoLevel {
return l.errNoLevel
}
if hasLevel && !levelAllowed {
return l.errNotAllowed
}
return l.next.Log(keyvals...)
}
// Option sets a parameter for the leveled logger.
type Option func(*logger)
// AllowAll is an alias for AllowDebug.
func AllowAll() Option {
return AllowDebug()
}
// AllowDebug allows error, warn, info and debug level log events to pass.
func AllowDebug() Option {
return allowed(levelError | levelWarn | levelInfo | levelDebug)
}
// AllowInfo allows error, warn and info level log events to pass.
func AllowInfo() Option {
return allowed(levelError | levelWarn | levelInfo)
}
// AllowWarn allows error and warn level log events to pass.
func AllowWarn() Option {
return allowed(levelError | levelWarn)
}
// AllowError allows only error level log events to pass.
func AllowError() Option {
return allowed(levelError)
}
// AllowNone allows no leveled log events to pass.
func AllowNone() Option {
return allowed(0)
}
func allowed(allowed level) Option {
return func(l *logger) { l.allowed = allowed }
}
// ErrNotAllowed sets the error to return from Log when it squelches a log
// event disallowed by the configured Allow[Level] option. By default,
// ErrNotAllowed is nil; in this case the log event is squelched with no
// error.
func ErrNotAllowed(err error) Option {
return func(l *logger) { l.errNotAllowed = err }
}
// SquelchNoLevel instructs Log to squelch log events with no level, so that
// they don't proceed through to the wrapped logger. If SquelchNoLevel is set
// to true and a log event is squelched in this way, the error value
// configured with ErrNoLevel is returned to the caller.
func SquelchNoLevel(squelch bool) Option {
return func(l *logger) { l.squelchNoLevel = squelch }
}
// ErrNoLevel sets the error to return from Log when it squelches a log event
// with no level. By default, ErrNoLevel is nil; in this case the log event is
// squelched with no error.
func ErrNoLevel(err error) Option {
return func(l *logger) { l.errNoLevel = err }
}
// NewInjector wraps next and returns a logger that adds a Key/level pair to
// the beginning of log events that don't already contain a level. In effect,
// this gives a default level to logs without a level.
func NewInjector(next log.Logger, level Value) log.Logger {
return &injector{
next: next,
level: level,
}
}
type injector struct {
next log.Logger
level interface{}
}
func (l *injector) Log(keyvals ...interface{}) error {
for i := 1; i < len(keyvals); i += 2 {
if _, ok := keyvals[i].(*levelValue); ok {
return l.next.Log(keyvals...)
}
}
kvs := make([]interface{}, len(keyvals)+2)
kvs[0], kvs[1] = key, l.level
copy(kvs[2:], keyvals)
return l.next.Log(kvs...)
}
// Value is the interface that each of the canonical level values implement.
// It contains unexported methods that prevent types from other packages from
// implementing it and guaranteeing that NewFilter can distinguish the levels
// defined in this package from all other values.
type Value interface {
String() string
levelVal()
}
// Key returns the unique key added to log events by the loggers in this
// package.
func Key() interface{} { return key }
// ErrorValue returns the unique value added to log events by Error.
func ErrorValue() Value { return errorValue }
// WarnValue returns the unique value added to log events by Warn.
func WarnValue() Value { return warnValue }
// InfoValue returns the unique value added to log events by Info.
func InfoValue() Value { return infoValue }
// DebugValue returns the unique value added to log events by Warn.
func DebugValue() Value { return debugValue }
var (
// key is of type interfae{} so that it allocates once during package
// initialization and avoids allocating every type the value is added to a
// []interface{} later.
key interface{} = "level"
errorValue = &levelValue{level: levelError, name: "error"}
warnValue = &levelValue{level: levelWarn, name: "warn"}
infoValue = &levelValue{level: levelInfo, name: "info"}
debugValue = &levelValue{level: levelDebug, name: "debug"}
)
type level byte
const (
levelDebug level = 1 << iota
levelInfo
levelWarn
levelError
)
type levelValue struct {
name string
level
}
func (v *levelValue) String() string { return v.name }
func (v *levelValue) levelVal() {}

View File

@@ -1,235 +0,0 @@
package level_test
import (
"bytes"
"errors"
"io"
"strings"
"testing"
"github.com/go-kit/kit/log"
"github.com/go-kit/kit/log/level"
)
func TestVariousLevels(t *testing.T) {
testCases := []struct {
name string
allowed level.Option
want string
}{
{
"AllowAll",
level.AllowAll(),
strings.Join([]string{
`{"level":"debug","this is":"debug log"}`,
`{"level":"info","this is":"info log"}`,
`{"level":"warn","this is":"warn log"}`,
`{"level":"error","this is":"error log"}`,
}, "\n"),
},
{
"AllowDebug",
level.AllowDebug(),
strings.Join([]string{
`{"level":"debug","this is":"debug log"}`,
`{"level":"info","this is":"info log"}`,
`{"level":"warn","this is":"warn log"}`,
`{"level":"error","this is":"error log"}`,
}, "\n"),
},
{
"AllowDebug",
level.AllowInfo(),
strings.Join([]string{
`{"level":"info","this is":"info log"}`,
`{"level":"warn","this is":"warn log"}`,
`{"level":"error","this is":"error log"}`,
}, "\n"),
},
{
"AllowWarn",
level.AllowWarn(),
strings.Join([]string{
`{"level":"warn","this is":"warn log"}`,
`{"level":"error","this is":"error log"}`,
}, "\n"),
},
{
"AllowError",
level.AllowError(),
strings.Join([]string{
`{"level":"error","this is":"error log"}`,
}, "\n"),
},
{
"AllowNone",
level.AllowNone(),
``,
},
}
for _, tc := range testCases {
t.Run(tc.name, func(t *testing.T) {
var buf bytes.Buffer
logger := level.NewFilter(log.NewJSONLogger(&buf), tc.allowed)
level.Debug(logger).Log("this is", "debug log")
level.Info(logger).Log("this is", "info log")
level.Warn(logger).Log("this is", "warn log")
level.Error(logger).Log("this is", "error log")
if want, have := tc.want, strings.TrimSpace(buf.String()); want != have {
t.Errorf("\nwant:\n%s\nhave:\n%s", want, have)
}
})
}
}
func TestErrNotAllowed(t *testing.T) {
myError := errors.New("squelched!")
opts := []level.Option{
level.AllowWarn(),
level.ErrNotAllowed(myError),
}
logger := level.NewFilter(log.NewNopLogger(), opts...)
if want, have := myError, level.Info(logger).Log("foo", "bar"); want != have {
t.Errorf("want %#+v, have %#+v", want, have)
}
if want, have := error(nil), level.Warn(logger).Log("foo", "bar"); want != have {
t.Errorf("want %#+v, have %#+v", want, have)
}
}
func TestErrNoLevel(t *testing.T) {
myError := errors.New("no level specified")
var buf bytes.Buffer
opts := []level.Option{
level.SquelchNoLevel(true),
level.ErrNoLevel(myError),
}
logger := level.NewFilter(log.NewJSONLogger(&buf), opts...)
if want, have := myError, logger.Log("foo", "bar"); want != have {
t.Errorf("want %v, have %v", want, have)
}
if want, have := ``, strings.TrimSpace(buf.String()); want != have {
t.Errorf("\nwant '%s'\nhave '%s'", want, have)
}
}
func TestAllowNoLevel(t *testing.T) {
var buf bytes.Buffer
opts := []level.Option{
level.SquelchNoLevel(false),
level.ErrNoLevel(errors.New("I should never be returned!")),
}
logger := level.NewFilter(log.NewJSONLogger(&buf), opts...)
if want, have := error(nil), logger.Log("foo", "bar"); want != have {
t.Errorf("want %v, have %v", want, have)
}
if want, have := `{"foo":"bar"}`, strings.TrimSpace(buf.String()); want != have {
t.Errorf("\nwant '%s'\nhave '%s'", want, have)
}
}
func TestLevelContext(t *testing.T) {
var buf bytes.Buffer
// Wrapping the level logger with a context allows users to use
// log.DefaultCaller as per normal.
var logger log.Logger
logger = log.NewLogfmtLogger(&buf)
logger = level.NewFilter(logger, level.AllowAll())
logger = log.With(logger, "caller", log.DefaultCaller)
level.Info(logger).Log("foo", "bar")
if want, have := `level=info caller=level_test.go:149 foo=bar`, strings.TrimSpace(buf.String()); want != have {
t.Errorf("\nwant '%s'\nhave '%s'", want, have)
}
}
func TestContextLevel(t *testing.T) {
var buf bytes.Buffer
// Wrapping a context with the level logger still works, but requires users
// to specify a higher callstack depth value.
var logger log.Logger
logger = log.NewLogfmtLogger(&buf)
logger = log.With(logger, "caller", log.Caller(5))
logger = level.NewFilter(logger, level.AllowAll())
level.Info(logger).Log("foo", "bar")
if want, have := `caller=level_test.go:165 level=info foo=bar`, strings.TrimSpace(buf.String()); want != have {
t.Errorf("\nwant '%s'\nhave '%s'", want, have)
}
}
func TestLevelFormatting(t *testing.T) {
testCases := []struct {
name string
format func(io.Writer) log.Logger
output string
}{
{
name: "logfmt",
format: log.NewLogfmtLogger,
output: `level=info foo=bar`,
},
{
name: "JSON",
format: log.NewJSONLogger,
output: `{"foo":"bar","level":"info"}`,
},
}
for _, tc := range testCases {
t.Run(tc.name, func(t *testing.T) {
var buf bytes.Buffer
logger := tc.format(&buf)
level.Info(logger).Log("foo", "bar")
if want, have := tc.output, strings.TrimSpace(buf.String()); want != have {
t.Errorf("\nwant: '%s'\nhave '%s'", want, have)
}
})
}
}
func TestInjector(t *testing.T) {
var (
output []interface{}
logger log.Logger
)
logger = log.LoggerFunc(func(keyvals ...interface{}) error {
output = keyvals
return nil
})
logger = level.NewInjector(logger, level.InfoValue())
logger.Log("foo", "bar")
if got, want := len(output), 4; got != want {
t.Errorf("missing level not injected: got len==%d, want len==%d", got, want)
}
if got, want := output[0], level.Key(); got != want {
t.Errorf("wrong level key: got %#v, want %#v", got, want)
}
if got, want := output[1], level.InfoValue(); got != want {
t.Errorf("wrong level value: got %#v, want %#v", got, want)
}
level.Error(logger).Log("foo", "bar")
if got, want := len(output), 4; got != want {
t.Errorf("leveled record modified: got len==%d, want len==%d", got, want)
}
if got, want := output[0], level.Key(); got != want {
t.Errorf("wrong level key: got %#v, want %#v", got, want)
}
if got, want := output[1], level.ErrorValue(); got != want {
t.Errorf("wrong level value: got %#v, want %#v", got, want)
}
}

View File

@@ -7,7 +7,7 @@ import "github.com/go-kit/kit/log"
// want a different set of levels, you can create your own levels type very
// easily, and you can elide the configuration.
type Levels struct {
logger log.Logger
ctx *log.Context
levelKey string
// We have a choice between storing level values in string fields or
@@ -34,7 +34,7 @@ type Levels struct {
// New creates a new leveled logger, wrapping the passed logger.
func New(logger log.Logger, options ...Option) Levels {
l := Levels{
logger: logger,
ctx: log.NewContext(logger),
levelKey: "level",
debugValue: "debug",
@@ -52,7 +52,7 @@ func New(logger log.Logger, options ...Option) Levels {
// With returns a new leveled logger that includes keyvals in all log events.
func (l Levels) With(keyvals ...interface{}) Levels {
return Levels{
logger: log.With(l.logger, keyvals...),
ctx: l.ctx.With(keyvals...),
levelKey: l.levelKey,
debugValue: l.debugValue,
infoValue: l.infoValue,
@@ -64,27 +64,27 @@ func (l Levels) With(keyvals ...interface{}) Levels {
// Debug returns a debug level logger.
func (l Levels) Debug() log.Logger {
return log.WithPrefix(l.logger, l.levelKey, l.debugValue)
return l.ctx.WithPrefix(l.levelKey, l.debugValue)
}
// Info returns an info level logger.
func (l Levels) Info() log.Logger {
return log.WithPrefix(l.logger, l.levelKey, l.infoValue)
return l.ctx.WithPrefix(l.levelKey, l.infoValue)
}
// Warn returns a warning level logger.
func (l Levels) Warn() log.Logger {
return log.WithPrefix(l.logger, l.levelKey, l.warnValue)
return l.ctx.WithPrefix(l.levelKey, l.warnValue)
}
// Error returns an error level logger.
func (l Levels) Error() log.Logger {
return log.WithPrefix(l.logger, l.levelKey, l.errorValue)
return l.ctx.WithPrefix(l.levelKey, l.errorValue)
}
// Crit returns a critical level logger.
func (l Levels) Crit() log.Logger {
return log.WithPrefix(l.logger, l.levelKey, l.critValue)
return l.ctx.WithPrefix(l.levelKey, l.critValue)
}
// Option sets a parameter for leveled loggers.

View File

@@ -6,7 +6,7 @@ import (
"testing"
"github.com/go-kit/kit/log"
levels "github.com/go-kit/kit/log/deprecated_levels"
"github.com/go-kit/kit/log/levels"
)
func TestDefaultLevels(t *testing.T) {

View File

@@ -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 or retains any of its elements must make a copy first.
// modifies any of its elements must make a copy first.
type Logger interface {
Log(keyvals ...interface{}) error
}
@@ -15,100 +15,62 @@ type Logger interface {
// the missing value.
var ErrMissingValue = errors.New("(MISSING)")
// 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.
//
// 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
}
l := newContext(logger)
kvs := append(l.keyvals, keyvals...)
if len(kvs)%2 != 0 {
kvs = append(kvs, ErrMissingValue)
}
return &context{
logger: l.logger,
// Limiting the capacity of the stored keyvals ensures that a new
// backing array is created if the slice must grow in Log or With.
// Using the extra capacity without copying risks a data race that
// would violate the Logger interface contract.
keyvals: kvs[:len(kvs):len(kvs)],
hasValuer: l.hasValuer || containsValuer(keyvals),
// 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}
}
// 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
}
l := newContext(logger)
// Limiting the capacity of the stored keyvals ensures that a new
// backing array is created if the slice must grow in Log or With.
// Using the extra capacity without copying risks a data race that
// would violate the Logger interface contract.
n := len(l.keyvals) + len(keyvals)
if len(keyvals)%2 != 0 {
n++
}
kvs := make([]interface{}, 0, n)
kvs = append(kvs, keyvals...)
if len(kvs)%2 != 0 {
kvs = append(kvs, ErrMissingValue)
}
kvs = append(kvs, l.keyvals...)
return &context{
logger: l.logger,
keyvals: kvs,
hasValuer: l.hasValuer || containsValuer(keyvals),
}
}
// 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
// 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
// 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.
//
// Two implementation details provide the needed stack depth consistency.
// 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 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 {
// 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.
//
// 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
}
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 {
func (l *Context) Log(keyvals ...interface{}) error {
kvs := append(l.keyvals, keyvals...)
if len(kvs)%2 != 0 {
kvs = append(kvs, ErrMissingValue)
@@ -124,6 +86,53 @@ func (l *context) Log(keyvals ...interface{}) error {
return l.logger.Log(kvs...)
}
// With returns a new Context with keyvals appended to those of the receiver.
func (l *Context) With(keyvals ...interface{}) *Context {
if len(keyvals) == 0 {
return l
}
kvs := append(l.keyvals, keyvals...)
if len(kvs)%2 != 0 {
kvs = append(kvs, ErrMissingValue)
}
return &Context{
logger: l.logger,
// Limiting the capacity of the stored keyvals ensures that a new
// backing array is created if the slice must grow in Log or With.
// Using the extra capacity without copying risks a data race that
// would violate the Logger interface contract.
keyvals: kvs[:len(kvs):len(kvs)],
hasValuer: l.hasValuer || containsValuer(keyvals),
}
}
// WithPrefix returns a new Context with keyvals prepended to those of the
// receiver.
func (l *Context) WithPrefix(keyvals ...interface{}) *Context {
if len(keyvals) == 0 {
return l
}
// Limiting the capacity of the stored keyvals ensures that a new
// backing array is created if the slice must grow in Log or With.
// Using the extra capacity without copying risks a data race that
// would violate the Logger interface contract.
n := len(l.keyvals) + len(keyvals)
if len(keyvals)%2 != 0 {
n++
}
kvs := make([]interface{}, 0, n)
kvs = append(kvs, keyvals...)
if len(kvs)%2 != 0 {
kvs = append(kvs, ErrMissingValue)
}
kvs = append(kvs, l.keyvals...)
return &Context{
logger: l.logger,
keyvals: kvs,
hasValuer: l.hasValuer || containsValuer(keyvals),
}
}
// 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.

View File

@@ -16,10 +16,10 @@ func TestContext(t *testing.T) {
logger := log.NewLogfmtLogger(buf)
kvs := []interface{}{"a", 123}
lc := log.With(logger, kvs...)
lc := log.NewContext(logger).With(kvs...)
kvs[1] = 0 // With should copy its key values
lc = log.With(lc, "b", "c") // With should stack
lc = lc.With("b", "c") // With should stack
if err := lc.Log("msg", "message"); err != nil {
t.Fatal(err)
}
@@ -28,7 +28,7 @@ func TestContext(t *testing.T) {
}
buf.Reset()
lc = log.WithPrefix(lc, "p", "first")
lc = lc.WithPrefix("p", "first")
if err := lc.Log("msg", "message"); err != nil {
t.Fatal(err)
}
@@ -45,7 +45,17 @@ func TestContextMissingValue(t *testing.T) {
return nil
}))
log.WithPrefix(log.With(logger, "k1"), "k0").Log("k2")
lc := log.NewContext(logger)
lc.Log("k")
if want, have := 2, len(output); want != have {
t.Errorf("want len(output) == %v, have %v", want, have)
}
if want, have := log.ErrMissingValue, output[1]; want != have {
t.Errorf("want %#v, have %#v", want, have)
}
lc.With("k1").WithPrefix("k0").Log("k2")
if want, have := 6, len(output); want != have {
t.Errorf("want len(output) == %v, have %v", want, have)
}
@@ -56,8 +66,10 @@ func TestContextMissingValue(t *testing.T) {
}
}
// Test that context.Log has a consistent function stack depth when binding
// Valuers, regardless of how many times With has been called.
// Test that Context.Log has a consistent function stack depth when binding
// log.Valuers, regardless of how many times Context.With has been called or
// whether Context.Log is called via an interface typed variable or a concrete
// typed variable.
func TestContextStackDepth(t *testing.T) {
t.Parallel()
fn := fmt.Sprintf("%n", stack.Caller(0))
@@ -79,25 +91,32 @@ func TestContextStackDepth(t *testing.T) {
return nil
})
logger = log.With(logger, "stack", stackValuer)
concrete := log.NewContext(logger).With("stack", stackValuer)
var iface log.Logger = concrete
// Call through interface to get baseline.
logger.Log("k", "v")
iface.Log("k", "v")
want := output[1].(int)
for len(output) < 10 {
logger.Log("k", "v")
concrete.Log("k", "v")
if have := output[1]; have != want {
t.Errorf("%d Withs: have %v, want %v", len(output)/2-1, have, want)
}
wrapped := log.With(logger)
iface.Log("k", "v")
if have := output[1]; have != want {
t.Errorf("%d Withs: have %v, want %v", len(output)/2-1, have, want)
}
wrapped := log.NewContext(concrete)
wrapped.Log("k", "v")
if have := output[1]; have != want {
t.Errorf("%d Withs: have %v, want %v", len(output)/2-1, have, want)
}
logger = log.With(logger, "k", "v")
concrete = concrete.With("k", "v")
iface = concrete
}
}
@@ -121,7 +140,7 @@ func TestWithConcurrent(t *testing.T) {
// With must be careful about handling slices that can grow without
// copying the underlying array, so give it a challenge.
l := log.With(logger, make([]interface{}, 0, 2)...)
l := log.NewContext(logger).With(make([]interface{}, 0, 2)...)
// Start logging concurrently. Each goroutine logs its id so the logger
// can bucket the event counts.
@@ -156,7 +175,7 @@ func BenchmarkDiscard(b *testing.B) {
func BenchmarkOneWith(b *testing.B) {
logger := log.NewNopLogger()
lc := log.With(logger, "k", "v")
lc := log.NewContext(logger).With("k", "v")
b.ReportAllocs()
b.ResetTimer()
for i := 0; i < b.N; i++ {
@@ -166,9 +185,9 @@ func BenchmarkOneWith(b *testing.B) {
func BenchmarkTwoWith(b *testing.B) {
logger := log.NewNopLogger()
lc := log.With(logger, "k", "v")
lc := log.NewContext(logger).With("k", "v")
for i := 1; i < 2; i++ {
lc = log.With(lc, "k", "v")
lc = lc.With("k", "v")
}
b.ReportAllocs()
b.ResetTimer()
@@ -179,9 +198,9 @@ func BenchmarkTwoWith(b *testing.B) {
func BenchmarkTenWith(b *testing.B) {
logger := log.NewNopLogger()
lc := log.With(logger, "k", "v")
lc := log.NewContext(logger).With("k", "v")
for i := 1; i < 10; i++ {
lc = log.With(lc, "k", "v")
lc = lc.With("k", "v")
}
b.ReportAllocs()
b.ResetTimer()

View File

@@ -12,7 +12,7 @@ func TestNopLogger(t *testing.T) {
if err := logger.Log("abc", 123); err != nil {
t.Error(err)
}
if err := log.With(logger, "def", "ghi").Log(); err != nil {
if err := log.NewContext(logger).With("def", "ghi").Log(); err != nil {
t.Error(err)
}
}

View File

@@ -39,7 +39,7 @@ func TimestampKey(key string) StdlibAdapterOption {
return func(a *StdlibAdapter) { a.timestampKey = key }
}
// FileKey sets the key for the file and line field. By default, it's "caller".
// FileKey sets the key for the file and line field. By default, it's "file".
func FileKey(key string) StdlibAdapterOption {
return func(a *StdlibAdapter) { a.fileKey = key }
}
@@ -55,7 +55,7 @@ func NewStdlibAdapter(logger Logger, options ...StdlibAdapterOption) io.Writer {
a := StdlibAdapter{
Logger: logger,
timestampKey: "ts",
fileKey: "caller",
fileKey: "file",
messageKey: "msg",
}
for _, option := range options {

View File

@@ -35,9 +35,9 @@ func TestStdlibAdapterUsage(t *testing.T) {
log.Ldate: "ts=" + date + " msg=hello\n",
log.Ltime: "ts=" + time + " msg=hello\n",
log.Ldate | log.Ltime: "ts=\"" + date + " " + time + "\" msg=hello\n",
log.Lshortfile: "caller=stdlib_test.go:44 msg=hello\n",
log.Lshortfile | log.Ldate: "ts=" + date + " caller=stdlib_test.go:44 msg=hello\n",
log.Lshortfile | log.Ldate | log.Ltime: "ts=\"" + date + " " + time + "\" caller=stdlib_test.go:44 msg=hello\n",
log.Lshortfile: "file=stdlib_test.go:44 msg=hello\n",
log.Lshortfile | log.Ldate: "ts=" + date + " file=stdlib_test.go:44 msg=hello\n",
log.Lshortfile | log.Ldate | log.Ltime: "ts=\"" + date + " " + time + "\" file=stdlib_test.go:44 msg=hello\n",
} {
buf.Reset()
stdlog.SetFlags(flag)
@@ -58,11 +58,11 @@ func TestStdLibAdapterExtraction(t *testing.T) {
"2009/01/23 01:23:23: hello": "ts=\"2009/01/23 01:23:23\" msg=hello\n",
"01:23:23: hello": "ts=01:23:23 msg=hello\n",
"2009/01/23 01:23:23.123123: hello": "ts=\"2009/01/23 01:23:23.123123\" msg=hello\n",
"2009/01/23 01:23:23.123123 /a/b/c/d.go:23: hello": "ts=\"2009/01/23 01:23:23.123123\" caller=/a/b/c/d.go:23 msg=hello\n",
"01:23:23.123123 /a/b/c/d.go:23: hello": "ts=01:23:23.123123 caller=/a/b/c/d.go:23 msg=hello\n",
"2009/01/23 01:23:23 /a/b/c/d.go:23: hello": "ts=\"2009/01/23 01:23:23\" caller=/a/b/c/d.go:23 msg=hello\n",
"2009/01/23 /a/b/c/d.go:23: hello": "ts=2009/01/23 caller=/a/b/c/d.go:23 msg=hello\n",
"/a/b/c/d.go:23: hello": "caller=/a/b/c/d.go:23 msg=hello\n",
"2009/01/23 01:23:23.123123 /a/b/c/d.go:23: hello": "ts=\"2009/01/23 01:23:23.123123\" file=/a/b/c/d.go:23 msg=hello\n",
"01:23:23.123123 /a/b/c/d.go:23: hello": "ts=01:23:23.123123 file=/a/b/c/d.go:23 msg=hello\n",
"2009/01/23 01:23:23 /a/b/c/d.go:23: hello": "ts=\"2009/01/23 01:23:23\" file=/a/b/c/d.go:23 msg=hello\n",
"2009/01/23 /a/b/c/d.go:23: hello": "ts=2009/01/23 file=/a/b/c/d.go:23 msg=hello\n",
"/a/b/c/d.go:23: hello": "file=/a/b/c/d.go:23 msg=hello\n",
} {
buf.Reset()
fmt.Fprint(writer, input)

View File

@@ -42,7 +42,7 @@ const (
// https://en.wikipedia.org/wiki/ANSI_escape_code#Colors.
var (
resetColorBytes = []byte("\x1b[39;49;22m")
resetColorBytes = []byte("\x1b[39;49m")
fgColorBytes [][]byte
bgColorBytes [][]byte
)

View File

@@ -27,7 +27,7 @@ func TestColorLogger(t *testing.T) {
if err := logger.Log("a", 1); err != nil {
t.Fatal(err)
}
if want, have := "\x1b[32;1m\x1b[47;1ma=1\n\x1b[39;49;22m", buf.String(); want != have {
if want, have := "\x1b[32;1m\x1b[47;1ma=1\n\x1b[39;49m", buf.String(); want != have {
t.Errorf("\nwant %#v\nhave %#v", want, have)
}
}
@@ -56,7 +56,7 @@ func TestColorLoggerConcurrency(t *testing.T) {
// copied from log/benchmark_test.go
func benchmarkRunner(b *testing.B, logger log.Logger, f func(log.Logger)) {
lc := log.With(logger, "common_key", "common_value")
lc := log.NewContext(logger).With("common_key", "common_value")
b.ReportAllocs()
b.ResetTimer()
for i := 0; i < b.N; i++ {
@@ -66,7 +66,7 @@ func benchmarkRunner(b *testing.B, logger log.Logger, f func(log.Logger)) {
var (
baseMessage = func(logger log.Logger) { logger.Log("foo_key", "foo_value") }
withMessage = func(logger log.Logger) { log.With(logger, "a", "b").Log("c", "d") }
withMessage = func(logger log.Logger) { log.NewContext(logger).With("a", "b").Log("c", "d") }
)
// copied from log/concurrency_test.go

View File

@@ -6,9 +6,9 @@ import (
"github.com/go-stack/stack"
)
// A Valuer generates a log value. When passed to With or WithPrefix in a
// value element (odd indexes), it represents a dynamic value which is re-
// evaluated with each log event.
// A Valuer generates a log value. When passed to Context.With in a value
// element (odd indexes), it represents a dynamic value which is re-evaluated
// with each log event.
type Valuer func() interface{}
// bindValues replaces all value elements (odd indexes) containing a Valuer
@@ -39,6 +39,16 @@ func Timestamp(t func() time.Time) Valuer {
return func() interface{} { return t() }
}
var (
// DefaultTimestamp is a Valuer that returns the current wallclock time,
// respecting time zones, when bound.
DefaultTimestamp Valuer = func() interface{} { return time.Now().Format(time.RFC3339) }
// DefaultTimestampUTC is a Valuer that returns the current time in UTC
// when bound.
DefaultTimestampUTC Valuer = func() interface{} { return time.Now().UTC().Format(time.RFC3339) }
)
// Caller returns a Valuer that returns a file and line from a specified depth
// in the callstack. Users will probably want to use DefaultCaller.
func Caller(depth int) Valuer {
@@ -46,18 +56,6 @@ func Caller(depth int) Valuer {
}
var (
// DefaultTimestamp is a Valuer that returns the current wallclock time,
// respecting time zones, when bound.
DefaultTimestamp = Valuer(func() interface{} {
return time.Now().Format(time.RFC3339Nano)
})
// DefaultTimestampUTC is a Valuer that returns the current time in UTC
// when bound.
DefaultTimestampUTC = Valuer(func() interface{} {
return time.Now().UTC().Format(time.RFC3339Nano)
})
// DefaultCaller is a Valuer that returns the file and line where the Log
// method was invoked. It can only be used with log.With.
DefaultCaller = Caller(3)

View File

@@ -24,7 +24,7 @@ func TestValueBinding(t *testing.T) {
return now
}
lc := log.With(logger, "ts", log.Timestamp(mocktime), "caller", log.DefaultCaller)
lc := log.NewContext(logger).With("ts", log.Timestamp(mocktime), "caller", log.DefaultCaller)
lc.Log("foo", "bar")
timestamp, ok := output[1].(time.Time)
@@ -68,7 +68,7 @@ func TestValueBinding_loggingZeroKeyvals(t *testing.T) {
return now
}
logger = log.With(logger, "ts", log.Timestamp(mocktime))
logger = log.NewContext(logger).With("ts", log.Timestamp(mocktime))
logger.Log()
timestamp, ok := output[1].(time.Time)
@@ -92,7 +92,7 @@ func TestValueBinding_loggingZeroKeyvals(t *testing.T) {
func BenchmarkValueBindingTimestamp(b *testing.B) {
logger := log.NewNopLogger()
lc := log.With(logger, "ts", log.DefaultTimestamp)
lc := log.NewContext(logger).With("ts", log.DefaultTimestamp)
b.ReportAllocs()
b.ResetTimer()
for i := 0; i < b.N; i++ {
@@ -102,7 +102,7 @@ func BenchmarkValueBindingTimestamp(b *testing.B) {
func BenchmarkValueBindingCaller(b *testing.B) {
logger := log.NewNopLogger()
lc := log.With(logger, "caller", log.DefaultCaller)
lc := log.NewContext(logger).With("caller", log.DefaultCaller)
b.ReportAllocs()
b.ResetTimer()
for i := 0; i < b.N; i++ {