Rclone sync logs show "Copied (new)" when file existed

larsen161 · December 27, 2021, 3:07pm

I ran an initial command which put the files into the finance-shared remote. These files were created on the 23rd.
.\rclone.exe sync 'D:\File Server\P Drive\Provider Folders' finance-shared:'/Provider Folders' --log-file C:\rclone\logs\upload-ProviderFolders.txt -v --fast-list --max-transfer 700G --drive-chunk-size=128M

Because of 400k object limitations, I manually moved these to a new shared drive and wanted to re-run the sync. I re-wrote the command to sync to the new remote and path. I did not expect to see in the logs "Copy (new)" again especially since I do not see a new version of the file at all either when looking at the Drive activity history and audit log.

.\rclone.exe sync 'D:\File Server\P Drive\Provider Folders\.ASN Travelers' provider-0:'/Provider Folders/.ASN Travelers' --log-file C:\rclone\logs\upload-ProviderFolders_.ASNTravelers.txt -v --fast-list --max-transfer 700G --drive-chunk-size=128M

asdffdsa · December 27, 2021, 3:15pm

it might be due to manually moving the files, that changed the modtime.
or
perhaps the dest dir is not correct.

rerun the command, add -vv --dry-run and for one trouble file, post the debug log output
or
take one file that has the issue, run rclone copy -vv --dry-run and post the entire output.

please do not use screenshots, instead copy/paste into a post, enclosed with three backticks.

larsen161 · December 27, 2021, 6:31pm

Some very unusual behaviour happening with Drive. I ran the same command twice, without changing anything in between and have very different results.

First time around I see that everything is going to be created even though it existed already from the initial sync.

2021/12/27 12:01:12 DEBUG : rclone: Version "v1.57.0" starting with parameters ["C:\\rclone\\rclone.exe" "sync" "D:\\File Server\\P Drive\\Provider Folders\\X" "provider-m:/X" "--log-file" "C:\\rclone\\logs\\upload-ProviderFolders_X.txt" "-vv" "--dry-run"]
2021/12/27 12:01:12 DEBUG : Creating backend with remote "D:\\File Server\\P Drive\\Provider Folders\\X"
2021/12/27 12:01:12 DEBUG : Using config file from "C:\\Users\\admin\\AppData\\Roaming\\rclone\\rclone.conf"
2021/12/27 12:01:12 DEBUG : fs cache: renaming cache item "D:\\File Server\\P Drive\\Provider Folders\\X" to be canonical "//?/D:/File Server/P Drive/Provider Folders/X"
2021/12/27 12:01:12 DEBUG : Creating backend with remote "provider-m:/X"
2021/12/27 12:01:12 DEBUG : provider-m: Loaded invalid token from config file - ignoring
2021/12/27 12:01:12 DEBUG : Saving config "token" in section "provider-m" of the config file
2021/12/27 12:01:12 DEBUG : Keeping previous permissions for config file: -rw-rw-rw-
2021/12/27 12:01:12 DEBUG : provider-m: Saved new token in config file
2021/12/27 12:01:12 DEBUG : fs cache: renaming cache item "provider-m:/X" to be canonical "provider-m:X"
2021/12/27 12:01:12 NOTICE: Xiong, Yi/Medestar Packet/BLS ACLS.pdf: Skipped copy as --dry-run is set (size 195.843Ki)
2021/12/27 12:01:12 NOTICE: Xiong, Yi/Medestar Packet/Background_3rd PArty_Ohio Medical Board Probation 01-11-18 release letter.pdf: Skipped copy as --dry-run is set (size 118.750Ki)
2021/12/27 12:01:12 NOTICE: Xiong, Yi/Medestar Packet/CV_Xiong_02.13.19.pdf: Skipped copy as --dry-run is set (size 199.867Ki)
2021/12/27 12:01:12 NOTICE: Xiong, Yi/Medestar Packet/Cert_Xiong_DO_University of North Texas.pdf: Skipped copy as --dry-run is set (size 1.188Mi)
2021/12/27 12:01:12 NOTICE: Xiong, Yi/Medestar Packet/Lic_Xiong_OH_Wall Cert.pdf: Skipped copy as --dry-run is set (size 1.877Mi)
2021/12/27 12:01:12 NOTICE: Xiong, Yi/Medestar Packet/Medestar APP_Xiong_02.09.19.pdf: Skipped copy as --dry-run is set (size 567.974Ki)
2021/12/27 12:01:12 NOTICE: Xiong, Yi/Medestar Packet/Medestar PSA_Xiong_02.06.19.pdf: Skipped copy as --dry-run is set (size 308.016Ki)
2021/12/27 12:01:12 NOTICE: Xiong, Yi/Medestar Packet/Medestar RA_Xiong_02.06.19.pdf: Skipped copy as --dry-run is set (size 89.625Ki)
2021/12/27 12:01:12 NOTICE: Xiong, Yi/Medestar Packet/Medestar W-9_Xiong_02.09.19.pdf: Skipped copy as --dry-run is set (size 366.814Ki)
2021/12/27 12:01:12 NOTICE: Xiong, Yi/Medestar Packet/Provider Packet checklist_2.7.2019.pdf: Skipped copy as --dry-run is set (size 109.508Ki)
2021/12/27 12:01:12 NOTICE: Xiong, Yi/Medestar Packet/Ref_Xiong_Brooks_Undated.pdf: Skipped copy as --dry-run is set (size 246.249Ki)
2021/12/27 12:01:12 NOTICE: Xiong, Yi/Medestar Packet/Ref_Xiong_Huda_02.12.2019.pdf: Skipped copy as --dry-run is set (size 59.316Ki)
2021/12/27 12:01:12 NOTICE: Xiong, Yi/Medestar Packet/Ref_Xiong_Irani_02.01.2019.pdf: Skipped copy as --dry-run is set (size 58.677Ki)
2021/12/27 12:01:12 NOTICE: Xiong, Yi/Medestar Packet/Xiong, Yi, DO Ohio Medical Board consent letter.pdf: Skipped copy as --dry-run is set (size 227.765Ki)
2021/12/27 12:01:12 NOTICE: Xiong, Yi/Medestar Packet/Xiong,_Yi Oklahoma Board of Nursing Stipulaton.pdf: Skipped copy as --dry-run is set (size 2.835Mi)

I then run again a little later but now see that files are being recognised.

2021/12/27 12:25:46 DEBUG : rclone: Version "v1.57.0" starting with parameters ["C:\\rclone\\rclone.exe" "sync" "D:\\File Server\\P Drive\\Provider Folders\\X" "provider-m:/X" "--log-file" "C:\\rclone\\logs\\upload-ProviderFolders_X.txt" "-vv" "--dry-run"]
2021/12/27 12:25:46 DEBUG : Creating backend with remote "D:\\File Server\\P Drive\\Provider Folders\\X"
2021/12/27 12:25:46 DEBUG : Using config file from "C:\\Users\\admin\\AppData\\Roaming\\rclone\\rclone.conf"
2021/12/27 12:25:46 DEBUG : fs cache: renaming cache item "D:\\File Server\\P Drive\\Provider Folders\\X" to be canonical "//?/D:/File Server/P Drive/Provider Folders/X"
2021/12/27 12:25:46 DEBUG : Creating backend with remote "provider-m:/X"
2021/12/27 12:25:46 DEBUG : fs cache: renaming cache item "provider-m:/X" to be canonical "provider-m:X"
2021/12/27 12:25:46 DEBUG : Xu, Shirley/Logistics/PI_Xu_Medpost_9.28.18-9.30.18_Approved.pdf: Size and modification time the same (differ by 0s, within tolerance 1ms)
2021/12/27 12:25:46 DEBUG : Xu, Shirley/Logistics/PI_Xu_Medpost_9.28.18-9.30.18_Approved.pdf: Unchanged skipping
2021/12/27 12:25:46 DEBUG : Xu, Shirley/Insurance/COI_Xu_MedPost Urgent Care_2017-2018.pdf: Size and modification time the same (differ by 0s, within tolerance 1ms)
2021/12/27 12:25:46 DEBUG : Xu, Shirley/Insurance/COI_Xu_MedPost Urgent Care_2017-2018.pdf: Unchanged skipping
2021/12/27 12:25:46 DEBUG : Xiong, Kheng/Medestar Packet/CV_Xiong_4.24.2019.pdf: Size and modification time the same (differ by -761.9µs, within tolerance 1ms)
2021/12/27 12:25:46 DEBUG : Xiong, Kheng/Medestar Packet/CV_Xiong_4.24.2019.pdf: Unchanged skipping
2021/12/27 12:25:46 DEBUG : Xiong, Kheng/Medestar Packet/Cert_Xiong_ACLS_8.1.2020.pdf: Size and modification time the same (differ by -846.5µs, within tolerance 1ms)
2021/12/27 12:25:46 DEBUG : Xiong, Kheng/Medestar Packet/Cert_Xiong_ACLS_8.1.2020.pdf: Unchanged skipping
2021/12/27 12:25:46 DEBUG : Xiong, Kheng/Medestar Packet/Cert_Xiong_BLS_8.1.2020.pdf: Size and modification time the same (differ by -830.7µs, within tolerance 1ms)
2021/12/27 12:25:46 DEBUG : Xiong, Kheng/Medestar Packet/Cert_Xiong_BLS_8.1.2020.pdf: Unchanged skipping
2021/12/27 12:25:46 DEBUG : Xiong, Kheng/Medestar Packet/Cert_Xiong_NCCPA_12.31.2019.PDF: Size and modification time the same (differ by -327.9µs, within tolerance 1ms)
2021/12/27 12:25:46 DEBUG : Xiong, Kheng/Medestar Packet/Cert_Xiong_NCCPA_12.31.2019.PDF: Unchanged skipping
2021/12/27 12:25:46 DEBUG : Xiong, Kheng/Medestar Packet/Cert_Xiong_PALS_4.12.2019.pdf: Size and modification time the same (differ by -402.3µs, within tolerance 1ms)
2021/12/27 12:25:46 DEBUG : Xiong, Kheng/Medestar Packet/Cert_Xiong_PALS_4.12.2019.pdf: Unchanged skipping
2021/12/27 12:25:46 DEBUG : Xiong, Kheng/Medestar Packet/DEA_Xiong_5.31.2020.pdf: Size and modification time the same (differ by -682.2µs, within tolerance 1ms)
2021/12/27 12:25:46 DEBUG : Xiong, Kheng/Medestar Packet/DEA_Xiong_5.31.2020.pdf: Unchanged skipping
2021/12/27 12:25:46 DEBUG : Xiong, Kheng/Medestar Packet/Direct Deposit_Xiong.pdf: Size and modification time the same (differ by -158.8µs, within tolerance 1ms)
2021/12/27 12:25:46 DEBUG : Xiong, Kheng/Medestar Packet/Direct Deposit_Xiong.pdf: Unchanged skipping
2021/12/27 12:25:46 DEBUG : Xiong, Kheng/Medestar Packet/Edu_Xiong_Wall Cert_BA in Sciense.pdf: Size and modification time the same (differ by -474µs, within tolerance 1ms)
2021/12/27 12:25:46 DEBUG : Xiong, Kheng/Medestar Packet/Edu_Xiong_Wall Cert_BA in Sciense.pdf: Unchanged skipping
2021/12/27 12:25:46 DEBUG : Xiong, Kheng/Medestar Packet/Edu_Xiong_Wall Cert_Cert of PA.pdf: Size and modification time the same (differ by -89µs, within tolerance 1ms)
2021/12/27 12:25:46 DEBUG : Xiong, Kheng/Medestar Packet/Edu_Xiong_Wall Cert_Cert of PA.pdf: Unchanged skipping
2021/12/27 12:25:46 DEBUG : Xiong, Kheng/Medestar Packet/Lic_Xiong_CA_4.30.2021.pdf: Size and modification time the same (differ by -585.5µs, within tolerance 1ms)
2021/12/27 12:25:46 DEBUG : Xiong, Kheng/Medestar Packet/Lic_Xiong_CA_4.30.2021.pdf: Unchanged skipping
2021/12/27 12:25:46 DEBUG : Xiong, Kheng/Medestar Packet/MISC_Xiong_Voided Check.pdf: Size and modification time the same (differ by -32.2µs, within tolerance 1ms)
2021/12/27 12:25:46 DEBUG : Xiong, Kheng/Medestar Packet/MISC_Xiong_Voided Check.pdf: Unchanged skipping
2021/12/27 12:25:46 DEBUG : Xiong, Kheng/Medestar Packet/Medestar App_Xiong_4.24.2019.pdf: Size and modification time the same (differ by -633.5µs, within tolerance 1ms)
2021/12/27 12:25:46 DEBUG : Xiong, Kheng/Medestar Packet/Medestar App_Xiong_4.24.2019.pdf: Unchanged skipping
2021/12/27 12:25:46 DEBUG : Xiong, Kheng/Medestar Packet/Medestar PSA_Xiong_4.24.2019.pdf: Size and modification time the same (differ by -572.7µs, within tolerance 1ms)
2021/12/27 12:25:46 DEBUG : Xiong, Kheng/Medestar Packet/Medestar PSA_Xiong_4.24.2019.pdf: Unchanged skipping
2021/12/27 12:25:46 DEBUG : Xiong, Kheng/Medestar Packet/Medestar RA_Xiong_4.24.2019.pdf: Size and modification time the same (differ by -908µs, within tolerance 1ms)
2021/12/27 12:25:46 DEBUG : Xiong, Kheng/Medestar Packet/Medestar RA_Xiong_4.24.2019.pdf: Unchanged skipping
2021/12/27 12:25:46 DEBUG : Xiong, Kheng/Medestar Packet/Medestar W-9_Xiong_4.24.2019.pdf: Size and modification time the same (differ by -236.3µs, within tolerance 1ms)
2021/12/27 12:25:46 DEBUG : Xiong, Kheng/Medestar Packet/Medestar W-9_Xiong_4.24.2019.pdf: Unchanged skipping
2021/12/27 12:25:46 DEBUG : Xiong, Kheng/Medestar Packet/QA_Packet Medical Checklist_2.25.2019.pdf: Size and modification time the same (differ by -332µs, within tolerance 1ms)
2021/12/27 12:25:46 DEBUG : Xiong, Kheng/Medestar Packet/QA_Packet Medical Checklist_2.25.2019.pdf: Unchanged skipping
2021/12/27 12:25:46 DEBUG : Xiong, Kheng/Medestar Packet/Ref_Xiong_Elazier_4.26.2019.pdf: Size and modification time the same (differ by -500µs, within tolerance 1ms)
2021/12/27 12:25:46 DEBUG : Xiong, Kheng/Medestar Packet/Ref_Xiong_Elazier_4.26.2019.pdf: Unchanged skipping
2021/12/27 12:25:46 DEBUG : Xiong, Kheng/Medestar Packet/Ref_Xiong_Xiong_4.26.2019.pdf: Size and modification time the same (differ by -216.3µs, within tolerance 1ms)
2021/12/27 12:25:46 DEBUG : Xiong, Kheng/Medestar Packet/Ref_Xiong_Xiong_4.26.2019.pdf: Unchanged skipping

asdffdsa · December 27, 2021, 6:41pm

since each log contains a different set of files, no way to direct compare the two logs.

perhaps some files exist in the dest and some do not.

larsen161 · December 28, 2021, 3:28pm

Please look at line 2 of each log, it's referencing the same source of files:
D:\\File Server\\P Drive\\Provider Folders\\X

Please look at line 5 of each log, it's referencing the same remote and path:
provider-m:X

asdffdsa · December 28, 2021, 3:35pm

pick a single file and let's work with that.

larsen161 · December 28, 2021, 3:39pm

Sure, from the same two log files as before

2021/12/27 12:01:12 DEBUG : rclone: Version "v1.57.0" starting with parameters ["C:\\rclone\\rclone.exe" "sync" "D:\\File Server\\P Drive\\Provider Folders\\X" "provider-m:/X" "--log-file" "C:\\rclone\\logs\\upload-ProviderFolders_X.txt" "-vv" "--dry-run"]
2021/12/27 12:01:12 DEBUG : Creating backend with remote "D:\\File Server\\P Drive\\Provider Folders\\X"
2021/12/27 12:01:12 DEBUG : Using config file from "C:\\Users\\admin\\AppData\\Roaming\\rclone\\rclone.conf"
2021/12/27 12:01:12 DEBUG : fs cache: renaming cache item "D:\\File Server\\P Drive\\Provider Folders\\X" to be canonical "//?/D:/File Server/P Drive/Provider Folders/X"
2021/12/27 12:01:12 DEBUG : Creating backend with remote "provider-m:/X"
2021/12/27 12:01:12 DEBUG : provider-m: Loaded invalid token from config file - ignoring
2021/12/27 12:01:12 DEBUG : Saving config "token" in section "provider-m" of the config file
2021/12/27 12:01:12 DEBUG : Keeping previous permissions for config file: -rw-rw-rw-
2021/12/27 12:01:12 DEBUG : provider-m: Saved new token in config file
2021/12/27 12:01:12 DEBUG : fs cache: renaming cache item "provider-m:/X"
2021/12/27 12:01:12 NOTICE: Xiong, Yi/Medestar Packet/BLS ACLS.pdf: Skipped copy as --dry-run is set (size 195.843Ki)

2021/12/27 12:25:46 DEBUG : rclone: Version "v1.57.0" starting with parameters ["C:\\rclone\\rclone.exe" "sync" "D:\\File Server\\P Drive\\Provider Folders\\X" "provider-m:/X" "--log-file" "C:\\rclone\\logs\\upload-ProviderFolders_X.txt" "-vv" "--dry-run"]
2021/12/27 12:25:46 DEBUG : Creating backend with remote "D:\\File Server\\P Drive\\Provider Folders\\X"
2021/12/27 12:25:46 DEBUG : Using config file from "C:\\Users\\mlynch.admin\\AppData\\Roaming\\rclone\\rclone.conf"
2021/12/27 12:25:46 DEBUG : fs cache: renaming cache item "D:\\File Server\\P Drive\\Provider Folders\\X" to be canonical "//?/D:/File Server/P Drive/Provider Folders/X"
2021/12/27 12:25:46 DEBUG : Creating backend with remote "provider-m:/X"
2021/12/27 12:25:46 DEBUG : fs cache: renaming cache item "provider-m:/X" to be canonical "provider-m:X"
2021/12/27 12:25:46 DEBUG : Xiong, Yi/Medestar Packet/BLS ACLS.pdf: Size and modification time the same (differ by -832.4µs, within tolerance 1ms)
2021/12/27 12:25:46 DEBUG : Xiong, Yi/Medestar Packet/BLS ACLS.pdf: Unchanged skipping

asdffdsa · December 28, 2021, 3:47pm

so betweeen 2021/12/27 12:01:12 and 2021/12/27 12:25:46, you did not run that command without --dry-run?

larsen161 · December 28, 2021, 3:49pm

that is correct, the file was uploaded on Dec 23rd

2021/12/23 17:27:32 INFO : X/Xiong, Yi/Medestar Packet/BLS ACLS.pdf: Copied (new)

asdffdsa · December 28, 2021, 3:54pm

ok, there is a small difference between the two logs.

first log, updates the the token and has this
DEBUG : fs cache: renaming cache item "provider-m:/X"

second log, does not update the token and has this
DEBUG : fs cache: renaming cache item "provider-m:/X" to be canonical "provider-m:X"

larsen161 · December 28, 2021, 3:58pm

and what does that mean? Both commands used were identical

asdffdsa · December 28, 2021, 4:08pm

really not sure at this point.

i think that gdrive tokens expire every 60 minutes.
so i would wait, then run the command again, twice in a row and let's see if we can replicate it.

system · January 27, 2022, 4:09pm

This topic was automatically closed 30 days after the last reply. New replies are no longer allowed.