From c27c041fb470ac35bc7ad12b3e589dcb30f7602d Mon Sep 17 00:00:00 2001 From: Novan Allanadi <25704935+nofun97@users.noreply.github.com> Date: Mon, 17 Feb 2020 17:09:42 +1100 Subject: [PATCH 1/6] WIP: early design for canonical log --- log/api.go | 3 +-- log/canonical.go | 43 +++++++++++++++++++++++++++++++++++++++++++ log/util.go | 38 ++++++++++++++++++++++++++++++++++++++ 3 files changed, 82 insertions(+), 2 deletions(-) create mode 100644 log/canonical.go diff --git a/log/api.go b/log/api.go index f8d5213..b5603ab 100644 --- a/log/api.go +++ b/log/api.go @@ -31,8 +31,7 @@ func Errorf(ctx context.Context, err error, format string, args ...interface{}) // 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.configureLogger(ctx, f.getCopiedLogger().(fieldSetter)) + return from(ctx, getFields(ctx)) } // Info logs from context at the debug level. diff --git a/log/canonical.go b/log/canonical.go new file mode 100644 index 0000000..bf7e9b5 --- /dev/null +++ b/log/canonical.go @@ -0,0 +1,43 @@ +package log + +import ( + "context" + + "github.com/arr-ai/frozen" +) + +func OnInfo(ctx context.Context, fields Fields) { + addCanonicalFields(getCanonicalFields(ctx), fields) +} + +func OnDebug(ctx context.Context, fields Fields) { + addCanonicalFields(getCanonicalFields(ctx), fields) +} + +func OnError(ctx context.Context, fields Fields) { + addCanonicalFields(getCanonicalFields(ctx), fields) +} + +func RegisterCanonicalListener(ctx context.Context, callback ...func(context.Context, Fields)) context.Context{ + callbacks := frozen.NewSetBuilder(len(callback)) + for _, c := range callback { + callbacks.Add(c) + } + return context.WithValue( + context.WithValue(ctx, canonicalFieldsKey{}, frozen.NewMapBuilder(0)), + canonicalListenerKey{}, + callbacks.Finish(), + ) +} + +func CanonicalInfo(ctx context.Context) { + from(ctx, Fields{getCanonicalFields(ctx).Finish()}).Info(ctx) +} + +func CanonicalDebug(ctx context.Context) { + from(ctx, Fields{getCanonicalFields(ctx).Finish()}).Debug(ctx) +} + +func CanonicalError(ctx context.Context, errMsg error) { + from(ctx, Fields{getCanonicalFields(ctx).Finish()}).Error(errMsg) +} diff --git a/log/util.go b/log/util.go index a2cac97..f09f84b 100644 --- a/log/util.go +++ b/log/util.go @@ -9,6 +9,8 @@ import ( const errMsgKey = "error_message" type fieldsContextKey struct{} +type canonicalFieldsKey struct{} +type canonicalListenerKey struct {} type loggerKey struct{} type suppress struct{} type ctxRef struct{ ctxKey interface{} } @@ -66,6 +68,42 @@ func (f Fields) with(key, val interface{}) Fields { return Fields{f.m.With(key, val)} } +func getCanonicalFields(ctx context.Context) *frozen.MapBuilder { + mb, exists := ctx.Value(canonicalFieldsKey{}).(*frozen.MapBuilder) + if !exists { + return frozen.NewMapBuilder(0) + } + return mb +} + +func addCanonicalFields(mb *frozen.MapBuilder, fields Fields) { + for i := fields.m.Range(); i.Next(); { + if f, exists := mb.Get(i.Key()); exists { + if val, isList := f.([]interface{}); isList { + mb.Put(i.Key(), append(val, i.Value())) + } else { + mb.Put(i.Key(), []interface{}{f, i.Value()}) + } + } else { + mb.Put(i.Key(), i.Value()) + } + } +} + +func doCallbackIfRegistered(ctx context.Context, fields Fields, cb func(context.Context, Fields)) { + callbacks, exists := ctx.Value(canonicalListenerKey{}).(frozen.Set) + if !exists { + return + } + if callbacks.Has(cb) { + cb(ctx, fields) + } +} + +func from(ctx context.Context, f Fields) Logger { + return f.configureLogger(ctx, f.getCopiedLogger().(fieldSetter)) +} + func getFields(ctx context.Context) Fields { fields, exists := ctx.Value(fieldsContextKey{}).(frozen.Map) if !exists { From 70cb1ab051b43dd49e2e1d1593861a7abf74fca6 Mon Sep 17 00:00:00 2001 From: Novan Allanadi <25704935+nofun97@users.noreply.github.com> Date: Mon, 17 Feb 2020 17:16:34 +1100 Subject: [PATCH 2/6] WIP: added callbacks --- log/util.go | 44 +++++++++++++++++++++++++++++++++----------- 1 file changed, 33 insertions(+), 11 deletions(-) diff --git a/log/util.go b/log/util.go index f09f84b..4d73b4e 100644 --- a/log/util.go +++ b/log/util.go @@ -27,14 +27,36 @@ func (f *fieldsCollector) PutFields(fields frozen.Map) Logger { func (f Fields) getCopiedLogger() Logger { logger, exists := f.m.Get(loggerKey{}) if !exists { - return NewStandardLogger() + panic("Logger has not been added") } return logger.(copyable).Copy() } -func (f Fields) configureLogger(ctx context.Context, logger fieldSetter) Logger { +func (f Fields) configureLogger(ctx context.Context, logger fieldSetter, configs frozen.Set) Logger { + for c := configs.Range(); c.Next(); { + err := c.(Config).Apply(logger.(Logger)) + if err != nil { + //TODO: should decide whether it should panic or not + panic(err) + } + } + return logger.PutFields(f.m) +} + +func (f Fields) applyConfiguration(logger Logger, configs frozen.Set) Logger { + for c := configs.Range(); c.Next(); { + err := c.(Config).Apply(logger.(Logger)) + if err != nil { + //TODO: should decide whether it should panic or not + panic(err) + } + } + return logger +} + +func (f Fields) getResolvedFields(ctx context.Context) (frozen.Map, frozen.Set) { fields := f.m - var toSuppress frozen.SetBuilder + var toSuppress, configBuilder frozen.SetBuilder toSuppress.Add(loggerKey{}) for i := fields.Range(); i.Next(); { switch k := i.Value().(type) { @@ -54,14 +76,10 @@ func (f Fields) configureLogger(ctx context.Context, logger fieldSetter) Logger toSuppress.Add(i.Key()) case Config: toSuppress.Add(i.Key()) - err := k.Apply(logger.(Logger)) - if err != nil { - //TODO: should decide whether it should panic or not - panic(err) - } + configBuilder.Add(k) } } - return logger.PutFields(fields.Without(toSuppress.Finish())) + return fields.Without(toSuppress.Finish()), configBuilder.Finish() } func (f Fields) with(key, val interface{}) Fields { @@ -100,8 +118,12 @@ func doCallbackIfRegistered(ctx context.Context, fields Fields, cb func(context. } } -func from(ctx context.Context, f Fields) Logger { - return f.configureLogger(ctx, f.getCopiedLogger().(fieldSetter)) +func from(ctx context.Context, f Fields, callback ...func(context.Context, Fields)) Logger { + fields, configs := f.getResolvedFields(ctx) + if len(callback) == 1 { + doCallbackIfRegistered(ctx, Fields{fields}, callback[0]) + } + return f.configureLogger(ctx, f.getCopiedLogger().(fieldSetter), configs) } func getFields(ctx context.Context) Fields { From a17cbcb3e29ab564eba6aace2e4be8294456b23e Mon Sep 17 00:00:00 2001 From: Novan Allanadi <25704935+nofun97@users.noreply.github.com> Date: Tue, 18 Feb 2020 09:44:56 +1100 Subject: [PATCH 3/6] WIP: working canonical log API --- log/api.go | 20 ++++++++++++++--- log/canonical.go | 34 +++++------------------------ log/util.go | 56 +++++++++++++++++++++++------------------------- 3 files changed, 49 insertions(+), 61 deletions(-) diff --git a/log/api.go b/log/api.go index b5603ab..dc2a48d 100644 --- a/log/api.go +++ b/log/api.go @@ -44,6 +44,21 @@ func Infof(ctx context.Context, format string, args ...interface{}) { Fields{}.Infof(ctx, format, args...) } +// RegisterListener registers callbacks that are called after a log. +func RegisterListener(ctx context.Context, callback func(context.Context, Fields)) context.Context{ + cbList, isList := ctx.Value(listenerKey{}).([]func(context.Context, Fields)) + if !isList { + cbList = []func(context.Context, Fields){callback} + } else { + cbList = append(cbList, callback) + } + return context.WithValue( + context.WithValue(ctx, canonicalFieldsKey{}, frozen.NewMapBuilder(0)), + listenerKey{}, + cbList, + ) +} + // Suppress will ensure that suppressed keys are not logged. func Suppress(keys ...string) Fields { return Fields{}.Suppress(keys...) @@ -161,9 +176,8 @@ func (f Fields) WithLogger(logger Logger) Fields { // String returns a string that represent the current fields func (f Fields) String(ctx context.Context) string { - fields := &fieldsCollector{} - f.configureLogger(ctx, fields) - return fields.fields.String() + m, _ := f.getResolvedFields(ctx) + return m.String() } // MergedString returns a string that represents the current fields merged by fields in context diff --git a/log/canonical.go b/log/canonical.go index bf7e9b5..fb8f56c 100644 --- a/log/canonical.go +++ b/log/canonical.go @@ -6,38 +6,14 @@ import ( "github.com/arr-ai/frozen" ) -func OnInfo(ctx context.Context, fields Fields) { +func OnLog(ctx context.Context, fields Fields) { addCanonicalFields(getCanonicalFields(ctx), fields) } -func OnDebug(ctx context.Context, fields Fields) { - addCanonicalFields(getCanonicalFields(ctx), fields) -} - -func OnError(ctx context.Context, fields Fields) { - addCanonicalFields(getCanonicalFields(ctx), fields) -} - -func RegisterCanonicalListener(ctx context.Context, callback ...func(context.Context, Fields)) context.Context{ - callbacks := frozen.NewSetBuilder(len(callback)) - for _, c := range callback { - callbacks.Add(c) - } - return context.WithValue( - context.WithValue(ctx, canonicalFieldsKey{}, frozen.NewMapBuilder(0)), - canonicalListenerKey{}, - callbacks.Finish(), - ) -} - -func CanonicalInfo(ctx context.Context) { - from(ctx, Fields{getCanonicalFields(ctx).Finish()}).Info(ctx) -} - -func CanonicalDebug(ctx context.Context) { - from(ctx, Fields{getCanonicalFields(ctx).Finish()}).Debug(ctx) +func CanonicalLog(ctx context.Context) { + from(ctx, Fields{getCanonicalFields(ctx).Finish()}).Info() } -func CanonicalError(ctx context.Context, errMsg error) { - from(ctx, Fields{getCanonicalFields(ctx).Finish()}).Error(errMsg) +func StartCanonicalLog(ctx context.Context) context.Context { + return context.WithValue(ctx, canonicalFieldsKey{}, frozen.NewMapBuilder(0)) } diff --git a/log/util.go b/log/util.go index 4d73b4e..3fbf88b 100644 --- a/log/util.go +++ b/log/util.go @@ -10,7 +10,7 @@ const errMsgKey = "error_message" type fieldsContextKey struct{} type canonicalFieldsKey struct{} -type canonicalListenerKey struct {} +type listenerKey struct {} type loggerKey struct{} type suppress struct{} type ctxRef struct{ ctxKey interface{} } @@ -27,23 +27,19 @@ func (f *fieldsCollector) PutFields(fields frozen.Map) Logger { func (f Fields) getCopiedLogger() Logger { logger, exists := f.m.Get(loggerKey{}) if !exists { - panic("Logger has not been added") + return NewStandardLogger() } return logger.(copyable).Copy() } -func (f Fields) configureLogger(ctx context.Context, logger fieldSetter, configs frozen.Set) Logger { - for c := configs.Range(); c.Next(); { - err := c.(Config).Apply(logger.(Logger)) - if err != nil { - //TODO: should decide whether it should panic or not - panic(err) - } +func configureLogger(logger fieldSetter, fields frozen.Map, configs frozen.Set) Logger { + if configs.Count() > 0 { + logger = applyConfiguration(logger.(Logger), configs).(fieldSetter) } - return logger.PutFields(f.m) + return logger.PutFields(fields) } -func (f Fields) applyConfiguration(logger Logger, configs frozen.Set) Logger { +func applyConfiguration(logger Logger, configs frozen.Set) Logger { for c := configs.Range(); c.Next(); { err := c.(Config).Apply(logger.(Logger)) if err != nil { @@ -96,34 +92,36 @@ func getCanonicalFields(ctx context.Context) *frozen.MapBuilder { func addCanonicalFields(mb *frozen.MapBuilder, fields Fields) { for i := fields.m.Range(); i.Next(); { - if f, exists := mb.Get(i.Key()); exists { - if val, isList := f.([]interface{}); isList { - mb.Put(i.Key(), append(val, i.Value())) + switch k := i.Key().(type) { + case Config, Logger: + mb.Put(k, i.Value()) + default: + if f, exists := mb.Get(k); exists { + if val, isList := f.([]interface{}); isList { + mb.Put(k, append(val, i.Value())) + } else { + mb.Put(k, []interface{}{f, i.Value()}) + } } else { - mb.Put(i.Key(), []interface{}{f, i.Value()}) + mb.Put(k, i.Value()) } - } else { - mb.Put(i.Key(), i.Value()) } } } -func doCallbackIfRegistered(ctx context.Context, fields Fields, cb func(context.Context, Fields)) { - callbacks, exists := ctx.Value(canonicalListenerKey{}).(frozen.Set) - if !exists { - return - } - if callbacks.Has(cb) { - cb(ctx, fields) +func doCallbacks(ctx context.Context, fields Fields) { + callbacks := ctx.Value(listenerKey{}) + if callbacks != nil { + for _, c := range callbacks.([]func(context.Context, Fields)) { + c(ctx, fields) + } } } -func from(ctx context.Context, f Fields, callback ...func(context.Context, Fields)) Logger { +func from(ctx context.Context, f Fields) Logger { fields, configs := f.getResolvedFields(ctx) - if len(callback) == 1 { - doCallbackIfRegistered(ctx, Fields{fields}, callback[0]) - } - return f.configureLogger(ctx, f.getCopiedLogger().(fieldSetter), configs) + doCallbacks(ctx, Fields{fields}) + return configureLogger(f.getCopiedLogger().(fieldSetter), fields, configs) } func getFields(ctx context.Context) Fields { From 5edcdc2da082e46e19f763dada21e4cc48da70f7 Mon Sep 17 00:00:00 2001 From: Novan Allanadi <25704935+nofun97@users.noreply.github.com> Date: Tue, 18 Feb 2020 10:04:16 +1100 Subject: [PATCH 4/6] WIP: fixed existing tests --- log/util.go | 22 ++++++++++------------ log/util_test.go | 8 ++++---- 2 files changed, 14 insertions(+), 16 deletions(-) diff --git a/log/util.go b/log/util.go index 3fbf88b..303da26 100644 --- a/log/util.go +++ b/log/util.go @@ -32,16 +32,13 @@ func (f Fields) getCopiedLogger() Logger { return logger.(copyable).Copy() } -func configureLogger(logger fieldSetter, fields frozen.Map, configs frozen.Set) Logger { - if configs.Count() > 0 { - logger = applyConfiguration(logger.(Logger), configs).(fieldSetter) - } - return logger.PutFields(fields) +func configureLogger(logger fieldSetter, fields frozen.Map, configs []Config) Logger { + return applyConfiguration(logger.(Logger), configs).(fieldSetter).PutFields(fields) } -func applyConfiguration(logger Logger, configs frozen.Set) Logger { - for c := configs.Range(); c.Next(); { - err := c.(Config).Apply(logger.(Logger)) +func applyConfiguration(logger Logger, configs []Config) Logger { + for _, c := range configs { + err := c.Apply(logger.(Logger)) if err != nil { //TODO: should decide whether it should panic or not panic(err) @@ -50,10 +47,11 @@ func applyConfiguration(logger Logger, configs frozen.Set) Logger { return logger } -func (f Fields) getResolvedFields(ctx context.Context) (frozen.Map, frozen.Set) { +func (f Fields) getResolvedFields(ctx context.Context) (frozen.Map, []Config) { fields := f.m - var toSuppress, configBuilder frozen.SetBuilder + var toSuppress frozen.SetBuilder toSuppress.Add(loggerKey{}) + configs := make([]Config, 0) for i := fields.Range(); i.Next(); { switch k := i.Value().(type) { case ctxRef: @@ -72,10 +70,10 @@ func (f Fields) getResolvedFields(ctx context.Context) (frozen.Map, frozen.Set) toSuppress.Add(i.Key()) case Config: toSuppress.Add(i.Key()) - configBuilder.Add(k) + configs = append(configs, k) } } - return fields.Without(toSuppress.Finish()), configBuilder.Finish() + return fields.Without(toSuppress.Finish()), configs } func (f Fields) with(key, val interface{}) Fields { diff --git a/log/util_test.go b/log/util_test.go index 24b3798..d3566f4 100644 --- a/log/util_test.go +++ b/log/util_test.go @@ -75,7 +75,7 @@ func TestConfigureLogger(t *testing.T) { for i := c.contextFields.Range(); i.Next(); { ctx = context.WithValue(ctx, i.Key(), i.Value()) } - Fields{c.unresolveds}.configureLogger(ctx, Logger(logger).(fieldSetter)) + logger = configureLogger(Logger(logger).(fieldSetter), c.expected, []Config{}).(*mockLogger) logger.AssertExpectations(t) }) } @@ -86,7 +86,7 @@ func TestConfigureLoggerWithConfigs(t *testing.T) { //TODO: add more configs testCase := getUnresolvedFieldsCases()[0] - unresolveds := Fields{testCase.unresolveds}.WithConfigs(NewJSONFormat()) + unresolved := Fields{testCase.unresolveds}.WithConfigs(NewJSONFormat()) expected := testCase.expected logger := newMockLogger() @@ -97,7 +97,7 @@ func TestConfigureLoggerWithConfigs(t *testing.T) { for i := testCase.contextFields.Range(); i.Next(); { ctx = context.WithValue(ctx, i.Key(), i.Value()) } - - unresolveds.configureLogger(ctx, Logger(logger).(fieldSetter)) + resolved, configs := unresolved.getResolvedFields(ctx) + configureLogger(Logger(logger).(fieldSetter), resolved, configs) logger.AssertExpectations(t) } From 1a542978014ad665676db7d351b4c4dc510f8808 Mon Sep 17 00:00:00 2001 From: Novan Allanadi <25704935+nofun97@users.noreply.github.com> Date: Tue, 18 Feb 2020 12:58:18 +1100 Subject: [PATCH 5/6] WIP: added tests and comments --- log/canonical.go | 9 ++++++- log/canonical_test.go | 62 +++++++++++++++++++++++++++++++++++++++++++ 2 files changed, 70 insertions(+), 1 deletion(-) create mode 100644 log/canonical_test.go diff --git a/log/canonical.go b/log/canonical.go index fb8f56c..c1808b3 100644 --- a/log/canonical.go +++ b/log/canonical.go @@ -6,14 +6,21 @@ import ( "github.com/arr-ai/frozen" ) +// OnLog is a callback that is called when fields and configurations are added to the logger. func OnLog(ctx context.Context, fields Fields) { + if fields := ctx.Value(canonicalFieldsKey{}); fields == nil { + Info(ctx, "Canonical fields have not been set up properly, fields will not be collected") + return + } addCanonicalFields(getCanonicalFields(ctx), fields) } +// CanonicalLog logs all the collected fields from previous logs in non-verbose mode. func CanonicalLog(ctx context.Context) { from(ctx, Fields{getCanonicalFields(ctx).Finish()}).Info() } -func StartCanonicalLog(ctx context.Context) context.Context { +// WithCanonicalLog creates a canonical fields collector. +func WithCanonicalLog(ctx context.Context) context.Context { return context.WithValue(ctx, canonicalFieldsKey{}, frozen.NewMapBuilder(0)) } diff --git a/log/canonical_test.go b/log/canonical_test.go new file mode 100644 index 0000000..94799f7 --- /dev/null +++ b/log/canonical_test.go @@ -0,0 +1,62 @@ +package log + +import ( + "context" + "testing" + + "github.com/alecthomas/assert" + "github.com/arr-ai/frozen" +) + +func TestCanonicalLog(t *testing.T) { + t.Parallel() + + ctx := WithCanonicalLog(context.Background()) + logger := newMockLogger() + + mb := getCanonicalFields(ctx) + + addValues(mb, logger) + setLogMockAssertion(logger, mb.Finish().Without(frozen.NewSet(loggerKey{}))) + logger.On("Info") + + // add the same values again because Finish would remove the values from the map builder. + addValues(mb, logger) + CanonicalLog(ctx) + + logger.AssertExpectations(t) +} + +func TestOnLogWithoutCanonicalFieldsSetup(t *testing.T) { + t.Parallel() + + logger := newMockLogger() + logger.On("Info", "Canonical fields have not been set up properly, fields will not be collected") + setLogMockAssertion(logger, frozen.NewMap()) + OnLog(WithLogger(logger).Onto(context.Background()), Fields{frozen.NewMap()}) + logger.AssertExpectations(t) +} + +func TestOnLog(t *testing.T) { + t.Parallel() + + ctx := WithCanonicalLog(context.Background()) + mb := getCanonicalFields(ctx) + addValues(mb, newMockLogger()) + + testField := frozen.NewMap().With("additional", "value").With("1", 1).With("byte", 'l') + OnLog(ctx, Fields{testField}) + + m := mb.Finish() + for i := testField.Range(); i.Next(); { + val, exists := m.Get(i.Key()) + assert.True(t, exists && val == i.Value()) + } +} + +func addValues(mb *frozen.MapBuilder, logger Logger) { + mb.Put("test", 1) + mb.Put("test2", 'k') + mb.Put("test3", "string value") + mb.Put(loggerKey{}, logger) +} \ No newline at end of file From beccddac04688f16655166ae275b62ca7a7d7034 Mon Sep 17 00:00:00 2001 From: Novan Allanadi <25704935+nofun97@users.noreply.github.com> Date: Tue, 18 Feb 2020 15:20:14 +1100 Subject: [PATCH 6/6] WIP: added test for RegisterListener --- log/util_test.go | 18 ++++++++++++++++++ 1 file changed, 18 insertions(+) diff --git a/log/util_test.go b/log/util_test.go index d3566f4..550bd24 100644 --- a/log/util_test.go +++ b/log/util_test.go @@ -5,6 +5,7 @@ import ( "testing" "github.com/arr-ai/frozen" + "github.com/stretchr/testify/assert" ) type key1 struct{} @@ -101,3 +102,20 @@ func TestConfigureLoggerWithConfigs(t *testing.T) { configureLogger(Logger(logger).(fieldSetter), resolved, configs) logger.AssertExpectations(t) } + +func TestRegisterListener(t *testing.T) { + t.Parallel() + + mockListener1 := OnLog + + ctx := RegisterListener(context.Background(), mockListener1) + cbs, isCallbackList := ctx.Value(listenerKey{}).([]func(context.Context, Fields)) + assert.True(t, isCallbackList) + assert.Equal(t, 1, len(cbs)) + + mockListener2 := func(context.Context, Fields){} + ctx = RegisterListener(ctx, mockListener2) + cbs, isCallbackList = ctx.Value(listenerKey{}).([]func(context.Context, Fields)) + assert.True(t, isCallbackList) + assert.Equal(t, 2, len(cbs)) +}