metrics: Initial integration of Prometheus metrics (#3709)

Signed-off-by: Dave Henderson <[email protected]>

admin.go

@@ -35,6 +35,8 @@ import (
 	"sync"
 	"time"
 
+	"github.com/prometheus/client_golang/prometheus"
+	"github.com/prometheus/client_golang/prometheus/promhttp"
 	"go.uber.org/zap"
 )
 
@@ -107,34 +109,53 @@ func (admin AdminConfig) newAdminHandler(addr NetworkAddress) adminHandler {
 		mux:            http.NewServeMux(),
 	}
 
+	addRouteWithMetrics := func(pattern string, handlerLabel string, h http.Handler) {
+		labels := prometheus.Labels{"path": pattern, "handler": handlerLabel}
+		h = promhttp.InstrumentHandlerCounter(
+			adminMetrics.requestCount.MustCurryWith(labels),
+			h,
+		)
+		muxWrap.mux.Handle(pattern, h)
+	}
 	// addRoute just calls muxWrap.mux.Handle after
 	// wrapping the handler with error handling
-	addRoute := func(pattern string, h AdminHandler) {
+	addRoute := func(pattern string, handlerLabel string, h AdminHandler) {
 		wrapper := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
 			err := h.ServeHTTP(w, r)
+			if err != nil {
+				labels := prometheus.Labels{
+					"path":    pattern,
+					"handler": handlerLabel,
+					"method":  r.Method,
+				}
+				adminMetrics.requestErrors.With(labels).Inc()
+			}
 			muxWrap.handleError(w, r, err)
 		})
-		muxWrap.mux.Handle(pattern, wrapper)
+		addRouteWithMetrics(pattern, handlerLabel, wrapper)
 	}
 
+	const handlerLabel = "admin"
+
 	// register standard config control endpoints
-	addRoute("/"+rawConfigKey+"/", AdminHandlerFunc(handleConfig))
-	addRoute("/id/", AdminHandlerFunc(handleConfigID))
-	addRoute("/stop", AdminHandlerFunc(handleStop))
+	addRoute("/"+rawConfigKey+"/", handlerLabel, AdminHandlerFunc(handleConfig))
+	addRoute("/id/", handlerLabel, AdminHandlerFunc(handleConfigID))
+	addRoute("/stop", handlerLabel, AdminHandlerFunc(handleStop))
 
 	// register debugging endpoints
-	muxWrap.mux.HandleFunc("/debug/pprof/", pprof.Index)
-	muxWrap.mux.HandleFunc("/debug/pprof/cmdline", pprof.Cmdline)
-	muxWrap.mux.HandleFunc("/debug/pprof/profile", pprof.Profile)
-	muxWrap.mux.HandleFunc("/debug/pprof/symbol", pprof.Symbol)
-	muxWrap.mux.HandleFunc("/debug/pprof/trace", pprof.Trace)
-	muxWrap.mux.Handle("/debug/vars", expvar.Handler())
+	addRouteWithMetrics("/debug/pprof/", handlerLabel, http.HandlerFunc(pprof.Index))
+	addRouteWithMetrics("/debug/pprof/cmdline", handlerLabel, http.HandlerFunc(pprof.Cmdline))
+	addRouteWithMetrics("/debug/pprof/profile", handlerLabel, http.HandlerFunc(pprof.Profile))
+	addRouteWithMetrics("/debug/pprof/symbol", handlerLabel, http.HandlerFunc(pprof.Symbol))
+	addRouteWithMetrics("/debug/pprof/trace", handlerLabel, http.HandlerFunc(pprof.Trace))
+	addRouteWithMetrics("/debug/vars", handlerLabel, expvar.Handler())
 
 	// register third-party module endpoints
 	for _, m := range GetModules("admin.api") {
 		router := m.New().(AdminRouter)
+		handlerLabel := m.ID.Name()
 		for _, route := range router.Routes() {
-			addRoute(route.Pattern, route.Handler)
+			addRoute(route.Pattern, handlerLabel, route.Handler)
 		}
 	}
 

caddyconfig/httpcaddyfile/directives.go

@@ -63,6 +63,7 @@ var directiveOrder = []string{
 
 	// handlers that typically respond to requests
 	"respond",
+	"metrics",
 	"reverse_proxy",
 	"php_fastcgi",
 	"file_server",

go.mod

@@ -17,6 +17,7 @@ require (
 	github.com/mholt/acmez v0.1.1-0.20200811184240-dc9c5f05ed1e
 	github.com/naoina/go-stringutil v0.1.0 // indirect
 	github.com/naoina/toml v0.1.1
+	github.com/prometheus/client_golang v1.7.1
 	github.com/smallstep/certificates v0.15.1
 	github.com/smallstep/cli v0.15.0
 	github.com/smallstep/nosql v0.3.0

metrics.go

@@ -0,0 +1,32 @@
+package caddy
+
+import (
+	"github.com/prometheus/client_golang/prometheus"
+	"github.com/prometheus/client_golang/prometheus/promauto"
+)
+
+// define and register the metrics used in this package.
+func init() {
+	prometheus.MustRegister(prometheus.NewBuildInfoCollector())
+
+	const ns, sub = "caddy", "admin"
+
+	adminMetrics.requestCount = promauto.NewCounterVec(prometheus.CounterOpts{
+		Namespace: ns,
+		Subsystem: sub,
+		Name:      "http_requests_total",
+		Help:      "Counter of requests made to the Admin API's HTTP endpoints.",
+	}, []string{"handler", "path", "code", "method"})
+	adminMetrics.requestErrors = promauto.NewCounterVec(prometheus.CounterOpts{
+		Namespace: ns,
+		Subsystem: sub,
+		Name:      "http_request_errors_total",
+		Help:      "Number of requests resulting in middleware errors.",
+	}, []string{"handler", "path", "method"})
+}
+
+// adminMetrics is a collection of metrics that can be tracked for the admin API.
+var adminMetrics = struct {
+	requestCount  *prometheus.CounterVec
+	requestErrors *prometheus.CounterVec
+}{}

modules/caddyhttp/app.go

@@ -226,6 +226,8 @@ func (app *App) Provision(ctx caddy.Context) error {
 		// route handler so that important security checks are done, etc.
 		primaryRoute := emptyHandler
 		if srv.Routes != nil {
+			// inject the server name for observability purposes
+			ctx.Context = contextWithServerName(ctx.Context, srvName)
 			err := srv.Routes.ProvisionHandlers(ctx)
 			if err != nil {
 				return fmt.Errorf("server %s: setting up route handlers: %v", srvName, err)

modules/caddyhttp/metrics.go

@@ -0,0 +1,195 @@
+package caddyhttp
+
+import (
+	"context"
+	"net/http"
+	"strconv"
+	"sync"
+	"time"
+
+	"github.com/prometheus/client_golang/prometheus"
+	"github.com/prometheus/client_golang/prometheus/promauto"
+)
+
+var httpMetrics = struct {
+	init             sync.Once
+	requestInFlight  *prometheus.GaugeVec
+	requestCount     *prometheus.CounterVec
+	requestErrors    *prometheus.CounterVec
+	requestDuration  *prometheus.HistogramVec
+	requestSize      *prometheus.HistogramVec
+	responseSize     *prometheus.HistogramVec
+	responseDuration *prometheus.HistogramVec
+}{
+	init: sync.Once{},
+}
+
+func initHTTPMetrics() {
+	const ns, sub = "caddy", "http"
+
+	basicLabels := []string{"server", "handler"}
+	httpMetrics.requestInFlight = promauto.NewGaugeVec(prometheus.GaugeOpts{
+		Namespace: ns,
+		Subsystem: sub,
+		Name:      "requests_in_flight",
+		Help:      "Number of requests currently handled by this server.",
+	}, basicLabels)
+	httpMetrics.requestErrors = promauto.NewCounterVec(prometheus.CounterOpts{
+		Namespace: ns,
+		Subsystem: sub,
+		Name:      "request_errors_total",
+		Help:      "Number of requests resulting in middleware errors.",
+	}, basicLabels)
+	httpMetrics.requestCount = promauto.NewCounterVec(prometheus.CounterOpts{
+		Namespace: ns,
+		Subsystem: sub,
+		Name:      "requests_total",
+		Help:      "Counter of HTTP(S) requests made.",
+	}, basicLabels)
+
+	// TODO: allow these to be customized in the config
+	durationBuckets := prometheus.DefBuckets
+	sizeBuckets := prometheus.ExponentialBuckets(256, 4, 8)
+
+	httpLabels := []string{"server", "handler", "code", "method"}
+	httpMetrics.requestDuration = promauto.NewHistogramVec(prometheus.HistogramOpts{
+		Namespace: ns,
+		Subsystem: sub,
+		Name:      "request_duration_seconds",
+		Help:      "Histogram of round-trip request durations.",
+		Buckets:   durationBuckets,
+	}, httpLabels)
+	httpMetrics.requestSize = promauto.NewHistogramVec(prometheus.HistogramOpts{
+		Namespace: ns,
+		Subsystem: sub,
+		Name:      "request_size_bytes",
+		Help:      "Total size of the request. Includes body",
+		Buckets:   sizeBuckets,
+	}, httpLabels)
+	httpMetrics.responseSize = promauto.NewHistogramVec(prometheus.HistogramOpts{
+		Namespace: ns,
+		Subsystem: sub,
+		Name:      "response_size_bytes",
+		Help:      "Size of the returned response.",
+		Buckets:   sizeBuckets,
+	}, httpLabels)
+	httpMetrics.responseDuration = promauto.NewHistogramVec(prometheus.HistogramOpts{
+		Namespace: ns,
+		Subsystem: sub,
+		Name:      "response_duration_seconds",
+		Help:      "Histogram of times to first byte in response bodies.",
+		Buckets:   durationBuckets,
+	}, httpLabels)
+}
+
+type ctxKeyServerName struct{}
+
+// serverNameFromContext extracts the current server name from the context.
+// Returns "UNKNOWN" if none is available (should probably never happen?)
+func serverNameFromContext(ctx context.Context) string {
+	srvName, ok := ctx.Value(ctxKeyServerName{}).(string)
+	if !ok {
+		return "UNKNOWN"
+	}
+	return srvName
+}
+
+func contextWithServerName(ctx context.Context, serverName string) context.Context {
+	return context.WithValue(ctx, ctxKeyServerName{}, serverName)
+}
+
+type metricsInstrumentedHandler struct {
+	labels       prometheus.Labels
+	statusLabels prometheus.Labels
+	mh           MiddlewareHandler
+}
+
+func newMetricsInstrumentedHandler(server, handler string, mh MiddlewareHandler) *metricsInstrumentedHandler {
+	httpMetrics.init.Do(func() {
+		initHTTPMetrics()
+	})
+
+	labels := prometheus.Labels{"server": server, "handler": handler}
+	statusLabels := prometheus.Labels{"server": server, "handler": handler, "code": "", "method": ""}
+	return &metricsInstrumentedHandler{labels, statusLabels, mh}
+}
+
+func (h *metricsInstrumentedHandler) ServeHTTP(w http.ResponseWriter, r *http.Request, next Handler) error {
+	inFlight := httpMetrics.requestInFlight.With(h.labels)
+	inFlight.Inc()
+	defer inFlight.Dec()
+
+	statusLabels := prometheus.Labels{"method": r.Method}
+	for k, v := range h.labels {
+		statusLabels[k] = v
+	}
+
+	start := time.Now()
+
+	// This is a _bit_ of a hack - it depends on the ShouldBufferFunc always
+	// being called when the headers are written.
+	// Effectively the same behaviour as promhttp.InstrumentHandlerTimeToWriteHeader.
+	writeHeaderRecorder := ShouldBufferFunc(func(status int, header http.Header) bool {
+		statusLabels["code"] = sanitizeCode(status)
+		ttfb := time.Since(start).Seconds()
+		observeWithExemplar(statusLabels, httpMetrics.responseDuration, ttfb)
+		return false
+	})
+	wrec := NewResponseRecorder(w, nil, writeHeaderRecorder)
+	err := h.mh.ServeHTTP(wrec, r, next)
+	dur := time.Since(start).Seconds()
+	httpMetrics.requestCount.With(h.labels).Inc()
+	if err != nil {
+		httpMetrics.requestErrors.With(h.labels).Inc()
+		return err
+	}
+
+	observeWithExemplar(statusLabels, httpMetrics.requestDuration, dur)
+	observeWithExemplar(statusLabels, httpMetrics.requestSize, float64(computeApproximateRequestSize(r)))
+	httpMetrics.responseSize.With(statusLabels).Observe(float64(wrec.Size()))
+
+	return nil
+}
+
+func observeWithExemplar(l prometheus.Labels, o *prometheus.HistogramVec, value float64) {
+	obs := o.With(l)
+	if oe, ok := obs.(prometheus.ExemplarObserver); ok {
+		oe.ObserveWithExemplar(value, l)
+		return
+	}
+	// _should_ be a noop, but here just in case...
+	obs.Observe(value)
+}
+
+func sanitizeCode(code int) string {
+	if code == 0 {
+		return "200"
+	}
+	return strconv.Itoa(code)
+
+}
+
+// taken from https://github.com/prometheus/client_golang/blob/6007b2b5cae01203111de55f753e76d8dac1f529/prometheus/promhttp/instrument_server.go#L298
+func computeApproximateRequestSize(r *http.Request) int {
+	s := 0
+	if r.URL != nil {
+		s += len(r.URL.String())
+	}
+
+	s += len(r.Method)
+	s += len(r.Proto)
+	for name, values := range r.Header {
+		s += len(name)
+		for _, value := range values {
+			s += len(value)
+		}
+	}
+	s += len(r.Host)
+
+	// N.B. r.Form and r.MultipartForm are assumed to be included in r.URL.
+
+	if r.ContentLength != -1 {
+		s += int(r.ContentLength)
+	}
+	return s
+}

modules/caddyhttp/metrics_test.go

@@ -0,0 +1,66 @@
+package caddyhttp
+
+import (
+	"context"
+	"errors"
+	"net/http"
+	"net/http/httptest"
+	"testing"
+
+	"github.com/prometheus/client_golang/prometheus/testutil"
+)
+
+func TestServerNameFromContext(t *testing.T) {
+	ctx := context.Background()
+	expected := "UNKNOWN"
+	if actual := serverNameFromContext(ctx); actual != expected {
+		t.Errorf("Not equal: expected %q, but got %q", expected, actual)
+	}
+
+	in := "foo"
+	ctx = contextWithServerName(ctx, in)
+	if actual := serverNameFromContext(ctx); actual != in {
+		t.Errorf("Not equal: expected %q, but got %q", in, actual)
+	}
+}
+
+func TestMetricsInstrumentedHandler(t *testing.T) {
+	handlerErr := errors.New("oh noes")
+	response := []byte("hello world!")
+	h := HandlerFunc(func(w http.ResponseWriter, r *http.Request) error {
+		if actual := testutil.ToFloat64(httpMetrics.requestInFlight); actual != 1.0 {
+			t.Errorf("Not same: expected %#v, but got %#v", 1.0, actual)
+		}
+		if handlerErr == nil {
+			w.Write(response)
+		}
+		return handlerErr
+	})
+
+	mh := middlewareHandlerFunc(func(w http.ResponseWriter, r *http.Request, h Handler) error {
+		return h.ServeHTTP(w, r)
+	})
+
+	ih := newMetricsInstrumentedHandler("foo", "bar", mh)
+
+	r := httptest.NewRequest("GET", "/", nil)
+	w := httptest.NewRecorder()
+
+	if actual := ih.ServeHTTP(w, r, h); actual != handlerErr {
+		t.Errorf("Not same: expected %#v, but got %#v", handlerErr, actual)
+	}
+	if actual := testutil.ToFloat64(httpMetrics.requestInFlight); actual != 0.0 {
+		t.Errorf("Not same: expected %#v, but got %#v", 0.0, actual)
+	}
+
+	handlerErr = nil
+	if err := ih.ServeHTTP(w, r, h); err != nil {
+		t.Errorf("Received unexpected error: %w", err)
+	}
+}
+
+type middlewareHandlerFunc func(http.ResponseWriter, *http.Request, Handler) error
+
+func (f middlewareHandlerFunc) ServeHTTP(w http.ResponseWriter, r *http.Request, h Handler) error {
+	return f(w, r, h)
+}