From 5739c2646c7293c773ed50d2086e843e3330781c Mon Sep 17 00:00:00 2001 From: Peter Bourgon Date: Tue, 6 Apr 2021 20:55:00 +0200 Subject: [PATCH] Initial import from go-kit/kit (#1) * Initial import, minus logrus and zap * GitHub Actions for CI * gofmt * Satisfy staticcheck * It was a nice idea * Satisfy staticcheck --- .github/workflows/test.yml | 37 ++++ README.md | 157 ++++++++++++++- benchmark_test.go | 21 ++ concurrency_test.go | 40 ++++ doc.go | 116 +++++++++++ example_test.go | 137 +++++++++++++ go.mod | 8 + go.sum | 4 + json_logger.go | 91 +++++++++ json_logger_test.go | 174 +++++++++++++++++ level/benchmark_test.go | 72 +++++++ level/doc.go | 22 +++ level/example_test.go | 39 ++++ level/level.go | 205 ++++++++++++++++++++ level/level_test.go | 235 +++++++++++++++++++++++ log.go | 179 +++++++++++++++++ log_test.go | 349 ++++++++++++++++++++++++++++++++++ logfmt_logger.go | 62 ++++++ logfmt_logger_test.go | 57 ++++++ nop_logger.go | 8 + nop_logger_test.go | 26 +++ stdlib.go | 151 +++++++++++++++ stdlib_test.go | 261 +++++++++++++++++++++++++ sync.go | 113 +++++++++++ sync_test.go | 101 ++++++++++ syslog/example_test.go | 29 +++ syslog/syslog.go | 147 ++++++++++++++ syslog/syslog_test.go | 170 +++++++++++++++++ term/LICENSE | 21 ++ term/colorlogger.go | 144 ++++++++++++++ term/colorlogger_test.go | 88 +++++++++ term/colorwriter_others.go | 12 ++ term/colorwriter_windows.go | 188 ++++++++++++++++++ term/example_test.go | 57 ++++++ term/term.go | 22 +++ term/terminal_darwin.go | 10 + term/terminal_freebsd.go | 7 + term/terminal_linux.go | 12 ++ term/terminal_notwindows.go | 25 +++ term/terminal_openbsd.go | 5 + term/terminal_stub.go | 15 ++ term/terminal_windows.go | 102 ++++++++++ term/terminal_windows_test.go | 69 +++++++ value.go | 110 +++++++++++ value_test.go | 150 +++++++++++++++ 45 files changed, 4046 insertions(+), 2 deletions(-) create mode 100644 .github/workflows/test.yml create mode 100644 benchmark_test.go create mode 100644 concurrency_test.go create mode 100644 doc.go create mode 100644 example_test.go create mode 100644 go.mod create mode 100644 go.sum create mode 100644 json_logger.go create mode 100644 json_logger_test.go create mode 100644 level/benchmark_test.go create mode 100644 level/doc.go create mode 100644 level/example_test.go create mode 100644 level/level.go create mode 100644 level/level_test.go create mode 100644 log.go create mode 100644 log_test.go create mode 100644 logfmt_logger.go create mode 100644 logfmt_logger_test.go create mode 100644 nop_logger.go create mode 100644 nop_logger_test.go create mode 100644 stdlib.go create mode 100644 stdlib_test.go create mode 100644 sync.go create mode 100644 sync_test.go create mode 100644 syslog/example_test.go create mode 100644 syslog/syslog.go create mode 100644 syslog/syslog_test.go create mode 100644 term/LICENSE create mode 100644 term/colorlogger.go create mode 100644 term/colorlogger_test.go create mode 100644 term/colorwriter_others.go create mode 100644 term/colorwriter_windows.go create mode 100644 term/example_test.go create mode 100644 term/term.go create mode 100644 term/terminal_darwin.go create mode 100644 term/terminal_freebsd.go create mode 100644 term/terminal_linux.go create mode 100644 term/terminal_notwindows.go create mode 100644 term/terminal_openbsd.go create mode 100644 term/terminal_stub.go create mode 100644 term/terminal_windows.go create mode 100644 term/terminal_windows_test.go create mode 100644 value.go create mode 100644 value_test.go diff --git a/.github/workflows/test.yml b/.github/workflows/test.yml new file mode 100644 index 0000000..7dc1486 --- /dev/null +++ b/.github/workflows/test.yml @@ -0,0 +1,37 @@ +on: push +name: Test +jobs: + test: + strategy: + matrix: + go-version: [1.16.x] + platform: [ubuntu-latest, macos-latest, windows-latest] + runs-on: ${{ matrix.platform }} + steps: + - name: Install Go + uses: actions/setup-go@v1 + with: + go-version: ${{ matrix.go-version }} + - name: Install staticcheck + run: go install honnef.co/go/tools/cmd/staticcheck@latest + shell: bash + - name: Install golint + run: go install golang.org/x/lint/golint@latest + shell: bash + - name: Update PATH + run: echo "$(go env GOPATH)/bin" >> $GITHUB_PATH + shell: bash + - name: Checkout code + uses: actions/checkout@v1 + - name: Fmt + if: matrix.platform != 'windows-latest' # :( + run: "diff <(gofmt -d .) <(printf '')" + shell: bash + - name: Vet + run: go vet ./... + - name: Staticcheck + run: staticcheck ./... + - name: Lint + run: golint ./... + - name: Test + run: go test -race ./... diff --git a/README.md b/README.md index 4f2698f..cdafd4b 100644 --- a/README.md +++ b/README.md @@ -1,2 +1,155 @@ -# log -A minimal and extensible structured logger +

:warning:   PRE-RELEASE   :warning:

+

DO NOT IMPORT THIS MODULE

+

YOUR PROJECT WILL BREAK

+ +# 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. + +## 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. + +```go +// Unstructured +log.Printf("HTTP server listening on %s", addr) + +// Structured +logger.Log("transport", "HTTP", "addr", addr, "msg", "listening") +``` + +## Usage + +### Typical application logging + +```go +w := log.NewSyncWriter(os.Stderr) +logger := log.NewLogfmtLogger(w) +logger.Log("question", "what is the meaning of life?", "answer", 42) + +// Output: +// question="what is the meaning of life?" answer=42 +``` + +### Contextual Loggers + +```go +func main() { + var logger log.Logger + logger = log.NewLogfmtLogger(log.NewSyncWriter(os.Stderr)) + logger = log.With(logger, "instance_id", 123) + + logger.Log("msg", "starting") + NewWorker(log.With(logger, "component", "worker")).Run() + NewSlacker(log.With(logger, "component", "slacker")).Run() +} + +// Output: +// instance_id=123 msg=starting +// instance_id=123 component=worker msg=running +// instance_id=123 component=slacker msg=running +``` + +### Interact with stdlib logger + +Redirect stdlib logger to Go kit logger. + +```go +import ( + "os" + stdlog "log" + kitlog "github.com/go-kit/log" +) + +func main() { + logger := kitlog.NewJSONLogger(kitlog.NewSyncWriter(os.Stdout)) + stdlog.SetOutput(kitlog.NewStdlibAdapter(logger)) + stdlog.Print("I sure like pie") +} + +// Output: +// {"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. + +```go +logger := kitlog.NewLogfmtLogger(kitlog.StdlibWriter{}) +logger.Log("legacy", true, "msg", "at least it's something") + +// Output: +// 2016/01/01 12:34:56 legacy=true msg="at least it's something" +``` + +### Timestamps and callers + +```go +var logger log.Logger +logger = log.NewLogfmtLogger(log.NewSyncWriter(os.Stderr)) +logger = log.With(logger, "ts", log.DefaultTimestampUTC, "caller", log.DefaultCaller) + +logger.Log("msg", "hello") + +// Output: +// ts=2016-01-01T12:34:56Z caller=main.go:15 msg=hello +``` + +## Levels + +Log levels are supported via the [level package](https://godoc.org/github.com/go-kit/log/level). + +## Supported output formats + +- [Logfmt](https://brandur.org/logfmt) ([see also](https://blog.codeship.com/logfmt-a-log-format-thats-easy-to-read-and-write)) +- JSON + +## Enhancements + +`package log` is centered on the one-method Logger interface. + +```go +type Logger interface { + Log(keyvals ...interface{}) error +} +``` + +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. + +Value-add packages and suggestions, +like improvements to [the leveled logger](https://godoc.org/github.com/go-kit/log/level), +are of course welcome. Good proposals should + +- Be composable with [contextual loggers](https://godoc.org/github.com/go-kit/log#With), +- Not break the behavior of [log.Caller](https://godoc.org/github.com/go-kit/log#Caller) in any wrapped contextual loggers, and +- Be friendly to packages that accept only an unadorned log.Logger. + +## Benchmarks & comparisons + +There are a few Go logging benchmarks and comparisons that include Go kit's package log. + +- [imkira/go-loggers-bench](https://github.com/imkira/go-loggers-bench) includes kit/log +- [uber-common/zap](https://github.com/uber-common/zap), a zero-alloc logging library, includes a comparison with kit/log diff --git a/benchmark_test.go b/benchmark_test.go new file mode 100644 index 0000000..785ca7c --- /dev/null +++ b/benchmark_test.go @@ -0,0 +1,21 @@ +package log_test + +import ( + "testing" + + "github.com/go-kit/log" +) + +func benchmarkRunner(b *testing.B, logger log.Logger, f func(log.Logger)) { + lc := log.With(logger, "common_key", "common_value") + b.ReportAllocs() + b.ResetTimer() + for i := 0; i < b.N; i++ { + f(lc) + } +} + +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") } +) diff --git a/concurrency_test.go b/concurrency_test.go new file mode 100644 index 0000000..91999d3 --- /dev/null +++ b/concurrency_test.go @@ -0,0 +1,40 @@ +package log_test + +import ( + "math" + "testing" + + "github.com/go-kit/log" +) + +// These test are designed to be run with the race detector. + +func testConcurrency(t *testing.T, logger log.Logger, total int) { + n := int(math.Sqrt(float64(total))) + share := total / n + + errC := make(chan error, n) + + for i := 0; i < n; i++ { + go func() { + errC <- spam(logger, share) + }() + } + + for i := 0; i < n; i++ { + err := <-errC + if err != nil { + t.Fatalf("concurrent logging error: %v", err) + } + } +} + +func spam(logger log.Logger, count int) error { + for i := 0; i < count; i++ { + err := logger.Log("key", i) + if err != nil { + return err + } + } + return nil +} diff --git a/doc.go b/doc.go new file mode 100644 index 0000000..f744382 --- /dev/null +++ b/doc.go @@ -0,0 +1,116 @@ +// Package log provides a structured logger. +// +// 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. 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. +// +// Contextual Loggers +// +// 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, WithPrefix, and WithSuffix +// 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) +// 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. 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. +// 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.NewSyncWriter(os.Stdout)) +// logger = log.With(logger, "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 +// two simple solutions for concurrent safe logging. +// +// NewSyncWriter wraps an 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 call 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. +// +// 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 diff --git a/example_test.go b/example_test.go new file mode 100644 index 0000000..ec0c23c --- /dev/null +++ b/example_test.go @@ -0,0 +1,137 @@ +package log_test + +import ( + "math/rand" + "os" + "sync" + "time" + + "github.com/go-kit/log" +) + +func Example_basic() { + logger := log.NewLogfmtLogger(os.Stdout) + + type Task struct { + ID int + } + + 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_contextual() { + 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.With(logger, "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: + // taskID=1 event="starting task" + // taskID=1 cmd="echo Hello, world!" dur=42ms + // taskID=1 event="task complete" +} + +func Example_valuer() { + logger := log.NewLogfmtLogger(os.Stdout) + + count := 0 + counter := func() interface{} { + count++ + return count + } + + logger = log.With(logger, "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.With(logger, "time", log.Timestamp(mockTime), "caller", log.DefaultCaller) + + logger.Log("call", "first") + logger.Log("call", "second") + + // ... + + 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" +} diff --git a/go.mod b/go.mod new file mode 100644 index 0000000..7c87949 --- /dev/null +++ b/go.mod @@ -0,0 +1,8 @@ +module github.com/go-kit/log + +go 1.16 + +require ( + github.com/go-logfmt/logfmt v0.5.0 + github.com/go-stack/stack v1.8.0 +) diff --git a/go.sum b/go.sum new file mode 100644 index 0000000..59a7cf6 --- /dev/null +++ b/go.sum @@ -0,0 +1,4 @@ +github.com/go-logfmt/logfmt v0.5.0 h1:TrB8swr/68K7m9CcGut2g3UOihhbcbiMAYiuTXdEih4= +github.com/go-logfmt/logfmt v0.5.0/go.mod h1:wCYkCAKZfumFQihp8CzCvQ3paCTfi41vtzG1KdI/P7A= +github.com/go-stack/stack v1.8.0 h1:5SgMzNM5HxrEjV0ww2lTmX6E2Izsfxas4+YHWRs3Lsk= +github.com/go-stack/stack v1.8.0/go.mod h1:v0f6uXyyMGvRgIKkXu+yp6POWl0qKG85gN/melR3HDY= diff --git a/json_logger.go b/json_logger.go new file mode 100644 index 0000000..0cedbf8 --- /dev/null +++ b/json_logger.go @@ -0,0 +1,91 @@ +package log + +import ( + "encoding" + "encoding/json" + "fmt" + "io" + "reflect" +) + +type jsonLogger struct { + io.Writer +} + +// NewJSONLogger returns a Logger that encodes keyvals to the Writer as a +// 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} +} + +func (l *jsonLogger) Log(keyvals ...interface{}) error { + n := (len(keyvals) + 1) / 2 // +1 to handle case when len is odd + m := make(map[string]interface{}, n) + for i := 0; i < len(keyvals); i += 2 { + k := keyvals[i] + var v interface{} = ErrMissingValue + if i+1 < len(keyvals) { + v = keyvals[i+1] + } + merge(m, k, v) + } + enc := json.NewEncoder(l.Writer) + enc.SetEscapeHTML(false) + return enc.Encode(m) +} + +func merge(dst map[string]interface{}, k, v interface{}) { + var key string + switch x := k.(type) { + case string: + key = x + case fmt.Stringer: + key = safeString(x) + default: + key = fmt.Sprint(x) + } + + // We want json.Marshaler and encoding.TextMarshaller to take priority over + // err.Error() and v.String(). But json.Marshall (called later) does that by + // default so we force a no-op if it's one of those 2 case. + switch x := v.(type) { + case json.Marshaler: + case encoding.TextMarshaler: + case error: + v = safeError(x) + case fmt.Stringer: + v = safeString(x) + } + + dst[key] = v +} + +func safeString(str fmt.Stringer) (s string) { + defer func() { + if panicVal := recover(); panicVal != nil { + if v := reflect.ValueOf(str); v.Kind() == reflect.Ptr && v.IsNil() { + s = "NULL" + } else { + panic(panicVal) + } + } + }() + s = str.String() + return +} + +func safeError(err error) (s interface{}) { + defer func() { + if panicVal := recover(); panicVal != nil { + if v := reflect.ValueOf(err); v.Kind() == reflect.Ptr && v.IsNil() { + s = nil + } else { + panic(panicVal) + } + } + }() + s = err.Error() + return +} diff --git a/json_logger_test.go b/json_logger_test.go new file mode 100644 index 0000000..cb049dd --- /dev/null +++ b/json_logger_test.go @@ -0,0 +1,174 @@ +package log_test + +import ( + "bytes" + "errors" + "io/ioutil" + "testing" + + "github.com/go-kit/log" +) + +func TestJSONLoggerCaller(t *testing.T) { + t.Parallel() + buf := &bytes.Buffer{} + logger := log.NewJSONLogger(buf) + logger = log.With(logger, "caller", log.DefaultCaller) + + if err := logger.Log(); err != nil { + t.Fatal(err) + } + if want, have := `{"caller":"json_logger_test.go:18"}`+"\n", buf.String(); want != have { + t.Errorf("\nwant %#v\nhave %#v", want, have) + } +} + +func TestJSONLogger(t *testing.T) { + t.Parallel() + buf := &bytes.Buffer{} + logger := log.NewJSONLogger(buf) + if err := logger.Log("err", errors.New("err"), "m", map[string]int{"0": 0}, "a", []int{1, 2, 3}); err != nil { + t.Fatal(err) + } + if want, have := `{"a":[1,2,3],"err":"err","m":{"0":0}}`+"\n", buf.String(); want != have { + t.Errorf("\nwant %#v\nhave %#v", want, have) + } +} + +func TestJSONLoggerMissingValue(t *testing.T) { + t.Parallel() + buf := &bytes.Buffer{} + logger := log.NewJSONLogger(buf) + if err := logger.Log("k"); err != nil { + t.Fatal(err) + } + if want, have := `{"k":"(MISSING)"}`+"\n", buf.String(); want != have { + t.Errorf("\nwant %#v\nhave %#v", want, have) + } +} + +func TestJSONLoggerNilStringerKey(t *testing.T) { + t.Parallel() + + buf := &bytes.Buffer{} + logger := log.NewJSONLogger(buf) + if err := logger.Log((*stringer)(nil), "v"); err != nil { + t.Fatal(err) + } + if want, have := `{"NULL":"v"}`+"\n", buf.String(); want != have { + t.Errorf("\nwant %#v\nhave %#v", want, have) + } +} + +func TestJSONLoggerNilErrorValue(t *testing.T) { + t.Parallel() + + buf := &bytes.Buffer{} + logger := log.NewJSONLogger(buf) + if err := logger.Log("err", (*stringError)(nil)); err != nil { + t.Fatal(err) + } + if want, have := `{"err":null}`+"\n", buf.String(); want != have { + t.Errorf("\nwant %#v\nhave %#v", want, have) + } +} + +func TestJSONLoggerNoHTMLEscape(t *testing.T) { + t.Parallel() + buf := &bytes.Buffer{} + logger := log.NewJSONLogger(buf) + if err := logger.Log("k", "<&>"); err != nil { + t.Fatal(err) + } + if want, have := `{"k":"<&>"}`+"\n", buf.String(); want != have { + t.Errorf("\nwant %#v\nhave%#v", want, have) + } +} + +// aller implements json.Marshaler, encoding.TextMarshaler, and fmt.Stringer. +type aller struct{} + +func (aller) MarshalJSON() ([]byte, error) { + return []byte("\"json\""), nil +} + +func (aller) MarshalText() ([]byte, error) { + return []byte("text"), nil +} + +func (aller) String() string { + return "string" +} + +func (aller) Error() string { + return "error" +} + +// textstringer implements encoding.TextMarshaler and fmt.Stringer. +type textstringer struct{} + +func (textstringer) MarshalText() ([]byte, error) { + return []byte("text"), nil +} + +func (textstringer) String() string { + return "string" +} + +func TestJSONLoggerStringValue(t *testing.T) { + t.Parallel() + tests := []struct { + v interface{} + expected string + }{ + { + v: aller{}, + expected: `{"v":"json"}`, + }, + { + v: textstringer{}, + expected: `{"v":"text"}`, + }, + { + v: stringer("string"), + expected: `{"v":"string"}`, + }, + } + + for _, test := range tests { + buf := &bytes.Buffer{} + logger := log.NewJSONLogger(buf) + if err := logger.Log("v", test.v); err != nil { + t.Fatal(err) + } + + if want, have := test.expected+"\n", buf.String(); want != have { + t.Errorf("\nwant %#v\nhave %#v", want, have) + } + } +} + +type stringer string + +func (s stringer) String() string { + return string(s) +} + +type stringError string + +func (s stringError) Error() string { + return string(s) +} + +func BenchmarkJSONLoggerSimple(b *testing.B) { + benchmarkRunner(b, log.NewJSONLogger(ioutil.Discard), baseMessage) +} + +func BenchmarkJSONLoggerContextual(b *testing.B) { + benchmarkRunner(b, log.NewJSONLogger(ioutil.Discard), withMessage) +} + +func TestJSONLoggerConcurrency(t *testing.T) { + t.Parallel() + testConcurrency(t, log.NewJSONLogger(ioutil.Discard), 10000) +} diff --git a/level/benchmark_test.go b/level/benchmark_test.go new file mode 100644 index 0000000..0e50fcb --- /dev/null +++ b/level/benchmark_test.go @@ -0,0 +1,72 @@ +package level_test + +import ( + "io/ioutil" + "testing" + + "github.com/go-kit/log" + "github.com/go-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") + } + }) + } + }) + } + }) + } +} diff --git a/level/doc.go b/level/doc.go new file mode 100644 index 0000000..505d307 --- /dev/null +++ b/level/doc.go @@ -0,0 +1,22 @@ +// Package level implements leveled logging on top of Go kit's log package. 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.AllowInfo()) // <-- +// logger = log.With(logger, "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 diff --git a/level/example_test.go b/level/example_test.go new file mode 100644 index 0000000..5f59f21 --- /dev/null +++ b/level/example_test.go @@ -0,0 +1,39 @@ +package level_test + +import ( + "errors" + "os" + + "github.com/go-kit/log" + "github.com/go-kit/log/level" +) + +func Example_basic() { + logger := log.NewLogfmtLogger(os.Stdout) + level.Debug(logger).Log("msg", "this message is at the debug level") + level.Info(logger).Log("msg", "this message is at the info level") + level.Warn(logger).Log("msg", "this message is at the warn level") + level.Error(logger).Log("msg", "this message is at the error level") + + // Output: + // level=debug msg="this message is at the debug level" + // level=info msg="this message is at the info level" + // level=warn msg="this message is at the warn level" + // level=error msg="this message is at the error level" +} + +func Example_filtered() { + // Set up 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:32 err="bad data" + // level=info caller=example_test.go:33 event="data saved" +} diff --git a/level/level.go b/level/level.go new file mode 100644 index 0000000..c94756c --- /dev/null +++ b/level/level.go @@ -0,0 +1,205 @@ +package level + +import "github.com/go-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 Debug. +func DebugValue() Value { return debugValue } + +var ( + // key is of type interface{} so that it allocates once during package + // initialization and avoids allocating every time 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() {} diff --git a/level/level_test.go b/level/level_test.go new file mode 100644 index 0000000..035fa5d --- /dev/null +++ b/level/level_test.go @@ -0,0 +1,235 @@ +package level_test + +import ( + "bytes" + "errors" + "io" + "strings" + "testing" + + "github.com/go-kit/log" + "github.com/go-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"), + }, + { + "AllowInfo", + 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) + } +} diff --git a/log.go b/log.go new file mode 100644 index 0000000..62e11ad --- /dev/null +++ b/log.go @@ -0,0 +1,179 @@ +package log + +import "errors" + +// Logger is the fundamental interface for all log operations. Log creates a +// 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. +type Logger interface { + Log(keyvals ...interface{}) error +} + +// ErrMissingValue is appended to keyvals slices with odd length to substitute +// 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, +// WithPrefix, or WithSuffix, 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), + sKeyvals: l.sKeyvals, + sHasValuer: l.sHasValuer, + } +} + +// 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, WithPrefix, or WithSuffix, 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), + sKeyvals: l.sKeyvals, + sHasValuer: l.sHasValuer, + } +} + +// WithSuffix returns a new contextual logger with keyvals appended to those +// passed to calls to Log. If logger is also a contextual logger created by +// With, WithPrefix, or WithSuffix, 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 WithSuffix(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.sKeyvals) + 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(l.sKeyvals, kvs...) + return &context{ + logger: l.logger, + keyvals: l.keyvals, + hasValuer: l.hasValuer, + sKeyvals: kvs, + sHasValuer: l.sHasValuer || containsValuer(keyvals), + } +} + +// context is the Logger implementation returned by With, WithPrefix, and +// WithSuffix. 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, WithPrefix, and WithSuffix 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{} + sKeyvals []interface{} // suffixes + hasValuer bool + sHasValuer 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))]) + } + kvs = append(kvs, l.sKeyvals...) + if l.sHasValuer { + bindValues(kvs[len(kvs)-len(l.sKeyvals):]) + } + 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. +type LoggerFunc func(...interface{}) error + +// Log implements Logger by calling f(keyvals...). +func (f LoggerFunc) Log(keyvals ...interface{}) error { + return f(keyvals...) +} diff --git a/log_test.go b/log_test.go new file mode 100644 index 0000000..6b0cd5a --- /dev/null +++ b/log_test.go @@ -0,0 +1,349 @@ +package log_test + +import ( + "bytes" + "fmt" + "sync" + "testing" + + "github.com/go-kit/log" + "github.com/go-stack/stack" +) + +func TestContext(t *testing.T) { + t.Parallel() + buf := &bytes.Buffer{} + logger := log.NewLogfmtLogger(buf) + + kvs := []interface{}{"a", 123} + lc := log.With(logger, kvs...) + kvs[1] = 0 // With should copy its key values + + lc = log.With(lc, "b", "c") // With should stack + if err := lc.Log("msg", "message"); err != nil { + t.Fatal(err) + } + if want, have := "a=123 b=c msg=message\n", buf.String(); want != have { + t.Errorf("\nwant: %shave: %s", want, have) + } + + buf.Reset() + lc = log.WithPrefix(lc, "p", "first") + if err := lc.Log("msg", "message"); err != nil { + t.Fatal(err) + } + if want, have := "p=first a=123 b=c msg=message\n", buf.String(); want != have { + t.Errorf("\nwant: %shave: %s", want, have) + } +} + +func TestContextMissingValue(t *testing.T) { + t.Parallel() + var output []interface{} + logger := log.Logger(log.LoggerFunc(func(keyvals ...interface{}) error { + output = keyvals + return nil + })) + + log.WithPrefix(log.With(logger, "k1"), "k0").Log("k2") + if want, have := 6, len(output); want != have { + t.Errorf("want len(output) == %v, have %v", want, have) + } + for i := 1; i < 6; i += 2 { + if want, have := log.ErrMissingValue, output[i]; want != have { + t.Errorf("want output[%d] == %#v, have %#v", i, want, have) + } + } +} + +func TestWithPrefixAndSuffix(t *testing.T) { + t.Parallel() + var output []interface{} + logger := log.Logger(log.LoggerFunc(func(keyvals ...interface{}) error { + output = keyvals + return nil + })) + + lc := log.WithPrefix(logger, "a", "first") + lc = log.WithSuffix(lc, "z", "last") + if err := lc.Log("msg", "message"); err != nil { + t.Fatal(err) + } + if want, have := 6, len(output); want != have { + t.Errorf("want len(output) == %v, have %v", want, have) + } + want := []string{"a", "first", "msg", "message", "z", "last"} + for i := 0; i < 6; i++ { + if want, have := want[i], output[i]; want != have { + t.Errorf("want output[%d] == %#v, have %#v", i, want, have) + } + } + + lc = log.With(logger, "b", "second") + lc = log.WithPrefix(lc, "a", "first") + lc = log.With(lc, "c", "third") + lc = log.WithSuffix(lc, "z", "last") + lc = log.WithSuffix(lc, "aa", "sequel") + if err := lc.Log("msg", "message"); err != nil { + t.Fatal(err) + } + if want, have := 12, len(output); want != have { + t.Errorf("want len(output) == %v, have %v", want, have) + } + want = []string{ + "a", "first", + "b", "second", + "c", "third", + "msg", "message", + "z", "last", + "aa", "sequel", + } + for i := 0; i < 12; i++ { + if want, have := want[i], output[i]; want != have { + t.Errorf("want output[%d] == %#v, have %#v", i, want, have) + } + } +} + +// 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)) + + var output []interface{} + + logger := log.Logger(log.LoggerFunc(func(keyvals ...interface{}) error { + output = keyvals + return nil + })) + + stackValuer := log.Valuer(func() interface{} { + for i, c := range stack.Trace() { + if fmt.Sprintf("%n", c) == fn { + return i + } + } + t.Fatal("Test function not found in stack trace.") + return nil + }) + + logger = log.With(logger, "stack", stackValuer) + + // Call through interface to get baseline. + logger.Log("k", "v") + want := output[1].(int) + + for len(output) < 10 { + logger.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) + 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") + } +} + +// Test that With returns a Logger safe for concurrent use. This test +// validates that the stored logging context does not get corrupted when +// multiple clients concurrently log additional keyvals. +// +// This test must be run with go test -cpu 2 (or more) to achieve its goal. +func TestWithConcurrent(t *testing.T) { + // Create some buckets to count how many events each goroutine logs. + const goroutines = 8 + counts := [goroutines]int{} + + // This logger extracts a goroutine id from the last value field and + // increments the referenced bucket. + logger := log.LoggerFunc(func(kv ...interface{}) error { + goroutine := kv[len(kv)-1].(int) + counts[goroutine]++ + return nil + }) + + // 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)...) + + // Start logging concurrently. Each goroutine logs its id so the logger + // can bucket the event counts. + var wg sync.WaitGroup + wg.Add(goroutines) + const n = 10000 + for i := 0; i < goroutines; i++ { + go func(idx int) { + defer wg.Done() + for j := 0; j < n; j++ { + l.Log("goroutineIdx", idx) + } + }(i) + } + wg.Wait() + + for bucket, have := range counts { + if want := n; want != have { + t.Errorf("bucket %d: want %d, have %d", bucket, want, have) // note Errorf + } + } +} + +func TestLogCopiesValuers(t *testing.T) { + t.Parallel() + var output []interface{} + logger := log.Logger(log.LoggerFunc(func(keyvals ...interface{}) error { + output = keyvals + return nil + })) + + valuerCallCount := 0 + counterValuer := log.Valuer(func() interface{} { + valuerCallCount++ + return valuerCallCount + }) + lc := log.WithPrefix(logger, "a", counterValuer) + lc = log.WithSuffix(lc, "z", counterValuer) + + if err := lc.Log(); err != nil { + t.Fatal(err) + } + want := []interface{}{"a", 1, "z", 2} + for i := 0; i < 4; i++ { + if want, have := want[i], output[i]; want != have { + t.Errorf("want output[%d] == %#v, have %#v", i, want, have) + } + } + + if err := lc.Log(); err != nil { + t.Fatal(err) + } + want = []interface{}{"a", 3, "z", 4} + for i := 0; i < 4; i++ { + if want, have := want[i], output[i]; want != have { + t.Errorf("want output[%d] == %#v, have %#v", i, want, have) + } + } +} + +func BenchmarkDiscard(b *testing.B) { + logger := log.NewNopLogger() + b.ReportAllocs() + b.ResetTimer() + for i := 0; i < b.N; i++ { + logger.Log("k", "v") + } +} + +func BenchmarkOneWith(b *testing.B) { + logger := log.NewNopLogger() + lc := log.With(logger, "k", "v") + b.ReportAllocs() + b.ResetTimer() + for i := 0; i < b.N; i++ { + lc.Log("k", "v") + } +} + +func BenchmarkTwoWith(b *testing.B) { + logger := log.NewNopLogger() + lc := log.With(logger, "k", "v") + for i := 1; i < 2; i++ { + lc = log.With(lc, "k", "v") + } + b.ReportAllocs() + b.ResetTimer() + for i := 0; i < b.N; i++ { + lc.Log("k", "v") + } +} + +func BenchmarkTenWith(b *testing.B) { + logger := log.NewNopLogger() + lc := log.With(logger, "k", "v") + for i := 1; i < 10; i++ { + lc = log.With(lc, "k", "v") + } + b.ReportAllocs() + b.ResetTimer() + for i := 0; i < b.N; i++ { + lc.Log("k", "v") + } +} + +func BenchmarkOneWithPrefix(b *testing.B) { + logger := log.NewNopLogger() + lc := log.WithPrefix(logger, "a", "first") + b.ReportAllocs() + b.ResetTimer() + for i := 0; i < b.N; i++ { + lc.Log("k", "v") + } +} + +func BenchmarkTenWithPrefix(b *testing.B) { + logger := log.NewNopLogger() + lc := log.WithPrefix(logger, "a", "first") + for i := 1; i < 10; i++ { + lc = log.WithPrefix(lc, "a", "first") + } + b.ReportAllocs() + b.ResetTimer() + for i := 0; i < b.N; i++ { + lc.Log("k", "v") + } +} + +func BenchmarkOneWithSuffix(b *testing.B) { + logger := log.NewNopLogger() + lc := log.WithSuffix(logger, "z", "last") + b.ReportAllocs() + b.ResetTimer() + for i := 0; i < b.N; i++ { + lc.Log("k", "v") + } +} + +func BenchmarkTenWithSuffix(b *testing.B) { + logger := log.NewNopLogger() + lc := log.WithSuffix(logger, "z", "last") + for i := 1; i < 10; i++ { + lc = log.WithSuffix(lc, "z", "last") + } + b.ReportAllocs() + b.ResetTimer() + for i := 0; i < b.N; i++ { + lc.Log("k", "v") + } +} + +func BenchmarkOneWithPrefixSuffix(b *testing.B) { + logger := log.NewNopLogger() + lc := log.WithSuffix(logger, "a", "first") + lc = log.WithSuffix(lc, "z", "last") + b.ReportAllocs() + b.ResetTimer() + for i := 0; i < b.N; i++ { + lc.Log("k", "v") + } +} + +func BenchmarkTenWithPrefixSuffix(b *testing.B) { + logger := log.NewNopLogger() + lc := log.WithPrefix(logger, "a", "first") + lc = log.WithSuffix(lc, "z", "last") + for i := 1; i < 10; i++ { + lc = log.WithPrefix(lc, "a", "first") + lc = log.WithSuffix(lc, "z", "last") + } + b.ReportAllocs() + b.ResetTimer() + for i := 0; i < b.N; i++ { + lc.Log("k", "v") + } +} diff --git a/logfmt_logger.go b/logfmt_logger.go new file mode 100644 index 0000000..a003052 --- /dev/null +++ b/logfmt_logger.go @@ -0,0 +1,62 @@ +package log + +import ( + "bytes" + "io" + "sync" + + "github.com/go-logfmt/logfmt" +) + +type logfmtEncoder struct { + *logfmt.Encoder + buf bytes.Buffer +} + +func (l *logfmtEncoder) Reset() { + l.Encoder.Reset() + l.buf.Reset() +} + +var logfmtEncoderPool = sync.Pool{ + New: func() interface{} { + var enc logfmtEncoder + enc.Encoder = logfmt.NewEncoder(&enc.buf) + return &enc + }, +} + +type logfmtLogger struct { + w io.Writer +} + +// NewLogfmtLogger returns a logger that encodes keyvals to the Writer in +// 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} +} + +func (l logfmtLogger) Log(keyvals ...interface{}) error { + enc := logfmtEncoderPool.Get().(*logfmtEncoder) + enc.Reset() + defer logfmtEncoderPool.Put(enc) + + if err := enc.EncodeKeyvals(keyvals...); err != nil { + return err + } + + // Add newline to the end of the buffer + if err := enc.EndRecord(); err != nil { + return err + } + + // The Logger interface requires implementations to be safe for concurrent + // use by multiple goroutines. For this implementation that means making + // only one call to l.w.Write() for each call to Log. + if _, err := l.w.Write(enc.buf.Bytes()); err != nil { + return err + } + return nil +} diff --git a/logfmt_logger_test.go b/logfmt_logger_test.go new file mode 100644 index 0000000..ffb66d2 --- /dev/null +++ b/logfmt_logger_test.go @@ -0,0 +1,57 @@ +package log_test + +import ( + "bytes" + "errors" + "io/ioutil" + "testing" + + "github.com/go-kit/log" + "github.com/go-logfmt/logfmt" +) + +func TestLogfmtLogger(t *testing.T) { + t.Parallel() + buf := &bytes.Buffer{} + logger := log.NewLogfmtLogger(buf) + + if err := logger.Log("hello", "world"); err != nil { + t.Fatal(err) + } + if want, have := "hello=world\n", buf.String(); want != have { + t.Errorf("want %#v, have %#v", want, have) + } + + buf.Reset() + if err := logger.Log("a", 1, "err", errors.New("error")); err != nil { + t.Fatal(err) + } + if want, have := "a=1 err=error\n", buf.String(); want != have { + t.Errorf("want %#v, have %#v", want, have) + } + + buf.Reset() + if err := logger.Log("std_map", map[int]int{1: 2}, "my_map", mymap{0: 0}); err != nil { + t.Fatal(err) + } + if want, have := "std_map=\""+logfmt.ErrUnsupportedValueType.Error()+"\" my_map=special_behavior\n", buf.String(); want != have { + t.Errorf("want %#v, have %#v", want, have) + } +} + +func BenchmarkLogfmtLoggerSimple(b *testing.B) { + benchmarkRunner(b, log.NewLogfmtLogger(ioutil.Discard), baseMessage) +} + +func BenchmarkLogfmtLoggerContextual(b *testing.B) { + benchmarkRunner(b, log.NewLogfmtLogger(ioutil.Discard), withMessage) +} + +func TestLogfmtLoggerConcurrency(t *testing.T) { + t.Parallel() + testConcurrency(t, log.NewLogfmtLogger(ioutil.Discard), 10000) +} + +type mymap map[int]int + +func (m mymap) String() string { return "special_behavior" } diff --git a/nop_logger.go b/nop_logger.go new file mode 100644 index 0000000..1047d62 --- /dev/null +++ b/nop_logger.go @@ -0,0 +1,8 @@ +package log + +type nopLogger struct{} + +// NewNopLogger returns a logger that doesn't do anything. +func NewNopLogger() Logger { return nopLogger{} } + +func (nopLogger) Log(...interface{}) error { return nil } diff --git a/nop_logger_test.go b/nop_logger_test.go new file mode 100644 index 0000000..e44d492 --- /dev/null +++ b/nop_logger_test.go @@ -0,0 +1,26 @@ +package log_test + +import ( + "testing" + + "github.com/go-kit/log" +) + +func TestNopLogger(t *testing.T) { + t.Parallel() + logger := log.NewNopLogger() + if err := logger.Log("abc", 123); err != nil { + t.Error(err) + } + if err := log.With(logger, "def", "ghi").Log(); err != nil { + t.Error(err) + } +} + +func BenchmarkNopLoggerSimple(b *testing.B) { + benchmarkRunner(b, log.NewNopLogger(), baseMessage) +} + +func BenchmarkNopLoggerContextual(b *testing.B) { + benchmarkRunner(b, log.NewNopLogger(), withMessage) +} diff --git a/stdlib.go b/stdlib.go new file mode 100644 index 0000000..0338edb --- /dev/null +++ b/stdlib.go @@ -0,0 +1,151 @@ +package log + +import ( + "bytes" + "io" + "log" + "regexp" + "strings" +) + +// StdlibWriter implements io.Writer by invoking the stdlib log.Print. It's +// designed to be passed to a Go kit logger as the writer, for cases where +// it's necessary to redirect all Go kit log output to the stdlib logger. +// +// If you have any choice in the matter, you shouldn't use this. Prefer to +// redirect the stdlib log to the Go kit logger via NewStdlibAdapter. +type StdlibWriter struct{} + +// Write implements io.Writer. +func (w StdlibWriter) Write(p []byte) (int, error) { + log.Print(strings.TrimSpace(string(p))) + return len(p), nil +} + +// StdlibAdapter wraps a Logger and allows it to be passed to the stdlib +// logger's SetOutput. It will extract date/timestamps, filenames, and +// messages, and place them under relevant keys. +type StdlibAdapter struct { + Logger + timestampKey string + fileKey string + messageKey string + prefix string + joinPrefixToMsg bool +} + +// StdlibAdapterOption sets a parameter for the StdlibAdapter. +type StdlibAdapterOption func(*StdlibAdapter) + +// TimestampKey sets the key for the timestamp field. By default, it's "ts". +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". +func FileKey(key string) StdlibAdapterOption { + return func(a *StdlibAdapter) { a.fileKey = key } +} + +// MessageKey sets the key for the actual log message. By default, it's "msg". +func MessageKey(key string) StdlibAdapterOption { + return func(a *StdlibAdapter) { a.messageKey = key } +} + +// Prefix configures the adapter to parse a prefix from stdlib log events. If +// you provide a non-empty prefix to the stdlib logger, then your should provide +// that same prefix to the adapter via this option. +// +// By default, the prefix isn't included in the msg key. Set joinPrefixToMsg to +// true if you want to include the parsed prefix in the msg. +func Prefix(prefix string, joinPrefixToMsg bool) StdlibAdapterOption { + return func(a *StdlibAdapter) { a.prefix = prefix; a.joinPrefixToMsg = joinPrefixToMsg } +} + +// NewStdlibAdapter returns a new StdlibAdapter wrapper around the passed +// logger. It's designed to be passed to log.SetOutput. +func NewStdlibAdapter(logger Logger, options ...StdlibAdapterOption) io.Writer { + a := StdlibAdapter{ + Logger: logger, + timestampKey: "ts", + fileKey: "caller", + messageKey: "msg", + } + for _, option := range options { + option(&a) + } + return a +} + +func (a StdlibAdapter) Write(p []byte) (int, error) { + p = a.handlePrefix(p) + + result := subexps(p) + keyvals := []interface{}{} + var timestamp string + if date, ok := result["date"]; ok && date != "" { + timestamp = date + } + if time, ok := result["time"]; ok && time != "" { + if timestamp != "" { + timestamp += " " + } + timestamp += time + } + if timestamp != "" { + keyvals = append(keyvals, a.timestampKey, timestamp) + } + if file, ok := result["file"]; ok && file != "" { + keyvals = append(keyvals, a.fileKey, file) + } + if msg, ok := result["msg"]; ok { + msg = a.handleMessagePrefix(msg) + keyvals = append(keyvals, a.messageKey, msg) + } + if err := a.Logger.Log(keyvals...); err != nil { + return 0, err + } + return len(p), nil +} + +func (a StdlibAdapter) handlePrefix(p []byte) []byte { + if a.prefix != "" { + p = bytes.TrimPrefix(p, []byte(a.prefix)) + } + return p +} + +func (a StdlibAdapter) handleMessagePrefix(msg string) string { + if a.prefix == "" { + return msg + } + + msg = strings.TrimPrefix(msg, a.prefix) + if a.joinPrefixToMsg { + msg = a.prefix + msg + } + return msg +} + +const ( + logRegexpDate = `(?P[0-9]{4}/[0-9]{2}/[0-9]{2})?[ ]?` + logRegexpTime = `(?P