diff --git a/analytics.go b/analytics.go index 8cb0d14b..189d421c 100644 --- a/analytics.go +++ b/analytics.go @@ -36,12 +36,16 @@ func NewAnalyticsProcessor(ctx context.Context, client *resty.Client, baseURL st endpoint: baseURL + AnalyticsEndpoint, log: log, } + log.Debugf("analytics processor starting") go processor.start(ctx, tickerInterval) return &processor } func (a *AnalyticsProcessor) start(ctx context.Context, tickerInterval int) { ticker := time.NewTicker(time.Duration(tickerInterval) * time.Millisecond) + defer func() { + a.log.Debugf("analytics processor stopped") + }() for { select { case <-ticker.C: diff --git a/analytics_test.go b/analytics_test.go index 3bffef28..6572e233 100644 --- a/analytics_test.go +++ b/analytics_test.go @@ -43,7 +43,7 @@ func TestAnalytics(t *testing.T) { client.SetHeader("X-Environment-Key", EnvironmentAPIKey) // Now let's create the processor - processor := NewAnalyticsProcessor(context.Background(), client, server.URL+"/api/v1/", &analyticsTimer, createLogger()) + processor := NewAnalyticsProcessor(context.Background(), client, server.URL+"/api/v1/", &analyticsTimer, newSlogToLoggerAdapter(createLogger())) // and, track some features processor.TrackFeature("feature_1") diff --git a/client.go b/client.go index ac3e4f6f..eccc2367 100644 --- a/client.go +++ b/client.go @@ -3,6 +3,7 @@ package flagsmith import ( "context" "fmt" + "log/slog" "strings" "sync/atomic" "time" @@ -34,7 +35,7 @@ type Client struct { client *resty.Client ctxLocalEval context.Context ctxAnalytics context.Context - log Logger + log *slog.Logger offlineHandler OfflineHandler errorHandler func(handler *FlagsmithAPIError) } @@ -70,7 +71,21 @@ func NewClient(apiKey string, options ...Option) *Client { opt(c) } } - c.client.SetLogger(c.log) + c.client = c.client. + SetLogger(newSlogToRestyAdapter(c.log)). + OnBeforeRequest(newRestyLogRequestMiddleware(c.log)). + OnAfterResponse(newRestyLogResponseMiddleware(c.log)) + + c.log.Debug("initialising Flagsmith client", + "base_url", c.config.baseURL, + "local_evaluation", c.config.localEvaluation, + "offline", c.config.offlineMode, + "analytics", c.config.enableAnalytics, + "realtime", c.config.useRealtime, + "realtime_url", c.config.realtimeBaseUrl, + "env_refresh_interval", c.config.envRefreshInterval, + "timeout", c.config.timeout, + ) if c.config.offlineMode && c.offlineHandler == nil { panic("offline handler must be provided to use offline mode.") @@ -97,7 +112,15 @@ func NewClient(apiKey string, options ...Option) *Client { } // Initialise analytics processor if c.config.enableAnalytics { - c.analyticsProcessor = NewAnalyticsProcessor(c.ctxAnalytics, c.client, c.config.baseURL, nil, c.log) + c.analyticsProcessor = NewAnalyticsProcessor( + c.ctxAnalytics, + c.client, + c.config.baseURL, + nil, + newSlogToLoggerAdapter( + c.log.With(slog.String("worker", "analytics")), + ), + ) } return c } @@ -319,7 +342,7 @@ func (c *Client) pollEnvironment(ctx context.Context) { defer cancel() err := c.UpdateEnvironment(ctx) if err != nil { - c.log.Errorf("Failed to update environment: %v", err) + c.log.Error("failed to update environment", "error", err) } } update() @@ -364,6 +387,7 @@ func (c *Client) UpdateEnvironment(ctx context.Context) error { } c.identitiesWithOverrides.Store(identitiesWithOverrides) + c.log.Info("environment updated", "environment", env.APIKey) return nil } diff --git a/client_test.go b/client_test.go index 4897aad7..0508593e 100644 --- a/client_test.go +++ b/client_test.go @@ -5,8 +5,10 @@ import ( "errors" "fmt" "io" + "log/slog" "net/http" "net/http/httptest" + "strings" "sync" "testing" "time" @@ -959,3 +961,19 @@ data: {"updated_at": %f} // Flush the event to the client flusher.Flush() } + +func TestWithSlogLogger(t *testing.T) { + // Given + var logOutput strings.Builder + slogLogger := slog.New(slog.NewTextHandler(&logOutput, &slog.HandlerOptions{ + Level: slog.LevelDebug, + })) + + // When + _ = flagsmith.NewClient(fixtures.EnvironmentAPIKey, flagsmith.WithSlogLogger(slogLogger)) + + // Then + logStr := logOutput.String() + t.Log(logStr) + assert.Contains(t, logStr, "initialising Flagsmith client") +} diff --git a/logger.go b/logger.go index 2e876e1d..e8dad1f3 100644 --- a/logger.go +++ b/logger.go @@ -1,8 +1,14 @@ package flagsmith import ( - "log" + "context" + "fmt" + "log/slog" "os" + "strings" + "time" + + "github.com/go-resty/resty/v2" ) // Logger is the interface used for logging by flagsmith client. This interface defines the methods @@ -19,33 +25,140 @@ type Logger interface { Debugf(format string, v ...interface{}) } -func createLogger() *logger { - l := &logger{l: log.New(os.Stderr, "", log.Ldate|log.Lmicroseconds)} - return l +// slogToRestyAdapter adapts a slog.Logger to resty.Logger. +type slogToRestyAdapter struct { + logger *slog.Logger +} + +func newSlogToRestyAdapter(logger *slog.Logger) *slogToRestyAdapter { + return &slogToRestyAdapter{logger: logger} +} + +func (l *slogToRestyAdapter) Errorf(format string, v ...interface{}) { + l.logger.Error(format, v...) +} + +func (l *slogToRestyAdapter) Warnf(format string, v ...interface{}) { + l.logger.Warn(format, v...) +} + +func (l *slogToRestyAdapter) Debugf(format string, v ...interface{}) { + l.logger.Debug(format, v...) } -var _ Logger = (*logger)(nil) +// slogToLoggerAdapter adapts a slog.Logger to our Logger interface. +type slogToLoggerAdapter struct { + logger *slog.Logger +} + +func newSlogToLoggerAdapter(logger *slog.Logger) *slogToLoggerAdapter { + return &slogToLoggerAdapter{logger: logger} +} + +func (l *slogToLoggerAdapter) Errorf(format string, v ...interface{}) { + l.logger.Error(fmt.Sprintf(format, v...)) +} -type logger struct { - l *log.Logger +func (l *slogToLoggerAdapter) Warnf(format string, v ...interface{}) { + l.logger.Warn(fmt.Sprintf(format, v...)) } -func (l *logger) Errorf(format string, v ...interface{}) { - l.output("ERROR FLAGSMITH: "+format, v...) +func (l *slogToLoggerAdapter) Debugf(format string, v ...interface{}) { + l.logger.Debug(fmt.Sprintf(format, v...)) } -func (l *logger) Warnf(format string, v ...interface{}) { - l.output("WARN FLAGSMITH: "+format, v...) +// loggerToSlogAdapter adapts our Logger interface to a slog.Logger. +type loggerToSlogAdapter struct { + logger Logger } -func (l *logger) Debugf(format string, v ...interface{}) { - l.output("DEBUG FLAGSMITH: "+format, v...) +func newLoggerToSlogAdapter(logger Logger) *slog.Logger { + return slog.New(&loggerToSlogAdapter{logger: logger}) } -func (l *logger) output(format string, v ...interface{}) { - if len(v) == 0 { - l.l.Print(format) - return +// implement slog.Handler interface to adapt our Logger interface to a slog.Logger + +func (l *loggerToSlogAdapter) Enabled(ctx context.Context, level slog.Level) bool { + return true +} + +func (l *loggerToSlogAdapter) Handle(ctx context.Context, r slog.Record) error { + msg := r.Message + var attrs strings.Builder + r.Attrs(func(a slog.Attr) bool { + attrs.WriteString(a.String() + " ") + return true + }) + msg += attrs.String() + + switch r.Level { + case slog.LevelError: + l.logger.Errorf(msg) + case slog.LevelWarn: + l.logger.Warnf(msg) + case slog.LevelDebug: + l.logger.Debugf(msg) + } + return nil +} + +func (l *loggerToSlogAdapter) WithAttrs(_ []slog.Attr) slog.Handler { + return l +} + +func (l *loggerToSlogAdapter) WithGroup(_ string) slog.Handler { + return l +} + +func createLogger() *slog.Logger { + return slog.New(slog.NewTextHandler(os.Stderr, &slog.HandlerOptions{ + Level: slog.LevelDebug, + })) +} + +const ( + contextLoggerKey contextKey = contextKey("logger") + contextStartTimeKey contextKey = contextKey("startTime") +) + +func newRestyLogRequestMiddleware(logger *slog.Logger) resty.RequestMiddleware { + return func(c *resty.Client, req *resty.Request) error { + // Create a child logger with request metadata + reqLogger := logger.WithGroup("http").With( + "method", req.Method, + "url", req.URL, + ) + reqLogger.Debug("request") + + // Store the logger in this request's context, and use it in the response + req.SetContext(context.WithValue(req.Context(), contextLoggerKey, reqLogger)) + + // Time the current request + req.SetContext(context.WithValue(req.Context(), contextStartTimeKey, time.Now())) + + return nil + } +} + +func newRestyLogResponseMiddleware(logger *slog.Logger) resty.ResponseMiddleware { + return func(client *resty.Client, resp *resty.Response) error { + // Retrieve the logger and start time from context + reqLogger, _ := resp.Request.Context().Value(contextLoggerKey).(*slog.Logger) + startTime, _ := resp.Request.Context().Value(contextStartTimeKey).(time.Time) + + if reqLogger == nil { + reqLogger = logger + } + reqLogger = reqLogger.With( + slog.Int("status", resp.StatusCode()), + slog.Duration("duration", time.Since(startTime)), + slog.Int64("content_length", resp.Size()), + ) + if resp.IsError() { + reqLogger.Error("error response") + } else { + reqLogger.Debug("response") + } + return nil } - l.l.Printf(format, v...) } diff --git a/options.go b/options.go index af919f9a..256231c6 100644 --- a/options.go +++ b/options.go @@ -4,6 +4,8 @@ import ( "context" "strings" "time" + + "log/slog" ) type Option func(c *Client) @@ -22,6 +24,8 @@ var _ = []Option{ WithProxy(""), WithRealtime(), WithRealtimeBaseURL(""), + WithLogger(nil), + WithSlogLogger(nil), } func WithBaseURL(url string) Option { @@ -93,6 +97,13 @@ func WithDefaultHandler(handler func(string) (Flag, error)) Option { // Allows the client to use any logger that implements the `Logger` interface. func WithLogger(logger Logger) Option { + return func(c *Client) { + c.log = newLoggerToSlogAdapter(logger) + } +} + +// WithSlogLogger allows the client to use a slog.Logger for logging. +func WithSlogLogger(logger *slog.Logger) Option { return func(c *Client) { c.log = logger } diff --git a/realtime.go b/realtime.go index 5227537d..06e0f73e 100644 --- a/realtime.go +++ b/realtime.go @@ -5,6 +5,7 @@ import ( "context" "encoding/json" "errors" + "log/slog" "net/http" "strings" "time" @@ -20,6 +21,13 @@ func (c *Client) startRealtimeUpdates(ctx context.Context) { env, _ := c.environment.Load().(*environments.EnvironmentModel) stream_url := c.config.realtimeBaseUrl + "sse/environments/" + env.APIKey + "/stream" envUpdatedAt := env.UpdatedAt + log := c.log.With( + slog.String("worker", "realtime"), + slog.String("stream", stream_url), + ) + defer func() { + log.Info("realtime stopped") + }() for { select { case <-ctx.Done(): @@ -27,10 +35,11 @@ func (c *Client) startRealtimeUpdates(ctx context.Context) { default: resp, err := http.Get(stream_url) if err != nil { - c.log.Errorf("Error connecting to realtime server: %v", err) + log.Error("failed to connect to realtime stream", "error", err) continue } defer resp.Body.Close() + log.Info("connected") scanner := bufio.NewScanner(resp.Body) for scanner.Scan() { @@ -38,23 +47,22 @@ func (c *Client) startRealtimeUpdates(ctx context.Context) { if strings.HasPrefix(line, "data: ") { parsedTime, err := parseUpdatedAtFromSSE(line) if err != nil { - c.log.Errorf("Error reading realtime stream: %v", err) + log.Error("failed to parse event message", "error", err, "message", line) continue } if parsedTime.After(envUpdatedAt) { err = c.UpdateEnvironment(ctx) if err != nil { - c.log.Errorf("Failed to update the environment: %v", err) + log.Error("failed to update environment after receiving event", "error", err) continue } env, _ := c.environment.Load().(*environments.EnvironmentModel) - envUpdatedAt = env.UpdatedAt } } } if err := scanner.Err(); err != nil { - c.log.Errorf("Error reading realtime stream: %v", err) + log.Error("error reading from realtime stream", "error", err) } } }