"./vfs.test -test.v -test.timeout 2h0m0s -remote TestFileFabric: -verbose -test.run '^TestDirReadDirAll$'" - Starting (try 2/5) 2022/03/24 08:10:38 DEBUG : Creating backend with remote "TestFileFabric:rclone-test-puyidaw3ziqeloq4qucudid3" 2022/03/24 08:10:38 DEBUG : Using config file from "/home/rclone/.rclone.conf" 2022/03/24 08:10:38 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': rpc: checkPathExists(map[path:rclone-test-puyidaw3ziqeloq4qucudid3 pid:120673762]) options=[] 2022/03/24 08:10:38 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': >rpc: result=Success (ok), err= 2022/03/24 08:10:38 DEBUG : Creating backend with remote "/tmp/rclone1188036160" === RUN TestDirReadDirAll run.go:181: Remote "filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3'", Local "Local file system at /tmp/rclone1188036160", Modify Window "1s" 2022/03/24 08:10:38 INFO : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': poll-interval is not supported by this remote 2022/03/24 08:10:38 NOTICE: filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': --vfs-cache-mode writes or full is recommended for this remote as it can't stream 2022/03/24 08:10:38 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': 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/24 08:10:40 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': >rpc: result=Success (ok), err= 2022/03/24 08:10:40 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': rpc: doCreateNewFolder(map[fi_name:rclone-test-puyidaw3ziqeloq4qucudid3 fi_pid:120673762]) options=[] 2022/03/24 08:11:07 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': >rpc: result=Success (ok), err= 2022/03/24 08:11:07 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': rpc: getFolderContents(map[count:1000 fi_pid:121421252 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/24 08:11:32 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': >rpc: result=Success (ok), err= 2022/03/24 08:11:32 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': rpc: doCreateNewFolder(map[fi_name:dir fi_pid:121421252]) options=[] 2022/03/24 08:11:54 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': >rpc: result=Success (ok), err= 2022/03/24 08:11:54 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': rpc: doInitUpload(map[directuploadsupport:n fi_contenttype:application/octet-stream fi_filename:file1 fi_localtime:2001-02-03 04:05:06 fi_modified:2001-02-03 04:05:06 fi_name:file1 fi_pid:121421255 fi_size:14 responsetype:json]) options=[] 2022/03/24 08:11:59 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': >rpc: result=Success (ok), err= 2022/03/24 08:12:01 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': rpc: doCompleteUpload(map[fi_size:14 remotetime:2001-02-03 04:05:06 uploadcode:c033b0982237cf24890bf26a9e4bf7dc]) options=[] 2022/03/24 08:12:07 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': >rpc: result=Success (ok), err= 2022/03/24 08:12:07 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': rpc: doInitUpload(map[directuploadsupport:n fi_contenttype:application/octet-stream fi_filename:file2 fi_localtime:2011-12-25 12:59:59 fi_modified:2011-12-25 12:59:59 fi_name:file2 fi_pid:121421255 fi_size:15 responsetype:json]) options=[] 2022/03/24 08:12:09 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': >rpc: result=Success (ok), err= 2022/03/24 08:12:10 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': rpc: doCompleteUpload(map[fi_size:15 remotetime:2011-12-25 12:59:59 uploadcode:5116d36bab4ba8e565736d82302067ce]) options=[] 2022/03/24 08:12:16 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': >rpc: result=Success (ok), err= 2022/03/24 08:12:16 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': rpc: getFolderContents(map[count:1000 fi_pid:121421255 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/24 08:12:29 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': >rpc: result=Success (ok), err= 2022/03/24 08:12:29 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': rpc: doCreateNewFolder(map[fi_name:subdir fi_pid:121421255]) options=[] 2022/03/24 08:12:42 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': >rpc: result=Success (ok), err= 2022/03/24 08:12:42 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': rpc: doInitUpload(map[directuploadsupport:n fi_contenttype:application/octet-stream fi_filename:file3 fi_localtime:2011-12-30 12:59:59 fi_modified:2011-12-30 12:59:59 fi_name:file3 fi_pid:121421259 fi_size:16 responsetype:json]) options=[] 2022/03/24 08:12:44 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': >rpc: result=Success (ok), err= 2022/03/24 08:12:45 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': rpc: doCompleteUpload(map[fi_size:16 remotetime:2011-12-30 12:59:59 uploadcode:36b165aa17bcfa8ba4590c8335806500]) options=[] 2022/03/24 08:12:59 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': >rpc: result=Success (ok), err= 2022/03/24 08:12:59 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': rpc: getFolderContents(map[count:1000 fi_pid:121421252 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/24 08:13:15 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': >rpc: result=Success (ok), err= 2022/03/24 08:13:15 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': rpc: getFolderContents(map[count:1000 fi_pid:121421255 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/24 08:13:31 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': >rpc: result=Success (ok), err= 2022/03/24 08:13:31 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': rpc: getFolderContents(map[count:1000 fi_pid:121421259 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/24 08:13:40 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': >rpc: result=Success (ok), err= 2022/03/24 08:13:40 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': rpc: getFolderContents(map[count:1000 fi_pid:121421252 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/24 08:13:41 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': >rpc: result=Success (ok), err= 2022/03/24 08:13:41 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': rpc: getFolderContents(map[count:1000 fi_pid:121421255 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/24 08:13:41 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': >rpc: result=Success (ok), err= 2022/03/24 08:13:41 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': rpc: getFolderContents(map[count:1000 fi_pid:121421259 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/24 08:13:42 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': >rpc: result=Success (ok), err= === RUN TestDirReadDirAll/Virtual 2022/03/24 08:13:42 DEBUG : dir: Added virtual directory entry vAddFile: "virtualFile" 2022/03/24 08:13:42 DEBUG : dir: Added virtual directory entry vAddDir: "virtualDir" 2022/03/24 08:13:42 DEBUG : dir: Added virtual directory entry vDel: "file2" 2022/03/24 08:13:42 DEBUG : dir: Added virtual directory entry vDel: "subdir" 2022/03/24 08:13:42 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': rpc: doInitUpload(map[directuploadsupport:n fi_contenttype:application/octet-stream fi_filename:virtualFile fi_localtime:2001-02-03 04:05:06 fi_modified:2001-02-03 04:05:06 fi_name:virtualFile fi_pid:121421255 fi_size:20 responsetype:json]) options=[] 2022/03/24 08:13:45 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': >rpc: result=Success (ok), err= 2022/03/24 08:13:47 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': rpc: doCompleteUpload(map[fi_size:20 remotetime:2001-02-03 04:05:06 uploadcode:14bd292abb46fc4d42d3bca582b3600c]) options=[] 2022/03/24 08:14:00 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': >rpc: result=Success (ok), err= 2022/03/24 08:14:00 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': rpc: getFolderContents(map[count:1000 fi_pid:121421255 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/24 08:14:13 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': >rpc: result=Success (ok), err= 2022/03/24 08:14:13 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': rpc: doCreateNewFolder(map[fi_name:virtualDir fi_pid:121421255]) options=[] 2022/03/24 08:14:30 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': >rpc: result=Success (ok), err= 2022/03/24 08:14:30 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': rpc: doInitUpload(map[directuploadsupport:n fi_contenttype:application/octet-stream fi_filename:testFile fi_localtime:2001-02-03 04:05:06 fi_modified:2001-02-03 04:05:06 fi_name:testFile fi_pid:121421265 fi_size:17 responsetype:json]) options=[] 2022/03/24 08:14:31 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': >rpc: result=Success (ok), err= 2022/03/24 08:14:33 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': rpc: doCompleteUpload(map[fi_size:17 remotetime:2001-02-03 04:05:06 uploadcode:f975b6cbc4c317905736c417a46fc930]) options=[] 2022/03/24 08:14:42 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': >rpc: result=Success (ok), err= 2022/03/24 08:14:42 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': rpc: checkPathExists(map[path:dir/file2 pid:121421252]) options=[] 2022/03/24 08:14:42 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': >rpc: result=Success (ok), err= 2022/03/24 08:14:42 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': rpc: doDeleteFile(map[completedeletion:n fi_id:121421257]) options=[] 2022/03/24 08:15:30 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': >rpc: result=Success (ok), err= 2022/03/24 08:15:30 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': rpc: doDeleteFolder(map[fi_id:121421259]) options=[] 2022/03/24 08:15:43 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': >rpc: result=Success (ok), err= 2022/03/24 08:15:43 DEBUG : dir: invalidating directory cache 2022/03/24 08:15:43 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': rpc: getFolderContents(map[count:1000 fi_pid:121421255 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/24 08:15:44 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': >rpc: result=Success (ok), err= 2022/03/24 08:15:44 DEBUG : dir: Removed virtual directory entry vAddDir: "virtualDir" 2022/03/24 08:15:44 DEBUG : dir: Removed virtual directory entry vDel: "file2" 2022/03/24 08:15:44 DEBUG : dir: Removed virtual directory entry vDel: "subdir" 2022/03/24 08:15:44 DEBUG : dir: Removed virtual directory entry vAddFile: "virtualFile" 2022/03/24 08:15:44 DEBUG : dir: Added virtual directory entry vAddFile: "virtualFile2" 2022/03/24 08:15:44 DEBUG : dir: Added virtual directory entry vAddDir: "virtualDir2" 2022/03/24 08:15:44 DEBUG : dir: Added virtual directory entry vDel: "file1" 2022/03/24 08:15:44 DEBUG : dir: invalidating directory cache 2022/03/24 08:15:44 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': rpc: getFolderContents(map[count:1000 fi_pid:121421255 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/24 08:15:44 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': >rpc: result=Success (ok), err= 2022/03/24 08:15:44 DEBUG : dir: Removed virtual directory entry vAddDir: "virtualDir2" 2022/03/24 08:15:44 DEBUG : dir: Removed virtual directory entry vDel: "file1" 2022/03/24 08:15:44 DEBUG : : forgetting directory cache 2022/03/24 08:15:44 DEBUG : dir: forgetting directory cache 2022/03/24 08:15:44 DEBUG : dir/virtualDir: forgetting directory cache 2022/03/24 08:15:44 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': rpc: getFolderContents(map[count:1000 fi_pid:121421255 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/24 08:15:45 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': >rpc: result=Success (ok), err= 2022/03/24 08:15:45 DEBUG : WaitForWriters: timeout=30s 2022/03/24 08:15:45 DEBUG : dir/virtualDir: Looking for writers 2022/03/24 08:15:45 DEBUG : dir: Looking for writers 2022/03/24 08:15:45 DEBUG : virtualFile: reading active writers 2022/03/24 08:15:45 DEBUG : virtualDir: reading active writers 2022/03/24 08:15:45 DEBUG : file1: reading active writers 2022/03/24 08:15:45 DEBUG : virtualFile2: reading active writers 2022/03/24 08:15:45 DEBUG : : Looking for writers 2022/03/24 08:15:45 DEBUG : dir: reading active writers 2022/03/24 08:15:45 DEBUG : >WaitForWriters: 2022/03/24 08:15:45 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': rpc: getFolderContents(map[count:1000 fi_pid:121421252 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/24 08:15:48 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': >rpc: result=Success (ok), err= 2022/03/24 08:15:48 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': rpc: getFolderContents(map[count:1000 fi_pid:121421255 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/24 08:15:48 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': >rpc: result=Success (ok), err= 2022/03/24 08:15:48 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': rpc: doDeleteFile(map[completedeletion:n fi_id:121421256]) options=[] 2022/03/24 08:16:34 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': >rpc: result=Success (ok), err= 2022/03/24 08:16:34 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': rpc: doDeleteFile(map[completedeletion:n fi_id:121421263]) options=[] 2022/03/24 08:17:16 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': >rpc: result=Success (ok), err= 2022/03/24 08:17:16 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': rpc: getFolderContents(map[count:1000 fi_pid:121421265 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/24 08:17:29 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': >rpc: result=Success (ok), err= 2022/03/24 08:17:29 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': rpc: doDeleteFile(map[completedeletion:n fi_id:121421266]) options=[] 2022/03/24 08:18:11 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': >rpc: result=Success (ok), err= 2022/03/24 08:18:11 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': rpc: getFolderContents(map[count:1000 fi_pid:121421265 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/24 08:18:24 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': >rpc: result=Success (ok), err= 2022/03/24 08:18:24 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': rpc: doDeleteFolder(map[fi_id:121421265]) options=[] 2022/03/24 08:18:41 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': >rpc: result=Success (ok), err= 2022/03/24 08:18:41 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': rpc: getFolderContents(map[count:1000 fi_pid:121421255 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/24 08:18:45 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': >rpc: result=Success (ok), err= 2022/03/24 08:18:45 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': rpc: doDeleteFolder(map[fi_id:121421255]) options=[] 2022/03/24 08:18:46 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': Sleeping for 1s to wait for "error_background" error to clear 2022/03/24 08:18:47 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/24 08:18:47 DEBUG : pacer: Rate limited, increasing sleep to 40ms 2022/03/24 08:18:50 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': Sleeping for 2s to wait for "error_background" error to clear 2022/03/24 08:18:52 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/24 08:18:52 DEBUG : pacer: Rate limited, increasing sleep to 80ms 2022/03/24 08:18:54 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': Sleeping for 4s to wait for "error_background" error to clear 2022/03/24 08:18:58 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/24 08:18:58 DEBUG : pacer: Rate limited, increasing sleep to 160ms 2022/03/24 08:19:02 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': Sleeping for 8s to wait for "error_background" error to clear 2022/03/24 08:19:10 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/24 08:19:10 DEBUG : pacer: Rate limited, increasing sleep to 320ms 2022/03/24 08:19:13 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': Sleeping for 16s to wait for "error_background" error to clear 2022/03/24 08:19:29 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/24 08:19:29 DEBUG : pacer: Rate limited, increasing sleep to 640ms 2022/03/24 08:19:43 DEBUG : pacer: Reducing sleep to 480ms 2022/03/24 08:19:43 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': >rpc: result=Success (ok), err= 2022/03/24 08:19:43 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': rpc: getFolderContents(map[count:1000 fi_pid:121421252 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/24 08:19:43 DEBUG : pacer: Reducing sleep to 360ms 2022/03/24 08:19:43 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': >rpc: result=Success (ok), err= --- PASS: TestDirReadDirAll (545.04s) --- PASS: TestDirReadDirAll/Virtual (122.94s) PASS 2022/03/24 08:19:43 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': Purge remote 2022/03/24 08:19:43 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': rpc: doDeleteFolder(map[fi_id:121421252]) options=[] 2022/03/24 08:19:48 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': Sleeping for 1s to wait for "error_background" error to clear 2022/03/24 08:19:49 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/24 08:19:49 DEBUG : pacer: Rate limited, increasing sleep to 720ms 2022/03/24 08:19:52 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': Sleeping for 2s to wait for "error_background" error to clear 2022/03/24 08:19: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)) 2022/03/24 08:19:54 DEBUG : pacer: Rate limited, increasing sleep to 1.44s 2022/03/24 08:19:56 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': Sleeping for 4s to wait for "error_background" error to clear 2022/03/24 08:20:00 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/24 08:20:00 DEBUG : pacer: Rate limited, increasing sleep to 2.88s 2022/03/24 08:20:04 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': Sleeping for 8s to wait for "error_background" error to clear 2022/03/24 08:20:12 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/24 08:20:12 DEBUG : pacer: Rate limited, increasing sleep to 5.76s 2022/03/24 08:20:26 DEBUG : pacer: Reducing sleep to 4.32s 2022/03/24 08:20:26 DEBUG : filefabric root 'rclone-test-puyidaw3ziqeloq4qucudid3': >rpc: result=Success (ok), err= "./vfs.test -test.v -test.timeout 2h0m0s -remote TestFileFabric: -verbose -test.run '^TestDirReadDirAll$'" - Finished OK in 9m48.186021314s (try 2/5)