🔊 Improve Logging: move to slog and add trace level (#276)

* Add Warn and Trace loglevels * Move to slog * fixes * missing test file * Fix tests * Add wrapper with trace * fix * fix lint * LINT * LINT * 🍱 Use only 4 level of logs * fix after merge * 🍱 fix lint * 🍱 fix lint + remove trace logger from tests * 🍱 fix tests * 🍱 fix lint * 🍱 try to fix test * 🍱 Fix tests * 🍱 fix README + adjust logs --------- Co-authored-by: maxlerebourg <maxlerebourg@gmail.com>
2026-07-21 11:38:59 +02:00 · 2026-03-13 18:03:12 +01:00
parent e54c1d5c4f
commit 7f776fe0fe
11 changed files with 595 additions and 95 deletions
@@ -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)
@@ -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
@@ -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"
@@ -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
@@ -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 {
@@ -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")
 }
@@ -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")
+}