From a7f94766c042c2f80b1880824561e095d262eb4d Mon Sep 17 00:00:00 2001 From: Thorsten Essig Date: Wed, 16 Aug 2023 10:52:30 +0200 Subject: [PATCH] refactor(core/zap): clean up zap module and add tests --- core/zap/logger.go | 16 ++ core/zap/logger_benchmark_test.go | 121 ++++++++ core/zap/logger_test.go | 443 +++++++++++++++++++++++------- core/zap/module.go | 35 ++- core/zap/options.go | 19 ++ 5 files changed, 527 insertions(+), 107 deletions(-) create mode 100644 core/zap/logger_benchmark_test.go create mode 100644 core/zap/options.go diff --git a/core/zap/logger.go b/core/zap/logger.go index 5c2bc449d..709996b75 100644 --- a/core/zap/logger.go +++ b/core/zap/logger.go @@ -16,6 +16,8 @@ import ( "flamingo.me/flamingo/v3/framework/web" ) +type Option func(*Logger) + var ( logCount = stats.Int64("flamingo/zap/logs", "Count of logs", stats.UnitDimensionless) keyLevel, _ = tag.NewKey("level") @@ -38,6 +40,18 @@ type ( } ) +func NewLogger(logger *zap.Logger, options ...Option) *Logger { + l := &Logger{ + Logger: logger, + } + + for _, option := range options { + option(l) + } + + return l +} + // WithContext returns a logger with fields filled from the context // businessId: From Header X-Business-ID // client_ip: From Header X-Forwarded-For or request if header is empty @@ -67,6 +81,7 @@ func (l *Logger) WithContext(ctx context.Context) flamingo.Logger { fields[flamingo.LogKeySession] = session.IDHash() } } + return l.WithFields(fields) } @@ -158,6 +173,7 @@ func (l *Logger) WithFields(fields map[flamingo.LogKey]interface{}) flamingo.Log copy(newFields, l.fields) area := l.configArea + for key, value := range fields { if key == flamingo.LogKeyArea { area = value.(string) diff --git a/core/zap/logger_benchmark_test.go b/core/zap/logger_benchmark_test.go new file mode 100644 index 000000000..879a30514 --- /dev/null +++ b/core/zap/logger_benchmark_test.go @@ -0,0 +1,121 @@ +package zap_test + +import ( + "testing" + + "flamingo.me/dingo" + "github.com/stretchr/testify/require" + + "flamingo.me/flamingo/v3/core/zap" + "flamingo.me/flamingo/v3/framework/config" + "flamingo.me/flamingo/v3/framework/flamingo" +) + +func BenchmarkLogger(b *testing.B) { + zapModule := new(zap.Module) + area := config.NewArea("test", []dingo.Module{zapModule}) + err := config.Load(area, "", + // Warn Level so that the benchmark does not print to output + config.AdditionalConfig([]string{"core.zap.loglevel: Warn"})) + require.NoError(b, err) + + injector, err := area.GetInitializedInjector() + require.NoError(b, err) + + l, err := injector.GetInstance(new(flamingo.Logger)) + require.NoError(b, err) + + require.IsTypef(b, new(zap.Logger), l, "logger must be a *zap.Logger") + logger := l.(flamingo.Logger) + + b.Run("withField-1-log", func(b *testing.B) { + b.ReportAllocs() + b.ResetTimer() + b.RunParallel(func(pb *testing.PB) { + for pb.Next() { + fieldedLogger := logger. + WithField("key1", "value1"). + WithField("key2", "value2"). + WithField("key3", "value3"). + WithField("key4", "value4"). + WithField("key5", "value5"). + WithField("key6", "value6") + fieldedLogger.Info("Test Log") + } + }) + }) + b.Run("withFields-1-log", func(b *testing.B) { + b.ReportAllocs() + b.ResetTimer() + b.RunParallel(func(pb *testing.PB) { + for pb.Next() { + fieldedLogger := logger. + WithFields( + map[flamingo.LogKey]interface{}{ + "key1": "value1", + "key2": "value2", + "key3": "value3", + "key4": "value4", + "key5": "value5", + "key6": "value6", + }) + fieldedLogger.Info("Test Log") + } + }) + }) + b.Run("withField-each-log", func(b *testing.B) { + b.ReportAllocs() + b.ResetTimer() + b.RunParallel(func(pb *testing.PB) { + for pb.Next() { + fieldedLogger := logger.WithField("key1", "value1") + fieldedLogger.Info("Test Log") + + fieldedLogger = fieldedLogger.WithField("key2", "value2") + fieldedLogger.Info("Test Log") + + fieldedLogger = fieldedLogger.WithField("key3", "value3") + fieldedLogger.Info("Test Log") + + fieldedLogger = fieldedLogger.WithField("key4", "value4") + fieldedLogger.Info("Test Log") + + fieldedLogger = fieldedLogger.WithField("key5", "value5") + fieldedLogger.Info("Test Log") + + fieldedLogger = fieldedLogger.WithField("key6", "value6") + fieldedLogger.Info("Test Log") + } + }) + }) + + b.Run("withFields-many-logs", func(b *testing.B) { + b.ReportAllocs() + b.ResetTimer() + b.RunParallel(func(pb *testing.PB) { + for pb.Next() { + fieldedLogger := logger. + WithFields( + map[flamingo.LogKey]interface{}{ + "key1": "value1", + "key2": "value2", + "key3": "value3", + "key4": "value4", + "key5": "value5", + "key6": "value6", + }) + + fieldedLogger.Info("Test Log") + fieldedLogger.Info("Test Log") + fieldedLogger.Info("Test Log") + fieldedLogger.Info("Test Log") + fieldedLogger.Info("Test Log") + fieldedLogger.Info("Test Log") + fieldedLogger.Info("Test Log") + fieldedLogger.Info("Test Log") + fieldedLogger.Info("Test Log") + fieldedLogger.Info("Test Log") + } + }) + }) +} diff --git a/core/zap/logger_test.go b/core/zap/logger_test.go index 879a30514..ae49e4254 100644 --- a/core/zap/logger_test.go +++ b/core/zap/logger_test.go @@ -1,121 +1,370 @@ package zap_test import ( + "context" + "net/http" "testing" - "flamingo.me/dingo" - "github.com/stretchr/testify/require" - "flamingo.me/flamingo/v3/core/zap" - "flamingo.me/flamingo/v3/framework/config" "flamingo.me/flamingo/v3/framework/flamingo" + "flamingo.me/flamingo/v3/framework/web" + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + "go.opencensus.io/trace" + uberZap "go.uber.org/zap" + "go.uber.org/zap/zapcore" + "go.uber.org/zap/zaptest/observer" ) -func BenchmarkLogger(b *testing.B) { - zapModule := new(zap.Module) - area := config.NewArea("test", []dingo.Module{zapModule}) - err := config.Load(area, "", - // Warn Level so that the benchmark does not print to output - config.AdditionalConfig([]string{"core.zap.loglevel: Warn"})) - require.NoError(b, err) - - injector, err := area.GetInitializedInjector() - require.NoError(b, err) - - l, err := injector.GetInstance(new(flamingo.Logger)) - require.NoError(b, err) - - require.IsTypef(b, new(zap.Logger), l, "logger must be a *zap.Logger") - logger := l.(flamingo.Logger) - - b.Run("withField-1-log", func(b *testing.B) { - b.ReportAllocs() - b.ResetTimer() - b.RunParallel(func(pb *testing.PB) { - for pb.Next() { - fieldedLogger := logger. - WithField("key1", "value1"). - WithField("key2", "value2"). - WithField("key3", "value3"). - WithField("key4", "value4"). - WithField("key5", "value5"). - WithField("key6", "value6") - fieldedLogger.Info("Test Log") +func TestLogger_WithContext(t *testing.T) { + t.Parallel() + + tests := []struct { + name string + argAndWant func(t *testing.T) (context.Context, map[flamingo.LogKey]string) + }{ + { + name: "trace and span id fields should be added", + argAndWant: func(t *testing.T) (context.Context, map[flamingo.LogKey]string) { + t.Helper() + + ctx, span := trace.StartSpan(context.Background(), "test") + t.Cleanup(span.End) + + return ctx, map[flamingo.LogKey]string{ + flamingo.LogKeyTraceID: span.SpanContext().TraceID.String(), + flamingo.LogKeySpanID: span.SpanContext().SpanID.String(), + } + }, + }, + { + name: "request method and path fields should be added", + argAndWant: func(t *testing.T) (context.Context, map[flamingo.LogKey]string) { + t.Helper() + + req, err := http.NewRequestWithContext(context.Background(), http.MethodGet, "https://example.com/deep/path", nil) + require.NoError(t, err) + + ctx := web.ContextWithRequest(context.Background(), web.CreateRequest(req, web.EmptySession())) + + return ctx, map[flamingo.LogKey]string{ + flamingo.LogKeyMethod: http.MethodGet, + flamingo.LogKeyPath: "/deep/path", + } + }, + }, + { + name: "sessoion id hash field should be added", + argAndWant: func(t *testing.T) (context.Context, map[flamingo.LogKey]string) { + t.Helper() + + session := web.EmptySession() + ctx := web.ContextWithSession(context.Background(), session) + + return ctx, map[flamingo.LogKey]string{ + flamingo.LogKeySession: session.IDHash(), + } + }, + }, + } + for _, tt := range tests { + tt := tt + t.Run(tt.name, func(t *testing.T) { + t.Parallel() + + core, observedLogs := observer.New(zapcore.InfoLevel) + l := zap.NewLogger(uberZap.New(core, uberZap.WithFatalHook(zapcore.WriteThenNoop)), zap.WithLogSession(true)) + + ctx, expectedFields := tt.argAndWant(t) + + ctxLogger := l.WithContext(ctx) + ctxLogger.Info() + + require.Equal(t, observedLogs.Len(), 1) + + foundFields := make(map[string]struct{}) + + for _, field := range observedLogs.All()[0].Context { + if expected, ok := expectedFields[flamingo.LogKey(field.Key)]; ok { + foundFields[field.Key] = struct{}{} + + assert.Equal(t, expected, field.String, "field %q not as value", field.Key) + } } - }) - }) - b.Run("withFields-1-log", func(b *testing.B) { - b.ReportAllocs() - b.ResetTimer() - b.RunParallel(func(pb *testing.PB) { - for pb.Next() { - fieldedLogger := logger. - WithFields( - map[flamingo.LogKey]interface{}{ - "key1": "value1", - "key2": "value2", - "key3": "value3", - "key4": "value4", - "key5": "value5", - "key6": "value6", - }) - fieldedLogger.Info("Test Log") + + for key := range expectedFields { + _, found := foundFields[string(key)] + assert.True(t, found, "expected log field %q not found in entry", key) } }) - }) - b.Run("withField-each-log", func(b *testing.B) { - b.ReportAllocs() - b.ResetTimer() - b.RunParallel(func(pb *testing.PB) { - for pb.Next() { - fieldedLogger := logger.WithField("key1", "value1") - fieldedLogger.Info("Test Log") + } +} + +func TestLogger_WithField(t *testing.T) { + t.Parallel() + + type fields struct { + fieldMap map[string]string + } + + type args struct { + key flamingo.LogKey + value string + } + + type want struct { + key string + value string + } - fieldedLogger = fieldedLogger.WithField("key2", "value2") - fieldedLogger.Info("Test Log") + tests := []struct { + name string + fields fields + args args + want want + wantFound bool + }{ + { + name: "add given field as log key", + args: args{ + key: flamingo.LogKeyCategory, + value: "test", + }, + want: want{ + key: string(flamingo.LogKeyCategory), + value: "test", + }, + wantFound: true, + }, + { + name: "add given field as log key using configured alias", + fields: fields{ + fieldMap: map[string]string{ + string(flamingo.LogKeyCategory): "alias", + }, + }, + args: args{ + key: flamingo.LogKeyCategory, + value: "test", + }, + want: want{ + key: "alias", + value: "test", + }, + wantFound: true, + }, + { + name: "ignore given field because of configured alias `-`", + fields: fields{ + fieldMap: map[string]string{ + string(flamingo.LogKeyCategory): "-", + }, + }, + args: args{ + key: flamingo.LogKeyCategory, + value: "test", + }, + wantFound: false, + }, + } + for _, tt := range tests { + tt := tt + t.Run(tt.name, func(t *testing.T) { + t.Parallel() - fieldedLogger = fieldedLogger.WithField("key3", "value3") - fieldedLogger.Info("Test Log") + core, observedLogs := observer.New(zapcore.InfoLevel) + l := zap.NewLogger(uberZap.New( + core, + uberZap.WithFatalHook(zapcore.WriteThenNoop)), + zap.WithFieldMap(tt.fields.fieldMap), + ).WithField(tt.args.key, tt.args.value) - fieldedLogger = fieldedLogger.WithField("key4", "value4") - fieldedLogger.Info("Test Log") + l.Info() + require.Equal(t, observedLogs.Len(), 1) - fieldedLogger = fieldedLogger.WithField("key5", "value5") - fieldedLogger.Info("Test Log") + found := false - fieldedLogger = fieldedLogger.WithField("key6", "value6") - fieldedLogger.Info("Test Log") + for _, field := range observedLogs.All()[0].Context { + if field.Key == tt.want.key { + found = true + + assert.Equal(t, tt.want.value, field.String) + } } + + assert.Equal(t, tt.wantFound, found, "key %q found: %t but wanted: %t", tt.args.key, found, tt.wantFound) }) - }) + } +} + +func TestLogger_WithFields(t *testing.T) { + t.Parallel() + + type fields struct { + fieldMap map[string]string + } + + type args struct { + fields map[flamingo.LogKey]any + } + + tests := []struct { + name string + fields fields + args args + want map[string]string + }{ + { + name: "add given fields as log keys", + args: args{ + fields: map[flamingo.LogKey]any{ + flamingo.LogKeyCategory: "test", + flamingo.LogKeySubCategory: "sub-test", + }, + }, + want: map[string]string{ + string(flamingo.LogKeyCategory): "test", + string(flamingo.LogKeySubCategory): "sub-test", + }, + }, + { + name: "add given field as log key using configured alias", + fields: fields{ + fieldMap: map[string]string{ + string(flamingo.LogKeyCategory): "alias", + string(flamingo.LogKeySubCategory): "alias2", + }, + }, + args: args{ + fields: map[flamingo.LogKey]any{ + flamingo.LogKeyCategory: "test", + flamingo.LogKeySubCategory: "sub-test", + }, + }, + want: map[string]string{ + "alias": "test", + "alias2": "sub-test", + }, + }, + { + name: "ignore given field because of configured alias `-`", + fields: fields{ + fieldMap: map[string]string{ + string(flamingo.LogKeyCategory): "-", + }, + }, + args: args{ + fields: map[flamingo.LogKey]any{ + flamingo.LogKeyCategory: "test", + flamingo.LogKeySubCategory: "sub-test", + }, + }, + want: map[string]string{ + string(flamingo.LogKeySubCategory): "sub-test", + }, + }, + } + for _, tt := range tests { + tt := tt + t.Run(tt.name, func(t *testing.T) { + t.Parallel() + + core, observedLogs := observer.New(zapcore.InfoLevel) + l := zap.NewLogger(uberZap.New(core, uberZap.WithFatalHook(zapcore.WriteThenNoop)), + zap.WithFieldMap(tt.fields.fieldMap), + ).WithFields(tt.args.fields) - b.Run("withFields-many-logs", func(b *testing.B) { - b.ReportAllocs() - b.ResetTimer() - b.RunParallel(func(pb *testing.PB) { - for pb.Next() { - fieldedLogger := logger. - WithFields( - map[flamingo.LogKey]interface{}{ - "key1": "value1", - "key2": "value2", - "key3": "value3", - "key4": "value4", - "key5": "value5", - "key6": "value6", - }) - - fieldedLogger.Info("Test Log") - fieldedLogger.Info("Test Log") - fieldedLogger.Info("Test Log") - fieldedLogger.Info("Test Log") - fieldedLogger.Info("Test Log") - fieldedLogger.Info("Test Log") - fieldedLogger.Info("Test Log") - fieldedLogger.Info("Test Log") - fieldedLogger.Info("Test Log") - fieldedLogger.Info("Test Log") + l.Info() + require.Equal(t, observedLogs.Len(), 1) + + foundFields := make(map[string]struct{}) + + for _, field := range observedLogs.All()[0].Context { + if expected, ok := tt.want[field.Key]; ok { + foundFields[field.Key] = struct{}{} + + assert.Equal(t, expected, field.String, "field %q not as value", field.Key) + } + } + + for key := range tt.want { + _, found := foundFields[key] + assert.True(t, found, "expected log field %q not found in entry", key) } }) + } +} + +func TestLogger_Debug(t *testing.T) { + t.Parallel() + + core, observedLogs := observer.New(zapcore.DebugLevel) + l := zap.NewLogger(uberZap.New(core, uberZap.WithFatalHook(zapcore.WriteThenNoop))) + + l.Debug("test") + + require.Equal(t, observedLogs.Len(), 1) + assert.Equal(t, "test", observedLogs.All()[0].Message) +} + +func TestLogger_Debugf(t *testing.T) { + t.Parallel() + + core, observedLogs := observer.New(zapcore.DebugLevel) + l := zap.NewLogger(uberZap.New(core, uberZap.WithFatalHook(zapcore.WriteThenNoop))) + + l.Debugf("test %s", "logger") + + require.Equal(t, observedLogs.Len(), 1) + assert.Equal(t, "test logger", observedLogs.All()[0].Message) +} + +func TestLogger_Info(t *testing.T) { + t.Parallel() + + core, observedLogs := observer.New(zapcore.InfoLevel) + l := zap.NewLogger(uberZap.New(core, uberZap.WithFatalHook(zapcore.WriteThenNoop))) + + l.Info("test") + + require.Equal(t, observedLogs.Len(), 1) + assert.Equal(t, "test", observedLogs.All()[0].Message) +} + +func TestLogger_Warn(t *testing.T) { + t.Parallel() + + core, observedLogs := observer.New(zapcore.WarnLevel) + l := zap.NewLogger(uberZap.New(core, uberZap.WithFatalHook(zapcore.WriteThenNoop))) + + l.Warn("test") + + require.Equal(t, observedLogs.Len(), 1) + assert.Equal(t, "test", observedLogs.All()[0].Message) +} + +func TestLogger_Error(t *testing.T) { + t.Parallel() + + core, observedLogs := observer.New(zapcore.ErrorLevel) + l := zap.NewLogger(uberZap.New(core, uberZap.WithFatalHook(zapcore.WriteThenNoop))) + + l.Error("test") + + require.Equal(t, observedLogs.Len(), 1) + assert.Equal(t, "test", observedLogs.All()[0].Message) +} + +func TestLogger_Fatal(t *testing.T) { + t.Parallel() + + core, observedLogs := observer.New(zapcore.FatalLevel) + l := zap.NewLogger(uberZap.New(core, uberZap.WithFatalHook(zapcore.WriteThenPanic))) + + assert.Panics(t, func() { + l.Fatal("test") }) + + require.Equal(t, observedLogs.Len(), 1) + assert.Equal(t, "test", observedLogs.All()[0].Message) } diff --git a/core/zap/module.go b/core/zap/module.go index b95c394b4..4b101e513 100644 --- a/core/zap/module.go +++ b/core/zap/module.go @@ -62,8 +62,10 @@ func (m *Module) Inject(config *struct { m.samplingInitial = config.SamplingInitial m.samplingThereafter = config.SamplingThereafter m.logSession = config.LogSession + if config.FieldMap != nil { m.fieldMap = make(map[string]string, len(config.FieldMap)) + for k, v := range config.FieldMap { if v, ok := v.(string); ok { m.fieldMap[k] = v @@ -72,8 +74,13 @@ func (m *Module) Inject(config *struct { } } -// Configure the logrus logger as flamingo.Logger (in JSON mode kibana compatible) +// Configure the zap logger as flamingo.Logger (in JSON mode kibana compatible) func (m *Module) Configure(injector *dingo.Injector) { + injector.Bind(new(flamingo.Logger)).ToInstance(m.createLoggerInstance()) + flamingo.BindEventSubscriber(injector).To(shutdownEventSubscriber{}) +} + +func (m *Module) createLoggerInstance() *Logger { level, ok := logLevels[m.logLevel] if !ok { // if nothing is configured user ErrorLevel @@ -93,10 +100,12 @@ func (m *Module) Configure(injector *dingo.Injector) { if m.json { output = "json" } + encoder := zapcore.CapitalLevelEncoder if m.coloredOutput { encoder = zapcore.CapitalColorLevelEncoder } + cfg := zap.Config{ Level: zap.NewAtomicLevelAt(level), Development: m.developmentMode, @@ -128,17 +137,16 @@ func (m *Module) Configure(injector *dingo.Injector) { panic(err) } - zapLogger := &Logger{ - Logger: logger, - fieldMap: m.fieldMap, - logSession: m.logSession, - configArea: m.area, - } + zapLogger := NewLogger( + logger, + WithFieldMap(m.fieldMap), + WithLogSession(m.logSession), + WithArea(m.area), + ) zapLogger = zapLogger.WithField(flamingo.LogKeyArea, m.area).(*Logger) - injector.Bind(new(flamingo.Logger)).ToInstance(zapLogger) - flamingo.BindEventSubscriber(injector).To(shutdownEventSubscriber{}) + return zapLogger } // Inject dependencies @@ -160,13 +168,20 @@ func (subscriber *shutdownEventSubscriber) Notify(_ context.Context, event flami func (m *Module) CueConfig() string { // language=cue return ` -core zap: { +core: zap: { loglevel: *"Debug" | "Info" | "Warn" | "Error" | "DPanic" | "Panic" | "Fatal" sampling: { enabled: bool | *true initial: int | *100 thereafter: int | *100 } + json: bool | *false + colored: bool | *false + devmode: bool | *false + logsession: bool | *false + fieldmap: { + [string]: string + } } ` } diff --git a/core/zap/options.go b/core/zap/options.go new file mode 100644 index 000000000..17a69215d --- /dev/null +++ b/core/zap/options.go @@ -0,0 +1,19 @@ +package zap + +func WithLogSession(value bool) Option { + return func(logger *Logger) { + logger.logSession = value + } +} + +func WithFieldMap(fieldMap map[string]string) Option { + return func(logger *Logger) { + logger.fieldMap = fieldMap + } +} + +func WithArea(area string) Option { + return func(logger *Logger) { + logger.configArea = area + } +}