From 40611a8494bbf62a09e5aa6fb57addb12cb09d62 Mon Sep 17 00:00:00 2001 From: Nicholas Wiersma Date: Fri, 14 May 2021 19:48:46 +0200 Subject: [PATCH] feat: major refactor (#17) --- .golangci.yml | 2 - .travis.yml | 1 - README.md | 22 +- bench_test.go | 95 +++-- ctx/ctx.go | 154 +++++++ doc.go | 14 +- event.go | 111 ++++- example_test.go | 51 +-- format.go | 479 ++++++++++----------- format_test.go | 563 +++++++++++++------------ go.mod | 7 +- go.sum | 3 +- handler.go | 190 --------- handler_test.go | 103 ----- internal/bytes/buffer.go | 68 +-- internal/bytes/buffer_internal_test.go | 62 +-- logger.go | 99 +++-- logger_test.go | 151 +++---- mocks_test.go | 14 - writer.go | 26 ++ writer_test.go | 22 + 21 files changed, 1073 insertions(+), 1164 deletions(-) create mode 100644 ctx/ctx.go delete mode 100644 handler.go delete mode 100644 handler_test.go delete mode 100644 mocks_test.go create mode 100644 writer.go create mode 100644 writer_test.go diff --git a/.golangci.yml b/.golangci.yml index 7b3753e..024ba5f 100644 --- a/.golangci.yml +++ b/.golangci.yml @@ -4,11 +4,9 @@ run: linters: enable-all: true disable: - - cyclop - exhaustive - exhaustivestruct - forcetypeassert - - funlen - gochecknoglobals - gochecknoinits - gocognit diff --git a/.travis.yml b/.travis.yml index 110a49c..87cb358 100644 --- a/.travis.yml +++ b/.travis.yml @@ -2,7 +2,6 @@ sudo: false language: go go: - - "1.15.x" - "1.16.x" - "1.x" diff --git a/README.md b/README.md index 8baea74..01dffa4 100644 --- a/README.md +++ b/README.md @@ -23,34 +23,26 @@ go get github.com/hamba/logger * **Logfmt** * **Console** -#### Handlers +#### Writers -* **StreamHandler** Write directly to a Writer, usually `os.Stdout` -* **BufferedStreamHandler** A buffered version of `StreamHandler` -* **FilterHandler** Filter log line using a function -* **LevelFilterHandler** Filter log line by level -* **DiscardHandler** Discard everything +* **SyncWriter** Write synchronised to a Writer ## Examples ```go -// Composable handlers -h := logger.LevelFilterHandler( - logger.Info, - logger.StreamHandler(os.Stdout, logger.LogfmtFormat()), -) +log := logger.New(os.Stdout, logger.LogfmtFormat(), logger.Info) -// The logger can have an initial context -l := logger.New(h, "env", "prod") +// Logger can have scoped context +log = log.With(ctx.Str("env", "prod")) // All messages can have a context -l.Warn("connection error", "redis", conn.Name(), "timeout", conn.Timeout()) +log.Warn("connection error", ctx.Str("redis", "dsn_1"), ctx.Int("timeout", conn.Timeout())) ``` Will log the message ``` -lvl=warn msg="connection error" redis=dsn_1 timeout=0.500 +lvl=warn msg="connection error" env=prod redis=dsn_1 timeout=0.500 ``` More examples can be found in the [godocs](https://godoc.org/github.com/hamba/logger). diff --git a/bench_test.go b/bench_test.go index 7c79bff..293e25f 100644 --- a/bench_test.go +++ b/bench_test.go @@ -1,77 +1,86 @@ package logger_test import ( - "io/ioutil" + "io" "os" "testing" "github.com/hamba/logger" + "github.com/hamba/logger/ctx" ) -func BenchmarkLogged_Logfmt(b *testing.B) { - l := logger.New(logger.StreamHandler(ioutil.Discard, logger.LogfmtFormat())) +func BenchmarkLogger_Logfmt(b *testing.B) { + log := logger.New(io.Discard, logger.LogfmtFormat(), logger.Debug) b.ReportAllocs() b.ResetTimer() - for i := 0; i < b.N; i++ { - l.Error("some message") - } - b.StopTimer() + b.RunParallel(func(pb *testing.PB) { + for pb.Next() { + log.Error("some message") + } + }) } -func BenchmarkLogged_Json(b *testing.B) { - l := logger.New(logger.StreamHandler(ioutil.Discard, logger.JSONFormat())) +func BenchmarkLogger_Json(b *testing.B) { + log := logger.New(io.Discard, logger.JSONFormat(), logger.Debug) b.ReportAllocs() b.ResetTimer() - for i := 0; i < b.N; i++ { - l.Error("some message") - } - b.StopTimer() + b.RunParallel(func(pb *testing.PB) { + for pb.Next() { + log.Error("some message") + } + }) } -func BenchmarkLogged_LogfmtCtx(b *testing.B) { - l := logger.New(logger.StreamHandler(ioutil.Discard, logger.LogfmtFormat()), "_n", "bench", "_p", 1) +func BenchmarkLogger_LogfmtCtx(b *testing.B) { + log := logger.New(io.Discard, logger.LogfmtFormat(), logger.Debug).With(ctx.Str("_n", "bench"), ctx.Int("_p", 1)) b.ReportAllocs() b.ResetTimer() - for i := 0; i < b.N; i++ { - l.Error("some message", "key", 1, "key2", 3.141592, "key3", "string", "key4", false) - } - b.StopTimer() + b.RunParallel(func(pb *testing.PB) { + for pb.Next() { + log.Error("some message", ctx.Int("key", 1), ctx.Float64("key2", 3.141592), ctx.Str("key3", "string"), ctx.Bool("key4", false)) + } + }) } -func BenchmarkLogged_JsonCtx(b *testing.B) { - l := logger.New(logger.StreamHandler(ioutil.Discard, logger.JSONFormat()), "_n", "bench", "_p", 1) +func BenchmarkLogger_JsonCtx(b *testing.B) { + log := logger.New(io.Discard, logger.JSONFormat(), logger.Debug).With(ctx.Str("_n", "bench"), ctx.Int("_p", 1)) b.ReportAllocs() b.ResetTimer() - for i := 0; i < b.N; i++ { - l.Error("some message", "key", 1, "key2", 3.141592, "key3", "string", "key4", false) - } - b.StopTimer() + b.RunParallel(func(pb *testing.PB) { + for pb.Next() { + log.Error("some message", ctx.Int("key", 1), ctx.Float64("key2", 3.141592), ctx.Str("key3", "string"), ctx.Bool("key4", false)) + } + }) } -func BenchmarkLevelLogged_Logfmt(b *testing.B) { +func BenchmarkLevelLogger_Logfmt(b *testing.B) { + log := logger.New(io.Discard, logger.LogfmtFormat(), logger.Debug).With(ctx.Str("_n", "bench"), ctx.Int("_p", os.Getpid())) + b.ResetTimer() - l := logger.New(logger.StreamHandler(ioutil.Discard, logger.LogfmtFormat()), "_n", "bench", "_p", os.Getpid()) - for i := 0; i < b.N; i++ { - l.Debug("debug", "key", 1, "key2", 3.141592, "key3", "string", "key4", false) - l.Info("info", "key", 1, "key2", 3.141592, "key3", "string", "key4", false) - l.Warn("warn", "key", 1, "key2", 3.141592, "key3", "string", "key4", false) - l.Error("error", "key", 1, "key2", 3.141592, "key3", "string", "key4", false) - } - b.StopTimer() + b.RunParallel(func(pb *testing.PB) { + for pb.Next() { + log.Debug("debug", ctx.Int("key", 1), ctx.Float64("key2", 3.141592), ctx.Str("key3", "string"), ctx.Bool("key4", false)) + log.Info("info", ctx.Int("key", 1), ctx.Float64("key2", 3.141592), ctx.Str("key3", "string"), ctx.Bool("key4", false)) + log.Warn("warn", ctx.Int("key", 1), ctx.Float64("key2", 3.141592), ctx.Str("key3", "string"), ctx.Bool("key4", false)) + log.Error("error", ctx.Int("key", 1), ctx.Float64("key2", 3.141592), ctx.Str("key3", "string"), ctx.Bool("key4", false)) + } + }) } -func BenchmarkLevelLogged_Json(b *testing.B) { +func BenchmarkLevelLogger_Json(b *testing.B) { + log := logger.New(io.Discard, logger.LogfmtFormat(), logger.Debug).With(ctx.Str("_n", "bench"), ctx.Int("_p", os.Getpid())) + b.ResetTimer() - l := logger.New(logger.StreamHandler(ioutil.Discard, logger.JSONFormat()), "_n", "bench", "_p", os.Getpid()) - for i := 0; i < b.N; i++ { - l.Debug("debug", "key", 1, "key2", 3.141592, "key3", "string", "key4", false) - l.Info("info", "key", 1, "key2", 3.141592, "key3", "string", "key4", false) - l.Warn("warn", "key", 1, "key2", 3.141592, "key3", "string", "key4", false) - l.Error("error", "key", 1, "key2", 3.141592, "key3", "string", "key4", false) - } - b.StopTimer() + b.RunParallel(func(pb *testing.PB) { + for pb.Next() { + log.Debug("debug", ctx.Int("key", 1), ctx.Float64("key2", 3.141592), ctx.Str("key3", "string"), ctx.Bool("key4", false)) + log.Info("info", ctx.Int("key", 1), ctx.Float64("key2", 3.141592), ctx.Str("key3", "string"), ctx.Bool("key4", false)) + log.Warn("warn", ctx.Int("key", 1), ctx.Float64("key2", 3.141592), ctx.Str("key3", "string"), ctx.Bool("key4", false)) + log.Error("error", ctx.Int("key", 1), ctx.Float64("key2", 3.141592), ctx.Str("key3", "string"), ctx.Bool("key4", false)) + } + }) } diff --git a/ctx/ctx.go b/ctx/ctx.go new file mode 100644 index 0000000..ea3cfff --- /dev/null +++ b/ctx/ctx.go @@ -0,0 +1,154 @@ +package ctx + +import ( + "time" + + "github.com/hamba/logger" +) + +// Str returns a string context field. +func Str(k, s string) logger.Field { + return func(e *logger.Event) { + e.AppendString(k, s) + } +} + +// Strs returns a string slice context field. +func Strs(k string, s []string) logger.Field { + return func(e *logger.Event) { + e.AppendStrings(k, s) + } +} + +// Bytes returns a byte slice context field. +func Bytes(k string, p []byte) logger.Field { + return func(e *logger.Event) { + e.AppendBytes(k, p) + } +} + +// Bool returns a boolean context field. +func Bool(k string, b bool) logger.Field { + return func(e *logger.Event) { + e.AppendBool(k, b) + } +} + +// Int returns an int context field. +func Int(k string, i int) logger.Field { + return func(e *logger.Event) { + e.AppendInt(k, int64(i)) + } +} + +// Ints returns an int slice context field. +func Ints(k string, a []int) logger.Field { + return func(e *logger.Event) { + e.AppendInts(k, a) + } +} + +// Int8 returns an int8 context field. +func Int8(k string, i int8) logger.Field { + return func(e *logger.Event) { + e.AppendInt(k, int64(i)) + } +} + +// Int16 returns an int16 context field. +func Int16(k string, i int16) logger.Field { + return func(e *logger.Event) { + e.AppendInt(k, int64(i)) + } +} + +// Int32 returns an int32 context field. +func Int32(k string, i int32) logger.Field { + return func(e *logger.Event) { + e.AppendInt(k, int64(i)) + } +} + +// Int64 returns an int64 context field. +func Int64(k string, i int64) logger.Field { + return func(e *logger.Event) { + e.AppendInt(k, i) + } +} + +// Uint returns a uint context field. +func Uint(k string, i uint) logger.Field { + return func(e *logger.Event) { + e.AppendUint(k, uint64(i)) + } +} + +// Uint8 returns a uint8 context field. +func Uint8(k string, i uint8) logger.Field { + return func(e *logger.Event) { + e.AppendUint(k, uint64(i)) + } +} + +// Uint16 returns a uint16 context field. +func Uint16(k string, i uint16) logger.Field { + return func(e *logger.Event) { + e.AppendUint(k, uint64(i)) + } +} + +// Uint32 returns a uint32 context field. +func Uint32(k string, i uint32) logger.Field { + return func(e *logger.Event) { + e.AppendUint(k, uint64(i)) + } +} + +// Uint64 returns a uint64 context field. +func Uint64(k string, i uint64) logger.Field { + return func(e *logger.Event) { + e.AppendUint(k, i) + } +} + +// Float32 returns a float32 context field. +func Float32(k string, f float32) logger.Field { + return func(e *logger.Event) { + e.AppendFloat(k, float64(f)) + } +} + +// Float64 returns a float64 context field. +func Float64(k string, f float64) logger.Field { + return func(e *logger.Event) { + e.AppendFloat(k, f) + } +} + +// Error returns an error context field. +func Error(k string, err error) logger.Field { + return func(e *logger.Event) { + e.AppendString(k, err.Error()) + } +} + +// Time returns a time context field. +func Time(k string, t time.Time) logger.Field { + return func(e *logger.Event) { + e.AppendTime(k, t) + } +} + +// Duration returns a duration context field. +func Duration(k string, d time.Duration) logger.Field { + return func(e *logger.Event) { + e.AppendDuration(k, d) + } +} + +// Interface returns an interface context field. +func Interface(k string, v interface{}) logger.Field { + return func(e *logger.Event) { + e.AppendInterface(k, v) + } +} diff --git a/doc.go b/doc.go index 5a151ae..4ba6fe8 100644 --- a/doc.go +++ b/doc.go @@ -1,19 +1,13 @@ /* Package logger implements a logging package. -logger implements github.com/hamba/pkg Logger interface. - Example usage: - // Composable handlers - h := logger.LevelFilterHandler( - logger.Info, - logger.StreamHandler(os.Stdout, logger.LogfmtFormat()), - ) + log := logger.New(os.Stdout, logger.LogfmtFormat(), logger.Info) - // The logger can have an initial context - l := logger.New(h, "env", "prod") + // Logger can have scoped context + log = log.With(ctx.Str("env", "prod")) // All messages can have a context - l.Error("connection error", "redis", conn.Name(), "timeout", conn.Timeout()) + log.Error("connection error", ctx.Str("redis", conn.Name()), ctx.Int("timeout", conn.Timeout())) */ package logger diff --git a/event.go b/event.go index bffe070..ae391da 100644 --- a/event.go +++ b/event.go @@ -1,29 +1,120 @@ package logger -import "sync" +import ( + "sync" + "time" + + "github.com/hamba/logger/internal/bytes" +) var eventPool = &sync.Pool{ New: func() interface{} { - return &Event{} + return &Event{ + buf: bytes.NewBuffer(512), + } }, } // Event is a log event. type Event struct { - Time int64 - Msg string - Lvl Level - BaseCtx []interface{} - Ctx []interface{} + fmtr Formatter + buf *bytes.Buffer } -func newEvent(msg string, lvl Level) *Event { +func newEvent(fmtr Formatter) *Event { e := eventPool.Get().(*Event) - e.Msg = msg - e.Lvl = lvl + e.fmtr = fmtr + e.buf.Reset() return e } func putEvent(e *Event) { eventPool.Put(e) } + +// AppendString appends a string to the event. +func (e *Event) AppendString(k, s string) { + e.fmtr.AppendKey(e.buf, k) + e.fmtr.AppendString(e.buf, s) +} + +// AppendStrings appends strings to the event. +func (e *Event) AppendStrings(k string, s []string) { + e.fmtr.AppendKey(e.buf, k) + e.fmtr.AppendArrayStart(e.buf) + for i, ss := range s { + if i > 0 { + e.fmtr.AppendArraySep(e.buf) + } + e.fmtr.AppendString(e.buf, ss) + } + e.fmtr.AppendArrayEnd(e.buf) +} + +// AppendBytes appends bytes to the event. +func (e *Event) AppendBytes(k string, p []byte) { + e.fmtr.AppendKey(e.buf, k) + e.fmtr.AppendArrayStart(e.buf) + for i, b := range p { + if i > 0 { + e.fmtr.AppendArraySep(e.buf) + } + e.fmtr.AppendInt(e.buf, int64(b)) + } + e.fmtr.AppendArrayEnd(e.buf) +} + +// AppendBool appends a bool to the event. +func (e *Event) AppendBool(k string, b bool) { + e.fmtr.AppendKey(e.buf, k) + e.fmtr.AppendBool(e.buf, b) +} + +// AppendInt appends an int to the event. +func (e *Event) AppendInt(k string, i int64) { + e.fmtr.AppendKey(e.buf, k) + e.fmtr.AppendInt(e.buf, i) +} + +// AppendInts appends ints to the event. +func (e *Event) AppendInts(k string, a []int) { + e.fmtr.AppendKey(e.buf, k) + e.fmtr.AppendArrayStart(e.buf) + for i, ii := range a { + if i > 0 { + e.fmtr.AppendArraySep(e.buf) + } + e.fmtr.AppendInt(e.buf, int64(ii)) + } + e.fmtr.AppendArrayEnd(e.buf) +} + +// AppendUint appends a uint to the event. +func (e *Event) AppendUint(k string, i uint64) { + e.fmtr.AppendKey(e.buf, k) + e.fmtr.AppendUint(e.buf, i) +} + +// AppendFloat appends a float to the event. +func (e *Event) AppendFloat(k string, f float64) { + e.fmtr.AppendKey(e.buf, k) + e.fmtr.AppendFloat(e.buf, f) +} + +// AppendTime appends a time to the event. +func (e *Event) AppendTime(k string, d time.Time) { + e.fmtr.AppendKey(e.buf, k) + e.fmtr.AppendTime(e.buf, d) +} + +// AppendDuration appends a duration to the event. +func (e *Event) AppendDuration(k string, d time.Duration) { + e.fmtr.AppendKey(e.buf, k) + e.fmtr.AppendDuration(e.buf, d) +} + +// AppendInterface appends a interface to the event. +func (e *Event) AppendInterface(k string, v interface{}) { + e.fmtr.AppendKey(e.buf, k) + e.fmtr.AppendInterface(e.buf, v) +} diff --git a/example_test.go b/example_test.go index b1ed0c0..18c24f0 100644 --- a/example_test.go +++ b/example_test.go @@ -2,58 +2,19 @@ package logger_test import ( "os" - "time" "github.com/hamba/logger" + "github.com/hamba/logger/ctx" ) func ExampleNew() { - h := logger.LevelFilterHandler( - logger.Info, - logger.StreamHandler(os.Stdout, logger.LogfmtFormat()), - ) + log := logger.New(os.Stdout, logger.LogfmtFormat(), logger.Info).With(ctx.Str("env", "prod")) - l := logger.New(h, "env", "prod") // The logger can have an initial context - - l.Info("redis connection", "redis", "some redis name", "timeout", 10) -} - -func ExampleBufferedStreamHandler() { - h := logger.BufferedStreamHandler(os.Stdout, 2000, 1*time.Second, logger.LogfmtFormat()) - - l := logger.New(h, "env", "prod") - - l.Info("redis connection", "redis", "some redis name", "timeout", 10) -} - -func ExampleStreamHandler() { - h := logger.StreamHandler(os.Stdout, logger.LogfmtFormat()) - - l := logger.New(h, "env", "prod") - - l.Info("redis connection", "redis", "some redis name", "timeout", 10) + log.Info("redis connection", ctx.Str("redis", "some redis name"), ctx.Int("timeout", 10)) } -func ExampleLevelFilterHandler() { - h := logger.LevelFilterHandler( - logger.Info, - logger.StreamHandler(os.Stdout, logger.LogfmtFormat()), - ) - - l := logger.New(h, "env", "prod") - - l.Info("redis connection", "redis", "some redis name", "timeout", 10) -} - -func ExampleFilterHandler() { - h := logger.FilterHandler( - func(e *logger.Event) bool { - return e.Msg == "some condition" - }, - logger.StreamHandler(os.Stdout, logger.LogfmtFormat()), - ) - - l := logger.New(h, "env", "prod") +func ExampleSyncWriter() { + log := logger.New(logger.NewSyncWriter(os.Stdout), logger.LogfmtFormat(), logger.Info).With(ctx.Str("env", "prod")) - l.Info("redis connection", "redis", "some redis name", "timeout", 10) + log.Info("redis connection", ctx.Str("redis", "some redis name"), ctx.Int("timeout", 10)) } diff --git a/format.go b/format.go index 0f3502f..982d0b8 100644 --- a/format.go +++ b/format.go @@ -19,197 +19,181 @@ const ( // Formatter represents a log message formatter. type Formatter interface { - // Format formats a log message. - Format(e *Event) []byte + WriteMessage(buf *bytes.Buffer, time int64, lvl Level, msg string) + AppendEndMarker(buf *bytes.Buffer) + AppendArrayStart(buf *bytes.Buffer) + AppendArraySep(buf *bytes.Buffer) + AppendArrayEnd(buf *bytes.Buffer) + AppendKey(buf *bytes.Buffer, key string) + AppendString(buf *bytes.Buffer, s string) + AppendBool(buf *bytes.Buffer, b bool) + AppendInt(buf *bytes.Buffer, i int64) + AppendUint(buf *bytes.Buffer, i uint64) + AppendFloat(buf *bytes.Buffer, f float64) + AppendTime(buf *bytes.Buffer, t time.Time) + AppendDuration(buf *bytes.Buffer, d time.Duration) + AppendInterface(buf *bytes.Buffer, v interface{}) } -// FormatterFunc is a function formatter. -type FormatterFunc func(e *Event) []byte +type json struct{} -// Format formats a log message. -func (f FormatterFunc) Format(e *Event) []byte { - return f(e) +// JSONFormat formats a log line in json format. +func JSONFormat() Formatter { + return &json{} } -type json struct { - pool bytes.Pool +func (j *json) WriteMessage(buf *bytes.Buffer, time int64, lvl Level, msg string) { + buf.WriteString(`{"`) + buf.WriteString(LevelKey) + buf.WriteString(`":"`) + buf.WriteString(lvl.String()) + buf.WriteString(`","`) + buf.WriteString(MessageKey) + buf.WriteString(`":`) + appendString(buf, msg, true) } -// JSONFormat formats a log line in json format. -func JSONFormat() Formatter { - return &json{ - pool: bytes.NewPool(512), - } +func (j *json) AppendEndMarker(buf *bytes.Buffer) { + buf.WriteString("}\n") } -func (j *json) Format(e *Event) []byte { - buf := j.pool.Get() +func (j *json) AppendArrayStart(buf *bytes.Buffer) { + buf.WriteByte('[') +} - _ = buf.WriteByte('{') - buf.WriteString(`"` + LevelKey + `":"` + e.Lvl.String() + `",`) - buf.WriteString(`"` + MessageKey + `":`) - escapeString(buf, e.Msg, true) +func (j *json) AppendArraySep(buf *bytes.Buffer) { + buf.WriteByte(',') +} - j.writeCtx(buf, e.BaseCtx) - j.writeCtx(buf, e.Ctx) +func (j *json) AppendArrayEnd(buf *bytes.Buffer) { + buf.WriteByte(']') +} - buf.WriteString("}\n") +func (j *json) AppendKey(buf *bytes.Buffer, key string) { + buf.WriteString(`,"`) + buf.WriteString(key) + buf.WriteString(`":`) +} - j.pool.Put(buf) - return buf.Bytes() +func (j *json) AppendString(buf *bytes.Buffer, s string) { + appendString(buf, s, true) } -func (j *json) writeCtx(buf *bytes.Buffer, ctx []interface{}) { - for i := 0; i < len(ctx); i += 2 { - _ = buf.WriteByte(',') +func (j *json) AppendBool(buf *bytes.Buffer, b bool) { + buf.AppendBool(b) +} - k, ok := ctx[i].(string) - if !ok { - buf.WriteString(`"` + errorKey + `"`) - _ = buf.WriteByte(':') - j.writeValue(buf, ctx[i]) - continue - } +func (j *json) AppendInt(buf *bytes.Buffer, i int64) { + buf.AppendInt(i) +} - buf.WriteString(`"` + k + `"`) - _ = buf.WriteByte(':') - j.writeValue(buf, ctx[i+1]) - } +func (j *json) AppendUint(buf *bytes.Buffer, i uint64) { + buf.AppendUint(i) +} + +func (j *json) AppendFloat(buf *bytes.Buffer, f float64) { + buf.AppendFloat(f, 'g', -1, 64) +} + +func (j *json) AppendTime(buf *bytes.Buffer, t time.Time) { + s := t.Format(timeFormat) + appendString(buf, s, true) } -func (j *json) writeValue(buf *bytes.Buffer, v interface{}) { +func (j *json) AppendDuration(buf *bytes.Buffer, d time.Duration) { + s := d.String() + appendString(buf, s, true) +} + +func (j *json) AppendInterface(buf *bytes.Buffer, v interface{}) { if v == nil { buf.WriteString("null") return } - switch val := v.(type) { - case time.Time: - _ = buf.WriteByte('"') - buf.AppendTime(val, timeFormat) - _ = buf.WriteByte('"') - case time.Duration: - escapeString(buf, val.String(), true) - case bool: - buf.AppendBool(val) - case float32: - buf.AppendFloat(float64(val), 'g', -1, 64) - case float64: - buf.AppendFloat(val, 'g', -1, 64) - case int: - buf.AppendInt(int64(val)) - case int8: - buf.AppendInt(int64(val)) - case int16: - buf.AppendInt(int64(val)) - case int32: - buf.AppendInt(int64(val)) - case int64: - buf.AppendInt(val) - case uint: - buf.AppendUint(uint64(val)) - case uint8: - buf.AppendUint(uint64(val)) - case uint16: - buf.AppendUint(uint64(val)) - case uint32: - buf.AppendUint(uint64(val)) - case uint64: - buf.AppendUint(val) - case string: - escapeString(buf, val, true) - default: - escapeString(buf, fmt.Sprintf("%+v", v), true) - } + j.AppendString(buf, fmt.Sprintf("%+v", v)) } -type logfmt struct { - pool bytes.Pool -} +type logfmt struct{} // LogfmtFormat formats a log line in logfmt format. func LogfmtFormat() Formatter { - return &logfmt{ - pool: bytes.NewPool(512), + return &logfmt{} +} + +func (l *logfmt) needsQuote(s string) bool { + for _, r := range s { + if r <= ' ' || r == '=' || r == '"' { + return true + } } + return false } -func (l *logfmt) Format(e *Event) []byte { - buf := l.pool.Get() +func (l *logfmt) WriteMessage(buf *bytes.Buffer, time int64, lvl Level, msg string) { + buf.WriteString(LevelKey) + buf.WriteByte('=') + buf.WriteString(lvl.String()) + buf.WriteByte(' ') + buf.WriteString(MessageKey) + buf.WriteByte('=') + appendString(buf, msg, l.needsQuote(msg)) +} - buf.WriteString(LevelKey + "=" + e.Lvl.String() + " ") - buf.WriteString(MessageKey + "=") - escapeString(buf, e.Msg, needsQuote(e.Msg)) +func (l *logfmt) AppendEndMarker(buf *bytes.Buffer) { + buf.WriteByte('\n') +} - l.writeCtx(buf, e.BaseCtx) - l.writeCtx(buf, e.Ctx) +func (l *logfmt) AppendArrayStart(_ *bytes.Buffer) {} - _ = buf.WriteByte('\n') +func (l *logfmt) AppendArraySep(buf *bytes.Buffer) { + buf.WriteByte(',') +} + +func (l *logfmt) AppendArrayEnd(_ *bytes.Buffer) {} - l.pool.Put(buf) - return buf.Bytes() +func (l *logfmt) AppendKey(buf *bytes.Buffer, key string) { + buf.WriteByte(' ') + buf.WriteString(key) + buf.WriteByte('=') } -func (l *logfmt) writeCtx(buf *bytes.Buffer, ctx []interface{}) { - for i := 0; i < len(ctx); i += 2 { - _ = buf.WriteByte(' ') +func (l *logfmt) AppendString(buf *bytes.Buffer, s string) { + appendString(buf, s, l.needsQuote(s)) +} - k, ok := ctx[i].(string) - if !ok { - buf.WriteString(errorKey) - _ = buf.WriteByte('=') - l.writeValue(buf, ctx[i]) - continue - } +func (l *logfmt) AppendBool(buf *bytes.Buffer, b bool) { + buf.AppendBool(b) +} - buf.WriteString(k) - _ = buf.WriteByte('=') - l.writeValue(buf, ctx[i+1]) - } +func (l *logfmt) AppendInt(buf *bytes.Buffer, i int64) { + buf.AppendInt(i) +} + +func (l *logfmt) AppendUint(buf *bytes.Buffer, i uint64) { + buf.AppendUint(i) +} + +func (l *logfmt) AppendFloat(buf *bytes.Buffer, f float64) { + buf.AppendFloat(f, 'f', 3, 64) +} + +func (l *logfmt) AppendTime(buf *bytes.Buffer, t time.Time) { + s := t.Format(timeFormat) + appendString(buf, s, l.needsQuote(s)) +} + +func (l *logfmt) AppendDuration(buf *bytes.Buffer, d time.Duration) { + s := d.String() + appendString(buf, s, l.needsQuote(s)) } -func (l *logfmt) writeValue(buf *bytes.Buffer, v interface{}) { +func (l *logfmt) AppendInterface(buf *bytes.Buffer, v interface{}) { if v == nil { return } - switch val := v.(type) { - case time.Time: - buf.AppendTime(val, timeFormat) - case time.Duration: - escapeString(buf, val.String(), false) - case bool: - buf.AppendBool(val) - case float32: - buf.AppendFloat(float64(val), 'f', 3, 64) - case float64: - buf.AppendFloat(val, 'f', 3, 64) - case int: - buf.AppendInt(int64(val)) - case int8: - buf.AppendInt(int64(val)) - case int16: - buf.AppendInt(int64(val)) - case int32: - buf.AppendInt(int64(val)) - case int64: - buf.AppendInt(val) - case uint: - buf.AppendUint(uint64(val)) - case uint8: - buf.AppendUint(uint64(val)) - case uint16: - buf.AppendUint(uint64(val)) - case uint32: - buf.AppendUint(uint64(val)) - case uint64: - buf.AppendUint(val) - case string: - escapeString(buf, val, needsQuote(val)) - default: - str := fmt.Sprintf("%+v", v) - escapeString(buf, str, needsQuote(str)) - } + l.AppendString(buf, fmt.Sprintf("%+v", v)) } const ( @@ -232,19 +216,19 @@ var noColor = newColor(colorReset) type color []int func newColor(attr ...int) color { - return color(attr) + return attr } func (c color) Write(buf *bytes.Buffer) { - _ = buf.WriteByte('\x1b') - _ = buf.WriteByte('[') + buf.WriteByte('\x1b') + buf.WriteByte('[') for i := 0; i < len(c); i++ { if i > 0 { - _ = buf.WriteByte(';') + buf.WriteByte(';') } buf.AppendInt(int64(c[i])) } - _ = buf.WriteByte('m') + buf.WriteByte('m') } func withColor(c color, buf *bytes.Buffer, fn func()) { @@ -253,33 +237,11 @@ func withColor(c color, buf *bytes.Buffer, fn func()) { noColor.Write(buf) } -type console struct { - pool bytes.Pool -} +type console struct{} // ConsoleFormat formats a log line in a console format. func ConsoleFormat() Formatter { - return &console{ - pool: bytes.NewPool(512), - } -} - -func (c *console) Format(e *Event) []byte { - buf := c.pool.Get() - - withColor(c.lvlColor(e.Lvl), buf, func() { - buf.WriteString(strings.ToUpper(e.Lvl.String())) - }) - _ = buf.WriteByte(' ') - escapeString(buf, e.Msg, false) - - c.writeCtx(buf, e.BaseCtx) - c.writeCtx(buf, e.Ctx) - - _ = buf.WriteByte('\n') - - c.pool.Put(buf) - return buf.Bytes() + return &console{} } func (c *console) lvlColor(lvl Level) color { @@ -298,105 +260,118 @@ func (c *console) lvlColor(lvl Level) color { return newColor(colorWhite) } -func (c *console) writeCtx(buf *bytes.Buffer, ctx []interface{}) { - for i := 0; i < len(ctx); i += 2 { - _ = buf.WriteByte(' ') +func (c *console) WriteMessage(buf *bytes.Buffer, time int64, lvl Level, msg string) { + withColor(c.lvlColor(lvl), buf, func() { + buf.WriteString(strings.ToUpper(lvl.String())) + }) + buf.WriteByte(' ') + appendString(buf, msg, false) +} - k, ok := ctx[i].(string) - if !ok { - withColor(newColor(colorRed), buf, func() { - buf.WriteString(errorKey) - _ = buf.WriteByte('=') - c.writeValue(buf, ctx[i], noColor) - }) - continue - } +func (c *console) AppendEndMarker(buf *bytes.Buffer) { + buf.WriteByte('\n') +} - var nameCol, valCol = newColor(colorCyan), noColor - if strings.HasPrefix(k, "err") { - nameCol, valCol = newColor(colorRed), newColor(colorRed) - } +func (c *console) AppendArrayStart(_ *bytes.Buffer) {} - withColor(nameCol, buf, func() { - buf.WriteString(k) - _ = buf.WriteByte('=') - }) - c.writeValue(buf, ctx[i+1], valCol) +func (c *console) AppendArraySep(buf *bytes.Buffer) { + buf.WriteByte(',') +} + +func (c *console) AppendArrayEnd(_ *bytes.Buffer) {} + +func (c *console) AppendKey(buf *bytes.Buffer, key string) { + buf.WriteByte(' ') + + var col = newColor(colorCyan) + if strings.HasPrefix(key, "err") { + col = newColor(colorRed) } + + withColor(col, buf, func() { + buf.WriteString(key) + buf.WriteByte('=') + }) } -func (c *console) writeValue(buf *bytes.Buffer, v interface{}, color color) { +func (c *console) AppendString(buf *bytes.Buffer, s string) { + appendString(buf, s, false) +} + +func (c *console) AppendBool(buf *bytes.Buffer, b bool) { + buf.AppendBool(b) +} + +func (c *console) AppendInt(buf *bytes.Buffer, i int64) { + buf.AppendInt(i) +} + +func (c *console) AppendUint(buf *bytes.Buffer, i uint64) { + buf.AppendUint(i) +} + +func (c *console) AppendFloat(buf *bytes.Buffer, f float64) { + buf.AppendFloat(f, 'f', 3, 64) +} + +func (c *console) AppendTime(buf *bytes.Buffer, t time.Time) { + s := t.Format(timeFormat) + appendString(buf, s, false) +} + +func (c *console) AppendDuration(buf *bytes.Buffer, d time.Duration) { + s := d.String() + appendString(buf, s, false) +} + +func (c *console) AppendInterface(buf *bytes.Buffer, v interface{}) { if v == nil { return } - needsColor := len(color) > 0 && color[0] != colorReset - if needsColor { - color.Write(buf) - } + c.AppendString(buf, fmt.Sprintf("%+v", v)) +} - switch val := v.(type) { - case time.Time: - buf.AppendTime(val, timeFormat) - case time.Duration: - escapeString(buf, val.String(), false) - case bool: - buf.AppendBool(val) - case float32: - buf.AppendFloat(float64(val), 'f', 3, 64) - case float64: - buf.AppendFloat(val, 'f', 3, 64) - case int: - buf.AppendInt(int64(val)) - case int8: - buf.AppendInt(int64(val)) - case int16: - buf.AppendInt(int64(val)) - case int32: - buf.AppendInt(int64(val)) - case int64: - buf.AppendInt(val) - case uint: - buf.AppendUint(uint64(val)) - case uint8: - buf.AppendUint(uint64(val)) - case uint16: - buf.AppendUint(uint64(val)) - case uint32: - buf.AppendUint(uint64(val)) - case uint64: - buf.AppendUint(val) - case string: - escapeString(buf, val, false) - default: - str := fmt.Sprintf("%+v", v) - escapeString(buf, str, false) - } +var noEscapeTable = [256]bool{} - if needsColor { - noColor.Write(buf) +func init() { + for i := 0; i <= 0x7e; i++ { + noEscapeTable[i] = i >= 0x20 && i != '\\' && i != '"' } } -func needsQuote(s string) bool { - for _, r := range s { - if r <= ' ' || r == '=' || r == '"' { - return true +func appendString(buf *bytes.Buffer, s string, quote bool) { + if quote { + buf.WriteByte('"') + } + + var needEscape bool + for i := 0; i < len(s); i++ { + if noEscapeTable[s[i]] { + continue } + needEscape = true + break + } + + if needEscape { + escapeString(buf, s) + } else { + buf.WriteString(s) } - return false -} -func escapeString(buf *bytes.Buffer, s string, quote bool) { if quote { - _ = buf.WriteByte('"') + buf.WriteByte('"') } +} +func escapeString(buf *bytes.Buffer, s string) { + // TODO: improve this if the need arises. for _, r := range s { switch r { case '\\', '"': - _ = buf.WriteByte('\\') - _ = buf.WriteByte(byte(r)) + buf.WriteByte('\\') + buf.WriteRune(r) case '\n': buf.WriteString("\\n") case '\r': @@ -404,11 +379,7 @@ func escapeString(buf *bytes.Buffer, s string, quote bool) { case '\t': buf.WriteString("\\t") default: - _ = buf.WriteByte(byte(r)) + buf.WriteRune(r) } } - - if quote { - _ = buf.WriteByte('"') - } } diff --git a/format_test.go b/format_test.go index d8993ac..cb2c1f9 100644 --- a/format_test.go +++ b/format_test.go @@ -1,403 +1,442 @@ package logger_test import ( - "encoding/json" "testing" "time" "github.com/hamba/logger" + "github.com/hamba/logger/internal/bytes" "github.com/stretchr/testify/assert" ) func TestJsonFormat(t *testing.T) { - f := logger.JSONFormat() - - e := &logger.Event{ - Msg: "some message", - Lvl: logger.Error, - BaseCtx: []interface{}{"x", 1, "y", 3.2}, - Ctx: []interface{}{ - "bool", true, - "carriage_return", "bang" + string('\r') + "foo", - "tab", "bar baz", - "newline", "foo\nbar", - "escape", string('\\'), - }, - } - b := f.Format(e) + fmtr := logger.JSONFormat() - expect := []byte(`{"lvl":"eror","msg":"some message","x":1,"y":3.2,"bool":true,"carriage_return":"bang\rfoo","tab":"bar\tbaz","newline":"foo\nbar","escape":"\\"}` + "\n") - assert.Equal(t, expect, b) + buf := bytes.NewBuffer(512) + fmtr.WriteMessage(buf, 0, logger.Error, "some message") + fmtr.AppendKey(buf, "error") + fmtr.AppendString(buf, "some error") + fmtr.AppendEndMarker(buf) - m := map[string]interface{}{} - err := json.Unmarshal(b, &m) - assert.NoError(t, err) + want := `{"lvl":"eror","msg":"some message","error":"some error"}` + "\n" + assert.Equal(t, want, string(buf.Bytes())) } -func TestJsonFormat_KeyError(t *testing.T) { - f := logger.JSONFormat() - - e := &logger.Event{ - Msg: "some message", - Lvl: logger.Error, - Ctx: []interface{}{1, "y"}, - } - b := f.Format(e) +func TestJsonFormat_Array(t *testing.T) { + fmtr := logger.JSONFormat() - expect := []byte(`{"lvl":"eror","msg":"some message","LOGGER_ERROR":1}` + "\n") - assert.Equal(t, expect, b) + buf := bytes.NewBuffer(512) + fmtr.AppendArrayStart(buf) + fmtr.AppendArraySep(buf) + fmtr.AppendArrayEnd(buf) - m := map[string]interface{}{} - err := json.Unmarshal(b, &m) - assert.NoError(t, err) + assert.Equal(t, "[,]", string(buf.Bytes())) } -func TestJsonFormat_Ints(t *testing.T) { - f := logger.JSONFormat() - - e := &logger.Event{ - Lvl: logger.Error, - Ctx: []interface{}{"int", 1, "int8", int8(2), "int16", int16(3), "int32", int32(4), "int64", int64(5)}, +func TestJsonFormat_Strings(t *testing.T) { + tests := []struct { + name string + in string + want string + }{ + { + name: "equals", + in: "=", + want: `"="`, + }, + { + name: "quote", + in: "\"", + want: `"\""`, + }, + { + name: "carriage_return", + in: "bang\rfoo", + want: `"bang\rfoo"`, + }, + { + name: "tab", + in: "bar baz", + want: `"bar\tbaz"`, + }, + { + name: "newline", + in: "foo\nbar", + want: `"foo\nbar"`, + }, + { + name: "escape", + in: string('\\'), + want: `"\\"`, + }, } - b := f.Format(e) - expect := []byte(`{"lvl":"eror","msg":"","int":1,"int8":2,"int16":3,"int32":4,"int64":5}` + "\n") - assert.Equal(t, expect, b) + for _, test := range tests { + test := test + t.Run(test.name, func(t *testing.T) { + fmtr := logger.JSONFormat() + + buf := bytes.NewBuffer(512) + fmtr.AppendString(buf, test.in) - m := map[string]interface{}{} - err := json.Unmarshal(b, &m) - assert.NoError(t, err) + assert.Equal(t, test.want, string(buf.Bytes())) + }) + } } -func TestJsonFormat_Uints(t *testing.T) { - f := logger.JSONFormat() +func TestJsonFormat_Bool(t *testing.T) { + fmtr := logger.JSONFormat() - e := &logger.Event{ - Lvl: logger.Error, - Ctx: []interface{}{"uint", uint(1), "uint8", uint8(2), "uint16", uint16(3), "uint32", uint32(4), "uint64", uint64(5)}, - } - b := f.Format(e) + buf := bytes.NewBuffer(512) + fmtr.AppendBool(buf, true) + fmtr.AppendBool(buf, false) + + assert.Equal(t, "truefalse", string(buf.Bytes())) +} + +func TestJsonFormat_Int(t *testing.T) { + fmtr := logger.JSONFormat() - expect := []byte(`{"lvl":"eror","msg":"","uint":1,"uint8":2,"uint16":3,"uint32":4,"uint64":5}` + "\n") - assert.Equal(t, expect, b) + buf := bytes.NewBuffer(512) + fmtr.AppendInt(buf, 5) - m := map[string]interface{}{} - err := json.Unmarshal(b, &m) - assert.NoError(t, err) + assert.Equal(t, "5", string(buf.Bytes())) } -func TestJsonFormat_Floats(t *testing.T) { - f := logger.JSONFormat() +func TestJsonFormat_Uint(t *testing.T) { + fmtr := logger.JSONFormat() - e := &logger.Event{ - Lvl: logger.Error, - Ctx: []interface{}{"float32", float32(1), "float64", float64(4.56)}, - } - b := f.Format(e) + buf := bytes.NewBuffer(512) + fmtr.AppendUint(buf, 5) + + assert.Equal(t, "5", string(buf.Bytes())) +} - expect := []byte(`{"lvl":"eror","msg":"","float32":1,"float64":4.56}` + "\n") - assert.Equal(t, expect, b) +func TestJsonFormat_Float(t *testing.T) { + fmtr := logger.JSONFormat() - m := map[string]interface{}{} - err := json.Unmarshal(b, &m) - assert.NoError(t, err) + buf := bytes.NewBuffer(512) + fmtr.AppendFloat(buf, 4.56) + + assert.Equal(t, "4.56", string(buf.Bytes())) } func TestJsonFormat_Time(t *testing.T) { - f := logger.JSONFormat() + fmtr := logger.JSONFormat() - e := &logger.Event{ - Lvl: logger.Error, - Ctx: []interface{}{"time", time.Unix(1541573670, 0).UTC()}, - } - b := f.Format(e) + buf := bytes.NewBuffer(512) + fmtr.AppendTime(buf, time.Unix(1541573670, 0).UTC()) + + assert.Equal(t, `"2018-11-07T06:54:30+0000"`, string(buf.Bytes())) +} + +func TestJsonFormat_Duration(t *testing.T) { + fmtr := logger.JSONFormat() - expect := []byte(`{"lvl":"eror","msg":"","time":"2018-11-07T06:54:30+0000"}` + "\n") - assert.Equal(t, expect, b) + buf := bytes.NewBuffer(512) + fmtr.AppendDuration(buf, time.Second) - m := map[string]interface{}{} - err := json.Unmarshal(b, &m) - assert.NoError(t, err) + assert.Equal(t, `"1s"`, string(buf.Bytes())) } -func TestJsonFormat_Unknown(t *testing.T) { +func TestJsonFormat_Interface(t *testing.T) { obj := struct { Name string }{Name: "test"} - f := logger.JSONFormat() + fmtr := logger.JSONFormat() - e := &logger.Event{ - Lvl: logger.Error, - Ctx: []interface{}{"what", obj, "nil", nil}, - } - b := f.Format(e) + buf := bytes.NewBuffer(512) + fmtr.AppendInterface(buf, obj) + fmtr.AppendInterface(buf, nil) - expect := []byte(`{"lvl":"eror","msg":"","what":"{Name:test}","nil":null}` + "\n") - assert.Equal(t, expect, b) + assert.Equal(t, `"{Name:test}"null`, string(buf.Bytes())) } func TestLogfmtFormat(t *testing.T) { - f := logger.LogfmtFormat() - - e := &logger.Event{ - Msg: "some message", - Lvl: logger.Error, - BaseCtx: []interface{}{"x", 1, "y", 3.2}, - Ctx: []interface{}{ - "bool", true, - "equals", "=", - "quote", "\"", - "carriage_return", "bang" + string('\r') + "foo", - "tab", "bar baz", - "newline", "foo\nbar", - "escape", string('\\'), + fmtr := logger.LogfmtFormat() + + buf := bytes.NewBuffer(512) + fmtr.WriteMessage(buf, 0, logger.Error, "some message") + fmtr.AppendKey(buf, "error") + fmtr.AppendString(buf, "some error") + fmtr.AppendEndMarker(buf) + + want := `lvl=eror msg="some message" error="some error"` + "\n" + assert.Equal(t, want, string(buf.Bytes())) +} + +func TestLogfmtFormat_Array(t *testing.T) { + fmtr := logger.LogfmtFormat() + + buf := bytes.NewBuffer(512) + fmtr.AppendArrayStart(buf) + fmtr.AppendArraySep(buf) + fmtr.AppendArrayEnd(buf) + + assert.Equal(t, ",", string(buf.Bytes())) +} + +func TestLogfmtFormat_Strings(t *testing.T) { + tests := []struct { + name string + in string + want string + }{ + { + name: "equals", + in: "=", + want: `"="`, + }, + { + name: "quote", + in: "\"", + want: `"\""`, + }, + { + name: "carriage_return", + in: "bang\rfoo", + want: `"bang\rfoo"`, + }, + { + name: "tab", + in: "bar baz", + want: `"bar\tbaz"`, + }, + { + name: "newline", + in: "foo\nbar", + want: `"foo\nbar"`, + }, + { + name: "escape", + in: string('\\'), + want: `\\`, }, } - b := f.Format(e) - expect := []byte(`lvl=eror msg="some message" x=1 y=3.200 bool=true equals="=" quote="\"" carriage_return="bang\rfoo" tab="bar\tbaz" newline="foo\nbar" escape=\\` + "\n") - assert.Equal(t, expect, b) -} + for _, test := range tests { + test := test + t.Run(test.name, func(t *testing.T) { + fmtr := logger.LogfmtFormat() -func TestLogfmtFormat_KeyError(t *testing.T) { - f := logger.LogfmtFormat() + buf := bytes.NewBuffer(512) + fmtr.AppendString(buf, test.in) - e := &logger.Event{ - Msg: "some message", - Lvl: logger.Error, - Ctx: []interface{}{1, "y"}, + assert.Equal(t, test.want, string(buf.Bytes())) + }) } - b := f.Format(e) +} + +func TestLogfmtFormat_Bool(t *testing.T) { + fmtr := logger.LogfmtFormat() + + buf := bytes.NewBuffer(512) + fmtr.AppendBool(buf, true) + fmtr.AppendBool(buf, false) - expect := []byte(`lvl=eror msg="some message" LOGGER_ERROR=1` + "\n") - assert.Equal(t, expect, b) + assert.Equal(t, "truefalse", string(buf.Bytes())) } -func TestLogfmtFormat_Ints(t *testing.T) { - f := logger.LogfmtFormat() +func TestLogfmtFormat_Int(t *testing.T) { + fmtr := logger.LogfmtFormat() - e := &logger.Event{ - Lvl: logger.Error, - Ctx: []interface{}{"int", 1, "int8", int8(2), "int16", int16(3), "int32", int32(4), "int64", int64(5)}, - } - b := f.Format(e) + buf := bytes.NewBuffer(512) + fmtr.AppendInt(buf, 5) - expect := []byte(`lvl=eror msg= int=1 int8=2 int16=3 int32=4 int64=5` + "\n") - assert.Equal(t, expect, b) + assert.Equal(t, "5", string(buf.Bytes())) } -func TestLogfmtFormat_Uints(t *testing.T) { - f := logger.LogfmtFormat() +func TestLogfmtFormat_Uint(t *testing.T) { + fmtr := logger.LogfmtFormat() - e := &logger.Event{ - Lvl: logger.Error, - Ctx: []interface{}{"uint", uint(1), "uint8", uint8(2), "uint16", uint16(3), "uint32", uint32(4), "uint64", uint64(5)}, - } - b := f.Format(e) + buf := bytes.NewBuffer(512) + fmtr.AppendUint(buf, 5) - expect := []byte(`lvl=eror msg= uint=1 uint8=2 uint16=3 uint32=4 uint64=5` + "\n") - assert.Equal(t, expect, b) + assert.Equal(t, "5", string(buf.Bytes())) } -func TestLogfmtFormat_Floats(t *testing.T) { - f := logger.LogfmtFormat() +func TestLogfmtFormat_Float(t *testing.T) { + fmtr := logger.LogfmtFormat() - e := &logger.Event{ - Lvl: logger.Error, - Ctx: []interface{}{"float32", float32(1.23), "float64", float64(4.56)}, - } - b := f.Format(e) + buf := bytes.NewBuffer(512) + fmtr.AppendFloat(buf, 4.56) - expect := []byte(`lvl=eror msg= float32=1.230 float64=4.560` + "\n") - assert.Equal(t, expect, b) + assert.Equal(t, "4.560", string(buf.Bytes())) } func TestLogfmtFormat_Time(t *testing.T) { - f := logger.LogfmtFormat() + fmtr := logger.LogfmtFormat() - e := &logger.Event{ - Lvl: logger.Error, - Ctx: []interface{}{"time", time.Unix(1541573670, 0).UTC()}, - } - b := f.Format(e) + buf := bytes.NewBuffer(512) + fmtr.AppendTime(buf, time.Unix(1541573670, 0).UTC()) + + assert.Equal(t, `2018-11-07T06:54:30+0000`, string(buf.Bytes())) +} - expect := []byte(`lvl=eror msg= time=2018-11-07T06:54:30+0000` + "\n") - assert.Equal(t, expect, b) +func TestLogfmtFormat_Duration(t *testing.T) { + fmtr := logger.LogfmtFormat() + + buf := bytes.NewBuffer(512) + fmtr.AppendDuration(buf, time.Second) + + assert.Equal(t, `1s`, string(buf.Bytes())) } -func TestLogfmtFormat_Unknown(t *testing.T) { +func TestLogfmtFormat_Interface(t *testing.T) { obj := struct { Name string }{Name: "test"} - f := logger.LogfmtFormat() + fmtr := logger.LogfmtFormat() - e := &logger.Event{ - Lvl: logger.Error, - Ctx: []interface{}{"what", obj, "nil", nil}, - } - b := f.Format(e) + buf := bytes.NewBuffer(512) + fmtr.AppendInterface(buf, obj) + fmtr.AppendInterface(buf, nil) - expect := []byte(`lvl=eror msg= what={Name:test} nil=` + "\n") - assert.Equal(t, expect, b) + assert.Equal(t, `{Name:test}`, string(buf.Bytes())) } func TestConsoleFormat(t *testing.T) { - f := logger.ConsoleFormat() - - e := &logger.Event{ - Msg: "some message", - Lvl: logger.Error, - BaseCtx: []interface{}{"x", 1, "y", 3.2}, - Ctx: []interface{}{ - "bool", true, - "equals", "=", - "quote", "\"", - "carriage_return", "bang" + string('\r') + "foo", - "tab", "bar baz", - "newline", "foo\nbar", - "escape", string('\\'), - "error", "test", - }, - } - b := f.Format(e) + fmtr := logger.ConsoleFormat() + + buf := bytes.NewBuffer(512) + fmtr.WriteMessage(buf, 0, logger.Error, "some message") + fmtr.AppendKey(buf, "error") + fmtr.AppendString(buf, "some error") + fmtr.AppendEndMarker(buf) - expect := []byte("\x1b[31mEROR\x1b[0m some message \x1b[36mx=\x1b[0m1 \x1b[36my=\x1b[0m3.200 \x1b[36mbool=\x1b[0mtrue \x1b[36mequals=\x1b[0m= \x1b[36mquote=\x1b[0m\\\" \x1b[36mcarriage_return=\x1b[0mbang\\rfoo \x1b[36mtab=\x1b[0mbar\\tbaz \x1b[36mnewline=\x1b[0mfoo\\nbar \x1b[36mescape=\x1b[0m\\\\ \x1b[31merror=\x1b[0m\x1b[31mtest\x1b[0m\n") - assert.Equal(t, expect, b) + want := "\x1b[31mEROR\x1b[0m some message \x1b[31merror=\x1b[0msome error\n" + assert.Equal(t, want, string(buf.Bytes())) } -func TestConsoleFormat_Levels(t *testing.T) { +func TestConsoleFormat_Array(t *testing.T) { + fmtr := logger.ConsoleFormat() + + buf := bytes.NewBuffer(512) + fmtr.AppendArrayStart(buf) + fmtr.AppendArraySep(buf) + fmtr.AppendArrayEnd(buf) + + assert.Equal(t, ",", string(buf.Bytes())) +} + +func TestConsoleFormat_Strings(t *testing.T) { tests := []struct { name string - lvl logger.Level + in string want string }{ { - name: "debug", - lvl: logger.Debug, - want: "\x1b[34mDBUG\x1b[0m \n", + name: "equals", + in: "=", + want: `=`, }, { - name: "info", - lvl: logger.Info, - want: "\x1b[32mINFO\x1b[0m \n", + name: "quote", + in: "\"", + want: `\"`, }, { - name: "warning", - lvl: logger.Warn, - want: "\x1b[33mWARN\x1b[0m \n", + name: "carriage_return", + in: "bang\rfoo", + want: `bang\rfoo`, }, { - name: "error", - lvl: logger.Error, - want: "\x1b[31mEROR\x1b[0m \n", + name: "tab", + in: "bar baz", + want: `bar\tbaz`, }, { - name: "crit", - lvl: logger.Crit, - want: "\x1b[31;1mCRIT\x1b[0m \n", + name: "newline", + in: "foo\nbar", + want: `foo\nbar`, }, { - name: "unknown", - lvl: logger.Level(1234), - want: "\x1b[37mUNKN\x1b[0m \n", + name: "escape", + in: string('\\'), + want: `\\`, }, } for _, test := range tests { + test := test t.Run(test.name, func(t *testing.T) { - f := logger.ConsoleFormat() - e := &logger.Event{ - Lvl: test.lvl, - } + fmtr := logger.ConsoleFormat() - b := f.Format(e) + buf := bytes.NewBuffer(512) + fmtr.AppendString(buf, test.in) - assert.Equal(t, test.want, string(b)) + assert.Equal(t, test.want, string(buf.Bytes())) }) } } -func TestConsoleFormat_KeyError(t *testing.T) { - f := logger.ConsoleFormat() +func TestConsoleFormat_Bool(t *testing.T) { + fmtr := logger.ConsoleFormat() - e := &logger.Event{ - Msg: "some message", - Lvl: logger.Error, - Ctx: []interface{}{1, "y"}, - } - b := f.Format(e) + buf := bytes.NewBuffer(512) + fmtr.AppendBool(buf, true) + fmtr.AppendBool(buf, false) - expect := []byte("\x1b[31mEROR\x1b[0m some message \x1b[31mLOGGER_ERROR=1\x1b[0m\n") - assert.Equal(t, expect, b) + assert.Equal(t, "truefalse", string(buf.Bytes())) } -func TestConsoleFormat_Ints(t *testing.T) { - f := logger.ConsoleFormat() +func TestConsoleFormat_Int(t *testing.T) { + fmtr := logger.ConsoleFormat() - e := &logger.Event{ - Lvl: logger.Error, - Ctx: []interface{}{"int", 1, "int8", int8(2), "int16", int16(3), "int32", int32(4), "int64", int64(5)}, - } - b := f.Format(e) + buf := bytes.NewBuffer(512) + fmtr.AppendInt(buf, 5) - expect := []byte("\x1b[31mEROR\x1b[0m \x1b[36mint=\x1b[0m1 \x1b[36mint8=\x1b[0m2 \x1b[36mint16=\x1b[0m3 \x1b[36mint32=\x1b[0m4 \x1b[36mint64=\x1b[0m5\n") - assert.Equal(t, expect, b) + assert.Equal(t, "5", string(buf.Bytes())) } -func TestConsoleFormat_Uints(t *testing.T) { - f := logger.ConsoleFormat() +func TestConsoleFormat_Uint(t *testing.T) { + fmtr := logger.ConsoleFormat() - e := &logger.Event{ - Lvl: logger.Error, - Ctx: []interface{}{"uint", uint(1), "uint8", uint8(2), "uint16", uint16(3), "uint32", uint32(4), "uint64", uint64(5)}, - } - b := f.Format(e) + buf := bytes.NewBuffer(512) + fmtr.AppendUint(buf, 5) - expect := []byte("\x1b[31mEROR\x1b[0m \x1b[36muint=\x1b[0m1 \x1b[36muint8=\x1b[0m2 \x1b[36muint16=\x1b[0m3 \x1b[36muint32=\x1b[0m4 \x1b[36muint64=\x1b[0m5\n") - assert.Equal(t, expect, b) + assert.Equal(t, "5", string(buf.Bytes())) } -func TestConsoleFormat_Floats(t *testing.T) { - f := logger.ConsoleFormat() +func TestConsoleFormat_Float(t *testing.T) { + fmtr := logger.ConsoleFormat() - e := &logger.Event{ - Lvl: logger.Error, - Ctx: []interface{}{"float32", float32(1.23), "float64", float64(4.56)}, - } - b := f.Format(e) + buf := bytes.NewBuffer(512) + fmtr.AppendFloat(buf, 4.56) - expect := []byte("\x1b[31mEROR\x1b[0m \x1b[36mfloat32=\x1b[0m1.230 \x1b[36mfloat64=\x1b[0m4.560\n") - assert.Equal(t, expect, b) + assert.Equal(t, "4.560", string(buf.Bytes())) } func TestConsoleFormat_Time(t *testing.T) { - f := logger.ConsoleFormat() + fmtr := logger.ConsoleFormat() - e := &logger.Event{ - Lvl: logger.Error, - Ctx: []interface{}{"time", time.Unix(1541573670, 0).UTC()}, - } - b := f.Format(e) + buf := bytes.NewBuffer(512) + fmtr.AppendTime(buf, time.Unix(1541573670, 0).UTC()) - expect := []byte("\x1b[31mEROR\x1b[0m \x1b[36mtime=\x1b[0m2018-11-07T06:54:30+0000\n") - assert.Equal(t, expect, b) + assert.Equal(t, `2018-11-07T06:54:30+0000`, string(buf.Bytes())) } -func TestConsoleFormat_Unknown(t *testing.T) { +func TestConsoleFormat_Duration(t *testing.T) { + fmtr := logger.ConsoleFormat() + + buf := bytes.NewBuffer(512) + fmtr.AppendDuration(buf, time.Second) + + assert.Equal(t, `1s`, string(buf.Bytes())) +} + +func TestConsoleFormat_Interface(t *testing.T) { obj := struct { Name string }{Name: "test"} - f := logger.ConsoleFormat() + fmtr := logger.ConsoleFormat() - e := &logger.Event{ - Lvl: logger.Error, - Ctx: []interface{}{"what", obj, "nil", nil}, - } - b := f.Format(e) + buf := bytes.NewBuffer(512) + fmtr.AppendInterface(buf, obj) + fmtr.AppendInterface(buf, nil) - expect := []byte("\x1b[31mEROR\x1b[0m \x1b[36mwhat=\x1b[0m{Name:test} \x1b[36mnil=\x1b[0m\n") - assert.Equal(t, expect, b) + assert.Equal(t, `{Name:test}`, string(buf.Bytes())) } diff --git a/go.mod b/go.mod index f971ff2..e8d28e0 100644 --- a/go.mod +++ b/go.mod @@ -1,8 +1,5 @@ module github.com/hamba/logger -go 1.11 +go 1.16 -require ( - github.com/davecgh/go-spew v1.1.1 // indirect - github.com/stretchr/testify v1.7.0 -) +require github.com/stretchr/testify v1.7.0 diff --git a/go.sum b/go.sum index ae276f4..acb88a4 100644 --- a/go.sum +++ b/go.sum @@ -1,6 +1,5 @@ +github.com/davecgh/go-spew v1.1.0 h1:ZDRjVQ15GmhC3fiQ8ni8+OwkZQO4DARzQgrnXU1Liz8= github.com/davecgh/go-spew v1.1.0/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38= -github.com/davecgh/go-spew v1.1.1 h1:vj9j/u1bqnvCEfJOwUhtlOARqs3+rkHYY13jYWTU97c= -github.com/davecgh/go-spew v1.1.1/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38= github.com/pmezard/go-difflib v1.0.0 h1:4DBwDE0NGyQoBHbLQYPwSUPoCMWR5BEzIk/f1lZbAQM= github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4= github.com/stretchr/objx v0.1.0/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME= diff --git a/handler.go b/handler.go deleted file mode 100644 index 1446ca9..0000000 --- a/handler.go +++ /dev/null @@ -1,190 +0,0 @@ -package logger - -import ( - "io" - "sync" - "time" - - "github.com/hamba/logger/internal/bytes" -) - -// Handler represents a log handler. -type Handler interface { - // Log write the log message. - Log(e *Event) -} - -// HandlerFunc is a function handler. -type HandlerFunc func(e *Event) - -// Log write the log message. -func (h HandlerFunc) Log(e *Event) { - h(e) -} - -type bufStreamHandler struct { - flushBytes int - flushInterval time.Duration - w io.Writer - fmtr Formatter - - mx sync.Mutex - pool bytes.Pool - buf *bytes.Buffer - ch chan *bytes.Buffer - - shutdown chan bool -} - -// BufferedStreamHandler writes buffered log messages to an io.Writer with the given format. -func BufferedStreamHandler(w io.Writer, flushBytes int, flushInterval time.Duration, fmtr Formatter) Handler { - pool := bytes.NewPool(flushBytes) - - h := &bufStreamHandler{ - flushBytes: flushBytes, - flushInterval: flushInterval, - fmtr: fmtr, - w: w, - pool: pool, - buf: pool.Get(), - ch: make(chan *bytes.Buffer, 32), - shutdown: make(chan bool, 1), - } - - go h.run() - - return h -} - -func (h *bufStreamHandler) run() { - doneChan := make(chan bool) - - go func() { - for buf := range h.ch { - _, _ = h.w.Write(buf.Bytes()) - h.pool.Put(buf) - } - doneChan <- true - }() - - ticker := time.NewTicker(h.flushInterval) - defer ticker.Stop() - - for { - select { - case <-ticker.C: - h.withBufferLock(func() { - h.swap() - }) - - case <-doneChan: - h.shutdown <- true - return - } - } -} - -// Log write the log message. -func (h *bufStreamHandler) Log(e *Event) { - h.withBufferLock(func() { - // Dont write to a closed buffer - if h.buf == nil { - return - } - - _, _ = h.buf.Write(h.fmtr.Format(e)) - - if h.buf.Len() >= h.flushBytes { - h.swap() - } - }) -} - -// Close closes the handler, waiting for all buffers to be flushed. -func (h *bufStreamHandler) Close() error { - h.withBufferLock(func() { - h.swap() - h.buf = nil - }) - - close(h.ch) - <-h.shutdown - - return nil -} - -func (h *bufStreamHandler) withBufferLock(fn func()) { - h.mx.Lock() - fn() - h.mx.Unlock() -} - -func (h *bufStreamHandler) swap() { - if h.buf == nil || h.buf.Len() == 0 { - return - } - - old := h.buf - h.buf = h.pool.Get() - h.ch <- old -} - -// StreamHandler writes log messages to an io.Writer with the given format. -func StreamHandler(w io.Writer, fmtr Formatter) Handler { - var mu sync.Mutex - - h := func(e *Event) { - mu.Lock() - _, _ = w.Write(fmtr.Format(e)) - mu.Unlock() - } - - return HandlerFunc(h) -} - -// FilterFunc represents a function that can filter messages. -type FilterFunc func(e *Event) bool - -// FilterHandler returns a handler that only writes messages to the wrapped -// handler if the given function evaluates true. -func FilterHandler(fn FilterFunc, h Handler) Handler { - c := &closeHandler{ - Handler: HandlerFunc(func(e *Event) { - if fn(e) { - h.Log(e) - } - }), - } - - if ch, ok := h.(io.Closer); ok { - c.Closer = ch - } - - return c -} - -// LevelFilterHandler returns a handler that filters by log level. -func LevelFilterHandler(maxLvl Level, h Handler) Handler { - return FilterHandler(func(e *Event) bool { - return e.Lvl <= maxLvl - }, h) -} - -// DiscardHandler does nothing, discarding all log messages. -func DiscardHandler() Handler { - return HandlerFunc(func(e *Event) {}) -} - -// closeHandler wraps a handler allowing it to close if it has a Close method. -type closeHandler struct { - io.Closer - Handler -} - -func (h *closeHandler) Close() error { - if h.Closer != nil { - return h.Closer.Close() - } - - return nil -} diff --git a/handler_test.go b/handler_test.go deleted file mode 100644 index 2617b76..0000000 --- a/handler_test.go +++ /dev/null @@ -1,103 +0,0 @@ -package logger_test - -import ( - "bytes" - "io" - "testing" - "time" - - "github.com/hamba/logger" - "github.com/stretchr/testify/assert" -) - -func TestBufferedStreamHandler(t *testing.T) { - buf := &bytes.Buffer{} - h := logger.BufferedStreamHandler(buf, 2000, time.Second, logger.LogfmtFormat()) - - h.Log(&logger.Event{Msg: "some message", Lvl: logger.Error}) - h.(io.Closer).Close() - - assert.Equal(t, "lvl=eror msg=\"some message\"\n", buf.String()) -} - -func TestBufferedStreamHandler_SendsMessagesAfterFlushInterval(t *testing.T) { - buf := &bytes.Buffer{} - h := logger.BufferedStreamHandler(buf, 2000, time.Millisecond, logger.LogfmtFormat()) - defer h.(io.Closer).Close() - - h.Log(&logger.Event{Msg: "some message", Lvl: logger.Error}) - - time.Sleep(5 * time.Millisecond) - - assert.Equal(t, "lvl=eror msg=\"some message\"\n", buf.String()) -} - -func TestBufferedStreamHandler_SendsMessagesAfterFlushBytes(t *testing.T) { - buf := &bytes.Buffer{} - h := logger.BufferedStreamHandler(buf, 40, time.Second, logger.LogfmtFormat()) - defer h.(io.Closer).Close() - - h.Log(&logger.Event{Msg: "some message", Lvl: logger.Error}) - h.Log(&logger.Event{Msg: "some message", Lvl: logger.Error}) - h.Log(&logger.Event{Msg: "some message", Lvl: logger.Error}) - - time.Sleep(time.Millisecond) - - assert.Equal(t, "lvl=eror msg=\"some message\"\nlvl=eror msg=\"some message\"\n", buf.String()) -} - -func TestBufferedStreamHandler_DoesntWriteAfterClose(t *testing.T) { - buf := &bytes.Buffer{} - h := logger.BufferedStreamHandler(buf, 40, time.Second, logger.LogfmtFormat()) - h.(io.Closer).Close() - - h.Log(&logger.Event{Msg: "some message", Lvl: logger.Error}) - - assert.Equal(t, "", buf.String()) -} - -func TestStreamHandler(t *testing.T) { - buf := &bytes.Buffer{} - h := logger.StreamHandler(buf, logger.LogfmtFormat()) - - h.Log(&logger.Event{Msg: "some message", Lvl: logger.Error}) - - assert.Equal(t, "lvl=eror msg=\"some message\"\n", buf.String()) -} - -func TestLevelFilterHandler(t *testing.T) { - count := 0 - testHandler := logger.HandlerFunc(func(e *logger.Event) { - count++ - }) - h := logger.LevelFilterHandler(logger.Info, testHandler) - - h.Log(&logger.Event{Msg: "test", Lvl: logger.Debug}) - h.Log(&logger.Event{Msg: "test", Lvl: logger.Info}) - - assert.Equal(t, 1, count) -} - -func TestLevelFilterHandler_TriesToCallUnderlyingClose(t *testing.T) { - testHandler := logger.HandlerFunc(func(e *logger.Event) {}) - h := logger.LevelFilterHandler(logger.Info, testHandler) - ch := h.(io.Closer) - - ch.Close() -} - -func TestLevelFilterHandler_CallsUnderlyingClose(t *testing.T) { - testHandler := &CloseableHandler{} - h := logger.LevelFilterHandler(logger.Info, testHandler) - ch := h.(io.Closer) - - ch.Close() - - assert.True(t, testHandler.CloseCalled) -} - -func TestDiscardHandler(t *testing.T) { - h := logger.DiscardHandler() - - h.Log(&logger.Event{Msg: "test", Lvl: logger.Crit}) -} diff --git a/internal/bytes/buffer.go b/internal/bytes/buffer.go index 58d2a93..d9aec22 100644 --- a/internal/bytes/buffer.go +++ b/internal/bytes/buffer.go @@ -2,41 +2,19 @@ package bytes import ( "strconv" - "sync" - "time" + "unicode/utf8" ) -// Pool is a Pool of Buffers. -type Pool struct { - p *sync.Pool -} - -// NewPool creates a new instance of Pool. -func NewPool(size int) Pool { - return Pool{p: &sync.Pool{ - New: func() interface{} { - return &Buffer{b: make([]byte, 0, size)} - }, - }} -} - -// Get retrieves a Buffer from the Pool, creating one if necessary. -func (p Pool) Get() *Buffer { - buf := p.p.Get().(*Buffer) - buf.Reset() - return buf -} - -// Put adds a Buffer to the Pool. -func (p Pool) Put(buf *Buffer) { - p.p.Put(buf) -} - // Buffer wraps a byte slice, providing continence functions. type Buffer struct { b []byte } +// NewBuffer returns a buffer. +func NewBuffer(size int) *Buffer { + return &Buffer{b: make([]byte, 0, size)} +} + // AppendInt appends an integer to the underlying Buffer. func (b *Buffer) AppendInt(i int64) { b.b = strconv.AppendInt(b.b, i, 10) @@ -57,15 +35,9 @@ func (b *Buffer) AppendBool(v bool) { b.b = strconv.AppendBool(b.b, v) } -// AppendTime appends a time to the underlying Buffer, in the given layout. -func (b *Buffer) AppendTime(t time.Time, layout string) { - b.b = t.AppendFormat(b.b, layout) -} - // WriteByte writes a single byte to the Buffer. -func (b *Buffer) WriteByte(v byte) error { +func (b *Buffer) WriteByte(v byte) { b.b = append(b.b, v) - return nil } // WriteString writes a string to the Buffer. @@ -73,21 +45,16 @@ func (b *Buffer) WriteString(s string) { b.b = append(b.b, s...) } -// Write implements io.Writer. -func (b *Buffer) Write(bs []byte) (int, error) { - b.b = append(b.b, bs...) - - return len(bs), nil -} - -// Len returns the length of the underlying byte slice. -func (b *Buffer) Len() int { - return len(b.b) +// WriteRune writes a rune to the Buffer. +func (b *Buffer) WriteRune(r rune) { + var buf [utf8.UTFMax]byte + n := utf8.EncodeRune(buf[:], r) + b.b = append(b.b, buf[:n]...) } -// Cap returns the capacity of the underlying byte slice. -func (b *Buffer) Cap() int { - return cap(b.b) +// Write implements io.Writer. +func (b *Buffer) Write(bs []byte) { + b.b = append(b.b, bs...) } // Bytes returns a mutable reference to the underlying byte slice. @@ -95,6 +62,11 @@ func (b *Buffer) Bytes() []byte { return b.b } +// Len returns the length of the buffer. +func (b *Buffer) Len() int { + return len(b.b) +} + // Reset resets the underlying byte slice. Subsequent writes re-use the slice's // backing array. func (b *Buffer) Reset() { diff --git a/internal/bytes/buffer_internal_test.go b/internal/bytes/buffer_internal_test.go index 6e76e9e..9076fe6 100644 --- a/internal/bytes/buffer_internal_test.go +++ b/internal/bytes/buffer_internal_test.go @@ -1,43 +1,13 @@ package bytes import ( - "sync" "testing" - "time" "github.com/stretchr/testify/assert" ) -func TestPool(t *testing.T) { - const dummyData = "dummy data" - - p := NewPool(512) - - var wg sync.WaitGroup - for i := 0; i < 10; i++ { - wg.Add(1) - go func() { - defer wg.Done() - - for i := 0; i < 100; i++ { - buf := p.Get() - assert.Zero(t, buf.Len(), "Expected truncated Buffer") - assert.NotZero(t, buf.Cap(), "Expected non-zero capacity") - - buf.WriteString(dummyData) - - assert.Equal(t, buf.Len(), len(dummyData), "Expected Buffer to contain dummy data") - - p.Put(buf) - } - }() - } - - wg.Wait() -} - func TestBuffer(t *testing.T) { - buf := NewPool(512).Get() + buf := NewBuffer(512) tests := []struct { name string @@ -46,7 +16,7 @@ func TestBuffer(t *testing.T) { }{ { name: "WriteByte", - fn: func() { _ = buf.WriteByte('v') }, + fn: func() { buf.WriteByte('v') }, want: "v", }, { @@ -54,49 +24,51 @@ func TestBuffer(t *testing.T) { fn: func() { buf.WriteString("foo") }, want: "foo", }, + { + name: "WriteRune", + fn: func() { buf.WriteRune('f') }, + want: "f", + }, { name: "Write", - fn: func() { _, _ = buf.Write([]byte("foo")) }, + fn: func() { buf.Write([]byte("foo")) }, want: "foo", }, { name: "AppendIntPositive", - fn: func() { buf.AppendInt(42) }, want: "42", + fn: func() { buf.AppendInt(42) }, + want: "42", }, { name: "AppendIntNegative", - fn: func() { buf.AppendInt(-42) }, want: "-42", + fn: func() { buf.AppendInt(-42) }, + want: "-42", }, { name: "AppendUint", - fn: func() { buf.AppendUint(42) }, want: "42", + fn: func() { buf.AppendUint(42) }, + want: "42", }, { name: "AppendBool", - fn: func() { buf.AppendBool(true) }, want: "true", + fn: func() { buf.AppendBool(true) }, + want: "true", }, { name: "AppendFloat64", fn: func() { buf.AppendFloat(3.14, 'f', 3, 64) }, want: "3.140", }, - { - name: "AppendTime", - fn: func() { buf.AppendTime(time.Unix(1541573670, 0).UTC(), time.RFC3339) }, - want: "2018-11-07T06:54:30Z", - }, } - assert.Equal(t, 512, buf.Cap()) - for _, tt := range tests { t.Run(tt.name, func(t *testing.T) { buf.Reset() tt.fn() - assert.Equal(t, tt.want, string(buf.Bytes())) assert.Equal(t, len(tt.want), buf.Len()) + assert.Equal(t, tt.want, string(buf.Bytes())) }) } } diff --git a/logger.go b/logger.go index 2b256e5..3ebdaea 100644 --- a/logger.go +++ b/logger.go @@ -5,11 +5,10 @@ import ( "io" ) -const errorKey = "LOGGER_ERROR" - // List of predefined log Levels. const ( - Crit Level = iota + Disabled Level = iota + Crit Error Warn Info @@ -55,85 +54,105 @@ func (l Level) String() string { } } +// Field is a context field. +type Field func(*Event) + // Logger represents a log writer. type Logger interface { - io.Closer - + // With returns a logger with context. + With(ctx ...Field) Logger // Debug logs a debug message. - Debug(msg string, ctx ...interface{}) + Debug(msg string, ctx ...Field) // Info logs an informational message. - Info(msg string, ctx ...interface{}) + Info(msg string, ctx ...Field) // Warn logs a warning message. - Warn(msg string, ctx ...interface{}) + Warn(msg string, ctx ...Field) // Error logs an error message. - Error(msg string, ctx ...interface{}) + Error(msg string, ctx ...Field) // Crit logs a critical message. - Crit(msg string, ctx ...interface{}) + Crit(msg string, ctx ...Field) } type logger struct { - h Handler - ctx []interface{} + w io.Writer + fmtr Formatter + lvl Level + ctx []byte } // New creates a new Logger. -func New(h Handler, ctx ...interface{}) Logger { - ctx = normalize(ctx) +func New(w io.Writer, fmtr Formatter, lvl Level) Logger { + return &logger{ + w: w, + fmtr: fmtr, + lvl: lvl, + } +} + +// With returns a new logger with the given context. +func (l *logger) With(ctx ...Field) Logger { + e := newEvent(l.fmtr) + defer putEvent(e) + + e.buf.Write(l.ctx) + + for _, field := range ctx { + field(e) + } + + b := make([]byte, e.buf.Len()) + copy(b, e.buf.Bytes()) return &logger{ - h: h, - ctx: ctx, + w: l.w, + fmtr: l.fmtr, + lvl: l.lvl, + ctx: b, } } // Debug logs a debug message. -func (l *logger) Debug(msg string, ctx ...interface{}) { +func (l *logger) Debug(msg string, ctx ...Field) { l.write(msg, Debug, ctx) } // Info logs an informational message. -func (l *logger) Info(msg string, ctx ...interface{}) { +func (l *logger) Info(msg string, ctx ...Field) { l.write(msg, Info, ctx) } // Warn logs a warning message. -func (l *logger) Warn(msg string, ctx ...interface{}) { +func (l *logger) Warn(msg string, ctx ...Field) { l.write(msg, Warn, ctx) } // Error logs an error message. -func (l *logger) Error(msg string, ctx ...interface{}) { +func (l *logger) Error(msg string, ctx ...Field) { l.write(msg, Error, ctx) } // Crit logs a critical message. -func (l *logger) Crit(msg string, ctx ...interface{}) { +func (l *logger) Crit(msg string, ctx ...Field) { l.write(msg, Crit, ctx) } -func (l *logger) write(msg string, lvl Level, ctx []interface{}) { - e := newEvent(msg, lvl) - e.BaseCtx = l.ctx - e.Ctx = normalize(ctx) - defer putEvent(e) +func (l *logger) write(msg string, lvl Level, ctx []Field) { + if lvl > l.lvl { + return + } - l.h.Log(e) -} + e := newEvent(l.fmtr) + + e.fmtr.WriteMessage(e.buf, 0, lvl, msg) + e.buf.Write(l.ctx) -// Close closes the logger. -func (l *logger) Close() error { - if h, ok := l.h.(io.Closer); ok { - return h.Close() + for _, field := range ctx { + field(e) } - return nil -} + e.fmtr.AppendEndMarker(e.buf) -func normalize(ctx []interface{}) []interface{} { - // ctx needs to be even as they are key/value pairs - if len(ctx)%2 != 0 { - ctx = append(ctx, nil, errorKey, "Normalised odd number of arguments by adding nil") - } + _, _ = l.w.Write(e.buf.Bytes()) - return ctx + putEvent(e) } diff --git a/logger_test.go b/logger_test.go index 5988e13..1963dfc 100644 --- a/logger_test.go +++ b/logger_test.go @@ -1,9 +1,14 @@ package logger_test import ( + "bytes" + "errors" + "io" "testing" + "time" "github.com/hamba/logger" + "github.com/hamba/logger/ctx" "github.com/stretchr/testify/assert" ) @@ -107,105 +112,101 @@ func TestLevel_String(t *testing.T) { } func TestNew(t *testing.T) { - h := logger.HandlerFunc(func(e *logger.Event) {}) + log := logger.New(io.Discard, logger.LogfmtFormat(), logger.Debug) - l := logger.New(h) - - assert.Implements(t, (*logger.Logger)(nil), l) + assert.Implements(t, (*logger.Logger)(nil), log) } func TestLogger(t *testing.T) { tests := []struct { - name string - fn func(l logger.Logger) - wantMsg string - wantLvl logger.Level - wantCtx []interface{} + name string + fn func(l logger.Logger) + want string }{ { - name: "Debug", - fn: func(l logger.Logger) { l.Debug("debug", "level", "debug") }, - wantMsg: "debug", - wantLvl: logger.Debug, - wantCtx: []interface{}{"level", "debug"}, + name: "Debug", + fn: func(l logger.Logger) { l.Debug("debug", ctx.Str("level", "debug")) }, + want: "lvl=dbug msg=debug level=debug\n", }, { - name: "Info", - fn: func(l logger.Logger) { l.Info("info", "level", "info") }, - wantMsg: "info", - wantLvl: logger.Info, - wantCtx: []interface{}{"level", "info"}, + name: "Info", + fn: func(l logger.Logger) { l.Info("info", ctx.Str("level", "info")) }, + want: "lvl=info msg=info level=info\n", }, { - name: "Warn", - fn: func(l logger.Logger) { l.Warn("warn", "level", "warn") }, - wantMsg: "warn", - wantLvl: logger.Warn, - wantCtx: []interface{}{"level", "warn"}, + name: "Warn", + fn: func(l logger.Logger) { l.Warn("warn", ctx.Str("level", "warn")) }, + want: "lvl=warn msg=warn level=warn\n", }, { - name: "Error", - fn: func(l logger.Logger) { l.Error("error", "level", "error") }, - wantMsg: "error", - wantLvl: logger.Error, - wantCtx: []interface{}{"level", "error"}, + name: "Error", + fn: func(l logger.Logger) { l.Error("error", ctx.Str("level", "error")) }, + want: "lvl=eror msg=error level=error\n", }, { - name: "Crit", - fn: func(l logger.Logger) { l.Crit("critical", "level", "critical") }, - wantMsg: "critical", - wantLvl: logger.Crit, - wantCtx: []interface{}{"level", "critical"}, + name: "Crit", + fn: func(l logger.Logger) { l.Crit("critical", ctx.Str("level", "critical")) }, + want: "lvl=crit msg=critical level=critical\n", }, } - for _, tt := range tests { - t.Run(tt.name, func(t *testing.T) { - var outMsg string - var outLvl logger.Level - var outCtx []interface{} - - h := logger.HandlerFunc(func(e *logger.Event) { - outMsg = e.Msg - outLvl = e.Lvl - outCtx = e.Ctx - }) - l := logger.New(h) - - tt.fn(l) - - assert.Equal(t, tt.wantMsg, outMsg) - assert.Equal(t, tt.wantLvl, outLvl) - assert.Equal(t, tt.wantCtx, outCtx) - }) - } -} - -func TestLogger_NormalizesCtx(t *testing.T) { - var out []interface{} - h := logger.HandlerFunc(func(e *logger.Event) { - out = e.Ctx - }) - l := logger.New(h) + for _, test := range tests { + test := test - l.Debug("test", "a") + t.Run(test.name, func(t *testing.T) { + t.Parallel() - assert.Len(t, out, 4) - assert.Equal(t, nil, out[1]) -} + var buf bytes.Buffer + log := logger.New(&buf, logger.LogfmtFormat(), logger.Debug) -func TestLogger_TriesToCallUnderlyingClose(t *testing.T) { - h := logger.HandlerFunc(func(e *logger.Event) {}) - l := logger.New(h) + test.fn(log) - l.Close() + assert.Equal(t, test.want, buf.String()) + }) + } } -func TestLogger_CallsUnderlyingClose(t *testing.T) { - h := &CloseableHandler{} - l := logger.New(h) +func TestLogger_DiscardsLogs(t *testing.T) { + var buf bytes.Buffer + log := logger.New(&buf, logger.LogfmtFormat(), logger.Error) + + log.Debug("some message") - l.Close() + assert.Equal(t, "", buf.String()) +} - assert.True(t, h.CloseCalled) +func TestLogger_Context(t *testing.T) { + obj := struct { + Name string + }{Name: "test"} + + var buf bytes.Buffer + log := logger.New(&buf, logger.LogfmtFormat(), logger.Info).With(ctx.Str("_n", "bench"), ctx.Int("_p", 1)) + + log.Info("some message", + ctx.Str("str", "string"), + ctx.Strs("strs", []string{"string1", "string2"}), + ctx.Bytes("bytes", []byte("bytes")), + ctx.Bool("bool", true), + ctx.Int("int", 1), + ctx.Ints("ints", []int{1, 2, 3}), + ctx.Int8("int8", 2), + ctx.Int16("int16", 3), + ctx.Int32("int32", 4), + ctx.Int64("int64", 5), + ctx.Uint("uint", 1), + ctx.Uint8("uint8", 2), + ctx.Uint16("uint16", 3), + ctx.Uint32("uint32", 4), + ctx.Uint64("uint64", 5), + ctx.Float32("float32", 1.23), + ctx.Float64("float64", 4.56), + ctx.Error("err", errors.New("test error")), + ctx.Time("str", time.Unix(1541573670, 0).UTC()), + ctx.Duration("str", time.Second), + ctx.Interface("str", obj), + ) + + want := `lvl=info msg="some message" _n=bench _p=1 str=string strs=string1,string2 bytes=98,121,116,101,115 bool=true int=1 ints=1,2,3 int8=2 int16=3 int32=4 int64=5 uint=1 uint8=2 uint16=3 uint32=4 uint64=5 float32=1.230 float64=4.560 err="test error" str=2018-11-07T06:54:30+0000 str=1s str={Name:test}` + "\n" + assert.Equal(t, want, buf.String()) } diff --git a/mocks_test.go b/mocks_test.go deleted file mode 100644 index 8e57d5f..0000000 --- a/mocks_test.go +++ /dev/null @@ -1,14 +0,0 @@ -package logger_test - -import "github.com/hamba/logger" - -type CloseableHandler struct { - CloseCalled bool -} - -func (h *CloseableHandler) Log(e *logger.Event) {} - -func (h *CloseableHandler) Close() error { - h.CloseCalled = true - return nil -} diff --git a/writer.go b/writer.go new file mode 100644 index 0000000..6df81a0 --- /dev/null +++ b/writer.go @@ -0,0 +1,26 @@ +package logger + +import ( + "io" + "sync" +) + +// SyncWriter implements a writer that is synchronised with a lock. +type SyncWriter struct { + mu sync.Mutex + w io.Writer +} + +// NewSyncWriter returns a synchronised writer. +func NewSyncWriter(w io.Writer) *SyncWriter { + return &SyncWriter{w: w} +} + +// Write writes to the writer. +func (w *SyncWriter) Write(p []byte) (n int, err error) { + w.mu.Lock() + n, err = w.w.Write(p) + w.mu.Unlock() + + return n, err +} diff --git a/writer_test.go b/writer_test.go new file mode 100644 index 0000000..ffa32a6 --- /dev/null +++ b/writer_test.go @@ -0,0 +1,22 @@ +package logger_test + +import ( + "bytes" + "testing" + + "github.com/hamba/logger" + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" +) + +func TestSyncWriter(t *testing.T) { + var buf bytes.Buffer + + w := logger.NewSyncWriter(&buf) + + n, err := w.Write([]byte("test")) + + require.NoError(t, err) + assert.Equal(t, 4, n) + assert.Equal(t, "test", buf.String()) +}