diff --git a/log/benchmark_test.go b/log/benchmark_test.go new file mode 100644 index 000000000..1a231593f --- /dev/null +++ b/log/benchmark_test.go @@ -0,0 +1,21 @@ +package log_test + +import ( + "testing" + + "github.com/peterbourgon/gokit/log" +) + +func benchmarkRunner(b *testing.B, logger log.Logger, f func(log.Logger)) { + logger = log.With(logger, "common_key", "common_value") + b.ReportAllocs() + b.ResetTimer() + for i := 0; i < b.N; i++ { + f(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") } +) diff --git a/log/json_logger.go b/log/json_logger.go new file mode 100644 index 000000000..8907c8f9d --- /dev/null +++ b/log/json_logger.go @@ -0,0 +1,45 @@ +package log + +import ( + "encoding/json" + "fmt" + "io" +) + +type jsonLogger struct { + io.Writer +} + +// NewJSONLogger returns a Logger that encodes keyvals to the Writer as a +// single JSON object. +func NewJSONLogger(w io.Writer) Logger { + return &jsonLogger{w} +} + +func (l *jsonLogger) Log(keyvals ...interface{}) error { + if len(keyvals)%2 == 1 { + panic("odd number of keyvals") + } + m := make(map[string]interface{}, len(keyvals)/2) + for i := 0; i < len(keyvals); i += 2 { + merge(m, keyvals[i], keyvals[i+1]) + } + return json.NewEncoder(l.Writer).Encode(m) +} + +func merge(dst map[string]interface{}, k, v interface{}) map[string]interface{} { + var key string + switch x := k.(type) { + case string: + key = x + case fmt.Stringer: + key = x.String() + default: + key = fmt.Sprintf("%v", x) + } + if x, ok := v.(error); ok { + v = x.Error() + } + dst[key] = v + return dst +} diff --git a/log/json_logger_test.go b/log/json_logger_test.go new file mode 100644 index 000000000..f724de1e5 --- /dev/null +++ b/log/json_logger_test.go @@ -0,0 +1,29 @@ +package log_test + +import ( + "bytes" + "errors" + "io/ioutil" + "testing" + + "github.com/peterbourgon/gokit/log" +) + +func TestJSONLogger(t *testing.T) { + 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("want %#v, have %#v", want, have) + } +} + +func BenchmarkJSONLoggerSimple(b *testing.B) { + benchmarkRunner(b, log.NewJSONLogger(ioutil.Discard), baseMessage) +} + +func BenchmarkJSONLoggerContextual(b *testing.B) { + benchmarkRunner(b, log.NewJSONLogger(ioutil.Discard), withMessage) +} diff --git a/log/levels.go b/log/levels.go new file mode 100644 index 000000000..4c7079bb0 --- /dev/null +++ b/log/levels.go @@ -0,0 +1,60 @@ +package log + +// Levels provides a default set of leveled loggers. +type Levels struct { + Debug Logger + Info Logger + Error Logger +} + +type levelOptions struct { + levelKey string + debugValue string + infoValue string + errorValue string +} + +// LevelOption sets a parameter for leveled loggers. +type LevelOption func(*levelOptions) + +// LevelKey sets the key for the field used to indicate log level. By default, +// the key is "level". +func LevelKey(key string) LevelOption { + return func(o *levelOptions) { o.levelKey = key } +} + +// DebugLevelValue sets the value for the field used to indicate the debug log +// level. By default, the value is "DEBUG". +func DebugLevelValue(value string) LevelOption { + return func(o *levelOptions) { o.debugValue = value } +} + +// InfoLevelValue sets the value for the field used to indicate the debug log +// level. By default, the value is "INFO". +func InfoLevelValue(value string) LevelOption { + return func(o *levelOptions) { o.infoValue = value } +} + +// ErrorLevelValue sets the value for the field used to indicate the debug log +// level. By default, the value is "ERROR". +func ErrorLevelValue(value string) LevelOption { + return func(o *levelOptions) { o.errorValue = value } +} + +// NewLevels returns a new set of leveled loggers based on the base logger. +func NewLevels(base Logger, options ...LevelOption) Levels { + opts := &levelOptions{ + levelKey: "level", + debugValue: "DEBUG", + infoValue: "INFO", + errorValue: "ERROR", + } + for _, option := range options { + option(opts) + } + return Levels{ + Debug: With(base, opts.levelKey, opts.debugValue), + Info: With(base, opts.levelKey, opts.infoValue), + Error: With(base, opts.levelKey, opts.errorValue), + } +} diff --git a/log/levels_test.go b/log/levels_test.go new file mode 100644 index 000000000..a906c7a30 --- /dev/null +++ b/log/levels_test.go @@ -0,0 +1,45 @@ +package log_test + +import ( + "bytes" + "testing" + + "github.com/peterbourgon/gokit/log" +) + +func TestDefaultLevels(t *testing.T) { + buf := bytes.Buffer{} + levels := log.NewLevels(log.NewPrefixLogger(&buf)) + + levels.Debug.Log("msg", "👨") // of course you'd want to do this + if want, have := "level=DEBUG msg=👨\n", buf.String(); want != have { + t.Errorf("want %#v, have %#v", want, have) + } + + buf.Reset() + levels.Info.Log("msg", "🚀") + if want, have := "level=INFO msg=🚀\n", buf.String(); want != have { + t.Errorf("want %#v, have %#v", want, have) + } + + buf.Reset() + levels.Error.Log("msg", "🍵") + if want, have := "level=ERROR msg=🍵\n", buf.String(); want != have { + t.Errorf("want %#v, have %#v", want, have) + } +} + +func TestModifiedLevels(t *testing.T) { + buf := bytes.Buffer{} + levels := log.NewLevels( + log.NewJSONLogger(&buf), + log.LevelKey("l"), + log.DebugLevelValue("⛄"), + log.InfoLevelValue("🌜"), + log.ErrorLevelValue("🌊"), + ) + log.With(levels.Debug, "easter_island", "🗿").Log("msg", "💃💃💃") + if want, have := `{"easter_island":"🗿","l":"⛄","msg":"💃💃💃"}`+"\n", buf.String(); want != have { + t.Errorf("want %#v, have %#v", want, have) + } +} diff --git a/log/log.go b/log/log.go new file mode 100644 index 000000000..305923899 --- /dev/null +++ b/log/log.go @@ -0,0 +1,33 @@ +package log + +// Logger is the least-common-denominator interface for all log operations. +type Logger interface { + Log(keyvals ...interface{}) error +} + +// With new, contextualized Logger with the passed keyvals already applied. +func With(logger Logger, keyvals ...interface{}) Logger { + if w, ok := logger.(Wither); ok { + return w.With(keyvals...) + } + return LoggerFunc(func(kvs ...interface{}) error { + return logger.Log(append(keyvals, 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...) +} + +// Wither describes an optimization that Logger implementations may make. If a +// Logger implements Wither, the package-level With function will invoke it +// when creating a new, contextual logger. +type Wither interface { + With(keyvals ...interface{}) Logger +} diff --git a/log/log_test.go b/log/log_test.go new file mode 100644 index 000000000..de002e6b7 --- /dev/null +++ b/log/log_test.go @@ -0,0 +1,35 @@ +package log_test + +import ( + "bytes" + "testing" + + "github.com/peterbourgon/gokit/log" +) + +func TestWith(t *testing.T) { + buf := &bytes.Buffer{} + logger := log.NewJSONLogger(buf) + logger = log.With(logger, "a", 123) + logger = log.With(logger, "b", "c") // With should stack + if err := logger.Log("msg", "message"); err != nil { + t.Fatal(err) + } + if want, have := `{"a":123,"b":"c","msg":"message"}`+"\n", buf.String(); want != have { + t.Errorf("want\n\t%#v, have\n\t%#v", want, have) + } +} + +func TestWither(t *testing.T) { + logger := &mylogger{} + log.With(logger, "a", "b").Log("c", "d") + if want, have := 1, logger.withs; want != have { + t.Errorf("want %d, have %d", want, have) + } +} + +type mylogger struct{ withs int } + +func (l *mylogger) Log(keyvals ...interface{}) error { return nil } + +func (l *mylogger) With(keyvals ...interface{}) log.Logger { l.withs++; return l } diff --git a/log/prefix_logger.go b/log/prefix_logger.go new file mode 100644 index 000000000..f37324a72 --- /dev/null +++ b/log/prefix_logger.go @@ -0,0 +1,36 @@ +package log + +import ( + "fmt" + "io" +) + +type prefixLogger struct { + io.Writer +} + +// NewPrefixLogger returns a basic logger that encodes keyvals as simple "k=v" +// pairs to the Writer. +func NewPrefixLogger(w io.Writer) Logger { + return &prefixLogger{w} +} + +func (l prefixLogger) Log(keyvals ...interface{}) error { + if len(keyvals)%2 == 1 { + panic("odd number of keyvals") + } + for i := 0; i < len(keyvals); i += 2 { + if i != 0 { + if _, err := fmt.Fprint(l.Writer, " "); err != nil { + return err + } + } + if _, err := fmt.Fprintf(l.Writer, "%s=%v", keyvals[i], keyvals[i+1]); err != nil { + return err + } + } + if _, err := fmt.Fprintln(l.Writer); err != nil { + return err + } + return nil +} diff --git a/log/prefix_logger_test.go b/log/prefix_logger_test.go new file mode 100644 index 000000000..f0bb60931 --- /dev/null +++ b/log/prefix_logger_test.go @@ -0,0 +1,50 @@ +package log_test + +import ( + "bytes" + "errors" + "io/ioutil" + "testing" + + "github.com/peterbourgon/gokit/log" +) + +func TestPrefixLogger(t *testing.T) { + buf := &bytes.Buffer{} + logger := log.NewPrefixLogger(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=map[1:2] my_map=special_behavior\n", buf.String(); want != have { + t.Errorf("want %#v, have %#v", want, have) + } +} + +type mymap map[int]int + +func (m mymap) String() string { return "special_behavior" } + +func BenchmarkPrefixLoggerSimple(b *testing.B) { + benchmarkRunner(b, log.NewPrefixLogger(ioutil.Discard), baseMessage) +} + +func BenchmarkPrefixLoggerContextual(b *testing.B) { + benchmarkRunner(b, log.NewPrefixLogger(ioutil.Discard), withMessage) +} diff --git a/log/stdlib_writer.go b/log/stdlib_writer.go new file mode 100644 index 000000000..fcdea1eee --- /dev/null +++ b/log/stdlib_writer.go @@ -0,0 +1,100 @@ +package log + +import ( + "io" + "regexp" +) + +// StdlibWriter 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 StdlibWriter struct { + Logger + timestampKey string + fileKey string + messageKey string +} + +// StdlibWriterOption sets a parameter for the StdlibWriter. +type StdlibWriterOption func(*StdlibWriter) + +// TimestampKey sets the key for the timestamp field. By default, it's "ts". +func TimestampKey(key string) StdlibWriterOption { + return func(w *StdlibWriter) { w.timestampKey = key } +} + +// FileKey sets the key for the file and line field. By default, it's "file". +func FileKey(key string) StdlibWriterOption { + return func(w *StdlibWriter) { w.fileKey = key } +} + +// MessageKey sets the key for the actual log message. By default, it's "msg". +func MessageKey(key string) StdlibWriterOption { + return func(w *StdlibWriter) { w.messageKey = key } +} + +// NewStdlibWriter returns a new StdlibWriter wrapper around the passed +// logger. It's designed to be passed to log.SetOutput. +func NewStdlibWriter(logger Logger, options ...StdlibWriterOption) io.Writer { + w := StdlibWriter{ + Logger: logger, + timestampKey: "ts", + fileKey: "file", + messageKey: "msg", + } + for _, option := range options { + option(&w) + } + return w +} + +func (w StdlibWriter) Write(p []byte) (int, error) { + 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, w.timestampKey, timestamp) + } + if file, ok := result["file"]; ok && file != "" { + keyvals = append(keyvals, w.fileKey, file) + } + if msg, ok := result["msg"]; ok { + keyvals = append(keyvals, w.messageKey, msg) + } + if err := w.Logger.Log(keyvals...); err != nil { + return 0, err + } + return len(p), nil +} + +const ( + logRegexpDate = `(?P[0-9]{4}/[0-9]{2}/[0-9]{2})?[ ]?` + logRegexpTime = `(?P