Repository: rclone/rclone (language: go)

Issue:
bisync through Dropbox+crypt constantly critically fails due to off-by-one differences in modtime
#### What is the problem you are having with rclone?

Almost everytime I run bisync first on one of my devices and then the other, bisync fails due to modtimes of multiple(not all) files on one of the endpoints being off by 1s


#### What is your rclone version (output from `rclone version`)

Android 14(crDroid): `v1.66.0-termux`
Manjaro Linux: `v1.67.0`


#### Which cloud storage system are you using? (e.g. Google Drive)

Dropbox, accessed through the crypt backend.

#### The command you were trying to run

On desktop: `rclone bisync Local:Documents/WorkingDocs Dropbox_crypt:WorkingDocs --fast-list --checkers 64 --transfers 32`

On mobile: `rclone bisync Dropbox_crypt:WorkingDocs Local:storage/shared/share/WorkingDocs --fast-list --checkers 64 --transfers 32`


#### A log from the command with the `-vv` flag

I don't want to repeat the failure yet again, so here's the self-explanatory output without the flag, with filenames anonymized:

```
2024/08/19 15:14:55 NOTICE: bisync is IN BETA. Don't use in production!
2024/08/19 15:15:08 ERROR : -          Modtime not equal in listing. Path1: 2022-03-20 19:14:59 +0000 UTC, Path2: 2022-03-20 19:14:58 +0000 UTC - Path1/File1.md
2024/08/19 15:15:08 ERROR : -          Modtime not equal in listing. Path1: 2021-05-14 11:59:18 +0000 UTC, Path2: 2021-05-14 11:59:17 +0000 UTC - Path1/Subdirectory/File2.pdf
2024/08/19 15:15:08 ERROR : -          Modtime not equal in listing. Path1: 2021-05-14 11:56:10 +0000 UTC, Path2: 2021-05-14 11:56:09 +0000 UTC - Path1/Subdirectory/File3.pdf

...this repeats several dozen times...

2024/08/19 15:15:08 ERROR : -          Modtime not equal in listing. Path1: 2021-05-14 11:59:24 +0000 UTC, Path2: 2021-05-14 11:59:23 +0000 UTC - Path4/File50.md
2024/08/19 15:15:08 ERROR : -          Modtime not equal in listing. Path1: 2022-02-06 20:33:42 +0000 UTC, Path2: 2022-02-06 20:33:41 +0000 UTC - Path5/File51.txt
2024/08/19 15:15:08 ERROR : Bisync critical error: path1 and path2 are out of sync, run --resync to recover
2024/08/19 15:15:08 ERROR : Bisync aborted. Must run --resync to recover.
```

#### How to use GitHub

* Please use the 👍 [reaction](https://blog.github.com/2016-03-10-add-reactions-to-pull-requests-issues-and-comments/) to show that you are affected by the same issue.
* Please don't comment if you have no relevant information to add. It's just extra noise for everyone subscribed to this issue.
* Subscribe to receive notifications on status change and new comments.


Discussion / hints:
I think this is because the `dropbox` backend rounds modtimes to second precision to get around an API limitation:

https://github.com/rclone/rclone/blob/4e708e59f2e21c9751e7023925071a2689a73d0f/backend/dropbox/dropbox.go#L1751-L1752

But this means that a time like `2022-03-20 19:14:58.500000000 +0000 UTC` will get rounded to `2022-03-20 19:14:59 +0000 UTC` and not `2022-03-20 19:14:58 +0000 UTC` (simply ignoring the extra precision) as bisync expects.

I think the line above should be using `Truncate` instead of `Round`, @ncw do agree?
Hmm. Does bisync use the Precision of the Fs? A one second precision should make these match shouldn't it? 

> I think the line above should be using `Truncate` instead of `Round`

That would make the timestamps less accurate wouldn't it?

I think bisync needs to be taking the precision of the two fses into account.

If we change the modtime rounding then it will likely cause rclone sync to re copy half the files so  care is needed with that option.

Bisync does already take the Fs precision into account:

https://github.com/rclone/rclone/blob/be448c9e1359ef7e61517575c93870d3c0ed3662/cmd/bisync/compare.go#L195-L215

But if the `modifyWindow` is `1s`, times that are exactly `1s` apart are not within the window. 

Perhaps it should be using `<=` and `>=` instead of `<` and `>`?

> That would make the timestamps less accurate wouldn't it?

In a sense yes, as any loss of precision is, by definition, less accurate. But I'm not sure I'd consider rounding down to be less accurate than rounding up, if thought of as just a loss of decimal places. And there is an advantage to truncating instead of rounding, as it means you can then use `.After()` to reliably determine which of two times has the greater precision. There is an example in the comment here:

https://github.com/rclone/rclone/blob/be448c9e1359ef7e61517575c93870d3c0ed3662/cmd/bisync/listing.go#L453-L469
@Asmageddon in case this is helpful to you in the short-term while we discuss the proper long-term fix: 
I think adding `--modify-window 2s` to your command would likely stop the critical errors.
Wow, I'm amazed at how quick the reply and analysis of the issue have been, complete with advice for a temp fix within less than half a day. Thanks :D 

`--modify-window 2s` seems to work, so far. So, thanks again :)
> Bisync does already take the Fs precision into account:

Ah yes, of course it does - sorry!

> https://github.com/rclone/rclone/blob/be448c9e1359ef7e61517575c93870d3c0ed3662/cmd/bisync/compare.go#L195-L215
> 
> But if the `modifyWindow` is `1s`, times that are exactly `1s` apart are not within the window.
> 
> Perhaps it should be using `<=` and `>=` instead of `<` and `>`?

I had a look through the other uses of modifyWindow and we seem to be quite consistent that the boundaries are not included in the modifyWindow.

(As an aside we should probably factor the modifyWindow comparison into a function in operations as we do it lots of times in the code!)

I think the problem must be elsewhere.

The modifyWindow comparisons assume that you've got the original precision on one side and the truncated/rounded precision on the other (note that Dropbox isn't the only backend to round the time if I remember correctly, some backends we give a full precision time to in RFC3339 format and they round it however they feel like).

So if you round 12:54:49.7 to 12:54:50 and then compare them with modify window then it will always be in the window.

What bisync is doing (I think) is truncating the actual time from 12:54:49.7 to 12:54:49 then comparing the modification time to what it gets back from the backend 12:54:50 which is now outside the window.

Could bisync keep that original time 12:54:49.7  and use that instead in the modifyWindow comparison? I guess not since it is comparing two backends.

Or alternatively we could do a bit of analysis... Let's say the backend A has a precision of PA, and B with PB and PA < PB

- precise time: t on source
- backend A time, tA = (t-PA, t+PA)  # this is the test that modify window does `(...)` being the open interval not including the endpoints
- backend B time: tB = (t-PB, t+PB)

We are comparing using PA (being the smaller) so we compare tB to see if it is in (t-PA, t+PA) which it should be since PB<PA. 

I'm not sure exactly what is happening in the bisync code so I've stopped the analysis here, but it gives us something to think about.

I think the truncation is throwing things out. Truncation effectively subtracts Precision/2 on average from the times.


> > That would make the timestamps less accurate wouldn't it?
> 
> In a sense yes, as any loss of precision is, by definition, less accurate. But I'm not sure I'd consider rounding down to be less accurate than rounding up, if thought of as just a loss of decimal places. And there is an advantage to truncating instead of rounding, as it means you can then use `.After()` to reliably determine which of two times has the greater precision.

I think if we want the backends to reliably round down then we will have to make an integration test for it and enforce it which is possible, but a fair amount of work.

Do you think that is the way we should be going?

Also note my concerns above about causing lots of resyncing! This won't be a problem for local <-> backend but could be for local <-> backend1 <-> backend2
> Could bisync keep that original time 12:54:49.7 and use that instead in the modifyWindow comparison?

I think actually it could, now that bisync considers the `modifyWindow` for same-side comparisons as well. I'm now remembering that the truncation stuff dates back to a time before we did that. Back then, it was problematic to save a listing with `12:54:49.7` for a backend that can't handle that precision, as on the next run the backend would report the time as `12:54:50` and bisync would think the file had changed. So the truncation was a workaround to anticipate this and proactively record the time with the precision we expect to receive next time. 

But now that we do consider the `modifyWindow`, I don't think it's a problem to save the time with extra precision. On the next run, bisync will compare it to the rounded time reported and if it's within the `modifyWindow`, it will treat them as equivalent. And therefore it should not matter whether the backend rounds up or down.

I will try this with the integration tests to make sure I'm not missing something, but I am optimistic that this is the answer.
> I will try this with the integration tests to make sure I'm not missing something, but I am optimistic that this is the answer.

Great news and crossed fingers!

Fix patch:
diff --git a/cmd/bisync/listing.go b/cmd/bisync/listing.go
index 8f6d8eb194a45..a95029abef5b7 100644
--- a/cmd/bisync/listing.go
+++ b/cmd/bisync/listing.go
@@ -43,8 +43,10 @@ var lineRegex = regexp.MustCompile(`^(\S) +(-?\d+) (\S+) (\S+) (\d{4}-\d\d-\d\dT
 const timeFormat = "2006-01-02T15:04:05.000000000-0700"
 
 // TZ defines time zone used in listings
-var TZ = time.UTC
-var tzLocal = false
+var (
+	TZ      = time.UTC
+	tzLocal = false
+)
 
 // fileInfo describes a file
 type fileInfo struct {
@@ -83,7 +85,7 @@ func (ls *fileList) has(file string) bool {
 	}
 	_, found := ls.info[file]
 	if !found {
-		//try unquoting
+		// try unquoting
 		file, _ = strconv.Unquote(`"` + file + `"`)
 		_, found = ls.info[file]
 	}
@@ -93,7 +95,7 @@ func (ls *fileList) has(file string) bool {
 func (ls *fileList) get(file string) *fileInfo {
 	info, found := ls.info[file]
 	if !found {
-		//try unquoting
+		// try unquoting
 		file, _ = strconv.Unquote(`"` + file + `"`)
 		info = ls.info[fmt.Sprint(file)]
 	}
@@ -420,7 +422,7 @@ func (b *bisyncRun) loadListingNum(listingNum int) (*fileList, error) {
 
 func (b *bisyncRun) listDirsOnly(listingNum int) (*fileList, error) {
 	var fulllisting *fileList
-	var dirsonly = newFileList()
+	dirsonly := newFileList()
 	var err error
 
 	if !b.opt.CreateEmptySrcDirs {
@@ -450,24 +452,6 @@ func (b *bisyncRun) listDirsOnly(listingNum int) (*fileList, error) {
 	return dirsonly, err
 }
 
-// ConvertPrecision returns the Modtime rounded to Dest's precision if lower, otherwise unchanged
-// Need to use the other fs's precision (if lower) when copying
-// Note: we need to use Truncate rather than Round so that After() is reliable.
-// (2023-11-02 20:22:45.552679442 +0000 < UTC 2023-11-02 20:22:45.553 +0000 UTC)
-func ConvertPrecision(Modtime time.Time, dst fs.Fs) time.Time {
-	DestPrecision := dst.Precision()
-
-	// In case it's wrapping an Fs with lower precision, try unwrapping and use the lowest.
-	if Modtime.Truncate(DestPrecision).After(Modtime.Truncate(fs.UnWrapFs(dst).Precision())) {
-		DestPrecision = fs.UnWrapFs(dst).Precision()
-	}
-
-	if Modtime.After(Modtime.Truncate(DestPrecision)) {
-		return Modtime.Truncate(DestPrecision)
-	}
-	return Modtime
-}
-
 // modifyListing will modify the listing based on the results of the sync
 func (b *bisyncRun) modifyListing(ctx context.Context, src fs.Fs, dst fs.Fs, results []Results, queues queues, is1to2 bool) (err error) {
 	queue := queues.copy2to1
@@ -533,13 +517,13 @@ func (b *bisyncRun) modifyListing(ctx context.Context, src fs.Fs, dst fs.Fs, res
 
 		// build src winners list
 		if result.IsSrc && result.Src != "" && (result.Winner.Err == nil || result.Flags == "d") {
-			srcWinners.put(result.Name, result.Size, ConvertPrecision(result.Modtime, src), result.Hash, "-", result.Flags)
+			srcWinners.put(result.Name, result.Size, result.Modtime, result.Hash, "-", result.Flags)
 			prettyprint(result, "winner: copy to src", fs.LogLevelDebug)
 		}
 
 		// build dst winners list
 		if result.IsWinner && result.Winner.Side != "none" && (result.Winner.Err == nil || result.Flags == "d") {
-			dstWinners.put(result.Name, result.Size, ConvertPrecision(result.Modtime, dst), result.Hash, "-", result.Flags)
+			dstWinners.put(result.Name, result.Size, result.Modtime, result.Hash, "-", result.Flags)
 			prettyprint(result, "winner: copy to dst", fs.LogLevelDebug)
 		}
 
@@ -623,7 +607,7 @@ func (b *bisyncRun) modifyListing(ctx context.Context, src fs.Fs, dst fs.Fs, res
 			}
 			if srcNewName != "" { // if it was renamed and not deleted
 				srcList.put(srcNewName, new.size, new.time, new.hash, new.id, new.flags)
-				dstList.put(srcNewName, new.size, ConvertPrecision(new.time, src), new.hash, new.id, new.flags)
+				dstList.put(srcNewName, new.size, new.time, new.hash, new.id, new.flags)
 			}
 			if srcNewName != srcOldName {
 				srcList.remove(srcOldName)
diff --git a/docs/content/bisync.md b/docs/content/bisync.md
index c51030df138ad..8f0bf4883dcfc 100644
--- a/docs/content/bisync.md
+++ b/docs/content/bisync.md
@@ -1812,6 +1812,12 @@ about _Unison_ and synchronization in general.
 
 ## Changelog
 
+### `v1.68`
+* Fixed an issue affecting backends that round modtimes to a lower precision.
+
+### `v1.67`
+* Added integration tests against all backends.
+
 ### `v1.66`
 * Copies and deletes are now handled in one operation instead of two
 * `--track-renames` and `--backup-dir` are now supported


Test patch: