metrics: Initial integration of Prometheus metrics (#3709)

Signed-off-by: Dave Henderson <dhenderson@gmail.com>

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)
+}

modules/caddyhttp/routes.go

@@ -157,7 +157,7 @@ func (routes RouteList) ProvisionHandlers(ctx caddy.Context) error {
 
 		// pre-compile the middleware handler chain
 		for _, midhandler := range routes[i].Handlers {
-			routes[i].middleware = append(routes[i].middleware, wrapMiddleware(midhandler))
+			routes[i].middleware = append(routes[i].middleware, wrapMiddleware(ctx, midhandler))
 		}
 	}
 	return nil
@@ -242,7 +242,13 @@ func wrapRoute(route Route) Middleware {
 // we need to pull this particular MiddlewareHandler
 // pointer into its own stack frame to preserve it so it
 // won't be overwritten in future loop iterations.
-func wrapMiddleware(mh MiddlewareHandler) Middleware {
+func wrapMiddleware(ctx caddy.Context, mh MiddlewareHandler) Middleware {
+	// first, wrap the middleware with metrics instrumentation
+	metricsHandler := newMetricsInstrumentedHandler(
+		serverNameFromContext(ctx.Context),
+		caddy.GetModuleName(mh),
+		mh,
+	)
 	return func(next Handler) Handler {
 		// copy the next handler (it's an interface, so it's
 		// just a very lightweight copy of a pointer); this
@@ -253,7 +259,7 @@ func wrapMiddleware(mh MiddlewareHandler) Middleware {
 		return HandlerFunc(func(w http.ResponseWriter, r *http.Request) error {
 			// TODO: This is where request tracing could be implemented
 			// TODO: see what the std lib gives us in terms of stack tracing too
-			return mh.ServeHTTP(w, r, nextCopy)
+			return metricsHandler.ServeHTTP(w, r, nextCopy)
 		})
 	}
 }