Avoiding Bisync 'times are equal' conflicts with newer?

In a recent but now closed thread I reported an issue with a conflict where no winner could be determined: Avoiding bisync conflicts: No winner can be determined

I am unsure if the access times of the conflict files helps or not:

-rw-rw-r--  1 salty salty    854 Jun 27 15:32 pom.xml.conflict1
-rw-rw-r--  1 salty salty   1134 Jun 27 15:48 pom.xml.conflict2

My rclone version v1.67.0, config, and everything else is the same as that thread.

Here is every mention of the file from the logs:

2024/06/20 17:14:35 INFO  : - Path2             File is new                                 - code/mod1234/labs/lab2/task3/pom.xml
2024/06/20 17:14:35 INFO  : - Path2             Queue copy to Path1                         - idrive-sync-crypt:/code/mod1234/labs/lab2/task3/pom.xml
2024/06/20 17:14:48 INFO  : code/mod1234/labs/lab2/task3/pom.xml: Copied (new)
2024/06/20 17:24:48 INFO  : - Path2             File changed: size (larger), time (newer)   - code/mod1234/labs/lab2/task3/pom.xml
2024/06/20 17:24:48 INFO  : - Path2             Queue copy to Path1                         - idrive-sync-crypt:/code/mod1234/labs/lab2/task3/pom.xml
2024/06/20 17:24:51 INFO  : code/mod1234/labs/lab2/task3/pom.xml: Copied (replaced existing)
2024/06/27 15:39:06 INFO  : - Path2             File changed: size (larger), time (newer)   - code/mod1234/labs/lab2/task3/pom.xml
2024/06/27 15:39:09 INFO  : - Path2             Queue copy to Path1                         - idrive-sync-crypt:/code/mod1234/labs/lab2/task3/pom.xml
2024/06/27 15:39:11 INFO  : code/mod1234/labs/lab2/task3/pom.xml: Copied (replaced existing)
2024/06/27 15:44:10 INFO  : - Path1             File changed: size (larger), time (newer)   - code/mod1234/labs/lab2/task3/pom.xml
2024/06/27 15:44:10 INFO  : - Path2             File changed: size (larger), time (newer)   - code/mod1234/labs/lab2/task3/pom.xml
2024/06/27 15:44:13 NOTICE: - WARNING           New or changed in both paths                - code/mod1234/labs/lab2/task3/pom.xml
2024/06/27 15:44:13 INFO  : Files are equal! Skipping: code/mod1234/labs/lab2/task3/pom.xml
2024/06/27 15:44:28 ERROR : code/mod1234/labs/lab2/task3/pom.xml: failed to check as hash is missing
2024/06/27 15:44:28 INFO  : code/mod1234/labs/lab2/task3/pom.xml: files not equal on recheck: code/mod1234/labs/lab2/task3/pom.xml code/mod1234/labs/lab2/task3/pom.xml
2024/06/27 15:44:32 ERROR : code/mod1234/labs/lab2/task3/pom.xml: failed to check as hash is missing
2024/06/27 15:44:32 INFO  : code/mod1234/labs/lab2/task3/pom.xml: files not equal on recheck: code/mod1234/labs/lab2/task3/pom.xml code/mod1234/labs/lab2/task3/pom.xml
2024/06/27 15:49:09 INFO  : - Path1             File changed: size (larger), time (newer)   - code/mod1234/labs/lab2/task3/pom.xml
2024/06/27 15:49:09 INFO  : - Path2             File changed: size (larger), time (newer)   - code/mod1234/labs/lab2/task3/pom.xml
2024/06/27 15:49:12 ERROR : code/mod1234/labs/lab2/task3/pom.xml: sizes differ
2024/06/27 15:49:12 NOTICE: - WARNING           New or changed in both paths                - code/mod1234/labs/lab2/task3/pom.xml
2024/06/27 15:49:12 INFO  : code/mod1234/labs/lab2/task3/pom.xml: Winner cannot be determined as times are equal. Path1: 2024-06-27 15:32:18.243949971 +0100 IST, Path2: 2024-06-27 15:32:18.243949971 +0100 IST, Difference: 0s
2024/06/27 15:49:12 INFO  : code/mod1234/labs/lab2/task3/pom.xml: A winner could not be determined.
2024/06/27 15:49:12 NOTICE: - Path1             Renaming Path1 copy                         - idrive-sync-crypt:/code/mod1234/labs/lab2/task3/pom.xml.conflict1
2024/06/27 15:49:13 INFO  : code/mod1234/labs/lab2/task3/pom.xml: Copied (server-side copy) to: code/mod1234/labs/lab2/task3/pom.xml.conflict1
2024/06/27 15:49:13 INFO  : code/mod1234/labs/lab2/task3/pom.xml: Deleted
2024/06/27 15:49:13 NOTICE: - Path1             Queue copy to Path2                         - local{b6816}:/home/daire/sync/code/mod1234/labs/lab2/task3/pom.xml.conflict1
2024/06/27 15:49:13 NOTICE: - Path2             Renaming Path2 copy                         - local{b6816}:/home/daire/sync/code/mod1234/labs/lab2/task3/pom.xml.conflict2
2024/06/27 15:49:13 INFO  : code/mod1234/labs/lab2/task3/pom.xml: Moved (server-side) to: code/mod1234/labs/lab2/task3/pom.xml.conflict2
2024/06/27 15:49:13 NOTICE: - Path2             Queue copy to Path1                         - idrive-sync-crypt:/code/mod1234/labs/lab2/task3/pom.xml.conflict2
2024/06/27 15:49:16 INFO  : code/mod1234/labs/lab2/task3/pom.xml.conflict2: Copied (new)
2024/06/27 15:49:19 INFO  : code/mod1234/labs/lab2/task3/pom.xml.conflict1: Copied (new)

If relevant I normally only develop on either my laptop or desktop at different locations and hours apart, so it should not be the case I was making changes to this file before they could be synced to the cloud and then to my other computer. Comparing the files conflict2 has a few extra lines I added, rather than the changes made in my last thread which were from using Find in Files to Replace all of a string with VS Code.

@nielash did already suggest --conflict-resolve path2 as an alternative to using newer but I am unsure if that is a good fit, although this may be due to my ignorance of exactly how this works. I would assume that where a file exists on the cloud newer than on the laptop or desktop that encounters it, that newer file should be synced to the local, otherwise the local should be synced to the cloud, this way my most recent work is preserved.

Perhaps this is normally what happens, but conflicts deal with something more specific where the resolve choice comes into effect? Either way, what is causing these conflicts to occur, and how can I either prevent them or configure rclone to resolve them without affecting the work flow I have mentioned please?

Not necessarily, because firstly it's the modification time (not access time) that matters, and secondly, we'd need to know what it was at the time bisync encountered it (after the fact, it is probably just reflecting the time that bisync renamed it.)

However, your log does help us with this. On the following line, you can see that bisync thinks both sides have a modtime of 2024-06-27 15:32:18.243949971 +0100 IST:

2024/06/27 15:49:12 INFO  : code/mod1234/labs/lab2/task3/pom.xml: Winner cannot be determined as times are equal. Path1: 2024-06-27 15:32:18.243949971 +0100 IST, Path2: 2024-06-27 15:32:18.243949971 +0100 IST, Difference: 0s

So, if you really want to get to the bottom of this, you would need to figure out why the file on one of the sides has an incorrect modtime (according to what bisync can see) at the time that bisync is encountering it. My first guess (as I mentioned in the other thread) is that an application on your machine may be editing its content without properly updating its modtime.

I do have another suggestion though, which might solve your problem: use --compare size,modtime,checksum to add a comparison based on hash. This should catch any files that have a change to their content without a corresponding change to their modtime. (Note that you should do a --resync when changing your --compare settings. See the docs for more details.)

The latter -- --conflict-resolve only comes into play when a file is new or changed on both sides relative to the prior sync. You can think of it as sort of a "tie-breaker" setting. It does not matter in the normal case, where only one side is changed.

I'd try the checksum idea first and see if that solves your problem. But if not, it would be helpful to see a debug log (-vv) to track this down more easily.

1 Like

Modified time, not access time indeed. If the issue is with VS Code, the only application used on the problem files, unless I changed something using Gnome Files, I wonder why the issue only occurs sometimes.

Can you tell me if any of the lines prior to Winner cannot be determined indicate the problem starting to occur, or if everything is normal up until that point? Otherwise I can just better monitor the notifications I get on when there are errors in the log to try and catch if I just did anything differently before the error.

Also, is my understanding of what occurs here correct:

2024/06/27 15:39:06 INFO  : - Path2             File changed: size (larger), time (newer)   - code/mod1234/labs/lab2/task3/pom.xml
2024/06/27 15:39:09 INFO  : - Path2             Queue copy to Path1 

A newer version of the file (with reference to the listing bisync builds at the start of each scan - from both local and remote files?) on my local is detected, and synced to the remote overwriting the version there.

2024/06/27 15:44:10 INFO  : - Path1             File changed: size (larger), time (newer)   - code/mod1234/labs/lab2/task3/pom.xml
2024/06/27 15:44:10 INFO  : - Path2             File changed: size (larger), time (newer)   - code/mod1234/labs/lab2/task3/pom.xml
2024/06/27 15:44:13 NOTICE: - WARNING           New or changed in both paths

Something similar occurs, only this this time both the local and remote versions have a more recent mod time than the new listing that was built at the beginning of the scan, again based on the newly built listing?

I am sure I have this wrong, but the log reads as if both files have an equal but more recent mod time than the listing that should have been created based on these very mod times a few minutes before this occurs?

What might cause the hash to be missing?

Thanks, I will try --compare size,modtime,checksum, which hopefully does not slow down the scan too much.

Then separate to how odd it may be that VS Code or my file manager is editing files without updating the mod time, how can files be changed on both the local and remote, when I am waiting for a bisync successful to occur on my laptop prior to starting any work? Unless the copying of the file to the remote from the logs in my last is the change?

I completed a resync with --compare size,modtime,checksum first before letting it run without resync. Are these warnings about no hashes in common and falling back to --compare modtime, size expected?

~$ rclone bisync "idrive-sync-crypt:/" "/home/salty/sync/" --check-access --fast-list --verbose --filter-from=/home/salty/.config/rclone/filters --links --recover --ignore-checksum --compare size,modtime,checksum --error-on-no-transfer --conflict-resolve newer --resilient
2024/07/04 10:41:57 NOTICE: bisync is IN BETA. Don't use in production!
2024/07/04 10:41:57 NOTICE: Local file system at /home/salty/sync: --checksum is in use but Path1 and Path2 have no hashes in common; falling back to --compare modtime,size for sync. (Use --compare size or --size-only to ignore modtime)
2024/07/04 10:41:57 INFO  : Path1 hashes: []
2024/07/04 10:41:57 INFO  : Path2 hashes: [md5, sha1, whirlpool, crc32, sha256, dropbox, hidrive, mailru, quickxor]
2024/07/04 10:41:57 NOTICE: Local file system at /home/salty/sync: will use md5 for same-side diffs on Path2 only
2024/07/04 10:41:57 NOTICE: WARNING: Checksums will be compared for deltas but not during sync as --checksum is not set.
2024/07/04 10:41:57 INFO  : Bisyncing with Comparison Settings:
{
	"Modtime": true,
	"Size": true,
	"Checksum": true,
	"HashType1": 0,
	"HashType2": 1,
	"NoSlowHash": false,
	"SlowHashSyncOnly": false,
	"SlowHashDetected": true,
	"DownloadHash": false
}
2024/07/04 10:41:57 INFO  : Synching Path1 "idrive-sync-crypt:/" with Path2 "local{b6816}:/home/salty/sync/"
2024/07/04 10:41:57 INFO  : Building Path1 and Path2 listings

New errors.

Bisync was successful before I made any changes.

I think my actions were:

mvn clean
edit 2 files in VS Code
mvn compile
mvn clean install

Pastebin logs

Is the -vv log only necessary for the issue that creates conflict files, rather than this new one?

EDIT: Not long after posting I noticed a few more of the automated bisync runs managed to resolve the issue. I also noticed that before the beginning of the log above, which starts with a Bisync successful, there were previous errors, also resolved. This new log provides more context: https://pastebin.com/ZSeBjgTj

Thanks for the logs -- very helpful. I think I see what's happening.

These are appearing because your Path2 (local) supports hashes, but your Path1 (crypt) does not. This is not necessarily a problem (hash support on both paths is not a requirement to use bisync) but you may want to consider wrapping your Path1 in a Hasher remote to allow both sides to support checksums (this is what I do when I bisync a crypt remote, and it works well). Alternatively, you could consider using --download-hash (but make sure to read about how it works first.)

The missing hash on Path1 is also responsible for these errors:

2024/06/27 15:44:28 ERROR : code/mod1234/labs/lab2/task3/pom.xml: failed to check as hash is missing
2024/06/27 15:44:28 INFO  : code/mod1234/labs/lab2/task3/pom.xml: files not equal on recheck: code/mod1234/labs/lab2/task3/pom.xml code/mod1234/labs/lab2/task3/pom.xml

Normally, in this particular part of the code, bisync is smart enough to detect that you're using crypt and accordingly use cryptcheck instead of check for these equality checks. However, you've disabled this by using --ignore-checksum. So, I would recommend removing --ignore-checksum, and then I think this will start doing what you want.

If my theory above is correct, all the stuff about the modtime is a red herring. What's happening is that the checksum settings are sending this into an endless cycle: we can't check if the files are equal because of --ignore-checksum, so we roll back the modtime in the listing to make sure it is "retried" on the next run. But on the next run, the hash is still missing and uncheckable, so we do the same thing again, repeatedly. (Whereas normally, the recheck would confirm that the files are equal, and we would update the listing, and that would break out of the cycle.)

Let me know if removing --ignore-checksum doesn't fix this!

1 Like

I had thought I read something in your post earlier about how rclone was reverting to modtime and size, not sure if I imagined that or this forum only shows edits on my own post!

I took a look at the hasher docs, is this as simple as just adding the default options to my config as below, and then editing my command to use "idrive-sync-hasher:/" for path1 instead of "idrive-sync-crypt:/", perhaps removing the existing line type = hasher from the [idrive-sync] block?

[idrive-sync]
type = s3
provider = IDrive
access_key_id = XXX
secret_access_key = XXX[[idrive-sync-hash]]
type = hasher
remote = myRemote:path
hashes = md5
max_age = off
acl = private
endpoint = x4y2.zk.idrivee6-11.com
bucket_acl = private
no_check_bucket = true
server_side_encryption = aws:kms

[idrive-sync-crypt]
type = crypt
remote = idrive-sync:sync
password = XXX
password2 = XXX
filename_encoding = base32768
### Double check the config for sensitive info before posting publicly

[idrive-sync-hasher]
type = hasher
remote = idrive-sync-crypt:
hashes = md5
max_age = off

In the interim, I removed --ignore-checksum and in case necessary I completed another --resync on both systems first. Can you please tell me once I setup the hasher, should I still use the command with the changes we have put in place for compare and now removing ignore checksum, or should I revert to my original version?

I wanted to flag the beginning of the output from the resync and subsequent scans (I thought they may differ but they do not) with you in case it is also not as expected now that --ignore-checksum has been removed:

~$ rclone bisync "idrive-sync-crypt:/" "/home/salty/sync/" --check-access --fast-list --verbose --filter-from=/home/salty/.config/rclone/filters --links --recover --compare size,modtime,checksum --error-on-no-transfer --conflict-resolve newer --resilient --resync
2024/07/05 09:15:21 NOTICE: bisync is IN BETA. Don't use in production!
2024/07/05 09:15:21 NOTICE: Local file system at /home/salty/sync: --checksum is in use but Path1 and Path2 have no hashes in common; falling back to --compare modtime,size for sync. (Use --compare size or --size-only to ignore modtime)
2024/07/05 09:15:21 INFO  : Path1 hashes: []
2024/07/05 09:15:21 INFO  : Path2 hashes: [md5, sha1, whirlpool, crc32, sha256, dropbox, hidrive, mailru, quickxor]
2024/07/05 09:15:21 NOTICE: Local file system at /home/salty/sync: will use md5 for same-side diffs on Path2 only
2024/07/05 09:15:21 NOTICE: WARNING: Checksums will be compared for deltas but not during sync as --checksum is not set.
2024/07/05 09:15:21 INFO  : Bisyncing with Comparison Settings: 
{
	"Modtime": true,
	"Size": true,
	"Checksum": true,
	"HashType1": 0,
	"HashType2": 1,
	"NoSlowHash": false,
	"SlowHashSyncOnly": false,
	"SlowHashDetected": true,
	"DownloadHash": false
}

Yes that's basically the idea. I think you might need to set a large auto_size value though, to make sure hashes are generated despite crypt lacking support. I use this:

[hasher_encrypted]
type = hasher
remote = encrypted:
hashes = md5
max_age = 3M
auto_size = 107374182400

I'd recommend keeping it, but it's up to you. Comparing with size,modtime,checksum is more robust than the default of size,modtime.

This looks as expected, since your Path1 still lacks hash support for the moment. Once you start using hasher, that WARNING line should go away.

1 Like

EDIT: Good news first, no conflicts and so far I have been able to continue working, despite what I describe below.

I was working on the project for 50 minutes today before my script flagged md5: errors during hash march though while I was gathering the logs a subsequent run was successful, so it resolved itself.

It is great rclone was able to fix the issue itself though I wonder if some further optimisation may prevent the errors in the first place, especially as when it happens there is a flood of the same error on the same file.

Other than now using the hasher in place of the crypt, I have left my rclone command as it was rclone bisync "idrive-sync-hasher:/" "/home/salty/sync/" --check-access --fast-list --verbose --filter-from=/home/salty/.config/rclone/filters --links --recover --compare size,modtime,checksum --error-on-no-transfer --conflict-resolve newer --resilient

My config now reads:

[idrive-sync]
type = s3
provider = IDrive
access_key_id = XXX
secret_access_key = XXX
acl = private
endpoint = x4y2.zk.idrivee6-11.com
bucket_acl = private
no_check_bucket = true
server_side_encryption = aws:kms

[idrive-sync-crypt]
type = crypt
remote = idrive-sync:sync
password = XXX
password2 = XXX
filename_encoding = base32768

[idrive-sync-hasher]
type = hasher
remote = idrive-sync-crypt:
hashes = md5
max_age = 3M
auto_size = 107374182400
### Double check the config for sensitive info before posting publicly

To set this up on both systems, I disabled the timer, created the hasher, and then completed a --resync before re-enabling the timers. I have kept an eye on the logs, there were no errors but only very light use of the remote, and no development.

For context I have included the full log from today which had to be split in 2:

More obscure errors referencing memory:

panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x0 pc=0x1a825d4]

goroutine 1 [running]:
github.com/rclone/rclone/cmd/bisync.(*bisyncRun).modifyListing(0xc000d0a000, {0x2b90370, 0x3f29360}, {0x2ba5f50, 0xc000b585a0}, {0x2ba5770, 0xc00068e750}, {0xc000baa000, 0xe6, 0x124}, ...)
	github.com/rclone/rclone/cmd/bisync/listing.go:625 +0x28b4
github.com/rclone/rclone/cmd/bisync.(*bisyncRun).runLocked(0xc000d0a000, {0x2b90370, 0x3f29360})
	github.com/rclone/rclone/cmd/bisync/operations.go:404 +0x1d87
github.com/rclone/rclone/cmd/bisync.Bisync({0x2b90370, 0x3f29360}, {0x2ba5770, 0xc00068e750}, {0x2ba5f50, 0xc000b585a0}, 0xc0006bbb08)
	github.com/rclone/rclone/cmd/bisync/operations.go:172 +0x765
github.com/rclone/rclone/cmd/bisync.init.func1.1()
	github.com/rclone/rclone/cmd/bisync/cmd.go:194 +0x2f
github.com/rclone/rclone/cmd.Run(0x0, 0x1, 0x3e88960, 0xc0005efc30)
	github.com/rclone/rclone/cmd/cmd.go:255 +0x125
github.com/rclone/rclone/cmd/bisync.init.func1(0x3e88960, {0xc0005d8b40, 0x2, 0xf})
	github.com/rclone/rclone/cmd/bisync/cmd.go:193 +0x2fb
github.com/spf13/cobra.(*Command).execute(0x3e88960, {0xc0005d8a50, 0xf, 0xf})
	github.com/spf13/cobra@v1.8.0/command.go:983 +0xaca
github.com/spf13/cobra.(*Command).ExecuteC(0x3e87260)
	github.com/spf13/cobra@v1.8.0/command.go:1115 +0x3ff
github.com/spf13/cobra.(*Command).Execute(...)
	github.com/spf13/cobra@v1.8.0/command.go:1039
github.com/rclone/rclone/cmd.Main()
	github.com/rclone/rclone/cmd/cmd.go:568 +0x31
main.main()
	github.com/rclone/rclone/rclone.go:14 +0xf

Offending scan log:

  • This also resolved itself at some point on subsequent timer runs.

It looks like the full error is:

md5: error hashing during march: hash: failed to open: open /home/salty/sync/code/mod1234/labs/lab2/task3/dodgygeezers/target/surefire-reports/DodgygeezersUnitTest.txt: no such file or directory

The no such file or directory part makes me wonder if another application on your machine could have deleted the file while bisync was running. Is that possible?

This one looks like a bug, and I think I see the problem. Are you able to reproduce it consistently enough to test a fix?

1 Like

I have searched the logs over the last month and the runtime error only occurred that one time. If it occurs again I will report and note what I was doing. Otherwise please let me know if I can help with this some other way.

Yes that is very possible, I have been working with files as normal while bisync is triggered every 5 minutes. This includes editing and deleting files in VS Code and compiling etc. with Maven, and in my file manager manually deleting, moving, and renaming files and directories.

I am not manually moving files I have finished working on in and out of /home/salty/sync/, as that seems more like backup. Rather I use bisync on my working files, so that they can be synced automatically and seamlessly, without me having to think about it. I had assumed bisync was intended for this, or is that not the case?

I would ask if bisync tolerating working files is demonstrated by bisync encountering the errors I have reported, and then on some number of automated subsequent runs of the same command (other than lock files for inactive PIDs removed by script where necessary) with no manual intervention the runs again return bisync successful - but I guess if that was intended bisync might report warnings instead of errors?

Another conflict was created yesterday but this definitely occurs less.

If you can confirm I should be able to use bisync on a working directory as I have been, I can add -vv to the script command, and on error share the log, and if necessary take note of my most recent file modifications or operations?

Perhaps erroring on one scan and bisync successful on the next as below are normal and expected when working on files in a remote that has bisync running constantly?

This were my only actions before the error occurred:

  1. Confirmed bisync successful on laptop and desktop before making any changes
  2. Opened task4 in VS Code on desktop and then from the IDE terminal mvn clean install

It's not really specific to bisync -- the same thing could happen with sync. Basically, there is a small window of time between when a file is "listed" and when it is "checked" (including hash), and if that file is deleted in between, it would cause this error.

Bisync's --recover feature is designed to self-correct from these kinds of transitory issues on the next run. If subsequent runs are finishing successfully, I don't think it's anything to worry about.

It should usually work well for this use case. The one exception is if you have a unique kind of directory where it's important for the whole directory to be synced atomically, as bisync is only atomic at the file level (not the directory level).

For future reference what are these atomic directories used for?

Separate to other errors subsequent runs correct, there were some more conflict files generated today unfortunately - though still less than before adding the hasher.

I will come back with a -vv log for when this happens again.