"./vfs.test -test.v -test.timeout 2h0m0s -remote TestFileFabric: -verbose" - Starting (try 1/5)
2022/03/03 05:44:39 DEBUG : Creating backend with remote "TestFileFabric:rclone-test-zoyijiw0zujumud5xuwoxas5"
2022/03/03 05:44:39 DEBUG : Using config file from "/home/rclone/.rclone.conf"
2022/03/03 05:44:39 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: checkPathExists(map[path:rclone-test-zoyijiw0zujumud5xuwoxas5 pid:120673762]) options=[]
2022/03/03 05:44:39 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 05:44:39 DEBUG : Creating backend with remote "/tmp/rclone2060667978"
=== RUN   TestDirHandleMethods
    run.go:181: Remote "filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5'", Local "Local file system at /tmp/rclone2060667978", Modify Window "1s"
2022/03/03 05:44:39 INFO  : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': poll-interval is not supported by this remote
2022/03/03 05:44:39 NOTICE: filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2022/03/03 05:44:39 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': 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/03 05:44:47 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 05:44:47 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doCreateNewFolder(map[fi_name:rclone-test-zoyijiw0zujumud5xuwoxas5 fi_pid:120673762]) options=[]
2022/03/03 05:45:03 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 05:45:03 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390288 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/03 05:45:12 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 05:45:12 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doCreateNewFolder(map[fi_name:dir fi_pid:121390288]) options=[]
2022/03/03 05:45:23 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 05:45:23 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': 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:121390290 fi_size:14 responsetype:json]) options=[]
2022/03/03 05:45:25 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 05:45:26 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doCompleteUpload(map[fi_size:14 remotetime:2001-02-03 04:05:06 uploadcode:056989ed16bc5d780469fe1527062fd1]) options=[]
2022/03/03 05:45:32 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 05:45:32 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390288 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/03 05:45:40 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 05:45:40 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390290 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/03 05:45:51 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 05:45:51 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390288 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/03 05:45:52 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 05:45:52 DEBUG : WaitForWriters: timeout=30s
2022/03/03 05:45:52 DEBUG : dir: Looking for writers
2022/03/03 05:45:52 DEBUG : : Looking for writers
2022/03/03 05:45:52 DEBUG : dir: reading active writers
2022/03/03 05:45:52 DEBUG : >WaitForWriters: 
2022/03/03 05:45:52 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390288 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/03 05:45:52 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 05:45:52 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390290 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/03 05:45:53 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 05:45:53 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doDeleteFile(map[completedeletion:n fi_id:121390291]) options=[]
2022/03/03 05:46:26 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 05:46:26 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390290 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/03 05:46:38 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 05:46:38 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doDeleteFolder(map[fi_id:121390290]) options=[]
2022/03/03 05:46:46 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 05:46:46 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390288 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/03 05:46:47 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
--- PASS: TestDirHandleMethods (128.13s)
=== RUN   TestDirHandleReaddir
    run.go:181: Remote "filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5'", Local "Local file system at /tmp/rclone2060667978", Modify Window "1s"
2022/03/03 05:46:47 INFO  : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': poll-interval is not supported by this remote
2022/03/03 05:46:47 NOTICE: filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2022/03/03 05:46:47 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390288 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/03 05:46:48 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 05:46:48 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doCreateNewFolder(map[fi_name:dir fi_pid:121390288]) options=[]
2022/03/03 05:46:48 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 1s to wait for "error_background" error to clear
2022/03/03 05:46:49 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/03 05:46:49 DEBUG : pacer: Rate limited, increasing sleep to 40ms
2022/03/03 05:46:50 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 2s to wait for "error_background" error to clear
2022/03/03 05:46:52 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/03 05:46:52 DEBUG : pacer: Rate limited, increasing sleep to 80ms
2022/03/03 05:46:54 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 4s to wait for "error_background" error to clear
2022/03/03 05:46:58 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/03 05:46:58 DEBUG : pacer: Rate limited, increasing sleep to 160ms
2022/03/03 05:46:58 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 8s to wait for "error_background" error to clear
2022/03/03 05:47:06 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/03 05:47:06 DEBUG : pacer: Rate limited, increasing sleep to 320ms
2022/03/03 05:47:07 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 16s to wait for "error_background" error to clear
2022/03/03 05:47:23 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/03 05:47:23 DEBUG : pacer: Rate limited, increasing sleep to 640ms
2022/03/03 05:47:35 DEBUG : pacer: Reducing sleep to 480ms
2022/03/03 05:47:35 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 05:47:35 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': 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:121390294 fi_size:14 responsetype:json]) options=[]
2022/03/03 05:47:37 DEBUG : pacer: Reducing sleep to 360ms
2022/03/03 05:47:37 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 05:47:38 DEBUG : pacer: Reducing sleep to 270ms
2022/03/03 05:47:38 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doCompleteUpload(map[fi_size:14 remotetime:2001-02-03 04:05:06 uploadcode:e230737f013a4fd5fb80a3f76726110c]) options=[]
2022/03/03 05:47:44 DEBUG : pacer: Reducing sleep to 202.5ms
2022/03/03 05:47:44 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 05:47:44 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': 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:121390294 fi_size:15 responsetype:json]) options=[]
2022/03/03 05:47:45 DEBUG : pacer: Reducing sleep to 151.875ms
2022/03/03 05:47:45 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 05:47:47 DEBUG : pacer: Reducing sleep to 113.90625ms
2022/03/03 05:47:47 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doCompleteUpload(map[fi_size:15 remotetime:2011-12-25 12:59:59 uploadcode:89e7d35166f44fa3ad2eea1ea29b728b]) options=[]
2022/03/03 05:47:51 DEBUG : pacer: Reducing sleep to 85.429687ms
2022/03/03 05:47:51 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 05:47:51 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390294 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/03 05:48:00 DEBUG : pacer: Reducing sleep to 64.072265ms
2022/03/03 05:48:00 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 05:48:00 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doCreateNewFolder(map[fi_name:subdir fi_pid:121390294]) options=[]
2022/03/03 05:48:13 DEBUG : pacer: Reducing sleep to 48.054198ms
2022/03/03 05:48:13 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 05:48:13 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': 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:121390297 fi_size:16 responsetype:json]) options=[]
2022/03/03 05:48:14 DEBUG : pacer: Reducing sleep to 36.040648ms
2022/03/03 05:48:14 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 05:48:16 DEBUG : pacer: Reducing sleep to 27.030486ms
2022/03/03 05:48:16 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doCompleteUpload(map[fi_size:16 remotetime:2011-12-30 12:59:59 uploadcode:1962e0c0e78c29bad61f2952ea3a58a4]) options=[]
2022/03/03 05:48:21 DEBUG : pacer: Reducing sleep to 20.272864ms
2022/03/03 05:48:21 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 05:48:21 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390288 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/03 05:48:29 DEBUG : pacer: Reducing sleep to 20ms
2022/03/03 05:48:29 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 05:48:29 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390294 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/03 05:48:37 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 05:48:37 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390297 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/03 05:48:46 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 05:48:46 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390288 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/03 05:48:47 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 05:48:47 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390294 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/03 05:48:48 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 05:48:48 DEBUG : WaitForWriters: timeout=30s
2022/03/03 05:48:48 DEBUG : dir/subdir: Looking for writers
2022/03/03 05:48:48 DEBUG : dir: Looking for writers
2022/03/03 05:48:48 DEBUG : file1: reading active writers
2022/03/03 05:48:48 DEBUG : file2: reading active writers
2022/03/03 05:48:48 DEBUG : subdir: reading active writers
2022/03/03 05:48:48 DEBUG : : Looking for writers
2022/03/03 05:48:48 DEBUG : dir: reading active writers
2022/03/03 05:48:48 DEBUG : >WaitForWriters: 
2022/03/03 05:48:48 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390288 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/03 05:48:48 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 05:48:48 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390294 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/03 05:48:49 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 05:48:49 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doDeleteFile(map[completedeletion:n fi_id:121390295]) options=[]
2022/03/03 05:49:27 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 05:49:27 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doDeleteFile(map[completedeletion:n fi_id:121390296]) options=[]
2022/03/03 05:49:59 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 05:49:59 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390297 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/03 05:49:59 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 05:49:59 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doDeleteFile(map[completedeletion:n fi_id:121390299]) options=[]
2022/03/03 05:50:44 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 05:50:44 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390297 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/03 05:50:59 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 05:50:59 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doDeleteFolder(map[fi_id:121390297]) options=[]
2022/03/03 05:51:14 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 05:51:14 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390294 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/03 05:51:15 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 05:51:15 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doDeleteFolder(map[fi_id:121390294]) options=[]
2022/03/03 05:51:15 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 1s to wait for "error_background" error to clear
2022/03/03 05:51:16 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/03 05:51:16 DEBUG : pacer: Rate limited, increasing sleep to 40ms
2022/03/03 05:51:17 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 2s to wait for "error_background" error to clear
2022/03/03 05:51:19 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/03 05:51:19 DEBUG : pacer: Rate limited, increasing sleep to 80ms
2022/03/03 05:51:19 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 4s to wait for "error_background" error to clear
2022/03/03 05:51:23 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/03 05:51:23 DEBUG : pacer: Rate limited, increasing sleep to 160ms
2022/03/03 05:51:24 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 8s to wait for "error_background" error to clear
2022/03/03 05:51:32 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/03 05:51:32 DEBUG : pacer: Rate limited, increasing sleep to 320ms
2022/03/03 05:51:33 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 16s to wait for "error_background" error to clear
2022/03/03 05:51:49 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/03 05:51:49 DEBUG : pacer: Rate limited, increasing sleep to 640ms
2022/03/03 05:51:50 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 32s to wait for "error_background" error to clear
2022/03/03 05:52:22 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/03 05:52:22 DEBUG : pacer: Rate limited, increasing sleep to 1.28s
2022/03/03 05:52:34 DEBUG : pacer: Reducing sleep to 960ms
2022/03/03 05:52:34 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 05:52:34 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390288 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/03 05:52:39 DEBUG : pacer: Reducing sleep to 720ms
2022/03/03 05:52:39 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
--- PASS: TestDirHandleReaddir (351.52s)
=== RUN   TestDirHandleReaddirnames
    run.go:181: Remote "filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5'", Local "Local file system at /tmp/rclone2060667978", Modify Window "1s"
2022/03/03 05:52:39 INFO  : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': poll-interval is not supported by this remote
2022/03/03 05:52:39 NOTICE: filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2022/03/03 05:52:39 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390288 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/03 05:52:39 DEBUG : pacer: Reducing sleep to 540ms
2022/03/03 05:52:39 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 05:52:39 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doCreateNewFolder(map[fi_name:dir fi_pid:121390288]) options=[]
2022/03/03 05:52:43 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 1s to wait for "error_background" error to clear
2022/03/03 05:52:44 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/03 05:52:44 DEBUG : pacer: Rate limited, increasing sleep to 1.08s
2022/03/03 05:52:47 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 2s to wait for "error_background" error to clear
2022/03/03 05:52:49 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/03 05:52:49 DEBUG : pacer: Rate limited, increasing sleep to 2.16s
2022/03/03 05:52:50 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 4s to wait for "error_background" error to clear
2022/03/03 05:52:54 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/03 05:52:54 DEBUG : pacer: Rate limited, increasing sleep to 4.32s
2022/03/03 05:53:06 DEBUG : pacer: Reducing sleep to 3.24s
2022/03/03 05:53:06 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 05:53:06 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': 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:121390313 fi_size:14 responsetype:json]) options=[]
2022/03/03 05:53:07 DEBUG : pacer: Reducing sleep to 2.43s
2022/03/03 05:53:07 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 05:53:11 DEBUG : pacer: Reducing sleep to 1.8225s
2022/03/03 05:53:11 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doCompleteUpload(map[fi_size:14 remotetime:2001-02-03 04:05:06 uploadcode:2fe09940f28e2475ec71dbc0ba91c0b7]) options=[]
2022/03/03 05:53:21 DEBUG : pacer: Reducing sleep to 1.366875s
2022/03/03 05:53:21 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 05:53:21 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390288 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/03 05:53:33 DEBUG : pacer: Reducing sleep to 1.02515625s
2022/03/03 05:53:33 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 05:53:33 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390313 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/03 05:53:44 DEBUG : pacer: Reducing sleep to 768.867187ms
2022/03/03 05:53:44 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 05:53:44 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390288 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/03 05:53:45 DEBUG : pacer: Reducing sleep to 576.65039ms
2022/03/03 05:53:45 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 05:53:45 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390313 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/03 05:53:46 DEBUG : pacer: Reducing sleep to 432.487792ms
2022/03/03 05:53:46 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 05:53:46 DEBUG : WaitForWriters: timeout=30s
2022/03/03 05:53:46 DEBUG : dir: Looking for writers
2022/03/03 05:53:46 DEBUG : file1: reading active writers
2022/03/03 05:53:46 DEBUG : : Looking for writers
2022/03/03 05:53:46 DEBUG : dir: reading active writers
2022/03/03 05:53:46 DEBUG : >WaitForWriters: 
2022/03/03 05:53:46 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390288 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/03 05:53:46 DEBUG : pacer: Reducing sleep to 324.365844ms
2022/03/03 05:53:46 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 05:53:46 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390313 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/03 05:53:47 DEBUG : pacer: Reducing sleep to 243.274383ms
2022/03/03 05:53:47 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 05:53:47 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doDeleteFile(map[completedeletion:n fi_id:121390314]) options=[]
2022/03/03 05:54:23 DEBUG : pacer: Reducing sleep to 182.455787ms
2022/03/03 05:54:23 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 05:54:23 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390313 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/03 05:54:38 DEBUG : pacer: Reducing sleep to 136.84184ms
2022/03/03 05:54:38 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 05:54:38 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doDeleteFolder(map[fi_id:121390313]) options=[]
2022/03/03 05:54:52 DEBUG : pacer: Reducing sleep to 102.63138ms
2022/03/03 05:54:52 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 05:54:52 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390288 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/03 05:54:56 DEBUG : pacer: Reducing sleep to 76.973535ms
2022/03/03 05:54:56 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
--- PASS: TestDirHandleReaddirnames (137.51s)
=== RUN   TestDirMethods
    run.go:181: Remote "filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5'", Local "Local file system at /tmp/rclone2060667978", Modify Window "1s"
2022/03/03 05:54:56 INFO  : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': poll-interval is not supported by this remote
2022/03/03 05:54:56 NOTICE: filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2022/03/03 05:54:56 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390288 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/03 05:54:57 DEBUG : pacer: Reducing sleep to 57.730151ms
2022/03/03 05:54:57 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 05:54:57 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doCreateNewFolder(map[fi_name:dir fi_pid:121390288]) options=[]
2022/03/03 05:55:00 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 1s to wait for "error_background" error to clear
2022/03/03 05:55:01 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/03 05:55:01 DEBUG : pacer: Rate limited, increasing sleep to 115.460302ms
2022/03/03 05:55:01 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 2s to wait for "error_background" error to clear
2022/03/03 05:55:03 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/03 05:55:03 DEBUG : pacer: Rate limited, increasing sleep to 230.920604ms
2022/03/03 05:55:16 DEBUG : pacer: Reducing sleep to 173.190453ms
2022/03/03 05:55:16 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 05:55:16 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': 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:121390319 fi_size:14 responsetype:json]) options=[]
2022/03/03 05:55:18 DEBUG : pacer: Reducing sleep to 129.892839ms
2022/03/03 05:55:18 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 05:55:19 DEBUG : pacer: Reducing sleep to 97.419629ms
2022/03/03 05:55:19 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doCompleteUpload(map[fi_size:14 remotetime:2001-02-03 04:05:06 uploadcode:823e182afd374ab2df5e91dac86dffcd]) options=[]
2022/03/03 05:55:28 DEBUG : pacer: Reducing sleep to 73.064721ms
2022/03/03 05:55:28 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 05:55:28 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390288 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/03 05:55:40 DEBUG : pacer: Reducing sleep to 54.79854ms
2022/03/03 05:55:40 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 05:55:40 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390319 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/03 05:55:56 DEBUG : pacer: Reducing sleep to 41.098905ms
2022/03/03 05:55:56 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 05:55:56 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390288 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/03 05:55:56 DEBUG : pacer: Reducing sleep to 30.824178ms
2022/03/03 05:55:56 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 05:55:56 DEBUG : WaitForWriters: timeout=30s
2022/03/03 05:55:56 DEBUG : dir: Looking for writers
2022/03/03 05:55:56 DEBUG : : Looking for writers
2022/03/03 05:55:56 DEBUG : dir: reading active writers
2022/03/03 05:55:56 DEBUG : >WaitForWriters: 
2022/03/03 05:55:56 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390288 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/03 05:55:57 DEBUG : pacer: Reducing sleep to 23.118133ms
2022/03/03 05:55:57 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 05:55:57 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390319 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/03 05:55:57 DEBUG : pacer: Reducing sleep to 20ms
2022/03/03 05:55:57 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 05:55:57 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doDeleteFile(map[completedeletion:n fi_id:121390321]) options=[]
2022/03/03 05:56:39 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 05:56:39 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390319 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/03 05:56:47 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 05:56:47 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doDeleteFolder(map[fi_id:121390319]) options=[]
2022/03/03 05:57:06 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 05:57:06 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390288 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/03 05:57:07 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
--- PASS: TestDirMethods (130.41s)
=== RUN   TestDirForgetAll
    run.go:181: Remote "filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5'", Local "Local file system at /tmp/rclone2060667978", Modify Window "1s"
2022/03/03 05:57:07 INFO  : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': poll-interval is not supported by this remote
2022/03/03 05:57:07 NOTICE: filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2022/03/03 05:57:07 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390288 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/03 05:57:07 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 05:57:07 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doCreateNewFolder(map[fi_name:dir fi_pid:121390288]) options=[]
2022/03/03 05:57:10 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 1s to wait for "error_background" error to clear
2022/03/03 05:57:11 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/03 05:57:11 DEBUG : pacer: Rate limited, increasing sleep to 40ms
2022/03/03 05:57:14 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 2s to wait for "error_background" error to clear
2022/03/03 05:57:16 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/03 05:57:16 DEBUG : pacer: Rate limited, increasing sleep to 80ms
2022/03/03 05:57:18 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 4s to wait for "error_background" error to clear
2022/03/03 05:57:22 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/03 05:57:22 DEBUG : pacer: Rate limited, increasing sleep to 160ms
2022/03/03 05:57:22 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 8s to wait for "error_background" error to clear
2022/03/03 05:57: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/03 05:57:30 DEBUG : pacer: Rate limited, increasing sleep to 320ms
2022/03/03 05:57:45 DEBUG : pacer: Reducing sleep to 240ms
2022/03/03 05:57:45 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 05:57:45 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': 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:121390326 fi_size:14 responsetype:json]) options=[]
2022/03/03 05:57:50 DEBUG : pacer: Reducing sleep to 180ms
2022/03/03 05:57:50 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 05:57:51 DEBUG : pacer: Reducing sleep to 135ms
2022/03/03 05:57:51 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doCompleteUpload(map[fi_size:14 remotetime:2001-02-03 04:05:06 uploadcode:5df255a777181a8c9c96ece5967ca47b]) options=[]
2022/03/03 05:58:04 DEBUG : pacer: Reducing sleep to 101.25ms
2022/03/03 05:58:04 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 05:58:04 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390288 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/03 05:58:15 DEBUG : pacer: Reducing sleep to 75.9375ms
2022/03/03 05:58:15 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 05:58:15 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390326 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/03 05:58:30 DEBUG : pacer: Reducing sleep to 56.953125ms
2022/03/03 05:58:30 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 05:58:30 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390288 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/03 05:58:31 DEBUG : pacer: Reducing sleep to 42.714843ms
2022/03/03 05:58:31 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 05:58:31 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390326 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/03 05:58:32 DEBUG : pacer: Reducing sleep to 32.036132ms
2022/03/03 05:58:32 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 05:58:32 DEBUG : dir: forgetting directory cache
2022/03/03 05:58:32 DEBUG : : forgetting directory cache
2022/03/03 05:58:32 DEBUG : dir: forgetting directory cache
2022/03/03 05:58:32 DEBUG : WaitForWriters: timeout=30s
2022/03/03 05:58:32 DEBUG : : Looking for writers
2022/03/03 05:58:32 DEBUG : >WaitForWriters: 
2022/03/03 05:58:32 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390288 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/03 05:58:32 DEBUG : pacer: Reducing sleep to 24.027099ms
2022/03/03 05:58:32 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 05:58:32 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390326 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/03 05:58:33 DEBUG : pacer: Reducing sleep to 20ms
2022/03/03 05:58:33 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 05:58:33 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doDeleteFile(map[completedeletion:n fi_id:121390327]) options=[]
2022/03/03 05:59:29 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 05:59:29 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390326 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/03 05:59:41 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 05:59:41 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doDeleteFolder(map[fi_id:121390326]) options=[]
2022/03/03 05:59:55 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 05:59:55 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390288 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/03 05:59:56 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
--- PASS: TestDirForgetAll (169.68s)
=== RUN   TestDirForgetPath
    run.go:181: Remote "filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5'", Local "Local file system at /tmp/rclone2060667978", Modify Window "1s"
2022/03/03 05:59:56 INFO  : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': poll-interval is not supported by this remote
2022/03/03 05:59:56 NOTICE: filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2022/03/03 05:59:56 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390288 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/03 05:59:57 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 05:59:57 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doCreateNewFolder(map[fi_name:dir fi_pid:121390288]) options=[]
2022/03/03 06:00:00 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 1s to wait for "error_background" error to clear
2022/03/03 06:00:01 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/03 06:00:01 DEBUG : pacer: Rate limited, increasing sleep to 40ms
2022/03/03 06:00:04 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 2s to wait for "error_background" error to clear
2022/03/03 06:00:06 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/03 06:00:06 DEBUG : pacer: Rate limited, increasing sleep to 80ms
2022/03/03 06:00:08 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 4s to wait for "error_background" error to clear
2022/03/03 06:00:12 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/03 06:00:12 DEBUG : pacer: Rate limited, increasing sleep to 160ms
2022/03/03 06:00:13 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 8s to wait for "error_background" error to clear
2022/03/03 06:00:21 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/03 06:00:21 DEBUG : pacer: Rate limited, increasing sleep to 320ms
2022/03/03 06:00:21 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 16s to wait for "error_background" error to clear
2022/03/03 06:00:37 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/03 06:00:37 DEBUG : pacer: Rate limited, increasing sleep to 640ms
2022/03/03 06:00:39 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 32s to wait for "error_background" error to clear
2022/03/03 06:01:11 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/03 06:01:11 DEBUG : pacer: Rate limited, increasing sleep to 1.28s
2022/03/03 06:01:12 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 1m4s to wait for "error_background" error to clear
2022/03/03 06:02:16 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/03 06:02:16 DEBUG : pacer: Rate limited, increasing sleep to 2.56s
2022/03/03 06:02:40 DEBUG : pacer: Reducing sleep to 1.92s
2022/03/03 06:02:40 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:02:40 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': 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:121390340 fi_size:14 responsetype:json]) options=[]
2022/03/03 06:02:41 DEBUG : pacer: Reducing sleep to 1.44s
2022/03/03 06:02:41 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:02:44 DEBUG : pacer: Reducing sleep to 1.08s
2022/03/03 06:02:44 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doCompleteUpload(map[fi_size:14 remotetime:2001-02-03 04:05:06 uploadcode:3df0ddc25205e12560ff1d33ce65d1f5]) options=[]
2022/03/03 06:02:53 DEBUG : pacer: Reducing sleep to 810ms
2022/03/03 06:02:53 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:02:53 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390288 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/03 06:03:04 DEBUG : pacer: Reducing sleep to 607.5ms
2022/03/03 06:03:04 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:03:04 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390340 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/03 06:03:16 DEBUG : pacer: Reducing sleep to 455.625ms
2022/03/03 06:03:16 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:03:16 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390288 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/03 06:03:17 DEBUG : pacer: Reducing sleep to 341.71875ms
2022/03/03 06:03:17 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:03:17 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390340 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/03 06:03:17 DEBUG : pacer: Reducing sleep to 256.289062ms
2022/03/03 06:03:17 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:03:17 DEBUG : : ForgetPath: relativePath="dir/notfound", type=1
2022/03/03 06:03:17 DEBUG : dir: invalidating directory cache
2022/03/03 06:03:17 DEBUG : : >ForgetPath: 
2022/03/03 06:03:17 DEBUG : : ForgetPath: relativePath="dir", type=0
2022/03/03 06:03:17 DEBUG : : invalidating directory cache
2022/03/03 06:03:17 DEBUG : dir: forgetting directory cache
2022/03/03 06:03:17 DEBUG : : >ForgetPath: 
2022/03/03 06:03:17 DEBUG : : ForgetPath: relativePath="not/in/cache", type=0
2022/03/03 06:03:17 DEBUG : : >ForgetPath: 
2022/03/03 06:03:17 DEBUG : WaitForWriters: timeout=30s
2022/03/03 06:03:17 DEBUG : dir: Looking for writers
2022/03/03 06:03:17 DEBUG : : Looking for writers
2022/03/03 06:03:17 DEBUG : dir: reading active writers
2022/03/03 06:03:17 DEBUG : >WaitForWriters: 
2022/03/03 06:03:17 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390288 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/03 06:03:18 DEBUG : pacer: Reducing sleep to 192.216796ms
2022/03/03 06:03:18 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:03:18 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390340 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/03 06:03:18 DEBUG : pacer: Reducing sleep to 144.162597ms
2022/03/03 06:03:18 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:03:18 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doDeleteFile(map[completedeletion:n fi_id:121390342]) options=[]
2022/03/03 06:04:28 DEBUG : pacer: Reducing sleep to 108.121947ms
2022/03/03 06:04:28 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:04:28 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390340 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/03 06:04:43 DEBUG : pacer: Reducing sleep to 81.09146ms
2022/03/03 06:04:43 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:04:43 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doDeleteFolder(map[fi_id:121390340]) options=[]
2022/03/03 06:04:58 DEBUG : pacer: Reducing sleep to 60.818595ms
2022/03/03 06:04:58 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:04:58 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390288 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/03 06:05:02 DEBUG : pacer: Reducing sleep to 45.613946ms
2022/03/03 06:05:02 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
--- PASS: TestDirForgetPath (305.63s)
=== RUN   TestDirWalk
    run.go:181: Remote "filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5'", Local "Local file system at /tmp/rclone2060667978", Modify Window "1s"
2022/03/03 06:05:02 INFO  : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': poll-interval is not supported by this remote
2022/03/03 06:05:02 NOTICE: filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2022/03/03 06:05:02 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390288 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/03 06:05:02 DEBUG : pacer: Reducing sleep to 34.210459ms
2022/03/03 06:05:02 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:05:02 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doCreateNewFolder(map[fi_name:dir fi_pid:121390288]) options=[]
2022/03/03 06:05:05 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 1s to wait for "error_background" error to clear
2022/03/03 06:05:06 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/03 06:05:06 DEBUG : pacer: Rate limited, increasing sleep to 68.420918ms
2022/03/03 06:05:09 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 2s to wait for "error_background" error to clear
2022/03/03 06:05:11 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/03 06:05:11 DEBUG : pacer: Rate limited, increasing sleep to 136.841836ms
2022/03/03 06:05:13 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 4s to wait for "error_background" error to clear
2022/03/03 06:05:17 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/03 06:05:17 DEBUG : pacer: Rate limited, increasing sleep to 273.683672ms
2022/03/03 06:05:21 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 8s to wait for "error_background" error to clear
2022/03/03 06:05:29 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/03 06:05:29 DEBUG : pacer: Rate limited, increasing sleep to 547.367344ms
2022/03/03 06:05:32 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 16s to wait for "error_background" error to clear
2022/03/03 06:05:48 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/03 06:05:48 DEBUG : pacer: Rate limited, increasing sleep to 1.094734688s
2022/03/03 06:05:51 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 32s to wait for "error_background" error to clear
2022/03/03 06:06:23 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/03 06:06:23 DEBUG : pacer: Rate limited, increasing sleep to 2.189469376s
2022/03/03 06:06:45 DEBUG : pacer: Reducing sleep to 1.642102032s
2022/03/03 06:06:45 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:06:45 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': 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:121390352 fi_size:14 responsetype:json]) options=[]
2022/03/03 06:06:46 DEBUG : pacer: Reducing sleep to 1.231576524s
2022/03/03 06:06:46 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:06:48 DEBUG : pacer: Reducing sleep to 923.682393ms
2022/03/03 06:06:48 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doCompleteUpload(map[fi_size:14 remotetime:2001-02-03 04:05:06 uploadcode:6c6ac13fa040698cd32f90d9861f774c]) options=[]
2022/03/03 06:06:55 DEBUG : pacer: Reducing sleep to 692.761794ms
2022/03/03 06:06:55 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:06:55 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390288 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/03 06:07:04 DEBUG : pacer: Reducing sleep to 519.571345ms
2022/03/03 06:07:04 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:07:04 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390352 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/03 06:07:12 DEBUG : pacer: Reducing sleep to 389.678508ms
2022/03/03 06:07:12 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:07:12 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390288 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/03 06:07:13 DEBUG : pacer: Reducing sleep to 292.258881ms
2022/03/03 06:07:13 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:07:13 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390288 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/03 06:07:14 DEBUG : pacer: Reducing sleep to 219.19416ms
2022/03/03 06:07:14 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:07:14 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doCreateNewFolder(map[fi_name:fil fi_pid:121390288]) options=[]
2022/03/03 06:07:32 DEBUG : pacer: Reducing sleep to 164.39562ms
2022/03/03 06:07:32 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:07:32 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390359 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/03 06:07:44 DEBUG : pacer: Reducing sleep to 123.296715ms
2022/03/03 06:07:44 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:07:44 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doCreateNewFolder(map[fi_name:a fi_pid:121390359]) options=[]
2022/03/03 06:08:00 DEBUG : pacer: Reducing sleep to 92.472536ms
2022/03/03 06:08:00 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:08:00 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390360 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/03 06:08:13 DEBUG : pacer: Reducing sleep to 69.354402ms
2022/03/03 06:08:13 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:08:13 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doCreateNewFolder(map[fi_name:b fi_pid:121390360]) options=[]
2022/03/03 06:08:32 DEBUG : pacer: Reducing sleep to 52.015801ms
2022/03/03 06:08:32 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:08:32 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': 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:121390363 fi_size:15 responsetype:json]) options=[]
2022/03/03 06:08:37 DEBUG : pacer: Reducing sleep to 39.01185ms
2022/03/03 06:08:37 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:08:38 DEBUG : pacer: Reducing sleep to 29.258887ms
2022/03/03 06:08:38 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doCompleteUpload(map[fi_size:15 remotetime:2001-02-03 04:05:06 uploadcode:771a830e6785dd7551d461408f0fd745]) options=[]
2022/03/03 06:08:48 DEBUG : pacer: Reducing sleep to 21.944165ms
2022/03/03 06:08:48 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:08:48 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390288 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/03 06:09:11 DEBUG : pacer: Reducing sleep to 20ms
2022/03/03 06:09:11 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:09:11 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390359 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/03 06:09:11 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390352 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/03 06:09:22 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:09:22 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:09:22 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390360 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/03 06:09:37 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:09:37 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390363 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/03 06:09:52 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:09:52 DEBUG : : forgetting directory cache
2022/03/03 06:09:52 DEBUG : dir: forgetting directory cache
2022/03/03 06:09:52 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390288 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/03 06:09:53 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:09:53 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390359 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/03 06:09:54 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:09:54 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390360 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/03 06:09:54 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:09:54 DEBUG : WaitForWriters: timeout=30s
2022/03/03 06:09:54 DEBUG : dir: Looking for writers
2022/03/03 06:09:54 DEBUG : fil/a/b: Looking for writers
2022/03/03 06:09:54 DEBUG : fil/a: Looking for writers
2022/03/03 06:09:54 DEBUG : b: reading active writers
2022/03/03 06:09:54 DEBUG : fil: Looking for writers
2022/03/03 06:09:54 DEBUG : a: reading active writers
2022/03/03 06:09:54 DEBUG : : Looking for writers
2022/03/03 06:09:54 DEBUG : dir: reading active writers
2022/03/03 06:09:54 DEBUG : fil: reading active writers
2022/03/03 06:09:54 DEBUG : >WaitForWriters: 
2022/03/03 06:09:54 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390288 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/03 06:09:55 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:09:55 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390359 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/03 06:09:55 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390352 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/03 06:09:55 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:09:55 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390360 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/03 06:09:55 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:09:55 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doDeleteFile(map[completedeletion:n fi_id:121390356]) options=[]
2022/03/03 06:09:56 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:10:32 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:10:32 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390363 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/03 06:10:32 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:10:32 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doDeleteFile(map[completedeletion:n fi_id:121390365]) options=[]
2022/03/03 06:11:35 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:11:35 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390363 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/03 06:11:48 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:11:48 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doDeleteFolder(map[fi_id:121390363]) options=[]
2022/03/03 06:12:00 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:12:00 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390360 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/03 06:12:00 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:12:00 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doDeleteFolder(map[fi_id:121390360]) options=[]
2022/03/03 06:12:04 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 1s to wait for "error_background" error to clear
2022/03/03 06:12:05 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/03 06:12:05 DEBUG : pacer: Rate limited, increasing sleep to 40ms
2022/03/03 06:12:08 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 2s to wait for "error_background" error to clear
2022/03/03 06:12:10 DEBUG : pacer: low level retry 2/10 (error The requested operation cannot be completed. A delete operation is already being processed in this folder. Please try again later. (error_background))
2022/03/03 06:12:10 DEBUG : pacer: Rate limited, increasing sleep to 80ms
2022/03/03 06:12:10 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 4s to wait for "error_background" error to clear
2022/03/03 06:12: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/03 06:12:14 DEBUG : pacer: Rate limited, increasing sleep to 160ms
2022/03/03 06:12:18 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 8s to wait for "error_background" error to clear
2022/03/03 06:12:26 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/03 06:12:26 DEBUG : pacer: Rate limited, increasing sleep to 320ms
2022/03/03 06:12:45 DEBUG : pacer: Reducing sleep to 240ms
2022/03/03 06:12:45 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:12:45 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390359 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/03 06:12:48 DEBUG : pacer: Reducing sleep to 180ms
2022/03/03 06:12:48 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:12:48 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doDeleteFolder(map[fi_id:121390359]) options=[]
2022/03/03 06:12:52 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 1s to wait for "error_background" error to clear
2022/03/03 06:12:53 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/03 06:12:53 DEBUG : pacer: Rate limited, increasing sleep to 360ms
2022/03/03 06:12:56 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 2s to wait for "error_background" error to clear
2022/03/03 06:12:58 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/03 06:12:58 DEBUG : pacer: Rate limited, increasing sleep to 720ms
2022/03/03 06:13:00 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 4s to wait for "error_background" error to clear
2022/03/03 06:13:04 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/03 06:13:04 DEBUG : pacer: Rate limited, increasing sleep to 1.44s
2022/03/03 06:13:04 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 8s to wait for "error_background" error to clear
2022/03/03 06:13:12 DEBUG : pacer: low level retry 4/10 (error The requested operation cannot be completed. A delete operation is already being processed in this folder. Please try again later. (error_background))
2022/03/03 06:13:12 DEBUG : pacer: Rate limited, increasing sleep to 2.88s
2022/03/03 06:13:16 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 16s to wait for "error_background" error to clear
2022/03/03 06:13:32 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/03 06:13:32 DEBUG : pacer: Rate limited, increasing sleep to 5.76s
2022/03/03 06:13:35 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 32s to wait for "error_background" error to clear
2022/03/03 06:14:07 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/03 06:14:07 DEBUG : pacer: Rate limited, increasing sleep to 10s
2022/03/03 06:14:19 DEBUG : pacer: Reducing sleep to 7.5s
2022/03/03 06:14:19 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:14:19 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390352 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/03 06:14:32 DEBUG : pacer: Reducing sleep to 5.625s
2022/03/03 06:14:32 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:14:32 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doDeleteFolder(map[fi_id:121390352]) options=[]
2022/03/03 06:14:40 DEBUG : pacer: Reducing sleep to 4.21875s
2022/03/03 06:14:40 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:14:40 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390288 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/03 06:14:44 DEBUG : pacer: Reducing sleep to 3.1640625s
2022/03/03 06:14:44 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
--- PASS: TestDirWalk (582.29s)
=== RUN   TestDirSetModTime
    run.go:181: Remote "filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5'", Local "Local file system at /tmp/rclone2060667978", Modify Window "1s"
2022/03/03 06:14:44 INFO  : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': poll-interval is not supported by this remote
2022/03/03 06:14:44 NOTICE: filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2022/03/03 06:14:44 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390288 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/03 06:14:45 DEBUG : pacer: Reducing sleep to 2.373046875s
2022/03/03 06:14:45 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:14:45 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doCreateNewFolder(map[fi_name:dir fi_pid:121390288]) options=[]
2022/03/03 06:14:52 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 1s to wait for "error_background" error to clear
2022/03/03 06:14:53 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/03 06:14:53 DEBUG : pacer: Rate limited, increasing sleep to 4.74609375s
2022/03/03 06:14:53 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 2s to wait for "error_background" error to clear
2022/03/03 06:14:55 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/03 06:14:55 DEBUG : pacer: Rate limited, increasing sleep to 9.4921875s
2022/03/03 06:15:00 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 4s to wait for "error_background" error to clear
2022/03/03 06:15:04 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/03 06:15:04 DEBUG : pacer: Rate limited, increasing sleep to 10s
2022/03/03 06:15:09 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 8s to wait for "error_background" error to clear
2022/03/03 06:15:17 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/03 06:15:21 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 16s to wait for "error_background" error to clear
2022/03/03 06:15:37 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/03 06:15:38 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 32s to wait for "error_background" error to clear
2022/03/03 06:16:10 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/03 06:16:12 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 1m4s to wait for "error_background" error to clear
2022/03/03 06:17:16 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/03 06:17:19 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 2m8s to wait for "error_background" error to clear
2022/03/03 06:19:27 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/03 06:19:30 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 4m16s to wait for "error_background" error to clear
2022/03/03 06:23:46 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/03 06:24:02 DEBUG : pacer: Reducing sleep to 7.5s
2022/03/03 06:24:02 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:24:02 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': 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:121390420 fi_size:14 responsetype:json]) options=[]
2022/03/03 06:24:06 DEBUG : pacer: Reducing sleep to 5.625s
2022/03/03 06:24:06 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:24:11 DEBUG : pacer: Reducing sleep to 4.21875s
2022/03/03 06:24:11 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doCompleteUpload(map[fi_size:14 remotetime:2001-02-03 04:05:06 uploadcode:8188d2e29e30611ff97fcee423bae13d]) options=[]
2022/03/03 06:24:21 DEBUG : pacer: Reducing sleep to 3.1640625s
2022/03/03 06:24:21 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:24:21 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390288 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/03 06:24:33 DEBUG : pacer: Reducing sleep to 2.373046875s
2022/03/03 06:24:33 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:24:33 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390420 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/03 06:24:45 DEBUG : pacer: Reducing sleep to 1.779785156s
2022/03/03 06:24:45 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:24:45 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390288 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/03 06:24:45 DEBUG : pacer: Reducing sleep to 1.334838867s
2022/03/03 06:24:45 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:24:45 DEBUG : WaitForWriters: timeout=30s
2022/03/03 06:24:45 DEBUG : dir: Looking for writers
2022/03/03 06:24:45 DEBUG : : Looking for writers
2022/03/03 06:24:45 DEBUG : dir: reading active writers
2022/03/03 06:24:45 DEBUG : >WaitForWriters: 
2022/03/03 06:24:45 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390288 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/03 06:25:00 DEBUG : pacer: Reducing sleep to 1.00112915s
2022/03/03 06:25:00 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:25:00 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390420 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/03 06:25:19 DEBUG : pacer: Reducing sleep to 750.846862ms
2022/03/03 06:25:19 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:25:19 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doDeleteFile(map[completedeletion:n fi_id:121390421]) options=[]
2022/03/03 06:26:12 DEBUG : pacer: Reducing sleep to 563.135146ms
2022/03/03 06:26:12 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:26:12 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390420 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/03 06:26:20 DEBUG : pacer: Reducing sleep to 422.351359ms
2022/03/03 06:26:20 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:26:20 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doDeleteFolder(map[fi_id:121390420]) options=[]
2022/03/03 06:26:39 DEBUG : pacer: Reducing sleep to 316.763519ms
2022/03/03 06:26:39 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:26:39 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390288 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/03 06:26:43 DEBUG : pacer: Reducing sleep to 237.572639ms
2022/03/03 06:26:43 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
--- PASS: TestDirSetModTime (718.58s)
=== RUN   TestDirStat
    run.go:181: Remote "filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5'", Local "Local file system at /tmp/rclone2060667978", Modify Window "1s"
2022/03/03 06:26:43 INFO  : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': poll-interval is not supported by this remote
2022/03/03 06:26:43 NOTICE: filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2022/03/03 06:26:43 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390288 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/03 06:26:43 DEBUG : pacer: Reducing sleep to 178.179479ms
2022/03/03 06:26:43 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:26:43 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doCreateNewFolder(map[fi_name:dir fi_pid:121390288]) options=[]
2022/03/03 06:26:46 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 1s to wait for "error_background" error to clear
2022/03/03 06:26:47 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/03 06:26:47 DEBUG : pacer: Rate limited, increasing sleep to 356.358958ms
2022/03/03 06:26:50 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 2s to wait for "error_background" error to clear
2022/03/03 06:26:52 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/03 06:26:52 DEBUG : pacer: Rate limited, increasing sleep to 712.717916ms
2022/03/03 06:26:53 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 4s to wait for "error_background" error to clear
2022/03/03 06:26: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/03 06:26:57 DEBUG : pacer: Rate limited, increasing sleep to 1.425435832s
2022/03/03 06:27:01 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 8s to wait for "error_background" error to clear
2022/03/03 06:27: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/03 06:27:09 DEBUG : pacer: Rate limited, increasing sleep to 2.850871664s
2022/03/03 06:27:13 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 16s to wait for "error_background" error to clear
2022/03/03 06:27:29 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/03 06:27:29 DEBUG : pacer: Rate limited, increasing sleep to 5.701743328s
2022/03/03 06:27:30 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 32s to wait for "error_background" error to clear
2022/03/03 06:28: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/03 06:28:02 DEBUG : pacer: Rate limited, increasing sleep to 10s
2022/03/03 06:28:03 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 1m4s to wait for "error_background" error to clear
2022/03/03 06:29:07 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/03 06:29:23 DEBUG : pacer: Reducing sleep to 7.5s
2022/03/03 06:29:23 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:29:23 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': 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:121390445 fi_size:14 responsetype:json]) options=[]
2022/03/03 06:29:24 DEBUG : pacer: Reducing sleep to 5.625s
2022/03/03 06:29:24 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:29:32 DEBUG : pacer: Reducing sleep to 4.21875s
2022/03/03 06:29:32 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doCompleteUpload(map[fi_size:14 remotetime:2001-02-03 04:05:06 uploadcode:6f1cce6dde3d3be380ab3f9f98cad722]) options=[]
2022/03/03 06:29:41 DEBUG : pacer: Reducing sleep to 3.1640625s
2022/03/03 06:29:41 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:29:41 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390288 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/03 06:29:49 DEBUG : pacer: Reducing sleep to 2.373046875s
2022/03/03 06:29:49 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:29:49 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390445 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/03 06:30:01 DEBUG : pacer: Reducing sleep to 1.779785156s
2022/03/03 06:30:01 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:30:01 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390288 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/03 06:30:16 DEBUG : pacer: Reducing sleep to 1.334838867s
2022/03/03 06:30:16 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:30:16 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390445 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/03 06:30:24 DEBUG : pacer: Reducing sleep to 1.00112915s
2022/03/03 06:30:24 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:30:24 DEBUG : WaitForWriters: timeout=30s
2022/03/03 06:30:24 DEBUG : dir: Looking for writers
2022/03/03 06:30:24 DEBUG : file1: reading active writers
2022/03/03 06:30:24 DEBUG : : Looking for writers
2022/03/03 06:30:24 DEBUG : dir: reading active writers
2022/03/03 06:30:24 DEBUG : >WaitForWriters: 
2022/03/03 06:30:24 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390288 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/03 06:30:25 DEBUG : pacer: Reducing sleep to 750.846862ms
2022/03/03 06:30:25 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:30:25 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390445 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/03 06:30:26 DEBUG : pacer: Reducing sleep to 563.135146ms
2022/03/03 06:30:26 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:30:26 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doDeleteFile(map[completedeletion:n fi_id:121390448]) options=[]
2022/03/03 06:31:10 DEBUG : pacer: Reducing sleep to 422.351359ms
2022/03/03 06:31:10 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:31:10 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390445 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/03 06:31:32 DEBUG : pacer: Reducing sleep to 316.763519ms
2022/03/03 06:31:32 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:31:32 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doDeleteFolder(map[fi_id:121390445]) options=[]
2022/03/03 06:31:47 DEBUG : pacer: Reducing sleep to 237.572639ms
2022/03/03 06:31:47 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:31:47 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390288 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/03 06:31:48 DEBUG : pacer: Reducing sleep to 178.179479ms
2022/03/03 06:31:48 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
--- PASS: TestDirStat (305.50s)
=== RUN   TestDirReadDirAll
    run.go:181: Remote "filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5'", Local "Local file system at /tmp/rclone2060667978", Modify Window "1s"
2022/03/03 06:31:48 INFO  : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': poll-interval is not supported by this remote
2022/03/03 06:31:48 NOTICE: filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2022/03/03 06:31:48 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390288 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/03 06:31:49 DEBUG : pacer: Reducing sleep to 133.634609ms
2022/03/03 06:31:49 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:31:49 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doCreateNewFolder(map[fi_name:dir fi_pid:121390288]) options=[]
2022/03/03 06:31:52 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 1s to wait for "error_background" error to clear
2022/03/03 06:31:53 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/03 06:31:53 DEBUG : pacer: Rate limited, increasing sleep to 267.269218ms
2022/03/03 06:31:56 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 2s to wait for "error_background" error to clear
2022/03/03 06:31:58 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/03 06:31:58 DEBUG : pacer: Rate limited, increasing sleep to 534.538436ms
2022/03/03 06:32:00 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 4s to wait for "error_background" error to clear
2022/03/03 06:32:04 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/03 06:32:04 DEBUG : pacer: Rate limited, increasing sleep to 1.069076872s
2022/03/03 06:32:04 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 8s to wait for "error_background" error to clear
2022/03/03 06:32:12 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/03 06:32:12 DEBUG : pacer: Rate limited, increasing sleep to 2.138153744s
2022/03/03 06:32:15 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 16s to wait for "error_background" error to clear
2022/03/03 06:32:31 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/03 06:32:31 DEBUG : pacer: Rate limited, increasing sleep to 4.276307488s
2022/03/03 06:32:32 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 32s to wait for "error_background" error to clear
2022/03/03 06:33:04 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/03 06:33:04 DEBUG : pacer: Rate limited, increasing sleep to 8.552614976s
2022/03/03 06:33:05 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 1m4s to wait for "error_background" error to clear
2022/03/03 06:34: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/03 06:34:09 DEBUG : pacer: Rate limited, increasing sleep to 10s
2022/03/03 06:34:09 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 2m8s to wait for "error_background" error to clear
2022/03/03 06:36:17 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/03 06:36:37 DEBUG : pacer: Reducing sleep to 7.5s
2022/03/03 06:36:37 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:36:37 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': 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:121390473 fi_size:14 responsetype:json]) options=[]
2022/03/03 06:36:37 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Token expired - refreshing
2022/03/03 06:36:37 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getTokenByAuthToken(map[authtoken:622506e6346e7ad6-c48bf9558d23a2ae token:*]) options=[]
2022/03/03 06:36:38 DEBUG : pacer: Reducing sleep to 5.625s
2022/03/03 06:36:38 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:36:38 DEBUG : Saving config "token" in section "TestFileFabric" of the config file
2022/03/03 06:36:38 DEBUG : Config file has changed externaly - reloading
2022/03/03 06:36:38 DEBUG : Saving config "token_expiry" in section "TestFileFabric" of the config file
2022/03/03 06:36:38 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getApplianceInfo(map[token:*]) options=[]
2022/03/03 06:36:45 DEBUG : pacer: Reducing sleep to 4.21875s
2022/03/03 06:36:45 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:36:45 DEBUG : Saving config "version" in section "TestFileFabric" of the config file
2022/03/03 06:36:54 DEBUG : pacer: Reducing sleep to 3.1640625s
2022/03/03 06:36:54 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:36:56 DEBUG : pacer: Reducing sleep to 2.373046875s
2022/03/03 06:36:56 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doCompleteUpload(map[fi_size:14 remotetime:2001-02-03 04:05:06 uploadcode:89def7051d150d26b76c10f87aa59350]) options=[]
2022/03/03 06:37:07 DEBUG : pacer: Reducing sleep to 1.779785156s
2022/03/03 06:37:07 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:37:07 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': 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:121390473 fi_size:15 responsetype:json]) options=[]
2022/03/03 06:37:09 DEBUG : pacer: Reducing sleep to 1.334838867s
2022/03/03 06:37:09 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:37:11 DEBUG : pacer: Reducing sleep to 1.00112915s
2022/03/03 06:37:11 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doCompleteUpload(map[fi_size:15 remotetime:2011-12-25 12:59:59 uploadcode:9af1d921110e84932c863939c1062964]) options=[]
2022/03/03 06:37:17 DEBUG : pacer: Reducing sleep to 750.846862ms
2022/03/03 06:37:17 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:37:17 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390473 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/03 06:37:29 DEBUG : pacer: Reducing sleep to 563.135146ms
2022/03/03 06:37:29 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:37:29 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doCreateNewFolder(map[fi_name:subdir fi_pid:121390473]) options=[]
2022/03/03 06:37:49 DEBUG : pacer: Reducing sleep to 422.351359ms
2022/03/03 06:37:49 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:37:49 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': 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:121390479 fi_size:16 responsetype:json]) options=[]
2022/03/03 06:37:53 DEBUG : pacer: Reducing sleep to 316.763519ms
2022/03/03 06:37:53 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:37:55 DEBUG : pacer: Reducing sleep to 237.572639ms
2022/03/03 06:37:55 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doCompleteUpload(map[fi_size:16 remotetime:2011-12-30 12:59:59 uploadcode:4fc7bf1b92a0b76a43a0529db1d25bc8]) options=[]
2022/03/03 06:38:04 DEBUG : pacer: Reducing sleep to 178.179479ms
2022/03/03 06:38:04 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:38:04 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390288 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/03 06:38:16 DEBUG : pacer: Reducing sleep to 133.634609ms
2022/03/03 06:38:16 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:38:16 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390473 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/03 06:38:32 DEBUG : pacer: Reducing sleep to 100.225956ms
2022/03/03 06:38:32 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:38:32 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390479 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/03 06:38:44 DEBUG : pacer: Reducing sleep to 75.169467ms
2022/03/03 06:38:44 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:38:44 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390288 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/03 06:38:55 DEBUG : pacer: Reducing sleep to 56.3771ms
2022/03/03 06:38:55 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:38:55 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390473 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/03 06:38:56 DEBUG : pacer: Reducing sleep to 42.282825ms
2022/03/03 06:38:56 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:38:56 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390479 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/03 06:38:56 DEBUG : pacer: Reducing sleep to 31.712118ms
2022/03/03 06:38:56 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
=== RUN   TestDirReadDirAll/Virtual
2022/03/03 06:38:56 DEBUG : dir: Added virtual directory entry vAddFile: "virtualFile"
2022/03/03 06:38:56 DEBUG : dir: Added virtual directory entry vAddDir: "virtualDir"
2022/03/03 06:38:56 DEBUG : dir: Added virtual directory entry vDel: "file2"
2022/03/03 06:38:56 DEBUG : dir: Added virtual directory entry vDel: "subdir"
2022/03/03 06:38:56 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': 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:121390473 fi_size:20 responsetype:json]) options=[]
2022/03/03 06:38:58 DEBUG : pacer: Reducing sleep to 23.784088ms
2022/03/03 06:38:58 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:38:59 DEBUG : pacer: Reducing sleep to 20ms
2022/03/03 06:38:59 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doCompleteUpload(map[fi_size:20 remotetime:2001-02-03 04:05:06 uploadcode:defb34a2b608798d85229e07e57c2db6]) options=[]
2022/03/03 06:39:11 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:39:11 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390473 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/03 06:39:20 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:39:20 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doCreateNewFolder(map[fi_name:virtualDir fi_pid:121390473]) options=[]
2022/03/03 06:39:42 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:39:42 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': 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:121390488 fi_size:17 responsetype:json]) options=[]
2022/03/03 06:39:46 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:39:48 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doCompleteUpload(map[fi_size:17 remotetime:2001-02-03 04:05:06 uploadcode:4c2a2876f0d91575f71cecff3e58e05f]) options=[]
2022/03/03 06:39:57 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:39:57 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: checkPathExists(map[path:dir/file2 pid:121390288]) options=[]
2022/03/03 06:39:57 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:39:57 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doDeleteFile(map[completedeletion:n fi_id:121390478]) options=[]
2022/03/03 06:40:40 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:40:40 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doDeleteFolder(map[fi_id:121390479]) options=[]
2022/03/03 06:40:59 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:40:59 DEBUG : dir: invalidating directory cache
2022/03/03 06:40:59 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390473 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/03 06:41:00 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:41:00 DEBUG : dir: Removed virtual directory entry vAddDir: "virtualDir"
2022/03/03 06:41:00 DEBUG : dir: Removed virtual directory entry vDel: "file2"
2022/03/03 06:41:00 DEBUG : dir: Removed virtual directory entry vDel: "subdir"
2022/03/03 06:41:00 DEBUG : dir: Removed virtual directory entry vAddFile: "virtualFile"
2022/03/03 06:41:00 DEBUG : dir: Added virtual directory entry vAddFile: "virtualFile2"
2022/03/03 06:41:00 DEBUG : dir: Added virtual directory entry vAddDir: "virtualDir2"
2022/03/03 06:41:00 DEBUG : dir: Added virtual directory entry vDel: "file1"
2022/03/03 06:41:00 DEBUG : dir: invalidating directory cache
2022/03/03 06:41:00 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390473 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/03 06:41:00 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:41:00 DEBUG : dir: Removed virtual directory entry vAddDir: "virtualDir2"
2022/03/03 06:41:00 DEBUG : dir: Removed virtual directory entry vDel: "file1"
2022/03/03 06:41:00 DEBUG : : forgetting directory cache
2022/03/03 06:41:00 DEBUG : dir: forgetting directory cache
2022/03/03 06:41:00 DEBUG : dir/virtualDir: forgetting directory cache
2022/03/03 06:41:00 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390473 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/03 06:41:01 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:41:01 DEBUG : WaitForWriters: timeout=30s
2022/03/03 06:41:01 DEBUG : dir/virtualDir: Looking for writers
2022/03/03 06:41:01 DEBUG : dir: Looking for writers
2022/03/03 06:41:01 DEBUG : file1: reading active writers
2022/03/03 06:41:01 DEBUG : virtualFile2: reading active writers
2022/03/03 06:41:01 DEBUG : virtualFile: reading active writers
2022/03/03 06:41:01 DEBUG : virtualDir: reading active writers
2022/03/03 06:41:01 DEBUG : : Looking for writers
2022/03/03 06:41:01 DEBUG : dir: reading active writers
2022/03/03 06:41:01 DEBUG : >WaitForWriters: 
2022/03/03 06:41:01 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390288 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/03 06:41:04 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:41:04 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390473 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/03 06:41:04 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:41:04 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doDeleteFile(map[completedeletion:n fi_id:121390476]) options=[]
2022/03/03 06:41:46 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:41:46 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doDeleteFile(map[completedeletion:n fi_id:121390484]) options=[]
2022/03/03 06:42:14 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:42:14 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390488 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/03 06:42:30 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:42:30 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doDeleteFile(map[completedeletion:n fi_id:121390490]) options=[]
2022/03/03 06:43:01 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:43:01 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390488 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/03 06:43:10 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:43:10 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doDeleteFolder(map[fi_id:121390488]) options=[]
2022/03/03 06:43:25 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:43:25 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390473 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/03 06:43:30 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:43:30 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doDeleteFolder(map[fi_id:121390473]) options=[]
2022/03/03 06:43:33 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 1s to wait for "error_background" error to clear
2022/03/03 06:43:34 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/03 06:43:34 DEBUG : pacer: Rate limited, increasing sleep to 40ms
2022/03/03 06:43:37 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 2s to wait for "error_background" error to clear
2022/03/03 06:43:39 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/03 06:43:39 DEBUG : pacer: Rate limited, increasing sleep to 80ms
2022/03/03 06:43:40 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 4s to wait for "error_background" error to clear
2022/03/03 06:43:44 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/03 06:43:44 DEBUG : pacer: Rate limited, increasing sleep to 160ms
2022/03/03 06:43:45 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 8s to wait for "error_background" error to clear
2022/03/03 06:43:53 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/03 06:43:53 DEBUG : pacer: Rate limited, increasing sleep to 320ms
2022/03/03 06:43:57 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 16s to wait for "error_background" error to clear
2022/03/03 06:44:13 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/03 06:44:13 DEBUG : pacer: Rate limited, increasing sleep to 640ms
2022/03/03 06:44:16 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 32s to wait for "error_background" error to clear
2022/03/03 06:44:48 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/03 06:44:48 DEBUG : pacer: Rate limited, increasing sleep to 1.28s
2022/03/03 06:44:50 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 1m4s to wait for "error_background" error to clear
2022/03/03 06:45:54 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/03 06:45:54 DEBUG : pacer: Rate limited, increasing sleep to 2.56s
2022/03/03 06:45:55 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 2m8s to wait for "error_background" error to clear
2022/03/03 06:48:03 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/03 06:48:03 DEBUG : pacer: Rate limited, increasing sleep to 5.12s
2022/03/03 06:48:17 DEBUG : pacer: Reducing sleep to 3.84s
2022/03/03 06:48:17 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:48:17 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390288 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/03 06:48:21 DEBUG : pacer: Reducing sleep to 2.88s
2022/03/03 06:48:21 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
--- PASS: TestDirReadDirAll (992.54s)
    --- PASS: TestDirReadDirAll/Virtual (124.48s)
=== RUN   TestDirOpen
    run.go:181: Remote "filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5'", Local "Local file system at /tmp/rclone2060667978", Modify Window "1s"
2022/03/03 06:48:21 INFO  : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': poll-interval is not supported by this remote
2022/03/03 06:48:21 NOTICE: filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2022/03/03 06:48:21 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390288 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/03 06:48:21 DEBUG : pacer: Reducing sleep to 2.16s
2022/03/03 06:48:21 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:48:21 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doCreateNewFolder(map[fi_name:dir fi_pid:121390288]) options=[]
2022/03/03 06:48:24 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 1s to wait for "error_background" error to clear
2022/03/03 06:48:25 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/03 06:48:25 DEBUG : pacer: Rate limited, increasing sleep to 4.32s
2022/03/03 06:48:28 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 2s to wait for "error_background" error to clear
2022/03/03 06:48:30 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/03 06:48:30 DEBUG : pacer: Rate limited, increasing sleep to 8.64s
2022/03/03 06:48:32 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 4s to wait for "error_background" error to clear
2022/03/03 06:48:36 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/03 06:48:36 DEBUG : pacer: Rate limited, increasing sleep to 10s
2022/03/03 06:48:40 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 8s to wait for "error_background" error to clear
2022/03/03 06:48:48 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/03 06:48:51 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 16s to wait for "error_background" error to clear
2022/03/03 06:49:07 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/03 06:49:11 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 32s to wait for "error_background" error to clear
2022/03/03 06:49:43 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/03 06:50:09 DEBUG : pacer: Reducing sleep to 7.5s
2022/03/03 06:50:09 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:50:09 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': 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:121390533 fi_size:14 responsetype:json]) options=[]
2022/03/03 06:50:11 DEBUG : pacer: Reducing sleep to 5.625s
2022/03/03 06:50:11 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:50:19 DEBUG : pacer: Reducing sleep to 4.21875s
2022/03/03 06:50:19 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doCompleteUpload(map[fi_size:14 remotetime:2001-02-03 04:05:06 uploadcode:e118c9b9ae920bed95ca09177b2ccbc9]) options=[]
2022/03/03 06:50:33 DEBUG : pacer: Reducing sleep to 3.1640625s
2022/03/03 06:50:33 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:50:33 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390288 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/03 06:50:55 DEBUG : pacer: Reducing sleep to 2.373046875s
2022/03/03 06:50:55 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:50:55 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390533 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/03 06:51:07 DEBUG : pacer: Reducing sleep to 1.779785156s
2022/03/03 06:51:07 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:51:07 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390288 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/03 06:51:07 DEBUG : pacer: Reducing sleep to 1.334838867s
2022/03/03 06:51:07 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:51:07 ERROR : dir/: Can only open directories read only
2022/03/03 06:51:07 DEBUG : WaitForWriters: timeout=30s
2022/03/03 06:51:07 DEBUG : dir: Looking for writers
2022/03/03 06:51:07 DEBUG : : Looking for writers
2022/03/03 06:51:07 DEBUG : dir: reading active writers
2022/03/03 06:51:07 DEBUG : >WaitForWriters: 
2022/03/03 06:51:07 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390288 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/03 06:51:09 DEBUG : pacer: Reducing sleep to 1.00112915s
2022/03/03 06:51:09 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:51:09 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390533 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/03 06:51:10 DEBUG : pacer: Reducing sleep to 750.846862ms
2022/03/03 06:51:10 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:51:10 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doDeleteFile(map[completedeletion:n fi_id:121390534]) options=[]
2022/03/03 06:51:59 DEBUG : pacer: Reducing sleep to 563.135146ms
2022/03/03 06:51:59 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:51:59 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390533 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/03 06:52:17 DEBUG : pacer: Reducing sleep to 422.351359ms
2022/03/03 06:52:17 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:52:17 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doDeleteFolder(map[fi_id:121390533]) options=[]
2022/03/03 06:52:30 DEBUG : pacer: Reducing sleep to 316.763519ms
2022/03/03 06:52:30 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:52:30 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390288 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/03 06:52:31 DEBUG : pacer: Reducing sleep to 237.572639ms
2022/03/03 06:52:31 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
--- PASS: TestDirOpen (249.76s)
=== RUN   TestDirCreate
    run.go:181: Remote "filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5'", Local "Local file system at /tmp/rclone2060667978", Modify Window "1s"
2022/03/03 06:52:31 INFO  : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': poll-interval is not supported by this remote
2022/03/03 06:52:31 NOTICE: filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2022/03/03 06:52:31 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390288 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/03 06:52:31 DEBUG : pacer: Reducing sleep to 178.179479ms
2022/03/03 06:52:31 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:52:31 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doCreateNewFolder(map[fi_name:dir fi_pid:121390288]) options=[]
2022/03/03 06:52:34 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 1s to wait for "error_background" error to clear
2022/03/03 06:52:35 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/03 06:52:35 DEBUG : pacer: Rate limited, increasing sleep to 356.358958ms
2022/03/03 06:52:38 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 2s to wait for "error_background" error to clear
2022/03/03 06:52:40 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/03 06:52:40 DEBUG : pacer: Rate limited, increasing sleep to 712.717916ms
2022/03/03 06:52:42 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 4s to wait for "error_background" error to clear
2022/03/03 06:52:46 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/03 06:52:46 DEBUG : pacer: Rate limited, increasing sleep to 1.425435832s
2022/03/03 06:52:49 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 8s to wait for "error_background" error to clear
2022/03/03 06:52: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/03 06:52:57 DEBUG : pacer: Rate limited, increasing sleep to 2.850871664s
2022/03/03 06:53:00 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 16s to wait for "error_background" error to clear
2022/03/03 06:53: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/03 06:53:16 DEBUG : pacer: Rate limited, increasing sleep to 5.701743328s
2022/03/03 06:53:20 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 32s to wait for "error_background" error to clear
2022/03/03 06:53: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/03 06:53:52 DEBUG : pacer: Rate limited, increasing sleep to 10s
2022/03/03 06:53:53 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 1m4s to wait for "error_background" error to clear
2022/03/03 06:54:57 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/03 06:55:18 DEBUG : pacer: Reducing sleep to 7.5s
2022/03/03 06:55:18 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:55:18 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': 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:121390546 fi_size:14 responsetype:json]) options=[]
2022/03/03 06:55:20 DEBUG : pacer: Reducing sleep to 5.625s
2022/03/03 06:55:20 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:55:27 DEBUG : pacer: Reducing sleep to 4.21875s
2022/03/03 06:55:27 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doCompleteUpload(map[fi_size:14 remotetime:2001-02-03 04:05:06 uploadcode:387c1e28b17b4bce5f57b1c4dd3e3e25]) options=[]
2022/03/03 06:55:41 DEBUG : pacer: Reducing sleep to 3.1640625s
2022/03/03 06:55:41 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:55:41 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390288 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/03 06:55:53 DEBUG : pacer: Reducing sleep to 2.373046875s
2022/03/03 06:55:53 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:55:53 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390546 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/03 06:56:05 DEBUG : pacer: Reducing sleep to 1.779785156s
2022/03/03 06:56:05 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:56:05 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390288 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/03 06:56:06 DEBUG : pacer: Reducing sleep to 1.334838867s
2022/03/03 06:56:06 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:56:06 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390546 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/03 06:56:07 DEBUG : pacer: Reducing sleep to 1.00112915s
2022/03/03 06:56:07 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:56:07 DEBUG : dir/potato: Open: flags=O_WRONLY|O_CREATE
2022/03/03 06:56:07 DEBUG : dir: Added virtual directory entry vAddFile: "potato"
2022/03/03 06:56:07 DEBUG : dir/potato: >Open: fd=dir/potato (w), err=<nil>
2022/03/03 06:56:07 DEBUG : dir: Added virtual directory entry vAddFile: "potato"
2022/03/03 06:56:07 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': File to upload is small (5 bytes), uploading instead of streaming
2022/03/03 06:56:07 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doInitUpload(map[directuploadsupport:n fi_contenttype:application/octet-stream fi_filename:potato fi_localtime:2022-03-03 06:56:07 fi_modified:2022-03-03 06:56:07 fi_name:potato fi_pid:121390546 fi_size:5 responsetype:json]) options=[]
2022/03/03 06:56:10 DEBUG : pacer: Reducing sleep to 750.846862ms
2022/03/03 06:56:10 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:56:11 DEBUG : pacer: Reducing sleep to 563.135146ms
2022/03/03 06:56:11 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doCompleteUpload(map[fi_size:5 remotetime:2022-03-03 06:56:07 uploadcode:e02c3c9254bf1414f87cfc2b8a741ab8]) options=[]
2022/03/03 06:56:20 DEBUG : pacer: Reducing sleep to 422.351359ms
2022/03/03 06:56:20 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:56:20 INFO  : dir/potato: Copied (new)
2022/03/03 06:56:20 DEBUG : dir: Added virtual directory entry vAddFile: "potato"
2022/03/03 06:56:20 DEBUG : WaitForWriters: timeout=30s
2022/03/03 06:56:20 DEBUG : dir: Looking for writers
2022/03/03 06:56:20 DEBUG : potato: reading active writers
2022/03/03 06:56:20 DEBUG : file1: reading active writers
2022/03/03 06:56:20 DEBUG : : Looking for writers
2022/03/03 06:56:20 DEBUG : dir: reading active writers
2022/03/03 06:56:20 DEBUG : >WaitForWriters: 
2022/03/03 06:56:20 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390288 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/03 06:56:21 DEBUG : pacer: Reducing sleep to 316.763519ms
2022/03/03 06:56:21 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:56:21 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390546 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/03 06:56:32 DEBUG : pacer: Reducing sleep to 237.572639ms
2022/03/03 06:56:32 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:56:32 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doDeleteFile(map[completedeletion:n fi_id:121390551]) options=[]
2022/03/03 06:57:51 DEBUG : pacer: Reducing sleep to 178.179479ms
2022/03/03 06:57:51 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:57:51 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doDeleteFile(map[completedeletion:n fi_id:121390553]) options=[]
2022/03/03 06:58:41 DEBUG : pacer: Reducing sleep to 133.634609ms
2022/03/03 06:58:41 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:58:41 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390546 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/03 06:58:52 DEBUG : pacer: Reducing sleep to 100.225956ms
2022/03/03 06:58:52 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:58:52 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doDeleteFolder(map[fi_id:121390546]) options=[]
2022/03/03 06:59:11 DEBUG : pacer: Reducing sleep to 75.169467ms
2022/03/03 06:59:11 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:59:11 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390288 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/03 06:59:15 DEBUG : pacer: Reducing sleep to 56.3771ms
2022/03/03 06:59:15 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
--- PASS: TestDirCreate (404.39s)
=== RUN   TestDirMkdir
    run.go:181: Remote "filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5'", Local "Local file system at /tmp/rclone2060667978", Modify Window "1s"
2022/03/03 06:59:15 INFO  : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': poll-interval is not supported by this remote
2022/03/03 06:59:15 NOTICE: filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2022/03/03 06:59:15 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390288 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/03 06:59:16 DEBUG : pacer: Reducing sleep to 42.282825ms
2022/03/03 06:59:16 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 06:59:16 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doCreateNewFolder(map[fi_name:dir fi_pid:121390288]) options=[]
2022/03/03 06:59:19 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 1s to wait for "error_background" error to clear
2022/03/03 06:59: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/03 06:59:20 DEBUG : pacer: Rate limited, increasing sleep to 84.56565ms
2022/03/03 06:59:22 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 2s to wait for "error_background" error to clear
2022/03/03 06:59:24 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/03 06:59:24 DEBUG : pacer: Rate limited, increasing sleep to 169.1313ms
2022/03/03 06:59:26 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 4s to wait for "error_background" error to clear
2022/03/03 06:59:30 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/03 06:59:30 DEBUG : pacer: Rate limited, increasing sleep to 338.2626ms
2022/03/03 06:59:33 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 8s to wait for "error_background" error to clear
2022/03/03 06:59:41 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/03 06:59:41 DEBUG : pacer: Rate limited, increasing sleep to 676.5252ms
2022/03/03 06:59:44 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 16s to wait for "error_background" error to clear
2022/03/03 07:00:00 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/03 07:00:00 DEBUG : pacer: Rate limited, increasing sleep to 1.3530504s
2022/03/03 07:00:16 DEBUG : pacer: Reducing sleep to 1.0147878s
2022/03/03 07:00:16 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 07:00:16 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': 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:121390573 fi_size:14 responsetype:json]) options=[]
2022/03/03 07:00:21 DEBUG : pacer: Reducing sleep to 761.09085ms
2022/03/03 07:00:21 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 07:00:22 DEBUG : pacer: Reducing sleep to 570.818137ms
2022/03/03 07:00:22 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doCompleteUpload(map[fi_size:14 remotetime:2001-02-03 04:05:06 uploadcode:aba40aab4e327990c6cacaf9cb39f1e6]) options=[]
2022/03/03 07:00:42 DEBUG : pacer: Reducing sleep to 428.113602ms
2022/03/03 07:00:42 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 07:00:42 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390288 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/03 07:00:58 DEBUG : pacer: Reducing sleep to 321.085201ms
2022/03/03 07:00:58 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 07:00:58 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390573 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/03 07:01:17 DEBUG : pacer: Reducing sleep to 240.8139ms
2022/03/03 07:01:17 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 07:01:17 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390288 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/03 07:01:17 DEBUG : pacer: Reducing sleep to 180.610425ms
2022/03/03 07:01:17 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 07:01:17 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390573 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/03 07:01:18 DEBUG : pacer: Reducing sleep to 135.457818ms
2022/03/03 07:01:18 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 07:01:18 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390573 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/03 07:01:18 DEBUG : pacer: Reducing sleep to 101.593363ms
2022/03/03 07:01:18 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 07:01:18 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doCreateNewFolder(map[fi_name:sub fi_pid:121390573]) options=[]
2022/03/03 07:01:39 DEBUG : pacer: Reducing sleep to 76.195022ms
2022/03/03 07:01:39 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 07:01:39 DEBUG : dir: Added virtual directory entry vAddDir: "sub"
2022/03/03 07:01:39 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390585 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/03 07:01:54 DEBUG : pacer: Reducing sleep to 57.146266ms
2022/03/03 07:01:54 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 07:01:54 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390288 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/03 07:02:03 DEBUG : pacer: Reducing sleep to 42.859699ms
2022/03/03 07:02:03 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 07:02:03 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390573 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/03 07:02:25 DEBUG : pacer: Reducing sleep to 32.144774ms
2022/03/03 07:02:25 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 07:02:25 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390585 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/03 07:02:26 DEBUG : pacer: Reducing sleep to 24.10858ms
2022/03/03 07:02:26 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 07:02:26 DEBUG : WaitForWriters: timeout=30s
2022/03/03 07:02:26 DEBUG : dir/sub: Looking for writers
2022/03/03 07:02:26 DEBUG : dir: Looking for writers
2022/03/03 07:02:26 DEBUG : file1: reading active writers
2022/03/03 07:02:26 DEBUG : sub: reading active writers
2022/03/03 07:02:26 DEBUG : : Looking for writers
2022/03/03 07:02:26 DEBUG : dir: reading active writers
2022/03/03 07:02:26 DEBUG : >WaitForWriters: 
2022/03/03 07:02:26 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390288 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/03 07:02:26 DEBUG : pacer: Reducing sleep to 20ms
2022/03/03 07:02:26 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 07:02:26 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390573 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/03 07:02:27 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 07:02:27 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doDeleteFile(map[completedeletion:n fi_id:121390575]) options=[]
2022/03/03 07:03:23 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 07:03:23 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390585 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/03 07:03:23 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 07:03:23 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390585 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/03 07:03:24 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 07:03:24 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doDeleteFolder(map[fi_id:121390585]) options=[]
2022/03/03 07:03:41 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 07:03:41 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390573 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/03 07:03:45 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 07:03:45 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doDeleteFolder(map[fi_id:121390573]) options=[]
2022/03/03 07:03:49 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 1s to wait for "error_background" error to clear
2022/03/03 07:03:50 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/03 07:03:50 DEBUG : pacer: Rate limited, increasing sleep to 40ms
2022/03/03 07:03:53 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 2s to wait for "error_background" error to clear
2022/03/03 07:03:55 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/03 07:03:55 DEBUG : pacer: Rate limited, increasing sleep to 80ms
2022/03/03 07:03:56 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 4s to wait for "error_background" error to clear
2022/03/03 07:04:00 DEBUG : pacer: low level retry 3/10 (error The requested operation cannot be completed. A delete operation is already being processed in this folder. Please try again later. (error_background))
2022/03/03 07:04:00 DEBUG : pacer: Rate limited, increasing sleep to 160ms
2022/03/03 07:04:04 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 8s to wait for "error_background" error to clear
2022/03/03 07:04:12 DEBUG : pacer: low level retry 4/10 (error The requested operation cannot be completed. A delete operation is already being processed in this folder. Please try again later. (error_background))
2022/03/03 07:04:12 DEBUG : pacer: Rate limited, increasing sleep to 320ms
2022/03/03 07:04:16 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 16s to wait for "error_background" error to clear
2022/03/03 07:04:32 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/03 07:04:32 DEBUG : pacer: Rate limited, increasing sleep to 640ms
2022/03/03 07:04:35 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 32s to wait for "error_background" error to clear
2022/03/03 07:05:07 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/03 07:05:07 DEBUG : pacer: Rate limited, increasing sleep to 1.28s
2022/03/03 07:05:09 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 1m4s to wait for "error_background" error to clear
2022/03/03 07:06:13 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/03 07:06:13 DEBUG : pacer: Rate limited, increasing sleep to 2.56s
2022/03/03 07:06:34 DEBUG : pacer: Reducing sleep to 1.92s
2022/03/03 07:06:34 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 07:06:34 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390288 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/03 07:06:35 DEBUG : pacer: Reducing sleep to 1.44s
2022/03/03 07:06:35 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
--- PASS: TestDirMkdir (440.04s)
=== RUN   TestDirMkdirSub
    run.go:181: Remote "filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5'", Local "Local file system at /tmp/rclone2060667978", Modify Window "1s"
2022/03/03 07:06:35 INFO  : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': poll-interval is not supported by this remote
2022/03/03 07:06:35 NOTICE: filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2022/03/03 07:06:35 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390288 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/03 07:06:37 DEBUG : pacer: Reducing sleep to 1.08s
2022/03/03 07:06:37 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 07:06:37 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doCreateNewFolder(map[fi_name:dir fi_pid:121390288]) options=[]
2022/03/03 07:06:39 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 1s to wait for "error_background" error to clear
2022/03/03 07:06:40 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/03 07:06:40 DEBUG : pacer: Rate limited, increasing sleep to 2.16s
2022/03/03 07:06:43 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 2s to wait for "error_background" error to clear
2022/03/03 07:06:45 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/03 07:06:45 DEBUG : pacer: Rate limited, increasing sleep to 4.32s
2022/03/03 07:06:46 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 4s to wait for "error_background" error to clear
2022/03/03 07:06:50 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/03 07:06:50 DEBUG : pacer: Rate limited, increasing sleep to 8.64s
2022/03/03 07:06:54 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 8s to wait for "error_background" error to clear
2022/03/03 07:07:02 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/03 07:07:02 DEBUG : pacer: Rate limited, increasing sleep to 10s
2022/03/03 07:07:02 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 16s to wait for "error_background" error to clear
2022/03/03 07:07:18 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/03 07:07:21 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 32s to wait for "error_background" error to clear
2022/03/03 07:07: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/03 07:07:54 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 1m4s to wait for "error_background" error to clear
2022/03/03 07:08: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/03 07:09:01 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 2m8s to wait for "error_background" error to clear
2022/03/03 07:11:09 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/03 07:11:11 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 4m16s to wait for "error_background" error to clear
2022/03/03 07:15:27 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/03 07:15:41 DEBUG : pacer: Reducing sleep to 7.5s
2022/03/03 07:15:41 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 07:15:41 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': 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:121390629 fi_size:14 responsetype:json]) options=[]
2022/03/03 07:15:46 DEBUG : pacer: Reducing sleep to 5.625s
2022/03/03 07:15:46 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 07:15:50 DEBUG : pacer: Reducing sleep to 4.21875s
2022/03/03 07:15:50 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doCompleteUpload(map[fi_size:14 remotetime:2001-02-03 04:05:06 uploadcode:546e26b6d8b071e0e196da4de70e0b9d]) options=[]
2022/03/03 07:16:01 DEBUG : pacer: Reducing sleep to 3.1640625s
2022/03/03 07:16:01 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 07:16:01 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390288 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/03 07:16:13 DEBUG : pacer: Reducing sleep to 2.373046875s
2022/03/03 07:16:13 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 07:16:13 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390629 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/03 07:16:22 DEBUG : pacer: Reducing sleep to 1.779785156s
2022/03/03 07:16:22 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 07:16:22 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390288 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/03 07:16:22 DEBUG : pacer: Reducing sleep to 1.334838867s
2022/03/03 07:16:22 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 07:16:22 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390629 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/03 07:16:24 DEBUG : pacer: Reducing sleep to 1.00112915s
2022/03/03 07:16:24 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 07:16:24 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390629 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/03 07:16:25 DEBUG : pacer: Reducing sleep to 750.846862ms
2022/03/03 07:16:25 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 07:16:25 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doCreateNewFolder(map[fi_name:sub fi_pid:121390629]) options=[]
2022/03/03 07:16:45 DEBUG : pacer: Reducing sleep to 563.135146ms
2022/03/03 07:16:45 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 07:16:45 DEBUG : dir: Added virtual directory entry vAddDir: "sub"
2022/03/03 07:16:45 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390634 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/03 07:16:53 DEBUG : pacer: Reducing sleep to 422.351359ms
2022/03/03 07:16:53 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 07:16:53 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390634 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/03 07:16:54 DEBUG : pacer: Reducing sleep to 316.763519ms
2022/03/03 07:16:54 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 07:16:54 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doCreateNewFolder(map[fi_name:subsub fi_pid:121390634]) options=[]
2022/03/03 07:17:08 DEBUG : pacer: Reducing sleep to 237.572639ms
2022/03/03 07:17:08 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 07:17:08 DEBUG : dir/sub: Added virtual directory entry vAddDir: "subsub"
2022/03/03 07:17:08 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390639 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/03 07:17:17 DEBUG : pacer: Reducing sleep to 178.179479ms
2022/03/03 07:17:17 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 07:17:17 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390288 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/03 07:17:35 DEBUG : pacer: Reducing sleep to 133.634609ms
2022/03/03 07:17:35 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 07:17:35 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390629 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/03 07:17:47 DEBUG : pacer: Reducing sleep to 100.225956ms
2022/03/03 07:17:47 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 07:17:47 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390634 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/03 07:18:05 DEBUG : pacer: Reducing sleep to 75.169467ms
2022/03/03 07:18:05 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 07:18:05 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390639 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/03 07:18:06 DEBUG : pacer: Reducing sleep to 56.3771ms
2022/03/03 07:18:06 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 07:18:06 DEBUG : WaitForWriters: timeout=30s
2022/03/03 07:18:06 DEBUG : dir/sub/subsub: Looking for writers
2022/03/03 07:18:06 DEBUG : dir/sub: Looking for writers
2022/03/03 07:18:06 DEBUG : subsub: reading active writers
2022/03/03 07:18:06 DEBUG : dir: Looking for writers
2022/03/03 07:18:06 DEBUG : sub: reading active writers
2022/03/03 07:18:06 DEBUG : file1: reading active writers
2022/03/03 07:18:06 DEBUG : : Looking for writers
2022/03/03 07:18:06 DEBUG : dir: reading active writers
2022/03/03 07:18:06 DEBUG : >WaitForWriters: 
2022/03/03 07:18:06 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390288 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/03 07:18:06 DEBUG : pacer: Reducing sleep to 42.282825ms
2022/03/03 07:18:06 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 07:18:06 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390629 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/03 07:18:07 DEBUG : pacer: Reducing sleep to 31.712118ms
2022/03/03 07:18:07 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 07:18:07 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doDeleteFile(map[completedeletion:n fi_id:121390631]) options=[]
2022/03/03 07:18:55 DEBUG : pacer: Reducing sleep to 23.784088ms
2022/03/03 07:18:55 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 07:18:55 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390634 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/03 07:18:55 DEBUG : pacer: Reducing sleep to 20ms
2022/03/03 07:18:55 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 07:18:55 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390639 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/03 07:18:56 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 07:18:56 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390639 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/03 07:18:57 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 07:18:57 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doDeleteFolder(map[fi_id:121390639]) options=[]
2022/03/03 07:19:21 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 07:19:21 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390634 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/03 07:19:25 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 07:19:25 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doDeleteFolder(map[fi_id:121390634]) options=[]
2022/03/03 07:19:29 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 1s to wait for "error_background" error to clear
2022/03/03 07:19:30 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/03 07:19:30 DEBUG : pacer: Rate limited, increasing sleep to 40ms
2022/03/03 07:19:32 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 2s to wait for "error_background" error to clear
2022/03/03 07:19:34 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/03 07:19:34 DEBUG : pacer: Rate limited, increasing sleep to 80ms
2022/03/03 07:19:36 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 4s to wait for "error_background" error to clear
2022/03/03 07:19:40 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/03 07:19:40 DEBUG : pacer: Rate limited, increasing sleep to 160ms
2022/03/03 07:19:44 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 8s to wait for "error_background" error to clear
2022/03/03 07:19:52 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/03 07:19:52 DEBUG : pacer: Rate limited, increasing sleep to 320ms
2022/03/03 07:19:55 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 16s to wait for "error_background" error to clear
2022/03/03 07:20:11 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/03 07:20:11 DEBUG : pacer: Rate limited, increasing sleep to 640ms
2022/03/03 07:20:14 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 32s to wait for "error_background" error to clear
2022/03/03 07:20:46 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/03 07:20:46 DEBUG : pacer: Rate limited, increasing sleep to 1.28s
2022/03/03 07:20:48 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 1m4s to wait for "error_background" error to clear
2022/03/03 07:21:52 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/03 07:21:52 DEBUG : pacer: Rate limited, increasing sleep to 2.56s
2022/03/03 07:21:55 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 2m8s to wait for "error_background" error to clear
2022/03/03 07:24:03 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/03 07:24:03 DEBUG : pacer: Rate limited, increasing sleep to 5.12s
2022/03/03 07:24:18 DEBUG : pacer: Reducing sleep to 3.84s
2022/03/03 07:24:18 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=We are not able to complete the requested operation. We are processing move folder in parent folder. Please try again later. (file_error), err=We are not able to complete the requested operation. We are processing move folder in parent folder. Please try again later. (file_error)
    run.go:126: removing dir "dir/sub" failed - try 1/3: failed to remove directory: We are not able to complete the requested operation. We are processing move folder in parent folder. Please try again later. (file_error)
2022/03/03 07:24:19 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390629 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/03 07:24:23 DEBUG : pacer: Reducing sleep to 2.88s
2022/03/03 07:24:23 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 07:24:23 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390634 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/03 07:24:24 DEBUG : pacer: Reducing sleep to 2.16s
2022/03/03 07:24:24 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 07:24:24 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doDeleteFolder(map[fi_id:121390634]) options=[]
2022/03/03 07:24:26 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 1s to wait for "error_background" error to clear
2022/03/03 07:24:27 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/03 07:24:27 DEBUG : pacer: Rate limited, increasing sleep to 4.32s
2022/03/03 07:24:30 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 2s to wait for "error_background" error to clear
2022/03/03 07:24:32 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/03 07:24:32 DEBUG : pacer: Rate limited, increasing sleep to 8.64s
2022/03/03 07:24:36 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 4s to wait for "error_background" error to clear
2022/03/03 07:24:40 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/03 07:24:40 DEBUG : pacer: Rate limited, increasing sleep to 10s
2022/03/03 07:24:43 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 8s to wait for "error_background" error to clear
2022/03/03 07:24:51 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/03 07:24:52 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 16s to wait for "error_background" error to clear
2022/03/03 07:25:08 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/03 07:25:09 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 32s to wait for "error_background" error to clear
2022/03/03 07:25:41 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/03 07:25:41 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 1m4s to wait for "error_background" error to clear
2022/03/03 07:26:45 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/03 07:26:46 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 2m8s to wait for "error_background" error to clear
2022/03/03 07:28:54 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/03 07:29:12 DEBUG : pacer: Reducing sleep to 7.5s
2022/03/03 07:29:12 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 07:29:12 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390629 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/03 07:29:17 DEBUG : pacer: Reducing sleep to 5.625s
2022/03/03 07:29:17 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 07:29:17 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doDeleteFolder(map[fi_id:121390629]) options=[]
2022/03/03 07:29:21 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 1s to wait for "error_background" error to clear
2022/03/03 07:29:22 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/03 07:29:22 DEBUG : pacer: Rate limited, increasing sleep to 10s
2022/03/03 07:29:26 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 2s to wait for "error_background" error to clear
2022/03/03 07:29:28 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/03 07:29:36 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 4s to wait for "error_background" error to clear
2022/03/03 07:29:40 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/03 07:29:50 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 8s to wait for "error_background" error to clear
2022/03/03 07:29:58 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/03 07:30:01 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 16s to wait for "error_background" error to clear
2022/03/03 07:30:17 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/03 07:30:20 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 32s to wait for "error_background" error to clear
2022/03/03 07:30:52 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/03 07:30:54 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 1m4s to wait for "error_background" error to clear
2022/03/03 07:31:58 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/03 07:32:00 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 2m8s to wait for "error_background" error to clear
2022/03/03 07:34:08 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/03 07:34:28 DEBUG : pacer: Reducing sleep to 7.5s
2022/03/03 07:34:28 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 07:34:28 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390288 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/03 07:34:28 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Token expired - refreshing
2022/03/03 07:34:28 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getTokenByAuthToken(map[authtoken:622506e6346e7ad6-c48bf9558d23a2ae token:*]) options=[]
2022/03/03 07:34:29 DEBUG : pacer: Reducing sleep to 5.625s
2022/03/03 07:34:29 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 07:34:29 DEBUG : Saving config "token" in section "TestFileFabric" of the config file
2022/03/03 07:34:29 DEBUG : Config file has changed externaly - reloading
2022/03/03 07:34:29 DEBUG : Saving config "token_expiry" in section "TestFileFabric" of the config file
2022/03/03 07:34:29 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getApplianceInfo(map[token:*]) options=[]
2022/03/03 07:34:36 DEBUG : pacer: Reducing sleep to 4.21875s
2022/03/03 07:34:36 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 07:34:36 DEBUG : Saving config "version" in section "TestFileFabric" of the config file
2022/03/03 07:34:44 DEBUG : pacer: Reducing sleep to 3.1640625s
2022/03/03 07:34:44 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
--- PASS: TestDirMkdirSub (1689.07s)
=== RUN   TestDirRemove
    run.go:181: Remote "filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5'", Local "Local file system at /tmp/rclone2060667978", Modify Window "1s"
2022/03/03 07:34:44 INFO  : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': poll-interval is not supported by this remote
2022/03/03 07:34:44 NOTICE: filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2022/03/03 07:34:44 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390288 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/03 07:34:46 DEBUG : pacer: Reducing sleep to 2.373046875s
2022/03/03 07:34:46 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 07:34:46 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doCreateNewFolder(map[fi_name:dir fi_pid:121390288]) options=[]
2022/03/03 07:34:52 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 1s to wait for "error_background" error to clear
2022/03/03 07:34:53 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/03 07:34:53 DEBUG : pacer: Rate limited, increasing sleep to 4.74609375s
2022/03/03 07:34:54 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 2s to wait for "error_background" error to clear
2022/03/03 07:34:56 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/03 07:34:56 DEBUG : pacer: Rate limited, increasing sleep to 9.4921875s
2022/03/03 07:35:00 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 4s to wait for "error_background" error to clear
2022/03/03 07:35:04 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/03 07:35:04 DEBUG : pacer: Rate limited, increasing sleep to 10s
2022/03/03 07:35:08 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 8s to wait for "error_background" error to clear
2022/03/03 07:35:16 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/03 07:35:20 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 16s to wait for "error_background" error to clear
2022/03/03 07:35:36 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/03 07:35:40 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 32s to wait for "error_background" error to clear
2022/03/03 07:36:12 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/03 07:36:15 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 1m4s to wait for "error_background" error to clear
2022/03/03 07:37:19 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/03 07:37:22 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 2m8s to wait for "error_background" error to clear
2022/03/03 07:39:30 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/03 07:39:42 DEBUG : pacer: Reducing sleep to 7.5s
2022/03/03 07:39:42 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 07:39:42 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': 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:121390703 fi_size:14 responsetype:json]) options=[]
2022/03/03 07:39:44 DEBUG : pacer: Reducing sleep to 5.625s
2022/03/03 07:39:44 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 07:39:51 DEBUG : pacer: Reducing sleep to 4.21875s
2022/03/03 07:39:51 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doCompleteUpload(map[fi_size:14 remotetime:2001-02-03 04:05:06 uploadcode:84138e174d95b3a2adb7e05cf63b63f3]) options=[]
2022/03/03 07:40:06 DEBUG : pacer: Reducing sleep to 3.1640625s
2022/03/03 07:40:06 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 07:40:06 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390288 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/03 07:40:21 DEBUG : pacer: Reducing sleep to 2.373046875s
2022/03/03 07:40:21 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 07:40:21 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390703 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/03 07:40:33 DEBUG : pacer: Reducing sleep to 1.779785156s
2022/03/03 07:40:33 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 07:40:33 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390288 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/03 07:40:33 DEBUG : pacer: Reducing sleep to 1.334838867s
2022/03/03 07:40:33 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 07:40:33 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390703 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/03 07:40:35 DEBUG : pacer: Reducing sleep to 1.00112915s
2022/03/03 07:40:35 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 07:40:35 ERROR : dir/: Dir.Remove not empty
2022/03/03 07:40:35 DEBUG : dir/file1: Remove: 
2022/03/03 07:40:35 DEBUG : dir: Added virtual directory entry vDel: "file1"
2022/03/03 07:40:35 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doDeleteFile(map[completedeletion:n fi_id:121390705]) options=[]
2022/03/03 07:41:22 DEBUG : pacer: Reducing sleep to 750.846862ms
2022/03/03 07:41:22 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 07:41:22 DEBUG : dir/file1: >Remove: err=<nil>
2022/03/03 07:41:22 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390703 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/03 07:41:44 DEBUG : pacer: Reducing sleep to 563.135146ms
2022/03/03 07:41:44 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 07:41:44 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doDeleteFolder(map[fi_id:121390703]) options=[]
2022/03/03 07:41:59 DEBUG : pacer: Reducing sleep to 422.351359ms
2022/03/03 07:41:59 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 07:41:59 DEBUG : : Added virtual directory entry vDel: "dir"
2022/03/03 07:41:59 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390288 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/03 07:42:04 DEBUG : pacer: Reducing sleep to 316.763519ms
2022/03/03 07:42:04 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 07:42:04 DEBUG : WaitForWriters: timeout=30s
2022/03/03 07:42:04 DEBUG : : Looking for writers
2022/03/03 07:42:04 DEBUG : >WaitForWriters: 
2022/03/03 07:42:04 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390288 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/03 07:42:04 DEBUG : pacer: Reducing sleep to 237.572639ms
2022/03/03 07:42:04 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 07:42:04 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390288 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/03 07:42:05 DEBUG : pacer: Reducing sleep to 178.179479ms
2022/03/03 07:42:05 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
--- PASS: TestDirRemove (440.78s)
=== RUN   TestDirRemoveAll
    run.go:181: Remote "filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5'", Local "Local file system at /tmp/rclone2060667978", Modify Window "1s"
2022/03/03 07:42:05 INFO  : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': poll-interval is not supported by this remote
2022/03/03 07:42:05 NOTICE: filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2022/03/03 07:42:05 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: getFolderContents(map[count:1000 fi_pid:121390288 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/03 07:42:05 DEBUG : pacer: Reducing sleep to 133.634609ms
2022/03/03 07:42:05 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': >rpc: result=Success (ok), err=<nil>
2022/03/03 07:42:05 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': rpc: doCreateNewFolder(map[fi_name:dir fi_pid:121390288]) options=[]
2022/03/03 07:42:07 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 1s to wait for "error_background" error to clear
2022/03/03 07:42:08 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/03 07:42:08 DEBUG : pacer: Rate limited, increasing sleep to 267.269218ms
2022/03/03 07:42:11 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 2s to wait for "error_background" error to clear
2022/03/03 07:42:13 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/03 07:42:13 DEBUG : pacer: Rate limited, increasing sleep to 534.538436ms
2022/03/03 07:42:14 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 4s to wait for "error_background" error to clear
2022/03/03 07:42: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/03 07:42:18 DEBUG : pacer: Rate limited, increasing sleep to 1.069076872s
2022/03/03 07:42:19 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 8s to wait for "error_background" error to clear
2022/03/03 07:42:27 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/03 07:42:27 DEBUG : pacer: Rate limited, increasing sleep to 2.138153744s
2022/03/03 07:42:30 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 16s to wait for "error_background" error to clear
2022/03/03 07:42:46 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/03 07:42:46 DEBUG : pacer: Rate limited, increasing sleep to 4.276307488s
2022/03/03 07:42:49 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 32s to wait for "error_background" error to clear
2022/03/03 07:43:21 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/03 07:43:21 DEBUG : pacer: Rate limited, increasing sleep to 8.552614976s
2022/03/03 07:43:22 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 1m4s to wait for "error_background" error to clear
2022/03/03 07:44:26 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/03 07:44:26 DEBUG : pacer: Rate limited, increasing sleep to 10s
2022/03/03 07:44:30 DEBUG : filefabric root 'rclone-test-zoyijiw0zujumud5xuwoxas5': Sleeping for 2m8s to wait for "error_background" error to clear
panic: test timed out after 2h0m0s

goroutine 4316 [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, 3 minutes]:
testing.(*T).Run(0xc0004c01a0, {0x1968341, 0x46d533}, 0x1a1ab08)
	/usr/local/go/src/testing/testing.go:1307 +0x375
testing.runTests.func1(0xc000603ce0)
	/usr/local/go/src/testing/testing.go:1598 +0x6e
testing.tRunner(0xc0004c01a0, 0xc000341ca0)
	/usr/local/go/src/testing/testing.go:1259 +0x102
testing.runTests(0xc000314080, {0x29f7560, 0x4a, 0x4a}, {0xee8780, 0xc000311230, 0x2a07c20})
	/usr/local/go/src/testing/testing.go:1596 +0x43f
testing.(*M).Run(0xc000314080)
	/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 8 [select]:
go.opencensus.io/stats/view.(*worker).start(0xc0000f7280)
	/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 58 [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 4246 [sleep]:
time.Sleep(0x1dcd650000)
	/usr/local/go/src/runtime/time.go:193 +0x12e
github.com/rclone/rclone/backend/filefabric.(*Fs).shouldRetry(0xc000624500, {0x1d23328, 0xc000040058}, 0xc0003d4cc0, {0x7f44b0132ee0, 0xc0003d4cc0}, {0x1d0cec0, 0xc0003d4cc0}, 0x8)
	/home/rclone/go/src/github.com/rclone/rclone/backend/filefabric/filefabric.go:252 +0x357
github.com/rclone/rclone/backend/filefabric.(*Fs).rpc.func1()
	/home/rclone/go/src/github.com/rclone/rclone/backend/filefabric/filefabric.go:412 +0x205
github.com/rclone/rclone/fs.pacerInvoker(0xc00031e480, 0xc000775501, 0x1cf1060)
	/home/rclone/go/src/github.com/rclone/rclone/fs/pacer.go:88 +0x38
github.com/rclone/rclone/lib/pacer.(*Pacer).call(0xc00031e480, 0xc000775548, 0xa)
	/home/rclone/go/src/github.com/rclone/rclone/lib/pacer/pacer.go:197 +0x85
github.com/rclone/rclone/lib/pacer.(*Pacer).Call(0xc00031e480, 0xc000a0ac60)
	/home/rclone/go/src/github.com/rclone/rclone/lib/pacer/pacer.go:216 +0x90
github.com/rclone/rclone/backend/filefabric.(*Fs).rpc(0xc000624500, {0x1d23328, 0xc000040058}, {0x196ae6a, 0x9}, 0xc000a0ab70, {0x1d0cec0, 0xc0003d4cc0}, {0x0, 0x0, ...})
	/home/rclone/go/src/github.com/rclone/rclone/backend/filefabric/filefabric.go:407 +0x91c
github.com/rclone/rclone/backend/filefabric.(*Fs).CreateDir(0xc000624500, {0x1d23328, 0xc000040058}, {0xc000a0c990, 0x9}, {0x195c228, 0x3})
	/home/rclone/go/src/github.com/rclone/rclone/backend/filefabric/filefabric.go:560 +0x1ad
github.com/rclone/rclone/lib/dircache.(*DirCache)._findDir(0xc000814000, {0x1d23328, 0xc000040058}, {0x195c228, 0x18}, 0x1)
	/home/rclone/go/src/github.com/rclone/rclone/lib/dircache/dircache.go:242 +0x189
github.com/rclone/rclone/lib/dircache.(*DirCache).FindDir(0xc000814000, {0x1d23328, 0xc000040058}, {0x195c228, 0x3}, 0x90)
	/home/rclone/go/src/github.com/rclone/rclone/lib/dircache/dircache.go:205 +0x15a
github.com/rclone/rclone/lib/dircache.(*DirCache).FindPath(0xc000814000, {0x1d23328, 0xc000040058}, {0x195c228, 0x0}, 0x67)
	/home/rclone/go/src/github.com/rclone/rclone/lib/dircache/dircache.go:275 +0xb2
github.com/rclone/rclone/backend/filefabric.(*Fs).createObject(0xc000624500, {0x1d23328, 0xc000040058}, {0x195c228, 0x9}, {0x50, 0x185e680, 0xc000808001}, 0xc000913bc8)
	/home/rclone/go/src/github.com/rclone/rclone/backend/filefabric/filefabric.go:686 +0x51
github.com/rclone/rclone/backend/filefabric.(*Fs).Put(0x0, {0x1d23328, 0xc000040058}, {0x1ce8aa0, 0xc000a0a810}, {0x1d3c6c0, 0xc000364ff0}, {0x0, 0x0, 0x0})
	/home/rclone/go/src/github.com/rclone/rclone/backend/filefabric/filefabric.go:708 +0xe8
github.com/rclone/rclone/fstest.(*Run).WriteObjectTo(0xc0002dee70, {0x1d23328, 0xc000040058}, {0x1d53f38, 0xc000624500}, {0x195c228, 0x9}, {0x1964e1d, 0xe}, {0x1dcd64ff, ...}, ...)
	/home/rclone/go/src/github.com/rclone/rclone/fstest/run.go:277 +0x432
github.com/rclone/rclone/fstest.(*Run).WriteObject(...)
	/home/rclone/go/src/github.com/rclone/rclone/fstest/run.go:294
github.com/rclone/rclone/vfs.dirCreate(0x24)
	/home/rclone/go/src/github.com/rclone/rclone/vfs/dir_test.go:21 +0xe5
github.com/rclone/rclone/vfs.TestDirRemoveAll(0x0)
	/home/rclone/go/src/github.com/rclone/rclone/vfs/dir_test.go:479 +0x47
testing.tRunner(0xc0004569c0, 0x1a1ab08)
	/usr/local/go/src/testing/testing.go:1259 +0x102
created by testing.(*T).Run
	/usr/local/go/src/testing/testing.go:1306 +0x35a

goroutine 75 [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
"./vfs.test -test.v -test.timeout 2h0m0s -remote TestFileFabric: -verbose" - Finished ERROR in 2h0m0.525275922s (try 1/5): exit status 2: Failed []