diff --git a/Dockerfile.builder b/Dockerfile.builder index 5841e31fad..9e22a4ba31 100644 --- a/Dockerfile.builder +++ b/Dockerfile.builder @@ -10,8 +10,8 @@ ARG KUBECTL_VERSION=v1.35.3 ARG KUSTOMIZE_VERSION=v5.6.0 ARG DOCKER_VERSION=29.3.0 ARG DOCKER_BUILDX_VERSION=v0.32.1 -ARG ENVTEST_VERSION=release-0.19 -ARG ENVTEST_K8S_VERSION=1.31.0 +ARG ENVTEST_VERSION=release-0.23 +ARG ENVTEST_K8S_VERSION=1.35.0 ARG GOVULNCHECK_VERSION=v1.3.0 RUN apt-get update && apt-get install -y podman && apt-get clean all diff --git a/pkg/common/observability/logging/logger.go b/pkg/common/observability/logging/logger.go index 0402faf7b6..b7c23d092d 100644 --- a/pkg/common/observability/logging/logger.go +++ b/pkg/common/observability/logging/logger.go @@ -33,21 +33,25 @@ import ( // level can be adjusted after the controller-runtime delegation is fulfilled. var atomicLevel = uberzap.NewAtomicLevelAt(zapcore.InfoLevel) -func customLevelEncoder(l zapcore.Level, enc zapcore.PrimitiveArrayEncoder) { +// LevelEncoder maps negative Zap levels to human-readable names that match +// the project's verbosity constants (VERBOSE=3, DEBUG=4, TRACE=5). Without +// this, controller-runtime's zap bridge emits all V(n) calls as "debug" in +// JSON output, which is misleading for V(1)-V(3) (verbose info). +func LevelEncoder(l zapcore.Level, enc zapcore.PrimitiveArrayEncoder) { if l >= 0 { zapcore.LowercaseLevelEncoder(l, enc) return } switch l { - case zapcore.Level(-1 * DEBUG): // -4 + case zapcore.Level(-1 * DEBUG): // V(4) -> "debug" enc.AppendString("debug") - case zapcore.Level(-1 * TRACE): // -5 + case zapcore.Level(-1 * TRACE): // V(5) -> "trace" enc.AppendString("trace") default: - if l >= zapcore.Level(-1*VERBOSE) { // >= -3 (i.e. V(1)-V(3)) + if l >= zapcore.Level(-1*VERBOSE) { // V(1)-V(3) -> "info" enc.AppendString("info") - } else { + } else { // V(6+) -> "trace" enc.AppendString("trace") } } @@ -55,7 +59,7 @@ func customLevelEncoder(l zapcore.Level, enc zapcore.PrimitiveArrayEncoder) { func InitSetupLogging() { config := uberzap.NewProductionEncoderConfig() - config.EncodeLevel = customLevelEncoder + config.EncodeLevel = LevelEncoder logger := zap.New( zap.Level(atomicLevel), diff --git a/pkg/common/observability/logging/logger_test.go b/pkg/common/observability/logging/logger_test.go index 233c902ab0..8ec7117f6c 100644 --- a/pkg/common/observability/logging/logger_test.go +++ b/pkg/common/observability/logging/logger_test.go @@ -87,7 +87,7 @@ func TestCustomLevelEncoder(t *testing.T) { for _, tt := range tests { t.Run(tt.name, func(t *testing.T) { enc := &mockArrayEncoder{} - customLevelEncoder(tt.level, enc) + LevelEncoder(tt.level, enc) if len(enc.strings) != 1 { t.Fatalf("Expected 1 string appended, got %d", len(enc.strings)) } diff --git a/pkg/epp/framework/plugins/datalayer/extractor/metrics/extractor.go b/pkg/epp/framework/plugins/datalayer/extractor/metrics/extractor.go index 71bb4f7a30..d9ab015225 100644 --- a/pkg/epp/framework/plugins/datalayer/extractor/metrics/extractor.go +++ b/pkg/epp/framework/plugins/datalayer/extractor/metrics/extractor.go @@ -40,10 +40,8 @@ const ( KVCacheUsagePercentKey = "KVCacheUsagePercent" WaitingQueueSizeKey = "WaitingQueueSize" RunningRequestsSizeKey = "RunningRequestsSize" - MaxActiveModelsKey = "MaxActiveModels" ActiveModelsKey = "ActiveModels" WaitingModelsKey = "WaitingModels" - UpdateTimeKey = "UpdateTime" // LoRA metrics based on MSP LoraInfoRunningAdaptersMetricName = "running_lora_adapters" diff --git a/pkg/sidecar/proxy/allowlist.go b/pkg/sidecar/proxy/allowlist.go index 6bf3323bb6..ea54b594e5 100644 --- a/pkg/sidecar/proxy/allowlist.go +++ b/pkg/sidecar/proxy/allowlist.go @@ -23,7 +23,6 @@ import ( "time" "github.com/go-logr/logr" - "github.com/llm-d/llm-d-router/pkg/common/routing" metav1 "k8s.io/apimachinery/pkg/apis/meta/v1" "k8s.io/apimachinery/pkg/apis/meta/v1/unstructured" "k8s.io/apimachinery/pkg/labels" @@ -35,6 +34,9 @@ import ( "k8s.io/client-go/tools/clientcmd" "k8s.io/utils/set" "sigs.k8s.io/controller-runtime/pkg/log" + + "github.com/llm-d/llm-d-router/pkg/common/observability/logging" + "github.com/llm-d/llm-d-router/pkg/common/routing" ) const ( @@ -183,7 +185,7 @@ func (av *AllowlistValidator) Stop() { // Stop all pod informers first av.podInformersMu.Lock() for poolName, stopCh := range av.podStopChans { - av.logger.V(4).Info("stopping pod informer", "pool", poolName) + av.logger.V(logging.DEBUG).Info("stopping pod informer", "pool", poolName) close(stopCh) } // Clear the maps @@ -209,7 +211,7 @@ func (av *AllowlistValidator) IsAllowed(hostPort string) bool { defer av.allowedTargetsMu.RUnlock() allowed := av.allowedTargets.Has(hostPort) - av.logger.V(4).Info("allowlist check", "hostPort", hostPort, "allowed", allowed) + av.logger.V(logging.DEBUG).Info("allowlist check", "hostPort", hostPort, "allowed", allowed) return allowed } @@ -337,7 +339,7 @@ func (av *AllowlistValidator) createPodInformer(poolName string, selector labels func (av *AllowlistValidator) onPodAdd(obj interface{}) { pod := obj.(*unstructured.Unstructured) podIP, _, _ := unstructured.NestedString(pod.Object, "status", "podIP") - av.logger.V(4).Info("Pod added", "name", pod.GetName(), "ip", podIP) + av.logger.V(logging.DEBUG).Info("Pod added", "name", pod.GetName(), "ip", podIP) av.rebuildAllowlist() } @@ -345,14 +347,14 @@ func (av *AllowlistValidator) onPodAdd(obj interface{}) { func (av *AllowlistValidator) onPodUpdate(_, newObj interface{}) { pod := newObj.(*unstructured.Unstructured) podIP, _, _ := unstructured.NestedString(pod.Object, "status", "podIP") - av.logger.V(4).Info("Pod updated", "name", pod.GetName(), "ip", podIP) + av.logger.V(logging.DEBUG).Info("Pod updated", "name", pod.GetName(), "ip", podIP) av.rebuildAllowlist() } // onPodDelete handles deleted pods func (av *AllowlistValidator) onPodDelete(obj interface{}) { pod := obj.(*unstructured.Unstructured) - av.logger.V(4).Info("Pod deleted", "name", pod.GetName()) + av.logger.V(logging.DEBUG).Info("Pod deleted", "name", pod.GetName()) av.rebuildAllowlist() } @@ -398,5 +400,5 @@ func (av *AllowlistValidator) addPodToAllowlist(pod *unstructured.Unstructured, av.allowedTargets.Insert(podName) } - av.logger.V(5).Info("added pod to allowlist", "pod", podName, "ip", podIP, "pool", poolName) + av.logger.V(logging.TRACE).Info("added pod to allowlist", "pod", podName, "ip", podIP, "pool", poolName) } diff --git a/pkg/sidecar/proxy/chat_completions.go b/pkg/sidecar/proxy/chat_completions.go index 34cb5d30b6..fb20d1b070 100644 --- a/pkg/sidecar/proxy/chat_completions.go +++ b/pkg/sidecar/proxy/chat_completions.go @@ -26,7 +26,7 @@ import ( "go.opentelemetry.io/otel/codes" "go.opentelemetry.io/otel/trace" - logging "github.com/llm-d/llm-d-router/pkg/common/observability/logging" + "github.com/llm-d/llm-d-router/pkg/common/observability/logging" "github.com/llm-d/llm-d-router/pkg/common/observability/tracing" "github.com/llm-d/llm-d-router/pkg/common/routing" ) @@ -101,7 +101,7 @@ func (s *Server) disaggregatedPrefillHandler(apiType APIType) http.HandlerFunc { } if len(prefillHostPort) == 0 { - s.logger.V(4).Info("skip disaggregated prefill", "api", apiType.String()) + s.logger.V(logging.DEBUG).Info("skip disaggregated prefill", "api", apiType.String()) span.SetAttributes( attribute.Bool("llm_d.pd_proxy.disaggregation_used", false), attribute.String("llm_d.pd_proxy.reason", "no_prefill_header"), @@ -129,7 +129,7 @@ func (s *Server) disaggregatedPrefillHandler(apiType APIType) http.HandlerFunc { http.Error(w, "Forbidden: prefill target not allowed by SSRF protection", http.StatusForbidden) return } - s.logger.V(4).Info("SSRF protection: prefill target allowed", "target", prefillHostPort) + s.logger.V(logging.DEBUG).Info("SSRF protection: prefill target allowed", "target", prefillHostPort) } kvCacheSource := strings.TrimSpace(r.Header.Get(routing.KVCacheSourceHeader)) @@ -166,7 +166,7 @@ func (s *Server) disaggregatedPrefillHandler(apiType APIType) http.HandlerFunc { encoderHost = strings.TrimSpace(encoderHost) if s.allowlistValidator.IsAllowed(encoderHost) { allowedEncoders = append(allowedEncoders, encoderHost) - s.logger.V(4).Info("SSRF protection: encoder target allowed", "target", encoderHost) + s.logger.V(logging.DEBUG).Info("SSRF protection: encoder target allowed", "target", encoderHost) } else { s.logger.Info("SSRF protection: encoder target not in allowlist, removing from list", "target", encoderHost, @@ -178,7 +178,7 @@ func (s *Server) disaggregatedPrefillHandler(apiType APIType) http.HandlerFunc { } if len(allowedEncoders) > 0 && s.handleECConnector != nil { - s.logger.V(4).Info("encoder headers detected, using EC connector", + s.logger.V(logging.DEBUG).Info("encoder headers detected, using EC connector", "encoderCount", len(allowedEncoders), "encoderCandidates", len(encoderHostPorts), "hasPrefiller", len(prefillHostPort) > 0) @@ -201,12 +201,12 @@ func (s *Server) disaggregatedPrefillHandler(apiType APIType) http.HandlerFunc { } if len(prefillHostPort) > 0 { - s.logger.V(4).Info("using P/D protocol") + s.logger.V(logging.DEBUG).Info("using P/D protocol") s.handlePDConnector(w, r, prefillHostPort, kvCacheSource, apiType) return } - s.logger.V(4).Info("no prefiller or encoder, using decoder only") + s.logger.V(logging.DEBUG).Info("no prefiller or encoder, using decoder only") if !s.forwardDataParallel || !s.dataParallelHandler(w, r) { if kvCacheSource != "" { s.decodeWithP2PSource(w, r, kvCacheSource) diff --git a/pkg/sidecar/proxy/connector_ec_common.go b/pkg/sidecar/proxy/connector_ec_common.go index a4a7b10c5d..ed98bbfc8b 100644 --- a/pkg/sidecar/proxy/connector_ec_common.go +++ b/pkg/sidecar/proxy/connector_ec_common.go @@ -14,7 +14,7 @@ import ( "fmt" "net/http" - logging "github.com/llm-d/llm-d-router/pkg/common/observability/logging" + "github.com/llm-d/llm-d-router/pkg/common/observability/logging" reqcommon "github.com/llm-d/llm-d-router/pkg/common/request" "golang.org/x/sync/errgroup" ) diff --git a/pkg/sidecar/proxy/connector_ec_nixl.go b/pkg/sidecar/proxy/connector_ec_nixl.go index fd4a2b5831..7975f3a836 100644 --- a/pkg/sidecar/proxy/connector_ec_nixl.go +++ b/pkg/sidecar/proxy/connector_ec_nixl.go @@ -8,7 +8,7 @@ import ( "sync" "github.com/google/uuid" - logging "github.com/llm-d/llm-d-router/pkg/common/observability/logging" + "github.com/llm-d/llm-d-router/pkg/common/observability/logging" ) // fanoutEncoderCollect fans out per-image encoder requests and merges diff --git a/pkg/sidecar/proxy/connector_ec_shared_storage.go b/pkg/sidecar/proxy/connector_ec_shared_storage.go index 13fa1e8d18..a981eaee50 100644 --- a/pkg/sidecar/proxy/connector_ec_shared_storage.go +++ b/pkg/sidecar/proxy/connector_ec_shared_storage.go @@ -21,7 +21,7 @@ import ( "net/http" "github.com/google/uuid" - logging "github.com/llm-d/llm-d-router/pkg/common/observability/logging" + "github.com/llm-d/llm-d-router/pkg/common/observability/logging" ) // fanoutEncoderPrimer sends concurrent encoder requests for each multimodal diff --git a/pkg/sidecar/proxy/connector_mooncake.go b/pkg/sidecar/proxy/connector_mooncake.go index 5ef1456262..fd74cd2608 100644 --- a/pkg/sidecar/proxy/connector_mooncake.go +++ b/pkg/sidecar/proxy/connector_mooncake.go @@ -29,6 +29,7 @@ import ( "go.opentelemetry.io/otel/codes" "go.opentelemetry.io/otel/trace" + "github.com/llm-d/llm-d-router/pkg/common/observability/logging" "github.com/llm-d/llm-d-router/pkg/common/observability/tracing" reqcommon "github.com/llm-d/llm-d-router/pkg/common/request" ) @@ -38,7 +39,7 @@ const mooncakeBootstrapTimeout = 5 * time.Second // set to same value as the oth const mooncakeDataParallelRankHeader = "X-data-parallel-rank" // to send rank id in header to prefill func (s *Server) handleMooncake(w http.ResponseWriter, r *http.Request, prefillPodHostPort string) { - s.logger.V(4).Info("running Mooncake protocol", "url", prefillPodHostPort) + s.logger.V(logging.DEBUG).Info("running Mooncake protocol", "url", prefillPodHostPort) body, err := io.ReadAll(r.Body) if err != nil { @@ -73,7 +74,7 @@ func (s *Server) handleMooncake(w http.ResponseWriter, r *http.Request, prefillP } transferID := "xfer-" + newUUID() - s.logger.V(5).Info("mooncake protocol info", + s.logger.V(logging.TRACE).Info("mooncake protocol info", "transfer_id", transferID, "bootstrap_addr", bootstrapAddr, "dp_rank", dpRank, @@ -100,7 +101,11 @@ func (s *Server) handleMooncake(w http.ResponseWriter, r *http.Request, prefillP return } - s.logger.V(5).Info("Prefill request", "body", string(prefillBody)) + // Guarded: stringifying the body allocates a copy per request even when + // TRACE is disabled. + if trace := s.logger.V(logging.TRACE); trace.Enabled() { + trace.Info("Prefill request", "body", string(prefillBody)) + } // Build decode request body decodeData := make(map[string]any) @@ -123,7 +128,9 @@ func (s *Server) handleMooncake(w http.ResponseWriter, r *http.Request, prefillP return } - s.logger.V(5).Info("Decode request", "body", string(decodeBody)) + if trace := s.logger.V(logging.TRACE); trace.Enabled() { + trace.Info("Decode request", "body", string(decodeBody)) + } s.handleMooncakeConcurrentRequests(w, r, prefillBody, decodeBody, prefillPodHostPort, dpRank) } @@ -229,7 +236,7 @@ func (s *Server) handleMooncakeConcurrentRequests(w http.ResponseWriter, r *http if isHTTPError(pw.statusCode) { prefillSpan.SetStatus(codes.Error, "prefill request failed") } - s.logger.V(5).Info("mooncake prefill request completed", "status", pw.statusCode) + s.logger.V(logging.TRACE).Info("mooncake prefill request completed", "status", pw.statusCode) }() // Decode Stage diff --git a/pkg/sidecar/proxy/connector_nixlv2.go b/pkg/sidecar/proxy/connector_nixlv2.go index a086d28c25..7c8281f80c 100644 --- a/pkg/sidecar/proxy/connector_nixlv2.go +++ b/pkg/sidecar/proxy/connector_nixlv2.go @@ -32,6 +32,7 @@ import ( "go.opentelemetry.io/otel/codes" "go.opentelemetry.io/otel/trace" + "github.com/llm-d/llm-d-router/pkg/common/observability/logging" "github.com/llm-d/llm-d-router/pkg/common/observability/tracing" ) @@ -53,7 +54,7 @@ func tokenLimitMap(req map[string]any, apiType APIType) (map[string]any, bool) { func (s *Server) handleNIXLV2(w http.ResponseWriter, r *http.Request, prefillPodHostPort, kvCacheSource string, apiType APIType) { tokenLimitFields := tokenLimitFieldsForAPIType(apiType) - s.logger.V(4).Info("running NIXL protocol V2", "url", prefillPodHostPort, "tokenLimitFields", tokenLimitFields) + s.logger.V(logging.DEBUG).Info("running NIXL protocol V2", "url", prefillPodHostPort, "tokenLimitFields", tokenLimitFields) original, completionRequest, ok := s.readJSONBody(r, w) if !ok { @@ -198,8 +199,12 @@ func (s *Server) handleNIXLV2(w http.ResponseWriter, r *http.Request, prefillPod } // 2. Forward request to prefiller - s.logger.V(4).Info("sending prefill request", "to", prefillPodHostPort) - s.logger.V(5).Info("Prefill request", "body", string(pbody)) + s.logger.V(logging.DEBUG).Info("sending prefill request", "to", prefillPodHostPort) + // Guarded: stringifying the body allocates a copy per request even when + // TRACE is disabled. + if trace := s.logger.V(logging.TRACE); trace.Enabled() { + trace.Info("Prefill request", "body", string(pbody)) + } // Retry on transient 5xx (502/503/504): these failures (e.g. connection // reset → 502) are common when the prefill pod's accept queue overflows @@ -284,7 +289,7 @@ retryLoop: pCachedTokens = 0 } - s.logger.V(5).Info("received prefiller response", requestFieldKVTransferParams, pKVTransferParams) + s.logger.V(logging.TRACE).Info("received prefiller response", requestFieldKVTransferParams, pKVTransferParams) // Decode Stage @@ -416,13 +421,15 @@ retryLoop: // 2. Forward to local decoder. - s.logger.V(5).Info("sending request to decoder", "body", string(dbody)) + if trace := s.logger.V(logging.TRACE); trace.Enabled() { + trace.Info("sending request to decoder", "body", string(dbody)) + } decodeWriter, finalizeDecodeWriter := newCachedTokensResponseWriterWithFinalize(w, pCachedTokens) dataParallelUsed := s.forwardDataParallel && s.dataParallelHandler(decodeWriter, dreq) decodeSpan.SetAttributes(attribute.Bool("llm_d.pd_proxy.decode.data_parallel", dataParallelUsed)) if !dataParallelUsed { - s.logger.V(4).Info("sending request to decoder", "to", s.config.DecoderURL.Host) + s.logger.V(logging.DEBUG).Info("sending request to decoder", "to", s.config.DecoderURL.Host) decodeSpan.SetAttributes(attribute.String("llm_d.pd_proxy.decode.target", s.config.DecoderURL.Host)) s.dispatchDecode(decodeWriter, dreq, completionRequest) } @@ -469,7 +476,7 @@ func (s *Server) runNIXLProtocolV2WriteParallel( w http.ResponseWriter, r *http.Request, original []byte, completionRequest map[string]any, uuidStr, transferID, prefillPodHostPort, kvCacheSource string, ) { - s.logger.V(4).Info("running NIXL protocol V2 (concurrent dispatch)", + s.logger.V(logging.DEBUG).Info("running NIXL protocol V2 (concurrent dispatch)", "url", prefillPodHostPort, "request_id", uuidStr) tracer := tracing.Tracer() @@ -664,8 +671,10 @@ func (s *Server) runNIXLProtocolV2WriteParallel( dreq.Body = io.NopCloser(bytes.NewReader(dbody)) dreq.ContentLength = int64(len(dbody)) - s.logger.V(5).Info("concurrent-dispatch prefill request body", "body", string(pbody)) - s.logger.V(5).Info("concurrent-dispatch decode request body", "body", string(dbody)) + if trace := s.logger.V(logging.TRACE); trace.Enabled() { + trace.Info("concurrent-dispatch prefill request body", "body", string(pbody)) + trace.Info("concurrent-dispatch decode request body", "body", string(dbody)) + } // Decode writes into a deferred writer that buffers everything until we // commit() (prefill succeeded -> flush + stream on) or abort() (prefill diff --git a/pkg/sidecar/proxy/connector_p2p.go b/pkg/sidecar/proxy/connector_p2p.go index b7e054ce6e..2aec135f62 100644 --- a/pkg/sidecar/proxy/connector_p2p.go +++ b/pkg/sidecar/proxy/connector_p2p.go @@ -33,7 +33,7 @@ import ( "go.opentelemetry.io/otel/codes" "go.opentelemetry.io/otel/trace" - logging "github.com/llm-d/llm-d-router/pkg/common/observability/logging" + "github.com/llm-d/llm-d-router/pkg/common/observability/logging" "github.com/llm-d/llm-d-router/pkg/common/observability/tracing" reqcommon "github.com/llm-d/llm-d-router/pkg/common/request" ) diff --git a/pkg/sidecar/proxy/connector_sglang.go b/pkg/sidecar/proxy/connector_sglang.go index b54d3e9632..3a4a01ebe3 100644 --- a/pkg/sidecar/proxy/connector_sglang.go +++ b/pkg/sidecar/proxy/connector_sglang.go @@ -31,6 +31,7 @@ import ( "go.opentelemetry.io/otel/codes" "go.opentelemetry.io/otel/trace" + "github.com/llm-d/llm-d-router/pkg/common/observability/logging" "github.com/llm-d/llm-d-router/pkg/common/observability/tracing" ) @@ -51,7 +52,7 @@ func init() { } func (s *Server) handleSGLang(w http.ResponseWriter, r *http.Request, prefillPodHostPort string) { - s.logger.V(4).Info("running SGLang protocol", "url", prefillPodHostPort) + s.logger.V(logging.DEBUG).Info("running SGLang protocol", "url", prefillPodHostPort) // Make Request requestData, err := s.parseSGLangRequest(r) @@ -129,7 +130,7 @@ func (s *Server) handleSGLangConcurrentRequests(w http.ResponseWriter, r *http.R if pw.statusCode < 200 || pw.statusCode >= 300 { prefillSpan.SetStatus(codes.Error, "prefill request failed") } - s.logger.V(5).Info("prefill request completed", "status", pw.statusCode) + s.logger.V(logging.TRACE).Info("prefill request completed", "status", pw.statusCode) }() // Decode Stage - sync @@ -190,7 +191,7 @@ func (s *Server) addSGLangBootstrapInfo(requestData map[string]interface{}, pref modifiedRequest[requestFieldBootstrapPort] = sglangBootstrapPort modifiedRequest[requestFieldBootstrapRoom] = roomID - s.logger.V(5).Info("bootstrap info added", + s.logger.V(logging.TRACE).Info("bootstrap info added", "bootstrap_host", bootstrapHost, "bootstrap_port", sglangBootstrapPort, "bootstrap_room", roomID) diff --git a/pkg/sidecar/proxy/connector_shared_storage.go b/pkg/sidecar/proxy/connector_shared_storage.go index cd8364c4db..bcb80fe2fe 100644 --- a/pkg/sidecar/proxy/connector_shared_storage.go +++ b/pkg/sidecar/proxy/connector_shared_storage.go @@ -23,10 +23,12 @@ import ( "maps" "net/http" "strings" + + "github.com/llm-d/llm-d-router/pkg/common/observability/logging" ) func (s *Server) handleSharedStorage(w http.ResponseWriter, r *http.Request, prefillPodHostPort string) { - s.logger.V(4).Info("running Shared Storage protocol", "url", prefillPodHostPort) + s.logger.V(logging.DEBUG).Info("running Shared Storage protocol", "url", prefillPodHostPort) original, completionRequest, ok := s.readJSONBody(r, w) if !ok { @@ -38,17 +40,17 @@ func (s *Server) handleSharedStorage(w http.ResponseWriter, r *http.Request, pre // we fall back to P/D disaggregation: perform prefill and then decode. // For more information refer to the RFC https://github.com/vllm-project/vllm/issues/24256 if cacheHitThreshold, hasCacheHitThreshold := completionRequest[requestFieldCacheHitThreshold]; hasCacheHitThreshold { - s.logger.V(4).Info("cache_hit_threshold field found in the request, trying to decode first", requestFieldCacheHitThreshold, cacheHitThreshold) + s.logger.V(logging.DEBUG).Info("cache_hit_threshold field found in the request, trying to decode first", requestFieldCacheHitThreshold, cacheHitThreshold) decodeReq := cloneRequestWithBody(r.Context(), r, original) needsPrefill, err := s.tryDecode(w, decodeReq, completionRequest) if err != nil { return } if !needsPrefill { - s.logger.V(4).Info("decode succeeded without prefill") + s.logger.V(logging.DEBUG).Info("decode succeeded without prefill") return } - s.logger.V(4).Info("decode failed due to failing to meet the cache hit threshold", requestFieldCacheHitThreshold, cacheHitThreshold) + s.logger.V(logging.DEBUG).Info("decode failed due to failing to meet the cache hit threshold", requestFieldCacheHitThreshold, cacheHitThreshold) } // we clone the completion request to avoid modifying the original request @@ -58,7 +60,7 @@ func (s *Server) handleSharedStorage(w http.ResponseWriter, r *http.Request, pre return } - s.logger.V(4).Info("forwarding to decoder after prefill") + s.logger.V(logging.DEBUG).Info("forwarding to decoder after prefill") completionRequest[requestFieldCacheHitThreshold] = 0 decodeRequestBody, err := json.Marshal(completionRequest) if err != nil { @@ -142,7 +144,7 @@ func (s *Server) tryDecodeStreaming(w *responseWriterWithBuffer, r *http.Request select { case <-w.firstChunkReady(): case <-done: - s.logger.V(4).Info("request completed without body data") + s.logger.V(logging.DEBUG).Info("request completed without body data") } statusCode := w.getStatusCode() @@ -156,13 +158,13 @@ func (s *Server) tryDecodeStreaming(w *responseWriterWithBuffer, r *http.Request // Check buffered SSE content for cache_threshold finish reason. if s.checkBufferedResponseForCacheThreshold(w.buffered()) { - s.logger.V(4).Info("finish reason cache_threshold detected, needs prefill") + s.logger.V(logging.DEBUG).Info("finish reason cache_threshold detected, needs prefill") return true, nil } // No cache_threshold finish reason found, flush buffer and switch to direct mode // to let the rest of the response stream through. - s.logger.V(4).Info("first response for request shows success without cache_threshold finish reason") + s.logger.V(logging.DEBUG).Info("first response for request shows success without cache_threshold finish reason") if err := w.flushBufferAndGoDirect(); err != nil { s.logger.Error(err, "failed to flush buffer to client and switch to direct mode") return false, err @@ -200,7 +202,7 @@ func (s *Server) checkBufferedResponseForCacheThreshold(data string) bool { jsonData := strings.TrimPrefix(line, "data: ") var response map[string]any if err := json.Unmarshal([]byte(jsonData), &response); err != nil { - s.logger.V(4).Info("skipping malformed SSE chunk", "chunk", jsonData) + s.logger.V(logging.DEBUG).Info("skipping malformed SSE chunk", "chunk", jsonData) continue } @@ -236,7 +238,7 @@ func (s *Server) prefill(w http.ResponseWriter, r *http.Request, prefillPodHostP } // send prefill request - s.logger.V(4).Info("sending prefill request", "to", prefillPodHostPort) + s.logger.V(logging.DEBUG).Info("sending prefill request", "to", prefillPodHostPort) pw := &bufferedResponseWriter{} prefillHandler.ServeHTTP(pw, preq) @@ -249,6 +251,6 @@ func (s *Server) prefill(w http.ResponseWriter, r *http.Request, prefillPodHostP return fmt.Errorf("prefill request failed with status code: %d", pw.statusCode) } - s.logger.V(4).Info("prefill completed successfully") + s.logger.V(logging.DEBUG).Info("prefill completed successfully") return nil } diff --git a/pkg/sidecar/proxy/data_parallel.go b/pkg/sidecar/proxy/data_parallel.go index f6f2fd95ea..85b53c5c82 100644 --- a/pkg/sidecar/proxy/data_parallel.go +++ b/pkg/sidecar/proxy/data_parallel.go @@ -11,6 +11,7 @@ import ( "golang.org/x/sync/errgroup" "sigs.k8s.io/controller-runtime/pkg/log" + "github.com/llm-d/llm-d-router/pkg/common/observability/logging" "github.com/llm-d/llm-d-router/pkg/common/routing" ) @@ -22,17 +23,17 @@ func (s *Server) dataParallelHandler(w http.ResponseWriter, r *http.Request) boo s.logger.Info("The use of the x-data-parallel-host-port is deprecated. Use Istio >= 1.28.1.") handler := s.dataParallelProxies[dataParallelPodHostPort] if handler != nil { - s.logger.V(4).Info("Data parallel routing", "to", dataParallelPodHostPort) + s.logger.V(logging.DEBUG).Info("Data parallel routing", "to", dataParallelPodHostPort) handler.ServeHTTP(w, r) } else { // Shouldn't happen, send to default server - s.logger.V(4).Info("Didn't find the Data Parallel Proxy", "for", dataParallelPodHostPort) + s.logger.V(logging.DEBUG).Info("Didn't find the Data Parallel Proxy", "for", dataParallelPodHostPort) w.WriteHeader(http.StatusBadRequest) } return true } - s.logger.V(4).Info("skip data parallel") + s.logger.V(logging.DEBUG).Info("skip data parallel") return false } diff --git a/pkg/sidecar/proxy/decode.go b/pkg/sidecar/proxy/decode.go index 2a75abd4ec..d2289b1702 100644 --- a/pkg/sidecar/proxy/decode.go +++ b/pkg/sidecar/proxy/decode.go @@ -25,10 +25,12 @@ import ( "strings" "time" - "github.com/llm-d/llm-d-router/pkg/common/observability/tracing" "go.opentelemetry.io/otel/attribute" "go.opentelemetry.io/otel/codes" "go.opentelemetry.io/otel/trace" + + "github.com/llm-d/llm-d-router/pkg/common/observability/logging" + "github.com/llm-d/llm-d-router/pkg/common/observability/tracing" ) const ( @@ -81,7 +83,7 @@ func (s *Server) runChunkedDecode(w http.ResponseWriter, r *http.Request) { // Non-streaming: accumulated chunks are reassembled into a single JSON response. // Streaming: each chunk is re-emitted as an SSE event; [DONE] closes the stream. func (s *Server) runChunkedDecodeFromMap(w http.ResponseWriter, r *http.Request, completionRequest map[string]any) { - s.logger.V(4).Info("running chunked decode", "chunkSize", s.config.DecodeChunkSize) + s.logger.V(logging.DEBUG).Info("running chunked decode", "chunkSize", s.config.DecodeChunkSize) ctx, span := tracing.Tracer(tracerScope).Start(r.Context(), "chunked_decode", trace.WithSpanKind(trace.SpanKindInternal), @@ -98,7 +100,7 @@ func (s *Server) runChunkedDecodeFromMap(w http.ResponseWriter, r *http.Request, // If the token budget fits within a single chunk, skip chunking entirely. if originalMaxTokens > 0 && originalMaxTokens <= s.config.DecodeChunkSize { - s.logger.V(4).Info("chunked decode: token budget <= chunk size, using regular decode", + s.logger.V(logging.DEBUG).Info("chunked decode: token budget <= chunk size, using regular decode", "maxTokens", originalMaxTokens, "chunkSize", s.config.DecodeChunkSize) s.decoderProxy.ServeHTTP(w, r) return @@ -134,7 +136,7 @@ func (s *Server) runChunkedDecodeFromMap(w http.ResponseWriter, r *http.Request, remaining := remainingTokens(originalMaxTokens, totalTokens) if remaining == 0 { - s.logger.V(4).Info("chunked decode: token budget exhausted", "totalTokens", totalTokens) + s.logger.V(logging.DEBUG).Info("chunked decode: token budget exhausted", "totalTokens", totalTokens) break } @@ -165,7 +167,7 @@ func (s *Server) runChunkedDecodeFromMap(w http.ResponseWriter, r *http.Request, return } - s.logger.V(4).Info("chunked decode: dispatching chunk", + s.logger.V(logging.DEBUG).Info("chunked decode: dispatching chunk", "chunk", chunkIndex, "chunkBudget", chunkBudget, "totalTokensSoFar", totalTokens) bw := &bufferedResponseWriter{} @@ -198,7 +200,7 @@ func (s *Server) runChunkedDecodeFromMap(w http.ResponseWriter, r *http.Request, } chunkIndex++ - s.logger.V(4).Info("chunked decode: chunk complete", "chunkTokens", chunkTokens, "totalTokens", totalTokens) + s.logger.V(logging.DEBUG).Info("chunked decode: chunk complete", "chunkTokens", chunkTokens, "totalTokens", totalTokens) finishReason := extractFinishReason(chunkResponse) chunkText := extractChoiceText(firstChoice(chunkResponse)) @@ -216,7 +218,7 @@ func (s *Server) runChunkedDecodeFromMap(w http.ResponseWriter, r *http.Request, } if finishReason != "" && finishReason != finishReasonLength { - s.logger.V(4).Info("chunked decode: terminal finish reason, stopping", + s.logger.V(logging.DEBUG).Info("chunked decode: terminal finish reason, stopping", "finishReason", finishReason, "chunks", chunkIndex) break } @@ -231,7 +233,7 @@ func (s *Server) runChunkedDecodeFromMap(w http.ResponseWriter, r *http.Request, // Append the generated text to the request so the next chunk continues // from where this one left off. - s.logger.V(5).Info("chunked decode: appending chunk text to request", "chunkText", chunkText) + s.logger.V(logging.TRACE).Info("chunked decode: appending chunk text to request", "chunkText", chunkText) appendChunkToRequest(completionRequest, chunkText) } diff --git a/pkg/sidecar/proxy/options.go b/pkg/sidecar/proxy/options.go index 1df1dbd37a..629f51eca1 100644 --- a/pkg/sidecar/proxy/options.go +++ b/pkg/sidecar/proxy/options.go @@ -693,35 +693,12 @@ func validatePortRange(startPort, rangeSize int) error { return nil } -// customLevelEncoder maps negative Zap levels to human-readable names that -// match the project's verbosity constants (VERBOSE=3, DEBUG=4, TRACE=5). -// Without this, controller-runtime's zap bridge emits all V(n) calls as -// "debug" in JSON output, which is misleading for V(1)–V(3) (verbose info). -func customLevelEncoder(l zapcore.Level, enc zapcore.PrimitiveArrayEncoder) { - if l >= 0 { - zapcore.LowercaseLevelEncoder(l, enc) - return - } - switch l { - case zapcore.Level(-1 * logutil.DEBUG): // V(4) → "debug" - enc.AppendString("debug") - case zapcore.Level(-1 * logutil.TRACE): // V(5) → "trace" - enc.AppendString("trace") - default: - if l >= zapcore.Level(-1*logutil.VERBOSE) { // V(1)–V(3) → "info" - enc.AppendString("info") - } else { // V(6+) → "trace" - enc.AppendString("trace") - } - } -} - // NewLogger returns a logger configured from the Options logging flags, // with a custom level encoder that maps verbosity levels to their semantic // names instead of always rendering V(n) as "debug". func (opts *Options) NewLogger() logr.Logger { config := uberzap.NewProductionEncoderConfig() - config.EncodeLevel = customLevelEncoder + config.EncodeLevel = logutil.LevelEncoder return zap.New( zap.UseFlagOptions(&opts.loggingOptions), zap.Encoder(zapcore.NewJSONEncoder(config)),