From c1bfc387a61cdc9e6c35bcc9c07e3b93e7c34f43 Mon Sep 17 00:00:00 2001 From: Tyler Date: Fri, 30 Jul 2021 16:55:29 -0400 Subject: [PATCH] Log warning when request counters exceed a threshold --- legacy/reqcounter/reqcounter.go | 61 +++++++++++++--------- legacy/reqcounter/reqcounter_test.go | 78 +++++++++++++++++----------- 2 files changed, 85 insertions(+), 54 deletions(-) diff --git a/legacy/reqcounter/reqcounter.go b/legacy/reqcounter/reqcounter.go index d76ff50f..5d0350b0 100644 --- a/legacy/reqcounter/reqcounter.go +++ b/legacy/reqcounter/reqcounter.go @@ -27,11 +27,13 @@ import ( // RequestCounter records the number of HTTP requests to GCR. type RequestCounter struct { - Mutex sync.Mutex // Lock to prevent race-conditions with concurrent processes. - Requests uint64 // Number of HTTP requests since recording started. - Since time.Time // When the current request counter began recording requests. - Interval time.Duration // The duration of time between each log. - Resettable bool // Reset after logging. + Mutex sync.Mutex // Lock to prevent race-conditions with concurrent processes. + Requests uint64 // Number of HTTP requests since recording started. + Since time.Time // When the current request counter began recording requests. + Interval time.Duration // The duration of time between each log. + Threshold uint64 // When to warn of a high request count during a logging cycle. Setting a + // non-zero threshold allows the request counter to reset each interval. Therefore, if left uninitialized, + // the request counter will be persistent and never warn or reset. } // increment adds 1 to the request counter, signifying another call to GCR. @@ -47,16 +49,26 @@ func (rc *RequestCounter) Flush() { rc.Mutex.Lock() defer rc.Mutex.Unlock() - // Log the number of requests within this measurement window. - msg := fmt.Sprintf("From %s to %s [%d min] there have been %d requests to GCR.", rc.Since.Format(TimestampFormat), Clock.Now().Format(TimestampFormat), rc.Interval/time.Minute, rc.Requests) - Debug(msg) + rc.log() - if rc.Resettable { + // Only allow request counters wi + if rc.Threshold > 0 { // Reset the request counter. rc.reset() } } +// log the number of HTTP requests found. If the number of requests exceeds the +// threshold, log an additional warning message. +func (rc *RequestCounter) log() { + msg := fmt.Sprintf("From %s to %s [%d min] there have been %d requests to GCR.", rc.Since.Format(TimestampFormat), Clock.Now().Format(TimestampFormat), rc.Interval/time.Minute, rc.Requests) + Debug(msg) + if rc.Threshold > 0 && rc.Requests > rc.Threshold { + msg = fmt.Sprintf("The threshold of %d requests has been surpassed.", rc.Threshold) + Warn(msg) + } +} + // reset clears the request counter and stamps the current time of reset. func (rc *RequestCounter) reset() { rc.Requests = 0 @@ -124,6 +136,8 @@ var ( NetMonitor *NetworkMonitor // Debug is defined to simplify testing of logrus.Debug calls. Debug func(args ...interface{}) = logrus.Debug + // Warn is defined to simplify testing of logrus.Warn calls. + Warn func(args ...interface{}) = logrus.Warn // Clock is defined to allow mocking of time functions. Clock tw.Time = tw.RealTime{} ) @@ -136,25 +150,24 @@ func Init() { // GCR quota, but acts as a rough estimation of this quota, indicating when throttling may occur. requestCounters := RequestCounters{ { - Mutex: sync.Mutex{}, - Requests: 0, - Since: Clock.Now(), - Interval: QuotaWindowShort, - Resettable: true, + Mutex: sync.Mutex{}, + Requests: 0, + Since: Clock.Now(), + Interval: QuotaWindowShort, + Threshold: 50000, }, { - Mutex: sync.Mutex{}, - Requests: 0, - Since: Clock.Now(), - Interval: QuotaWindowLong, - Resettable: true, + Mutex: sync.Mutex{}, + Requests: 0, + Since: Clock.Now(), + Interval: QuotaWindowLong, + Threshold: 1000000, }, { - Mutex: sync.Mutex{}, - Requests: 0, - Since: Clock.Now(), - Interval: QuotaWindowShort, - Resettable: false, + Mutex: sync.Mutex{}, + Requests: 0, + Since: Clock.Now(), + Interval: QuotaWindowShort, }, } diff --git a/legacy/reqcounter/reqcounter_test.go b/legacy/reqcounter/reqcounter_test.go index cbd23067..90a4d9b7 100644 --- a/legacy/reqcounter/reqcounter_test.go +++ b/legacy/reqcounter/reqcounter_test.go @@ -27,6 +27,9 @@ import ( tw "sigs.k8s.io/k8s-container-image-promoter/legacy/timewrapper" ) +// defaultThreshold should be used as a default request counter threshold. +const defaultThreshold = 10000 + // defaultTime should be used as a timestamp for all request counters. // The actual time represents: September 22, 2002 at 05:03:16. var defaultTime, _ = time.Parse("020106 150405", "020106 150405") @@ -35,11 +38,11 @@ var defaultTime, _ = time.Parse("020106 150405", "020106 150405") // All other object fields are set to default values. func NewRequestCounter(requests uint64) rc.RequestCounter { return rc.RequestCounter{ - Mutex: sync.Mutex{}, - Requests: requests, - Since: defaultTime, - Interval: time.Second, - Resettable: true, + Mutex: sync.Mutex{}, + Requests: requests, + Since: defaultTime, + Interval: time.Second, + Threshold: defaultThreshold, } } @@ -118,13 +121,28 @@ func TestFlush(t *testing.T) { require.Equal(t, uint64(0), requestCounter.Requests, "Calling Flush() did not reset the request counter to 0.") require.True(t, defaultTime.Before(requestCounter.Since), "Calling Flush() did not reset the request counter timestamp.") - // Create a non-resettable request counter. + // Create a persistent request counter. requestCounter = NewRequestCounter(66) - requestCounter.Resettable = false + requestCounter.Threshold = 0 requestCounter.Flush() // Ensure the request counter did not reset. require.Equal(t, uint64(66), requestCounter.Requests, "Calling Flush() reset the requests of a non-resettable request counter.") require.True(t, defaultTime.Equal(requestCounter.Since), "Calling Flush() reset the timestamp of a non-resettable request counter.") + + // Create a request counter that exceeded a threshold. + requestCounter = NewRequestCounter(600) + requestCounter.Threshold = 599 + // Reset debug counter. + debugCalls = 0 + // Mock logrus.Warn. + warnCalls := 0 + rc.Warn = func(args ...interface{}) { + warnCalls++ + } + requestCounter.Flush() + // Ensure both logrus.Debug and logrus.Warn was called. + require.Equal(t, 1, debugCalls, "Flush() failed to trigger a debug statement after exceeding the threshold.") + require.Equal(t, 1, warnCalls, "Flush() failed to trigger a warning statement after exceeding the threshold.") } func TestRequestCounterIncrement(t *testing.T) { @@ -141,41 +159,41 @@ func TestRequestCounterIncrement(t *testing.T) { func TestCycle(t *testing.T) { // Define the variables of each test. type cycleTest struct { - interval time.Duration // Specify logging interval. - requests []int // The number of HTTP request to simulate for each cycle. - resettable bool // Reset after logging. + interval time.Duration // Specify logging interval. + requests []int // The number of HTTP request to simulate for each cycle. + threshold uint64 // When to fire a warning log. } // Define all tests. cycleTests := []cycleTest{ { - interval: rc.QuotaWindowShort, - requests: []int{3, 7, 50, 1}, - resettable: true, + interval: rc.QuotaWindowShort, + requests: []int{3, 7, 50, 1}, + threshold: defaultThreshold, }, { - interval: rc.QuotaWindowLong, - requests: []int{2, 622, 5, 8}, - resettable: true, + interval: rc.QuotaWindowLong, + requests: []int{2, 622, 5, 8}, + threshold: defaultThreshold, }, { - interval: time.Second, - requests: []int{9, 0, 13, 700}, - resettable: true, + interval: time.Second, + requests: []int{9, 0, 13, 700}, + threshold: defaultThreshold, }, { - interval: time.Minute * 30, - requests: []int{9, 0, 13, 700}, - resettable: true, + interval: time.Minute * 30, + requests: []int{9, 0, 13, 700}, + threshold: defaultThreshold, }, { - interval: time.Hour * 10, - requests: []int{9, 0, 13, 700}, - resettable: true, + interval: time.Hour * 10, + requests: []int{9, 0, 13, 700}, + threshold: defaultThreshold, }, { - interval: time.Hour * 10, - requests: []int{9, 0, 13, 700}, - resettable: false, + interval: time.Hour * 10, + requests: []int{9, 0, 13, 700}, + threshold: 0, }, } // Simulate HTTP requests by repeatedly incrementing the request counter. @@ -191,7 +209,7 @@ func TestCycle(t *testing.T) { // Create a simple request counter. requestCounter := NewRequestCounter(0) requestCounter.Interval = ct.interval - requestCounter.Resettable = ct.resettable + requestCounter.Threshold = ct.threshold // Collect logging statements. logs := []string{} // Mock logrus.Debug calls. @@ -213,7 +231,7 @@ func TestCycle(t *testing.T) { nextClock := testClock.Add(ct.interval) expectedRequests := requests expectedStartingClock := testClock - if !ct.resettable { + if ct.threshold == 0 { // Record a running tally. totalRequests += requests expectedRequests = totalRequests