"./sync.test -test.v -test.timeout 1h0m0s -remote TestFileFabric: -verbose -test.run '^(TestSyncBackupDirSuffixOnly|TestSyncBackupDirWithSuffix|TestSyncSuffix)$'" - Starting (try 4/5)
2021/02/08 06:40:38 DEBUG : Creating backend with remote "TestFileFabric:rclone-test-rafazat2wabitec5pobusev1"
2021/02/08 06:40:38 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: checkPathExists(map[path:rclone-test-rafazat2wabitec5pobusev1 pid:120673762]) options=[]
2021/02/08 06:40:38 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:40:38 DEBUG : Creating backend with remote "/tmp/rclone609366669"
=== RUN   TestSyncBackupDirWithSuffix
    run.go:176: Remote "filefabric root 'rclone-test-rafazat2wabitec5pobusev1'", Local "Local file system at /tmp/rclone609366669", Modify Window "1s"
2021/02/08 06:40:38 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': 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/02/08 06:40:39 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:40:39 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: doCreateNewFolder(map[fi_name:rclone-test-rafazat2wabitec5pobusev1 fi_pid:120673762]) options=[]
2021/02/08 06:40:42 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:40:42 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: getFolderContents(map[count:1000 fi_pid:120835287 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/02/08 06:40:43 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:40:43 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: doCreateNewFolder(map[fi_name:dst fi_pid:120835287]) options=[]
2021/02/08 06:40:46 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:40:46 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': 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:120835288 fi_size:3 responsetype:json]) options=[]
2021/02/08 06:40:47 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:40:48 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: doCompleteUpload(map[fi_size:3 remotetime:2001-02-03 04:05:06 uploadcode:5e6d37d14160cf3acb81b044e7d05605]) options=[]
2021/02/08 06:40:49 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:40:49 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': 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:120835288 fi_size:3 responsetype:json]) options=[]
2021/02/08 06:40:50 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:40:52 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: doCompleteUpload(map[fi_size:3 remotetime:2001-02-03 04:05:06 uploadcode:959450c257da4b47c496095103a5c022]) options=[]
2021/02/08 06:40:53 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:40:53 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': 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:120835288 fi_size:5 responsetype:json]) options=[]
2021/02/08 06:40:54 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:40:55 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: doCompleteUpload(map[fi_size:5 remotetime:2001-02-03 04:05:06 uploadcode:f7d96521edf219918200ae5b42edf562]) options=[]
2021/02/08 06:40:56 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:40:56 DEBUG : dst/three.txt: Correcting mime type from "text/plain" to "text/plain; charset=utf-8"
2021/02/08 06:40:56 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: doModifyFile(map[data:fi_contenttype=text/plain; charset=utf-8
 fi_id:120835292]) options=[]
2021/02/08 06:40:57 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:40:57 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: getFolderContents(map[count:1000 fi_pid:120835287 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/02/08 06:40:57 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:40:57 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: getFolderContents(map[count:1000 fi_pid:120835288 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/02/08 06:40:58 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:40:58 DEBUG : Creating backend with remote "TestFileFabric:rclone-test-rafazat2wabitec5pobusev1/dst"
2021/02/08 06:40:58 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': rpc: checkPathExists(map[path:rclone-test-rafazat2wabitec5pobusev1/dst pid:120673762]) options=[]
2021/02/08 06:40:59 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:40:59 DEBUG : Creating backend with remote "TestFileFabric:rclone-test-rafazat2wabitec5pobusev1/backup"
2021/02/08 06:40:59 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/backup': rpc: checkPathExists(map[path:rclone-test-rafazat2wabitec5pobusev1/backup pid:120673762]) options=[]
2021/02/08 06:40:59 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/backup': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:40:59 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': rpc: getFolderContents(map[count:1000 fi_pid:120835288 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/02/08 06:40:59 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:40:59 DEBUG : one: Sizes differ (src 4 vs dst 3)
2021/02/08 06:40:59 DEBUG : two: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2021/02/08 06:40:59 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/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/02/08 06:40:59 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': Waiting for checks to finish
2021/02/08 06:40:59 DEBUG : two: Unchanged skipping
2021/02/08 06:41:00 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/backup': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:41:00 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/backup': rpc: getFolderContents(map[count:1000 fi_pid:120835287 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/02/08 06:41:01 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/backup': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:41:01 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/backup': rpc: getFolderContents(map[count:1000 fi_pid:120835287 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/02/08 06:41:01 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/backup': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:41:01 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/backup': rpc: doCreateNewFolder(map[fi_name:backup fi_pid:120835287]) options=[]
2021/02/08 06:41:04 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/backup': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:41:04 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/backup': rpc: doRenameFile(map[fi_id:120835289 fi_name:one.bak.riwalaw5]) options=[]
2021/02/08 06:41:12 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/backup': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:41:12 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/backup': rpc: doMoveFiles(map[dir_id:120835293 fi_ids:120835289]) options=[]
2021/02/08 06:41:33 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/backup': >rpc: result=Succcess. (ok), err=<nil>
2021/02/08 06:41:33 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/backup': rpc: doRenameFile(map[fi_id:120835289 fi_name:one.bak]) options=[]
2021/02/08 06:41:41 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/backup': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:41:41 INFO  : one: Moved (server-side) to: one.bak
2021/02/08 06:41:41 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': Waiting for transfers to finish
2021/02/08 06:41:41 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/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:120835288 fi_size:4 responsetype:json]) options=[]
2021/02/08 06:41:41 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:41:43 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': rpc: doCompleteUpload(map[fi_size:4 remotetime:2011-12-25 12:59:59 uploadcode:09ca23dfd8fc6b8d375ed6e0e634f83a]) options=[]
2021/02/08 06:41:44 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:41:44 INFO  : one: Copied (new)
2021/02/08 06:41:44 DEBUG : Waiting for deletions to finish
2021/02/08 06:41:44 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/backup': rpc: checkPathExists(map[path:three.txt.bak pid:120835293]) options=[]
2021/02/08 06:41:44 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/backup': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:41:44 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/backup': rpc: doRenameFile(map[fi_id:120835292 fi_name:three.txt.bak.gohipeg7]) options=[]
2021/02/08 06:41:52 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/backup': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:41:52 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/backup': rpc: doMoveFiles(map[dir_id:120835293 fi_ids:120835292]) options=[]
2021/02/08 06:42:11 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/backup': >rpc: result=Succcess. (ok), err=<nil>
2021/02/08 06:42:11 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/backup': rpc: doRenameFile(map[fi_id:120835292 fi_name:three.txt.bak]) options=[]
2021/02/08 06:42:19 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/backup': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:42:19 INFO  : three.txt: Moved (server-side) to: three.txt.bak
2021/02/08 06:42:19 INFO  : three.txt: Moved into backup dir
2021/02/08 06:42:19 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: getFolderContents(map[count:1000 fi_pid:120835287 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/02/08 06:42:20 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:42:20 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: getFolderContents(map[count:1000 fi_pid:120835288 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/02/08 06:42:20 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: getFolderContents(map[count:1000 fi_pid:120835293 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/02/08 06:42:21 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:42:21 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
    fstest.go:297: Sleeping for 1s for list eventual consistency: 1/3
    fstest.go:300: Flushing the directory cache
2021/02/08 06:42:22 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': 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/02/08 06:42:23 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:42:23 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: getFolderContents(map[count:1000 fi_pid:120835287 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/02/08 06:42:23 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:42:23 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: getFolderContents(map[count:1000 fi_pid:120835288 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/02/08 06:42:23 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: getFolderContents(map[count:1000 fi_pid:120835293 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/02/08 06:42:24 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:42:24 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
    fstest.go:297: Sleeping for 2s for list eventual consistency: 2/3
    fstest.go:300: Flushing the directory cache
2021/02/08 06:42:26 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': 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/02/08 06:42:27 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:42:27 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: getFolderContents(map[count:1000 fi_pid:120835287 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/02/08 06:42:27 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:42:27 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: getFolderContents(map[count:1000 fi_pid:120835288 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/02/08 06:42:27 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: getFolderContents(map[count:1000 fi_pid:120835293 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/02/08 06:42:27 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:42:27 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
    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:1733
        	            				sync_test.go:1764
        	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:1733
        	            				sync_test.go:1764
        	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:1733
        	            				sync_test.go:1764
        	Error:      	Not equal: 
        	            	expected: 0
        	            	actual  : 1
        	Test:       	TestSyncBackupDirWithSuffix
        	Messages:   	1 objects not found
2021/02/08 06:42:31 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': 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/02/08 06:42:32 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:42:32 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: getFolderContents(map[count:1000 fi_pid:120835287 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/02/08 06:42:32 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:42:32 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': 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:120835288 fi_size:6 responsetype:json]) options=[]
2021/02/08 06:42:33 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:42:34 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: doCompleteUpload(map[fi_size:6 remotetime:2011-12-25 12:59:59 uploadcode:1987667fadd0c5688dddc60a49f1adba]) options=[]
2021/02/08 06:42:35 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:42:35 DEBUG : dst/three.txt: Correcting mime type from "text/plain" to "text/plain; charset=utf-8"
2021/02/08 06:42:35 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: doModifyFile(map[data:fi_contenttype=text/plain; charset=utf-8
 fi_id:120835304]) options=[]
2021/02/08 06:42:36 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:42:36 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: getFolderContents(map[count:1000 fi_pid:120835287 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/02/08 06:42:37 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:42:37 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: getFolderContents(map[count:1000 fi_pid:120835293 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/02/08 06:42:37 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: getFolderContents(map[count:1000 fi_pid:120835288 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/02/08 06:42:37 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:42:38 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
    fstest.go:297: Sleeping for 1s for list eventual consistency: 1/3
    fstest.go:300: Flushing the directory cache
2021/02/08 06:42:39 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': 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/02/08 06:42:40 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:42:40 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: getFolderContents(map[count:1000 fi_pid:120835287 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/02/08 06:42:40 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:42:40 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: getFolderContents(map[count:1000 fi_pid:120835288 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/02/08 06:42:40 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: getFolderContents(map[count:1000 fi_pid:120835293 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/02/08 06:42:41 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:42:41 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
    fstest.go:297: Sleeping for 2s for list eventual consistency: 2/3
    fstest.go:300: Flushing the directory cache
2021/02/08 06:42:43 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': 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/02/08 06:42:43 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:42:43 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: getFolderContents(map[count:1000 fi_pid:120835287 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/02/08 06:42:43 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:42:43 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: getFolderContents(map[count:1000 fi_pid:120835288 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/02/08 06:42:43 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: getFolderContents(map[count:1000 fi_pid:120835293 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/02/08 06:42:44 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:42:44 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
    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:1739
        	            				sync_test.go:1764
        	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:1739
        	            				sync_test.go:1764
        	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:1739
        	            				sync_test.go:1764
        	Error:      	Not equal: 
        	            	expected: 0
        	            	actual  : 1
        	Test:       	TestSyncBackupDirWithSuffix
        	Messages:   	1 objects not found
2021/02/08 06:42:48 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': rpc: getFolderContents(map[count:1000 fi_pid:120835288 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/02/08 06:42:48 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:42:48 DEBUG : one: Sizes differ (src 5 vs dst 4)
2021/02/08 06:42:48 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/backup': rpc: checkPathExists(map[path:one.bak pid:120835293]) options=[]
2021/02/08 06:42:48 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': Waiting for checks to finish
2021/02/08 06:42:48 DEBUG : two: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2021/02/08 06:42:48 DEBUG : two: Unchanged skipping
2021/02/08 06:42:48 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/backup': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:42:48 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/backup': rpc: doDeleteFile(map[completedeletion:n fi_id:120835289]) options=[]
2021/02/08 06:42:56 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/backup': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:42:56 INFO  : one.bak: Deleted
2021/02/08 06:42:56 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/backup': rpc: doRenameFile(map[fi_id:120835298 fi_name:one.bak.muxalaz9]) options=[]
2021/02/08 06:43:04 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/backup': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:43:04 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/backup': rpc: doMoveFiles(map[dir_id:120835293 fi_ids:120835298]) options=[]
2021/02/08 06:43:22 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/backup': >rpc: result=Succcess. (ok), err=<nil>
2021/02/08 06:43:22 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/backup': rpc: doRenameFile(map[fi_id:120835298 fi_name:one.bak]) options=[]
2021/02/08 06:43:30 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/backup': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:43:30 INFO  : one: Moved (server-side) to: one.bak
2021/02/08 06:43:30 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': Waiting for transfers to finish
2021/02/08 06:43:30 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/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:120835288 fi_size:5 responsetype:json]) options=[]
2021/02/08 06:43:31 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:43:33 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': rpc: doCompleteUpload(map[fi_size:5 remotetime:2011-12-30 12:59:59 uploadcode:f28b67787cc91b83da9a50e351ca0670]) options=[]
2021/02/08 06:43:34 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:43:34 INFO  : one: Copied (new)
2021/02/08 06:43:34 DEBUG : Waiting for deletions to finish
2021/02/08 06:43:34 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/backup': rpc: checkPathExists(map[path:three.txt.bak pid:120835293]) options=[]
2021/02/08 06:43:34 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/backup': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:43:34 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/backup': rpc: doRenameFile(map[fi_id:120835304 fi_name:three.txt.bak.gotidib1]) options=[]
2021/02/08 06:43:42 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/backup': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:43:42 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/backup': rpc: doMoveFiles(map[dir_id:120835293 fi_ids:120835304]) options=[]
2021/02/08 06:44:01 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/backup': >rpc: result=Succcess. (ok), err=<nil>
2021/02/08 06:44:01 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/backup': rpc: doRenameFile(map[fi_id:120835304 fi_name:three.txt.bak]) options=[]
2021/02/08 06:44:03 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/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/02/08 06:44:03 ERROR : three.txt: Couldn't move: failed to rename leaf: There is a file with the same name in the folder. (error)
2021/02/08 06:44:03 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/02/08 06:44:03 ERROR : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': not deleting directories as there were IO errors
    sync_test.go:1745: 
        	Error Trace:	sync_test.go:1745
        	            				sync_test.go:1764
        	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:717
        	            	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:1744
        	            	github.com/rclone/rclone/fs/sync.TestSyncBackupDirWithSuffix
        	            		/home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync_test.go:1764
        	            	testing.tRunner
        	            		/usr/local/go/src/testing/testing.go:1123
        	            	runtime.goexit
        	            		/usr/local/go/src/runtime/asm_amd64.s:1374
        	Test:       	TestSyncBackupDirWithSuffix
2021/02/08 06:44:03 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': 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/02/08 06:44:03 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:44:03 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: getFolderContents(map[count:1000 fi_pid:120835287 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/02/08 06:44:04 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:44:04 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: getFolderContents(map[count:1000 fi_pid:120835288 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/02/08 06:44:04 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: getFolderContents(map[count:1000 fi_pid:120835293 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/02/08 06:44:05 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:44:05 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: doDeleteFile(map[completedeletion:n fi_id:120835310]) options=[]
2021/02/08 06:44:05 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:44:12 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:44:12 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: doDeleteFile(map[completedeletion:n fi_id:120835290]) options=[]
2021/02/08 06:44:19 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:44:19 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: doDeleteFile(map[completedeletion:n fi_id:120835298]) options=[]
2021/02/08 06:44:31 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:44:31 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: doDeleteFile(map[completedeletion:n fi_id:120835304]) options=[]
2021/02/08 06:44:38 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:44:38 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: doDeleteFile(map[completedeletion:n fi_id:120835292]) options=[]
2021/02/08 06:44:45 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:44:45 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: getFolderContents(map[count:1000 fi_pid:120835288 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/02/08 06:44:46 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:44:46 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: doDeleteFolder(map[fi_id:120835288]) options=[]
2021/02/08 06:44:48 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:44:48 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: getFolderContents(map[count:1000 fi_pid:120835293 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/02/08 06:44:49 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:44:49 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: doDeleteFolder(map[fi_id:120835293]) options=[]
2021/02/08 06:44:50 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:44:50 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: getFolderContents(map[count:1000 fi_pid:120835287 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/02/08 06:44:51 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
--- FAIL: TestSyncBackupDirWithSuffix (252.84s)
=== RUN   TestSyncBackupDirSuffixOnly
    run.go:176: Remote "filefabric root 'rclone-test-rafazat2wabitec5pobusev1'", Local "Local file system at /tmp/rclone609366669", Modify Window "1s"
2021/02/08 06:44:51 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: getFolderContents(map[count:1000 fi_pid:120835287 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/02/08 06:44:51 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:44:51 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: doCreateNewFolder(map[fi_name:dst fi_pid:120835287]) options=[]
2021/02/08 06:44:52 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': Sleeping for 6s to wait for "error_background" error to clear
2021/02/08 06:44:58 DEBUG : pacer: low level retry 1/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2021/02/08 06:44:58 DEBUG : pacer: Rate limited, increasing sleep to 40ms
2021/02/08 06:45:00 DEBUG : pacer: Reducing sleep to 30ms
2021/02/08 06:45:00 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:45:00 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': 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:120835318 fi_size:3 responsetype:json]) options=[]
2021/02/08 06:45:01 DEBUG : pacer: Reducing sleep to 22.5ms
2021/02/08 06:45:01 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:45:03 DEBUG : pacer: Reducing sleep to 20ms
2021/02/08 06:45:03 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: doCompleteUpload(map[fi_size:3 remotetime:2001-02-03 04:05:06 uploadcode:b98bb466be82c94c0f8e5247d5cf166f]) options=[]
2021/02/08 06:45:04 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:45:04 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': 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:120835318 fi_size:3 responsetype:json]) options=[]
2021/02/08 06:45:05 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:45:06 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: doCompleteUpload(map[fi_size:3 remotetime:2001-02-03 04:05:06 uploadcode:433e3dd7d1fa863f523df882a9e9e94a]) options=[]
2021/02/08 06:45:07 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:45:07 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': 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:120835318 fi_size:5 responsetype:json]) options=[]
2021/02/08 06:45:09 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:45:10 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: doCompleteUpload(map[fi_size:5 remotetime:2001-02-03 04:05:06 uploadcode:663f34fa429b0d754ad706791dd65d30]) options=[]
2021/02/08 06:45:11 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:45:11 DEBUG : dst/three.txt: Correcting mime type from "text/plain" to "text/plain; charset=utf-8"
2021/02/08 06:45:11 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: doModifyFile(map[data:fi_contenttype=text/plain; charset=utf-8
 fi_id:120835322]) options=[]
2021/02/08 06:45:11 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:45:11 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: getFolderContents(map[count:1000 fi_pid:120835287 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/02/08 06:45:12 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:45:12 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: getFolderContents(map[count:1000 fi_pid:120835318 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/02/08 06:45:13 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:45:13 DEBUG : Creating backend with remote "TestFileFabric:rclone-test-rafazat2wabitec5pobusev1/dst"
2021/02/08 06:45:13 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': rpc: checkPathExists(map[path:rclone-test-rafazat2wabitec5pobusev1/dst pid:120673762]) options=[]
2021/02/08 06:45:13 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:45:13 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': rpc: getFolderContents(map[count:1000 fi_pid:120835318 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/02/08 06:45:14 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:45:14 DEBUG : two: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2021/02/08 06:45:14 DEBUG : two: Unchanged skipping
2021/02/08 06:45:14 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': Waiting for checks to finish
2021/02/08 06:45:14 DEBUG : one: Sizes differ (src 4 vs dst 3)
2021/02/08 06:45:14 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': rpc: checkPathExists(map[path:one.bak pid:120835318]) options=[]
2021/02/08 06:45:14 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:45:14 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': rpc: doRenameFile(map[fi_id:120835319 fi_name:one.bak]) options=[]
2021/02/08 06:45:21 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:45:21 INFO  : one: Moved (server-side) to: one.bak
2021/02/08 06:45:21 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': Waiting for transfers to finish
2021/02/08 06:45:21 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/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:120835318 fi_size:4 responsetype:json]) options=[]
2021/02/08 06:45:22 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:45:23 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': rpc: doCompleteUpload(map[fi_size:4 remotetime:2011-12-25 12:59:59 uploadcode:2aacf469ec37f4258bf99adc25b89dea]) options=[]
2021/02/08 06:45:25 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:45:25 INFO  : one: Copied (new)
2021/02/08 06:45:25 DEBUG : Waiting for deletions to finish
2021/02/08 06:45:25 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': rpc: checkPathExists(map[path:three.txt.bak pid:120835318]) options=[]
2021/02/08 06:45:25 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:45:25 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': rpc: doRenameFile(map[fi_id:120835322 fi_name:three.txt.bak]) options=[]
2021/02/08 06:45:32 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:45:32 INFO  : three.txt: Moved (server-side) to: three.txt.bak
2021/02/08 06:45:32 INFO  : three.txt: Moved into backup dir
2021/02/08 06:45:32 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: getFolderContents(map[count:1000 fi_pid:120835287 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/02/08 06:45:33 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:45:33 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: getFolderContents(map[count:1000 fi_pid:120835318 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/02/08 06:45:34 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
    fstest.go:297: Sleeping for 1s for list eventual consistency: 1/3
    fstest.go:300: Flushing the directory cache
2021/02/08 06:45:35 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': 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/02/08 06:45:36 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:45:36 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: getFolderContents(map[count:1000 fi_pid:120835287 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/02/08 06:45:36 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:45:36 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: getFolderContents(map[count:1000 fi_pid:120835318 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/02/08 06:45:37 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
    fstest.go:297: Sleeping for 2s for list eventual consistency: 2/3
    fstest.go:300: Flushing the directory cache
2021/02/08 06:45:39 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': 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/02/08 06:45:40 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:45:40 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: getFolderContents(map[count:1000 fi_pid:120835287 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/02/08 06:45:40 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:45:40 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: getFolderContents(map[count:1000 fi_pid:120835318 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/02/08 06:45:40 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
    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:1733
        	            				sync_test.go:1770
        	Error:      	Should be true
        	Test:       	TestSyncBackupDirSuffixOnly
        	Messages:   	listing wrong, want
        	            	  dst/one (4), dst/one.bak (3), dst/three.txt.bak (5), dst/two (3) got
        	            	  dst/one (4), dst/one.bak (3), dst/three.txt.bak.txt (5), dst/two (3)
    fstest.go:190: 
        	Error Trace:	fstest.go:190
        	            				fstest.go:307
        	            				fstest.go:337
        	            				fstest.go:349
        	            				sync_test.go:1733
        	            				sync_test.go:1770
        	Error:      	Should be true
        	Test:       	TestSyncBackupDirSuffixOnly
        	Messages:   	Unexpected file "dst/three.txt.bak.txt"
    fstest.go:202: Not found "dst/three.txt.bak"
    fstest.go:205: 
        	Error Trace:	fstest.go:205
        	            				fstest.go:309
        	            				fstest.go:337
        	            				fstest.go:349
        	            				sync_test.go:1733
        	            				sync_test.go:1770
        	Error:      	Not equal: 
        	            	expected: 0
        	            	actual  : 1
        	Test:       	TestSyncBackupDirSuffixOnly
        	Messages:   	1 objects not found
2021/02/08 06:45:44 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': 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/02/08 06:45:46 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:45:46 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: getFolderContents(map[count:1000 fi_pid:120835287 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/02/08 06:45:46 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:45:46 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': 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:120835318 fi_size:6 responsetype:json]) options=[]
2021/02/08 06:45:47 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:45:48 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: doCompleteUpload(map[fi_size:6 remotetime:2011-12-25 12:59:59 uploadcode:92a9e8b8655ddde2660102081655959f]) options=[]
2021/02/08 06:45:49 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:45:49 DEBUG : dst/three.txt: Correcting mime type from "text/plain" to "text/plain; charset=utf-8"
2021/02/08 06:45:49 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: doModifyFile(map[data:fi_contenttype=text/plain; charset=utf-8
 fi_id:120835327]) options=[]
2021/02/08 06:45:50 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:45:50 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: getFolderContents(map[count:1000 fi_pid:120835287 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/02/08 06:45:50 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:45:50 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: getFolderContents(map[count:1000 fi_pid:120835318 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/02/08 06:45:51 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
    fstest.go:297: Sleeping for 1s for list eventual consistency: 1/3
    fstest.go:300: Flushing the directory cache
2021/02/08 06:45:52 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': 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/02/08 06:45:53 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:45:53 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: getFolderContents(map[count:1000 fi_pid:120835287 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/02/08 06:45:54 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:45:54 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: getFolderContents(map[count:1000 fi_pid:120835318 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/02/08 06:45:55 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
    fstest.go:297: Sleeping for 2s for list eventual consistency: 2/3
    fstest.go:300: Flushing the directory cache
2021/02/08 06:45:57 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': 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/02/08 06:45:57 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:45:57 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: getFolderContents(map[count:1000 fi_pid:120835287 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/02/08 06:45:58 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:45:58 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: getFolderContents(map[count:1000 fi_pid:120835318 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/02/08 06:45:58 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
    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:1739
        	            				sync_test.go:1770
        	Error:      	Should be true
        	Test:       	TestSyncBackupDirSuffixOnly
        	Messages:   	listing wrong, want
        	            	  dst/one (4), dst/one.bak (3), dst/three.txt (6), dst/three.txt.bak (5), dst/two (3) got
        	            	  dst/one (4), dst/one.bak (3), dst/three.txt (6), dst/three.txt.bak.txt (5), dst/two (3)
    fstest.go:190: 
        	Error Trace:	fstest.go:190
        	            				fstest.go:307
        	            				fstest.go:337
        	            				fstest.go:349
        	            				sync_test.go:1739
        	            				sync_test.go:1770
        	Error:      	Should be true
        	Test:       	TestSyncBackupDirSuffixOnly
        	Messages:   	Unexpected file "dst/three.txt.bak.txt"
    fstest.go:202: Not found "dst/three.txt.bak"
    fstest.go:205: 
        	Error Trace:	fstest.go:205
        	            				fstest.go:309
        	            				fstest.go:337
        	            				fstest.go:349
        	            				sync_test.go:1739
        	            				sync_test.go:1770
        	Error:      	Not equal: 
        	            	expected: 0
        	            	actual  : 1
        	Test:       	TestSyncBackupDirSuffixOnly
        	Messages:   	1 objects not found
2021/02/08 06:46:02 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': rpc: getFolderContents(map[count:1000 fi_pid:120835318 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/02/08 06:46:02 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:46:02 DEBUG : one.bak: Excluded
2021/02/08 06:46:02 DEBUG : one: Sizes differ (src 5 vs dst 4)
2021/02/08 06:46:02 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': rpc: checkPathExists(map[path:one.bak pid:120835318]) options=[]
2021/02/08 06:46:02 DEBUG : two: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2021/02/08 06:46:02 DEBUG : two: Unchanged skipping
2021/02/08 06:46:02 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': Waiting for checks to finish
2021/02/08 06:46:02 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:46:02 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': rpc: doDeleteFile(map[completedeletion:n fi_id:120835319]) options=[]
2021/02/08 06:46:09 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:46:09 INFO  : one.bak: Deleted
2021/02/08 06:46:09 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': rpc: doRenameFile(map[fi_id:120835324 fi_name:one.bak]) options=[]
2021/02/08 06:46:17 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:46:17 INFO  : one: Moved (server-side) to: one.bak
2021/02/08 06:46:17 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': Waiting for transfers to finish
2021/02/08 06:46:17 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/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:120835318 fi_size:5 responsetype:json]) options=[]
2021/02/08 06:46:18 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:46:19 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': rpc: doCompleteUpload(map[fi_size:5 remotetime:2011-12-30 12:59:59 uploadcode:2944227b2b7d925cf6671fca70944a72]) options=[]
2021/02/08 06:46:20 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:46:20 INFO  : one: Copied (new)
2021/02/08 06:46:20 DEBUG : Waiting for deletions to finish
2021/02/08 06:46:20 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': rpc: checkPathExists(map[path:three.txt.bak pid:120835318]) options=[]
2021/02/08 06:46:20 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': rpc: checkPathExists(map[path:three.txt.bak.txt.bak pid:120835318]) options=[]
2021/02/08 06:46:21 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:46:21 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': rpc: doRenameFile(map[fi_id:120835327 fi_name:three.txt.bak]) options=[]
2021/02/08 06:46:21 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:46:21 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': rpc: doRenameFile(map[fi_id:120835322 fi_name:three.txt.bak.txt.bak]) options=[]
2021/02/08 06:46:22 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': >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/02/08 06:46:22 ERROR : three.txt: Couldn't move: failed to rename leaf: There is a file with the same name in the folder. (error)
2021/02/08 06:46:22 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/02/08 06:46:28 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:46:28 INFO  : three.txt.bak.txt: Moved (server-side) to: three.txt.bak.txt.bak
2021/02/08 06:46:28 INFO  : three.txt.bak.txt: Moved into backup dir
2021/02/08 06:46:28 ERROR : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': not deleting directories as there were IO errors
    sync_test.go:1745: 
        	Error Trace:	sync_test.go:1745
        	            				sync_test.go:1770
        	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:717
        	            	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:1744
        	            	github.com/rclone/rclone/fs/sync.TestSyncBackupDirSuffixOnly
        	            		/home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync_test.go:1770
        	            	testing.tRunner
        	            		/usr/local/go/src/testing/testing.go:1123
        	            	runtime.goexit
        	            		/usr/local/go/src/runtime/asm_amd64.s:1374
        	Test:       	TestSyncBackupDirSuffixOnly
2021/02/08 06:46:28 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': 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/02/08 06:46:29 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:46:29 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: getFolderContents(map[count:1000 fi_pid:120835287 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/02/08 06:46:30 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:46:30 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: getFolderContents(map[count:1000 fi_pid:120835318 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/02/08 06:46:30 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:46:30 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: doDeleteFile(map[completedeletion:n fi_id:120835330]) options=[]
2021/02/08 06:46:42 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:46:42 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: doDeleteFile(map[completedeletion:n fi_id:120835324]) options=[]
2021/02/08 06:46:53 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:46:53 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: doDeleteFile(map[completedeletion:n fi_id:120835327]) options=[]
2021/02/08 06:47:00 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:47:00 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: doDeleteFile(map[completedeletion:n fi_id:120835322]) options=[]
2021/02/08 06:47:07 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:47:07 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: doDeleteFile(map[completedeletion:n fi_id:120835320]) options=[]
2021/02/08 06:47:19 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:47:19 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: getFolderContents(map[count:1000 fi_pid:120835318 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/02/08 06:47:20 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:47:20 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: doDeleteFolder(map[fi_id:120835318]) options=[]
2021/02/08 06:47:21 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:47:21 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: getFolderContents(map[count:1000 fi_pid:120835287 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/02/08 06:47:22 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
--- FAIL: TestSyncBackupDirSuffixOnly (151.30s)
=== RUN   TestSyncSuffix
    run.go:176: Remote "filefabric root 'rclone-test-rafazat2wabitec5pobusev1'", Local "Local file system at /tmp/rclone609366669", Modify Window "1s"
2021/02/08 06:47:22 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: getFolderContents(map[count:1000 fi_pid:120835287 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/02/08 06:47:23 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:47:23 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: doCreateNewFolder(map[fi_name:dst fi_pid:120835287]) options=[]
2021/02/08 06:47:23 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': Sleeping for 6s to wait for "error_background" error to clear
2021/02/08 06:47:29 DEBUG : pacer: low level retry 1/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2021/02/08 06:47:29 DEBUG : pacer: Rate limited, increasing sleep to 40ms
2021/02/08 06:47:32 DEBUG : pacer: Reducing sleep to 30ms
2021/02/08 06:47:32 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:47:32 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': 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:120835331 fi_size:3 responsetype:json]) options=[]
2021/02/08 06:47:33 DEBUG : pacer: Reducing sleep to 22.5ms
2021/02/08 06:47:33 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:47:34 DEBUG : pacer: Reducing sleep to 20ms
2021/02/08 06:47:34 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: doCompleteUpload(map[fi_size:3 remotetime:2001-02-03 04:05:06 uploadcode:f406cbc03bcf1f20230f25943e7cd2a0]) options=[]
2021/02/08 06:47:35 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:47:35 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': 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:120835331 fi_size:3 responsetype:json]) options=[]
2021/02/08 06:47:36 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:47:37 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: doCompleteUpload(map[fi_size:3 remotetime:2001-02-03 04:05:06 uploadcode:1310e184ec81b995d7756982b8f80086]) options=[]
2021/02/08 06:47:38 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:47:38 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': 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:120835331 fi_size:5 responsetype:json]) options=[]
2021/02/08 06:47:39 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:47:41 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: doCompleteUpload(map[fi_size:5 remotetime:2001-02-03 04:05:06 uploadcode:4def38b96d9679837eb53696ec328c1f]) options=[]
2021/02/08 06:47:42 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:47:42 DEBUG : dst/three.txt: Correcting mime type from "text/plain" to "text/plain; charset=utf-8"
2021/02/08 06:47:42 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: doModifyFile(map[data:fi_contenttype=text/plain; charset=utf-8
 fi_id:120835334]) options=[]
2021/02/08 06:47:42 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:47:42 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: getFolderContents(map[count:1000 fi_pid:120835287 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/02/08 06:47:43 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:47:43 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: getFolderContents(map[count:1000 fi_pid:120835331 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/02/08 06:47:44 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:47:44 DEBUG : Creating backend with remote "TestFileFabric:rclone-test-rafazat2wabitec5pobusev1/dst"
2021/02/08 06:47:44 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': rpc: checkPathExists(map[path:rclone-test-rafazat2wabitec5pobusev1/dst pid:120673762]) options=[]
2021/02/08 06:47:44 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:47:44 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': rpc: checkPathExists(map[path:one pid:120835331]) options=[]
2021/02/08 06:47:45 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:47:45 DEBUG : one: Sizes differ (src 4 vs dst 3)
2021/02/08 06:47:45 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': rpc: checkPathExists(map[path:one.bak pid:120835331]) options=[]
2021/02/08 06:47:45 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:47:45 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': rpc: doRenameFile(map[fi_id:120835332 fi_name:one.bak]) options=[]
2021/02/08 06:47:53 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:47:53 INFO  : one: Moved (server-side) to: one.bak
2021/02/08 06:47:53 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/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:120835331 fi_size:4 responsetype:json]) options=[]
2021/02/08 06:47:54 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:47:55 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': rpc: doCompleteUpload(map[fi_size:4 remotetime:2011-12-25 12:59:59 uploadcode:7b1e5a3ab37b6afd5b1a6f3b01cf9e8c]) options=[]
2021/02/08 06:47:56 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:47:56 INFO  : one: Copied (new)
2021/02/08 06:47:56 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': rpc: checkPathExists(map[path:two pid:120835331]) options=[]
2021/02/08 06:47:56 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:47:56 DEBUG : two: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2021/02/08 06:47:56 DEBUG : two: Unchanged skipping
2021/02/08 06:47:56 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': rpc: checkPathExists(map[path:three.txt pid:120835331]) options=[]
2021/02/08 06:47:56 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:47:56 DEBUG : three.txt: Sizes differ (src 6 vs dst 5)
2021/02/08 06:47:56 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': rpc: checkPathExists(map[path:three.txt.bak pid:120835331]) options=[]
2021/02/08 06:47:57 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:47:57 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': rpc: doRenameFile(map[fi_id:120835334 fi_name:three.txt.bak]) options=[]
2021/02/08 06:48:04 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:48:04 INFO  : three.txt: Moved (server-side) to: three.txt.bak
2021/02/08 06:48:04 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': 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:120835331 fi_size:6 responsetype:json]) options=[]
2021/02/08 06:48:06 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:48:07 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': rpc: doCompleteUpload(map[fi_size:6 remotetime:2001-02-03 04:05:06 uploadcode:03e913552ea00f2d65f397f99dd6fe96]) options=[]
2021/02/08 06:48:08 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:48:08 DEBUG : three.txt: Correcting mime type from "text/plain" to "text/plain; charset=utf-8"
2021/02/08 06:48:08 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': rpc: doModifyFile(map[data:fi_contenttype=text/plain; charset=utf-8
 fi_id:120835336]) options=[]
2021/02/08 06:48:08 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:48:08 INFO  : three.txt: Copied (new)
2021/02/08 06:48:08 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: getFolderContents(map[count:1000 fi_pid:120835287 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/02/08 06:48:09 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:48:09 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: getFolderContents(map[count:1000 fi_pid:120835331 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/02/08 06:48:10 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
    fstest.go:297: Sleeping for 1s for list eventual consistency: 1/3
    fstest.go:300: Flushing the directory cache
2021/02/08 06:48:11 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': 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/02/08 06:48:12 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:48:12 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: getFolderContents(map[count:1000 fi_pid:120835287 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/02/08 06:48:13 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:48:13 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: getFolderContents(map[count:1000 fi_pid:120835331 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/02/08 06:48:13 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
    fstest.go:297: Sleeping for 2s for list eventual consistency: 2/3
    fstest.go:300: Flushing the directory cache
2021/02/08 06:48:15 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': 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/02/08 06:48:15 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:48:15 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: getFolderContents(map[count:1000 fi_pid:120835287 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/02/08 06:48:16 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:48:16 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: getFolderContents(map[count:1000 fi_pid:120835331 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/02/08 06:48:16 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
    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:1828
        	            				sync_test.go:1860
        	Error:      	Should be true
        	Test:       	TestSyncSuffix
        	Messages:   	listing wrong, want
        	            	  dst/one (4), dst/one.bak (3), dst/three.txt (6), dst/three.txt.bak (5), dst/two (3) got
        	            	  dst/one (4), dst/one.bak (3), dst/three.txt (6), dst/three.txt.bak.txt (5), dst/two (3)
    fstest.go:190: 
        	Error Trace:	fstest.go:190
        	            				fstest.go:307
        	            				fstest.go:337
        	            				fstest.go:349
        	            				sync_test.go:1828
        	            				sync_test.go:1860
        	Error:      	Should be true
        	Test:       	TestSyncSuffix
        	Messages:   	Unexpected file "dst/three.txt.bak.txt"
    fstest.go:202: Not found "dst/three.txt.bak"
    fstest.go:205: 
        	Error Trace:	fstest.go:205
        	            				fstest.go:309
        	            				fstest.go:337
        	            				fstest.go:349
        	            				sync_test.go:1828
        	            				sync_test.go:1860
        	Error:      	Not equal: 
        	            	expected: 0
        	            	actual  : 1
        	Test:       	TestSyncSuffix
        	Messages:   	1 objects not found
2021/02/08 06:48:20 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': 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/02/08 06:48:20 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:48:20 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: getFolderContents(map[count:1000 fi_pid:120835287 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/02/08 06:48:21 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:48:21 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: getFolderContents(map[count:1000 fi_pid:120835331 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/02/08 06:48:21 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
    fstest.go:297: Sleeping for 1s for list eventual consistency: 1/3
    fstest.go:300: Flushing the directory cache
2021/02/08 06:48:22 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': 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/02/08 06:48:23 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:48:23 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: getFolderContents(map[count:1000 fi_pid:120835287 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/02/08 06:48:23 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:48:23 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: getFolderContents(map[count:1000 fi_pid:120835331 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/02/08 06:48:23 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
    fstest.go:297: Sleeping for 2s for list eventual consistency: 2/3
    fstest.go:300: Flushing the directory cache
2021/02/08 06:48:25 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': 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/02/08 06:48:26 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:48:26 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: getFolderContents(map[count:1000 fi_pid:120835287 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/02/08 06:48:26 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:48:26 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: getFolderContents(map[count:1000 fi_pid:120835331 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/02/08 06:48:27 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
    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:1834
        	            				sync_test.go:1860
        	Error:      	Should be true
        	Test:       	TestSyncSuffix
        	Messages:   	listing wrong, want
        	            	  dst/one (4), dst/one.bak (3), dst/three.txt (6), dst/three.txt.bak (5), dst/two (3) got
        	            	  dst/one (4), dst/one.bak (3), dst/three.txt (6), dst/three.txt.bak.txt (5), dst/two (3)
    fstest.go:190: 
        	Error Trace:	fstest.go:190
        	            				fstest.go:307
        	            				fstest.go:337
        	            				fstest.go:349
        	            				sync_test.go:1834
        	            				sync_test.go:1860
        	Error:      	Should be true
        	Test:       	TestSyncSuffix
        	Messages:   	Unexpected file "dst/three.txt.bak.txt"
    fstest.go:202: Not found "dst/three.txt.bak"
    fstest.go:205: 
        	Error Trace:	fstest.go:205
        	            				fstest.go:309
        	            				fstest.go:337
        	            				fstest.go:349
        	            				sync_test.go:1834
        	            				sync_test.go:1860
        	Error:      	Not equal: 
        	            	expected: 0
        	            	actual  : 1
        	Test:       	TestSyncSuffix
        	Messages:   	1 objects not found
2021/02/08 06:48:31 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': rpc: checkPathExists(map[path:one pid:120835331]) options=[]
2021/02/08 06:48:31 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:48:31 DEBUG : one: Sizes differ (src 5 vs dst 4)
2021/02/08 06:48:31 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': rpc: checkPathExists(map[path:one.bak pid:120835331]) options=[]
2021/02/08 06:48:31 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:48:31 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': rpc: doDeleteFile(map[completedeletion:n fi_id:120835332]) options=[]
2021/02/08 06:48:43 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:48:43 INFO  : one.bak: Deleted
2021/02/08 06:48:43 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': rpc: doRenameFile(map[fi_id:120835335 fi_name:one.bak]) options=[]
2021/02/08 06:48:50 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:48:50 INFO  : one: Moved (server-side) to: one.bak
2021/02/08 06:48:50 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/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:120835331 fi_size:5 responsetype:json]) options=[]
2021/02/08 06:48:51 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:48:53 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': rpc: doCompleteUpload(map[fi_size:5 remotetime:2011-12-30 12:59:59 uploadcode:e2dea9dde903848cdadd2b54794e53e2]) options=[]
2021/02/08 06:48:54 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:48:54 INFO  : one: Copied (new)
2021/02/08 06:48:54 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': rpc: checkPathExists(map[path:two pid:120835331]) options=[]
2021/02/08 06:48:54 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:48:54 DEBUG : two: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2021/02/08 06:48:54 DEBUG : two: Unchanged skipping
2021/02/08 06:48:54 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': rpc: checkPathExists(map[path:three.txt pid:120835331]) options=[]
2021/02/08 06:48:55 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:48:55 DEBUG : three.txt: Sizes differ (src 19 vs dst 6)
2021/02/08 06:48:55 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': rpc: checkPathExists(map[path:three.txt.bak pid:120835331]) options=[]
2021/02/08 06:48:55 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:48:55 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': rpc: doRenameFile(map[fi_id:120835336 fi_name:three.txt.bak]) options=[]
2021/02/08 06:48:57 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1/dst': >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/02/08 06:48:57 ERROR : three.txt: Couldn't move: failed to rename leaf: There is a file with the same name in the folder. (error)
    sync_test.go:1844: 
        	Error Trace:	sync_test.go:1844
        	            				sync_test.go:1860
        	Error:      	Received unexpected error:
        	            	failed to rename leaf: There is a file with the same name in the folder. (error)
        	            	moving to --backup-dir failed
        	            	github.com/rclone/rclone/fs/operations.moveOrCopyFile
        	            		/home/rclone/go/src/github.com/rclone/rclone/fs/operations/operations.go:1753
        	            	github.com/rclone/rclone/fs/operations.CopyFile
        	            		/home/rclone/go/src/github.com/rclone/rclone/fs/operations/operations.go:1777
        	            	github.com/rclone/rclone/fs/sync.testSyncSuffix
        	            		/home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync_test.go:1843
        	            	github.com/rclone/rclone/fs/sync.TestSyncSuffix
        	            		/home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync_test.go:1860
        	            	testing.tRunner
        	            		/usr/local/go/src/testing/testing.go:1123
        	            	runtime.goexit
        	            		/usr/local/go/src/runtime/asm_amd64.s:1374
        	Test:       	TestSyncSuffix
2021/02/08 06:48:57 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': 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/02/08 06:48:58 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:48:58 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: getFolderContents(map[count:1000 fi_pid:120835287 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/02/08 06:48:59 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:48:59 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: getFolderContents(map[count:1000 fi_pid:120835331 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/02/08 06:49:00 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:49:00 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: doDeleteFile(map[completedeletion:n fi_id:120835337]) options=[]
2021/02/08 06:49:11 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:49:11 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: doDeleteFile(map[completedeletion:n fi_id:120835335]) options=[]
2021/02/08 06:49:22 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:49:22 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: doDeleteFile(map[completedeletion:n fi_id:120835336]) options=[]
2021/02/08 06:49:34 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:49:34 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: doDeleteFile(map[completedeletion:n fi_id:120835334]) options=[]
2021/02/08 06:49:41 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:49:41 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: doDeleteFile(map[completedeletion:n fi_id:120835333]) options=[]
2021/02/08 06:49:53 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:49:53 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: getFolderContents(map[count:1000 fi_pid:120835331 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/02/08 06:49:54 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:49:54 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: doDeleteFolder(map[fi_id:120835331]) options=[]
2021/02/08 06:49:55 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
2021/02/08 06:49:55 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: getFolderContents(map[count:1000 fi_pid:120835287 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/02/08 06:49:56 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
--- FAIL: TestSyncSuffix (153.55s)
FAIL
2021/02/08 06:49:56 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': Purge remote
2021/02/08 06:49:56 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': rpc: doDeleteFolder(map[fi_id:120835287]) options=[]
2021/02/08 06:49:56 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': Sleeping for 6s to wait for "error_background" error to clear
2021/02/08 06:50:02 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/02/08 06:50:02 DEBUG : pacer: Rate limited, increasing sleep to 40ms
2021/02/08 06:50:02 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': Sleeping for 6s to wait for "error_background" error to clear
2021/02/08 06:50:08 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/02/08 06:50:08 DEBUG : pacer: Rate limited, increasing sleep to 80ms
2021/02/08 06:50:10 DEBUG : pacer: Reducing sleep to 60ms
2021/02/08 06:50:10 DEBUG : filefabric root 'rclone-test-rafazat2wabitec5pobusev1': >rpc: result=Success (ok), err=<nil>
"./sync.test -test.v -test.timeout 1h0m0s -remote TestFileFabric: -verbose -test.run '^(TestSyncBackupDirSuffixOnly|TestSyncBackupDirWithSuffix|TestSyncSuffix)$'" - Finished ERROR in 9m31.961771281s (try 4/5): exit status 1: Failed [TestSyncBackupDirWithSuffix TestSyncBackupDirSuffixOnly TestSyncSuffix]