From 7f776fe0fe658f99b07312347166853f957110c3 Mon Sep 17 00:00:00 2001 From: David Date: Fri, 13 Mar 2026 18:03:12 +0100 Subject: [PATCH] =?UTF-8?q?=F0=9F=94=8A=20Improve=20Logging:=20move=20to?= =?UTF-8?q?=20slog=20and=20add=20trace=20level=20(#276)?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit * Add Warn and Trace loglevels * Move to slog * fixes * missing test file * Fix tests * Add wrapper with trace * fix * fix lint * LINT * LINT * :bento: Use only 4 level of logs * fix after merge * :bento: fix lint * :bento: fix lint + remove trace logger from tests * :bento: fix tests * :bento: fix lint * :bento: try to fix test * :bento: Fix tests * :bento: fix README + adjust logs --------- Co-authored-by: maxlerebourg --- .golangci.yml | 1 + README.md | 7 +- bouncer.go | 23 +- bouncer_logging_test.go | 320 ++++++++++++++++++++++++ pkg/cache/cache.go | 9 +- pkg/captcha/captcha.go | 6 +- pkg/configuration/configuration.go | 31 +-- pkg/configuration/configuration_test.go | 9 +- pkg/ip/ip.go | 5 +- pkg/logger/logger.go | 123 +++++---- pkg/logger/logger_test.go | 156 ++++++++++++ 11 files changed, 595 insertions(+), 95 deletions(-) create mode 100644 bouncer_logging_test.go create mode 100644 pkg/logger/logger_test.go diff --git a/.golangci.yml b/.golangci.yml index 78dd020..2a5e6de 100644 --- a/.golangci.yml +++ b/.golangci.yml @@ -73,6 +73,7 @@ linters: - gci - mnd - exportloopref + - contextcheck issues: exclude-use-default: false max-same-issues: 0 diff --git a/README.md b/README.md index 377b493..84bb9b0 100644 --- a/README.md +++ b/README.md @@ -329,8 +329,12 @@ make run - Enable the plugin - LogLevel - string - - default: `INFO`, expected values are: `INFO`, `DEBUG`, `ERROR` + - default: `INFO`, expected values are: `DEBUG`, `INFO`, `WARN`, `ERROR` - Log are written to `stdout` / `stderr` or file if LogFilePath is provided +- LogFormat + - string + - default: `common`, expected values are: `common`, `json` + - Log format: `common` for traditional text logs, `json` for structured JSON logs - LogFilePath - string - default: "" @@ -590,6 +594,7 @@ http: bouncer: enabled: false logLevel: DEBUG + logFormat: common LogFilePath: "" updateIntervalSeconds: 60 updateMaxFailure: 0 diff --git a/bouncer.go b/bouncer.go index f2ab596..0e2de43 100644 --- a/bouncer.go +++ b/bouncer.go @@ -11,6 +11,7 @@ import ( "fmt" htmltemplate "html/template" "io" + "log/slog" "net/http" "net/url" "strconv" @@ -117,7 +118,7 @@ type Bouncer struct { httpAppsecClient *http.Client cacheClient *cache.Client captchaClient *captcha.Client - log *logger.Log + log *slog.Logger } // New creates the crowdsec bouncer plugin. @@ -125,8 +126,8 @@ type Bouncer struct { //nolint:gocyclo func New(_ context.Context, next http.Handler, config *configuration.Config, name string) (http.Handler, error) { config.LogLevel = strings.ToUpper(config.LogLevel) - log := logger.New(config.LogLevel, config.LogFilePath) - err := configuration.ValidateParams(config) + log := logger.NewWithFormat(config.LogLevel, config.LogFilePath, config.LogFormat) + err := configuration.ValidateParams(config, log) if err != nil { log.Error("New:validateParams " + err.Error()) return nil, err @@ -455,7 +456,7 @@ func (bouncer *Bouncer) handleBanServeHTTP(rw http.ResponseWriter, req *http.Req err := bouncer.banTemplate.Execute(rw, templateData) if err != nil { - bouncer.log.Error("handleBanServeHTTP banTemplateServe " + err.Error()) + bouncer.log.Warn("handleBanServeHTTP could not write template to ResponseWriter: " + err.Error()) } } @@ -486,7 +487,7 @@ func (bouncer *Bouncer) handleNextServeHTTP(rw http.ResponseWriter, req *http.Re func handleStreamTicker(bouncer *Bouncer) { if err := handleStreamCache(bouncer); err != nil { - bouncer.log.Debug(fmt.Sprintf("handleStreamTicker updateFailure:%d isCrowdsecStreamHealthy:%t %s", updateFailure, isCrowdsecStreamHealthy, err.Error())) + bouncer.log.Warn(fmt.Sprintf("handleStreamTicker updateFailure:%d isCrowdsecStreamHealthy:%t %s", updateFailure, isCrowdsecStreamHealthy, err.Error())) if bouncer.updateMaxFailure != -1 && updateFailure >= bouncer.updateMaxFailure && isCrowdsecStreamHealthy { isCrowdsecStreamHealthy = false bouncer.log.Error(fmt.Sprintf("handleStreamTicker:error updateFailure:%d %s", updateFailure, err.Error())) @@ -504,7 +505,7 @@ func handleMetricsTicker(bouncer *Bouncer) { } } -func startTicker(name string, updateInterval int64, log *logger.Log, work func()) chan bool { +func startTicker(name string, updateInterval int64, log *slog.Logger, work func()) chan bool { ticker := time.NewTicker(time.Duration(updateInterval) * time.Second) stop := make(chan bool, 1) go func() { @@ -571,7 +572,7 @@ func handleNoStreamCache(bouncer *Bouncer, remoteIP string) (string, error) { case "captcha": value = cache.CaptchaValue default: - bouncer.log.Debug("handleStreamCache:unknownType " + decision.Type) + bouncer.log.Info("handleStreamCache:unknownType " + decision.Type) } if isLiveMode && bouncer.defaultDecisionTimeout > 0 { durationSecond := int64(duration.Seconds()) @@ -607,11 +608,11 @@ func getToken(bouncer *Bouncer) error { if err != nil { return fmt.Errorf("getToken:parsingBody %w", err) } - if login.Code == 200 && len(login.Token) > 0 { + if login.Code == http.StatusOK && len(login.Token) > 0 { bouncer.crowdsecKey = login.Token - bouncer.log.Debug(fmt.Sprintf("getToken statusCode:%d", login.Code)) return nil } + bouncer.log.Warn(fmt.Sprintf("getToken statusCode:%d", login.Code)) return fmt.Errorf("getToken statusCode:%d", login.Code) } @@ -654,7 +655,7 @@ func handleStreamCache(bouncer *Bouncer) error { case "captcha": value = cache.CaptchaValue default: - bouncer.log.Debug("handleStreamCache:unknownType " + decision.Type) + bouncer.log.Info("handleStreamCache:unknownType " + decision.Type) } bouncer.cacheClient.Set(decision.Value, value, int64(duration.Seconds())) } @@ -662,7 +663,7 @@ func handleStreamCache(bouncer *Bouncer) error { for _, decision := range stream.Deleted { bouncer.cacheClient.Delete(decision.Value) } - bouncer.log.Debug("handleStreamCache:updated") + bouncer.log.Info("handleStreamCache:updated") return nil } diff --git a/bouncer_logging_test.go b/bouncer_logging_test.go new file mode 100644 index 0000000..b2834d0 --- /dev/null +++ b/bouncer_logging_test.go @@ -0,0 +1,320 @@ +package crowdsec_bouncer_traefik_plugin //nolint:revive,stylecheck + +import ( + "context" + "encoding/json" + "net/http" + "net/http/httptest" + "os" + "path/filepath" + "strings" + "testing" + "time" + + "github.com/maxlerebourg/crowdsec-bouncer-traefik-plugin/pkg/configuration" +) + +// getTestConfig returns a minimal valid configuration for testing. +// Override specific fields by modifying the returned config. +func getTestConfig() *configuration.Config { + return &configuration.Config{ + Enabled: true, + LogLevel: "INFO", + LogFormat: "common", + LogFilePath: "", + CrowdsecMode: "none", + CrowdsecLapiKey: "test-key", + CrowdsecLapiHost: "localhost", + CrowdsecLapiScheme: "http", + UpdateIntervalSeconds: 60, + DefaultDecisionSeconds: 60, + HTTPTimeoutSeconds: 10, + ForwardedHeadersTrustedIPs: []string{"127.0.0.1"}, + ForwardedHeadersCustomName: "", + RemediationStatusCode: 403, + BanHTMLFilePath: "", + RemediationHeadersCustomName: "", + CaptchaProvider: "", + CaptchaSiteKey: "", + CaptchaSecretKey: "", + CaptchaGracePeriodSeconds: 1, + CaptchaHTMLFilePath: "", + RedisCacheEnabled: false, + RedisCacheHost: "", + RedisCachePassword: "", + RedisCacheDatabase: "", + RedisCacheUnreachableBlock: false, + CrowdsecAppsecEnabled: false, + CrowdsecAppsecHost: "", + CrowdsecAppsecPath: "", + CrowdsecAppsecFailureBlock: false, + CrowdsecAppsecUnreachableBlock: false, + CrowdsecLapiTLSInsecureVerify: true, + CrowdsecLapiTLSCertificateBouncer: "", + CrowdsecLapiTLSCertificateBouncerKey: "", + CrowdsecCapiMachineID: "", + CrowdsecCapiPassword: "", + CrowdsecCapiScenarios: []string{}, + UpdateMaxFailure: 0, + MetricsUpdateIntervalSeconds: 0, + } +} + +// Helper function to create and execute a bouncer request for testing +func createAndExecuteBouncerRequest(t *testing.T, config *configuration.Config) { + t.Helper() + + // Create a mock next handler + nextHandler := http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { + w.WriteHeader(http.StatusOK) + _, _ = w.Write([]byte("OK")) + }) + + // Create the bouncer plugin (this will initialize the logger with file output) + bouncerHandler, err := New(context.Background(), nextHandler, config, "test-bouncer") + if err != nil { + t.Fatalf("Failed to create bouncer: %v", err) + } + + // Create a test request to trigger logging + req := httptest.NewRequest(http.MethodGet, "http://example.com/test", nil) + req.RemoteAddr = "192.168.1.100:12345" // Use a non-trusted IP to trigger logging + rw := httptest.NewRecorder() + + // Process the request (this should generate log entries) + bouncerHandler.ServeHTTP(rw, req) + + // Give a moment for log writes to complete + time.Sleep(100 * time.Millisecond) +} + +// Helper function to parse log file and extract found levels +func parseLogFileAndExtractLevels(t *testing.T, logFile string) map[string]bool { + t.Helper() + + // Verify the log file was created and contains entries + if _, statErr := os.Stat(logFile); os.IsNotExist(statErr) { + t.Fatalf("Log file was not created: %s", logFile) + } + + // Read the log file content + // #nosec G304 - logFile is a test-generated temporary file path + logContent, err := os.ReadFile(logFile) + if err != nil { + t.Fatalf("Failed to read log file: %v", err) + } + + logString := string(logContent) + if len(logString) == 0 { + return make(map[string]bool) // Return empty map for empty log files + } + + // Parse and verify JSON log entries + lines := strings.Split(strings.TrimSpace(logString), "\n") + foundLevels := make(map[string]bool) + + for _, line := range lines { + if strings.TrimSpace(line) == "" { + continue + } + + var logEntry map[string]interface{} + if err := json.Unmarshal([]byte(line), &logEntry); err != nil { + t.Errorf("Invalid JSON log entry: %s, error: %v", line, err) + continue + } + + // Verify required fields + validateLogEntry(t, logEntry) + + // Track log levels we've seen + if level, ok := logEntry["level"].(string); ok { + foundLevels[level] = true + } + } + + return foundLevels +} + +// Helper function to validate log entry structure +func validateLogEntry(t *testing.T, logEntry map[string]interface{}) { + t.Helper() + + if logEntry["time"] == nil { + t.Error("Log entry missing 'time' field") + } + if logEntry["level"] == nil { + t.Error("Log entry missing 'level' field") + } + if logEntry["msg"] == nil { + t.Error("Log entry missing 'msg' field") + } + if logEntry["component"] != "CrowdsecBouncerTraefikPlugin" { + t.Errorf("Expected component 'CrowdsecBouncerTraefikPlugin', got %v", logEntry["component"]) + } +} + +// Helper function to verify expected and forbidden log levels +func verifyLogLevels(t *testing.T, foundLevels map[string]bool, expectedLevels, forbiddenLevels []string, logLevel string) { + t.Helper() + + // Handle case where no logs are expected + if len(expectedLevels) == 0 { + if len(foundLevels) > 0 { + t.Errorf("Expected no logs at %s level, but found: %v", logLevel, foundLevels) + } + } else { + // Verify we got some log entries + if len(foundLevels) == 0 { + t.Fatal("No valid log entries found") + } + + // Verify expected levels are present + for _, expectedLevel := range expectedLevels { + if !foundLevels[expectedLevel] { + t.Errorf("Expected to find %s level logs, but didn't. Found levels: %v", expectedLevel, foundLevels) + } + } + } + + // Verify forbidden levels are NOT present + for _, forbiddenLevel := range forbiddenLevels { + if foundLevels[forbiddenLevel] { + t.Errorf("Found forbidden %s level logs at %s level. Found levels: %v", forbiddenLevel, logLevel, foundLevels) + } + } +} + +func TestBouncerFileLoggingLevels(t *testing.T) { + tests := []struct { + name string + logLevel string + expectedLevels []string // Levels that should appear + forbiddenLevels []string // Levels that should NOT appear + }{ + { + name: "DEBUG level should show DEBUG only", + logLevel: "DEBUG", + expectedLevels: []string{"DEBUG"}, + forbiddenLevels: []string{}, + }, + { + name: "INFO level should show no logs (bouncer doesn't generate INFO during normal operation)", + logLevel: "INFO", + expectedLevels: []string{}, // No logs expected for normal operation + forbiddenLevels: []string{"DEBUG"}, + }, + } + + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + // Create temporary directory for log file + tmpDir := t.TempDir() + logFile := filepath.Join(tmpDir, "bouncer.log") + + // Get test config and override specific fields + config := getTestConfig() + config.LogLevel = tt.logLevel + config.LogFormat = "json" // Use JSON format for easier parsing + config.LogFilePath = logFile + + // Create and execute bouncer request + createAndExecuteBouncerRequest(t, config) + + // Parse log file and extract found levels + foundLevels := parseLogFileAndExtractLevels(t, logFile) + + // Handle empty log files for higher log levels (expected behavior) + if len(foundLevels) == 0 && len(tt.expectedLevels) > 0 { + t.Fatalf("Expected log entries but log file is empty for level %s", tt.logLevel) + } + if len(foundLevels) == 0 { + // Empty file is expected for this log level + t.Logf("LogLevel %s: No logs generated (expected behavior)", tt.logLevel) + return + } + + // Verify expected and forbidden log levels + verifyLogLevels(t, foundLevels, tt.expectedLevels, tt.forbiddenLevels, tt.logLevel) + + t.Logf("LogLevel %s: Successfully logged to file with levels: %v", tt.logLevel, foundLevels) + }) + } +} + +func TestBouncerFileLoggingCommonFormat(t *testing.T) { + // Create temporary directory for log file + tmpDir := t.TempDir() + logFile := filepath.Join(tmpDir, "bouncer-common.log") + + // Get test config and override specific fields + config := getTestConfig() + config.LogLevel = "DEBUG" + config.LogFormat = "common" // Use common format + config.LogFilePath = logFile + + // Create a mock next handler + nextHandler := http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { + w.WriteHeader(http.StatusOK) + _, _ = w.Write([]byte("OK")) + }) + + // Create the bouncer plugin + bouncerHandler, err := New(context.Background(), nextHandler, config, "test-bouncer") + if err != nil { + t.Fatalf("Failed to create bouncer: %v", err) + } + + // Create a test request to trigger logging + req := httptest.NewRequest(http.MethodGet, "http://example.com/test", nil) + req.RemoteAddr = "192.168.1.100:12345" + rw := httptest.NewRecorder() + + // Process the request + bouncerHandler.ServeHTTP(rw, req) + + // Give a moment for log writes to complete + time.Sleep(100 * time.Millisecond) + + // Verify the log file was created and contains entries + if _, statErr := os.Stat(logFile); os.IsNotExist(statErr) { + t.Fatalf("Log file was not created: %s", logFile) + } + + // Read the log file content + // #nosec G304 - logFile is a test-generated temporary file path + logContent, err := os.ReadFile(logFile) + if err != nil { + t.Fatalf("Failed to read log file: %v", err) + } + + logString := string(logContent) + if len(logString) == 0 { + t.Fatal("Log file is empty") + } + + // Verify common format structure + lines := strings.Split(strings.TrimSpace(logString), "\n") + foundDebug := false + + for _, line := range lines { + if strings.TrimSpace(line) == "" { + continue + } + + // Common format should contain time, level, msg, and component + if strings.Contains(line, "level=DEBUG") { + foundDebug = true + } + if !strings.Contains(line, "component=CrowdsecBouncerTraefikPlugin") { + t.Errorf("Log line missing component field: %s", line) + } + } + + // We should see DEBUG level logs since we set LogLevel to DEBUG + if !foundDebug { + t.Errorf("Expected to find DEBUG level logs in common format. Log content:\n%s", logString) + } + + t.Logf("Successfully logged to file %s in common format with %d lines", logFile, len(lines)) +} diff --git a/pkg/cache/cache.go b/pkg/cache/cache.go index fcfe6c2..e966638 100644 --- a/pkg/cache/cache.go +++ b/pkg/cache/cache.go @@ -5,11 +5,10 @@ package cache import ( "errors" "fmt" + "log/slog" ttl_map "github.com/leprosus/golang-ttl-map" simpleredis "github.com/maxlerebourg/simpleredis" - - logger "github.com/maxlerebourg/crowdsec-bouncer-traefik-plugin/pkg/logger" ) const ( @@ -53,7 +52,7 @@ func (localCache) delete(key string) { } type redisCache struct { - log *logger.Log + log *slog.Logger } func (redisCache) get(key string) (string, error) { @@ -93,11 +92,11 @@ type cacheInterface interface { // Client Cache client. type Client struct { cache cacheInterface - log *logger.Log + log *slog.Logger } // New Initialize cache client. -func (c *Client) New(log *logger.Log, isRedis bool, host, pass, database string) { +func (c *Client) New(log *slog.Logger, isRedis bool, host, pass, database string) { c.log = log if isRedis { redis.Init(host, pass, database) diff --git a/pkg/captcha/captcha.go b/pkg/captcha/captcha.go index 5686aaa..c356779 100644 --- a/pkg/captcha/captcha.go +++ b/pkg/captcha/captcha.go @@ -5,13 +5,13 @@ import ( "encoding/json" "fmt" "html/template" + "log/slog" "net/http" "net/url" "strings" cache "github.com/maxlerebourg/crowdsec-bouncer-traefik-plugin/pkg/cache" configuration "github.com/maxlerebourg/crowdsec-bouncer-traefik-plugin/pkg/configuration" - logger "github.com/maxlerebourg/crowdsec-bouncer-traefik-plugin/pkg/logger" ) // Client Captcha client. @@ -24,7 +24,7 @@ type Client struct { captchaTemplate *template.Template cacheClient *cache.Client httpClient *http.Client - log *logger.Log + log *slog.Logger infoProvider *infoProvider } @@ -59,7 +59,7 @@ var infoProviders = map[string]*infoProvider{ } // New Initialize captcha client. -func (c *Client) New(log *logger.Log, cacheClient *cache.Client, httpClient *http.Client, provider, js, key, response, validate, siteKey, secretKey, remediationCustomHeader, captchaTemplatePath string, gracePeriodSeconds int64) error { +func (c *Client) New(log *slog.Logger, cacheClient *cache.Client, httpClient *http.Client, provider, js, key, response, validate, siteKey, secretKey, remediationCustomHeader, captchaTemplatePath string, gracePeriodSeconds int64) error { c.Valid = provider != "" if !c.Valid { return nil diff --git a/pkg/configuration/configuration.go b/pkg/configuration/configuration.go index 8ad86ff..acd34ad 100644 --- a/pkg/configuration/configuration.go +++ b/pkg/configuration/configuration.go @@ -7,6 +7,7 @@ import ( "errors" "fmt" "html/template" + "log/slog" "net/http" "net/url" "os" @@ -16,7 +17,6 @@ import ( "strings" ip "github.com/maxlerebourg/crowdsec-bouncer-traefik-plugin/pkg/ip" - logger "github.com/maxlerebourg/crowdsec-bouncer-traefik-plugin/pkg/logger" ) // Enums for crowdsec mode. @@ -30,6 +30,7 @@ const ( HTTP = "http" LogDEBUG = "DEBUG" LogINFO = "INFO" + LogWARN = "WARN" LogERROR = "ERROR" ReasonTECH = "TECHNICAL_ISSUE" ReasonLAPI = "LAPI" @@ -44,6 +45,7 @@ const ( type Config struct { Enabled bool `json:"enabled,omitempty"` LogLevel string `json:"logLevel,omitempty"` + LogFormat string `json:"logFormat,omitempty"` LogFilePath string `json:"logFilePath,omitempty"` CrowdsecMode string `json:"crowdsecMode,omitempty"` CrowdsecAppsecEnabled bool `json:"crowdsecAppsecEnabled,omitempty"` @@ -124,6 +126,7 @@ func New() *Config { return &Config{ Enabled: false, LogLevel: LogINFO, + LogFormat: "common", LogFilePath: "", CrowdsecMode: LiveMode, CrowdsecAppsecEnabled: false, @@ -218,7 +221,7 @@ func GetHTMLTemplate(path string) (*template.Template, error) { // ValidateParams validate all the param gave by user. // //nolint:gocyclo,gocognit -func ValidateParams(config *Config) error { +func ValidateParams(config *Config, log *slog.Logger) error { if err := validateParamsRequired(config); err != nil { return err } @@ -227,10 +230,10 @@ func ValidateParams(config *Config) error { return err } - if err := validateParamsIPs(config.ForwardedHeadersTrustedIPs, "ForwardedHeadersTrustedIPs"); err != nil { + if err := validateParamsIPs(log, config.ForwardedHeadersTrustedIPs, "ForwardedHeadersTrustedIPs"); err != nil { return err } - if err := validateParamsIPs(config.ClientTrustedIPs, "ClientTrustedIPs"); err != nil { + if err := validateParamsIPs(log, config.ClientTrustedIPs, "ClientTrustedIPs"); err != nil { return err } @@ -317,8 +320,8 @@ func ValidateParams(config *Config) error { // Check logging configuration // to upper allow of anycase of log level - if !contains([]string{LogERROR, LogDEBUG, LogINFO}, strings.ToUpper(config.LogLevel)) { - return fmt.Errorf("LogLevel should be one of (%s,%s,%s)", LogDEBUG, LogINFO, LogERROR) + if !contains([]string{LogDEBUG, LogINFO, LogWARN, LogERROR}, strings.ToUpper(config.LogLevel)) { + return fmt.Errorf("LogLevel should be one of (%s,%s,%s,%s)", LogDEBUG, LogINFO, LogWARN, LogERROR) } if config.LogFilePath != "" { _, err = os.OpenFile(filepath.Clean(config.LogFilePath), os.O_APPEND|os.O_CREATE|os.O_WRONLY, 0600) @@ -366,9 +369,9 @@ func validateParamsTLS(config *Config) error { return nil } -func validateParamsIPs(listIP []string, key string) error { +func validateParamsIPs(log *slog.Logger, listIP []string, key string) error { if len(listIP) > 0 { - if _, err := ip.NewChecker(logger.New(LogINFO, ""), listIP); err != nil { + if _, err := ip.NewChecker(log, listIP); err != nil { return fmt.Errorf("%s must be a list of IP/CIDR :%w", key, err) } } @@ -446,17 +449,17 @@ func validateParamsRequired(config *Config) error { return nil } -func getTLSConfig(config *Config, log *logger.Log, prefix, scheme string, insecureVerify bool) (*tls.Config, error) { +func getTLSConfig(config *Config, log *slog.Logger, prefix, scheme string, insecureVerify bool) (*tls.Config, error) { tlsConfig := new(tls.Config) tlsConfig.RootCAs = x509.NewCertPool() if scheme != HTTPS { - log.Debug("getTLSConfigCrowdsec:" + prefix + "Scheme https:no") + log.Debug("getTLSConfig:" + prefix + "Scheme https:no") return tlsConfig, nil } //nolint:nestif if insecureVerify { tlsConfig.InsecureSkipVerify = true - log.Debug("getTLSConfigCrowdsec:" + prefix + "TLSInsecureVerify tlsInsecure:true") + log.Debug("getTLSConfig:" + prefix + "TLSInsecureVerify tlsInsecure:true") // If we return here and still want to use client auth this won't work // return tlsConfig, nil } else { @@ -468,9 +471,9 @@ func getTLSConfig(config *Config, log *logger.Log, prefix, scheme string, insecu if !tlsConfig.RootCAs.AppendCertsFromPEM([]byte(certAuthority)) { // here we return because if CrowdsecLapiTLSInsecureVerify is false // and CA not load, we can't communicate with https - return nil, errors.New("getTLSConfigCrowdsec:" + prefix + "cannot load CA and verify cert is enabled") + return nil, errors.New("getTLSConfig:" + prefix + " cannot load CA and verify cert is enabled") } - log.Debug("getTLSConfigCrowdsec:" + prefix + "TLSCertificateAuthority CA added successfully") + log.Debug("getTLSConfig:" + prefix + "TLSCertificateAuthority CA added successfully") } } certBouncer, err := GetVariable(config, prefix+"TLSCertificateBouncer") @@ -494,7 +497,7 @@ func getTLSConfig(config *Config, log *logger.Log, prefix, scheme string, insecu } // GetTLSConfigCrowdsec get TLS config from Config. -func GetTLSConfigCrowdsec(config *Config, log *logger.Log, isAppsec bool) (*tls.Config, error) { +func GetTLSConfigCrowdsec(config *Config, log *slog.Logger, isAppsec bool) (*tls.Config, error) { var prefix string if isAppsec && config.CrowdsecAppsecScheme != "" { prefix = "CrowdsecAppsec" diff --git a/pkg/configuration/configuration_test.go b/pkg/configuration/configuration_test.go index ad6ce49..5a735aa 100644 --- a/pkg/configuration/configuration_test.go +++ b/pkg/configuration/configuration_test.go @@ -72,6 +72,7 @@ func Test_GetVariable(t *testing.T) { } func Test_ValidateParams(t *testing.T) { + log := logger.New("INFO", "") cfg1 := New() cfg1.CrowdsecLapiKey = "test\n\n" cfg2 := New() @@ -117,7 +118,7 @@ func Test_ValidateParams(t *testing.T) { } for _, tt := range tests { t.Run(tt.name, func(t *testing.T) { - if err := ValidateParams(tt.args.config); (err != nil) != tt.wantErr { + if err := ValidateParams(tt.args.config, log); (err != nil) != tt.wantErr { t.Errorf("validateParams() error = %v, wantErr %v", err, tt.wantErr) } }) @@ -145,6 +146,7 @@ func Test_validateParamsTLS(t *testing.T) { } func Test_validateParamsIPs(t *testing.T) { + log := logger.New("INFO", "") type args struct { listIP []string key string @@ -164,7 +166,7 @@ func Test_validateParamsIPs(t *testing.T) { } for _, tt := range tests { t.Run(tt.name, func(t *testing.T) { - if err := validateParamsIPs(tt.args.listIP, tt.args.key); (err != nil) != tt.wantErr { + if err := validateParamsIPs(log, tt.args.listIP, tt.args.key); (err != nil) != tt.wantErr { t.Errorf("validateParamsIPs() error = %v, wantErr %v", err, tt.wantErr) } }) @@ -230,6 +232,7 @@ func Test_validateParamsAPIKey(t *testing.T) { } func Test_GetTLSConfigCrowdsec(t *testing.T) { + log := logger.New("INFO", "") type args struct { config *Config } @@ -243,7 +246,7 @@ func Test_GetTLSConfigCrowdsec(t *testing.T) { } for _, tt := range tests { t.Run(tt.name, func(t *testing.T) { - got, err := GetTLSConfigCrowdsec(tt.args.config, logger.New("INFO", ""), false) + got, err := GetTLSConfigCrowdsec(tt.args.config, log, false) if (err != nil) != tt.wantErr { t.Errorf("getTLSConfigCrowdsec() error = %v, wantErr %v", err, tt.wantErr) return diff --git a/pkg/ip/ip.go b/pkg/ip/ip.go index 9900957..50bc7ed 100644 --- a/pkg/ip/ip.go +++ b/pkg/ip/ip.go @@ -5,11 +5,10 @@ package ip import ( "errors" "fmt" + "log/slog" "net" "net/http" "strings" - - logger "github.com/maxlerebourg/crowdsec-bouncer-traefik-plugin/pkg/logger" ) // CHECKER @@ -21,7 +20,7 @@ type Checker struct { } // NewChecker builds a new Checker given a list of CIDR-Strings to trusted IPs. -func NewChecker(log *logger.Log, trustedIPs []string) (*Checker, error) { +func NewChecker(log *slog.Logger, trustedIPs []string) (*Checker, error) { checker := &Checker{} for _, ipMaskRaw := range trustedIPs { diff --git a/pkg/logger/logger.go b/pkg/logger/logger.go index a66cd19..da1696f 100644 --- a/pkg/logger/logger.go +++ b/pkg/logger/logger.go @@ -1,79 +1,92 @@ // Package logger implements utility routines to write to stdout and stderr. -// It supports trace, debug, info and error level +// It supports trace, debug, info, warn and error level using Go's standard log/slog package logger import ( - "fmt" - "io" - "log" + "log/slog" "os" "path/filepath" ) -// Log Logger struct. -type Log struct { - logError *log.Logger - logInfo *log.Logger - logDebug *log.Logger +// Custom log levels following slog best practices. +const ( + LevelDebug = slog.LevelDebug + LevelInfo = slog.LevelInfo + LevelWarn = slog.LevelWarn + LevelError = slog.LevelError +) + +// New creates a Log wrapper with default format (common). +func New(logLevel string, logFilePath string) *slog.Logger { + return NewWithFormat(logLevel, logFilePath, "common") } -// New Set Default log level to info in case log level to defined. -func New(logLevel string, logFilePath string) *Log { - // Initialize loggers with discard output - logError := log.New(io.Discard, "ERROR: CrowdsecBouncerTraefikPlugin: ", log.Ldate|log.Ltime) - logInfo := log.New(io.Discard, "INFO: CrowdsecBouncerTraefikPlugin: ", log.Ldate|log.Ltime) - logDebug := log.New(io.Discard, "DEBUG: CrowdsecBouncerTraefikPlugin: ", log.Ldate|log.Ltime) +// NewWithFormat creates a Log wrapper with specified format (common or json). +func NewWithFormat(logLevel, logFilePath, logFormat string) *slog.Logger { + // Determine log level + var level slog.Level + switch logLevel { + case "ERROR": + level = LevelError + case "WARN": + level = LevelWarn + case "INFO": + level = LevelInfo + case "DEBUG": + level = LevelDebug + default: + // Default to INFO level + level = LevelInfo + } - // we initialize logger to STDOUT/STDERR first so if the file logger cannot be initialized we can inform the user - output := os.Stdout - errorOutput := os.Stderr - - // prepare file logging if specified + // Set output destination + var output *os.File if logFilePath != "" { logFile, err := os.OpenFile(filepath.Clean(logFilePath), os.O_APPEND|os.O_CREATE|os.O_WRONLY, 0600) if err == nil { output = logFile - errorOutput = logFile } else { - _ = fmt.Errorf("LogFilePath is not writable %w", err) + // Fall back to stdout and log the error + output = os.Stdout + slog.Warn("LogFilePath is not writable, using stdout", "error", err) } + } else { + output = os.Stdout } - // Set error logger output - logError.SetOutput(errorOutput) - - // Configure log levels - switch logLevel { - case "ERROR": - // Only error logging is enabled - case "INFO": - logInfo.SetOutput(output) - case "DEBUG": - logInfo.SetOutput(output) - logDebug.SetOutput(output) - default: - // Default to INFO level - logInfo.SetOutput(output) + // Create handler based on format with custom level names + var handler slog.Handler + opts := &slog.HandlerOptions{ + Level: level, + ReplaceAttr: func(_ []string, a slog.Attr) slog.Attr { + // Customize level names to match our expected format + if a.Key == slog.LevelKey { + lvl, ok := a.Value.Any().(slog.Level) + if !ok { + return a + } + switch { + case lvl < LevelInfo: + a.Value = slog.StringValue("DEBUG") + case lvl < LevelWarn: + a.Value = slog.StringValue("INFO") + case lvl < LevelError: + a.Value = slog.StringValue("WARN") + default: + a.Value = slog.StringValue("ERROR") + } + } + return a + }, } - return &Log{ - logError: logError, - logInfo: logInfo, - logDebug: logDebug, + if logFormat == "json" { + handler = slog.NewJSONHandler(output, opts) + } else { + // Common format (default) + handler = slog.NewTextHandler(output, opts) } -} -// Info log to Stdout. -func (l *Log) Info(str string) { - l.logInfo.Printf("%s", str) -} - -// Debug log to Stdout. -func (l *Log) Debug(str string) { - l.logDebug.Printf("%s", str) -} - -// Error log to Stderr. -func (l *Log) Error(str string) { - l.logError.Printf("%s", str) + // Create logger with component attribute + return slog.New(handler).With("component", "CrowdsecBouncerTraefikPlugin") } diff --git a/pkg/logger/logger_test.go b/pkg/logger/logger_test.go new file mode 100644 index 0000000..f4bfa7a --- /dev/null +++ b/pkg/logger/logger_test.go @@ -0,0 +1,156 @@ +package logger + +import ( + "bytes" + "encoding/json" + "log/slog" + "strings" + "testing" +) + +func TestNew(t *testing.T) { + tests := []struct { + name string + logLevel string + }{ + {name: "ERROR level", logLevel: "ERROR"}, + {name: "WARN level", logLevel: "WARN"}, + {name: "INFO level", logLevel: "INFO"}, + {name: "DEBUG level", logLevel: "DEBUG"}, + {name: "Default level (INFO)", logLevel: "INVALID"}, + } + + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + logger := New(tt.logLevel, "") + + // Verify logger is created + if logger == nil { + t.Fatal("Expected logger to be created, got nil") + } + + // Verify it's a slog.Logger (we can call methods on it) + logger.Info("test initialization") + }) + } +} + +func TestJSONLogFormat(t *testing.T) { + var buf bytes.Buffer + + // Create a logger with JSON handler to capture output + handler := slog.NewJSONHandler(&buf, &slog.HandlerOptions{Level: slog.LevelInfo}) + logger := slog.New(handler).With("component", "CrowdsecBouncerTraefikPlugin") + + testMessage := "json test message" + logger.Info(testMessage) + + output := buf.String() + lines := strings.Split(strings.TrimSpace(output), "\n") + + if len(lines) != 1 { + t.Fatalf("Expected 1 log line, got %d", len(lines)) + } + + // Verify it's valid JSON + var logEntry map[string]interface{} + err := json.Unmarshal([]byte(lines[0]), &logEntry) + if err != nil { + t.Fatalf("Expected valid JSON output, got error: %v, output: %s", err, output) + } + + // Verify JSON structure + if logEntry["level"] != "INFO" { + t.Errorf("Expected level 'INFO', got '%v'", logEntry["level"]) + } + if logEntry["msg"] != testMessage { + t.Errorf("Expected message '%s', got '%v'", testMessage, logEntry["msg"]) + } + if logEntry["time"] == nil { + t.Error("Expected timestamp to be set") + } + if logEntry["component"] != "CrowdsecBouncerTraefikPlugin" { + t.Errorf("Expected component 'CrowdsecBouncerTraefikPlugin', got '%v'", logEntry["component"]) + } +} + +func TestCommonLogFormat(t *testing.T) { + var buf bytes.Buffer + + // Create a logger with text handler to capture output + handler := slog.NewTextHandler(&buf, &slog.HandlerOptions{Level: slog.LevelInfo}) + logger := slog.New(handler).With("component", "CrowdsecBouncerTraefikPlugin") + + testMessage := "common test message" + logger.Info(testMessage) + + output := buf.String() + + // Verify common format (should contain level and message) + if !strings.Contains(output, "level=INFO") { + t.Error("Expected common format with INFO level") + } + if !strings.Contains(output, testMessage) { + t.Error("Expected test message in common format") + } + if !strings.Contains(output, "component=CrowdsecBouncerTraefikPlugin") { + t.Error("Expected component field in common format") + } + + // Should NOT be JSON (should be slog text format) + var logEntry map[string]interface{} + err := json.Unmarshal([]byte(strings.TrimSpace(output)), &logEntry) + if err == nil { + t.Error("Expected common format (not JSON), but got valid JSON") + } +} + +func TestErrorLevel(t *testing.T) { + var buf bytes.Buffer + + // Create a logger with ERROR level to capture output + handler := slog.NewTextHandler(&buf, &slog.HandlerOptions{Level: slog.LevelError}) + logger := slog.New(handler).With("component", "CrowdsecBouncerTraefikPlugin") + + testMessage := "error only test" + + // Test all log methods + logger.Error(testMessage) + logger.Warn(testMessage) // Should not appear + logger.Info(testMessage) // Should not appear + logger.Debug(testMessage) // Should not appear + + output := buf.String() + + // Only ERROR should appear + if !strings.Contains(output, "level=ERROR") { + t.Error("Expected ERROR message to appear") + } + + // Other levels should NOT appear + unwantedLevels := []string{"level=WARN", "level=INFO", "level=DEBUG"} + for _, level := range unwantedLevels { + if strings.Contains(output, level) { + t.Errorf("Unexpected %s message appeared at ERROR level", level) + } + } + + // Verify only one message appears + messageCount := strings.Count(output, testMessage) + if messageCount != 1 { + t.Errorf("Expected 1 occurrence of test message at ERROR level, got %d", messageCount) + } +} + +func TestInvalidLogFile(t *testing.T) { + // Try to create logger with invalid file path + logger := New("INFO", "/invalid/path/that/does/not/exist/test.log") + + // Logger should still be created (falls back to stdout) + if logger == nil { + t.Fatal("Expected logger to be created even with invalid file path") + } + + // Should not panic when logging + logger.Info("test message") +}