From 1ea30e560ba0bf9ef766f1648d9a9f93c7d7684d Mon Sep 17 00:00:00 2001 From: Kiro Agent <244629292+kiro-agent@users.noreply.github.com> Date: Fri, 31 Jul 2026 02:54:46 +0000 Subject: [PATCH] feat(observability): add OpenTelemetry tracing and Prometheus metrics Tracing: - internal/observability/tracing.go: OTLP HTTP exporter, resource attrs (service.name/namespace/deployment.environment), ParentBased ratio sampler, W3C propagation. No-op when disabled so dev/tests need no collector; never fails the app on telemetry errors - instrument the HTTP server via otelhttp, naming spans after the matched mux route instead of the raw path to avoid span-name explosion, and excluding /sse - instrument pgx with otelpgx and all outbound clients with an otelhttp transport via utils.NewHTTPClient - RequestID now prefers the active span's trace/span ids so log lines correlate with the traces Tempo actually stores Metrics: - internal/observability: dedicated registry with Go runtime + process collectors and app metrics (sse_active_clients, cache_operations_total, upstream_request_duration_seconds, http_requests_total/duration) - serve /metrics and /healthz on a separate internal-only port, never on the public router - record per-upstream latency and outcome in the SSE fetch path, where failures were previously silent Wiring: - make init order explicit in main: loaders, then tracing, then the pgx pool and handlers, because otelpgx/otelhttp capture the global tracer provider at construction time - flush spans last during graceful shutdown - compose: join the shared observability network, set GOMEMLIMIT with a memory limit, keep the metrics port unpublished --- .env.example | 7 +- Dockerfile | 4 + cmd/api/main.go | 40 +++++++++ compose.yaml | 24 ++++++ go.mod | 37 +++++++-- go.sum | 92 ++++++++++++++++++--- internal/cache/cache.go | 7 ++ internal/clients/cloudflare/client.go | 4 +- internal/clients/github/client.go | 4 +- internal/clients/jellyfin/client.go | 4 +- internal/clients/navidrome/client.go | 4 +- internal/clients/pixiv/client.go | 4 +- internal/clients/pushover/client.go | 4 +- internal/clients/spotify/client.go | 4 +- internal/db/sqlc/gen.go | 16 +++- internal/features/sse/service.go | 77 ++++++++++-------- internal/middleware/metrics.go | 49 +++++++++++ internal/middleware/requestid.go | 38 ++++++--- internal/observability/http.go | 62 ++++++++++++++ internal/observability/metrics.go | 87 ++++++++++++++++++++ internal/observability/server.go | 65 +++++++++++++++ internal/observability/tracing.go | 112 ++++++++++++++++++++++++++ internal/server/handlers.go | 13 ++- internal/server/server.go | 7 +- internal/utils/http.go | 23 ++++++ 25 files changed, 715 insertions(+), 73 deletions(-) create mode 100644 internal/middleware/metrics.go create mode 100644 internal/observability/http.go create mode 100644 internal/observability/metrics.go create mode 100644 internal/observability/server.go create mode 100644 internal/observability/tracing.go create mode 100644 internal/utils/http.go diff --git a/.env.example b/.env.example index 9735086..2b6e88a 100644 --- a/.env.example +++ b/.env.example @@ -52,10 +52,15 @@ LOG_FORMAT=json # METRICS_PORT: internal-only port for /metrics and /healthz (added later). # Do NOT publish this port; the collector scrapes it over the Docker network. METRICS_PORT=9090 -# OTEL_* follow the OpenTelemetry spec so the SDK reads them natively (later). +# OTEL_* follow the OpenTelemetry spec so the SDK reads them natively. OTEL_SERVICE_NAME=api +# Tracing is opt-in. When disabled (or the endpoint is empty) the tracer is a +# no-op, so local development and tests need no collector. TRACING_ENABLED=false +# Alloy's OTLP HTTP receiver, e.g. http://alloy:4318 OTEL_EXPORTER_OTLP_ENDPOINT= +# Ratio of NEW traces to sample. Errors and slow requests are kept regardless +# by tail sampling in the collector, which needs the whole trace to decide. TRACE_SAMPLE_RATIO=0.1 # --- diff --git a/Dockerfile b/Dockerfile index 53abb8a..3ff980b 100644 --- a/Dockerfile +++ b/Dockerfile @@ -35,6 +35,10 @@ ENTRYPOINT [ "/main" ] EXPOSE 4000 +# Internal-only metrics/health port. Documented here but deliberately not +# published to the host in compose; the collector scrapes it over the network. +EXPOSE 9090 + LABEL org.opencontainers.image.authors="ami@ccrsxx.com" \ org.opencontainers.image.source="https://github.com/ccrsxx/api" \ org.opencontainers.image.description="My personal API for my projects" \ diff --git a/cmd/api/main.go b/cmd/api/main.go index 1ab77bb..9d5e363 100644 --- a/cmd/api/main.go +++ b/cmd/api/main.go @@ -2,29 +2,59 @@ package main import ( "context" + "errors" "log/slog" + "net/http" "os/signal" "syscall" "time" "github.com/ccrsxx/api/internal/config" "github.com/ccrsxx/api/internal/db/sqlc" + "github.com/ccrsxx/api/internal/observability" "github.com/ccrsxx/api/internal/server" ) func main() { cfg := config.Load() + // Configure logging (and error rendering) first so every subsequent line, + // including telemetry setup, is properly structured. + server.LoadLoaders(cfg) + shutdownCtx, cancelShutdown := signal.NotifyContext(context.Background(), syscall.SIGTERM, syscall.SIGINT) defer cancelShutdown() + // Tracing must be initialized before the pgx pool and HTTP handlers are + // built: otelpgx and otelhttp capture the global tracer provider at + // construction time, so initializing later would silently lose all spans. + // A telemetry failure must never prevent the API from serving, so we log + // and continue with the returned no-op shutdown. + shutdownTracing, err := observability.InitTracing(shutdownCtx, cfg) + + if err != nil { + slog.Error("tracing init failed", "error", err) + } + pool, db := sqlc.NewQueries(shutdownCtx, cfg.DatabaseURL) defer pool.Close() server := server.New(shutdownCtx, cfg, pool, db) + // Internal-only server for /metrics and /healthz. Its port is deliberately + // not published; the collector scrapes it over the Docker network. + metricsServer := observability.NewServer(cfg, pool) + + go func() { + slog.Info("metrics server start listening", "port", metricsServer.Addr) + + if err := metricsServer.ListenAndServe(); err != nil && !errors.Is(err, http.ErrServerClosed) { + slog.Error("metrics server stop listening", "error", err) + } + }() + go func() { slog.Info("server start listening", "port", server.Addr, "env", cfg.AppEnv) @@ -54,5 +84,15 @@ func main() { slog.Error("server shutdown failed", "error", err) } + if err := metricsServer.Shutdown(shutdownTimeoutCtx); err != nil { + slog.Error("metrics server shutdown failed", "error", err) + } + + // Flush buffered spans last, so spans produced by in-flight requests during + // the graceful shutdown window are still exported. + if err := shutdownTracing(shutdownTimeoutCtx); err != nil { + slog.Error("tracing shutdown failed", "error", err) + } + slog.Info("server stopped gracefully") } diff --git a/compose.yaml b/compose.yaml index 916b12a..7d05d34 100644 --- a/compose.yaml +++ b/compose.yaml @@ -12,6 +12,20 @@ services: - PORT=4000 - APP_ENV=production - DATABASE_URL=postgres://postgres:${DATABASE_PASSWORD}@db:5432/postgres + # Observability. METRICS_PORT is intentionally NOT published: the Alloy + # collector scrapes it over the shared 'observability' network. + - METRICS_PORT=9090 + - OTEL_SERVICE_NAME=api + - TRACING_ENABLED=${TRACING_ENABLED:-false} + - OTEL_EXPORTER_OTLP_ENDPOINT=${OTEL_EXPORTER_OTLP_ENDPOINT:-} + - TRACE_SAMPLE_RATIO=${TRACE_SAMPLE_RATIO:-0.1} + # Tell the Go runtime about the container memory limit so it GCs harder + # instead of being OOM-killed. Keep below the limit below. + - GOMEMLIMIT=450MiB + deploy: + resources: + limits: + memory: 512M read_only: true cap_drop: - ALL @@ -20,6 +34,9 @@ services: depends_on: db: condition: service_healthy + networks: + - default + - observability db: image: postgres:18.4 @@ -60,3 +77,10 @@ services: volumes: db-data: + +networks: + default: + # Shared with the LGTM stack so Alloy can scrape api:9090 and the API can + # reach the collector's OTLP endpoint. Create once: docker network create observability + observability: + external: true diff --git a/go.mod b/go.mod index 1e82ebc..b42e6c9 100644 --- a/go.mod +++ b/go.mod @@ -5,30 +5,55 @@ go 1.26.2 require ( github.com/bdpiprava/scalar-go v0.13.0 github.com/caarlos0/env/v11 v11.4.1 + github.com/exaring/otelpgx v0.11.1 github.com/go-playground/validator/v10 v10.30.3 github.com/golang-jwt/jwt/v5 v5.3.1 github.com/google/uuid v1.6.0 github.com/ipinfo/go/v2 v2.14.0 github.com/jackc/pgx/v5 v5.10.0 github.com/joho/godotenv v1.5.1 + github.com/prometheus/client_golang v1.24.1 + go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp v0.69.0 + go.opentelemetry.io/otel v1.44.0 + go.opentelemetry.io/otel/exporters/otlp/otlptrace/otlptracehttp v1.44.0 + go.opentelemetry.io/otel/sdk v1.44.0 + go.opentelemetry.io/otel/trace v1.44.0 golang.org/x/oauth2 v0.36.0 golang.org/x/time v0.15.0 ) require ( + github.com/beorn7/perks v1.0.1 // indirect + github.com/cenkalti/backoff/v5 v5.0.3 // indirect + github.com/cespare/xxhash/v2 v2.3.0 // indirect + github.com/felixge/httpsnoop v1.0.4 // indirect github.com/gabriel-vasile/mimetype v1.4.13 // indirect + github.com/go-logr/logr v1.4.3 // indirect + github.com/go-logr/stdr v1.2.2 // indirect github.com/go-playground/locales v0.14.1 // indirect github.com/go-playground/universal-translator v0.18.1 // indirect + github.com/grpc-ecosystem/grpc-gateway/v2 v2.29.0 // indirect github.com/jackc/pgpassfile v1.0.0 // indirect github.com/jackc/pgservicefile v0.0.0-20240606120523-5a60cdf6a761 // indirect github.com/jackc/puddle/v2 v2.2.2 // indirect - github.com/kr/text v0.2.0 // indirect github.com/leodido/go-urn v1.4.0 // indirect + github.com/munnerz/goautoneg v0.0.0-20191010083416-a7dc8b61c822 // indirect github.com/patrickmn/go-cache v2.1.0+incompatible // indirect - github.com/rogpeppe/go-internal v1.14.1 // indirect - golang.org/x/crypto v0.52.0 // indirect - golang.org/x/sync v0.20.0 // indirect - golang.org/x/sys v0.45.0 // indirect - golang.org/x/text v0.37.0 // indirect + github.com/prometheus/client_model v0.6.2 // indirect + github.com/prometheus/common v0.70.1 // indirect + github.com/prometheus/procfs v0.21.1 // indirect + go.opentelemetry.io/auto/sdk v1.2.1 // indirect + go.opentelemetry.io/otel/exporters/otlp/otlptrace v1.44.0 // indirect + go.opentelemetry.io/otel/metric v1.44.0 // indirect + go.opentelemetry.io/proto/otlp v1.10.0 // indirect + golang.org/x/crypto v0.54.0 // indirect + golang.org/x/net v0.57.0 // indirect + golang.org/x/sync v0.22.0 // indirect + golang.org/x/sys v0.47.0 // indirect + golang.org/x/text v0.40.0 // indirect + google.golang.org/genproto/googleapis/api v0.0.0-20260526163538-3dc84a4a5aaa // indirect + google.golang.org/genproto/googleapis/rpc v0.0.0-20260526163538-3dc84a4a5aaa // indirect + google.golang.org/grpc v1.81.1 // indirect + google.golang.org/protobuf v1.36.11 // indirect gopkg.in/yaml.v3 v3.0.1 // indirect ) diff --git a/go.sum b/go.sum index b1d4b15..aa3c36f 100644 --- a/go.sum +++ b/go.sum @@ -1,13 +1,27 @@ github.com/bdpiprava/scalar-go v0.13.0 h1:TuhOwYalDpLAziohyEwZlq4PqtEJ+6P/V92dDCdja9k= github.com/bdpiprava/scalar-go v0.13.0/go.mod h1:e5Nn4yIhcYjlucu4ACMqcs410nIAe5whqj78H3Qv7vw= +github.com/beorn7/perks v1.0.1 h1:VlbKKnNfV8bJzeqoa4cOKqO6bYr3WgKZxO8Z16+hsOM= +github.com/beorn7/perks v1.0.1/go.mod h1:G2ZrVWU2WbWT9wwq4/hrbKbnv/1ERSJQ0ibhJ6rlkpw= github.com/caarlos0/env/v11 v11.4.1 h1:fYwH0sWEsBSMPG7t4e/PEfTFzrWrpjyygXyUnWiSwEw= github.com/caarlos0/env/v11 v11.4.1/go.mod h1:qupehSf/Y0TUTsxKywqRt/vJjN5nz6vauiYEUUr8P4U= -github.com/creack/pty v1.1.9/go.mod h1:oKZEueFk5CKHvIhNR5MUki03XCEU+Q6VDXinZuGJ33E= +github.com/cenkalti/backoff/v5 v5.0.3 h1:ZN+IMa753KfX5hd8vVaMixjnqRZ3y8CuJKRKj1xcsSM= +github.com/cenkalti/backoff/v5 v5.0.3/go.mod h1:rkhZdG3JZukswDf7f0cwqPNk4K0sa+F97BxZthm/crw= +github.com/cespare/xxhash/v2 v2.3.0 h1:UL815xU9SqsFlibzuggzjXhog7bL6oX9BbNZnL2UFvs= +github.com/cespare/xxhash/v2 v2.3.0/go.mod h1:VGX0DQ3Q6kWi7AoAeZDth3/j3BFtOZR5XLFGgcrjCOs= github.com/davecgh/go-spew v1.1.0/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38= github.com/davecgh/go-spew v1.1.1 h1:vj9j/u1bqnvCEfJOwUhtlOARqs3+rkHYY13jYWTU97c= github.com/davecgh/go-spew v1.1.1/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38= +github.com/exaring/otelpgx v0.11.1 h1:pE79fIg/qh/Lpu00kvswFC5dKfqyJJhMJ4Y4N3w5Lj4= +github.com/exaring/otelpgx v0.11.1/go.mod h1:3OojrUKhhy3lTbYIMBijP3YjMey/jo14eHAW5cXcUdk= +github.com/felixge/httpsnoop v1.0.4 h1:NFTV2Zj1bL4mc9sqWACXbQFVBBg2W3GPvqp8/ESS2Wg= +github.com/felixge/httpsnoop v1.0.4/go.mod h1:m8KPJKqk1gH5J9DgRY2ASl2lWCfGKXixSwevea8zH2U= github.com/gabriel-vasile/mimetype v1.4.13 h1:46nXokslUBsAJE/wMsp5gtO500a4F3Nkz9Ufpk2AcUM= github.com/gabriel-vasile/mimetype v1.4.13/go.mod h1:d+9Oxyo1wTzWdyVUPMmXFvp4F9tea18J8ufA774AB3s= +github.com/go-logr/logr v1.2.2/go.mod h1:jdQByPbusPIv2/zmleS9BjJVeZ6kBagPoEUsqbVz/1A= +github.com/go-logr/logr v1.4.3 h1:CjnDlHq8ikf6E492q6eKboGOC0T8CDaOvkHCIg8idEI= +github.com/go-logr/logr v1.4.3/go.mod h1:9T104GzyrTigFIr8wt5mBrctHMim0Nb2HLGrmQ40KvY= +github.com/go-logr/stdr v1.2.2 h1:hSWxHoqTgW2S2qGc0LTAI563KZ5YKYRhT3MFKZMbjag= +github.com/go-logr/stdr v1.2.2/go.mod h1:mMo/vtBO5dYbehREoey6XUKy/eSumjCCveDpRre4VKE= github.com/go-playground/assert/v2 v2.2.0 h1:JvknZsQTYeFEAhQwI4qEt9cyV5ONwRHC+lYKSsYSR8s= github.com/go-playground/assert/v2 v2.2.0/go.mod h1:VDjEfimB/XKnb+ZQfWdccd7VUvScMdVu0Titje2rxJ4= github.com/go-playground/locales v0.14.1 h1:EWaQ/wswjilfKLTECiXz7Rh+3BjFhfDFKv/oXslEjJA= @@ -18,8 +32,14 @@ github.com/go-playground/validator/v10 v10.30.3 h1:4MU6YkEwx7GbcPJOZxrtbu+QfF3pJ github.com/go-playground/validator/v10 v10.30.3/go.mod h1:4Axh7oCNGcoGkqLoE4YWt6n20mcEIsPRlB7vPk3lpyc= github.com/golang-jwt/jwt/v5 v5.3.1 h1:kYf81DTWFe7t+1VvL7eS+jKFVWaUnK9cB1qbwn63YCY= github.com/golang-jwt/jwt/v5 v5.3.1/go.mod h1:fxCRLWMO43lRc8nhHWY6LGqRcf+1gQWArsqaEUEa5bE= +github.com/golang/protobuf v1.5.4 h1:i7eJL8qZTpSEXOPTxNKhASYpMn+8e5Q6AdndVa1dWek= +github.com/golang/protobuf v1.5.4/go.mod h1:lnTiLA8Wa4RWRcIUkrtSVa5nRhsEGBg48fD6rSs7xps= +github.com/google/go-cmp v0.7.0 h1:wk8382ETsv4JYUZwIsn6YpYiWiBsYLSJiTsyBybVuN8= +github.com/google/go-cmp v0.7.0/go.mod h1:pXiqmnSA92OHEEa9HXL2W4E7lf9JzCmGVUdgjX3N/iU= github.com/google/uuid v1.6.0 h1:NIvaJDMOsjHA8n1jAhLSgzrAzy1Hgr+hNrb57e+94F0= github.com/google/uuid v1.6.0/go.mod h1:TIyPZe4MgqvfeYDBFedMoGGpEw/LqOeaOT+nhxU+yHo= +github.com/grpc-ecosystem/grpc-gateway/v2 v2.29.0 h1:5VipnvEpbqr2gA2VbM+nYVbkIF28c5ZQfqCBQ5g2xfk= +github.com/grpc-ecosystem/grpc-gateway/v2 v2.29.0/go.mod h1:Hyl3n6Twe1hvtd9XUXDec4pTvgMSEixRuQKPTMH2bNs= github.com/ipinfo/go/v2 v2.14.0 h1:suK/cRZd91ycwz4dkxvq89ywC4ZZnZWarDkf2Ll3LSw= github.com/ipinfo/go/v2 v2.14.0/go.mod h1:YMqoJR6iO7Sq2X7s0lgD9DnX9UjldRMp6QJZk30+48w= github.com/jackc/pgpassfile v1.0.0 h1:/6Hmqy13Ss2zCq62VdNG8tM1wchn8zjSGOBJ6icpsIM= @@ -32,16 +52,30 @@ github.com/jackc/puddle/v2 v2.2.2 h1:PR8nw+E/1w0GLuRFSmiioY6UooMp6KJv0/61nB7icHo github.com/jackc/puddle/v2 v2.2.2/go.mod h1:vriiEXHvEE654aYKXXjOvZM39qJ0q+azkZFrfEOc3H4= github.com/joho/godotenv v1.5.1 h1:7eLL/+HRGLY0ldzfGMeQkb7vMd0as4CfYvUVzLqw0N0= github.com/joho/godotenv v1.5.1/go.mod h1:f4LDr5Voq0i2e/R5DDNOoa2zzDfwtkZa6DnEwAbqwq4= -github.com/kr/pretty v0.3.0 h1:WgNl7dwNpEZ6jJ9k1snq4pZsg7DOEN8hP9Xw0Tsjwk0= -github.com/kr/pretty v0.3.0/go.mod h1:640gp4NfQd8pI5XOwp5fnNeVWj67G7CFk/SaSQn7NBk= +github.com/klauspost/compress v1.19.1 h1:VsB4HPswih7mmZ8WleSFQ75c/Ui1M4trX5oAsJnhSlk= +github.com/klauspost/compress v1.19.1/go.mod h1:cwPg85FWrGar70rWktvGQj8/hthj3wpl0PGDogxkrSQ= +github.com/kr/pretty v0.3.1 h1:flRD4NNwYAUpkphVc1HcthR4KEIFJ65n8Mw5qdRn3LE= +github.com/kr/pretty v0.3.1/go.mod h1:hoEshYVHaxMs3cyo3Yncou5ZscifuDolrwPKZanG3xk= github.com/kr/text v0.2.0 h1:5Nx0Ya0ZqY2ygV366QzturHI13Jq95ApcVaJBhpS+AY= github.com/kr/text v0.2.0/go.mod h1:eLer722TekiGuMkidMxC/pM04lWEeraHUUmBw8l2grE= +github.com/kylelemons/godebug v1.1.0 h1:RPNrshWIDI6G2gRW9EHilWtl7Z6Sb1BR0xunSBf0SNc= +github.com/kylelemons/godebug v1.1.0/go.mod h1:9/0rRGxNHcop5bhtWyNeEfOS8JIWk580+fNqagV/RAw= github.com/leodido/go-urn v1.4.0 h1:WT9HwE9SGECu3lg4d/dIA+jxlljEa1/ffXKmRjqdmIQ= github.com/leodido/go-urn v1.4.0/go.mod h1:bvxc+MVxLKB4z00jd1z+Dvzr47oO32F/QSNjSBOlFxI= +github.com/munnerz/goautoneg v0.0.0-20191010083416-a7dc8b61c822 h1:C3w9PqII01/Oq1c1nUAm88MOHcQC9l5mIlSMApZMrHA= +github.com/munnerz/goautoneg v0.0.0-20191010083416-a7dc8b61c822/go.mod h1:+n7T8mK8HuQTcFwEeznm/DIxMOiR9yIdICNftLE1DvQ= github.com/patrickmn/go-cache v2.1.0+incompatible h1:HRMgzkcYKYpi3C8ajMPV8OFXaaRUnok+kx1WdO15EQc= github.com/patrickmn/go-cache v2.1.0+incompatible/go.mod h1:3Qf8kWWT7OJRJbdiICTKqZju1ZixQ/KpMGzzAfe6+WQ= github.com/pmezard/go-difflib v1.0.0 h1:4DBwDE0NGyQoBHbLQYPwSUPoCMWR5BEzIk/f1lZbAQM= github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4= +github.com/prometheus/client_golang v1.24.1 h1:JnJkREXzWxUdCuPFpIWZiPispT9xVV59uiuyR2bPlnU= +github.com/prometheus/client_golang v1.24.1/go.mod h1:F+oSRECHg4sse5ucfYpYDeIv/hu68Zo0uoHKetWnzcE= +github.com/prometheus/client_model v0.6.2 h1:oBsgwpGs7iVziMvrGhE53c/GrLUsZdHnqNwqPLxwZyk= +github.com/prometheus/client_model v0.6.2/go.mod h1:y3m2F6Gdpfy6Ut/GBsUqTWZqCUvMVzSfMLjcu6wAwpE= +github.com/prometheus/common v0.70.1 h1:1HvjP4D5oL3t8RsPlwxA9onvvStjtIHYE5XuuwOi/PY= +github.com/prometheus/common v0.70.1/go.mod h1:VdFUQDMZK3VLkurFUVhia6uys/0suUp86TJz5qbJRhc= +github.com/prometheus/procfs v0.21.1 h1:GljZCt+zSTS+NZq88cyQ1LjZ+RCHp3uVuabBWA5+OJI= +github.com/prometheus/procfs v0.21.1/go.mod h1:aB55Cww9pdSJVHk0hUf0inxWyyjPogFIjmHKYgMKmtY= github.com/rogpeppe/go-internal v1.14.1 h1:UQB4HGPB6osV0SQTLymcB4TgvyWu6ZyliaW0tI/otEQ= github.com/rogpeppe/go-internal v1.14.1/go.mod h1:MaRKkUm5W0goXpeCfT7UZI6fk/L7L7so1lCWt35ZSgc= github.com/stretchr/objx v0.1.0/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME= @@ -49,18 +83,54 @@ github.com/stretchr/testify v1.3.0/go.mod h1:M5WIy9Dh21IEIfnGCwXGc5bZfKNJtfHm1UV github.com/stretchr/testify v1.7.0/go.mod h1:6Fq8oRcR53rry900zMqJjRRixrwX3KX962/h/Wwjteg= github.com/stretchr/testify v1.11.1 h1:7s2iGBzp5EwR7/aIZr8ao5+dra3wiQyKjjFuvgVKu7U= github.com/stretchr/testify v1.11.1/go.mod h1:wZwfW3scLgRK+23gO65QZefKpKQRnfz6sD981Nm4B6U= -golang.org/x/crypto v0.52.0 h1:RMs7fP2rXdep0CftQlK8Uf+kibLm7qkCcradZWYz988= -golang.org/x/crypto v0.52.0/go.mod h1:1QgfPxDqh0T2M/elOJtp9RvuR95kVjir0e6/BvEmGbc= +go.opentelemetry.io/auto/sdk v1.2.1 h1:jXsnJ4Lmnqd11kwkBV2LgLoFMZKizbCi5fNZ/ipaZ64= +go.opentelemetry.io/auto/sdk v1.2.1/go.mod h1:KRTj+aOaElaLi+wW1kO/DZRXwkF4C5xPbEe3ZiIhN7Y= +go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp v0.69.0 h1:8tvICD4vSTOOsNrsI4Ljf6C+6UKvpTEH5XY3JMoyPoo= +go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp v0.69.0/go.mod h1:z9+yiacE0IHRqM4qFfkbt/JYlmYXgss8GY/jXoNuPJI= +go.opentelemetry.io/otel v1.44.0 h1:JjwHmHpA4iZ3wBxluu2fbbE7j4kqlE8jXyAyPXH7HqU= +go.opentelemetry.io/otel v1.44.0/go.mod h1:BMgjTHL9WPRlRjL2oZCBTL4whCGtXch2H4BhOPIAyYc= +go.opentelemetry.io/otel/exporters/otlp/otlptrace v1.44.0 h1:4YsVu3B8+3qtWYYrsUYgn0OG78pN0rnNPRGX4SbokQI= +go.opentelemetry.io/otel/exporters/otlp/otlptrace v1.44.0/go.mod h1:+wnlSn0mD1ADVMe3v9Z/WIaiz6q6gL2J/ejaAmdmv80= +go.opentelemetry.io/otel/exporters/otlp/otlptrace/otlptracehttp v1.44.0 h1:lgh3PiVrRUWMLOVSkQicxzZll5NjF1r+AtsX1XRIHw0= +go.opentelemetry.io/otel/exporters/otlp/otlptrace/otlptracehttp v1.44.0/go.mod h1:5Cnhth3m/AgOeTgE3ex12pPmiu/gGtZit03kSzx9X7s= +go.opentelemetry.io/otel/metric v1.44.0 h1:1w0gILTcHdr3YI+ixLyjemwrVnsMURbTZFrSYCdDdmc= +go.opentelemetry.io/otel/metric v1.44.0/go.mod h1:8O7hanEPBNgEMmybD3s2VBKcgWOCsA6tzHBPODAiquo= +go.opentelemetry.io/otel/sdk v1.44.0 h1:nHYwb9lK+fJPU/dnT6s7W7Z8itMWyqrnVfbheVYrZ58= +go.opentelemetry.io/otel/sdk v1.44.0/go.mod h1:Osuydd3Se74nqjAKxid74N5eC+jfEqfTegHRnq58oK0= +go.opentelemetry.io/otel/sdk/metric v1.44.0 h1:3LlKgI+VjbVsjNRFZJZAJ30WjXC5VkNRks6si09iEfI= +go.opentelemetry.io/otel/sdk/metric v1.44.0/go.mod h1:5B5pMARnXxKhltooO4xUuCBorl65a4EpnTalObqOigA= +go.opentelemetry.io/otel/trace v1.44.0 h1:jxF5CsGYCe74MCRx2X4g7WsY/VBKRqqpNvXlX/6gtIk= +go.opentelemetry.io/otel/trace v1.44.0/go.mod h1:oLl1jrMQAVo6v3GAggN+1VH9VIz9iUSvW53sW1Q8PIE= +go.opentelemetry.io/proto/otlp v1.10.0 h1:IQRWgT5srOCYfiWnpqUYz9CVmbO8bFmKcwYxpuCSL2g= +go.opentelemetry.io/proto/otlp v1.10.0/go.mod h1:/CV4QoCR/S9yaPj8utp3lvQPoqMtxXdzn7ozvvozVqk= +go.uber.org/goleak v1.3.0 h1:2K3zAYmnTNqV73imy9J1T3WC+gmCePx2hEGkimedGto= +go.uber.org/goleak v1.3.0/go.mod h1:CoHD4mav9JJNrW/WLlf7HGZPjdw8EucARQHekz1X6bE= +go.yaml.in/yaml/v2 v2.4.4 h1:tuyd0P+2Ont/d6e2rl3be67goVK4R6deVxCUX5vyPaQ= +go.yaml.in/yaml/v2 v2.4.4/go.mod h1:gMZqIpDtDqOfM0uNfy0SkpRhvUryYH0Z6wdMYcacYXQ= +golang.org/x/crypto v0.54.0 h1:YLIA59K4fiNzHzjnZt2tUJQjQtUWfWbeHBqKtk3eScw= +golang.org/x/crypto v0.54.0/go.mod h1:KWL8ny2AZdGR2cWmzeHrp2azQPGogOv+HeQaVEXC2dk= +golang.org/x/net v0.57.0 h1:K5+3DljvIuDG9/Jv9rvyMywYNFCQ9RSUY6OOTTkT+tE= +golang.org/x/net v0.57.0/go.mod h1:KpXc8iv+r3XplLAG/f7Jsf9RPszJzdR0f58q9vGOuEU= golang.org/x/oauth2 v0.36.0 h1:peZ/1z27fi9hUOFCAZaHyrpWG5lwe0RJEEEeH0ThlIs= golang.org/x/oauth2 v0.36.0/go.mod h1:YDBUJMTkDnJS+A4BP4eZBjCqtokkg1hODuPjwiGPO7Q= -golang.org/x/sync v0.20.0 h1:e0PTpb7pjO8GAtTs2dQ6jYa5BWYlMuX047Dco/pItO4= -golang.org/x/sync v0.20.0/go.mod h1:9xrNwdLfx4jkKbNva9FpL6vEN7evnE43NNNJQ2LF3+0= -golang.org/x/sys v0.45.0 h1:dO4czNzziLiiXplLQgBCEpCvXQ3dnkn0SdaZSYdQ+FY= -golang.org/x/sys v0.45.0/go.mod h1:4GL1E5IUh+htKOUEOaiffhrAeqysfVGipDYzABqnCmw= -golang.org/x/text v0.37.0 h1:Cqjiwd9eSg8e0QAkyCaQTNHFIIzWtidPahFWR83rTrc= -golang.org/x/text v0.37.0/go.mod h1:a5sjxXGs9hsn/AJVwuElvCAo9v8QYLzvavO5z2PiM38= +golang.org/x/sync v0.22.0 h1:SZjpbeLmrCk4xhRSZFNZW5gFUeCeFgjekvI/+gfScek= +golang.org/x/sync v0.22.0/go.mod h1:9xrNwdLfx4jkKbNva9FpL6vEN7evnE43NNNJQ2LF3+0= +golang.org/x/sys v0.47.0 h1:o7XGOvZQCADBQQ4Y7VNq2dRWQR7JmOUW8Kxx4ZsNgWs= +golang.org/x/sys v0.47.0/go.mod h1:4GL1E5IUh+htKOUEOaiffhrAeqysfVGipDYzABqnCmw= +golang.org/x/text v0.40.0 h1:Ub2Z6/xjgF1WrYQz2nuITOEegKFtiIy+rieRJ5lHZKs= +golang.org/x/text v0.40.0/go.mod h1:hpnzDAfGV753zIKo+wk3u1bVKCGPbrnF7+7LBF/UHVY= golang.org/x/time v0.15.0 h1:bbrp8t3bGUeFOx08pvsMYRTCVSMk89u4tKbNOZbp88U= golang.org/x/time v0.15.0/go.mod h1:Y4YMaQmXwGQZoFaVFk4YpCt4FLQMYKZe9oeV/f4MSno= +gonum.org/v1/gonum v0.17.0 h1:VbpOemQlsSMrYmn7T2OUvQ4dqxQXU+ouZFQsZOx50z4= +gonum.org/v1/gonum v0.17.0/go.mod h1:El3tOrEuMpv2UdMrbNlKEh9vd86bmQ6vqIcDwxEOc1E= +google.golang.org/genproto/googleapis/api v0.0.0-20260526163538-3dc84a4a5aaa h1:Kjn0N0tCrDgiAFW+lGO4JZ3ck44CehvJQMAwj9QF0G8= +google.golang.org/genproto/googleapis/api v0.0.0-20260526163538-3dc84a4a5aaa/go.mod h1:q4lMZS6kskjT5HvCPrnnypcDPVJqT/f4nfxmkE7gryY= +google.golang.org/genproto/googleapis/rpc v0.0.0-20260526163538-3dc84a4a5aaa h1:mZHHdPZl0dbGHCflZgAq/Q468DWVFcU2whhB2KAo8fk= +google.golang.org/genproto/googleapis/rpc v0.0.0-20260526163538-3dc84a4a5aaa/go.mod h1:4Hqkh8ycfw05ld/3BWL7rJOSfebL2Q+DVDeRgYgxUU8= +google.golang.org/grpc v1.81.1 h1:VnnIIZ88UzOOKLukQi+ImGz8O1Wdp8nAGGnvOfEIWQQ= +google.golang.org/grpc v1.81.1/go.mod h1:xGH9GfzOyMTGIOXBJmXt+BX/V0kcdQbdcuwQ/zNw42I= +google.golang.org/protobuf v1.36.11 h1:fV6ZwhNocDyBLK0dj+fg8ektcVegBBuEolpbTQyBNVE= +google.golang.org/protobuf v1.36.11/go.mod h1:HTf+CrKn2C3g5S8VImy6tdcUvCska2kB7j23XfzDpco= gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0= gopkg.in/check.v1 v1.0.0-20201130134442-10cb98267c6c h1:Hei/4ADfdWqJk1ZMxUNpqntNwaWcugrBjAiHlqqRiVk= gopkg.in/check.v1 v1.0.0-20201130134442-10cb98267c6c/go.mod h1:JHkPIbrfpd72SG/EVd6muEfDQjcINNoR0C8j2r3qZ4Q= diff --git a/internal/cache/cache.go b/internal/cache/cache.go index de78133..19ac410 100644 --- a/internal/cache/cache.go +++ b/internal/cache/cache.go @@ -5,6 +5,8 @@ import ( "errors" "log/slog" "time" + + "github.com/ccrsxx/api/internal/observability" ) var ErrCacheMiss = errors.New("cache miss") @@ -43,11 +45,16 @@ func GetOrFetch[T any]( if err == nil { if casted, ok := val.(T); ok { + observability.CacheOperationsTotal.WithLabelValues("hit").Inc() + slog.Debug("cache hit", "key", key) + return casted, nil } } + observability.CacheOperationsTotal.WithLabelValues("miss").Inc() + data, err := fetcher() if err != nil { diff --git a/internal/clients/cloudflare/client.go b/internal/clients/cloudflare/client.go index 068777a..6537b64 100644 --- a/internal/clients/cloudflare/client.go +++ b/internal/clients/cloudflare/client.go @@ -9,6 +9,8 @@ import ( "net/http" "time" + "github.com/ccrsxx/api/internal/utils" + "github.com/ccrsxx/api/internal/api" ) @@ -34,7 +36,7 @@ func NewClient(cfg Config) *Client { } if cfg.HTTPClient == nil { - cfg.HTTPClient = &http.Client{Timeout: 8 * time.Second} + cfg.HTTPClient = utils.NewHTTPClient(8 * time.Second) } return &Client{ diff --git a/internal/clients/github/client.go b/internal/clients/github/client.go index ff46252..b8f7404 100644 --- a/internal/clients/github/client.go +++ b/internal/clients/github/client.go @@ -7,6 +7,8 @@ import ( "log/slog" "net/http" "time" + + "github.com/ccrsxx/api/internal/utils" ) type Client struct { @@ -30,7 +32,7 @@ func NewClient(cfg Config) *Client { } if cfg.HTTPClient == nil { - cfg.HTTPClient = &http.Client{Timeout: 8 * time.Second} + cfg.HTTPClient = utils.NewHTTPClient(8 * time.Second) } return &Client{ diff --git a/internal/clients/jellyfin/client.go b/internal/clients/jellyfin/client.go index 44e63d5..992a4f6 100644 --- a/internal/clients/jellyfin/client.go +++ b/internal/clients/jellyfin/client.go @@ -7,6 +7,8 @@ import ( "log/slog" "net/http" "time" + + "github.com/ccrsxx/api/internal/utils" ) type Config struct { @@ -27,7 +29,7 @@ type Client struct { func NewClient(cfg Config) *Client { if cfg.HTTPClient == nil { - cfg.HTTPClient = &http.Client{Timeout: 8 * time.Second} + cfg.HTTPClient = utils.NewHTTPClient(8 * time.Second) } return &Client{ diff --git a/internal/clients/navidrome/client.go b/internal/clients/navidrome/client.go index eae306f..071b562 100644 --- a/internal/clients/navidrome/client.go +++ b/internal/clients/navidrome/client.go @@ -13,6 +13,8 @@ import ( "net/http" "time" + "github.com/ccrsxx/api/internal/utils" + "github.com/ccrsxx/api/internal/api" ) @@ -37,7 +39,7 @@ const ( func NewClient(cfg Config) *Client { if cfg.HTTPClient == nil { - cfg.HTTPClient = &http.Client{Timeout: 8 * time.Second} + cfg.HTTPClient = utils.NewHTTPClient(8 * time.Second) } authParams := createAuthParams(cfg.Username, cfg.Password) diff --git a/internal/clients/pixiv/client.go b/internal/clients/pixiv/client.go index 16110ac..9f921b8 100644 --- a/internal/clients/pixiv/client.go +++ b/internal/clients/pixiv/client.go @@ -8,6 +8,8 @@ import ( "net/http" "strings" "time" + + "github.com/ccrsxx/api/internal/utils" ) const ( @@ -30,7 +32,7 @@ type Client struct { func NewClient(cfg Config) *Client { if cfg.HTTPClient == nil { - cfg.HTTPClient = &http.Client{Timeout: 8 * time.Second} + cfg.HTTPClient = utils.NewHTTPClient(8 * time.Second) } if cfg.BaseURL == "" { diff --git a/internal/clients/pushover/client.go b/internal/clients/pushover/client.go index ad9d207..d346daf 100644 --- a/internal/clients/pushover/client.go +++ b/internal/clients/pushover/client.go @@ -8,6 +8,8 @@ import ( "log/slog" "net/http" "time" + + "github.com/ccrsxx/api/internal/utils" ) type Client struct { @@ -34,7 +36,7 @@ func NewClient(cfg Config) *Client { } if cfg.HTTPClient == nil { - cfg.HTTPClient = &http.Client{Timeout: 8 * time.Second} + cfg.HTTPClient = utils.NewHTTPClient(8 * time.Second) } return &Client{ diff --git a/internal/clients/spotify/client.go b/internal/clients/spotify/client.go index 5120107..d013bc2 100644 --- a/internal/clients/spotify/client.go +++ b/internal/clients/spotify/client.go @@ -12,6 +12,8 @@ import ( "strings" "time" + "github.com/ccrsxx/api/internal/utils" + "github.com/ccrsxx/api/internal/cache" ) @@ -44,7 +46,7 @@ var ErrNoContent = errors.New("spotify currently playing no content") func NewClient(cfg Config) *Client { if cfg.HTTPClient == nil { - cfg.HTTPClient = &http.Client{Timeout: 8 * time.Second} + cfg.HTTPClient = utils.NewHTTPClient(8 * time.Second) } if cfg.APIURL == "" { diff --git a/internal/db/sqlc/gen.go b/internal/db/sqlc/gen.go index 616a69e..a1a1b2d 100644 --- a/internal/db/sqlc/gen.go +++ b/internal/db/sqlc/gen.go @@ -4,11 +4,25 @@ import ( "context" "fmt" + "github.com/exaring/otelpgx" "github.com/jackc/pgx/v5/pgxpool" ) func NewQueries(ctx context.Context, databaseString string) (*pgxpool.Pool, *Queries) { - pool, err := pgxpool.New(ctx, databaseString) + poolConfig, err := pgxpool.ParseConfig(databaseString) + + if err != nil { + panic(fmt.Errorf("db config parse error: %w", err)) + } + + // Emit a span per query so slow SQL shows up in the trace waterfall + // alongside the HTTP and upstream spans. Tracing being disabled makes this + // a no-op via the global no-op tracer provider. + poolConfig.ConnConfig.Tracer = otelpgx.NewTracer( + otelpgx.WithTrimSQLInSpanName(), + ) + + pool, err := pgxpool.NewWithConfig(ctx, poolConfig) if err != nil { panic(fmt.Errorf("db create error: %w", err)) diff --git a/internal/features/sse/service.go b/internal/features/sse/service.go index 34626f3..3c7d883 100644 --- a/internal/features/sse/service.go +++ b/internal/features/sse/service.go @@ -11,6 +11,7 @@ import ( "github.com/ccrsxx/api/internal/api" "github.com/ccrsxx/api/internal/model" + "github.com/ccrsxx/api/internal/observability" "github.com/google/uuid" ) @@ -114,6 +115,8 @@ func (s *Service) AddClient(ctx context.Context, clientChan chan string, ipAddre s.clients[clientChan] = meta s.ipAddressCounts[ipAddress]++ + observability.SSEActiveClients.Set(float64(len(s.clients))) + slog.Info("sse client connected", "id", meta.ID, "ip_address", meta.IPAddress, @@ -156,6 +159,8 @@ func (s *Service) RemoveClient(ctx context.Context, clientChan chan string) { delete(s.ipAddressCounts, meta.IPAddress) } + observability.SSEActiveClients.Set(float64(len(s.clients))) + slog.Info("sse client disconnected", "id", meta.ID, "ip_address", meta.IPAddress, @@ -254,55 +259,61 @@ type sseData struct { navidrome string } -func (s *Service) getSSEData(ctx context.Context) sseData { - var spotifyData, jellyfinData, navidromeData model.CurrentlyPlaying - - var wg sync.WaitGroup +// fetchCurrentlyPlaying fetches from a single upstream, records its latency and +// outcome, and falls back to a default payload on error. +// +// The metric matters because the fallback is silent: without it, an upstream +// outage is indistinguishable from "the user isn't listening to anything". +func fetchCurrentlyPlaying( + ctx context.Context, + platform model.Platform, + fetcher dataFetcher, +) model.CurrentlyPlaying { + start := time.Now() - timeoutCtx, cancel := context.WithTimeout(ctx, 2*time.Second) + data, err := fetcher.GetCurrentlyPlaying(ctx) - defer cancel() + result := "success" - wg.Go(func() { - data, err := s.spotifyService.GetCurrentlyPlaying(timeoutCtx) + if err != nil { + result = "error" + } - if err != nil { - slog.Warn("sse spotify fetch error", "error", err) + observability.UpstreamRequestDuration. + WithLabelValues(string(platform), result). + Observe(time.Since(start).Seconds()) - spotifyData = model.NewDefaultCurrentlyPlaying(model.PlatformSpotify) + if err != nil { + slog.WarnContext(ctx, "sse upstream fetch error", + "platform", platform, + "error", err, + ) - return - } + return model.NewDefaultCurrentlyPlaying(platform) + } - spotifyData = data - }) + return data +} - wg.Go(func() { - data, err := s.jellyfinService.GetCurrentlyPlaying(timeoutCtx) +func (s *Service) getSSEData(ctx context.Context) sseData { + var spotifyData, jellyfinData, navidromeData model.CurrentlyPlaying - if err != nil { - slog.Warn("sse jellyfin fetch error", "error", err) + var wg sync.WaitGroup - jellyfinData = model.NewDefaultCurrentlyPlaying(model.PlatformJellyfin) + timeoutCtx, cancel := context.WithTimeout(ctx, 2*time.Second) - return - } + defer cancel() - jellyfinData = data + wg.Go(func() { + spotifyData = fetchCurrentlyPlaying(timeoutCtx, model.PlatformSpotify, s.spotifyService) }) wg.Go(func() { - data, err := s.navidromeService.GetCurrentlyPlaying(timeoutCtx) - - if err != nil { - slog.Warn("sse navidrome fetch error", "error", err) - - navidromeData = model.NewDefaultCurrentlyPlaying(model.PlatformNavidrome) - - return - } + jellyfinData = fetchCurrentlyPlaying(timeoutCtx, model.PlatformJellyfin, s.jellyfinService) + }) - navidromeData = data + wg.Go(func() { + navidromeData = fetchCurrentlyPlaying(timeoutCtx, model.PlatformNavidrome, s.navidromeService) }) wg.Wait() diff --git a/internal/middleware/metrics.go b/internal/middleware/metrics.go new file mode 100644 index 0000000..c6b316e --- /dev/null +++ b/internal/middleware/metrics.go @@ -0,0 +1,49 @@ +package middleware + +import ( + "cmp" + "net/http" + "strconv" + "time" + + "github.com/ccrsxx/api/internal/observability" +) + +// Metrics records request counts and latency for Prometheus. +// +// Only the matched mux pattern (r.Pattern) is used as the route label, never +// the raw path, to keep cardinality bounded. +// +// SSE is skipped for the same reason it is skipped in Logging: a long-lived +// stream would be recorded as one multi-hour request and ruin the latency +// histogram. +func Metrics(next http.Handler) http.Handler { + return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + if r.URL.Path == "/sse" { + next.ServeHTTP(w, r) + return + } + + start := time.Now() + + wrapped := &wrappedWriter{ + ResponseWriter: w, + statusCode: http.StatusOK, + } + + next.ServeHTTP(wrapped, r) + + route := cmp.Or(r.Pattern, "unmatched") + + observability.HTTPRequestsTotal.WithLabelValues( + route, + r.Method, + strconv.Itoa(wrapped.statusCode), + ).Inc() + + observability.HTTPRequestDuration.WithLabelValues( + route, + r.Method, + ).Observe(time.Since(start).Seconds()) + }) +} diff --git a/internal/middleware/requestid.go b/internal/middleware/requestid.go index f38a219..b6384e1 100644 --- a/internal/middleware/requestid.go +++ b/internal/middleware/requestid.go @@ -6,6 +6,7 @@ import ( "github.com/ccrsxx/api/internal/logger" "github.com/google/uuid" + "go.opentelemetry.io/otel/trace" ) const requestIDHeader = "X-Request-Id" @@ -13,19 +14,18 @@ const requestIDHeader = "X-Request-Id" // RequestID establishes per-request correlation identifiers and stores them in // the request context so the logger can attach them to every log line. // -// It must be registered as the OUTERMOST middleware so the identifiers exist -// before any other middleware (recovery, logging, rate limiting) runs. +// It runs inside the OpenTelemetry HTTP handler (so an active span exists) but +// outside recovery/logging/rate limiting, so the identifiers are available to +// every log line those middlewares produce, including panics. // // Sources, in order of preference: -// 1. W3C "traceparent" header (trace_id/span_id) if a caller propagated one. -// 2. An inbound X-Request-Id header (lets a frontend/proxy set its own id). -// 3. A freshly generated UUID. -// -// When OpenTelemetry is added, the active span becomes the source of truth for -// trace_id/span_id; this middleware then moves inside the otel handler. +// 1. The active OpenTelemetry span (authoritative when tracing is enabled). +// 2. W3C "traceparent" header, if a caller propagated one. +// 3. An inbound X-Request-Id header (lets a frontend/proxy set its own id). +// 4. A freshly generated UUID. func RequestID(next http.Handler) http.Handler { return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { - traceID, spanID := parseTraceparent(r.Header.Get("traceparent")) + traceID, spanID := traceIDsFromRequest(r) requestID := r.Header.Get(requestIDHeader) @@ -48,6 +48,26 @@ func RequestID(next http.Handler) http.Handler { }) } +// traceIDsFromRequest resolves the trace and span id for this request. +// +// When tracing is enabled, an OpenTelemetry span is already active (the otel +// HTTP handler wraps this middleware), and that span is the source of truth: +// using it guarantees the trace_id in the logs is the same one Tempo stores, +// which is what makes the log -> trace jump in Grafana work. +// +// When tracing is disabled there is no recording span, so we fall back to +// parsing the inbound W3C traceparent header. This keeps correlation working +// for callers that propagate trace context even while our own tracing is off. +func traceIDsFromRequest(r *http.Request) (traceID, spanID string) { + spanCtx := trace.SpanContextFromContext(r.Context()) + + if spanCtx.IsValid() { + return spanCtx.TraceID().String(), spanCtx.SpanID().String() + } + + return parseTraceparent(r.Header.Get("traceparent")) +} + // parseTraceparent extracts the trace-id and span-id from a W3C traceparent // header. Returns empty strings when the header is absent or malformed. // diff --git a/internal/observability/http.go b/internal/observability/http.go new file mode 100644 index 0000000..bf6c143 --- /dev/null +++ b/internal/observability/http.go @@ -0,0 +1,62 @@ +package observability + +import ( + "net/http" + + "go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp" + semconv "go.opentelemetry.io/otel/semconv/v1.41.0" + "go.opentelemetry.io/otel/trace" +) + +// TraceHandler wraps an HTTP handler with OpenTelemetry instrumentation. +// +// The span is initially named after the HTTP method only. The default +// formatter would use the raw URL path, producing one distinct span name per +// URL (e.g. every blog slug), which explodes Tempo's span name index. +// TraceRoute renames the span to the matched route once the mux has resolved +// it. +// +// /sse is excluded: long-lived streaming connections would produce multi-hour +// spans that distort trace views and waste storage. +// +// When tracing is disabled the global tracer provider is a no-op, so this adds +// negligible overhead and needs no conditional wiring. +func TraceHandler(next http.Handler) http.Handler { + return otelhttp.NewHandler(next, "", + otelhttp.WithSpanNameFormatter(func(_ string, r *http.Request) string { + return r.Method + }), + otelhttp.WithFilter(func(r *http.Request) bool { + return r.URL.Path != "/sse" + }), + ) +} + +// TraceRoute renames the active span to the matched mux pattern and records it +// as the http.route attribute. +// +// It must be registered as the INNERMOST middleware (directly wrapping the +// router), because http.ServeMux only populates r.Pattern while dispatching. +// Renaming after next.ServeHTTP returns is safe: otelhttp ends the span after +// the whole chain unwinds, and SetName before End is valid. +// +// Unmatched requests keep the bare method as their span name, which stays low +// cardinality. +func TraceRoute(next http.Handler) http.Handler { + return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + next.ServeHTTP(w, r) + + if r.Pattern == "" { + return + } + + span := trace.SpanFromContext(r.Context()) + + if !span.IsRecording() { + return + } + + span.SetName(r.Method + " " + r.Pattern) + span.SetAttributes(semconv.HTTPRoute(r.Pattern)) + }) +} diff --git a/internal/observability/metrics.go b/internal/observability/metrics.go new file mode 100644 index 0000000..bfcb327 --- /dev/null +++ b/internal/observability/metrics.go @@ -0,0 +1,87 @@ +package observability + +import ( + "github.com/prometheus/client_golang/prometheus" + "github.com/prometheus/client_golang/prometheus/collectors" +) + +// Registry is the application's Prometheus registry. +// +// A dedicated registry (instead of prometheus.DefaultRegisterer) keeps the +// exposed metrics explicit and avoids surprises from libraries that register +// into the global default. +var Registry = prometheus.NewRegistry() + +// HTTP server metrics. +// +// Labels are deliberately low cardinality: route is the matched mux pattern +// (never the raw path), so /contents/{slug} is one series instead of one per +// slug. +var ( + HTTPRequestsTotal = prometheus.NewCounterVec( + prometheus.CounterOpts{ + Name: "http_requests_total", + Help: "Total number of HTTP requests handled.", + }, + []string{"route", "method", "status_code"}, + ) + + HTTPRequestDuration = prometheus.NewHistogramVec( + prometheus.HistogramOpts{ + Name: "http_request_duration_seconds", + Help: "HTTP request latency in seconds.", + Buckets: prometheus.DefBuckets, + }, + []string{"route", "method"}, + ) +) + +// Application metrics. +// +// These surface behaviour that is currently invisible: how many SSE clients are +// connected, whether the cache is actually helping, and which upstream +// (Spotify/Jellyfin/Navidrome) is slow. The upstream histogram matters most +// because the SSE service silently falls back to a default payload on error, +// making an outage indistinguishable from "nothing is playing". +var ( + SSEActiveClients = prometheus.NewGauge( + prometheus.GaugeOpts{ + Name: "sse_active_clients", + Help: "Number of currently connected SSE clients.", + }, + ) + + CacheOperationsTotal = prometheus.NewCounterVec( + prometheus.CounterOpts{ + Name: "cache_operations_total", + Help: "Cache lookups by result (hit or miss).", + }, + []string{"result"}, + ) + + UpstreamRequestDuration = prometheus.NewHistogramVec( + prometheus.HistogramOpts{ + Name: "upstream_request_duration_seconds", + Help: "Upstream provider request latency in seconds.", + Buckets: prometheus.DefBuckets, + }, + []string{"platform", "result"}, + ) +) + +func init() { + Registry.MustRegister( + // Go runtime: go_goroutines, heap, GC. go_goroutines is the key leak + // signal for this app because every SSE client parks a goroutine and + // cache writes are fire-and-forget. + collectors.NewGoCollector(), + collectors.NewProcessCollector(collectors.ProcessCollectorOpts{}), + + HTTPRequestsTotal, + HTTPRequestDuration, + + SSEActiveClients, + CacheOperationsTotal, + UpstreamRequestDuration, + ) +} diff --git a/internal/observability/server.go b/internal/observability/server.go new file mode 100644 index 0000000..c429038 --- /dev/null +++ b/internal/observability/server.go @@ -0,0 +1,65 @@ +package observability + +import ( + "context" + "log/slog" + "net/http" + "strconv" + "time" + + "github.com/ccrsxx/api/internal/config" + "github.com/prometheus/client_golang/prometheus/promhttp" +) + +// Pinger is satisfied by *pgxpool.Pool. Kept as an interface so this package +// does not depend on the database layer. +type Pinger interface { + Ping(ctx context.Context) error +} + +// NewServer builds the internal observability server exposing /metrics and +// /healthz. +// +// This is deliberately a SEPARATE server on its own port, not a route on the +// public router: the public router is exposed at BACKEND_PUBLIC_URL, and +// publishing /metrics there would leak the application's internal state and +// infrastructure inventory. The port is not published in compose; the +// collector scrapes it over the Docker network. +func NewServer(cfg config.AppConfig, pinger Pinger) *http.Server { + mux := http.NewServeMux() + + mux.Handle("GET /metrics", promhttp.HandlerFor(Registry, promhttp.HandlerOpts{ + // Surface scrape problems in our own logs rather than silently 500ing. + ErrorLog: slog.NewLogLogger(slog.Default().Handler(), slog.LevelWarn), + ErrorHandling: promhttp.HTTPErrorOnError, + })) + + mux.HandleFunc("GET /healthz", func(w http.ResponseWriter, r *http.Request) { + healthCtx, cancel := context.WithTimeout(r.Context(), 2*time.Second) + + defer cancel() + + if pinger != nil { + if err := pinger.Ping(healthCtx); err != nil { + slog.WarnContext(r.Context(), "health check failed", "error", err) + + http.Error(w, "database unavailable", http.StatusServiceUnavailable) + + return + } + } + + w.Header().Set("Content-Type", "text/plain; charset=utf-8") + w.WriteHeader(http.StatusOK) + + if _, err := w.Write([]byte("ok")); err != nil { + slog.WarnContext(r.Context(), "health check write failed", "error", err) + } + }) + + return &http.Server{ + Addr: ":" + strconv.Itoa(cfg.MetricsPort), + Handler: mux, + ReadHeaderTimeout: 5 * time.Second, + } +} diff --git a/internal/observability/tracing.go b/internal/observability/tracing.go new file mode 100644 index 0000000..cce758e --- /dev/null +++ b/internal/observability/tracing.go @@ -0,0 +1,112 @@ +package observability + +import ( + "context" + "fmt" + "log/slog" + "time" + + "github.com/ccrsxx/api/internal/config" + "go.opentelemetry.io/otel" + "go.opentelemetry.io/otel/exporters/otlp/otlptrace/otlptracehttp" + "go.opentelemetry.io/otel/propagation" + "go.opentelemetry.io/otel/sdk/resource" + sdktrace "go.opentelemetry.io/otel/sdk/trace" + semconv "go.opentelemetry.io/otel/semconv/v1.41.0" +) + +// ServiceNamespace groups every signal emitted by this application. It matches +// the service_namespace label the log/metric collector applies, so logs, +// metrics and traces line up in Grafana. +const ServiceNamespace = "personal-api" + +// ShutdownFunc flushes and releases telemetry resources. +type ShutdownFunc func(ctx context.Context) error + +func noopShutdown(context.Context) error { return nil } + +// InitTracing configures the global OpenTelemetry tracer provider. +// +// It is a no-op (returning a no-op shutdown) when tracing is disabled or no +// OTLP endpoint is configured, so local development and tests need zero +// infrastructure. +// +// Sampling is ParentBased(TraceIDRatioBased): if an upstream caller already +// decided to sample a trace we respect that decision, otherwise we sample a +// ratio of new traces. Keeping errors and slow requests regardless is handled +// by tail sampling in the collector, which needs the whole trace to decide. +func InitTracing(ctx context.Context, cfg config.AppConfig) (ShutdownFunc, error) { + if !cfg.TracingEnabled || cfg.OtlpEndpoint == "" { + slog.Info("tracing disabled", + "tracing_enabled", cfg.TracingEnabled, + "otlp_endpoint", cfg.OtlpEndpoint, + ) + + return noopShutdown, nil + } + + // The OTLP HTTP exporter reads OTEL_EXPORTER_OTLP_ENDPOINT itself, but we + // pass it explicitly so the value always comes from our validated config. + exporter, err := otlptracehttp.New(ctx, + otlptracehttp.WithEndpointURL(cfg.OtlpEndpoint), + ) + + if err != nil { + return noopShutdown, fmt.Errorf("otlp trace exporter create error: %w", err) + } + + res, err := resource.New(ctx, + resource.WithAttributes( + semconv.ServiceName(cfg.ServiceName), + semconv.ServiceNamespace(ServiceNamespace), + semconv.DeploymentEnvironmentNameKey.String(string(cfg.AppEnv)), + ), + ) + + if err != nil { + return noopShutdown, fmt.Errorf("otel resource create error: %w", err) + } + + provider := sdktrace.NewTracerProvider( + sdktrace.WithResource(res), + sdktrace.WithBatcher(exporter), + sdktrace.WithSampler( + sdktrace.ParentBased( + sdktrace.TraceIDRatioBased(cfg.TraceSampleRatio), + ), + ), + ) + + otel.SetTracerProvider(provider) + + // W3C trace context + baggage so trace ids propagate over HTTP in and out. + otel.SetTextMapPropagator( + propagation.NewCompositeTextMapPropagator( + propagation.TraceContext{}, + propagation.Baggage{}, + ), + ) + + // Never let a telemetry failure take down or spam the application. + otel.SetErrorHandler(otel.ErrorHandlerFunc(func(err error) { + slog.Warn("otel error", "error", err) + })) + + slog.Info("tracing enabled", + "otlp_endpoint", cfg.OtlpEndpoint, + "sample_ratio", cfg.TraceSampleRatio, + ) + + return func(ctx context.Context) error { + // Give the exporter a bounded window to flush buffered spans. + flushCtx, cancel := context.WithTimeout(ctx, 5*time.Second) + + defer cancel() + + if err := provider.Shutdown(flushCtx); err != nil { + return fmt.Errorf("tracer provider shutdown error: %w", err) + } + + return nil + }, nil +} diff --git a/internal/server/handlers.go b/internal/server/handlers.go index ffc990e..84ff4bf 100644 --- a/internal/server/handlers.go +++ b/internal/server/handlers.go @@ -35,6 +35,7 @@ import ( "github.com/ccrsxx/api/internal/features/tools" "github.com/ccrsxx/api/internal/features/views" "github.com/ccrsxx/api/internal/middleware" + "github.com/ccrsxx/api/internal/observability" "github.com/jackc/pgx/v5/pgxpool" "golang.org/x/oauth2" "golang.org/x/oauth2/github" @@ -308,13 +309,19 @@ func LoadHandlers(ctx context.Context, cfg config.AppConfig, pool *pgxpool.Pool, middleware.Recovery( middleware.Cors(cfg.AllowedOrigins)( middleware.Logging( - middleware.RateLimit(ctx, 100, 1*time.Minute)( - router, + middleware.Metrics( + middleware.RateLimit(ctx, 100, 1*time.Minute)( + // Innermost: renames the span to the matched route + // once the mux has resolved r.Pattern. + observability.TraceRoute(router), + ), ), ), ), ), ) - return handlers + // Tracing wraps everything so a span exists before RequestID runs, letting + // the log correlation ids come straight from the active span. + return observability.TraceHandler(handlers) } diff --git a/internal/server/server.go b/internal/server/server.go index 5674350..e5b6978 100644 --- a/internal/server/server.go +++ b/internal/server/server.go @@ -10,9 +10,12 @@ import ( "github.com/jackc/pgx/v5/pgxpool" ) +// New builds the public API server. +// +// LoadLoaders must have been called by the caller beforehand, so that logging +// and tracing are configured before any instrumented component (the pgx pool, +// the HTTP handlers) captures the global tracer provider. func New(ctx context.Context, cfg config.AppConfig, pool *pgxpool.Pool, db *sqlc.Queries) *http.Server { - LoadLoaders(cfg) - addr := ":" + strconv.Itoa(cfg.Port) handler := LoadHandlers(ctx, cfg, pool, db) diff --git a/internal/utils/http.go b/internal/utils/http.go new file mode 100644 index 0000000..66ab97b --- /dev/null +++ b/internal/utils/http.go @@ -0,0 +1,23 @@ +package utils + +import ( + "net/http" + "time" + + "go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp" +) + +// NewHTTPClient returns an HTTP client instrumented for distributed tracing. +// +// Every outbound call gets its own span and propagates W3C trace context, so a +// slow third party (Spotify, Jellyfin, Navidrome, ...) appears as a labelled +// span in the request's trace waterfall instead of unexplained latency. +// +// When tracing is disabled the global tracer provider is a no-op, so this +// behaves like a plain http.Client. +func NewHTTPClient(timeout time.Duration) *http.Client { + return &http.Client{ + Timeout: timeout, + Transport: otelhttp.NewTransport(http.DefaultTransport), + } +}