"./sync.test -test.v -test.timeout 1h0m0s -remote TestFileFabric: -verbose -test.run '^TestSyncBackupDirWithSuffix$'" - Starting (try 4/5) 2021/04/05 06:18:04 DEBUG : Creating backend with remote "TestFileFabric:rclone-test-pumuzil8qixujar5kuziwam0" 2021/04/05 06:18:04 DEBUG : filefabric root 'rclone-test-pumuzil8qixujar5kuziwam0': rpc: checkPathExists(map[path:rclone-test-pumuzil8qixujar5kuziwam0 pid:120673762]) options=[] 2021/04/05 06:18:05 DEBUG : filefabric root 'rclone-test-pumuzil8qixujar5kuziwam0': >rpc: result=Success (ok), err= 2021/04/05 06:18:05 DEBUG : Creating backend with remote "/tmp/rclone512152997" === RUN TestSyncBackupDirWithSuffix run.go:176: Remote "filefabric root 'rclone-test-pumuzil8qixujar5kuziwam0'", Local "Local file system at /tmp/rclone512152997", Modify Window "1s" 2021/04/05 06:18:05 DEBUG : filefabric root 'rclone-test-pumuzil8qixujar5kuziwam0': rpc: getFolderContents(map[count:1000 fi_pid:120673762 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/04/05 06:18:06 DEBUG : filefabric root 'rclone-test-pumuzil8qixujar5kuziwam0': >rpc: result=Success (ok), err= 2021/04/05 06:18:06 DEBUG : filefabric root 'rclone-test-pumuzil8qixujar5kuziwam0': rpc: doCreateNewFolder(map[fi_name:rclone-test-pumuzil8qixujar5kuziwam0 fi_pid:120673762]) options=[] 2021/04/05 06:18:10 DEBUG : filefabric root 'rclone-test-pumuzil8qixujar5kuziwam0': >rpc: result=Success (ok), err= 2021/04/05 06:18:10 DEBUG : filefabric root 'rclone-test-pumuzil8qixujar5kuziwam0': rpc: getFolderContents(map[count:1000 fi_pid:120895694 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/04/05 06:18:11 DEBUG : filefabric root 'rclone-test-pumuzil8qixujar5kuziwam0': >rpc: result=Success (ok), err= 2021/04/05 06:18:11 DEBUG : filefabric root 'rclone-test-pumuzil8qixujar5kuziwam0': rpc: doCreateNewFolder(map[fi_name:dst fi_pid:120895694]) options=[] 2021/04/05 06:18:14 DEBUG : filefabric root 'rclone-test-pumuzil8qixujar5kuziwam0': >rpc: result=Success (ok), err= 2021/04/05 06:18:14 DEBUG : filefabric root 'rclone-test-pumuzil8qixujar5kuziwam0': 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:120895695 fi_size:3 responsetype:json]) options=[] 2021/04/05 06:18:16 DEBUG : filefabric root 'rclone-test-pumuzil8qixujar5kuziwam0': >rpc: result=Success (ok), err= 2021/04/05 06:18:17 DEBUG : filefabric root 'rclone-test-pumuzil8qixujar5kuziwam0': rpc: doCompleteUpload(map[fi_size:3 remotetime:2001-02-03 04:05:06 uploadcode:a4611e6dc11133cc8125b2375cc24c47]) options=[] 2021/04/05 06:18:19 DEBUG : filefabric root 'rclone-test-pumuzil8qixujar5kuziwam0': >rpc: result=Success (ok), err= 2021/04/05 06:18:19 DEBUG : filefabric root 'rclone-test-pumuzil8qixujar5kuziwam0': 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:120895695 fi_size:3 responsetype:json]) options=[] 2021/04/05 06:18:20 DEBUG : filefabric root 'rclone-test-pumuzil8qixujar5kuziwam0': >rpc: result=Success (ok), err= 2021/04/05 06:18:21 DEBUG : filefabric root 'rclone-test-pumuzil8qixujar5kuziwam0': rpc: doCompleteUpload(map[fi_size:3 remotetime:2001-02-03 04:05:06 uploadcode:452c8cd99be16d8aa0f30bcb66bfb002]) options=[] 2021/04/05 06:18:25 DEBUG : filefabric root 'rclone-test-pumuzil8qixujar5kuziwam0': >rpc: result=Success (ok), err= 2021/04/05 06:18:25 DEBUG : filefabric root 'rclone-test-pumuzil8qixujar5kuziwam0': 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:120895695 fi_size:5 responsetype:json]) options=[] 2021/04/05 06:18:26 DEBUG : filefabric root 'rclone-test-pumuzil8qixujar5kuziwam0': >rpc: result=Success (ok), err= 2021/04/05 06:18:27 DEBUG : filefabric root 'rclone-test-pumuzil8qixujar5kuziwam0': rpc: doCompleteUpload(map[fi_size:5 remotetime:2001-02-03 04:05:06 uploadcode:56db700dbf81d6a1ac2def8aebb928fc]) options=[] 2021/04/05 06:18:30 DEBUG : filefabric root 'rclone-test-pumuzil8qixujar5kuziwam0': >rpc: result=Success (ok), err= 2021/04/05 06:18:30 DEBUG : dst/three.txt: Correcting mime type from "text/plain" to "text/plain; charset=utf-8" 2021/04/05 06:18:30 DEBUG : filefabric root 'rclone-test-pumuzil8qixujar5kuziwam0': rpc: doModifyFile(map[data:fi_contenttype=text/plain; charset=utf-8 fi_id:120895698]) options=[] 2021/04/05 06:18:30 DEBUG : filefabric root 'rclone-test-pumuzil8qixujar5kuziwam0': >rpc: result=Success (ok), err= 2021/04/05 06:18:30 DEBUG : filefabric root 'rclone-test-pumuzil8qixujar5kuziwam0': rpc: getFolderContents(map[count:1000 fi_pid:120895694 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/04/05 06:18:31 DEBUG : filefabric root 'rclone-test-pumuzil8qixujar5kuziwam0': >rpc: result=Success (ok), err= 2021/04/05 06:18:31 DEBUG : filefabric root 'rclone-test-pumuzil8qixujar5kuziwam0': rpc: getFolderContents(map[count:1000 fi_pid:120895695 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/04/05 06:18:32 DEBUG : filefabric root 'rclone-test-pumuzil8qixujar5kuziwam0': >rpc: result=Success (ok), err= 2021/04/05 06:18:32 DEBUG : Creating backend with remote "TestFileFabric:rclone-test-pumuzil8qixujar5kuziwam0/dst" 2021/04/05 06:18:32 DEBUG : filefabric root 'rclone-test-pumuzil8qixujar5kuziwam0/dst': rpc: checkPathExists(map[path:rclone-test-pumuzil8qixujar5kuziwam0/dst pid:120673762]) options=[] 2021/04/05 06:18:32 DEBUG : filefabric root 'rclone-test-pumuzil8qixujar5kuziwam0/dst': >rpc: result=Success (ok), err= 2021/04/05 06:18:32 DEBUG : Creating backend with remote "TestFileFabric:rclone-test-pumuzil8qixujar5kuziwam0/backup" 2021/04/05 06:18:32 DEBUG : filefabric root 'rclone-test-pumuzil8qixujar5kuziwam0/backup': rpc: checkPathExists(map[path:rclone-test-pumuzil8qixujar5kuziwam0/backup pid:120673762]) options=[] 2021/04/05 06:18:33 DEBUG : filefabric root 'rclone-test-pumuzil8qixujar5kuziwam0/backup': >rpc: result=Success (ok), err= 2021/04/05 06:18:33 DEBUG : filefabric root 'rclone-test-pumuzil8qixujar5kuziwam0/dst': rpc: getFolderContents(map[count:1000 fi_pid:120895695 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/04/05 06:18:33 DEBUG : filefabric root 'rclone-test-pumuzil8qixujar5kuziwam0/dst': >rpc: result=Success (ok), err= 2021/04/05 06:18:33 DEBUG : one: Sizes differ (src 4 vs dst 3) 2021/04/05 06:18:33 DEBUG : filefabric root 'rclone-test-pumuzil8qixujar5kuziwam0/backup': rpc: getFolderContents(map[count:1000 fi_pid:120673762 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/04/05 06:18:33 DEBUG : two: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2021/04/05 06:18:33 DEBUG : two: Unchanged skipping 2021/04/05 06:18:33 DEBUG : filefabric root 'rclone-test-pumuzil8qixujar5kuziwam0/dst': Waiting for checks to finish 2021/04/05 06:18:34 DEBUG : filefabric root 'rclone-test-pumuzil8qixujar5kuziwam0/backup': >rpc: result=Success (ok), err= 2021/04/05 06:18:34 DEBUG : filefabric root 'rclone-test-pumuzil8qixujar5kuziwam0/backup': rpc: getFolderContents(map[count:1000 fi_pid:120895694 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/04/05 06:18:34 DEBUG : filefabric root 'rclone-test-pumuzil8qixujar5kuziwam0/backup': >rpc: result=Success (ok), err= 2021/04/05 06:18:34 DEBUG : filefabric root 'rclone-test-pumuzil8qixujar5kuziwam0/backup': rpc: getFolderContents(map[count:1000 fi_pid:120895694 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/04/05 06:18:35 DEBUG : filefabric root 'rclone-test-pumuzil8qixujar5kuziwam0/backup': >rpc: result=Success (ok), err= 2021/04/05 06:18:35 DEBUG : filefabric root 'rclone-test-pumuzil8qixujar5kuziwam0/backup': rpc: doCreateNewFolder(map[fi_name:backup fi_pid:120895694]) options=[] 2021/04/05 06:18:35 DEBUG : filefabric root 'rclone-test-pumuzil8qixujar5kuziwam0/backup': Sleeping for 6s to wait for "error_background" error to clear 2021/04/05 06:18:41 DEBUG : pacer: low level retry 1/10 (error Can not create folder now. We are not able to complete the requested operation. We are processing move folder in parent folder. Please try again later. (error_background)) 2021/04/05 06:18:41 DEBUG : pacer: Rate limited, increasing sleep to 40ms 2021/04/05 06:18:41 DEBUG : filefabric root 'rclone-test-pumuzil8qixujar5kuziwam0/backup': Sleeping for 6s to wait for "error_background" error to clear 2021/04/05 06:18:47 DEBUG : pacer: low level retry 2/10 (error Can not create folder now. We are not able to complete the requested operation. We are processing move folder in parent folder. Please try again later. (error_background)) 2021/04/05 06:18:47 DEBUG : pacer: Rate limited, increasing sleep to 80ms 2021/04/05 06:18:48 DEBUG : filefabric root 'rclone-test-pumuzil8qixujar5kuziwam0/backup': Sleeping for 6s to wait for "error_background" error to clear 2021/04/05 06:18:54 DEBUG : pacer: low level retry 3/10 (error Can not create folder now. We are not able to complete the requested operation. We are processing move folder in parent folder. Please try again later. (error_background)) 2021/04/05 06:18:54 DEBUG : pacer: Rate limited, increasing sleep to 160ms 2021/04/05 06:18:54 DEBUG : filefabric root 'rclone-test-pumuzil8qixujar5kuziwam0/backup': Sleeping for 6s to wait for "error_background" error to clear 2021/04/05 06:19:00 DEBUG : pacer: low level retry 4/10 (error Can not create folder now. We are not able to complete the requested operation. We are processing move folder in parent folder. Please try again later. (error_background)) 2021/04/05 06:19:00 DEBUG : pacer: Rate limited, increasing sleep to 320ms 2021/04/05 06:19:00 DEBUG : filefabric root 'rclone-test-pumuzil8qixujar5kuziwam0/backup': Sleeping for 6s to wait for "error_background" error to clear 2021/04/05 06:19:06 DEBUG : pacer: low level retry 5/10 (error Can not create folder now. We are not able to complete the requested operation. We are processing move folder in parent folder. Please try again later. (error_background)) 2021/04/05 06:19:06 DEBUG : pacer: Rate limited, increasing sleep to 640ms 2021/04/05 06:19:07 DEBUG : filefabric root 'rclone-test-pumuzil8qixujar5kuziwam0/backup': Sleeping for 6s to wait for "error_background" error to clear 2021/04/05 06:19:13 DEBUG : pacer: low level retry 6/10 (error Can not create folder now. We are not able to complete the requested operation. We are processing move folder in parent folder. Please try again later. (error_background)) 2021/04/05 06:19:13 DEBUG : pacer: Rate limited, increasing sleep to 1.28s 2021/04/05 06:19:13 DEBUG : filefabric root 'rclone-test-pumuzil8qixujar5kuziwam0/backup': Sleeping for 6s to wait for "error_background" error to clear 2021/04/05 06:19:19 DEBUG : pacer: low level retry 7/10 (error Can not create folder now. We are not able to complete the requested operation. We are processing move folder in parent folder. Please try again later. (error_background)) 2021/04/05 06:19:19 DEBUG : pacer: Rate limited, increasing sleep to 2.56s 2021/04/05 06:19:19 DEBUG : filefabric root 'rclone-test-pumuzil8qixujar5kuziwam0/backup': Sleeping for 6s to wait for "error_background" error to clear 2021/04/05 06:19:25 DEBUG : pacer: low level retry 8/10 (error Can not create folder now. We are not able to complete the requested operation. We are processing move folder in parent folder. Please try again later. (error_background)) 2021/04/05 06:19:25 DEBUG : pacer: Rate limited, increasing sleep to 5.12s 2021/04/05 06:19:26 DEBUG : filefabric root 'rclone-test-pumuzil8qixujar5kuziwam0/backup': Sleeping for 6s to wait for "error_background" error to clear 2021/04/05 06:19:32 DEBUG : pacer: low level retry 9/10 (error Can not create folder now. We are not able to complete the requested operation. We are processing move folder in parent folder. Please try again later. (error_background)) 2021/04/05 06:19:32 DEBUG : pacer: Rate limited, increasing sleep to 10s 2021/04/05 06:19:32 DEBUG : filefabric root 'rclone-test-pumuzil8qixujar5kuziwam0/backup': Sleeping for 6s to wait for "error_background" error to clear 2021/04/05 06:19:38 DEBUG : pacer: low level retry 10/10 (error Can not create folder now. We are not able to complete the requested operation. We are processing move folder in parent folder. Please try again later. (error_background)) 2021/04/05 06:19:38 DEBUG : filefabric root 'rclone-test-pumuzil8qixujar5kuziwam0/backup': >rpc: result=Can not create folder now. We are not able to complete the requested operation. We are processing move folder in parent folder. Please try again later. (error_background), err=Can not create folder now. We are not able to complete the requested operation. We are processing move folder in parent folder. Please try again later. (error_background) 2021/04/05 06:19:38 ERROR : one: Couldn't move: failed to make directory: failed to create directory: Can not create folder now. We are not able to complete the requested operation. We are processing move folder in parent folder. Please try again later. (error_background) 2021/04/05 06:19:38 DEBUG : filefabric root 'rclone-test-pumuzil8qixujar5kuziwam0/dst': Waiting for transfers to finish 2021/04/05 06:19:38 ERROR : filefabric root 'rclone-test-pumuzil8qixujar5kuziwam0/dst': not deleting files as there were IO errors 2021/04/05 06:19:38 ERROR : filefabric root 'rclone-test-pumuzil8qixujar5kuziwam0/dst': not deleting directories as there were IO errors sync_test.go:1692: Error Trace: sync_test.go:1692 sync_test.go:1736 Error: Received unexpected error: failed to make directory: failed to create directory: Can not create folder now. We are not able to complete the requested operation. We are processing move folder in parent folder. Please try again later. (error_background) Test: TestSyncBackupDirWithSuffix 2021/04/05 06:19:38 DEBUG : filefabric root 'rclone-test-pumuzil8qixujar5kuziwam0': rpc: getFolderContents(map[count:1000 fi_pid:120895694 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/04/05 06:19:39 DEBUG : filefabric root 'rclone-test-pumuzil8qixujar5kuziwam0': >rpc: result=Success (ok), err= 2021/04/05 06:19:39 DEBUG : filefabric root 'rclone-test-pumuzil8qixujar5kuziwam0': rpc: getFolderContents(map[count:1000 fi_pid:120895695 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/04/05 06:19:40 DEBUG : filefabric root 'rclone-test-pumuzil8qixujar5kuziwam0': >rpc: result=Success (ok), err= 2021/04/05 06:19:40 DEBUG : filefabric root 'rclone-test-pumuzil8qixujar5kuziwam0': rpc: doDeleteFile(map[completedeletion:n fi_id:120895696]) options=[] 2021/04/05 06:19:51 DEBUG : filefabric root 'rclone-test-pumuzil8qixujar5kuziwam0': >rpc: result=Success (ok), err= 2021/04/05 06:19:51 DEBUG : filefabric root 'rclone-test-pumuzil8qixujar5kuziwam0': rpc: doDeleteFile(map[completedeletion:n fi_id:120895698]) options=[] 2021/04/05 06:19:59 DEBUG : filefabric root 'rclone-test-pumuzil8qixujar5kuziwam0': >rpc: result=Success (ok), err= 2021/04/05 06:19:59 DEBUG : filefabric root 'rclone-test-pumuzil8qixujar5kuziwam0': rpc: doDeleteFile(map[completedeletion:n fi_id:120895697]) options=[] 2021/04/05 06:20:08 DEBUG : filefabric root 'rclone-test-pumuzil8qixujar5kuziwam0': >rpc: result=Success (ok), err= 2021/04/05 06:20:08 DEBUG : filefabric root 'rclone-test-pumuzil8qixujar5kuziwam0': rpc: getFolderContents(map[count:1000 fi_pid:120895695 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/04/05 06:20:09 DEBUG : filefabric root 'rclone-test-pumuzil8qixujar5kuziwam0': >rpc: result=Success (ok), err= 2021/04/05 06:20:09 DEBUG : filefabric root 'rclone-test-pumuzil8qixujar5kuziwam0': rpc: doDeleteFolder(map[fi_id:120895695]) options=[] 2021/04/05 06:20:12 DEBUG : filefabric root 'rclone-test-pumuzil8qixujar5kuziwam0': >rpc: result=Success (ok), err= 2021/04/05 06:20:12 DEBUG : filefabric root 'rclone-test-pumuzil8qixujar5kuziwam0': rpc: getFolderContents(map[count:1000 fi_pid:120895694 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/04/05 06:20:13 DEBUG : filefabric root 'rclone-test-pumuzil8qixujar5kuziwam0': >rpc: result=Success (ok), err= --- FAIL: TestSyncBackupDirWithSuffix (128.63s) FAIL 2021/04/05 06:20:13 DEBUG : filefabric root 'rclone-test-pumuzil8qixujar5kuziwam0': Purge remote 2021/04/05 06:20:13 DEBUG : filefabric root 'rclone-test-pumuzil8qixujar5kuziwam0': rpc: doDeleteFolder(map[fi_id:120895694]) options=[] 2021/04/05 06:20:14 DEBUG : filefabric root 'rclone-test-pumuzil8qixujar5kuziwam0': Sleeping for 6s to wait for "error_background" error to clear 2021/04/05 06:20:20 DEBUG : pacer: low level retry 1/10 (error The requested operation cannot be completed. A delete operation is already being processed in this folder. Please try again later. (error_background)) 2021/04/05 06:20:20 DEBUG : pacer: Rate limited, increasing sleep to 40ms 2021/04/05 06:20:20 DEBUG : filefabric root 'rclone-test-pumuzil8qixujar5kuziwam0': Sleeping for 6s to wait for "error_background" error to clear 2021/04/05 06:20:26 DEBUG : pacer: low level retry 2/10 (error The requested operation cannot be completed. A delete operation is already being processed in this folder. Please try again later. (error_background)) 2021/04/05 06:20:26 DEBUG : pacer: Rate limited, increasing sleep to 80ms 2021/04/05 06:20:26 DEBUG : filefabric root 'rclone-test-pumuzil8qixujar5kuziwam0': Sleeping for 6s to wait for "error_background" error to clear 2021/04/05 06:20:32 DEBUG : pacer: low level retry 3/10 (error The requested operation cannot be completed. A delete operation is already being processed in this folder. Please try again later. (error_background)) 2021/04/05 06:20:32 DEBUG : pacer: Rate limited, increasing sleep to 160ms 2021/04/05 06:20:35 DEBUG : pacer: Reducing sleep to 120ms 2021/04/05 06:20:35 DEBUG : filefabric root 'rclone-test-pumuzil8qixujar5kuziwam0': >rpc: result=Success (ok), err= "./sync.test -test.v -test.timeout 1h0m0s -remote TestFileFabric: -verbose -test.run '^TestSyncBackupDirWithSuffix$'" - Finished ERROR in 2m30.628658361s (try 4/5): exit status 1: Failed [TestSyncBackupDirWithSuffix]