Expose Prometheus metrics on a separate port

Metrics are served on METRICS_PORT (default 2112, "off" to disable), never on
the public port. Besides the Go runtime and process metrics this adds:

- http_requests_total and http_request_duration_seconds per route pattern,
  from an Echo middleware.
- musicserver_songs_requested_total and musicserver_songs_played_total by
  pick mode (random, low, classic). The mode is now stored with each queued
  song (migration 000006, not released yet).
- Library size, sync duration, last successful sync, broken songs from the
  last full sync, and the database connection pool.

Refs #35, #36, #37

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

internal/metrics/app.go

@@ -0,0 +1,53 @@
+package metrics
+
+import (
+	"github.com/prometheus/client_golang/prometheus"
+	"github.com/prometheus/client_golang/prometheus/promauto"
+)
+
+// MusicServer's own metrics. Labels only take values from small fixed sets: never song
+// names, IDs, tokens or IPs, since every value creates a new time series.
+var (
+	// SongsRequested counts random songs handed out, by how they were picked.
+	SongsRequested = promauto.NewCounterVec(prometheus.CounterOpts{
+		Name: "musicserver_songs_requested_total",
+		Help: "Random songs handed out, by how they were picked (random, low, classic).",
+	}, []string{"mode"})
+
+	// SongsPlayed counts songs marked as played, by how they were picked.
+	SongsPlayed = promauto.NewCounterVec(prometheus.CounterOpts{
+		Name: "musicserver_songs_played_total",
+		Help: "Songs marked as played, by how they were picked (random, low, classic).",
+	}, []string{"mode"})
+
+	// LibrarySoundtracks is the number of soundtracks in the library.
+	LibrarySoundtracks = promauto.NewGauge(prometheus.GaugeOpts{
+		Name: "musicserver_library_soundtracks",
+		Help: "Soundtracks in the library, counted at startup and after each sync.",
+	})
+
+	// LibrarySongs is the number of songs in the library.
+	LibrarySongs = promauto.NewGauge(prometheus.GaugeOpts{
+		Name: "musicserver_library_songs",
+		Help: "Songs in the library, counted at startup and after each sync.",
+	})
+
+	// SyncDuration is how long syncs take, by type.
+	SyncDuration = promauto.NewHistogramVec(prometheus.HistogramOpts{
+		Name:    "musicserver_sync_duration_seconds",
+		Help:    "How long a sync took, by type (full, changes).",
+		Buckets: []float64{1, 5, 10, 30, 60, 120, 300, 600, 1200, 1800, 3600},
+	}, []string{"type"})
+
+	// SyncLastSuccess is when the last sync without errors finished.
+	SyncLastSuccess = promauto.NewGauge(prometheus.GaugeOpts{
+		Name: "musicserver_sync_last_success_timestamp_seconds",
+		Help: "Unix time when the last sync without errors finished.",
+	})
+
+	// BrokenSongs is the number of songs the last full sync found missing and removed.
+	BrokenSongs = promauto.NewGauge(prometheus.GaugeOpts{
+		Name: "musicserver_broken_songs",
+		Help: "Songs whose file was missing in the last full sync. They are removed from the library.",
+	})
+)

internal/metrics/http.go

@@ -0,0 +1,49 @@
+package metrics
+
+import (
+	"strconv"
+	"time"
+
+	"github.com/labstack/echo/v5"
+	"github.com/prometheus/client_golang/prometheus"
+	"github.com/prometheus/client_golang/prometheus/promauto"
+)
+
+var (
+	httpRequests = promauto.NewCounterVec(prometheus.CounterOpts{
+		Name: "http_requests_total",
+		Help: "HTTP requests by method, route and status code.",
+	}, []string{"method", "route", "code"})
+
+	httpDuration = promauto.NewHistogramVec(prometheus.HistogramOpts{
+		Name: "http_request_duration_seconds",
+		Help: "HTTP request latency by method and route. Song downloads include the transfer.",
+		// Up to 30 s, since songs can take long to send to slow clients.
+		Buckets: []float64{.005, .01, .025, .05, .1, .25, .5, 1, 2.5, 5, 10, 30},
+	}, []string{"method", "route"})
+)
+
+// unmatchedRoute labels requests that matched no route, so raw URLs never become labels.
+const unmatchedRoute = "unmatched"
+
+// Middleware records the count and latency of requests per route. The route label is the
+// registered pattern, like /api/v1/songs/:uuid, never the URL with its IDs and query.
+// Register it outside Recover, so requests that panic are counted as 500.
+func Middleware() echo.MiddlewareFunc {
+	return func(next echo.HandlerFunc) echo.HandlerFunc {
+		return func(c *echo.Context) error {
+			start := time.Now()
+			err := next(c)
+
+			route := c.Path()
+			if route == "" {
+				route = unmatchedRoute
+			}
+			_, status := echo.ResolveResponseStatus(c.Response(), err)
+			method := c.Request().Method
+			httpRequests.WithLabelValues(method, route, strconv.Itoa(status)).Inc()
+			httpDuration.WithLabelValues(method, route).Observe(time.Since(start).Seconds())
+			return err
+		}
+	}
+}

internal/metrics/http_test.go

@@ -0,0 +1,75 @@
+package metrics
+
+import (
+	"errors"
+	"net/http"
+	"net/http/httptest"
+	"testing"
+
+	"github.com/labstack/echo/v5"
+	echoMiddleware "github.com/labstack/echo/v5/middleware"
+	"github.com/prometheus/client_golang/prometheus"
+	"github.com/prometheus/client_golang/prometheus/testutil"
+	dto "github.com/prometheus/client_model/go"
+	"github.com/stretchr/testify/assert"
+)
+
+func newEcho() *echo.Echo {
+	e := echo.New()
+	e.Use(Middleware())
+	e.Use(echoMiddleware.Recover())
+	e.GET("/items/:id", func(c *echo.Context) error { return c.String(http.StatusOK, "item") })
+	e.GET("/fail", func(c *echo.Context) error { return errors.New("broken") })
+	e.GET("/panic", func(c *echo.Context) error { panic("boom") })
+	return e
+}
+
+func serve(e *echo.Echo, method, target string) {
+	e.ServeHTTP(httptest.NewRecorder(), httptest.NewRequest(method, target, nil))
+}
+
+func requests(method, route, code string) float64 {
+	return testutil.ToFloat64(httpRequests.WithLabelValues(method, route, code))
+}
+
+func TestMiddlewareCountsRequestsByRoutePattern(t *testing.T) {
+	e := newEcho()
+	before := requests("GET", "/items/:id", "200")
+
+	serve(e, http.MethodGet, "/items/1?x=secret")
+	serve(e, http.MethodGet, "/items/2")
+
+	assert.Equal(t, before+2, requests("GET", "/items/:id", "200"))
+	assert.Equal(t, 0.0, requests("GET", "/items/1?x=secret", "200"), "the URL is never a label")
+	assert.Equal(t, 0.0, requests("GET", "/items/1", "200"))
+}
+
+func TestMiddlewareRecordsErrorStatus(t *testing.T) {
+	e := newEcho()
+	failBefore := requests("GET", "/fail", "500")
+	panicBefore := requests("GET", "/panic", "500")
+	missingBefore := requests("GET", unmatchedRoute, "404")
+
+	serve(e, http.MethodGet, "/fail")
+	serve(e, http.MethodGet, "/panic")
+	serve(e, http.MethodGet, "/no/such/page?q=1")
+
+	assert.Equal(t, failBefore+1, requests("GET", "/fail", "500"))
+	assert.Equal(t, panicBefore+1, requests("GET", "/panic", "500"), "Recover turns the panic into a 500")
+	assert.Equal(t, missingBefore+1, requests("GET", unmatchedRoute, "404"))
+}
+
+func observations(method, route string) uint64 {
+	m := &dto.Metric{}
+	_ = httpDuration.WithLabelValues(method, route).(prometheus.Metric).Write(m)
+	return m.GetHistogram().GetSampleCount()
+}
+
+func TestMiddlewareRecordsLatency(t *testing.T) {
+	e := newEcho()
+	before := observations("GET", "/items/:id")
+
+	serve(e, http.MethodGet, "/items/1")
+
+	assert.Equal(t, before+1, observations("GET", "/items/:id"))
+}

internal/metrics/pool.go

@@ -0,0 +1,70 @@
+package metrics
+
+import (
+	"github.com/jackc/pgx/v5/pgxpool"
+	"github.com/prometheus/client_golang/prometheus"
+)
+
+// poolCollector reports the database connection pool's statistics on every scrape.
+type poolCollector struct {
+	pool *pgxpool.Pool
+
+	acquiredConns        *prometheus.Desc
+	idleConns            *prometheus.Desc
+	totalConns           *prometheus.Desc
+	maxConns             *prometheus.Desc
+	acquires             *prometheus.Desc
+	acquireWait          *prometheus.Desc
+	emptyAcquires        *prometheus.Desc
+	canceledAcquires     *prometheus.Desc
+	newConns             *prometheus.Desc
+	maxLifetimeDestroyed *prometheus.Desc
+	maxIdleDestroyed     *prometheus.Desc
+}
+
+// NewPoolCollector returns a collector for the musicserver_db_pool_* metrics of pool.
+// Register it once, for example with prometheus.MustRegister.
+func NewPoolCollector(pool *pgxpool.Pool) prometheus.Collector {
+	desc := func(name, help string) *prometheus.Desc {
+		return prometheus.NewDesc("musicserver_db_pool_"+name, help, nil, nil)
+	}
+	return &poolCollector{
+		pool:                 pool,
+		acquiredConns:        desc("acquired_conns", "Connections in use."),
+		idleConns:            desc("idle_conns", "Idle connections."),
+		totalConns:           desc("total_conns", "Open connections, in use, idle and being opened."),
+		maxConns:             desc("max_conns", "Most connections the pool opens."),
+		acquires:             desc("acquires_total", "Connections handed out."),
+		acquireWait:          desc("acquire_wait_seconds_total", "Total time spent waiting for a connection."),
+		emptyAcquires:        desc("empty_acquires_total", "Acquires that had to wait because no connection was idle."),
+		canceledAcquires:     desc("canceled_acquires_total", "Acquires canceled while waiting, for example by a timeout."),
+		newConns:             desc("new_conns_total", "Connections opened."),
+		maxLifetimeDestroyed: desc("max_lifetime_destroyed_total", "Connections closed for reaching their maximum lifetime."),
+		maxIdleDestroyed:     desc("max_idle_destroyed_total", "Connections closed for being idle too long."),
+	}
+}
+
+func (c *poolCollector) Describe(ch chan<- *prometheus.Desc) {
+	prometheus.DescribeByCollect(c, ch)
+}
+
+func (c *poolCollector) Collect(ch chan<- prometheus.Metric) {
+	s := c.pool.Stat()
+	gauge := func(d *prometheus.Desc, v float64) {
+		ch <- prometheus.MustNewConstMetric(d, prometheus.GaugeValue, v)
+	}
+	counter := func(d *prometheus.Desc, v float64) {
+		ch <- prometheus.MustNewConstMetric(d, prometheus.CounterValue, v)
+	}
+	gauge(c.acquiredConns, float64(s.AcquiredConns()))
+	gauge(c.idleConns, float64(s.IdleConns()))
+	gauge(c.totalConns, float64(s.TotalConns()))
+	gauge(c.maxConns, float64(s.MaxConns()))
+	counter(c.acquires, float64(s.AcquireCount()))
+	counter(c.acquireWait, s.AcquireDuration().Seconds())
+	counter(c.emptyAcquires, float64(s.EmptyAcquireCount()))
+	counter(c.canceledAcquires, float64(s.CanceledAcquireCount()))
+	counter(c.newConns, float64(s.NewConnsCount()))
+	counter(c.maxLifetimeDestroyed, float64(s.MaxLifetimeDestroyCount()))
+	counter(c.maxIdleDestroyed, float64(s.MaxIdleDestroyCount()))
+}

internal/metrics/pool_test.go

@@ -0,0 +1,33 @@
+package metrics
+
+import (
+	"context"
+	"strings"
+	"testing"
+
+	"github.com/jackc/pgx/v5/pgxpool"
+	"github.com/prometheus/client_golang/prometheus"
+	"github.com/prometheus/client_golang/prometheus/testutil"
+	"github.com/stretchr/testify/assert"
+	"github.com/stretchr/testify/require"
+)
+
+func TestPoolCollector(t *testing.T) {
+	// The pool connects lazily, so no database is needed to read its statistics.
+	pool, err := pgxpool.New(context.Background(), "postgres://user:pass@127.0.0.1:1/music?pool_max_conns=7")
+	require.NoError(t, err)
+	t.Cleanup(pool.Close)
+
+	registry := prometheus.NewRegistry()
+	registry.MustRegister(NewPoolCollector(pool))
+
+	assert.Equal(t, 11, testutil.CollectAndCount(registry))
+	require.NoError(t, testutil.GatherAndCompare(registry, strings.NewReader(`
+# HELP musicserver_db_pool_max_conns Most connections the pool opens.
+# TYPE musicserver_db_pool_max_conns gauge
+musicserver_db_pool_max_conns 7
+# HELP musicserver_db_pool_acquired_conns Connections in use.
+# TYPE musicserver_db_pool_acquired_conns gauge
+musicserver_db_pool_acquired_conns 0
+`), "musicserver_db_pool_max_conns", "musicserver_db_pool_acquired_conns"))
+}

internal/metrics/server.go

@@ -0,0 +1,60 @@
+// Package metrics exposes Prometheus metrics: the Go runtime and process metrics that the
+// default registry collects, HTTP request metrics and MusicServer's own metrics.
+package metrics
+
+import (
+	"context"
+	"errors"
+	"fmt"
+	"net"
+	"net/http"
+	"time"
+
+	"music-server/internal/logging"
+
+	"github.com/prometheus/client_golang/prometheus/promhttp"
+	"go.uber.org/zap"
+)
+
+// Server serves /metrics on a port of its own, so it is never reachable through the
+// public port.
+type Server struct {
+	httpServer *http.Server
+}
+
+// NewServer creates a metrics server for the given port.
+func NewServer(port int) *Server {
+	mux := http.NewServeMux()
+	mux.Handle("GET /metrics", promhttp.Handler())
+	return &Server{httpServer: &http.Server{
+		Addr:              fmt.Sprintf(":%d", port),
+		Handler:           mux,
+		ReadHeaderTimeout: 5 * time.Second,
+	}}
+}
+
+// Handler returns the handler that serves /metrics.
+func (s *Server) Handler() http.Handler {
+	return s.httpServer.Handler
+}
+
+// Start listens on the port and serves metrics in the background. It returns an error
+// when the port cannot be opened.
+func (s *Server) Start() error {
+	ln, err := net.Listen("tcp", s.httpServer.Addr)
+	if err != nil {
+		return err
+	}
+	logging.GetLogger().Info("Metrics server starting", zap.String("address", s.httpServer.Addr))
+	go func() {
+		if err := s.httpServer.Serve(ln); !errors.Is(err, http.ErrServerClosed) {
+			logging.GetLogger().Error("Metrics server error", zap.Error(err))
+		}
+	}()
+	return nil
+}
+
+// Shutdown stops the metrics server.
+func (s *Server) Shutdown(ctx context.Context) error {
+	return s.httpServer.Shutdown(ctx)
+}

internal/metrics/server_test.go

@@ -0,0 +1,63 @@
+package metrics
+
+import (
+	"context"
+	"io"
+	"net"
+	"net/http"
+	"net/http/httptest"
+	"os"
+	"testing"
+
+	"music-server/internal/logging"
+
+	"github.com/stretchr/testify/assert"
+	"github.com/stretchr/testify/require"
+)
+
+func TestMain(m *testing.M) {
+	logging.Init("fatal", false)
+	os.Exit(m.Run())
+}
+
+func TestServerServesRuntimeMetrics(t *testing.T) {
+	rec := httptest.NewRecorder()
+	NewServer(0).Handler().ServeHTTP(rec, httptest.NewRequest(http.MethodGet, "/metrics", nil))
+
+	assert.Equal(t, http.StatusOK, rec.Code)
+	assert.Contains(t, rec.Body.String(), "go_goroutines")
+	assert.Contains(t, rec.Body.String(), "process_start_time_seconds")
+}
+
+func TestServerServesOnlyMetrics(t *testing.T) {
+	rec := httptest.NewRecorder()
+	NewServer(0).Handler().ServeHTTP(rec, httptest.NewRequest(http.MethodGet, "/", nil))
+	assert.Equal(t, http.StatusNotFound, rec.Code)
+}
+
+func TestServerStartAndShutdown(t *testing.T) {
+	ln, err := net.Listen("tcp", "127.0.0.1:0")
+	require.NoError(t, err)
+	port := ln.Addr().(*net.TCPAddr).Port
+	require.NoError(t, ln.Close())
+
+	s := NewServer(port)
+	require.NoError(t, s.Start())
+	resp, err := http.Get("http://" + ln.Addr().String() + "/metrics")
+	require.NoError(t, err)
+	body, _ := io.ReadAll(resp.Body)
+	resp.Body.Close()
+	assert.Contains(t, string(body), "go_goroutines")
+
+	require.NoError(t, s.Shutdown(context.Background()))
+	_, err = http.Get("http://" + ln.Addr().String() + "/metrics")
+	assert.Error(t, err, "the port is closed after shutdown")
+}
+
+func TestServerStartFailsWhenPortIsTaken(t *testing.T) {
+	ln, err := net.Listen("tcp", ":0")
+	require.NoError(t, err)
+	defer ln.Close()
+
+	assert.Error(t, NewServer(ln.Addr().(*net.TCPAddr).Port).Start())
+}