From 8ca209a4cc7c178ca4d0acf374a6d33f2b0e7c9d Mon Sep 17 00:00:00 2001 From: marcusDenslow Date: Fri, 1 May 2026 13:38:24 +0200 Subject: [PATCH] feat: add cart/auth/stripe metrics and slog-based log-level counter MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Adds Prometheus instrumentation across the checkout funnel, auth flow, Stripe calls, rate limiters, and HTTP middleware (inflight gauge, request and response sizes). Introduces a slog handler that counts log lines by level so the dashboard can show error/warn rates; existing log.Printf calls are routed through slog and counted as info. Backs the new "terminalshop — Service Overview" Grafana dashboard. Co-Authored-By: Claude Opus 4.7 --- api/handlers/auth.go | 10 +++ api/handlers/cart.go | 22 +++++++ api/main.go | 4 ++ api/middleware/logger.go | 13 +++- api/middleware/metrics.go | 128 +++++++++++++++++++++++++++++++++++- api/middleware/ratelimit.go | 2 + pkg/observability/logger.go | 62 +++++++++++++++++ 7 files changed, 236 insertions(+), 5 deletions(-) create mode 100644 pkg/observability/logger.go diff --git a/api/handlers/auth.go b/api/handlers/auth.go index 1941ab5..23140a8 100644 --- a/api/handlers/auth.go +++ b/api/handlers/auth.go @@ -4,6 +4,7 @@ import ( "encoding/json" "net/http" + "terminalShop/api/middleware" "terminalShop/pkg/auth" "terminalShop/pkg/database" "terminalShop/pkg/models" @@ -46,18 +47,21 @@ func (h *AuthHandler) GetToken(w http.ResponseWriter, r *http.Request) { var req TokenRequest if err := json.NewDecoder(r.Body).Decode(&req); err != nil { + middleware.RecordAuthAttempt("invalid_json") utils.RespondError(w, http.StatusBadRequest, "INVALID_JSON", "invalid request body", nil) return } // validate shared secret if req.ClientSecret != h.authFingerprintKey { + middleware.RecordAuthAttempt("invalid_secret") utils.RespondError(w, http.StatusUnauthorized, "INVALID_SECRET", "invalid client secret", nil) return } // Return if no fingerprint is found if req.Fingerprint == "" { + middleware.RecordAuthAttempt("missing_fingerprint") utils.RespondError(w, http.StatusBadRequest, "MISSING_FINGERPRINT", "fingerprint is required", nil) return } @@ -67,6 +71,7 @@ func (h *AuthHandler) GetToken(w http.ResponseWriter, r *http.Request) { err := db.Where("ssh_key_fingerprint = ?", req.Fingerprint).First(&user).Error if err == gorm.ErrRecordNotFound { if req.SSHPublicKey == "" { + middleware.RecordAuthAttempt("user_not_found") utils.RespondError(w, http.StatusUnauthorized, "USER_NOT_FOUND", "no user found for this fingerprint", nil) return } @@ -75,20 +80,25 @@ func (h *AuthHandler) GetToken(w http.ResponseWriter, r *http.Request) { SSHPublicKey: req.SSHPublicKey, } if err := db.Create(&user).Error; err != nil { + middleware.RecordAuthAttempt("error") utils.RespondError(w, http.StatusInternalServerError, "DATABASE_ERROR", "failed to create user", nil) return } + middleware.RecordAuthAttempt("registered") } else if err != nil { + middleware.RecordAuthAttempt("error") utils.RespondError(w, http.StatusInternalServerError, "DATABASE_ERROR", "failed to look up user", nil) return } token, err := h.jwtManager.GenerateToken(user.ID, user.Email, user.Name) if err != nil { + middleware.RecordAuthAttempt("error") utils.RespondError(w, http.StatusInternalServerError, "TOKEN_ERROR", "failed to generate token", nil) return } + middleware.RecordAuthAttempt("success") utils.RespondSuccess(w, http.StatusOK, map[string]interface{}{ "access_token": token, "token_type": "Bearer", diff --git a/api/handlers/cart.go b/api/handlers/cart.go index 2f55c37..2bf9f38 100644 --- a/api/handlers/cart.go +++ b/api/handlers/cart.go @@ -4,6 +4,7 @@ import ( "encoding/json" "fmt" "net/http" + "time" "github.com/stripe/stripe-go/v78" "github.com/stripe/stripe-go/v78/paymentintent" @@ -251,6 +252,7 @@ func (h *CartHandler) ConvertCart(w http.ResponseWriter, r *http.Request) { cart, err := getOrCreateCart(userID) if err != nil { + middleware.RecordCartConversion("cart_lookup_failed") utils.RespondError(w, http.StatusInternalServerError, "CART_ERROR", "failed to get cart", nil) return } @@ -259,34 +261,40 @@ func (h *CartHandler) ConvertCart(w http.ResponseWriter, r *http.Request) { db.Where("cart_id = ? AND quantity > 0", cart.ID).Preload("Coffee").Find(&items) if len(items) == 0 { + middleware.RecordCartConversion("validation_empty_cart") utils.RespondError(w, http.StatusBadRequest, "VALIDATION_ERROR", "cart is empty", nil) return } if cart.AddressID == nil { + middleware.RecordCartConversion("validation_missing_address") utils.RespondError(w, http.StatusBadRequest, "VALIDATION_ERROR", "shipping address is required", nil) return } if cart.CardID == nil { + middleware.RecordCartConversion("validation_missing_card") utils.RespondError(w, http.StatusBadRequest, "VALIDATION_ERROR", "payment card is required", nil) return } var address models.Address if err := db.First(&address, *cart.AddressID).Error; err != nil { + middleware.RecordCartConversion("validation_invalid_address") utils.RespondError(w, http.StatusBadRequest, "INVALID_ADDRESS", "shipping address not found", nil) return } var card models.Card if err := db.First(&card, *cart.CardID).Error; err != nil { + middleware.RecordCartConversion("validation_invalid_card") utils.RespondError(w, http.StatusBadRequest, "INVALID_CARD", "payment card not found", nil) return } var user models.User if err := db.First(&user, userID).Error; err != nil { + middleware.RecordCartConversion("user_not_found") utils.RespondError(w, http.StatusNotFound, "USER_NOT_FOUND", "user not found", nil) return } @@ -295,6 +303,7 @@ func (h *CartHandler) ConvertCart(w http.ResponseWriter, r *http.Request) { // Ensure the user has a Stripe customer (shared helper with cards handler). if err := ensureStripeCustomer(db, &user); err != nil { + middleware.RecordCartConversion("stripe_customer_failed") utils.RespondError(w, http.StatusInternalServerError, "STRIPE_ERROR", "failed to create stripe customer", nil) return } @@ -343,6 +352,7 @@ func (h *CartHandler) ConvertCart(w http.ResponseWriter, r *http.Request) { total := subtotal + cart.ShippingCost if total < 50 { + middleware.RecordCartConversion("validation_min_amount") utils.RespondError(w, http.StatusBadRequest, "VALIDATION_ERROR", "order total must be at least $0.50", nil) return } @@ -369,6 +379,7 @@ func (h *CartHandler) ConvertCart(w http.ResponseWriter, r *http.Request) { } if err := db.Create(&order).Error; err != nil { + middleware.RecordCartConversion("db_create_order_failed") utils.RespondError(w, http.StatusInternalServerError, "DATABASE_ERROR", "failed to create order", nil) return } @@ -405,27 +416,35 @@ func (h *CartHandler) ConvertCart(w http.ResponseWriter, r *http.Request) { "order_id": fmt.Sprintf("%d", order.ID), } + stripeStart := time.Now() pi, err := paymentintent.New(piParams) + stripeDur := time.Since(stripeStart).Seconds() if err != nil { + middleware.ObserveStripeRequest("payment_intent_create", "error", stripeDur) db.Model(&order).Update("status", models.OrderStatusFailed) if stripeErr, ok := err.(*stripe.Error); ok { switch stripeErr.Type { case stripe.ErrorTypeCard: + middleware.RecordCartConversion("card_declined") audit.OrderFailed(userID, order.ID, total, stripeErr.Msg) utils.RespondError(w, http.StatusPaymentRequired, "CARD_DECLINED", stripeErr.Msg, nil) case stripe.ErrorTypeInvalidRequest: + middleware.RecordCartConversion("stripe_invalid_request") audit.OrderFailed(userID, order.ID, total, stripeErr.Msg) utils.RespondError(w, http.StatusBadRequest, "INVALID_PAYMENT", stripeErr.Msg, nil) default: + middleware.RecordCartConversion("stripe_error") audit.OrderFailed(userID, order.ID, total, stripeErr.Error()) utils.RespondError(w, http.StatusInternalServerError, "PAYMENT_FAILED", "payment failed", nil) } return } + middleware.RecordCartConversion("stripe_error") audit.OrderFailed(userID, order.ID, total, err.Error()) utils.RespondError(w, http.StatusInternalServerError, "PAYMENT_FAILED", "payment failed", nil) return } + middleware.ObserveStripeRequest("payment_intent_create", "success", stripeDur) // Commit payment ID and clear cart in a single transaction. txErr := db.Transaction(func(tx *gorm.DB) error { @@ -447,6 +466,7 @@ func (h *CartHandler) ConvertCart(w http.ResponseWriter, r *http.Request) { // most dangerous failure mode: the customer paid but has no order. // The reconciliation job will catch this within 5 minutes. // The audit log entry below must be treated as a critical alert. + middleware.RecordCartConversion("payment_critical") audit.PaymentCritical(order.ID, pi.ID, txErr) utils.RespondError(w, http.StatusInternalServerError, "DATABASE_ERROR", "payment succeeded but failed to record order — please contact support", nil) return @@ -454,6 +474,8 @@ func (h *CartHandler) ConvertCart(w http.ResponseWriter, r *http.Request) { audit.OrderPaid(userID, order.ID, total, pi.ID) middleware.RecordOrderCreated(string(order.Status)) + middleware.RecordCartConversion("success") + middleware.ObserveOrderValueCents(total) if err := db.Preload("Items").First(&order, order.ID).Error; err != nil { utils.RespondError(w, http.StatusInternalServerError, "INTERNAL_ERROR", "failed to preload items", nil) diff --git a/api/main.go b/api/main.go index 174532c..7d772d9 100644 --- a/api/main.go +++ b/api/main.go @@ -11,6 +11,7 @@ import ( "time" "terminalShop/api/handlers" + "terminalShop/api/middleware" "terminalShop/api/routes" "terminalShop/pkg/auth" "terminalShop/pkg/config" @@ -21,6 +22,9 @@ import ( const version = "v0.1.0" func main() { + observability.InitLogger() + middleware.SetBuildInfo(version) + ctx, cancel := context.WithCancel(context.Background()) defer cancel() // Load configuration diff --git a/api/middleware/logger.go b/api/middleware/logger.go index c1e05a6..0a8e4f4 100644 --- a/api/middleware/logger.go +++ b/api/middleware/logger.go @@ -8,14 +8,15 @@ import ( "go.opentelemetry.io/otel/trace" ) -// responseWriter wraps http.ResponseWriter to capture status code +// responseWriter wraps http.ResponseWriter to capture status code and response size. type responseWriter struct { http.ResponseWriter - statusCode int + statusCode int + bytesWritten int64 } func newResponseWriter(w http.ResponseWriter) *responseWriter { - return &responseWriter{w, http.StatusOK} + return &responseWriter{ResponseWriter: w, statusCode: http.StatusOK} } func (rw *responseWriter) WriteHeader(code int) { @@ -23,6 +24,12 @@ func (rw *responseWriter) WriteHeader(code int) { rw.ResponseWriter.WriteHeader(code) } +func (rw *responseWriter) Write(b []byte) (int, error) { + n, err := rw.ResponseWriter.Write(b) + rw.bytesWritten += int64(n) + return n, err +} + // Logger logs HTTP requests func Logger(next http.Handler) http.Handler { return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { diff --git a/api/middleware/metrics.go b/api/middleware/metrics.go index 5090ac5..cbc70a7 100644 --- a/api/middleware/metrics.go +++ b/api/middleware/metrics.go @@ -29,6 +29,31 @@ var ( []string{"method", "route"}, ) + httpInflightRequests = promauto.NewGauge( + prometheus.GaugeOpts{ + Name: "http_inflight_requests", + Help: "Number of HTTP requests currently being handled", + }, + ) + + httpRequestSize = promauto.NewHistogramVec( + prometheus.HistogramOpts{ + Name: "http_request_size_bytes", + Help: "HTTP request body size in bytes", + Buckets: prometheus.ExponentialBuckets(64, 4, 8), + }, + []string{"method", "route"}, + ) + + httpResponseSize = promauto.NewHistogramVec( + prometheus.HistogramOpts{ + Name: "http_response_size_bytes", + Help: "HTTP response body size in bytes", + Buckets: prometheus.ExponentialBuckets(64, 4, 8), + }, + []string{"method", "route"}, + ) + ordersCreatedTotal = promauto.NewCounterVec( prometheus.CounterOpts{ Name: "orders_created_total", @@ -36,14 +61,74 @@ var ( }, []string{"status"}, ) + + cartConversionTotal = promauto.NewCounterVec( + prometheus.CounterOpts{ + Name: "cart_conversion_total", + Help: "Cart checkout outcomes (success, validation_failed, card_declined, stripe_failed, db_failed, payment_critical)", + }, + []string{"outcome"}, + ) + + orderValueDollars = promauto.NewHistogram( + prometheus.HistogramOpts{ + Name: "order_value_dollars", + Help: "Distribution of completed order totals, in dollars", + Buckets: []float64{1, 5, 10, 20, 30, 50, 75, 100, 150, 250, 500, 1000}, + }, + ) + + stripeRequestDuration = promauto.NewHistogramVec( + prometheus.HistogramOpts{ + Name: "stripe_request_duration_seconds", + Help: "Latency of outbound Stripe API calls", + Buckets: prometheus.DefBuckets, + }, + []string{"op", "outcome"}, + ) + + authAttemptsTotal = promauto.NewCounterVec( + prometheus.CounterOpts{ + Name: "auth_attempts_total", + Help: "Authentication attempts, by result (success, invalid_secret, missing_fingerprint, user_not_found, registered, error)", + }, + []string{"result"}, + ) + + rateLimitRejectionsTotal = promauto.NewCounterVec( + prometheus.CounterOpts{ + Name: "rate_limit_rejections_total", + Help: "Number of requests rejected by rate limiters", + }, + []string{"scope"}, + ) + + logMessagesTotal = promauto.NewCounterVec( + prometheus.CounterOpts{ + Name: "log_messages_total", + Help: "Total log lines emitted, labeled by level", + }, + []string{"level"}, + ) + + buildInfo = promauto.NewGaugeVec( + prometheus.GaugeOpts{ + Name: "terminalshop_build_info", + Help: "Build metadata; value is always 1, version is on the label", + }, + []string{"version"}, + ) ) -// Metrics records request count and latency for every request +// Metrics records request count, latency, sizes, and concurrency for every request. func Metrics(next http.Handler) http.Handler { return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { start := time.Now() wrapped := newResponseWriter(w) + httpInflightRequests.Inc() + defer httpInflightRequests.Dec() + next.ServeHTTP(wrapped, r) route := chi.RouteContext(r.Context()).RoutePattern() @@ -56,15 +141,54 @@ func Metrics(next http.Handler) http.Handler { httpRequestsTotal.WithLabelValues(r.Method, route, status).Inc() httpRequestDuration.WithLabelValues(r.Method, route).Observe(duration) + if r.ContentLength > 0 { + httpRequestSize.WithLabelValues(r.Method, route).Observe(float64(r.ContentLength)) + } + httpResponseSize.WithLabelValues(r.Method, route).Observe(float64(wrapped.bytesWritten)) }) } -// MetricsHandler returns the Prometheus scrape endpoint +// MetricsHandler returns the Prometheus scrape endpoint. func MetricsHandler() http.Handler { return promhttp.Handler() } +// SetBuildInfo records build metadata as a gauge of value 1. +func SetBuildInfo(version string) { + buildInfo.WithLabelValues(version).Set(1) +} + // RecordOrderCreated records a successfully created order. func RecordOrderCreated(status string) { ordersCreatedTotal.WithLabelValues(status).Inc() } + +// RecordCartConversion records the outcome of a checkout attempt. +func RecordCartConversion(outcome string) { + cartConversionTotal.WithLabelValues(outcome).Inc() +} + +// ObserveOrderValueCents records the value of a completed order (cents → dollars). +func ObserveOrderValueCents(cents int) { + orderValueDollars.Observe(float64(cents) / 100.0) +} + +// ObserveStripeRequest records latency of a Stripe API call. +func ObserveStripeRequest(op, outcome string, durSec float64) { + stripeRequestDuration.WithLabelValues(op, outcome).Observe(durSec) +} + +// RecordAuthAttempt records an authentication attempt outcome. +func RecordAuthAttempt(result string) { + authAttemptsTotal.WithLabelValues(result).Inc() +} + +// RecordRateLimitRejection records a request blocked by a rate limiter. +func RecordRateLimitRejection(scope string) { + rateLimitRejectionsTotal.WithLabelValues(scope).Inc() +} + +// RecordLogLevel increments the per-level log counter. +func RecordLogLevel(level string) { + logMessagesTotal.WithLabelValues(level).Inc() +} diff --git a/api/middleware/ratelimit.go b/api/middleware/ratelimit.go index 65659f1..9c1ce64 100644 --- a/api/middleware/ratelimit.go +++ b/api/middleware/ratelimit.go @@ -16,6 +16,7 @@ func RateLimitByIP(limit int, window time.Duration) func(http.Handler) http.Hand limit, window, httprate.WithKeyFuncs(httprate.KeyByIP), httprate.WithLimitHandler(func(w http.ResponseWriter, r *http.Request) { + RecordRateLimitRejection("ip") utils.RespondError(w, http.StatusTooManyRequests, "RATE_LIMITED", "too many requests", nil) }), ) @@ -34,6 +35,7 @@ func RateLimitByUser(limit int, window time.Duration) func(http.Handler) http.Ha return "user:" + strconv.FormatUint(uint64(userID), 10), nil }), httprate.WithLimitHandler(func(w http.ResponseWriter, r *http.Request) { + RecordRateLimitRejection("user") utils.RespondError(w, http.StatusTooManyRequests, "RATE_LIMITED", "too many requests", nil) }), ) diff --git a/pkg/observability/logger.go b/pkg/observability/logger.go new file mode 100644 index 0000000..9fdb218 --- /dev/null +++ b/pkg/observability/logger.go @@ -0,0 +1,62 @@ +package observability + +import ( + "context" + "log" + "log/slog" + "os" + "strings" + + "terminalShop/api/middleware" +) + +// countingHandler wraps a slog.Handler and increments the log_messages_total +// counter for every record before delegating to the inner handler. This is +// what gives the dashboard a per-level log rate without forcing call sites +// to thread metrics manually. +type countingHandler struct { + inner slog.Handler +} + +func (h *countingHandler) Enabled(ctx context.Context, l slog.Level) bool { + return h.inner.Enabled(ctx, l) +} + +func (h *countingHandler) Handle(ctx context.Context, r slog.Record) error { + middleware.RecordLogLevel(strings.ToLower(r.Level.String())) + return h.inner.Handle(ctx, r) +} + +func (h *countingHandler) WithAttrs(attrs []slog.Attr) slog.Handler { + return &countingHandler{inner: h.inner.WithAttrs(attrs)} +} + +func (h *countingHandler) WithGroup(name string) slog.Handler { + return &countingHandler{inner: h.inner.WithGroup(name)} +} + +// InitLogger installs a slog-based default logger with a level-counting wrapper +// and bridges the stdlib `log` package through slog so existing log.Printf +// calls are also counted (as INFO). +func InitLogger() { + level := slog.LevelInfo + if env := strings.ToLower(os.Getenv("LOG_LEVEL")); env != "" { + switch env { + case "debug": + level = slog.LevelDebug + case "warn", "warning": + level = slog.LevelWarn + case "error": + level = slog.LevelError + } + } + + base := slog.NewJSONHandler(os.Stdout, &slog.HandlerOptions{Level: level}) + handler := &countingHandler{inner: base} + slog.SetDefault(slog.New(handler)) + + // Route the stdlib log package through slog at INFO so legacy log.Printf + // calls show up in structured output and bump the counter. + slog.SetLogLoggerLevel(slog.LevelInfo) + log.SetFlags(0) +}