Repository: kopia/kopia (go)

Issue:
Long-running snapshot leave behind incomplete snapshots and shows 0 byte size
I have a policy that snapshots a directory daily at 4:30 am. Every day, it runs on schedule, takes around 2-3 hours, then reports that it finished. However, at that point, the snapshot size shows “0 B”, where in reality it’s around 2.2 TB. Looking at the list of snapshots for that policy, I see "incomplete" snapshots every 45 mins after the backup started (i.e. 5:15 am, 6:00 am, etc.). That makes sense, given how incomplete snapshots work ([FAQs - What are Incomplete Snapshots?](https://kopia.io/docs/faqs/#what-are-incomplete-snapshots)), but it **doesn't** make sense that they would persist after the snapshot completes.

Looking in the logs for the snapshot tasks (“Tasks” tab in UI, drill into relevant row), I don’t see any errors or indications of a problem. As far as I can tell, the snapshot does complete successfully (as such), it just doesn't clean up the incomplete snapshots. Plus it reports the size as 0 B.

The next snapshot that runs (whether manual or scheduled) cleans this up. It takes a few seconds, cleans up the incomplete snapshots, shows a full complete snapshot instead, and updates the size to show ~2.2 TB. It does **not** however actually take a new snapshot. For that reason, I was manually clicking "Snapshot Now" every day to work around this issue. Then someone on the forum suggested a second daily snapshot, and that's working for me. I have a second snapshot scheduled at 9:30 am every day, and that cleans up the 4:30 snapshot for me.

As I mentioned, I posted about this issue on the forum. There's more detail there, including screenshots.
[Daily snapshot finishes, shows 0B, retries](https://kopia.discourse.group/t/daily-snapshot-finishes-shows-0b-retries/2194)

Pull request description:
fix(snapshots): Remove checkpoints after a complete snapshot
This is an attempt to fix #3347.

I have proposed [several possible options](https://github.com/kopia/kopia/issues/3347#issuecomment-2697898973) to fix this bug, but instead of waiting for opinions, I went ahead and decided to implement the second one. I scanned through the code base and it seemed to me that nothing relys on checkpoints' start time being eqaul to their end time, and all tests are passing on my local machine, so I guess this option could be the best solution.

Patch:
diff --git a/snapshot/upload/upload.go b/snapshot/upload/upload.go
index 3dd8f0f3..02b82435 100644
--- a/snapshot/upload/upload.go
+++ b/snapshot/upload/upload.go
@@ -488,10 +488,12 @@ func newCachedDirEntry(md, cached fs.Entry, fname string) (*snapshot.DirEntry, e
 }
 
 // uploadFileWithCheckpointing uploads the specified File to the repository.
-func (u *Uploader) uploadFileWithCheckpointing(ctx context.Context, relativePath string, file fs.File, pol *policy.Policy, sourceInfo snapshot.SourceInfo) (*snapshot.DirEntry, error) {
+func (u *Uploader) uploadFileWithCheckpointing(ctx context.Context, relativePath string, file fs.File, pol *policy.Policy, sourceInfo snapshot.SourceInfo, startTime fs.UTCTimestamp) (*snapshot.DirEntry, error) {
 	var cp checkpointRegistry
 
-	cancelCheckpointer := u.periodicallyCheckpoint(ctx, &cp, &snapshot.Manifest{Source: sourceInfo})
+	// Make checkpoints one nanosecond older than the current snapshot, so that they are cleaned
+	// up by retention policies upon creation of the snapshot.
+	cancelCheckpointer := u.periodicallyCheckpoint(ctx, &cp, &snapshot.Manifest{Source: sourceInfo, StartTime: startTime - 1})
 	defer cancelCheckpointer()
 
 	res, err := u.uploadFileInternal(ctx, &cp, relativePath, file, pol)
@@ -531,7 +533,6 @@ func (u *Uploader) checkpointRoot(ctx context.Context, cp *checkpointRegistry, p
 	man := *prototypeManifest
 	man.RootEntry = rootEntry
 	man.EndTime = fs.UTCTimestampFromTime(u.repo.Time())
-	man.StartTime = man.EndTime
 	man.IncompleteReason = IncompleteReasonCheckpoint
 	man.Tags = u.CheckpointLabels
 
@@ -584,13 +585,15 @@ func (u *Uploader) periodicallyCheckpoint(ctx context.Context, cp *checkpointReg
 }
 
 // uploadDirWithCheckpointing uploads the specified Directory to the repository.
-func (u *Uploader) uploadDirWithCheckpointing(ctx context.Context, rootDir fs.Directory, policyTree *policy.Tree, previousDirs []fs.Directory, sourceInfo snapshot.SourceInfo) (*snapshot.DirEntry, error) {
+func (u *Uploader) uploadDirWithCheckpointing(ctx context.Context, rootDir fs.Directory, policyTree *policy.Tree, previousDirs []fs.Directory, sourceInfo snapshot.SourceInfo, startTime fs.UTCTimestamp) (*snapshot.DirEntry, error) {
 	var (
 		dmb snapshotfs.DirManifestBuilder
 		cp  checkpointRegistry
 	)
 
-	cancelCheckpointer := u.periodicallyCheckpoint(ctx, &cp, &snapshot.Manifest{Source: sourceInfo})
+	// Make checkpoints one nanosecond older than the current snapshot, so that they are cleaned
+	// up by retention policies upon creation of the snapshot.
+	cancelCheckpointer := u.periodicallyCheckpoint(ctx, &cp, &snapshot.Manifest{Source: sourceInfo, StartTime: startTime - 1})
 	defer cancelCheckpointer()
 
 	var hc actionContext
@@ -1284,11 +1287,11 @@ func (u *Uploader) Upload(
 
 	switch entry := source.(type) {
 	case fs.Directory:
-		s.RootEntry, err = u.uploadDir(ctx, previousManifests, entry, policyTree, sourceInfo)
+		s.RootEntry, err = u.uploadDir(ctx, previousManifests, entry, policyTree, sourceInfo, s.StartTime)
 
 	case fs.File:
 		u.Progress.EstimatedDataSize(1, entry.Size())
-		s.RootEntry, err = u.uploadFileWithCheckpointing(ctx, entry.Name(), entry, policyTree.EffectivePolicy(), sourceInfo)
+		s.RootEntry, err = u.uploadFileWithCheckpointing(ctx, entry.Name(), entry, policyTree.EffectivePolicy(), sourceInfo, s.StartTime)
 
 	default:
 		return nil, errors.Errorf("unsupported source: %v", s.Source)
@@ -1311,6 +1314,7 @@ func (u *Uploader) uploadDir(
 	entry fs.Directory,
 	policyTree *policy.Tree,
 	sourceInfo snapshot.SourceInfo,
+	startTime fs.UTCTimestamp,
 ) (*snapshot.DirEntry, error) {
 	var previousDirs []fs.Directory
 
@@ -1328,7 +1332,7 @@ func (u *Uploader) uploadDir(
 
 	wrapped := u.wrapIgnorefs(uploadLog(ctx), entry, policyTree, true /* reportIgnoreStats */)
 
-	return u.uploadDirWithCheckpointing(ctx, wrapped, policyTree, previousDirs, sourceInfo)
+	return u.uploadDirWithCheckpointing(ctx, wrapped, policyTree, previousDirs, sourceInfo, startTime)
 }
 
 func (u *Uploader) startDataSizeEstimation(


Test patch:
diff --git a/snapshot/upload/upload_test.go b/snapshot/upload/upload_test.go
index 49b3dc7a..955de668 100644
--- a/snapshot/upload/upload_test.go
+++ b/snapshot/upload/upload_test.go
@@ -814,23 +814,26 @@ func TestUploadWithCheckpointing(t *testing.T) {
 		})
 	}
 
-	if _, err := u.Upload(ctx, th.sourceDir, policyTree, si); err != nil {
+	s, err := u.Upload(ctx, th.sourceDir, policyTree, si)
+	if err != nil {
 		t.Errorf("Upload error: %v", err)
 	}
 
-	snapshots, err := snapshot.ListSnapshots(ctx, th.repo, si)
+	checkpoints, err := snapshot.ListSnapshots(ctx, th.repo, si)
 	if err != nil {
 		t.Fatalf("error listing snapshots: %v", err)
 	}
 
-	require.Len(t, snapshots, len(dirsToCheckpointAt))
+	require.Len(t, checkpoints, len(dirsToCheckpointAt))
 
-	for _, sn := range snapshots {
-		if got, want := sn.IncompleteReason, IncompleteReasonCheckpoint; got != want {
+	for _, cp := range checkpoints {
+		if got, want := cp.IncompleteReason, IncompleteReasonCheckpoint; got != want {
 			t.Errorf("unexpected incompleteReason %q, want %q", got, want)
 		}
 
-		assert.Equal(t, labels, sn.Tags)
+		assert.Equal(t, time.Duration(1), s.StartTime.Sub(cp.StartTime))
+
+		assert.Equal(t, labels, cp.Tags)
 	}
 }
 
diff --git a/tests/clitestutil/clitestutil.go b/tests/clitestutil/clitestutil.go
index 5095a9c8..6180f0ec 100644
--- a/tests/clitestutil/clitestutil.go
+++ b/tests/clitestutil/clitestutil.go
@@ -17,9 +17,11 @@ type SourceInfo struct {
 
 // SnapshotInfo represents a single snapshot information.
 type SnapshotInfo struct {
-	ObjectID   string
-	SnapshotID string
-	Time       time.Time
+	ObjectID         string
+	SnapshotID       string
+	Time             time.Time
+	Incomplete       bool
+	IncompleteReason string
 }
 
 // MustParseSnapshots parsers the output of 'snapshot list'.
@@ -58,6 +60,8 @@ func MustParseSnapshots(t *testing.T, lines []string) []SourceInfo {
 func mustParseSnaphotInfo(t *testing.T, l string) SnapshotInfo {
 	t.Helper()
 
+	incomplete := strings.Contains(l, "incomplete")
+
 	parts := strings.Split(l, " ")
 
 	ts, err := time.Parse("2006-01-02 15:04:05 MST", strings.Join(parts[0:3], " "))
@@ -65,13 +69,27 @@ func mustParseSnaphotInfo(t *testing.T, l string) SnapshotInfo {
 		t.Fatalf("err: %v", err)
 	}
 
-	manifestField := parts[7]
+	var manifestField string
+
+	if incomplete {
+		manifestField = parts[8]
+	} else {
+		manifestField = parts[7]
+	}
+
 	snapID := strings.TrimPrefix(manifestField, "manifest:")
 
+	incompleteReason := ""
+	if incomplete {
+		incompleteReason = strings.Split(parts[4], ":")[1]
+	}
+
 	return SnapshotInfo{
-		Time:       ts,
-		ObjectID:   parts[3],
-		SnapshotID: snapID,
+		Time:             ts,
+		ObjectID:         parts[3],
+		SnapshotID:       snapID,
+		Incomplete:       incomplete,
+		IncompleteReason: incompleteReason,
 	}
 }
 
diff --git a/tests/end_to_end_test/snapshot_create_test.go b/tests/end_to_end_test/snapshot_create_test.go
index 400ab9b9..8ffef912 100644
--- a/tests/end_to_end_test/snapshot_create_test.go
+++ b/tests/end_to_end_test/snapshot_create_test.go
@@ -1,6 +1,7 @@
 package endtoend_test
 
 import (
+	"math/rand"
 	"os"
 	"path"
 	"path/filepath"
@@ -17,6 +18,7 @@
 
 	"github.com/kopia/kopia/cli"
 	"github.com/kopia/kopia/internal/cachedir"
+	"github.com/kopia/kopia/internal/clock"
 	"github.com/kopia/kopia/internal/testutil"
 	"github.com/kopia/kopia/snapshot"
 	"github.com/kopia/kopia/snapshot/policy"
@@ -799,3 +801,61 @@ func TestSnapshotCreateWithAllAndPath(t *testing.T) {
 	e.RunAndExpectSuccess(t, "snapshot", "create", sharedTestDataDir2)
 	e.RunAndExpectFailure(t, "snapshot", "create", sharedTestDataDir1, "--all")
 }
+
+func TestSnapshotNoLeftoverCheckpoints(t *testing.T) {
+	// 1 GiB of data seems to be enough for the snapshot time to exceed one second.
+	const (
+		fileSize                  = 1 << 30
+		checkpointInterval        = "1s"
+		checkpointIntervalSeconds = 1
+	)
+
+	t.Parallel()
+
+	runner := testenv.NewInProcRunner(t)
+	e := testenv.NewCLITest(t, testenv.RepoFormatNotImportant, runner)
+
+	defer e.RunAndExpectSuccess(t, "repo", "disconnect")
+
+	e.RunAndExpectSuccess(t, "repo", "create", "filesystem", "--path", e.RepoDir)
+
+	baseDir := testutil.TempDirectory(t)
+	files := []testFileEntry{
+		{
+			Name: "/foo",
+			Content: []string{
+				generateRandomLetters(fileSize),
+			},
+		},
+	}
+
+	require.NoError(t, createFileStructure(baseDir, files))
+
+	startTime := clock.Now()
+
+	e.RunAndExpectSuccess(t, "snapshot", "create", baseDir, "--checkpoint-interval", checkpointInterval)
+
+	endTime := clock.Now()
+
+	snapshotTimeSurpassedCheckpointInterval := endTime.Sub(startTime).Seconds() > checkpointIntervalSeconds
+	require.True(t, snapshotTimeSurpassedCheckpointInterval)
+
+	// This exploits the implementation detail of `ListSnapshotsAndExpectSuccess`, that it does
+	// not sanitize `targets` to exclude flags.
+	si := clitestutil.ListSnapshotsAndExpectSuccess(t, e, "--incomplete", baseDir)
+	require.Len(t, si, 1)
+	require.Len(t, si[0].Snapshots, 1)
+	require.False(t, si[0].Snapshots[0].Incomplete)
+}
+
+// https://stackoverflow.com/a/31832326
+func generateRandomLetters(n int) string {
+	const letterBytes = "abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ"
+
+	b := make([]byte, n)
+	for i := range b {
+		b[i] = letterBytes[rand.Int63()%int64(len(letterBytes))]
+	}
+
+	return string(b)
+}