Merge pull request #13 from dappnode/feat/diagnosable-errors

feat: classify every error and name the build in logs and metrics

Author: Marketen

.github/workflows/release-and-push.yml

@@ -76,6 +76,8 @@ jobs:
             --label org.opencontainers.image.source=https://github.com/dappnode/dappnode-nexus-gateway \
             --label org.opencontainers.image.revision=${{ github.sha }} \
             --label org.opencontainers.image.version="$VERSION" \
+            --build-arg VERSION="$VERSION" \
+            --build-arg COMMIT=${{ github.sha }} \
             -t "$ECR_REGISTRY/$IMAGE_NAME:$VERSION" \
             -t "$ECR_REGISTRY/$IMAGE_NAME:latest" \
             -t "$ECR_REGISTRY/$IMAGE_NAME:sha-${{ github.sha }}" \

apps/gateway/Dockerfile

@@ -7,7 +7,12 @@ COPY go.mod go.sum ./
 RUN go mod download
 
 COPY . .
-RUN CGO_ENABLED=0 GOOS=linux go build -ldflags="-s -w" -o /gateway ./apps/gateway
+# Release builds name themselves; logs and metrics carry these values.
+ARG VERSION=dev
+ARG COMMIT=
+RUN CGO_ENABLED=0 GOOS=linux go build \
+    -ldflags="-s -w -X github.com/dappnode/dappnode-nexus-gateway/pkg/buildinfo.Version=${VERSION} -X github.com/dappnode/dappnode-nexus-gateway/pkg/buildinfo.Commit=${COMMIT}" \
+    -o /gateway ./apps/gateway
 
 # ---- Runtime stage ----
 FROM alpine:3.20

apps/gateway/internal/adapters/http/handlers/chat_completions_handler.go

@@ -33,19 +33,19 @@ func NewChatCompletionsHandler(service *services.ChatCompletionsService, logger
 func (h *ChatCompletionsHandler) Handle(w http.ResponseWriter, r *http.Request) {
 	token, err := ExtractBearerToken(r)
 	if err != nil {
-		WriteErrorWithLog(w, r, h.logger, err)
+		rejectRequest(w, r, h.logger, domain.EndpointChatCompletions, err)
 		return
 	}
 
 	body, err := io.ReadAll(io.LimitReader(r.Body, maxRequestBodySize))
 	if err != nil {
-		WriteErrorWithLog(w, r, h.logger, domain.ErrInvalidField("failed to read request body"))
+		rejectRequest(w, r, h.logger, domain.EndpointChatCompletions, domain.ErrInvalidField("failed to read request body"))
 		return
 	}
 
 	genReq, err := mapper.ChatCompletionRequestToDomain(body)
 	if err != nil {
-		WriteErrorWithLog(w, r, h.logger, err)
+		rejectRequest(w, r, h.logger, domain.EndpointChatCompletions, err)
 		return
 	}
 

apps/gateway/internal/adapters/http/handlers/common.go

@@ -7,6 +7,7 @@ import (
 
 	"github.com/dappnode/dappnode-nexus-gateway/apps/gateway/internal/adapters/http/dto"
 	"github.com/dappnode/dappnode-nexus-gateway/apps/gateway/internal/adapters/http/middleware"
+	"github.com/dappnode/dappnode-nexus-gateway/apps/gateway/internal/adapters/observability/metrics"
 	"github.com/dappnode/dappnode-nexus-gateway/apps/gateway/internal/application/ports"
 	"github.com/dappnode/dappnode-nexus-gateway/pkg/domain"
 )
@@ -43,29 +44,21 @@ func WriteErrorWithLog(w http.ResponseWriter, r *http.Request, logger ports.Logg
 			"path", r.URL.Path,
 			"error_type", fmt.Sprintf("%T", err),
 		)
-		gwErr = domain.ErrInternal("an internal error occurred")
+		gwErr = domain.ErrInternal("an internal error occurred").WithMeta("cause", domain.CauseUntypedError)
 	}
 
-	// Log at warn for client errors, error for server errors.
+	// Log at warn for client errors, error for server errors. Provider errors
+	// can echo prompts: only the classification and log-safe metadata go in.
+	fields := []any{
+		"request_id", middleware.GetRequestID(r.Context()),
+		"path", r.URL.Path,
+		"status", gwErr.HTTPStatus,
+	}
+	fields = append(fields, domain.DiagnosticFields(gwErr)...)
 	if gwErr.HTTPStatus >= 500 {
-		fields := []any{
-			"request_id", middleware.GetRequestID(r.Context()),
-			"status", gwErr.HTTPStatus,
-			"gateway_status", gwErr.HTTPStatus,
-			"error_code", gwErr.Code,
-		}
-		// Provider errors can echo prompts; only retain numeric upstream status.
-		if status, ok := gwErr.Metadata["upstream_status"].(int); ok {
-			fields = append(fields, "upstream_status", status)
-		}
 		logger.Error("request failed", fields...)
 	} else if gwErr.HTTPStatus >= 400 {
-		logger.Warn("request error",
-			"request_id", middleware.GetRequestID(r.Context()),
-			"status", gwErr.HTTPStatus,
-			"gateway_status", gwErr.HTTPStatus,
-			"error_code", gwErr.Code,
-		)
+		logger.Warn("request error", fields...)
 	}
 
 	if gwErr.RetryAfter != "" {
@@ -89,6 +82,14 @@ func errorDetail(err *domain.GatewayError) dto.ErrorDetail {
 	return detail
 }
 
+// rejectRequest answers a generation request that failed before reaching the
+// generation service (missing key, unreadable or invalid body), counting it
+// with the failures the service records itself.
+func rejectRequest(w http.ResponseWriter, r *http.Request, logger ports.Logger, endpoint string, err error) {
+	metrics.RecordError(endpoint, metrics.UnresolvedModel, "unknown", metrics.PhaseRequest, err)
+	WriteErrorWithLog(w, r, logger, err)
+}
+
 // ExtractBearerToken extracts the bearer token from the Authorization header.
 func ExtractBearerToken(r *http.Request) (string, error) {
 	auth := r.Header.Get("Authorization")

apps/gateway/internal/adapters/http/handlers/confidential_chat_completions_handler.go

@@ -80,20 +80,20 @@ func (h *ConfidentialChatCompletionsHandler) Handle(w http.ResponseWriter, r *ht
 	w.Header().Set("Cache-Control", "no-store, no-transform")
 
 	if r.Body == nil || r.Body == http.NoBody || r.ContentLength == 0 {
-		WriteErrorWithLog(w, r, h.logger, domain.ErrInvalidField("confidential request body is required"))
+		rejectRequest(w, r, h.logger, domain.EndpointChatCompletions, domain.ErrInvalidField("confidential request body is required"))
 		return
 	}
 	encapsulatedKeys := r.Header.Values(protocol.EncapsulatedKeyHeader)
 	if len(encapsulatedKeys) == 0 {
-		WriteErrorWithLog(w, r, h.logger, domain.ErrInvalidField("confidential endpoint requires an EHBP-encrypted body"))
+		rejectRequest(w, r, h.logger, domain.EndpointChatCompletions, domain.ErrInvalidField("confidential endpoint requires an EHBP-encrypted body"))
 		return
 	}
 	if len(encapsulatedKeys) != 1 || !isCanonicalEHBPKey(encapsulatedKeys[0]) {
-		WriteErrorWithLog(w, r, h.logger, domain.ErrInvalidField("invalid EHBP encapsulated key header"))
+		rejectRequest(w, r, h.logger, domain.EndpointChatCompletions, domain.ErrInvalidField("invalid EHBP encapsulated key header"))
 		return
 	}
 	if r.ContentLength > confidentialMaxEHBPBody {
-		WriteErrorWithLog(w, r, h.logger, domain.ErrInvalidField("encrypted request body exceeds the maximum size"))
+		rejectRequest(w, r, h.logger, domain.EndpointChatCompletions, domain.ErrInvalidField("encrypted request body exceeds the maximum size"))
 		return
 	}
 
@@ -118,47 +118,48 @@ func isCanonicalEHBPKey(encoded string) bool {
 func (h *ConfidentialChatCompletionsHandler) handleDecrypted(w http.ResponseWriter, r *http.Request) {
 	body, err := io.ReadAll(io.LimitReader(r.Body, confidentialEnvelopeLimit+1))
 	if err != nil {
-		WriteErrorWithLog(w, r, h.logger, domain.ErrInvalidField("failed to read confidential request"))
+		rejectRequest(w, r, h.logger, domain.EndpointChatCompletions, domain.ErrInvalidField("failed to read confidential request"))
 		return
 	}
 	if len(body) > confidentialEnvelopeLimit {
-		WriteErrorWithLog(w, r, h.logger, domain.ErrInvalidField("confidential request body exceeds the maximum size"))
+		rejectRequest(w, r, h.logger, domain.EndpointChatCompletions, domain.ErrInvalidField("confidential request body exceeds the maximum size"))
 		return
 	}
 
 	envelope, err := decodeConfidentialEnvelope(body)
 	if err != nil {
-		WriteErrorWithLog(w, r, h.logger, domain.ErrInvalidField(err.Error()))
+		rejectRequest(w, r, h.logger, domain.EndpointChatCompletions, domain.ErrInvalidField(err.Error()))
 		return
 	}
 
 	now := h.now().UTC()
 	issuedAt, err := time.Parse(time.RFC3339, envelope.IssuedAt)
 	if err != nil {
-		WriteErrorWithLog(w, r, h.logger, domain.ErrInvalidField("issued_at must be an RFC3339 timestamp"))
+		rejectRequest(w, r, h.logger, domain.EndpointChatCompletions, domain.ErrInvalidField("issued_at must be an RFC3339 timestamp"))
 		return
 	}
 	if issuedAt.Before(now.Add(-confidentialMaxAge)) {
-		WriteErrorWithLog(w, r, h.logger, domain.ErrInvalidField("confidential request is stale"))
+		rejectRequest(w, r, h.logger, domain.EndpointChatCompletions, domain.ErrInvalidField("confidential request is stale"))
 		return
 	}
 	if issuedAt.After(now.Add(confidentialFutureSkew)) {
-		WriteErrorWithLog(w, r, h.logger, domain.ErrInvalidField("confidential request timestamp is in the future"))
+		rejectRequest(w, r, h.logger, domain.EndpointChatCompletions, domain.ErrInvalidField("confidential request timestamp is in the future"))
 		return
 	}
 
 	parsedID, err := uuid.Parse(envelope.RequestID)
 	if err != nil || parsedID == uuid.Nil || parsedID.String() != envelope.RequestID {
-		WriteErrorWithLog(w, r, h.logger, domain.ErrInvalidField("request_id must be a canonical UUID"))
+		rejectRequest(w, r, h.logger, domain.EndpointChatCompletions, domain.ErrInvalidField("request_id must be a canonical UUID"))
 		return
 	}
 
 	switch h.replays.checkAndStore(envelope.RequestID, now) {
 	case replayDuplicate:
-		WriteErrorWithLog(w, r, h.logger, domain.ErrConflict("confidential request was already processed"))
+		rejectRequest(w, r, h.logger, domain.EndpointChatCompletions, domain.ErrConflict("confidential request was already processed"))
 		return
 	case replayCapacityReached:
-		WriteErrorWithLog(w, r, h.logger, domain.ErrProviderUnavailable("confidential replay protection"))
+		rejectRequest(w, r, h.logger, domain.EndpointChatCompletions, domain.ErrProviderUnavailable("confidential replay protection").WithMeta(
+			"fault", domain.FaultNexus, "dependency", "replay_store", "cause", domain.CauseReplayStoreFull))
 		return
 	}
 

apps/gateway/internal/adapters/http/handlers/reject_metrics_test.go

@@ -0,0 +1,57 @@
+package handlers
+
+import (
+	"net/http/httptest"
+	"strings"
+	"testing"
+
+	"github.com/dappnode/dappnode-nexus-gateway/apps/gateway/internal/adapters/observability/metrics"
+	"github.com/dappnode/dappnode-nexus-gateway/pkg/domain"
+	"github.com/prometheus/client_golang/prometheus/testutil"
+)
+
+// Requests the handler rejects before the generation service sees them are
+// counted with the service's own failures.
+func TestChatHandlerCountsRejectedRequests(t *testing.T) {
+	logger := &privacyLogger{}
+	handler := NewChatCompletionsHandler(nil, logger)
+	for name, tc := range map[string]struct {
+		auth, body, code string
+	}{
+		"missing key":  {body: `{"model":"m","messages":[]}`, code: domain.ErrCodeInvalidAPIKey},
+		"invalid body": {auth: "Bearer sk-test", body: `{`, code: domain.ErrCodeInvalidField},
+	} {
+		t.Run(name, func(t *testing.T) {
+			counter := metrics.ErrorsTotal.WithLabelValues(domain.EndpointChatCompletions, metrics.UnresolvedModel, "unknown",
+				metrics.PhaseRequest, domain.FaultCaller, tc.code, "none")
+			before := testutil.ToFloat64(counter)
+			req := httptest.NewRequest("POST", "/v1/chat/completions", strings.NewReader(tc.body))
+			if tc.auth != "" {
+				req.Header.Set("Authorization", tc.auth)
+			}
+			handler.Handle(httptest.NewRecorder(), req)
+			if got := testutil.ToFloat64(counter) - before; got != 1 {
+				t.Fatalf("errors_total delta = %v, want 1", got)
+			}
+		})
+	}
+}
+
+// Error lines carry the classification, and provider text that is not an
+// identifier never reaches the log.
+func TestErrorLogsCarryClassification(t *testing.T) {
+	const secret = "PRIVATE PROMPT CANARY"
+	logger := &privacyLogger{}
+	err := domain.ErrInternal("an internal error occurred").WithMeta("dependency", "pii", "cause", domain.CausePIIFilterTimeout,
+		"upstream_code", secret, "account_id", "acc_1")
+	WriteErrorWithLog(httptest.NewRecorder(), httptest.NewRequest("POST", "/v1/chat/completions", nil), logger, err)
+	out := logger.output.String()
+	for _, want := range []string{"fault nexus", "cause pii_filter_timeout", "dependency pii", "account_id acc_1"} {
+		if !strings.Contains(out, want) {
+			t.Errorf("log %q lacks %q", out, want)
+		}
+	}
+	if strings.Contains(out, secret) {
+		t.Fatal("error log leaked provider text")
+	}
+}

apps/gateway/internal/adapters/http/handlers/systemone_handler.go

@@ -22,17 +22,17 @@ func NewSystemOneHandler(service *services.GenerateService, logger ports.Logger)
 func (h *SystemOneHandler) Handle(w http.ResponseWriter, r *http.Request) {
 	token, err := ExtractBearerToken(r)
 	if err != nil {
-		WriteErrorWithLog(w, r, h.logger, err)
+		rejectRequest(w, r, h.logger, domain.EndpointSystemOne, err)
 		return
 	}
 	body, err := io.ReadAll(http.MaxBytesReader(w, r.Body, maxRequestBodySize))
 	if err != nil {
-		WriteErrorWithLog(w, r, h.logger, domain.ErrInvalidField("request body unreadable or too large"))
+		rejectRequest(w, r, h.logger, domain.EndpointSystemOne, domain.ErrInvalidField("request body unreadable or too large"))
 		return
 	}
 	req, err := mapper.SystemOneRequestToDomain(body)
 	if err != nil {
-		WriteErrorWithLog(w, r, h.logger, err)
+		rejectRequest(w, r, h.logger, domain.EndpointSystemOne, err)
 		return
 	}
 	call, err := h.service.Proxy(r.Context(), domain.EndpointSystemOne, body, req, token)

apps/gateway/internal/adapters/http/middleware/metrics.go

@@ -12,11 +12,18 @@ import (
 // intentionally placed as the outermost middleware so the recorded duration
 // covers the full handler chain.
 //
-// The route label is read from r.Pattern after the handler runs, because the
-// stdlib ServeMux only populates it when dispatching to a matched route
-// handler. Requests that match no route use the fixed "unmatched" label so a
-// flood of 404s cannot create unbounded series.
-func Metrics(next http.Handler) http.Handler {
+// The route label comes from route, which names the mux pattern a request
+// matches: inner middleware passes the mux a copy of the request, so
+// r.Pattern is never set on the request seen here. Requests that match no
+// route use the fixed "unmatched" label so a flood of 404s cannot create
+// unbounded series.
+func Metrics(route func(*http.Request) string) func(http.Handler) http.Handler {
+	return func(next http.Handler) http.Handler {
+		return metricsHandler(next, route)
+	}
+}
+
+func metricsHandler(next http.Handler, routeOf func(*http.Request) string) http.Handler {
 	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
 		mw := &metricsWriter{ResponseWriter: w, status: http.StatusOK}
 
@@ -26,7 +33,7 @@ func Metrics(next http.Handler) http.Handler {
 		duration := time.Since(start).Seconds()
 		metrics.HTTPInflight.Dec()
 
-		route := r.Pattern
+		route := routeOf(r)
 		if route == "" {
 			route = "unmatched"
 		}

apps/gateway/internal/adapters/http/router.go

@@ -42,7 +42,12 @@ func NewRouter(
 	handler = middleware.Logging(logger)(handler)
 	handler = middleware.Recovery(logger)(handler)
 	handler = middleware.RequestID(handler)
-	handler = middleware.Metrics(handler)
+	// Middleware hands the mux a copy of the request, so the route pattern is
+	// read from the mux rather than from the request the metrics see.
+	handler = middleware.Metrics(func(r *http.Request) string {
+		_, pattern := mux.Handler(r)
+		return pattern
+	})(handler)
 
 	return handler
 }

apps/gateway/internal/adapters/http/router_test.go

@@ -7,6 +7,8 @@ import (
 	"testing"
 
 	"github.com/dappnode/dappnode-nexus-gateway/apps/gateway/internal/adapters/http/handlers"
+	"github.com/dappnode/dappnode-nexus-gateway/apps/gateway/internal/adapters/observability/metrics"
+	"github.com/prometheus/client_golang/prometheus/testutil"
 )
 
 type routerTestLogger struct{}
@@ -56,3 +58,23 @@ func TestNewRouter_PreservesLegacyChatRouteWithoutConfidentialHandler(t *testing
 		t.Fatalf("unauthenticated EHBP key discovery status = %d, want 404", keyDiscoveryResponse.Code)
 	}
 }
+
+// Requests are counted under the route they matched, though the middleware
+// in between hands the mux a copy of the request.
+func TestNewRouter_LabelsMetricsWithTheMatchedRoute(t *testing.T) {
+	logger := &routerTestLogger{}
+	router := NewRouter(handlers.NewHealthHandler(), handlers.NewModelsHandler(nil), handlers.NewChatCompletionsHandler(nil, logger), nil, nil, nil, nil, logger)
+	health := metrics.HTTPRequestsTotal.WithLabelValues("GET /healthz", http.MethodGet, "2xx")
+	unmatched := metrics.HTTPRequestsTotal.WithLabelValues("unmatched", http.MethodGet, "4xx")
+	healthBefore, unmatchedBefore := testutil.ToFloat64(health), testutil.ToFloat64(unmatched)
+
+	router.ServeHTTP(httptest.NewRecorder(), httptest.NewRequest(http.MethodGet, "/healthz", nil))
+	router.ServeHTTP(httptest.NewRecorder(), httptest.NewRequest(http.MethodGet, "/nope", nil))
+
+	if got := testutil.ToFloat64(health) - healthBefore; got != 1 {
+		t.Fatalf("GET /healthz count delta = %v, want 1", got)
+	}
+	if got := testutil.ToFloat64(unmatched) - unmatchedBefore; got != 1 {
+		t.Fatalf("unmatched count delta = %v, want 1", got)
+	}
+}