"./sync.test -test.v -test.timeout 1h0m0s -remote TestFileFabric: -verbose -test.run '^(TestServerSideMoveDeleteEmptySourceDirs|TestSyncBackupDirSuffixOnly|TestSyncBackupDirWithSuffix|TestSyncSuffix)$'" - Starting (try 2/5) 2021/02/08 06:19:40 DEBUG : Creating backend with remote "TestFileFabric:rclone-test-qavamaq7pesizip2zufigoc3" 2021/02/08 06:19:40 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: checkPathExists(map[path:rclone-test-qavamaq7pesizip2zufigoc3 pid:120673762]) options=[] 2021/02/08 06:19:41 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:19:41 DEBUG : Creating backend with remote "/tmp/rclone216482712" === RUN TestServerSideMoveDeleteEmptySourceDirs run.go:176: Remote "filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3'", Local "Local file system at /tmp/rclone216482712", Modify Window "1s" 2021/02/08 06:19:41 DEBUG : Creating backend with remote "TestFileFabric:rclone-test-yutapul2cucitad2rijakoz7" 2021/02/08 06:19:41 DEBUG : filefabric root 'rclone-test-yutapul2cucitad2rijakoz7': rpc: checkPathExists(map[path:rclone-test-yutapul2cucitad2rijakoz7 pid:120673762]) options=[] 2021/02/08 06:19:41 DEBUG : filefabric root 'rclone-test-yutapul2cucitad2rijakoz7': >rpc: result=Success (ok), err= 2021/02/08 06:19:41 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': 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:19:42 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:19:42 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: doCreateNewFolder(map[fi_name:rclone-test-qavamaq7pesizip2zufigoc3 fi_pid:120673762]) options=[] 2021/02/08 06:19:45 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:19:45 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: doInitUpload(map[directuploadsupport:n fi_contenttype:application/octet-stream fi_filename:potato2 fi_localtime:2001-02-03 04:05:06 fi_modified:2001-02-03 04:05:06 fi_name:potato2 fi_pid:120835046 fi_size:60 responsetype:json]) options=[] 2021/02/08 06:19:46 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:19:47 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: doCompleteUpload(map[fi_size:60 remotetime:2001-02-03 04:05:06 uploadcode:11b72aeeb9423620a9c063073b9f08a0]) options=[] 2021/02/08 06:19:49 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:19:49 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: doInitUpload(map[directuploadsupport:n fi_contenttype:application/octet-stream fi_filename:empty space fi_localtime:2011-12-25 12:59:59 fi_modified:2011-12-25 12:59:59 fi_name:empty space fi_pid:120835046 fi_size:1 responsetype:json]) options=[] 2021/02/08 06:19:50 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:19:52 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: doCompleteUpload(map[fi_size:1 remotetime:2011-12-25 12:59:59 uploadcode:f6572da691e5cb85e863e6b38dcba552]) options=[] 2021/02/08 06:19:53 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:19:53 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: doInitUpload(map[directuploadsupport:n fi_contenttype:application/octet-stream fi_filename:potato3 fi_localtime:2011-12-25 12:59:59 fi_modified:2011-12-25 12:59:59 fi_name:potato3 fi_pid:120835046 fi_size:68 responsetype:json]) options=[] 2021/02/08 06:19:55 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:19:56 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: doCompleteUpload(map[fi_size:68 remotetime:2011-12-25 12:59:59 uploadcode:6eea205adff306412068e7c633e23dc7]) options=[] 2021/02/08 06:19:57 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:19:57 DEBUG : tomatoDir: Making directory 2021/02/08 06:19:57 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: getFolderContents(map[count:1000 fi_pid:120835046 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:19:59 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:19:59 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: doCreateNewFolder(map[fi_name:tomatoDir fi_pid:120835046]) options=[] 2021/02/08 06:20:02 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:20:02 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: getFolderContents(map[count:1000 fi_pid:120835046 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:20:03 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:20:03 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: getFolderContents(map[count:1000 fi_pid:120835054 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:20:03 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= sync_test.go:1294: Server side move (if possible) filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3' -> filefabric root 'rclone-test-yutapul2cucitad2rijakoz7' 2021/02/08 06:20:03 DEBUG : filefabric root 'rclone-test-yutapul2cucitad2rijakoz7': 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:20:04 DEBUG : filefabric root 'rclone-test-yutapul2cucitad2rijakoz7': >rpc: result=Success (ok), err= 2021/02/08 06:20:04 DEBUG : filefabric root 'rclone-test-yutapul2cucitad2rijakoz7': rpc: doCreateNewFolder(map[fi_name:rclone-test-yutapul2cucitad2rijakoz7 fi_pid:120673762]) options=[] 2021/02/08 06:20:07 DEBUG : filefabric root 'rclone-test-yutapul2cucitad2rijakoz7': >rpc: result=Success (ok), err= 2021/02/08 06:20:07 DEBUG : filefabric root 'rclone-test-yutapul2cucitad2rijakoz7': rpc: doInitUpload(map[directuploadsupport:n fi_contenttype:application/octet-stream fi_filename:empty space fi_localtime:2011-12-25 12:59:59 fi_modified:2011-12-25 12:59:59 fi_name:empty space fi_pid:120835055 fi_size:1 responsetype:json]) options=[] 2021/02/08 06:20:08 DEBUG : filefabric root 'rclone-test-yutapul2cucitad2rijakoz7': >rpc: result=Success (ok), err= 2021/02/08 06:20:10 DEBUG : filefabric root 'rclone-test-yutapul2cucitad2rijakoz7': rpc: doCompleteUpload(map[fi_size:1 remotetime:2011-12-25 12:59:59 uploadcode:cdc861c966b7464f05a8d23278686aae]) options=[] 2021/02/08 06:20:11 DEBUG : filefabric root 'rclone-test-yutapul2cucitad2rijakoz7': >rpc: result=Success (ok), err= 2021/02/08 06:20:11 DEBUG : filefabric root 'rclone-test-yutapul2cucitad2rijakoz7': rpc: doInitUpload(map[directuploadsupport:n fi_contenttype:application/octet-stream fi_filename:potato3 fi_localtime:2001-02-03 04:05:06 fi_modified:2001-02-03 04:05:06 fi_name:potato3 fi_pid:120835055 fi_size:60 responsetype:json]) options=[] 2021/02/08 06:20:12 DEBUG : filefabric root 'rclone-test-yutapul2cucitad2rijakoz7': >rpc: result=Success (ok), err= 2021/02/08 06:20:14 DEBUG : filefabric root 'rclone-test-yutapul2cucitad2rijakoz7': rpc: doCompleteUpload(map[fi_size:60 remotetime:2001-02-03 04:05:06 uploadcode:7d0109d3391bd72f65ac0c6b634fcd3b]) options=[] 2021/02/08 06:20:15 DEBUG : filefabric root 'rclone-test-yutapul2cucitad2rijakoz7': >rpc: result=Success (ok), err= 2021/02/08 06:20:15 DEBUG : filefabric root 'rclone-test-yutapul2cucitad2rijakoz7': rpc: getFolderContents(map[count:1000 fi_pid:120835055 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:20:15 DEBUG : filefabric root 'rclone-test-yutapul2cucitad2rijakoz7': >rpc: result=Success (ok), err= 2021/02/08 06:20:15 DEBUG : filefabric root 'rclone-test-yutapul2cucitad2rijakoz7': Using server-side directory move 2021/02/08 06:20:15 INFO : filefabric root 'rclone-test-yutapul2cucitad2rijakoz7': Server side directory move failed - fallback to file moves: can't copy directory - destination already exists 2021/02/08 06:20:15 DEBUG : filefabric root 'rclone-test-yutapul2cucitad2rijakoz7': rpc: getFolderContents(map[count:1000 fi_pid:120835055 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:20:15 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: getFolderContents(map[count:1000 fi_pid:120835046 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:20:16 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:20:16 DEBUG : filefabric root 'rclone-test-yutapul2cucitad2rijakoz7': >rpc: result=Success (ok), err= 2021/02/08 06:20:16 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: getFolderContents(map[count:1000 fi_pid:120835054 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:20:16 DEBUG : empty space: Size and modification time the same (differ by 0s, within tolerance 1s) 2021/02/08 06:20:16 DEBUG : empty space: Unchanged skipping 2021/02/08 06:20:16 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: doDeleteFile(map[completedeletion:n fi_id:120835049]) options=[] 2021/02/08 06:20:16 DEBUG : filefabric root 'rclone-test-yutapul2cucitad2rijakoz7': rpc: doMoveFiles(map[dir_id:120835055 fi_ids:120835048]) options=[] 2021/02/08 06:20:16 DEBUG : potato3: Sizes differ (src 68 vs dst 60) 2021/02/08 06:20:16 DEBUG : filefabric root 'rclone-test-yutapul2cucitad2rijakoz7': rpc: doDeleteFile(map[completedeletion:n fi_id:120835057]) options=[] 2021/02/08 06:20:16 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:20:16 DEBUG : filefabric root 'rclone-test-yutapul2cucitad2rijakoz7': Waiting for checks to finish 2021/02/08 06:20:24 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:20:24 INFO : empty space: Deleted 2021/02/08 06:20:24 DEBUG : filefabric root 'rclone-test-yutapul2cucitad2rijakoz7': Waiting for transfers to finish 2021/02/08 06:20:25 DEBUG : filefabric root 'rclone-test-yutapul2cucitad2rijakoz7': >rpc: result=Success (ok), err= 2021/02/08 06:20:25 INFO : potato3: Deleted 2021/02/08 06:20:25 DEBUG : filefabric root 'rclone-test-yutapul2cucitad2rijakoz7': rpc: doMoveFiles(map[dir_id:120835055 fi_ids:120835052]) options=[] 2021/02/08 06:20:36 DEBUG : filefabric root 'rclone-test-yutapul2cucitad2rijakoz7': >rpc: result=Succcess. (ok), err= 2021/02/08 06:20:36 INFO : potato2: Moved (server-side) 2021/02/08 06:20:45 DEBUG : filefabric root 'rclone-test-yutapul2cucitad2rijakoz7': >rpc: result=Succcess. (ok), err= 2021/02/08 06:20:45 INFO : potato3: Moved (server-side) 2021/02/08 06:20:45 DEBUG : tomatoDir: Removing directory 2021/02/08 06:20:45 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: getFolderContents(map[count:1000 fi_pid:120835054 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:20:45 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:20:45 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: doDeleteFolder(map[fi_id:120835054]) options=[] 2021/02/08 06:20:47 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:20:47 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': deleted 1 directories 2021/02/08 06:20:47 INFO : There was nothing to transfer 2021/02/08 06:20:47 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: getFolderContents(map[count:1000 fi_pid:120835046 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:20:47 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:20:47 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: getFolderContents(map[count:1000 fi_pid:120835046 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:20:48 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:20:48 DEBUG : filefabric root 'rclone-test-yutapul2cucitad2rijakoz7': rpc: getFolderContents(map[count:1000 fi_pid:120835055 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:20:49 DEBUG : filefabric root 'rclone-test-yutapul2cucitad2rijakoz7': >rpc: result=Success (ok), err= 2021/02/08 06:20:49 DEBUG : Creating backend with remote "TestFileFabric:rclone-test-fewacuh6kewovam1tukovaq0" 2021/02/08 06:20:49 DEBUG : filefabric root 'rclone-test-fewacuh6kewovam1tukovaq0': rpc: checkPathExists(map[path:rclone-test-fewacuh6kewovam1tukovaq0 pid:120673762]) options=[] 2021/02/08 06:20:49 DEBUG : filefabric root 'rclone-test-fewacuh6kewovam1tukovaq0': >rpc: result=Success (ok), err= 2021/02/08 06:20:49 DEBUG : tomatoDir: Making directory 2021/02/08 06:20:49 DEBUG : filefabric root 'rclone-test-yutapul2cucitad2rijakoz7': rpc: getFolderContents(map[count:1000 fi_pid:120835055 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:20:49 DEBUG : filefabric root 'rclone-test-yutapul2cucitad2rijakoz7': >rpc: result=Success (ok), err= 2021/02/08 06:20:49 DEBUG : filefabric root 'rclone-test-yutapul2cucitad2rijakoz7': rpc: doCreateNewFolder(map[fi_name:tomatoDir fi_pid:120835055]) options=[] 2021/02/08 06:20:52 DEBUG : filefabric root 'rclone-test-yutapul2cucitad2rijakoz7': >rpc: result=Success (ok), err= 2021/02/08 06:20:52 DEBUG : filefabric root 'rclone-test-fewacuh6kewovam1tukovaq0': Using server-side directory move 2021/02/08 06:20:52 DEBUG : filefabric root 'rclone-test-fewacuh6kewovam1tukovaq0': 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:20:53 DEBUG : filefabric root 'rclone-test-fewacuh6kewovam1tukovaq0': >rpc: result=Success (ok), err= 2021/02/08 06:20:53 DEBUG : filefabric root 'rclone-test-fewacuh6kewovam1tukovaq0': rpc: doRenameFolder(map[fi_id:120835055 fi_name:rclone-test-fewacuh6kewovam1tukovaq0]) options=[] 2021/02/08 06:21:03 DEBUG : filefabric root 'rclone-test-fewacuh6kewovam1tukovaq0': >rpc: result=Success (ok), err= 2021/02/08 06:21:03 DEBUG : filefabric root 'rclone-test-fewacuh6kewovam1tukovaq0': rpc: getUserBackgroundTasks(map[taskid:1078939]) options=[] 2021/02/08 06:21:04 DEBUG : filefabric root 'rclone-test-fewacuh6kewovam1tukovaq0': >rpc: result=Success (ok), err= 2021/02/08 06:21:04 DEBUG : filefabric root 'rclone-test-fewacuh6kewovam1tukovaq0': Waiting for task ID 1078939: Rename folder S3 Storage/smestoragencw/rclone-test-fewacuh6kewovam1tukovaq0: to completed for 1s - waited 584.856837ms already 2021/02/08 06:21:05 DEBUG : filefabric root 'rclone-test-fewacuh6kewovam1tukovaq0': rpc: getUserBackgroundTasks(map[taskid:1078939]) options=[] 2021/02/08 06:21:05 DEBUG : filefabric root 'rclone-test-fewacuh6kewovam1tukovaq0': >rpc: result=Success (ok), err= 2021/02/08 06:21:05 DEBUG : filefabric root 'rclone-test-fewacuh6kewovam1tukovaq0': Waiting for task ID 1078939: Rename folder S3 Storage/smestoragencw/rclone-test-fewacuh6kewovam1tukovaq0: to completed for 1s - waited 2.206957118s already 2021/02/08 06:21:06 DEBUG : filefabric root 'rclone-test-fewacuh6kewovam1tukovaq0': rpc: getUserBackgroundTasks(map[taskid:1078939]) options=[] 2021/02/08 06:21:07 DEBUG : filefabric root 'rclone-test-fewacuh6kewovam1tukovaq0': >rpc: result=Success (ok), err= 2021/02/08 06:21:07 DEBUG : filefabric root 'rclone-test-fewacuh6kewovam1tukovaq0': Waiting for task ID 1078939: Rename folder S3 Storage/smestoragencw/rclone-test-fewacuh6kewovam1tukovaq0: to completed for 1s - waited 3.850826817s already 2021/02/08 06:21:08 DEBUG : filefabric root 'rclone-test-fewacuh6kewovam1tukovaq0': rpc: getUserBackgroundTasks(map[taskid:1078939]) options=[] 2021/02/08 06:21:08 DEBUG : filefabric root 'rclone-test-fewacuh6kewovam1tukovaq0': >rpc: result=Success (ok), err= 2021/02/08 06:21:08 DEBUG : filefabric root 'rclone-test-fewacuh6kewovam1tukovaq0': Waiting for task ID 1078939: Rename folder S3 Storage/smestoragencw/rclone-test-fewacuh6kewovam1tukovaq0: to completed for 1s - waited 5.421025268s already 2021/02/08 06:21:09 DEBUG : filefabric root 'rclone-test-fewacuh6kewovam1tukovaq0': rpc: getUserBackgroundTasks(map[taskid:1078939]) options=[] 2021/02/08 06:21:10 DEBUG : filefabric root 'rclone-test-fewacuh6kewovam1tukovaq0': >rpc: result=Success (ok), err= 2021/02/08 06:21:10 DEBUG : filefabric root 'rclone-test-fewacuh6kewovam1tukovaq0': Waiting for task ID 1078939: Rename folder S3 Storage/smestoragencw/rclone-test-fewacuh6kewovam1tukovaq0: to completed for 1s - waited 6.962619778s already 2021/02/08 06:21:11 DEBUG : filefabric root 'rclone-test-fewacuh6kewovam1tukovaq0': rpc: getUserBackgroundTasks(map[taskid:1078939]) options=[] 2021/02/08 06:21:12 DEBUG : filefabric root 'rclone-test-fewacuh6kewovam1tukovaq0': >rpc: result=Success (ok), err= 2021/02/08 06:21:12 DEBUG : filefabric root 'rclone-test-fewacuh6kewovam1tukovaq0': Waiting for task ID 1078939: Rename folder S3 Storage/smestoragencw/rclone-test-fewacuh6kewovam1tukovaq0: to completed for 1s - waited 8.699625115s already 2021/02/08 06:21:13 DEBUG : filefabric root 'rclone-test-fewacuh6kewovam1tukovaq0': rpc: getUserBackgroundTasks(map[taskid:1078939]) options=[] 2021/02/08 06:21:13 DEBUG : filefabric root 'rclone-test-fewacuh6kewovam1tukovaq0': >rpc: result=Success (ok), err= 2021/02/08 06:21:13 DEBUG : filefabric root 'rclone-test-fewacuh6kewovam1tukovaq0': Waiting for task ID 1078939: Rename folder S3 Storage/smestoragencw/rclone-test-fewacuh6kewovam1tukovaq0: to completed for 1s - waited 10.387022164s already 2021/02/08 06:21:14 DEBUG : filefabric root 'rclone-test-fewacuh6kewovam1tukovaq0': rpc: getUserBackgroundTasks(map[taskid:1078939]) options=[] 2021/02/08 06:21:15 DEBUG : filefabric root 'rclone-test-fewacuh6kewovam1tukovaq0': >rpc: result=Success (ok), err= 2021/02/08 06:21:15 DEBUG : filefabric root 'rclone-test-fewacuh6kewovam1tukovaq0': Waiting for task ID 1078939: Rename folder S3 Storage/smestoragencw/rclone-test-fewacuh6kewovam1tukovaq0: to completed for 1s - waited 12.115525335s already 2021/02/08 06:21:16 DEBUG : filefabric root 'rclone-test-fewacuh6kewovam1tukovaq0': rpc: getUserBackgroundTasks(map[taskid:1078939]) options=[] 2021/02/08 06:21:17 DEBUG : filefabric root 'rclone-test-fewacuh6kewovam1tukovaq0': >rpc: result=Success (ok), err= 2021/02/08 06:21:17 DEBUG : filefabric root 'rclone-test-fewacuh6kewovam1tukovaq0': Waiting for task ID 1078939: Rename folder S3 Storage/smestoragencw/rclone-test-fewacuh6kewovam1tukovaq0: to completed for 1s - waited 13.781599485s already 2021/02/08 06:21:18 DEBUG : filefabric root 'rclone-test-fewacuh6kewovam1tukovaq0': rpc: getUserBackgroundTasks(map[taskid:1078939]) options=[] 2021/02/08 06:21:19 DEBUG : filefabric root 'rclone-test-fewacuh6kewovam1tukovaq0': >rpc: result=Success (ok), err= 2021/02/08 06:21:19 DEBUG : filefabric root 'rclone-test-fewacuh6kewovam1tukovaq0': Waiting for task ID 1078939: Rename folder S3 Storage/smestoragencw/rclone-test-fewacuh6kewovam1tukovaq0: to completed for 1s - waited 15.519764037s already 2021/02/08 06:21:20 DEBUG : filefabric root 'rclone-test-fewacuh6kewovam1tukovaq0': rpc: getUserBackgroundTasks(map[taskid:1078939]) options=[] 2021/02/08 06:21:20 DEBUG : filefabric root 'rclone-test-fewacuh6kewovam1tukovaq0': >rpc: result=Success (ok), err= 2021/02/08 06:21:20 DEBUG : filefabric root 'rclone-test-fewacuh6kewovam1tukovaq0': Waiting for task ID 1078939: Rename folder S3 Storage/smestoragencw/rclone-test-fewacuh6kewovam1tukovaq0: to completed for 1s - waited 17.063801898s already 2021/02/08 06:21:21 DEBUG : filefabric root 'rclone-test-fewacuh6kewovam1tukovaq0': rpc: getUserBackgroundTasks(map[taskid:1078939]) options=[] 2021/02/08 06:21:22 DEBUG : filefabric root 'rclone-test-fewacuh6kewovam1tukovaq0': >rpc: result=Success (ok), err= 2021/02/08 06:21:22 DEBUG : filefabric root 'rclone-test-fewacuh6kewovam1tukovaq0': Waiting for task ID 1078939: Rename folder S3 Storage/smestoragencw/rclone-test-fewacuh6kewovam1tukovaq0: to completed for 1s - waited 18.93985973s already 2021/02/08 06:21:23 DEBUG : filefabric root 'rclone-test-fewacuh6kewovam1tukovaq0': rpc: getUserBackgroundTasks(map[taskid:1078939]) options=[] 2021/02/08 06:21:24 DEBUG : filefabric root 'rclone-test-fewacuh6kewovam1tukovaq0': >rpc: result=Success (ok), err= 2021/02/08 06:21:24 DEBUG : filefabric root 'rclone-test-fewacuh6kewovam1tukovaq0': Waiting for task ID 1078939: Rename folder S3 Storage/smestoragencw/rclone-test-fewacuh6kewovam1tukovaq0: to completed for 1s - waited 20.978717198s already 2021/02/08 06:21:25 DEBUG : filefabric root 'rclone-test-fewacuh6kewovam1tukovaq0': rpc: getUserBackgroundTasks(map[taskid:1078939]) options=[] 2021/02/08 06:21:26 DEBUG : filefabric root 'rclone-test-fewacuh6kewovam1tukovaq0': >rpc: result=Success (ok), err= 2021/02/08 06:21:26 DEBUG : filefabric root 'rclone-test-fewacuh6kewovam1tukovaq0': Waiting for task ID 1078939: Rename folder S3 Storage/smestoragencw/rclone-test-fewacuh6kewovam1tukovaq0: to completed for 1s - waited 22.64660104s already 2021/02/08 06:21:27 DEBUG : filefabric root 'rclone-test-fewacuh6kewovam1tukovaq0': rpc: getUserBackgroundTasks(map[taskid:1078939]) options=[] 2021/02/08 06:21:27 DEBUG : filefabric root 'rclone-test-fewacuh6kewovam1tukovaq0': >rpc: result=Success (ok), err= 2021/02/08 06:21:27 DEBUG : filefabric root 'rclone-test-fewacuh6kewovam1tukovaq0': Waiting for task ID 1078939: Rename folder S3 Storage/smestoragencw/rclone-test-fewacuh6kewovam1tukovaq0: to completed for 1s - waited 24.368381482s already 2021/02/08 06:21:28 DEBUG : filefabric root 'rclone-test-fewacuh6kewovam1tukovaq0': rpc: getUserBackgroundTasks(map[taskid:1078939]) options=[] 2021/02/08 06:21:29 DEBUG : filefabric root 'rclone-test-fewacuh6kewovam1tukovaq0': >rpc: result=Success (ok), err= 2021/02/08 06:21:29 DEBUG : filefabric root 'rclone-test-fewacuh6kewovam1tukovaq0': Waiting for task ID 1078939: Rename folder S3 Storage/smestoragencw/rclone-test-fewacuh6kewovam1tukovaq0: to completed for 1s - waited 26.026661569s already 2021/02/08 06:21:30 DEBUG : filefabric root 'rclone-test-fewacuh6kewovam1tukovaq0': rpc: getUserBackgroundTasks(map[taskid:1078939]) options=[] 2021/02/08 06:21:31 DEBUG : filefabric root 'rclone-test-fewacuh6kewovam1tukovaq0': >rpc: result=Success (ok), err= 2021/02/08 06:21:31 DEBUG : filefabric root 'rclone-test-fewacuh6kewovam1tukovaq0': Waiting for task ID 1078939: Rename folder S3 Storage/smestoragencw/rclone-test-fewacuh6kewovam1tukovaq0: to completed for 1s - waited 27.798894668s already 2021/02/08 06:21:32 DEBUG : filefabric root 'rclone-test-fewacuh6kewovam1tukovaq0': rpc: getUserBackgroundTasks(map[taskid:1078939]) options=[] 2021/02/08 06:21:32 DEBUG : filefabric root 'rclone-test-fewacuh6kewovam1tukovaq0': >rpc: result=Success (ok), err= 2021/02/08 06:21:32 DEBUG : filefabric root 'rclone-test-fewacuh6kewovam1tukovaq0': Waiting for task ID 1078939: Rename folder S3 Storage/smestoragencw/rclone-test-fewacuh6kewovam1tukovaq0: to completed for 1s - waited 29.486218477s already 2021/02/08 06:21:33 DEBUG : filefabric root 'rclone-test-fewacuh6kewovam1tukovaq0': rpc: getUserBackgroundTasks(map[taskid:1078939]) options=[] 2021/02/08 06:21:34 DEBUG : filefabric root 'rclone-test-fewacuh6kewovam1tukovaq0': >rpc: result=Success (ok), err= 2021/02/08 06:21:34 INFO : filefabric root 'rclone-test-fewacuh6kewovam1tukovaq0': Server side directory move succeeded 2021/02/08 06:21:34 DEBUG : filefabric root 'rclone-test-fewacuh6kewovam1tukovaq0': 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:21:35 DEBUG : filefabric root 'rclone-test-fewacuh6kewovam1tukovaq0': >rpc: result=Success (ok), err= 2021/02/08 06:21:35 DEBUG : filefabric root 'rclone-test-fewacuh6kewovam1tukovaq0': rpc: getFolderContents(map[count:1000 fi_pid:120835055 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:21:36 DEBUG : filefabric root 'rclone-test-fewacuh6kewovam1tukovaq0': >rpc: result=Success (ok), err= 2021/02/08 06:21:36 DEBUG : filefabric root 'rclone-test-fewacuh6kewovam1tukovaq0': rpc: getFolderContents(map[count:1000 fi_pid:120835067 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:21:37 DEBUG : filefabric root 'rclone-test-fewacuh6kewovam1tukovaq0': >rpc: result=Success (ok), err= 2021/02/08 06:21:37 DEBUG : filefabric root 'rclone-test-yutapul2cucitad2rijakoz7': 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:21:37 DEBUG : filefabric root 'rclone-test-yutapul2cucitad2rijakoz7': >rpc: result=Success (ok), err= 2021/02/08 06:21:37 ERROR : : error listing: directory not found 2021/02/08 06:21:37 DEBUG : filefabric root 'rclone-test-yutapul2cucitad2rijakoz7': 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:21:37 DEBUG : filefabric root 'rclone-test-yutapul2cucitad2rijakoz7': >rpc: result=Success (ok), err= 2021/02/08 06:21:37 ERROR : : error listing: directory not found 2021/02/08 06:21:37 DEBUG : filefabric root 'rclone-test-fewacuh6kewovam1tukovaq0': Purge remote 2021/02/08 06:21:37 DEBUG : filefabric root 'rclone-test-fewacuh6kewovam1tukovaq0': rpc: doDeleteFolder(map[fi_id:120835055]) options=[] 2021/02/08 06:21:39 DEBUG : filefabric root 'rclone-test-fewacuh6kewovam1tukovaq0': >rpc: result=Success (ok), err= 2021/02/08 06:21:39 DEBUG : filefabric root 'rclone-test-yutapul2cucitad2rijakoz7': Purge remote 2021/02/08 06:21:39 DEBUG : filefabric root 'rclone-test-yutapul2cucitad2rijakoz7': 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:21:39 DEBUG : filefabric root 'rclone-test-yutapul2cucitad2rijakoz7': >rpc: result=Success (ok), err= 2021/02/08 06:21:39 purge failed: directory not found 2021/02/08 06:21:39 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: getFolderContents(map[count:1000 fi_pid:120835046 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:21:40 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:21:40 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: getFolderContents(map[count:1000 fi_pid:120835046 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:21:41 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= --- PASS: TestServerSideMoveDeleteEmptySourceDirs (119.93s) === RUN TestSyncBackupDirWithSuffix run.go:176: Remote "filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3'", Local "Local file system at /tmp/rclone216482712", Modify Window "1s" 2021/02/08 06:21:41 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: getFolderContents(map[count:1000 fi_pid:120835046 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:21:41 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:21:41 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: doCreateNewFolder(map[fi_name:dst fi_pid:120835046]) options=[] 2021/02/08 06:21:44 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:21:44 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': 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:120835081 fi_size:3 responsetype:json]) options=[] 2021/02/08 06:21:45 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:21:46 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: doCompleteUpload(map[fi_size:3 remotetime:2001-02-03 04:05:06 uploadcode:34a80abfab73b11daed952142c153dca]) options=[] 2021/02/08 06:21:47 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:21:47 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': 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:120835081 fi_size:3 responsetype:json]) options=[] 2021/02/08 06:21:48 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:21:50 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: doCompleteUpload(map[fi_size:3 remotetime:2001-02-03 04:05:06 uploadcode:9b86c1aaa53182d8ca0cad00f95f7ccf]) options=[] 2021/02/08 06:21:51 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:21:51 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': 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:120835081 fi_size:5 responsetype:json]) options=[] 2021/02/08 06:21:52 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:21:53 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: doCompleteUpload(map[fi_size:5 remotetime:2001-02-03 04:05:06 uploadcode:d63cf528de62a60034b109a255bf72e9]) options=[] 2021/02/08 06:21:54 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:21:54 DEBUG : dst/three.txt: Correcting mime type from "text/plain" to "text/plain; charset=utf-8" 2021/02/08 06:21:54 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: doModifyFile(map[data:fi_contenttype=text/plain; charset=utf-8 fi_id:120835090]) options=[] 2021/02/08 06:21:54 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:21:54 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: getFolderContents(map[count:1000 fi_pid:120835046 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:21:55 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:21:55 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: getFolderContents(map[count:1000 fi_pid:120835081 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:21:56 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:21:56 DEBUG : Creating backend with remote "TestFileFabric:rclone-test-qavamaq7pesizip2zufigoc3/dst" 2021/02/08 06:21:56 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': rpc: checkPathExists(map[path:rclone-test-qavamaq7pesizip2zufigoc3/dst pid:120673762]) options=[] 2021/02/08 06:21:56 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': >rpc: result=Success (ok), err= 2021/02/08 06:21:56 DEBUG : Creating backend with remote "TestFileFabric:rclone-test-qavamaq7pesizip2zufigoc3/backup" 2021/02/08 06:21:56 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/backup': rpc: checkPathExists(map[path:rclone-test-qavamaq7pesizip2zufigoc3/backup pid:120673762]) options=[] 2021/02/08 06:21:57 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/backup': >rpc: result=Success (ok), err= 2021/02/08 06:21:57 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': rpc: getFolderContents(map[count:1000 fi_pid:120835081 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:21:57 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': >rpc: result=Success (ok), err= 2021/02/08 06:21:57 DEBUG : one: Sizes differ (src 4 vs dst 3) 2021/02/08 06:21:57 DEBUG : two: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2021/02/08 06:21:57 DEBUG : two: Unchanged skipping 2021/02/08 06:21:57 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/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:21:57 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': Waiting for checks to finish 2021/02/08 06:21:58 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/backup': >rpc: result=Success (ok), err= 2021/02/08 06:21:58 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/backup': rpc: getFolderContents(map[count:1000 fi_pid:120835046 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:21:58 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/backup': >rpc: result=Success (ok), err= 2021/02/08 06:21:58 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/backup': rpc: getFolderContents(map[count:1000 fi_pid:120835046 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:21:58 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/backup': >rpc: result=Success (ok), err= 2021/02/08 06:21:58 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/backup': rpc: doCreateNewFolder(map[fi_name:backup fi_pid:120835046]) options=[] 2021/02/08 06:22:01 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/backup': >rpc: result=Success (ok), err= 2021/02/08 06:22:01 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/backup': rpc: doRenameFile(map[fi_id:120835085 fi_name:one.bak.juzaley2]) options=[] 2021/02/08 06:22:08 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/backup': >rpc: result=Success (ok), err= 2021/02/08 06:22:08 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/backup': rpc: doMoveFiles(map[dir_id:120835092 fi_ids:120835085]) options=[] 2021/02/08 06:22:27 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/backup': >rpc: result=Succcess. (ok), err= 2021/02/08 06:22:27 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/backup': rpc: doRenameFile(map[fi_id:120835085 fi_name:one.bak]) options=[] 2021/02/08 06:22:36 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/backup': >rpc: result=Success (ok), err= 2021/02/08 06:22:36 INFO : one: Moved (server-side) to: one.bak 2021/02/08 06:22:36 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': Waiting for transfers to finish 2021/02/08 06:22:36 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/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:120835081 fi_size:4 responsetype:json]) options=[] 2021/02/08 06:22:37 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': >rpc: result=Success (ok), err= 2021/02/08 06:22:38 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': rpc: doCompleteUpload(map[fi_size:4 remotetime:2011-12-25 12:59:59 uploadcode:cbfc612321560141929b94d598ea1139]) options=[] 2021/02/08 06:22:39 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': >rpc: result=Success (ok), err= 2021/02/08 06:22:39 INFO : one: Copied (new) 2021/02/08 06:22:39 DEBUG : Waiting for deletions to finish 2021/02/08 06:22:39 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/backup': rpc: checkPathExists(map[path:three.txt.bak pid:120835092]) options=[] 2021/02/08 06:22:39 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/backup': >rpc: result=Success (ok), err= 2021/02/08 06:22:39 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/backup': rpc: doRenameFile(map[fi_id:120835090 fi_name:three.txt.bak.zeworuc5]) options=[] 2021/02/08 06:22:47 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/backup': >rpc: result=Success (ok), err= 2021/02/08 06:22:47 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/backup': rpc: doMoveFiles(map[dir_id:120835092 fi_ids:120835090]) options=[] 2021/02/08 06:23:07 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/backup': >rpc: result=Succcess. (ok), err= 2021/02/08 06:23:07 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/backup': rpc: doRenameFile(map[fi_id:120835090 fi_name:three.txt.bak]) options=[] 2021/02/08 06:23:15 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/backup': >rpc: result=Success (ok), err= 2021/02/08 06:23:15 INFO : three.txt: Moved (server-side) to: three.txt.bak 2021/02/08 06:23:15 INFO : three.txt: Moved into backup dir 2021/02/08 06:23:15 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: getFolderContents(map[count:1000 fi_pid:120835046 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:23:16 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:23:16 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: getFolderContents(map[count:1000 fi_pid:120835081 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:23:16 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: getFolderContents(map[count:1000 fi_pid:120835092 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:23:16 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:23:16 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= fstest.go:297: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:300: Flushing the directory cache 2021/02/08 06:23:17 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': 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:23:18 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:23:18 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: getFolderContents(map[count:1000 fi_pid:120835046 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:23:18 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:23:18 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: getFolderContents(map[count:1000 fi_pid:120835092 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:23:18 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: getFolderContents(map[count:1000 fi_pid:120835081 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:23:19 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:23:19 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= fstest.go:297: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:300: Flushing the directory cache 2021/02/08 06:23:21 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': 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:23:22 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:23:22 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: getFolderContents(map[count:1000 fi_pid:120835046 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:23:23 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:23:23 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: getFolderContents(map[count:1000 fi_pid:120835081 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:23:23 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: getFolderContents(map[count:1000 fi_pid:120835092 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:23:23 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:23:23 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= fstest.go:297: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:300: Flushing the directory cache fstest.go:304: Error Trace: fstest.go:304 fstest.go:337 fstest.go:349 sync_test.go: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:23:27 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': 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:23:28 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:23:28 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: getFolderContents(map[count:1000 fi_pid:120835046 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:23:28 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:23:28 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': 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:120835081 fi_size:6 responsetype:json]) options=[] 2021/02/08 06:23:29 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:23:30 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: doCompleteUpload(map[fi_size:6 remotetime:2011-12-25 12:59:59 uploadcode:7eafc343375363965384d5b8584557c8]) options=[] 2021/02/08 06:23:31 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:23:31 DEBUG : dst/three.txt: Correcting mime type from "text/plain" to "text/plain; charset=utf-8" 2021/02/08 06:23:31 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: doModifyFile(map[data:fi_contenttype=text/plain; charset=utf-8 fi_id:120835129]) options=[] 2021/02/08 06:23:32 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:23:32 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: getFolderContents(map[count:1000 fi_pid:120835046 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:23:32 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:23:32 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: getFolderContents(map[count:1000 fi_pid:120835081 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:23:32 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: getFolderContents(map[count:1000 fi_pid:120835092 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:23:32 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:23:33 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= fstest.go:297: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:300: Flushing the directory cache 2021/02/08 06:23:34 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': 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:23:34 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:23:34 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: getFolderContents(map[count:1000 fi_pid:120835046 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:23:34 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:23:34 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: getFolderContents(map[count:1000 fi_pid:120835081 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:23:34 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: getFolderContents(map[count:1000 fi_pid:120835092 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:23:35 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:23:36 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= fstest.go:297: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:300: Flushing the directory cache 2021/02/08 06:23:38 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': 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:23:39 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:23:39 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: getFolderContents(map[count:1000 fi_pid:120835046 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:23:39 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:23:39 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: getFolderContents(map[count:1000 fi_pid:120835081 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:23:39 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: getFolderContents(map[count:1000 fi_pid:120835092 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:23:40 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:23:40 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= fstest.go:297: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:300: Flushing the directory cache fstest.go:304: Error Trace: fstest.go:304 fstest.go:337 fstest.go:349 sync_test.go: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:23:44 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': rpc: getFolderContents(map[count:1000 fi_pid:120835081 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:23:44 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': >rpc: result=Success (ok), err= 2021/02/08 06:23:44 DEBUG : one: Sizes differ (src 5 vs dst 4) 2021/02/08 06:23:44 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/backup': rpc: checkPathExists(map[path:one.bak pid:120835092]) options=[] 2021/02/08 06:23:44 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': Waiting for checks to finish 2021/02/08 06:23:44 DEBUG : two: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2021/02/08 06:23:44 DEBUG : two: Unchanged skipping 2021/02/08 06:23:44 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/backup': >rpc: result=Success (ok), err= 2021/02/08 06:23:44 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/backup': rpc: doDeleteFile(map[completedeletion:n fi_id:120835085]) options=[] 2021/02/08 06:23:53 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/backup': >rpc: result=Success (ok), err= 2021/02/08 06:23:53 INFO : one.bak: Deleted 2021/02/08 06:23:53 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/backup': rpc: doRenameFile(map[fi_id:120835107 fi_name:one.bak.bunuhed7]) options=[] 2021/02/08 06:24:01 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/backup': >rpc: result=Success (ok), err= 2021/02/08 06:24:01 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/backup': rpc: doMoveFiles(map[dir_id:120835092 fi_ids:120835107]) options=[] 2021/02/08 06:24:20 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/backup': >rpc: result=Succcess. (ok), err= 2021/02/08 06:24:20 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/backup': rpc: doRenameFile(map[fi_id:120835107 fi_name:one.bak]) options=[] 2021/02/08 06:24:28 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/backup': >rpc: result=Success (ok), err= 2021/02/08 06:24:28 INFO : one: Moved (server-side) to: one.bak 2021/02/08 06:24:28 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': Waiting for transfers to finish 2021/02/08 06:24:28 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/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:120835081 fi_size:5 responsetype:json]) options=[] 2021/02/08 06:24:29 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': >rpc: result=Success (ok), err= 2021/02/08 06:24:30 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': rpc: doCompleteUpload(map[fi_size:5 remotetime:2011-12-30 12:59:59 uploadcode:d5c5b18320bb4bb81f4ec2808ecef4bf]) options=[] 2021/02/08 06:24:31 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': >rpc: result=Success (ok), err= 2021/02/08 06:24:31 INFO : one: Copied (new) 2021/02/08 06:24:31 DEBUG : Waiting for deletions to finish 2021/02/08 06:24:31 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/backup': rpc: checkPathExists(map[path:three.txt.bak pid:120835092]) options=[] 2021/02/08 06:24:32 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/backup': >rpc: result=Success (ok), err= 2021/02/08 06:24:32 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/backup': rpc: doRenameFile(map[fi_id:120835129 fi_name:three.txt.bak.vozakih0]) options=[] 2021/02/08 06:24:39 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/backup': >rpc: result=Success (ok), err= 2021/02/08 06:24:39 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/backup': rpc: doMoveFiles(map[dir_id:120835092 fi_ids:120835129]) options=[] 2021/02/08 06:24:58 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/backup': >rpc: result=Succcess. (ok), err= 2021/02/08 06:24:58 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/backup': rpc: doRenameFile(map[fi_id:120835129 fi_name:three.txt.bak]) options=[] 2021/02/08 06:25:00 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/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:25:00 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:25:00 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:25:00 ERROR : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/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:25:00 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': 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:25:00 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:25:00 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: getFolderContents(map[count:1000 fi_pid:120835046 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:25:01 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:25:01 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: getFolderContents(map[count:1000 fi_pid:120835081 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:25:01 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: getFolderContents(map[count:1000 fi_pid:120835092 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:25:02 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:25:02 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: doDeleteFile(map[completedeletion:n fi_id:120835107]) options=[] 2021/02/08 06:25:02 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:25:14 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:25:14 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: doDeleteFile(map[completedeletion:n fi_id:120835090]) options=[] 2021/02/08 06:25:21 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:25:21 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: doDeleteFile(map[completedeletion:n fi_id:120835129]) options=[] 2021/02/08 06:25:29 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:25:29 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: doDeleteFile(map[completedeletion:n fi_id:120835139]) options=[] 2021/02/08 06:25:35 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:25:35 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: doDeleteFile(map[completedeletion:n fi_id:120835087]) options=[] 2021/02/08 06:25:42 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:25:42 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: getFolderContents(map[count:1000 fi_pid:120835081 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:25:43 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:25:43 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: doDeleteFolder(map[fi_id:120835081]) options=[] 2021/02/08 06:25:44 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:25:44 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: getFolderContents(map[count:1000 fi_pid:120835092 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:25:45 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:25:45 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: doDeleteFolder(map[fi_id:120835092]) options=[] 2021/02/08 06:25:47 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:25:47 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: getFolderContents(map[count:1000 fi_pid:120835046 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:25:48 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= --- FAIL: TestSyncBackupDirWithSuffix (247.07s) === RUN TestSyncBackupDirSuffixOnly run.go:176: Remote "filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3'", Local "Local file system at /tmp/rclone216482712", Modify Window "1s" 2021/02/08 06:25:48 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: getFolderContents(map[count:1000 fi_pid:120835046 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:25:48 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:25:48 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: doCreateNewFolder(map[fi_name:dst fi_pid:120835046]) options=[] 2021/02/08 06:25:48 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': Sleeping for 6s to wait for "error_background" error to clear 2021/02/08 06:25:54 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:25:54 DEBUG : pacer: Rate limited, increasing sleep to 40ms 2021/02/08 06:25:57 DEBUG : pacer: Reducing sleep to 30ms 2021/02/08 06:25:57 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:25:57 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': 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:120835151 fi_size:3 responsetype:json]) options=[] 2021/02/08 06:25:58 DEBUG : pacer: Reducing sleep to 22.5ms 2021/02/08 06:25:58 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:25:59 DEBUG : pacer: Reducing sleep to 20ms 2021/02/08 06:25:59 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: doCompleteUpload(map[fi_size:3 remotetime:2001-02-03 04:05:06 uploadcode:de534a6196a72de332aa2d5acca34427]) options=[] 2021/02/08 06:26:01 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:26:01 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': 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:120835151 fi_size:3 responsetype:json]) options=[] 2021/02/08 06:26:02 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:26:03 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: doCompleteUpload(map[fi_size:3 remotetime:2001-02-03 04:05:06 uploadcode:1382cb361e14e493828a727aec6b2255]) options=[] 2021/02/08 06:26:04 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:26:04 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': 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:120835151 fi_size:5 responsetype:json]) options=[] 2021/02/08 06:26:06 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:26:07 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: doCompleteUpload(map[fi_size:5 remotetime:2001-02-03 04:05:06 uploadcode:c0b08479329b242356441a61da52659b]) options=[] 2021/02/08 06:26:08 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:26:08 DEBUG : dst/three.txt: Correcting mime type from "text/plain" to "text/plain; charset=utf-8" 2021/02/08 06:26:08 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: doModifyFile(map[data:fi_contenttype=text/plain; charset=utf-8 fi_id:120835155]) options=[] 2021/02/08 06:26:08 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:26:08 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: getFolderContents(map[count:1000 fi_pid:120835046 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:26:09 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:26:09 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: getFolderContents(map[count:1000 fi_pid:120835151 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:26:10 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:26:10 DEBUG : Creating backend with remote "TestFileFabric:rclone-test-qavamaq7pesizip2zufigoc3/dst" 2021/02/08 06:26:10 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': rpc: checkPathExists(map[path:rclone-test-qavamaq7pesizip2zufigoc3/dst pid:120673762]) options=[] 2021/02/08 06:26:10 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': >rpc: result=Success (ok), err= 2021/02/08 06:26:10 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': rpc: getFolderContents(map[count:1000 fi_pid:120835151 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:26:10 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': >rpc: result=Success (ok), err= 2021/02/08 06:26:10 DEBUG : two: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2021/02/08 06:26:10 DEBUG : two: Unchanged skipping 2021/02/08 06:26:10 DEBUG : one: Sizes differ (src 4 vs dst 3) 2021/02/08 06:26:10 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': rpc: checkPathExists(map[path:one.bak pid:120835151]) options=[] 2021/02/08 06:26:10 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': Waiting for checks to finish 2021/02/08 06:26:11 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': >rpc: result=Success (ok), err= 2021/02/08 06:26:11 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': rpc: doRenameFile(map[fi_id:120835152 fi_name:one.bak]) options=[] 2021/02/08 06:26:19 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': >rpc: result=Success (ok), err= 2021/02/08 06:26:19 INFO : one: Moved (server-side) to: one.bak 2021/02/08 06:26:19 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': Waiting for transfers to finish 2021/02/08 06:26:19 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/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:120835151 fi_size:4 responsetype:json]) options=[] 2021/02/08 06:26:20 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': >rpc: result=Success (ok), err= 2021/02/08 06:26:21 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': rpc: doCompleteUpload(map[fi_size:4 remotetime:2011-12-25 12:59:59 uploadcode:6f290862022860a427cd720c51e92d1c]) options=[] 2021/02/08 06:26:22 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': >rpc: result=Success (ok), err= 2021/02/08 06:26:22 INFO : one: Copied (new) 2021/02/08 06:26:22 DEBUG : Waiting for deletions to finish 2021/02/08 06:26:22 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': rpc: checkPathExists(map[path:three.txt.bak pid:120835151]) options=[] 2021/02/08 06:26:22 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': >rpc: result=Success (ok), err= 2021/02/08 06:26:22 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': rpc: doRenameFile(map[fi_id:120835155 fi_name:three.txt.bak]) options=[] 2021/02/08 06:26:30 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': >rpc: result=Success (ok), err= 2021/02/08 06:26:30 INFO : three.txt: Moved (server-side) to: three.txt.bak 2021/02/08 06:26:30 INFO : three.txt: Moved into backup dir 2021/02/08 06:26:30 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: getFolderContents(map[count:1000 fi_pid:120835046 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:26:31 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:26:31 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: getFolderContents(map[count:1000 fi_pid:120835151 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:26:32 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= fstest.go:297: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:300: Flushing the directory cache 2021/02/08 06:26:33 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': 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:26:34 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:26:34 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: getFolderContents(map[count:1000 fi_pid:120835046 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:26:34 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:26:34 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: getFolderContents(map[count:1000 fi_pid:120835151 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:26:34 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= fstest.go:297: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:300: Flushing the directory cache 2021/02/08 06:26:36 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': 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:26:37 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:26:37 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: getFolderContents(map[count:1000 fi_pid:120835046 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:26:38 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:26:38 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: getFolderContents(map[count:1000 fi_pid:120835151 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:26:39 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= fstest.go:297: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:300: Flushing the directory cache fstest.go:304: Error Trace: fstest.go:304 fstest.go:337 fstest.go:349 sync_test.go: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:26:43 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': 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:26:44 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:26:44 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: getFolderContents(map[count:1000 fi_pid:120835046 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:26:45 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:26:45 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': 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:120835151 fi_size:6 responsetype:json]) options=[] 2021/02/08 06:26:46 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:26:47 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: doCompleteUpload(map[fi_size:6 remotetime:2011-12-25 12:59:59 uploadcode:50f48bc1c8f78e1782634944acf17028]) options=[] 2021/02/08 06:26:48 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:26:48 DEBUG : dst/three.txt: Correcting mime type from "text/plain" to "text/plain; charset=utf-8" 2021/02/08 06:26:48 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: doModifyFile(map[data:fi_contenttype=text/plain; charset=utf-8 fi_id:120835163]) options=[] 2021/02/08 06:26:49 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:26:49 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: getFolderContents(map[count:1000 fi_pid:120835046 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:26:49 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:26:49 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: getFolderContents(map[count:1000 fi_pid:120835151 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:26:50 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= fstest.go:297: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:300: Flushing the directory cache 2021/02/08 06:26:51 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': 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:26:52 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:26:52 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: getFolderContents(map[count:1000 fi_pid:120835046 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:26:53 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:26:53 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: getFolderContents(map[count:1000 fi_pid:120835151 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:26:53 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= fstest.go:297: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:300: Flushing the directory cache 2021/02/08 06:26:55 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': 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:26:55 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:26:55 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: getFolderContents(map[count:1000 fi_pid:120835046 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:26:55 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:26:55 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: getFolderContents(map[count:1000 fi_pid:120835151 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:26:56 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= fstest.go:297: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:300: Flushing the directory cache fstest.go:304: Error Trace: fstest.go:304 fstest.go:337 fstest.go:349 sync_test.go: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:27:00 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': rpc: getFolderContents(map[count:1000 fi_pid:120835151 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:27:00 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': >rpc: result=Success (ok), err= 2021/02/08 06:27:00 DEBUG : one.bak: Excluded 2021/02/08 06:27:00 DEBUG : one: Sizes differ (src 5 vs dst 4) 2021/02/08 06:27:00 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': rpc: checkPathExists(map[path:one.bak pid:120835151]) options=[] 2021/02/08 06:27:00 DEBUG : two: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2021/02/08 06:27:00 DEBUG : two: Unchanged skipping 2021/02/08 06:27:00 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': Waiting for checks to finish 2021/02/08 06:27:00 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': >rpc: result=Success (ok), err= 2021/02/08 06:27:00 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': rpc: doDeleteFile(map[completedeletion:n fi_id:120835152]) options=[] 2021/02/08 06:27:08 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': >rpc: result=Success (ok), err= 2021/02/08 06:27:08 INFO : one.bak: Deleted 2021/02/08 06:27:08 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': rpc: doRenameFile(map[fi_id:120835159 fi_name:one.bak]) options=[] 2021/02/08 06:27:15 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': >rpc: result=Success (ok), err= 2021/02/08 06:27:15 INFO : one: Moved (server-side) to: one.bak 2021/02/08 06:27:15 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': Waiting for transfers to finish 2021/02/08 06:27:15 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/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:120835151 fi_size:5 responsetype:json]) options=[] 2021/02/08 06:27:16 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': >rpc: result=Success (ok), err= 2021/02/08 06:27:18 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': rpc: doCompleteUpload(map[fi_size:5 remotetime:2011-12-30 12:59:59 uploadcode:a242b5354df096a7eadfb1841bc40174]) options=[] 2021/02/08 06:27:20 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': >rpc: result=Success (ok), err= 2021/02/08 06:27:20 INFO : one: Copied (new) 2021/02/08 06:27:20 DEBUG : Waiting for deletions to finish 2021/02/08 06:27:20 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': rpc: checkPathExists(map[path:three.txt.bak.txt.bak pid:120835151]) options=[] 2021/02/08 06:27:20 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': rpc: checkPathExists(map[path:three.txt.bak pid:120835151]) options=[] 2021/02/08 06:27:20 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': >rpc: result=Success (ok), err= 2021/02/08 06:27:20 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': rpc: doRenameFile(map[fi_id:120835155 fi_name:three.txt.bak.txt.bak]) options=[] 2021/02/08 06:27:20 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': >rpc: result=Success (ok), err= 2021/02/08 06:27:20 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': rpc: doRenameFile(map[fi_id:120835163 fi_name:three.txt.bak]) options=[] 2021/02/08 06:27:22 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/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:27: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:27: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:27:28 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': >rpc: result=Success (ok), err= 2021/02/08 06:27:28 INFO : three.txt.bak.txt: Moved (server-side) to: three.txt.bak.txt.bak 2021/02/08 06:27:28 INFO : three.txt.bak.txt: Moved into backup dir 2021/02/08 06:27:28 ERROR : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/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:27:28 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': 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:27:29 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:27:29 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: getFolderContents(map[count:1000 fi_pid:120835046 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:27:30 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:27:30 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: getFolderContents(map[count:1000 fi_pid:120835151 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:27:31 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:27:31 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: doDeleteFile(map[completedeletion:n fi_id:120835167]) options=[] 2021/02/08 06:27:43 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:27:43 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: doDeleteFile(map[completedeletion:n fi_id:120835159]) options=[] 2021/02/08 06:27:54 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:27:54 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: doDeleteFile(map[completedeletion:n fi_id:120835163]) options=[] 2021/02/08 06:28:02 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:28:02 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: doDeleteFile(map[completedeletion:n fi_id:120835155]) options=[] 2021/02/08 06:28:09 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:28:09 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: doDeleteFile(map[completedeletion:n fi_id:120835153]) options=[] 2021/02/08 06:28:21 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:28:21 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: getFolderContents(map[count:1000 fi_pid:120835151 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:28:22 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:28:22 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: doDeleteFolder(map[fi_id:120835151]) options=[] 2021/02/08 06:28:24 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:28:24 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: getFolderContents(map[count:1000 fi_pid:120835046 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:28:24 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= --- FAIL: TestSyncBackupDirSuffixOnly (156.78s) === RUN TestSyncSuffix run.go:176: Remote "filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3'", Local "Local file system at /tmp/rclone216482712", Modify Window "1s" 2021/02/08 06:28:24 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: getFolderContents(map[count:1000 fi_pid:120835046 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:28:25 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:28:25 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: doCreateNewFolder(map[fi_name:dst fi_pid:120835046]) options=[] 2021/02/08 06:28:25 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': Sleeping for 6s to wait for "error_background" error to clear 2021/02/08 06:28:31 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:28:31 DEBUG : pacer: Rate limited, increasing sleep to 40ms 2021/02/08 06:28:34 DEBUG : pacer: Reducing sleep to 30ms 2021/02/08 06:28:34 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:28:34 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': 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:120835177 fi_size:3 responsetype:json]) options=[] 2021/02/08 06:28:35 DEBUG : pacer: Reducing sleep to 22.5ms 2021/02/08 06:28:35 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:28:36 DEBUG : pacer: Reducing sleep to 20ms 2021/02/08 06:28:36 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: doCompleteUpload(map[fi_size:3 remotetime:2001-02-03 04:05:06 uploadcode:f0b2aaba45bc6d9a6567e101029c3b8a]) options=[] 2021/02/08 06:28:37 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:28:37 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': 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:120835177 fi_size:3 responsetype:json]) options=[] 2021/02/08 06:28:39 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:28:40 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: doCompleteUpload(map[fi_size:3 remotetime:2001-02-03 04:05:06 uploadcode:b54e4ee267e53e28737c582783441fd9]) options=[] 2021/02/08 06:28:41 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:28:41 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': 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:120835177 fi_size:5 responsetype:json]) options=[] 2021/02/08 06:28:42 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:28:43 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: doCompleteUpload(map[fi_size:5 remotetime:2001-02-03 04:05:06 uploadcode:a0bcab4d245fe6d5a2ded3855c02b3c1]) options=[] 2021/02/08 06:28:44 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:28:44 DEBUG : dst/three.txt: Correcting mime type from "text/plain" to "text/plain; charset=utf-8" 2021/02/08 06:28:44 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: doModifyFile(map[data:fi_contenttype=text/plain; charset=utf-8 fi_id:120835180]) options=[] 2021/02/08 06:28:45 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:28:45 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: getFolderContents(map[count:1000 fi_pid:120835046 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:28:45 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:28:45 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: getFolderContents(map[count:1000 fi_pid:120835177 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:28:46 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:28:46 DEBUG : Creating backend with remote "TestFileFabric:rclone-test-qavamaq7pesizip2zufigoc3/dst" 2021/02/08 06:28:46 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': rpc: checkPathExists(map[path:rclone-test-qavamaq7pesizip2zufigoc3/dst pid:120673762]) options=[] 2021/02/08 06:28:47 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': >rpc: result=Success (ok), err= 2021/02/08 06:28:47 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': rpc: checkPathExists(map[path:one pid:120835177]) options=[] 2021/02/08 06:28:47 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': >rpc: result=Success (ok), err= 2021/02/08 06:28:47 DEBUG : one: Sizes differ (src 4 vs dst 3) 2021/02/08 06:28:47 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': rpc: checkPathExists(map[path:one.bak pid:120835177]) options=[] 2021/02/08 06:28:47 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': >rpc: result=Success (ok), err= 2021/02/08 06:28:47 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': rpc: doRenameFile(map[fi_id:120835178 fi_name:one.bak]) options=[] 2021/02/08 06:28:55 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': >rpc: result=Success (ok), err= 2021/02/08 06:28:55 INFO : one: Moved (server-side) to: one.bak 2021/02/08 06:28:55 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/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:120835177 fi_size:4 responsetype:json]) options=[] 2021/02/08 06:28:56 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': >rpc: result=Success (ok), err= 2021/02/08 06:28:58 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': rpc: doCompleteUpload(map[fi_size:4 remotetime:2011-12-25 12:59:59 uploadcode:17689f2729fcda4f260a9c53a60c7bb9]) options=[] 2021/02/08 06:28:59 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': >rpc: result=Success (ok), err= 2021/02/08 06:28:59 INFO : one: Copied (new) 2021/02/08 06:28:59 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': rpc: checkPathExists(map[path:two pid:120835177]) options=[] 2021/02/08 06:28:59 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': >rpc: result=Success (ok), err= 2021/02/08 06:28:59 DEBUG : two: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2021/02/08 06:28:59 DEBUG : two: Unchanged skipping 2021/02/08 06:28:59 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': rpc: checkPathExists(map[path:three.txt pid:120835177]) options=[] 2021/02/08 06:28:59 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': >rpc: result=Success (ok), err= 2021/02/08 06:28:59 DEBUG : three.txt: Sizes differ (src 6 vs dst 5) 2021/02/08 06:28:59 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': rpc: checkPathExists(map[path:three.txt.bak pid:120835177]) options=[] 2021/02/08 06:28:59 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': >rpc: result=Success (ok), err= 2021/02/08 06:28:59 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': rpc: doRenameFile(map[fi_id:120835180 fi_name:three.txt.bak]) options=[] 2021/02/08 06:29:07 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': >rpc: result=Success (ok), err= 2021/02/08 06:29:07 INFO : three.txt: Moved (server-side) to: three.txt.bak 2021/02/08 06:29:07 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/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:120835177 fi_size:6 responsetype:json]) options=[] 2021/02/08 06:29:08 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': >rpc: result=Success (ok), err= 2021/02/08 06:29:09 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': rpc: doCompleteUpload(map[fi_size:6 remotetime:2001-02-03 04:05:06 uploadcode:3ebcbd6ce012343e03d98f9ad8d9f6d5]) options=[] 2021/02/08 06:29:10 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': >rpc: result=Success (ok), err= 2021/02/08 06:29:10 DEBUG : three.txt: Correcting mime type from "text/plain" to "text/plain; charset=utf-8" 2021/02/08 06:29:10 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': rpc: doModifyFile(map[data:fi_contenttype=text/plain; charset=utf-8 fi_id:120835190]) options=[] 2021/02/08 06:29:10 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': >rpc: result=Success (ok), err= 2021/02/08 06:29:10 INFO : three.txt: Copied (new) 2021/02/08 06:29:10 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: getFolderContents(map[count:1000 fi_pid:120835046 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:29:11 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:29:11 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: getFolderContents(map[count:1000 fi_pid:120835177 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:29:12 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= fstest.go:297: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:300: Flushing the directory cache 2021/02/08 06:29:13 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': 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:29:14 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:29:14 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: getFolderContents(map[count:1000 fi_pid:120835046 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:29:14 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:29:14 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: getFolderContents(map[count:1000 fi_pid:120835177 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:29:14 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= fstest.go:297: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:300: Flushing the directory cache 2021/02/08 06:29:16 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': 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:29:16 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:29:16 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: getFolderContents(map[count:1000 fi_pid:120835046 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:29:17 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:29:17 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: getFolderContents(map[count:1000 fi_pid:120835177 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:29:17 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= fstest.go:297: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:300: Flushing the directory cache fstest.go:304: Error Trace: fstest.go:304 fstest.go:337 fstest.go:349 sync_test.go: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:29:21 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': 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:29:22 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:29:22 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: getFolderContents(map[count:1000 fi_pid:120835046 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:29:23 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:29:23 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: getFolderContents(map[count:1000 fi_pid:120835177 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:29:23 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= fstest.go:297: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:300: Flushing the directory cache 2021/02/08 06:29:25 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': 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:29:25 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:29:25 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: getFolderContents(map[count:1000 fi_pid:120835046 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:29:25 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:29:25 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: getFolderContents(map[count:1000 fi_pid:120835177 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:29:26 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= fstest.go:297: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:300: Flushing the directory cache 2021/02/08 06:29:28 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': 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:29:28 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:29:28 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: getFolderContents(map[count:1000 fi_pid:120835046 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:29:29 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:29:29 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: getFolderContents(map[count:1000 fi_pid:120835177 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:29:29 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= fstest.go:297: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:300: Flushing the directory cache fstest.go:304: Error Trace: fstest.go:304 fstest.go:337 fstest.go:349 sync_test.go: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:29:33 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': rpc: checkPathExists(map[path:one pid:120835177]) options=[] 2021/02/08 06:29:33 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': >rpc: result=Success (ok), err= 2021/02/08 06:29:33 DEBUG : one: Sizes differ (src 5 vs dst 4) 2021/02/08 06:29:33 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': rpc: checkPathExists(map[path:one.bak pid:120835177]) options=[] 2021/02/08 06:29:34 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': >rpc: result=Success (ok), err= 2021/02/08 06:29:34 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': rpc: doDeleteFile(map[completedeletion:n fi_id:120835178]) options=[] 2021/02/08 06:29:46 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': >rpc: result=Success (ok), err= 2021/02/08 06:29:46 INFO : one.bak: Deleted 2021/02/08 06:29:46 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': rpc: doRenameFile(map[fi_id:120835184 fi_name:one.bak]) options=[] 2021/02/08 06:29:54 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': >rpc: result=Success (ok), err= 2021/02/08 06:29:54 INFO : one: Moved (server-side) to: one.bak 2021/02/08 06:29:54 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/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:120835177 fi_size:5 responsetype:json]) options=[] 2021/02/08 06:29:55 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': >rpc: result=Success (ok), err= 2021/02/08 06:29:56 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': rpc: doCompleteUpload(map[fi_size:5 remotetime:2011-12-30 12:59:59 uploadcode:82329bca19be348069c40a090a5b63a8]) options=[] 2021/02/08 06:29:57 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': >rpc: result=Success (ok), err= 2021/02/08 06:29:57 INFO : one: Copied (new) 2021/02/08 06:29:57 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': rpc: checkPathExists(map[path:two pid:120835177]) options=[] 2021/02/08 06:29:57 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': >rpc: result=Success (ok), err= 2021/02/08 06:29:57 DEBUG : two: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2021/02/08 06:29:57 DEBUG : two: Unchanged skipping 2021/02/08 06:29:57 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': rpc: checkPathExists(map[path:three.txt pid:120835177]) options=[] 2021/02/08 06:29:58 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': >rpc: result=Success (ok), err= 2021/02/08 06:29:58 DEBUG : three.txt: Sizes differ (src 19 vs dst 6) 2021/02/08 06:29:58 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': rpc: checkPathExists(map[path:three.txt.bak pid:120835177]) options=[] 2021/02/08 06:29:58 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': >rpc: result=Success (ok), err= 2021/02/08 06:29:58 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/dst': rpc: doRenameFile(map[fi_id:120835190 fi_name:three.txt.bak]) options=[] 2021/02/08 06:30:00 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3/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:30:00 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:30:00 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': 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:30:00 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:30:00 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: getFolderContents(map[count:1000 fi_pid:120835046 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:30:01 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:30:01 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: getFolderContents(map[count:1000 fi_pid:120835177 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:30:02 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:30:02 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: doDeleteFile(map[completedeletion:n fi_id:120835199]) options=[] 2021/02/08 06:30:14 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:30:14 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: doDeleteFile(map[completedeletion:n fi_id:120835184]) options=[] 2021/02/08 06:30:26 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:30:26 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: doDeleteFile(map[completedeletion:n fi_id:120835190]) options=[] 2021/02/08 06:30:37 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:30:37 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: doDeleteFile(map[completedeletion:n fi_id:120835180]) options=[] 2021/02/08 06:30:45 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:30:45 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: doDeleteFile(map[completedeletion:n fi_id:120835179]) options=[] 2021/02/08 06:30:56 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:30:56 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: getFolderContents(map[count:1000 fi_pid:120835177 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:30:57 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:30:57 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: doDeleteFolder(map[fi_id:120835177]) options=[] 2021/02/08 06:30:58 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= 2021/02/08 06:30:58 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: getFolderContents(map[count:1000 fi_pid:120835046 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:30:59 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= --- FAIL: TestSyncSuffix (154.45s) FAIL 2021/02/08 06:30:59 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': Purge remote 2021/02/08 06:30:59 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': rpc: doDeleteFolder(map[fi_id:120835046]) options=[] 2021/02/08 06:30:59 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': Sleeping for 6s to wait for "error_background" error to clear 2021/02/08 06:31:05 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:31:05 DEBUG : pacer: Rate limited, increasing sleep to 40ms 2021/02/08 06:31:05 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': Sleeping for 6s to wait for "error_background" error to clear 2021/02/08 06:31:11 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:31:11 DEBUG : pacer: Rate limited, increasing sleep to 80ms 2021/02/08 06:31:12 DEBUG : pacer: Reducing sleep to 60ms 2021/02/08 06:31:12 DEBUG : filefabric root 'rclone-test-qavamaq7pesizip2zufigoc3': >rpc: result=Success (ok), err= "./sync.test -test.v -test.timeout 1h0m0s -remote TestFileFabric: -verbose -test.run '^(TestServerSideMoveDeleteEmptySourceDirs|TestSyncBackupDirSuffixOnly|TestSyncBackupDirWithSuffix|TestSyncSuffix)$'" - Finished ERROR in 11m32.022938889s (try 2/5): exit status 1: Failed [TestSyncBackupDirWithSuffix TestSyncBackupDirSuffixOnly TestSyncSuffix]