"./sync.test -test.v -test.timeout 2h0m0s -remote TestFileFabric: -verbose -test.run '^(TestSyncAfterRemovingAFileAndAddingAFile|TestSyncAfterRemovingAFileAndAddingAFileDryRun)$'" - Starting (try 2/5)
2022/03/23 07:13:55 DEBUG : Creating backend with remote "TestFileFabric:rclone-test-todupof3xugagog3toliriy1"
2022/03/23 07:13:55 DEBUG : Using config file from "/home/rclone/.rclone.conf"
2022/03/23 07:13:55 DEBUG : filefabric root 'rclone-test-todupof3xugagog3toliriy1': rpc: checkPathExists(map[path:rclone-test-todupof3xugagog3toliriy1 pid:120673762]) options=[]
2022/03/23 07:13:55 DEBUG : filefabric root 'rclone-test-todupof3xugagog3toliriy1': >rpc: result=Success (ok), err=<nil>
2022/03/23 07:13:55 DEBUG : Creating backend with remote "/tmp/rclone2462285413"
=== RUN   TestSyncAfterRemovingAFileAndAddingAFileDryRun
    run.go:181: Remote "filefabric root 'rclone-test-todupof3xugagog3toliriy1'", Local "Local file system at /tmp/rclone2462285413", Modify Window "1s"
2022/03/23 07:13:55 DEBUG : filefabric root 'rclone-test-todupof3xugagog3toliriy1': 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=[]
2022/03/23 07:14:11 DEBUG : filefabric root 'rclone-test-todupof3xugagog3toliriy1': >rpc: result=Success (ok), err=<nil>
2022/03/23 07:14:11 DEBUG : filefabric root 'rclone-test-todupof3xugagog3toliriy1': rpc: doCreateNewFolder(map[fi_name:rclone-test-todupof3xugagog3toliriy1 fi_pid:120673762]) options=[]
2022/03/23 07:14:21 DEBUG : filefabric root 'rclone-test-todupof3xugagog3toliriy1': >rpc: result=Success (ok), err=<nil>
2022/03/23 07:14:21 DEBUG : filefabric root 'rclone-test-todupof3xugagog3toliriy1': rpc: doInitUpload(map[directuploadsupport:n fi_contenttype:application/octet-stream fi_filename:potato fi_localtime:2011-12-25 12:59:59 fi_modified:2011-12-25 12:59:59 fi_name:potato fi_pid:121419685 fi_size:21 responsetype:json]) options=[]
2022/03/23 07:14:23 DEBUG : filefabric root 'rclone-test-todupof3xugagog3toliriy1': >rpc: result=Success (ok), err=<nil>
2022/03/23 07:14:25 DEBUG : filefabric root 'rclone-test-todupof3xugagog3toliriy1': rpc: doCompleteUpload(map[fi_size:21 remotetime:2011-12-25 12:59:59 uploadcode:fb4a205e3473d7d50da1447c41b8f6df]) options=[]
2022/03/23 07:14:33 DEBUG : filefabric root 'rclone-test-todupof3xugagog3toliriy1': >rpc: result=Success (ok), err=<nil>
2022/03/23 07:14:33 DEBUG : filefabric root 'rclone-test-todupof3xugagog3toliriy1': 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:121419685 fi_size:1 responsetype:json]) options=[]
2022/03/23 07:14:34 DEBUG : filefabric root 'rclone-test-todupof3xugagog3toliriy1': >rpc: result=Success (ok), err=<nil>
2022/03/23 07:14:36 DEBUG : filefabric root 'rclone-test-todupof3xugagog3toliriy1': rpc: doCompleteUpload(map[fi_size:1 remotetime:2011-12-25 12:59:59 uploadcode:bcba0ead802c9a3e932901cf26535c5a]) options=[]
2022/03/23 07:14:45 DEBUG : filefabric root 'rclone-test-todupof3xugagog3toliriy1': >rpc: result=Success (ok), err=<nil>
2022/03/23 07:14:45 DEBUG : filefabric root 'rclone-test-todupof3xugagog3toliriy1': rpc: getFolderContents(map[count:1000 fi_pid:121419685 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/23 07:14:58 DEBUG : filefabric root 'rclone-test-todupof3xugagog3toliriy1': >rpc: result=Success (ok), err=<nil>
2022/03/23 07:14:58 NOTICE: potato2: Skipped copy as --dry-run is set (size 60)
2022/03/23 07:14:58 DEBUG : filefabric root 'rclone-test-todupof3xugagog3toliriy1': Waiting for checks to finish
2022/03/23 07:14:58 DEBUG : empty space: Size and modification time the same (differ by -123.456789ms, within tolerance 1s)
2022/03/23 07:14:58 DEBUG : empty space: Unchanged skipping
2022/03/23 07:14:58 DEBUG : filefabric root 'rclone-test-todupof3xugagog3toliriy1': Waiting for transfers to finish
2022/03/23 07:14:58 DEBUG : Waiting for deletions to finish
2022/03/23 07:14:58 NOTICE: potato: Skipped delete as --dry-run is set (size 21)
2022/03/23 07:14:58 DEBUG : filefabric root 'rclone-test-todupof3xugagog3toliriy1': rpc: getFolderContents(map[count:1000 fi_pid:121419685 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/23 07:14:58 DEBUG : filefabric root 'rclone-test-todupof3xugagog3toliriy1': >rpc: result=Success (ok), err=<nil>
2022/03/23 07:14:58 DEBUG : filefabric root 'rclone-test-todupof3xugagog3toliriy1': rpc: getFolderContents(map[count:1000 fi_pid:121419685 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/23 07:14:59 DEBUG : filefabric root 'rclone-test-todupof3xugagog3toliriy1': >rpc: result=Success (ok), err=<nil>
2022/03/23 07:14:59 DEBUG : filefabric root 'rclone-test-todupof3xugagog3toliriy1': rpc: doDeleteFile(map[completedeletion:n fi_id:121419688]) options=[]
2022/03/23 07:15:48 DEBUG : filefabric root 'rclone-test-todupof3xugagog3toliriy1': >rpc: result=Success (ok), err=<nil>
2022/03/23 07:15:48 DEBUG : filefabric root 'rclone-test-todupof3xugagog3toliriy1': rpc: doDeleteFile(map[completedeletion:n fi_id:121419686]) options=[]
2022/03/23 07:16:26 DEBUG : filefabric root 'rclone-test-todupof3xugagog3toliriy1': >rpc: result=Success (ok), err=<nil>
2022/03/23 07:16:26 DEBUG : filefabric root 'rclone-test-todupof3xugagog3toliriy1': rpc: getFolderContents(map[count:1000 fi_pid:121419685 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/23 07:16:35 DEBUG : filefabric root 'rclone-test-todupof3xugagog3toliriy1': >rpc: result=Success (ok), err=<nil>
--- PASS: TestSyncAfterRemovingAFileAndAddingAFileDryRun (159.44s)
=== RUN   TestSyncAfterRemovingAFileAndAddingAFile
    run.go:181: Remote "filefabric root 'rclone-test-todupof3xugagog3toliriy1'", Local "Local file system at /tmp/rclone2462285413", Modify Window "1s"
2022/03/23 07:16:35 DEBUG : filefabric root 'rclone-test-todupof3xugagog3toliriy1': rpc: doInitUpload(map[directuploadsupport:n fi_contenttype:application/octet-stream fi_filename:potato fi_localtime:2011-12-25 12:59:59 fi_modified:2011-12-25 12:59:59 fi_name:potato fi_pid:121419685 fi_size:21 responsetype:json]) options=[]
2022/03/23 07:16:39 DEBUG : filefabric root 'rclone-test-todupof3xugagog3toliriy1': >rpc: result=Success (ok), err=<nil>
2022/03/23 07:16:41 DEBUG : filefabric root 'rclone-test-todupof3xugagog3toliriy1': rpc: doCompleteUpload(map[fi_size:21 remotetime:2011-12-25 12:59:59 uploadcode:d7d465fb788d8ad4a5e0dd62e4ad915c]) options=[]
2022/03/23 07:16:47 DEBUG : filefabric root 'rclone-test-todupof3xugagog3toliriy1': >rpc: result=Success (ok), err=<nil>
2022/03/23 07:16:47 DEBUG : filefabric root 'rclone-test-todupof3xugagog3toliriy1': 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:121419685 fi_size:1 responsetype:json]) options=[]
2022/03/23 07:16:48 DEBUG : filefabric root 'rclone-test-todupof3xugagog3toliriy1': >rpc: result=Success (ok), err=<nil>
2022/03/23 07:16:50 DEBUG : filefabric root 'rclone-test-todupof3xugagog3toliriy1': rpc: doCompleteUpload(map[fi_size:1 remotetime:2011-12-25 12:59:59 uploadcode:bcd74b57081f90f04327d923a6f71259]) options=[]
2022/03/23 07:17:04 DEBUG : filefabric root 'rclone-test-todupof3xugagog3toliriy1': >rpc: result=Success (ok), err=<nil>
2022/03/23 07:17:04 DEBUG : filefabric root 'rclone-test-todupof3xugagog3toliriy1': rpc: getFolderContents(map[count:1000 fi_pid:121419685 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/23 07:17:14 DEBUG : filefabric root 'rclone-test-todupof3xugagog3toliriy1': >rpc: result=Success (ok), err=<nil>
2022/03/23 07:17:14 DEBUG : filefabric root 'rclone-test-todupof3xugagog3toliriy1': rpc: getFolderContents(map[count:1000 fi_pid:121419685 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/23 07:17:15 DEBUG : filefabric root 'rclone-test-todupof3xugagog3toliriy1': >rpc: result=Success (ok), err=<nil>
2022/03/23 07:17:15 DEBUG : filefabric root 'rclone-test-todupof3xugagog3toliriy1': Waiting for checks to finish
2022/03/23 07:17:15 DEBUG : empty space: Size and modification time the same (differ by -123.456789ms, within tolerance 1s)
2022/03/23 07:17:15 DEBUG : empty space: Unchanged skipping
2022/03/23 07:17:15 DEBUG : filefabric root 'rclone-test-todupof3xugagog3toliriy1': Waiting for transfers to finish
2022/03/23 07:17:15 DEBUG : filefabric root 'rclone-test-todupof3xugagog3toliriy1': 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:121419685 fi_size:60 responsetype:json]) options=[]
2022/03/23 07:17:19 DEBUG : filefabric root 'rclone-test-todupof3xugagog3toliriy1': >rpc: result=Success (ok), err=<nil>
2022/03/23 07:17:21 DEBUG : filefabric root 'rclone-test-todupof3xugagog3toliriy1': rpc: doCompleteUpload(map[fi_size:60 remotetime:2001-02-03 04:05:06 uploadcode:257a579f33973b485798431a629a4672]) options=[]
2022/03/23 07:17:27 DEBUG : filefabric root 'rclone-test-todupof3xugagog3toliriy1': >rpc: result=Success (ok), err=<nil>
2022/03/23 07:17:27 INFO  : potato2: Copied (new)
2022/03/23 07:17:27 DEBUG : Waiting for deletions to finish
2022/03/23 07:17:27 DEBUG : filefabric root 'rclone-test-todupof3xugagog3toliriy1': rpc: doDeleteFile(map[completedeletion:n fi_id:121419691]) options=[]
2022/03/23 07:18:10 DEBUG : filefabric root 'rclone-test-todupof3xugagog3toliriy1': >rpc: result=Success (ok), err=<nil>
2022/03/23 07:18:10 INFO  : potato: Deleted
2022/03/23 07:18:10 DEBUG : filefabric root 'rclone-test-todupof3xugagog3toliriy1': rpc: getFolderContents(map[count:1000 fi_pid:121419685 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/23 07:18:30 DEBUG : filefabric root 'rclone-test-todupof3xugagog3toliriy1': >rpc: result=Success (ok), err=<nil>
2022/03/23 07:18:30 DEBUG : filefabric root 'rclone-test-todupof3xugagog3toliriy1': rpc: getFolderContents(map[count:1000 fi_pid:121419685 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/23 07:18:31 DEBUG : filefabric root 'rclone-test-todupof3xugagog3toliriy1': >rpc: result=Success (ok), err=<nil>
2022/03/23 07:18:31 DEBUG : filefabric root 'rclone-test-todupof3xugagog3toliriy1': rpc: doDeleteFile(map[completedeletion:n fi_id:121419692]) options=[]
2022/03/23 07:19:20 DEBUG : filefabric root 'rclone-test-todupof3xugagog3toliriy1': >rpc: result=Success (ok), err=<nil>
2022/03/23 07:19:20 DEBUG : filefabric root 'rclone-test-todupof3xugagog3toliriy1': rpc: doDeleteFile(map[completedeletion:n fi_id:121419695]) options=[]
2022/03/23 07:19:57 DEBUG : filefabric root 'rclone-test-todupof3xugagog3toliriy1': >rpc: result=Success (ok), err=<nil>
2022/03/23 07:19:57 DEBUG : filefabric root 'rclone-test-todupof3xugagog3toliriy1': rpc: getFolderContents(map[count:1000 fi_pid:121419685 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/23 07:20:07 DEBUG : filefabric root 'rclone-test-todupof3xugagog3toliriy1': >rpc: result=Success (ok), err=<nil>
--- PASS: TestSyncAfterRemovingAFileAndAddingAFile (211.87s)
PASS
2022/03/23 07:20:07 DEBUG : filefabric root 'rclone-test-todupof3xugagog3toliriy1': Purge remote
2022/03/23 07:20:07 DEBUG : filefabric root 'rclone-test-todupof3xugagog3toliriy1': rpc: doDeleteFolder(map[fi_id:121419685]) options=[]
2022/03/23 07:20:22 DEBUG : filefabric root 'rclone-test-todupof3xugagog3toliriy1': >rpc: result=Success (ok), err=<nil>
"./sync.test -test.v -test.timeout 2h0m0s -remote TestFileFabric: -verbose -test.run '^(TestSyncAfterRemovingAFileAndAddingAFile|TestSyncAfterRemovingAFileAndAddingAFileDryRun)$'" - Finished OK in 6m27.530922635s (try 2/5)