Logging Middleware: Add GitHub API Rate Limiting information (#413)

githubapp/middleware.go

@@ -75,8 +75,9 @@ func ClientMetrics(registry metrics.Registry) ClientMiddleware {
 				remainingMetric := fmt.Sprintf("%s[installation:%d]", MetricsKeyRateLimitRemaining, installationID)
 
 				// Headers from https://developer.github.com/v3/#rate-limiting
-				updateRegistryForHeader(res.Header, "X-RateLimit-Limit", metrics.GetOrRegisterGauge(limitMetric, registry))
-				updateRegistryForHeader(res.Header, "X-RateLimit-Remaining", metrics.GetOrRegisterGauge(remainingMetric, registry))
+				updateRegistryForHeader(res.Header, httpHeaderRateLimit, metrics.GetOrRegisterGauge(limitMetric, registry))
+				updateRegistryForHeader(res.Header, httpHeaderRateRemaining, metrics.GetOrRegisterGauge(remainingMetric, registry))
+				// TODO Think about to add X-Ratelimit-Used, X-Ratelimit-Reset and X-Ratelimit-Resource as well
 			}
 
 			return res, err

githubapp/middleware_logging.go

@@ -19,12 +19,21 @@ import (
 	"io"
 	"net/http"
 	"regexp"
+	"strconv"
 	"time"
 
 	"github.com/gregjones/httpcache"
 	"github.com/rs/zerolog"
 )
 
+const (
+	httpHeaderRateLimit     = "X-Ratelimit-Limit"
+	httpHeaderRateRemaining = "X-Ratelimit-Remaining"
+	httpHeaderRateUsed      = "X-Ratelimit-Used"
+	httpHeaderRateReset     = "X-Ratelimit-Reset"
+	httpHeaderRateResource  = "X-Ratelimit-Resource"
+)
+
 // ClientLogging creates client middleware that logs request and response
 // information at the given level. If the request fails without creating a
 // response, it is logged with a status code of -1. The middleware uses a
@@ -83,6 +92,7 @@ func ClientLogging(lvl zerolog.Level, opts ...ClientLoggingOption) ClientMiddlew
 					Int64("size", -1)
 			}
 
+			addRateLimitInformationToLog(options.LogRateLimitInformation, evt, res)
 			evt.Msg("github_request")
 			return res, err
 		})
@@ -95,6 +105,18 @@ type ClientLoggingOption func(*clientLoggingOptions)
 type clientLoggingOptions struct {
 	RequestBodyPatterns  []*regexp.Regexp
 	ResponseBodyPatterns []*regexp.Regexp
+
+	// Output control
+	LogRateLimitInformation *RateLimitLoggingOption
+}
+
+// RateLimitLoggingOption controls which rate limit information is logged.
+type RateLimitLoggingOption struct {
+	Limit     bool
+	Remaining bool
+	Used      bool
+	Reset     bool
+	Resource  bool
 }
 
 // LogRequestBody enables request body logging for requests to paths matching
@@ -117,6 +139,14 @@ func LogResponseBody(patterns ...string) ClientLoggingOption {
 	}
 }
 
+// LogRateLimitInformation defines which rate limit information like
+// the number of requests remaining in the current rate limit window is getting logged.
+func LogRateLimitInformation(options *RateLimitLoggingOption) ClientLoggingOption {
+	return func(opts *clientLoggingOptions) {
+		opts.LogRateLimitInformation = options
+	}
+}
+
 func mirrorRequestBody(r *http.Request) (*http.Request, []byte, error) {
 	switch {
 	case r.Body == nil || r.Body == http.NoBody:
@@ -174,3 +204,34 @@ func requestMatches(r *http.Request, pats []*regexp.Regexp) bool {
 func closeBody(b io.ReadCloser) {
 	_ = b.Close() // per http.Transport impl, ignoring close errors is fine
 }
+
+func addRateLimitInformationToLog(loggingOptions *RateLimitLoggingOption, evt *zerolog.Event, res *http.Response) {
+	// Exit early if no rate limit information is requested
+	if loggingOptions == nil {
+		return
+	}
+
+	rateLimitDict := zerolog.Dict()
+	if limitHeader := res.Header.Get(httpHeaderRateLimit); loggingOptions.Limit && limitHeader != "" {
+		limit, _ := strconv.Atoi(limitHeader)
+		rateLimitDict.Int("limit", limit)
+	}
+	if remainingHeader := res.Header.Get(httpHeaderRateRemaining); loggingOptions.Remaining && remainingHeader != "" {
+		remaining, _ := strconv.Atoi(remainingHeader)
+		rateLimitDict.Int("remaining", remaining)
+	}
+	if usedHeader := res.Header.Get(httpHeaderRateUsed); loggingOptions.Used && usedHeader != "" {
+		used, _ := strconv.Atoi(usedHeader)
+		rateLimitDict.Int("used", used)
+	}
+	if resetHeader := res.Header.Get(httpHeaderRateReset); loggingOptions.Reset && resetHeader != "" {
+		if v, _ := strconv.ParseInt(resetHeader, 10, 64); v != 0 {
+			rateLimitDict.Time("reset", time.Unix(v, 0))
+		}
+	}
+	if resourceHeader := res.Header.Get(httpHeaderRateResource); loggingOptions.Resource && resourceHeader != "" {
+		rateLimitDict.Str("resource", resourceHeader)
+	}
+
+	evt.Dict("ratelimit", rateLimitDict)
+}