Open EvilOlaf opened 2 years ago
Interesting. Please try a few things for me:
1) Simply delete a file on Path1 and see if you get the same failure. Does the problem seem to depend on a sequence of events?
2) Run rclonesync with another -v
so as to turn on rclone's transaction logging. Perhaps there is some error that rclone is flagging on the attempted delete of testfile2 on Gdrive.
3) Try another version of rclone. I'm currently running rclone v1.55.1-DEV.
Note that rclonesync's algorithm is being incorporated into rclone. See https://github.com/rclone/rclone/pull/5164 and bisync beta builds. If this issue turns out to be an rclonesync bug I'll certainly fix it.
regards, cjn
Hey, thanks for answering.
I could reproduce as I was writing the issue report earlier today but now I was unable to in first place.
Created a file on PATH1, synced, removed from PATH1, synced again, works. Created a file on PATH2, synced, removed from PATH1, synced again, works as well now. Wasn't before.
However I then tried something a little more "complicated". Created three testfiles on PATH2, synced, then removed one ("testfile6") from PATH1 and another from PATH2 ("testfile5") . This is the output with -vv:
rclone@nas-v2:~$ rclonesync --check-access -vv ../plain homeshare:plain
2021-09-28 18:39:48,660: ***** BiDirectional Sync for Cloud Services using rclone (V3.2 201201) *****
2021-09-28 18:39:49,118: Lock file created: </tmp/rclonesync_LOCK_.._plain_homeshare_plain_>
2021-09-28 18:39:49,119: Synching Path1 <../plain/> with Path2 <homeshare:plain/>
2021-09-28 18:39:49,119: Command args: <Path1=../plain, Path2=homeshare:plain, check_access=True, check_filename=RCLONE_TEST, check_sync_only=False, config=None, dry_run=False, filters_file=None, first_sync=False, force=False, max_deletes=50, no_check_sync=False, no_cleanup=False, no_datetime_log=False, rc_verbose=None, rclone=rclone, rclone_args=None, remove_empty_directories=False, verbose=2, workdir=/ext/rclone/.rclonesyncwd>
2021-09-28 18:39:49,119: >>>>> Path1 Checking for Diffs
2021-09-28 18:39:49,137: rclone command: ['rclone', 'lsl', '../plain/', '--config', '/ext/rclone/.config/rclone/rclone.conf']
2021-09-28 18:39:51,198: Path1 File was deleted - testfile6
2021-09-28 18:39:51,223: 1 file change(s) on Path1: 0 new, 0 newer, 0 older, 1 deleted
2021-09-28 18:39:51,223: >>>>> Path2 Checking for Diffs
2021-09-28 18:39:51,225: rclone command: ['rclone', 'lsl', 'homeshare:plain/', '--config', '/ext/rclone/.config/rclone/rclone.conf']
2021-09-28 18:40:08,665: Path2 File was deleted - testfile5
2021-09-28 18:40:08,692: 1 file change(s) on Path2: 0 new, 0 newer, 0 older, 1 deleted
2021-09-28 18:40:08,692: >>>>> Checking Path1 and Path2 rclone filesystems access health
2021-09-28 18:40:08,692: Found <1> matching <RCLONE_TEST> files on both paths
2021-09-28 18:40:08,692: >>>>> Determining and applying changes
2021-09-28 18:40:08,693: Path2 Queue delete - homeshare:plain/testfile6
2021-09-28 18:40:08,693: Path1 Queue delete - ../plain/testfile5
2021-09-28 18:40:08,694: Do queued deletes on - Path1
2021-09-28 18:40:08,695: rclone command: ['rclone', 'delete', '--config', '/ext/rclone/.config/rclone/rclone.conf', '../plain/', '--files-from-raw', '/ext/rclone/.rclonesyncwd/LSL_.._plain_homeshare_plain__files_delete_P1']
2021-09-28 18:40:08,799: Do queued deletes on - Path2
2021-09-28 18:40:08,801: rclone command: ['rclone', 'delete', '--config', '/ext/rclone/.config/rclone/rclone.conf', 'homeshare:plain/', '--files-from-raw', '/ext/rclone/.rclonesyncwd/LSL_.._plain_homeshare_plain__files_delete_P2']
2021-09-28 18:40:10,731: >>>>> Refreshing Path1 and Path2 lsl files
2021-09-28 18:40:10,734: rclone command: ['rclone', 'lsl', '../plain/', '--config', '/ext/rclone/.config/rclone/rclone.conf']
2021-09-28 18:40:11,185: rclone command: ['rclone', 'lsl', 'homeshare:plain/', '--config', '/ext/rclone/.config/rclone/rclone.conf']
2021-09-28 18:40:20,283: >>>>> Checking integrity of LSL history files for Path1 <../plain/> versus Path2 <homeshare:plain/>
2021-09-28 18:40:21,902: ERROR Path2 file not found in Path1 - testfile6
2021-09-28 18:40:21,903: ERROR: The content of Path1 and Path2 are out of sync. --first-sync required to recover.
2021-09-28 18:40:21,922: Lock file removed: </tmp/rclonesync_LOCK_.._plain_homeshare_plain_>
2021-09-28 18:40:21,923: ***** Critical Error Abort - Must run --first-sync to recover. See README.md *****
Once again it was the file deleted via PATH1 that caused the issue.
I tried the whole thing again with rclone 1.55.1 and it worked. So might be either luck or upstream issue or upstream incompatibility.... Even though this time everything went fine here is the output anyways:
rclone@nas-v2:~$ rm ../plain/testfile5
rclone@nas-v2:~$ rclonesync --check-access -vv ../plain homeshare:plain
2021-09-28 18:44:52,830: ***** BiDirectional Sync for Cloud Services using rclone (V3.2 201201) *****
2021-09-28 18:44:53,124: Lock file created: </tmp/rclonesync_LOCK_.._plain_homeshare_plain_>
2021-09-28 18:44:53,125: Synching Path1 <../plain/> with Path2 <homeshare:plain/>
2021-09-28 18:44:53,125: Command args: <Path1=../plain, Path2=homeshare:plain, check_access=True, check_filename=RCLONE_TEST, check_sync_only=False, config=None, dry_run=False, filters_file=None, first_sync=False, force=False, max_deletes=50, no_check_sync=False, no_cleanup=False, no_datetime_log=False, rc_verbose=None, rclone=rclone, rclone_args=None, remove_empty_directories=False, verbose=2, workdir=/ext/rclone/.rclonesyncwd>
2021-09-28 18:44:53,125: >>>>> Path1 Checking for Diffs
2021-09-28 18:44:53,143: rclone command: ['rclone', 'lsl', '../plain/', '--config', '/ext/rclone/.config/rclone/rclone.conf']
2021-09-28 18:44:55,187: Path1 File was deleted - testfile5
2021-09-28 18:44:55,212: 1 file change(s) on Path1: 0 new, 0 newer, 0 older, 1 deleted
2021-09-28 18:44:55,213: >>>>> Path2 Checking for Diffs
2021-09-28 18:44:55,214: rclone command: ['rclone', 'lsl', 'homeshare:plain/', '--config', '/ext/rclone/.config/rclone/rclone.conf']
2021-09-28 18:45:06,825: Path2 File was deleted - testfile6
2021-09-28 18:45:06,852: 1 file change(s) on Path2: 0 new, 0 newer, 0 older, 1 deleted
2021-09-28 18:45:06,853: >>>>> Checking Path1 and Path2 rclone filesystems access health
2021-09-28 18:45:06,853: Found <1> matching <RCLONE_TEST> files on both paths
2021-09-28 18:45:06,853: >>>>> Determining and applying changes
2021-09-28 18:45:06,853: Path2 Queue delete - homeshare:plain/testfile5
2021-09-28 18:45:06,853: Path1 Queue delete - ../plain/testfile6
2021-09-28 18:45:06,854: Do queued deletes on - Path1
2021-09-28 18:45:06,855: rclone command: ['rclone', 'delete', '--config', '/ext/rclone/.config/rclone/rclone.conf', '../plain/', '--files-from-raw', '/ext/rclone/.rclonesyncwd/LSL_.._plain_homeshare_plain__files_delete_P1']
2021-09-28 18:45:06,956: Do queued deletes on - Path2
2021-09-28 18:45:06,958: rclone command: ['rclone', 'delete', '--config', '/ext/rclone/.config/rclone/rclone.conf', 'homeshare:plain/', '--files-from-raw', '/ext/rclone/.rclonesyncwd/LSL_.._plain_homeshare_plain__files_delete_P2']
2021-09-28 18:45:08,692: >>>>> Refreshing Path1 and Path2 lsl files
2021-09-28 18:45:08,693: rclone command: ['rclone', 'lsl', '../plain/', '--config', '/ext/rclone/.config/rclone/rclone.conf']
2021-09-28 18:45:09,109: rclone command: ['rclone', 'lsl', 'homeshare:plain/', '--config', '/ext/rclone/.config/rclone/rclone.conf']
2021-09-28 18:45:21,656: >>>>> Checking integrity of LSL history files for Path1 <../plain/> versus Path2 <homeshare:plain/>
2021-09-28 18:45:23,289: Lock file removed: </tmp/rclonesync_LOCK_.._plain_homeshare_plain_>
2021-09-28 18:45:23,290: >>>>> Successful run. All done.
Cheers Werner
Unfortunately, I can't reproduce this. It looks like an rclone bug or a problem on Google Drive.
I set up a test case to create file21, file22, file23 on Path2 (GDrive), do a sync, then delete one of them on Path1 and another on Path2, and then a final sync. I ran it at least a dozen times with no fails. Hum... Any other clues? No chance that Google drive was restoring files for you?
The test runs in a testdir
subdir beneath the root of each path. The initial directory content was one other file.
SyncCmds.txt contents for test_issue75:
:RCSEXEC: :PATH1: :PATH2: --first-sync
:RCLONE: copyto :TESTCASEROOT:modfiles/file5R.txt :PATH2:file21.txt
:RCLONE: copyto :TESTCASEROOT:modfiles/file5R.txt :PATH2:file22.txt
:RCLONE: copyto :TESTCASEROOT:modfiles/file5R.txt :PATH2:file23.txt
:RCSEXEC: :PATH1: :PATH2:
:RCLONE: delete :PATH1:file21.txt
:RCLONE: delete :PATH2:file22.txt
:RCSEXEC: :PATH1: :PATH2:
testrcsync run:
$ ./testrcsync local GDrive: test_issue75 --no-cleanup -r ../../rclone-v1.56.1/rclone
***** Test case <test_issue75> using Path1 <./testdir/path1/>, Path2 <GDrive:testdir/path2/>, <../rclonesync>, and <../../rclone-v1.56.1/rclone>
CLEAN UP any remnant test content and SET UP the INITIAL STATE on both Path1 and Path2
RUN SYNCCMDS (console output captured to consolelog.txt)
../rclonesync ./testdir/path1/ GDrive:testdir/path2/ --first-sync --verbose --workdir ./testwd/ --no-datetime-log --no-cleanup --rclone ../../rclone-v1.56.1/rclone --config /home/cjn/.config/rclone/rclone.conf
../../rclone-v1.56.1/rclone copyto ./tests/test_issue75/modfiles/file5R.txt GDrive:testdir/path2/file21.txt
../../rclone-v1.56.1/rclone copyto ./tests/test_issue75/modfiles/file5R.txt GDrive:testdir/path2/file22.txt
../../rclone-v1.56.1/rclone copyto ./tests/test_issue75/modfiles/file5R.txt GDrive:testdir/path2/file23.txt
../rclonesync ./testdir/path1/ GDrive:testdir/path2/ --verbose --workdir ./testwd/ --no-datetime-log --no-cleanup --rclone ../../rclone-v1.56.1/rclone --config /home/cjn/.config/rclone/rclone.conf
../../rclone-v1.56.1/rclone delete ./testdir/path1/file21.txt
../../rclone-v1.56.1/rclone delete GDrive:testdir/path2/file22.txt
../rclonesync ./testdir/path1/ GDrive:testdir/path2/ --verbose --workdir ./testwd/ --no-datetime-log --no-cleanup --rclone ../../rclone-v1.56.1/rclone --config /home/cjn/.config/rclone/rclone.conf
COMPARE RESULTS files to the testcase golden directory
----------------------------------------------------------
Number of results files (8) match
----------------------------------------------------------
Match: <LSL_._testdir_path1_GDrive_testdir_path2__Path1>
----------------------------------------------------------
Match: <LSL_._testdir_path1_GDrive_testdir_path2__Path1_NEW>
----------------------------------------------------------
Match: <LSL_._testdir_path1_GDrive_testdir_path2__Path2>
----------------------------------------------------------
Match: <LSL_._testdir_path1_GDrive_testdir_path2__Path2_NEW>
----------------------------------------------------------
Match: <LSL_._testdir_path1_GDrive_testdir_path2__files_copy_P2P1>
----------------------------------------------------------
Match: <LSL_._testdir_path1_GDrive_testdir_path2__files_delete_P1>
----------------------------------------------------------
Match: <LSL_._testdir_path1_GDrive_testdir_path2__files_delete_P2>
----------------------------------------------------------
Match: <consolelog.txt>
----------------------------------------------------------
SKIPPING CLEANUP of testdirs and workdir
TEST <test_issue75> PASSED
No chance that Google drive was restoring files for you?
I am pretty confident that it did not. It had no reason to do so. I had browser window open next to terminal and could see the file being removed when synced.
Any idea how to dig even deeper?
When it fails is the file actually gone on google drive, but it still shows up in the LSL file (in /ext/rclone/.rclonesyncwd)? I was assuming that the delete was not happening but maybe the bug is an incorrect LSL listing?
Above I miss-stated the the rclone verbose switch. Add --rc-verbose --rc-verbose
(yes, twice) to the rclonesync command line to get rclone to output debug trace info. Please post rclone's debug logging for a failed delete.
As a work around, if the results seem stable on 1.55 then use it for a while to prove stability. You might also try the bisync beta noted above.
I may have found the culprit. I am using this with a decent amount of files (~20k) and if I run the sync a few times in a row I hit the user rate limit. Kind a odd since the quota is 20k requests per 100 seconds and I barely exceed 1% of that but whatever. I work around this now by setting --tpslimit 5
.
Time will tell if this is a persistent fix.
I'll leave this open for a bit. Please update sometime in the future. regards, cjn
Hey there,
not sure what I am doing wrong, maybe somebody can enlighten me. Note: Both local and remote were synced beforehand via rclone manually to get started with
rclonesync
faster.First sync.
RCLONE_TEST
files have been created beforehand.Nice.
Created a
testfile
at PATH1 with random data:rclone@nas-v2:~$ dd if=/dev/urandom of=../plain/testfile
Sync:Nice.
Now I deleted the testfile from PATH2 and sync again:
Nice.
Now I created a
testfile2
on PATH2 and sync again:Nice.
Now I delete the freshly synced
testfile2
from PATH1rm ../plain/testfile2
and sync againWelp...why?
Debian Bullseye aarch64 Python 3.9.2 rclone v1.56.1 Remote is a Gdrive
Cheers Werner