Metrics (#324)

- adding additional metrics and instrumentation
- adding metrics covering the latency on providers interctions
- adding metrics for tokens issues, renewed and exchanged

CHANGELOG.md

@@ -3,8 +3,10 @@
 
 FEATURES:
 * Added a --enable-default-deny option to make denial by default [#PR320](https://github.com/gambol99/keycloak-proxy/pull/320)
+* Added spelling check to the tests [#PR322](https://github.com/gambol99/keycloak-proxy/pull/322)
 * Added the X-Auth-Audience to the upstream headers [#PR319](https://github.com/gambol99/keycloak-proxy/pull/319)
 * Added the ability to control the timeout on the initial openid configuration from .well-known/openid-configuration [#PR315](https://github.com/gambol99/keycloak-proxy/pull/315)
+* Adding additional metrics covering provider request latency, token breakdown [#PR324](https://github.com/gambol99/keycloak-proxy/pull/324)
 * Changed the upstream-keepalive to default to true [#PR321](https://github.com/gambol99/keycloak-proxy/pull/321)
 * Updated the docker base image alpine 3.7 [#PR313](https://github.com/gambol99/keycloak-proxy/pull/313)
 * Updated to Golang version 1.10 [#PR316](https://github.com/gambol99/keycloak-proxy/pull/316)

doc.go

@@ -23,6 +23,7 @@ import (
 	"time"
 
 	"github.com/gambol99/go-oidc/jose"
+	"github.com/prometheus/client_golang/prometheus"
 )
 
 var (
@@ -73,6 +74,36 @@ const (
 	headerXRequestID         = "X-Request-ID"
 )
 
+var (
+	oauthTokensMetric = prometheus.NewCounterVec(
+		prometheus.CounterOpts{
+			Name: "proxy_oauth_tokens_total",
+			Help: "A summary of the tokens issuesd, renewed or failed logins",
+		},
+		[]string{"action"},
+	)
+	oauthLatencyMetric = prometheus.NewSummaryVec(
+		prometheus.SummaryOpts{
+			Name: "proxy_oauth_request_latency_sec",
+			Help: "A summary of the request latancy for requests against the openid provider",
+		},
+		[]string{"action"},
+	)
+	latencyMetric = prometheus.NewSummary(
+		prometheus.SummaryOpts{
+			Name: "proxy_request_duration_sec",
+			Help: "A summary of the http request latency for proxy requests",
+		},
+	)
+	statusMetric = prometheus.NewCounterVec(
+		prometheus.CounterOpts{
+			Name: "proxy_request_status_total",
+			Help: "The HTTP requests partitioned by status code",
+		},
+		[]string{"code", "method"},
+	)
+)
+
 var (
 	// ErrSessionNotFound no session found in the request
 	ErrSessionNotFound = errors.New("authentication session not found")

handlers.go

@@ -31,6 +31,7 @@ import (
 	"time"
 
 	"github.com/gambol99/go-oidc/oauth2"
+
 	"github.com/pressly/chi"
 	"go.uber.org/zap"
 )
@@ -161,6 +162,9 @@ func (r *oauthProxy) oauthCallbackHandler(w http.ResponseWriter, req *http.Reque
 		zap.String("expires", identity.ExpiresAt.Format(time.RFC3339)),
 		zap.String("duration", time.Until(identity.ExpiresAt).String()))
 
+	// @metric a token has beeb issued
+	oauthTokensMetric.WithLabelValues("issued").Inc()
+
 	// step: does the response has a refresh token and we are NOT ignore refresh tokens?
 	if r.config.EnableRefreshTokens && resp.RefreshToken != "" {
 		var encrypted string
@@ -224,13 +228,16 @@ func (r *oauthProxy) loginHandler(w http.ResponseWriter, req *http.Request) {
 			return "unable to create the oauth client for user_credentials request", http.StatusInternalServerError, err
 		}
 
+		start := time.Now()
 		token, err := client.UserCredsToken(username, password)
 		if err != nil {
 			if strings.HasPrefix(err.Error(), oauth2.ErrorInvalidGrant) {
 				return "invalid user credentials provided", http.StatusUnauthorized, err
 			}
 			return "unable to request the access token via grant_type 'password'", http.StatusInternalServerError, err
 		}
+		// @metric observe the time taken for a login request
+		oauthLatencyMetric.WithLabelValues("login").Observe(time.Since(start).Seconds())
 
 		_, identity, err := parseToken(token.AccessToken)
 		if err != nil {
@@ -239,6 +246,9 @@ func (r *oauthProxy) loginHandler(w http.ResponseWriter, req *http.Request) {
 
 		r.dropAccessTokenCookie(req, w, token.AccessToken, time.Until(identity.ExpiresAt))
 
+		// @metric a token has been issued
+		oauthTokensMetric.WithLabelValues("login").Inc()
+
 		w.Header().Set("Content-Type", "application/json")
 		if err := json.NewEncoder(w).Encode(tokenResponse{
 			IDToken:      token.IDToken,
@@ -286,6 +296,9 @@ func (r *oauthProxy) logoutHandler(w http.ResponseWriter, req *http.Request) {
 	}
 	r.clearAllCookies(req, w)
 
+	// @metric increment the logout counter
+	oauthTokensMetric.WithLabelValues("logout").Inc()
+
 	// step: check if the user has a state session and if so revoke it
 	if r.useStore() {
 		go func() {
@@ -322,15 +335,18 @@ func (r *oauthProxy) logoutHandler(w http.ResponseWriter, req *http.Request) {
 			w.WriteHeader(http.StatusInternalServerError)
 			return
 		}
+
 		// step: add the authentication headers and content-type
 		request.SetBasicAuth(encodedID, encodedSecret)
 		request.Header.Set("Content-Type", "application/x-www-form-urlencoded")
 
+		start := time.Now()
 		response, err := client.HttpClient().Do(request)
 		if err != nil {
 			r.log.Error("unable to post to revocation endpoint", zap.Error(err))
 			return
 		}
+		oauthLatencyMetric.WithLabelValues("revocation").Observe(time.Since(start).Seconds())
 
 		// step: check the response
 		switch response.StatusCode {

middleware.go

@@ -26,7 +26,6 @@ import (
 	"github.com/PuerkitoBio/purell"
 	"github.com/gambol99/go-oidc/jose"
 	"github.com/go-chi/chi/middleware"
-	"github.com/prometheus/client_golang/prometheus"
 	"github.com/unrolled/secure"
 	"go.uber.org/zap"
 )
@@ -49,11 +48,16 @@ func entrypointMiddleware(next http.Handler) http.Handler {
 		req.RequestURI = req.URL.RawPath
 		req.URL.RawPath = req.URL.Path
 
-		// continue the flow
+		// @step: create a context for the request
 		scope := &RequestScope{}
 		resp := middleware.NewWrapResponseWriter(w, 1)
+		start := time.Now()
 		next.ServeHTTP(resp, req.WithContext(context.WithValue(req.Context(), contextScopeName, scope)))
 
+		// @metric record the time taken then response code
+		latencyMetric.Observe(time.Since(start).Seconds())
+		statusMetric.WithLabelValues(fmt.Sprintf("%d", resp.Status()), req.Method).Inc()
+
 		// place back the original uri for proxying request
 		req.URL.Path = keep
 		req.URL.RawPath = keep
@@ -78,27 +82,6 @@ func (r *oauthProxy) loggingMiddleware(next http.Handler) http.Handler {
 	})
 }
 
-// metricsMiddleware is responsible for collecting metrics
-func (r *oauthProxy) metricsMiddleware(next http.Handler) http.Handler {
-	r.log.Info("enabled the service metrics middleware, available on", zap.String("path", fmt.Sprintf("%s%s", oauthURL, metricsURL)))
-
-	statusMetrics := prometheus.NewCounterVec(
-		prometheus.CounterOpts{
-			Name: "http_request_total",
-			Help: "The HTTP requests partitioned by status code",
-		},
-		[]string{"code", "method"},
-	)
-	prometheus.MustRegister(statusMetrics)
-
-	return http.HandlerFunc(func(w http.ResponseWriter, req *http.Request) {
-		resp := w.(middleware.WrapResponseWriter)
-		statusMetrics.WithLabelValues(fmt.Sprintf("%d", resp.Status()), req.Method).Inc()
-
-		next.ServeHTTP(w, req)
-	})
-}
-
 // authenticationMiddleware is responsible for verifying the access token
 func (r *oauthProxy) authenticationMiddleware(resource *Resource) func(http.Handler) http.Handler {
 	return func(next http.Handler) http.Handler {

middleware_test.go

@@ -298,7 +298,7 @@ func TestMetricsMiddleware(t *testing.T) {
 		{
 			URI:                     oauthURL + metricsURL,
 			ExpectedCode:            http.StatusOK,
-			ExpectedContentContains: "http_request_total",
+			ExpectedContentContains: "proxy_request_status_total",
 		},
 		{
 			URI: oauthURL + metricsURL,

oauth.go

@@ -112,7 +112,22 @@ func getUserinfo(client *oauth2.Client, endpoint string, token string) (jose.Cla
 
 // getToken retrieves a code from the provider, extracts and verified the token
 func getToken(client *oauth2.Client, grantType, code string) (oauth2.TokenResponse, error) {
-	return client.RequestToken(grantType, code)
+	start := time.Now()
+	token, err := client.RequestToken(grantType, code)
+	if err != nil {
+		return token, err
+	}
+	taken := time.Since(start).Seconds()
+	switch grantType {
+	case oauth2.GrantTypeAuthCode:
+		oauthTokensMetric.WithLabelValues("exchange").Inc()
+		oauthLatencyMetric.WithLabelValues("exchange").Observe(taken)
+	case oauth2.GrantTypeRefreshToken:
+		oauthTokensMetric.WithLabelValues("renew").Inc()
+		oauthLatencyMetric.WithLabelValues("renew").Observe(taken)
+	}
+
+	return token, err
 }
 
 // parseToken retrieve the user identity from the token

server.go

@@ -36,7 +36,7 @@ import (
 
 	httplog "log"
 
-	"github.com/armon/go-proxyproto"
+	proxyproto "github.com/armon/go-proxyproto"
 	"github.com/gambol99/go-oidc/oidc"
 	"github.com/gambol99/goproxy"
 	"github.com/pressly/chi"
@@ -65,6 +65,11 @@ type oauthProxy struct {
 func init() {
 	time.LoadLocation("UTC")             // ensure all time is in UTC
 	runtime.GOMAXPROCS(runtime.NumCPU()) // set the core
+	// @step: register the instrumentation
+	prometheus.MustRegister(latencyMetric)
+	prometheus.MustRegister(oauthLatencyMetric)
+	prometheus.MustRegister(oauthTokensMetric)
+	prometheus.MustRegister(statusMetric)
 }
 
 // newProxy create's a new proxy from configuration
@@ -161,9 +166,6 @@ func (r *oauthProxy) createReverseProxy() error {
 	if r.config.EnableLogging {
 		engine.Use(r.loggingMiddleware)
 	}
-	if r.config.EnableMetrics {
-		engine.Use(r.metricsMiddleware)
-	}
 	if r.config.EnableSecurityFilter {
 		engine.Use(r.securityMiddleware)
 	}
@@ -194,6 +196,7 @@ func (r *oauthProxy) createReverseProxy() error {
 		e.Get(tokenURL, r.tokenHandler)
 		e.Post(loginURL, r.loginHandler)
 		if r.config.EnableMetrics {
+			r.log.Info("enabled the service metrics middleware, available on", zap.String("path", fmt.Sprintf("%s%s", oauthURL, metricsURL)))
 			e.Get(metricsURL, r.proxyMetricsHandler)
 		}
 	})