From 0d0f48a7ee741ef8263d608ef5bfef172ed4cf4f Mon Sep 17 00:00:00 2001 From: Jarek Kowalski Date: Fri, 22 Oct 2021 15:35:09 -0700 Subject: [PATCH] clock: discard monotonic clock component in clock.Now() (#1437) The dual time measurement is described in https://go.googlesource.com/proposal/+/master/design/12914-monotonic.md The fix is to discard hidden monotonic time component of time.Time by converting to unix time and back. Reviewed usage of clock.Now() and replaced with timetrack.StartTimer() when measuring time. The problem in #1402 was that passage of time was measured using the monotonic time and not wall clock time. When the computer goes to sleep, monotonic time is still monotonic while wall clock time makes a leap when the computer wakes up. This is the behavior that epoch manager (and most other compontents in Kopia) rely upon. Fixes #1402 Co-authored-by: Julio Lopez --- .golangci.yml | 6 ++-- cli/command_logs_session.go | 4 +-- cli/command_maintenance_info.go | 2 +- fs/loggingfs/loggingfs.go | 10 +++--- internal/apiclient/apiclient.go | 11 +++--- internal/blobtesting/cleanup.go | 4 ++- internal/blobtesting/eventually_consistent.go | 2 +- internal/cache/persistent_lru_cache.go | 8 +++-- internal/clock/now.go | 22 ++++++------ internal/clock/now_prod.go | 2 +- internal/clock/now_testing.go | 6 ++-- internal/server/source_manager.go | 2 +- internal/timetrack/estimator.go | 2 +- internal/timetrack/timer.go | 21 ++++++++++++ internal/zaplogutil/zaplogutil.go | 2 +- repo/blob/logging/logging_storage.go | 34 +++++++++---------- repo/blob/rclone/rclone_storage_test.go | 5 +-- repo/blob/s3/s3_storage_test.go | 7 ++-- repo/blob/sftp/sftp_storage_test.go | 6 ++-- repo/content/content_manager_indexes.go | 6 ++-- repo/maintenance/maintenance_run.go | 2 +- repo/open.go | 2 +- .../api_server_repository_test.go | 7 ++-- .../end_to_end_test/snapshot_actions_test.go | 11 +++--- tests/robustness/engine/engine.go | 2 +- tests/robustness/engine/stats.go | 6 ++-- .../multiclient_test/multiclient_test.go | 7 ++-- .../robustness_test/robustness_test.go | 7 ++-- tests/testenv/cli_test_env.go | 6 ++-- 29 files changed, 123 insertions(+), 89 deletions(-) create mode 100644 internal/timetrack/timer.go 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 }