"./vfs.test -test.v -test.timeout 2h0m0s -remote TestFileFabric: -verbose" - Starting (try 1/5)
2022/03/14 06:14:01 DEBUG : Creating backend with remote "TestFileFabric:rclone-test-vasoxuh7tigalok4siqitah8"
2022/03/14 06:14:01 DEBUG : Using config file from "/home/rclone/.rclone.conf"
2022/03/14 06:14:01 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: checkPathExists(map[path:rclone-test-vasoxuh7tigalok4siqitah8 pid:120673762]) options=[]
2022/03/14 06:14:01 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:14:01 DEBUG : Creating backend with remote "/tmp/rclone1943342244"
=== RUN   TestDirHandleMethods
    run.go:181: Remote "filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8'", Local "Local file system at /tmp/rclone1943342244", Modify Window "1s"
2022/03/14 06:14:01 INFO  : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': poll-interval is not supported by this remote
2022/03/14 06:14:01 NOTICE: filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2022/03/14 06:14:01 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': 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/14 06:14:17 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:14:17 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: doCreateNewFolder(map[fi_name:rclone-test-vasoxuh7tigalok4siqitah8 fi_pid:120673762]) options=[]
2022/03/14 06:14:41 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:14:41 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407059 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/14 06:14:58 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:14:58 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: doCreateNewFolder(map[fi_name:dir fi_pid:121407059]) options=[]
2022/03/14 06:15:14 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:15:14 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': 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:121407065 fi_size:14 responsetype:json]) options=[]
2022/03/14 06:15:19 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:15:21 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: doCompleteUpload(map[fi_size:14 remotetime:2001-02-03 04:05:06 uploadcode:907ed9f33bcc290a2ca2e666779cc858]) options=[]
2022/03/14 06:15:34 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:15:34 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407059 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/14 06:15:47 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:15:47 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407065 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/14 06:15:59 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:15:59 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407059 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/14 06:16:00 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:16:00 DEBUG : WaitForWriters: timeout=30s
2022/03/14 06:16:00 DEBUG : dir: Looking for writers
2022/03/14 06:16:00 DEBUG : : Looking for writers
2022/03/14 06:16:00 DEBUG : dir: reading active writers
2022/03/14 06:16:00 DEBUG : >WaitForWriters: 
2022/03/14 06:16:00 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407059 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/14 06:16:00 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:16:00 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407065 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/14 06:16:01 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:16:01 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: doDeleteFile(map[completedeletion:n fi_id:121407066]) options=[]
2022/03/14 06:17:04 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:17:04 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407065 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/14 06:17:17 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:17:17 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: doDeleteFolder(map[fi_id:121407065]) options=[]
2022/03/14 06:17:33 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:17:33 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407059 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/14 06:17:34 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
--- PASS: TestDirHandleMethods (212.60s)
=== RUN   TestDirHandleReaddir
    run.go:181: Remote "filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8'", Local "Local file system at /tmp/rclone1943342244", Modify Window "1s"
2022/03/14 06:17:34 INFO  : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': poll-interval is not supported by this remote
2022/03/14 06:17:34 NOTICE: filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2022/03/14 06:17:34 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407059 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/14 06:17:34 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:17:34 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: doCreateNewFolder(map[fi_name:dir fi_pid:121407059]) options=[]
2022/03/14 06:17:35 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 1s to wait for "error_background" error to clear
2022/03/14 06:17:36 DEBUG : pacer: low level retry 1/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/14 06:17:36 DEBUG : pacer: Rate limited, increasing sleep to 40ms
2022/03/14 06:17:39 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 2s to wait for "error_background" error to clear
2022/03/14 06:17:41 DEBUG : pacer: low level retry 2/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/14 06:17:41 DEBUG : pacer: Rate limited, increasing sleep to 80ms
2022/03/14 06:17:43 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 4s to wait for "error_background" error to clear
2022/03/14 06:17:47 DEBUG : pacer: low level retry 3/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/14 06:17:47 DEBUG : pacer: Rate limited, increasing sleep to 160ms
2022/03/14 06:17:51 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 8s to wait for "error_background" error to clear
2022/03/14 06:17:59 DEBUG : pacer: low level retry 4/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/14 06:17:59 DEBUG : pacer: Rate limited, increasing sleep to 320ms
2022/03/14 06:18:00 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 16s to wait for "error_background" error to clear
2022/03/14 06:18:16 DEBUG : pacer: low level retry 5/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/14 06:18:16 DEBUG : pacer: Rate limited, increasing sleep to 640ms
2022/03/14 06:18:20 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 32s to wait for "error_background" error to clear
2022/03/14 06:18:52 DEBUG : pacer: low level retry 6/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/14 06:18:52 DEBUG : pacer: Rate limited, increasing sleep to 1.28s
2022/03/14 06:19:08 DEBUG : pacer: Reducing sleep to 960ms
2022/03/14 06:19:08 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:19:08 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': 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:121407078 fi_size:14 responsetype:json]) options=[]
2022/03/14 06:19:13 DEBUG : pacer: Reducing sleep to 720ms
2022/03/14 06:19:13 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:19:14 DEBUG : pacer: Reducing sleep to 540ms
2022/03/14 06:19:14 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: doCompleteUpload(map[fi_size:14 remotetime:2001-02-03 04:05:06 uploadcode:13a1a132706a2829e5c08e212ca34bd3]) options=[]
2022/03/14 06:19:24 DEBUG : pacer: Reducing sleep to 405ms
2022/03/14 06:19:24 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:19:24 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': 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:121407078 fi_size:15 responsetype:json]) options=[]
2022/03/14 06:19:29 DEBUG : pacer: Reducing sleep to 303.75ms
2022/03/14 06:19:29 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:19:31 DEBUG : pacer: Reducing sleep to 227.8125ms
2022/03/14 06:19:31 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: doCompleteUpload(map[fi_size:15 remotetime:2011-12-25 12:59:59 uploadcode:4242964f129d64c58a6b8edcd2d54764]) options=[]
2022/03/14 06:19:44 DEBUG : pacer: Reducing sleep to 170.859375ms
2022/03/14 06:19:44 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:19:44 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407078 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/14 06:19:57 DEBUG : pacer: Reducing sleep to 128.144531ms
2022/03/14 06:19:57 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:19:57 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: doCreateNewFolder(map[fi_name:subdir fi_pid:121407078]) options=[]
2022/03/14 06:20:09 DEBUG : pacer: Reducing sleep to 96.108398ms
2022/03/14 06:20:09 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:20:09 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': 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:121407082 fi_size:16 responsetype:json]) options=[]
2022/03/14 06:20:11 DEBUG : pacer: Reducing sleep to 72.081298ms
2022/03/14 06:20:11 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:20:12 DEBUG : pacer: Reducing sleep to 54.060973ms
2022/03/14 06:20:12 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: doCompleteUpload(map[fi_size:16 remotetime:2011-12-30 12:59:59 uploadcode:620b7f782f8ebde5006b371fdd871761]) options=[]
2022/03/14 06:20:18 DEBUG : pacer: Reducing sleep to 40.545729ms
2022/03/14 06:20:18 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:20:18 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407059 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/14 06:20:31 DEBUG : pacer: Reducing sleep to 30.409296ms
2022/03/14 06:20:31 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:20:31 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407078 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/14 06:20:39 DEBUG : pacer: Reducing sleep to 22.806972ms
2022/03/14 06:20:39 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:20:39 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407082 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/14 06:20:56 DEBUG : pacer: Reducing sleep to 20ms
2022/03/14 06:20:56 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:20:56 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407059 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/14 06:21:08 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:21:08 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407078 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/14 06:21:08 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:21:08 DEBUG : WaitForWriters: timeout=30s
2022/03/14 06:21:08 DEBUG : dir/subdir: Looking for writers
2022/03/14 06:21:08 DEBUG : dir: Looking for writers
2022/03/14 06:21:08 DEBUG : file1: reading active writers
2022/03/14 06:21:08 DEBUG : file2: reading active writers
2022/03/14 06:21:08 DEBUG : subdir: reading active writers
2022/03/14 06:21:08 DEBUG : : Looking for writers
2022/03/14 06:21:08 DEBUG : dir: reading active writers
2022/03/14 06:21:08 DEBUG : >WaitForWriters: 
2022/03/14 06:21:08 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407059 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/14 06:21:09 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:21:09 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407078 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/14 06:21:09 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:21:09 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: doDeleteFile(map[completedeletion:n fi_id:121407079]) options=[]
2022/03/14 06:22:06 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:22:06 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: doDeleteFile(map[completedeletion:n fi_id:121407080]) options=[]
2022/03/14 06:22:47 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:22:47 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407082 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/14 06:22:47 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:22:47 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: doDeleteFile(map[completedeletion:n fi_id:121407084]) options=[]
2022/03/14 06:23:46 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:23:46 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407082 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/14 06:24:02 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:24:02 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: doDeleteFolder(map[fi_id:121407082]) options=[]
2022/03/14 06:24:15 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:24:15 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407078 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/14 06:24:16 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:24:16 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: doDeleteFolder(map[fi_id:121407078]) options=[]
2022/03/14 06:24:20 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 1s to wait for "error_background" error to clear
2022/03/14 06:24:21 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/14 06:24:21 DEBUG : pacer: Rate limited, increasing sleep to 40ms
2022/03/14 06:24:24 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 2s to wait for "error_background" error to clear
2022/03/14 06:24: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))
2022/03/14 06:24:26 DEBUG : pacer: Rate limited, increasing sleep to 80ms
2022/03/14 06:24:28 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 4s to wait for "error_background" error to clear
2022/03/14 06:24: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))
2022/03/14 06:24:32 DEBUG : pacer: Rate limited, increasing sleep to 160ms
2022/03/14 06:24:33 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 8s to wait for "error_background" error to clear
2022/03/14 06:24:41 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/14 06:24:41 DEBUG : pacer: Rate limited, increasing sleep to 320ms
2022/03/14 06:24:41 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 16s to wait for "error_background" error to clear
2022/03/14 06:24:57 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/14 06:24:57 DEBUG : pacer: Rate limited, increasing sleep to 640ms
2022/03/14 06:25:16 DEBUG : pacer: Reducing sleep to 480ms
2022/03/14 06:25:16 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:25:16 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407059 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/14 06:25:21 DEBUG : pacer: Reducing sleep to 360ms
2022/03/14 06:25:21 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
--- PASS: TestDirHandleReaddir (466.97s)
=== RUN   TestDirHandleReaddirnames
    run.go:181: Remote "filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8'", Local "Local file system at /tmp/rclone1943342244", Modify Window "1s"
2022/03/14 06:25:21 INFO  : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': poll-interval is not supported by this remote
2022/03/14 06:25:21 NOTICE: filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2022/03/14 06:25:21 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407059 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/14 06:25:21 DEBUG : pacer: Reducing sleep to 270ms
2022/03/14 06:25:21 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:25:21 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: doCreateNewFolder(map[fi_name:dir fi_pid:121407059]) options=[]
2022/03/14 06:25:25 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 1s to wait for "error_background" error to clear
2022/03/14 06:25:26 DEBUG : pacer: low level retry 1/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/14 06:25:26 DEBUG : pacer: Rate limited, increasing sleep to 540ms
2022/03/14 06:25:29 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 2s to wait for "error_background" error to clear
2022/03/14 06:25:31 DEBUG : pacer: low level retry 2/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/14 06:25:31 DEBUG : pacer: Rate limited, increasing sleep to 1.08s
2022/03/14 06:25:33 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 4s to wait for "error_background" error to clear
2022/03/14 06:25:37 DEBUG : pacer: low level retry 3/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/14 06:25:37 DEBUG : pacer: Rate limited, increasing sleep to 2.16s
2022/03/14 06:25:37 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 8s to wait for "error_background" error to clear
2022/03/14 06:25:45 DEBUG : pacer: low level retry 4/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/14 06:25:45 DEBUG : pacer: Rate limited, increasing sleep to 4.32s
2022/03/14 06:25:50 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 16s to wait for "error_background" error to clear
2022/03/14 06:26:06 DEBUG : pacer: low level retry 5/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/14 06:26:06 DEBUG : pacer: Rate limited, increasing sleep to 8.64s
2022/03/14 06:26:10 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 32s to wait for "error_background" error to clear
2022/03/14 06:26:42 DEBUG : pacer: low level retry 6/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/14 06:26:42 DEBUG : pacer: Rate limited, increasing sleep to 10s
2022/03/14 06:26:55 DEBUG : pacer: Reducing sleep to 7.5s
2022/03/14 06:26:55 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:26:55 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': 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:121407110 fi_size:14 responsetype:json]) options=[]
2022/03/14 06:26:56 DEBUG : pacer: Reducing sleep to 5.625s
2022/03/14 06:26:56 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:27:04 DEBUG : pacer: Reducing sleep to 4.21875s
2022/03/14 06:27:04 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: doCompleteUpload(map[fi_size:14 remotetime:2001-02-03 04:05:06 uploadcode:907e1148b5465287846392e08cc5227c]) options=[]
2022/03/14 06:27:18 DEBUG : pacer: Reducing sleep to 3.1640625s
2022/03/14 06:27:18 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:27:18 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407059 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/14 06:27:31 DEBUG : pacer: Reducing sleep to 2.373046875s
2022/03/14 06:27:31 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:27:31 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407110 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/14 06:27:54 DEBUG : pacer: Reducing sleep to 1.779785156s
2022/03/14 06:27:54 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:27:54 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407059 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/14 06:27:55 DEBUG : pacer: Reducing sleep to 1.334838867s
2022/03/14 06:27:55 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:27:55 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407110 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/14 06:27:56 DEBUG : pacer: Reducing sleep to 1.00112915s
2022/03/14 06:27:56 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:27:56 DEBUG : WaitForWriters: timeout=30s
2022/03/14 06:27:56 DEBUG : dir: Looking for writers
2022/03/14 06:27:56 DEBUG : file1: reading active writers
2022/03/14 06:27:56 DEBUG : : Looking for writers
2022/03/14 06:27:56 DEBUG : dir: reading active writers
2022/03/14 06:27:56 DEBUG : >WaitForWriters: 
2022/03/14 06:27:56 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407059 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/14 06:27:58 DEBUG : pacer: Reducing sleep to 750.846862ms
2022/03/14 06:27:58 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:27:58 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407110 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/14 06:27:59 DEBUG : pacer: Reducing sleep to 563.135146ms
2022/03/14 06:27:59 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:27:59 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: doDeleteFile(map[completedeletion:n fi_id:121407114]) options=[]
2022/03/14 06:28:47 DEBUG : pacer: Reducing sleep to 422.351359ms
2022/03/14 06:28:47 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:28:47 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407110 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/14 06:29:08 DEBUG : pacer: Reducing sleep to 316.763519ms
2022/03/14 06:29:08 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:29:08 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: doDeleteFolder(map[fi_id:121407110]) options=[]
2022/03/14 06:29:27 DEBUG : pacer: Reducing sleep to 237.572639ms
2022/03/14 06:29:27 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:29:27 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407059 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/14 06:29:32 DEBUG : pacer: Reducing sleep to 178.179479ms
2022/03/14 06:29:32 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
--- PASS: TestDirHandleReaddirnames (251.16s)
=== RUN   TestDirMethods
    run.go:181: Remote "filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8'", Local "Local file system at /tmp/rclone1943342244", Modify Window "1s"
2022/03/14 06:29:32 INFO  : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': poll-interval is not supported by this remote
2022/03/14 06:29:32 NOTICE: filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2022/03/14 06:29:32 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407059 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/14 06:29:32 DEBUG : pacer: Reducing sleep to 133.634609ms
2022/03/14 06:29:32 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:29:32 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: doCreateNewFolder(map[fi_name:dir fi_pid:121407059]) options=[]
2022/03/14 06:29:36 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 1s to wait for "error_background" error to clear
2022/03/14 06:29:37 DEBUG : pacer: low level retry 1/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/14 06:29:37 DEBUG : pacer: Rate limited, increasing sleep to 267.269218ms
2022/03/14 06:29:40 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 2s to wait for "error_background" error to clear
2022/03/14 06:29:42 DEBUG : pacer: low level retry 2/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/14 06:29:42 DEBUG : pacer: Rate limited, increasing sleep to 534.538436ms
2022/03/14 06:29:44 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 4s to wait for "error_background" error to clear
2022/03/14 06:29:48 DEBUG : pacer: low level retry 3/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/14 06:29:48 DEBUG : pacer: Rate limited, increasing sleep to 1.069076872s
2022/03/14 06:29:52 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 8s to wait for "error_background" error to clear
2022/03/14 06:30:00 DEBUG : pacer: low level retry 4/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/14 06:30:00 DEBUG : pacer: Rate limited, increasing sleep to 2.138153744s
2022/03/14 06:30:01 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 16s to wait for "error_background" error to clear
2022/03/14 06:30:17 DEBUG : pacer: low level retry 5/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/14 06:30:17 DEBUG : pacer: Rate limited, increasing sleep to 4.276307488s
2022/03/14 06:30:21 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 32s to wait for "error_background" error to clear
2022/03/14 06:30:53 DEBUG : pacer: low level retry 6/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/14 06:30:53 DEBUG : pacer: Rate limited, increasing sleep to 8.552614976s
2022/03/14 06:30:54 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 1m4s to wait for "error_background" error to clear
2022/03/14 06:31:58 DEBUG : pacer: low level retry 7/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/14 06:31:58 DEBUG : pacer: Rate limited, increasing sleep to 10s
2022/03/14 06:32:26 DEBUG : pacer: Reducing sleep to 7.5s
2022/03/14 06:32:26 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:32:26 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': 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:121407128 fi_size:14 responsetype:json]) options=[]
2022/03/14 06:32:30 DEBUG : pacer: Reducing sleep to 5.625s
2022/03/14 06:32:30 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:32:35 DEBUG : pacer: Reducing sleep to 4.21875s
2022/03/14 06:32:35 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: doCompleteUpload(map[fi_size:14 remotetime:2001-02-03 04:05:06 uploadcode:cbaaccd140426685a87c8eac229473b8]) options=[]
2022/03/14 06:32:58 DEBUG : pacer: Reducing sleep to 3.1640625s
2022/03/14 06:32:58 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:32:58 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407059 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/14 06:33:17 DEBUG : pacer: Reducing sleep to 2.373046875s
2022/03/14 06:33:17 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:33:17 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407128 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/14 06:33:33 DEBUG : pacer: Reducing sleep to 1.779785156s
2022/03/14 06:33:33 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:33:33 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407059 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/14 06:33:34 DEBUG : pacer: Reducing sleep to 1.334838867s
2022/03/14 06:33:34 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:33:34 DEBUG : WaitForWriters: timeout=30s
2022/03/14 06:33:34 DEBUG : dir: Looking for writers
2022/03/14 06:33:34 DEBUG : : Looking for writers
2022/03/14 06:33:34 DEBUG : dir: reading active writers
2022/03/14 06:33:34 DEBUG : >WaitForWriters: 
2022/03/14 06:33:34 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407059 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/14 06:33:35 DEBUG : pacer: Reducing sleep to 1.00112915s
2022/03/14 06:33:35 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:33:35 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407128 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/14 06:33:37 DEBUG : pacer: Reducing sleep to 750.846862ms
2022/03/14 06:33:37 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:33:37 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: doDeleteFile(map[completedeletion:n fi_id:121407129]) options=[]
2022/03/14 06:34:23 DEBUG : pacer: Reducing sleep to 563.135146ms
2022/03/14 06:34:23 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:34:23 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407128 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/14 06:34:42 DEBUG : pacer: Reducing sleep to 422.351359ms
2022/03/14 06:34:42 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:34:42 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: doDeleteFolder(map[fi_id:121407128]) options=[]
2022/03/14 06:34:58 DEBUG : pacer: Reducing sleep to 316.763519ms
2022/03/14 06:34:58 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:34:58 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407059 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/14 06:35:02 DEBUG : pacer: Reducing sleep to 237.572639ms
2022/03/14 06:35:02 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
--- PASS: TestDirMethods (330.50s)
=== RUN   TestDirForgetAll
    run.go:181: Remote "filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8'", Local "Local file system at /tmp/rclone1943342244", Modify Window "1s"
2022/03/14 06:35:02 INFO  : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': poll-interval is not supported by this remote
2022/03/14 06:35:02 NOTICE: filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2022/03/14 06:35:02 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407059 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/14 06:35:03 DEBUG : pacer: Reducing sleep to 178.179479ms
2022/03/14 06:35:03 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:35:03 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: doCreateNewFolder(map[fi_name:dir fi_pid:121407059]) options=[]
2022/03/14 06:35:06 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 1s to wait for "error_background" error to clear
2022/03/14 06:35:07 DEBUG : pacer: low level retry 1/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/14 06:35:07 DEBUG : pacer: Rate limited, increasing sleep to 356.358958ms
2022/03/14 06:35:10 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 2s to wait for "error_background" error to clear
2022/03/14 06:35:12 DEBUG : pacer: low level retry 2/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/14 06:35:12 DEBUG : pacer: Rate limited, increasing sleep to 712.717916ms
2022/03/14 06:35:14 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 4s to wait for "error_background" error to clear
2022/03/14 06:35:18 DEBUG : pacer: low level retry 3/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/14 06:35:18 DEBUG : pacer: Rate limited, increasing sleep to 1.425435832s
2022/03/14 06:35:22 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 8s to wait for "error_background" error to clear
2022/03/14 06:35:30 DEBUG : pacer: low level retry 4/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/14 06:35:30 DEBUG : pacer: Rate limited, increasing sleep to 2.850871664s
2022/03/14 06:35:34 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 16s to wait for "error_background" error to clear
2022/03/14 06:35:50 DEBUG : pacer: low level retry 5/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/14 06:35:50 DEBUG : pacer: Rate limited, increasing sleep to 5.701743328s
2022/03/14 06:35:54 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 32s to wait for "error_background" error to clear
2022/03/14 06:36:26 DEBUG : pacer: low level retry 6/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/14 06:36:26 DEBUG : pacer: Rate limited, increasing sleep to 10s
2022/03/14 06:36:27 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 1m4s to wait for "error_background" error to clear
2022/03/14 06:37:31 DEBUG : pacer: low level retry 7/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/14 06:37:51 DEBUG : pacer: Reducing sleep to 7.5s
2022/03/14 06:37:51 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:37:51 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': 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:121407145 fi_size:14 responsetype:json]) options=[]
2022/03/14 06:37:56 DEBUG : pacer: Reducing sleep to 5.625s
2022/03/14 06:37:56 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:38:00 DEBUG : pacer: Reducing sleep to 4.21875s
2022/03/14 06:38:00 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: doCompleteUpload(map[fi_size:14 remotetime:2001-02-03 04:05:06 uploadcode:25e0a4194b4f197ac868d450f4c347b2]) options=[]
2022/03/14 06:38:19 DEBUG : pacer: Reducing sleep to 3.1640625s
2022/03/14 06:38:19 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:38:19 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407059 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/14 06:38:35 DEBUG : pacer: Reducing sleep to 2.373046875s
2022/03/14 06:38:35 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:38:35 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407145 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/14 06:38:47 DEBUG : pacer: Reducing sleep to 1.779785156s
2022/03/14 06:38:47 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:38:47 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407059 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/14 06:38:48 DEBUG : pacer: Reducing sleep to 1.334838867s
2022/03/14 06:38:48 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:38:48 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407145 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/14 06:38:50 DEBUG : pacer: Reducing sleep to 1.00112915s
2022/03/14 06:38:50 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:38:50 DEBUG : dir: forgetting directory cache
2022/03/14 06:38:50 DEBUG : : forgetting directory cache
2022/03/14 06:38:50 DEBUG : dir: forgetting directory cache
2022/03/14 06:38:50 DEBUG : WaitForWriters: timeout=30s
2022/03/14 06:38:50 DEBUG : : Looking for writers
2022/03/14 06:38:50 DEBUG : >WaitForWriters: 
2022/03/14 06:38:50 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407059 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/14 06:38:51 DEBUG : pacer: Reducing sleep to 750.846862ms
2022/03/14 06:38:51 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:38:51 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407145 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/14 06:38:52 DEBUG : pacer: Reducing sleep to 563.135146ms
2022/03/14 06:38:52 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:38:52 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: doDeleteFile(map[completedeletion:n fi_id:121407146]) options=[]
2022/03/14 06:39:53 DEBUG : pacer: Reducing sleep to 422.351359ms
2022/03/14 06:39:53 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:39:53 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407145 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/14 06:40:08 DEBUG : pacer: Reducing sleep to 316.763519ms
2022/03/14 06:40:08 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:40:08 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: doDeleteFolder(map[fi_id:121407145]) options=[]
2022/03/14 06:40:24 DEBUG : pacer: Reducing sleep to 237.572639ms
2022/03/14 06:40:24 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:40:24 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407059 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/14 06:40:25 DEBUG : pacer: Reducing sleep to 178.179479ms
2022/03/14 06:40:25 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
--- PASS: TestDirForgetAll (322.70s)
=== RUN   TestDirForgetPath
    run.go:181: Remote "filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8'", Local "Local file system at /tmp/rclone1943342244", Modify Window "1s"
2022/03/14 06:40:25 INFO  : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': poll-interval is not supported by this remote
2022/03/14 06:40:25 NOTICE: filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2022/03/14 06:40:25 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407059 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/14 06:40:26 DEBUG : pacer: Reducing sleep to 133.634609ms
2022/03/14 06:40:26 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:40:26 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: doCreateNewFolder(map[fi_name:dir fi_pid:121407059]) options=[]
2022/03/14 06:40:29 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 1s to wait for "error_background" error to clear
2022/03/14 06:40:30 DEBUG : pacer: low level retry 1/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/14 06:40:30 DEBUG : pacer: Rate limited, increasing sleep to 267.269218ms
2022/03/14 06:40:33 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 2s to wait for "error_background" error to clear
2022/03/14 06:40:35 DEBUG : pacer: low level retry 2/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/14 06:40:35 DEBUG : pacer: Rate limited, increasing sleep to 534.538436ms
2022/03/14 06:40:37 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 4s to wait for "error_background" error to clear
2022/03/14 06:40:41 DEBUG : pacer: low level retry 3/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/14 06:40:41 DEBUG : pacer: Rate limited, increasing sleep to 1.069076872s
2022/03/14 06:40:42 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 8s to wait for "error_background" error to clear
2022/03/14 06:40:50 DEBUG : pacer: low level retry 4/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/14 06:40:50 DEBUG : pacer: Rate limited, increasing sleep to 2.138153744s
2022/03/14 06:40:52 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 16s to wait for "error_background" error to clear
2022/03/14 06:41:08 DEBUG : pacer: low level retry 5/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/14 06:41:08 DEBUG : pacer: Rate limited, increasing sleep to 4.276307488s
2022/03/14 06:41:09 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 32s to wait for "error_background" error to clear
2022/03/14 06:41:41 DEBUG : pacer: low level retry 6/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/14 06:41:41 DEBUG : pacer: Rate limited, increasing sleep to 8.552614976s
2022/03/14 06:41:43 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 1m4s to wait for "error_background" error to clear
2022/03/14 06:42:47 DEBUG : pacer: low level retry 7/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/14 06:42:47 DEBUG : pacer: Rate limited, increasing sleep to 10s
2022/03/14 06:42:51 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 2m8s to wait for "error_background" error to clear
2022/03/14 06:44:59 DEBUG : pacer: low level retry 8/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/14 06:45:10 DEBUG : pacer: Reducing sleep to 7.5s
2022/03/14 06:45:10 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:45:10 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': 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:121407171 fi_size:14 responsetype:json]) options=[]
2022/03/14 06:45:12 DEBUG : pacer: Reducing sleep to 5.625s
2022/03/14 06:45:12 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:45:19 DEBUG : pacer: Reducing sleep to 4.21875s
2022/03/14 06:45:19 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: doCompleteUpload(map[fi_size:14 remotetime:2001-02-03 04:05:06 uploadcode:2db51c05e4f7aae532a3808dc11ebd14]) options=[]
2022/03/14 06:45:30 DEBUG : pacer: Reducing sleep to 3.1640625s
2022/03/14 06:45:30 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:45:30 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407059 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/14 06:45:47 DEBUG : pacer: Reducing sleep to 2.373046875s
2022/03/14 06:45:47 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:45:47 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407171 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/14 06:45:59 DEBUG : pacer: Reducing sleep to 1.779785156s
2022/03/14 06:45:59 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:45:59 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407059 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/14 06:46:00 DEBUG : pacer: Reducing sleep to 1.334838867s
2022/03/14 06:46:00 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:46:00 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407171 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/14 06:46:01 DEBUG : pacer: Reducing sleep to 1.00112915s
2022/03/14 06:46:01 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:46:01 DEBUG : : ForgetPath: relativePath="dir/notfound", type=1
2022/03/14 06:46:01 DEBUG : dir: invalidating directory cache
2022/03/14 06:46:01 DEBUG : : >ForgetPath: 
2022/03/14 06:46:01 DEBUG : : ForgetPath: relativePath="dir", type=0
2022/03/14 06:46:01 DEBUG : : invalidating directory cache
2022/03/14 06:46:01 DEBUG : dir: forgetting directory cache
2022/03/14 06:46:01 DEBUG : : >ForgetPath: 
2022/03/14 06:46:01 DEBUG : : ForgetPath: relativePath="not/in/cache", type=0
2022/03/14 06:46:01 DEBUG : : >ForgetPath: 
2022/03/14 06:46:01 DEBUG : WaitForWriters: timeout=30s
2022/03/14 06:46:01 DEBUG : dir: Looking for writers
2022/03/14 06:46:01 DEBUG : : Looking for writers
2022/03/14 06:46:01 DEBUG : dir: reading active writers
2022/03/14 06:46:01 DEBUG : >WaitForWriters: 
2022/03/14 06:46:01 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407059 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/14 06:46:03 DEBUG : pacer: Reducing sleep to 750.846862ms
2022/03/14 06:46:03 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:46:03 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407171 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/14 06:46:04 DEBUG : pacer: Reducing sleep to 563.135146ms
2022/03/14 06:46:04 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:46:04 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: doDeleteFile(map[completedeletion:n fi_id:121407172]) options=[]
2022/03/14 06:47:05 DEBUG : pacer: Reducing sleep to 422.351359ms
2022/03/14 06:47:05 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:47:05 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407171 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/14 06:47:17 DEBUG : pacer: Reducing sleep to 316.763519ms
2022/03/14 06:47:17 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:47:17 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: doDeleteFolder(map[fi_id:121407171]) options=[]
2022/03/14 06:47:35 DEBUG : pacer: Reducing sleep to 237.572639ms
2022/03/14 06:47:35 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:47:35 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407059 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/14 06:47:35 DEBUG : pacer: Reducing sleep to 178.179479ms
2022/03/14 06:47:35 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
--- PASS: TestDirForgetPath (430.31s)
=== RUN   TestDirWalk
    run.go:181: Remote "filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8'", Local "Local file system at /tmp/rclone1943342244", Modify Window "1s"
2022/03/14 06:47:35 INFO  : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': poll-interval is not supported by this remote
2022/03/14 06:47:35 NOTICE: filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2022/03/14 06:47:35 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407059 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/14 06:47:36 DEBUG : pacer: Reducing sleep to 133.634609ms
2022/03/14 06:47:36 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:47:36 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: doCreateNewFolder(map[fi_name:dir fi_pid:121407059]) options=[]
2022/03/14 06:47:36 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 1s to wait for "error_background" error to clear
2022/03/14 06:47:37 DEBUG : pacer: low level retry 1/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/14 06:47:37 DEBUG : pacer: Rate limited, increasing sleep to 267.269218ms
2022/03/14 06:47:41 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 2s to wait for "error_background" error to clear
2022/03/14 06:47:43 DEBUG : pacer: low level retry 2/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/14 06:47:43 DEBUG : pacer: Rate limited, increasing sleep to 534.538436ms
2022/03/14 06:47:45 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 4s to wait for "error_background" error to clear
2022/03/14 06:47:49 DEBUG : pacer: low level retry 3/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/14 06:47:49 DEBUG : pacer: Rate limited, increasing sleep to 1.069076872s
2022/03/14 06:47:49 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 8s to wait for "error_background" error to clear
2022/03/14 06:47:57 DEBUG : pacer: low level retry 4/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/14 06:47:57 DEBUG : pacer: Rate limited, increasing sleep to 2.138153744s
2022/03/14 06:48:01 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 16s to wait for "error_background" error to clear
2022/03/14 06:48:17 DEBUG : pacer: low level retry 5/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/14 06:48:17 DEBUG : pacer: Rate limited, increasing sleep to 4.276307488s
2022/03/14 06:48:18 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 32s to wait for "error_background" error to clear
2022/03/14 06:48:50 DEBUG : pacer: low level retry 6/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/14 06:48:50 DEBUG : pacer: Rate limited, increasing sleep to 8.552614976s
2022/03/14 06:48:51 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 1m4s to wait for "error_background" error to clear
2022/03/14 06:49:55 DEBUG : pacer: low level retry 7/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/14 06:49:55 DEBUG : pacer: Rate limited, increasing sleep to 10s
2022/03/14 06:49:56 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 2m8s to wait for "error_background" error to clear
2022/03/14 06:52:04 DEBUG : pacer: low level retry 8/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/14 06:52:05 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 4m16s to wait for "error_background" error to clear
2022/03/14 06:56:21 DEBUG : pacer: low level retry 9/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/14 06:56:36 DEBUG : pacer: Reducing sleep to 7.5s
2022/03/14 06:56:36 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:56:36 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': 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:121407202 fi_size:14 responsetype:json]) options=[]
2022/03/14 06:56:36 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Token expired - refreshing
2022/03/14 06:56:36 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getTokenByAuthToken(map[authtoken:622506e6346e7ad6-c48bf9558d23a2ae token:*]) options=[]
2022/03/14 06:56:37 DEBUG : pacer: Reducing sleep to 5.625s
2022/03/14 06:56:37 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:56:37 DEBUG : Saving config "token" in section "TestFileFabric" of the config file
2022/03/14 06:56:37 DEBUG : Config file has changed externaly - reloading
2022/03/14 06:56:37 DEBUG : Saving config "token_expiry" in section "TestFileFabric" of the config file
2022/03/14 06:56:37 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getApplianceInfo(map[token:*]) options=[]
2022/03/14 06:56:44 DEBUG : pacer: Reducing sleep to 4.21875s
2022/03/14 06:56:44 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:56:44 DEBUG : Saving config "version" in section "TestFileFabric" of the config file
2022/03/14 06:56:53 DEBUG : pacer: Reducing sleep to 3.1640625s
2022/03/14 06:56:53 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:56:55 DEBUG : pacer: Reducing sleep to 2.373046875s
2022/03/14 06:56:55 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: doCompleteUpload(map[fi_size:14 remotetime:2001-02-03 04:05:06 uploadcode:3127d87dddffd1e39cc16a7860adebc2]) options=[]
2022/03/14 06:57:04 DEBUG : pacer: Reducing sleep to 1.779785156s
2022/03/14 06:57:04 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:57:04 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407059 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/14 06:57:17 DEBUG : pacer: Reducing sleep to 1.334838867s
2022/03/14 06:57:17 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:57:17 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407202 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/14 06:57:37 DEBUG : pacer: Reducing sleep to 1.00112915s
2022/03/14 06:57:37 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:57:37 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407059 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/14 06:57:53 DEBUG : pacer: Reducing sleep to 750.846862ms
2022/03/14 06:57:53 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:57:53 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407059 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/14 06:57:54 DEBUG : pacer: Reducing sleep to 563.135146ms
2022/03/14 06:57:54 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:57:54 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: doCreateNewFolder(map[fi_name:fil fi_pid:121407059]) options=[]
2022/03/14 06:58:22 DEBUG : pacer: Reducing sleep to 422.351359ms
2022/03/14 06:58:22 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:58:22 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407205 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/14 06:58:42 DEBUG : pacer: Reducing sleep to 316.763519ms
2022/03/14 06:58:42 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:58:42 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: doCreateNewFolder(map[fi_name:a fi_pid:121407205]) options=[]
2022/03/14 06:59:06 DEBUG : pacer: Reducing sleep to 237.572639ms
2022/03/14 06:59:06 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:59:06 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407209 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/14 06:59:26 DEBUG : pacer: Reducing sleep to 178.179479ms
2022/03/14 06:59:26 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:59:26 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: doCreateNewFolder(map[fi_name:b fi_pid:121407209]) options=[]
2022/03/14 06:59:47 DEBUG : pacer: Reducing sleep to 133.634609ms
2022/03/14 06:59:47 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:59:47 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: doInitUpload(map[directuploadsupport:n fi_contenttype:application/octet-stream fi_filename:c fi_localtime:2001-02-03 04:05:06 fi_modified:2001-02-03 04:05:06 fi_name:c fi_pid:121407210 fi_size:15 responsetype:json]) options=[]
2022/03/14 06:59:52 DEBUG : pacer: Reducing sleep to 100.225956ms
2022/03/14 06:59:52 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 06:59:53 DEBUG : pacer: Reducing sleep to 75.169467ms
2022/03/14 06:59:53 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: doCompleteUpload(map[fi_size:15 remotetime:2001-02-03 04:05:06 uploadcode:e99a28bc0b241b92e98e9b3cf82ec29b]) options=[]
2022/03/14 07:00:07 DEBUG : pacer: Reducing sleep to 56.3771ms
2022/03/14 07:00:07 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 07:00:07 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407059 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/14 07:00:19 DEBUG : pacer: Reducing sleep to 42.282825ms
2022/03/14 07:00:19 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 07:00:19 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407205 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/14 07:00:19 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407202 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/14 07:00:19 DEBUG : pacer: Reducing sleep to 31.712118ms
2022/03/14 07:00:19 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 07:00:31 DEBUG : pacer: Reducing sleep to 23.784088ms
2022/03/14 07:00:31 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 07:00:31 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407209 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/14 07:00:44 DEBUG : pacer: Reducing sleep to 20ms
2022/03/14 07:00:44 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 07:00:44 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407210 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/14 07:00:57 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 07:00:57 DEBUG : : forgetting directory cache
2022/03/14 07:00:57 DEBUG : dir: forgetting directory cache
2022/03/14 07:00:57 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407059 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/14 07:00:57 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 07:00:57 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407205 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/14 07:00:58 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 07:00:58 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407209 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/14 07:00:58 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 07:00:58 DEBUG : WaitForWriters: timeout=30s
2022/03/14 07:00:58 DEBUG : fil/a/b: Looking for writers
2022/03/14 07:00:58 DEBUG : fil/a: Looking for writers
2022/03/14 07:00:58 DEBUG : b: reading active writers
2022/03/14 07:00:58 DEBUG : fil: Looking for writers
2022/03/14 07:00:58 DEBUG : a: reading active writers
2022/03/14 07:00:58 DEBUG : dir: Looking for writers
2022/03/14 07:00:58 DEBUG : : Looking for writers
2022/03/14 07:00:58 DEBUG : dir: reading active writers
2022/03/14 07:00:58 DEBUG : fil: reading active writers
2022/03/14 07:00:58 DEBUG : >WaitForWriters: 
2022/03/14 07:00:58 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407059 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/14 07:00:59 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 07:00:59 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407205 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/14 07:00:59 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407202 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/14 07:01:00 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 07:01:00 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407209 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/14 07:01:00 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 07:01:00 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: doDeleteFile(map[completedeletion:n fi_id:121407203]) options=[]
2022/03/14 07:01:00 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 07:01:58 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 07:01:58 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407210 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/14 07:01:59 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 07:01:59 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: doDeleteFile(map[completedeletion:n fi_id:121407211]) options=[]
2022/03/14 07:03:11 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 07:03:11 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407210 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/14 07:03:24 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 07:03:24 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: doDeleteFolder(map[fi_id:121407210]) options=[]
2022/03/14 07:03:33 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 07:03:33 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407209 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/14 07:03:34 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 07:03:34 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: doDeleteFolder(map[fi_id:121407209]) options=[]
2022/03/14 07:03:34 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 1s to wait for "error_background" error to clear
2022/03/14 07:03:35 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/14 07:03:35 DEBUG : pacer: Rate limited, increasing sleep to 40ms
2022/03/14 07:03:36 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 2s to wait for "error_background" error to clear
2022/03/14 07:03:38 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/14 07:03:38 DEBUG : pacer: Rate limited, increasing sleep to 80ms
2022/03/14 07:03:41 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 4s to wait for "error_background" error to clear
2022/03/14 07:03:45 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/14 07:03:45 DEBUG : pacer: Rate limited, increasing sleep to 160ms
2022/03/14 07:03:46 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 8s to wait for "error_background" error to clear
2022/03/14 07:03:54 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/14 07:03:54 DEBUG : pacer: Rate limited, increasing sleep to 320ms
2022/03/14 07:03:54 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 16s to wait for "error_background" error to clear
2022/03/14 07:04:10 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/14 07:04:10 DEBUG : pacer: Rate limited, increasing sleep to 640ms
2022/03/14 07:04:11 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 32s to wait for "error_background" error to clear
2022/03/14 07:04:43 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/14 07:04:43 DEBUG : pacer: Rate limited, increasing sleep to 1.28s
2022/03/14 07:04:47 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 1m4s to wait for "error_background" error to clear
2022/03/14 07:05:51 DEBUG : pacer: low level retry 7/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/14 07:05:51 DEBUG : pacer: Rate limited, increasing sleep to 2.56s
2022/03/14 07:06:10 DEBUG : pacer: Reducing sleep to 1.92s
2022/03/14 07:06:10 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 07:06:10 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407205 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/14 07:06:14 DEBUG : pacer: Reducing sleep to 1.44s
2022/03/14 07:06:14 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 07:06:14 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: doDeleteFolder(map[fi_id:121407205]) options=[]
2022/03/14 07:06:18 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 1s to wait for "error_background" error to clear
2022/03/14 07:06:19 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/14 07:06:19 DEBUG : pacer: Rate limited, increasing sleep to 2.88s
2022/03/14 07:06:22 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 2s to wait for "error_background" error to clear
2022/03/14 07:06:24 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/14 07:06:24 DEBUG : pacer: Rate limited, increasing sleep to 5.76s
2022/03/14 07:06:26 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 4s to wait for "error_background" error to clear
2022/03/14 07:06:30 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/14 07:06:30 DEBUG : pacer: Rate limited, increasing sleep to 10s
2022/03/14 07:06:34 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 8s to wait for "error_background" error to clear
2022/03/14 07:06:42 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/14 07:06:46 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 16s to wait for "error_background" error to clear
2022/03/14 07:07:02 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/14 07:07:02 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 32s to wait for "error_background" error to clear
2022/03/14 07:07:34 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/14 07:07:43 DEBUG : pacer: Reducing sleep to 7.5s
2022/03/14 07:07:43 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 07:07:43 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407202 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/14 07:07:56 DEBUG : pacer: Reducing sleep to 5.625s
2022/03/14 07:07:56 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 07:07:56 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: doDeleteFolder(map[fi_id:121407202]) options=[]
2022/03/14 07:08:08 DEBUG : pacer: Reducing sleep to 4.21875s
2022/03/14 07:08:08 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 07:08:08 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407059 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/14 07:08:09 DEBUG : pacer: Reducing sleep to 3.1640625s
2022/03/14 07:08:09 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
--- PASS: TestDirWalk (1233.74s)
=== RUN   TestDirSetModTime
    run.go:181: Remote "filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8'", Local "Local file system at /tmp/rclone1943342244", Modify Window "1s"
2022/03/14 07:08:09 INFO  : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': poll-interval is not supported by this remote
2022/03/14 07:08:09 NOTICE: filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2022/03/14 07:08:09 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407059 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/14 07:08:13 DEBUG : pacer: Reducing sleep to 2.373046875s
2022/03/14 07:08:13 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 07:08:13 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: doCreateNewFolder(map[fi_name:dir fi_pid:121407059]) options=[]
2022/03/14 07:08:19 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 1s to wait for "error_background" error to clear
2022/03/14 07:08:20 DEBUG : pacer: low level retry 1/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/14 07:08:20 DEBUG : pacer: Rate limited, increasing sleep to 4.74609375s
2022/03/14 07:08:23 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 2s to wait for "error_background" error to clear
2022/03/14 07:08:25 DEBUG : pacer: low level retry 2/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/14 07:08:25 DEBUG : pacer: Rate limited, increasing sleep to 9.4921875s
2022/03/14 07:08:27 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 4s to wait for "error_background" error to clear
2022/03/14 07:08:31 DEBUG : pacer: low level retry 3/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/14 07:08:31 DEBUG : pacer: Rate limited, increasing sleep to 10s
2022/03/14 07:08:35 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 8s to wait for "error_background" error to clear
2022/03/14 07:08:43 DEBUG : pacer: low level retry 4/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/14 07:08:47 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 16s to wait for "error_background" error to clear
2022/03/14 07:09:03 DEBUG : pacer: low level retry 5/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/14 07:09:07 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 32s to wait for "error_background" error to clear
2022/03/14 07:09:39 DEBUG : pacer: low level retry 6/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/14 07:09:40 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 1m4s to wait for "error_background" error to clear
2022/03/14 07:10:44 DEBUG : pacer: low level retry 7/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/14 07:10:46 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 2m8s to wait for "error_background" error to clear
2022/03/14 07:12:54 DEBUG : pacer: low level retry 8/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/14 07:13:20 DEBUG : pacer: Reducing sleep to 7.5s
2022/03/14 07:13:20 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 07:13:20 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': 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:121407249 fi_size:14 responsetype:json]) options=[]
2022/03/14 07:13:24 DEBUG : pacer: Reducing sleep to 5.625s
2022/03/14 07:13:24 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 07:13:29 DEBUG : pacer: Reducing sleep to 4.21875s
2022/03/14 07:13:29 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: doCompleteUpload(map[fi_size:14 remotetime:2001-02-03 04:05:06 uploadcode:da751022bf6c8871d7f62464a1915134]) options=[]
2022/03/14 07:13:40 DEBUG : pacer: Reducing sleep to 3.1640625s
2022/03/14 07:13:40 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 07:13:40 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407059 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/14 07:13:59 DEBUG : pacer: Reducing sleep to 2.373046875s
2022/03/14 07:13:59 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 07:13:59 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407249 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/14 07:14:22 DEBUG : pacer: Reducing sleep to 1.779785156s
2022/03/14 07:14:22 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 07:14:22 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407059 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/14 07:14:23 DEBUG : pacer: Reducing sleep to 1.334838867s
2022/03/14 07:14:23 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 07:14:23 DEBUG : WaitForWriters: timeout=30s
2022/03/14 07:14:23 DEBUG : dir: Looking for writers
2022/03/14 07:14:23 DEBUG : : Looking for writers
2022/03/14 07:14:23 DEBUG : dir: reading active writers
2022/03/14 07:14:23 DEBUG : >WaitForWriters: 
2022/03/14 07:14:23 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407059 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/14 07:14:25 DEBUG : pacer: Reducing sleep to 1.00112915s
2022/03/14 07:14:25 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 07:14:25 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407249 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/14 07:14:26 DEBUG : pacer: Reducing sleep to 750.846862ms
2022/03/14 07:14:26 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 07:14:26 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: doDeleteFile(map[completedeletion:n fi_id:121407251]) options=[]
2022/03/14 07:15:42 DEBUG : pacer: Reducing sleep to 563.135146ms
2022/03/14 07:15:42 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 07:15:42 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407249 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/14 07:15:46 DEBUG : pacer: Reducing sleep to 422.351359ms
2022/03/14 07:15:46 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 07:15:46 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: doDeleteFolder(map[fi_id:121407249]) options=[]
2022/03/14 07:15:50 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 1s to wait for "error_background" error to clear
2022/03/14 07:15:51 DEBUG : pacer: low level retry 1/10 (error We are not able to complete the requested operation. We are processing move folder in parent folder. Please try again later. (error_background))
2022/03/14 07:15:51 DEBUG : pacer: Rate limited, increasing sleep to 844.702718ms
2022/03/14 07:15:55 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 2s to wait for "error_background" error to clear
2022/03/14 07:15:57 DEBUG : pacer: low level retry 2/10 (error We are not able to complete the requested operation. We are processing move folder in parent folder. Please try again later. (error_background))
2022/03/14 07:15:57 DEBUG : pacer: Rate limited, increasing sleep to 1.689405436s
2022/03/14 07:15:58 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 4s to wait for "error_background" error to clear
2022/03/14 07:16:02 DEBUG : pacer: low level retry 3/10 (error We are not able to complete the requested operation. We are processing move folder in parent folder. Please try again later. (error_background))
2022/03/14 07:16:02 DEBUG : pacer: Rate limited, increasing sleep to 3.378810872s
2022/03/14 07:16:03 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 8s to wait for "error_background" error to clear
2022/03/14 07:16:11 DEBUG : pacer: low level retry 4/10 (error We are not able to complete the requested operation. We are processing move folder in parent folder. Please try again later. (error_background))
2022/03/14 07:16:11 DEBUG : pacer: Rate limited, increasing sleep to 6.757621744s
2022/03/14 07:16:15 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 16s to wait for "error_background" error to clear
2022/03/14 07:16:31 DEBUG : pacer: low level retry 5/10 (error We are not able to complete the requested operation. We are processing move folder in parent folder. Please try again later. (error_background))
2022/03/14 07:16:31 DEBUG : pacer: Rate limited, increasing sleep to 10s
2022/03/14 07:16:35 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 32s to wait for "error_background" error to clear
2022/03/14 07:17:07 DEBUG : pacer: low level retry 6/10 (error We are not able to complete the requested operation. We are processing move folder in parent folder. Please try again later. (error_background))
2022/03/14 07:17:08 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 1m4s to wait for "error_background" error to clear
2022/03/14 07:18:12 DEBUG : pacer: low level retry 7/10 (error We are not able to complete the requested operation. We are processing move folder in parent folder. Please try again later. (error_background))
2022/03/14 07:18:15 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 2m8s to wait for "error_background" error to clear
2022/03/14 07:20:23 DEBUG : pacer: low level retry 8/10 (error We are not able to complete the requested operation. We are processing move folder in parent folder. Please try again later. (error_background))
2022/03/14 07:20:23 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 4m16s to wait for "error_background" error to clear
2022/03/14 07:24:39 DEBUG : pacer: low level retry 9/10 (error We are not able to complete the requested operation. We are processing move folder in parent folder. Please try again later. (error_background))
2022/03/14 07:24:58 DEBUG : pacer: Reducing sleep to 7.5s
2022/03/14 07:24:58 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 07:24:58 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407059 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/14 07:25:02 DEBUG : pacer: Reducing sleep to 5.625s
2022/03/14 07:25:02 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
--- PASS: TestDirSetModTime (1012.59s)
=== RUN   TestDirStat
    run.go:181: Remote "filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8'", Local "Local file system at /tmp/rclone1943342244", Modify Window "1s"
2022/03/14 07:25:02 INFO  : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': poll-interval is not supported by this remote
2022/03/14 07:25:02 NOTICE: filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2022/03/14 07:25:02 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407059 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/14 07:25:06 DEBUG : pacer: Reducing sleep to 4.21875s
2022/03/14 07:25:06 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 07:25:06 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: doCreateNewFolder(map[fi_name:dir fi_pid:121407059]) options=[]
2022/03/14 07:25:11 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 1s to wait for "error_background" error to clear
2022/03/14 07:25:12 DEBUG : pacer: low level retry 1/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/14 07:25:12 DEBUG : pacer: Rate limited, increasing sleep to 8.4375s
2022/03/14 07:25:16 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 2s to wait for "error_background" error to clear
2022/03/14 07:25:18 DEBUG : pacer: low level retry 2/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/14 07:25:18 DEBUG : pacer: Rate limited, increasing sleep to 10s
2022/03/14 07:25:25 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 4s to wait for "error_background" error to clear
2022/03/14 07:25:29 DEBUG : pacer: low level retry 3/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/14 07:25:37 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 8s to wait for "error_background" error to clear
2022/03/14 07:25:45 DEBUG : pacer: low level retry 4/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/14 07:25:49 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 16s to wait for "error_background" error to clear
2022/03/14 07:26:05 DEBUG : pacer: low level retry 5/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/14 07:26:06 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 32s to wait for "error_background" error to clear
2022/03/14 07:26:38 DEBUG : pacer: low level retry 6/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/14 07:26:41 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 1m4s to wait for "error_background" error to clear
2022/03/14 07:27:45 DEBUG : pacer: low level retry 7/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/14 07:27:46 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 2m8s to wait for "error_background" error to clear
2022/03/14 07:29:54 DEBUG : pacer: low level retry 8/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/14 07:29:55 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 4m16s to wait for "error_background" error to clear
2022/03/14 07:34:11 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))
2022/03/14 07:34:14 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 8m32s to wait for "error_background" error to clear
2022/03/14 07:42:46 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))
2022/03/14 07:42:46 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >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)
    run.go:283: Retry Put of "dir/file1" to filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': 1/10 (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))
2022/03/14 07:42:48 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407059 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/14 07:42:59 DEBUG : pacer: Reducing sleep to 7.5s
2022/03/14 07:42:59 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 07:42:59 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: doCreateNewFolder(map[fi_name:dir fi_pid:121407059]) options=[]
2022/03/14 07:43:24 DEBUG : pacer: Reducing sleep to 5.625s
2022/03/14 07:43:24 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 07:43:24 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': 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:121407323 fi_size:14 responsetype:json]) options=[]
2022/03/14 07:43:26 DEBUG : pacer: Reducing sleep to 4.21875s
2022/03/14 07:43:26 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 07:43:31 DEBUG : pacer: Reducing sleep to 3.1640625s
2022/03/14 07:43:31 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: doCompleteUpload(map[fi_size:14 remotetime:2001-02-03 04:05:06 uploadcode:4a352b9ddb307ceb2180b69c88c7df86]) options=[]
2022/03/14 07:43:45 DEBUG : pacer: Reducing sleep to 2.373046875s
2022/03/14 07:43:45 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 07:43:45 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407059 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/14 07:44:05 DEBUG : pacer: Reducing sleep to 1.779785156s
2022/03/14 07:44:05 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 07:44:05 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407323 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/14 07:44:17 DEBUG : pacer: Reducing sleep to 1.334838867s
2022/03/14 07:44:17 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 07:44:17 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407059 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/14 07:44:17 DEBUG : pacer: Reducing sleep to 1.00112915s
2022/03/14 07:44:17 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 07:44:17 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407323 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/14 07:44:19 DEBUG : pacer: Reducing sleep to 750.846862ms
2022/03/14 07:44:19 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 07:44:19 DEBUG : WaitForWriters: timeout=30s
2022/03/14 07:44:19 DEBUG : dir: Looking for writers
2022/03/14 07:44:19 DEBUG : file1: reading active writers
2022/03/14 07:44:19 DEBUG : : Looking for writers
2022/03/14 07:44:19 DEBUG : dir: reading active writers
2022/03/14 07:44:19 DEBUG : >WaitForWriters: 
2022/03/14 07:44:19 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407059 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/14 07:44:20 DEBUG : pacer: Reducing sleep to 563.135146ms
2022/03/14 07:44:20 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 07:44:20 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407323 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/14 07:44:20 DEBUG : pacer: Reducing sleep to 422.351359ms
2022/03/14 07:44:20 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 07:44:20 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: doDeleteFile(map[completedeletion:n fi_id:121407327]) options=[]
2022/03/14 07:45:06 DEBUG : pacer: Reducing sleep to 316.763519ms
2022/03/14 07:45:06 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 07:45:06 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407323 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/14 07:45:18 DEBUG : pacer: Reducing sleep to 237.572639ms
2022/03/14 07:45:18 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 07:45:18 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: doDeleteFolder(map[fi_id:121407323]) options=[]
2022/03/14 07:45:38 DEBUG : pacer: Reducing sleep to 178.179479ms
2022/03/14 07:45:38 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 07:45:38 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407059 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/14 07:45:42 DEBUG : pacer: Reducing sleep to 133.634609ms
2022/03/14 07:45:42 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
--- PASS: TestDirStat (1239.92s)
=== RUN   TestDirReadDirAll
    run.go:181: Remote "filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8'", Local "Local file system at /tmp/rclone1943342244", Modify Window "1s"
2022/03/14 07:45:42 INFO  : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': poll-interval is not supported by this remote
2022/03/14 07:45:42 NOTICE: filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2022/03/14 07:45:42 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407059 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/14 07:45:42 DEBUG : pacer: Reducing sleep to 100.225956ms
2022/03/14 07:45:42 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 07:45:42 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: doCreateNewFolder(map[fi_name:dir fi_pid:121407059]) options=[]
2022/03/14 07:45:45 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 1s to wait for "error_background" error to clear
2022/03/14 07:45:46 DEBUG : pacer: low level retry 1/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/14 07:45:46 DEBUG : pacer: Rate limited, increasing sleep to 200.451912ms
2022/03/14 07:45:49 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 2s to wait for "error_background" error to clear
2022/03/14 07:45:51 DEBUG : pacer: low level retry 2/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/14 07:45:51 DEBUG : pacer: Rate limited, increasing sleep to 400.903824ms
2022/03/14 07:45:53 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 4s to wait for "error_background" error to clear
2022/03/14 07:45:57 DEBUG : pacer: low level retry 3/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/14 07:45:57 DEBUG : pacer: Rate limited, increasing sleep to 801.807648ms
2022/03/14 07:46:01 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 8s to wait for "error_background" error to clear
2022/03/14 07:46:09 DEBUG : pacer: low level retry 4/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/14 07:46:09 DEBUG : pacer: Rate limited, increasing sleep to 1.603615296s
2022/03/14 07:46:14 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 16s to wait for "error_background" error to clear
2022/03/14 07:46:30 DEBUG : pacer: low level retry 5/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/14 07:46:30 DEBUG : pacer: Rate limited, increasing sleep to 3.207230592s
2022/03/14 07:46:30 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 32s to wait for "error_background" error to clear
2022/03/14 07:47:02 DEBUG : pacer: low level retry 6/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/14 07:47:02 DEBUG : pacer: Rate limited, increasing sleep to 6.414461184s
2022/03/14 07:47:05 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 1m4s to wait for "error_background" error to clear
2022/03/14 07:48:09 DEBUG : pacer: low level retry 7/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/14 07:48:09 DEBUG : pacer: Rate limited, increasing sleep to 10s
2022/03/14 07:48:27 DEBUG : pacer: Reducing sleep to 7.5s
2022/03/14 07:48:27 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 07:48:27 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': 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:121407339 fi_size:14 responsetype:json]) options=[]
2022/03/14 07:48:32 DEBUG : pacer: Reducing sleep to 5.625s
2022/03/14 07:48:32 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 07:48:36 DEBUG : pacer: Reducing sleep to 4.21875s
2022/03/14 07:48:36 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: doCompleteUpload(map[fi_size:14 remotetime:2001-02-03 04:05:06 uploadcode:6fb882ea9762e21437927ec1059343f4]) options=[]
2022/03/14 07:48:56 DEBUG : pacer: Reducing sleep to 3.1640625s
2022/03/14 07:48:56 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 07:48:56 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': 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:121407339 fi_size:15 responsetype:json]) options=[]
2022/03/14 07:48:57 DEBUG : pacer: Reducing sleep to 2.373046875s
2022/03/14 07:48:57 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 07:49:01 DEBUG : pacer: Reducing sleep to 1.779785156s
2022/03/14 07:49:01 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: doCompleteUpload(map[fi_size:15 remotetime:2011-12-25 12:59:59 uploadcode:1e841dcbb605f9b72758fae399d9acad]) options=[]
2022/03/14 07:49:16 DEBUG : pacer: Reducing sleep to 1.334838867s
2022/03/14 07:49:16 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 07:49:16 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407339 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/14 07:49:28 DEBUG : pacer: Reducing sleep to 1.00112915s
2022/03/14 07:49:28 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 07:49:28 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: doCreateNewFolder(map[fi_name:subdir fi_pid:121407339]) options=[]
2022/03/14 07:49:52 DEBUG : pacer: Reducing sleep to 750.846862ms
2022/03/14 07:49:52 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 07:49:52 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': 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:121407347 fi_size:16 responsetype:json]) options=[]
2022/03/14 07:49:54 DEBUG : pacer: Reducing sleep to 563.135146ms
2022/03/14 07:49:54 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 07:49:55 DEBUG : pacer: Reducing sleep to 422.351359ms
2022/03/14 07:49:55 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: doCompleteUpload(map[fi_size:16 remotetime:2011-12-30 12:59:59 uploadcode:ec26563bbf8a1c4d9d3610c32d22cd11]) options=[]
2022/03/14 07:50:01 DEBUG : pacer: Reducing sleep to 316.763519ms
2022/03/14 07:50:01 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 07:50:01 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407059 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/14 07:50:10 DEBUG : pacer: Reducing sleep to 237.572639ms
2022/03/14 07:50:10 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 07:50:10 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407339 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/14 07:50:26 DEBUG : pacer: Reducing sleep to 178.179479ms
2022/03/14 07:50:26 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 07:50:26 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407347 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/14 07:50:38 DEBUG : pacer: Reducing sleep to 133.634609ms
2022/03/14 07:50:38 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 07:50:38 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407059 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/14 07:50:54 DEBUG : pacer: Reducing sleep to 100.225956ms
2022/03/14 07:50:54 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 07:50:54 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407339 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/14 07:50:55 DEBUG : pacer: Reducing sleep to 75.169467ms
2022/03/14 07:50:55 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 07:50:55 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407347 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/14 07:50:56 DEBUG : pacer: Reducing sleep to 56.3771ms
2022/03/14 07:50:56 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
=== RUN   TestDirReadDirAll/Virtual
2022/03/14 07:50:56 DEBUG : dir: Added virtual directory entry vAddFile: "virtualFile"
2022/03/14 07:50:56 DEBUG : dir: Added virtual directory entry vAddDir: "virtualDir"
2022/03/14 07:50:56 DEBUG : dir: Added virtual directory entry vDel: "file2"
2022/03/14 07:50:56 DEBUG : dir: Added virtual directory entry vDel: "subdir"
2022/03/14 07:50:56 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': 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:121407339 fi_size:20 responsetype:json]) options=[]
2022/03/14 07:51:00 DEBUG : pacer: Reducing sleep to 42.282825ms
2022/03/14 07:51:00 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 07:51:02 DEBUG : pacer: Reducing sleep to 31.712118ms
2022/03/14 07:51:02 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: doCompleteUpload(map[fi_size:20 remotetime:2001-02-03 04:05:06 uploadcode:75ece3445b12fd6129d3d252b4451303]) options=[]
2022/03/14 07:51:07 DEBUG : pacer: Reducing sleep to 23.784088ms
2022/03/14 07:51:07 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 07:51:07 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407339 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/14 07:51:24 DEBUG : pacer: Reducing sleep to 20ms
2022/03/14 07:51:24 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 07:51:24 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: doCreateNewFolder(map[fi_name:virtualDir fi_pid:121407339]) options=[]
2022/03/14 07:51:44 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 07:51:44 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': 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:121407354 fi_size:17 responsetype:json]) options=[]
2022/03/14 07:51:44 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Token expired - refreshing
2022/03/14 07:51:44 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getTokenByAuthToken(map[authtoken:622506e6346e7ad6-c48bf9558d23a2ae token:*]) options=[]
2022/03/14 07:51:44 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 07:51:44 DEBUG : Saving config "token" in section "TestFileFabric" of the config file
2022/03/14 07:51:44 DEBUG : Config file has changed externaly - reloading
2022/03/14 07:51:44 DEBUG : Saving config "token_expiry" in section "TestFileFabric" of the config file
2022/03/14 07:51:44 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getApplianceInfo(map[token:*]) options=[]
2022/03/14 07:51:45 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 07:51:45 DEBUG : Saving config "version" in section "TestFileFabric" of the config file
2022/03/14 07:51:49 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 07:51:51 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: doCompleteUpload(map[fi_size:17 remotetime:2001-02-03 04:05:06 uploadcode:1eb61ecc0723067863a0ee6c2b6612c2]) options=[]
2022/03/14 07:51:56 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 07:51:56 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: checkPathExists(map[path:dir/file2 pid:121407059]) options=[]
2022/03/14 07:51:57 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 07:51:57 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: doDeleteFile(map[completedeletion:n fi_id:121407343]) options=[]
2022/03/14 07:52:42 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 07:52:42 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: doDeleteFolder(map[fi_id:121407347]) options=[]
2022/03/14 07:52:59 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 07:52:59 DEBUG : dir: invalidating directory cache
2022/03/14 07:52:59 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407339 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/14 07:53:00 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 07:53:00 DEBUG : dir: Removed virtual directory entry vDel: "file2"
2022/03/14 07:53:00 DEBUG : dir: Removed virtual directory entry vDel: "subdir"
2022/03/14 07:53:00 DEBUG : dir: Removed virtual directory entry vAddDir: "virtualDir"
2022/03/14 07:53:00 DEBUG : dir: Removed virtual directory entry vAddFile: "virtualFile"
2022/03/14 07:53:00 DEBUG : dir: Added virtual directory entry vAddFile: "virtualFile2"
2022/03/14 07:53:00 DEBUG : dir: Added virtual directory entry vAddDir: "virtualDir2"
2022/03/14 07:53:00 DEBUG : dir: Added virtual directory entry vDel: "file1"
2022/03/14 07:53:00 DEBUG : dir: invalidating directory cache
2022/03/14 07:53:00 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407339 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/14 07:53:00 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 07:53:00 DEBUG : dir: Removed virtual directory entry vAddDir: "virtualDir2"
2022/03/14 07:53:00 DEBUG : dir: Removed virtual directory entry vDel: "file1"
2022/03/14 07:53:00 DEBUG : : forgetting directory cache
2022/03/14 07:53:00 DEBUG : dir: forgetting directory cache
2022/03/14 07:53:00 DEBUG : dir/virtualDir: forgetting directory cache
2022/03/14 07:53:00 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407339 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/14 07:53:01 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 07:53:01 DEBUG : WaitForWriters: timeout=30s
2022/03/14 07:53:01 DEBUG : dir/virtualDir: Looking for writers
2022/03/14 07:53:01 DEBUG : dir: Looking for writers
2022/03/14 07:53:01 DEBUG : file1: reading active writers
2022/03/14 07:53:01 DEBUG : virtualFile2: reading active writers
2022/03/14 07:53:01 DEBUG : virtualFile: reading active writers
2022/03/14 07:53:01 DEBUG : virtualDir: reading active writers
2022/03/14 07:53:01 DEBUG : : Looking for writers
2022/03/14 07:53:01 DEBUG : dir: reading active writers
2022/03/14 07:53:01 DEBUG : >WaitForWriters: 
2022/03/14 07:53:01 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407059 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/14 07:53:03 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 07:53:03 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407339 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/14 07:53:04 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 07:53:04 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: doDeleteFile(map[completedeletion:n fi_id:121407342]) options=[]
2022/03/14 07:53:37 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 07:53:37 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: doDeleteFile(map[completedeletion:n fi_id:121407352]) options=[]
2022/03/14 07:54:19 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 07:54:19 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407354 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/14 07:54:28 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 07:54:28 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: doDeleteFile(map[completedeletion:n fi_id:121407356]) options=[]
2022/03/14 07:55:20 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 07:55:20 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407354 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/14 07:55:30 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 07:55:30 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: doDeleteFolder(map[fi_id:121407354]) options=[]
2022/03/14 07:55:54 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 07:55:54 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407339 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/14 07:55:58 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 07:55:58 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: doDeleteFolder(map[fi_id:121407339]) options=[]
2022/03/14 07:56:02 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 1s to wait for "error_background" error to clear
2022/03/14 07:56:03 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/14 07:56:03 DEBUG : pacer: Rate limited, increasing sleep to 40ms
2022/03/14 07:56:06 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 2s to wait for "error_background" error to clear
2022/03/14 07:56:08 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/14 07:56:08 DEBUG : pacer: Rate limited, increasing sleep to 80ms
2022/03/14 07:56:10 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 4s to wait for "error_background" error to clear
2022/03/14 07:56:14 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/14 07:56:14 DEBUG : pacer: Rate limited, increasing sleep to 160ms
2022/03/14 07:56:15 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 8s to wait for "error_background" error to clear
2022/03/14 07:56:23 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/14 07:56:23 DEBUG : pacer: Rate limited, increasing sleep to 320ms
2022/03/14 07:56:27 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 16s to wait for "error_background" error to clear
2022/03/14 07:56:43 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/14 07:56:43 DEBUG : pacer: Rate limited, increasing sleep to 640ms
2022/03/14 07:56:44 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 32s to wait for "error_background" error to clear
2022/03/14 07:57:16 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/14 07:57:16 DEBUG : pacer: Rate limited, increasing sleep to 1.28s
2022/03/14 07:57:17 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 1m4s to wait for "error_background" error to clear
2022/03/14 07:58:21 DEBUG : pacer: low level retry 7/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/14 07:58:21 DEBUG : pacer: Rate limited, increasing sleep to 2.56s
2022/03/14 07:58:23 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 2m8s to wait for "error_background" error to clear
2022/03/14 08:00:31 DEBUG : pacer: low level retry 8/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/14 08:00:31 DEBUG : pacer: Rate limited, increasing sleep to 5.12s
2022/03/14 08:00:41 DEBUG : pacer: Reducing sleep to 3.84s
2022/03/14 08:00:41 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 08:00:41 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407059 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/14 08:00:42 DEBUG : pacer: Reducing sleep to 2.88s
2022/03/14 08:00:42 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
--- PASS: TestDirReadDirAll (900.16s)
    --- PASS: TestDirReadDirAll/Virtual (125.04s)
=== RUN   TestDirOpen
    run.go:181: Remote "filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8'", Local "Local file system at /tmp/rclone1943342244", Modify Window "1s"
2022/03/14 08:00:42 INFO  : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': poll-interval is not supported by this remote
2022/03/14 08:00:42 NOTICE: filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2022/03/14 08:00:42 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407059 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/14 08:00:45 DEBUG : pacer: Reducing sleep to 2.16s
2022/03/14 08:00:45 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 08:00:45 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: doCreateNewFolder(map[fi_name:dir fi_pid:121407059]) options=[]
2022/03/14 08:00:50 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 1s to wait for "error_background" error to clear
2022/03/14 08:00:51 DEBUG : pacer: low level retry 1/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/14 08:00:51 DEBUG : pacer: Rate limited, increasing sleep to 4.32s
2022/03/14 08:00:52 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 2s to wait for "error_background" error to clear
2022/03/14 08:00:54 DEBUG : pacer: low level retry 2/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/14 08:00:54 DEBUG : pacer: Rate limited, increasing sleep to 8.64s
2022/03/14 08:01:09 DEBUG : pacer: Reducing sleep to 6.48s
2022/03/14 08:01:09 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 08:01:09 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': 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:121407378 fi_size:14 responsetype:json]) options=[]
2022/03/14 08:01:11 DEBUG : pacer: Reducing sleep to 4.86s
2022/03/14 08:01:11 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 08:01:17 DEBUG : pacer: Reducing sleep to 3.645s
2022/03/14 08:01:17 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: doCompleteUpload(map[fi_size:14 remotetime:2001-02-03 04:05:06 uploadcode:7b5baf0a3bcacad6da9a5cdc830951c4]) options=[]
2022/03/14 08:01:26 DEBUG : pacer: Reducing sleep to 2.73375s
2022/03/14 08:01:26 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 08:01:26 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407059 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/14 08:01:42 DEBUG : pacer: Reducing sleep to 2.0503125s
2022/03/14 08:01:42 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 08:01:42 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407378 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/14 08:01:58 DEBUG : pacer: Reducing sleep to 1.537734375s
2022/03/14 08:01:58 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 08:01:58 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407059 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/14 08:01:58 DEBUG : pacer: Reducing sleep to 1.153300781s
2022/03/14 08:01:58 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 08:01:58 ERROR : dir/: Can only open directories read only
2022/03/14 08:01:58 DEBUG : WaitForWriters: timeout=30s
2022/03/14 08:01:58 DEBUG : dir: Looking for writers
2022/03/14 08:01:58 DEBUG : : Looking for writers
2022/03/14 08:01:58 DEBUG : dir: reading active writers
2022/03/14 08:01:58 DEBUG : >WaitForWriters: 
2022/03/14 08:01:58 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407059 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/14 08:02:00 DEBUG : pacer: Reducing sleep to 864.975585ms
2022/03/14 08:02:00 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 08:02:00 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407378 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/14 08:02:01 DEBUG : pacer: Reducing sleep to 648.731688ms
2022/03/14 08:02:01 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 08:02:01 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: doDeleteFile(map[completedeletion:n fi_id:121407380]) options=[]
2022/03/14 08:02:47 DEBUG : pacer: Reducing sleep to 486.548766ms
2022/03/14 08:02:47 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 08:02:47 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407378 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/14 08:02:59 DEBUG : pacer: Reducing sleep to 364.911574ms
2022/03/14 08:02:59 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 08:02:59 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: doDeleteFolder(map[fi_id:121407378]) options=[]
2022/03/14 08:03:08 DEBUG : pacer: Reducing sleep to 273.68368ms
2022/03/14 08:03:08 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 08:03:08 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407059 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/14 08:03:12 DEBUG : pacer: Reducing sleep to 205.26276ms
2022/03/14 08:03:12 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
--- PASS: TestDirOpen (149.78s)
=== RUN   TestDirCreate
    run.go:181: Remote "filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8'", Local "Local file system at /tmp/rclone1943342244", Modify Window "1s"
2022/03/14 08:03:12 INFO  : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': poll-interval is not supported by this remote
2022/03/14 08:03:12 NOTICE: filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2022/03/14 08:03:12 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407059 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/14 08:03:12 DEBUG : pacer: Reducing sleep to 153.94707ms
2022/03/14 08:03:12 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 08:03:12 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: doCreateNewFolder(map[fi_name:dir fi_pid:121407059]) options=[]
2022/03/14 08:03:13 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 1s to wait for "error_background" error to clear
2022/03/14 08:03:14 DEBUG : pacer: low level retry 1/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/14 08:03:14 DEBUG : pacer: Rate limited, increasing sleep to 307.89414ms
2022/03/14 08:03:16 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 2s to wait for "error_background" error to clear
2022/03/14 08:03:18 DEBUG : pacer: low level retry 2/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/14 08:03:18 DEBUG : pacer: Rate limited, increasing sleep to 615.78828ms
2022/03/14 08:03:20 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 4s to wait for "error_background" error to clear
2022/03/14 08:03:24 DEBUG : pacer: low level retry 3/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/14 08:03:24 DEBUG : pacer: Rate limited, increasing sleep to 1.23157656s
2022/03/14 08:03:28 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 8s to wait for "error_background" error to clear
2022/03/14 08:03:36 DEBUG : pacer: low level retry 4/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/14 08:03:36 DEBUG : pacer: Rate limited, increasing sleep to 2.46315312s
2022/03/14 08:03:39 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 16s to wait for "error_background" error to clear
2022/03/14 08:03:55 DEBUG : pacer: low level retry 5/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/14 08:03:55 DEBUG : pacer: Rate limited, increasing sleep to 4.92630624s
2022/03/14 08:03:57 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 32s to wait for "error_background" error to clear
2022/03/14 08:04:29 DEBUG : pacer: low level retry 6/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/14 08:04:29 DEBUG : pacer: Rate limited, increasing sleep to 9.85261248s
2022/03/14 08:04:42 DEBUG : pacer: Reducing sleep to 7.38945936s
2022/03/14 08:04:42 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 08:04:42 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': 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:121407385 fi_size:14 responsetype:json]) options=[]
2022/03/14 08:04:47 DEBUG : pacer: Reducing sleep to 5.54209452s
2022/03/14 08:04:47 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 08:04:51 DEBUG : pacer: Reducing sleep to 4.15657089s
2022/03/14 08:04:51 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: doCompleteUpload(map[fi_size:14 remotetime:2001-02-03 04:05:06 uploadcode:775625f6bc1441ca8100893e38cbb862]) options=[]
2022/03/14 08:05:03 DEBUG : pacer: Reducing sleep to 3.117428167s
2022/03/14 08:05:03 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 08:05:03 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407059 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/14 08:05:15 DEBUG : pacer: Reducing sleep to 2.338071125s
2022/03/14 08:05:15 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 08:05:15 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407385 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/14 08:05:28 DEBUG : pacer: Reducing sleep to 1.753553343s
2022/03/14 08:05:28 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 08:05:28 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407059 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/14 08:05:29 DEBUG : pacer: Reducing sleep to 1.315165007s
2022/03/14 08:05:29 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 08:05:29 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407385 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/14 08:05:49 DEBUG : pacer: Reducing sleep to 986.373755ms
2022/03/14 08:05:49 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 08:05:49 DEBUG : dir/potato: Open: flags=O_WRONLY|O_CREATE
2022/03/14 08:05:49 DEBUG : dir: Added virtual directory entry vAddFile: "potato"
2022/03/14 08:05:49 DEBUG : dir/potato: >Open: fd=dir/potato (w), err=<nil>
2022/03/14 08:05:49 DEBUG : dir: Added virtual directory entry vAddFile: "potato"
2022/03/14 08:05:49 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': File to upload is small (5 bytes), uploading instead of streaming
2022/03/14 08:05:49 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: doInitUpload(map[directuploadsupport:n fi_contenttype:application/octet-stream fi_filename:potato fi_localtime:2022-03-14 08:05:49 fi_modified:2022-03-14 08:05:49 fi_name:potato fi_pid:121407385 fi_size:5 responsetype:json]) options=[]
2022/03/14 08:05:53 DEBUG : pacer: Reducing sleep to 739.780316ms
2022/03/14 08:05:53 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 08:05:55 DEBUG : pacer: Reducing sleep to 554.835237ms
2022/03/14 08:05:55 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: doCompleteUpload(map[fi_size:5 remotetime:2022-03-14 08:05:49 uploadcode:453d83d5ed3a544a820eccea90984c91]) options=[]
2022/03/14 08:06:01 DEBUG : pacer: Reducing sleep to 416.126427ms
2022/03/14 08:06:01 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 08:06:01 INFO  : dir/potato: Copied (new)
2022/03/14 08:06:01 DEBUG : dir: Added virtual directory entry vAddFile: "potato"
2022/03/14 08:06:01 DEBUG : WaitForWriters: timeout=30s
2022/03/14 08:06:01 DEBUG : dir: Looking for writers
2022/03/14 08:06:01 DEBUG : file1: reading active writers
2022/03/14 08:06:01 DEBUG : potato: reading active writers
2022/03/14 08:06:01 DEBUG : : Looking for writers
2022/03/14 08:06:01 DEBUG : dir: reading active writers
2022/03/14 08:06:01 DEBUG : >WaitForWriters: 
2022/03/14 08:06:01 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407059 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/14 08:06:13 DEBUG : pacer: Reducing sleep to 312.09482ms
2022/03/14 08:06:13 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 08:06:13 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407385 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/14 08:06:32 DEBUG : pacer: Reducing sleep to 234.071115ms
2022/03/14 08:06:32 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 08:06:32 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: doDeleteFile(map[completedeletion:n fi_id:121407387]) options=[]
2022/03/14 08:07:12 DEBUG : pacer: Reducing sleep to 175.553336ms
2022/03/14 08:07:12 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 08:07:12 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: doDeleteFile(map[completedeletion:n fi_id:121407391]) options=[]
2022/03/14 08:07:45 DEBUG : pacer: Reducing sleep to 131.665002ms
2022/03/14 08:07:45 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 08:07:45 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407385 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/14 08:07:57 DEBUG : pacer: Reducing sleep to 98.748751ms
2022/03/14 08:07:57 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 08:07:57 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: doDeleteFolder(map[fi_id:121407385]) options=[]
2022/03/14 08:08:13 DEBUG : pacer: Reducing sleep to 74.061563ms
2022/03/14 08:08:13 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 08:08:13 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407059 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/14 08:08:18 DEBUG : pacer: Reducing sleep to 55.546172ms
2022/03/14 08:08:18 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
--- PASS: TestDirCreate (306.17s)
=== RUN   TestDirMkdir
    run.go:181: Remote "filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8'", Local "Local file system at /tmp/rclone1943342244", Modify Window "1s"
2022/03/14 08:08:18 INFO  : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': poll-interval is not supported by this remote
2022/03/14 08:08:18 NOTICE: filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2022/03/14 08:08:18 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407059 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/14 08:08:18 DEBUG : pacer: Reducing sleep to 41.659629ms
2022/03/14 08:08:18 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 08:08:18 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: doCreateNewFolder(map[fi_name:dir fi_pid:121407059]) options=[]
2022/03/14 08:08:22 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 1s to wait for "error_background" error to clear
2022/03/14 08:08:23 DEBUG : pacer: low level retry 1/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/14 08:08:23 DEBUG : pacer: Rate limited, increasing sleep to 83.319258ms
2022/03/14 08:08:26 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 2s to wait for "error_background" error to clear
2022/03/14 08:08:28 DEBUG : pacer: low level retry 2/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/14 08:08:28 DEBUG : pacer: Rate limited, increasing sleep to 166.638516ms
2022/03/14 08:08:39 DEBUG : pacer: Reducing sleep to 124.978887ms
2022/03/14 08:08:39 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 08:08:39 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': 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:121407397 fi_size:14 responsetype:json]) options=[]
2022/03/14 08:08:40 DEBUG : pacer: Reducing sleep to 93.734165ms
2022/03/14 08:08:40 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 08:08:42 DEBUG : pacer: Reducing sleep to 70.300623ms
2022/03/14 08:08:42 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: doCompleteUpload(map[fi_size:14 remotetime:2001-02-03 04:05:06 uploadcode:caff00680a45e9df031b45cc9d6334c6]) options=[]
2022/03/14 08:08:48 DEBUG : pacer: Reducing sleep to 52.725467ms
2022/03/14 08:08:48 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 08:08:48 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407059 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/14 08:09:00 DEBUG : pacer: Reducing sleep to 39.5441ms
2022/03/14 08:09:00 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 08:09:00 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407397 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/14 08:09:11 DEBUG : pacer: Reducing sleep to 29.658075ms
2022/03/14 08:09:11 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 08:09:11 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407059 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/14 08:09:12 DEBUG : pacer: Reducing sleep to 22.243556ms
2022/03/14 08:09:12 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 08:09:12 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407397 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/14 08:09:12 DEBUG : pacer: Reducing sleep to 20ms
2022/03/14 08:09:12 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 08:09:12 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407397 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/14 08:09:13 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 08:09:13 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: doCreateNewFolder(map[fi_name:sub fi_pid:121407397]) options=[]
2022/03/14 08:09:38 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 08:09:38 DEBUG : dir: Added virtual directory entry vAddDir: "sub"
2022/03/14 08:09:38 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407401 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/14 08:09:47 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 08:09:47 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407059 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/14 08:09:59 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 08:09:59 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407397 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/14 08:10:19 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 08:10:19 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407401 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/14 08:10:19 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 08:10:19 DEBUG : WaitForWriters: timeout=30s
2022/03/14 08:10:19 DEBUG : dir/sub: Looking for writers
2022/03/14 08:10:19 DEBUG : dir: Looking for writers
2022/03/14 08:10:19 DEBUG : file1: reading active writers
2022/03/14 08:10:19 DEBUG : sub: reading active writers
2022/03/14 08:10:19 DEBUG : : Looking for writers
2022/03/14 08:10:19 DEBUG : dir: reading active writers
2022/03/14 08:10:19 DEBUG : >WaitForWriters: 
2022/03/14 08:10:19 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407059 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/14 08:10:20 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 08:10:20 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407397 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/14 08:10:20 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 08:10:20 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: doDeleteFile(map[completedeletion:n fi_id:121407399]) options=[]
2022/03/14 08:11:09 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 08:11:09 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407401 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/14 08:11:10 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 08:11:10 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407401 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/14 08:11:11 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 08:11:11 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: doDeleteFolder(map[fi_id:121407401]) options=[]
2022/03/14 08:11:33 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 08:11:33 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407397 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/14 08:11:37 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 08:11:37 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: doDeleteFolder(map[fi_id:121407397]) options=[]
2022/03/14 08:11:41 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 1s to wait for "error_background" error to clear
2022/03/14 08:11:42 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/14 08:11:42 DEBUG : pacer: Rate limited, increasing sleep to 40ms
2022/03/14 08:11:46 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 2s to wait for "error_background" error to clear
2022/03/14 08:11:48 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/14 08:11:48 DEBUG : pacer: Rate limited, increasing sleep to 80ms
2022/03/14 08:11:50 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 4s to wait for "error_background" error to clear
2022/03/14 08:11:54 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/14 08:11:54 DEBUG : pacer: Rate limited, increasing sleep to 160ms
2022/03/14 08:11:54 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 8s to wait for "error_background" error to clear
2022/03/14 08:12:02 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/14 08:12:02 DEBUG : pacer: Rate limited, increasing sleep to 320ms
2022/03/14 08:12:17 DEBUG : pacer: Reducing sleep to 240ms
2022/03/14 08:12:17 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 08:12:17 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407059 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/14 08:12:21 DEBUG : pacer: Reducing sleep to 180ms
2022/03/14 08:12:21 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
--- PASS: TestDirMkdir (243.59s)
=== RUN   TestDirMkdirSub
    run.go:181: Remote "filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8'", Local "Local file system at /tmp/rclone1943342244", Modify Window "1s"
2022/03/14 08:12:21 INFO  : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': poll-interval is not supported by this remote
2022/03/14 08:12:21 NOTICE: filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2022/03/14 08:12:21 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407059 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/14 08:12:22 DEBUG : pacer: Reducing sleep to 135ms
2022/03/14 08:12:22 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 08:12:22 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: doCreateNewFolder(map[fi_name:dir fi_pid:121407059]) options=[]
2022/03/14 08:12:25 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 1s to wait for "error_background" error to clear
2022/03/14 08:12:26 DEBUG : pacer: low level retry 1/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/14 08:12:26 DEBUG : pacer: Rate limited, increasing sleep to 270ms
2022/03/14 08:12:29 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 2s to wait for "error_background" error to clear
2022/03/14 08:12:31 DEBUG : pacer: low level retry 2/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/14 08:12:31 DEBUG : pacer: Rate limited, increasing sleep to 540ms
2022/03/14 08:12:33 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 4s to wait for "error_background" error to clear
2022/03/14 08:12:37 DEBUG : pacer: low level retry 3/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/14 08:12:37 DEBUG : pacer: Rate limited, increasing sleep to 1.08s
2022/03/14 08:12:41 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 8s to wait for "error_background" error to clear
2022/03/14 08:12:49 DEBUG : pacer: low level retry 4/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/14 08:12:49 DEBUG : pacer: Rate limited, increasing sleep to 2.16s
2022/03/14 08:12:50 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': Sleeping for 16s to wait for "error_background" error to clear
2022/03/14 08:13:06 DEBUG : pacer: low level retry 5/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/14 08:13:06 DEBUG : pacer: Rate limited, increasing sleep to 4.32s
2022/03/14 08:13:29 DEBUG : pacer: Reducing sleep to 3.24s
2022/03/14 08:13:29 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 08:13:29 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': 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:121407408 fi_size:14 responsetype:json]) options=[]
2022/03/14 08:13:34 DEBUG : pacer: Reducing sleep to 2.43s
2022/03/14 08:13:34 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 08:13:35 DEBUG : pacer: Reducing sleep to 1.8225s
2022/03/14 08:13:35 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: doCompleteUpload(map[fi_size:14 remotetime:2001-02-03 04:05:06 uploadcode:c1d0ab99bb7d277e33af4b6d95832fdc]) options=[]
2022/03/14 08:13:42 DEBUG : pacer: Reducing sleep to 1.366875s
2022/03/14 08:13:42 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 08:13:42 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407059 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/14 08:13:51 DEBUG : pacer: Reducing sleep to 1.02515625s
2022/03/14 08:13:51 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': >rpc: result=Success (ok), err=<nil>
2022/03/14 08:13:51 DEBUG : filefabric root 'rclone-test-vasoxuh7tigalok4siqitah8': rpc: getFolderContents(map[count:1000 fi_pid:121407408 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
panic: test timed out after 2h0m0s

goroutine 3699 [running]:
testing.(*M).startAlarm.func1()
	/usr/local/go/src/testing/testing.go:1788 +0x8e
created by time.goFunc
	/usr/local/go/src/time/sleep.go:180 +0x31

goroutine 1 [chan receive, 2 minutes]:
testing.(*T).Run(0xc00050ab60, {0x1972486, 0x46d533}, 0x1a27c08)
	/usr/local/go/src/testing/testing.go:1307 +0x375
testing.runTests.func1(0xc0006468a0)
	/usr/local/go/src/testing/testing.go:1598 +0x6e
testing.tRunner(0xc00050ab60, 0xc000a07ca0)
	/usr/local/go/src/testing/testing.go:1259 +0x102
testing.runTests(0xc00053c000, {0x2a0d7c0, 0x4a, 0x4a}, {0xee88c0, 0xc000235a28, 0x2a1de80})
	/usr/local/go/src/testing/testing.go:1596 +0x43f
testing.(*M).Run(0xc00053c000)
	/usr/local/go/src/testing/testing.go:1504 +0x51d
github.com/rclone/rclone/fstest.TestMain(0xc0000001a0)
	/home/rclone/go/src/github.com/rclone/rclone/fstest/run.go:70 +0x9e
github.com/rclone/rclone/vfs.TestMain(...)
	/home/rclone/go/src/github.com/rclone/rclone/vfs/vfs_test.go:37
main.main()
	_testmain.go:193 +0x166

goroutine 18 [select]:
go.opencensus.io/stats/view.(*worker).start(0xc00013c780)
	/home/rclone/go/pkg/mod/go.opencensus.io@v0.23.0/stats/view/worker.go:276 +0xb9
created by go.opencensus.io/stats/view.init.0
	/home/rclone/go/pkg/mod/go.opencensus.io@v0.23.0/stats/view/worker.go:34 +0x92

goroutine 3601 [semacquire]:
sync.runtime_Semacquire(0xc00079d860)
	/usr/local/go/src/runtime/sema.go:56 +0x25
sync.(*WaitGroup).Wait(0x1d31da8)
	/usr/local/go/src/sync/waitgroup.go:130 +0x71
github.com/rclone/rclone/fs/walk.walk({0x1d31da8, 0xc000040058}, {0x1d62bb8, 0xc00023a800}, {0x0, 0x0}, 0x1, 0xffffffffffffffff, 0xc000652100, 0x1a279f8)
	/home/rclone/go/src/github.com/rclone/rclone/fs/walk/walk.go:453 +0x3fb
github.com/rclone/rclone/fs/walk.walkListDirSorted(...)
	/home/rclone/go/src/github.com/rclone/rclone/fs/walk/walk.go:349
github.com/rclone/rclone/fs/walk.Walk({0x1d31da8, 0xc000040058}, {0x1d62bb8, 0xc00023a800}, {0x0, 0x0}, 0x1, 0xffffffffffffffff, 0x76223e)
	/home/rclone/go/src/github.com/rclone/rclone/fs/walk/walk.go:75 +0x285
github.com/rclone/rclone/fs/walk.listRwalk({0x1d31da8, 0xc000040058}, {0x1d62bb8, 0xc00023a800}, {0x0, 0x0}, 0x0, 0xc00066e401, 0x3, 0xc000642198)
	/home/rclone/go/src/github.com/rclone/rclone/fs/walk/walk.go:169 +0x115
github.com/rclone/rclone/fs/walk.ListR({0x1d31da8, 0xc000040058}, {0x1d62bb8, 0xc00023a800}, {0x0, 0x0}, 0x1, 0xffffffffffffffff, 0x3, 0xc000642198)
	/home/rclone/go/src/github.com/rclone/rclone/fs/walk/walk.go:159 +0x230
github.com/rclone/rclone/fs/walk.GetAll({0x1d31da8, 0xc000040058}, {0x1d62bb8, 0xc00023a800}, {0x0, 0x0}, 0x0, 0xe)
	/home/rclone/go/src/github.com/rclone/rclone/fs/walk/walk.go:620 +0x112
github.com/rclone/rclone/fstest.CheckListingWithRoot(0xc0006f49c0, {0x1d62bb8, 0xc00023a800}, {0x0, 0x0}, {0xc00053aac0, 0x19681b5, 0x1}, {0x0, 0x0, ...}, ...)
	/home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:281 +0x2a5
github.com/rclone/rclone/fstest.CheckListingWithPrecision(...)
	/home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:339
github.com/rclone/rclone/fstest.CheckItemsWithPrecision(...)
	/home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:351
github.com/rclone/rclone/fstest.(*Run).CheckRemoteItems(...)
	/home/rclone/go/src/github.com/rclone/rclone/fstest/run.go:342
github.com/rclone/rclone/vfs.dirCreate(0x1e40921)
	/home/rclone/go/src/github.com/rclone/rclone/vfs/dir_test.go:22 +0x28a
github.com/rclone/rclone/vfs.TestDirMkdirSub(0x1)
	/home/rclone/go/src/github.com/rclone/rclone/vfs/dir_test.go:413 +0x7a
testing.tRunner(0xc0006f49c0, 0x1a27c08)
	/usr/local/go/src/testing/testing.go:1259 +0x102
created by testing.(*T).Run
	/usr/local/go/src/testing/testing.go:1306 +0x35a

goroutine 3721 [IO wait]:
internal/poll.runtime_pollWait(0x7f6ce8cdee48, 0x72)
	/usr/local/go/src/runtime/netpoll.go:234 +0x89
internal/poll.(*pollDesc).wait(0xc0000f6c80, 0xc0005dea00, 0x0)
	/usr/local/go/src/internal/poll/fd_poll_runtime.go:84 +0x32
internal/poll.(*pollDesc).waitRead(...)
	/usr/local/go/src/internal/poll/fd_poll_runtime.go:89
internal/poll.(*FD).Read(0xc0000f6c80, {0xc0005dea00, 0x1481, 0x1481})
	/usr/local/go/src/internal/poll/fd_unix.go:167 +0x25a
net.(*netFD).Read(0xc0000f6c80, {0xc0005dea00, 0x4fe658, 0x61})
	/usr/local/go/src/net/fd_posix.go:56 +0x29
net.(*conn).Read(0xc000207450, {0xc0005dea00, 0x684265, 0xc00082d500})
	/usr/local/go/src/net/net.go:183 +0x45
github.com/rclone/rclone/fs/fshttp.(*timeoutConn).Read(0xc000954738, {0xc0005dea00, 0xc00008b8c0, 0x100000000000000})
	/home/rclone/go/src/github.com/rclone/rclone/fs/fshttp/dialer.go:104 +0x32
crypto/tls.(*atLeastReader).Read(0xc000954990, {0xc0005dea00, 0x0, 0x40ba4d})
	/usr/local/go/src/crypto/tls/conn.go:777 +0x3d
bytes.(*Buffer).ReadFrom(0xc00082d778, {0x1cf7580, 0xc000954990})
	/usr/local/go/src/bytes/buffer.go:204 +0x98
crypto/tls.(*Conn).readFromUntil(0xc00082d500, {0x7f6ce83d6540, 0xc000954738}, 0x10100c0002ab908)
	/usr/local/go/src/crypto/tls/conn.go:799 +0xe5
crypto/tls.(*Conn).readRecordOrCCS(0xc00082d500, 0x0)
	/usr/local/go/src/crypto/tls/conn.go:606 +0x112
crypto/tls.(*Conn).readRecord(...)
	/usr/local/go/src/crypto/tls/conn.go:574
crypto/tls.(*Conn).Read(0xc00082d500, {0xc0004ec000, 0x1000, 0x101000000203000})
	/usr/local/go/src/crypto/tls/conn.go:1277 +0x16f
net/http.(*persistConn).Read(0xc0004f8c60, {0xc0004ec000, 0x406f1d, 0x60})
	/usr/local/go/src/net/http/transport.go:1926 +0x4e
bufio.(*Reader).fill(0xc0009786c0)
	/usr/local/go/src/bufio/bufio.go:101 +0x103
bufio.(*Reader).Peek(0xc0009786c0, 0x1)
	/usr/local/go/src/bufio/bufio.go:139 +0x5d
net/http.(*persistConn).readLoop(0xc0004f8c60)
	/usr/local/go/src/net/http/transport.go:2087 +0x1ac
created by net/http.(*Transport).dialConn
	/usr/local/go/src/net/http/transport.go:1747 +0x1e05

goroutine 3645 [select]:
github.com/rclone/rclone/fs/walk.walk.func2()
	/home/rclone/go/src/github.com/rclone/rclone/fs/walk/walk.go:398 +0x18a
created by github.com/rclone/rclone/fs/walk.walk
	/home/rclone/go/src/github.com/rclone/rclone/fs/walk/walk.go:395 +0x1a6

goroutine 70 [chan receive, 120 minutes]:
github.com/rclone/rclone/lib/atexit.Register.func1.1()
	/home/rclone/go/src/github.com/rclone/rclone/lib/atexit/atexit.go:45 +0x2f
created by github.com/rclone/rclone/lib/atexit.Register.func1
	/home/rclone/go/src/github.com/rclone/rclone/lib/atexit/atexit.go:44 +0x6d

goroutine 46 [syscall, 120 minutes]:
os/signal.signal_recv()
	/usr/local/go/src/runtime/sigqueue.go:169 +0x98
os/signal.loop()
	/usr/local/go/src/os/signal/signal_unix.go:24 +0x19
created by os/signal.Notify.func1.1
	/usr/local/go/src/os/signal/signal.go:151 +0x2c

goroutine 3646 [select]:
github.com/rclone/rclone/fs/walk.walk.func2()
	/home/rclone/go/src/github.com/rclone/rclone/fs/walk/walk.go:398 +0x18a
created by github.com/rclone/rclone/fs/walk.walk
	/home/rclone/go/src/github.com/rclone/rclone/fs/walk/walk.go:395 +0x1a6

goroutine 3644 [select]:
github.com/rclone/rclone/fs/walk.walk.func2()
	/home/rclone/go/src/github.com/rclone/rclone/fs/walk/walk.go:398 +0x18a
created by github.com/rclone/rclone/fs/walk.walk
	/home/rclone/go/src/github.com/rclone/rclone/fs/walk/walk.go:395 +0x1a6

goroutine 3648 [select]:
github.com/rclone/rclone/fs/walk.walk.func2()
	/home/rclone/go/src/github.com/rclone/rclone/fs/walk/walk.go:398 +0x18a
created by github.com/rclone/rclone/fs/walk.walk
	/home/rclone/go/src/github.com/rclone/rclone/fs/walk/walk.go:395 +0x1a6

goroutine 3643 [select]:
github.com/rclone/rclone/fs/walk.walk.func2()
	/home/rclone/go/src/github.com/rclone/rclone/fs/walk/walk.go:398 +0x18a
created by github.com/rclone/rclone/fs/walk.walk
	/home/rclone/go/src/github.com/rclone/rclone/fs/walk/walk.go:395 +0x1a6

goroutine 3722 [select]:
net/http.(*persistConn).writeLoop(0xc0004f8c60)
	/usr/local/go/src/net/http/transport.go:2386 +0xfb
created by net/http.(*Transport).dialConn
	/usr/local/go/src/net/http/transport.go:1748 +0x1e65

goroutine 3647 [select]:
github.com/rclone/rclone/fs/walk.walk.func2()
	/home/rclone/go/src/github.com/rclone/rclone/fs/walk/walk.go:398 +0x18a
created by github.com/rclone/rclone/fs/walk.walk
	/home/rclone/go/src/github.com/rclone/rclone/fs/walk/walk.go:395 +0x1a6

goroutine 3698 [select]:
net/http.(*persistConn).roundTrip(0xc0004f8c60, 0xc00063e700)
	/usr/local/go/src/net/http/transport.go:2614 +0x97d
net/http.(*Transport).roundTrip(0xc0002bc500, 0xc000555200)
	/usr/local/go/src/net/http/transport.go:594 +0x7d1
net/http.(*Transport).RoundTrip(...)
	/usr/local/go/src/net/http/roundtrip.go:18
github.com/rclone/rclone/fs/fshttp.(*Transport).RoundTrip(0xc0004fa320, 0xc000555200)
	/home/rclone/go/src/github.com/rclone/rclone/fs/fshttp/http.go:274 +0x4c8
net/http.send(0xc000555200, {0x1cfa860, 0xc0004fa320}, {0x1921180, 0x1, 0x0})
	/usr/local/go/src/net/http/client.go:252 +0x5d8
net/http.(*Client).send(0xc0004f56e0, 0xc000555200, {0xc000877740, 0x2f, 0x0})
	/usr/local/go/src/net/http/client.go:176 +0x9b
net/http.(*Client).do(0xc0004f56e0, 0xc000555200)
	/usr/local/go/src/net/http/client.go:725 +0x908
net/http.(*Client).Do(...)
	/usr/local/go/src/net/http/client.go:593
github.com/rclone/rclone/lib/rest.(*Client).Call(0xc0004fa370, {0x1d31da8, 0xc000040058}, 0xc0004f8b40)
	/home/rclone/go/src/github.com/rclone/rclone/lib/rest/rest.go:288 +0xc45
github.com/rclone/rclone/lib/rest.(*Client).callCodec(0x2989b40, {0x1d31da8, 0xc000040058}, 0xc0004fe040, {0x0, 0x0}, {0x16ea520, 0xc000274540}, 0xc0004fe040, 0x1a27ba8, ...)
	/home/rclone/go/src/github.com/rclone/rclone/lib/rest/rest.go:485 +0x465
github.com/rclone/rclone/lib/rest.(*Client).CallJSON(...)
	/home/rclone/go/src/github.com/rclone/rclone/lib/rest/rest.go:428
github.com/rclone/rclone/backend/filefabric.(*Fs).rpc.func1()
	/home/rclone/go/src/github.com/rclone/rclone/backend/filefabric/filefabric.go:411 +0x17b
github.com/rclone/rclone/fs.pacerInvoker(0xc0004f6480, 0xc000623888, 0x100000000452c49)
	/home/rclone/go/src/github.com/rclone/rclone/fs/pacer.go:88 +0x38
github.com/rclone/rclone/lib/pacer.(*Pacer).call(0xc0004f6480, 0xc0006238d0, 0xa)
	/home/rclone/go/src/github.com/rclone/rclone/lib/pacer/pacer.go:197 +0x85
github.com/rclone/rclone/lib/pacer.(*Pacer).Call(0xc0004f6480, 0xc0008776e0)
	/home/rclone/go/src/github.com/rclone/rclone/lib/pacer/pacer.go:216 +0x90
github.com/rclone/rclone/backend/filefabric.(*Fs).rpc(0xc00023a800, {0x1d31da8, 0xc000040058}, {0x1977099, 0x0}, 0xc000877650, {0x1d1b888, 0xc000274540}, {0x0, 0x0, ...})
	/home/rclone/go/src/github.com/rclone/rclone/backend/filefabric/filefabric.go:407 +0x90b
github.com/rclone/rclone/backend/filefabric.(*Fs).listAll(0xc00023a800, {0x1d31da8, 0xc000040058}, {0xc0009942b0, 0x9}, 0x0, 0x0, 0xc000623d58)
	/home/rclone/go/src/github.com/rclone/rclone/backend/filefabric/filefabric.go:596 +0x270
github.com/rclone/rclone/backend/filefabric.(*Fs).List(0xc00023a800, {0x1d31da8, 0xc000040058}, {0xc0002e8b3c, 0x3})
	/home/rclone/go/src/github.com/rclone/rclone/backend/filefabric/filefabric.go:652 +0x12c
github.com/rclone/rclone/fs/list.DirSorted({0x1d31da8, 0xc000040058}, {0x1d62bb8, 0xc00023a800}, 0x1, {0xc0002e8b3c, 0x3})
	/home/rclone/go/src/github.com/rclone/rclone/fs/list/list.go:24 +0x79
github.com/rclone/rclone/fs/walk.walk.func2()
	/home/rclone/go/src/github.com/rclone/rclone/fs/walk/walk.go:403 +0x205
created by github.com/rclone/rclone/fs/walk.walk
	/home/rclone/go/src/github.com/rclone/rclone/fs/walk/walk.go:395 +0x1a6

goroutine 3649 [select]:
github.com/rclone/rclone/fs/walk.walk.func2()
	/home/rclone/go/src/github.com/rclone/rclone/fs/walk/walk.go:398 +0x18a
created by github.com/rclone/rclone/fs/walk.walk
	/home/rclone/go/src/github.com/rclone/rclone/fs/walk/walk.go:395 +0x1a6
"./vfs.test -test.v -test.timeout 2h0m0s -remote TestFileFabric: -verbose" - Finished ERROR in 2h0m0.558142793s (try 1/5): exit status 2: Failed []