diff --git a/.gitattributes b/.gitattributes new file mode 100644 index 0000000..2e97079 --- /dev/null +++ b/.gitattributes @@ -0,0 +1 @@ +go.sum linguist-generated=true diff --git a/go.mod b/go.mod index f71424f..264929d 100644 --- a/go.mod +++ b/go.mod @@ -3,7 +3,11 @@ module github.com/anz-bank/pkg go 1.13 require ( - github.com/marcelocantos/frozen v0.4.0 + github.com/alecthomas/assert v0.0.0-20170929043011-405dbfeb8e38 + github.com/alecthomas/colour v0.1.0 // indirect + github.com/alecthomas/repr v0.0.0-20181024024818-d37bc2a10ba1 // indirect + github.com/arr-ai/frozen v0.11.1 + github.com/mattn/go-isatty v0.0.12 // indirect github.com/sirupsen/logrus v1.4.2 github.com/stretchr/testify v1.4.0 ) diff --git a/go.sum b/go.sum index b1fb587..06e3567 100644 --- a/go.sum +++ b/go.sum @@ -1,3 +1,13 @@ +github.com/alecthomas/assert v0.0.0-20170929043011-405dbfeb8e38 h1:smF2tmSOzy2Mm+0dGI2AIUHY+w0BUc+4tn40djz7+6U= +github.com/alecthomas/assert v0.0.0-20170929043011-405dbfeb8e38/go.mod h1:r7bzyVFMNntcxPZXK3/+KdruV1H5KSlyVY0gc+NgInI= +github.com/alecthomas/colour v0.1.0 h1:nOE9rJm6dsZ66RGWYSFrXw461ZIt9A6+nHgL7FRrDUk= +github.com/alecthomas/colour v0.1.0/go.mod h1:QO9JBoKquHd+jz9nshCh40fOfO+JzsoXy8qTHF68zU0= +github.com/alecthomas/repr v0.0.0-20181024024818-d37bc2a10ba1 h1:GDQdwm/gAcJcLAKQQZGOJ4knlw+7rfEQQcmwTbt4p5E= +github.com/alecthomas/repr v0.0.0-20181024024818-d37bc2a10ba1/go.mod h1:xTS7Pm1pD1mvyM075QCDSRqH6qRLXylzS24ZTpRiSzQ= +github.com/arr-ai/frozen v0.11.1 h1:mX5fS6eeONZUNLFp/ZVEBaU+1RKUH8HgSUQflQm7YIA= +github.com/arr-ai/frozen v0.11.1/go.mod h1:YEr4TubkrAoA3f9U1R4PcEVB5ocBUdiS3NKh03cbVts= +github.com/arr-ai/hash v0.4.0 h1:VPIDl5nkhq8qntxmsNd00bdj+UVs2vRKFzzM7HZkR7Q= +github.com/arr-ai/hash v0.4.0/go.mod h1:2fLB6qpmZbH+dpvNooTW2m9o5z1pEsUQxfGmZs6Z8QQ= 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= @@ -8,10 +18,8 @@ github.com/kr/pretty v0.1.0/go.mod h1:dAy3ld7l9f0ibDNOQOHHMYYIIbhfbHSm3C4ZsoJORN github.com/kr/pty v1.1.1/go.mod h1:pFQYn66WHrOpPYNljwOMqo10TkYh1fy3cYio2l3bCsQ= github.com/kr/text v0.1.0 h1:45sCR5RtlFHMR4UwH9sdQ5TC8v0qDQCHnXt+kaKSTVE= github.com/kr/text v0.1.0/go.mod h1:4Jbv+DJW3UT/LiOwJeYQe1efqtUx/iVham/4vfdArNI= -github.com/marcelocantos/frozen v0.4.0 h1:GzYtr+BWZBTGpYeXZvACr3HUDN0wZKDg5tApuKdt59E= -github.com/marcelocantos/frozen v0.4.0/go.mod h1:kMkkLrWmAufGtJqXshM37prrD5O3ovVmb1pvG6mXfvY= -github.com/marcelocantos/hash v0.2.0 h1:pHimAPlPACKciZw0VeMbj8qmca7VmG6w8fAuUOi9gZo= -github.com/marcelocantos/hash v0.2.0/go.mod h1:ZpakDB4Kjclkjg4f6wxrlINDjQ/Wxpky/0bvbwyET7A= +github.com/mattn/go-isatty v0.0.12 h1:wuysRhFDzyxgEmMf5xjvJ2M9dZoWAXNNr5LSBS7uHXY= +github.com/mattn/go-isatty v0.0.12/go.mod h1:cbi8OIDigv2wuxKPP5vlRcQ1OAZbq2CE4Kysco4FUpU= 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/sergi/go-diff v1.1.0 h1:we8PVUC3FE2uYfodKH/nBHMSetSfHDR6scGdBi+erh0= @@ -26,8 +34,8 @@ github.com/stretchr/testify v1.4.0 h1:2E4SXV/wtOkTonXsotYi4li6zVWxYlZuYNCXe9XRJy github.com/stretchr/testify v1.4.0/go.mod h1:j7eGeouHqKxXV5pUuKE4zz7dFj8WfuZ+81PSLYec5m4= golang.org/x/sys v0.0.0-20190422165155-953cdadca894/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs= golang.org/x/sys v0.0.0-20191204072324-ce4227a45e2e/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs= -golang.org/x/sys v0.0.0-20191220220014-0732a990476f h1:72l8qCJ1nGxMGH26QVBVIxKd/D34cfGt0OvrPtpemyY= -golang.org/x/sys v0.0.0-20191220220014-0732a990476f/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs= +golang.org/x/sys v0.0.0-20200116001909-b77594299b42 h1:vEOn+mP2zCOVzKckCZy6YsCtDblrpj/w7B9nxGNELpg= +golang.org/x/sys v0.0.0-20200116001909-b77594299b42/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs= gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0= gopkg.in/check.v1 v1.0.0-20190902080502-41f04d3bba15 h1:YR8cESwS4TdDjEe65xsg0ogRM/Nc3DYOhEAlW+xobZo= gopkg.in/check.v1 v1.0.0-20190902080502-41f04d3bba15/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0= diff --git a/log/api.go b/log/api.go index ba3d94d..611128b 100644 --- a/log/api.go +++ b/log/api.go @@ -3,29 +3,107 @@ package log import ( "context" - "github.com/anz-bank/pkg/log/loggers" + "github.com/arr-ai/frozen" ) -type loggerContextKey int +// Fields is a struct that contains all the fields data to log. +type Fields struct{ m frozen.Map } -const loggerKey loggerContextKey = iota +// From returns a copied logger from the context that you can use to access logger API. +func From(ctx context.Context) Logger { + f := getFields(ctx) + return f.getCopiedLogger().(internalLoggerOps).PutFields(f.resolveFields(ctx)) +} + +// Suppress will ensure that suppressed keys are not logged. +func Suppress(keys ...string) Fields { + return Fields{}.Suppress(keys...) +} + +// With creates a field with a single key value pair. +func With(key string, val interface{}) Fields { + return Fields{}.With(key, val) +} + +// WithCtxRef creates a field with a key that refers to the provided context key, +// fields will use key as the fields property and take the value that corresponds +// to ctxKey. +func WithCtxRef(key string, ctxKey interface{}) Fields { + return Fields{}.WithCtxRef(key, ctxKey) +} -// With adds a copy of the logger to the context -func With(ctx context.Context, logger loggers.Logger) context.Context { - return context.WithValue(ctx, loggerKey, logger.Copy()) +// WithFunc creates a field with a string key and a callback value. +func WithFunc(key string, f func(context.Context) interface{}) Fields { + return Fields{}.WithFunc(key, f) } -// WithFields adds multiple fields in the scope of the context, fields will be logged alphabetically -func WithFields(ctx context.Context, fields MultipleFields) context.Context { - return context.WithValue(ctx, loggerKey, - getCopiedLogger(ctx).PutFields(fromFields([]Fields{fields}))) +// WithLogger adds logger which will be used for the log operation. +func WithLogger(logger Logger) Fields { + return Fields{}.WithLogger(logger) } -// From is a way to access the API of the logger inside the context and add log-specific fields -func From(ctx context.Context, fields ...Fields) loggers.Logger { - logger := getCopiedLogger(ctx) - if len(fields) == 0 { - return logger +// Chain merges all the fields and returns the merged fields, the precedence +// of fields in case of overlapping gets higher from left to right. +func (f Fields) Chain(fieldses ...Fields) Fields { + merged := f.m + for _, fields := range fieldses { + merged = merged.Update(fields.m) } - return logger.PutFields(fromFields(fields)) + return Fields{merged} +} + +// From returns a logger with the new fields which is the fields from the context +// merged with the current fields were current fields replaces value from +// the context fields. +func (f Fields) From(ctx context.Context) Logger { + return From(f.Onto(ctx)) +} + +// Onto finishes fields operation, merge them all with the precedence of fields +// in case overlapping gets higher from left to right, and puts the merged fields +// in the context. +func (f Fields) Onto(ctx context.Context) context.Context { + return context.WithValue(ctx, fieldsContextKey{}, getFields(ctx).Chain(f).m) +} + +// Suppress ensures that the keys will not be logger. +func (f Fields) Suppress(keys ...string) Fields { + return f.Chain(Fields{ + frozen.NewMapFromKeys( + frozen.NewSetFromStrings(keys...), + func(_ interface{}) interface{} { + return suppress{} + }, + ), + }) +} + +// With adds to the fields a single key value pair. +func (f Fields) With(key string, val interface{}) Fields { + return f.with(key, val) +} + +// WithCtxRef adds key and the context key to the fields. +func (f Fields) WithCtxRef(key string, ctxKey interface{}) Fields { + return f.with(key, ctxRef{ctxKey}) +} + +// WithFunc adds key and the function to the fields. +func (f Fields) WithFunc(key string, val func(context.Context) interface{}) Fields { + return f.with(key, val) +} + +// WithLogger adds logger which will be used for the log operation. +func (f Fields) WithLogger(logger Logger) Fields { + return f.with(loggerKey{}, logger.(internalLoggerOps).Copy()) +} + +// String returns a string that represent the current fields +func (f Fields) String(ctx context.Context) string { + return f.resolveFields(ctx).String() +} + +// MergedString returns a string that represents the current fields merged by fields in context +func (f Fields) MergedString(ctx context.Context) string { + return getFields(ctx).Chain(f).String(ctx) } diff --git a/log/api_test.go b/log/api_test.go index 7c8f9bb..fdebc27 100644 --- a/log/api_test.go +++ b/log/api_test.go @@ -2,126 +2,206 @@ package log import ( "context" + "strconv" "testing" - "github.com/anz-bank/pkg/log/loggers" + "github.com/alecthomas/assert" "github.com/anz-bank/pkg/log/testutil" - "github.com/marcelocantos/frozen" - "github.com/stretchr/testify/assert" + "github.com/arr-ai/frozen" "github.com/stretchr/testify/mock" - "github.com/stretchr/testify/require" ) -func TestWithLogger(t *testing.T) { +type fieldsTest struct { + name string + unresolveds frozen.Map + contextFields frozen.Map + expected frozen.Map +} + +func TestChain(t *testing.T) { t.Parallel() - logger := loggers.NewMockLogger() - setMockCopyAssertion(logger) - With(context.Background(), logger) + init := Fields{generateSimpleField(5)} + fields1 := Fields{frozen.Map{}.With("6", 6).With("7", suppress{})} + fields2 := Fields{ + frozen.Map{}. + With("2", 10). + With("8", func(context.Context) interface{} { + return 8 + }), + } + fields3 := Fields{frozen.Map{}.With("7", 7).With("8", suppress{})} + expected := generateSimpleField(5). + With("2", 10). + With("6", 6). + With("7", 7). + With("8", suppress{}) - require.True(t, logger.AssertExpectations(t)) + assert.True(t, expected.Equal(init.Chain(fields1, fields2, fields3).m)) } -func TestWithFields(t *testing.T) { +func TestFrom(t *testing.T) { + for _, c := range getUnresolvedFieldsCases() { + c := c + t.Run(c.name, func(t *testing.T) { + t.Parallel() + + logger := newMockLogger() + setLogMockAssertion(logger, c.expected) + ctx := context.WithValue(context.Background(), fieldsContextKey{}, c.unresolveds.With(loggerKey{}, logger)) + for i := c.contextFields.Range(); i.Next(); { + ctx = context.WithValue(ctx, i.Key(), i.Value()) + } + From(ctx) + logger.AssertExpectations(t) + }) + } +} + +func TestOnto(t *testing.T) { cases := testutil.GenerateMultipleFieldsCases() for _, c := range cases { c := c - t.Run("TestWithFields"+" "+c.Name, func(tt *testing.T) { - tt.Parallel() + t.Run(c.Name, func(t *testing.T) { + t.Parallel() + + logger := newMockLogger() + setMockCopyAssertion(logger) - logger := loggers.NewMockLogger() - setLogSpecificFieldAssertion(logger, c.Fields) + fields := WithLogger(logger) + for i := c.Fields.Range(); i.Next(); { + fields = fields.With(i.Key().(string), i.Value()) + } + ctx := fields.Onto(context.Background()) - ctx := context.WithValue(context.Background(), loggerKey, logger) - WithFields(ctx, testutil.ConvertToGoMap(c.Fields)) - logger = ctx.Value(loggerKey).(*loggers.MockLogger) + logger = getLoggerFromContext(t, ctx) - assert.True(tt, logger.AssertExpectations(tt)) + logger.AssertExpectations(t) }) } } -func TestLogger(t *testing.T) { - tests := []struct { - name string - fields []Fields - }{ - { - name: "Empty fields", - fields: []Fields{}, +func TestSuppress(t *testing.T) { + runFieldsMethod( + t, + func(t *testing.T) { + t.Parallel() + + assert.True(t, + frozen.NewMapFromKeys( + generateSimpleField(3).Keys(), + func(_ interface{}) interface{} { + return suppress{} + }, + ). + Equal(Suppress("0", "1", "2").m), + ) }, - { - name: "Single fields only", - fields: []Fields{ - NewField("test", 1), - NewField("test again", 2), - NewField("another test", 3), - }, + func(t *testing.T) { + t.Parallel() + + initial := generateSimpleField(5) + + expected := generateSimpleField(5). + With("2", suppress{}). + With("4", suppress{}). + With("5", suppress{}) + + assert.True(t, expected.Equal(Fields{initial}.Suppress("2", "4", "5").m)) }, - { - name: "Multiple fields only", - fields: []Fields{ - FromMap( - map[string]interface{}{ - "test": '1', - "test2": 2, - }, - ), - FromMap( - map[string]interface{}{ - "test3": 3, - "test4": 4, - }, - ), - }, + ) +} + +func TestWith(t *testing.T) { + runFieldsMethod(t, + func(t *testing.T) { + t.Parallel() + + assert.True(t, + generateSimpleField(5). + Equal( + With("0", 0). + With("1", 1). + With("2", 2). + With("3", 3). + With("4", 4).m), + ) }, - { - name: "Mixed Fields", - fields: []Fields{ - NewField("test", 1), - FromMap( - map[string]interface{}{ - "test3": 3, - "test4": 4, - }, - ), - NewField("another test", 2), - }, + func(t *testing.T) { + t.Parallel() + + simpleField := generateSimpleField(5) + expected := simpleField.With("1", 4).With("2", 5) + assert.True(t, expected.Equal(Fields{simpleField}.With("1", 4).With("2", 5).m)) }, - } + ) +} - for _, ts := range tests { - ts := ts - t.Run(ts.name, func(tt *testing.T) { - tt.Parallel() +func TestWithCtxRef(t *testing.T) { + t.Parallel() - logger := loggers.NewMockLogger() - setLogSpecificFieldAssertion(logger, fromFields(ts.fields)) + f := WithCtxRef("key1", key1{}).WithCtxRef("key2", key2{}).WithCtxRef("key3", key3{}) - ctx := context.WithValue(context.Background(), loggerKey, logger) - From(ctx, ts.fields...) - assert.True(tt, logger.AssertExpectations(tt)) - }) + for i := f.m.Range(); i.Next(); { + assert.IsType(t, ctxRef{}, i.Value()) } } -func setLogSpecificFieldAssertion(logger *loggers.MockLogger, fields frozen.Map) { - logger.On("Copy").Return(logger) - if fields.Count() != 0 { - logger.On( - "PutFields", - mock.MatchedBy( - func(arg frozen.Map) bool { - return fields.Equal(arg) - }, - ), - ).Return(logger) +func TestWithLogger(t *testing.T) { + t.Parallel() + + logger := newMockLogger() + setMockCopyAssertion(logger) + WithLogger(logger).Onto(context.Background()) + + logger.AssertExpectations(t) +} + +func setLogMockAssertion(logger *mockLogger, fields frozen.Map) { + setMockCopyAssertion(logger) + logger.On( + "PutFields", + mock.MatchedBy( + func(arg frozen.Map) bool { + return fields.Equal(arg) + }, + ), + ).Return(logger) +} + +func getLoggerFromContext(t *testing.T, ctx context.Context) *mockLogger { + m, exists := ctx.Value(fieldsContextKey{}).(frozen.Map) + if !exists { + t.Fatal("Fields not set yet") } + return m.MustGet(loggerKey{}).(*mockLogger) } -func setMockCopyAssertion(logger *loggers.MockLogger) { +func setMockCopyAssertion(logger *mockLogger) { // set to return the same logger for testing purposes, in real case it will return // a copied logger. Tests that use these usually are not checked for their return value // as the return value is mocked logger.On("Copy").Return(logger) } + +func runFieldsMethod(t *testing.T, empty, nonEmpty func(*testing.T)) { + t.Run("empty fields", empty) + t.Run("non empty fields", nonEmpty) +} + +func generateSimpleField(limit int) frozen.Map { + keys := make([]string, 0, limit) + for i := 0; i < limit; i++ { + keys = append(keys, strconv.Itoa(i)) + } + return frozen.NewMapFromKeys( + frozen.NewSetFromStrings(keys...), + func(a interface{}) interface{} { + num, err := strconv.Atoi(a.(string)) + if err != nil { + panic("not a number") + } + return num + }, + ) +} diff --git a/log/benchmark/benchmark_test.go b/log/benchmark/benchmark_test.go new file mode 100644 index 0000000..f1a9b1b --- /dev/null +++ b/log/benchmark/benchmark_test.go @@ -0,0 +1,77 @@ +package log + +import ( + "bytes" + "context" + "strconv" + "testing" + + "github.com/anz-bank/pkg/log" + "github.com/anz-bank/pkg/log/loggers" + "github.com/sirupsen/logrus" +) + +func BenchmarkLog5Fields(b *testing.B) { + runBenchmark(b, 5) +} + +func BenchmarkLog10Fields(b *testing.B) { + runBenchmark(b, 10) +} + +func BenchmarkLog50Fields(b *testing.B) { + runBenchmark(b, 50) +} + +func BenchmarkLog100Fields(b *testing.B) { + runBenchmark(b, 100) +} + +func BenchmarkLog1000Fields(b *testing.B) { + runBenchmark(b, 1000) +} + +func BenchmarkWith(b *testing.B) { + logger := loggers.NewNullLogger() + ctx := log.With("key", "val").With("abc", 123).WithLogger(logger).Onto(context.Background()) + + for i := 0; i < b.N; i++ { + log.With("foo", "bar"). + With("hello", "world"). + With("myvar", "myval"). + With("this", "that"). + Onto(ctx) + } +} + +func BenchmarkLogrus(b *testing.B) { + logger := logrus.New() + logger.SetOutput(&bytes.Buffer{}) + logger.SetReportCaller(true) + + for i := 0; i < b.N; i++ { + logger.Info("TestMsg") + } +} + +func BenchmarkLog(b *testing.B) { + logger := loggers.NewNullLogger() + ctx := log.With("x-user-id", "12344"). + With("x-trace-id", "acbdd"). + WithLogger(logger). + Onto(context.Background()) + + for i := 0; i < b.N; i++ { + log.From(ctx).Info("TestMsg") + } +} + +func runBenchmark(b *testing.B, l int) { + for i := 0; i < b.N; i++ { + var f log.Fields + for j := 0; j < l; j++ { + f = f.With(strconv.Itoa(j), j) + } + f.WithLogger(loggers.NewNullLogger()).From(context.Background()).Info("test") + } +} diff --git a/log/examples.md b/log/examples.md index 9d8c7eb..d7ff798 100644 --- a/log/examples.md +++ b/log/examples.md @@ -2,6 +2,8 @@ ## Setup +Adding logger to the context + ```go package main @@ -13,125 +15,139 @@ import ( ) func main() { - // User is expected to choose a logger and add it to the context using the library's API ctx := context.Background() - - // this is a logger based on the logrus standard logger logger := loggers.NewStandardLogger() - // With returns a new context - ctx = log.With(ctx, logger) + // This adds logger to the context. + // Trying to log without a logger inside the context will make it panic. + ctx = log.WithLogger(logger).Onto(ctx) + + // Since logger is treated as fields you can also do this while adding fields. + // You need to ensure that logger exist in the context or the fields + // you are about to add to context (more about fields in the next section). + ctx = log.With("key", "value").WithLogger(ctx).Onto(ctx) } ``` -That's all in setup, now logging can be used by using the context. +## Fields -## Usage +Fields are key value pair information that will be logged along with the log +message. ```go -import ( - "github.com/anz-bank/pkg/log" -) - -func stuffToLog(ctx context.Context) { - // logging requires the context variable so it must be given to any function that requires it - log.From(ctx).Debug("Debug") - log.From(ctx).Trace("Trace") - log.From(ctx).Warn("Warn") - log.From(ctx).Error("Error") - log.From(ctx).Fatal("Fatal") - log.From(ctx).Panic("Panic") - - // Expected to log - // (time in RFC3339Nano Format) (Level) (Message) - // - // Example: - // 2019-12-12T08:23:59.210878+11:00 PRINT Hello There - // - // Each API also has its Format counterpart (Debugf, Printf, Tracef, Warnf, Errorf, Fatalf, Panicf) +func fieldsDemo(ctx context.Context) { + // In this library, fields are treated as an object that you can + // manipulate and add to the context when ready, there are three + // kinds of fields you can add. + + // With adds a regular key value pair. + fields := log.With("hello", "world") + + // WithCtxRef adds a key whose value will be taken from the context + // before logging. You have to define an alias to the key which will + // be used during logging as context key are usually a struct or iota + // which has no information about it when logged. If the key does not + // exist in the context, it will not be logged. + fields = fields.WithCtxRef("my alias", contextKey{}) + + // WithFunc adds a key and a function with a context argument which + // will be called before logging. If the result of the function is + // nil, it will not be logged. + ctx = context.WithValue(ctx, "bar", 42) + fields = fields.WithFunc("foo", func(ctx context.Context) interface{} { + return ctx.Value("bar") + }) + ctx = context.WithValue(ctx, contextKey{}, "now exist in context") + + // Fields operation can also be chained either by the With APIs or Chain API. + // An important thing to note is that fields operation always merge with the + // previous fields, but when key overlaps, the newest fields will always replace + // the overlapping keys. This means, in a chain operation or Chain API, the precedence + // gets higher from left to right. + + // In this example, the final fields will have ("test": "test four") instead of ("test": "test too"). + fields = fields. + With("test", "test too"). + WithCtxRef("test three", contextKey2{}). + WithFunc("doesn't", func(context.Context) interface{} { + return "matter" + }). + With("test", "test four") + + // The final fields will have ("out of": "things to write") + fields1 := log.With("I'm", "running") + fields2 := log.With("out of", "examples") + fields3 := log.With("out of", "things to write") + fields = fields.Chain(fields1, fields2, fields3) + + // Fields are also immutable so it will be thread-safe. Adding fields + // to the context can be done using the Onto API which returns a context + // that contains the fields. Onto will merge instead of replacing the fields. + ctx = fields.Onto(ctx) + + // If you would like to suppress certain fields, you can use the Suppress API. + // Just give it the keys that you would like to not be logged and it will ensure + // that fields will be ignored during logging. + fields = fields.Suppress("test", "doesn't") + + // Remember to finalize it with Onto if you want to remove it from the context. If you + // would like to use it just for specific log, you don't need to finalize it. + // If you want to unsuppress a value, you would have to add the value back using the With API. + ctx = fields.Onto(ctx) + + // If you do not want to put the fields in the context, you can also just generate + // a logger that contains all the fields with the From method. The logger will always + // merge your current fields with the fields the context contains. But you need to make sure + // that logger has been added. Logger is treated as another fields, so you can just chain it + // with the WithLogger API. Trying to generate a logger without setting up the logger will make the + // program panic. More about logging in another function. + logger1, logger2 := loggers.NewNullLogger(), loggers.NewStandardLogger() + + // Creating a context that contains logger1. + ctx = log.WithLogger(logger1).Onto(ctx) + + // Since logger is treated like fields, this log will use logger2 instead due to higher precedence. + fields.With("additional", "fields").WithLogger(logger2).From(ctx).Info("Logging additional fields with logger2") + + // You can also just log directly from context. Logger will always take the fields + // from context before logging. + log.From(ctx).Info("Since this uses logger1 which is a null logger, this will not be logged") } ``` -Fields are also supported in the logging. There are two kinds of fields, context-level fields and log-level fields. +## Logging -```go -import ( - "github.com/anz-bank/pkg/log" -) - - -// With fields, it is expected to log -// (time in RFC3339Nano Format) (Fields) (Level) (Message) -// -// Fields will be logged alphabetically (using the StandardLogger). If the same key field is added to the context logger, -// it will replace the existing value that corresponds to that key. -// -// Example: -// 2019-12-12T08:23:59.210878+11:00 random=stuff very=random PRINT Hello There -// -// Each API also has its Format counterpart (Debugf, Printf, Tracef, Warnf, Errorf, Fatalf, Panicf) - - -func logWithField(ctx context.Context) { - // context-level field adds fields to the context and creates a new context - ctx = log.WithFields(ctx, map[string]interface{}{ - "just": "stuff", - "stuff": 1, - }) - - // or - ctx = log.WithFields(ctx, MultipleFields{ - "just": "stuff", - "stuff": 1, - }) - - // Any log at this point will have fields and to any function that uses the same context - // just=stuff random=stuff stuff=1 - contextLevelField(ctx) - logLevelField(ctx) -} - -func contextLevelField(ctx context.Context) { - // This is expected to log something like - // 2019-12-12T08:23:59.210878+11:00 just=stuff random=stuff stuff=1 WARN Warn - log.From(ctx).Warn("Warn") -} +Logging can be done through the `From` API. -func logLevelField(ctx context.Context) { - - // Log level fields are fields that are not stored into the context logger - // Log level fields will add fields on top of the existing context level fields - // If an existing key exists in the stored field, it will replace the value - // This is expected to log something like - // 2019-12-12T08:23:59.210878+11:00 just=stuff more=random stuff random=stuff stuff=1 very=random WARN Warn - - - // You can add multiple fields at once through FromMap API or just use MultipleFields struct - log.From(ctx, - log.FromMap(map[string]interface{}{ - "more": "random stuff", - "very": "random", - }, - )).Warn("Warn") - - // or - - log.From( - ctx, - log.MultipleFields{ - "more": "random stuff", - "very": "random", - }, - ).Warn("Warn") - - // You can also add single field through the API NewField - log.From(ctx, - log.NewField("more", "random stuff"), - log.NewField("very", "random"), - ).Warn("Warn") - - // As long as context logger is not modified, it will log again only the context level fields - contextLevelField(ctx) +```go +func loggingDemo(ctx context.Context) { + // You can choose different loggers or implement your own. + // For this example, we are using the standard logger. + logger := loggers.NewStandardLogger() + + // Adding logger can be done through the WithLogger API. Do not forget to finalize it with + // the Onto API if you want the logger to be contained in the context. + ctx = log.WithLogger(logger).Onto(ctx) + + // Logging from the context can be done using the From API which will take the logger + // from the context and take any fields contained in the context and get them logged + // by the logger. There are two levels of logging, Debug and Info. Each will also have + // the format counterpart, Debugf and Infof. + // Logging will log in the following format: + // (time in RFC3339Nano Format) (Fields) (Level) (Message) + // Fields themselves are logged as a space separated list of key=value + log.From(ctx).Debug("This does not have any fields") + + ctx = log.With("this", "one").With("have", "fields").Onto(ctx) + log.From(ctx).Info("log with fields") + + // Sometimes, you might like to log with additional fields and not have to add them to the + // context. This can be done with the From method which generates Logger with the + // context fields merged with additional fields. Additional fields of course have higher + // precedence and will replace context fields when keys overlap. But since the fields + // is not added to the context, context fields will be untouched. + log.With("have", "additional fields").With("log-specific", "fields").From(ctx).Debug("log-specific fields") + log.From(ctx).Info("context fields are still untouched as long as the context is unchanged") } ``` diff --git a/log/examples/example.go b/log/examples/example.go index c6c7dc0..6a1d6c7 100644 --- a/log/examples/example.go +++ b/log/examples/example.go @@ -2,100 +2,133 @@ package main import ( "context" + "fmt" "github.com/anz-bank/pkg/log" "github.com/anz-bank/pkg/log/loggers" ) +type contextKey struct{} +type contextKey2 struct{} + func main() { - // User is expected to choose a logger and add it to the context using the library's API ctx := context.Background() - - // this is a logger based on the logrus standard logger - logger := loggers.NewStandardLogger() - - // With returns a new context - ctx = log.With(ctx, logger) - - logLevelsDemo(ctx) - logWithFieldsDemo(ctx) + fieldsDemo(ctx) + loggingDemo(ctx) } -func logLevelsDemo(ctx context.Context) { - // logging requires the context variable so it must be given to any function that requires it - log.From(ctx).Debug("Debug") - log.From(ctx).Trace("Trace") - log.From(ctx).Warn("Warn") - log.From(ctx).Error("Error") - - // commented so it does not block the demo - // log.From(ctx).Fatal("Fatal") - // log.From(ctx).Panic("Panic") - - // Expected to log - // (time in RFC3339Nano Format) (Level) (Message) - // - // Example: - // 2019-12-12T08:23:59.210878+11:00 PRINT Hello There - // - // Each API also has its Format counterpart (Debugf, Printf, Tracef, Warnf, Errorf, Fatalf, Panicf) +func fieldsDemo(ctx context.Context) { + // In this library, fields are treated as an object that you can + // manipulate and add to the context when ready, there are three + // kinds of fields you can add. + + // With adds a regular key value pair. + fields := log.With("hello", "world") + + // WithCtxRef adds a key whose value will be taken from the context + // before logging. You have to define an alias to the key which will + // be used during logging as context key are usually a struct or iota + // which has no information about it when logged. If the key does not + // exist in the context, it will not be logged. + fields = fields.WithCtxRef("my alias", contextKey{}) + + // WithFunc adds a key and a function with a context argument which + // will be called before logging. If the result of the function is + // nil, it will not be logged. + ctx = context.WithValue(ctx, "bar", 42) + fields = fields.WithFunc("foo", func(ctx context.Context) interface{} { + return ctx.Value("bar") + }) + fmt.Printf("Current Fields after using the With API: %s\n", fields.String(ctx)) + ctx = context.WithValue(ctx, contextKey{}, "now exist in context") + fmt.Printf("Current Fields after using the With API and adding my alias to context: %s\n", fields.String(ctx)) + + // Fields operation can also be chained either by the With APIs or Chain API. + // An important thing to note is that fields operation always merge with the + // previous fields, but when key overlaps, the newest fields will always replace + // the overlapping keys. This means, in a chain operation or Chain API, the precedence + // gets higher from left to right. + + // In this example, the final fields will have ("test": "test four") instead of ("test": "test too"). + fields = fields. + With("test", "test too"). + WithCtxRef("test three", contextKey2{}). + WithFunc("doesn't", func(context.Context) interface{} { + return "matter" + }). + With("test", "test four") + + // The final fields will have ("out of": "things to write") + fields1 := log.With("I'm", "running") + fields2 := log.With("out of", "examples") + fields3 := log.With("out of", "things to write") + fields = fields.Chain(fields1, fields2, fields3) + fmt.Printf("Current Fields after chaining: %s\n", fields.String(ctx)) + + // Fields are also immutable so it will be thread-safe. Adding fields + // to the context can be done using the Onto API which returns a context + // that contains the fields. Onto will merge instead of replacing the fields. + ctx = fields.Onto(ctx) + fmt.Printf("Current Fields in context: %s\n", log.Fields{}.MergedString(ctx)) + + // If you would like to suppress certain fields, you can use the Suppress API. + // Just give it the keys that you would like to not be logged and it will ensure + // that fields will be ignored during logging. + fields = fields.Suppress("test", "doesn't") + fmt.Printf("Suppressing: %s\n", fields.String(ctx)) + + // Remember to finalize it with Onto if you want to remove it from the context. If you + // would like to use it just for specific log, you don't need to finalize it. + // If you want to unsuppress a value, you would have to add the value back using the With API. + fmt.Printf("Current fields in context before finalizing the suppressed fields: %s\n", log.Fields{}.MergedString(ctx)) + ctx = fields.Onto(ctx) + fmt.Printf("Current Fields in context after suppressing: %s\n", log.Fields{}.MergedString(ctx)) + + // If you do not want to put the fields in the context, you can also just generate + // a logger that contains all the fields with the From method. The logger will always + // merge your current fields with the fields the context contains. But you need to make sure + // that logger has been added. Logger is treated as another fields, so you can just chain it + // with the WithLogger API. Trying to generate a logger without setting up the logger will make the + // program panic. More about logging in another function. + logger1, logger2 := loggers.NewNullLogger(), loggers.NewStandardLogger() + + // Creating a context that contains logger1. + ctx = log.WithLogger(logger1).Onto(ctx) + + // Since logger is treated like fields, this log will use logger2 instead due to higher precedence. + fields.With("additional", "fields").WithLogger(logger2).From(ctx).Info("Logging additional fields with logger2") + + // You can also just log directly from context. Logger will always take the fields + // from context before logging. + log.From(ctx).Info("Since this uses logger1 which is a null logger, this will not be logged") } -func logWithFieldsDemo(ctx context.Context) { - // context-level field adds fields to the context and creates a new context - ctx = log.WithFields(ctx, map[string]interface{}{ - "just": "stuff", - "stuff": 1, - }) - - // or alternatively - // ctx = log.WithFields(ctx, MultipleFields{ - // "just": "stuff", - // "stuff": 1 - // }) - - // Any log at this point will have fields and to any function that uses the same context - // just=stuff random=stuff stuff=1 - contextLevelField(ctx) - logLevelField(ctx) -} +func loggingDemo(ctx context.Context) { + // You can choose different loggers or implement your own. + // For this example, we are using the standard logger. + logger := loggers.NewStandardLogger() -func contextLevelField(ctx context.Context) { - // This is expected to log something like - // 2019-12-12T08:23:59.210878+11:00 just=stuff random=stuff stuff=1 WARN Warn - log.From(ctx).Warn("Warn") + // Adding logger can be done through the WithLogger API. Do not forget to finalize it with + // the Onto API if you want the logger to be contained in the context. + ctx = log.WithLogger(logger).Onto(ctx) + + // Logging from the context can be done using the From API which will take the logger + // from the context and take any fields contained in the context and get them logged + // by the logger. There are two levels of logging, Debug and Info. Each will also have + // the format counterpart, Debugf and Infof. + // Logging will log in the following format: + // (time in RFC3339Nano Format) (Fields) (Level) (Message) + // Fields themselves are logged as a space separated list of key=value + log.From(ctx).Debug("This does not have any fields") + + ctx = log.With("this", "one").With("have", "fields").Onto(ctx) + log.From(ctx).Info("log with fields") + + // Sometimes, you might like to log with additional fields and not have to add them to the + // context. This can be done with the From method which generates Logger with the + // context fields merged with additional fields. Additional fields of course have higher + // precedence and will replace context fields when keys overlap. But since the fields + // is not added to the context, context fields will be untouched. + log.With("have", "additional fields").With("log-specific", "fields").From(ctx).Debug("log-specific fields") + log.From(ctx).Info("context fields are still untouched as long as the context is unchanged") } - -func logLevelField(ctx context.Context) { - // Log level fields are fields that are not stored into the context logger - // Log level fields will add fields on top of the existing context level fields - // If an existing key exists in the stored field, it will replace the value - // This is expected to log something like - // 2019-12-12T08:23:59.210878+11:00 just=stuff more=random stuff random=stuff stuff=1 very=random WARN Warn - - // You can add multiple fields at once through FromMap API or just use MultipleFields struct - log.From(ctx, - log.FromMap(map[string]interface{}{ - "more": "random stuff", - "very": "random", - }, - )).Warn("Warn") - - // or alternatively - // log.From( - // ctx, - // log.MultipleFields{ - // "more": "random stuff", - // "very": "random", - // }, - // ).Warn("Warn") - - // You can also add single field through the API NewField - // log.From(ctx, - // log.NewField("more", "random stuff"), - // log.NewField("very", "random"), - // ).Warn("Warn") - - // since context logger is not modified, it will log again only the context level fields - contextLevelField(ctx) -} \ No newline at end of file diff --git a/log/field.go b/log/field.go deleted file mode 100644 index 81a2e69..0000000 --- a/log/field.go +++ /dev/null @@ -1,39 +0,0 @@ -package log - -import "github.com/marcelocantos/frozen" - -// Fields is an interface that represents a collection of key values -type Fields interface { - GetKeyValues() []frozen.KeyValue -} - -// SingleField represents a single key value -type SingleField struct { - key string - value interface{} -} - -// MultipleFields is a type for map of string to interface, meant for type checking -// you can use FromMap to create it or directly use MultipleFields{} -type MultipleFields map[string]interface{} - -// NewField creates a Fields interface representing a single key value -func NewField(key string, value interface{}) Fields { - return &SingleField{key: key, value: value} -} - -func (sf *SingleField) GetKeyValues() []frozen.KeyValue { - return []frozen.KeyValue{frozen.KV(sf.key, sf.value)} -} - -func FromMap(m map[string]interface{}) Fields { - return MultipleFields(m) -} - -func (mf MultipleFields) GetKeyValues() []frozen.KeyValue { - keyVals := []frozen.KeyValue{} - for k, v := range mf { - keyVals = append(keyVals, frozen.KV(k, v)) - } - return keyVals -} diff --git a/log/loggerInterface.go b/log/loggerInterface.go new file mode 100644 index 0000000..6f2654a --- /dev/null +++ b/log/loggerInterface.go @@ -0,0 +1,22 @@ +package log + +import "github.com/arr-ai/frozen" + +// Logger is the underlying logger that is to be added to a context +type Logger interface { + // Debug logs the message at the Debug level + Debug(args ...interface{}) + // Debugf logs the message at the Debug level + Debugf(format string, args ...interface{}) + // Info logs the message at the Info level + Info(args ...interface{}) + // Infof logs the message at the Info level + Infof(format string, args ...interface{}) +} + +type internalLoggerOps interface { + // PutFields returns the Logger with the new fields added + PutFields(fields frozen.Map) Logger + // Copy returns a logger whose data is copied from the caller + Copy() Logger +} diff --git a/log/loggers/loggerInterface.go b/log/loggers/loggerInterface.go deleted file mode 100644 index 8d17ce0..0000000 --- a/log/loggers/loggerInterface.go +++ /dev/null @@ -1,39 +0,0 @@ -package loggers - -import "github.com/marcelocantos/frozen" - -// Logger is the underlying logger that is to be added to a context -type Logger interface { - // Debug logs the message at the Debug level - Debug(args ...interface{}) - // Debugf logs the message at the Debug level - Debugf(format string, args ...interface{}) - // Error logs the message at the Error level - Error(args ...interface{}) - // Errorf logs the message at the Error level - Errorf(format string, args ...interface{}) - // Exit exits the program with specified code - Exit(code int) - // Fatal logs the message at the Fatal level and exits the program with code 1 - Fatal(args ...interface{}) - // Fatalf logs the message at the Fatal level and exits the program with code 1 - Fatalf(format string, args ...interface{}) - // Panic logs the message at the Panic level - Panic(args ...interface{}) - // Panicf logs the message at the Panic level - Panicf(format string, args ...interface{}) - // Trace logs the message at the Trace level - Trace(args ...interface{}) - // Tracef logs the message at the Trace level - Tracef(format string, args ...interface{}) - // Warn logs the message at the Warn level - Warn(args ...interface{}) - // Warnf logs the message at the Warn level - Warnf(format string, args ...interface{}) - // PutField returns the Logger with the new field added - PutField(key string, val interface{}) Logger - // PutFields returns the Logger with the new fields added - PutFields(fields frozen.Map) Logger - // Copy returns a logger whose data is copied from the caller - Copy() Logger -} diff --git a/log/loggers/mockLogger.go b/log/loggers/mockLogger.go deleted file mode 100644 index 0748e83..0000000 --- a/log/loggers/mockLogger.go +++ /dev/null @@ -1,80 +0,0 @@ -package loggers - -import ( - "github.com/marcelocantos/frozen" - "github.com/stretchr/testify/mock" -) - -// MockLogger is a mock interface for testing the main API, not for use -type MockLogger struct { - Logger - mock.Mock -} - -func NewMockLogger() *MockLogger { - return &MockLogger{} -} - -func (m *MockLogger) Debug(args ...interface{}) { - m.Called(args...) -} - -func (m *MockLogger) Debugf(format string, args ...interface{}) { - m.Called(append([]interface{}{format}, args...)...) -} - -func (m *MockLogger) Error(args ...interface{}) { - m.Called(args...) -} - -func (m *MockLogger) Errorf(format string, args ...interface{}) { - m.Called(append([]interface{}{format}, args...)...) -} - -func (m *MockLogger) Exit(code int) { - m.Called(code) -} - -func (m *MockLogger) Fatal(args ...interface{}) { - m.Called(args...) -} - -func (m *MockLogger) Fatalf(format string, args ...interface{}) { - m.Called(append([]interface{}{format}, args...)...) -} - -func (m *MockLogger) Panic(args ...interface{}) { - m.Called(args...) -} - -func (m *MockLogger) Panicf(format string, args ...interface{}) { - m.Called(append([]interface{}{format}, args...)...) -} - -func (m *MockLogger) Trace(args ...interface{}) { - m.Called(args...) -} - -func (m *MockLogger) Tracef(format string, args ...interface{}) { - m.Called(append([]interface{}{format}, args...)...) -} - -func (m *MockLogger) Warn(args ...interface{}) { - m.Called(args...) -} - -func (m *MockLogger) Warnf(format string, args ...interface{}) { - m.Called(append([]interface{}{format}, args...)...) -} - -func (m *MockLogger) PutField(key string, val interface{}) Logger { - return m.Called(key, val).Get(0).(Logger) -} - -func (m *MockLogger) PutFields(fields frozen.Map) Logger { - return m.Called(fields).Get(0).(Logger) -} - -func (m *MockLogger) Copy() Logger { - return m.Called().Get(0).(Logger) -} diff --git a/log/loggers/nullLogger.go b/log/loggers/nullLogger.go new file mode 100644 index 0000000..007420f --- /dev/null +++ b/log/loggers/nullLogger.go @@ -0,0 +1,49 @@ +package loggers + +import ( + "bytes" + + "github.com/anz-bank/pkg/log" + "github.com/arr-ai/frozen" +) + +type nullLogger struct { + internal *standardLogger +} + +func NewNullLogger() log.Logger { + return &nullLogger{internal: setUpLogger()} +} + +func (n *nullLogger) Debug(args ...interface{}) { + n.internal.Debug(args...) +} + +func (n *nullLogger) Debugf(format string, args ...interface{}) { + n.internal.Debugf(format, args...) +} + +func (n *nullLogger) Info(args ...interface{}) { + n.internal.Info(args...) +} + +func (n *nullLogger) Infof(format string, args ...interface{}) { + n.internal.Infof(format, args...) +} + +func (n *nullLogger) PutFields(fields frozen.Map) log.Logger { + n.internal.fields = fields + return n +} + +func (n *nullLogger) Copy() log.Logger { + return &nullLogger{ + setUpLogger().PutFields(n.internal.fields).(*standardLogger), + } +} + +func setUpLogger() *standardLogger { + logger := NewStandardLogger().(*standardLogger) + logger.internal.SetOutput(&bytes.Buffer{}) + return logger +} diff --git a/log/loggers/standardLogger.go b/log/loggers/standardLogger.go index c977b27..2454665 100644 --- a/log/loggers/standardLogger.go +++ b/log/loggers/standardLogger.go @@ -3,20 +3,19 @@ package loggers import ( "fmt" "os" - "sort" "strings" "time" - "github.com/marcelocantos/frozen" + "github.com/anz-bank/pkg/log" + "github.com/arr-ai/frozen" "github.com/sirupsen/logrus" ) const keyFields = "_fields" type standardLogger struct { - fields frozen.Map - sortedFields []string - internal *logrus.Logger + internal *logrus.Logger + fields frozen.Map } type standardFormat struct{} @@ -45,14 +44,8 @@ func (sf *standardFormat) Format(entry *logrus.Entry) ([]byte, error) { } // NewStandardLogger returns a logger with logrus standard logger as the internal logger -func NewStandardLogger() Logger { - logger := setupStandardLogger() - - return &standardLogger{ - fields: frozen.NewMap(), - sortedFields: []string{}, - internal: logger, - } +func NewStandardLogger() log.Logger { + return &standardLogger{internal: setupStandardLogger()} } func (sl *standardLogger) Debug(args ...interface{}) { @@ -63,82 +56,21 @@ func (sl *standardLogger) Debugf(format string, args ...interface{}) { sl.setInfo().Debugf(format, args...) } -func (sl *standardLogger) Error(args ...interface{}) { - sl.setInfo().Error(args...) -} - -func (sl *standardLogger) Errorf(format string, args ...interface{}) { - sl.setInfo().Errorf(format, args...) -} - -func (sl *standardLogger) Exit(code int) { - sl.internal.Exit(code) -} - -func (sl *standardLogger) Fatal(args ...interface{}) { - sl.setInfo().Fatal(args...) -} - -func (sl *standardLogger) Fatalf(format string, args ...interface{}) { - sl.setInfo().Fatalf(format, args...) -} - -func (sl *standardLogger) Panic(args ...interface{}) { - sl.setInfo().Panic(args...) -} - -func (sl *standardLogger) Panicf(format string, args ...interface{}) { - sl.setInfo().Panicf(format, args...) -} - -func (sl *standardLogger) Trace(args ...interface{}) { - sl.setInfo().Trace(args...) +func (sl *standardLogger) Info(args ...interface{}) { + sl.setInfo().Info(args...) } -func (sl *standardLogger) Tracef(format string, args ...interface{}) { - sl.setInfo().Tracef(format, args...) +func (sl *standardLogger) Infof(format string, args ...interface{}) { + sl.setInfo().Infof(format, args...) } -func (sl *standardLogger) Warn(args ...interface{}) { - sl.setInfo().Warn(args...) -} - -func (sl *standardLogger) Warnf(format string, args ...interface{}) { - sl.setInfo().Warnf(format, args...) -} - -func (sl *standardLogger) PutField(key string, val interface{}) Logger { - if !sl.fields.Has(key) { - sl.insertFieldsKey(key) - } - sl.fields = sl.fields.With(key, val) - return sl -} - -func (sl *standardLogger) PutFields(fields frozen.Map) Logger { - if fields.Count() == 0 { - panic("fields can not be empty") - } - - keys := make([]string, fields.Count()) - index := 0 - for i := fields.Keys().Range(); i.Next(); { - if !sl.fields.Has(i.Value()) { - keys[index] = i.Value().(string) - index++ - } - sl.fields = sl.fields.With(i.Value(), fields.MustGet(i.Value())) - } - if index > 0 { - sl.insertFieldsKey(keys[:index]...) - } +func (sl *standardLogger) PutFields(fields frozen.Map) log.Logger { + sl.fields = fields return sl } -func (sl *standardLogger) insertFieldsKey(fields ...string) { - newFields := append(sl.sortedFields, fields...) - sort.Strings(newFields) - sl.sortedFields = newFields +func (sl *standardLogger) Copy() log.Logger { + return &standardLogger{setupStandardLogger(), sl.fields} } func (sl *standardLogger) setInfo() *logrus.Entry { @@ -154,32 +86,21 @@ func (sl *standardLogger) getFormattedField() string { } fields := strings.Builder{} - fields.WriteString(fmt.Sprintf("%s=%v", sl.sortedFields[0], sl.fields.MustGet(sl.sortedFields[0]))) - if sl.fields.Count() > 1 { - for _, field := range sl.sortedFields[1:] { - fields.WriteString(fmt.Sprintf(" %s=%v", field, sl.fields.MustGet(field))) - } + i := sl.fields.Range() + i.Next() + fields.WriteString(fmt.Sprintf("%v=%v", i.Key(), i.Value())) + for i.Next() { + fields.WriteString(fmt.Sprintf(" %v=%v", i.Key(), i.Value())) } return fields.String() } -func (sl *standardLogger) Copy() Logger { - sortedFields := make([]string, sl.fields.Count()) - copy(sortedFields, sl.sortedFields) - - return &standardLogger{ - fields: frozen.NewMapFromKeys(sl.fields.Keys(), sl.fields.MustGet), - internal: setupStandardLogger(), - sortedFields: sortedFields, - } -} - func setupStandardLogger() *logrus.Logger { logger := logrus.New() logger.SetFormatter(&standardFormat{}) // makes sure that it always logs every level - logger.SetLevel(logrus.TraceLevel) + logger.SetLevel(logrus.DebugLevel) // explicitly set it to os.Stderr logger.SetOutput(os.Stderr) diff --git a/log/loggers/standardLogger_test.go b/log/loggers/standardLogger_test.go index ff2f92e..3ec23d0 100644 --- a/log/loggers/standardLogger_test.go +++ b/log/loggers/standardLogger_test.go @@ -1,12 +1,11 @@ package loggers import ( - "sort" "strings" "testing" "github.com/anz-bank/pkg/log/testutil" - "github.com/marcelocantos/frozen" + "github.com/arr-ai/frozen" "github.com/sirupsen/logrus" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" @@ -22,6 +21,7 @@ var testField = testutil.GenerateMultipleFieldsCases()[0].Fields func TestCopyStandardLogger(t *testing.T) { t.Parallel() + logger := getNewStandardLogger().PutFields( frozen.NewMap( frozen.KV("numberVal", 1), @@ -32,8 +32,6 @@ func TestCopyStandardLogger(t *testing.T) { copiedLogger := logger.Copy().(*standardLogger) assert.NotEqual(t, logger.internal, copiedLogger.internal) assert.True(t, logger.fields.Equal(copiedLogger.fields)) - assert.Equal(t, logger.sortedFields, copiedLogger.sortedFields) - assert.True(t, sort.StringsAreSorted(logger.sortedFields)) assert.True(t, logger != copiedLogger) } @@ -47,60 +45,6 @@ func TestDebug(t *testing.T) { }) } -func TestWarn(t *testing.T) { - testLogOutput(t, logrus.WarnLevel, frozen.NewMap(), func() { - NewStandardLogger().Warn(testMessage) - }) - - testLogOutput(t, logrus.WarnLevel, testField, func() { - getStandardLoggerWithFields().Warn(testMessage) - }) -} - -func TestTrace(t *testing.T) { - testLogOutput(t, logrus.TraceLevel, frozen.NewMap(), func() { - NewStandardLogger().Trace(testMessage) - }) - - testLogOutput(t, logrus.TraceLevel, testField, func() { - getStandardLoggerWithFields().Trace(testMessage) - }) -} - -func TestPanic(t *testing.T) { - testLogOutput(t, logrus.PanicLevel, frozen.NewMap(), func() { - require.Panics(t, func() { - NewStandardLogger().Panic(testMessage) - }) - }) - - testLogOutput(t, logrus.PanicLevel, frozen.NewMap(), func() { - require.Panics(t, func() { - getStandardLoggerWithFields().Panic(testMessage) - }) - }) -} - -func TestError(t *testing.T) { - testLogOutput(t, logrus.ErrorLevel, frozen.NewMap(), func() { - NewStandardLogger().Error(testMessage) - }) - - testLogOutput(t, logrus.ErrorLevel, testField, func() { - getStandardLoggerWithFields().Error(testMessage) - }) -} - -func TestErrorf(t *testing.T) { - testLogOutput(t, logrus.ErrorLevel, frozen.NewMap(), func() { - NewStandardLogger().Errorf(simpleFormat, testMessage) - }) - - testLogOutput(t, logrus.ErrorLevel, testField, func() { - getStandardLoggerWithFields().Errorf(simpleFormat, testMessage) - }) -} - func TestDebugf(t *testing.T) { testLogOutput(t, logrus.DebugLevel, frozen.NewMap(), func() { NewStandardLogger().Debugf(simpleFormat, testMessage) @@ -111,50 +55,31 @@ func TestDebugf(t *testing.T) { }) } -func TestWarnf(t *testing.T) { - testLogOutput(t, logrus.WarnLevel, frozen.NewMap(), func() { - NewStandardLogger().Warnf(simpleFormat, testMessage) +func TestInfo(t *testing.T) { + testLogOutput(t, logrus.InfoLevel, frozen.NewMap(), func() { + NewStandardLogger().Info(testMessage) }) - testLogOutput(t, logrus.WarnLevel, testField, func() { - getStandardLoggerWithFields().Warnf(simpleFormat, testMessage) + testLogOutput(t, logrus.InfoLevel, testField, func() { + getStandardLoggerWithFields().Info(testMessage) }) } -func TestTracef(t *testing.T) { - testLogOutput(t, logrus.TraceLevel, frozen.NewMap(), func() { - NewStandardLogger().Tracef(simpleFormat, testMessage) +func TestInfof(t *testing.T) { + testLogOutput(t, logrus.InfoLevel, frozen.NewMap(), func() { + NewStandardLogger().Infof(simpleFormat, testMessage) }) - testLogOutput(t, logrus.TraceLevel, testField, func() { - getStandardLoggerWithFields().Tracef(simpleFormat, testMessage) - }) -} - -func TestPanicf(t *testing.T) { - testLogOutput(t, logrus.PanicLevel, frozen.NewMap(), func() { - require.Panics(t, func() { - NewStandardLogger().Panicf(simpleFormat, testMessage) - }) - }) - - testLogOutput(t, logrus.PanicLevel, testField, func() { - require.Panics(t, func() { - getStandardLoggerWithFields().Panicf(simpleFormat, testMessage) - }) + testLogOutput(t, logrus.InfoLevel, testField, func() { + getStandardLoggerWithFields().Infof(simpleFormat, testMessage) }) } func testLogOutput(t *testing.T, level logrus.Level, fields frozen.Map, logFunc func()) { - outputtedFields := "" - if fields.Count() != 0 { - outputtedFields = testutil.OutputFormattedFields(fields) - } - - expectedOutput := strings.Join([]string{outputtedFields, strings.ToUpper(level.String()), testMessage}, " ") + expectedOutput := strings.Join([]string{strings.ToUpper(level.String()), testMessage}, " ") actualOutput := testutil.RedirectOutput(t, logFunc) - // uses Contains to avoid checking timestamps + // uses Contains to avoid checking timestamps and fields assert.Contains(t, actualOutput, expectedOutput) } @@ -183,172 +108,28 @@ func TestGetFormattedFieldWithFields(t *testing.T) { frozen.KV("stringVal", "this is a sentence"), ), ).(*standardLogger) - - expected := "byteVal=107 numberVal=1 stringVal=this is a sentence" - assert.Equal(t, expected, logger.getFormattedField()) -} - -func TestInsertFieldsKeyEmpty(t *testing.T) { - t.Parallel() - - logger := getNewStandardLogger() - logger.insertFieldsKey() - assert.Equal(t, 0, len(logger.sortedFields)) -} - -func TestInsertFieldsKey(t *testing.T) { - t.Parallel() - - logger := getNewStandardLogger() - fields := []string{"some", "random", "fields"} - logger.insertFieldsKey(fields...) - - sort.Strings(fields) - assert.Equal(t, fields, logger.sortedFields) -} - -func TestInsertFieldsKeyAddMoreFields(t *testing.T) { - t.Parallel() - - logger := getNewStandardLogger() - fields1 := []string{"some", "random", "fields"} - fields2 := []string{"even", "more", "stuff"} - - logger.insertFieldsKey(fields1...) - logger.insertFieldsKey(fields2...) - - combined := append(fields1, fields2...) - sort.Strings(combined) - assert.Equal(t, combined, logger.sortedFields) -} - -func TestSetInfo(t *testing.T) { - cases := testutil.GenerateMultipleFieldsCases() - for _, c := range cases { - t.Run("TestSetInfo"+c.Name, func(mc testutil.MultipleFields) func(*testing.T) { - return func(tt *testing.T) { - tt.Parallel() - - logger := getNewStandardLogger().PutFields(mc.Fields).(*standardLogger) - entry := logger.setInfo() - expected := testutil.OutputFormattedFields(mc.Fields) - - assert.Equal(tt, expected, entry.Data[keyFields]) - } - }(c)) + // fields are in a random order + expectedFields := []string{"byteVal=107", "numberVal=1", "stringVal=this is a sentence"} + actualFields := logger.getFormattedField() + for _, e := range expectedFields { + assert.Contains(t, actualFields, e) } } -func TestWithFields(t *testing.T) { - cases := testutil.GenerateMultipleFieldsCases() - for _, c := range cases { - t.Run("TestWithFields"+c.Name, - func(mc testutil.MultipleFields) func(*testing.T) { - return func(tt *testing.T) { - tt.Parallel() - - logger := getNewStandardLogger() - - if mc.Fields.Count() == 0 { - require.Panics(tt, func() { - logger.PutFields(mc.Fields) - }) - return - } - - logger.PutFields(mc.Fields) - expectedKeys := testutil.GetSortedKeys(mc.Fields) - assert.Equal(tt, expectedKeys, logger.sortedFields) - assert.True(tt, mc.Fields.Equal(logger.fields)) - } - }(c)) - } -} - -func TestWithField(t *testing.T) { - cases := testutil.GenerateSingleFieldCases() - for _, c := range cases { - t.Run("TestWithField"+c.Name, - func(sc testutil.SingleField) func(*testing.T) { - return func(tt *testing.T) { - tt.Parallel() - - logger := getNewStandardLogger() - logger.PutField(sc.Key, sc.Val) - value, exists := logger.fields.Get(sc.Key) - - require.True(tt, exists) - assert.Equal(tt, sc.Val, value) - } - }(c)) - } -} +func TestPutFields(t *testing.T) { + t.Parallel() -func TestWithFieldWithAddingMoreValues(t *testing.T) { cases := testutil.GenerateMultipleFieldsCases() for _, c := range cases { - t.Run("TestWithFieldWithAddingMoreValues"+c.Name, - func(mc testutil.MultipleFields) func(*testing.T) { - return func(tt *testing.T) { - tt.Parallel() - - logger := getNewStandardLogger() - - for i := mc.Fields.Range(); i.Next(); { - logger.PutField(i.Key().(string), i.Value()) - } - - expectedKeys := testutil.GetSortedKeys(mc.Fields) - assert.Equal(tt, expectedKeys, logger.sortedFields) - assert.True(tt, mc.Fields.Equal(logger.fields)) - } - }(c)) - } -} - -func TestWithFieldReplaceValues(t *testing.T) { - t.Parallel() - - key := "random" - oldVal := 1 - newVal := 2 - - logger := getNewStandardLogger() - - logger.PutField(key, oldVal) - assertFieldExists(t, logger, frozen.NewMap(frozen.KV(key, oldVal))) - - logger.PutField(key, newVal) - assertFieldExists(t, logger, frozen.NewMap(frozen.KV(key, newVal))) - assert.Equal(t, []string{key}, logger.sortedFields) -} - -func TestWithFieldsReplaceValues(t *testing.T) { - t.Parallel() - field := frozen.NewMap( - frozen.KV("1", 1), - frozen.KV("2", 2), - frozen.KV("3", 3), - ) - - logger := getNewStandardLogger().PutFields(field).(*standardLogger) - - assertFieldExists(t, logger, field) - - for i := field.Range(); i.Next(); { - field = field.With(i.Key(), "replaced") - } - logger.PutFields(field) - - assertFieldExists(t, logger, field) - assert.Equal(t, testutil.GetSortedKeys(field), logger.sortedFields) -} - -func assertFieldExists(t *testing.T, logger *standardLogger, expectedFields frozen.Map) { - for i := expectedFields.Range(); i.Next(); { - curVal, exists := logger.fields.Get(i.Key()) - require.True(t, exists) - assert.Equal(t, i.Value(), curVal) + c := c + t.Run(c.Name, + func(t *testing.T) { + t.Parallel() + + logger := getNewStandardLogger() + logger.PutFields(c.Fields) + assert.True(t, c.Fields.Equal(logger.fields)) + }) } } @@ -357,6 +138,6 @@ func getNewStandardLogger() *standardLogger { } func getStandardLoggerWithFields() *standardLogger { - logger := NewStandardLogger().PutFields(testField) + logger := getNewStandardLogger().PutFields(testField) return logger.(*standardLogger) } diff --git a/log/mockLogger.go b/log/mockLogger.go new file mode 100644 index 0000000..51a4825 --- /dev/null +++ b/log/mockLogger.go @@ -0,0 +1,39 @@ +package log + +import ( + "github.com/arr-ai/frozen" + "github.com/stretchr/testify/mock" +) + +type mockLogger struct { + Logger + mock.Mock +} + +func newMockLogger() *mockLogger { + return &mockLogger{} +} + +func (m *mockLogger) Debug(args ...interface{}) { + m.Called(args...) +} + +func (m *mockLogger) Debugf(format string, args ...interface{}) { + m.Called(append([]interface{}{format}, args...)...) +} + +func (m *mockLogger) Info(args ...interface{}) { + m.Called(args...) +} + +func (m *mockLogger) Infof(format string, args ...interface{}) { + m.Called(append([]interface{}{format}, args...)...) +} + +func (m *mockLogger) PutFields(fields frozen.Map) Logger { + return m.Called(fields).Get(0).(Logger) +} + +func (m *mockLogger) Copy() Logger { + return m.Called().Get(0).(Logger) +} diff --git a/log/testutil/testutil.go b/log/testutil/testutil.go index 2e919cb..e30e300 100644 --- a/log/testutil/testutil.go +++ b/log/testutil/testutil.go @@ -9,53 +9,13 @@ import ( "strings" "testing" - "github.com/marcelocantos/frozen" + "github.com/arr-ai/frozen" "github.com/stretchr/testify/require" ) -type SingleField struct { - Name, Key string - Val interface{} -} - type MultipleFields struct { - Name string - Fields frozen.Map -} - -func GenerateSingleFieldCases() []SingleField { - return []SingleField{ - { - Name: "String Value", - Key: "random", - Val: "Value", - }, - { - Name: "Number Value", - Key: "int", - Val: 3, - }, - { - Name: "Byte Value", - Key: "byte", - Val: 'q', - }, - { - Name: "Empty Key", - Key: "", - Val: "Empty", - }, - { - Name: "Empty Value", - Key: "Empty", - Val: "", - }, - { - Name: "Nil Value", - Key: "nil", - Val: nil, - }, - } + Name string + Fields, GlobalFields frozen.Map } func GenerateMultipleFieldsCases() []MultipleFields { @@ -89,10 +49,10 @@ func RedirectOutput(t *testing.T, print func()) string { print() outC := make(chan string) - go func(tt *testing.T) { + go func(t *testing.T) { var buf bytes.Buffer _, err := io.Copy(&buf, r) - require.NoError(tt, err) + require.NoError(t, err) outC <- buf.String() }(t) @@ -127,21 +87,10 @@ func OutputFormattedFields(fields frozen.Map) string { return output.String() } -func GetSortedKeys(fields frozen.Map) []string { - keys := make([]string, fields.Count()) - index := 0 - for i := fields.Range(); i.Next(); { - keys[index] = i.Key().(string) - index++ - } - sort.Strings(keys) - return keys -} - -func ConvertToGoMap(fields frozen.Map) map[string]interface{} { - goMap := make(map[string]interface{}) +func ConvertToGoMap(fields frozen.Map) map[interface{}]interface{} { + goMap := make(map[interface{}]interface{}) for i := fields.Range(); i.Next(); { - goMap[i.Key().(string)] = i.Value() + goMap[i.Key()] = i.Value() } return goMap } diff --git a/log/util.go b/log/util.go index e0a320c..9734842 100644 --- a/log/util.go +++ b/log/util.go @@ -3,27 +3,55 @@ package log import ( "context" - "github.com/anz-bank/pkg/log/loggers" - "github.com/marcelocantos/frozen" + "github.com/arr-ai/frozen" ) -func getCopiedLogger(ctx context.Context) loggers.Logger { - logger, exists := ctx.Value(loggerKey).(loggers.Logger) +type fieldsContextKey struct{} +type loggerKey struct{} +type suppress struct{} +type ctxRef struct{ ctxKey interface{} } + +func (f Fields) getCopiedLogger() Logger { + logger, exists := f.m.Get(loggerKey{}) if !exists { - panic("Logger does not exist in context") + panic("Logger has not been added") } - return logger.Copy() + return logger.(internalLoggerOps).Copy() } -func fromFields(fields []Fields) frozen.Map { - // set capacity to 0 because length of fields is undetermined - frozenMapBuilder := frozen.NewMapBuilder(0) - - for _, f := range fields { - for _, kv := range f.GetKeyValues() { - frozenMapBuilder.Put(kv.Key, kv.Value) +func (f Fields) resolveFields(ctx context.Context) frozen.Map { + fields := f.m + var toSuppress frozen.SetBuilder + toSuppress.Add(loggerKey{}) + for i := fields.Range(); i.Next(); { + switch k := i.Value().(type) { + case ctxRef: + if val := ctx.Value(k.ctxKey); val != nil { + fields = fields.With(i.Key(), val) + } else { + toSuppress.Add(i.Key()) + } + case func(context.Context) interface{}: + if val := k(ctx); val != nil { + fields = fields.With(i.Key(), val) + } else { + toSuppress.Add(i.Key()) + } + case suppress: + toSuppress.Add(i.Key()) } } + return fields.Without(toSuppress.Finish()) +} - return frozenMapBuilder.Finish() +func (f Fields) with(key, val interface{}) Fields { + return Fields{f.m.With(key, val)} +} + +func getFields(ctx context.Context) Fields { + fields, exists := ctx.Value(fieldsContextKey{}).(frozen.Map) + if !exists { + return Fields{} + } + return Fields{fields} } diff --git a/log/util_test.go b/log/util_test.go index ca40ce6..e1dda8b 100644 --- a/log/util_test.go +++ b/log/util_test.go @@ -4,31 +4,78 @@ import ( "context" "testing" - "github.com/anz-bank/pkg/log/loggers" - "github.com/stretchr/testify/assert" - "github.com/stretchr/testify/require" + "github.com/alecthomas/assert" + "github.com/arr-ai/frozen" ) -func TestGetCopiedLogger(t *testing.T) { - t.Parallel() +type key1 struct{} +type key2 struct{} +type key3 struct{} - t.Run("Context has no logger", func(tt *testing.T) { - tt.Parallel() - - require.Panics(tt, func() { - getCopiedLogger(context.Background()) - }) - }) - t.Run("Context has a logger", func(tt *testing.T) { - tt.Parallel() +func getUnresolvedFieldsCases() []fieldsTest { + return []fieldsTest{ + { + name: "regular unresolved fields", + unresolveds: frozen.NewMap( + frozen.KV("a", 1), + frozen.KV("b", 2), + frozen.KV("c", ctxRef{key1{}}), + frozen.KV("d", suppress{}), + frozen.KV("e", func(context.Context) interface{} { return "f" }), + ), + contextFields: frozen.NewMap( + frozen.KV(key1{}, "g"), + ), + expected: frozen.NewMap( + frozen.KV("a", 1), + frozen.KV("b", 2), + frozen.KV("c", "g"), + frozen.KV("e", "f"), + ), + }, + { + name: "key does not exist in context", + unresolveds: frozen.NewMap( + frozen.KV("a", 1), + frozen.KV("b", 2), + frozen.KV("c", ctxRef{key1{}}), + frozen.KV("d", suppress{}), + frozen.KV("e", func(context.Context) interface{} { return "f" }), + ), + expected: frozen.NewMap( + frozen.KV("a", 1), + frozen.KV("b", 2), + frozen.KV("e", "f"), + ), + }, + { + name: "nothing to resolve", + unresolveds: frozen.NewMap( + frozen.KV("a", 1), + frozen.KV("b", 2), + frozen.KV("c", 3), + ), + expected: frozen.NewMap( + frozen.KV("a", 1), + frozen.KV("b", 2), + frozen.KV("c", 3), + ), + }, + } +} - ctx := context.Background() - ctx = With(ctx, loggers.NewStandardLogger()) +func TestResolveFields(t *testing.T) { + for _, c := range getUnresolvedFieldsCases() { + c := c + t.Run(c.name, func(t *testing.T) { + t.Parallel() - logger := getCopiedLogger(ctx) - require.NotNil(t, logger) + ctx := context.Background() + for i := c.contextFields.Range(); i.Next(); { + ctx = context.WithValue(ctx, i.Key(), i.Value()) + } - fromContext := ctx.Value(loggerKey).(loggers.Logger) - assert.True(t, logger != fromContext) - }) + assert.True(t, c.expected.Equal(Fields{c.unresolveds}.resolveFields(ctx))) + }) + } }