"./vfs.test -test.v -test.timeout 2h0m0s -remote TestFileFabric: -verbose -test.run '^(TestDirMethods|TestRcGetVFS|TestVFSNew)$'" - Starting (try 4/5)
2021/12/01 11:30:50 DEBUG : Creating backend with remote "TestFileFabric:rclone-test-tekikow2wetunak5jahusam2"
2021/12/01 11:30:50 DEBUG : Using config file from "/home/rclone/.rclone.conf"
2021/12/01 11:30:50 DEBUG : filefabric root 'rclone-test-tekikow2wetunak5jahusam2': rpc: checkPathExists(map[path:rclone-test-tekikow2wetunak5jahusam2 pid:120673762]) options=[]
2021/12/01 11:30:51 DEBUG : filefabric root 'rclone-test-tekikow2wetunak5jahusam2': >rpc: result=Success (ok), err=<nil>
2021/12/01 11:30:51 DEBUG : Creating backend with remote "/tmp/rclone1155632613"
=== RUN   TestDirMethods
    run.go:181: Remote "filefabric root 'rclone-test-tekikow2wetunak5jahusam2'", Local "Local file system at /tmp/rclone1155632613", Modify Window "1s"
2021/12/01 11:30:51 INFO  : filefabric root 'rclone-test-tekikow2wetunak5jahusam2': poll-interval is not supported by this remote
2021/12/01 11:30:51 NOTICE: filefabric root 'rclone-test-tekikow2wetunak5jahusam2': --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2021/12/01 11:30:51 DEBUG : filefabric root 'rclone-test-tekikow2wetunak5jahusam2': 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/12/01 11:30:52 DEBUG : filefabric root 'rclone-test-tekikow2wetunak5jahusam2': >rpc: result=Success (ok), err=<nil>
2021/12/01 11:30:52 DEBUG : filefabric root 'rclone-test-tekikow2wetunak5jahusam2': rpc: doCreateNewFolder(map[fi_name:rclone-test-tekikow2wetunak5jahusam2 fi_pid:120673762]) options=[]
2021/12/01 11:30:59 DEBUG : filefabric root 'rclone-test-tekikow2wetunak5jahusam2': >rpc: result=Success (ok), err=<nil>
2021/12/01 11:30:59 DEBUG : filefabric root 'rclone-test-tekikow2wetunak5jahusam2': rpc: getFolderContents(map[count:1000 fi_pid:121231283 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/12/01 11:31:03 DEBUG : filefabric root 'rclone-test-tekikow2wetunak5jahusam2': >rpc: result=Success (ok), err=<nil>
2021/12/01 11:31:03 DEBUG : filefabric root 'rclone-test-tekikow2wetunak5jahusam2': rpc: doCreateNewFolder(map[fi_name:dir fi_pid:121231283]) options=[]
2021/12/01 11:31:08 DEBUG : filefabric root 'rclone-test-tekikow2wetunak5jahusam2': >rpc: result=Success (ok), err=<nil>
2021/12/01 11:31:08 DEBUG : filefabric root 'rclone-test-tekikow2wetunak5jahusam2': 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:121231284 fi_size:14 responsetype:json]) options=[]
2021/12/01 11:31:10 DEBUG : filefabric root 'rclone-test-tekikow2wetunak5jahusam2': >rpc: result=Success (ok), err=<nil>
2021/12/01 11:31:11 DEBUG : filefabric root 'rclone-test-tekikow2wetunak5jahusam2': rpc: doCompleteUpload(map[fi_size:14 remotetime:2001-02-03 04:05:06 uploadcode:9c6510e5b9d5274038a6630b0597997b]) options=[]
2021/12/01 11:31:14 DEBUG : filefabric root 'rclone-test-tekikow2wetunak5jahusam2': >rpc: result=Success (ok), err=<nil>
2021/12/01 11:31:14 DEBUG : filefabric root 'rclone-test-tekikow2wetunak5jahusam2': rpc: getFolderContents(map[count:1000 fi_pid:121231283 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/12/01 11:31:18 DEBUG : filefabric root 'rclone-test-tekikow2wetunak5jahusam2': >rpc: result=Success (ok), err=<nil>
2021/12/01 11:31:18 DEBUG : filefabric root 'rclone-test-tekikow2wetunak5jahusam2': rpc: getFolderContents(map[count:1000 fi_pid:121231284 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/12/01 11:31:22 DEBUG : filefabric root 'rclone-test-tekikow2wetunak5jahusam2': >rpc: result=Success (ok), err=<nil>
2021/12/01 11:31:22 DEBUG : filefabric root 'rclone-test-tekikow2wetunak5jahusam2': rpc: getFolderContents(map[count:1000 fi_pid:121231283 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/12/01 11:31:22 DEBUG : filefabric root 'rclone-test-tekikow2wetunak5jahusam2': >rpc: result=Success (ok), err=<nil>
2021/12/01 11:31:22 DEBUG : WaitForWriters: timeout=30s
2021/12/01 11:31:22 DEBUG : dir: Looking for writers
2021/12/01 11:31:22 DEBUG : : Looking for writers
2021/12/01 11:31:22 DEBUG : dir: reading active writers
2021/12/01 11:31:22 DEBUG : >WaitForWriters: 
2021/12/01 11:31:22 DEBUG : filefabric root 'rclone-test-tekikow2wetunak5jahusam2': rpc: getFolderContents(map[count:1000 fi_pid:121231283 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/12/01 11:31:23 DEBUG : filefabric root 'rclone-test-tekikow2wetunak5jahusam2': >rpc: result=Success (ok), err=<nil>
2021/12/01 11:31:23 DEBUG : filefabric root 'rclone-test-tekikow2wetunak5jahusam2': rpc: getFolderContents(map[count:1000 fi_pid:121231284 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/12/01 11:31:23 DEBUG : filefabric root 'rclone-test-tekikow2wetunak5jahusam2': >rpc: result=Success (ok), err=<nil>
2021/12/01 11:31:23 DEBUG : filefabric root 'rclone-test-tekikow2wetunak5jahusam2': rpc: doDeleteFile(map[completedeletion:n fi_id:121231285]) options=[]
2021/12/01 11:31:41 DEBUG : filefabric root 'rclone-test-tekikow2wetunak5jahusam2': >rpc: result=Success (ok), err=<nil>
2021/12/01 11:31:41 DEBUG : filefabric root 'rclone-test-tekikow2wetunak5jahusam2': rpc: getFolderContents(map[count:1000 fi_pid:121231284 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/12/01 11:31:45 DEBUG : filefabric root 'rclone-test-tekikow2wetunak5jahusam2': >rpc: result=Success (ok), err=<nil>
2021/12/01 11:31:45 DEBUG : filefabric root 'rclone-test-tekikow2wetunak5jahusam2': rpc: doDeleteFolder(map[fi_id:121231284]) options=[]
2021/12/01 11:31:49 DEBUG : filefabric root 'rclone-test-tekikow2wetunak5jahusam2': >rpc: result=Success (ok), err=<nil>
2021/12/01 11:31:49 DEBUG : filefabric root 'rclone-test-tekikow2wetunak5jahusam2': rpc: getFolderContents(map[count:1000 fi_pid:121231283 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/12/01 11:31:50 DEBUG : filefabric root 'rclone-test-tekikow2wetunak5jahusam2': >rpc: result=Success (ok), err=<nil>
--- PASS: TestDirMethods (59.03s)
=== RUN   TestRcGetVFS
    run.go:181: Remote "filefabric root 'rclone-test-tekikow2wetunak5jahusam2'", Local "Local file system at /tmp/rclone1155632613", Modify Window "1s"
2021/12/01 11:31:50 INFO  : filefabric root 'rclone-test-tekikow2wetunak5jahusam2': poll-interval is not supported by this remote
2021/12/01 11:31:50 NOTICE: filefabric root 'rclone-test-tekikow2wetunak5jahusam2': --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2021/12/01 11:31:50 INFO  : filefabric root 'rclone-test-tekikow2wetunak5jahusam2': poll-interval is not supported by this remote
2021/12/01 11:31:50 NOTICE: filefabric root 'rclone-test-tekikow2wetunak5jahusam2': --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2021/12/01 11:31:50 DEBUG : WaitForWriters: timeout=30s
2021/12/01 11:31:50 DEBUG : : Looking for writers
2021/12/01 11:31:50 DEBUG : >WaitForWriters: 
2021/12/01 11:31:50 DEBUG : filefabric root 'rclone-test-tekikow2wetunak5jahusam2': rpc: getFolderContents(map[count:1000 fi_pid:121231283 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/12/01 11:31:51 DEBUG : filefabric root 'rclone-test-tekikow2wetunak5jahusam2': >rpc: result=Success (ok), err=<nil>
2021/12/01 11:31:51 DEBUG : filefabric root 'rclone-test-tekikow2wetunak5jahusam2': rpc: getFolderContents(map[count:1000 fi_pid:121231283 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/12/01 11:31:51 DEBUG : filefabric root 'rclone-test-tekikow2wetunak5jahusam2': >rpc: result=Success (ok), err=<nil>
--- PASS: TestRcGetVFS (1.05s)
=== RUN   TestVFSNew
    run.go:181: Remote "filefabric root 'rclone-test-tekikow2wetunak5jahusam2'", Local "Local file system at /tmp/rclone1155632613", Modify Window "1s"
2021/12/01 11:31:51 INFO  : filefabric root 'rclone-test-tekikow2wetunak5jahusam2': poll-interval is not supported by this remote
2021/12/01 11:31:51 NOTICE: filefabric root 'rclone-test-tekikow2wetunak5jahusam2': --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2021/12/01 11:31:51 DEBUG : filefabric root 'rclone-test-tekikow2wetunak5jahusam2': Re-using VFS from active cache
2021/12/01 11:31:51 DEBUG : WaitForWriters: timeout=30s
2021/12/01 11:31:51 DEBUG : : Looking for writers
2021/12/01 11:31:51 DEBUG : >WaitForWriters: 
2021/12/01 11:31:51 DEBUG : filefabric root 'rclone-test-tekikow2wetunak5jahusam2': rpc: getFolderContents(map[count:1000 fi_pid:121231283 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/12/01 11:31:52 DEBUG : filefabric root 'rclone-test-tekikow2wetunak5jahusam2': >rpc: result=Success (ok), err=<nil>
2021/12/01 11:31:52 DEBUG : filefabric root 'rclone-test-tekikow2wetunak5jahusam2': rpc: getFolderContents(map[count:1000 fi_pid:121231283 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2021/12/01 11:31:52 DEBUG : filefabric root 'rclone-test-tekikow2wetunak5jahusam2': >rpc: result=Success (ok), err=<nil>
--- PASS: TestVFSNew (1.17s)
PASS
2021/12/01 11:31:52 DEBUG : filefabric root 'rclone-test-tekikow2wetunak5jahusam2': Purge remote
2021/12/01 11:31:52 DEBUG : filefabric root 'rclone-test-tekikow2wetunak5jahusam2': rpc: doDeleteFolder(map[fi_id:121231283]) options=[]
2021/12/01 11:31:53 DEBUG : filefabric root 'rclone-test-tekikow2wetunak5jahusam2': Sleeping for 1s to wait for "error_background" error to clear
2021/12/01 11:31:54 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/12/01 11:31:54 DEBUG : pacer: Rate limited, increasing sleep to 40ms
2021/12/01 11:31:54 DEBUG : filefabric root 'rclone-test-tekikow2wetunak5jahusam2': Sleeping for 2s to wait for "error_background" error to clear
2021/12/01 11:31:56 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/12/01 11:31:56 DEBUG : pacer: Rate limited, increasing sleep to 80ms
2021/12/01 11:31:57 DEBUG : filefabric root 'rclone-test-tekikow2wetunak5jahusam2': Sleeping for 4s to wait for "error_background" error to clear
2021/12/01 11:32:01 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/12/01 11:32:01 DEBUG : pacer: Rate limited, increasing sleep to 160ms
2021/12/01 11:32:04 DEBUG : pacer: Reducing sleep to 120ms
2021/12/01 11:32:04 DEBUG : filefabric root 'rclone-test-tekikow2wetunak5jahusam2': >rpc: result=Success (ok), err=<nil>
"./vfs.test -test.v -test.timeout 2h0m0s -remote TestFileFabric: -verbose -test.run '^(TestDirMethods|TestRcGetVFS|TestVFSNew)$'" - Finished OK in 1m14.020958961s (try 4/5)