[WIP] Creating simple faketime package for time.Sleep mocking

legacy/faketime/faketime.go

@@ -0,0 +1,57 @@
+/*
+Copyright 2021 The Kubernetes Authors.
+Licensed under the Apache License, Version 2.0 (the "License");
+you may not use this file except in compliance with the License.
+You may obtain a copy of the License at
+    http://www.apache.org/licenses/LICENSE-2.0
+Unless required by applicable law or agreed to in writing, software
+distributed under the License is distributed on an "AS IS" BASIS,
+WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+See the License for the specific language governing permissions and
+limitations under the License.
+*/
+
+package faketime
+
+import (
+	"fmt"
+	"sync/atomic"
+	"time"
+)
+
+type Time interface {
+	Now() time.Time
+	Sleep(d time.Duration)
+}
+
+type RealTime struct{}
+
+func (RealTime) Now() time.Time        { return time.Now() }
+func (RealTime) Sleep(d time.Duration) { time.Sleep(d) }
+
+type FakeTime struct {
+	time int64 // The current global time measured in Nanoseconds.
+}
+
+// Advance adds the given duration to the global time.
+func (ft *FakeTime) Advance(d time.Duration) {
+	atomic.StoreInt64(&ft.time, d.Nanoseconds())
+}
+
+// Now returns the current global time.
+func (ft *FakeTime) Now() time.Time {
+	return time.Unix(0, ft.time)
+}
+
+// Sleep until the global time has met or exceeded the given duration.
+func (ft *FakeTime) Sleep(d time.Duration) {
+	fmt.Println("sleeping...")
+	// Determine when to the goroutine should unblock.
+	until := atomic.LoadInt64(&ft.time) + d.Nanoseconds()
+	// Repeatedly check the global time,.
+	for {
+		if atomic.LoadInt64(&ft.time) >= until {
+			return
+		}
+	}
+}

legacy/reqcounter/reqcounter.go

@@ -22,6 +22,7 @@ import (
 	"time"
 
 	"github.com/sirupsen/logrus"
+	ft "sigs.k8s.io/k8s-container-image-promoter/legacy/faketime"
 )
 
 // RequestCounter records the number of HTTP requests to GCR.
@@ -48,7 +49,7 @@ func (rc *RequestCounter) Flush() {
 	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), time.Now().Format(timestampFormat), rc.Interval/time.Minute, rc.Requests)
+	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)
 
 	// Reset the request counter.
@@ -60,14 +61,14 @@ func (rc *RequestCounter) Flush() {
 // if it must be reset.
 func (rc *RequestCounter) reset() {
 	rc.Requests = 0
-	rc.Since = time.Now()
+	rc.Since = Clock.Now()
 }
 
 // watch continuously logs the request counter at the specified intervals.
 func (rc *RequestCounter) watch() {
 	go func() {
 		for {
-			Sleep(rc.Interval)
+			Clock.Sleep(rc.Interval)
 			rc.Flush()
 		}
 	}()
@@ -104,8 +105,8 @@ const (
 	// requests counters to perfectly line up with the actual GCR quota.
 	// Source: https://cloud.google.com/container-registry/quotas
 	MeasurementWindow time.Duration = time.Minute * 10
-	// timestampFormat specifies the syntax for logging time stamps of request counters.
-	timestampFormat string = "2006-01-02 15:04:05"
+	// TimestampFormat specifies the syntax for logging time stamps of request counters.
+	TimestampFormat string = "2006-01-02 15:04:05"
 )
 
 var (
@@ -116,8 +117,8 @@ var (
 	NetMonitor *NetworkMonitor
 	// Debug is defined to simplify testing of logrus.Debug calls.
 	Debug func(args ...interface{}) = logrus.Debug
-	// Sleep is defined to allow mocking of the time.Sleep function in tests.
-	Sleep func(d time.Duration) = time.Sleep
+	// Clock is defined to allow mocking of the time functions.
+	Clock ft.Time = ft.RealTime{}
 )
 
 // Init allows request counting to begin.
@@ -129,7 +130,7 @@ func Init() {
 	requestCounter := &RequestCounter{
 		Mutex:    sync.Mutex{},
 		Requests: 0,
-		Since:    time.Now(),
+		Since:    Clock.Now(),
 		Interval: MeasurementWindow,
 	}
 

legacy/reqcounter/reqcounter_test.go

@@ -17,11 +17,13 @@ limitations under the License.
 package reqcounter_test
 
 import (
+	"fmt"
 	"sync"
 	"testing"
 	"time"
 
 	"github.com/stretchr/testify/require"
+	ft "sigs.k8s.io/k8s-container-image-promoter/legacy/faketime"
 	rc "sigs.k8s.io/k8s-container-image-promoter/legacy/reqcounter"
 )
 
@@ -124,3 +126,48 @@ func TestRequestCounterIncrement(t *testing.T) {
 	// Ensure the request counter was incremented.
 	require.EqualValues(t, &expected, &requestCounter, "The request counter failed to increment its request field.")
 }
+
+func TestLog(t *testing.T) {
+	// Create multiple request counters with unique intervals.
+	requestCounters := []rc.RequestCounter{
+		NewRequestCounter(0),
+		NewRequestCounter(9),
+		NewRequestCounter(2839),
+	}
+	requestCounters[0].Interval = time.Second * 2
+	requestCounters[1].Interval = time.Second
+	requestCounters[2].Interval = time.Hour
+	// Load request counters into network monitor.
+	netMonitor := &rc.NetworkMonitor{
+		RequestCounters: rc.RequestCounters{
+			&requestCounters[0],
+			&requestCounters[1],
+			&requestCounters[2],
+		},
+	}
+	// Mock the Debug function, capturing each statement.
+	logged := []string{}
+	rc.Debug = func(args ...interface{}) {
+		logged = append(logged, fmt.Sprint(args[0]))
+	}
+	// Mock the global clock with fake time.
+	fakeTime := &ft.FakeTime{}
+	timeStep := time.Second * 2
+	rc.Clock = fakeTime
+	// Create expected logging messages.
+	start, end := time.Unix(0, 0), time.Unix(0, timeStep.Nanoseconds())
+	expected := []string{
+		fmt.Sprintf("From %s to %s [%d min] there have been %d requests to GCR.", start.Format(rc.TimestampFormat), end.Format(rc.TimestampFormat), requestCounters[1].Interval/time.Minute, requestCounters[1].Requests),
+		fmt.Sprintf("From %s to %s [%d min] there have been %d requests to GCR.", start.Format(rc.TimestampFormat), end.Format(rc.TimestampFormat), requestCounters[1].Interval/time.Minute, requestCounters[1].Requests),
+		fmt.Sprintf("From %s to %s [%d min] there have been %d requests to GCR.", start.Format(rc.TimestampFormat), end.Format(rc.TimestampFormat), requestCounters[0].Interval/time.Minute, requestCounters[0].Requests),
+	}
+	// Log all request counters.
+	netMonitor.Log()
+	// Move fake time forward.
+	fakeTime.Advance(timeStep)
+
+	time.Sleep(time.Second) // *********** COMMENT ME OUT
+
+	// Ensure the correct counters have been logged.
+	require.EqualValues(t, expected, logged, "The correct request counters did not log correctly.")
+}