lint: fixed vet-time-inject and replaced with forbidigo linter (#848)

added faketime.NewClockTimeWithOffset and used that to fix flaky
'TestDeleteUnreferencedBlobs' test.

.golangci.yml

@@ -4,6 +4,11 @@ linters-settings:
   funlen:
     lines: 100
     statements: 60
+  forbidigo:
+    forbid:
+    - time.Now # use clock.Now
+    - time.Since # use clock.Since
+    - time.Until # use clock.Until
   gocognit:
     min-complexity: 40
   gocyclo:
@@ -59,9 +64,6 @@ run:
 issues:
   exclude-use-default: false
   exclude-rules:
-    - path: cli
-      linters:
-      - forbidigo # allow fmt.Printf in the CLI
     - path: _test\.go|testing|tests|test_env|fshasher
       linters:
       - gomnd
@@ -71,7 +73,6 @@ issues:
       - gosec
       - nestif
       - wrapcheck
-      - forbidigo
       - nolintlint
     - text: "Magic number: 1e"
       linters:

Makefile

@@ -60,14 +60,7 @@ lint-and-log: $(linter)
 	$(linter) --deadline $(LINTER_DEADLINE) run $(linter_flags) | tee .linterr.txt
 
 
-vet-time-inject:
-ifneq ($(TRAVIS_OS_NAME),windows)
-	! find . -name '*.go' \
-	-exec grep -n -e time.Now -e time.Since -e time.Until {} + \
-	grep -v src/golang.org | grep -v -e allow:no-inject-time
-endif
-
-vet: vet-time-inject
+vet:
 	go vet -all .
 
 go-modules:

internal/clock/now_prod.go

@@ -6,5 +6,5 @@
 
 // Now returns current wall clock time.
 func Now() time.Time {
-	return time.Now() // allow:no-inject-time
+	return time.Now() // nolint:forbidigo
 }

internal/clock/now_testing.go

@@ -14,7 +14,7 @@
 const refreshServerTimeEvery = 3 * time.Second
 
 // Now is overridable function that returns current wall clock time.
-var Now = time.Now // allow:no-inject-time
+var Now = time.Now // nolint:forbidigo
 
 func init() {
 	fakeTimeServer := os.Getenv("KOPIA_FAKE_CLOCK_ENDPOINT")
@@ -40,13 +40,13 @@ func getTimeFromServer(endpoint string) func() time.Time {
 		Until int64 `json:"until"`
 	}
 
-	nextRefreshRealTime := time.Now() // allow:no-inject-time
+	nextRefreshRealTime := time.Now() // nolint:forbidigo
 
 	return func() time.Time {
 		mu.Lock()
 		defer mu.Unlock()
 
-		if timeInfo.Next >= timeInfo.Until || time.Now().After(nextRefreshRealTime) { // allow:no-inject-time
+		if timeInfo.Next >= timeInfo.Until || time.Now().After(nextRefreshRealTime) { // nolint:forbidigo
 			resp, err := http.Get(endpoint) //nolint:gosec,noctx
 			if err != nil {
 				log.Fatalf("unable to get fake time from server: %v", err)
@@ -61,7 +61,7 @@ func getTimeFromServer(endpoint string) func() time.Time {
 				log.Fatalf("invalid time received from fake time server: %v", err)
 			}
 
-			nextRefreshRealTime = time.Now().Add(refreshServerTimeEvery) // allow:no-inject-time
+			nextRefreshRealTime = time.Now().Add(refreshServerTimeEvery) // nolint:forbidigo
 		}
 
 		v := timeInfo.Next

internal/editor/editor.go

@@ -51,7 +51,7 @@ func EditLoop(ctx context.Context, fname, initial string, parse func(updated str
 		}
 
 		log(ctx).Errorf("%v", err)
-		fmt.Print("Reopen editor to fix? (Y/n) ") //nolint:forbidigo
+		fmt.Print("Reopen editor to fix? (Y/n) ")
 
 		var shouldReopen string
 

internal/faketime/faketime.go

@@ -4,6 +4,8 @@
 import (
 	"sync/atomic"
 	"time"
+
+	"github.com/kopia/kopia/internal/clock"
 )
 
 // Frozen returns a function that always returns t.
@@ -53,3 +55,28 @@ func (t *TimeAdvance) Advance(dt time.Duration) time.Time {
 
 	return t.base.Add(time.Duration(advance))
 }
+
+// ClockTimeWithOffset allows controlling the passage of time. Intended to be used in
+// tests.
+type ClockTimeWithOffset struct {
+	offset time.Duration
+}
+
+// NewClockTimeWithOffset creates a ClockTimeWithOffset with the given start time.
+func NewClockTimeWithOffset(offset time.Duration) *ClockTimeWithOffset {
+	return &ClockTimeWithOffset{}
+}
+
+// NowFunc returns a time provider function for t.
+func (t *ClockTimeWithOffset) NowFunc() func() time.Time {
+	return func() time.Time {
+		return clock.Now().Add(t.offset)
+	}
+}
+
+// Advance advances t by dt, such that the next call to t.NowFunc()() returns
+// current t + dt.
+func (t *ClockTimeWithOffset) Advance(dt time.Duration) time.Time {
+	t.offset += dt
+	return clock.Now().Add(t.offset)
+}

repo/blob/retrying/retrying_storage_test.go

@@ -2,11 +2,11 @@
 
 import (
 	"testing"
-	"time"
 
 	"github.com/pkg/errors"
 
 	"github.com/kopia/kopia/internal/blobtesting"
+	"github.com/kopia/kopia/internal/clock"
 	"github.com/kopia/kopia/internal/gather"
 	"github.com/kopia/kopia/internal/testlogging"
 	"github.com/kopia/kopia/repo/blob"
@@ -47,7 +47,7 @@ func TestRetrying(t *testing.T) {
 
 	must(t, rs.PutBlob(ctx, blobID2, gather.FromSlice([]byte{1, 2, 3, 4})))
 
-	must(t, rs.SetTime(ctx, blobID, time.Now()))
+	must(t, rs.SetTime(ctx, blobID, clock.Now()))
 
 	_, err := rs.GetBlob(ctx, blobID, 0, -1)
 	must(t, err)

repo/blob/s3/s3_storage_test.go

@@ -189,7 +189,7 @@ func TestInvalidCredsFailsFast(t *testing.T) {
 
 	ctx := testlogging.Context(t)
 
-	t0 := time.Now()
+	t0 := clock.Now()
 
 	if _, err := New(ctx, &Options{
 		Endpoint:        minioEndpoint,
@@ -203,7 +203,7 @@ func TestInvalidCredsFailsFast(t *testing.T) {
 		t.Fatalf("unexpected success with bad credentials")
 	}
 
-	if dt := time.Since(t0); dt > 10*time.Second {
+	if dt := clock.Since(t0); dt > 10*time.Second {
 		t.Fatalf("opening storage took too long, probably due to retries")
 	}
 }

repo/blob/sftp/sftp_storage_test.go

@@ -17,6 +17,7 @@
 	"github.com/pkg/errors"
 
 	"github.com/kopia/kopia/internal/blobtesting"
+	"github.com/kopia/kopia/internal/clock"
 	"github.com/kopia/kopia/internal/testlogging"
 	"github.com/kopia/kopia/internal/testutil"
 	"github.com/kopia/kopia/repo/blob"
@@ -103,8 +104,8 @@ func startDockerSFTPServerOrSkip(t *testing.T, idRSA string) (host string, port
 	sftpEndpoint := testutil.GetContainerMappedPortAddress(t, shortContainerID, "22")
 
 	// wait for SFTP server to come up.
-	deadline := time.Now().Add(dialTimeout)
-	for time.Now().Before(deadline) {
+	deadline := clock.Now().Add(dialTimeout)
+	for clock.Now().Before(deadline) {
 		t.Logf("waiting for SFTP server to come up on '%v'...", sftpEndpoint)
 
 		conn, err := net.DialTimeout("tcp", sftpEndpoint, time.Second)
@@ -206,13 +207,13 @@ func TestInvalidServerFailsFast(t *testing.T) {
 	mustRunCommand(t, "ssh-keygen", "-t", "rsa", "-P", "", "-f", idRSA)
 	ioutil.WriteFile(knownHostsFile, nil, 0600)
 
-	t0 := time.Now()
+	t0 := clock.Now()
 
 	if _, err := createSFTPStorage(ctx, t, "no-such-host", 22, idRSA, knownHostsFile, false); err == nil {
 		t.Fatalf("unexpected success with bad credentials")
 	}
 
-	if dt := time.Since(t0); dt > 10*time.Second {
+	if dt := clock.Since(t0); dt > 10*time.Second {
 		t.Fatalf("opening storage took too long, probably due to retries")
 	}
 }

repo/maintenance/blob_gc.go

@@ -92,7 +92,7 @@ func DeleteUnreferencedBlobs(ctx context.Context, rep repo.DirectRepositoryWrite
 	// belong to alive sessions.
 	if err := rep.ContentManager().IterateUnreferencedBlobs(ctx, prefixes, opt.Parallel, func(bm blob.Metadata) error {
 		if age := rep.Time().Sub(bm.Timestamp); age < opt.MinAge {
-			log(ctx).Debugf("  preserving %v because it's too new (age: %v)", bm.BlobID, age)
+			log(ctx).Debugf("  preserving %v because it's too new (age: %v bm: %v)", bm.BlobID, bm.Timestamp, age)
 			return nil
 		}
 

repo/maintenance/blob_gc_test.go

@@ -12,6 +12,7 @@
 	"github.com/google/go-cmp/cmp"
 	"github.com/pkg/errors"
 
+	"github.com/kopia/kopia/internal/clock"
 	"github.com/kopia/kopia/internal/faketime"
 	"github.com/kopia/kopia/internal/gather"
 	"github.com/kopia/kopia/internal/repotesting"
@@ -29,7 +30,9 @@ func TestDeleteUnreferencedBlobs(t *testing.T) {
 
 	var env repotesting.Environment
 
-	ta := faketime.NewTimeAdvance(time.Now(), 1*time.Second)
+	// set up fake clock which is initially synchronized to wall clock time
+	// and moved at the same speed but which can be moved forward.
+	ta := faketime.NewClockTimeWithOffset(0)
 
 	// setup repository without encryption and without HMAC so we can implant session blobs
 	defer env.Setup(t, repotesting.Options{
@@ -102,7 +105,7 @@ func TestDeleteUnreferencedBlobs(t *testing.T) {
 	mustPutDummyBlob(t, env.RepositoryWriter.BlobStorage(), extraBlobIDWithSession3)
 
 	session1Marker := mustPutDummySessionBlob(t, env.RepositoryWriter.BlobStorage(), "s01", &content.SessionInfo{
-		CheckpointTime: ta.NowFunc()(),
+		CheckpointTime: clock.Now(),
 	})
 	session2Marker := mustPutDummySessionBlob(t, env.RepositoryWriter.BlobStorage(), "s02", &content.SessionInfo{
 		CheckpointTime: ta.NowFunc()(),

tests/end_to_end_test/api_server_repository_test.go

@@ -8,6 +8,7 @@
 	"time"
 
 	"github.com/kopia/kopia/internal/apiclient"
+	"github.com/kopia/kopia/internal/clock"
 	"github.com/kopia/kopia/internal/serverapi"
 	"github.com/kopia/kopia/internal/testlogging"
 	"github.com/kopia/kopia/repo"
@@ -232,7 +233,7 @@ func testAPIServerRepository(t *testing.T, serverStartArgs []string, useGRPC, al
 	serverapi.Shutdown(ctx, cli)
 
 	// open repository client to a dead server, this should fail quickly instead of retrying forever.
-	t0 := time.Now()
+	t0 := clock.Now()
 
 	repo.OpenAPIServer(ctx, &repo.APIServerInfo{
 		BaseURL:                             sp.baseURL,
@@ -243,7 +244,7 @@ func testAPIServerRepository(t *testing.T, serverStartArgs []string, useGRPC, al
 		Hostname: "bar",
 	}, "baz")
 
-	if dur := time.Since(t0); dur > 15*time.Second {
+	if dur := clock.Since(t0); dur > 15*time.Second {
 		t.Fatalf("failed connection took %v", dur)
 	}
 }

tests/end_to_end_test/snapshot_actions_test.go

@@ -10,6 +10,7 @@
 	"testing"
 	"time"
 
+	"github.com/kopia/kopia/internal/clock"
 	"github.com/kopia/kopia/internal/testutil"
 	"github.com/kopia/kopia/tests/testenv"
 )
@@ -77,13 +78,13 @@ func TestSnapshotActionsBeforeSnapshotRoot(t *testing.T) {
 		th+" --exit-code=3 --sleep=30s",
 		"--action-command-mode=async")
 
-	t0 := time.Now()
+	t0 := clock.Now()
 
 	// at this point the data is all cached so this will be quick, definitely less than 30s,
 	// async action failure will not prevent snapshot success.
 	e.RunAndExpectSuccess(t, "snapshot", "create", sharedTestDataDir1)
 
-	if dur := time.Since(t0); dur > 30*time.Second {
+	if dur := clock.Since(t0); dur > 30*time.Second {
 		t.Errorf("command did not execute asynchronously (took %v)", dur)
 	}
 
@@ -94,12 +95,12 @@ func TestSnapshotActionsBeforeSnapshotRoot(t *testing.T) {
 		th+" --sleep=30s",
 		"--action-command-timeout=3s")
 
-	t0 = time.Now()
+	t0 = clock.Now()
 
 	// the action will be killed after 3s and cause a failure.
 	e.RunAndExpectFailure(t, "snapshot", "create", sharedTestDataDir1)
 
-	if dur := time.Since(t0); dur > 30*time.Second {
+	if dur := clock.Since(t0); dur > 30*time.Second {
 		t.Errorf("command did not apply timeout (took %v)", dur)
 	}
 

tests/robustness/checker/checker.go

@@ -293,7 +293,7 @@ func (chk *Checker) DeleteSnapshot(ctx context.Context, snapID string, opts map[
 		return err
 	}
 
-	ssMeta.DeletionTime = time.Now()
+	ssMeta.DeletionTime = clock.Now()
 	ssMeta.ValidationData = nil
 
 	err = chk.saveSnapshotMetadata(ssMeta)

tests/robustness/engine/action.go

@@ -10,8 +10,8 @@
 	"math/rand"
 	"strconv"
 	"strings"
-	"time"
 
+	"github.com/kopia/kopia/internal/clock"
 	"github.com/kopia/kopia/tests/robustness"
 )
 
@@ -26,7 +26,7 @@ func (e *Engine) ExecAction(actionKey ActionKey, opts map[string]string) (map[st
 	log.Printf("Engine executing ACTION: name=%q actionCount=%v totActCount=%v t=%vs (%vs)", actionKey, e.RunStats.ActionCounter, e.CumulativeStats.ActionCounter, e.RunStats.getLifetimeSeconds(), e.getRuntimeSeconds())
 
 	action := actions[actionKey]
-	st := time.Now()
+	st := clock.Now()
 
 	logEntry := &LogEntry{
 		StartTime:       st,

tests/robustness/engine/engine.go

@@ -11,8 +11,8 @@
 	"os"
 	"path/filepath"
 	"strings"
-	"time"
 
+	"github.com/kopia/kopia/internal/clock"
 	"github.com/kopia/kopia/tests/robustness"
 	"github.com/kopia/kopia/tests/robustness/checker"
 )
@@ -63,7 +63,7 @@ func New(args *Args) (*Engine, error) {
 			baseDirPath: args.WorkingDir,
 			RunStats: Stats{
 				RunCounter:     1,
-				CreationTime:   time.Now(),
+				CreationTime:   clock.Now(),
 				PerActionStats: make(map[ActionKey]*ActionStats),
 			},
 		}
@@ -127,7 +127,7 @@ func (e *Engine) Shutdown() error {
 
 	log.Print(cleanupSummaryBuilder.String())
 
-	e.RunStats.RunTime = time.Since(e.RunStats.CreationTime)
+	e.RunStats.RunTime = clock.Since(e.RunStats.CreationTime)
 	e.CumulativeStats.RunTime += e.RunStats.RunTime
 
 	defer e.cleanComponents()

tests/robustness/engine/engine_test.go

@@ -23,6 +23,7 @@
 	"github.com/minio/minio-go/v7"
 	"github.com/minio/minio-go/v7/pkg/credentials"
 
+	"github.com/kopia/kopia/internal/clock"
 	"github.com/kopia/kopia/internal/testutil"
 	"github.com/kopia/kopia/tests/robustness"
 	"github.com/kopia/kopia/tests/robustness/fiofilewriter"
@@ -627,7 +628,7 @@ func TestIOLimitPerWriteAction(t *testing.T) {
 		},
 	}
 
-	st := time.Now()
+	st := clock.Now()
 
 	numActions := 1
 	for loop := 0; loop < numActions; loop++ {
@@ -635,7 +636,7 @@ func TestIOLimitPerWriteAction(t *testing.T) {
 		testenv.AssertNoError(t, err)
 	}
 
-	if time.Since(st) > timeout {
+	if clock.Since(st) > timeout {
 		t.Errorf("IO limit parameter did not cut down on the fio runtime")
 	}
 }
@@ -663,7 +664,7 @@ func TestStatsPersist(t *testing.T) {
 		MaxRuntime:   35 * time.Minute,
 	}
 
-	creationTime := time.Now().Add(-time.Hour)
+	creationTime := clock.Now().Add(-time.Hour)
 
 	eng := &Engine{
 		MetaStore: snapStore,
@@ -727,8 +728,8 @@ func TestLogsPersist(t *testing.T) {
 	logData := Log{
 		Log: []*LogEntry{
 			{
-				StartTime: time.Now().Add(-time.Hour),
-				EndTime:   time.Now(),
+				StartTime: clock.Now().Add(-time.Hour),
+				EndTime:   clock.Now(),
 				Action:    ActionKey("some action"),
 				Error:     "some error",
 				Idx:       11235,

tests/robustness/engine/log.go

@@ -6,6 +6,8 @@
 	"fmt"
 	"strings"
 	"time"
+
+	"github.com/kopia/kopia/internal/clock"
 )
 
 // Log keeps track of the actions taken by the engine.
@@ -83,7 +85,7 @@ func (elog *Log) AddEntry(l *LogEntry) {
 // AddCompleted finalizes a log entry at the time it is called
 // and with the provided error, before adding it to the Log.
 func (elog *Log) AddCompleted(logEntry *LogEntry, err error) {
-	logEntry.EndTime = time.Now()
+	logEntry.EndTime = clock.Now()
 	if err != nil {
 		logEntry.Error = err.Error()
 	}

tests/robustness/engine/metadata.go

@@ -5,8 +5,8 @@
 import (
 	"encoding/json"
 	"errors"
-	"time"
 
+	"github.com/kopia/kopia/internal/clock"
 	"github.com/kopia/kopia/tests/robustness/snapmeta"
 )
 
@@ -65,7 +65,7 @@ func (e *Engine) loadStats() error {
 			// Swallow key-not-found error. We may not have historical
 			// stats data. Initialize the action map for the cumulative stats
 			e.CumulativeStats.PerActionStats = make(map[ActionKey]*ActionStats)
-			e.CumulativeStats.CreationTime = time.Now()
+			e.CumulativeStats.CreationTime = clock.Now()
 
 			return nil
 		}

tests/robustness/engine/stats.go

@@ -6,6 +6,8 @@
 	"fmt"
 	"strings"
 	"time"
+
+	"github.com/kopia/kopia/internal/clock"
 )
 
 var (
@@ -112,7 +114,7 @@ func (s *ActionStats) AverageRuntime() time.Duration {
 // Record records the current time against the provided start time
 // and updates the stats accordingly.
 func (s *ActionStats) Record(st time.Time, err error) {
-	thisRuntime := time.Since(st)
+	thisRuntime := clock.Since(st)
 	s.TotalRuntime += thisRuntime
 
 	if thisRuntime > s.MaxRuntime {
@@ -131,7 +133,7 @@ func (s *ActionStats) Record(st time.Time, err error) {
 }
 
 func (stats *Stats) getLifetimeSeconds() int64 {
-	return durationToSec(time.Since(stats.CreationTime))
+	return durationToSec(clock.Since(stats.CreationTime))
 }
 
 func durationToSec(dur time.Duration) int64 {
@@ -151,5 +153,5 @@ func (e *Engine) getTimestampS() int64 {
 }
 
 func (e *Engine) getRuntimeSeconds() int64 {
-	return durationToSec(e.CumulativeStats.RunTime + time.Since(e.RunStats.CreationTime))
+	return durationToSec(e.CumulativeStats.RunTime + clock.Since(e.RunStats.CreationTime))
 }

tests/robustness/robustness_test/robustness_test.go

@@ -7,8 +7,8 @@
 	"fmt"
 	"strconv"
 	"testing"
-	"time"
 
+	"github.com/kopia/kopia/internal/clock"
 	"github.com/kopia/kopia/tests/robustness"
 	"github.com/kopia/kopia/tests/robustness/engine"
 	"github.com/kopia/kopia/tests/robustness/fiofilewriter"
@@ -86,7 +86,7 @@ func TestManySmallFilesAcrossDirecoryTree(t *testing.T) {
 }
 
 func TestRandomizedSmall(t *testing.T) {
-	st := time.Now()
+	st := clock.Now()
 
 	opts := engine.ActionOpts{
 		engine.ActionControlActionKey: map[string]string{
@@ -104,7 +104,7 @@ func TestRandomizedSmall(t *testing.T) {
 		},
 	}
 
-	for time.Since(st) <= *randomizedTestDur {
+	for clock.Since(st) <= *randomizedTestDur {
 		err := eng.RandomAction(opts)
 		if errors.Is(err, robustness.ErrNoOp) {
 			t.Log("Random action resulted in no-op")