diff --git a/.golangci.yml b/.golangci.yml index acb660f77..ba821168a 100644 --- a/.golangci.yml +++ b/.golangci.yml @@ -13,9 +13,9 @@ linters-settings: - ioutil.TempDir # use os.MkdirTemp - ioutil.TempFile # use os.CreateTemp - ioutil.WriteFile # use os.WriteFile - - time.Now # use clock.Now - - time.Since # use clock.Since - - time.Until # use clock.Until + - time.Now # do not use outside of 'clock' and 'timetrack' packages use clock.Now or timetrack.StartTimer + - time.Since # use timetrack.Timer.Elapsed() + - time.Until # never use this - filepath.IsAbs # use ospath.IsAbs which supports windows UNC paths gocognit: min-complexity: 40 diff --git a/cli/command_logs_session.go b/cli/command_logs_session.go index e70e1c733..ee0188df6 100644 --- a/cli/command_logs_session.go +++ b/cli/command_logs_session.go @@ -48,13 +48,13 @@ func (c *logSelectionCriteria) filterLogSessions(allSessions []*logSessionInfo) if c.youngerThan > 0 { allSessions = filterLogSessions(allSessions, func(ls *logSessionInfo) bool { - return clock.Since(ls.startTime) < c.youngerThan + return clock.Now().Sub(ls.startTime) < c.youngerThan }) } if c.olderThan > 0 { allSessions = filterLogSessions(allSessions, func(ls *logSessionInfo) bool { - return clock.Since(ls.startTime) > c.olderThan + return clock.Now().Sub(ls.startTime) > c.olderThan }) } diff --git a/cli/command_maintenance_info.go b/cli/command_maintenance_info.go index 2557ab79d..c7bb1dd7c 100644 --- a/cli/command_maintenance_info.go +++ b/cli/command_maintenance_info.go @@ -97,7 +97,7 @@ func (c *commandMaintenanceInfo) displayCycleInfo(cp *maintenance.CycleParams, t c.out.printStdout(" interval: %v\n", cp.Interval) if rep.Time().Before(t) { - c.out.printStdout(" next run: %v (in %v)\n", formatTimestamp(t), clock.Until(t).Truncate(time.Second)) + c.out.printStdout(" next run: %v (in %v)\n", formatTimestamp(t), t.Sub(clock.Now()).Truncate(time.Second)) } else { c.out.printStdout(" next run: now\n") } diff --git a/fs/loggingfs/loggingfs.go b/fs/loggingfs/loggingfs.go index 819d587a9..c732bd405 100644 --- a/fs/loggingfs/loggingfs.go +++ b/fs/loggingfs/loggingfs.go @@ -5,7 +5,7 @@ "context" "github.com/kopia/kopia/fs" - "github.com/kopia/kopia/internal/clock" + "github.com/kopia/kopia/internal/timetrack" ) type loggingOptions struct { @@ -20,9 +20,9 @@ type loggingDirectory struct { } func (ld *loggingDirectory) Child(ctx context.Context, name string) (fs.Entry, error) { - t0 := clock.Now() + timer := timetrack.StartTimer() entry, err := ld.Directory.Child(ctx, name) - dt := clock.Since(t0) + dt := timer.Elapsed() ld.options.printf(ld.options.prefix+"Child(%v) took %v and returned %v", ld.relativePath, dt, err) if err != nil { @@ -34,9 +34,9 @@ func (ld *loggingDirectory) Child(ctx context.Context, name string) (fs.Entry, e } func (ld *loggingDirectory) Readdir(ctx context.Context) (fs.Entries, error) { - t0 := clock.Now() + timer := timetrack.StartTimer() entries, err := ld.Directory.Readdir(ctx) - dt := clock.Since(t0) + dt := timer.Elapsed() ld.options.printf(ld.options.prefix+"Readdir(%v) took %v and returned %v items", ld.relativePath, dt, len(entries)) loggingEntries := make(fs.Entries, len(entries)) diff --git a/internal/apiclient/apiclient.go b/internal/apiclient/apiclient.go index 94c011381..1d0c30a3f 100644 --- a/internal/apiclient/apiclient.go +++ b/internal/apiclient/apiclient.go @@ -11,7 +11,7 @@ "github.com/pkg/errors" - "github.com/kopia/kopia/internal/clock" + "github.com/kopia/kopia/internal/timetrack" "github.com/kopia/kopia/internal/tlsutil" "github.com/kopia/kopia/repo/logging" ) @@ -191,15 +191,16 @@ type loggingTransport struct { } func (t loggingTransport) RoundTrip(req *http.Request) (*http.Response, error) { - t0 := clock.Now() - + timer := timetrack.StartTimer() resp, err := t.base.RoundTrip(req) + dur := timer.Elapsed() + if err != nil { - log(req.Context()).Debugf("%v %v took %v and failed with %v", req.Method, req.URL, clock.Since(t0), err) + log(req.Context()).Debugf("%v %v took %v and failed with %v", req.Method, req.URL, dur, err) return nil, errors.Wrap(err, "round-trip error") } - log(req.Context()).Debugf("%v %v took %v and returned %v", req.Method, req.URL, clock.Since(t0), resp.Status) + log(req.Context()).Debugf("%v %v took %v and returned %v", req.Method, req.URL, dur, resp.Status) return resp, nil } diff --git a/internal/blobtesting/cleanup.go b/internal/blobtesting/cleanup.go index 2680eabb4..1885b63ca 100644 --- a/internal/blobtesting/cleanup.go +++ b/internal/blobtesting/cleanup.go @@ -21,8 +21,10 @@ func CleanupOldData(ctx context.Context, tb testing.TB, st blob.Storage, cleanup pq := parallelwork.NewQueue() + now := clock.Now() + _ = st.ListBlobs(ctx, "", func(it blob.Metadata) error { - age := clock.Since(it.Timestamp) + age := now.Sub(it.Timestamp) if age > cleanupAge { pq.EnqueueBack(ctx, func() error { tb.Logf("deleting %v", it.BlobID) diff --git a/internal/blobtesting/eventually_consistent.go b/internal/blobtesting/eventually_consistent.go index 054f30b4f..96941d193 100644 --- a/internal/blobtesting/eventually_consistent.go +++ b/internal/blobtesting/eventually_consistent.go @@ -75,7 +75,7 @@ type ecCacheEntry struct { } func (e *ecCacheEntry) isValid() bool { - return clock.Since(e.accessTime) < ecCacheDuration + return clock.Now().Sub(e.accessTime) < ecCacheDuration } type eventuallyConsistentStorage struct { diff --git a/internal/cache/persistent_lru_cache.go b/internal/cache/persistent_lru_cache.go index 8cfad747a..9ccf5f4f1 100644 --- a/internal/cache/persistent_lru_cache.go +++ b/internal/cache/persistent_lru_cache.go @@ -11,8 +11,8 @@ "github.com/pkg/errors" "go.opencensus.io/stats" - "github.com/kopia/kopia/internal/clock" "github.com/kopia/kopia/internal/gather" + "github.com/kopia/kopia/internal/timetrack" "github.com/kopia/kopia/repo/blob" "github.com/kopia/kopia/repo/logging" ) @@ -193,7 +193,7 @@ func (h *contentMetadataHeap) Pop() interface{} { } func (c *PersistentCache) sweepDirectory(ctx context.Context) (err error) { - t0 := clock.Now() + timer := timetrack.StartTimer() var h contentMetadataHeap @@ -217,7 +217,9 @@ func (c *PersistentCache) sweepDirectory(ctx context.Context) (err error) { return errors.Wrapf(err, "error listing %v", c.description) } - log(ctx).Debugf("finished sweeping %v in %v and retained %v/%v bytes (%v %%)", c.description, clock.Since(t0), totalRetainedSize, c.maxSizeBytes, 100*totalRetainedSize/c.maxSizeBytes) + dur := timer.Elapsed() + + log(ctx).Debugf("finished sweeping %v in %v and retained %v/%v bytes (%v %%)", c.description, dur, totalRetainedSize, c.maxSizeBytes, 100*totalRetainedSize/c.maxSizeBytes) return nil } diff --git a/internal/clock/now.go b/internal/clock/now.go index c2a76a7bf..805f194da 100644 --- a/internal/clock/now.go +++ b/internal/clock/now.go @@ -1,16 +1,14 @@ -// Package clock provides indirection for accessing current time. +// Package clock provides indirection for accessing current wall clock time. +// this is suitable for timestamps and long-term time operations, not short-term time measurements. package clock -import ( - "time" -) +import "time" -// Since returns time since the given timestamp. -func Since(t time.Time) time.Duration { - return Now().Sub(t) -} - -// Until returns duration of time between now and a given time. -func Until(t time.Time) time.Duration { - return t.Sub(Now()) +// discardMonotonicTime discards any monotonic time component of time, +// which behaves incorrectly when the computer goes to sleep and we want to measure durations +// between points in time. +// +// See https://go.googlesource.com/proposal/+/master/design/12914-monotonic.md +func discardMonotonicTime(t time.Time) time.Time { + return time.Unix(0, t.UnixNano()) } diff --git a/internal/clock/now_prod.go b/internal/clock/now_prod.go index 2a0c320b6..8a6085f30 100644 --- a/internal/clock/now_prod.go +++ b/internal/clock/now_prod.go @@ -7,5 +7,5 @@ // Now returns current wall clock time. func Now() time.Time { - return time.Now() // nolint:forbidigo + return discardMonotonicTime(time.Now()) // nolint:forbidigo } diff --git a/internal/clock/now_testing.go b/internal/clock/now_testing.go index 52ec9b2ec..35f47f3ad 100644 --- a/internal/clock/now_testing.go +++ b/internal/clock/now_testing.go @@ -15,7 +15,9 @@ const refreshServerTimeEvery = 3 * time.Second // Now is overridable function that returns current wall clock time. -var Now = time.Now // nolint:forbidigo +var Now = func() time.Time { + return discardMonotonicTime(time.Now()) // nolint:forbidigo +} func init() { fakeTimeServer := os.Getenv("KOPIA_FAKE_CLOCK_ENDPOINT") @@ -71,6 +73,6 @@ func getTimeFromServer(endpoint string) func() time.Time { localTimeOffset = timeInfo.Time.Sub(localTime) } - return localTime.Add(localTimeOffset) + return discardMonotonicTime(localTime.Add(localTimeOffset)) } } diff --git a/internal/server/source_manager.go b/internal/server/source_manager.go index fcfcbf2e9..f55b09e8f 100644 --- a/internal/server/source_manager.go +++ b/internal/server/source_manager.go @@ -126,7 +126,7 @@ func (s *sourceManager) runLocal(ctx context.Context) { var waitTime time.Duration if s.nextSnapshotTime != nil { - waitTime = clock.Until(*s.nextSnapshotTime) + waitTime = s.nextSnapshotTime.Sub(clock.Now()) } else { waitTime = oneDay } diff --git a/internal/timetrack/estimator.go b/internal/timetrack/estimator.go index 962aabb00..617abad55 100644 --- a/internal/timetrack/estimator.go +++ b/internal/timetrack/estimator.go @@ -39,7 +39,7 @@ func (v Estimator) Estimate(completed, total float64) (Timings, bool) { predictedSeconds := elapsed.Seconds() / completedRatio predictedEndTime := v.startTime.Add(time.Duration(predictedSeconds) * time.Second) - dt := clock.Until(predictedEndTime).Truncate(time.Second) + dt := predictedEndTime.Sub(clock.Now()).Truncate(time.Second) if dt < 0 { dt = 0 } diff --git a/internal/timetrack/timer.go b/internal/timetrack/timer.go new file mode 100644 index 000000000..b367de833 --- /dev/null +++ b/internal/timetrack/timer.go @@ -0,0 +1,21 @@ +// Package timetrack tracks the progress and estimates completion of a task. +package timetrack + +import ( + "time" +) + +// Timer measures elapsed time of operations. +type Timer struct { + startTime time.Time +} + +// Elapsed returns time elapsed since the timer was started. +func (t Timer) Elapsed() time.Duration { + return time.Since(t.startTime) // nolint:forbidigo +} + +// StartTimer starts the timer. +func StartTimer() Timer { + return Timer{time.Now()} // nolint:forbidigo +} diff --git a/internal/zaplogutil/zaplogutil.go b/internal/zaplogutil/zaplogutil.go index a85b89a70..41d68c9b5 100644 --- a/internal/zaplogutil/zaplogutil.go +++ b/internal/zaplogutil/zaplogutil.go @@ -17,7 +17,7 @@ type theClock struct{ func (c theClock) Now() time.Time { return clock.Now() } func (c theClock) NewTicker(d time.Duration) *time.Ticker { return time.NewTicker(d) } -// Clock isn aimplementation of zapcore.Clock that uses clock.Now(). +// Clock is an implementation of zapcore.Clock that uses clock.Now(). var Clock zapcore.Clock = theClock{} // TimezoneAdjust returns zapcore.TimeEncoder that adjusts the time to either UTC or local time before logging. diff --git a/repo/blob/logging/logging_storage.go b/repo/blob/logging/logging_storage.go index 4d960907f..eda187046 100644 --- a/repo/blob/logging/logging_storage.go +++ b/repo/blob/logging/logging_storage.go @@ -5,8 +5,8 @@ "context" "time" - "github.com/kopia/kopia/internal/clock" "github.com/kopia/kopia/internal/gather" + "github.com/kopia/kopia/internal/timetrack" "github.com/kopia/kopia/repo/blob" ) @@ -19,9 +19,9 @@ type loggingStorage struct { } func (s *loggingStorage) GetBlob(ctx context.Context, id blob.ID, offset, length int64, output *gather.WriteBuffer) error { - t0 := clock.Now() + timer := timetrack.StartTimer() err := s.base.GetBlob(ctx, id, offset, length, output) - dt := clock.Since(t0) + dt := timer.Elapsed() if output.Length() < maxLoggedBlobLength { s.printf(s.prefix+"GetBlob(%q,%v,%v)=(%v, %#v) took %v", id, offset, length, output, err, dt) @@ -34,9 +34,9 @@ func (s *loggingStorage) GetBlob(ctx context.Context, id blob.ID, offset, length } func (s *loggingStorage) GetMetadata(ctx context.Context, id blob.ID) (blob.Metadata, error) { - t0 := clock.Now() + timer := timetrack.StartTimer() result, err := s.base.GetMetadata(ctx, id) - dt := clock.Since(t0) + dt := timer.Elapsed() s.printf(s.prefix+"GetMetadata(%q)=(%v, %#v) took %v", id, result, err, dt) @@ -45,9 +45,9 @@ func (s *loggingStorage) GetMetadata(ctx context.Context, id blob.ID) (blob.Meta } func (s *loggingStorage) PutBlob(ctx context.Context, id blob.ID, data blob.Bytes) error { - t0 := clock.Now() + timer := timetrack.StartTimer() err := s.base.PutBlob(ctx, id, data) - dt := clock.Since(t0) + dt := timer.Elapsed() s.printf(s.prefix+"PutBlob(%q,len=%v)=%#v took %v", id, data.Length(), err, dt) // nolint:wrapcheck @@ -55,9 +55,9 @@ func (s *loggingStorage) PutBlob(ctx context.Context, id blob.ID, data blob.Byte } func (s *loggingStorage) SetTime(ctx context.Context, id blob.ID, t time.Time) error { - t0 := clock.Now() + timer := timetrack.StartTimer() err := s.base.SetTime(ctx, id, t) - dt := clock.Since(t0) + dt := timer.Elapsed() s.printf(s.prefix+"SetTime(%q,%v)=%#v took %v", id, t, err, dt) // nolint:wrapcheck @@ -65,9 +65,9 @@ func (s *loggingStorage) SetTime(ctx context.Context, id blob.ID, t time.Time) e } func (s *loggingStorage) DeleteBlob(ctx context.Context, id blob.ID) error { - t0 := clock.Now() + timer := timetrack.StartTimer() err := s.base.DeleteBlob(ctx, id) - dt := clock.Since(t0) + dt := timer.Elapsed() s.printf(s.prefix+"DeleteBlob(%q)=%#v took %v", id, err, dt) // nolint:wrapcheck @@ -75,22 +75,22 @@ func (s *loggingStorage) DeleteBlob(ctx context.Context, id blob.ID) error { } func (s *loggingStorage) ListBlobs(ctx context.Context, prefix blob.ID, callback func(blob.Metadata) error) error { - t0 := clock.Now() + timer := timetrack.StartTimer() cnt := 0 err := s.base.ListBlobs(ctx, prefix, func(bi blob.Metadata) error { cnt++ return callback(bi) }) - s.printf(s.prefix+"ListBlobs(%q)=%v returned %v items and took %v", prefix, err, cnt, clock.Since(t0)) + s.printf(s.prefix+"ListBlobs(%q)=%v returned %v items and took %v", prefix, err, cnt, timer.Elapsed()) // nolint:wrapcheck return err } func (s *loggingStorage) Close(ctx context.Context) error { - t0 := clock.Now() + timer := timetrack.StartTimer() err := s.base.Close(ctx) - dt := clock.Since(t0) + dt := timer.Elapsed() s.printf(s.prefix+"Close()=%#v took %v", err, dt) // nolint:wrapcheck @@ -106,9 +106,9 @@ func (s *loggingStorage) DisplayName() string { } func (s *loggingStorage) FlushCaches(ctx context.Context) error { - t0 := clock.Now() + timer := timetrack.StartTimer() err := s.base.FlushCaches(ctx) - dt := clock.Since(t0) + dt := timer.Elapsed() s.printf(s.prefix+"FlushCaches()=%#v took %v", err, dt) // nolint:wrapcheck diff --git a/repo/blob/rclone/rclone_storage_test.go b/repo/blob/rclone/rclone_storage_test.go index 7ceee29b7..5f89092c9 100644 --- a/repo/blob/rclone/rclone_storage_test.go +++ b/repo/blob/rclone/rclone_storage_test.go @@ -257,9 +257,10 @@ func cleanupOldData(ctx context.Context, t *testing.T, opt *rclone.Options, clea func cleanupAllBlobs(ctx context.Context, t *testing.T, st blob.Storage, cleanupAge time.Duration) { t.Helper() + now := clock.Now() + _ = st.ListBlobs(ctx, "", func(it blob.Metadata) error { - age := clock.Since(it.Timestamp) - if age > cleanupAge { + if age := now.Sub(it.Timestamp); age > cleanupAge { if err := st.DeleteBlob(ctx, it.BlobID); err != nil { t.Errorf("warning: unable to delete %q: %v", it.BlobID, err) } diff --git a/repo/blob/s3/s3_storage_test.go b/repo/blob/s3/s3_storage_test.go index 0fe41504c..72fa1bed0 100644 --- a/repo/blob/s3/s3_storage_test.go +++ b/repo/blob/s3/s3_storage_test.go @@ -21,11 +21,11 @@ "github.com/stretchr/testify/require" "github.com/kopia/kopia/internal/blobtesting" - "github.com/kopia/kopia/internal/clock" "github.com/kopia/kopia/internal/gather" "github.com/kopia/kopia/internal/providervalidation" "github.com/kopia/kopia/internal/testlogging" "github.com/kopia/kopia/internal/testutil" + "github.com/kopia/kopia/internal/timetrack" "github.com/kopia/kopia/repo/blob" ) @@ -205,7 +205,7 @@ func TestInvalidCredsFailsFast(t *testing.T) { ctx := testlogging.Context(t) - t0 := clock.Now() + timer := timetrack.StartTimer() _, err := New(ctx, &Options{ Endpoint: minioEndpoint, @@ -218,7 +218,8 @@ func TestInvalidCredsFailsFast(t *testing.T) { }) require.Error(t, err) - if dt := clock.Since(t0); dt > 10*time.Second { + // nolint:forbidigo + if dt := timer.Elapsed(); 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 bfe2f7257..7af92288d 100644 --- a/repo/blob/sftp/sftp_storage_test.go +++ b/repo/blob/sftp/sftp_storage_test.go @@ -21,6 +21,7 @@ "github.com/kopia/kopia/internal/providervalidation" "github.com/kopia/kopia/internal/testlogging" "github.com/kopia/kopia/internal/testutil" + "github.com/kopia/kopia/internal/timetrack" "github.com/kopia/kopia/repo/blob" "github.com/kopia/kopia/repo/blob/sftp" ) @@ -250,7 +251,7 @@ func TestInvalidServerFailsFast(t *testing.T) { mustRunCommand(t, "ssh-keygen", "-t", "rsa", "-P", "", "-f", idRSA) os.WriteFile(knownHostsFile, nil, 0o600) - t0 := clock.Now() + timer := timetrack.StartTimer() if _, err := createSFTPStorage(ctx, t, sftp.Options{ Path: "/upload", @@ -263,7 +264,8 @@ func TestInvalidServerFailsFast(t *testing.T) { t.Fatalf("unexpected success with bad credentials") } - if dt := clock.Since(t0); dt > 10*time.Second { + // nolint:forbidigo + if dt := timer.Elapsed(); dt > 10*time.Second { t.Fatalf("opening storage took too long, probably due to retries") } } diff --git a/repo/content/content_manager_indexes.go b/repo/content/content_manager_indexes.go index 46d070927..5e4e056e5 100644 --- a/repo/content/content_manager_indexes.go +++ b/repo/content/content_manager_indexes.go @@ -6,8 +6,8 @@ "github.com/pkg/errors" - "github.com/kopia/kopia/internal/clock" "github.com/kopia/kopia/internal/gather" + "github.com/kopia/kopia/internal/timetrack" "github.com/kopia/kopia/repo/blob" ) @@ -39,10 +39,10 @@ func (sm *SharedManager) Refresh(ctx context.Context) error { sm.indexBlobManager.invalidate(ctx) - t0 := clock.Now() + timer := timetrack.StartTimer() err := sm.loadPackIndexesLocked(ctx) - sm.log.Debugf("Refresh completed in %v", clock.Since(t0)) + sm.log.Debugf("Refresh completed in %v", timer.Elapsed()) return err } diff --git a/repo/maintenance/maintenance_run.go b/repo/maintenance/maintenance_run.go index aa38a585f..69e8cd81e 100644 --- a/repo/maintenance/maintenance_run.go +++ b/repo/maintenance/maintenance_run.go @@ -301,7 +301,7 @@ func notRewritingContents(ctx context.Context) { } func notDeletingOrphanedBlobs(ctx context.Context, s *Schedule, safety SafetyParameters) { - left := clock.Until(nextBlobDeleteTime(s, safety)).Truncate(time.Second) + left := nextBlobDeleteTime(s, safety).Sub(clock.Now()).Truncate(time.Second) log(ctx).Infof("Skipping blob deletion because not enough time has passed yet (%v left).", left) } diff --git a/repo/open.go b/repo/open.go index c5fdd576a..8efad4ed8 100644 --- a/repo/open.go +++ b/repo/open.go @@ -307,7 +307,7 @@ func readFormatBlobBytesFromCache(ctx context.Context, cachedFile string, validD return nil, errors.Wrap(err, "unable to open cache file") } - if clock.Since(cst.ModTime()) > validDuration { + if clock.Now().Sub(cst.ModTime()) > validDuration { // got cached file, but it's too old, remove it if err := os.Remove(cachedFile); err != nil { log(ctx).Debugf("unable to remove cache file: %v", err) 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 974255772..f500c93c3 100644 --- a/tests/end_to_end_test/api_server_repository_test.go +++ b/tests/end_to_end_test/api_server_repository_test.go @@ -8,10 +8,10 @@ "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/internal/testutil" + "github.com/kopia/kopia/internal/timetrack" "github.com/kopia/kopia/repo" "github.com/kopia/kopia/repo/blob" "github.com/kopia/kopia/tests/clitestutil" @@ -264,7 +264,7 @@ func testAPIServerRepository(t *testing.T, serverStartArgs []string, useGRPC, al logErrorAndIgnore(t, serverapi.Shutdown(ctx, uiUserCLI)) // open repository client to a dead server, this should fail quickly instead of retrying forever. - t0 := clock.Now() + timer := timetrack.StartTimer() repo.OpenAPIServer(ctx, &repo.APIServerInfo{ BaseURL: sp.baseURL, @@ -275,7 +275,8 @@ func testAPIServerRepository(t *testing.T, serverStartArgs []string, useGRPC, al Hostname: "bar", }, nil, "baz") - if dur := clock.Since(t0); dur > 15*time.Second { + // nolint:forbidigo + if dur := timer.Elapsed(); 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 6b5832fbc..0ababc4a3 100644 --- a/tests/end_to_end_test/snapshot_actions_test.go +++ b/tests/end_to_end_test/snapshot_actions_test.go @@ -11,8 +11,8 @@ "github.com/stretchr/testify/require" - "github.com/kopia/kopia/internal/clock" "github.com/kopia/kopia/internal/testutil" + "github.com/kopia/kopia/internal/timetrack" "github.com/kopia/kopia/snapshot" "github.com/kopia/kopia/tests/clitestutil" "github.com/kopia/kopia/tests/testenv" @@ -94,13 +94,13 @@ func TestSnapshotActionsBeforeSnapshotRoot(t *testing.T) { th+" --exit-code=3 --sleep=30s", "--action-command-mode=async") - t0 := clock.Now() + timer := timetrack.StartTimer() // 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 := clock.Since(t0); dur > 30*time.Second { + if dur := timer.Elapsed(); dur > 30*time.Second { t.Errorf("command did not execute asynchronously (took %v)", dur) } @@ -111,12 +111,11 @@ func TestSnapshotActionsBeforeSnapshotRoot(t *testing.T) { th+" --sleep=30s", "--action-command-timeout=3s") - t0 = clock.Now() - + timer = timetrack.StartTimer() // the action will be killed after 3s and cause a failure. e.RunAndExpectFailure(t, "snapshot", "create", sharedTestDataDir1) - if dur := clock.Since(t0); dur > 30*time.Second { + if dur := timer.Elapsed(); dur > 30*time.Second { t.Errorf("command did not apply timeout (took %v)", dur) } diff --git a/tests/robustness/engine/engine.go b/tests/robustness/engine/engine.go index c44432542..014b94e4a 100644 --- a/tests/robustness/engine/engine.go +++ b/tests/robustness/engine/engine.go @@ -129,7 +129,7 @@ func (e *Engine) Shutdown(ctx context.Context) error { log.Print(cleanupSummaryBuilder.String()) - e.RunStats.RunTime = clock.Since(e.RunStats.CreationTime) + e.RunStats.RunTime = clock.Now().Sub(e.RunStats.CreationTime) e.CumulativeStats.RunTime += e.RunStats.RunTime defer e.cleanComponents() diff --git a/tests/robustness/engine/stats.go b/tests/robustness/engine/stats.go index 89d8d5c3e..fa3e0a484 100644 --- a/tests/robustness/engine/stats.go +++ b/tests/robustness/engine/stats.go @@ -116,7 +116,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 := clock.Since(st) + thisRuntime := clock.Now().Sub(st) s.TotalRuntime += thisRuntime if thisRuntime > s.MaxRuntime { @@ -135,7 +135,7 @@ func (s *ActionStats) Record(st time.Time, err error) { } func (stats *Stats) getLifetimeSeconds() int64 { - return durationToSec(clock.Since(stats.CreationTime)) + return durationToSec(clock.Now().Sub(stats.CreationTime)) } func durationToSec(dur time.Duration) int64 { @@ -155,7 +155,7 @@ func (e *Engine) getTimestampS() int64 { } func (e *Engine) getRuntimeSeconds() int64 { - return durationToSec(e.CumulativeStats.RunTime + clock.Since(e.RunStats.CreationTime)) + return durationToSec(e.CumulativeStats.RunTime + clock.Now().Sub(e.RunStats.CreationTime)) } type statsUpdatetype int diff --git a/tests/robustness/multiclient_test/multiclient_test.go b/tests/robustness/multiclient_test/multiclient_test.go index 49dfd0eb7..2439c604c 100644 --- a/tests/robustness/multiclient_test/multiclient_test.go +++ b/tests/robustness/multiclient_test/multiclient_test.go @@ -14,8 +14,8 @@ "github.com/stretchr/testify/require" - "github.com/kopia/kopia/internal/clock" "github.com/kopia/kopia/internal/testlogging" + "github.com/kopia/kopia/internal/timetrack" "github.com/kopia/kopia/tests/robustness" "github.com/kopia/kopia/tests/robustness/engine" "github.com/kopia/kopia/tests/robustness/fiofilewriter" @@ -124,7 +124,7 @@ func TestManySmallFilesAcrossDirecoryTree(t *testing.T) { func TestRandomizedSmall(t *testing.T) { numClients := 4 - st := clock.Now() + st := timetrack.StartTimer() opts := engine.ActionOpts{ engine.ActionControlActionKey: map[string]string{ @@ -146,7 +146,8 @@ func TestRandomizedSmall(t *testing.T) { err := tryRestoreIntoDataDirectory(ctx, t) require.NoError(t, err) - for clock.Since(st) <= *randomizedTestDur { + // nolint:forbidigo + for st.Elapsed() <= *randomizedTestDur { err := tryRandomAction(ctx, t, opts) require.NoError(t, err) } diff --git a/tests/robustness/robustness_test/robustness_test.go b/tests/robustness/robustness_test/robustness_test.go index 2bd7a6bac..b10aa494e 100644 --- a/tests/robustness/robustness_test/robustness_test.go +++ b/tests/robustness/robustness_test/robustness_test.go @@ -11,8 +11,8 @@ "github.com/stretchr/testify/require" - "github.com/kopia/kopia/internal/clock" "github.com/kopia/kopia/internal/testlogging" + "github.com/kopia/kopia/internal/timetrack" "github.com/kopia/kopia/tests/robustness" "github.com/kopia/kopia/tests/robustness/engine" "github.com/kopia/kopia/tests/robustness/fiofilewriter" @@ -95,7 +95,7 @@ func TestManySmallFilesAcrossDirecoryTree(t *testing.T) { } func TestRandomizedSmall(t *testing.T) { - st := clock.Now() + st := timetrack.StartTimer() opts := engine.ActionOpts{ engine.ActionControlActionKey: map[string]string{ @@ -114,7 +114,8 @@ func TestRandomizedSmall(t *testing.T) { } ctx := testlogging.ContextWithLevel(t, testlogging.LevelInfo) - for clock.Since(st) <= *randomizedTestDur { + + for st.Elapsed() <= *randomizedTestDur { err := eng.RandomAction(ctx, opts) if errors.Is(err, robustness.ErrNoOp) { t.Log("Random action resulted in no-op") diff --git a/tests/testenv/cli_test_env.go b/tests/testenv/cli_test_env.go index 66067bfc7..8928687af 100644 --- a/tests/testenv/cli_test_env.go +++ b/tests/testenv/cli_test_env.go @@ -16,6 +16,7 @@ "github.com/kopia/kopia/internal/clock" "github.com/kopia/kopia/internal/testutil" + "github.com/kopia/kopia/internal/timetrack" ) const ( @@ -177,7 +178,7 @@ func (e *CLITest) Run(t *testing.T, expectedError bool, args ...string) (stdout, args = e.cmdArgs(args) t.Logf("running 'kopia %v'", strings.Join(args, " ")) - t0 := clock.Now() + timer := timetrack.StartTimer() stdoutReader, stderrReader, wait, _ := e.Runner.Start(t, args) @@ -223,7 +224,8 @@ func (e *CLITest) Run(t *testing.T, expectedError bool, args ...string) (stdout, require.NoError(t, gotErr, "unexpected error when running 'kopia %v' (stdout:\n%v\nstderr:\n%v", strings.Join(args, " "), strings.Join(stdout, "\n"), strings.Join(stderr, "\n")) } - t.Logf("finished in %v: 'kopia %v'", clock.Since(t0).Milliseconds(), strings.Join(args, " ")) + // nolint:forbidigo + t.Logf("finished in %v: 'kopia %v'", timer.Elapsed().Milliseconds(), strings.Join(args, " ")) return stdout, stderr, gotErr }