Merge pull request #2 from juitde/logging

Add logging to plugin

.traefik.yml

@@ -4,7 +4,7 @@ type: middleware
 
 import: github.com/juitde/traefik-plugin-fail2ban
 
-summary: 'Block or allow IPs depending on various conditions'
+summary: 'Block or allow IPs depending on various conditions (requires Traefik >= 2.10.0)'
 
 testData:
   enabled: true

README.md

@@ -13,6 +13,13 @@ Inspirations taken from:
 
 Installation instructions are provided via the [traefik Plugin Catalog](https://plugins.traefik.io/plugins/).
 
+### CAUTION: Breaking Changes
+
+#### Version 0.2.0
+
+- traefik v2.10+ is required due to now having a vendored dependency which results
+  in go routine panics in previous traefik versions.
+
 ## Configuration
 
 All configuration options may be specified either in config files or as CLI parameters.

docker-compose.yml

@@ -2,7 +2,7 @@ version: '3.8'
 
 services:
   traefik:
-    image: traefik:v2.9
+    image: traefik:v2.10
     ports:
       - target: 8080
         published: 8080

fail2ban.go

@@ -11,6 +11,8 @@ import (
 	"strconv"
 	"strings"
 	"time"
+
+	"github.com/zerodha/logf"
 )
 
 type configIPSpec struct {
@@ -64,6 +66,7 @@ type Fail2Ban struct {
 	next                http.Handler
 	name                string
 	cache               *Cache
+	logger              *logf.Logger
 	enabled             bool
 	staticAllowedIPNets []*net.IPNet
 	staticDeniedIPNets  []*net.IPNet
@@ -147,11 +150,12 @@ func parseResponseRules(config configResponse) responseRules {
 }
 
 // New creates a Fail2Ban plugin instance.
-func New(ctx context.Context, next http.Handler, config *Config, name string) (http.Handler, error) {
+func New(_ context.Context, next http.Handler, config *Config, name string) (http.Handler, error) {
 	return &Fail2Ban{
 		next:                next,
 		name:                name,
 		cache:               NewCache(),
+		logger:              NewLogger(config.LogLevel),
 		enabled:             config.Enabled,
 		staticAllowedIPNets: parseConfigIPList(config.AlwaysAllowed.IP),
 		staticDeniedIPNets:  parseConfigIPList(config.AlwaysDenied.IP),
@@ -164,25 +168,32 @@ func New(ctx context.Context, next http.Handler, config *Config, name string) (h
 
 func (a *Fail2Ban) ServeHTTP(responseWriter http.ResponseWriter, request *http.Request) {
 	if !a.enabled {
+		a.logger.Debug("Handler is not enabled. Skipping.", "phase", "accept_request")
 		a.next.ServeHTTP(responseWriter, request)
 		return
 	}
+	a.logger.Debug("Handler is enabled. Analyzing request.", "phase", "accept_request")
 
 	remoteIP, _, err := net.SplitHostPort(request.RemoteAddr)
 	if err != nil {
+		a.logger.Error("Failed to detect remoteIP from request.RemoteAddr.", "request.RemoteAddr", request.RemoteAddr, "phase", "accept_request")
 		responseWriter.WriteHeader(http.StatusInternalServerError)
 		return
 	}
 
 	for _, ipNet := range a.staticDeniedIPNets {
+		a.logger.Debug("Checking if remoteIP is in static denied Netmask.", "remoteIP", remoteIP, "netmask", ipNet, "phase", "check_request")
 		if ipNet.Contains(net.ParseIP(remoteIP)) {
+			a.logger.Info("RemoteIP was found in staticDeniedIPNets. Access Denied.", "remoteIP", remoteIP, "staticDeniedIPNets", a.staticDeniedIPNets, "phase", "check_request", "status", "denied")
 			responseWriter.WriteHeader(http.StatusForbidden)
 			return
 		}
 	}
 
 	for _, ipNet := range a.staticAllowedIPNets {
+		a.logger.Debug("Checking if remoteIP is in static allowed Netmask.", "remoteIP", remoteIP, "netmask", ipNet, "phase", "check_request")
 		if ipNet.Contains(net.ParseIP(remoteIP)) {
+			a.logger.Info("RemoteIP was found in staticAllowedIPNets. Access Granted.", "remoteIP", remoteIP, "staticAllowedIPNets", a.staticAllowedIPNets, "phase", "check_request", "status", "granted")
 			a.next.ServeHTTP(responseWriter, request)
 			return
 		}
@@ -194,10 +205,12 @@ func (a *Fail2Ban) ServeHTTP(responseWriter http.ResponseWriter, request *http.R
 	entry := a.cache.CreateEntry(remoteIP, requestTime)
 
 	if entry.GetTimesSeen() >= a.maxRetries && !entry.IsBanned() {
+		a.logger.Info("Client has been banned.", "remoteIP", remoteIP, "maxRetries", a.maxRetries, "banTime", a.banTime, "findTime", a.findTime, "phase", "check_request", "status", "denied")
 		entry.IssueBan()
 	}
 
 	if entry.IsBanned() {
+		a.logger.Debug("Client is still banned.", "remoteIP", remoteIP, "phase", "check_request", "status", "denied")
 		responseWriter.WriteHeader(http.StatusForbidden)
 		return
 	}
@@ -208,6 +221,7 @@ func (a *Fail2Ban) ServeHTTP(responseWriter http.ResponseWriter, request *http.R
 	// Response rules will be checked in the wrapped response writer
 	wrappedResponseWriter := &ResponseWriter{
 		ResponseWriter: responseWriter,
+		logger:         a.logger,
 		cacheEntry:     entry,
 		rules:          a.responseRules,
 	}

go.mod

@@ -1,3 +1,5 @@
 module github.com/juitde/traefik-plugin-fail2ban
 
 go 1.19
+
+require github.com/zerodha/logf v0.5.5

go.sum

@@ -0,0 +1,6 @@
+github.com/davecgh/go-spew v1.1.1 h1:vj9j/u1bqnvCEfJOwUhtlOARqs3+rkHYY13jYWTU97c=
+github.com/pmezard/go-difflib v1.0.0 h1:4DBwDE0NGyQoBHbLQYPwSUPoCMWR5BEzIk/f1lZbAQM=
+github.com/stretchr/testify v1.8.0 h1:pSgiaMZlXftHpm5L7V1+rVB+AZJydKsMxsQBIJw4PKk=
+github.com/zerodha/logf v0.5.5 h1:AhxHlixHNYwhFjvlgTv6uO4VBKYKxx2I6SbHoHtWLBk=
+github.com/zerodha/logf v0.5.5/go.mod h1:HWpfKsie+WFFpnUnUxelT6Z0FC6xu9+qt+oXNMPg6y8=
+gopkg.in/yaml.v3 v3.0.1 h1:fxVm/GzAzEWqLHuvctI91KS9hhNmmWOoWu0XTYJS7CA=

logger.go

@@ -0,0 +1,28 @@
+package traefik_plugin_fail2ban //nolint:revive,stylecheck
+
+import (
+	"fmt"
+	"strings"
+	"time"
+
+	"github.com/zerodha/logf"
+)
+
+// NewLogger creates new instance of logger.
+func NewLogger(logLevel string) *logf.Logger {
+	parsedLogLevel, err := logf.LevelFromString(strings.ToLower(logLevel))
+	if err != nil {
+		parsedLogLevel = logf.InfoLevel
+	}
+	logger := logf.New(logf.Opts{
+		EnableColor:     false,
+		Level:           parsedLogLevel,
+		EnableCaller:    false,
+		TimestampFormat: fmt.Sprintf("\"%s\"", time.RFC3339),
+		DefaultFields:   []any{"plugin", "JUIT Fail2Ban"},
+	})
+
+	logger.Debug(fmt.Sprintf("Setting log level to %s", strings.ToUpper(parsedLogLevel.String())), "phase", "initialize")
+
+	return &logger
+}

response_writer.go

@@ -3,12 +3,15 @@ package traefik_plugin_fail2ban //nolint:revive,stylecheck
 import (
 	"net/http"
 	"strconv"
+
+	"github.com/zerodha/logf"
 )
 
 // ResponseWriter wrapping original ResponseWriter with response check handling.
 type ResponseWriter struct {
 	http.ResponseWriter
 
+	logger     *logf.Logger
 	cacheEntry *CacheEntry
 	rules      responseRules
 }
@@ -20,7 +23,10 @@ func (rw *ResponseWriter) WriteHeader(code int) {
 
 	if rw.rules.StatusCode != nil {
 		if rw.rules.StatusCode.MatchString(strconv.Itoa(code)) {
+			rw.logger.Debug("Response Status Code matched rule. Incrementing.", "statusCodeRegexp", rw.rules.StatusCode, "responseStatusCode", code, "phase", "check_response", "status", "denied")
 			rw.cacheEntry.IncrementTimesSeen()
+		} else {
+			rw.logger.Debug("Response Status Code does not match rule. Skipping.", "statusCodeRegexp", rw.rules.StatusCode, "responseStatusCode", code, "phase", "check_response", "status", "granted")
 		}
 	}
 }