From e694367da81f3a2f144960ad0cefc9892a41da5e Mon Sep 17 00:00:00 2001 From: Jarek Kowalski Date: Sun, 21 Feb 2021 07:46:04 -0800 Subject: [PATCH] lint: fixed vet-time-inject and replaced with forbidigo linter (#848) added faketime.NewClockTimeWithOffset and used that to fix flaky 'TestDeleteUnreferencedBlobs' test. --- .golangci.yml | 9 ++++--- Makefile | 9 +------ internal/clock/now_prod.go | 2 +- internal/clock/now_testing.go | 8 +++--- internal/editor/editor.go | 2 +- internal/faketime/faketime.go | 27 +++++++++++++++++++ repo/blob/retrying/retrying_storage_test.go | 4 +-- repo/blob/s3/s3_storage_test.go | 4 +-- repo/blob/sftp/sftp_storage_test.go | 9 ++++--- repo/maintenance/blob_gc.go | 2 +- repo/maintenance/blob_gc_test.go | 7 +++-- .../api_server_repository_test.go | 5 ++-- .../end_to_end_test/snapshot_actions_test.go | 9 ++++--- tests/robustness/checker/checker.go | 2 +- tests/robustness/engine/action.go | 4 +-- tests/robustness/engine/engine.go | 6 ++--- tests/robustness/engine/engine_test.go | 11 ++++---- tests/robustness/engine/log.go | 4 ++- tests/robustness/engine/metadata.go | 4 +-- tests/robustness/engine/stats.go | 8 +++--- .../robustness_test/robustness_test.go | 6 ++--- 21 files changed, 87 insertions(+), 55 deletions(-) diff --git a/.golangci.yml b/.golangci.yml index a8cda6186..c776747bb 100644 --- a/.golangci.yml +++ b/.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: diff --git a/Makefile b/Makefile index 3a1e5d8f7..dad862e2e 100644 --- a/Makefile +++ b/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: diff --git a/internal/clock/now_prod.go b/internal/clock/now_prod.go index 5db84279d..aab97d59d 100644 --- a/internal/clock/now_prod.go +++ b/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 } diff --git a/internal/clock/now_testing.go b/internal/clock/now_testing.go index 8b5fb54ac..bfad86b1c 100644 --- a/internal/clock/now_testing.go +++ b/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 diff --git a/internal/editor/editor.go b/internal/editor/editor.go index 793dbf25b..1368fb645 100644 --- a/internal/editor/editor.go +++ b/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 diff --git a/internal/faketime/faketime.go b/internal/faketime/faketime.go index d73d007a3..91c4089df 100644 --- a/internal/faketime/faketime.go +++ b/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) +} diff --git a/repo/blob/retrying/retrying_storage_test.go b/repo/blob/retrying/retrying_storage_test.go index c33f24713..edbfc6dc1 100644 --- a/repo/blob/retrying/retrying_storage_test.go +++ b/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) diff --git a/repo/blob/s3/s3_storage_test.go b/repo/blob/s3/s3_storage_test.go index cf26c53ce..a3b6201e1 100644 --- a/repo/blob/s3/s3_storage_test.go +++ b/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") } } diff --git a/repo/blob/sftp/sftp_storage_test.go b/repo/blob/sftp/sftp_storage_test.go index ba51cf115..4e9c38a1e 100644 --- a/repo/blob/sftp/sftp_storage_test.go +++ b/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") } } diff --git a/repo/maintenance/blob_gc.go b/repo/maintenance/blob_gc.go index 45d94d338..3c4076d9b 100644 --- a/repo/maintenance/blob_gc.go +++ b/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 } diff --git a/repo/maintenance/blob_gc_test.go b/repo/maintenance/blob_gc_test.go index 29b64870b..fce34426e 100644 --- a/repo/maintenance/blob_gc_test.go +++ b/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()(), diff --git a/tests/end_to_end_test/api_server_repository_test.go b/tests/end_to_end_test/api_server_repository_test.go index 9308a707d..b61156343 100644 --- a/tests/end_to_end_test/api_server_repository_test.go +++ b/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) } } diff --git a/tests/end_to_end_test/snapshot_actions_test.go b/tests/end_to_end_test/snapshot_actions_test.go index 89a869adb..a254b7aa1 100644 --- a/tests/end_to_end_test/snapshot_actions_test.go +++ b/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) } diff --git a/tests/robustness/checker/checker.go b/tests/robustness/checker/checker.go index c1af6b056..d2073f9aa 100644 --- a/tests/robustness/checker/checker.go +++ b/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) diff --git a/tests/robustness/engine/action.go b/tests/robustness/engine/action.go index 9f2a6f70d..8487cb7aa 100644 --- a/tests/robustness/engine/action.go +++ b/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, diff --git a/tests/robustness/engine/engine.go b/tests/robustness/engine/engine.go index 565ba5af6..22e8b81d8 100644 --- a/tests/robustness/engine/engine.go +++ b/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() diff --git a/tests/robustness/engine/engine_test.go b/tests/robustness/engine/engine_test.go index 97e279b1f..42fb5f7de 100644 --- a/tests/robustness/engine/engine_test.go +++ b/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, diff --git a/tests/robustness/engine/log.go b/tests/robustness/engine/log.go index a3f0bcb4e..66c821ebe 100644 --- a/tests/robustness/engine/log.go +++ b/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() } diff --git a/tests/robustness/engine/metadata.go b/tests/robustness/engine/metadata.go index 5ed261317..80f316229 100644 --- a/tests/robustness/engine/metadata.go +++ b/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 } diff --git a/tests/robustness/engine/stats.go b/tests/robustness/engine/stats.go index de90ed050..997e18267 100644 --- a/tests/robustness/engine/stats.go +++ b/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)) } diff --git a/tests/robustness/robustness_test/robustness_test.go b/tests/robustness/robustness_test/robustness_test.go index 44c33c316..fe6c8ec3a 100644 --- a/tests/robustness/robustness_test/robustness_test.go +++ b/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")