Merge pull request #49 from thushan/feature/security-august-2025

feat: security & log consolidation

Author: thushan

docs/content/concepts/proxy-profiles.md

@@ -43,8 +43,8 @@ proxy:
   profile: "auto"  # auto, streaming, or standard
 ```
 
-!!! note "Environment Variable Not Supported"
-    The proxy profile can only be configured via the YAML configuration file. Environment variable override is not currently implemented.
+You can also use `OLLA_PROXY_PROFILE` environment variable to configure the Proxy Profile.
+
 
 ## Profile Behaviour
 

docs/content/configuration/reference.md

@@ -396,6 +396,7 @@ OLLA_SERVER_REQUEST_LOGGING=true
 # Proxy settings
 OLLA_PROXY_ENGINE=olla
 OLLA_PROXY_LOAD_BALANCER=round-robin
+OLLA_PROXY_PROFILE=auto
 
 # Logging
 OLLA_LOGGING_LEVEL=debug

internal/adapter/proxy/olla/service.go

@@ -388,13 +388,12 @@ func (s *Service) ProxyRequestToEndpoints(ctx context.Context, w http.ResponseWr
 	reqCtx.targetURL = targetURL.String()
 
 	if ctxLogger != nil {
-		ctxLogger.Info("Request dispatching to endpoint",
+		ctxLogger.Info("Request dispatching",
 			"endpoint", endpoint.Name,
 			"target", stats.TargetUrl,
-			"model", stats.Model,
-			"request_id", middleware.GetRequestID(ctx))
+			"model", stats.Model)
 	} else {
-		rlog.Info("Request dispatching to endpoint", "endpoint", endpoint.Name, "target", stats.TargetUrl, "model", stats.Model)
+		rlog.Info("Request dispatching", "endpoint", endpoint.Name, "target", stats.TargetUrl, "model", stats.Model)
 	}
 
 	// Create and prepare proxy request
@@ -592,9 +591,9 @@ func (s *Service) handleSuccessfulResponse(ctx context.Context, w http.ResponseW
 	stats.EndTime = time.Now()
 	stats.Latency = duration.Milliseconds()
 
-	// Log detailed completion metrics
+	// Log detailed completion metrics at Debug level to reduce redundancy
 	if ctxLogger != nil {
-		ctxLogger.Info("Olla proxy request completed",
+		ctxLogger.Debug("Olla proxy metrics",
 			"endpoint", endpoint.Name,
 			"latency_ms", stats.Latency,
 			"processing_ms", stats.RequestProcessingMs,

internal/adapter/proxy/sherpa/service.go

@@ -204,13 +204,12 @@ func (s *Service) ProxyRequestToEndpoints(ctx context.Context, w http.ResponseWr
 	stats.EndpointName = endpoint.Name
 
 	if ctxLogger != nil {
-		ctxLogger.Info("Request dispatching to endpoint",
+		ctxLogger.Info("Request dispatching",
 			"endpoint", endpoint.Name,
 			"target", stats.TargetUrl,
-			"model", stats.Model,
-			"request_id", middleware.GetRequestID(ctx))
+			"model", stats.Model)
 	} else {
-		rlog.Info("Request dispatching to endpoint", "endpoint", endpoint.Name, "target", stats.TargetUrl, "model", stats.Model)
+		rlog.Info("Request dispatching", "endpoint", endpoint.Name, "target", stats.TargetUrl, "model", stats.Model)
 	}
 
 	s.Selector.IncrementConnections(endpoint)
@@ -312,9 +311,9 @@ func (s *Service) ProxyRequestToEndpoints(ctx context.Context, w http.ResponseWr
 	stats.Latency = stats.EndTime.Sub(stats.StartTime).Milliseconds()
 	stats.TotalBytes = bytesWritten
 
-	// Log detailed completion metrics
+	// Log detailed completion metrics at Debug level to reduce redundancy
 	if ctxLogger != nil {
-		ctxLogger.Info("Sherpa proxy request completed",
+		ctxLogger.Debug("Sherpa proxy metrics",
 			"endpoint", endpoint.Name,
 			"latency_ms", stats.Latency,
 			"processing_ms", stats.RequestProcessingMs,

internal/app/handlers/handler_proxy.go

@@ -6,6 +6,7 @@ import (
 	"net/http"
 	"time"
 
+	"github.com/thushan/olla/internal/app/middleware"
 	"github.com/thushan/olla/internal/core/constants"
 	"github.com/thushan/olla/internal/core/domain"
 	"github.com/thushan/olla/internal/core/ports"
@@ -14,16 +15,17 @@ import (
 )
 
 type proxyRequest struct {
-	stats         *ports.RequestStats
 	requestLogger logger.StyledLogger
+	stats         *ports.RequestStats
+	profile       *domain.RequestProfile
 	clientIP      string
 	targetPath    string
-	profile       *domain.RequestProfile
 	model         string
 	contentType   string
 	method        string
 	path          string
 	query         string
+	userAgent     string
 	contentLength int64
 }
 
@@ -52,8 +54,19 @@ func (a *Application) proxyHandler(w http.ResponseWriter, r *http.Request) {
 }
 
 func (a *Application) initializeProxyRequest(r *http.Request) *proxyRequest {
+	// get the requestID from the middleware context first
+	requestID := ""
+	if id, ok := r.Context().Value(middleware.RequestIDKey).(string); ok {
+		requestID = id
+	}
+
+	// fallback to generating a new one otherwise
+	if requestID == "" {
+		requestID = util.GenerateRequestID()
+	}
+
 	stats := &ports.RequestStats{
-		RequestID: util.GenerateRequestID(),
+		RequestID: requestID,
 		StartTime: time.Now(),
 	}
 
@@ -65,6 +78,7 @@ func (a *Application) initializeProxyRequest(r *http.Request) *proxyRequest {
 		path:          r.URL.Path,
 		query:         r.URL.RawQuery,
 		contentLength: r.ContentLength,
+		userAgent:     r.UserAgent(),
 	}
 }
 
@@ -121,34 +135,69 @@ func (a *Application) executeProxyRequest(ctx context.Context, w http.ResponseWr
 }
 
 func (a *Application) logRequestStart(pr *proxyRequest, endpointCount int) {
+	// Log essential operational info at INFO level
 	logFields := []any{
 		"client_ip", pr.clientIP,
 		"method", pr.method,
 		"path", pr.path,
-		"target_path", pr.targetPath,
 		"compatible_endpoints", endpointCount,
-		"path_resolution_ms", pr.stats.PathResolutionMs,
-		"query", pr.query,
-		"content_type", pr.contentType,
-		"content_length", pr.contentLength,
 	}
 
+	// Add user agent if present
+	if pr.userAgent != "" {
+		logFields = append(logFields, "user_agent", pr.userAgent)
+	}
+
+	// Add model if identified
 	if pr.model != "" {
 		logFields = append(logFields, "model", pr.model)
 	}
 
-	pr.requestLogger.Info("Request started", logFields...)
+	// Add content length if it's a POST/PUT with body
+	if pr.contentLength > 0 {
+		logFields = append(logFields, "content_length", pr.contentLength)
+	}
+
+	pr.requestLogger.Info("Request received", logFields...)
+
+	// Log additional details at DEBUG level
+	debugFields := []any{
+		"target_path", pr.targetPath,
+		"path_resolution_ms", pr.stats.PathResolutionMs,
+		"query", pr.query,
+		"content_type", pr.contentType,
+	}
+
+	pr.requestLogger.Debug("Request details", debugFields...)
 }
 
 func (a *Application) logRequestResult(pr *proxyRequest, err error) {
 	duration := time.Since(pr.stats.StartTime)
 
-	logFields := a.buildLogFields(pr, duration)
-
 	if err != nil {
+		logFields := a.buildLogFields(pr, duration)
 		pr.requestLogger.Error("Request failed", append([]any{"error", err}, logFields...)...)
 	} else {
-		pr.requestLogger.Info("Request completed", logFields...)
+		// Log essential completion info at INFO level
+		infoFields := []any{
+			"endpoint", pr.stats.EndpointName,
+			"duration_ms", duration.Milliseconds(),
+			"status", "completed",
+		}
+
+		if pr.model != "" {
+			infoFields = append(infoFields, "model", pr.model)
+		}
+
+		if pr.stats.TotalBytes > 0 {
+			infoFields = append(infoFields, "total_bytes", pr.stats.TotalBytes)
+		}
+
+		pr.requestLogger.Info("Request completed", infoFields...)
+
+		// Log detailed metrics at DEBUG level
+		debugFields := a.buildLogFields(pr, duration)
+		pr.requestLogger.Debug("Request metrics", debugFields...)
 	}
 }
 

internal/app/handlers/handler_status_endpoints.go

@@ -20,7 +20,6 @@ const (
 
 type EndpointSummary struct {
 	Name          string `json:"name"`
-	URL           string `json:"url"`
 	Type          string `json:"type"`
 	Status        string `json:"status"`
 	LastModelSync string `json:"last_model_sync,omitempty"`
@@ -103,7 +102,6 @@ func (a *Application) buildEndpointSummaryOptimised(endpoint *domain.Endpoint, s
 
 	summary := EndpointSummary{
 		Name:     endpoint.Name,
-		URL:      url,
 		Type:     endpoint.Type,
 		Status:   endpoint.Status.String(),
 		Priority: endpoint.Priority,

internal/app/middleware/logging.go

@@ -5,6 +5,7 @@ import (
 	"fmt"
 	"log/slog"
 	"net/http"
+	"strings"
 	"time"
 
 	"github.com/thushan/olla/internal/core/constants"
@@ -22,6 +23,15 @@ const (
 	LoggerKey    contextKey = "logger"
 )
 
+// IsProxyRequest determines if a request is for the proxy endpoints
+// Used to decide logging levels to avoid redundancy with proxy handler logging
+func IsProxyRequest(path string) bool {
+	// checks for proxy prefixes
+	// /olla/ is the main proxy prefix
+	return strings.Contains(path, constants.DefaultOllaProxyPathPrefix) ||
+		(strings.HasPrefix(path, "/api/") && !strings.HasPrefix(path, "/api/v0/")) // /api/v0/ is internal
+}
+
 // responseWriter wraps http.ResponseWriter to capture response size and status
 type responseWriter struct {
 	http.ResponseWriter
@@ -89,7 +99,7 @@ func EnhancedLoggingMiddleware(styledLogger logger.StyledLogger) func(http.Handl
 			ctx := context.WithValue(r.Context(), RequestIDKey, requestID)
 
 			// Create a base logger with request ID
-			baseLogger := slog.Default().With("request_id", requestID)
+			baseLogger := slog.Default().With(constants.ContextRequestIdKey, requestID)
 			ctx = context.WithValue(ctx, LoggerKey, baseLogger)
 
 			// Add to response header for client tracking
@@ -98,29 +108,48 @@ func EnhancedLoggingMiddleware(styledLogger logger.StyledLogger) func(http.Handl
 			// Wrap response writer to capture metrics
 			wrapped := &responseWriter{ResponseWriter: w, status: 200}
 
-			// Log request start
-			baseLogger.Info("Request started",
+			// Log request start - use Debug for proxy requests to reduce noise
+			// Proxy requests will log their own "Request received" at INFO level
+			logFields := []any{
 				"method", r.Method,
 				"path", r.URL.Path,
 				"remote_addr", r.RemoteAddr,
 				"user_agent", r.UserAgent(),
 				"request_bytes", requestSize,
-				"request_size_formatted", formatBytes(requestSize))
+				"request_size_formatted", formatBytes(requestSize),
+			}
+
+			if IsProxyRequest(r.URL.Path) {
+				// For proxy requests, just log at debug level since handler will log INFO
+				baseLogger.Debug("HTTP request started", logFields...)
+			} else {
+				// For non-proxy requests (health, status, etc), log at INFO
+				baseLogger.Info("Request started", logFields...)
+			}
 
 			next.ServeHTTP(wrapped, r.WithContext(ctx))
 
 			duration := time.Since(start)
 
-			// Log request completion
-			baseLogger.Info("Request completed",
+			// Log request completion - use Debug for proxy requests to reduce noise
+			completionFields := []any{
 				"method", r.Method,
 				"path", r.URL.Path,
 				"status", wrapped.status,
 				"duration_ms", duration.Milliseconds(),
 				"duration_formatted", duration.String(),
 				"request_bytes", requestSize,
 				"response_bytes", wrapped.size,
-				"size_flow", fmt.Sprintf("%s -> %s", formatBytes(requestSize), formatBytes(wrapped.size)))
+				"size_flow", fmt.Sprintf("%s -> %s", formatBytes(requestSize), formatBytes(wrapped.size)),
+			}
+
+			if IsProxyRequest(r.URL.Path) {
+				// For proxy requests, just log at debug level since handler will log INFO
+				baseLogger.Debug("HTTP request completed", completionFields...)
+			} else {
+				// For non-proxy requests, log at INFO
+				baseLogger.Info("Request completed", completionFields...)
+			}
 		})
 	}
 }

internal/app/middleware/logging_proxy_test.go

@@ -0,0 +1,79 @@
+package middleware
+
+import "testing"
+
+func TestIsProxyRequest(t *testing.T) {
+	tests := []struct {
+		name     string
+		path     string
+		expected bool
+	}{
+		// Proxy requests
+		{
+			name:     "olla proxy ollama path",
+			path:     "/olla/ollama/api/chat",
+			expected: true,
+		},
+		{
+			name:     "olla proxy lmstudio path",
+			path:     "/olla/lmstudio/v1/models",
+			expected: true,
+		},
+		{
+			name:     "olla proxy generic path",
+			path:     "/olla/proxy/some/endpoint",
+			expected: true,
+		},
+		{
+			name:     "direct api path",
+			path:     "/api/chat",
+			expected: true,
+		},
+		{
+			name:     "api models path",
+			path:     "/api/models",
+			expected: true,
+		},
+
+		// Non-proxy requests
+		{
+			name:     "health check endpoint",
+			path:     "/internal/health",
+			expected: false,
+		},
+		{
+			name:     "status endpoint",
+			path:     "/internal/status",
+			expected: false,
+		},
+		{
+			name:     "version endpoint",
+			path:     "/version",
+			expected: false,
+		},
+		{
+			name:     "root path",
+			path:     "/",
+			expected: false,
+		},
+		{
+			name:     "internal api v0 models",
+			path:     "/api/v0/models",
+			expected: false,
+		},
+		{
+			name:     "internal api v0 status",
+			path:     "/api/v0/status",
+			expected: false,
+		},
+	}
+
+	for _, tt := range tests {
+		t.Run(tt.name, func(t *testing.T) {
+			result := IsProxyRequest(tt.path)
+			if result != tt.expected {
+				t.Errorf("IsProxyRequest(%q) = %v, want %v", tt.path, result, tt.expected)
+			}
+		})
+	}
+}