Jwink3101 / syncrclone

Python-based bi-direction sync tool for rclone
MIT License
150 stars 13 forks source link

Issues on exfat #14

Closed llucax closed 2 years ago

llucax commented 2 years ago

Hi, I'm trying out this tool as I need a 2-way sync. One remote is nextcloud, the other one is a local exFAT. I'm having errors when syncrclone tries to write its own files, I think because mtimes can't be set properly.

I tried even with size in compare and other config where that can be set, and disabling setting the lock file, but nothing seems to make syncrclone without errors.

Is there any way to make this working having one remote with exFAT?

Here are some run logs (click to expand) Here is a run with `set_lock` and `mtime`: ```console $ syncrclone -i Fotos_syncrclone.py 2021-11-21 22:29:13: syncrclone (20211015.0.BETA) 2021-11-21 22:29:13: config path: 'Fotos_syncrclone.py' 2021-11-21 22:29:13: A: '/media/Fotos' 2021-11-21 22:29:13: B: 'cloud:Photos' 2021-11-21 22:29:13: rclone version: 2021-11-21 22:29:14: rclone: rclone v1.53.3-DEV 2021-11-21 22:29:14: rclone: - os/arch: linux/arm 2021-11-21 22:29:14: rclone: - go version: go1.15.5 2021-11-21 22:29:14: 2021-11-21 22:29:14: Running shell commands 2021-11-21 22:29:14: $ mount | egrep '^/dev/sd.1 on /media/Fotos type fuseblk' 2021-11-21 22:29:14: STDOUT: /dev/sdc1 on /media/Fotos type fuseblk (rw,nosuid,nodev,relatime,user_id=0,group_id=0,default_permissions,allow_other,blksize=4096,uhelper=udisks2) 2021-11-21 22:29:14: STDOUT: 2021-11-21 22:29:14: 2021-11-21 22:29:14: Refreshing file list on A '/media/Fotos' 2021-11-21 22:29:14: 0 files, 0.00 b 2021-11-21 22:29:14: Refreshing file list on B 'cloud:Photos' 2021-11-21 22:52:23: 92321 files, 539.36 gb 2021-11-21 22:52:23: 2021-11-21 22:52:23: Setting lock on A 2021-11-21 22:52:23: rclone: ERROR : LOCK_pi@cloud:pno9Z: Failed to copy: open /media/Fotos/.syncrclone/LOCK/LOCK_pi@cloud:pno9Z: no such file or directory 2021-11-21 22:52:23: rclone: ERROR : Attempt 1/3 failed with 1 errors and: open /media/Fotos/.syncrclone/LOCK/LOCK_pi@cloud:pno9Z: no such file or directory 2021-11-21 22:52:23: rclone: ERROR : LOCK_pi@cloud:pno9Z: Failed to copy: open /media/Fotos/.syncrclone/LOCK/LOCK_pi@cloud:pno9Z: no such file or directory 2021-11-21 22:52:23: rclone: ERROR : Attempt 2/3 failed with 1 errors and: open /media/Fotos/.syncrclone/LOCK/LOCK_pi@cloud:pno9Z: no such file or directory 2021-11-21 22:52:23: rclone: ERROR : LOCK_pi@cloud:pno9Z: Failed to copy: open /media/Fotos/.syncrclone/LOCK/LOCK_pi@cloud:pno9Z: no such file or directory 2021-11-21 22:52:23: rclone: ERROR : Attempt 3/3 failed with 1 errors and: open /media/Fotos/.syncrclone/LOCK/LOCK_pi@cloud:pno9Z: no such file or directory 2021-11-21 22:52:23: rclone: INFO : 0 / 0 Bytes, -, 0 Bytes/s, ETA - 2021-11-21 22:52:23: rclone: Failed to copyto: open /media/Fotos/.syncrclone/LOCK/LOCK_pi@cloud:pno9Z: no such file or directory 2021-11-21 22:52:23: RCLONE ERROR 2021-11-21 22:52:23: CMD ['rclone', 'copyto', '-v', '--stats-one-line', '--log-format', '', '--no-check-dest', '--ignore-times', '--no-traverse', '/tmp/tmpg_x16g2i/LOCK_pi@cloud:pno9Z', '/media/Fotos/.syncrclone/LOCK/LOCK_pi@cloud:pno9Z'] 2021-11-21 22:52:23: STDOUT and STDERR ERROR : LOCK_pi@cloud:pno9Z: Failed to copy: open /media/Fotos/.syncrclone/LOCK/LOCK_pi@cloud:pno9Z: no such file or directory ERROR : Attempt 1/3 failed with 1 errors and: open /media/Fotos/.syncrclone/LOCK/LOCK_pi@cloud:pno9Z: no such file or directory ERROR : LOCK_pi@cloud:pno9Z: Failed to copy: open /media/Fotos/.syncrclone/LOCK/LOCK_pi@cloud:pno9Z: no such file or directory ERROR : Attempt 2/3 failed with 1 errors and: open /media/Fotos/.syncrclone/LOCK/LOCK_pi@cloud:pno9Z: no such file or directory ERROR : LOCK_pi@cloud:pno9Z: Failed to copy: open /media/Fotos/.syncrclone/LOCK/LOCK_pi@cloud:pno9Z: no such file or directory ERROR : Attempt 3/3 failed with 1 errors and: open /media/Fotos/.syncrclone/LOCK/LOCK_pi@cloud:pno9Z: no such file or directory INFO : 0 / 0 Bytes, -, 0 Bytes/s, ETA - Failed to copyto: open /media/Fotos/.syncrclone/LOCK/LOCK_pi@cloud:pno9Z: no such file or directory ERROR. Dumping logs (with debug) to '/tmp/tmp8lorhogo/log.txt' 2021-11-21 22:52:23: ERROR: Command '['rclone', 'copyto', '-v', '--stats-one-line', '--log-format', '', '--no-check-dest', '--ignore-times', '--no-traverse', '/tmp/tmpg_x16g2i/LOCK_pi@cloud:pno9Z', '/media/Fotos/.syncrclone/LOCK/LOCK_pi@cloud:pno9Z']' returned non-zero exit status 1. ``` Here with `size` and no `set_lock` (I used a different B remote directory because the original was too big and taking too long to get the file list): ```console $ syncrclone -i Fotos_syncrclone.py 2021-11-22 00:34:00: syncrclone (20211015.0.BETA) 2021-11-22 00:34:00: config path: 'Fotos_syncrclone.py' 2021-11-22 00:34:00: A: '/media/Fotos' 2021-11-22 00:34:00: B: 'cloud:Photos/Webcam' 2021-11-22 00:34:00: rclone version: 2021-11-22 00:34:00: rclone: rclone v1.53.3-DEV 2021-11-22 00:34:00: rclone: - os/arch: linux/arm 2021-11-22 00:34:00: rclone: - go version: go1.15.5 2021-11-22 00:34:00: 2021-11-22 00:34:00: Running shell commands 2021-11-22 00:34:00: $ mount | egrep '^/dev/sd.1 on /media/Fotos type ' 2021-11-22 00:34:00: STDOUT: /dev/sdc1 on /media/Fotos type fuseblk (rw,nosuid,nodev,relatime,user_id=0,group_id=0,default_permissions,allow_other,blksize=4096,uhelper=udisks2) 2021-11-22 00:34:00: STDOUT: 2021-11-22 00:34:00: 2021-11-22 00:34:00: Refreshing file list on A '/media/Fotos' 2021-11-22 00:34:00: 0 files, 0.00 b 2021-11-22 00:34:00: Refreshing file list on B 'cloud:Photos/Webcam' 2021-11-22 00:34:04: 28 files, 1.59 mb 2021-11-22 00:34:04: 2021-11-22 00:34:04: 2021-11-22 00:34:04: Actions queued on A: 2021-11-22 00:34:04: 2021-11-22 00:34:04: Actions queued on B: 2021-11-22 00:34:04: 2021-11-22 00:34:04: (PLANNED) A >>> B 0 files, 0.00 b 2021-11-22 00:34:04: 2021-11-22 00:34:04: (PLANNED) A <<< B 28 files, 1.59 mb 2021-11-22 00:34:04: (PLANNED) Transfer A <<< B: '2020-12-20-111946.jpg' ... Would you like to continue? Y/[N]: y 2021-11-22 00:34:13: 2021-11-22 00:34:13: Performing Actions on A 2021-11-22 00:34:13: 2021-11-22 00:34:13: Performing Actions on B 2021-11-22 00:34:15: 2021-11-22 00:34:15: A >>> B 0 files, 0.00 b 2021-11-22 00:34:15: 2021-11-22 00:34:15: A <<< B 28 files, 1.59 mb 2021-11-22 00:34:38: rclone: ERROR : 2020-12-20-111657.jpg: Failed to copy: chtimes /media/Fotos/2020-12-20-111657.jpg: operation not permitted .... 2021-11-22 00:34:53: rclone: INFO : There was nothing to transfer 2021-11-22 00:34:53: rclone: ERROR : Attempt 1/3 failed with 28 errors and: chtimes /media/Fotos/2021-11-20-174407.jpg: operation not permitted 2021-11-22 00:35:16: rclone: ERROR : 2020-12-20-111525.jpg: Failed to copy: chtimes /media/Fotos/2020-12-20-111525.jpg: operation not permitted .... 2021-11-22 00:35:17: rclone: INFO : 1.793M / 2.908 MBytes, 62%, 79.005 kBytes/s, ETA 14s (xfr#0/24) 2021-11-22 00:35:19: rclone: ERROR : 2020-12-20-111752.jpg: Failed to copy: chtimes /media/Fotos/2020-12-20-111752.jpg: operation not permitted .... 2021-11-22 00:35:32: rclone: INFO : There was nothing to transfer 2021-11-22 00:35:32: rclone: ERROR : Attempt 2/3 failed with 28 errors and: chtimes /media/Fotos/2021-11-20-172706.jpg: operation not permitted 2021-11-22 00:35:52: rclone: ERROR : 2020-12-20-111657.jpg: Failed to copy: chtimes /media/Fotos/2020-12-20-111657.jpg: operation not permitted .... 2021-11-22 00:36:07: rclone: INFO : There was nothing to transfer 2021-11-22 00:36:07: rclone: ERROR : Attempt 3/3 failed with 28 errors and: chtimes /media/Fotos/2021-11-20-174407.jpg: operation not permitted 2021-11-22 00:36:07: rclone: INFO : 4.774M / 4.774 MBytes, 100%, 88.149 kBytes/s, ETA 0s 2021-11-22 00:36:07: rclone: Failed to copy with 28 errors: last error was: chtimes /media/Fotos/2021-11-20-174407.jpg: operation not permitted 2021-11-22 00:36:07: RCLONE ERROR 2021-11-22 00:36:07: CMD ['rclone', 'copy', '-v', '--stats-one-line', '--log-format', '', '--ignore-times', '--no-traverse', '--files-from', '/tmp/tmpf6mxpr7vB2A_transfer', 'cloud:Photos/Webcam', '/media/Fotos'] 2021-11-22 00:36:07: STDOUT and STDERR ERROR : 2020-12-20-111657.jpg: Failed to copy: chtimes /media/Fotos/2020-12-20-111657.jpg: operation not permitted ERROR : 2020-10-14-134309.jpg: Failed to copy: chtimes /media/Fotos/2020-10-14-134309.jpg: operation not permitted .... INFO : There was nothing to transfer ERROR : Attempt 1/3 failed with 28 errors and: chtimes /media/Fotos/2021-11-20-174407.jpg: operation not permitted ERROR : 2020-12-20-111525.jpg: Failed to copy: chtimes /media/Fotos/2020-12-20-111525.jpg: operation not permitted .... INFO : 1.793M / 2.908 MBytes, 62%, 79.005 kBytes/s, ETA 14s (xfr#0/24) ERROR : 2020-12-20-111752.jpg: Failed to copy: chtimes /media/Fotos/2020-12-20-111752.jpg: operation not permitted .... INFO : There was nothing to transfer ERROR : Attempt 3/3 failed with 28 errors and: chtimes /media/Fotos/2021-11-20-174407.jpg: operation not permitted INFO : 4.774M / 4.774 MBytes, 100%, 88.149 kBytes/s, ETA 0s Failed to copy with 28 errors: last error was: chtimes /media/Fotos/2021-11-20-174407.jpg: operation not permitted ERROR. Dumping logs (with debug) to '/tmp/tmpgr8x0cih/log.txt' 2021-11-22 00:36:07: ERROR: Command '['rclone', 'copy', '-v', '--stats-one-line', '--log-format', '', '--ignore-times', '--no-traverse', '--files-from', '/tmp/tmpf6mxpr7vB2A_transfer', 'cloud:Photos/Webcam', '/media/Fotos']' returned non-zero exit status 1. ``` The files were copied though, but there was nothing in `/media/Fotos/.syncrclone` which I guess is a bad thing if 2-way sync need to keep state. A try with `hash` as compare ends up with this message: ``` 2021-11-22 00:38:40: ERROR: No common hashes found and/or one or both remotes do not provide hashes ``` Trying again with `mtime` and `no_lock` (now with the existing files that were transferred with `size`): ```console $ syncrclone -i Fotos_syncrclone.py 2021-11-22 00:40:22: syncrclone (20211015.0.BETA) 2021-11-22 00:40:22: config path: 'Fotos_syncrclone.py' 2021-11-22 00:40:22: A: '/media/Fotos' 2021-11-22 00:40:22: B: 'cloud:Photos/Webcam' 2021-11-22 00:40:22: rclone version: 2021-11-22 00:40:23: rclone: rclone v1.53.3-DEV 2021-11-22 00:40:23: rclone: - os/arch: linux/arm 2021-11-22 00:40:23: rclone: - go version: go1.15.5 2021-11-22 00:40:23: 2021-11-22 00:40:23: Running shell commands 2021-11-22 00:40:23: $ mount | egrep '^/dev/sd.1 on /media/Fotos type ' 2021-11-22 00:40:23: STDOUT: /dev/sdc1 on /media/Fotos type fuseblk (rw,nosuid,nodev,relatime,user_id=0,group_id=0,default_permissions,allow_other,blksize=4096,uhelper=udisks2) 2021-11-22 00:40:23: STDOUT: 2021-11-22 00:40:23: 2021-11-22 00:40:23: Refreshing file list on A '/media/Fotos' 2021-11-22 00:40:23: 28 files, 1.59 mb 2021-11-22 00:40:23: Refreshing file list on B 'cloud:Photos/Webcam' 2021-11-22 00:40:27: 28 files, 1.59 mb 2021-11-22 00:40:27: 2021-11-22 00:40:27: 2021-11-22 00:40:27: Actions queued on A: 2021-11-22 00:40:27: 2021-11-22 00:40:27: Actions queued on B: 2021-11-22 00:40:27: 2021-11-22 00:40:27: (PLANNED) A >>> B 0 files, 0.00 b 2021-11-22 00:40:27: 2021-11-22 00:40:27: (PLANNED) A <<< B 0 files, 0.00 b Would you like to continue? Y/[N]: y 2021-11-22 00:40:34: 2021-11-22 00:40:34: Performing Actions on A 2021-11-22 00:40:34: 2021-11-22 00:40:34: Performing Actions on B 2021-11-22 00:40:36: 2021-11-22 00:40:36: A >>> B 0 files, 0.00 b 2021-11-22 00:40:36: 2021-11-22 00:40:36: A <<< B 0 files, 0.00 b 2021-11-22 00:40:36: 2021-11-22 00:40:36: No need to refresh file list on A 2021-11-22 00:40:36: No need to refresh file list on B 2021-11-22 00:40:39: Uploading filelists 2021-11-22 00:40:39: rclone stderr: 2021/11/22 00:40:39 ERROR : A_curr: Failed to copy: chtimes /media/Fotos/.syncrclone/A-pi_cloud_pno9Z_fl.json.xz: operation not permitted 2021/11/22 00:40:39 ERROR : Attempt 1/3 failed with 1 errors and: chtimes /media/Fotos/.syncrclone/A-pi_cloud_pno9Z_fl.json.xz: operation not permitted 2021/11/22 00:40:39 ERROR : A-pi_cloud_pno9Z_fl.json.xz: Failed to set modification time: chtimes /media/Fotos/.syncrclone/A-pi_cloud_pno9Z_fl.json.xz: operation not permitted 2021/11/22 00:40:39 ERROR : Attempt 2/3 failed with 1 errors and: chtimes /media/Fotos/.syncrclone/A-pi_cloud_pno9Z_fl.json.xz: operation not permitted 2021/11/22 00:40:39 ERROR : A-pi_cloud_pno9Z_fl.json.xz: Failed to set modification time: chtimes /media/Fotos/.syncrclone/A-pi_cloud_pno9Z_fl.json.xz: operation not permitted 2021/11/22 00:40:39 ERROR : Attempt 3/3 failed with 1 errors and: chtimes /media/Fotos/.syncrclone/A-pi_cloud_pno9Z_fl.json.xz: operation not permitted 2021/11/22 00:40:39 Failed to copyto: chtimes /media/Fotos/.syncrclone/A-pi_cloud_pno9Z_fl.json.xz: operation not permitted 2021-11-22 00:40:39: RCLONE ERROR 2021-11-22 00:40:39: CMD ['rclone', 'copyto', '/tmp/tmp_81y82xb/A_curr', '/media/Fotos/.syncrclone/A-pi_cloud_pno9Z_fl.json.xz'] 2021-11-22 00:40:39: STDOUT 2021-11-22 00:40:39: STDERR 2021/11/22 00:40:39 ERROR : A_curr: Failed to copy: chtimes /media/Fotos/.syncrclone/A-pi_cloud_pno9Z_fl.json.xz: operation not permitted 2021/11/22 00:40:39 ERROR : Attempt 1/3 failed with 1 errors and: chtimes /media/Fotos/.syncrclone/A-pi_cloud_pno9Z_fl.json.xz: operation not permitted 2021/11/22 00:40:39 ERROR : A-pi_cloud_pno9Z_fl.json.xz: Failed to set modification time: chtimes /media/Fotos/.syncrclone/A-pi_cloud_pno9Z_fl.json.xz: operation not permitted 2021/11/22 00:40:39 ERROR : Attempt 2/3 failed with 1 errors and: chtimes /media/Fotos/.syncrclone/A-pi_cloud_pno9Z_fl.json.xz: operation not permitted 2021/11/22 00:40:39 ERROR : A-pi_cloud_pno9Z_fl.json.xz: Failed to set modification time: chtimes /media/Fotos/.syncrclone/A-pi_cloud_pno9Z_fl.json.xz: operation not permitted 2021/11/22 00:40:39 ERROR : Attempt 3/3 failed with 1 errors and: chtimes /media/Fotos/.syncrclone/A-pi_cloud_pno9Z_fl.json.xz: operation not permitted 2021/11/22 00:40:39 Failed to copyto: chtimes /media/Fotos/.syncrclone/A-pi_cloud_pno9Z_fl.json.xz: operation not permitted ERROR. Dumping logs (with debug) to '/tmp/tmp6oi38_uk/log.txt' 2021-11-22 00:40:39: ERROR: Command '['rclone', 'copyto', '/tmp/tmp_81y82xb/A_curr', '/media/Fotos/.syncrclone/A-pi_cloud_pno9Z_fl.json.xz']' returned non-zero exit status 1. ``` The file `/media/Fotos/.syncrclone/A-pi_cloud_pno9Z_fl.json.xz` is also actually created and have some json that makes sense (`[{"Path": "2020-10-14-134309.jpg", "Size": 32165, "mtime": 1637537752.0}, ...]`).
Jwink3101 commented 2 years ago

These errors are happening inside rclone, not syncrclone.

First, before doing anything else, update rclone. You're four major versions behind

But if that doesn't help, see if you can copy from your local machine to the external with rclone. See if you can do the 1-way sync with just rclone. What does that look like?

Jwink3101 commented 2 years ago

Not on mobile so I can add some more here.

Do note that just because you are not using mtime to compare or resolve, rclone still provides it by default. There is the following option (with documentation)

# Some remotes (e.g. S3) require an additional API call to get modtimes. If you
# are comparing with 'size' or 'hash', you can forgo this API call by setting
# this to False. Future versions may be smart about this and allow for 
# server-side modtime with a cache but that is not yet possible.
always_get_mtime = True 

but note you must set everything else using ModTime to false. See this line for the actual requirements imposed.

Also, notice in the logs it says things like

ERROR. Dumping logs (with debug) to '/tmp/tmp6oi38_uk/log.txt'

Can you post those? I really think this is an rclone issue but the question I have is whether you can tweak syncrclone to avoid it

Jwink3101 commented 2 years ago

One final note. I can't test your exact setup but on macOS, I created an exFAT disk image and ran the tests. It passes there too.

I think it would be good to understand why rclone (not syncrclone) can't write to your setup.

And I regularly do 2-5x the number of files from your 92321 files, 539.36 gb. Mine are smaller but scaling internally is based on number of files, not size. So I don't think that is the issue. And I do it on a super under-powered machines

llucax commented 2 years ago

Hi Justin, thanks a lot for the quick reply.

TL;DR It seems to be some weird exFAT issue. Using sudo makes it work (with mtime everywhere).

The drive was mounted by root, but permissions are shown as if everybody can write (as exFAT doesn´t really suppport unix permissions), so I assumed it was OK to do the sync with a regular user. Never came across this issue before with exFAT.

About the listing files taking too long, I blame Nextcloud 100% for that (it sucks), I also didn't want to imply it was a syncrclone (or rclone) issue. I was just mentioning it in case you saw discrepancies in the logs of different runs.

Thanks for the support again and sorry for the noise in the issue tracker. :)

Jwink3101 commented 2 years ago

I am glad it worked out for you. It is odd that you need sudo but if you don't mind doing it and the risks, then that works great!

File Listings

Yes, this is very frustrating and I run into it too. Especially with remotes that do not support ListR (in rclone's words).

It isn't actually slower than when rclone does it for a one-way sync except that rclone starts working right away while syncrclone has to wait.

Since your runs all errored, I can't see in the logs but make sure you set

avoid_relist = True

The default is False so you need to check it. This will save doing a second listing post-sync and instead propagate the new state over. It introduces some edge cases around move tracking with hashes but not horrible ones.

llucax commented 2 years ago

Thanks again for the tip. I'm still having issues though, and these seem to be rclone but doing a plain 1-way rclone instead it seems to work. I'm not sure if this is what you mean by

It isn't actually slower than when rclone does it for a one-way sync except that rclone starts working right away while syncrclone has to wait.

But I thought this was only the initial listing. What I get is this for the initial sync (there is nothing in the destination, B):

...
2021-11-23 21:41:16: Performing Actions on A                                                                                 
2021-11-23 21:41:16:                                                                                        
2021-11-23 21:41:16: Performing Actions on B                                                                                        
2021-11-23 21:41:19:                                                                                                                         
2021-11-23 21:41:19: A >>> B 0 files, 0.00 b                                  
2021-11-23 21:41:22:                                                          
2021-11-23 21:41:22: A <<< B 92369 files, 540.20 gb                           
2021-11-23 21:42:24: rclone: INFO  :          0 / 0 Bytes, -, 0 Bytes/s, ETA -
...
2021-11-24 09:05:24: rclone: INFO  :          0 / 0 Bytes, -, 0 Bytes/s, ETA -

So it's been running for ~12h and didn't even started copying anything. Is this to be expected? If not any ideas of what could be going on? Again, a plain rclone:

$ sudo rclone -v copy cloud:Photos /media/Fotos/Photos-test/
2021/11/24 09:01:39 INFO  : Screenshot_20210813_132134.png: Copied (new)
2021/11/24 09:01:39 INFO  : exif-date-fix.sh: Copied (new)
2021/11/24 09:01:39 INFO  : Screenshot_20211022_140201.png: Copied (new)
2021/11/24 09:01:42 INFO  : exif-fix-and-rename.sh: Copied (new)
2021/11/24 09:01:51 INFO  : exif-rename.sh: Copied (new)
...
Jwink3101 commented 2 years ago

I have a bunch of thoughts and questions. I will say though, this seems odd. It is clearly stuck in the rclone call but I wish to understand why.

How long is the actual file listing taking? What is the cloud: remote? Do setting locks work?

The way syncrclone works is that is has to list all of the files on both sides, decide what to sync, and then tell rclone to do that. You got to this last step.

The thing is, usually you are only syncing a few files out of a large set so --no-traverse flag is set for the sync. Reading this reply makes me think this is the issue. (hence why I also asked about the file listing times and the remote type).

The reason I asked if locks work is that setting them will confirm if rclone is working correctly. I know you say direct rclone is working but it would also be good to verify it is the same rclone. On that note, have you updated rclone to the latest?

If file listings are taking too long (you truncated the log...) that problem will never go away (though you can set --checkers) but that is a problem within rclone too.

Here is what I suggest:

I would test the above on some subdirectories first so it is faster and easier. Convince yourself that it is working as expected.

llucax commented 2 years ago

How long is the actual file listing taking?

2021-11-21 22:29:14: Refreshing file list on B 'cloud:Photos'                                                                                  
2021-11-21 22:52:23: 92321 files, 539.36 gb                                                                                                    

Around 23 minutes.

What is the cloud: remote?

Nextcloud running on the same machine I'm using syncrclone.

Do setting locks work?

I would say yes. After a Ctrl-C I even need to use the --break-lock both option.

Also doing it on a small folder works ``` 2021-11-24 20:41:16: syncrclone (20211015.0.BETA) 2021-11-24 20:41:16: config path: 'Fotos_syncrclone.py' 2021-11-24 20:41:16: WARNING: avoid_relist is experimental. Use with caution. 2021-11-24 20:41:16: A: '/media/Fotos/Webcam' 2021-11-24 20:41:16: B: 'cloud:Photos/Webcam' 2021-11-24 20:41:16: rclone version: 2021-11-24 20:41:16: rclone: rclone v1.53.3-DEV 2021-11-24 20:41:16: rclone: - os/arch: linux/arm 2021-11-24 20:41:16: rclone: - go version: go1.15.5 2021-11-24 20:41:16: 2021-11-24 20:41:16: Running shell commands 2021-11-24 20:41:16: $ mount | egrep '^/dev/sd.1 on /media/Fotos type ' 2021-11-24 20:41:16: STDOUT: /dev/sdc1 on /media/Fotos type fuseblk (rw,nosuid,nodev,relatime,user_id=0,group_id=0,default_permissions,allow_other,blksize=4096,uhelper=udisks2) 2021-11-24 20:41:16: STDOUT: 2021-11-24 20:41:16: 2021-11-24 20:41:16: Refreshing file list on A '/media/Fotos/Webcam' 2021-11-24 20:41:16: 0 files, 0.00 b 2021-11-24 20:41:16: Refreshing file list on B 'cloud:Photos/Webcam' 2021-11-24 20:41:21: 28 files, 1.59 mb 2021-11-24 20:41:21: 2021-11-24 20:41:21: Setting lock on A 2021-11-24 20:41:21: rclone: INFO : LOCK_pi_cloud_pno9Z: Copied (new) 2021-11-24 20:41:21: rclone: INFO : 17 / 17 Bytes, 100%, 1.544 kBytes/s, ETA 0s 2021-11-24 20:41:21: 2021-11-24 20:41:21: Setting lock on B 2021-11-24 20:41:35: rclone: INFO : LOCK_pi_cloud_pno9Z: Copied (new) 2021-11-24 20:41:35: rclone: INFO : 17 / 17 Bytes, 100%, 1 Bytes/s, ETA 0s 2021-11-24 20:41:35: 2021-11-24 20:41:35: 2021-11-24 20:41:35: Actions queued on A: 2021-11-24 20:41:35: 2021-11-24 20:41:35: Actions queued on B: 2021-11-24 20:41:35: 2021-11-24 20:41:35: (PLANNED) A >>> B 0 files, 0.00 b 2021-11-24 20:41:35: 2021-11-24 20:41:35: (PLANNED) A <<< B 28 files, 1.59 mb 2021-11-24 20:41:35: (PLANNED) Transfer A <<< B: '2021-11-20-173511.jpg' 2021-11-24 20:41:35: (PLANNED) Transfer A <<< B: '2020-12-20-111525.jpg' 2021-11-24 20:41:35: (PLANNED) Transfer A <<< B: '2021-11-20-173104.jpg' 2021-11-24 20:41:35: (PLANNED) Transfer A <<< B: '2020-12-20-111946.jpg' 2021-11-24 20:41:35: (PLANNED) Transfer A <<< B: '2021-11-20-173836.jpg' 2021-11-24 20:41:35: (PLANNED) Transfer A <<< B: '2020-12-20-112131.jpg' 2021-11-24 20:41:35: (PLANNED) Transfer A <<< B: '2020-12-20-112031.jpg' 2021-11-24 20:41:35: (PLANNED) Transfer A <<< B: '2021-11-20-173458.jpg' 2021-11-24 20:41:35: (PLANNED) Transfer A <<< B: '2020-12-20-111747.jpg' 2021-11-24 20:41:35: (PLANNED) Transfer A <<< B: '2021-11-20-173447.jpg' 2021-11-24 20:41:35: (PLANNED) Transfer A <<< B: '2021-11-20-174407.jpg' 2021-11-24 20:41:35: (PLANNED) Transfer A <<< B: '2020-10-14-134309.jpg' 2021-11-24 20:41:35: (PLANNED) Transfer A <<< B: '2020-12-20-112038.jpg' 2021-11-24 20:41:35: (PLANNED) Transfer A <<< B: '2021-11-20-172949.jpg' 2021-11-24 20:41:35: (PLANNED) Transfer A <<< B: '2020-12-20-112122.jpg' 2021-11-24 20:41:35: (PLANNED) Transfer A <<< B: '2021-11-20-173705.jpg' 2021-11-24 20:41:35: (PLANNED) Transfer A <<< B: '2021-11-20-172927.jpg' 2021-11-24 20:41:35: (PLANNED) Transfer A <<< B: '2020-12-20-111752.jpg' 2021-11-24 20:41:35: (PLANNED) Transfer A <<< B: '2020-12-20-111626.jpg' 2021-11-24 20:41:35: (PLANNED) Transfer A <<< B: '2021-11-20-173822.jpg' 2021-11-24 20:41:35: (PLANNED) Transfer A <<< B: '2020-12-20-111657.jpg' 2021-11-24 20:41:35: (PLANNED) Transfer A <<< B: '2021-11-20-173927.jpg' 2021-11-24 20:41:35: (PLANNED) Transfer A <<< B: '2021-11-20-173913.jpg' 2021-11-24 20:41:35: (PLANNED) Transfer A <<< B: '2021-11-20-172730.jpg' 2021-11-24 20:41:35: (PLANNED) Transfer A <<< B: '2021-11-20-173918.jpg' 2021-11-24 20:41:35: (PLANNED) Transfer A <<< B: '2021-11-20-173622.jpg' 2021-11-24 20:41:35: (PLANNED) Transfer A <<< B: '2021-11-20-173815.jpg' 2021-11-24 20:41:35: (PLANNED) Transfer A <<< B: '2021-11-20-172706.jpg' Would you like to continue? Y/[N]: y 2021-11-24 20:41:40: 2021-11-24 20:41:40: Performing Actions on A 2021-11-24 20:41:41: 2021-11-24 20:41:41: Performing Actions on B 2021-11-24 20:41:43: 2021-11-24 20:41:43: A >>> B 0 files, 0.00 b 2021-11-24 20:41:43: 2021-11-24 20:41:43: A <<< B 28 files, 1.59 mb 2021-11-24 20:42:07: rclone: INFO : 2020-10-14-134309.jpg: Copied (new) 2021-11-24 20:42:07: rclone: INFO : 2020-12-20-111657.jpg: Copied (new) 2021-11-24 20:42:07: rclone: INFO : 2020-12-20-111525.jpg: Copied (new) 2021-11-24 20:42:07: rclone: INFO : 2020-12-20-111626.jpg: Copied (new) 2021-11-24 20:42:10: rclone: INFO : 2020-12-20-111946.jpg: Copied (new) 2021-11-24 20:42:10: rclone: INFO : 2020-12-20-111747.jpg: Copied (new) 2021-11-24 20:42:10: rclone: INFO : 2020-12-20-111752.jpg: Copied (new) 2021-11-24 20:42:10: rclone: INFO : 2020-12-20-112031.jpg: Copied (new) 2021-11-24 20:42:13: rclone: INFO : 2020-12-20-112131.jpg: Copied (new) 2021-11-24 20:42:13: rclone: INFO : 2020-12-20-112122.jpg: Copied (new) 2021-11-24 20:42:13: rclone: INFO : 2020-12-20-112038.jpg: Copied (new) 2021-11-24 20:42:13: rclone: INFO : 2021-11-20-172706.jpg: Copied (new) 2021-11-24 20:42:15: rclone: INFO : 2021-11-20-173104.jpg: Copied (new) 2021-11-24 20:42:15: rclone: INFO : 2021-11-20-172927.jpg: Copied (new) 2021-11-24 20:42:15: rclone: INFO : 2021-11-20-172730.jpg: Copied (new) 2021-11-24 20:42:15: rclone: INFO : 2021-11-20-172949.jpg: Copied (new) 2021-11-24 20:42:18: rclone: INFO : 2021-11-20-173511.jpg: Copied (new) 2021-11-24 20:42:18: rclone: INFO : 2021-11-20-173447.jpg: Copied (new) 2021-11-24 20:42:18: rclone: INFO : 2021-11-20-173458.jpg: Copied (new) 2021-11-24 20:42:18: rclone: INFO : 2021-11-20-173622.jpg: Copied (new) 2021-11-24 20:42:20: rclone: INFO : 2021-11-20-173705.jpg: Copied (new) 2021-11-24 20:42:21: rclone: INFO : 2021-11-20-173815.jpg: Copied (new) 2021-11-24 20:42:21: rclone: INFO : 2021-11-20-173836.jpg: Copied (new) 2021-11-24 20:42:21: rclone: INFO : 2021-11-20-173822.jpg: Copied (new) 2021-11-24 20:42:23: rclone: INFO : 2021-11-20-173927.jpg: Copied (new) 2021-11-24 20:42:23: rclone: INFO : 2021-11-20-174407.jpg: Copied (new) 2021-11-24 20:42:23: rclone: INFO : 2021-11-20-173913.jpg: Copied (new) 2021-11-24 20:42:23: rclone: INFO : 2021-11-20-173918.jpg: Copied (new) 2021-11-24 20:42:23: rclone: INFO : 1.591M / 1.591 MBytes, 100%, 82.956 kBytes/s, ETA 0s 2021-11-24 20:42:23: 2021-11-24 20:42:23: Apply changes to file lists instead of refreshing 2021-11-24 20:42:26: Uploading filelists 2021-11-24 20:42:35: 2021-11-24 20:42:35: Breaking locks on A. May return errors if A is not locked 2021-11-24 20:42:35: rclone: INFO : LOCK_pi_cloud_pno9Z: Deleted 2021-11-24 20:42:35: 2021-11-24 20:42:35: Breaking locks on B. May return errors if B is not locked 2021-11-24 20:42:40: rclone: INFO : LOCK_pi_cloud_pno9Z: Deleted 2021-11-24 20:42:40: Logs will be saved on remotes to '.syncrclone/logs/pi_cloud_pno9Z_2021-11-24T204116.log' 2021-11-24 20:42:40: ---- END OF LOG ---- 2021-11-24 20:42:40: rclone: INFO : log: Copied (new) 2021-11-24 20:42:40: rclone: INFO : 6.698k / 6.698 kBytes, 100%, 14.062 kBytes/s, ETA 0s 2021-11-24 20:42:47: rclone: INFO : log: Copied (new) 2021-11-24 20:42:47: rclone: INFO : 6.698k / 6.698 kBytes, 100%, 987 Bytes/s, ETA 0s ```

As you can see the transfer speed is pretty awful. Nextcloud is awful by itself but using the desktop app in my laptop via wifi I get better transfers rates than locally using (sync)rclone.

I finally decided to do an initial one-way copy of the files from the filesystem instead of going through nextcloud/(sync)rclone because at these rates is unusable. I'm still interested if a following sync would work in a reasonable amount of time, as I expect to do sync not very often, not loads of files would change and I'm fine leaving it for a sync overnight. At this point I'm willing to sacrifice that for a 2way sync.

The reason I asked if locks work is that setting them will confirm if rclone is working correctly. I know you say direct rclone is working but it would also be good to verify it is the same rclone

It is the same rclone, is the only one I have installed.

On that note, have you updated rclone to the latest?

No, sorry, is a server where I prefer to use packaged software. For testing I could try a more recent version if you think it could be an rclone bug.

Here is what I suggest:

OK, I will try that, as I said I already did the initial copy, so now I just have to see what happens with syncrclone over that.

llucax commented 2 years ago

Hi, sorry for the delay, really busy lately (baby coming and all). I tried this, and syncrclone wants to copy/update all? (at least most) of the files of my remote (nextcloud). I think it might be because of mtime resolution in exFAT or something like that, because nothing changed locally in the exFAT since the manual sync/copy. And I guess I can't use any option to ignore mtime because that's how changes are detected, right?

You said you run some tests with exFAT and everything worked well?

Jwink3101 commented 2 years ago

And I guess I can't use any option to ignore mtime because that's how changes are detected, right

NO. You can change all settings to totally ignore mtime. In fact, with many remotes, you have no choice since they do not report reliable mtimes anyway.

compare = 'size'
conflict_mode = 'larger' # anything but 'newer' and 'older'
reuse_hashesA = False
reuse_hashesB = False
always_get_mtime = True 

The last one is actually optional. It just tells syncrclone to tell rclone to not even request mtime.

Also, if you do want to use mtime, you can change

dt = 1.1 # seconds

to something longer.

You said you run some tests with exFAT and everything worked well?

Yes. Though it was on a macOS disk image. It should be the same but it is hard to know for sure.


I think the next step is to understand why it wants to sync everything. By design syncrclone primarily uses the current state of the remotes to detect changes (and then uses the previous to resolve). This means we should be able to tell from the current state alone. But, it is worth noting that other tools use a method to detect changes where they compare against previous state first. It has pros and cons and I do no not like it as much. Also they may or may not work without mtime. But you could try them out.


I would be interested in seeing what syncrclone is seeing. On both remotes, can you backup the (A/B)-pi_cloud_pno9Z_fl.json.xz (or something like that) on both sides, then run syncrclone with --reset-state and send me all four? (and then you may want to restore the original ones).

Jwink3101 commented 2 years ago

I am going to close this issue if there is no followup or additional questions. I don;t have NextCloud to test with but I have used WebDAV without a problem before.

Nextcloud is awful by itself but using the desktop app in my laptop via wifi I get better transfers rates than locally using (sync)rclone.

That is because Nextcloud is a real-time-sync. It uses some filesystem APIs locally to detect changes and its own system on the server. Then it can easily just move the changes. Syncrclone is not real-time. It needs to list the files on both sides (which is probably the slow part).

llucax commented 2 years ago

I have very little time to dedicate to this, so totally fine to close it (I'm still very thankful for the support and even considering this an "issue" in the first place :). If I can sit down and investigate further, I will write again. Thanks!