"./sync.test -test.v -test.timeout 2h0m0s -remote TestFileFabric: -verbose -test.run '^TestSyncAfterRemovingAFileAndAddingAFileSubDir$'" - Starting (try 2/5) 2021/12/01 07:00:17 DEBUG : Creating backend with remote "TestFileFabric:rclone-test-hafuhab1sanusek8qegamim2" 2021/12/01 07:00:17 DEBUG : Using config file from "/home/rclone/.rclone.conf" 2021/12/01 07:00:17 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': rpc: checkPathExists(map[path:rclone-test-hafuhab1sanusek8qegamim2 pid:120673762]) options=[] 2021/12/01 07:00:17 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': >rpc: result=Success (ok), err= 2021/12/01 07:00:17 DEBUG : Creating backend with remote "/tmp/rclone1945006036" === RUN TestSyncAfterRemovingAFileAndAddingAFileSubDir run.go:181: Remote "filefabric root 'rclone-test-hafuhab1sanusek8qegamim2'", Local "Local file system at /tmp/rclone1945006036", Modify Window "1s" 2021/12/01 07:00:17 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': rpc: getFolderContents(map[count:1000 fi_pid:120673762 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/12/01 07:00:21 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': >rpc: result=Success (ok), err= 2021/12/01 07:00:21 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': rpc: doCreateNewFolder(map[fi_name:rclone-test-hafuhab1sanusek8qegamim2 fi_pid:120673762]) options=[] 2021/12/01 07:00:29 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': >rpc: result=Success (ok), err= 2021/12/01 07:00:29 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': rpc: getFolderContents(map[count:1000 fi_pid:121230575 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/12/01 07:00:33 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': >rpc: result=Success (ok), err= 2021/12/01 07:00:33 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': rpc: doCreateNewFolder(map[fi_name:b fi_pid:121230575]) options=[] 2021/12/01 07:00:38 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': >rpc: result=Success (ok), err= 2021/12/01 07:00:38 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': rpc: doInitUpload(map[directuploadsupport:n fi_contenttype:application/octet-stream fi_filename:potato fi_localtime:2011-12-25 12:59:59 fi_modified:2011-12-25 12:59:59 fi_name:potato fi_pid:121230576 fi_size:21 responsetype:json]) options=[] 2021/12/01 07:00:39 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': >rpc: result=Success (ok), err= 2021/12/01 07:00:40 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': rpc: doCompleteUpload(map[fi_size:21 remotetime:2011-12-25 12:59:59 uploadcode:61387b7e904c7f8ef6992d7a23df0c17]) options=[] 2021/12/01 07:00:43 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': >rpc: result=Success (ok), err= 2021/12/01 07:00:43 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': rpc: getFolderContents(map[count:1000 fi_pid:121230575 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/12/01 07:00:48 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': >rpc: result=Success (ok), err= 2021/12/01 07:00:48 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': rpc: doCreateNewFolder(map[fi_name:c fi_pid:121230575]) options=[] 2021/12/01 07:00:55 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': >rpc: result=Success (ok), err= 2021/12/01 07:00:55 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': rpc: doInitUpload(map[directuploadsupport:n fi_contenttype:application/octet-stream fi_filename:non empty space fi_localtime:2011-12-25 12:59:59 fi_modified:2011-12-25 12:59:59 fi_name:non empty space fi_pid:121230580 fi_size:5 responsetype:json]) options=[] 2021/12/01 07:00:58 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': >rpc: result=Success (ok), err= 2021/12/01 07:00:59 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': rpc: doCompleteUpload(map[fi_size:5 remotetime:2011-12-25 12:59:59 uploadcode:6c37103c1c19f16227b86770df1648c6]) options=[] 2021/12/01 07:01:06 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': >rpc: result=Success (ok), err= 2021/12/01 07:01:06 DEBUG : d: Making directory 2021/12/01 07:01:06 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': rpc: getFolderContents(map[count:1000 fi_pid:121230575 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/12/01 07:01:13 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': >rpc: result=Success (ok), err= 2021/12/01 07:01:13 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': rpc: doCreateNewFolder(map[fi_name:d fi_pid:121230575]) options=[] 2021/12/01 07:01:23 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': >rpc: result=Success (ok), err= 2021/12/01 07:01:23 DEBUG : d/e: Making directory 2021/12/01 07:01:23 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': rpc: getFolderContents(map[count:1000 fi_pid:121230587 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/12/01 07:01:27 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': >rpc: result=Success (ok), err= 2021/12/01 07:01:27 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': rpc: doCreateNewFolder(map[fi_name:e fi_pid:121230587]) options=[] 2021/12/01 07:01:35 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': >rpc: result=Success (ok), err= 2021/12/01 07:01:35 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': rpc: getFolderContents(map[count:1000 fi_pid:121230575 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/12/01 07:01:44 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': >rpc: result=Success (ok), err= 2021/12/01 07:01:44 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': rpc: getFolderContents(map[count:1000 fi_pid:121230587 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/12/01 07:01:44 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': rpc: getFolderContents(map[count:1000 fi_pid:121230576 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/12/01 07:01:44 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': rpc: getFolderContents(map[count:1000 fi_pid:121230580 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/12/01 07:01:52 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': >rpc: result=Success (ok), err= 2021/12/01 07:01:52 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': >rpc: result=Success (ok), err= 2021/12/01 07:01:52 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': >rpc: result=Success (ok), err= 2021/12/01 07:01:52 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': rpc: getFolderContents(map[count:1000 fi_pid:121230589 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/12/01 07:02:01 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': >rpc: result=Success (ok), err= 2021/12/01 07:02:01 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': rpc: getFolderContents(map[count:1000 fi_pid:121230575 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/12/01 07:02:02 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': >rpc: result=Success (ok), err= 2021/12/01 07:02:02 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': rpc: getFolderContents(map[count:1000 fi_pid:121230580 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/12/01 07:02:02 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': rpc: getFolderContents(map[count:1000 fi_pid:121230587 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/12/01 07:02:02 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': rpc: getFolderContents(map[count:1000 fi_pid:121230576 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/12/01 07:02:02 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': rpc: getFolderContents(map[count:1000 fi_pid:121230575 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/12/01 07:02:02 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': >rpc: result=Success (ok), err= 2021/12/01 07:02:02 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': >rpc: result=Success (ok), err= 2021/12/01 07:02:02 DEBUG : c/non empty space: Size and modification time the same (differ by -123.456789ms, within tolerance 1s) 2021/12/01 07:02:02 DEBUG : c/non empty space: Unchanged skipping 2021/12/01 07:02:02 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': >rpc: result=Success (ok), err= 2021/12/01 07:02:02 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': rpc: doCreateNewFolder(map[fi_name:a fi_pid:121230575]) options=[] 2021/12/01 07:02:02 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': >rpc: result=Success (ok), err= 2021/12/01 07:02:09 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': >rpc: result=Success (ok), err= 2021/12/01 07:02:09 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': rpc: doInitUpload(map[directuploadsupport:n fi_contenttype:application/octet-stream fi_filename:potato2 fi_localtime:2001-02-03 04:05:06 fi_modified:2001-02-03 04:05:06 fi_name:potato2 fi_pid:121230592 fi_size:60 responsetype:json]) options=[] 2021/12/01 07:02:09 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': rpc: getFolderContents(map[count:1000 fi_pid:121230589 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/12/01 07:02:10 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': >rpc: result=Success (ok), err= 2021/12/01 07:02:10 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': Waiting for checks to finish 2021/12/01 07:02:10 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': Waiting for transfers to finish 2021/12/01 07:02:11 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': >rpc: result=Success (ok), err= 2021/12/01 07:02:12 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': rpc: doCompleteUpload(map[fi_size:60 remotetime:2001-02-03 04:05:06 uploadcode:2cdfb71f5b8182b2acbc674c131665c8]) options=[] 2021/12/01 07:02:16 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': >rpc: result=Success (ok), err= 2021/12/01 07:02:16 INFO : a/potato2: Copied (new) 2021/12/01 07:02:16 DEBUG : Waiting for deletions to finish 2021/12/01 07:02:16 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': rpc: doDeleteFile(map[completedeletion:n fi_id:121230578]) options=[] 2021/12/01 07:02:35 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': >rpc: result=Success (ok), err= 2021/12/01 07:02:35 INFO : b/potato: Deleted 2021/12/01 07:02:35 INFO : d/e: Removing directory 2021/12/01 07:02:35 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': rpc: getFolderContents(map[count:1000 fi_pid:121230589 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/12/01 07:02:35 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': >rpc: result=Success (ok), err= 2021/12/01 07:02:35 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': rpc: doDeleteFolder(map[fi_id:121230589]) options=[] 2021/12/01 07:02:40 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': >rpc: result=Success (ok), err= 2021/12/01 07:02:40 INFO : d: Removing directory 2021/12/01 07:02:40 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': rpc: getFolderContents(map[count:1000 fi_pid:121230587 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/12/01 07:02:41 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': >rpc: result=Success (ok), err= 2021/12/01 07:02:41 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': rpc: doDeleteFolder(map[fi_id:121230587]) options=[] 2021/12/01 07:02:42 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': Sleeping for 1s to wait for "error_background" error to clear 2021/12/01 07:02:43 DEBUG : pacer: low level retry 1/10 (error The requested operation cannot be completed. A delete operation is already being processed in this folder. Please try again later. (error_background)) 2021/12/01 07:02:43 DEBUG : pacer: Rate limited, increasing sleep to 40ms 2021/12/01 07:02:43 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': Sleeping for 2s to wait for "error_background" error to clear 2021/12/01 07:02:45 DEBUG : pacer: low level retry 2/10 (error The requested operation cannot be completed. A delete operation is already being processed in this folder. Please try again later. (error_background)) 2021/12/01 07:02:45 DEBUG : pacer: Rate limited, increasing sleep to 80ms 2021/12/01 07:02:46 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': Sleeping for 4s to wait for "error_background" error to clear 2021/12/01 07:02:50 DEBUG : pacer: low level retry 3/10 (error The requested operation cannot be completed. A delete operation is already being processed in this folder. Please try again later. (error_background)) 2021/12/01 07:02:50 DEBUG : pacer: Rate limited, increasing sleep to 160ms 2021/12/01 07:02:50 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': Sleeping for 8s to wait for "error_background" error to clear 2021/12/01 07:02:58 DEBUG : pacer: low level retry 4/10 (error The requested operation cannot be completed. A delete operation is already being processed in this folder. Please try again later. (error_background)) 2021/12/01 07:02:58 DEBUG : pacer: Rate limited, increasing sleep to 320ms 2021/12/01 07:03:00 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': Sleeping for 16s to wait for "error_background" error to clear 2021/12/01 07:03:16 DEBUG : pacer: low level retry 5/10 (error The requested operation cannot be completed. A delete operation is already being processed in this folder. Please try again later. (error_background)) 2021/12/01 07:03:16 DEBUG : pacer: Rate limited, increasing sleep to 640ms 2021/12/01 07:03:16 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': Sleeping for 32s to wait for "error_background" error to clear 2021/12/01 07:03:48 DEBUG : pacer: low level retry 6/10 (error The requested operation cannot be completed. A delete operation is already being processed in this folder. Please try again later. (error_background)) 2021/12/01 07:03:48 DEBUG : pacer: Rate limited, increasing sleep to 1.28s 2021/12/01 07:03:53 DEBUG : pacer: Reducing sleep to 960ms 2021/12/01 07:03:53 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': >rpc: result=Success (ok), err= 2021/12/01 07:03:53 INFO : b: Removing directory 2021/12/01 07:03:53 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': rpc: getFolderContents(map[count:1000 fi_pid:121230576 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/12/01 07:03:57 DEBUG : pacer: Reducing sleep to 720ms 2021/12/01 07:03:57 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': >rpc: result=Success (ok), err= 2021/12/01 07:03:57 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': rpc: doDeleteFolder(map[fi_id:121230576]) options=[] 2021/12/01 07:04:03 DEBUG : pacer: Reducing sleep to 540ms 2021/12/01 07:04:03 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': >rpc: result=Success (ok), err= 2021/12/01 07:04:03 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': deleted 3 directories 2021/12/01 07:04:03 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': rpc: getFolderContents(map[count:1000 fi_pid:121230575 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/12/01 07:04:05 DEBUG : pacer: Reducing sleep to 405ms 2021/12/01 07:04:05 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': >rpc: result=Success (ok), err= 2021/12/01 07:04:05 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': rpc: getFolderContents(map[count:1000 fi_pid:121230580 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/12/01 07:04:05 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': rpc: getFolderContents(map[count:1000 fi_pid:121230592 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/12/01 07:04:05 DEBUG : pacer: Reducing sleep to 303.75ms 2021/12/01 07:04:05 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': >rpc: result=Success (ok), err= 2021/12/01 07:04:10 DEBUG : pacer: Reducing sleep to 227.8125ms 2021/12/01 07:04:10 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': >rpc: result=Success (ok), err= 2021/12/01 07:04:10 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': rpc: getFolderContents(map[count:1000 fi_pid:121230575 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/12/01 07:04:10 DEBUG : pacer: Reducing sleep to 170.859375ms 2021/12/01 07:04:10 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': >rpc: result=Success (ok), err= 2021/12/01 07:04:10 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': rpc: getFolderContents(map[count:1000 fi_pid:121230580 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/12/01 07:04:10 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': rpc: getFolderContents(map[count:1000 fi_pid:121230592 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/12/01 07:04:11 DEBUG : pacer: Reducing sleep to 128.144531ms 2021/12/01 07:04:11 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': >rpc: result=Success (ok), err= 2021/12/01 07:04:11 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': rpc: doDeleteFile(map[completedeletion:n fi_id:121230581]) options=[] 2021/12/01 07:04:11 DEBUG : pacer: Reducing sleep to 96.108398ms 2021/12/01 07:04:11 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': >rpc: result=Success (ok), err= 2021/12/01 07:04:27 DEBUG : pacer: Reducing sleep to 72.081298ms 2021/12/01 07:04:27 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': >rpc: result=Success (ok), err= 2021/12/01 07:04:27 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': rpc: doDeleteFile(map[completedeletion:n fi_id:121230593]) options=[] 2021/12/01 07:04:44 DEBUG : pacer: Reducing sleep to 54.060973ms 2021/12/01 07:04:44 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': >rpc: result=Success (ok), err= 2021/12/01 07:04:44 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': rpc: getFolderContents(map[count:1000 fi_pid:121230580 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/12/01 07:04:51 DEBUG : pacer: Reducing sleep to 40.545729ms 2021/12/01 07:04:51 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': >rpc: result=Success (ok), err= 2021/12/01 07:04:51 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': rpc: doDeleteFolder(map[fi_id:121230580]) options=[] 2021/12/01 07:04:56 DEBUG : pacer: Reducing sleep to 30.409296ms 2021/12/01 07:04:56 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': >rpc: result=Success (ok), err= 2021/12/01 07:04:56 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': rpc: getFolderContents(map[count:1000 fi_pid:121230592 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/12/01 07:05:00 DEBUG : pacer: Reducing sleep to 22.806972ms 2021/12/01 07:05:00 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': >rpc: result=Success (ok), err= 2021/12/01 07:05:00 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': rpc: doDeleteFolder(map[fi_id:121230592]) options=[] 2021/12/01 07:05:09 DEBUG : pacer: Reducing sleep to 20ms 2021/12/01 07:05:09 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': >rpc: result=Success (ok), err= 2021/12/01 07:05:09 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': rpc: getFolderContents(map[count:1000 fi_pid:121230575 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/12/01 07:05:10 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': >rpc: result=Success (ok), err= --- PASS: TestSyncAfterRemovingAFileAndAddingAFileSubDir (293.11s) PASS 2021/12/01 07:05:10 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': Purge remote 2021/12/01 07:05:10 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': rpc: doDeleteFolder(map[fi_id:121230575]) options=[] 2021/12/01 07:05:12 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': Sleeping for 1s to wait for "error_background" error to clear 2021/12/01 07:05:13 DEBUG : pacer: low level retry 1/10 (error The requested operation cannot be completed. A delete operation is already being processed in this folder. Please try again later. (error_background)) 2021/12/01 07:05:13 DEBUG : pacer: Rate limited, increasing sleep to 40ms 2021/12/01 07:05:14 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': Sleeping for 2s to wait for "error_background" error to clear 2021/12/01 07:05:16 DEBUG : pacer: low level retry 2/10 (error The requested operation cannot be completed. A delete operation is already being processed in this folder. Please try again later. (error_background)) 2021/12/01 07:05:16 DEBUG : pacer: Rate limited, increasing sleep to 80ms 2021/12/01 07:05:17 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': Sleeping for 4s to wait for "error_background" error to clear 2021/12/01 07:05:21 DEBUG : pacer: low level retry 3/10 (error The requested operation cannot be completed. A delete operation is already being processed in this folder. Please try again later. (error_background)) 2021/12/01 07:05:21 DEBUG : pacer: Rate limited, increasing sleep to 160ms 2021/12/01 07:05:23 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': Sleeping for 8s to wait for "error_background" error to clear 2021/12/01 07:05:31 DEBUG : pacer: low level retry 4/10 (error The requested operation cannot be completed. A delete operation is already being processed in this folder. Please try again later. (error_background)) 2021/12/01 07:05:31 DEBUG : pacer: Rate limited, increasing sleep to 320ms 2021/12/01 07:05:31 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': Sleeping for 16s to wait for "error_background" error to clear 2021/12/01 07:05:47 DEBUG : pacer: low level retry 5/10 (error The requested operation cannot be completed. A delete operation is already being processed in this folder. Please try again later. (error_background)) 2021/12/01 07:05:47 DEBUG : pacer: Rate limited, increasing sleep to 640ms 2021/12/01 07:05:49 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': Sleeping for 32s to wait for "error_background" error to clear 2021/12/01 07:06:21 DEBUG : pacer: low level retry 6/10 (error The requested operation cannot be completed. A delete operation is already being processed in this folder. Please try again later. (error_background)) 2021/12/01 07:06:21 DEBUG : pacer: Rate limited, increasing sleep to 1.28s 2021/12/01 07:06:21 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': Sleeping for 1m4s to wait for "error_background" error to clear 2021/12/01 07:07:25 DEBUG : pacer: low level retry 7/10 (error The requested operation cannot be completed. A delete operation is already being processed in this folder. Please try again later. (error_background)) 2021/12/01 07:07:25 DEBUG : pacer: Rate limited, increasing sleep to 2.56s 2021/12/01 07:07:35 DEBUG : pacer: Reducing sleep to 1.92s 2021/12/01 07:07:35 DEBUG : filefabric root 'rclone-test-hafuhab1sanusek8qegamim2': >rpc: result=Success (ok), err= "./sync.test -test.v -test.timeout 2h0m0s -remote TestFileFabric: -verbose -test.run '^TestSyncAfterRemovingAFileAndAddingAFileSubDir$'" - Finished OK in 7m17.700282264s (try 2/5)