From 11954b521cc6197d0dc04b163e66e38d4c288047 Mon Sep 17 00:00:00 2001 From: James Milligan <75740990+james-milligan@users.noreply.github.com> Date: Fri, 2 Dec 2022 09:53:25 +0000 Subject: [PATCH] feat: enable request logging via the --debug flag (#226) ## This PR - The `--debug` flag now also controls the logging for requests, when set all logging levels are enabled for the `XXXWithID` `logger` methods and allows the setting of request fields, allowing for improved performance when logs are not required. - `NewLogger` now takes an additional boolean argument to set the internal `reqIDLogging` field, this field is also set to false when the `*zap.Logger` argument is nil ### Related Issues ### Notes ### Follow-up Tasks This flag should be set by default in the operator https://github.com/open-feature/open-feature-operator/pull/260 ### How to test Signed-off-by: James Milligan Signed-off-by: James Milligan <75740990+james-milligan@users.noreply.github.com> Co-authored-by: Skye Gill --- cmd/start.go | 2 +- pkg/eval/fractional_evaluation_test.go | 2 +- pkg/eval/json_evaluator_test.go | 18 +++++++------- pkg/logger/logger.go | 33 +++++++++++++++++++++++--- pkg/logger/logger_test.go | 4 ++-- pkg/service/connect_service_test.go | 22 ++++++++--------- pkg/sync/filepath_sync_test.go | 6 ++--- pkg/sync/http_sync_test.go | 4 ++-- 8 files changed, 59 insertions(+), 32 deletions(-) diff --git a/cmd/start.go b/cmd/start.go index 3dc3c929d..1790bfa1b 100644 --- a/cmd/start.go +++ b/cmd/start.go @@ -85,7 +85,7 @@ var startCmd = &cobra.Command{ if err != nil { log.Fatalf("can't initialize zap logger: %v", err) } - logger := logger.NewLogger(l) + logger := logger.NewLogger(l, Debug) rtLogger := logger.WithFields(zap.String("component", "start")) if viper.GetString(syncProviderFlagName) != "" { diff --git a/pkg/eval/fractional_evaluation_test.go b/pkg/eval/fractional_evaluation_test.go index 9576687a4..86a45689b 100644 --- a/pkg/eval/fractional_evaluation_test.go +++ b/pkg/eval/fractional_evaluation_test.go @@ -281,7 +281,7 @@ func TestFractionalEvaluation(t *testing.T) { const reqID = "default" for name, tt := range tests { t.Run(name, func(t *testing.T) { - je := NewJSONEvaluator(logger.NewLogger(nil)) + je := NewJSONEvaluator(logger.NewLogger(nil, false)) je.state = tt.flags value, variant, reason, err := resolve[string]( diff --git a/pkg/eval/json_evaluator_test.go b/pkg/eval/json_evaluator_test.go index a90cbea41..9da74448a 100644 --- a/pkg/eval/json_evaluator_test.go +++ b/pkg/eval/json_evaluator_test.go @@ -275,7 +275,7 @@ var Flags = fmt.Sprintf(`{ DisabledFlag) func TestGetState_Valid_ContainsFlag(t *testing.T) { - evaluator := eval.JSONEvaluator{Logger: logger.NewLogger(nil)} + evaluator := eval.JSONEvaluator{Logger: logger.NewLogger(nil, false)} _, err := evaluator.SetState("", ValidFlags) if err != nil { t.Fatalf("Expected no error") @@ -295,7 +295,7 @@ func TestGetState_Valid_ContainsFlag(t *testing.T) { } func TestSetState_Invalid_Error(t *testing.T) { - evaluator := eval.JSONEvaluator{Logger: logger.NewLogger(nil)} + evaluator := eval.JSONEvaluator{Logger: logger.NewLogger(nil, false)} // set state with an invalid flag definition _, err := evaluator.SetState("", InvalidFlags) @@ -305,7 +305,7 @@ func TestSetState_Invalid_Error(t *testing.T) { } func TestSetState_Valid_NoError(t *testing.T) { - evaluator := eval.JSONEvaluator{Logger: logger.NewLogger(nil)} + evaluator := eval.JSONEvaluator{Logger: logger.NewLogger(nil, false)} // set state with a valid flag definition _, err := evaluator.SetState("", ValidFlags) @@ -329,7 +329,7 @@ func TestResolveBooleanValue(t *testing.T) { {DisabledFlag, nil, StaticBoolValue, model.ErrorReason, model.FlagDisabledErrorCode}, } const reqID = "default" - evaluator := eval.JSONEvaluator{Logger: logger.NewLogger(nil)} + evaluator := eval.JSONEvaluator{Logger: logger.NewLogger(nil, false)} _, err := evaluator.SetState("", Flags) if err != nil { t.Fatalf("Expected no error") @@ -368,7 +368,7 @@ func TestResolveStringValue(t *testing.T) { {DisabledFlag, nil, "", model.ErrorReason, model.FlagDisabledErrorCode}, } const reqID = "default" - evaluator := eval.JSONEvaluator{Logger: logger.NewLogger(nil)} + evaluator := eval.JSONEvaluator{Logger: logger.NewLogger(nil, false)} _, err := evaluator.SetState("", Flags) if err != nil { t.Fatalf("Expected no error") @@ -408,7 +408,7 @@ func TestResolveFloatValue(t *testing.T) { {DisabledFlag, nil, 0, model.ErrorReason, model.FlagDisabledErrorCode}, } const reqID = "default" - evaluator := eval.JSONEvaluator{Logger: logger.NewLogger(nil)} + evaluator := eval.JSONEvaluator{Logger: logger.NewLogger(nil, false)} _, err := evaluator.SetState("", Flags) if err != nil { t.Fatalf("Expected no error") @@ -448,7 +448,7 @@ func TestResolveIntValue(t *testing.T) { {DisabledFlag, nil, 0, model.ErrorReason, model.FlagDisabledErrorCode}, } const reqID = "default" - evaluator := eval.JSONEvaluator{Logger: logger.NewLogger(nil)} + evaluator := eval.JSONEvaluator{Logger: logger.NewLogger(nil, false)} _, err := evaluator.SetState("", Flags) if err != nil { t.Fatalf("Expected no error") @@ -488,7 +488,7 @@ func TestResolveObjectValue(t *testing.T) { {DisabledFlag, nil, "{}", model.ErrorReason, model.FlagDisabledErrorCode}, } const reqID = "default" - evaluator := eval.JSONEvaluator{Logger: logger.NewLogger(nil)} + evaluator := eval.JSONEvaluator{Logger: logger.NewLogger(nil, false)} _, err := evaluator.SetState("", Flags) if err != nil { t.Fatalf("Expected no error") @@ -606,7 +606,7 @@ func TestMergeFlags(t *testing.T) { tt := tt t.Run(tt.name, func(t *testing.T) { t.Parallel() - got, _ := tt.current.Merge(logger.NewLogger(nil), tt.newSource, tt.new) + got, _ := tt.current.Merge(logger.NewLogger(nil, false), tt.newSource, tt.new) require.Equal(t, tt.want, got) }) } diff --git a/pkg/logger/logger.go b/pkg/logger/logger.go index f8f2dcd97..540e3a66a 100644 --- a/pkg/logger/logger.go +++ b/pkg/logger/logger.go @@ -40,9 +40,13 @@ type Logger struct { requestFields *sync.Map Logger *zap.Logger fields []zap.Field + reqIDLogging bool } func (l *Logger) DebugWithID(reqID string, msg string, fields ...zap.Field) { + if !l.reqIDLogging { + return + } if ce := l.Logger.Check(zap.DebugLevel, msg); ce != nil { fields = append(fields, l.getFieldsForLog(reqID)...) ce.Write(fields...) @@ -57,6 +61,9 @@ func (l *Logger) Debug(msg string, fields ...zap.Field) { } func (l *Logger) InfoWithID(reqID string, msg string, fields ...zap.Field) { + if !l.reqIDLogging { + return + } if ce := l.Logger.Check(zap.InfoLevel, msg); ce != nil { fields = append(fields, l.getFieldsForLog(reqID)...) ce.Write(fields...) @@ -71,6 +78,9 @@ func (l *Logger) Info(msg string, fields ...zap.Field) { } func (l *Logger) WarnWithID(reqID string, msg string, fields ...zap.Field) { + if !l.reqIDLogging { + return + } if ce := l.Logger.Check(zap.WarnLevel, msg); ce != nil { fields = append(fields, l.getFieldsForLog(reqID)...) ce.Write(fields...) @@ -85,6 +95,9 @@ func (l *Logger) Warn(msg string, fields ...zap.Field) { } func (l *Logger) ErrorWithID(reqID string, msg string, fields ...zap.Field) { + if !l.reqIDLogging { + return + } if ce := l.Logger.Check(zap.ErrorLevel, msg); ce != nil { fields = append(fields, l.getFieldsForLog(reqID)...) ce.Write(fields...) @@ -99,6 +112,9 @@ func (l *Logger) Error(msg string, fields ...zap.Field) { } func (l *Logger) FatalWithID(reqID string, msg string, fields ...zap.Field) { + if !l.reqIDLogging { + return + } if ce := l.Logger.Check(zap.FatalLevel, msg); ce != nil { fields = append(fields, l.getFieldsForLog(reqID)...) ce.Write(fields...) @@ -115,6 +131,9 @@ func (l *Logger) Fatal(msg string, fields ...zap.Field) { // WriteFields adds field key and value pairs to the highest level Logger, they will be applied to all // subsequent log calls using the matching requestID func (l *Logger) WriteFields(reqID string, fields ...zap.Field) { + if !l.reqIDLogging { + return + } res := append(l.getFields(reqID), fields...) l.requestFields.Store(reqID, res) } @@ -140,6 +159,9 @@ func (l *Logger) getFieldsForLog(reqID string) []zap.Field { // ClearFields clears all stored fields for a given requestID, important for maintaining performance func (l *Logger) ClearFields(reqID string) { + if !l.reqIDLogging { + return + } l.requestFields.Delete(reqID) } @@ -169,15 +191,19 @@ func NewZapLogger(level zapcore.Level) (*zap.Logger, error) { return cfg.Build() } -// NewLogger returns the logging wrapper for a given *zap.logger, -// will return a wrapped zap noop logger if none is provided -func NewLogger(logger *zap.Logger) *Logger { +// NewLogger returns the logging wrapper for a given *zap.logger. +// Noop logger bypasses the setting of fields, improving performance. +// If *zap.Logger is nil a noop logger is set +// and the reqIDLogging argument is overwritten to false +func NewLogger(logger *zap.Logger, reqIDLogging bool) *Logger { if logger == nil { + reqIDLogging = false logger = zap.New(nil) } return &Logger{ Logger: logger.WithOptions(zap.AddCallerSkip(1)), requestFields: &sync.Map{}, + reqIDLogging: reqIDLogging, } } @@ -189,5 +215,6 @@ func (l *Logger) WithFields(fields ...zap.Field) *Logger { Logger: l.Logger, requestFields: l.requestFields, fields: fields, + reqIDLogging: l.reqIDLogging, } } diff --git a/pkg/logger/logger_test.go b/pkg/logger/logger_test.go index 3b13e7077..b05759fac 100644 --- a/pkg/logger/logger_test.go +++ b/pkg/logger/logger_test.go @@ -20,7 +20,7 @@ func TestFieldStorageAndRetrieval(t *testing.T) { }, } for name, test := range tests { - l := NewLogger(nil) + l := NewLogger(&zap.Logger{}, true) l.WriteFields(name, test.fields...) returnedFields := l.getFields(name) if !reflect.DeepEqual(returnedFields, test.fields) { @@ -32,7 +32,7 @@ func TestFieldStorageAndRetrieval(t *testing.T) { func TestLoggerChildOperation(t *testing.T) { id := "test" // create parent logger - p := NewLogger(nil) + p := NewLogger(&zap.Logger{}, true) // add field 1 field1 := zap.Int("field", 1) p.WriteFields(id, field1) diff --git a/pkg/service/connect_service_test.go b/pkg/service/connect_service_test.go index 509fe332e..5de33c7ed 100644 --- a/pkg/service/connect_service_test.go +++ b/pkg/service/connect_service_test.go @@ -87,7 +87,7 @@ func TestConnectService_UnixConnection(t *testing.T) { ConnectServiceConfiguration: &service.ConnectServiceConfiguration{ ServerSocketPath: tt.socketPath, }, - Logger: logger.NewLogger(nil), + Logger: logger.NewLogger(nil, false), } ctx := context.Background() ctx, cancel := context.WithTimeout(ctx, 5*time.Second) @@ -181,7 +181,7 @@ func TestConnectService_ResolveBoolean(t *testing.T) { ).AnyTimes() s := service.ConnectService{ Eval: eval, - Logger: logger.NewLogger(nil), + Logger: logger.NewLogger(nil, false), } got, err := s.ResolveBoolean(tt.functionArgs.ctx, connect.NewRequest(tt.functionArgs.req)) if err != nil && !errors.Is(err, tt.wantErr) { @@ -229,7 +229,7 @@ func BenchmarkConnectService_ResolveBoolean(b *testing.B) { ).AnyTimes() s := service.ConnectService{ Eval: eval, - Logger: logger.NewLogger(nil), + Logger: logger.NewLogger(nil, false), } b.Run(name, func(b *testing.B) { for i := 0; i < b.N; i++ { @@ -315,7 +315,7 @@ func TestConnectService_ResolveString(t *testing.T) { ) s := service.ConnectService{ Eval: eval, - Logger: logger.NewLogger(nil), + Logger: logger.NewLogger(nil, false), } got, err := s.ResolveString(tt.functionArgs.ctx, connect.NewRequest(tt.functionArgs.req)) if (err != nil) && !errors.Is(err, tt.wantErr) { @@ -364,7 +364,7 @@ func BenchmarkConnectService_ResolveString(b *testing.B) { s := service.ConnectService{ Eval: eval, - Logger: logger.NewLogger(nil), + Logger: logger.NewLogger(nil, false), } b.Run(name, func(b *testing.B) { for i := 0; i < b.N; i++ { @@ -450,7 +450,7 @@ func TestConnectService_ResolveFloat(t *testing.T) { ).AnyTimes() s := service.ConnectService{ Eval: eval, - Logger: logger.NewLogger(nil), + Logger: logger.NewLogger(nil, false), } got, err := s.ResolveFloat(tt.functionArgs.ctx, connect.NewRequest(tt.functionArgs.req)) if (err != nil) && !errors.Is(err, tt.wantErr) { @@ -499,7 +499,7 @@ func BenchmarkConnectService_ResolveFloat(b *testing.B) { s := service.ConnectService{ Eval: eval, - Logger: logger.NewLogger(nil), + Logger: logger.NewLogger(nil, false), } b.Run(name, func(b *testing.B) { for i := 0; i < b.N; i++ { @@ -585,7 +585,7 @@ func TestConnectService_ResolveInt(t *testing.T) { ).AnyTimes() s := service.ConnectService{ Eval: eval, - Logger: logger.NewLogger(nil), + Logger: logger.NewLogger(nil, false), } got, err := s.ResolveInt(tt.functionArgs.ctx, connect.NewRequest(tt.functionArgs.req)) if (err != nil) && !errors.Is(err, tt.wantErr) { @@ -634,7 +634,7 @@ func BenchmarkConnectService_ResolveInt(b *testing.B) { s := service.ConnectService{ Eval: eval, - Logger: logger.NewLogger(nil), + Logger: logger.NewLogger(nil, false), } b.Run(name, func(b *testing.B) { for i := 0; i < b.N; i++ { @@ -724,7 +724,7 @@ func TestConnectService_ResolveObject(t *testing.T) { ).AnyTimes() s := service.ConnectService{ Eval: eval, - Logger: logger.NewLogger(nil), + Logger: logger.NewLogger(nil, false), } if name != "eval returns error" { @@ -783,7 +783,7 @@ func BenchmarkConnectService_ResolveObject(b *testing.B) { s := service.ConnectService{ Eval: eval, - Logger: logger.NewLogger(nil), + Logger: logger.NewLogger(nil, false), } if name != "eval returns error" { outParsed, err := structpb.NewStruct(tt.evalFields.result) diff --git a/pkg/sync/filepath_sync_test.go b/pkg/sync/filepath_sync_test.go index c7f216faa..2f1cf295f 100644 --- a/pkg/sync/filepath_sync_test.go +++ b/pkg/sync/filepath_sync_test.go @@ -74,7 +74,7 @@ func TestFilePathSync_Notify(t *testing.T) { fpSync := sync.FilePathSync{ URI: dirName, - Logger: logger.NewLogger(nil), + Logger: logger.NewLogger(nil, false), } inotifyChan := make(chan sync.INotify) @@ -118,7 +118,7 @@ func TestFilePathSync_Fetch(t *testing.T) { "success": { fpSync: sync.FilePathSync{ URI: fmt.Sprintf("%s/%s", dirName, fetchFileName), - Logger: logger.NewLogger(nil), + Logger: logger.NewLogger(nil, false), }, handleResponse: func(t *testing.T, fetched string, err error) { if err != nil { @@ -133,7 +133,7 @@ func TestFilePathSync_Fetch(t *testing.T) { "not found": { fpSync: sync.FilePathSync{ URI: fmt.Sprintf("%s/%s", dirName, "not_found"), - Logger: logger.NewLogger(nil), + Logger: logger.NewLogger(nil, false), }, handleResponse: func(t *testing.T, fetched string, err error) { if err == nil { diff --git a/pkg/sync/http_sync_test.go b/pkg/sync/http_sync_test.go index 1e8fb2ad3..b4ca52cc3 100644 --- a/pkg/sync/http_sync_test.go +++ b/pkg/sync/http_sync_test.go @@ -105,7 +105,7 @@ func TestHTTPSync_Fetch(t *testing.T) { Client: mockClient, BearerToken: tt.bearerToken, LastBodySHA: tt.lastBodySHA, - Logger: logger.NewLogger(nil), + Logger: logger.NewLogger(nil, false), } fetched, err := httpSync.Fetch(context.Background()) @@ -188,7 +188,7 @@ func TestHTTPSync_Notify(t *testing.T) { Client: mockClient, Cron: mockCron, LastBodySHA: tt.lastBodySHA, - Logger: logger.NewLogger(nil), + Logger: logger.NewLogger(nil, false), } go func() {