feat: use slog and add debuging logs

go.mod

@@ -10,6 +10,7 @@ require (
 	github.com/oklog/run v1.2.0
 	github.com/prometheus/alertmanager v0.31.1
 	github.com/prometheus/client_golang v1.23.2
+	github.com/prometheus/common v0.67.5
 	github.com/prometheus/prometheus v0.310.0
 	gotest.tools/v3 v3.5.2
 )
@@ -46,7 +47,6 @@ require (
 	github.com/munnerz/goautoneg v0.0.0-20191010083416-a7dc8b61c822 // indirect
 	github.com/oklog/ulid/v2 v2.1.1 // indirect
 	github.com/prometheus/client_model v0.6.2 // indirect
-	github.com/prometheus/common v0.67.5 // indirect
 	github.com/prometheus/procfs v0.16.1 // indirect
 	go.opentelemetry.io/auto/sdk v1.2.1 // indirect
 	go.opentelemetry.io/otel v1.41.0 // indirect

injectproxy/enforce.go

@@ -16,6 +16,7 @@ package injectproxy
 import (
 	"errors"
 	"fmt"
+	"log/slog"
 	"slices"
 
 	"github.com/prometheus/prometheus/model/labels"
@@ -56,14 +57,17 @@ var (
 func (ms *PromQLEnforcer) Enforce(q string) (string, error) {
 	expr, err := parser.ParseExpr(q)
 	if err != nil {
+		slog.Error("Failed to parse PromQL expression", "error", err, "query", q)
 		return "", fmt.Errorf("%w: %w", ErrQueryParse, err)
 	}
 
 	if err := ms.EnforceNode(expr); err != nil {
 		if errors.Is(err, ErrIllegalLabelMatcher) {
+			slog.Warn("Illegal label matcher encountered during enforcement", "query", q, "error", err)
 			return "", err
 		}
 
+		slog.Error("Failed to enforce label on AST node", "error", err, "query", q)
 		return "", fmt.Errorf("%w: %w", ErrEnforceLabel, err)
 	}
 
@@ -271,6 +275,7 @@ func (ms PromQLEnforcer) EnforceMatchers(targets []*labels.Matcher) ([]*labels.M
 			}
 
 			if !ok {
+				slog.Info("Label matcher conflict detected", "targetMatcher", target.String(), "injectedMatcher", matcher.String())
 				return res, fmt.Errorf("%w: label matcher %q conflicts with injected matcher %q", ErrIllegalLabelMatcher, target.String(), matcher.String())
 			}
 		}
@@ -282,6 +287,7 @@ func (ms PromQLEnforcer) EnforceMatchers(targets []*labels.Matcher) ([]*labels.M
 		// In both cases, the enforced matcher will be added after
 		// iterating on all the expression's matchers.
 		if matcher.Type == labels.MatchEqual || matcher.String() == target.String() {
+			slog.Info("Dropping existing label matcher in favor of injected matcher", "droppedMatcher", target.String(), "injectedMatcher", matcher.String())
 			continue
 		}
 

injectproxy/routes.go

@@ -21,7 +21,7 @@ import (
 	"errors"
 	"fmt"
 	"io"
-	"log"
+	"log/slog"
 	"net/http"
 	"net/http/httputil"
 	"net/url"
@@ -54,8 +54,6 @@ type routes struct {
 	errorOnReplace        bool
 	regexMatch            bool
 	rulesWithActiveAlerts bool
-
-	logger *log.Logger
 }
 
 type options struct {
@@ -146,6 +144,26 @@ func WithRegexMatch() Option {
 	})
 }
 
+// loggingResponseWriter wraps http.ResponseWriter to capture the HTTP status code and prevent double-logging.
+type loggingResponseWriter struct {
+	http.ResponseWriter
+	statusCode int
+}
+
+// WriteHeader captures the status code before writing it to the underlying response writer.
+func (lrw *loggingResponseWriter) WriteHeader(code int) {
+	lrw.statusCode = code
+	lrw.ResponseWriter.WriteHeader(code)
+}
+
+// Write ensures a default 200 OK status is captured if WriteHeader wasn't explicitly called.
+func (lrw *loggingResponseWriter) Write(b []byte) (int, error) {
+	if lrw.statusCode == 0 {
+		lrw.statusCode = http.StatusOK
+	}
+	return lrw.ResponseWriter.Write(b)
+}
+
 // mux abstracts away the behavior we expect from the http.ServeMux type in this package.
 type mux interface {
 	http.Handler
@@ -223,14 +241,16 @@ type ExtractLabeler interface {
 // HTTPFormEnforcer enforces a label value extracted from the HTTP form and query parameters.
 type HTTPFormEnforcer struct {
 	ParameterName string
+	Label         string
 }
 
 // ExtractLabel implements the ExtractLabeler interface.
 func (hff HTTPFormEnforcer) ExtractLabel(next http.HandlerFunc) http.Handler {
 	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
 		labelValues, err := hff.getLabelValues(r)
 		if err != nil {
-			prometheusAPIError(w, humanFriendlyErrorMessage(err), http.StatusBadRequest)
+			slog.Error("Failed to extract labels from PostForm", "error", err, "source", "queryParameter", "parameter", hff.ParameterName)
+			prometheusAPIError(w, r, humanFriendlyErrorMessage(err), http.StatusBadRequest)
 			return
 		}
 
@@ -242,7 +262,8 @@ func (hff HTTPFormEnforcer) ExtractLabel(next http.HandlerFunc) http.Handler {
 		// Remove the param from the PostForm.
 		if r.Method == http.MethodPost {
 			if err := r.ParseForm(); err != nil {
-				prometheusAPIError(w, fmt.Sprintf("Failed to parse the PostForm: %v", err), http.StatusInternalServerError)
+				slog.Error("Failed to parse the PostForm", "error", err, "source", "queryParameter", "parameter", hff.ParameterName)
+				prometheusAPIError(w, r, fmt.Sprintf("Failed to parse the PostForm: %v", err), http.StatusInternalServerError)
 				return
 			}
 			if r.PostForm.Get(hff.ParameterName) != "" {
@@ -255,6 +276,7 @@ func (hff HTTPFormEnforcer) ExtractLabel(next http.HandlerFunc) http.Handler {
 			}
 		}
 
+		slog.Info("Extracted label from PostForm", "source", "parameter", "queryParameter", hff.ParameterName, "label", hff.Label, "values", labelValues)
 		next.ServeHTTP(w, r.WithContext(WithLabelValues(r.Context(), labelValues)))
 	})
 }
@@ -276,6 +298,7 @@ func (hff HTTPFormEnforcer) getLabelValues(r *http.Request) ([]string, error) {
 // HTTPHeaderEnforcer enforces a label value extracted from the HTTP headers.
 type HTTPHeaderEnforcer struct {
 	Name            string
+	Label           string
 	ParseListSyntax bool
 }
 
@@ -284,10 +307,12 @@ func (hhe HTTPHeaderEnforcer) ExtractLabel(next http.HandlerFunc) http.Handler {
 	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
 		labelValues, err := hhe.getLabelValues(r)
 		if err != nil {
-			prometheusAPIError(w, humanFriendlyErrorMessage(err), http.StatusBadRequest)
+			slog.Error("Failed to extract labels from header", "error", err, "source", "header", "header", hhe.Name)
+			prometheusAPIError(w, r, humanFriendlyErrorMessage(err), http.StatusBadRequest)
 			return
 		}
 
+		slog.Info("Extracted label from header", "source", "header", "header", hhe.Name, "label", hhe.Label, "values", labelValues)
 		next.ServeHTTP(w, r.WithContext(WithLabelValues(r.Context(), labelValues)))
 	})
 }
@@ -309,12 +334,16 @@ func (hhe HTTPHeaderEnforcer) getLabelValues(r *http.Request) ([]string, error)
 }
 
 // StaticLabelEnforcer enforces a static label value.
-type StaticLabelEnforcer []string
+type StaticLabelEnforcer struct {
+	Label       string
+	LabelValues []string
+}
 
 // ExtractLabel implements the ExtractLabeler interface.
 func (sle StaticLabelEnforcer) ExtractLabel(next http.HandlerFunc) http.Handler {
 	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
-		next(w, r.WithContext(WithLabelValues(r.Context(), sle)))
+		slog.Info("Extracted static label", "source", "static", "label", sle.Label, "values", sle.LabelValues)
+		next(w, r.WithContext(WithLabelValues(r.Context(), sle.LabelValues)))
 	})
 }
 
@@ -338,7 +367,6 @@ func NewRoutes(upstream *url.URL, label string, extractLabeler ExtractLabeler, o
 		errorOnReplace:        opt.errorOnReplace,
 		regexMatch:            opt.regexMatch,
 		rulesWithActiveAlerts: opt.rulesWithActiveAlerts,
-		logger:                log.Default(),
 	}
 	mux := newStrictMux(newInstrumentedMux(http.NewServeMux(), opt.registerer))
 
@@ -451,13 +479,23 @@ func NewRoutes(upstream *url.URL, label string, extractLabeler ExtractLabeler, o
 	proxy.Transport = transport
 	proxy.ModifyResponse = r.ModifyResponse
 	proxy.ErrorHandler = r.errorHandler
-	proxy.ErrorLog = log.Default()
-
+	proxy.ErrorLog = slog.NewLogLogger(slog.Default().Handler(), slog.LevelError)
 	return r, nil
 }
 
 func (r *routes) ServeHTTP(w http.ResponseWriter, req *http.Request) {
-	r.mux.ServeHTTP(w, req)
+	lrw := &loggingResponseWriter{ResponseWriter: w, statusCode: http.StatusOK}
+
+	r.mux.ServeHTTP(lrw, req)
+
+	// log if it's an error AND it hasn't been logged yet
+	if lrw.statusCode >= 400 && lrw.Header().Get("X-Proxy-Error-Logged") == "" {
+		slog.Debug("HTTP request failed",
+			"method", req.Method,
+			"path", req.URL.Path,
+			"status", lrw.statusCode,
+		)
+	}
 }
 
 func (r *routes) ModifyResponse(resp *http.Response) error {
@@ -470,8 +508,15 @@ func (r *routes) ModifyResponse(resp *http.Response) error {
 	return m(resp)
 }
 
-func (r *routes) errorHandler(rw http.ResponseWriter, _ *http.Request, err error) {
-	r.logger.Printf("http: proxy error: %v", err)
+func (r *routes) errorHandler(rw http.ResponseWriter, req *http.Request, err error) {
+	rw.Header().Set("X-Proxy-Error-Logged", "true")
+
+	slog.Error("HTTP proxy error",
+		"error", err,
+		"path", req.URL.Path,
+		"method", req.Method,
+	)
+
 	if errors.Is(err, errModifyResponseFailed) {
 		rw.WriteHeader(http.StatusBadRequest)
 	}
@@ -492,7 +537,7 @@ func enforceMethods(h http.HandlerFunc, methods ...string) http.HandlerFunc {
 func (r *routes) errorIfRegexpMatch(next http.HandlerFunc) http.HandlerFunc {
 	return func(w http.ResponseWriter, req *http.Request) {
 		if r.regexMatch {
-			prometheusAPIError(w, "support for regex match not implemented", http.StatusNotImplemented)
+			prometheusAPIError(w, req, "support for regex match not implemented", http.StatusNotImplemented)
 			return
 		}
 
@@ -551,7 +596,7 @@ func (r *routes) passthrough(w http.ResponseWriter, req *http.Request) {
 func (r *routes) query(w http.ResponseWriter, req *http.Request) {
 	matcher, err := r.newLabelMatcher(MustLabelValues(req.Context())...)
 	if err != nil {
-		prometheusAPIError(w, err.Error(), http.StatusBadRequest)
+		prometheusAPIError(w, req, err.Error(), http.StatusBadRequest)
 		return
 	}
 
@@ -566,11 +611,11 @@ func (r *routes) query(w http.ResponseWriter, req *http.Request) {
 	if err != nil {
 		switch {
 		case errors.Is(err, ErrIllegalLabelMatcher):
-			prometheusAPIError(w, err.Error(), http.StatusBadRequest)
+			prometheusAPIError(w, req, err.Error(), http.StatusBadRequest)
 		case errors.Is(err, ErrQueryParse):
-			prometheusAPIError(w, err.Error(), http.StatusBadRequest)
+			prometheusAPIError(w, req, err.Error(), http.StatusBadRequest)
 		case errors.Is(err, ErrEnforceLabel):
-			prometheusAPIError(w, err.Error(), http.StatusInternalServerError)
+			prometheusAPIError(w, req, err.Error(), http.StatusInternalServerError)
 		}
 
 		return
@@ -581,17 +626,17 @@ func (r *routes) query(w http.ResponseWriter, req *http.Request) {
 	// Enforce the query in the POST body if needed.
 	if req.Method == http.MethodPost {
 		if err := req.ParseForm(); err != nil {
-			prometheusAPIError(w, err.Error(), http.StatusBadRequest)
+			prometheusAPIError(w, req, err.Error(), http.StatusBadRequest)
 		}
 		q, found2, err = enforceQueryValues(e, req.PostForm)
 		if err != nil {
 			switch {
 			case errors.Is(err, ErrIllegalLabelMatcher):
-				prometheusAPIError(w, err.Error(), http.StatusBadRequest)
+				prometheusAPIError(w, req, err.Error(), http.StatusBadRequest)
 			case errors.Is(err, ErrQueryParse):
-				prometheusAPIError(w, err.Error(), http.StatusBadRequest)
+				prometheusAPIError(w, req, err.Error(), http.StatusBadRequest)
 			case errors.Is(err, ErrEnforceLabel):
-				prometheusAPIError(w, err.Error(), http.StatusInternalServerError)
+				prometheusAPIError(w, req, err.Error(), http.StatusInternalServerError)
 			}
 
 			return
@@ -615,15 +660,18 @@ func enforceQueryValues(e *PromQLEnforcer, v url.Values) (values string, noQuery
 	// If no values were given or no query is present,
 	// e.g. because the query came in the POST body
 	// but the URL query string was passed, then finish early.
-	if v.Get(queryParam) == "" {
+	origQuery := v.Get(queryParam)
+	if origQuery == "" {
 		return v.Encode(), false, nil
 	}
 
-	q, err := e.Enforce(v.Get(queryParam))
+	q, err := e.Enforce(origQuery)
 	if err != nil {
+		slog.Error("Failed to enforce query", "error", err, "query", origQuery)
 		return "", true, err
 	}
 
+	slog.Info("Successfully enforced query", "originalQuery", origQuery, "enforcedQuery", q)
 	v.Set(queryParam, q)
 
 	return v.Encode(), true, nil
@@ -668,13 +716,13 @@ func (r *routes) newLabelMatcher(vals ...string) (*labels.Matcher, error) {
 func (r *routes) matcher(w http.ResponseWriter, req *http.Request) {
 	matcher, err := r.newLabelMatcher(MustLabelValues(req.Context())...)
 	if err != nil {
-		prometheusAPIError(w, err.Error(), http.StatusBadRequest)
+		prometheusAPIError(w, req, err.Error(), http.StatusBadRequest)
 		return
 	}
 
 	q := req.URL.Query()
 	if err := injectMatcher(q, matcher); err != nil {
-		prometheusAPIError(w, err.Error(), http.StatusBadRequest)
+		prometheusAPIError(w, req, err.Error(), http.StatusBadRequest)
 		return
 	}
 
@@ -700,22 +748,27 @@ func (r *routes) matcher(w http.ResponseWriter, req *http.Request) {
 }
 
 func injectMatcher(q url.Values, matcher *labels.Matcher) error {
+	origMatchers := append([]string(nil), q[matchersParam]...)
+
 	matchers := q[matchersParam]
 	if len(matchers) == 0 {
 		q.Set(matchersParam, matchersToString(matcher))
+		slog.Info("Successfully injected matcher", "originalMatchers", origMatchers, "enforcedMatchers", q[matchersParam])
 		return nil
 	}
 
 	// Inject label into existing matchers.
 	for i, m := range matchers {
 		ms, err := parser.ParseMetricSelector(m)
 		if err != nil {
+			slog.Error("Failed to parse metric selector during matcher injection", "error", err, "matcher", m)
 			return err
 		}
 
 		matchers[i] = matchersToString(append(ms, matcher)...)
 	}
 	q[matchersParam] = matchers
+	slog.Info("Successfully injected matchers", "originalMatchers", origMatchers, "enforcedMatchers", q[matchersParam])
 
 	return nil
 }