"./operations.test -test.v -test.timeout 1h0m0s -remote TestFileFabric: -verbose -test.run '^TestRmdirsWithFilter$'" - Starting (try 2/5)
2021/03/23 06:13:50 DEBUG : Creating backend with remote "TestFileFabric:rclone-test-bamurur4saroquq9kisonax9"
2021/03/23 06:13:50 DEBUG : filefabric root 'rclone-test-bamurur4saroquq9kisonax9': rpc: checkPathExists(map[path:rclone-test-bamurur4saroquq9kisonax9 pid:120673762]) options=[]
2021/03/23 06:13:50 DEBUG : filefabric root 'rclone-test-bamurur4saroquq9kisonax9': >rpc: result=Success (ok), err=<nil>
2021/03/23 06:13:50 DEBUG : Creating backend with remote "/tmp/rclone416143583"
=== RUN   TestRmdirsWithFilter
    run.go:176: Remote "filefabric root 'rclone-test-bamurur4saroquq9kisonax9'", Local "Local file system at /tmp/rclone416143583", Modify Window "1s"
2021/03/23 06:13:50 DEBUG : filefabric root 'rclone-test-bamurur4saroquq9kisonax9': 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/03/23 06:13:51 DEBUG : filefabric root 'rclone-test-bamurur4saroquq9kisonax9': >rpc: result=Success (ok), err=<nil>
2021/03/23 06:13:51 DEBUG : filefabric root 'rclone-test-bamurur4saroquq9kisonax9': rpc: doCreateNewFolder(map[fi_name:rclone-test-bamurur4saroquq9kisonax9 fi_pid:120673762]) options=[]
2021/03/23 06:13:55 DEBUG : filefabric root 'rclone-test-bamurur4saroquq9kisonax9': >rpc: result=Success (ok), err=<nil>
2021/03/23 06:13:55 DEBUG : A1: Making directory
2021/03/23 06:13:55 DEBUG : filefabric root 'rclone-test-bamurur4saroquq9kisonax9': rpc: getFolderContents(map[count:1000 fi_pid:120880701 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/03/23 06:13:57 DEBUG : filefabric root 'rclone-test-bamurur4saroquq9kisonax9': >rpc: result=Success (ok), err=<nil>
2021/03/23 06:13:57 DEBUG : filefabric root 'rclone-test-bamurur4saroquq9kisonax9': rpc: doCreateNewFolder(map[fi_name:A1 fi_pid:120880701]) options=[]
2021/03/23 06:14:00 DEBUG : filefabric root 'rclone-test-bamurur4saroquq9kisonax9': >rpc: result=Success (ok), err=<nil>
2021/03/23 06:14:00 DEBUG : A1/B1: Making directory
2021/03/23 06:14:00 DEBUG : filefabric root 'rclone-test-bamurur4saroquq9kisonax9': rpc: getFolderContents(map[count:1000 fi_pid:120880702 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/03/23 06:14:02 DEBUG : filefabric root 'rclone-test-bamurur4saroquq9kisonax9': >rpc: result=Success (ok), err=<nil>
2021/03/23 06:14:02 DEBUG : filefabric root 'rclone-test-bamurur4saroquq9kisonax9': rpc: doCreateNewFolder(map[fi_name:B1 fi_pid:120880702]) options=[]
2021/03/23 06:14:05 DEBUG : filefabric root 'rclone-test-bamurur4saroquq9kisonax9': >rpc: result=Success (ok), err=<nil>
2021/03/23 06:14:05 DEBUG : A1/B1/C1: Making directory
2021/03/23 06:14:05 DEBUG : filefabric root 'rclone-test-bamurur4saroquq9kisonax9': rpc: getFolderContents(map[count:1000 fi_pid:120880705 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/03/23 06:14:06 DEBUG : filefabric root 'rclone-test-bamurur4saroquq9kisonax9': >rpc: result=Success (ok), err=<nil>
2021/03/23 06:14:06 DEBUG : filefabric root 'rclone-test-bamurur4saroquq9kisonax9': rpc: doCreateNewFolder(map[fi_name:C1 fi_pid:120880705]) options=[]
2021/03/23 06:14:09 DEBUG : filefabric root 'rclone-test-bamurur4saroquq9kisonax9': >rpc: result=Success (ok), err=<nil>
2021/03/23 06:14:09 DEBUG : filefabric root 'rclone-test-bamurur4saroquq9kisonax9': rpc: getFolderContents(map[count:1000 fi_pid:120880701 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/03/23 06:14:10 DEBUG : filefabric root 'rclone-test-bamurur4saroquq9kisonax9': >rpc: result=Success (ok), err=<nil>
2021/03/23 06:14:10 DEBUG : filefabric root 'rclone-test-bamurur4saroquq9kisonax9': rpc: getFolderContents(map[count:1000 fi_pid:120880702 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/03/23 06:14:11 DEBUG : filefabric root 'rclone-test-bamurur4saroquq9kisonax9': >rpc: result=Success (ok), err=<nil>
2021/03/23 06:14:11 DEBUG : filefabric root 'rclone-test-bamurur4saroquq9kisonax9': rpc: getFolderContents(map[count:1000 fi_pid:120880705 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/03/23 06:14:12 DEBUG : filefabric root 'rclone-test-bamurur4saroquq9kisonax9': >rpc: result=Success (ok), err=<nil>
2021/03/23 06:14:12 DEBUG : filefabric root 'rclone-test-bamurur4saroquq9kisonax9': rpc: getFolderContents(map[count:1000 fi_pid:120880706 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/03/23 06:14:13 DEBUG : filefabric root 'rclone-test-bamurur4saroquq9kisonax9': >rpc: result=Success (ok), err=<nil>
2021/03/23 06:14:13 DEBUG : filefabric root 'rclone-test-bamurur4saroquq9kisonax9': rpc: getFolderContents(map[count:1000 fi_pid:120880701 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/03/23 06:14:14 DEBUG : filefabric root 'rclone-test-bamurur4saroquq9kisonax9': >rpc: result=Success (ok), err=<nil>
2021/03/23 06:14:14 DEBUG : filefabric root 'rclone-test-bamurur4saroquq9kisonax9': rpc: getFolderContents(map[count:1000 fi_pid:120880702 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/03/23 06:14:14 DEBUG : filefabric root 'rclone-test-bamurur4saroquq9kisonax9': >rpc: result=Success (ok), err=<nil>
2021/03/23 06:14:14 DEBUG : filefabric root 'rclone-test-bamurur4saroquq9kisonax9': rpc: getFolderContents(map[count:1000 fi_pid:120880705 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/03/23 06:14:14 DEBUG : filefabric root 'rclone-test-bamurur4saroquq9kisonax9': >rpc: result=Success (ok), err=<nil>
2021/03/23 06:14:14 DEBUG : filefabric root 'rclone-test-bamurur4saroquq9kisonax9': rpc: getFolderContents(map[count:1000 fi_pid:120880706 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/03/23 06:14:15 DEBUG : filefabric root 'rclone-test-bamurur4saroquq9kisonax9': >rpc: result=Success (ok), err=<nil>
2021/03/23 06:14:15 DEBUG : A1/B1/C1: Removing directory
2021/03/23 06:14:15 DEBUG : filefabric root 'rclone-test-bamurur4saroquq9kisonax9': rpc: getFolderContents(map[count:1000 fi_pid:120880706 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/03/23 06:14:15 DEBUG : filefabric root 'rclone-test-bamurur4saroquq9kisonax9': >rpc: result=Success (ok), err=<nil>
2021/03/23 06:14:15 DEBUG : filefabric root 'rclone-test-bamurur4saroquq9kisonax9': rpc: doDeleteFolder(map[fi_id:120880706]) options=[]
2021/03/23 06:14:17 DEBUG : filefabric root 'rclone-test-bamurur4saroquq9kisonax9': >rpc: result=Success (ok), err=<nil>
2021/03/23 06:14:17 DEBUG : A1/B1: Removing directory
2021/03/23 06:14:17 DEBUG : filefabric root 'rclone-test-bamurur4saroquq9kisonax9': rpc: getFolderContents(map[count:1000 fi_pid:120880705 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/03/23 06:14:18 DEBUG : filefabric root 'rclone-test-bamurur4saroquq9kisonax9': >rpc: result=Success (ok), err=<nil>
2021/03/23 06:14:18 DEBUG : filefabric root 'rclone-test-bamurur4saroquq9kisonax9': rpc: doDeleteFolder(map[fi_id:120880705]) options=[]
2021/03/23 06:14:18 DEBUG : filefabric root 'rclone-test-bamurur4saroquq9kisonax9': Sleeping for 6s to wait for "error_background" error to clear
2021/03/23 06:14:24 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/03/23 06:14:24 DEBUG : pacer: Rate limited, increasing sleep to 40ms
2021/03/23 06:14:25 DEBUG : filefabric root 'rclone-test-bamurur4saroquq9kisonax9': Sleeping for 6s to wait for "error_background" error to clear
2021/03/23 06:14:31 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/03/23 06:14:31 DEBUG : pacer: Rate limited, increasing sleep to 80ms
2021/03/23 06:14:31 DEBUG : filefabric root 'rclone-test-bamurur4saroquq9kisonax9': Sleeping for 6s to wait for "error_background" error to clear
2021/03/23 06:14:37 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/03/23 06:14:37 DEBUG : pacer: Rate limited, increasing sleep to 160ms
2021/03/23 06:14:39 DEBUG : pacer: Reducing sleep to 120ms
2021/03/23 06:14:39 DEBUG : filefabric root 'rclone-test-bamurur4saroquq9kisonax9': >rpc: result=Success (ok), err=<nil>
2021/03/23 06:14:39 DEBUG : filefabric root 'rclone-test-bamurur4saroquq9kisonax9': rpc: getFolderContents(map[count:1000 fi_pid:120880701 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/03/23 06:14:39 DEBUG : pacer: Reducing sleep to 90ms
2021/03/23 06:14:39 DEBUG : filefabric root 'rclone-test-bamurur4saroquq9kisonax9': >rpc: result=Success (ok), err=<nil>
2021/03/23 06:14:39 DEBUG : filefabric root 'rclone-test-bamurur4saroquq9kisonax9': rpc: getFolderContents(map[count:1000 fi_pid:120880702 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/03/23 06:14:41 DEBUG : pacer: Reducing sleep to 67.5ms
2021/03/23 06:14:41 DEBUG : filefabric root 'rclone-test-bamurur4saroquq9kisonax9': >rpc: result=Success (ok), err=<nil>
2021/03/23 06:14:41 DEBUG : filefabric root 'rclone-test-bamurur4saroquq9kisonax9': rpc: getFolderContents(map[count:1000 fi_pid:120880701 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/03/23 06:14:41 DEBUG : pacer: Reducing sleep to 50.625ms
2021/03/23 06:14:41 DEBUG : filefabric root 'rclone-test-bamurur4saroquq9kisonax9': >rpc: result=Success (ok), err=<nil>
2021/03/23 06:14:41 DEBUG : filefabric root 'rclone-test-bamurur4saroquq9kisonax9': rpc: getFolderContents(map[count:1000 fi_pid:120880702 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/03/23 06:14:41 DEBUG : pacer: Reducing sleep to 37.96875ms
2021/03/23 06:14:41 DEBUG : filefabric root 'rclone-test-bamurur4saroquq9kisonax9': >rpc: result=Success (ok), err=<nil>
2021/03/23 06:14:41 DEBUG : filefabric root 'rclone-test-bamurur4saroquq9kisonax9': rpc: getFolderContents(map[count:1000 fi_pid:120880702 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/03/23 06:14:42 DEBUG : pacer: Reducing sleep to 28.476562ms
2021/03/23 06:14:42 DEBUG : filefabric root 'rclone-test-bamurur4saroquq9kisonax9': >rpc: result=Success (ok), err=<nil>
2021/03/23 06:14:42 DEBUG : filefabric root 'rclone-test-bamurur4saroquq9kisonax9': rpc: doDeleteFolder(map[fi_id:120880702]) options=[]
2021/03/23 06:14:42 DEBUG : filefabric root 'rclone-test-bamurur4saroquq9kisonax9': Sleeping for 6s to wait for "error_background" error to clear
2021/03/23 06:14:48 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/03/23 06:14:48 DEBUG : pacer: Rate limited, increasing sleep to 56.953124ms
2021/03/23 06:14:48 DEBUG : filefabric root 'rclone-test-bamurur4saroquq9kisonax9': Sleeping for 6s to wait for "error_background" error to clear
2021/03/23 06:14:54 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/03/23 06:14:54 DEBUG : pacer: Rate limited, increasing sleep to 113.906248ms
2021/03/23 06:14:57 DEBUG : pacer: Reducing sleep to 85.429686ms
2021/03/23 06:14:57 DEBUG : filefabric root 'rclone-test-bamurur4saroquq9kisonax9': >rpc: result=Success (ok), err=<nil>
2021/03/23 06:14:57 DEBUG : filefabric root 'rclone-test-bamurur4saroquq9kisonax9': rpc: getFolderContents(map[count:1000 fi_pid:120880701 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/03/23 06:14:58 DEBUG : pacer: Reducing sleep to 64.072264ms
2021/03/23 06:14:58 DEBUG : filefabric root 'rclone-test-bamurur4saroquq9kisonax9': >rpc: result=Success (ok), err=<nil>
--- PASS: TestRmdirsWithFilter (67.44s)
PASS
2021/03/23 06:14:58 DEBUG : filefabric root 'rclone-test-bamurur4saroquq9kisonax9': Purge remote
2021/03/23 06:14:58 DEBUG : filefabric root 'rclone-test-bamurur4saroquq9kisonax9': rpc: doDeleteFolder(map[fi_id:120880701]) options=[]
2021/03/23 06:14:58 DEBUG : filefabric root 'rclone-test-bamurur4saroquq9kisonax9': Sleeping for 6s to wait for "error_background" error to clear
2021/03/23 06:15:04 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/03/23 06:15:04 DEBUG : pacer: Rate limited, increasing sleep to 128.144528ms
2021/03/23 06:15:04 DEBUG : filefabric root 'rclone-test-bamurur4saroquq9kisonax9': Sleeping for 6s to wait for "error_background" error to clear
2021/03/23 06:15:10 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/03/23 06:15:10 DEBUG : pacer: Rate limited, increasing sleep to 256.289056ms
2021/03/23 06:15:11 DEBUG : filefabric root 'rclone-test-bamurur4saroquq9kisonax9': Sleeping for 6s to wait for "error_background" error to clear
2021/03/23 06:15:17 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/03/23 06:15:17 DEBUG : pacer: Rate limited, increasing sleep to 512.578112ms
2021/03/23 06:15:19 DEBUG : pacer: Reducing sleep to 384.433584ms
2021/03/23 06:15:19 DEBUG : filefabric root 'rclone-test-bamurur4saroquq9kisonax9': >rpc: result=Success (ok), err=<nil>
"./operations.test -test.v -test.timeout 1h0m0s -remote TestFileFabric: -verbose -test.run '^TestRmdirsWithFilter$'" - Finished OK in 1m29.604157739s (try 2/5)