diff --git a/CHANGELOG.md b/CHANGELOG.md index f4d0622d..0be38220 100644 --- a/CHANGELOG.md +++ b/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) diff --git a/doc.go b/doc.go index c89fab5f..9349bc2b 100644 --- a/doc.go +++ b/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") diff --git a/handlers.go b/handlers.go index 944ce180..3ef3a35b 100644 --- a/handlers.go +++ b/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,6 +228,7 @@ 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) { @@ -231,6 +236,8 @@ func (r *oauthProxy) loginHandler(w http.ResponseWriter, req *http.Request) { } 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 { diff --git a/middleware.go b/middleware.go index 01a3e69d..21574027 100644 --- a/middleware.go +++ b/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 { diff --git a/middleware_test.go b/middleware_test.go index c8d96805..eb80fa52 100644 --- a/middleware_test.go +++ b/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, diff --git a/oauth.go b/oauth.go index b66131a4..f65c908c 100644 --- a/oauth.go +++ b/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 diff --git a/server.go b/server.go index 1ef3dcaa..0e28535f 100644 --- a/server.go +++ b/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) } })