Merge pull request #31 from microservices-demo/monitoring/rationalise…

…-prometheus

Rationalise prometheus to produce RED metrics

cmd/cataloguesvc/main.go

@@ -8,10 +8,8 @@ import (
 	"syscall"
 
 	"github.com/go-kit/kit/log"
-	kitprometheus "github.com/go-kit/kit/metrics/prometheus"
 	stdopentracing "github.com/opentracing/opentracing-go"
 	zipkin "github.com/openzipkin/zipkin-go-opentracing"
-	stdprometheus "github.com/prometheus/client_golang/prometheus"
 
 	"net/http"
 
@@ -20,6 +18,7 @@ import (
 	_ "github.com/go-sql-driver/mysql"
 	"github.com/jmoiron/sqlx"
 	"github.com/microservices-demo/catalogue"
+	"github.com/microservices-demo/catalogue/middleware"
 	"golang.org/x/net/context"
 )
 
@@ -96,38 +95,32 @@ func main() {
 		logger.Log("Error", "Unable to connect to Database", "DSN", dsn)
 	}
 
-	fieldKeys := []string{"method"}
 	// Service domain.
 	var service catalogue.Service
 	{
 		service = catalogue.NewCatalogueService(db, logger)
 		service = catalogue.LoggingMiddleware(logger)(service)
-		service = catalogue.NewInstrumentingService(
-			kitprometheus.NewCounterFrom(
-				stdprometheus.CounterOpts{
-					Namespace: "microservices_demo",
-					Subsystem: "catalogue",
-					Name:      "request_count",
-					Help:      "Number of requests received.",
-				},
-				fieldKeys),
-			kitprometheus.NewSummaryFrom(stdprometheus.SummaryOpts{
-				Namespace: "microservices_demo",
-				Subsystem: "catalogue",
-				Name:      "request_latency_microseconds",
-				Help:      "Total duration of requests in microseconds.",
-			}, fieldKeys),
-			service,
-		)
 	}
 
 	// Endpoint domain.
 	endpoints := catalogue.MakeEndpoints(service, tracer)
 
+	// HTTP router
+	router := catalogue.MakeHTTPHandler(ctx, endpoints, *images, logger, tracer)
+
+	httpMiddleware := []middleware.Interface{
+		middleware.Instrument{
+			Duration:     middleware.HTTPLatency,
+			RouteMatcher: router,
+		},
+	}
+
+	// Handler
+	handler := middleware.Merge(httpMiddleware...).Wrap(router)
+
 	// Create and launch the HTTP server.
 	go func() {
 		logger.Log("transport", "HTTP", "port", *port)
-		handler := catalogue.MakeHTTPHandler(ctx, endpoints, *images, logger, tracer)
 		errc <- http.ListenAndServe(":"+*port, handler)
 	}()
 

logging.go

@@ -0,0 +1,88 @@
+package catalogue
+
+import (
+	"strings"
+	"time"
+
+	"github.com/go-kit/kit/log"
+)
+
+// LoggingMiddleware logs method calls, parameters, results, and elapsed time.
+func LoggingMiddleware(logger log.Logger) Middleware {
+	return func(next Service) Service {
+		return loggingMiddleware{
+			next:   next,
+			logger: logger,
+		}
+	}
+}
+
+type loggingMiddleware struct {
+	next   Service
+	logger log.Logger
+}
+
+func (mw loggingMiddleware) List(tags []string, order string, pageNum, pageSize int) (socks []Sock, err error) {
+	defer func(begin time.Time) {
+		mw.logger.Log(
+			"method", "List",
+			"tags", strings.Join(tags, ", "),
+			"order", order,
+			"pageNum", pageNum,
+			"pageSize", pageSize,
+			"result", len(socks),
+			"err", err,
+			"took", time.Since(begin),
+		)
+	}(time.Now())
+	return mw.next.List(tags, order, pageNum, pageSize)
+}
+
+func (mw loggingMiddleware) Count(tags []string) (n int, err error) {
+	defer func(begin time.Time) {
+		mw.logger.Log(
+			"method", "Count",
+			"tags", strings.Join(tags, ", "),
+			"result", n,
+			"err", err,
+			"took", time.Since(begin),
+		)
+	}(time.Now())
+	return mw.next.Count(tags)
+}
+
+func (mw loggingMiddleware) Get(id string) (s Sock, err error) {
+	defer func(begin time.Time) {
+		mw.logger.Log(
+			"method", "Get",
+			"id", id,
+			"sock", s.ID,
+			"err", err,
+			"took", time.Since(begin),
+		)
+	}(time.Now())
+	return mw.next.Get(id)
+}
+
+func (mw loggingMiddleware) Tags() (tags []string, err error) {
+	defer func(begin time.Time) {
+		mw.logger.Log(
+			"method", "Tags",
+			"result", len(tags),
+			"err", err,
+			"took", time.Since(begin),
+		)
+	}(time.Now())
+	return mw.next.Tags()
+}
+
+func (mw loggingMiddleware) Health() (health []Health) {
+	defer func(begin time.Time) {
+		mw.logger.Log(
+			"method", "Health",
+			"result", len(health),
+			"took", time.Since(begin),
+		)
+	}(time.Now())
+	return mw.next.Health()
+}

middleware/instrument.go

@@ -0,0 +1,93 @@
+package middleware
+
+import (
+	"net/http"
+	"regexp"
+	"strconv"
+	"strings"
+	"time"
+
+	"github.com/felixge/httpsnoop"
+	"github.com/gorilla/mux"
+	"github.com/prometheus/client_golang/prometheus"
+)
+
+var (
+	HTTPLatency = prometheus.NewHistogramVec(prometheus.HistogramOpts{
+		Name:    "request_duration_seconds",
+		Help:    "Time (in seconds) spent serving HTTP requests.",
+		Buckets: prometheus.DefBuckets,
+	}, []string{"method", "route", "status_code"})
+)
+
+func init() {
+	prometheus.MustRegister(HTTPLatency)
+}
+
+// RouteMatcher matches routes
+type RouteMatcher interface {
+	Match(*http.Request, *mux.RouteMatch) bool
+}
+
+// Instrument is a Middleware which records timings for every HTTP request
+type Instrument struct {
+	RouteMatcher RouteMatcher
+	Duration     *prometheus.HistogramVec
+}
+
+// Wrap implements middleware.Interface
+func (i Instrument) Wrap(next http.Handler) http.Handler {
+	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+		begin := time.Now()
+		interceptor := httpsnoop.CaptureMetrics(next, w, r)
+		route := i.getRouteName(r)
+		var (
+			status = strconv.Itoa(interceptor.Code)
+			took   = time.Since(begin)
+		)
+		i.Duration.WithLabelValues(r.Method, route, status).Observe(took.Seconds())
+	})
+}
+
+// Return a name identifier for ths request.  There are three options:
+//   1. The request matches a gorilla mux route, with a name.  Use that.
+//   2. The request matches an unamed gorilla mux router.  Munge the path
+//      template such that templates like '/api/{org}/foo' come out as
+//      'api_org_foo'.
+//   3. The request doesn't match a mux route.  Munge the Path in the same
+//      manner as (2).
+// We do all this as we do not wish to emit high cardinality labels to
+// prometheus.
+func (i Instrument) getRouteName(r *http.Request) string {
+	var routeMatch mux.RouteMatch
+	if i.RouteMatcher != nil && i.RouteMatcher.Match(r, &routeMatch) {
+		if name := routeMatch.Route.GetName(); name != "" {
+			return name
+		}
+		if tmpl, err := routeMatch.Route.GetPathTemplate(); err == nil {
+			return MakeLabelValue(tmpl)
+		}
+	}
+	return MakeLabelValue(r.URL.Path)
+}
+
+var invalidChars = regexp.MustCompile(`[^a-zA-Z0-9]+`)
+
+// MakeLabelValue converts a Gorilla mux path to a string suitable for use in
+// a Prometheus label value.
+func MakeLabelValue(path string) string {
+	// Convert non-alnums to underscores.
+	result := invalidChars.ReplaceAllString(path, "_")
+
+	// Trim leading and trailing underscores.
+	result = strings.Trim(result, "_")
+
+	// Make it all lowercase
+	result = strings.ToLower(result)
+
+	// Special case.
+	if result == "" {
+		result = "root"
+	}
+	return result
+}

middleware/middleware.go

@@ -0,0 +1,33 @@
+package middleware
+
+import (
+	"net/http"
+)
+
+// Interface is the shared contract for all middlesware, and allows middlesware
+// to wrap handlers.
+type Interface interface {
+	Wrap(http.Handler) http.Handler
+}
+
+// Func is to Interface as http.HandlerFunc is to http.Handler
+type Func func(http.Handler) http.Handler
+
+// Wrap implements Interface
+func (m Func) Wrap(next http.Handler) http.Handler {
+	return m(next)
+}
+
+// Identity is an Interface which doesn't do anything.
+var Identity Interface = Func(func(h http.Handler) http.Handler { return h })
+
+// Merge produces a middleware that applies multiple middlesware in turn;
+// ie Merge(f,g,h).Wrap(handler) == f.Wrap(g.Wrap(h.Wrap(handler)))
+func Merge(middlesware ...Interface) Interface {
+	return Func(func(next http.Handler) http.Handler {
+		for i := len(middlesware) - 1; i >= 0; i-- {
+			next = middlesware[i].Wrap(next)
+		}
+		return next
+	})
+}