Sync fails and contents of .rclonesyncwd copied to active directories being synched

[DACN]

Not sure what is happening here. But a failure to synchronise files between Microsoft onedrive and laptop (PC2)

• Have a setup with two PCs and rclonesync being run on each with the task scheduler running a batch file every hour on PC1 and PC2
• PC1 <> OneDrive <> PC2
• Changes to files currently being actively made on PC1.
• Two directories being synched across D:\Debbie, D:\Debbie_archive. Changes today to the D:\Debbie directories on PC1, which were successfully copied across to onedrive
• Naming conventions same for the directories on both PCs, and with onedrive:\Debbie (etc)
• Looking at the logs on PC2, where the synch failed this morning.
• Sync commands issued from the batch file below (PC2 version = "Arainn")

set t=%TIME: =0%
set hour=%t:~0,2%

SET backup=D:\Debbie
py c:\Python39\Scripts\rclonesync.py d:\Debbie onedrive:\Debbie  --filters-file c:\users\Debbie\.rclonesyncwd\filter.txt -v 2>> c:\users\Debbie\.rclonesyncwd\logs.txt
IF %ERRORLEVEL% NEQ 0 (CALL :display_fail) ELSE (CALL :display_success)

SET backup=D:\Debbie_archive
py c:\Python39\Scripts\rclonesync.py d:\Debbie_archive onedrive:\Debbie_archive  --filters-file c:\users\Debbie\.rclonesyncwd\filter.txt -v 2>> c:\users\Debbie\.rclonesyncwd\logs.txt
IF %ERRORLEVEL% NEQ 0 (CALL :display_fail) ELSE (CALL :display_success)

GOTO :end

:display_success
if "%hour%" == "10" py c:\Python39\Scripts\telegram-send-dn.py "Onedrive success for %backup% on Arainn"
echo Success at %time% %date% for %backup% >> c:\users\Debbie\.rclonesyncwd\bat_log.txt
call powershell -WindowStyle hidden -Command "[reflection.assembly]::loadwithpartialname('System.Windows.Forms');[reflection.assembly]::loadwithpartialname('System.Drawing');$notify = new-object system.windows.forms.notifyicon;$notify.icon = [System.Drawing.SystemIcons]::Information;$notify.visible = $true;$notify.showballoontip(3,'INFORMATION','Onedrive sync successful for %backup%',[system.windows.forms.tooltipicon]::None)"  
EXIT /B

:display_fail
py c:\Python39\Scripts\telegram-send-dn.py "Onedrive FAIL for %backup% on Arainn"
echo Fail at %time% %date% for %backup% >> c:\users\Debbie\.rclonesyncwd\bat_log.txt
call powershell -WindowStyle hidden -Command "[reflection.assembly]::loadwithpartialname('System.Windows.Forms');[reflection.assembly]::loadwithpartialname('System.Drawing');$notify = new-object system.windows.forms.notifyicon;$notify.icon = [System.Drawing.SystemIcons]::Information;$notify.visible = $true;$notify.showballoontip(10,'WARNING','Onedrive sync fail for %backup%',[system.windows.forms.tooltipicon]::None)"  
EXIT /B

:end

On success or fail, powershell pops up a message
On fail, telegram message sent to android phone
On success - but once a day only - telegram message sent to android phone

And as of this morning
rclonesync: "V3.2 201201"
rclone: 1.56.2.
python 3.9

Looking at the logs.txt file from this morning on PC2, the synchronisation started well ..

• It found three new files copied from PC1 on D:\Debbie onto Microsoft onedrive:\Debbie
• But when it tried to do the copy, it found that a number of the files from the c:\users\Debbie.rclonesyncwd directory had been copied across to the active directories we are syncing in

2021-11-26 09:53:09,634: ***** BiDirectional Sync for Cloud Services using rclone (V3.2 201201) *****
2021-11-26 09:53:10,635: Lock file created: <C:\Users\Debbie\AppData\Local\Temp\rclonesync_LOCK_d__Debbie_onedrive__Debbie_>
2021-11-26 09:53:10,635: Synching Path1 <d:\Debbie/> with Path2 onedrive:\Debbie/
2021-11-26 09:53:10,635: Command args: <Path1=d:\Debbie, Path2=onedrive:\Debbie, check_access=False, check_filename=RCLONE_TEST, check_sync_only=False, config=None, dry_run=False, filters_file=c:\users\Debbie.rclonesyncwd\filter.txt, 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=1, workdir=C:\Users\Debbie/.rclonesyncwd>
2021-11-26 09:53:10,635: Using filters-file <c:\users\Debbie.rclonesyncwd\filter.txt>
2021-11-26 09:53:10,635: >>>>> Path1 Checking for Diffs
2021-11-26 09:53:11,921: >>>>> Path2 Checking for Diffs
2021-11-26 09:54:00,981: Path2 File is newer - INVOICES/CURRENT May 2021 - Apr 2022/YYYSEP_to_NOV_2021.docx
2021-11-26 09:54:00,981: Path2 File is new - AAAAAAA/BBB/XXX 2021/ZZZZBrief_fr_def-EN.docx
2021-11-26 09:54:00,981: Path2 File is new - AAAAAAA/BBB/XXX 2021/ZZZZ_Policy Brief_EN.docx
2021-11-26 09:54:00,981: 3 file change(s) on Path2: 2 new, 1 newer, 0 older, 0 deleted
2021-11-26 09:54:00,981: >>>>> Determining and applying changes
2021-11-26 09:54:00,981: Path2 Queue copy to Path1 - d:\Debbie/AAAAAAA/BBB/XXX 2021/ZZZZBrief_fr_def-EN.docx
2021-11-26 09:54:00,981: Path2 Queue copy to Path1 - d:\Debbie/AAAAAAA/BBB/XXX 2021/ZZZ_Policy Brief_EN.docx
2021-11-26 09:54:00,981: Path2 Queue copy to Path1 - d:\Debbie/INVOICES/CURRENT May 2021 - Apr 2022/YYYSEP_to_NOV_2021.docx
2021-11-26 09:54:00,981: Path2 Do queued copies to - Path1
2021-11-26 09:54:09,903: >>>>> Refreshing Path1 and Path2 lsl files
2021-11-26 09:54:10,133: >>>>> Checking integrity of LSL history files for Path1 <d:\Debbie/> versus Path2 onedrive:\Debbie/
2021-11-26 09:54:10,313: ERROR Path1 file not found in Path2 - AAAAAAA/PPPPPP/QQQQ & RRRR 2021/.rclonesyncwd/LSL_d__Debbie_archive_onedrive__Debbie_archive__Path1
2021-11-26 09:54:10,313: ERROR Path1 file not found in Path2 - AAAAAAA/PPPPPP/QQQQ & RRRR 2021/.rclonesyncwd/LSL_d__Debbie_archive_onedrive__Debbie_archive__Path2
2021-11-26 09:54:10,313: ERROR Path1 file not found in Path2 - AAAAAAA/PPPPPP/QQQQ & RRRR 2021/.rclonesyncwd/LSL_d__Debbie_onedrive__Debbie__Path1
2021-11-26 09:54:10,313: ERROR Path1 file not found in Path2 - AAAAAAA/PPPPPP/QQQQ & RRRR 2021/.rclonesyncwd/LSL_d__Debbie_onedrive__Debbie__Path2
2021-11-26 09:54:10,313: ERROR Path1 file not found in Path2 - AAAAAAA/PPPPPP/QQQQ & RRRR 2021/.rclonesyncwd/bat_log.txt
2021-11-26 09:54:10,313: ERROR Path1 file not found in Path2 - AAAAAAA/PPPPPP/QQQQ & RRRR 2021/.rclonesyncwd/filter.txt
2021-11-26 09:54:10,313: ERROR Path1 file not found in Path2 - AAAAAAA/PPPPPP/QQQQ & RRRR 2021/.rclonesyncwd/filter.txt-MD5
2021-11-26 09:54:10,313: ERROR Path1 file not found in Path2 - AAAAAAA/PPPPPP/QQQQ & RRRR 2021/.rclonesyncwd/logs.txt
2021-11-26 09:54:10,328: ERROR: The content of Path1 and Path2 are out of sync. --first-sync required to recover.
2021-11-26 09:54:10,328: Lock file removed: <C:\Users\Debbie\AppData\Local\Temp\rclonesync_LOCK_d__Debbie_onedrive__Debbie_>
2021-11-26 09:54:10,328: ***** Critical Error Abort - Must run --first-sync to recover. See README.md *****

I don't understand how directory c:\users\debbie.rclonesync got copied into the directory of files being synchronised which currently shows the following files:

26/11/2021  09:53    <DIR>          .
26/11/2021  09:53    <DIR>          ..
26/11/2021  09:09             5,109 bat_log.txt
10/11/2021  08:03               710 filter.txt
24/11/2021  13:51                32 filter.txt-MD5
26/11/2021  09:09           549,777 logs.txt
26/11/2021  09:08           666,633 LSL_d__Debbie_archive_onedrive__Debbie_archive__Path1
26/11/2021  09:09           666,633 LSL_d__Debbie_archive_onedrive__Debbie_archive__Path2
26/11/2021  09:07         1,030,890 LSL_d__Debbie_onedrive__Debbie__Path1
26/11/2021  09:08         1,030,890 LSL_d__Debbie_onedrive__Debbie__Path2

In the meantime, the similar sync job on PC1 continues to work without any problems so that PC1 and onedrive remain in sync.

Notes

• filenames slightly obfuscated to hide names of clients
• the active directory with the gash .rclonesyncwd is in a different part of the directory tree from the files being copied
• the datestamp on the gash .rclonesyncwd directory matches the time of the rclonesync run

[cjnaz]

Looks like a bug. One clue I see here is that there is a missing slash in the path to the filters file. The slash is not missing in your invocation.

2021-11-26 09:53:10,635: Using filters-file <c:\users\Debbie.rclonesyncwd\filter.txt>

At this point, its not clear to me why the workdir contents are appearing within the sync tree. The slash issue that is visible for the filters-file may be in play for the workdir path also.

Please check a couple items

1. On PC1 with --verbose, what is listed for the filters-file path? Is it also missing the slash, as above for PC2?
2. Check if the contents of this bogus directoryAAAAAAA/PPPPPP/QQQQ & RRRR 2021/.rclonesyncwd appear to be an exact copy of the proper/desired workdir at C:\Users\Debbie/.rclonesyncwd. It may be that the proper workdir is not getting used and the actual workdir is getting created within the tree being synced. Whether it is an exact copy or not may be a useful clue.

[cjnaz]

I've built some experiments on my Windows box and I cannot recreate any problems.

I suspect that the missing slash in the above Using filters-file line is due to your hand sanitizing the log? I also see missing < and > on Path2 in Synching Path1 <d:\Debbie/> with Path2 onedrive:\Debbie/ line, so again I suspect hand edits. Please confirm.

It seems that you are getting a copy of the workdir down is some lower level of the directory tree. Is there any chance that some other background sync is running also? Again, please check per 2. above. Also check the timestamps in the correct and duplicate .rclonesyncwd files - perhaps there are clues for when they were created.

[DACN]

Thanks for looking at this. A few more thoughts

1. There is not really a missing slash in the filters file path, that is only an artefact of the backslash quoting in the markdown here. If I write (backslash)(dot) . it comes out as just a dot. It comes out ok further down where the (backslash)(dot) is in the "code" section. This shows as backslash dot \. as I put in two backslashes
2. Similarly the missing brackets are not really missing (but not sure fully why some brackets come out and the others don't)
3. You ask "Check if the contents of this bogus directoryAAAAAAA/PPPPPP/QQQQ & RRRR 2021/.rclonesyncwd appear to be an exact copy". Think so but as other things have continued to run, can't prove it.
4. However, I note that the while the time-stamp of the bogus .rclonesyncwd directory is same as the failed run, timestamp of the some of the files is about when I woke up the laptop (PC2) that morning [in enough time to trial the telegram notifications between 10.00 and 11.00]. Not sure what that means - some carry over error from previous development of the scripts?
5. No other sync jobs running on PC2 for these directories. The native 'onedrive' sync is operating on the c:\users\debbie\onedrive directory; but not on the D: drive. There is another sync running on PC1 (running with "Tresorit") and trying to do a similar job with PC1 <> Tresorit <> PC2_predecessor . But that is not installed on PC2
6. Similarly, I have tried some experiments - eg deliberately creating a .rclonesyncwd directory on the path of the directories being synced. Cannot reproduce.
7. Could believe that there was an element of finger trouble on my behalf as I was updating and migrating the scripts - but can't work out anything plausible.
8. Even with that, the sync finding two new files and a new file at around 2021-11-26 09:54:00,981 - but then at 2021-11-26 09:54:10,313 finding the bogus .rclonesyncwd directory is very strange.
9. Without further clues - would be happy to close for now. Am reasonably content with the active monitoring I have put in place, so should be able to spot any re-emergent issues quickly.

[cjnaz]

I'll leave this open as a sighting for now. Let me know if it reoccurs and/or if you find the root cause or more clues.