"./sync.test -test.v -test.timeout 2h0m0s -remote TestFileFabric: -verbose -test.run '^TestServerSideCopy$'" - Starting (try 4/5)
2022/03/02 12:40:02 DEBUG : Creating backend with remote "TestFileFabric:rclone-test-tukibul8feyigat8ricijuv2"
2022/03/02 12:40:02 DEBUG : Using config file from "/home/rclone/.rclone.conf"
2022/03/02 12:40:02 DEBUG : filefabric root 'rclone-test-tukibul8feyigat8ricijuv2': rpc: checkPathExists(map[path:rclone-test-tukibul8feyigat8ricijuv2 pid:120673762]) options=[]
2022/03/02 12:40:02 DEBUG : filefabric root 'rclone-test-tukibul8feyigat8ricijuv2': >rpc: result=Success (ok), err=<nil>
2022/03/02 12:40:02 DEBUG : Creating backend with remote "/tmp/rclone2461588256"
=== RUN   TestServerSideCopy
    run.go:181: Remote "filefabric root 'rclone-test-tukibul8feyigat8ricijuv2'", Local "Local file system at /tmp/rclone2461588256", Modify Window "1s"
2022/03/02 12:40:02 DEBUG : filefabric root 'rclone-test-tukibul8feyigat8ricijuv2': 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/02 12:40:11 DEBUG : filefabric root 'rclone-test-tukibul8feyigat8ricijuv2': >rpc: result=Success (ok), err=<nil>
2022/03/02 12:40:11 DEBUG : filefabric root 'rclone-test-tukibul8feyigat8ricijuv2': rpc: doCreateNewFolder(map[fi_name:rclone-test-tukibul8feyigat8ricijuv2 fi_pid:120673762]) options=[]
2022/03/02 12:40:24 DEBUG : filefabric root 'rclone-test-tukibul8feyigat8ricijuv2': >rpc: result=Success (ok), err=<nil>
2022/03/02 12:40:24 DEBUG : filefabric root 'rclone-test-tukibul8feyigat8ricijuv2': rpc: getFolderContents(map[count:1000 fi_pid:121389825 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/02 12:40:32 DEBUG : filefabric root 'rclone-test-tukibul8feyigat8ricijuv2': >rpc: result=Success (ok), err=<nil>
2022/03/02 12:40:32 DEBUG : filefabric root 'rclone-test-tukibul8feyigat8ricijuv2': rpc: doCreateNewFolder(map[fi_name:sub dir fi_pid:121389825]) options=[]
2022/03/02 12:40:48 DEBUG : filefabric root 'rclone-test-tukibul8feyigat8ricijuv2': >rpc: result=Success (ok), err=<nil>
2022/03/02 12:40:48 DEBUG : filefabric root 'rclone-test-tukibul8feyigat8ricijuv2': rpc: doInitUpload(map[directuploadsupport:n fi_contenttype:application/octet-stream fi_filename:hello world fi_localtime:2001-02-03 04:05:06 fi_modified:2001-02-03 04:05:06 fi_name:hello world fi_pid:121389826 fi_size:11 responsetype:json]) options=[]
2022/03/02 12:40:49 DEBUG : filefabric root 'rclone-test-tukibul8feyigat8ricijuv2': >rpc: result=Success (ok), err=<nil>
2022/03/02 12:40:51 DEBUG : filefabric root 'rclone-test-tukibul8feyigat8ricijuv2': rpc: doCompleteUpload(map[fi_size:11 remotetime:2001-02-03 04:05:06 uploadcode:8e588068a6880f2b81b7daefb0b9a986]) options=[]
2022/03/02 12:40:56 DEBUG : filefabric root 'rclone-test-tukibul8feyigat8ricijuv2': >rpc: result=Success (ok), err=<nil>
2022/03/02 12:40:56 DEBUG : filefabric root 'rclone-test-tukibul8feyigat8ricijuv2': rpc: getFolderContents(map[count:1000 fi_pid:121389825 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/02 12:41:08 DEBUG : filefabric root 'rclone-test-tukibul8feyigat8ricijuv2': >rpc: result=Success (ok), err=<nil>
2022/03/02 12:41:08 DEBUG : filefabric root 'rclone-test-tukibul8feyigat8ricijuv2': rpc: getFolderContents(map[count:1000 fi_pid:121389826 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/02 12:41:19 DEBUG : filefabric root 'rclone-test-tukibul8feyigat8ricijuv2': >rpc: result=Success (ok), err=<nil>
2022/03/02 12:41:19 DEBUG : Creating backend with remote "TestFileFabric:rclone-test-waboven7meqamal1vuluyov2"
2022/03/02 12:41:19 DEBUG : filefabric root 'rclone-test-waboven7meqamal1vuluyov2': rpc: checkPathExists(map[path:rclone-test-waboven7meqamal1vuluyov2 pid:120673762]) options=[]
2022/03/02 12:41:19 DEBUG : filefabric root 'rclone-test-waboven7meqamal1vuluyov2': >rpc: result=Success (ok), err=<nil>
    sync_test.go:275: Server side copy (if possible) filefabric root 'rclone-test-tukibul8feyigat8ricijuv2' -> filefabric root 'rclone-test-waboven7meqamal1vuluyov2'
2022/03/02 12:41:19 DEBUG : filefabric root 'rclone-test-waboven7meqamal1vuluyov2': 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/02 12:41:19 DEBUG : filefabric root 'rclone-test-tukibul8feyigat8ricijuv2': rpc: getFolderContents(map[count:1000 fi_pid:121389825 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/02 12:41:20 DEBUG : filefabric root 'rclone-test-tukibul8feyigat8ricijuv2': >rpc: result=Success (ok), err=<nil>
2022/03/02 12:41:23 DEBUG : filefabric root 'rclone-test-waboven7meqamal1vuluyov2': >rpc: result=Success (ok), err=<nil>
2022/03/02 12:41:23 DEBUG : filefabric root 'rclone-test-tukibul8feyigat8ricijuv2': rpc: getFolderContents(map[count:1000 fi_pid:121389826 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/02 12:41:23 DEBUG : filefabric root 'rclone-test-tukibul8feyigat8ricijuv2': >rpc: result=Success (ok), err=<nil>
2022/03/02 12:41:23 DEBUG : filefabric root 'rclone-test-waboven7meqamal1vuluyov2': 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/02 12:41:23 DEBUG : filefabric root 'rclone-test-waboven7meqamal1vuluyov2': Waiting for checks to finish
2022/03/02 12:41:23 DEBUG : filefabric root 'rclone-test-waboven7meqamal1vuluyov2': Waiting for transfers to finish
2022/03/02 12:41:24 DEBUG : filefabric root 'rclone-test-waboven7meqamal1vuluyov2': >rpc: result=Success (ok), err=<nil>
2022/03/02 12:41:24 DEBUG : filefabric root 'rclone-test-waboven7meqamal1vuluyov2': rpc: doCreateNewFolder(map[fi_name:rclone-test-waboven7meqamal1vuluyov2 fi_pid:120673762]) options=[]
2022/03/02 12:41:38 DEBUG : filefabric root 'rclone-test-waboven7meqamal1vuluyov2': >rpc: result=Success (ok), err=<nil>
2022/03/02 12:41:38 DEBUG : filefabric root 'rclone-test-waboven7meqamal1vuluyov2': rpc: getFolderContents(map[count:1000 fi_pid:121389828 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/02 12:41:47 DEBUG : filefabric root 'rclone-test-waboven7meqamal1vuluyov2': >rpc: result=Success (ok), err=<nil>
2022/03/02 12:41:47 DEBUG : filefabric root 'rclone-test-waboven7meqamal1vuluyov2': rpc: doCreateNewFolder(map[fi_name:sub dir fi_pid:121389828]) options=[]
2022/03/02 12:41:59 DEBUG : filefabric root 'rclone-test-waboven7meqamal1vuluyov2': >rpc: result=Success (ok), err=<nil>
2022/03/02 12:41:59 DEBUG : filefabric root 'rclone-test-waboven7meqamal1vuluyov2': rpc: doCopyFile(map[fi_id:121389827 fi_name:hello world fi_pid:121389831 force:y options:allownoextension]) options=[]
2022/03/02 12:42:11 DEBUG : filefabric root 'rclone-test-waboven7meqamal1vuluyov2': >rpc: result=Success (ok), err=<nil>
2022/03/02 12:42:11 INFO  : sub dir/hello world: Copied (server-side copy)
2022/03/02 12:42:11 DEBUG : filefabric root 'rclone-test-waboven7meqamal1vuluyov2': rpc: getFolderContents(map[count:1000 fi_pid:121389828 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/02 12:42:22 DEBUG : filefabric root 'rclone-test-waboven7meqamal1vuluyov2': >rpc: result=Success (ok), err=<nil>
2022/03/02 12:42:22 DEBUG : filefabric root 'rclone-test-waboven7meqamal1vuluyov2': rpc: getFolderContents(map[count:1000 fi_pid:121389831 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/02 12:42:34 DEBUG : filefabric root 'rclone-test-waboven7meqamal1vuluyov2': >rpc: result=Success (ok), err=<nil>
2022/03/02 12:42:34 DEBUG : filefabric root 'rclone-test-waboven7meqamal1vuluyov2': Purge remote
2022/03/02 12:42:34 DEBUG : filefabric root 'rclone-test-waboven7meqamal1vuluyov2': rpc: doDeleteFolder(map[fi_id:121389828]) options=[]
2022/03/02 12:42:43 DEBUG : filefabric root 'rclone-test-waboven7meqamal1vuluyov2': >rpc: result=Success (ok), err=<nil>
2022/03/02 12:42:43 DEBUG : filefabric root 'rclone-test-tukibul8feyigat8ricijuv2': rpc: getFolderContents(map[count:1000 fi_pid:121389825 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/02 12:42:43 DEBUG : filefabric root 'rclone-test-tukibul8feyigat8ricijuv2': >rpc: result=Success (ok), err=<nil>
2022/03/02 12:42:43 DEBUG : filefabric root 'rclone-test-tukibul8feyigat8ricijuv2': rpc: getFolderContents(map[count:1000 fi_pid:121389826 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/02 12:42:44 DEBUG : filefabric root 'rclone-test-tukibul8feyigat8ricijuv2': >rpc: result=Success (ok), err=<nil>
2022/03/02 12:42:44 DEBUG : filefabric root 'rclone-test-tukibul8feyigat8ricijuv2': rpc: doDeleteFile(map[completedeletion:n fi_id:121389827]) options=[]
2022/03/02 12:43:37 DEBUG : filefabric root 'rclone-test-tukibul8feyigat8ricijuv2': >rpc: result=Success (ok), err=<nil>
2022/03/02 12:43:37 DEBUG : filefabric root 'rclone-test-tukibul8feyigat8ricijuv2': rpc: getFolderContents(map[count:1000 fi_pid:121389826 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/02 12:43:47 DEBUG : filefabric root 'rclone-test-tukibul8feyigat8ricijuv2': >rpc: result=Success (ok), err=<nil>
2022/03/02 12:43:47 DEBUG : filefabric root 'rclone-test-tukibul8feyigat8ricijuv2': rpc: doDeleteFolder(map[fi_id:121389826]) options=[]
2022/03/02 12:44:00 DEBUG : filefabric root 'rclone-test-tukibul8feyigat8ricijuv2': >rpc: result=Success (ok), err=<nil>
2022/03/02 12:44:00 DEBUG : filefabric root 'rclone-test-tukibul8feyigat8ricijuv2': rpc: getFolderContents(map[count:1000 fi_pid:121389825 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/02 12:44:04 DEBUG : filefabric root 'rclone-test-tukibul8feyigat8ricijuv2': >rpc: result=Success (ok), err=<nil>
--- PASS: TestServerSideCopy (241.46s)
PASS
2022/03/02 12:44:04 DEBUG : filefabric root 'rclone-test-tukibul8feyigat8ricijuv2': Purge remote
2022/03/02 12:44:04 DEBUG : filefabric root 'rclone-test-tukibul8feyigat8ricijuv2': rpc: doDeleteFolder(map[fi_id:121389825]) options=[]
2022/03/02 12:44:08 DEBUG : filefabric root 'rclone-test-tukibul8feyigat8ricijuv2': Sleeping for 1s to wait for "error_background" error to clear
2022/03/02 12:44:09 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))
2022/03/02 12:44:09 DEBUG : pacer: Rate limited, increasing sleep to 40ms
2022/03/02 12:44:12 DEBUG : filefabric root 'rclone-test-tukibul8feyigat8ricijuv2': Sleeping for 2s to wait for "error_background" error to clear
2022/03/02 12:44:14 DEBUG : pacer: low level retry 2/10 (error The requested operation cannot be completed. A delete operation is already being processed in this folder. Please try again later. (error_background))
2022/03/02 12:44:14 DEBUG : pacer: Rate limited, increasing sleep to 80ms
2022/03/02 12:44:15 DEBUG : filefabric root 'rclone-test-tukibul8feyigat8ricijuv2': Sleeping for 4s to wait for "error_background" error to clear
2022/03/02 12:44:19 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))
2022/03/02 12:44:19 DEBUG : pacer: Rate limited, increasing sleep to 160ms
2022/03/02 12:44:23 DEBUG : filefabric root 'rclone-test-tukibul8feyigat8ricijuv2': Sleeping for 8s to wait for "error_background" error to clear
2022/03/02 12:44:31 DEBUG : pacer: low level retry 4/10 (error The requested operation cannot be completed. A delete operation is already being processed in this folder. Please try again later. (error_background))
2022/03/02 12:44:31 DEBUG : pacer: Rate limited, increasing sleep to 320ms
2022/03/02 12:44:36 DEBUG : filefabric root 'rclone-test-tukibul8feyigat8ricijuv2': Sleeping for 16s to wait for "error_background" error to clear
2022/03/02 12:44:52 DEBUG : pacer: low level retry 5/10 (error The requested operation cannot be completed. A delete operation is already being processed in this folder. Please try again later. (error_background))
2022/03/02 12:44:52 DEBUG : pacer: Rate limited, increasing sleep to 640ms
2022/03/02 12:44:53 DEBUG : filefabric root 'rclone-test-tukibul8feyigat8ricijuv2': Sleeping for 32s to wait for "error_background" error to clear
2022/03/02 12:45:25 DEBUG : pacer: low level retry 6/10 (error The requested operation cannot be completed. A delete operation is already being processed in this folder. Please try again later. (error_background))
2022/03/02 12:45:25 DEBUG : pacer: Rate limited, increasing sleep to 1.28s
2022/03/02 12:45:37 DEBUG : pacer: Reducing sleep to 960ms
2022/03/02 12:45:37 DEBUG : filefabric root 'rclone-test-tukibul8feyigat8ricijuv2': >rpc: result=Success (ok), err=<nil>
"./sync.test -test.v -test.timeout 2h0m0s -remote TestFileFabric: -verbose -test.run '^TestServerSideCopy$'" - Finished OK in 5m35.63892427s (try 4/5)