Repository: syncthing/syncthing (language: go)

Issue:
Unexpected cleanup behavior for Simple File Versioning
### Issue
"Clean out after" setting removes files based on their last modified time (mtime)
### Expected Result
Files are removed based on when they were deleted (~datestamp tag value)

## Overview:

I had been following #6527 and #6884 and finally got around to trying it out in my deployment. Based on the cleanup documentation (https://docs.syncthing.net/users/versioning.html) I expected the behavior to follow "_If this is set to a positive number of days, files will be removed when they have been in the trash can that long_," however, on first run, clean up removed considerably more files than I expected (obviously, these files were already in the .stversions directory, so non-critical in this case). Based on quick look through the code, cleanByDay func called by both the Trash Can and Simple Versioning methods directly reference the file's ModTime (https://github.com/syncthing/syncthing/blob/main/lib/versioner/util.go#L318) and ignore the datestamp applied when the file was archived by the simple versioning process.

### Example/reproduce

- Clean out after is set to 30 days, runs once a day
- File (say, a picture) is modified on 2021-04-29
- File is deleted on 2021-10-02, and moved to .stversions
- File's mtime is unchanged (no content change)
- Clean runs later in the day, and immediately deletes the file because mtime is > 30 days in the past, even though the datestamp is less than 24 hours in the past

This could lead to a user deleting a file that was last modified greater than the "Clean out after" setting, and be unable to recover as the clean task removed it immediately on next run. Additionally, collecting logs for this behavior is difficult as the clean functions do not appear to have any debug logging - I can easily trace where a file is archived, but only see when the clean job is run, not specific files cleaned.




Discussion / hints:
You're 100% right. I've just tested this too.

1. Trash Can changes the file's mtime and performs cleanup based on that.
2. Staggered adds date to the filename and uses that for cleanup without changing the mtime.
3. Simple should be same as Staggered, but it's actually same as Trash Can right now. Yet, it doesn't update the mtime, making the versioner base its decisions on the original mtime.

In my testing, I set the cleanup interval to `10` with the maximum age set to `30`. Next, I deleted a 6-month-old file, which was then send to `.stversions` on the other device. The file was wiped out from there almost immediately.
> This could lead to a user deleting a file that was last modified greater than the "Clean out after" setting, and be unable to recover as the clean task removed it immediately on next run.

That is exactly what happend to me... Fortunately I was able to recover the files from an external source.
I think this is a serious issue, because it is hard to detect while testing the versioning (it works with newer files) and could lead to preventable data loss.

Is there a recommended workaround until the problem is fixed?
> Is there a recommended workaround until the problem is fixed?

There is no workaround unless you re-implement the same logic using a custom script with external versioning. Otherwise, I'd suggest to switch to staggered for now (yes, it's not the same and can potentially use much more disk space, but it's definitely better than the unexpected early deletions).
Just for the record, the cleanup functionality hadn't originally been present in the Simple File Versioning at all. It was only added in https://github.com/syncthing/syncthing/pull/6884. However, it seems that the PR simply took out the Trashcan cleanup function, moved it to `lib/versioner/util.go`, and then re-used it as it was for Simple Versioning. This couldn't really work in practice, as the Trashcan cleanup is based on the fact that files have their mtime changed upon being moved to `.stversions`, and then they're cleaned up based on that changed mtime. In the case of Simple Versioning, there's no mtime change, so the Trashcan cleanup code is simply not suitable for it.

I assume that one way to fix the issue could be to move the Trashcan cleanup function from `lib/versioner/util.go` back to `lib/versioner/trashcan.go`, and then move the Staggered cleanup function from `lib/versioner/staggered.go` to `lib/versioner/util.go` instead, so that it could be re-used for both Staggered and Simple Versioning. I think this should work fine, as both Simple and Staggered Versioning seem to use the same version filename scheme (i.e. adding dates to versioned file names instead of relying on mtime).

Fix patch:
diff --git a/lib/versioner/simple.go b/lib/versioner/simple.go
index e4865116a01..1d173ba7fca 100644
--- a/lib/versioner/simple.go
+++ b/lib/versioner/simple.go
@@ -8,6 +8,7 @@ package versioner
 
 import (
 	"context"
+	"sort"
 	"strconv"
 	"time"
 
@@ -57,17 +58,7 @@ func (v simple) Archive(filePath string) error {
 		return err
 	}
 
-	// Versions are sorted by timestamp in the file name, oldest first.
-	versions := findAllVersions(v.versionsFs, filePath)
-	if len(versions) > v.keep {
-		for _, toRemove := range versions[:len(versions)-v.keep] {
-			l.Debugln("cleaning out", toRemove)
-			err = v.versionsFs.Remove(toRemove)
-			if err != nil {
-				l.Warnln("removing old version:", err)
-			}
-		}
-	}
+	cleanVersions(v.versionsFs, findAllVersions(v.versionsFs, filePath), v.toRemove)
 
 	return nil
 }
@@ -81,5 +72,40 @@ func (v simple) Restore(filepath string, versionTime time.Time) error {
 }
 
 func (v simple) Clean(ctx context.Context) error {
-	return cleanByDay(ctx, v.versionsFs, v.cleanoutDays)
+	return clean(ctx, v.versionsFs, v.toRemove)
+}
+
+func (v simple) toRemove(versions []string, now time.Time) []string {
+	var remove []string
+
+	// The list of versions may or may not be properly sorted.
+	sort.Strings(versions)
+
+	// If the amount of elements exceeds the limit: the oldest elements are to be removed.
+	if len(versions) > v.keep {
+		remove = versions[:len(versions)-v.keep]
+		versions = versions[len(versions)-v.keep:]
+	}
+
+	// If cleanoutDays is not a positive value then don't remove based on age.
+	if v.cleanoutDays <= 0 {
+		return remove
+	}
+
+	maxAge := time.Duration(v.cleanoutDays) * 24 * time.Hour
+
+	// For the rest of the versions, elements which are too old are to be removed
+	for _, version := range versions {
+		versionTime, err := time.ParseInLocation(TimeFormat, extractTag(version), time.Local)
+		if err != nil {
+			l.Debugf("Versioner: file name %q is invalid: %v", version, err)
+			continue
+		}
+
+		if now.Sub(versionTime) > maxAge {
+			remove = append(remove, version)
+		}
+	}
+
+	return remove
 }
diff --git a/lib/versioner/staggered.go b/lib/versioner/staggered.go
index 2a341590e19..6f844b19555 100644
--- a/lib/versioner/staggered.go
+++ b/lib/versioner/staggered.go
@@ -60,79 +60,7 @@ func newStaggered(cfg config.FolderConfiguration) Versioner {
 }
 
 func (v *staggered) Clean(ctx context.Context) error {
-	l.Debugln("Versioner clean: Cleaning", v.versionsFs)
-
-	if _, err := v.versionsFs.Stat("."); fs.IsNotExist(err) {
-		// There is no need to clean a nonexistent dir.
-		return nil
-	}
-
-	versionsPerFile := make(map[string][]string)
-	dirTracker := make(emptyDirTracker)
-
-	walkFn := func(path string, f fs.FileInfo, err error) error {
-		if err != nil {
-			return err
-		}
-		select {
-		case <-ctx.Done():
-			return ctx.Err()
-		default:
-		}
-
-		if f.IsDir() && !f.IsSymlink() {
-			dirTracker.addDir(path)
-			return nil
-		}
-
-		// Regular file, or possibly a symlink.
-		dirTracker.addFile(path)
-
-		name, _ := UntagFilename(path)
-		if name == "" {
-			return nil
-		}
-
-		versionsPerFile[name] = append(versionsPerFile[name], path)
-
-		return nil
-	}
-
-	if err := v.versionsFs.Walk(".", walkFn); err != nil {
-		l.Warnln("Versioner: error scanning versions dir", err)
-		return err
-	}
-
-	for _, versionList := range versionsPerFile {
-		select {
-		case <-ctx.Done():
-			return ctx.Err()
-		default:
-		}
-		v.expire(versionList)
-	}
-
-	dirTracker.deleteEmptyDirs(v.versionsFs)
-
-	l.Debugln("Cleaner: Finished cleaning", v.versionsFs)
-	return nil
-}
-
-func (v *staggered) expire(versions []string) {
-	l.Debugln("Versioner: Expiring versions", versions)
-	for _, file := range v.toRemove(versions, time.Now()) {
-		if fi, err := v.versionsFs.Lstat(file); err != nil {
-			l.Warnln("versioner:", err)
-			continue
-		} else if fi.IsDir() {
-			l.Infof("non-file %q is named like a file version", file)
-			continue
-		}
-
-		if err := v.versionsFs.Remove(file); err != nil {
-			l.Warnf("Versioner: can't remove %q: %v", file, err)
-		}
-	}
+	return clean(ctx, v.versionsFs, v.toRemove)
 }
 
 func (v *staggered) toRemove(versions []string, now time.Time) []string {
@@ -192,7 +120,7 @@ func (v *staggered) Archive(filePath string) error {
 		return err
 	}
 
-	v.expire(findAllVersions(v.versionsFs, filePath))
+	cleanVersions(v.versionsFs, findAllVersions(v.versionsFs, filePath), v.toRemove)
 
 	return nil
 }
diff --git a/lib/versioner/trashcan.go b/lib/versioner/trashcan.go
index a72d7b42e47..e300de92a67 100644
--- a/lib/versioner/trashcan.go
+++ b/lib/versioner/trashcan.go
@@ -56,7 +56,51 @@ func (t *trashcan) String() string {
 }
 
 func (t *trashcan) Clean(ctx context.Context) error {
-	return cleanByDay(ctx, t.versionsFs, t.cleanoutDays)
+	if t.cleanoutDays <= 0 {
+		return nil
+	}
+
+	if _, err := t.versionsFs.Lstat("."); fs.IsNotExist(err) {
+		return nil
+	}
+
+	cutoff := time.Now().Add(time.Duration(-24*t.cleanoutDays) * time.Hour)
+	dirTracker := make(emptyDirTracker)
+
+	walkFn := func(path string, info fs.FileInfo, err error) error {
+		if err != nil {
+			return err
+		}
+
+		select {
+		case <-ctx.Done():
+			return ctx.Err()
+		default:
+		}
+
+		if info.IsDir() && !info.IsSymlink() {
+			dirTracker.addDir(path)
+			return nil
+		}
+
+		if info.ModTime().Before(cutoff) {
+			// The file is too old; remove it.
+			err = t.versionsFs.Remove(path)
+		} else {
+			// Keep this file, and remember it so we don't unnecessarily try
+			// to remove this directory.
+			dirTracker.addFile(path)
+		}
+		return err
+	}
+
+	if err := t.versionsFs.Walk(".", walkFn); err != nil {
+		return err
+	}
+
+	dirTracker.deleteEmptyDirs(t.versionsFs)
+
+	return nil
 }
 
 func (t *trashcan) GetVersions() (map[string][]FileVersion, error) {
diff --git a/lib/versioner/util.go b/lib/versioner/util.go
index 07e76f14ee6..04809a2a467 100644
--- a/lib/versioner/util.go
+++ b/lib/versioner/util.go
@@ -287,50 +287,70 @@ func findAllVersions(fs fs.Filesystem, filePath string) []string {
 	return versions
 }
 
-func cleanByDay(ctx context.Context, versionsFs fs.Filesystem, cleanoutDays int) error {
-	if cleanoutDays <= 0 {
-		return nil
-	}
+func clean(ctx context.Context, versionsFs fs.Filesystem, toRemove func([]string, time.Time) []string) error {
+	l.Debugln("Versioner clean: Cleaning", versionsFs)
 
-	if _, err := versionsFs.Lstat("."); fs.IsNotExist(err) {
+	if _, err := versionsFs.Stat("."); fs.IsNotExist(err) {
+		// There is no need to clean a nonexistent dir.
 		return nil
 	}
 
-	cutoff := time.Now().Add(time.Duration(-24*cleanoutDays) * time.Hour)
+	versionsPerFile := make(map[string][]string)
 	dirTracker := make(emptyDirTracker)
 
-	walkFn := func(path string, info fs.FileInfo, err error) error {
+	walkFn := func(path string, f fs.FileInfo, err error) error {
 		if err != nil {
 			return err
 		}
-
 		select {
 		case <-ctx.Done():
 			return ctx.Err()
 		default:
 		}
 
-		if info.IsDir() && !info.IsSymlink() {
+		if f.IsDir() && !f.IsSymlink() {
 			dirTracker.addDir(path)
 			return nil
 		}
 
-		if info.ModTime().Before(cutoff) {
-			// The file is too old; remove it.
-			err = versionsFs.Remove(path)
-		} else {
-			// Keep this file, and remember it so we don't unnecessarily try
-			// to remove this directory.
-			dirTracker.addFile(path)
+		// Regular file, or possibly a symlink.
+		dirTracker.addFile(path)
+
+		name, _ := UntagFilename(path)
+		if name == "" {
+			return nil
 		}
-		return err
+
+		versionsPerFile[name] = append(versionsPerFile[name], path)
+
+		return nil
 	}
 
 	if err := versionsFs.Walk(".", walkFn); err != nil {
+		l.Warnln("Versioner: error scanning versions dir", err)
 		return err
 	}
 
+	for _, versionList := range versionsPerFile {
+		select {
+		case <-ctx.Done():
+			return ctx.Err()
+		default:
+		}
+		cleanVersions(versionsFs, versionList, toRemove)
+	}
+
 	dirTracker.deleteEmptyDirs(versionsFs)
 
+	l.Debugln("Cleaner: Finished cleaning", versionsFs)
 	return nil
 }
+
+func cleanVersions(versionsFs fs.Filesystem, versions []string, toRemove func([]string, time.Time) []string) {
+	l.Debugln("Versioner: Expiring versions", versions)
+	for _, file := range toRemove(versions, time.Now()) {
+		if err := versionsFs.Remove(file); err != nil {
+			l.Warnf("Versioner: can't remove %q: %v", file, err)
+		}
+	}
+}


Test patch:
diff --git a/lib/versioner/trashcan_test.go b/lib/versioner/trashcan_test.go
index 35bad47ce4d..348d2ac4176 100644
--- a/lib/versioner/trashcan_test.go
+++ b/lib/versioner/trashcan_test.go
@@ -7,7 +7,11 @@
 package versioner
 
 import (
+	"context"
+	"fmt"
 	"io"
+	"os"
+	"path/filepath"
 	"testing"
 	"time"
 
@@ -120,3 +124,70 @@ func writeFile(t *testing.T, filesystem fs.Filesystem, name, content string) {
 		t.Fatal(n, len(content), err)
 	}
 }
+
+func TestTrashcanCleanOut(t *testing.T) {
+	testDir := t.TempDir()
+
+	cfg := config.FolderConfiguration{
+		FilesystemType: fs.FilesystemTypeBasic,
+		Path:           testDir,
+		Versioning: config.VersioningConfiguration{
+			Params: map[string]string{
+				"cleanoutDays": "7",
+			},
+		},
+	}
+
+	fs := cfg.Filesystem(nil)
+
+	v := newTrashcan(cfg)
+
+	var testcases = map[string]bool{
+		".stversions/file1":                     false,
+		".stversions/file2":                     true,
+		".stversions/keep1/file1":               false,
+		".stversions/keep1/file2":               false,
+		".stversions/keep2/file1":               false,
+		".stversions/keep2/file2":               true,
+		".stversions/keep3/keepsubdir/file1":    false,
+		".stversions/remove/file1":              true,
+		".stversions/remove/file2":              true,
+		".stversions/remove/removesubdir/file1": true,
+	}
+
+	t.Run(fmt.Sprintf("trashcan versioner trashcan clean up"), func(t *testing.T) {
+		oldTime := time.Now().Add(-8 * 24 * time.Hour)
+		for file, shouldRemove := range testcases {
+			fs.MkdirAll(filepath.Dir(file), 0777)
+
+			writeFile(t, fs, file, "some content")
+
+			if shouldRemove {
+				if err := fs.Chtimes(file, oldTime, oldTime); err != nil {
+					t.Fatal(err)
+				}
+			}
+		}
+
+		if err := v.Clean(context.Background()); err != nil {
+			t.Fatal(err)
+		}
+
+		for file, shouldRemove := range testcases {
+			_, err := fs.Lstat(file)
+			if shouldRemove && !os.IsNotExist(err) {
+				t.Error(file, "should have been removed")
+			} else if !shouldRemove && err != nil {
+				t.Error(file, "should not have been removed")
+			}
+		}
+
+		if _, err := fs.Lstat(".stversions/keep3"); os.IsNotExist(err) {
+			t.Error("directory with non empty subdirs should not be removed")
+		}
+
+		if _, err := fs.Lstat(".stversions/remove"); !os.IsNotExist(err) {
+			t.Error("empty directory should have been removed")
+		}
+	})
+}
diff --git a/lib/versioner/versioner_test.go b/lib/versioner/versioner_test.go
deleted file mode 100644
index 4ba73c36c6a..00000000000
--- a/lib/versioner/versioner_test.go
+++ /dev/null
@@ -1,90 +0,0 @@
-// Copyright (C) 2020 The Syncthing Authors.
-//
-// This Source Code Form is subject to the terms of the Mozilla Public
-// License, v. 2.0. If a copy of the MPL was not distributed with this file,
-// You can obtain one at https://mozilla.org/MPL/2.0/.
-
-package versioner
-
-import (
-	"context"
-	"fmt"
-	"os"
-	"path/filepath"
-	"testing"
-	"time"
-
-	"github.com/syncthing/syncthing/lib/config"
-	"github.com/syncthing/syncthing/lib/fs"
-)
-
-func TestVersionerCleanOut(t *testing.T) {
-	cfg := config.FolderConfiguration{
-		FilesystemType: fs.FilesystemTypeBasic,
-		Path:           "testdata",
-		Versioning: config.VersioningConfiguration{
-			Params: map[string]string{
-				"cleanoutDays": "7",
-			},
-		},
-	}
-
-	testCasesVersioner := map[string]Versioner{
-		"simple":   newSimple(cfg),
-		"trashcan": newTrashcan(cfg),
-	}
-
-	var testcases = map[string]bool{
-		"testdata/.stversions/file1":                     false,
-		"testdata/.stversions/file2":                     true,
-		"testdata/.stversions/keep1/file1":               false,
-		"testdata/.stversions/keep1/file2":               false,
-		"testdata/.stversions/keep2/file1":               false,
-		"testdata/.stversions/keep2/file2":               true,
-		"testdata/.stversions/keep3/keepsubdir/file1":    false,
-		"testdata/.stversions/remove/file1":              true,
-		"testdata/.stversions/remove/file2":              true,
-		"testdata/.stversions/remove/removesubdir/file1": true,
-	}
-
-	for versionerType, versioner := range testCasesVersioner {
-		t.Run(fmt.Sprintf("%v versioner trashcan clean up", versionerType), func(t *testing.T) {
-			os.RemoveAll("testdata")
-			defer os.RemoveAll("testdata")
-
-			oldTime := time.Now().Add(-8 * 24 * time.Hour)
-			for file, shouldRemove := range testcases {
-				os.MkdirAll(filepath.Dir(file), 0777)
-				if err := os.WriteFile(file, []byte("data"), 0644); err != nil {
-					t.Fatal(err)
-				}
-				if shouldRemove {
-					if err := os.Chtimes(file, oldTime, oldTime); err != nil {
-						t.Fatal(err)
-					}
-				}
-			}
-
-			if err := versioner.Clean(context.Background()); err != nil {
-				t.Fatal(err)
-			}
-
-			for file, shouldRemove := range testcases {
-				_, err := os.Lstat(file)
-				if shouldRemove && !os.IsNotExist(err) {
-					t.Error(file, "should have been removed")
-				} else if !shouldRemove && err != nil {
-					t.Error(file, "should not have been removed")
-				}
-			}
-
-			if _, err := os.Lstat("testdata/.stversions/keep3"); os.IsNotExist(err) {
-				t.Error("directory with non empty subdirs should not be removed")
-			}
-
-			if _, err := os.Lstat("testdata/.stversions/remove"); !os.IsNotExist(err) {
-				t.Error("empty directory should have been removed")
-			}
-		})
-	}
-}