feat: extended metrics (#66)

* feat: count the API hits for each good route and store in expvar metrics

* corrected package comment

* moved declaration to pkg level to be compatible with existing tests.

* addressing PR comments

* addressing PR comments

* using github.com/go-kit/kit for metrics

* small change

* some linter fixes

* adjusting tests and linters

* simplifying after review

* change Response time to Counter

* adjusted expvar keys

* making sure the chi router is defined only one time.

* small change after PR

Author: pawels-optimizely

go.mod

@@ -5,6 +5,7 @@ go 1.12
 require (
 	github.com/go-chi/chi v4.0.2+incompatible
 	github.com/go-chi/render v1.0.1
+	github.com/go-kit/kit v0.9.0 // indirect
 	github.com/google/uuid v1.1.1
 	github.com/nsqio/nsq v1.2.0
 	github.com/optimizely/go-sdk v1.0.0-beta5.0.20191031194604-0f774263df60

go.sum

@@ -36,6 +36,8 @@ github.com/go-chi/chi v4.0.2+incompatible/go.mod h1:eB3wogJHnLi3x/kFX2A+IbTBlXxm
 github.com/go-chi/render v1.0.1 h1:4/5tis2cKaNdnv9zFLfXzcquC9HbeZgCnxGnKrltBS8=
 github.com/go-chi/render v1.0.1/go.mod h1:pq4Rr7HbnsdaeHagklXub+p6Wd16Af5l9koip1OvJns=
 github.com/go-kit/kit v0.8.0/go.mod h1:xBxKIO96dXMWWy0MnWVtmwkA9/13aqxPnvrjFYMA2as=
+github.com/go-kit/kit v0.9.0 h1:wDJmvq38kDhkVxi50ni9ykkdUr1PKgqKOoi01fa0Mdk=
+github.com/go-kit/kit v0.9.0/go.mod h1:xBxKIO96dXMWWy0MnWVtmwkA9/13aqxPnvrjFYMA2as=
 github.com/go-logfmt/logfmt v0.3.0/go.mod h1:Qt1PoO58o5twSAckw1HlFXLmHsOX5/0LbT9GBnD5lWE=
 github.com/go-logfmt/logfmt v0.4.0/go.mod h1:3RMwSq7FuexP4Kalkev3ejPJsZTpXXBr9+V4qmtdjCk=
 github.com/go-stack/stack v1.8.0/go.mod h1:v0f6uXyyMGvRgIKkXu+yp6POWl0qKG85gN/melR3HDY=

pkg/api/middleware/metrics.go

@@ -18,22 +18,74 @@
 package middleware
 
 import (
-	"expvar"
+	"context"
 	"net/http"
-	"strings"
+	"time"
 
-	"github.com/go-chi/chi"
+	"github.com/go-kit/kit/metrics"
+	"github.com/go-kit/kit/metrics/expvar"
 )
 
-// HitCount update counts for each URL hit, key being a combination of a method and route pattern
-func HitCount(counts *expvar.Map) func(http.Handler) http.Handler {
+const metricPrefix = "timers."
+
+type contextString string
+
+const responseTime = contextString("responseTime")
+
+// Metrics struct contains url hit counts, response time and its histogram
+type Metrics struct {
+	HitCounts             metrics.Counter
+	ResponseTime          metrics.Counter
+	ResponseTimeHistogram metrics.Histogram
+}
+
+// NewMetrics initialized metrics
+func NewMetrics(key string) *Metrics {
+
+	uniqueName := metricPrefix + key
+
+	return &Metrics{
+		HitCounts:             expvar.NewCounter(uniqueName + ".counts"),
+		ResponseTime:          expvar.NewCounter(uniqueName + ".responseTime"),
+		ResponseTimeHistogram: expvar.NewHistogram(uniqueName+".responseTimeHist", 50),
+	}
+}
+
+// Metricize updates counts, total response time, and response time histogram
+// for each URL hit, key being a combination of a method and route pattern
+func Metricize(key string) func(http.Handler) http.Handler {
+	singleMetric := NewMetrics(key)
+
 	f := func(h http.Handler) http.Handler {
+
 		fn := func(w http.ResponseWriter, r *http.Request) {
-			key := r.Method + "_" + strings.ReplaceAll(chi.RouteContext(r.Context()).RoutePattern(), "/", "_")
-			counts.Add(key, 1)
+
+			singleMetric.HitCounts.Add(1)
+			ctx := r.Context()
+			startTime, ok := ctx.Value(responseTime).(time.Time)
+			if ok {
+				defer func() {
+					endTime := time.Now()
+					timeDiff := endTime.Sub(startTime).Seconds()
+					singleMetric.ResponseTime.Add(timeDiff)
+					singleMetric.ResponseTimeHistogram.Observe(timeDiff)
+				}()
+			}
+
 			h.ServeHTTP(w, r)
 		}
 		return http.HandlerFunc(fn)
 	}
 	return f
 }
+
+// SetTime middleware sets the start time in request context
+func SetTime(next http.Handler) http.Handler {
+
+	fn := func(w http.ResponseWriter, r *http.Request) {
+
+		ctx := context.WithValue(r.Context(), responseTime, time.Now())
+		next.ServeHTTP(w, r.WithContext(ctx))
+	}
+	return http.HandlerFunc(fn)
+}

pkg/api/middleware/metrics_test.go

@@ -24,8 +24,8 @@ import (
 	"net/http"
 	"net/http/httptest"
 	"testing"
+	"time"
 
-	"github.com/go-chi/chi"
 	"github.com/stretchr/testify/suite"
 )
 
@@ -43,24 +43,24 @@ type RequestMetrics struct {
 	handler http.Handler
 }
 
-func (rm *RequestMetrics) setRoute(metricsKey string) {
+func (rm *RequestMetrics) SetupRoute(key string) {
 
-	metricsMap := expvar.NewMap(metricsKey)
 	rm.rw = httptest.NewRecorder()
 	r := httptest.NewRequest("GET", "/", nil)
 
-	rctx := chi.NewRouteContext()
-	rctx.RoutePatterns = []string{"/item/{set_item}"}
-
-	rm.req = r.WithContext(context.WithValue(r.Context(), chi.RouteCtxKey, rctx))
-	rm.handler = http.Handler(HitCount(metricsMap)(getTestMetrics()))
+	rm.req = r.WithContext(context.WithValue(r.Context(), responseTime, time.Now()))
+	rm.handler = http.Handler(Metricize(key)(getTestMetrics()))
 
 }
 
 func (rm RequestMetrics) serveRoute() {
 	rm.handler.ServeHTTP(rm.rw, rm.req)
 }
 
+func (rm RequestMetrics) serveSetTimehHandler() {
+	http.Handler(SetTime(getTestMetrics())).ServeHTTP(rm.rw, rm.req)
+}
+
 func (rm RequestMetrics) serveExpvarRoute() {
 	expvar.Handler().ServeHTTP(rm.rw, rm.req)
 }
@@ -77,36 +77,32 @@ func (rm RequestMetrics) getCode() int {
 	return rm.rw.(*httptest.ResponseRecorder).Code
 }
 
+var sufixList = []string{".counts", ".responseTime", ".responseTimeHist.p50", ".responseTimeHist.p90", ".responseTimeHist.p95", ".responseTimeHist.p99"}
+
 func (suite *RequestMetrics) TestUpdateMetricsHitOnce() {
 
-	var metricsKey = "counter"
+	suite.SetupRoute("some_key")
 
-	suite.setRoute(metricsKey)
 	suite.serveRoute()
 
 	suite.Equal(http.StatusOK, suite.getCode(), "Status code differs")
-
 	suite.serveExpvarRoute()
 
 	expVarMap := suite.getMetricsMap()
+	for _, item := range sufixList {
+		expectedKey := metricPrefix + "some_key" + item
+		value, ok := expVarMap[expectedKey]
+		suite.True(ok)
 
-	counterMap, ok := expVarMap[metricsKey]
-	suite.True(ok)
-
-	suite.Contains(counterMap, "GET__item_{set_item}")
-
-	m := counterMap.(map[string]interface{})
-
-	suite.Equal(1.0, m["GET__item_{set_item}"])
-
+		suite.NotEqual(0.0, value)
+	}
 }
 
 func (suite *RequestMetrics) TestUpdateMetricsHitMultiple() {
 
-	var metricsKey = "counter1"
 	const hitNumber = 10.0
 
-	suite.setRoute(metricsKey)
+	suite.SetupRoute("different_key")
 
 	for i := 0; i < hitNumber; i++ {
 		suite.serveRoute()
@@ -118,15 +114,11 @@ func (suite *RequestMetrics) TestUpdateMetricsHitMultiple() {
 
 	expVarMap := suite.getMetricsMap()
 
-	counterMap, ok := expVarMap[metricsKey]
+	expectedKey := metricPrefix + "different_key.counts"
+	value, ok := expVarMap[expectedKey]
 	suite.True(ok)
 
-	suite.Contains(counterMap, "GET__item_{set_item}")
-
-	m := counterMap.(map[string]interface{})
-
-	suite.Equal(hitNumber, m["GET__item_{set_item}"])
-
+	suite.NotEqual(0.0, value)
 }
 
 func TestRequestMetrics(t *testing.T) {

pkg/api/router.go

@@ -18,8 +18,6 @@
 package api
 
 import (
-	"expvar"
-
 	"github.com/optimizely/sidedoor/pkg/api/handlers"
 	"github.com/optimizely/sidedoor/pkg/api/middleware"
 	"github.com/optimizely/sidedoor/pkg/optimizely"
@@ -49,31 +47,28 @@ func NewDefaultRouter(optlyCache optimizely.Cache) *chi.Mux {
 	return NewRouter(spec)
 }
 
-const metricsPrefix = "route_counters"
-
-var routeCounts = expvar.NewMap(metricsPrefix)
-
 // NewRouter returns HTTP API router backed by an optimizely.Cache implementation
 func NewRouter(opt *RouterOptions) *chi.Mux {
 	r := chi.NewRouter()
 
+	r.Use(middleware.SetTime)
 	r.Use(render.SetContentType(render.ContentTypeJSON), middleware.SetRequestID)
 
-	r.With(chimw.AllowContentType("application/json"), middleware.HitCount(routeCounts)).Post("/user-event", opt.userEventAPI.AddUserEvent)
+	r.With(chimw.AllowContentType("application/json"), middleware.Metricize("user-event")).Post("/user-event", opt.userEventAPI.AddUserEvent)
 
 	r.Route("/features", func(r chi.Router) {
 		r.Use(opt.middleware.ClientCtx)
-		r.With(middleware.HitCount(routeCounts)).Get("/", opt.featureAPI.ListFeatures)
-		r.With(middleware.HitCount(routeCounts)).Get("/{featureKey}", opt.featureAPI.GetFeature)
+		r.With(middleware.Metricize("list-features")).Get("/", opt.featureAPI.ListFeatures)
+		r.With(middleware.Metricize("get-feature")).Get("/{featureKey}", opt.featureAPI.GetFeature)
 	})
 
 	r.Route("/users/{userID}", func(r chi.Router) {
 		r.Use(opt.middleware.ClientCtx, opt.middleware.UserCtx)
 
-		r.With(middleware.HitCount(routeCounts)).Post("/events/{eventKey}", opt.userAPI.TrackEvent)
+		r.With(middleware.Metricize("track-event")).Post("/events/{eventKey}", opt.userAPI.TrackEvent)
 
-		r.With(middleware.HitCount(routeCounts)).Get("/features/{featureKey}", opt.userAPI.GetFeature)
-		r.With(middleware.HitCount(routeCounts)).Post("/features/{featureKey}", opt.userAPI.TrackFeature)
+		r.With(middleware.Metricize("get-user-feature")).Get("/features/{featureKey}", opt.userAPI.GetFeature)
+		r.With(middleware.Metricize("track-user-feature")).Post("/features/{featureKey}", opt.userAPI.TrackFeature)
 	})
 
 	return r

pkg/api/router_test.go

@@ -21,6 +21,7 @@ import (
 	"encoding/json"
 	"net/http"
 	"net/http/httptest"
+	"sync"
 	"testing"
 
 	"github.com/go-chi/chi"
@@ -98,18 +99,23 @@ type RouterTestSuite struct {
 	mux *chi.Mux
 }
 
+var once sync.Once
+
 func (suite *RouterTestSuite) SetupTest() {
-	testClient := optimizelytest.NewClient()
-	suite.tc = testClient
-
-	opts := &RouterOptions{
-		featureAPI:   new(MockFeatureAPI),
-		userEventAPI: new(MockUserEventAPI),
-		userAPI:      new(MockUserAPI),
-		middleware:   new(MockOptlyMiddleware),
-	}
 
-	suite.mux = NewRouter(opts)
+	once.Do(func() {
+		testClient := optimizelytest.NewClient()
+		suite.tc = testClient
+
+		opts := &RouterOptions{
+			featureAPI:   new(MockFeatureAPI),
+			userEventAPI: new(MockUserEventAPI),
+			userAPI:      new(MockUserAPI),
+			middleware:   new(MockOptlyMiddleware),
+		}
+
+		suite.mux = NewRouter(opts)
+	})
 }
 
 func (suite *RouterTestSuite) TestListFeatures() {