From b65a26fbc52afed98dec79124ea8487d7c4343fb Mon Sep 17 00:00:00 2001 From: Andy Grunwald Date: Sat, 25 Jan 2025 21:59:53 +0100 Subject: [PATCH 1/9] Logging Middleware: Add GitHub API Rate Limiting information --- githubapp/middleware_logging.go | 55 +++++++++++++++++++++++++++++++++ 1 file changed, 55 insertions(+) diff --git a/githubapp/middleware_logging.go b/githubapp/middleware_logging.go index 8e4dfec46..422c8dcd5 100644 --- a/githubapp/middleware_logging.go +++ b/githubapp/middleware_logging.go @@ -19,12 +19,21 @@ import ( "io" "net/http" "regexp" + "strconv" "time" "github.com/gregjones/httpcache" "github.com/rs/zerolog" ) +const ( + headerRateLimit = "X-Ratelimit-Limit" + headerRateRemaining = "X-Ratelimit-Remaining" + headerRateUsed = "X-Ratelimit-Used" + headerRateReset = "X-Ratelimit-Reset" + headerRateResource = "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,10 @@ func ClientLogging(lvl zerolog.Level, opts ...ClientLoggingOption) ClientMiddlew Int64("size", -1) } + if options.LogRateLimitInformation { + addRateLimitInformationToLog(evt, res) + } + evt.Msg("github_request") return res, err }) @@ -95,6 +108,9 @@ type ClientLoggingOption func(*clientLoggingOptions) type clientLoggingOptions struct { RequestBodyPatterns []*regexp.Regexp ResponseBodyPatterns []*regexp.Regexp + + // Output control + LogRateLimitInformation bool } // LogRequestBody enables request body logging for requests to paths matching @@ -117,6 +133,22 @@ func LogResponseBody(patterns ...string) ClientLoggingOption { } } +// EnableRateLimitInformation enables logging of rate limit information like +// the number of requests remaining in the current rate limit window. +func EnableRateLimitInformation() ClientLoggingOption { + return func(opts *clientLoggingOptions) { + opts.LogRateLimitInformation = true + } +} + +// DisableRateLimitInformation disables logging of rate limit information like +// the number of requests remaining in the current rate limit window. +func DisableRateLimitInformation() ClientLoggingOption { + return func(opts *clientLoggingOptions) { + opts.LogRateLimitInformation = false + } +} + func mirrorRequestBody(r *http.Request) (*http.Request, []byte, error) { switch { case r.Body == nil || r.Body == http.NoBody: @@ -174,3 +206,26 @@ 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(evt *zerolog.Event, res *http.Response) { + if limitHeader := res.Header.Get(headerRateLimit); limitHeader != "" { + limit, _ := strconv.Atoi(limitHeader) + evt.Int("ratelimit-limit", limit) + } + if remainingHeader := res.Header.Get(headerRateRemaining); remainingHeader != "" { + remaining, _ := strconv.Atoi(remainingHeader) + evt.Int("ratelimit-remaining", remaining) + } + if usedHeader := res.Header.Get(headerRateUsed); usedHeader != "" { + used, _ := strconv.Atoi(usedHeader) + evt.Int("ratelimit-used", used) + } + if resetHeader := res.Header.Get(headerRateReset); resetHeader != "" { + if v, _ := strconv.ParseInt(resetHeader, 10, 64); v != 0 { + evt.Time("ratelimit-reset", time.Unix(v, 0)) + } + } + if resourceHeader := res.Header.Get(headerRateResource); resourceHeader != "" { + evt.Str("ratelimit-resource", resourceHeader) + } +} From 25da132bebec21efc3f18f91042a2889802aa56b Mon Sep 17 00:00:00 2001 From: Andy Grunwald Date: Mon, 27 Jan 2025 14:20:37 +0100 Subject: [PATCH 2/9] Rate Limiting Header: Rename constants from headerRate* to HTTPHeaderRate* --- githubapp/middleware_logging.go | 20 ++++++++++---------- 1 file changed, 10 insertions(+), 10 deletions(-) diff --git a/githubapp/middleware_logging.go b/githubapp/middleware_logging.go index 422c8dcd5..ce06039e1 100644 --- a/githubapp/middleware_logging.go +++ b/githubapp/middleware_logging.go @@ -27,11 +27,11 @@ import ( ) const ( - headerRateLimit = "X-Ratelimit-Limit" - headerRateRemaining = "X-Ratelimit-Remaining" - headerRateUsed = "X-Ratelimit-Used" - headerRateReset = "X-Ratelimit-Reset" - headerRateResource = "X-Ratelimit-Resource" + 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 @@ -208,24 +208,24 @@ func closeBody(b io.ReadCloser) { } func addRateLimitInformationToLog(evt *zerolog.Event, res *http.Response) { - if limitHeader := res.Header.Get(headerRateLimit); limitHeader != "" { + if limitHeader := res.Header.Get(HTTPHeaderRateLimit); limitHeader != "" { limit, _ := strconv.Atoi(limitHeader) evt.Int("ratelimit-limit", limit) } - if remainingHeader := res.Header.Get(headerRateRemaining); remainingHeader != "" { + if remainingHeader := res.Header.Get(HTTPHeaderRateRemaining); remainingHeader != "" { remaining, _ := strconv.Atoi(remainingHeader) evt.Int("ratelimit-remaining", remaining) } - if usedHeader := res.Header.Get(headerRateUsed); usedHeader != "" { + if usedHeader := res.Header.Get(HTTPHeaderRateUsed); usedHeader != "" { used, _ := strconv.Atoi(usedHeader) evt.Int("ratelimit-used", used) } - if resetHeader := res.Header.Get(headerRateReset); resetHeader != "" { + if resetHeader := res.Header.Get(HTTPHeaderRateReset); resetHeader != "" { if v, _ := strconv.ParseInt(resetHeader, 10, 64); v != 0 { evt.Time("ratelimit-reset", time.Unix(v, 0)) } } - if resourceHeader := res.Header.Get(headerRateResource); resourceHeader != "" { + if resourceHeader := res.Header.Get(HTTPHeaderRateResource); resourceHeader != "" { evt.Str("ratelimit-resource", resourceHeader) } } From 1d48f15a04486632e55694cd95474a8e8a45365a Mon Sep 17 00:00:00 2001 From: Andy Grunwald Date: Mon, 27 Jan 2025 14:22:45 +0100 Subject: [PATCH 3/9] Metrics Middleware: Use new HTTPHeaderRate* constant --- githubapp/middleware.go | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/githubapp/middleware.go b/githubapp/middleware.go index ec11fbc14..06ac7b19d 100644 --- a/githubapp/middleware.go +++ b/githubapp/middleware.go @@ -75,8 +75,8 @@ 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)) } return res, err From d07099e3b80025439ee93c37342fcb6777d94c51 Mon Sep 17 00:00:00 2001 From: Andy Grunwald Date: Mon, 27 Jan 2025 14:30:05 +0100 Subject: [PATCH 4/9] Metrics Middleware: Add TODO about missing metrics --- githubapp/middleware.go | 1 + 1 file changed, 1 insertion(+) diff --git a/githubapp/middleware.go b/githubapp/middleware.go index 06ac7b19d..6cafc98b8 100644 --- a/githubapp/middleware.go +++ b/githubapp/middleware.go @@ -77,6 +77,7 @@ func ClientMetrics(registry metrics.Registry) ClientMiddleware { // Headers from https://developer.github.com/v3/#rate-limiting 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 From afdd35b9a302da10d487a93a87ac95044a021020 Mon Sep 17 00:00:00 2001 From: Andy Grunwald Date: Mon, 27 Jan 2025 14:55:20 +0100 Subject: [PATCH 5/9] Logging Middleware: Make Rate limit logging options configurable --- githubapp/middleware_logging.go | 44 ++++++++++++++++----------------- 1 file changed, 21 insertions(+), 23 deletions(-) diff --git a/githubapp/middleware_logging.go b/githubapp/middleware_logging.go index ce06039e1..0766be054 100644 --- a/githubapp/middleware_logging.go +++ b/githubapp/middleware_logging.go @@ -92,10 +92,7 @@ func ClientLogging(lvl zerolog.Level, opts ...ClientLoggingOption) ClientMiddlew Int64("size", -1) } - if options.LogRateLimitInformation { - addRateLimitInformationToLog(evt, res) - } - + addRateLimitInformationToLog(options.LogRateLimitInformation, evt, res) evt.Msg("github_request") return res, err }) @@ -110,7 +107,16 @@ type clientLoggingOptions struct { ResponseBodyPatterns []*regexp.Regexp // Output control - LogRateLimitInformation bool + 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 @@ -133,19 +139,11 @@ func LogResponseBody(patterns ...string) ClientLoggingOption { } } -// EnableRateLimitInformation enables logging of rate limit information like -// the number of requests remaining in the current rate limit window. -func EnableRateLimitInformation() ClientLoggingOption { - return func(opts *clientLoggingOptions) { - opts.LogRateLimitInformation = true - } -} - -// DisableRateLimitInformation disables logging of rate limit information like -// the number of requests remaining in the current rate limit window. -func DisableRateLimitInformation() ClientLoggingOption { +// SetRateLimitInformation defines which rate limit information like +// the number of requests remaining in the current rate limit window is getting logged. +func SetRateLimitInformation(options *RateLimitLoggingOption) ClientLoggingOption { return func(opts *clientLoggingOptions) { - opts.LogRateLimitInformation = false + opts.LogRateLimitInformation = options } } @@ -207,25 +205,25 @@ func closeBody(b io.ReadCloser) { _ = b.Close() // per http.Transport impl, ignoring close errors is fine } -func addRateLimitInformationToLog(evt *zerolog.Event, res *http.Response) { - if limitHeader := res.Header.Get(HTTPHeaderRateLimit); limitHeader != "" { +func addRateLimitInformationToLog(loggingOptions *RateLimitLoggingOption, evt *zerolog.Event, res *http.Response) { + if limitHeader := res.Header.Get(HTTPHeaderRateLimit); loggingOptions.Limit && limitHeader != "" { limit, _ := strconv.Atoi(limitHeader) evt.Int("ratelimit-limit", limit) } - if remainingHeader := res.Header.Get(HTTPHeaderRateRemaining); remainingHeader != "" { + if remainingHeader := res.Header.Get(HTTPHeaderRateRemaining); loggingOptions.Remaining && remainingHeader != "" { remaining, _ := strconv.Atoi(remainingHeader) evt.Int("ratelimit-remaining", remaining) } - if usedHeader := res.Header.Get(HTTPHeaderRateUsed); usedHeader != "" { + if usedHeader := res.Header.Get(HTTPHeaderRateUsed); loggingOptions.Used && usedHeader != "" { used, _ := strconv.Atoi(usedHeader) evt.Int("ratelimit-used", used) } - if resetHeader := res.Header.Get(HTTPHeaderRateReset); resetHeader != "" { + if resetHeader := res.Header.Get(HTTPHeaderRateReset); loggingOptions.Reset && resetHeader != "" { if v, _ := strconv.ParseInt(resetHeader, 10, 64); v != 0 { evt.Time("ratelimit-reset", time.Unix(v, 0)) } } - if resourceHeader := res.Header.Get(HTTPHeaderRateResource); resourceHeader != "" { + if resourceHeader := res.Header.Get(HTTPHeaderRateResource); loggingOptions.Resource && resourceHeader != "" { evt.Str("ratelimit-resource", resourceHeader) } } From 74b6344966e743226b495271824618974cd770ee Mon Sep 17 00:00:00 2001 From: Andy Grunwald Date: Tue, 4 Feb 2025 08:15:21 +0100 Subject: [PATCH 6/9] Renamed `SetRateLimitInformation` to `LogRateLimitInformation` --- githubapp/middleware_logging.go | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/githubapp/middleware_logging.go b/githubapp/middleware_logging.go index 0766be054..20d76dc09 100644 --- a/githubapp/middleware_logging.go +++ b/githubapp/middleware_logging.go @@ -139,9 +139,9 @@ func LogResponseBody(patterns ...string) ClientLoggingOption { } } -// SetRateLimitInformation defines which rate limit information like +// LogRateLimitInformation defines which rate limit information like // the number of requests remaining in the current rate limit window is getting logged. -func SetRateLimitInformation(options *RateLimitLoggingOption) ClientLoggingOption { +func LogRateLimitInformation(options *RateLimitLoggingOption) ClientLoggingOption { return func(opts *clientLoggingOptions) { opts.LogRateLimitInformation = options } From 69c805bd707e57d96f914248576ccfa1df13c63b Mon Sep 17 00:00:00 2001 From: Andy Grunwald Date: Tue, 4 Feb 2025 08:17:41 +0100 Subject: [PATCH 7/9] Renamed `HTTPHeaderRate*` to `httpHeaderRate*` to keep them package internal --- githubapp/middleware.go | 4 ++-- githubapp/middleware_logging.go | 20 ++++++++++---------- 2 files changed, 12 insertions(+), 12 deletions(-) diff --git a/githubapp/middleware.go b/githubapp/middleware.go index 6cafc98b8..1382bc5d1 100644 --- a/githubapp/middleware.go +++ b/githubapp/middleware.go @@ -75,8 +75,8 @@ 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, HTTPHeaderRateLimit, metrics.GetOrRegisterGauge(limitMetric, registry)) - updateRegistryForHeader(res.Header, HTTPHeaderRateRemaining, 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 } diff --git a/githubapp/middleware_logging.go b/githubapp/middleware_logging.go index 20d76dc09..5ad3e9467 100644 --- a/githubapp/middleware_logging.go +++ b/githubapp/middleware_logging.go @@ -27,11 +27,11 @@ import ( ) const ( - HTTPHeaderRateLimit = "X-Ratelimit-Limit" - HTTPHeaderRateRemaining = "X-Ratelimit-Remaining" - HTTPHeaderRateUsed = "X-Ratelimit-Used" - HTTPHeaderRateReset = "X-Ratelimit-Reset" - HTTPHeaderRateResource = "X-Ratelimit-Resource" + 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 @@ -206,24 +206,24 @@ func closeBody(b io.ReadCloser) { } func addRateLimitInformationToLog(loggingOptions *RateLimitLoggingOption, evt *zerolog.Event, res *http.Response) { - if limitHeader := res.Header.Get(HTTPHeaderRateLimit); loggingOptions.Limit && limitHeader != "" { + if limitHeader := res.Header.Get(httpHeaderRateLimit); loggingOptions.Limit && limitHeader != "" { limit, _ := strconv.Atoi(limitHeader) evt.Int("ratelimit-limit", limit) } - if remainingHeader := res.Header.Get(HTTPHeaderRateRemaining); loggingOptions.Remaining && remainingHeader != "" { + if remainingHeader := res.Header.Get(httpHeaderRateRemaining); loggingOptions.Remaining && remainingHeader != "" { remaining, _ := strconv.Atoi(remainingHeader) evt.Int("ratelimit-remaining", remaining) } - if usedHeader := res.Header.Get(HTTPHeaderRateUsed); loggingOptions.Used && usedHeader != "" { + if usedHeader := res.Header.Get(httpHeaderRateUsed); loggingOptions.Used && usedHeader != "" { used, _ := strconv.Atoi(usedHeader) evt.Int("ratelimit-used", used) } - if resetHeader := res.Header.Get(HTTPHeaderRateReset); loggingOptions.Reset && resetHeader != "" { + if resetHeader := res.Header.Get(httpHeaderRateReset); loggingOptions.Reset && resetHeader != "" { if v, _ := strconv.ParseInt(resetHeader, 10, 64); v != 0 { evt.Time("ratelimit-reset", time.Unix(v, 0)) } } - if resourceHeader := res.Header.Get(HTTPHeaderRateResource); loggingOptions.Resource && resourceHeader != "" { + if resourceHeader := res.Header.Get(httpHeaderRateResource); loggingOptions.Resource && resourceHeader != "" { evt.Str("ratelimit-resource", resourceHeader) } } From 190651e912542c121bb326cccaef87bcacfa555e Mon Sep 17 00:00:00 2001 From: Andy Grunwald Date: Tue, 4 Feb 2025 08:37:45 +0100 Subject: [PATCH 8/9] TestClientLogging/requestBody: Fix "panic: runtime error: invalid memory address or nil pointer dereference [recovered]" --- githubapp/middleware_logging.go | 5 +++++ 1 file changed, 5 insertions(+) diff --git a/githubapp/middleware_logging.go b/githubapp/middleware_logging.go index 5ad3e9467..e9bae40fc 100644 --- a/githubapp/middleware_logging.go +++ b/githubapp/middleware_logging.go @@ -206,6 +206,11 @@ func closeBody(b io.ReadCloser) { } func addRateLimitInformationToLog(loggingOptions *RateLimitLoggingOption, evt *zerolog.Event, res *http.Response) { + // Exit early if no rate limit information is requested + if loggingOptions == nil { + return + } + if limitHeader := res.Header.Get(httpHeaderRateLimit); loggingOptions.Limit && limitHeader != "" { limit, _ := strconv.Atoi(limitHeader) evt.Int("ratelimit-limit", limit) From 1913140480a9c599cfc0b1238dd9495f643a0b97 Mon Sep 17 00:00:00 2001 From: Andy Grunwald Date: Tue, 4 Feb 2025 08:44:13 +0100 Subject: [PATCH 9/9] Switch ratelimit information to `zerolog.Dict()` --- githubapp/middleware_logging.go | 13 ++++++++----- 1 file changed, 8 insertions(+), 5 deletions(-) diff --git a/githubapp/middleware_logging.go b/githubapp/middleware_logging.go index e9bae40fc..f33882a19 100644 --- a/githubapp/middleware_logging.go +++ b/githubapp/middleware_logging.go @@ -211,24 +211,27 @@ func addRateLimitInformationToLog(loggingOptions *RateLimitLoggingOption, evt *z return } + rateLimitDict := zerolog.Dict() if limitHeader := res.Header.Get(httpHeaderRateLimit); loggingOptions.Limit && limitHeader != "" { limit, _ := strconv.Atoi(limitHeader) - evt.Int("ratelimit-limit", limit) + rateLimitDict.Int("limit", limit) } if remainingHeader := res.Header.Get(httpHeaderRateRemaining); loggingOptions.Remaining && remainingHeader != "" { remaining, _ := strconv.Atoi(remainingHeader) - evt.Int("ratelimit-remaining", remaining) + rateLimitDict.Int("remaining", remaining) } if usedHeader := res.Header.Get(httpHeaderRateUsed); loggingOptions.Used && usedHeader != "" { used, _ := strconv.Atoi(usedHeader) - evt.Int("ratelimit-used", used) + rateLimitDict.Int("used", used) } if resetHeader := res.Header.Get(httpHeaderRateReset); loggingOptions.Reset && resetHeader != "" { if v, _ := strconv.ParseInt(resetHeader, 10, 64); v != 0 { - evt.Time("ratelimit-reset", time.Unix(v, 0)) + rateLimitDict.Time("reset", time.Unix(v, 0)) } } if resourceHeader := res.Header.Get(httpHeaderRateResource); loggingOptions.Resource && resourceHeader != "" { - evt.Str("ratelimit-resource", resourceHeader) + rateLimitDict.Str("resource", resourceHeader) } + + evt.Dict("ratelimit", rateLimitDict) }