logging: unify stdlib log usage to pkg/observability (zap) (#134)

* logging: unify stdlib log usage to pkg/observability (zap)

Signed-off-by: Jintao Zhang <[email protected]>

* apply for review comments

Signed-off-by: Jintao Zhang <[email protected]>

---------

Signed-off-by: Jintao Zhang <[email protected]>

Author: tao12345666333

src/semantic-router/cmd/main.go

@@ -3,7 +3,6 @@ package main
 import (
 	"flag"
 	"fmt"
-	"log"
 	"net/http"
 	"os"
 
@@ -26,43 +25,44 @@ func main() {
 
 	// Initialize logging (zap) from environment.
 	if _, err := observability.InitLoggerFromEnv(); err != nil {
-		log.Printf("failed to initialize logger, falling back to stdlib: %v", err)
+		// Fallback to stderr since logger initialization failed
+		fmt.Fprintf(os.Stderr, "failed to initialize logger: %v\n", err)
 	}
 
 	// Check if config file exists
 	if _, err := os.Stat(*configPath); os.IsNotExist(err) {
-		log.Fatalf("Config file not found: %s", *configPath)
+		observability.Fatalf("Config file not found: %s", *configPath)
 	}
 
 	// Start metrics server
 	go func() {
 		http.Handle("/metrics", promhttp.Handler())
 		metricsAddr := fmt.Sprintf(":%d", *metricsPort)
-		log.Printf("Starting metrics server on %s", metricsAddr)
+		observability.Infof("Starting metrics server on %s", metricsAddr)
 		if err := http.ListenAndServe(metricsAddr, nil); err != nil {
-			log.Printf("Metrics server error: %v", err)
+			observability.Errorf("Metrics server error: %v", err)
 		}
 	}()
 
 	// Create and start the ExtProc server
 	server, err := extproc.NewServer(*configPath, *port)
 	if err != nil {
-		log.Fatalf("Failed to create ExtProc server: %v", err)
+		observability.Fatalf("Failed to create ExtProc server: %v", err)
 	}
 
-	log.Printf("Starting vLLM Semantic Router ExtProc with config: %s", *configPath)
+	observability.Infof("Starting vLLM Semantic Router ExtProc with config: %s", *configPath)
 
 	// Start API server if enabled
 	if *enableAPI {
 		go func() {
-			log.Printf("Starting Classification API server on port %d", *apiPort)
+			observability.Infof("Starting Classification API server on port %d", *apiPort)
 			if err := api.StartClassificationAPI(*configPath, *apiPort); err != nil {
-				log.Printf("Classification API server error: %v", err)
+				observability.Errorf("Classification API server error: %v", err)
 			}
 		}()
 	}
 
 	if err := server.Start(); err != nil {
-		log.Fatalf("ExtProc server error: %v", err)
+		observability.Fatalf("ExtProc server error: %v", err)
 	}
 }

src/semantic-router/pkg/api/server.go

@@ -5,13 +5,13 @@ import (
 	"encoding/json"
 	"fmt"
 	"io"
-	"log"
 	"net/http"
 	"runtime"
 	"time"
 
 	"github.com/vllm-project/semantic-router/src/semantic-router/pkg/config"
 	"github.com/vllm-project/semantic-router/src/semantic-router/pkg/metrics"
+	"github.com/vllm-project/semantic-router/src/semantic-router/pkg/observability"
 	"github.com/vllm-project/semantic-router/src/semantic-router/pkg/services"
 )
 
@@ -97,13 +97,13 @@ func StartClassificationAPI(configPath string, port int) error {
 	classificationSvc := getClassificationServiceWithRetry(5, 500*time.Millisecond)
 	if classificationSvc == nil {
 		// If no global service exists, try auto-discovery unified classifier
-		log.Printf("No global classification service found, attempting auto-discovery...")
+		observability.Infof("No global classification service found, attempting auto-discovery...")
 		autoSvc, err := services.NewClassificationServiceWithAutoDiscovery(cfg)
 		if err != nil {
-			log.Printf("Auto-discovery failed: %v, using placeholder service", err)
+			observability.Warnf("Auto-discovery failed: %v, using placeholder service", err)
 			classificationSvc = services.NewPlaceholderClassificationService()
 		} else {
-			log.Printf("Auto-discovery successful, using unified classifier service")
+			observability.Infof("Auto-discovery successful, using unified classifier service")
 			classificationSvc = autoSvc
 		}
 	}
@@ -138,25 +138,25 @@ func StartClassificationAPI(configPath string, port int) error {
 		IdleTimeout:  60 * time.Second,
 	}
 
-	log.Printf("Classification API server listening on port %d", port)
+	observability.Infof("Classification API server listening on port %d", port)
 	return server.ListenAndServe()
 }
 
 // getClassificationServiceWithRetry attempts to get the global classification service with retry logic
 func getClassificationServiceWithRetry(maxRetries int, retryInterval time.Duration) *services.ClassificationService {
 	for i := 0; i < maxRetries; i++ {
 		if svc := services.GetGlobalClassificationService(); svc != nil {
-			log.Printf("Found global classification service on attempt %d/%d", i+1, maxRetries)
+			observability.Infof("Found global classification service on attempt %d/%d", i+1, maxRetries)
 			return svc
 		}
 
 		if i < maxRetries-1 { // Don't sleep on the last attempt
-			log.Printf("Global classification service not ready, retrying in %v (attempt %d/%d)", retryInterval, i+1, maxRetries)
+			observability.Infof("Global classification service not ready, retrying in %v (attempt %d/%d)", retryInterval, i+1, maxRetries)
 			time.Sleep(retryInterval)
 		}
 	}
 
-	log.Printf("Failed to find global classification service after %d attempts", maxRetries)
+	observability.Warnf("Failed to find global classification service after %d attempts", maxRetries)
 	return nil
 }
 
@@ -387,7 +387,7 @@ func (s *ClassificationAPIServer) writeJSONResponse(w http.ResponseWriter, statu
 	w.WriteHeader(statusCode)
 
 	if err := json.NewEncoder(w).Encode(data); err != nil {
-		log.Printf("Failed to encode JSON response: %v", err)
+		observability.Errorf("Failed to encode JSON response: %v", err)
 	}
 }
 

src/semantic-router/pkg/extproc/model_selector.go

@@ -1,7 +1,7 @@
 package extproc
 
 import (
-	"log"
+	"github.com/vllm-project/semantic-router/src/semantic-router/pkg/observability"
 )
 
 // classifyAndSelectBestModel chooses best models based on category classification and model quality and expected TTFT
@@ -17,7 +17,7 @@ func (r *OpenAIRouter) findCategoryForClassification(query string) string {
 
 	categoryName, _, err := r.Classifier.ClassifyCategory(query)
 	if err != nil {
-		log.Printf("Category classification error: %v", err)
+		observability.Errorf("Category classification error: %v", err)
 		return ""
 	}
 

src/semantic-router/pkg/extproc/processor.go

@@ -4,17 +4,17 @@ import (
 	"context"
 	"errors"
 	"io"
-	"log"
 
 	ext_proc "github.com/envoyproxy/go-control-plane/envoy/service/ext_proc/v3"
 	"github.com/vllm-project/semantic-router/src/semantic-router/pkg/metrics"
+	"github.com/vllm-project/semantic-router/src/semantic-router/pkg/observability"
 	"google.golang.org/grpc/codes"
 	"google.golang.org/grpc/status"
 )
 
 // Process implements the ext_proc calls
 func (r *OpenAIRouter) Process(stream ext_proc.ExternalProcessor_ProcessServer) error {
-	log.Println("Started processing a new request")
+	observability.Infof("Started processing a new request")
 
 	// Initialize request context
 	ctx := &RequestContext{
@@ -26,62 +26,60 @@ func (r *OpenAIRouter) Process(stream ext_proc.ExternalProcessor_ProcessServer)
 		if err != nil {
 			// Handle EOF - this indicates the client has closed the stream gracefully
 			if err == io.EOF {
-				log.Println("Stream ended gracefully")
+				observability.Infof("Stream ended gracefully")
 				return nil
 			}
 
 			// Handle gRPC status-based cancellations/timeouts
 			if s, ok := status.FromError(err); ok {
 				switch s.Code() {
 				case codes.Canceled:
-					log.Println("Stream canceled gracefully")
+					observability.Infof("Stream canceled gracefully")
 					metrics.RecordRequestError(ctx.RequestModel, "cancellation")
 					return nil
 				case codes.DeadlineExceeded:
-					log.Println("Stream deadline exceeded")
+					observability.Infof("Stream deadline exceeded")
 					metrics.RecordRequestError(ctx.RequestModel, "timeout")
 					return nil
 				}
 			}
 
 			// Handle context cancellation from the server-side context
 			if errors.Is(err, context.Canceled) {
-				log.Println("Stream canceled gracefully")
+				observability.Infof("Stream canceled gracefully")
 				metrics.RecordRequestError(ctx.RequestModel, "cancellation")
 				return nil
 			}
 			if errors.Is(err, context.DeadlineExceeded) {
-				log.Println("Stream deadline exceeded")
+				observability.Infof("Stream deadline exceeded")
 				metrics.RecordRequestError(ctx.RequestModel, "timeout")
 				return nil
 			}
 
-			log.Printf("Error receiving request: %v", err)
+			observability.Errorf("Error receiving request: %v", err)
 			return err
 		}
 
 		switch v := req.Request.(type) {
 		case *ext_proc.ProcessingRequest_RequestHeaders:
 			response, err := r.handleRequestHeaders(v, ctx)
 			if err != nil {
-				log.Printf("ERROR: handleRequestHeaders failed: %v", err)
+				observability.Errorf("handleRequestHeaders failed: %v", err)
 				return err
 			}
 			if err := sendResponse(stream, response, "request header"); err != nil {
-				log.Printf("ERROR: sendResponse for headers failed: %v", err)
+				observability.Errorf("sendResponse for headers failed: %v", err)
 				return err
 			}
 
 		case *ext_proc.ProcessingRequest_RequestBody:
-			log.Printf("DEBUG: Processing Request Body - THIS IS WHERE ROUTING HAPPENS")
-
 			response, err := r.handleRequestBody(v, ctx)
 			if err != nil {
-				log.Printf("ERROR: handleRequestBody failed: %v", err)
+				observability.Errorf("handleRequestBody failed: %v", err)
 				return err
 			}
 			if err := sendResponse(stream, response, "request body"); err != nil {
-				log.Printf("ERROR: sendResponse for body failed: %v", err)
+				observability.Errorf("sendResponse for body failed: %v", err)
 				return err
 			}
 
@@ -104,7 +102,7 @@ func (r *OpenAIRouter) Process(stream ext_proc.ExternalProcessor_ProcessServer)
 			}
 
 		default:
-			log.Printf("Unknown request type: %v", v)
+			observability.Warnf("Unknown request type: %v", v)
 
 			// For unknown message types, create a body response with CONTINUE status
 			response := &ext_proc.ProcessingResponse{

src/semantic-router/pkg/extproc/reason_mode_selector.go

@@ -3,11 +3,11 @@ package extproc
 import (
 	"encoding/json"
 	"fmt"
-	"log"
 	"strings"
 
 	"github.com/vllm-project/semantic-router/src/semantic-router/pkg/config"
 	"github.com/vllm-project/semantic-router/src/semantic-router/pkg/metrics"
+	"github.com/vllm-project/semantic-router/src/semantic-router/pkg/observability"
 	"github.com/vllm-project/semantic-router/src/semantic-router/pkg/utils/entropy"
 )
 
@@ -24,7 +24,7 @@ func (r *OpenAIRouter) getReasoningModeAndCategory(query string) (bool, string)
 
 	// If no category was determined (empty string), default to no reasoning
 	if categoryName == "" {
-		log.Printf("No category determined for query, defaulting to no reasoning mode")
+		observability.Infof("No category determined for query, defaulting to no reasoning mode")
 		return false, ""
 	}
 
@@ -38,14 +38,14 @@ func (r *OpenAIRouter) getReasoningModeAndCategory(query string) (bool, string)
 			if category.UseReasoning {
 				reasoningStatus = "ENABLED"
 			}
-			log.Printf("Reasoning mode decision: Category '%s' → %s",
+			observability.Infof("Reasoning mode decision: Category '%s' → %s",
 				categoryName, reasoningStatus)
 			return category.UseReasoning, categoryName
 		}
 	}
 
 	// If category not found in config, default to no reasoning
-	log.Printf("Category '%s' not found in configuration, defaulting to no reasoning mode", categoryName)
+	observability.Infof("Category '%s' not found in configuration, defaulting to no reasoning mode", categoryName)
 	return false, categoryName
 }
 
@@ -55,7 +55,7 @@ func (r *OpenAIRouter) getEntropyBasedReasoningModeAndCategory(query string) (bo
 	categoryName, confidence, reasoningDecision, err := r.Classifier.ClassifyCategoryWithEntropy(query)
 
 	if err != nil {
-		log.Printf("Entropy-based classification error: %v, falling back to traditional method", err)
+		observability.Warnf("Entropy-based classification error: %v, falling back to traditional method", err)
 
 		// Record fallback metrics
 		metrics.RecordEntropyFallback("classification_error", "traditional_method")
@@ -74,12 +74,12 @@ func (r *OpenAIRouter) getEntropyBasedReasoningModeAndCategory(query string) (bo
 	}
 
 	// Log the entropy-based decision
-	log.Printf("Entropy-based reasoning decision: category='%s', confidence=%.3f, use_reasoning=%t, reason=%s, strategy=%s",
+	observability.Infof("Entropy-based reasoning decision: category='%s', confidence=%.3f, use_reasoning=%t, reason=%s, strategy=%s",
 		categoryName, confidence, reasoningDecision.UseReasoning, reasoningDecision.DecisionReason, reasoningDecision.FallbackStrategy)
 
 	// If we have top categories from entropy analysis, log them
 	if len(reasoningDecision.TopCategories) > 0 {
-		log.Printf("Top predicted categories: %v", reasoningDecision.TopCategories)
+		observability.Infof("Top predicted categories: %v", reasoningDecision.TopCategories)
 	}
 
 	return reasoningDecision.UseReasoning, categoryName, reasoningDecision
@@ -181,11 +181,11 @@ func (r *OpenAIRouter) setReasoningModeToRequestBody(requestBody []byte, enabled
 
 	// Log based on what actually happened
 	if enabled && !reasoningApplied {
-		log.Printf("No reasoning support for model: %s (no reasoning family configured)", model)
+		observability.Infof("No reasoning support for model: %s (no reasoning family configured)", model)
 	} else if reasoningApplied {
-		log.Printf("Applied reasoning mode (enabled: %v) with effort (%s) to model: %s", enabled, appliedEffort, model)
+		observability.Infof("Applied reasoning mode (enabled: %v) with effort (%s) to model: %s", enabled, appliedEffort, model)
 	} else {
-		log.Printf("Reasoning mode disabled for model: %s", model)
+		observability.Infof("Reasoning mode disabled for model: %s", model)
 	}
 
 	// Record metrics for template usage and effort when enabled
@@ -228,7 +228,7 @@ func (r *OpenAIRouter) setReasoningModeToRequestBody(requestBody []byte, enabled
 // logReasoningConfiguration logs the reasoning mode configuration for all categories during startup
 func (r *OpenAIRouter) logReasoningConfiguration() {
 	if len(r.Config.Categories) == 0 {
-		log.Printf("No categories configured for reasoning mode")
+		observability.Infof("No categories configured for reasoning mode")
 		return
 	}
 
@@ -243,14 +243,14 @@ func (r *OpenAIRouter) logReasoningConfiguration() {
 		}
 	}
 
-	log.Printf("Reasoning configuration - Total categories: %d", len(r.Config.Categories))
+	observability.Infof("Reasoning configuration - Total categories: %d", len(r.Config.Categories))
 
 	if len(reasoningEnabled) > 0 {
-		log.Printf("Reasoning ENABLED for categories (%d): %v", len(reasoningEnabled), reasoningEnabled)
+		observability.Infof("Reasoning ENABLED for categories (%d): %v", len(reasoningEnabled), reasoningEnabled)
 	}
 
 	if len(reasoningDisabled) > 0 {
-		log.Printf("Reasoning DISABLED for categories (%d): %v", len(reasoningDisabled), reasoningDisabled)
+		observability.Infof("Reasoning DISABLED for categories (%d): %v", len(reasoningDisabled), reasoningDisabled)
 	}
 }
 
@@ -266,7 +266,7 @@ func (r *OpenAIRouter) ClassifyAndDetermineReasoningMode(query string) (string,
 	if useReasoning {
 		reasoningStatus = "enabled"
 	}
-	log.Printf("Model selection complete: model=%s, reasoning=%s", bestModel, reasoningStatus)
+	observability.Infof("Model selection complete: model=%s, reasoning=%s", bestModel, reasoningStatus)
 
 	return bestModel, useReasoning
 }
@@ -284,7 +284,7 @@ func (r *OpenAIRouter) LogReasoningConfigurationSummary() {
 		}
 	}
 
-	log.Printf("Reasoning mode summary: %d/%d categories have reasoning enabled", enabledCount, len(r.Config.Categories))
+	observability.Infof("Reasoning mode summary: %d/%d categories have reasoning enabled", enabledCount, len(r.Config.Categories))
 }
 
 // getReasoningEffort returns the reasoning effort level for a given category