From 8650f266a8b2968cf7967dfdd2a3013fa888ef86 Mon Sep 17 00:00:00 2001 From: Peter Bourgon Date: Thu, 26 Mar 2015 09:01:39 +0100 Subject: [PATCH 01/11] log: first draft of alternate implementation --- log/basic_logger.go | 40 ++++++++++++++++++ log/basic_logger_test.go | 31 ++++++++++++++ log/field_encoders.go | 49 ++++++++++++++++++++++ log/field_encoders_test.go | 84 ++++++++++++++++++++++++++++++++++++++ log/json_logger.go | 79 +++++++++++++++++++++++++++++++++++ log/json_logger_test.go | 42 +++++++++++++++++++ log/log.go | 14 +++++++ 7 files changed, 339 insertions(+) create mode 100644 log/basic_logger.go create mode 100644 log/basic_logger_test.go create mode 100644 log/field_encoders.go create mode 100644 log/field_encoders_test.go create mode 100644 log/json_logger.go create mode 100644 log/json_logger_test.go create mode 100644 log/log.go diff --git a/log/basic_logger.go b/log/basic_logger.go new file mode 100644 index 000000000..4d7b6001a --- /dev/null +++ b/log/basic_logger.go @@ -0,0 +1,40 @@ +package log + +import ( + "fmt" + "io" +) + +// NewBasicLogger is the default, simple implementation of a Logger. Fields +// are encoded and prefixed to every log entry. +func NewBasicLogger(w io.Writer, e FieldEncoder) Logger { + return &basicLogger{w, e, []Field{}} +} + +type basicLogger struct { + io.Writer + FieldEncoder + fields []Field +} + +func (l *basicLogger) With(f Field) Logger { + return &basicLogger{ + Writer: l.Writer, + FieldEncoder: l.FieldEncoder, + fields: append(l.fields, f), + } +} + +func (l *basicLogger) Logf(format string, args ...interface{}) error { + var err error + if err = EncodeMany(l.Writer, l.FieldEncoder, l.fields); err != nil { + return err // TODO: should we continue, best-effort? + } + if _, err = fmt.Fprintf(l.Writer, format, args...); err != nil { + return err + } + if len(format) > 0 && format[len(format)-1] != '\n' { + _, err = fmt.Fprintf(l.Writer, "\n") + } + return err +} diff --git a/log/basic_logger_test.go b/log/basic_logger_test.go new file mode 100644 index 000000000..28047351e --- /dev/null +++ b/log/basic_logger_test.go @@ -0,0 +1,31 @@ +package log_test + +import ( + "bytes" + "strings" + "testing" + + "github.com/peterbourgon/gokit/log" +) + +func TestBasicLogger(t *testing.T) { + var ( + buf bytes.Buffer + baseLogger = log.NewBasicLogger(&buf, log.ValueOnly) + debugLogger = baseLogger.With(log.Field{Key: "level", Value: "DEBUG"}) + infoLogger = baseLogger.With(log.Field{Key: "level", Value: "INFO"}) + errorLogger = baseLogger.With(log.Field{Key: "level", Value: "ERROR"}) + ) + + debugLogger.Logf("debug %d", 1) + infoLogger.Logf("info %d", 2) + errorLogger.Logf("error %d", 3) + + if want, have := strings.Join([]string{ + `DEBUG debug 1`, + `INFO info 2`, + `ERROR error 3`, + }, "\n"), strings.TrimSpace(buf.String()); want != have { + t.Errorf("want \n%s, have \n%s", want, have) + } +} diff --git a/log/field_encoders.go b/log/field_encoders.go new file mode 100644 index 000000000..abbb5bb0b --- /dev/null +++ b/log/field_encoders.go @@ -0,0 +1,49 @@ +package log + +import ( + "bytes" + "encoding/json" + "fmt" + "io" +) + +// FieldEncoder describes a way to encode fields. +type FieldEncoder func(io.Writer, Field) error + +// KeyEqualsValue is a field encoder that yields "key=value". +func KeyEqualsValue(w io.Writer, f Field) error { + _, err := fmt.Fprintf(w, "%s=%v", f.Key, f.Value) + return err +} + +// ValueOnly is a field encoder that yields "value". +func ValueOnly(w io.Writer, f Field) error { + _, err := fmt.Fprintf(w, "%v", f.Value) + return err +} + +// JSON is a field encoder that yields '{"key":"value"}' without a trailing +// newline. +func JSON(w io.Writer, f Field) error { + var buf bytes.Buffer + if err := json.NewEncoder(&buf).Encode(map[string]interface{}{f.Key: f.Value}); err != nil { + return err + } + buf.Truncate(buf.Len() - 1) // remove trailing newline + _, err := buf.WriteTo(w) + return err +} + +// EncodeMany uses the field encoder to serialize the fields to the writer, +// putting a space character between each serialized field. +func EncodeMany(w io.Writer, e FieldEncoder, fields []Field) error { + for _, f := range fields { + if err := e(w, f); err != nil { + return err + } + if _, err := fmt.Fprint(w, " "); err != nil { + return err + } + } + return nil +} diff --git a/log/field_encoders_test.go b/log/field_encoders_test.go new file mode 100644 index 000000000..a8f5e5836 --- /dev/null +++ b/log/field_encoders_test.go @@ -0,0 +1,84 @@ +package log_test + +import ( + "bytes" + "errors" + "strings" + "testing" + + "github.com/peterbourgon/gokit/log" +) + +func TestFieldEqualsValue(t *testing.T) { + for f, want := range map[log.Field]string{ + log.Field{Key: "", Value: ""}: "=", + log.Field{Key: "", Value: nil}: "=", + log.Field{Key: "", Value: 0}: "=0", + log.Field{Key: "k", Value: "v"}: "k=v", + log.Field{Key: "k", Value: errors.New("123")}: "k=123", + } { + var buf bytes.Buffer + if err := log.KeyEqualsValue(&buf, f); err != nil { + t.Errorf("%v: %v", f, err) + continue + } + if have := buf.String(); want != have { + t.Errorf("%v: want %q, have %q", f, want, have) + } + } +} + +func TestValueOnly(t *testing.T) { + for f, want := range map[log.Field]string{ + log.Field{Key: "", Value: ""}: "", + log.Field{Key: "", Value: nil}: "", + log.Field{Key: "", Value: 0}: "0", + log.Field{Key: "k", Value: "v"}: "v", + log.Field{Key: "k", Value: errors.New("123")}: "123", + } { + var buf bytes.Buffer + if err := log.ValueOnly(&buf, f); err != nil { + t.Errorf("%v: %v", f, err) + continue + } + if have := buf.String(); want != have { + t.Errorf("%v: want %q, have %q", f, want, have) + } + } +} + +func TestJSON(t *testing.T) { + for f, want := range map[log.Field]string{ + log.Field{Key: "", Value: ""}: `{"":""}`, + log.Field{Key: "", Value: nil}: `{"":null}`, + log.Field{Key: "", Value: 0}: `{"":0}`, + log.Field{Key: "k", Value: "v"}: `{"k":"v"}`, + log.Field{Key: "k", Value: struct { + V int `json:"v"` + }{V: 123}}: `{"k":{"v":123}}`, + } { + var buf bytes.Buffer + if err := log.JSON(&buf, f); err != nil { + t.Errorf("%v: %v", f, err) + continue + } + if have := strings.TrimSpace(buf.String()); want != have { + t.Errorf("%v: want %q, have %q", f, want, have) + } + } +} + +func TestEncodeMany(t *testing.T) { + var buf bytes.Buffer + if err := log.EncodeMany(&buf, log.JSON, []log.Field{ + log.Field{Key: "k", Value: "v"}, + log.Field{Key: "123", Value: 456}, + }); err != nil { + t.Fatal(err) + } + want := `{"k":"v"} {"123":456}` + have := strings.TrimSpace(buf.String()) + if want != have { + t.Fatalf("want %q, have %q", want, have) + } +} diff --git a/log/json_logger.go b/log/json_logger.go new file mode 100644 index 000000000..ae8fc3590 --- /dev/null +++ b/log/json_logger.go @@ -0,0 +1,79 @@ +package log + +import ( + "bytes" + "encoding/json" + "fmt" + "io" +) + +// JSONFieldBehavior dictates how fields are encoded in a JSON logger. +type JSONFieldBehavior int + +const ( + // PrefixedFields encodes each field as its own JSON object, and prefixes + // each log event with those objects, separated by spaces. + PrefixedFields JSONFieldBehavior = iota + + // MixedFields encodes each field into the same JSON object as the log + // event. Logged events take precedence. + MixedFields +) + +// NewJSONLogger returns a Logger that encodes log events as JSON objects. +// Logged events are expected to be valid JSON. +func NewJSONLogger(w io.Writer, fieldBehavior JSONFieldBehavior) Logger { + return &jsonLogger{w, fieldBehavior, []Field{}} +} + +type jsonLogger struct { + io.Writer + JSONFieldBehavior + fields []Field +} + +func (l *jsonLogger) With(f Field) Logger { + return &jsonLogger{ + Writer: l.Writer, + JSONFieldBehavior: l.JSONFieldBehavior, + fields: append(l.fields, f), + } +} + +func (l *jsonLogger) Logf(format string, args ...interface{}) error { + var buf bytes.Buffer + if _, err := fmt.Fprintf(&buf, format, args...); err != nil { + return err + } + + m := map[string]interface{}{} + if err := json.NewDecoder(&buf).Decode(&m); err != nil { + return err + } + + buf.Reset() + switch l.JSONFieldBehavior { + case PrefixedFields: + if err := EncodeMany(&buf, JSON, l.fields); err != nil { + return err + } + if err := json.NewEncoder(&buf).Encode(m); err != nil { + return err + } + + case MixedFields: + final := map[string]interface{}{} + for _, f := range l.fields { + final[f.Key] = f.Value // fields first, so that... + } + for k, v := range m { + final[k] = v // ...logged data takes precedence + } + if err := json.NewEncoder(&buf).Encode(final); err != nil { + return err + } + } + + _, err := buf.WriteTo(l.Writer) + return err +} diff --git a/log/json_logger_test.go b/log/json_logger_test.go new file mode 100644 index 000000000..0971d6b0e --- /dev/null +++ b/log/json_logger_test.go @@ -0,0 +1,42 @@ +package log_test + +import ( + "bytes" + "strings" + "testing" + + "github.com/peterbourgon/gokit/log" +) + +func TestJSONLoggerPrefixedFields(t *testing.T) { + buf := bytes.Buffer{} + logger := log.NewJSONLogger(&buf, log.PrefixedFields) + if err := logger.Logf(`{"alpha" : "beta"}`); err != nil { + t.Fatal(err) + } + if want, have := `{"alpha":"beta"}`+"\n", buf.String(); want != have { + t.Fatalf("want\n\t%s, have\n\t%s", want, have) + } + + buf.Reset() + + logger = logger.With(log.Field{Key: "foo", Value: "bar"}) + if err := logger.Logf(`{ "delta": "gamma" }`); err != nil { + t.Fatal(err) + } + if want, have := `{"foo":"bar"} {"delta":"gamma"}`, strings.TrimSpace(buf.String()); want != have { + t.Errorf("want\n\t%s, have\n\t%s", want, have) + } +} + +func TestJSONLoggerMixedFields(t *testing.T) { + buf := bytes.Buffer{} + logger := log.NewJSONLogger(&buf, log.MixedFields) + logger = logger.With(log.Field{Key: "m", Value: "n"}) + if err := logger.Logf(`{"a":"b"}`); err != nil { + t.Fatal(err) + } + if want, have := `{"a":"b","m":"n"}`, strings.TrimSpace(buf.String()); want != have { + t.Fatalf("want\n\t%s, have\n\t%s", want, have) + } +} diff --git a/log/log.go b/log/log.go new file mode 100644 index 000000000..28b1203e5 --- /dev/null +++ b/log/log.go @@ -0,0 +1,14 @@ +package log + +// Logger is the least-common-denominator interface for all log operations. +type Logger interface { + With(Field) Logger + Logf(string, ...interface{}) error +} + +// Field is a key/value pair associated with a log event. Fields may be +// ignored by implementations. +type Field struct { + Key string + Value interface{} +} From 2a88002225fdcf17f03084a4b23e4d8252bf22e7 Mon Sep 17 00:00:00 2001 From: Peter Bourgon Date: Fri, 27 Mar 2015 12:08:50 +0100 Subject: [PATCH 02/11] log: some simplifications - With now takes multiple fields - Remove FieldEncoders; couple that to the concrete Logger impl --- log/basic_logger.go | 40 ------------------ log/basic_logger_test.go | 31 -------------- log/field_encoders.go | 49 --------------------- log/field_encoders_test.go | 84 ------------------------------------ log/json_logger.go | 87 ++++++++++++-------------------------- log/json_logger_test.go | 38 ++++++++--------- log/kv_logger.go | 43 +++++++++++++++++++ log/kv_logger_test.go | 62 +++++++++++++++++++++++++++ log/log.go | 7 ++- 9 files changed, 153 insertions(+), 288 deletions(-) delete mode 100644 log/basic_logger.go delete mode 100644 log/basic_logger_test.go delete mode 100644 log/field_encoders.go delete mode 100644 log/field_encoders_test.go create mode 100644 log/kv_logger.go create mode 100644 log/kv_logger_test.go diff --git a/log/basic_logger.go b/log/basic_logger.go deleted file mode 100644 index 4d7b6001a..000000000 --- a/log/basic_logger.go +++ /dev/null @@ -1,40 +0,0 @@ -package log - -import ( - "fmt" - "io" -) - -// NewBasicLogger is the default, simple implementation of a Logger. Fields -// are encoded and prefixed to every log entry. -func NewBasicLogger(w io.Writer, e FieldEncoder) Logger { - return &basicLogger{w, e, []Field{}} -} - -type basicLogger struct { - io.Writer - FieldEncoder - fields []Field -} - -func (l *basicLogger) With(f Field) Logger { - return &basicLogger{ - Writer: l.Writer, - FieldEncoder: l.FieldEncoder, - fields: append(l.fields, f), - } -} - -func (l *basicLogger) Logf(format string, args ...interface{}) error { - var err error - if err = EncodeMany(l.Writer, l.FieldEncoder, l.fields); err != nil { - return err // TODO: should we continue, best-effort? - } - if _, err = fmt.Fprintf(l.Writer, format, args...); err != nil { - return err - } - if len(format) > 0 && format[len(format)-1] != '\n' { - _, err = fmt.Fprintf(l.Writer, "\n") - } - return err -} diff --git a/log/basic_logger_test.go b/log/basic_logger_test.go deleted file mode 100644 index 28047351e..000000000 --- a/log/basic_logger_test.go +++ /dev/null @@ -1,31 +0,0 @@ -package log_test - -import ( - "bytes" - "strings" - "testing" - - "github.com/peterbourgon/gokit/log" -) - -func TestBasicLogger(t *testing.T) { - var ( - buf bytes.Buffer - baseLogger = log.NewBasicLogger(&buf, log.ValueOnly) - debugLogger = baseLogger.With(log.Field{Key: "level", Value: "DEBUG"}) - infoLogger = baseLogger.With(log.Field{Key: "level", Value: "INFO"}) - errorLogger = baseLogger.With(log.Field{Key: "level", Value: "ERROR"}) - ) - - debugLogger.Logf("debug %d", 1) - infoLogger.Logf("info %d", 2) - errorLogger.Logf("error %d", 3) - - if want, have := strings.Join([]string{ - `DEBUG debug 1`, - `INFO info 2`, - `ERROR error 3`, - }, "\n"), strings.TrimSpace(buf.String()); want != have { - t.Errorf("want \n%s, have \n%s", want, have) - } -} diff --git a/log/field_encoders.go b/log/field_encoders.go deleted file mode 100644 index abbb5bb0b..000000000 --- a/log/field_encoders.go +++ /dev/null @@ -1,49 +0,0 @@ -package log - -import ( - "bytes" - "encoding/json" - "fmt" - "io" -) - -// FieldEncoder describes a way to encode fields. -type FieldEncoder func(io.Writer, Field) error - -// KeyEqualsValue is a field encoder that yields "key=value". -func KeyEqualsValue(w io.Writer, f Field) error { - _, err := fmt.Fprintf(w, "%s=%v", f.Key, f.Value) - return err -} - -// ValueOnly is a field encoder that yields "value". -func ValueOnly(w io.Writer, f Field) error { - _, err := fmt.Fprintf(w, "%v", f.Value) - return err -} - -// JSON is a field encoder that yields '{"key":"value"}' without a trailing -// newline. -func JSON(w io.Writer, f Field) error { - var buf bytes.Buffer - if err := json.NewEncoder(&buf).Encode(map[string]interface{}{f.Key: f.Value}); err != nil { - return err - } - buf.Truncate(buf.Len() - 1) // remove trailing newline - _, err := buf.WriteTo(w) - return err -} - -// EncodeMany uses the field encoder to serialize the fields to the writer, -// putting a space character between each serialized field. -func EncodeMany(w io.Writer, e FieldEncoder, fields []Field) error { - for _, f := range fields { - if err := e(w, f); err != nil { - return err - } - if _, err := fmt.Fprint(w, " "); err != nil { - return err - } - } - return nil -} diff --git a/log/field_encoders_test.go b/log/field_encoders_test.go deleted file mode 100644 index a8f5e5836..000000000 --- a/log/field_encoders_test.go +++ /dev/null @@ -1,84 +0,0 @@ -package log_test - -import ( - "bytes" - "errors" - "strings" - "testing" - - "github.com/peterbourgon/gokit/log" -) - -func TestFieldEqualsValue(t *testing.T) { - for f, want := range map[log.Field]string{ - log.Field{Key: "", Value: ""}: "=", - log.Field{Key: "", Value: nil}: "=", - log.Field{Key: "", Value: 0}: "=0", - log.Field{Key: "k", Value: "v"}: "k=v", - log.Field{Key: "k", Value: errors.New("123")}: "k=123", - } { - var buf bytes.Buffer - if err := log.KeyEqualsValue(&buf, f); err != nil { - t.Errorf("%v: %v", f, err) - continue - } - if have := buf.String(); want != have { - t.Errorf("%v: want %q, have %q", f, want, have) - } - } -} - -func TestValueOnly(t *testing.T) { - for f, want := range map[log.Field]string{ - log.Field{Key: "", Value: ""}: "", - log.Field{Key: "", Value: nil}: "", - log.Field{Key: "", Value: 0}: "0", - log.Field{Key: "k", Value: "v"}: "v", - log.Field{Key: "k", Value: errors.New("123")}: "123", - } { - var buf bytes.Buffer - if err := log.ValueOnly(&buf, f); err != nil { - t.Errorf("%v: %v", f, err) - continue - } - if have := buf.String(); want != have { - t.Errorf("%v: want %q, have %q", f, want, have) - } - } -} - -func TestJSON(t *testing.T) { - for f, want := range map[log.Field]string{ - log.Field{Key: "", Value: ""}: `{"":""}`, - log.Field{Key: "", Value: nil}: `{"":null}`, - log.Field{Key: "", Value: 0}: `{"":0}`, - log.Field{Key: "k", Value: "v"}: `{"k":"v"}`, - log.Field{Key: "k", Value: struct { - V int `json:"v"` - }{V: 123}}: `{"k":{"v":123}}`, - } { - var buf bytes.Buffer - if err := log.JSON(&buf, f); err != nil { - t.Errorf("%v: %v", f, err) - continue - } - if have := strings.TrimSpace(buf.String()); want != have { - t.Errorf("%v: want %q, have %q", f, want, have) - } - } -} - -func TestEncodeMany(t *testing.T) { - var buf bytes.Buffer - if err := log.EncodeMany(&buf, log.JSON, []log.Field{ - log.Field{Key: "k", Value: "v"}, - log.Field{Key: "123", Value: 456}, - }); err != nil { - t.Fatal(err) - } - want := `{"k":"v"} {"123":456}` - have := strings.TrimSpace(buf.String()) - if want != have { - t.Fatalf("want %q, have %q", want, have) - } -} diff --git a/log/json_logger.go b/log/json_logger.go index ae8fc3590..04a378fe6 100644 --- a/log/json_logger.go +++ b/log/json_logger.go @@ -1,79 +1,48 @@ package log import ( - "bytes" "encoding/json" - "fmt" - "io" -) - -// JSONFieldBehavior dictates how fields are encoded in a JSON logger. -type JSONFieldBehavior int - -const ( - // PrefixedFields encodes each field as its own JSON object, and prefixes - // each log event with those objects, separated by spaces. - PrefixedFields JSONFieldBehavior = iota - // MixedFields encodes each field into the same JSON object as the log - // event. Logged events take precedence. - MixedFields + "io" ) -// NewJSONLogger returns a Logger that encodes log events as JSON objects. -// Logged events are expected to be valid JSON. -func NewJSONLogger(w io.Writer, fieldBehavior JSONFieldBehavior) Logger { - return &jsonLogger{w, fieldBehavior, []Field{}} -} - type jsonLogger struct { io.Writer - JSONFieldBehavior + key string fields []Field } -func (l *jsonLogger) With(f Field) Logger { - return &jsonLogger{ - Writer: l.Writer, - JSONFieldBehavior: l.JSONFieldBehavior, - fields: append(l.fields, f), - } +// NewJSONLogger returns a Logger that marshals each log line as a JSON +// object. Because fields are keys in a JSON object, they must be unique, and +// last-writer-wins. The actual log message is placed under the "msg" key. To +// change that, use the NewJSONLoggerWithKey constructor. +func NewJSONLogger(w io.Writer) Logger { + return NewJSONLoggerWithKey(w, "msg") } -func (l *jsonLogger) Logf(format string, args ...interface{}) error { - var buf bytes.Buffer - if _, err := fmt.Fprintf(&buf, format, args...); err != nil { - return err +// NewJSONLoggerWithKey is the same as NewJSONLogger but allows the user to +// specify the key under which the actual log message is placed in the JSON +// object. +func NewJSONLoggerWithKey(w io.Writer, messageKey string) Logger { + return &jsonLogger{ + Writer: w, + key: messageKey, } +} - m := map[string]interface{}{} - if err := json.NewDecoder(&buf).Decode(&m); err != nil { - return err +func (l *jsonLogger) With(fields ...Field) Logger { + return &jsonLogger{ + Writer: l.Writer, + key: l.key, + fields: append(l.fields, fields...), } +} - buf.Reset() - switch l.JSONFieldBehavior { - case PrefixedFields: - if err := EncodeMany(&buf, JSON, l.fields); err != nil { - return err - } - if err := json.NewEncoder(&buf).Encode(m); err != nil { - return err - } - - case MixedFields: - final := map[string]interface{}{} - for _, f := range l.fields { - final[f.Key] = f.Value // fields first, so that... - } - for k, v := range m { - final[k] = v // ...logged data takes precedence - } - if err := json.NewEncoder(&buf).Encode(final); err != nil { - return err - } +func (l *jsonLogger) Log(s string) error { + m := make(map[string]interface{}, len(l.fields)+1) + for _, f := range l.fields { + m[f.Key] = f.Value } - - _, err := buf.WriteTo(l.Writer) - return err + m[l.key] = s + return json.NewEncoder(l.Writer).Encode(m) } diff --git a/log/json_logger_test.go b/log/json_logger_test.go index 0971d6b0e..ddc5b8e2a 100644 --- a/log/json_logger_test.go +++ b/log/json_logger_test.go @@ -2,41 +2,37 @@ package log_test import ( "bytes" - "strings" "testing" + "time" "github.com/peterbourgon/gokit/log" ) -func TestJSONLoggerPrefixedFields(t *testing.T) { +func TestJSONLogger(t *testing.T) { buf := bytes.Buffer{} - logger := log.NewJSONLogger(&buf, log.PrefixedFields) - if err := logger.Logf(`{"alpha" : "beta"}`); err != nil { - t.Fatal(err) - } - if want, have := `{"alpha":"beta"}`+"\n", buf.String(); want != have { - t.Fatalf("want\n\t%s, have\n\t%s", want, have) + logger := log.NewJSONLogger(&buf) + logger.Log("a") + if want, have := `{"msg":"a"}`+"\n", buf.String(); want != have { + t.Errorf("want %#v, have %#v", want, have) } buf.Reset() - - logger = logger.With(log.Field{Key: "foo", Value: "bar"}) - if err := logger.Logf(`{ "delta": "gamma" }`); err != nil { + if err := logger.With(log.Field{Key: "level", Value: "INFO"}).Log("b"); err != nil { t.Fatal(err) } - if want, have := `{"foo":"bar"} {"delta":"gamma"}`, strings.TrimSpace(buf.String()); want != have { - t.Errorf("want\n\t%s, have\n\t%s", want, have) + if want, have := `{"level":"INFO","msg":"b"}`+"\n", buf.String(); want != have { + t.Errorf("want %#v, have %#v", want, have) } -} -func TestJSONLoggerMixedFields(t *testing.T) { - buf := bytes.Buffer{} - logger := log.NewJSONLogger(&buf, log.MixedFields) - logger = logger.With(log.Field{Key: "m", Value: "n"}) - if err := logger.Logf(`{"a":"b"}`); err != nil { + buf.Reset() + logger = logger.With(log.Field{Key: "request.size", Value: 1024}) + logger = logger.With(log.Field{Key: "response.code", Value: 200}) + logger = logger.With(log.Field{Key: "response.duration", Value: 42 * time.Millisecond}) + logger = logger.With(log.Field{Key: "headers", Value: map[string][]string{"X-Foo": []string{"A", "B"}}}) + if err := logger.Log("OK"); err != nil { t.Fatal(err) } - if want, have := `{"a":"b","m":"n"}`, strings.TrimSpace(buf.String()); want != have { - t.Fatalf("want\n\t%s, have\n\t%s", want, have) + if want, have := `{"headers":{"X-Foo":["A","B"]},"msg":"OK","request.size":1024,"response.code":200,"response.duration":42000000}`+"\n", buf.String(); want != have { + t.Errorf("want\n\t%#v, have\n\t%#v", want, have) } } diff --git a/log/kv_logger.go b/log/kv_logger.go new file mode 100644 index 000000000..8c2c410ac --- /dev/null +++ b/log/kv_logger.go @@ -0,0 +1,43 @@ +package log + +import ( + "fmt" + "io" +) + +type kvLogger struct { + io.Writer + fields []Field +} + +// NewKVLogger returns a Logger that prefixes fields as space-separated "k=v" +// pairs on every log line. +func NewKVLogger(w io.Writer) Logger { + return &kvLogger{ + Writer: w, + } +} + +func (l *kvLogger) With(fields ...Field) Logger { + return &kvLogger{ + Writer: l.Writer, + fields: append(l.fields, fields...), + } +} + +func (l *kvLogger) Log(s string) error { + for _, f := range l.fields { + if _, err := fmt.Fprintf(l.Writer, "%s=%v ", f.Key, f.Value); err != nil { + return err + } + } + if _, err := fmt.Fprintf(l.Writer, s); err != nil { + return err + } + if s[len(s)-1] != '\n' { + if _, err := fmt.Fprintf(l.Writer, "\n"); err != nil { + return err + } + } + return nil +} diff --git a/log/kv_logger_test.go b/log/kv_logger_test.go new file mode 100644 index 000000000..57ef4abfe --- /dev/null +++ b/log/kv_logger_test.go @@ -0,0 +1,62 @@ +package log_test + +import ( + "bytes" + "testing" + + "github.com/peterbourgon/gokit/log" +) + +func TestKVLogger(t *testing.T) { + buf := bytes.Buffer{} + logger := log.NewKVLogger(&buf) + logger.Log("a") + if want, have := "a\n", buf.String(); want != have { + t.Errorf("want %#v, have %#v", want, have) + } + + buf.Reset() + logger = logger.With(log.Field{Key: "level", Value: "DEBUG"}) + if err := logger.Log("b"); err != nil { + t.Fatal(err) + } + if want, have := "level=DEBUG b\n", buf.String(); want != have { + t.Errorf("want %#v, have %#v", want, have) + } + + buf.Reset() + if err := logger.With(log.Field{Key: "count", Value: 123}).Log("c"); err != nil { + t.Fatal(err) + } + if want, have := "level=DEBUG count=123 c\n", buf.String(); want != have { + t.Errorf("want %#v, have %#v", want, have) + } + + buf.Reset() + if err := logger.With(log.Field{Key: "m", Value: map[int]int{1: 2}}).Log("d"); err != nil { + t.Fatal(err) + } + if want, have := "level=DEBUG m=map[1:2] d\n", buf.String(); want != have { + t.Errorf("want %#v, have %#v", want, have) + } + + buf.Reset() + if err := logger.With(log.Field{Key: "my", Value: myMap{0: 0}}).Log("e"); err != nil { + t.Fatal(err) + } + if want, have := "level=DEBUG my=special-behavior e\n", buf.String(); want != have { + t.Errorf("want %#v, have %#v", want, have) + } + + buf.Reset() + if err := logger.With(log.Field{Key: "a", Value: 1}, log.Field{Key: "b", Value: 2}).Log("f"); err != nil { + t.Fatal(err) + } + if want, have := "level=DEBUG a=1 b=2 f\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" } diff --git a/log/log.go b/log/log.go index 28b1203e5..c4958b2a7 100644 --- a/log/log.go +++ b/log/log.go @@ -2,12 +2,11 @@ package log // Logger is the least-common-denominator interface for all log operations. type Logger interface { - With(Field) Logger - Logf(string, ...interface{}) error + With(...Field) Logger + Log(string) error } -// Field is a key/value pair associated with a log event. Fields may be -// ignored by implementations. +// Field is a key/value pair associated with a log event. type Field struct { Key string Value interface{} From 1b9a63463571c2bc578d594d9ed3833b5501dfab Mon Sep 17 00:00:00 2001 From: Peter Bourgon Date: Fri, 27 Mar 2015 12:24:54 +0100 Subject: [PATCH 03/11] Prefer fmt.Fprint where possible --- log/kv_logger.go | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/log/kv_logger.go b/log/kv_logger.go index 8c2c410ac..d5c403beb 100644 --- a/log/kv_logger.go +++ b/log/kv_logger.go @@ -31,11 +31,11 @@ func (l *kvLogger) Log(s string) error { return err } } - if _, err := fmt.Fprintf(l.Writer, s); err != nil { + if _, err := fmt.Fprint(l.Writer, s); err != nil { return err } if s[len(s)-1] != '\n' { - if _, err := fmt.Fprintf(l.Writer, "\n"); err != nil { + if _, err := fmt.Fprint(l.Writer, "\n"); err != nil { return err } } From 9fae5e68990c7276cb226b5bc6fef3cf7029e5ca Mon Sep 17 00:00:00 2001 From: Peter Bourgon Date: Fri, 27 Mar 2015 12:25:27 +0100 Subject: [PATCH 04/11] Prefer fmt.Fprintln where possible --- log/kv_logger.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/log/kv_logger.go b/log/kv_logger.go index d5c403beb..b086e701a 100644 --- a/log/kv_logger.go +++ b/log/kv_logger.go @@ -35,7 +35,7 @@ func (l *kvLogger) Log(s string) error { return err } if s[len(s)-1] != '\n' { - if _, err := fmt.Fprint(l.Writer, "\n"); err != nil { + if _, err := fmt.Fprintln(l.Writer); err != nil { return err } } From 0c141e5eba6bcde4d36391c14f387731c6064621 Mon Sep 17 00:00:00 2001 From: Peter Bourgon Date: Fri, 27 Mar 2015 16:36:44 +0100 Subject: [PATCH 05/11] log: add Levels object --- log/levels.go | 60 ++++++++++++++++++++++++++++++++++++++++++++++ log/levels_test.go | 46 +++++++++++++++++++++++++++++++++++ 2 files changed, 106 insertions(+) create mode 100644 log/levels.go create mode 100644 log/levels_test.go diff --git a/log/levels.go b/log/levels.go new file mode 100644 index 000000000..e5f5b0edb --- /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: base.With(Field{Key: opts.levelKey, Value: opts.debugValue}), + Info: base.With(Field{Key: opts.levelKey, Value: opts.infoValue}), + Error: base.With(Field{Key: opts.levelKey, Value: opts.errorValue}), + } +} diff --git a/log/levels_test.go b/log/levels_test.go new file mode 100644 index 000000000..670ee5cbc --- /dev/null +++ b/log/levels_test.go @@ -0,0 +1,46 @@ +package log_test + +import ( + "bytes" + "testing" + + "github.com/peterbourgon/gokit/log" +) + +func TestBasicLevels(t *testing.T) { + buf := bytes.Buffer{} + levels := log.NewLevels(log.NewKVLogger(&buf)) + + levels.Debug.Log("👨") // of course you'd want to do this + if want, have := "level=DEBUG 👨\n", buf.String(); want != have { + t.Errorf("want %#v, have %#v", want, have) + } + + buf.Reset() + levels.Info.Log("🚀") + if want, have := "level=INFO 🚀\n", buf.String(); want != have { + t.Errorf("want %#v, have %#v", want, have) + } + + buf.Reset() + levels.Error.Log("🍵") + if want, have := "level=ERROR 🍵\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("🌊"), + ) + + levels.Debug.With(log.Field{Key: "what", Value: "🗿"}).Log("💃💃💃") + if want, have := `{"l":"⛄","msg":"💃💃💃","what":"🗿"}`+"\n", buf.String(); want != have { + t.Errorf("want %#v, have %#v", want, have) + } +} From de6593151bf3980b946a95b2e3af8f4ca5386927 Mon Sep 17 00:00:00 2001 From: Peter Bourgon Date: Mon, 30 Mar 2015 12:57:08 +0200 Subject: [PATCH 06/11] log: changes from feedback - Drop the Field type; all methods take variadic interface{} - Introduce benchmarks - s/KVLogger/PrefixLogger/g --- log/benchmark_test.go | 21 +++++++++++++ log/json_logger.go | 47 +++++++++++++++++++++-------- log/json_logger_test.go | 24 ++++++++++----- log/kv_logger.go | 43 -------------------------- log/kv_logger_test.go | 62 -------------------------------------- log/levels.go | 6 ++-- log/levels_test.go | 6 ++-- log/log.go | 10 ++----- log/prefix_logger.go | 63 +++++++++++++++++++++++++++++++++++++++ log/prefix_logger_test.go | 46 ++++++++++++++++++++++++++++ 10 files changed, 190 insertions(+), 138 deletions(-) create mode 100644 log/benchmark_test.go delete mode 100644 log/kv_logger.go delete mode 100644 log/kv_logger_test.go create mode 100644 log/prefix_logger.go create mode 100644 log/prefix_logger_test.go diff --git a/log/benchmark_test.go b/log/benchmark_test.go new file mode 100644 index 000000000..d1ac7b9aa --- /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 = logger.With("common_key", "common_value") + b.ReportAllocs() + b.ResetTimer() + for i := 0; i < b.N; i++ { + f(logger) + } +} + +var ( + simpleMessage = func(logger log.Logger) { logger.Log("foo") } + contextualMessage = func(logger log.Logger) { logger.Log("bar", "foo_key", "foo_value") } +) diff --git a/log/json_logger.go b/log/json_logger.go index 04a378fe6..b5118a5e6 100644 --- a/log/json_logger.go +++ b/log/json_logger.go @@ -2,14 +2,14 @@ package log import ( "encoding/json" - + "fmt" "io" ) type jsonLogger struct { io.Writer - key string - fields []Field + key string + keyvals []interface{} } // NewJSONLogger returns a Logger that marshals each log line as a JSON @@ -30,19 +30,42 @@ func NewJSONLoggerWithKey(w io.Writer, messageKey string) Logger { } } -func (l *jsonLogger) With(fields ...Field) Logger { +func (l *jsonLogger) With(keyvals ...interface{}) Logger { + if len(keyvals)%2 == 1 { + panic("odd number of keyvals") + } return &jsonLogger{ - Writer: l.Writer, - key: l.key, - fields: append(l.fields, fields...), + Writer: l.Writer, + key: l.key, + keyvals: append(l.keyvals, keyvals...), } } -func (l *jsonLogger) Log(s string) error { - m := make(map[string]interface{}, len(l.fields)+1) - for _, f := range l.fields { - m[f.Key] = f.Value +func (l *jsonLogger) Log(message string, keyvals ...interface{}) error { + if len(keyvals)%2 == 1 { + panic("odd number of keyvals") + } + m := make(map[string]interface{}, len(l.keyvals)+len(keyvals)+1) + for i := 0; i < len(l.keyvals); i += 2 { + merge(m, l.keyvals[i], l.keyvals[i+1]) + } + for i := 0; i < len(keyvals); i += 2 { + merge(m, keyvals[i], keyvals[i+1]) } - m[l.key] = s + m[l.key] = message 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) + } + dst[key] = v + return dst +} diff --git a/log/json_logger_test.go b/log/json_logger_test.go index ddc5b8e2a..60854efb9 100644 --- a/log/json_logger_test.go +++ b/log/json_logger_test.go @@ -2,6 +2,7 @@ package log_test import ( "bytes" + "io/ioutil" "testing" "time" @@ -9,15 +10,16 @@ import ( ) func TestJSONLogger(t *testing.T) { - buf := bytes.Buffer{} - logger := log.NewJSONLogger(&buf) + buf := &bytes.Buffer{} + logger := log.NewJSONLogger(buf) + logger.Log("a") if want, have := `{"msg":"a"}`+"\n", buf.String(); want != have { t.Errorf("want %#v, have %#v", want, have) } buf.Reset() - if err := logger.With(log.Field{Key: "level", Value: "INFO"}).Log("b"); err != nil { + if err := logger.With("level", "INFO").Log("b"); err != nil { t.Fatal(err) } if want, have := `{"level":"INFO","msg":"b"}`+"\n", buf.String(); want != have { @@ -25,10 +27,10 @@ func TestJSONLogger(t *testing.T) { } buf.Reset() - logger = logger.With(log.Field{Key: "request.size", Value: 1024}) - logger = logger.With(log.Field{Key: "response.code", Value: 200}) - logger = logger.With(log.Field{Key: "response.duration", Value: 42 * time.Millisecond}) - logger = logger.With(log.Field{Key: "headers", Value: map[string][]string{"X-Foo": []string{"A", "B"}}}) + logger = logger.With("request.size", 1024) + logger = logger.With("response.code", 200) + logger = logger.With("response.duration", 42*time.Millisecond) + logger = logger.With("headers", map[string][]string{"X-Foo": []string{"A", "B"}}) if err := logger.Log("OK"); err != nil { t.Fatal(err) } @@ -36,3 +38,11 @@ func TestJSONLogger(t *testing.T) { t.Errorf("want\n\t%#v, have\n\t%#v", want, have) } } + +func BenchmarkJSONLoggerSimple(b *testing.B) { + benchmarkRunner(b, log.NewJSONLogger(ioutil.Discard), simpleMessage) +} + +func BenchmarkJSONLoggerContextual(b *testing.B) { + benchmarkRunner(b, log.NewJSONLogger(ioutil.Discard), contextualMessage) +} diff --git a/log/kv_logger.go b/log/kv_logger.go deleted file mode 100644 index b086e701a..000000000 --- a/log/kv_logger.go +++ /dev/null @@ -1,43 +0,0 @@ -package log - -import ( - "fmt" - "io" -) - -type kvLogger struct { - io.Writer - fields []Field -} - -// NewKVLogger returns a Logger that prefixes fields as space-separated "k=v" -// pairs on every log line. -func NewKVLogger(w io.Writer) Logger { - return &kvLogger{ - Writer: w, - } -} - -func (l *kvLogger) With(fields ...Field) Logger { - return &kvLogger{ - Writer: l.Writer, - fields: append(l.fields, fields...), - } -} - -func (l *kvLogger) Log(s string) error { - for _, f := range l.fields { - if _, err := fmt.Fprintf(l.Writer, "%s=%v ", f.Key, f.Value); err != nil { - return err - } - } - if _, err := fmt.Fprint(l.Writer, s); err != nil { - return err - } - if s[len(s)-1] != '\n' { - if _, err := fmt.Fprintln(l.Writer); err != nil { - return err - } - } - return nil -} diff --git a/log/kv_logger_test.go b/log/kv_logger_test.go deleted file mode 100644 index 57ef4abfe..000000000 --- a/log/kv_logger_test.go +++ /dev/null @@ -1,62 +0,0 @@ -package log_test - -import ( - "bytes" - "testing" - - "github.com/peterbourgon/gokit/log" -) - -func TestKVLogger(t *testing.T) { - buf := bytes.Buffer{} - logger := log.NewKVLogger(&buf) - logger.Log("a") - if want, have := "a\n", buf.String(); want != have { - t.Errorf("want %#v, have %#v", want, have) - } - - buf.Reset() - logger = logger.With(log.Field{Key: "level", Value: "DEBUG"}) - if err := logger.Log("b"); err != nil { - t.Fatal(err) - } - if want, have := "level=DEBUG b\n", buf.String(); want != have { - t.Errorf("want %#v, have %#v", want, have) - } - - buf.Reset() - if err := logger.With(log.Field{Key: "count", Value: 123}).Log("c"); err != nil { - t.Fatal(err) - } - if want, have := "level=DEBUG count=123 c\n", buf.String(); want != have { - t.Errorf("want %#v, have %#v", want, have) - } - - buf.Reset() - if err := logger.With(log.Field{Key: "m", Value: map[int]int{1: 2}}).Log("d"); err != nil { - t.Fatal(err) - } - if want, have := "level=DEBUG m=map[1:2] d\n", buf.String(); want != have { - t.Errorf("want %#v, have %#v", want, have) - } - - buf.Reset() - if err := logger.With(log.Field{Key: "my", Value: myMap{0: 0}}).Log("e"); err != nil { - t.Fatal(err) - } - if want, have := "level=DEBUG my=special-behavior e\n", buf.String(); want != have { - t.Errorf("want %#v, have %#v", want, have) - } - - buf.Reset() - if err := logger.With(log.Field{Key: "a", Value: 1}, log.Field{Key: "b", Value: 2}).Log("f"); err != nil { - t.Fatal(err) - } - if want, have := "level=DEBUG a=1 b=2 f\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" } diff --git a/log/levels.go b/log/levels.go index e5f5b0edb..40f93ea6b 100644 --- a/log/levels.go +++ b/log/levels.go @@ -53,8 +53,8 @@ func NewLevels(base Logger, options ...LevelOption) Levels { option(opts) } return Levels{ - Debug: base.With(Field{Key: opts.levelKey, Value: opts.debugValue}), - Info: base.With(Field{Key: opts.levelKey, Value: opts.infoValue}), - Error: base.With(Field{Key: opts.levelKey, Value: opts.errorValue}), + Debug: base.With(opts.levelKey, opts.debugValue), + Info: base.With(opts.levelKey, opts.infoValue), + Error: base.With(opts.levelKey, opts.errorValue), } } diff --git a/log/levels_test.go b/log/levels_test.go index 670ee5cbc..565b9de0e 100644 --- a/log/levels_test.go +++ b/log/levels_test.go @@ -9,7 +9,7 @@ import ( func TestBasicLevels(t *testing.T) { buf := bytes.Buffer{} - levels := log.NewLevels(log.NewKVLogger(&buf)) + levels := log.NewLevels(log.NewPrefixLogger(&buf)) levels.Debug.Log("👨") // of course you'd want to do this if want, have := "level=DEBUG 👨\n", buf.String(); want != have { @@ -39,8 +39,8 @@ func TestModifiedLevels(t *testing.T) { log.ErrorLevelValue("🌊"), ) - levels.Debug.With(log.Field{Key: "what", Value: "🗿"}).Log("💃💃💃") - if want, have := `{"l":"⛄","msg":"💃💃💃","what":"🗿"}`+"\n", buf.String(); want != have { + levels.Debug.With("easter_island", "🗿").Log("💃💃💃") + 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 index c4958b2a7..cc646300c 100644 --- a/log/log.go +++ b/log/log.go @@ -2,12 +2,6 @@ package log // Logger is the least-common-denominator interface for all log operations. type Logger interface { - With(...Field) Logger - Log(string) error -} - -// Field is a key/value pair associated with a log event. -type Field struct { - Key string - Value interface{} + With(keyvals ...interface{}) Logger + Log(message string, keyvals ...interface{}) error } diff --git a/log/prefix_logger.go b/log/prefix_logger.go new file mode 100644 index 000000000..983c611d4 --- /dev/null +++ b/log/prefix_logger.go @@ -0,0 +1,63 @@ +package log + +import ( + "fmt" + "io" +) + +type prefixLogger struct { + io.Writer + keyvals []interface{} +} + +// NewPrefixLogger returns a basic logger that encodes all keyvals as simple +// "k=v" pairs prefixed on each log line. +func NewPrefixLogger(w io.Writer) Logger { + return &prefixLogger{ + Writer: w, + } +} + +func (l *prefixLogger) With(keyvals ...interface{}) Logger { + if len(keyvals)%2 == 1 { + panic("odd number of keyvals") + } + return &prefixLogger{ + Writer: l.Writer, + keyvals: append(l.keyvals, keyvals...), + } +} + +func (l *prefixLogger) Log(message string, keyvals ...interface{}) error { + if len(keyvals)%2 == 1 { + panic("odd number of keyvals") + } + if err := encodeMany(l.Writer, l.keyvals...); err != nil { + return err + } + if err := encodeMany(l.Writer, keyvals...); err != nil { + return err + } + if _, err := fmt.Fprint(l.Writer, message); err != nil { + return err + } + if message[len(message)-1] != '\n' { + if _, err := fmt.Fprintln(l.Writer); err != nil { + return err + } + } + return nil +} + +func encodeMany(w io.Writer, keyvals ...interface{}) error { + if len(keyvals)%2 == 1 { + panic("odd number of keyvals") + } + for i := 0; i < len(keyvals); i += 2 { + _, err := fmt.Fprintf(w, "%s=%v ", keyvals[i], keyvals[i+1]) + if 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..c998e6d1a --- /dev/null +++ b/log/prefix_logger_test.go @@ -0,0 +1,46 @@ +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"); err != nil { + t.Fatal(err) + } + if want, have := "hello\n", buf.String(); want != have { + t.Errorf("want %#v, have %#v", want, have) + } + + buf.Reset() + if err := logger.Log("world", "k", "v"); err != nil { + t.Fatal(err) + } + if want, have := "k=v world\n", buf.String(); want != have { + t.Errorf("want %#v, have %#v", want, have) + } + + buf.Reset() + if err := logger.With("z", 1, "a", 2).Log("🐰", "m", errors.New("n")); err != nil { + t.Fatal(err) + } + if want, have := "z=1 a=2 m=n 🐰\n", buf.String(); want != have { + t.Errorf("want %#v, have %#v", want, have) + } +} + +func BenchmarkPrefixLoggerSimple(b *testing.B) { + benchmarkRunner(b, log.NewPrefixLogger(ioutil.Discard), simpleMessage) +} + +func BenchmarkPrefixLoggerContextual(b *testing.B) { + benchmarkRunner(b, log.NewPrefixLogger(ioutil.Discard), contextualMessage) +} From 580420abdcf6ac7a3aea162191a657bd3fdc8429 Mon Sep 17 00:00:00 2001 From: Peter Bourgon Date: Tue, 31 Mar 2015 13:56:08 +0200 Subject: [PATCH 07/11] Resolve JSON logger error vals --- log/json_logger.go | 3 +++ log/json_logger_test.go | 11 +++++++++++ 2 files changed, 14 insertions(+) diff --git a/log/json_logger.go b/log/json_logger.go index b5118a5e6..df23b79c4 100644 --- a/log/json_logger.go +++ b/log/json_logger.go @@ -66,6 +66,9 @@ func merge(dst map[string]interface{}, k, v interface{}) map[string]interface{} 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 index 60854efb9..dfa662cd0 100644 --- a/log/json_logger_test.go +++ b/log/json_logger_test.go @@ -2,6 +2,7 @@ package log_test import ( "bytes" + "errors" "io/ioutil" "testing" "time" @@ -39,6 +40,16 @@ func TestJSONLogger(t *testing.T) { } } +func TestJSONLoggerErrorVal(t *testing.T) { + buf := &bytes.Buffer{} + if err := log.NewJSONLogger(buf).Log("-", "error", errors.New(":(")); err != nil { + t.Fatal(err) + } + if want, have := `{"error":":(","msg":"-"}`+"\n", buf.String(); want != have { + t.Errorf("want\n\t%#v, have\n\t%#v", want, have) + } +} + func BenchmarkJSONLoggerSimple(b *testing.B) { benchmarkRunner(b, log.NewJSONLogger(ioutil.Discard), simpleMessage) } From f307245c7b0e803ee71081baf7ec34e755eb416f Mon Sep 17 00:00:00 2001 From: Peter Bourgon Date: Wed, 1 Apr 2015 16:48:32 +0200 Subject: [PATCH 08/11] Logger becomes one-method interface - With extracted to helper function - Add Wither optimization interface - Rework the two Logger implementations - Rework tests and benchmarks --- log/benchmark_test.go | 6 ++--- log/json_logger.go | 39 ++++------------------------ log/json_logger_test.go | 38 +++------------------------- log/levels.go | 6 ++--- log/levels_test.go | 17 ++++++------- log/log.go | 28 ++++++++++++++++++++- log/log_test.go | 35 ++++++++++++++++++++++++++ log/prefix_logger.go | 53 ++++++++++----------------------------- log/prefix_logger_test.go | 20 +++++++++------ 9 files changed, 110 insertions(+), 132 deletions(-) create mode 100644 log/log_test.go diff --git a/log/benchmark_test.go b/log/benchmark_test.go index d1ac7b9aa..1a231593f 100644 --- a/log/benchmark_test.go +++ b/log/benchmark_test.go @@ -7,7 +7,7 @@ import ( ) func benchmarkRunner(b *testing.B, logger log.Logger, f func(log.Logger)) { - logger = logger.With("common_key", "common_value") + logger = log.With(logger, "common_key", "common_value") b.ReportAllocs() b.ResetTimer() for i := 0; i < b.N; i++ { @@ -16,6 +16,6 @@ func benchmarkRunner(b *testing.B, logger log.Logger, f func(log.Logger)) { } var ( - simpleMessage = func(logger log.Logger) { logger.Log("foo") } - contextualMessage = func(logger log.Logger) { logger.Log("bar", "foo_key", "foo_value") } + 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 index df23b79c4..8907c8f9d 100644 --- a/log/json_logger.go +++ b/log/json_logger.go @@ -8,51 +8,22 @@ import ( type jsonLogger struct { io.Writer - key string - keyvals []interface{} } -// NewJSONLogger returns a Logger that marshals each log line as a JSON -// object. Because fields are keys in a JSON object, they must be unique, and -// last-writer-wins. The actual log message is placed under the "msg" key. To -// change that, use the NewJSONLoggerWithKey constructor. +// NewJSONLogger returns a Logger that encodes keyvals to the Writer as a +// single JSON object. func NewJSONLogger(w io.Writer) Logger { - return NewJSONLoggerWithKey(w, "msg") + return &jsonLogger{w} } -// NewJSONLoggerWithKey is the same as NewJSONLogger but allows the user to -// specify the key under which the actual log message is placed in the JSON -// object. -func NewJSONLoggerWithKey(w io.Writer, messageKey string) Logger { - return &jsonLogger{ - Writer: w, - key: messageKey, - } -} - -func (l *jsonLogger) With(keyvals ...interface{}) Logger { - if len(keyvals)%2 == 1 { - panic("odd number of keyvals") - } - return &jsonLogger{ - Writer: l.Writer, - key: l.key, - keyvals: append(l.keyvals, keyvals...), - } -} - -func (l *jsonLogger) Log(message string, keyvals ...interface{}) error { +func (l *jsonLogger) Log(keyvals ...interface{}) error { if len(keyvals)%2 == 1 { panic("odd number of keyvals") } - m := make(map[string]interface{}, len(l.keyvals)+len(keyvals)+1) - for i := 0; i < len(l.keyvals); i += 2 { - merge(m, l.keyvals[i], l.keyvals[i+1]) - } + m := make(map[string]interface{}, len(keyvals)/2) for i := 0; i < len(keyvals); i += 2 { merge(m, keyvals[i], keyvals[i+1]) } - m[l.key] = message return json.NewEncoder(l.Writer).Encode(m) } diff --git a/log/json_logger_test.go b/log/json_logger_test.go index dfa662cd0..f724de1e5 100644 --- a/log/json_logger_test.go +++ b/log/json_logger_test.go @@ -5,7 +5,6 @@ import ( "errors" "io/ioutil" "testing" - "time" "github.com/peterbourgon/gokit/log" ) @@ -13,47 +12,18 @@ import ( func TestJSONLogger(t *testing.T) { buf := &bytes.Buffer{} logger := log.NewJSONLogger(buf) - - logger.Log("a") - if want, have := `{"msg":"a"}`+"\n", buf.String(); want != have { - t.Errorf("want %#v, have %#v", want, have) - } - - buf.Reset() - if err := logger.With("level", "INFO").Log("b"); err != nil { + 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 := `{"level":"INFO","msg":"b"}`+"\n", buf.String(); want != have { + 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) } - - buf.Reset() - logger = logger.With("request.size", 1024) - logger = logger.With("response.code", 200) - logger = logger.With("response.duration", 42*time.Millisecond) - logger = logger.With("headers", map[string][]string{"X-Foo": []string{"A", "B"}}) - if err := logger.Log("OK"); err != nil { - t.Fatal(err) - } - if want, have := `{"headers":{"X-Foo":["A","B"]},"msg":"OK","request.size":1024,"response.code":200,"response.duration":42000000}`+"\n", buf.String(); want != have { - t.Errorf("want\n\t%#v, have\n\t%#v", want, have) - } -} - -func TestJSONLoggerErrorVal(t *testing.T) { - buf := &bytes.Buffer{} - if err := log.NewJSONLogger(buf).Log("-", "error", errors.New(":(")); err != nil { - t.Fatal(err) - } - if want, have := `{"error":":(","msg":"-"}`+"\n", buf.String(); want != have { - t.Errorf("want\n\t%#v, have\n\t%#v", want, have) - } } func BenchmarkJSONLoggerSimple(b *testing.B) { - benchmarkRunner(b, log.NewJSONLogger(ioutil.Discard), simpleMessage) + benchmarkRunner(b, log.NewJSONLogger(ioutil.Discard), baseMessage) } func BenchmarkJSONLoggerContextual(b *testing.B) { - benchmarkRunner(b, log.NewJSONLogger(ioutil.Discard), contextualMessage) + benchmarkRunner(b, log.NewJSONLogger(ioutil.Discard), withMessage) } diff --git a/log/levels.go b/log/levels.go index 40f93ea6b..4c7079bb0 100644 --- a/log/levels.go +++ b/log/levels.go @@ -53,8 +53,8 @@ func NewLevels(base Logger, options ...LevelOption) Levels { option(opts) } return Levels{ - Debug: base.With(opts.levelKey, opts.debugValue), - Info: base.With(opts.levelKey, opts.infoValue), - Error: base.With(opts.levelKey, opts.errorValue), + 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 index 565b9de0e..a906c7a30 100644 --- a/log/levels_test.go +++ b/log/levels_test.go @@ -7,24 +7,24 @@ import ( "github.com/peterbourgon/gokit/log" ) -func TestBasicLevels(t *testing.T) { +func TestDefaultLevels(t *testing.T) { buf := bytes.Buffer{} levels := log.NewLevels(log.NewPrefixLogger(&buf)) - levels.Debug.Log("👨") // of course you'd want to do this - if want, have := "level=DEBUG 👨\n", buf.String(); want != have { + 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("🚀") - if want, have := "level=INFO 🚀\n", buf.String(); want != have { + 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("🍵") - if want, have := "level=ERROR 🍵\n", buf.String(); want != have { + levels.Error.Log("msg", "🍵") + if want, have := "level=ERROR msg=🍵\n", buf.String(); want != have { t.Errorf("want %#v, have %#v", want, have) } } @@ -38,8 +38,7 @@ func TestModifiedLevels(t *testing.T) { log.InfoLevelValue("🌜"), log.ErrorLevelValue("🌊"), ) - - levels.Debug.With("easter_island", "🗿").Log("💃💃💃") + 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 index cc646300c..305923899 100644 --- a/log/log.go +++ b/log/log.go @@ -2,6 +2,32 @@ 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 - Log(message string, keyvals ...interface{}) error } 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 index 983c611d4..f37324a72 100644 --- a/log/prefix_logger.go +++ b/log/prefix_logger.go @@ -7,57 +7,30 @@ import ( type prefixLogger struct { io.Writer - keyvals []interface{} } -// NewPrefixLogger returns a basic logger that encodes all keyvals as simple -// "k=v" pairs prefixed on each log line. +// NewPrefixLogger returns a basic logger that encodes keyvals as simple "k=v" +// pairs to the Writer. func NewPrefixLogger(w io.Writer) Logger { - return &prefixLogger{ - Writer: w, - } -} - -func (l *prefixLogger) With(keyvals ...interface{}) Logger { - if len(keyvals)%2 == 1 { - panic("odd number of keyvals") - } - return &prefixLogger{ - Writer: l.Writer, - keyvals: append(l.keyvals, keyvals...), - } + return &prefixLogger{w} } -func (l *prefixLogger) Log(message string, keyvals ...interface{}) error { - if len(keyvals)%2 == 1 { - panic("odd number of keyvals") - } - if err := encodeMany(l.Writer, l.keyvals...); err != nil { - return err - } - if err := encodeMany(l.Writer, keyvals...); err != nil { - return err - } - if _, err := fmt.Fprint(l.Writer, message); err != nil { - return err - } - if message[len(message)-1] != '\n' { - if _, err := fmt.Fprintln(l.Writer); err != nil { - return err - } - } - return nil -} - -func encodeMany(w io.Writer, keyvals ...interface{}) error { +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 { - _, err := fmt.Fprintf(w, "%s=%v ", keyvals[i], keyvals[i+1]) - if err != nil { + 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 index c998e6d1a..f0bb60931 100644 --- a/log/prefix_logger_test.go +++ b/log/prefix_logger_test.go @@ -13,34 +13,38 @@ func TestPrefixLogger(t *testing.T) { buf := &bytes.Buffer{} logger := log.NewPrefixLogger(buf) - if err := logger.Log("hello"); err != nil { + if err := logger.Log("hello", "world"); err != nil { t.Fatal(err) } - if want, have := "hello\n", buf.String(); want != have { + if want, have := "hello=world\n", buf.String(); want != have { t.Errorf("want %#v, have %#v", want, have) } buf.Reset() - if err := logger.Log("world", "k", "v"); err != nil { + if err := logger.Log("a", 1, "err", errors.New("error")); err != nil { t.Fatal(err) } - if want, have := "k=v world\n", buf.String(); want != have { + 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.With("z", 1, "a", 2).Log("🐰", "m", errors.New("n")); err != nil { + if err := logger.Log("std_map", map[int]int{1: 2}, "my_map", mymap{0: 0}); err != nil { t.Fatal(err) } - if want, have := "z=1 a=2 m=n 🐰\n", buf.String(); want != have { + 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), simpleMessage) + benchmarkRunner(b, log.NewPrefixLogger(ioutil.Discard), baseMessage) } func BenchmarkPrefixLoggerContextual(b *testing.B) { - benchmarkRunner(b, log.NewPrefixLogger(ioutil.Discard), contextualMessage) + benchmarkRunner(b, log.NewPrefixLogger(ioutil.Discard), withMessage) } From dd0f49fe8579e8cc0e1a35a9a87e049f90ab61d0 Mon Sep 17 00:00:00 2001 From: Peter Bourgon Date: Thu, 2 Apr 2015 12:41:06 +0200 Subject: [PATCH 09/11] Add StdlibWriter adapter - Allows Loggers to be passed to log.SetOutput - Extracts date, time, file, message keyvals - I have no idea how to support SetPrefix :( --- log/stdlib_writer.go | 100 ++++++++++++++++++++++++++++++++++++ log/stdlib_writer_test.go | 103 ++++++++++++++++++++++++++++++++++++++ 2 files changed, 203 insertions(+) create mode 100644 log/stdlib_writer.go create mode 100644 log/stdlib_writer_test.go 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