"./sync.test -test.v -test.timeout 1h0m0s -remote TestFileFabric: -verbose -test.run '^TestSyncBackupDirWithSuffix$'" - Starting (try 2/5) 2021/03/04 06:31:43 DEBUG : Creating backend with remote "TestFileFabric:rclone-test-jolucax5kofukik0bopuceh4" 2021/03/04 06:31:43 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': rpc: checkPathExists(map[path:rclone-test-jolucax5kofukik0bopuceh4 pid:120673762]) options=[] 2021/03/04 06:31:43 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': >rpc: result=Success (ok), err= 2021/03/04 06:31:43 DEBUG : Creating backend with remote "/tmp/rclone196095917" === RUN TestSyncBackupDirWithSuffix run.go:176: Remote "filefabric root 'rclone-test-jolucax5kofukik0bopuceh4'", Local "Local file system at /tmp/rclone196095917", Modify Window "1s" 2021/03/04 06:31:43 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': 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/03/04 06:31:45 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': >rpc: result=Success (ok), err= 2021/03/04 06:31:45 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': rpc: doCreateNewFolder(map[fi_name:rclone-test-jolucax5kofukik0bopuceh4 fi_pid:120673762]) options=[] 2021/03/04 06:31:47 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': >rpc: result=Success (ok), err= 2021/03/04 06:31:47 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': rpc: getFolderContents(map[count:1000 fi_pid:120859454 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/03/04 06:31:48 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': >rpc: result=Success (ok), err= 2021/03/04 06:31:48 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': rpc: doCreateNewFolder(map[fi_name:dst fi_pid:120859454]) options=[] 2021/03/04 06:31:52 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': >rpc: result=Success (ok), err= 2021/03/04 06:31:52 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': rpc: doInitUpload(map[directuploadsupport:n fi_contenttype:application/octet-stream fi_filename:one fi_localtime:2001-02-03 04:05:06 fi_modified:2001-02-03 04:05:06 fi_name:one fi_pid:120859456 fi_size:3 responsetype:json]) options=[] 2021/03/04 06:31:53 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': >rpc: result=Success (ok), err= 2021/03/04 06:31:54 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': rpc: doCompleteUpload(map[fi_size:3 remotetime:2001-02-03 04:05:06 uploadcode:03cb3afe2c5a8353083861e8672208e3]) options=[] 2021/03/04 06:31:56 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': >rpc: result=Success (ok), err= 2021/03/04 06:31:56 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': rpc: doInitUpload(map[directuploadsupport:n fi_contenttype:application/octet-stream fi_filename:two fi_localtime:2001-02-03 04:05:06 fi_modified:2001-02-03 04:05:06 fi_name:two fi_pid:120859456 fi_size:3 responsetype:json]) options=[] 2021/03/04 06:31:57 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': >rpc: result=Success (ok), err= 2021/03/04 06:31:58 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': rpc: doCompleteUpload(map[fi_size:3 remotetime:2001-02-03 04:05:06 uploadcode:840114ff339bdae1eccde32e8658808c]) options=[] 2021/03/04 06:32:00 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': >rpc: result=Success (ok), err= 2021/03/04 06:32:00 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': rpc: doInitUpload(map[directuploadsupport:n fi_contenttype:text/plain; charset=utf-8 fi_filename:three.txt fi_localtime:2001-02-03 04:05:06 fi_modified:2001-02-03 04:05:06 fi_name:three.txt fi_pid:120859456 fi_size:5 responsetype:json]) options=[] 2021/03/04 06:32:01 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': >rpc: result=Success (ok), err= 2021/03/04 06:32:02 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': rpc: doCompleteUpload(map[fi_size:5 remotetime:2001-02-03 04:05:06 uploadcode:2d2598d8ddcfe6853b6f5d9c2ec0a242]) options=[] 2021/03/04 06:32:04 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': >rpc: result=Success (ok), err= 2021/03/04 06:32:04 DEBUG : dst/three.txt: Correcting mime type from "text/plain" to "text/plain; charset=utf-8" 2021/03/04 06:32:04 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': rpc: doModifyFile(map[data:fi_contenttype=text/plain; charset=utf-8 fi_id:120859461]) options=[] 2021/03/04 06:32:05 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': >rpc: result=Success (ok), err= 2021/03/04 06:32:05 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': rpc: getFolderContents(map[count:1000 fi_pid:120859454 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/03/04 06:32:06 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': >rpc: result=Success (ok), err= 2021/03/04 06:32:06 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': rpc: getFolderContents(map[count:1000 fi_pid:120859456 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/03/04 06:32:06 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': >rpc: result=Success (ok), err= 2021/03/04 06:32:06 DEBUG : Creating backend with remote "TestFileFabric:rclone-test-jolucax5kofukik0bopuceh4/dst" 2021/03/04 06:32:06 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4/dst': rpc: checkPathExists(map[path:rclone-test-jolucax5kofukik0bopuceh4/dst pid:120673762]) options=[] 2021/03/04 06:32:07 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4/dst': >rpc: result=Success (ok), err= 2021/03/04 06:32:07 DEBUG : Creating backend with remote "TestFileFabric:rclone-test-jolucax5kofukik0bopuceh4/backup" 2021/03/04 06:32:07 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4/backup': rpc: checkPathExists(map[path:rclone-test-jolucax5kofukik0bopuceh4/backup pid:120673762]) options=[] 2021/03/04 06:32:07 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4/backup': >rpc: result=Success (ok), err= 2021/03/04 06:32:07 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4/dst': rpc: getFolderContents(map[count:1000 fi_pid:120859456 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/03/04 06:32:07 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4/dst': >rpc: result=Success (ok), err= 2021/03/04 06:32:07 DEBUG : one: Sizes differ (src 4 vs dst 3) 2021/03/04 06:32:07 DEBUG : two: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2021/03/04 06:32:07 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4/backup': 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/03/04 06:32:07 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4/dst': Waiting for checks to finish 2021/03/04 06:32:07 DEBUG : two: Unchanged skipping 2021/03/04 06:32:08 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4/backup': >rpc: result=Success (ok), err= 2021/03/04 06:32:08 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4/backup': rpc: getFolderContents(map[count:1000 fi_pid:120859454 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/03/04 06:32:09 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4/backup': >rpc: result=Success (ok), err= 2021/03/04 06:32:09 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4/backup': rpc: getFolderContents(map[count:1000 fi_pid:120859454 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/03/04 06:32:09 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4/backup': >rpc: result=Success (ok), err= 2021/03/04 06:32:09 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4/backup': rpc: doCreateNewFolder(map[fi_name:backup fi_pid:120859454]) options=[] 2021/03/04 06:32:13 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4/backup': >rpc: result=Success (ok), err= 2021/03/04 06:32:13 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4/backup': rpc: doRenameFile(map[fi_id:120859458 fi_name:one.bak.yuyuyup6]) options=[] 2021/03/04 06:32:21 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4/backup': >rpc: result=Success (ok), err= 2021/03/04 06:32:21 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4/backup': rpc: doMoveFiles(map[dir_id:120859463 fi_ids:120859458]) options=[] 2021/03/04 06:32:46 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4/backup': >rpc: result=Succcess. (ok), err= 2021/03/04 06:32:46 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4/backup': rpc: doRenameFile(map[fi_id:120859458 fi_name:one.bak]) options=[] 2021/03/04 06:32:56 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4/backup': >rpc: result=Success (ok), err= 2021/03/04 06:32:56 INFO : one: Moved (server-side) to: one.bak 2021/03/04 06:32:56 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4/dst': Waiting for transfers to finish 2021/03/04 06:32:56 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4/dst': rpc: doInitUpload(map[directuploadsupport:n fi_contenttype:application/octet-stream fi_filename:one fi_localtime:2011-12-25 12:59:59 fi_modified:2011-12-25 12:59:59 fi_name:one fi_pid:120859456 fi_size:4 responsetype:json]) options=[] 2021/03/04 06:32:57 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4/dst': >rpc: result=Success (ok), err= 2021/03/04 06:32:58 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4/dst': rpc: doCompleteUpload(map[fi_size:4 remotetime:2011-12-25 12:59:59 uploadcode:76bcac8860c6758177c13e78fde9d18b]) options=[] 2021/03/04 06:32:59 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4/dst': >rpc: result=Success (ok), err= 2021/03/04 06:32:59 INFO : one: Copied (new) 2021/03/04 06:32:59 DEBUG : Waiting for deletions to finish 2021/03/04 06:32:59 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4/backup': rpc: checkPathExists(map[path:three.txt.bak pid:120859463]) options=[] 2021/03/04 06:33:00 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4/backup': >rpc: result=Success (ok), err= 2021/03/04 06:33:00 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4/backup': rpc: doRenameFile(map[fi_id:120859461 fi_name:three.txt.bak.hixijam6]) options=[] 2021/03/04 06:33:08 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4/backup': >rpc: result=Success (ok), err= 2021/03/04 06:33:08 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4/backup': rpc: doMoveFiles(map[dir_id:120859463 fi_ids:120859461]) options=[] 2021/03/04 06:33:30 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4/backup': >rpc: result=Succcess. (ok), err= 2021/03/04 06:33:30 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4/backup': rpc: doRenameFile(map[fi_id:120859461 fi_name:three.txt.bak]) options=[] 2021/03/04 06:33:39 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4/backup': >rpc: result=Success (ok), err= 2021/03/04 06:33:39 INFO : three.txt: Moved (server-side) to: three.txt.bak 2021/03/04 06:33:39 INFO : three.txt: Moved into backup dir 2021/03/04 06:33:39 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': rpc: getFolderContents(map[count:1000 fi_pid:120859454 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/03/04 06:33:40 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': >rpc: result=Success (ok), err= 2021/03/04 06:33:40 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': rpc: getFolderContents(map[count:1000 fi_pid:120859456 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/03/04 06:33:40 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': rpc: getFolderContents(map[count:1000 fi_pid:120859463 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/03/04 06:33:41 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': >rpc: result=Success (ok), err= 2021/03/04 06:33:41 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': >rpc: result=Success (ok), err= fstest.go:297: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:300: Flushing the directory cache 2021/03/04 06:33:42 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': 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/03/04 06:33:42 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': >rpc: result=Success (ok), err= 2021/03/04 06:33:42 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': rpc: getFolderContents(map[count:1000 fi_pid:120859454 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/03/04 06:33:43 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': >rpc: result=Success (ok), err= 2021/03/04 06:33:43 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': rpc: getFolderContents(map[count:1000 fi_pid:120859456 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/03/04 06:33:43 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': rpc: getFolderContents(map[count:1000 fi_pid:120859463 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/03/04 06:33:43 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': >rpc: result=Success (ok), err= 2021/03/04 06:33:44 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': >rpc: result=Success (ok), err= fstest.go:297: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:300: Flushing the directory cache 2021/03/04 06:33:46 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': 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/03/04 06:33:46 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': >rpc: result=Success (ok), err= 2021/03/04 06:33:46 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': rpc: getFolderContents(map[count:1000 fi_pid:120859454 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/03/04 06:33:47 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': >rpc: result=Success (ok), err= 2021/03/04 06:33:47 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': rpc: getFolderContents(map[count:1000 fi_pid:120859456 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/03/04 06:33:47 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': rpc: getFolderContents(map[count:1000 fi_pid:120859463 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/03/04 06:33:48 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': >rpc: result=Success (ok), err= 2021/03/04 06:33:48 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': >rpc: result=Success (ok), err= fstest.go:297: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:300: Flushing the directory cache fstest.go:304: Error Trace: fstest.go:304 fstest.go:337 fstest.go:349 sync_test.go:1767 sync_test.go:1798 Error: Should be true Test: TestSyncBackupDirWithSuffix Messages: listing wrong, want backup/one.bak (3), backup/three.txt.bak (5), dst/one (4), dst/two (3) got backup/one.bak (3), backup/three.txt.bak.txt (5), dst/one (4), dst/two (3) fstest.go:190: Error Trace: fstest.go:190 fstest.go:307 fstest.go:337 fstest.go:349 sync_test.go:1767 sync_test.go:1798 Error: Should be true Test: TestSyncBackupDirWithSuffix Messages: Unexpected file "backup/three.txt.bak.txt" fstest.go:202: Not found "backup/three.txt.bak" fstest.go:205: Error Trace: fstest.go:205 fstest.go:309 fstest.go:337 fstest.go:349 sync_test.go:1767 sync_test.go:1798 Error: Not equal: expected: 0 actual : 1 Test: TestSyncBackupDirWithSuffix Messages: 1 objects not found 2021/03/04 06:33:52 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': 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/03/04 06:33:53 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': >rpc: result=Success (ok), err= 2021/03/04 06:33:53 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': rpc: getFolderContents(map[count:1000 fi_pid:120859454 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/03/04 06:33:53 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': >rpc: result=Success (ok), err= 2021/03/04 06:33:53 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': rpc: doInitUpload(map[directuploadsupport:n fi_contenttype:text/plain; charset=utf-8 fi_filename:three.txt fi_localtime:2011-12-25 12:59:59 fi_modified:2011-12-25 12:59:59 fi_name:three.txt fi_pid:120859456 fi_size:6 responsetype:json]) options=[] 2021/03/04 06:33:54 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': >rpc: result=Success (ok), err= 2021/03/04 06:33:55 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': rpc: doCompleteUpload(map[fi_size:6 remotetime:2011-12-25 12:59:59 uploadcode:868c7033ab4e81e159976767bf8251f0]) options=[] 2021/03/04 06:33:57 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': >rpc: result=Success (ok), err= 2021/03/04 06:33:57 DEBUG : dst/three.txt: Correcting mime type from "text/plain" to "text/plain; charset=utf-8" 2021/03/04 06:33:57 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': rpc: doModifyFile(map[data:fi_contenttype=text/plain; charset=utf-8 fi_id:120859479]) options=[] 2021/03/04 06:33:58 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': >rpc: result=Success (ok), err= 2021/03/04 06:33:58 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': rpc: getFolderContents(map[count:1000 fi_pid:120859454 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/03/04 06:33:59 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': >rpc: result=Success (ok), err= 2021/03/04 06:33:59 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': rpc: getFolderContents(map[count:1000 fi_pid:120859456 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/03/04 06:33:59 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': rpc: getFolderContents(map[count:1000 fi_pid:120859463 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/03/04 06:33:59 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': >rpc: result=Success (ok), err= 2021/03/04 06:34:00 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': >rpc: result=Success (ok), err= fstest.go:297: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:300: Flushing the directory cache 2021/03/04 06:34:01 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': 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/03/04 06:34:01 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': >rpc: result=Success (ok), err= 2021/03/04 06:34:01 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': rpc: getFolderContents(map[count:1000 fi_pid:120859454 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/03/04 06:34:02 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': >rpc: result=Success (ok), err= 2021/03/04 06:34:02 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': rpc: getFolderContents(map[count:1000 fi_pid:120859456 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/03/04 06:34:02 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': rpc: getFolderContents(map[count:1000 fi_pid:120859463 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/03/04 06:34:02 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': >rpc: result=Success (ok), err= 2021/03/04 06:34:02 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': >rpc: result=Success (ok), err= fstest.go:297: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:300: Flushing the directory cache 2021/03/04 06:34:04 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': 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/03/04 06:34:04 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': >rpc: result=Success (ok), err= 2021/03/04 06:34:04 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': rpc: getFolderContents(map[count:1000 fi_pid:120859454 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/03/04 06:34:05 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': >rpc: result=Success (ok), err= 2021/03/04 06:34:05 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': rpc: getFolderContents(map[count:1000 fi_pid:120859456 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/03/04 06:34:05 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': rpc: getFolderContents(map[count:1000 fi_pid:120859463 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/03/04 06:34:05 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': >rpc: result=Success (ok), err= 2021/03/04 06:34:05 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': >rpc: result=Success (ok), err= fstest.go:297: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:300: Flushing the directory cache fstest.go:304: Error Trace: fstest.go:304 fstest.go:337 fstest.go:349 sync_test.go:1773 sync_test.go:1798 Error: Should be true Test: TestSyncBackupDirWithSuffix Messages: listing wrong, want backup/one.bak (3), backup/three.txt.bak (5), dst/one (4), dst/three.txt (6), dst/two (3) got backup/one.bak (3), backup/three.txt.bak.txt (5), dst/one (4), dst/three.txt (6), dst/two (3) fstest.go:190: Error Trace: fstest.go:190 fstest.go:307 fstest.go:337 fstest.go:349 sync_test.go:1773 sync_test.go:1798 Error: Should be true Test: TestSyncBackupDirWithSuffix Messages: Unexpected file "backup/three.txt.bak.txt" fstest.go:202: Not found "backup/three.txt.bak" fstest.go:205: Error Trace: fstest.go:205 fstest.go:309 fstest.go:337 fstest.go:349 sync_test.go:1773 sync_test.go:1798 Error: Not equal: expected: 0 actual : 1 Test: TestSyncBackupDirWithSuffix Messages: 1 objects not found 2021/03/04 06:34:09 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4/dst': rpc: getFolderContents(map[count:1000 fi_pid:120859456 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/03/04 06:34:09 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4/dst': >rpc: result=Success (ok), err= 2021/03/04 06:34:09 DEBUG : one: Sizes differ (src 5 vs dst 4) 2021/03/04 06:34:09 DEBUG : two: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2021/03/04 06:34:09 DEBUG : two: Unchanged skipping 2021/03/04 06:34:09 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4/backup': rpc: checkPathExists(map[path:one.bak pid:120859463]) options=[] 2021/03/04 06:34:09 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4/dst': Waiting for checks to finish 2021/03/04 06:34:09 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4/backup': >rpc: result=Success (ok), err= 2021/03/04 06:34:09 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4/backup': rpc: doDeleteFile(map[completedeletion:n fi_id:120859458]) options=[] 2021/03/04 06:34:20 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4/backup': >rpc: result=Success (ok), err= 2021/03/04 06:34:20 INFO : one.bak: Deleted 2021/03/04 06:34:20 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4/backup': rpc: doRenameFile(map[fi_id:120859471 fi_name:one.bak.cajihod2]) options=[] 2021/03/04 06:34:29 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4/backup': >rpc: result=Success (ok), err= 2021/03/04 06:34:29 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4/backup': rpc: doMoveFiles(map[dir_id:120859463 fi_ids:120859471]) options=[] 2021/03/04 06:34:50 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4/backup': >rpc: result=Succcess. (ok), err= 2021/03/04 06:34:50 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4/backup': rpc: doRenameFile(map[fi_id:120859471 fi_name:one.bak]) options=[] 2021/03/04 06:34:59 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4/backup': >rpc: result=Success (ok), err= 2021/03/04 06:34:59 INFO : one: Moved (server-side) to: one.bak 2021/03/04 06:34:59 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4/dst': Waiting for transfers to finish 2021/03/04 06:34:59 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4/dst': rpc: doInitUpload(map[directuploadsupport:n fi_contenttype:application/octet-stream fi_filename:one fi_localtime:2011-12-30 12:59:59 fi_modified:2011-12-30 12:59:59 fi_name:one fi_pid:120859456 fi_size:5 responsetype:json]) options=[] 2021/03/04 06:35:00 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4/dst': >rpc: result=Success (ok), err= 2021/03/04 06:35:01 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4/dst': rpc: doCompleteUpload(map[fi_size:5 remotetime:2011-12-30 12:59:59 uploadcode:14c5ea417f36c27bd72c01998fb8db1f]) options=[] 2021/03/04 06:35:02 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4/dst': >rpc: result=Success (ok), err= 2021/03/04 06:35:02 INFO : one: Copied (new) 2021/03/04 06:35:02 DEBUG : Waiting for deletions to finish 2021/03/04 06:35:02 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4/backup': rpc: checkPathExists(map[path:three.txt.bak pid:120859463]) options=[] 2021/03/04 06:35:03 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4/backup': >rpc: result=Success (ok), err= 2021/03/04 06:35:03 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4/backup': rpc: doRenameFile(map[fi_id:120859479 fi_name:three.txt.bak.gosuvuj9]) options=[] 2021/03/04 06:35:11 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4/backup': >rpc: result=Success (ok), err= 2021/03/04 06:35:11 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4/backup': rpc: doMoveFiles(map[dir_id:120859463 fi_ids:120859479]) options=[] 2021/03/04 06:35:32 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4/backup': >rpc: result=Succcess. (ok), err= 2021/03/04 06:35:32 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4/backup': rpc: doRenameFile(map[fi_id:120859479 fi_name:three.txt.bak]) options=[] 2021/03/04 06:35:35 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4/backup': >rpc: result=There is a file with the same name in the folder. (error), err=There is a file with the same name in the folder. (error) 2021/03/04 06:35:35 ERROR : three.txt: Couldn't move: failed to rename leaf: There is a file with the same name in the folder. (error) 2021/03/04 06:35:35 ERROR : three.txt: Couldn't move into backup dir: failed to rename leaf: There is a file with the same name in the folder. (error) 2021/03/04 06:35:35 ERROR : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4/dst': not deleting directories as there were IO errors sync_test.go:1779: Error Trace: sync_test.go:1779 sync_test.go:1798 Error: Received unexpected error: failed to delete 1 files github.com/rclone/rclone/fs/operations.DeleteFilesWithBackupDir /home/rclone/go/src/github.com/rclone/rclone/fs/operations/operations.go:727 github.com/rclone/rclone/fs/sync.(*syncCopyMove).deleteFiles /home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync.go:533 github.com/rclone/rclone/fs/sync.(*syncCopyMove).run /home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync.go:877 github.com/rclone/rclone/fs/sync.runSyncCopyMove /home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync.go:1078 github.com/rclone/rclone/fs/sync.Sync /home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync.go:1084 github.com/rclone/rclone/fs/sync.testSyncBackupDir /home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync_test.go:1778 github.com/rclone/rclone/fs/sync.TestSyncBackupDirWithSuffix /home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync_test.go:1798 testing.tRunner /usr/local/go/src/testing/testing.go:1123 runtime.goexit /usr/local/go/src/runtime/asm_amd64.s:1374 Test: TestSyncBackupDirWithSuffix 2021/03/04 06:35:35 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': 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/03/04 06:35:36 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': >rpc: result=Success (ok), err= 2021/03/04 06:35:36 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': rpc: getFolderContents(map[count:1000 fi_pid:120859454 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/03/04 06:35:37 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': >rpc: result=Success (ok), err= 2021/03/04 06:35:37 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': rpc: getFolderContents(map[count:1000 fi_pid:120859456 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/03/04 06:35:37 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': rpc: getFolderContents(map[count:1000 fi_pid:120859463 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/03/04 06:35:38 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': >rpc: result=Success (ok), err= 2021/03/04 06:35:38 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': rpc: doDeleteFile(map[completedeletion:n fi_id:120859492]) options=[] 2021/03/04 06:35:39 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': >rpc: result=Success (ok), err= 2021/03/04 06:35:46 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': >rpc: result=Success (ok), err= 2021/03/04 06:35:46 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': rpc: doDeleteFile(map[completedeletion:n fi_id:120859460]) options=[] 2021/03/04 06:35:54 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': >rpc: result=Success (ok), err= 2021/03/04 06:35:54 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': rpc: doDeleteFile(map[completedeletion:n fi_id:120859471]) options=[] 2021/03/04 06:36:09 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': >rpc: result=Success (ok), err= 2021/03/04 06:36:09 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': rpc: doDeleteFile(map[completedeletion:n fi_id:120859479]) options=[] 2021/03/04 06:36:17 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': >rpc: result=Success (ok), err= 2021/03/04 06:36:17 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': rpc: doDeleteFile(map[completedeletion:n fi_id:120859461]) options=[] 2021/03/04 06:36:26 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': >rpc: result=Success (ok), err= 2021/03/04 06:36:26 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': rpc: getFolderContents(map[count:1000 fi_pid:120859456 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/03/04 06:36:28 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': >rpc: result=Success (ok), err= 2021/03/04 06:36:28 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': rpc: doDeleteFolder(map[fi_id:120859456]) options=[] 2021/03/04 06:36:31 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': >rpc: result=Success (ok), err= 2021/03/04 06:36:31 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': rpc: getFolderContents(map[count:1000 fi_pid:120859463 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/03/04 06:36:32 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': >rpc: result=Success (ok), err= 2021/03/04 06:36:32 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': rpc: doDeleteFolder(map[fi_id:120859463]) options=[] 2021/03/04 06:36:35 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': >rpc: result=Success (ok), err= 2021/03/04 06:36:35 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': rpc: getFolderContents(map[count:1000 fi_pid:120859454 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/03/04 06:36:36 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': >rpc: result=Success (ok), err= --- FAIL: TestSyncBackupDirWithSuffix (292.19s) FAIL 2021/03/04 06:36:36 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': Purge remote 2021/03/04 06:36:36 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': rpc: doDeleteFolder(map[fi_id:120859454]) options=[] 2021/03/04 06:36:36 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': Sleeping for 6s to wait for "error_background" error to clear 2021/03/04 06:36:42 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/03/04 06:36:42 DEBUG : pacer: Rate limited, increasing sleep to 40ms 2021/03/04 06:36:42 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': Sleeping for 6s to wait for "error_background" error to clear 2021/03/04 06:36:48 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/03/04 06:36:48 DEBUG : pacer: Rate limited, increasing sleep to 80ms 2021/03/04 06:36:48 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': Sleeping for 6s to wait for "error_background" error to clear 2021/03/04 06:36:54 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/03/04 06:36:54 DEBUG : pacer: Rate limited, increasing sleep to 160ms 2021/03/04 06:36:55 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': Sleeping for 6s to wait for "error_background" error to clear 2021/03/04 06:37:01 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/03/04 06:37:01 DEBUG : pacer: Rate limited, increasing sleep to 320ms 2021/03/04 06:37:01 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': Sleeping for 6s to wait for "error_background" error to clear 2021/03/04 06:37:07 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/03/04 06:37:07 DEBUG : pacer: Rate limited, increasing sleep to 640ms 2021/03/04 06:37:08 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': Sleeping for 6s to wait for "error_background" error to clear 2021/03/04 06:37:14 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/03/04 06:37:14 DEBUG : pacer: Rate limited, increasing sleep to 1.28s 2021/03/04 06:37:14 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': Sleeping for 6s to wait for "error_background" error to clear 2021/03/04 06:37:20 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/03/04 06:37:20 DEBUG : pacer: Rate limited, increasing sleep to 2.56s 2021/03/04 06:37:20 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': Sleeping for 6s to wait for "error_background" error to clear 2021/03/04 06:37:26 DEBUG : pacer: low level retry 8/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/03/04 06:37:26 DEBUG : pacer: Rate limited, increasing sleep to 5.12s 2021/03/04 06:37:27 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': Sleeping for 6s to wait for "error_background" error to clear 2021/03/04 06:37:33 DEBUG : pacer: low level retry 9/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/03/04 06:37:33 DEBUG : pacer: Rate limited, increasing sleep to 10s 2021/03/04 06:37:33 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': Sleeping for 6s to wait for "error_background" error to clear 2021/03/04 06:37:39 DEBUG : pacer: low level retry 10/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/03/04 06:37:39 DEBUG : filefabric root 'rclone-test-jolucax5kofukik0bopuceh4': >rpc: result=The requested operation cannot be completed. A delete operation is already being processed in this folder. Please try again later. (error_background), err=The requested operation cannot be completed. A delete operation is already being processed in this folder. Please try again later. (error_background) 2021/03/04 06:37:39 purge failed: failed to remove directory: The requested operation cannot be completed. A delete operation is already being processed in this folder. Please try again later. (error_background) "./sync.test -test.v -test.timeout 1h0m0s -remote TestFileFabric: -verbose -test.run '^TestSyncBackupDirWithSuffix$'" - Finished ERROR in 5m56.179068537s (try 2/5): exit status 1: Failed [TestSyncBackupDirWithSuffix]