From fcf369b1c10318f2a4df3a336920bfae1271baef Mon Sep 17 00:00:00 2001 From: Nicholas Wiersma Date: Mon, 11 Feb 2019 09:09:44 +0200 Subject: [PATCH] Initial commit --- .gitignore | 0 .travis.yml | 21 +++ LICENCE | 22 +++ Makefile | 1 + README.md | 38 ++++ bench_test.go | 59 +++++++ doc.go | 19 ++ example_test.go | 59 +++++++ format.go | 236 +++++++++++++++++++++++++ format_test.go | 170 ++++++++++++++++++ go.mod | 7 + go.sum | 6 + handler.go | 190 ++++++++++++++++++++ handler_test.go | 102 +++++++++++ internal/bytes/buffer.go | 102 +++++++++++ internal/bytes/buffer_internal_test.go | 102 +++++++++++ logger.go | 142 +++++++++++++++ logger_test.go | 223 +++++++++++++++++++++++ mocks_test.go | 14 ++ 19 files changed, 1513 insertions(+) create mode 100644 .gitignore create mode 100644 .travis.yml create mode 100644 LICENCE create mode 100644 Makefile create mode 100644 README.md create mode 100644 bench_test.go create mode 100644 doc.go create mode 100644 example_test.go create mode 100644 format.go create mode 100644 format_test.go create mode 100644 go.mod create mode 100644 go.sum create mode 100644 handler.go create mode 100644 handler_test.go create mode 100644 internal/bytes/buffer.go create mode 100644 internal/bytes/buffer_internal_test.go create mode 100644 logger.go create mode 100644 logger_test.go create mode 100644 mocks_test.go diff --git a/.gitignore b/.gitignore new file mode 100644 index 0000000..e69de29 diff --git a/.travis.yml b/.travis.yml new file mode 100644 index 0000000..bd85e94 --- /dev/null +++ b/.travis.yml @@ -0,0 +1,21 @@ +sudo: false + +language: go +go: +- "1.11" +- "1.x" +env: +- GO111MODULE=on + +before_install: +- go get -u golang.org/x/lint/golint +- go get github.com/mattn/goveralls + +script: +- golint ./... +- go vet ./... +- go test -covermode=count -coverprofile=profile.cov ./... +- goveralls -coverprofile=profile.cov -service=travis-ci + +notifications: + email: false \ No newline at end of file diff --git a/LICENCE b/LICENCE new file mode 100644 index 0000000..cb197c2 --- /dev/null +++ b/LICENCE @@ -0,0 +1,22 @@ +Copyright (c) 2019 Nicholas Wiersma + +MIT License + +Permission is hereby granted, free of charge, to any person obtaining +a copy of this software and associated documentation files (the +"Software"), to deal in the Software without restriction, including +without limitation the rights to use, copy, modify, merge, publish, +distribute, sublicense, and/or sell copies of the Software, and to +permit persons to whom the Software is furnished to do so, subject to +the following conditions: + +The above copyright notice and this permission notice shall be +included in all copies or substantial portions of the Software. + +THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, +EXPRESS OR IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF +MERCHANTABILITY, FITNESS FOR A PARTICULAR PURPOSE AND +NONINFRINGEMENT. IN NO EVENT SHALL THE AUTHORS OR COPYRIGHT HOLDERS BE +LIABLE FOR ANY CLAIM, DAMAGES OR OTHER LIABILITY, WHETHER IN AN ACTION +OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, OUT OF OR IN CONNECTION +WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE SOFTWARE. \ No newline at end of file diff --git a/Makefile b/Makefile new file mode 100644 index 0000000..a182b7b --- /dev/null +++ b/Makefile @@ -0,0 +1 @@ +include github.com/hamba/make/golang diff --git a/README.md b/README.md new file mode 100644 index 0000000..42bb7cb --- /dev/null +++ b/README.md @@ -0,0 +1,38 @@ +![Logo](http://svg.wiersma.co.za/github/project?lang=go&title=logger&tag=fast%20Go%20logger) + +[![Go Report Card](https://goreportcard.com/badge/github.com/hamba/logger)](https://goreportcard.com/report/github.com/hamba/logger) +[![Build Status](https://travis-ci.org/hamba/logger.svg?branch=master)](https://travis-ci.org/hamba/logger) +[![Coverage Status](https://coveralls.io/repos/github/hamba/logger/badge.svg?branch=master)](https://coveralls.io/github/hamba/logger?branch=master) +[![GoDoc](https://godoc.org/github.com/hamba/logger?status.svg)](https://godoc.org/github.com/hamba/logger) +[![GitHub release](https://img.shields.io/github/release/hamba/logger.svg)](https://github.com/hamba/logger/releases) +[![GitHub license](https://img.shields.io/badge/license-MIT-blue.svg)](https://raw.githubusercontent.com/hamba/logger/master/LICENSE) + +## Overview + +Install with: + +```shell +go get github.com/hamba/logger +``` + +## Examples + +```go +// Composable handlers +h := logger.LevelFilterHandler( + logger.Info, + logger.StreamHandler(os.Stdout, logger.LogfmtFormat()), +) + +// The logger can have an initial context +l := logger.New(h, "env", "prod") + +// All messages can have a context +l.Warn("connection error", "redis", conn.Name(), "timeout", conn.Timeout()) +``` + +Will log the message + +``` +lvl=warn msg="connection error" redis=dsn_1 timeout=0.500 +``` \ No newline at end of file diff --git a/bench_test.go b/bench_test.go new file mode 100644 index 0000000..ecefa14 --- /dev/null +++ b/bench_test.go @@ -0,0 +1,59 @@ +package logger_test + +import ( + "bytes" + "os" + "testing" + + "github.com/hamba/logger" +) + +func BenchmarkLogged_Logfmt(b *testing.B) { + buf := &bytes.Buffer{} + l := logger.New(logger.StreamHandler(buf, logger.LogfmtFormat()), "_n", "bench", "_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() +} + +func BenchmarkLogged_Json(b *testing.B) { + buf := &bytes.Buffer{} + l := logger.New(logger.StreamHandler(buf, logger.JSONFormat()), "_n", "bench", "_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() +} + +func BenchmarkLevelLogged_Logfmt(b *testing.B) { + buf := &bytes.Buffer{} + b.ResetTimer() + l := logger.New(logger.StreamHandler(buf, 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() +} + +func BenchmarkLevelLogged_Json(b *testing.B) { + buf := &bytes.Buffer{} + b.ResetTimer() + l := logger.New(logger.StreamHandler(buf, 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() +} diff --git a/doc.go b/doc.go new file mode 100644 index 0000000..235ef88 --- /dev/null +++ b/doc.go @@ -0,0 +1,19 @@ +/* +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()), + ) + + // The logger can have an initial context + l := logger.New(h, "env", "prod") + + // All messages can have a context + l.Error("connection error", "redis", conn.Name(), "timeout", conn.Timeout()) + */ +package logger diff --git a/example_test.go b/example_test.go new file mode 100644 index 0000000..a380e00 --- /dev/null +++ b/example_test.go @@ -0,0 +1,59 @@ +package logger_test + +import ( + "os" + "time" + + "github.com/hamba/logger" +) + +func ExampleNew() { + h := logger.LevelFilterHandler( + logger.Info, + logger.StreamHandler(os.Stdout, logger.LogfmtFormat()), + ) + + 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) +} + +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(msg string, lvl logger.Level, ctx []interface{}) bool { + return msg == "some condition" + }, + logger.StreamHandler(os.Stdout, logger.LogfmtFormat()), + ) + + l := logger.New(h, "env", "prod") + + l.Info("redis connection", "redis", "some redis name", "timeout", 10) +} diff --git a/format.go b/format.go new file mode 100644 index 0000000..2c8dfe6 --- /dev/null +++ b/format.go @@ -0,0 +1,236 @@ +package logger + +import ( + "fmt" + "time" + + "github.com/hamba/logger/internal/bytes" +) + +const ( + //LevelKey is the key used for message levels. + LevelKey = "lvl" + // MessageKey is the key used for message descriptions. + MessageKey = "msg" + + timeFormat = "2006-01-02T15:04:05-0700" // ISO8601 format +) + +// Formatter represents a log message formatter. +type Formatter interface { + // Format formats a log message. + Format(msg string, lvl Level, ctx []interface{}) []byte +} + +// FormatterFunc is a function formatter. +type FormatterFunc func(msg string, lvl Level, ctx []interface{}) []byte + +// Format formats a log message. +func (f FormatterFunc) Format(msg string, lvl Level, ctx []interface{}) []byte { + return f(msg, lvl, ctx) +} + +var jsonPool = bytes.NewPool(512) + +// JSONFormat formats a log line in json format. +func JSONFormat() Formatter { + return FormatterFunc(func(msg string, lvl Level, ctx []interface{}) []byte { + buf := jsonPool.Get() + + // Append initial keys to the buffer + buf.WriteByte('{') + buf.WriteString(`"` + LevelKey + `":"` + lvl.String() + `",`) + buf.WriteString(`"` + MessageKey + `":`) + quoteString(buf, msg) + + // Append ctx to the buffer + for i := 0; i < len(ctx); i += 2 { + buf.WriteByte(',') + + k, ok := ctx[i].(string) + if !ok { + buf.WriteString(`"` + errorKey + `"`) + buf.WriteByte(':') + formatJSONValue(buf, ctx[i]) + continue + } + + buf.WriteString(`"` + k + `"`) + buf.WriteByte(':') + formatJSONValue(buf, ctx[i+1]) + } + + buf.WriteString("}\n") + + jsonPool.Put(buf) + return buf.Bytes() + }) +} + +// formatJSONValue formats a value, adding it to the buffer. +func formatJSONValue(buf *bytes.Buffer, value interface{}) { + if value == nil { + buf.WriteString("null") + return + } + + switch v := value.(type) { + case time.Time: + buf.WriteByte('"') + buf.AppendTime(v, timeFormat) + buf.WriteByte('"') + case bool: + buf.AppendBool(v) + case float32: + buf.AppendFloat(float64(v), 'g', -1, 64) + case float64: + buf.AppendFloat(v, 'g', -1, 64) + case int: + buf.AppendInt(int64(v)) + case int8: + buf.AppendInt(int64(v)) + case int16: + buf.AppendInt(int64(v)) + case int32: + buf.AppendInt(int64(v)) + case int64: + buf.AppendInt(v) + case uint: + buf.AppendUint(uint64(v)) + case uint8: + buf.AppendUint(uint64(v)) + case uint16: + buf.AppendUint(uint64(v)) + case uint32: + buf.AppendUint(uint64(v)) + case uint64: + buf.AppendUint(v) + case string: + quoteString(buf, v) + default: + quoteString(buf, fmt.Sprintf("%+v", value)) + } +} + +var logfmtPool = bytes.NewPool(512) + +// LogfmtFormat formats a log line in logfmt format. +func LogfmtFormat() Formatter { + return FormatterFunc(func(msg string, lvl Level, ctx []interface{}) []byte { + buf := logfmtPool.Get() + + // Append initial keys to the buffer + buf.WriteString(LevelKey + "=" + lvl.String() + " ") + buf.WriteString(MessageKey + "=") + logfmtQuoteString(buf, msg) + + // Append ctx to the buffer + for i := 0; i < len(ctx); i += 2 { + buf.WriteByte(' ') + + k, ok := ctx[i].(string) + if !ok { + buf.WriteString(errorKey) + buf.WriteByte('=') + formatLogfmtValue(buf, ctx[i]) + continue + } + + buf.WriteString(k) + buf.WriteByte('=') + formatLogfmtValue(buf, ctx[i+1]) + } + + buf.WriteByte('\n') + + logfmtPool.Put(buf) + return buf.Bytes() + }) +} + +// formatLogfmtValue formats a value, adding it to the buffer. +func formatLogfmtValue(buf *bytes.Buffer, value interface{}) { + if value == nil { + return + } + + switch v := value.(type) { + case time.Time: + buf.AppendTime(v, timeFormat) + case bool: + buf.AppendBool(v) + case float32: + buf.AppendFloat(float64(v), 'f', 3, 64) + case float64: + buf.AppendFloat(v, 'f', 3, 64) + case int: + buf.AppendInt(int64(v)) + case int8: + buf.AppendInt(int64(v)) + case int16: + buf.AppendInt(int64(v)) + case int32: + buf.AppendInt(int64(v)) + case int64: + buf.AppendInt(v) + case uint: + buf.AppendUint(uint64(v)) + case uint8: + buf.AppendUint(uint64(v)) + case uint16: + buf.AppendUint(uint64(v)) + case uint32: + buf.AppendUint(uint64(v)) + case uint64: + buf.AppendUint(v) + case string: + logfmtQuoteString(buf, v) + default: + logfmtQuoteString(buf, fmt.Sprintf("%+v", value)) + } +} + +func logfmtQuoteString(buf *bytes.Buffer, s string) { + needsQuotes := false + for _, r := range s { + if r <= ' ' || r == '=' || r == '"' { + needsQuotes = true + } + } + + if needsQuotes { + buf.WriteByte('"') + } + + escapeString(buf, s) + + if needsQuotes { + buf.WriteByte('"') + } +} + +func quoteString(buf *bytes.Buffer, s string) { + buf.WriteByte('"') + + escapeString(buf, s) + + buf.WriteByte('"') +} + +func escapeString(buf *bytes.Buffer, s string) { + for _, r := range s { + switch r { + case '\\', '"': + buf.WriteByte('\\') + buf.WriteByte(byte(r)) + case '\n': + buf.WriteString("\\n") + case '\r': + buf.WriteString("\\r") + case '\t': + buf.WriteString("\\t") + default: + buf.WriteByte(byte(r)) + } + } +} diff --git a/format_test.go b/format_test.go new file mode 100644 index 0000000..c8b4544 --- /dev/null +++ b/format_test.go @@ -0,0 +1,170 @@ +package logger_test + +import ( + "encoding/json" + "testing" + "time" + + "github.com/hamba/logger" + "github.com/stretchr/testify/assert" +) + +func TestJsonFormat(t *testing.T) { + f := logger.JSONFormat() + + b := f.Format("some message", logger.Error, []interface{}{"x", 1, "y", 3.2, "bool", true, + "carriage_return", "bang" + string('\r') + "foo", "tab", "bar baz", "newline", "foo\nbar", "escape", string('\\')}) + + 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) + + m := map[string]interface{}{} + err := json.Unmarshal(b, &m) + assert.NoError(t, err) +} + +func TestJsonFormat_KeyError(t *testing.T) { + f := logger.JSONFormat() + + b := f.Format("some message", logger.Error, []interface{}{1, "y"}) + + expect := []byte(`{"lvl":"eror","msg":"some message","LOGGER_ERROR":1}` + "\n") + assert.Equal(t, expect, b) + + m := map[string]interface{}{} + err := json.Unmarshal(b, &m) + assert.NoError(t, err) +} + +func TestJsonFormat_Ints(t *testing.T) { + f := logger.JSONFormat() + + b := f.Format("", logger.Error, []interface{}{"int", 1, "int8", int8(2), "int16", int16(3), "int32", int32(4), "int64", int64(5)}) + + expect := []byte(`{"lvl":"eror","msg":"","int":1,"int8":2,"int16":3,"int32":4,"int64":5}` + "\n") + assert.Equal(t, expect, b) + + m := map[string]interface{}{} + err := json.Unmarshal(b, &m) + assert.NoError(t, err) +} + +func TestJsonFormat_Uints(t *testing.T) { + f := logger.JSONFormat() + + b := f.Format("", logger.Error, []interface{}{"uint", uint(1), "uint8", uint8(2), "uint16", uint16(3), "uint32", uint32(4), "uint64", uint64(5)}) + + expect := []byte(`{"lvl":"eror","msg":"","uint":1,"uint8":2,"uint16":3,"uint32":4,"uint64":5}` + "\n") + assert.Equal(t, expect, b) + + m := map[string]interface{}{} + err := json.Unmarshal(b, &m) + assert.NoError(t, err) +} + +func TestJsonFormat_Floats(t *testing.T) { + f := logger.JSONFormat() + + b := f.Format("", logger.Error, []interface{}{"float32", float32(1), "float64", float64(4.56)}) + + expect := []byte(`{"lvl":"eror","msg":"","float32":1,"float64":4.56}` + "\n") + assert.Equal(t, expect, b) + + m := map[string]interface{}{} + err := json.Unmarshal(b, &m) + assert.NoError(t, err) +} + +func TestJsonFormat_Time(t *testing.T) { + f := logger.JSONFormat() + + b := f.Format("", logger.Error, []interface{}{"time", time.Unix(1541573670, 0).UTC()}) + + expect := []byte(`{"lvl":"eror","msg":"","time":"2018-11-07T06:54:30+0000"}` + "\n") + assert.Equal(t, expect, b) + + m := map[string]interface{}{} + err := json.Unmarshal(b, &m) + assert.NoError(t, err) +} + +func TestJsonFormat_Unknown(t *testing.T) { + obj := struct { + Name string + }{Name: "test"} + + f := logger.JSONFormat() + + b := f.Format("", logger.Error, []interface{}{"what", obj, "nil", nil}) + + expect := []byte(`{"lvl":"eror","msg":"","what":"{Name:test}","nil":null}` + "\n") + assert.Equal(t, expect, b) +} + +func TestLogfmtFormat(t *testing.T) { + f := logger.LogfmtFormat() + + b := f.Format("some message", logger.Error, []interface{}{"x", 1, "y", 3.2, "bool", true, "equals", "=", "quote", "\"", + "carriage_return", "bang" + string('\r') + "foo", "tab", "bar baz", "newline", "foo\nbar", "escape", string('\\')}) + + 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) +} + +func TestLogfmtFormat_KeyError(t *testing.T) { + f := logger.LogfmtFormat() + + b := f.Format("some message", logger.Error, []interface{}{1, "y"}) + + expect := []byte(`lvl=eror msg="some message" LOGGER_ERROR=1` + "\n") + assert.Equal(t, expect, b) +} + +func TestLogfmtFormat_Ints(t *testing.T) { + f := logger.LogfmtFormat() + + b := f.Format("", logger.Error, []interface{}{"int", 1, "int8", int8(2), "int16", int16(3), "int32", int32(4), "int64", int64(5)}) + + expect := []byte(`lvl=eror msg= int=1 int8=2 int16=3 int32=4 int64=5` + "\n") + assert.Equal(t, expect, b) +} + +func TestLogfmtFormat_Uints(t *testing.T) { + f := logger.LogfmtFormat() + + b := f.Format("", logger.Error, []interface{}{"uint", uint(1), "uint8", uint8(2), "uint16", uint16(3), "uint32", uint32(4), "uint64", uint64(5)}) + + expect := []byte(`lvl=eror msg= uint=1 uint8=2 uint16=3 uint32=4 uint64=5` + "\n") + assert.Equal(t, expect, b) +} + +func TestLogfmtFormat_Floats(t *testing.T) { + f := logger.LogfmtFormat() + + b := f.Format("", logger.Error, []interface{}{"float32", float32(1.23), "float64", float64(4.56)}) + + expect := []byte(`lvl=eror msg= float32=1.230 float64=4.560` + "\n") + assert.Equal(t, expect, b) +} + +func TestLogfmtFormat_Time(t *testing.T) { + f := logger.LogfmtFormat() + + b := f.Format("", logger.Error, []interface{}{"time", time.Unix(1541573670, 0).UTC()}) + + expect := []byte(`lvl=eror msg= time=2018-11-07T06:54:30+0000` + "\n") + assert.Equal(t, expect, b) +} + +func TestLogfmtFormat_Unknown(t *testing.T) { + obj := struct { + Name string + }{Name: "test"} + + f := logger.LogfmtFormat() + + b := f.Format("", logger.Error, []interface{}{"what", obj, "nil", nil}) + + expect := []byte(`lvl=eror msg= what={Name:test} nil=` + "\n") + assert.Equal(t, expect, b) +} diff --git a/go.mod b/go.mod new file mode 100644 index 0000000..3d8243a --- /dev/null +++ b/go.mod @@ -0,0 +1,7 @@ +module github.com/hamba/logger + +require ( + github.com/davecgh/go-spew v1.1.1 // indirect + github.com/pmezard/go-difflib v1.0.0 // indirect + github.com/stretchr/testify v1.2.2 +) diff --git a/go.sum b/go.sum new file mode 100644 index 0000000..e03ee77 --- /dev/null +++ b/go.sum @@ -0,0 +1,6 @@ +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/testify v1.2.2 h1:bSDNvY7ZPG5RlJ8otE/7V6gMiyenm9RtJ7IUVIAoJ1w= +github.com/stretchr/testify v1.2.2/go.mod h1:a8OnRcib4nhh0OaRAV+Yts87kKdq0PP7pXfy6kDkUVs= diff --git a/handler.go b/handler.go new file mode 100644 index 0000000..35213e8 --- /dev/null +++ b/handler.go @@ -0,0 +1,190 @@ +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(msg string, lvl Level, ctx []interface{}) +} + +// HandlerFunc is a function handler. +type HandlerFunc func(msg string, lvl Level, ctx []interface{}) + +// Log write the log message. +func (h HandlerFunc) Log(msg string, lvl Level, ctx []interface{}) { + h(msg, lvl, ctx) +} + +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(msg string, lvl Level, ctx []interface{}) { + h.withBufferLock(func() { + // Dont write to a closed + if h.buf == nil { + return + } + + h.buf.Write(h.fmtr.Format(msg, lvl, ctx)) + + 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(msg string, lvl Level, ctx []interface{}) { + mu.Lock() + w.Write(fmtr.Format(msg, lvl, ctx)) + mu.Unlock() + } + + return HandlerFunc(h) +} + +// FilterFunc represents a function that can filter messages. +type FilterFunc func(msg string, lvl Level, ctx []interface{}) 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(msg string, lvl Level, ctx []interface{}) { + if fn(msg, lvl, ctx) { + h.Log(msg, lvl, ctx) + } + }), + } + + if ch, ok := h.(io.Closer); ok { + c.Closer = ch + } + + return c +} + +// LevelFilterHandler returns a handler that +func LevelFilterHandler(maxLvl Level, h Handler) Handler { + return FilterHandler(func(msg string, lvl Level, ctx []interface{}) bool { + return lvl <= maxLvl + }, h) +} + +// DiscardHandler does nothing, discarding all log messages. +func DiscardHandler() Handler { + return HandlerFunc(func(msg string, lvl Level, ctx []interface{}) {}) +} + +// 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 new file mode 100644 index 0000000..9d7e0bf --- /dev/null +++ b/handler_test.go @@ -0,0 +1,102 @@ +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("some message", logger.Error, []interface{}{}) + 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("some message", logger.Error, []interface{}{}) + + time.Sleep(2 * 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("some message", logger.Error, []interface{}{}) + h.Log("some message", logger.Error, []interface{}{}) + + 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("some message", logger.Error, []interface{}{}) + + assert.Equal(t, "", buf.String()) +} + +func TestStreamHandler(t *testing.T) { + buf := &bytes.Buffer{} + h := logger.StreamHandler(buf, logger.LogfmtFormat()) + + h.Log("some message", logger.Error, []interface{}{}) + + assert.Equal(t, "lvl=eror msg=\"some message\"\n", buf.String()) +} + +func TestLevelFilterHandler(t *testing.T) { + count := 0 + testHandler := logger.HandlerFunc(func(msg string, lvl logger.Level, ctx []interface{}) { + count++ + }) + h := logger.LevelFilterHandler(logger.Info, testHandler) + + h.Log("test", logger.Debug, []interface{}{}) + h.Log("test", logger.Info, []interface{}{}) + + assert.Equal(t, 1, count) +} + +func TestLevelFilterHandler_TriesToCallUnderlyingClose(t *testing.T) { + testHandler := logger.HandlerFunc(func(msg string, lvl logger.Level, ctx []interface{}) {}) + 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("test", logger.Crit, []interface{}{}) +} diff --git a/internal/bytes/buffer.go b/internal/bytes/buffer.go new file mode 100644 index 0000000..58d2a93 --- /dev/null +++ b/internal/bytes/buffer.go @@ -0,0 +1,102 @@ +package bytes + +import ( + "strconv" + "sync" + "time" +) + +// 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 +} + +// AppendInt appends an integer to the underlying Buffer. +func (b *Buffer) AppendInt(i int64) { + b.b = strconv.AppendInt(b.b, i, 10) +} + +// AppendUint appends an unsigned integer to the underlying Buffer. +func (b *Buffer) AppendUint(i uint64) { + b.b = strconv.AppendUint(b.b, i, 10) +} + +// AppendFloat appends a float to the underlying Buffer. +func (b *Buffer) AppendFloat(f float64, fmt byte, prec, bitSize int) { + b.b = strconv.AppendFloat(b.b, f, fmt, prec, bitSize) +} + +// AppendBool appends a bool to the underlying Buffer. +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 { + b.b = append(b.b, v) + return nil +} + +// WriteString writes a string to the Buffer. +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) +} + +// Cap returns the capacity of the underlying byte slice. +func (b *Buffer) Cap() int { + return cap(b.b) +} + +// Bytes returns a mutable reference to the underlying byte slice. +func (b *Buffer) Bytes() []byte { + return b.b +} + +// Reset resets the underlying byte slice. Subsequent writes re-use the slice's +// backing array. +func (b *Buffer) Reset() { + b.b = b.b[:0] +} diff --git a/internal/bytes/buffer_internal_test.go b/internal/bytes/buffer_internal_test.go new file mode 100644 index 0000000..3134bf8 --- /dev/null +++ b/internal/bytes/buffer_internal_test.go @@ -0,0 +1,102 @@ +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() + + tests := []struct { + name string + fn func() + want string + }{ + { + name: "WriteByte", + fn: func() { buf.WriteByte('v') }, + want: "v", + }, + { + name: "WriteString", + fn: func() { buf.WriteString("foo") }, + want: "foo", + }, + { + name: "Write", + fn: func() { buf.Write([]byte("foo")) }, + want: "foo", + }, + { + name: "AppendIntPositive", + fn: func() { buf.AppendInt(42) }, want: "42", + }, + { + name: "AppendIntNegative", + fn: func() { buf.AppendInt(-42) }, want: "-42", + }, + { + name: "AppendUint", + fn: func() { buf.AppendUint(42) }, want: "42", + }, + { + name: "AppendBool", + 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()) + }) + } +} diff --git a/logger.go b/logger.go new file mode 100644 index 0000000..92d0237 --- /dev/null +++ b/logger.go @@ -0,0 +1,142 @@ +package logger + +import ( + "errors" + "io" +) + +const errorKey = "LOGGER_ERROR" + +// List of predefined log Levels +const ( + Crit Level = iota + Error + Warn + Info + Debug +) + +// Level represents the predefined log level. +type Level int + +// LevelFromString converts a string to Level. +func LevelFromString(lvl string) (Level, error) { + switch lvl { + case "debug", "dbug": + return Debug, nil + case "info": + return Info, nil + case "warn": + return Warn, nil + case "error", "eror": + return Error, nil + case "crit": + return Crit, nil + default: + return 0, errors.New("unknown level " + lvl) + } +} + +// String returns the string representation of the level. +func (l Level) String() string { + switch l { + case Debug: + return "dbug" + case Info: + return "info" + case Warn: + return "warn" + case Error: + return "eror" + case Crit: + return "crit" + default: + return "unkn" + } +} + +// Logger represents a log writer. +type Logger interface { + io.Closer + + // Debug logs a debug message. + Debug(msg string, ctx ...interface{}) + // Info logs an informational message. + Info(msg string, ctx ...interface{}) + // Warn logs a warning message. + Warn(msg string, ctx ...interface{}) + // Error logs an error message. + Error(msg string, ctx ...interface{}) + // Crit logs a critical message. + Crit(msg string, ctx ...interface{}) +} + +type logger struct { + h Handler + ctx []interface{} +} + +// New creates a new Logger. +func New(h Handler, ctx ...interface{}) Logger { + return &logger{ + h: h, + ctx: ctx, + } +} + +// Debug logs a debug message. +func (l *logger) Debug(msg string, ctx ...interface{}) { + l.write(msg, Debug, ctx) +} + +// Info logs an informational message. +func (l *logger) Info(msg string, ctx ...interface{}) { + l.write(msg, Info, ctx) +} + +// Warn logs a warning message. +func (l *logger) Warn(msg string, ctx ...interface{}) { + l.write(msg, Warn, ctx) +} + +// Error logs an error message. +func (l *logger) Error(msg string, ctx ...interface{}) { + l.write(msg, Error, ctx) +} + +// Crit logs a critical message. +func (l *logger) Crit(msg string, ctx ...interface{}) { + l.write(msg, Crit, ctx) +} + +func (l *logger) write(msg string, lvl Level, ctx []interface{}) { + ctx = normalize(ctx) + + l.h.Log(msg, lvl, merge(l.ctx, ctx)) +} + +// Close closes the logger. +func (l *logger) Close() error { + if h, ok := l.h.(io.Closer); ok { + return h.Close() + } + + return nil +} + +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") + } + + return ctx +} + +func merge(prefix, suffix []interface{}) []interface{} { + newCtx := make([]interface{}, len(prefix)+len(suffix)) + n := copy(newCtx, prefix) + copy(newCtx[n:], suffix) + + return newCtx +} diff --git a/logger_test.go b/logger_test.go new file mode 100644 index 0000000..cb937b7 --- /dev/null +++ b/logger_test.go @@ -0,0 +1,223 @@ +package logger_test + +import ( + "testing" + + "github.com/hamba/logger" + "github.com/stretchr/testify/assert" +) + +func TestLevelFromString(t *testing.T) { + tests := []struct { + lvl string + want logger.Level + wantError bool + }{ + { + lvl: "dbug", + want: logger.Debug, + wantError: false, + }, + { + lvl: "debug", + want: logger.Debug, + wantError: false, + }, + { + lvl: "info", + want: logger.Info, + wantError: false, + }, + { + lvl: "warn", + want: logger.Warn, + wantError: false, + }, + { + lvl: "eror", + want: logger.Error, + wantError: false, + }, + { + lvl: "error", + want: logger.Error, + wantError: false, + }, + { + lvl: "crit", + want: logger.Crit, + wantError: false, + }, + { + lvl: "unkn", + want: logger.Level(123), + wantError: true, + }, + } + + for _, tt := range tests { + t.Run(tt.lvl, func(t *testing.T) { + lvl, err := logger.LevelFromString(tt.lvl) + + if tt.wantError { + assert.Error(t, err) + return + } + + assert.NoError(t, err) + assert.Equal(t, tt.want, lvl, ) + }) + } +} + +func TestLevel_String(t *testing.T) { + tests := []struct { + lvl logger.Level + want string + }{ + { + lvl: logger.Debug, + want: "dbug", + }, + { + lvl: logger.Info, + want: "info", + }, + { + lvl: logger.Warn, + want: "warn", + }, + { + lvl: logger.Error, + want: "eror", + }, + { + lvl: logger.Crit, + want: "crit", + }, + { + lvl: logger.Level(123), + want: "unkn", + }, + } + + for _, tt := range tests { + assert.Equal(t, tt.want, tt.lvl.String()) + } +} + +func TestNew(t *testing.T) { + h := logger.HandlerFunc(func(msg string, lvl logger.Level, ctx []interface{}) {}) + + l := logger.New(h) + + assert.Implements(t, (*logger.Logger)(nil), l) +} + +func TestLogger(t *testing.T) { + tests := []struct { + name string + fn func(l logger.Logger) + wantMsg string + wantLvl logger.Level + wantCtx []interface{} + }{ + { + name: "Debug", + fn: func(l logger.Logger) { l.Debug("debug", "level", "debug") }, + wantMsg: "debug", + wantLvl: logger.Debug, + wantCtx: []interface{}{"level", "debug"}, + }, + { + name: "Info", + fn: func(l logger.Logger) { l.Info("info", "level", "info") }, + wantMsg: "info", + wantLvl: logger.Info, + wantCtx: []interface{}{"level", "info"}, + }, + { + name: "Warn", + fn: func(l logger.Logger) { l.Warn("warn", "level", "warn") }, + wantMsg: "warn", + wantLvl: logger.Warn, + wantCtx: []interface{}{"level", "warn"}, + }, + { + name: "Error", + fn: func(l logger.Logger) { l.Error("error", "level", "error") }, + wantMsg: "error", + wantLvl: logger.Error, + wantCtx: []interface{}{"level", "error"}, + }, + { + name: "Crit", + fn: func(l logger.Logger) { l.Crit("critical", "level", "critical") }, + wantMsg: "critical", + wantLvl: logger.Crit, + wantCtx: []interface{}{"level", "critical"}, + }, + } + + 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(msg string, lvl logger.Level, ctx []interface{}) { + outMsg = msg + outLvl = lvl + outCtx = 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_MergesCtx(t *testing.T) { + var out []interface{} + h := logger.HandlerFunc(func(msg string, lvl logger.Level, ctx []interface{}) { + out = ctx + }) + l := logger.New(h, "a", "b") + + l.Debug("test", "c", "d") + + assert.Equal(t, []interface{}{"a", "b", "c", "d"}, out) +} + +func TestLogger_NormalizesCtx(t *testing.T) { + var out []interface{} + h := logger.HandlerFunc(func(msg string, lvl logger.Level, ctx []interface{}) { + out = ctx + }) + l := logger.New(h) + + l.Debug("test", "a") + + assert.Len(t, out, 4) + assert.Equal(t, nil, out[1]) +} + +func TestLogger_TriesToCallUnderlyingClose(t *testing.T) { + h := logger.HandlerFunc(func(msg string, lvl logger.Level, ctx []interface{}) {}) + l := logger.New(h) + + l.Close() +} + +func TestLogger_CallsUnderlyingClose(t *testing.T) { + h := &CloseableHandler{} + l := logger.New(h) + + l.Close() + + assert.True(t, h.CloseCalled) +} diff --git a/mocks_test.go b/mocks_test.go new file mode 100644 index 0000000..683531f --- /dev/null +++ b/mocks_test.go @@ -0,0 +1,14 @@ +package logger_test + +import "github.com/hamba/logger" + +type CloseableHandler struct { + CloseCalled bool +} + +func (h *CloseableHandler) Log(msg string, lvl logger.Level, ctx []interface{}) {} + +func (h *CloseableHandler) Close() error { + h.CloseCalled = true + return nil +}