"./sync.test -test.v -test.timeout 1h0m0s -remote TestFileFabric: -verbose -test.run '^TestSyncBackupDirWithSuffix$'" - Starting (try 2/5) 2021/04/05 06:03:55 DEBUG : Creating backend with remote "TestFileFabric:rclone-test-sopuqaf7woqucoq4yemepag4" 2021/04/05 06:03:55 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': rpc: checkPathExists(map[path:rclone-test-sopuqaf7woqucoq4yemepag4 pid:120673762]) options=[] 2021/04/05 06:03:56 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': >rpc: result=Success (ok), err= 2021/04/05 06:03:56 DEBUG : Creating backend with remote "/tmp/rclone683982136" === RUN TestSyncBackupDirWithSuffix run.go:176: Remote "filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4'", Local "Local file system at /tmp/rclone683982136", Modify Window "1s" 2021/04/05 06:03:56 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': 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/04/05 06:03:57 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': >rpc: result=Success (ok), err= 2021/04/05 06:03:57 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': rpc: doCreateNewFolder(map[fi_name:rclone-test-sopuqaf7woqucoq4yemepag4 fi_pid:120673762]) options=[] 2021/04/05 06:04:02 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': >rpc: result=Success (ok), err= 2021/04/05 06:04:02 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': rpc: getFolderContents(map[count:1000 fi_pid:120895558 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/04/05 06:04:04 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': >rpc: result=Success (ok), err= 2021/04/05 06:04:04 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': rpc: doCreateNewFolder(map[fi_name:dst fi_pid:120895558]) options=[] 2021/04/05 06:04:08 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': >rpc: result=Success (ok), err= 2021/04/05 06:04:08 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': 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:120895561 fi_size:3 responsetype:json]) options=[] 2021/04/05 06:04:10 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': >rpc: result=Success (ok), err= 2021/04/05 06:04:11 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': rpc: doCompleteUpload(map[fi_size:3 remotetime:2001-02-03 04:05:06 uploadcode:18d4fea96bf06001e59e21fee22f3853]) options=[] 2021/04/05 06:04:13 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': >rpc: result=Success (ok), err= 2021/04/05 06:04:13 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': 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:120895561 fi_size:3 responsetype:json]) options=[] 2021/04/05 06:04:14 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': >rpc: result=Success (ok), err= 2021/04/05 06:04:15 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': rpc: doCompleteUpload(map[fi_size:3 remotetime:2001-02-03 04:05:06 uploadcode:89c666cf61d0177d9d5591ee37443898]) options=[] 2021/04/05 06:04:19 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': >rpc: result=Success (ok), err= 2021/04/05 06:04:19 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': 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:120895561 fi_size:5 responsetype:json]) options=[] 2021/04/05 06:04:21 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': >rpc: result=Success (ok), err= 2021/04/05 06:04:22 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': rpc: doCompleteUpload(map[fi_size:5 remotetime:2001-02-03 04:05:06 uploadcode:cb1ae24abf490e30fc099ef64cc70237]) options=[] 2021/04/05 06:04:26 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': >rpc: result=Success (ok), err= 2021/04/05 06:04:26 DEBUG : dst/three.txt: Correcting mime type from "text/plain" to "text/plain; charset=utf-8" 2021/04/05 06:04:26 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': rpc: doModifyFile(map[data:fi_contenttype=text/plain; charset=utf-8 fi_id:120895564]) options=[] 2021/04/05 06:04:26 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': >rpc: result=Success (ok), err= 2021/04/05 06:04:26 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': rpc: getFolderContents(map[count:1000 fi_pid:120895558 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/04/05 06:04:28 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': >rpc: result=Success (ok), err= 2021/04/05 06:04:28 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': rpc: getFolderContents(map[count:1000 fi_pid:120895561 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/04/05 06:04:30 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': >rpc: result=Success (ok), err= 2021/04/05 06:04:30 DEBUG : Creating backend with remote "TestFileFabric:rclone-test-sopuqaf7woqucoq4yemepag4/dst" 2021/04/05 06:04:30 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4/dst': rpc: checkPathExists(map[path:rclone-test-sopuqaf7woqucoq4yemepag4/dst pid:120673762]) options=[] 2021/04/05 06:04:30 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4/dst': >rpc: result=Success (ok), err= 2021/04/05 06:04:30 DEBUG : Creating backend with remote "TestFileFabric:rclone-test-sopuqaf7woqucoq4yemepag4/backup" 2021/04/05 06:04:30 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4/backup': rpc: checkPathExists(map[path:rclone-test-sopuqaf7woqucoq4yemepag4/backup pid:120673762]) options=[] 2021/04/05 06:04:31 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4/backup': >rpc: result=Success (ok), err= 2021/04/05 06:04:31 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4/dst': rpc: getFolderContents(map[count:1000 fi_pid:120895561 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/04/05 06:04:31 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4/dst': >rpc: result=Success (ok), err= 2021/04/05 06:04:31 DEBUG : one: Sizes differ (src 4 vs dst 3) 2021/04/05 06:04:31 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4/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/04/05 06:04:31 DEBUG : two: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2021/04/05 06:04:31 DEBUG : two: Unchanged skipping 2021/04/05 06:04:31 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4/dst': Waiting for checks to finish 2021/04/05 06:04:32 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4/backup': >rpc: result=Success (ok), err= 2021/04/05 06:04:32 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4/backup': rpc: getFolderContents(map[count:1000 fi_pid:120895558 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/04/05 06:04:33 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4/backup': >rpc: result=Success (ok), err= 2021/04/05 06:04:33 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4/backup': rpc: getFolderContents(map[count:1000 fi_pid:120895558 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/04/05 06:04:33 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4/backup': >rpc: result=Success (ok), err= 2021/04/05 06:04:33 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4/backup': rpc: doCreateNewFolder(map[fi_name:backup fi_pid:120895558]) options=[] 2021/04/05 06:04:38 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4/backup': >rpc: result=Success (ok), err= 2021/04/05 06:04:38 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4/backup': rpc: doRenameFile(map[fi_id:120895562 fi_name:one.bak.yukusuj8]) options=[] 2021/04/05 06:04:49 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4/backup': >rpc: result=Success (ok), err= 2021/04/05 06:04:49 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4/backup': rpc: doMoveFiles(map[dir_id:120895571 fi_ids:120895562]) options=[] 2021/04/05 06:05:23 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4/backup': >rpc: result=Succcess. (ok), err= 2021/04/05 06:05:23 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4/backup': rpc: doRenameFile(map[fi_id:120895562 fi_name:one.bak]) options=[] 2021/04/05 06:05:37 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4/backup': >rpc: result=Success (ok), err= 2021/04/05 06:05:37 INFO : one: Moved (server-side) to: one.bak 2021/04/05 06:05:37 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4/dst': Waiting for transfers to finish 2021/04/05 06:05:37 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4/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:120895561 fi_size:4 responsetype:json]) options=[] 2021/04/05 06:05:38 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4/dst': >rpc: result=Success (ok), err= 2021/04/05 06:05:40 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4/dst': rpc: doCompleteUpload(map[fi_size:4 remotetime:2011-12-25 12:59:59 uploadcode:6c8c246096ce6b58b7fe171c7926cba2]) options=[] 2021/04/05 06:05:41 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4/dst': >rpc: result=Success (ok), err= 2021/04/05 06:05:41 INFO : one: Copied (new) 2021/04/05 06:05:41 DEBUG : Waiting for deletions to finish 2021/04/05 06:05:41 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4/backup': rpc: checkPathExists(map[path:three.txt.bak pid:120895571]) options=[] 2021/04/05 06:05:41 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4/backup': >rpc: result=Success (ok), err= 2021/04/05 06:05:41 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4/backup': rpc: doRenameFile(map[fi_id:120895564 fi_name:three.txt.bak.pegeril5]) options=[] 2021/04/05 06:05:52 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4/backup': >rpc: result=Success (ok), err= 2021/04/05 06:05:52 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4/backup': rpc: doMoveFiles(map[dir_id:120895571 fi_ids:120895564]) options=[] 2021/04/05 06:06:23 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4/backup': >rpc: result=Succcess. (ok), err= 2021/04/05 06:06:23 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4/backup': rpc: doRenameFile(map[fi_id:120895564 fi_name:three.txt.bak]) options=[] 2021/04/05 06:06:36 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4/backup': >rpc: result=Success (ok), err= 2021/04/05 06:06:36 INFO : three.txt: Moved (server-side) to: three.txt.bak 2021/04/05 06:06:36 INFO : three.txt: Moved into backup dir 2021/04/05 06:06:36 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': rpc: getFolderContents(map[count:1000 fi_pid:120895558 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/04/05 06:06:37 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': >rpc: result=Success (ok), err= 2021/04/05 06:06:37 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': rpc: getFolderContents(map[count:1000 fi_pid:120895561 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/04/05 06:06:37 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': rpc: getFolderContents(map[count:1000 fi_pid:120895571 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/04/05 06:06:38 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': >rpc: result=Success (ok), err= 2021/04/05 06:06:39 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': >rpc: result=Success (ok), err= fstest.go:299: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:302: Flushing the directory cache 2021/04/05 06:06:40 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': 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/04/05 06:06:41 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': >rpc: result=Success (ok), err= 2021/04/05 06:06:41 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': rpc: getFolderContents(map[count:1000 fi_pid:120895558 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/04/05 06:06:41 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': >rpc: result=Success (ok), err= 2021/04/05 06:06:41 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': rpc: getFolderContents(map[count:1000 fi_pid:120895561 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/04/05 06:06:41 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': rpc: getFolderContents(map[count:1000 fi_pid:120895571 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/04/05 06:06:41 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': >rpc: result=Success (ok), err= 2021/04/05 06:06:41 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': >rpc: result=Success (ok), err= fstest.go:299: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:302: Flushing the directory cache 2021/04/05 06:06:43 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': 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/04/05 06:06:45 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': >rpc: result=Success (ok), err= 2021/04/05 06:06:45 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': rpc: getFolderContents(map[count:1000 fi_pid:120895558 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/04/05 06:06:45 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': >rpc: result=Success (ok), err= 2021/04/05 06:06:45 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': rpc: getFolderContents(map[count:1000 fi_pid:120895571 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/04/05 06:06:45 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': rpc: getFolderContents(map[count:1000 fi_pid:120895561 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/04/05 06:06:45 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': >rpc: result=Success (ok), err= 2021/04/05 06:06:45 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': >rpc: result=Success (ok), err= fstest.go:299: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:302: Flushing the directory cache fstest.go:306: Error Trace: fstest.go:306 fstest.go:339 fstest.go:351 sync_test.go:1705 sync_test.go:1736 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:192: Error Trace: fstest.go:192 fstest.go:309 fstest.go:339 fstest.go:351 sync_test.go:1705 sync_test.go:1736 Error: Should be true Test: TestSyncBackupDirWithSuffix Messages: Unexpected file "backup/three.txt.bak.txt" fstest.go:204: Not found "backup/three.txt.bak" fstest.go:207: Error Trace: fstest.go:207 fstest.go:311 fstest.go:339 fstest.go:351 sync_test.go:1705 sync_test.go:1736 Error: Not equal: expected: 0 actual : 1 Test: TestSyncBackupDirWithSuffix Messages: 1 objects not found 2021/04/05 06:06:49 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': 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/04/05 06:06:51 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': >rpc: result=Success (ok), err= 2021/04/05 06:06:51 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': rpc: getFolderContents(map[count:1000 fi_pid:120895558 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/04/05 06:06:51 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': >rpc: result=Success (ok), err= 2021/04/05 06:06:51 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': 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:120895561 fi_size:6 responsetype:json]) options=[] 2021/04/05 06:06:52 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': >rpc: result=Success (ok), err= 2021/04/05 06:06:53 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': rpc: doCompleteUpload(map[fi_size:6 remotetime:2011-12-25 12:59:59 uploadcode:e17cad88cc81680dd2264ba8b10c0b3c]) options=[] 2021/04/05 06:06:55 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': >rpc: result=Success (ok), err= 2021/04/05 06:06:55 DEBUG : dst/three.txt: Correcting mime type from "text/plain" to "text/plain; charset=utf-8" 2021/04/05 06:06:55 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': rpc: doModifyFile(map[data:fi_contenttype=text/plain; charset=utf-8 fi_id:120895600]) options=[] 2021/04/05 06:06:55 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': >rpc: result=Success (ok), err= 2021/04/05 06:06:55 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': rpc: getFolderContents(map[count:1000 fi_pid:120895558 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/04/05 06:06:56 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': >rpc: result=Success (ok), err= 2021/04/05 06:06:56 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': rpc: getFolderContents(map[count:1000 fi_pid:120895561 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/04/05 06:06:56 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': rpc: getFolderContents(map[count:1000 fi_pid:120895571 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/04/05 06:06:56 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': >rpc: result=Success (ok), err= 2021/04/05 06:06:57 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': >rpc: result=Success (ok), err= fstest.go:299: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:302: Flushing the directory cache 2021/04/05 06:06:58 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': 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/04/05 06:06:58 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': >rpc: result=Success (ok), err= 2021/04/05 06:06:58 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': rpc: getFolderContents(map[count:1000 fi_pid:120895558 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/04/05 06:06:59 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': >rpc: result=Success (ok), err= 2021/04/05 06:06:59 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': rpc: getFolderContents(map[count:1000 fi_pid:120895561 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/04/05 06:06:59 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': rpc: getFolderContents(map[count:1000 fi_pid:120895571 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/04/05 06:06:59 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': >rpc: result=Success (ok), err= 2021/04/05 06:06:59 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': >rpc: result=Success (ok), err= fstest.go:299: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:302: Flushing the directory cache 2021/04/05 06:07:01 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': 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/04/05 06:07:02 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': >rpc: result=Success (ok), err= 2021/04/05 06:07:02 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': rpc: getFolderContents(map[count:1000 fi_pid:120895558 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/04/05 06:07:04 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': >rpc: result=Success (ok), err= 2021/04/05 06:07:04 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': rpc: getFolderContents(map[count:1000 fi_pid:120895561 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/04/05 06:07:04 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': rpc: getFolderContents(map[count:1000 fi_pid:120895571 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/04/05 06:07:04 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': >rpc: result=Success (ok), err= 2021/04/05 06:07:05 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': >rpc: result=Success (ok), err= fstest.go:299: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:302: Flushing the directory cache fstest.go:306: Error Trace: fstest.go:306 fstest.go:339 fstest.go:351 sync_test.go:1711 sync_test.go:1736 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:192: Error Trace: fstest.go:192 fstest.go:309 fstest.go:339 fstest.go:351 sync_test.go:1711 sync_test.go:1736 Error: Should be true Test: TestSyncBackupDirWithSuffix Messages: Unexpected file "backup/three.txt.bak.txt" fstest.go:204: Not found "backup/three.txt.bak" fstest.go:207: Error Trace: fstest.go:207 fstest.go:311 fstest.go:339 fstest.go:351 sync_test.go:1711 sync_test.go:1736 Error: Not equal: expected: 0 actual : 1 Test: TestSyncBackupDirWithSuffix Messages: 1 objects not found 2021/04/05 06:07:09 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4/dst': rpc: getFolderContents(map[count:1000 fi_pid:120895561 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/04/05 06:07:10 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4/dst': >rpc: result=Success (ok), err= 2021/04/05 06:07:10 DEBUG : one: Sizes differ (src 5 vs dst 4) 2021/04/05 06:07:10 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4/backup': rpc: checkPathExists(map[path:one.bak pid:120895571]) options=[] 2021/04/05 06:07:10 DEBUG : two: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2021/04/05 06:07:10 DEBUG : two: Unchanged skipping 2021/04/05 06:07:10 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4/dst': Waiting for checks to finish 2021/04/05 06:07:10 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4/backup': >rpc: result=Success (ok), err= 2021/04/05 06:07:10 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4/backup': rpc: doDeleteFile(map[completedeletion:n fi_id:120895562]) options=[] 2021/04/05 06:07:22 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4/backup': >rpc: result=Success (ok), err= 2021/04/05 06:07:22 INFO : one.bak: Deleted 2021/04/05 06:07:22 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4/backup': rpc: doRenameFile(map[fi_id:120895589 fi_name:one.bak.xazuyag4]) options=[] 2021/04/05 06:07:32 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4/backup': >rpc: result=Success (ok), err= 2021/04/05 06:07:32 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4/backup': rpc: doMoveFiles(map[dir_id:120895571 fi_ids:120895589]) options=[] 2021/04/05 06:07:56 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4/backup': >rpc: result=Succcess. (ok), err= 2021/04/05 06:07:56 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4/backup': rpc: doRenameFile(map[fi_id:120895589 fi_name:one.bak]) options=[] 2021/04/05 06:08:08 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4/backup': >rpc: result=Success (ok), err= 2021/04/05 06:08:08 INFO : one: Moved (server-side) to: one.bak 2021/04/05 06:08:08 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4/dst': Waiting for transfers to finish 2021/04/05 06:08:08 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4/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:120895561 fi_size:5 responsetype:json]) options=[] 2021/04/05 06:08:09 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4/dst': >rpc: result=Success (ok), err= 2021/04/05 06:08:10 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4/dst': rpc: doCompleteUpload(map[fi_size:5 remotetime:2011-12-30 12:59:59 uploadcode:c0e9e0f238c13f7bd59f3dbe11d0ad4d]) options=[] 2021/04/05 06:08:15 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4/dst': >rpc: result=Success (ok), err= 2021/04/05 06:08:15 INFO : one: Copied (new) 2021/04/05 06:08:15 DEBUG : Waiting for deletions to finish 2021/04/05 06:08:15 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4/backup': rpc: checkPathExists(map[path:three.txt.bak pid:120895571]) options=[] 2021/04/05 06:08:15 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4/backup': >rpc: result=Success (ok), err= 2021/04/05 06:08:15 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4/backup': rpc: doRenameFile(map[fi_id:120895600 fi_name:three.txt.bak.qomevoq3]) options=[] 2021/04/05 06:08:27 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4/backup': >rpc: result=Success (ok), err= 2021/04/05 06:08:27 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4/backup': rpc: doMoveFiles(map[dir_id:120895571 fi_ids:120895600]) options=[] 2021/04/05 06:08:55 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4/backup': >rpc: result=Succcess. (ok), err= 2021/04/05 06:08:55 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4/backup': rpc: doRenameFile(map[fi_id:120895600 fi_name:three.txt.bak]) options=[] 2021/04/05 06:08:58 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4/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/04/05 06:08:58 ERROR : three.txt: Couldn't move: failed to rename leaf: There is a file with the same name in the folder. (error) 2021/04/05 06:08:58 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/04/05 06:08:58 ERROR : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4/dst': not deleting directories as there were IO errors sync_test.go:1717: Error Trace: sync_test.go:1717 sync_test.go:1736 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:730 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:1716 github.com/rclone/rclone/fs/sync.TestSyncBackupDirWithSuffix /home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync_test.go:1736 testing.tRunner /usr/local/go/src/testing/testing.go:1123 runtime.goexit /usr/local/go/src/runtime/asm_amd64.s:1374 Test: TestSyncBackupDirWithSuffix 2021/04/05 06:08:58 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': 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/04/05 06:08:59 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': >rpc: result=Success (ok), err= 2021/04/05 06:08:59 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': rpc: getFolderContents(map[count:1000 fi_pid:120895558 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/04/05 06:09:00 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': >rpc: result=Success (ok), err= 2021/04/05 06:09:00 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': rpc: getFolderContents(map[count:1000 fi_pid:120895561 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/04/05 06:09:00 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': rpc: getFolderContents(map[count:1000 fi_pid:120895571 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/04/05 06:09:02 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': >rpc: result=Success (ok), err= 2021/04/05 06:09:02 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': rpc: doDeleteFile(map[completedeletion:n fi_id:120895589]) options=[] 2021/04/05 06:09:02 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': >rpc: result=Success (ok), err= 2021/04/05 06:09:16 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': >rpc: result=Success (ok), err= 2021/04/05 06:09:16 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': rpc: doDeleteFile(map[completedeletion:n fi_id:120895600]) options=[] 2021/04/05 06:09:25 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': >rpc: result=Success (ok), err= 2021/04/05 06:09:25 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': rpc: doDeleteFile(map[completedeletion:n fi_id:120895564]) options=[] 2021/04/05 06:09:33 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': >rpc: result=Success (ok), err= 2021/04/05 06:09:33 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': rpc: doDeleteFile(map[completedeletion:n fi_id:120895624]) options=[] 2021/04/05 06:09:43 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': >rpc: result=Success (ok), err= 2021/04/05 06:09:43 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': rpc: doDeleteFile(map[completedeletion:n fi_id:120895563]) options=[] 2021/04/05 06:09:52 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': >rpc: result=Success (ok), err= 2021/04/05 06:09:52 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': rpc: getFolderContents(map[count:1000 fi_pid:120895561 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/04/05 06:09:53 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': >rpc: result=Success (ok), err= 2021/04/05 06:09:53 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': rpc: doDeleteFolder(map[fi_id:120895561]) options=[] 2021/04/05 06:09:57 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': >rpc: result=Success (ok), err= 2021/04/05 06:09:57 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': rpc: getFolderContents(map[count:1000 fi_pid:120895571 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/04/05 06:09:58 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': >rpc: result=Success (ok), err= 2021/04/05 06:09:58 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': rpc: doDeleteFolder(map[fi_id:120895571]) options=[] 2021/04/05 06:10:00 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': >rpc: result=Success (ok), err= 2021/04/05 06:10:00 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': rpc: getFolderContents(map[count:1000 fi_pid:120895558 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/04/05 06:10:01 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': >rpc: result=Success (ok), err= --- FAIL: TestSyncBackupDirWithSuffix (365.42s) FAIL 2021/04/05 06:10:01 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': Purge remote 2021/04/05 06:10:01 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': rpc: doDeleteFolder(map[fi_id:120895558]) options=[] 2021/04/05 06:10:02 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': Sleeping for 6s to wait for "error_background" error to clear 2021/04/05 06:10:08 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/04/05 06:10:08 DEBUG : pacer: Rate limited, increasing sleep to 40ms 2021/04/05 06:10:08 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': Sleeping for 6s to wait for "error_background" error to clear 2021/04/05 06:10:14 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/04/05 06:10:14 DEBUG : pacer: Rate limited, increasing sleep to 80ms 2021/04/05 06:10:14 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': Sleeping for 6s to wait for "error_background" error to clear 2021/04/05 06:10:20 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/04/05 06:10:20 DEBUG : pacer: Rate limited, increasing sleep to 160ms 2021/04/05 06:10:21 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': Sleeping for 6s to wait for "error_background" error to clear 2021/04/05 06:10:27 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/04/05 06:10:27 DEBUG : pacer: Rate limited, increasing sleep to 320ms 2021/04/05 06:10:28 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': Sleeping for 6s to wait for "error_background" error to clear 2021/04/05 06:10:34 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/04/05 06:10:34 DEBUG : pacer: Rate limited, increasing sleep to 640ms 2021/04/05 06:10:36 DEBUG : pacer: Reducing sleep to 480ms 2021/04/05 06:10:36 DEBUG : filefabric root 'rclone-test-sopuqaf7woqucoq4yemepag4': >rpc: result=Success (ok), err= "./sync.test -test.v -test.timeout 1h0m0s -remote TestFileFabric: -verbose -test.run '^TestSyncBackupDirWithSuffix$'" - Finished ERROR in 6m40.355994652s (try 2/5): exit status 1: Failed [TestSyncBackupDirWithSuffix]