log

README

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

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

// Unstructured
log.Printf("HTTP server listening on %s", addr)

// Structured
logger.Log("transport", "HTTP", "addr", addr, "msg", "listening")

Usage

Typical application logging

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

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.

import (
	"os"
	stdlog "log"
	kitlog "github.com/AshleyDumaine/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.

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

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.

Supported output formats

• Logfmt (see also)
• JSON

Enhancements

package log is centered on the one-method Logger interface.

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, a talk by Chris Hines. Also, please see #63, #76, #131, #157, #164, and #252 to review historical conversations about package log and the Logger interface.

Value-add packages and suggestions, like improvements to the leveled logger, are of course welcome. Good proposals should

• Be composable with contextual loggers,
• Not break the behavior of 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 includes kit/log
• uber-common/zap, a zero-alloc logging library, includes a comparison with kit/log

Documentation

Overview

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 and WithPrefix add context to a logger. We can use With to improve the RunTask example.

func RunTask(task Task, logger log.Logger) string {
    logger = log.With(logger, "taskID", task.ID)
    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
})

Example (Basic)

package main

import (
	"os"

	"github.com/AshleyDumaine/kit/log"
)

func main() {
	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"

Example (Contextual)

package main

import (
	"os"
	"time"

	"github.com/AshleyDumaine/kit/log"
)

func main() {
	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"

Example (DebugInfo)

package main

import (
	"os"
	"time"

	"github.com/AshleyDumaine/kit/log"
)

func main() {
	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

Example (SyncWriter)

package main

import (
	"math/rand"
	"os"
	"sync"
	"time"

	"github.com/AshleyDumaine/kit/log"
)

func main() {
	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()

}

Output:

taskID=1 event="starting task"
taskID=2 event="starting task"
taskID=1 event="task complete"
taskID=2 event="task complete"

Example (Valuer)

package main

import (
	"os"

	"github.com/AshleyDumaine/kit/log"
)

func main() {
	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

Index

• Variables
• func NewStdlibAdapter(logger Logger, options ...StdlibAdapterOption) io.Writer
• func NewSyncWriter(w io.Writer) io.Writer
• type Logger
  • func NewJSONLogger(w io.Writer) Logger
  • func NewLogfmtLogger(w io.Writer) Logger
  • func NewNopLogger() Logger
  • func NewSyncLogger(logger Logger) Logger
  • func With(logger Logger, keyvals ...interface{}) Logger
  • func WithPrefix(logger Logger, keyvals ...interface{}) Logger
• type LoggerFunc
  • func (f LoggerFunc) Log(keyvals ...interface{}) error
• type StdlibAdapter
  • func (a StdlibAdapter) Write(p []byte) (int, error)
• type StdlibAdapterOption
  • func FileKey(key string) StdlibAdapterOption
  • func MessageKey(key string) StdlibAdapterOption
  • func TimestampKey(key string) StdlibAdapterOption
• type StdlibWriter
  • func (w StdlibWriter) Write(p []byte) (int, error)
• type SwapLogger
  • func (l *SwapLogger) Log(keyvals ...interface{}) error
  • func (l *SwapLogger) Swap(logger Logger)
• type Valuer
  • func Caller(depth int) Valuer
  • func Timestamp(t func() time.Time) Valuer
  • func TimestampFormat(t func() time.Time, layout string) Valuer

Examples

• Package (Basic)
• Package (Contextual)
• Package (DebugInfo)
• Package (SyncWriter)
• Package (Valuer)

Variables

var (
	// DefaultTimestamp is a Valuer that returns the current wallclock time,
	// respecting time zones, when bound.
	DefaultTimestamp = TimestampFormat(time.Now, time.RFC3339Nano)

	// DefaultTimestampUTC is a Valuer that returns the current time in UTC
	// when bound.
	DefaultTimestampUTC = TimestampFormat(
		func() time.Time { return time.Now().UTC() },
		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)
)

var ErrMissingValue = errors.New("(MISSING)")

ErrMissingValue is appended to keyvals slices with odd length to substitute the missing value.

Functions

func NewStdlibAdapter

func NewStdlibAdapter(logger Logger, options ...StdlibAdapterOption) io.Writer

NewStdlibAdapter returns a new StdlibAdapter wrapper around the passed logger. It's designed to be passed to log.SetOutput.

func NewSyncWriter

func NewSyncWriter(w io.Writer) io.Writer

NewSyncWriter returns a new writer that is safe for concurrent use by multiple goroutines. Writes to the returned writer are passed on to w. If another write is already in progress, the calling goroutine blocks until the writer is available.

If w implements the following interface, so does the returned writer.

interface {
    Fd() uintptr
}

Types

type Logger

type Logger interface {
	Log(keyvals ...interface{}) error
}

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.

func NewJSONLogger

func NewJSONLogger(w io.Writer) Logger

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 NewLogfmtLogger

func NewLogfmtLogger(w io.Writer) Logger

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 NewNopLogger

func NewNopLogger() Logger

NewNopLogger returns a logger that doesn't do anything.

func NewSyncLogger

func NewSyncLogger(logger Logger) Logger

NewSyncLogger returns a logger that synchronizes concurrent use of the wrapped logger. When multiple goroutines use the SyncLogger concurrently only one goroutine will be allowed to log to the wrapped logger at a time. The other goroutines will block until the logger is available.

func With

func With(logger Logger, keyvals ...interface{}) Logger

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 WithPrefix

func WithPrefix(logger Logger, keyvals ...interface{}) 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.

type LoggerFunc

type LoggerFunc func(...interface{}) error

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.

func (LoggerFunc) Log

func (f LoggerFunc) Log(keyvals ...interface{}) error

Log implements Logger by calling f(keyvals...).

type StdlibAdapter

type StdlibAdapter struct {
	Logger
	// contains filtered or unexported fields
}

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.

func (StdlibAdapter) Write

func (a StdlibAdapter) Write(p []byte) (int, error)

type StdlibAdapterOption

type StdlibAdapterOption func(*StdlibAdapter)

StdlibAdapterOption sets a parameter for the StdlibAdapter.

func FileKey

func FileKey(key string) StdlibAdapterOption

FileKey sets the key for the file and line field. By default, it's "caller".

func MessageKey

func MessageKey(key string) StdlibAdapterOption

MessageKey sets the key for the actual log message. By default, it's "msg".

func TimestampKey

func TimestampKey(key string) StdlibAdapterOption

TimestampKey sets the key for the timestamp field. By default, it's "ts".

type StdlibWriter

type StdlibWriter struct{}

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.

func (StdlibWriter) Write

func (w StdlibWriter) Write(p []byte) (int, error)

Write implements io.Writer.

type SwapLogger

type SwapLogger struct {
	// contains filtered or unexported fields
}

SwapLogger wraps another logger that may be safely replaced while other goroutines use the SwapLogger concurrently. The zero value for a SwapLogger will discard all log events without error.

SwapLogger serves well as a package global logger that can be changed by importers.

func (*SwapLogger) Log

func (l *SwapLogger) Log(keyvals ...interface{}) error

Log implements the Logger interface by forwarding keyvals to the currently wrapped logger. It does not log anything if the wrapped logger is nil.

func (*SwapLogger) Swap

func (l *SwapLogger) Swap(logger Logger)

Swap replaces the currently wrapped logger with logger. Swap may be called concurrently with calls to Log from other goroutines.

type Valuer

type Valuer func() interface{}

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.

func Caller

func Caller(depth int) Valuer

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 Timestamp

func Timestamp(t func() time.Time) Valuer

Timestamp returns a timestamp Valuer. It invokes the t function to get the time; unless you are doing something tricky, pass time.Now.

Most users will want to use DefaultTimestamp or DefaultTimestampUTC, which are TimestampFormats that use the RFC3339Nano format.

func TimestampFormat

func TimestampFormat(t func() time.Time, layout string) Valuer

TimestampFormat returns a timestamp Valuer with a custom time format. It invokes the t function to get the time to format; unless you are doing something tricky, pass time.Now. The layout string is passed to Time.Format.

Most users will want to use DefaultTimestamp or DefaultTimestampUTC, which are TimestampFormats that use the RFC3339Nano format.