refactor(middleware): improve logging

This change improves logging by providing timing data for request processing and middleware execution, and reducing noise in logs and making the middleware execution flow easier to follow.

middleware/circuitbreaker/circuitbreaker.go

@@ -56,8 +56,6 @@ func New(maxRequests uint32, interval, timeout time.Duration) *CircuitBreakerMid
 
 // Process applies the circuit breaker before passing the request to the next middleware.
 func (m *CircuitBreakerMiddleware) Process(ctx context.Context, httpClient *http.Client, req *http.Request, next middleware.NextFunc) (*http.Response, error) {
-	m.logger.Debug("Processing request with circuit breaker middleware")
-
 	// Execute the request with the circuit breaker
 	result, err := m.breaker.Execute(func() (interface{}, error) {
 		return next(ctx, httpClient, req)

middleware/cookie/cookie.go

@@ -40,12 +40,9 @@ func New(cookies [][]*http.Cookie) *CookieMiddleware {
 func (m *CookieMiddleware) Process(ctx context.Context, httpClient *http.Client, req *http.Request, next middleware.NextFunc) (*http.Response, error) {
 	// Check if the cookie middleware is disabled via context
 	if isDisabled, ok := ctx.Value(SkipCookieKey{}).(bool); ok && isDisabled {
-		m.logger.Debug("Cookie middleware disabled via context")
 		return next(ctx, httpClient, req)
 	}
 
-	m.logger.Debug("Processing request with cookie middleware")
-
 	m.mu.RLock()
 	cookiesLen := len(m.cookies)
 	m.mu.RUnlock()

middleware/header/header.go

@@ -24,8 +24,6 @@ func New(headers http.Header) *HeaderMiddleware {
 
 // Process applies headers to the request before passing it to the next middleware.
 func (m *HeaderMiddleware) Process(ctx context.Context, httpClient *http.Client, req *http.Request, next middleware.NextFunc) (*http.Response, error) {
-	m.logger.Debug("Processing request with header middleware")
-
 	for key, values := range m.headers {
 		for _, value := range values {
 			req.Header.Add(key, value)

middleware/proxy/proxy.go

@@ -43,12 +43,9 @@ func New(proxies []*url.URL) *ProxyMiddleware {
 // Process applies proxy logic before passing the request to the next middleware.
 func (m *ProxyMiddleware) Process(ctx context.Context, httpClient *http.Client, req *http.Request, next middleware.NextFunc) (*http.Response, error) {
 	if skipProxy, ok := ctx.Value(SkipProxyKey{}).(bool); ok && skipProxy {
-		m.logger.Debug("Skipping proxy for this request")
 		return next(ctx, httpClient, req)
 	}
 
-	m.logger.Debug("Processing request with proxy middleware")
-
 	m.mu.RLock()
 	proxyLen := len(m.proxies)
 	m.mu.RUnlock()

middleware/ratelimit/ratelimit.go

@@ -27,8 +27,6 @@ func New(requestsPerSecond float64, burst int) *RateLimiterMiddleware {
 
 // Process applies rate limiting before passing the request to the next middleware.
 func (m *RateLimiterMiddleware) Process(ctx context.Context, httpClient *http.Client, req *http.Request, next middleware.NextFunc) (*http.Response, error) {
-	m.logger.Debug("Processing request with rate limiter middleware")
-
 	// Wait for rate limiter permission
 	if err := m.limiter.Wait(ctx); err != nil {
 		if strings.Contains(err.Error(), "would exceed context deadline") {

middleware/redis/redis.go

@@ -49,7 +49,6 @@ func New(redisClient rueidis.Client, expiration time.Duration) *RedisMiddleware
 func (m *RedisMiddleware) Process(ctx context.Context, httpClient *http.Client, req *http.Request, next middleware.NextFunc) (*http.Response, error) {
 	// Check if caching should be skipped
 	if skipCache, ok := ctx.Value(SkipCacheKey{}).(bool); ok && skipCache {
-		m.logger.Debug("Skipping cache for this request")
 		return next(ctx, httpClient, req)
 	}
 
@@ -63,7 +62,6 @@ func (m *RedisMiddleware) Process(ctx context.Context, httpClient *http.Client,
 	}
 
 	// Cache miss, proceed with the request
-	m.logger.Debug("Cache miss")
 	resp, err := next(ctx, httpClient, req)
 	if err != nil {
 		return resp, err

middleware/retry/retry.go

@@ -31,8 +31,6 @@ func New(maxAttempts uint64, initialInterval, maxInterval time.Duration) *RetryM
 
 // Process applies retry logic before passing the request to the next middleware.
 func (m *RetryMiddleware) Process(ctx context.Context, httpClient *http.Client, req *http.Request, next middleware.NextFunc) (*http.Response, error) {
-	m.logger.Debug("Processing request with retry middleware")
-
 	// Create an exponential backoff strategy with a maximum number of retries
 	expBackoff := backoff.WithMaxRetries(backoff.NewExponentialBackOff(
 		backoff.WithInitialInterval(m.initialInterval),

middleware/singleflight/singleflight.go

@@ -40,8 +40,6 @@ func New() *SingleFlightMiddleware {
 
 // Process applies the singleflight pattern before passing the request to the next middleware.
 func (m *SingleFlightMiddleware) Process(ctx context.Context, httpClient *http.Client, req *http.Request, next middleware.NextFunc) (*http.Response, error) {
-	m.logger.Debug("Processing request with singleflight middleware")
-
 	// Generate a unique key for the request
 	key, err := m.generateRequestKey(req)
 	if err != nil {

pkg/client/middleware/middleware_chain.go

@@ -5,6 +5,7 @@ import (
 	"fmt"
 	"net/http"
 	"reflect"
+	"time"
 
 	"github.com/jaxron/axonet/pkg/client/errors"
 	"github.com/jaxron/axonet/pkg/client/logger"
@@ -48,45 +49,52 @@ func (c *Chain) Process(ctx context.Context, httpClient *http.Client, req *http.
 		return c.performRequest(ctx, httpClient, req)
 	}
 
-	c.logMiddlewareChain()
 	return c.processMiddleware(ctx, httpClient, req, 0)
 }
 
-// logMiddlewareChain logs the available middleware in the chain.
-func (c *Chain) logMiddlewareChain() {
-	for i, m := range c.middlewares {
-		c.logger.WithFields(
-			logger.Int("index", i),
-			logger.String("type", reflect.TypeOf(m).String()),
-		).Debug("Middleware in chain")
-	}
-}
-
 // processMiddleware recursively applies each middleware in the chain.
 func (c *Chain) processMiddleware(ctx context.Context, httpClient *http.Client, req *http.Request, index int) (*http.Response, error) {
 	// If we've reached the end of the middleware chain, perform the request
 	if index == len(c.middlewares) {
 		return c.performRequest(ctx, httpClient, req)
 	}
 
+	start := time.Now()
+	middleware := c.middlewares[index]
+
 	// Otherwise, apply the middleware and continue
-	return c.middlewares[index].Process(ctx, httpClient, req, func(ctx context.Context, client *http.Client, req *http.Request) (*http.Response, error) {
+	resp, err := middleware.Process(ctx, httpClient, req, func(ctx context.Context, client *http.Client, req *http.Request) (*http.Response, error) {
+		c.logger.WithFields(
+			logger.Int("index", index),
+			logger.String("middleware", reflect.TypeOf(middleware).String()),
+			logger.Duration("duration", time.Since(start)),
+		).Debug("Middleware executed")
 		return c.processMiddleware(ctx, client, req, index+1)
 	})
+
+	return resp, err
 }
 
 // performRequest executes the actual HTTP request.
 func (c *Chain) performRequest(ctx context.Context, httpClient *http.Client, req *http.Request) (*http.Response, error) {
+	start := time.Now()
+
 	// Log the request details
 	c.logger.WithFields(
 		logger.String("method", req.Method),
 		logger.String("url", req.URL.String()),
 		logger.Int("len_headers", len(req.Header)),
-	).Debug("Request")
+	).Debug("Request started")
 
 	// Send the request
 	resp, err := httpClient.Do(req.WithContext(ctx))
+	duration := time.Since(start)
 	if err != nil {
+		c.logger.WithFields(
+			logger.String("error", err.Error()),
+			logger.Duration("duration", duration),
+		).Debug("Request failed")
+
 		if errors.Is(err, context.DeadlineExceeded) {
 			return nil, fmt.Errorf("%w: %w", errors.ErrTimeout, err)
 		}
@@ -97,7 +105,8 @@ func (c *Chain) performRequest(ctx context.Context, httpClient *http.Client, req
 	c.logger.WithFields(
 		logger.Int("status", resp.StatusCode),
 		logger.Int("len_headers", len(resp.Header)),
-	).Debug("Response")
+		logger.Duration("duration", duration),
+	).Debug("Request completed")
 
 	return resp, nil
 }