Add Exemplars for http_request_duration_seconds histogram

Signed-off-by: Matthias Loibl <mail@matthiasloibl.com>

A lot of these changes are actually changing the order of calling the
middlwares. Going forward we need to make sure to first call the tracing
middleware so that by the time our monitoring/instrumentation middleware
gets hit the tracing spans are already populated.

cmd/thanos/query_frontend.go

@@ -229,14 +229,14 @@ func runQueryFrontend(
 				if !cfg.webDisableCORS {
 					api.SetCORS(w)
 				}
-				ins.NewHandler(
+				tracing.HTTPMiddleware(
+					tracer,
 					name,
-					logMiddleware.HTTPMiddleware(
+					logger,
+					ins.NewHandler(
 						name,
-						tracing.HTTPMiddleware(
-							tracer,
+						logMiddleware.HTTPMiddleware(
 							name,
-							logger,
 							gziphandler.GzipHandler(middleware.RequestID(f)),
 						),
 					),

go.mod

@@ -46,7 +46,7 @@ require (
 	github.com/pkg/errors v0.9.1
 	github.com/pmezard/go-difflib v1.0.0
 	github.com/prometheus/alertmanager v0.21.1-0.20210310093010-0f9cab6991e6
-	github.com/prometheus/client_golang v1.9.0
+	github.com/prometheus/client_golang v1.10.0
 	github.com/prometheus/client_model v0.2.0
 	github.com/prometheus/common v0.18.0
 	github.com/prometheus/prometheus v1.8.2-0.20210315220929-1cba1741828b
@@ -67,6 +67,7 @@ require (
 	google.golang.org/grpc v1.34.0
 	gopkg.in/alecthomas/kingpin.v2 v2.2.6
 	gopkg.in/fsnotify.v1 v1.4.7
+	gopkg.in/fsnotify/fsnotify.v1 v1.4.7 // indirect
 	gopkg.in/yaml.v2 v2.4.0
 	gopkg.in/yaml.v3 v3.0.0-20210107192922-496545a6307b
 )

go.sum

@@ -1050,6 +1050,8 @@ github.com/prometheus/client_golang v1.7.1/go.mod h1:PY5Wy2awLA44sXw4AOSfFBetzPP
 github.com/prometheus/client_golang v1.8.0/go.mod h1:O9VU6huf47PktckDQfMTX0Y8tY0/7TSWwj+ITvv0TnM=
 github.com/prometheus/client_golang v1.9.0 h1:Rrch9mh17XcxvEu9D9DEpb4isxjGBtcevQjKvxPRQIU=
 github.com/prometheus/client_golang v1.9.0/go.mod h1:FqZLKOZnGdFAhOK4nqGHa7D66IdsO+O441Eve7ptJDU=
+github.com/prometheus/client_golang v1.10.0 h1:/o0BDeWzLWXNZ+4q5gXltUvaMpJqckTa+jTNoB+z4cg=
+github.com/prometheus/client_golang v1.10.0/go.mod h1:WJM3cc3yu7XKBKa/I8WeZm+V3eltZnBwfENSU7mdogU=
 github.com/prometheus/client_model v0.0.0-20170216185247-6f3806018612/go.mod h1:MbSGuTsp3dbXC40dX6PRTWyKYBIrTGTE9sqQNg2J8bo=
 github.com/prometheus/client_model v0.0.0-20180712105110-5c3871d89910/go.mod h1:MbSGuTsp3dbXC40dX6PRTWyKYBIrTGTE9sqQNg2J8bo=
 github.com/prometheus/client_model v0.0.0-20190115171406-56726106282f/go.mod h1:MbSGuTsp3dbXC40dX6PRTWyKYBIrTGTE9sqQNg2J8bo=
@@ -1094,6 +1096,8 @@ github.com/prometheus/procfs v0.0.11/go.mod h1:lV6e/gmhEcM9IjHGsFOCxxuZ+z1YqCvr4
 github.com/prometheus/procfs v0.1.3/go.mod h1:lV6e/gmhEcM9IjHGsFOCxxuZ+z1YqCvr4OA4YeYWdaU=
 github.com/prometheus/procfs v0.2.0 h1:wH4vA7pcjKuZzjF7lM8awk4fnuJO6idemZXoKnULUx4=
 github.com/prometheus/procfs v0.2.0/go.mod h1:lV6e/gmhEcM9IjHGsFOCxxuZ+z1YqCvr4OA4YeYWdaU=
+github.com/prometheus/procfs v0.6.0 h1:mxy4L2jP6qMonqmq+aTtOx1ifVWUgG/TAmntgbh3xv4=
+github.com/prometheus/procfs v0.6.0/go.mod h1:cz+aTbrPOrUb4q7XlbU9ygM+/jj0fzG6c1xBZuNvfVA=
 github.com/prometheus/prometheus v1.8.2-0.20210315220929-1cba1741828b h1:TTOvmIV3W6IUIj3pYFs9gfCgueHlriLStMGBsnNdEX4=
 github.com/prometheus/prometheus v1.8.2-0.20210315220929-1cba1741828b/go.mod h1:MS/bpdil77lPbfQeKk6OqVQ9OLnpN3Rszd0hka0EOWE=
 github.com/prometheus/tsdb v0.7.1/go.mod h1:qhTCs0VvXwvX/y3TZrWD7rabWM+ijKTux40TwIPHuXU=
@@ -1556,6 +1560,8 @@ golang.org/x/sys v0.0.0-20210104204734-6f8348627aad/go.mod h1:h1NjWce9XRLGQEsW7w
 golang.org/x/sys v0.0.0-20210119212857-b64e53b001e4/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
 golang.org/x/sys v0.0.0-20210124154548-22da62e12c0c h1:VwygUrnw9jn88c4u8GD3rZQbqrP/tgas88tPUbBxQrk=
 golang.org/x/sys v0.0.0-20210124154548-22da62e12c0c/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
+golang.org/x/sys v0.0.0-20210309074719-68d13333faf2 h1:46ULzRKLh1CwgRq2dC5SlBzEqqNCi8rreOZnNrbqcIY=
+golang.org/x/sys v0.0.0-20210309074719-68d13333faf2/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
 golang.org/x/term v0.0.0-20201117132131-f5c789dd3221/go.mod h1:Nr5EML6q2oocZ2LXRh80K7BxOlk5/8JxuGnuhpl+muw=
 golang.org/x/term v0.0.0-20201126162022-7de9c90e9dd1 h1:v+OssWQX+hTHEmOBgwxdZxK4zHq3yOs8F9J7mk0PY8E=
 golang.org/x/term v0.0.0-20201126162022-7de9c90e9dd1/go.mod h1:bj7SfCRtBDWHUb9snDiAeCFNEtKQo2Wmx5Cou7ajbmo=

pkg/api/api.go

@@ -216,7 +216,16 @@ func GetInstr(
 				w.WriteHeader(http.StatusNoContent)
 			}
 		})
-		return ins.NewHandler(name, logMiddleware.HTTPMiddleware(name, tracing.HTTPMiddleware(tracer, name, logger, gziphandler.GzipHandler(middleware.RequestID(hf)))))
+
+		return tracing.HTTPMiddleware(tracer, name, logger,
+			ins.NewHandler(name,
+				logMiddleware.HTTPMiddleware(name,
+					gziphandler.GzipHandler(
+						middleware.RequestID(hf),
+					),
+				),
+			),
+		)
 	}
 	return instr
 }

pkg/extprom/http/instrument_server.go

@@ -4,11 +4,16 @@
 package http
 
 import (
+	"fmt"
 	"net/http"
+	"strings"
+	"time"
 
+	"github.com/opentracing/opentracing-go"
 	"github.com/prometheus/client_golang/prometheus"
 	"github.com/prometheus/client_golang/prometheus/promauto"
 	"github.com/prometheus/client_golang/prometheus/promhttp"
+	"github.com/uber/jaeger-client-go"
 )
 
 // InstrumentationMiddleware holds necessary metrics to instrument an http.Server
@@ -21,9 +26,9 @@ type InstrumentationMiddleware interface {
 type nopInstrumentationMiddleware struct{}
 
 func (ins nopInstrumentationMiddleware) NewHandler(handlerName string, handler http.Handler) http.HandlerFunc {
-	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+	return func(w http.ResponseWriter, r *http.Request) {
 		handler.ServeHTTP(w, r)
-	})
+	}
 }
 
 // NewNopInstrumentationMiddleware provides a InstrumentationMiddleware which does nothing.
@@ -90,17 +95,72 @@ func NewInstrumentationMiddleware(reg prometheus.Registerer, buckets []float64)
 // value. http_requests_total is a metric vector partitioned by HTTP method
 // (label name "method") and HTTP status code (label name "code").
 func (ins *defaultInstrumentationMiddleware) NewHandler(handlerName string, handler http.Handler) http.HandlerFunc {
-	return promhttp.InstrumentHandlerDuration(
-		ins.requestDuration.MustCurryWith(prometheus.Labels{"handler": handlerName}),
-		promhttp.InstrumentHandlerRequestSize(
-			ins.requestSize.MustCurryWith(prometheus.Labels{"handler": handlerName}),
-			promhttp.InstrumentHandlerCounter(
-				ins.requestsTotal.MustCurryWith(prometheus.Labels{"handler": handlerName}),
-				promhttp.InstrumentHandlerResponseSize(
-					ins.responseSize.MustCurryWith(prometheus.Labels{"handler": handlerName}),
-					handler,
-				),
+	return promhttp.InstrumentHandlerRequestSize(
+		ins.requestSize.MustCurryWith(prometheus.Labels{"handler": handlerName}),
+		promhttp.InstrumentHandlerCounter(
+			ins.requestsTotal.MustCurryWith(prometheus.Labels{"handler": handlerName}),
+			promhttp.InstrumentHandlerResponseSize(
+				ins.responseSize.MustCurryWith(prometheus.Labels{"handler": handlerName}),
+				http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+					now := time.Now()
+
+					wd := &responseWriterDelegator{w: w}
+					handler.ServeHTTP(wd, r)
+
+					observer := ins.requestDuration.WithLabelValues(
+						wd.Status(),
+						handlerName,
+						strings.ToLower(r.Method),
+					)
+					observer.Observe(time.Since(now).Seconds())
+
+					// If we find a tracingID we'll expose it as Exemplar.
+					span := opentracing.SpanFromContext(r.Context())
+					if span != nil {
+						spanCtx, ok := span.Context().(jaeger.SpanContext)
+						if ok {
+							observer.(prometheus.ExemplarObserver).ObserveWithExemplar(
+								time.Since(now).Seconds(),
+								prometheus.Labels{
+									"traceID": spanCtx.TraceID().String(),
+								},
+							)
+						}
+					}
+				}),
 			),
 		),
 	)
 }
+
+// responseWriterDelegator implements http.ResponseWriter and extracts the statusCode.
+type responseWriterDelegator struct {
+	w          http.ResponseWriter
+	written    bool
+	statusCode int
+}
+
+func (wd *responseWriterDelegator) Header() http.Header {
+	return wd.w.Header()
+}
+
+func (wd *responseWriterDelegator) Write(bytes []byte) (int, error) {
+	return wd.w.Write(bytes)
+}
+
+func (wd *responseWriterDelegator) WriteHeader(statusCode int) {
+	wd.written = true
+	wd.statusCode = statusCode
+	wd.w.WriteHeader(statusCode)
+}
+
+func (wd *responseWriterDelegator) StatusCode() int {
+	if !wd.written {
+		return http.StatusOK
+	}
+	return wd.statusCode
+}
+
+func (wd *responseWriterDelegator) Status() string {
+	return fmt.Sprintf("%d", wd.StatusCode())
+}

pkg/receive/handler.go

@@ -157,10 +157,11 @@ func NewHandler(logger log.Logger, o *Options) *Handler {
 
 	readyf := h.testReady
 	instrf := func(name string, next func(w http.ResponseWriter, r *http.Request)) http.HandlerFunc {
+		next = ins.NewHandler(name, http.HandlerFunc(next))
 		if o.Tracer != nil {
 			next = tracing.HTTPMiddleware(o.Tracer, name, logger, http.HandlerFunc(next))
 		}
-		return ins.NewHandler(name, http.HandlerFunc(next))
+		return next
 	}
 
 	h.router.Post("/api/v1/receive", instrf("receive", readyf(middleware.RequestID(http.HandlerFunc(h.receiveHTTP)))))

pkg/server/http/http.go

@@ -104,7 +104,9 @@ func registerProfiler(mux *http.ServeMux) {
 
 func registerMetrics(mux *http.ServeMux, g prometheus.Gatherer) {
 	if g != nil {
-		mux.Handle("/metrics", promhttp.HandlerFor(g, promhttp.HandlerOpts{}))
+		mux.Handle("/metrics", promhttp.HandlerFor(g, promhttp.HandlerOpts{
+			EnableOpenMetrics: true,
+		}))
 	}
 }