"./vfs.test -test.v -test.timeout 1h0m0s -remote TestFileFabric: -verbose -test.run '^(TestDirRename|TestFileRename)$/^(minimal,forceCache=true|writes,forceCache=true)$'" - Starting (try 3/5) 2021/07/25 06:12:27 DEBUG : Creating backend with remote "TestFileFabric:rclone-test-julejil3zikirov7labijum8" 2021/07/25 06:12:27 DEBUG : Using config file from "/home/rclone/.rclone.conf" 2021/07/25 06:12:27 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: checkPathExists(map[path:rclone-test-julejil3zikirov7labijum8 pid:120673762]) options=[] 2021/07/25 06:12:27 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:12:27 DEBUG : Creating backend with remote "/tmp/rclone416378569" === RUN TestDirRename run.go:176: Remote "filefabric root 'rclone-test-julejil3zikirov7labijum8'", Local "Local file system at /tmp/rclone416378569", Modify Window "1s" 2021/07/25 06:12:27 INFO : filefabric root 'rclone-test-julejil3zikirov7labijum8': poll-interval is not supported by this remote 2021/07/25 06:12:27 NOTICE: filefabric root 'rclone-test-julejil3zikirov7labijum8': --vfs-cache-mode writes or full is recommended for this remote as it can't stream 2021/07/25 06:12:27 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: getFolderContents(map[count:1000 fi_pid:120673762 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:12:29 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:12:29 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: doCreateNewFolder(map[fi_name:rclone-test-julejil3zikirov7labijum8 fi_pid:120673762]) options=[] 2021/07/25 06:12:33 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:12:33 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: getFolderContents(map[count:1000 fi_pid:121000261 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:12:35 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:12:35 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: doCreateNewFolder(map[fi_name:dir fi_pid:121000261]) options=[] 2021/07/25 06:12:39 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:12:39 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': 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:121000266 fi_size:14 responsetype:json]) options=[] 2021/07/25 06:12:40 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:12:41 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: doCompleteUpload(map[fi_size:14 remotetime:2001-02-03 04:05:06 uploadcode:578b2df0df06faf81ccb43cf8146d564]) options=[] 2021/07/25 06:12:44 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:12:44 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: getFolderContents(map[count:1000 fi_pid:121000261 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:12:45 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:12:45 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: getFolderContents(map[count:1000 fi_pid:121000266 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:12:47 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:12:47 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: getFolderContents(map[count:1000 fi_pid:121000261 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:12:48 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:12:48 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: doInitUpload(map[directuploadsupport:n fi_contenttype:application/octet-stream fi_filename:file3 fi_localtime:2001-02-03 04:05:06 fi_modified:2001-02-03 04:05:06 fi_name:file3 fi_pid:121000266 fi_size:15 responsetype:json]) options=[] 2021/07/25 06:12:49 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:12:50 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: doCompleteUpload(map[fi_size:15 remotetime:2001-02-03 04:05:06 uploadcode:f38acfe65dc607e525fc29e5d2c8109d]) options=[] 2021/07/25 06:12:52 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:12:52 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: getFolderContents(map[count:1000 fi_pid:121000261 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:12:52 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:12:52 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: getFolderContents(map[count:1000 fi_pid:121000266 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:12:54 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:12:54 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: getFolderContents(map[count:1000 fi_pid:121000266 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:12:54 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:12:54 ERROR : dir/not found: Dir.Rename error: file does not exist 2021/07/25 06:12:54 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: getFolderContents(map[count:1000 fi_pid:121000261 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:12:54 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:12:54 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: doRenameFolder(map[fi_id:121000266 fi_name:dir2]) options=[] 2021/07/25 06:13:15 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:13:15 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: getUserBackgroundTasks(map[taskid:1277149]) options=[] 2021/07/25 06:13:17 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:13:17 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': Waiting for task ID 1277149: Rename folder 'S3 Storage/smestoragencw/rclone-test-julejil3zikirov7labijum8/dir2': to completed for 1s - waited 1.983804047s already 2021/07/25 06:13:18 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: getUserBackgroundTasks(map[taskid:1277149]) options=[] 2021/07/25 06:13:19 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:13:19 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': Waiting for task ID 1277149: Rename folder 'S3 Storage/smestoragencw/rclone-test-julejil3zikirov7labijum8/dir2': to completed for 1s - waited 4.867939015s already 2021/07/25 06:13:20 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: getUserBackgroundTasks(map[taskid:1277149]) options=[] 2021/07/25 06:13:22 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:13:22 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': Waiting for task ID 1277149: Rename folder 'S3 Storage/smestoragencw/rclone-test-julejil3zikirov7labijum8/dir2': to completed for 1s - waited 7.321966738s already 2021/07/25 06:13:23 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: getUserBackgroundTasks(map[taskid:1277149]) options=[] 2021/07/25 06:13:25 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:13:25 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': Waiting for task ID 1277149: Rename folder 'S3 Storage/smestoragencw/rclone-test-julejil3zikirov7labijum8/dir2': to completed for 1s - waited 9.978120263s already 2021/07/25 06:13:26 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: getUserBackgroundTasks(map[taskid:1277149]) options=[] 2021/07/25 06:13:27 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:13:27 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': Waiting for task ID 1277149: Rename folder 'S3 Storage/smestoragencw/rclone-test-julejil3zikirov7labijum8/dir2': to completed for 1s - waited 12.384300042s already 2021/07/25 06:13:28 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: getUserBackgroundTasks(map[taskid:1277149]) options=[] 2021/07/25 06:13:29 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:13:29 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': Waiting for task ID 1277149: Rename folder 'S3 Storage/smestoragencw/rclone-test-julejil3zikirov7labijum8/dir2': to completed for 1s - waited 14.888783328s already 2021/07/25 06:13:30 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: getUserBackgroundTasks(map[taskid:1277149]) options=[] 2021/07/25 06:13:34 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:13:34 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': Waiting for task ID 1277149: Rename folder 'S3 Storage/smestoragencw/rclone-test-julejil3zikirov7labijum8/dir2': to completed for 1s - waited 19.620413887s already 2021/07/25 06:13:35 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: getUserBackgroundTasks(map[taskid:1277149]) options=[] 2021/07/25 06:13:37 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:13:37 DEBUG : dir: Updating dir with dir2 0xc0001a06c0 2021/07/25 06:13:37 DEBUG : dir: forgetting directory cache 2021/07/25 06:13:37 DEBUG : : Added virtual directory entry vDel: "dir" 2021/07/25 06:13:37 DEBUG : : Added virtual directory entry vAddDir: "dir2" 2021/07/25 06:13:37 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: getFolderContents(map[count:1000 fi_pid:121000261 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:13:39 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:13:39 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: getFolderContents(map[count:1000 fi_pid:121000266 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:13:41 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:13:41 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: getFolderContents(map[count:1000 fi_pid:121000261 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:13:41 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:13:41 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: getFolderContents(map[count:1000 fi_pid:121000266 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:13:41 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:13:41 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: checkPathExists(map[path:file2 pid:121000261]) options=[] 2021/07/25 06:13:42 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:13:42 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: doRenameFile(map[fi_id:121000270 fi_name:file2.vufeqok4]) options=[] 2021/07/25 06:13:53 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:13:53 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: doMoveFiles(map[dir_id:121000261 fi_ids:121000270]) options=[] 2021/07/25 06:14:29 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Succcess. (ok), err= 2021/07/25 06:14:29 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: doRenameFile(map[fi_id:121000270 fi_name:file2]) options=[] 2021/07/25 06:14:42 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:14:42 INFO : dir2/file1: Moved (server-side) to: file2 2021/07/25 06:14:42 DEBUG : file2: Updating file with file2 0xc0000d58c0 2021/07/25 06:14:42 DEBUG : dir2: Added virtual directory entry vDel: "file1" 2021/07/25 06:14:42 DEBUG : : Added virtual directory entry vAddFile: "file2" 2021/07/25 06:14:42 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: getFolderContents(map[count:1000 fi_pid:121000261 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:14:43 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:14:43 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: getFolderContents(map[count:1000 fi_pid:121000266 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:14:45 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:14:45 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: checkPathExists(map[path:dir2/file3 pid:121000261]) options=[] 2021/07/25 06:14:45 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:14:45 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: doDeleteFile(map[completedeletion:n fi_id:121000271]) options=[] 2021/07/25 06:14:56 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:14:56 INFO : dir2/file3: Deleted 2021/07/25 06:14:56 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: doRenameFile(map[fi_id:121000270 fi_name:file3.pisuvud3]) options=[] 2021/07/25 06:15:08 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:15:08 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: doMoveFiles(map[dir_id:121000266 fi_ids:121000270]) options=[] 2021/07/25 06:15:41 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Succcess. (ok), err= 2021/07/25 06:15:41 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: doRenameFile(map[fi_id:121000270 fi_name:file3]) options=[] 2021/07/25 06:15:52 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:15:52 INFO : file2: Moved (server-side) to: dir2/file3 2021/07/25 06:15:52 DEBUG : dir2/file3: Updating file with dir2/file3 0xc0000d58c0 2021/07/25 06:15:52 DEBUG : : Added virtual directory entry vDel: "file2" 2021/07/25 06:15:52 DEBUG : dir2: Added virtual directory entry vAddFile: "file3" 2021/07/25 06:15:52 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: getFolderContents(map[count:1000 fi_pid:121000261 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:15:54 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:15:54 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: getFolderContents(map[count:1000 fi_pid:121000266 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:15:55 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:15:55 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: getFolderContents(map[count:1000 fi_pid:121000261 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:15:55 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:15:55 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: doCreateNewFolder(map[fi_name:empty directory fi_pid:121000261]) options=[] 2021/07/25 06:16:01 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:16:01 DEBUG : : Added virtual directory entry vAddDir: "empty directory" 2021/07/25 06:16:01 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: getFolderContents(map[count:1000 fi_pid:121000261 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:16:03 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:16:03 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: doRenameFolder(map[fi_id:121000287 fi_name:renamed empty directory]) options=[] 2021/07/25 06:16:15 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err=json: cannot unmarshal number into Go struct field FileResponse.taskid of type string 2021/07/25 06:16:15 ERROR : empty directory: Dir.Rename error: failed to rename leaf: json: cannot unmarshal number into Go struct field FileResponse.taskid of type string dir_test.go:582: Error Trace: dir_test.go:582 Error: Received unexpected error: json: cannot unmarshal number into Go struct field FileResponse.taskid of type string failed to rename leaf github.com/rclone/rclone/backend/filefabric.(*Fs).renameLeaf /home/rclone/go/src/github.com/rclone/rclone/backend/filefabric/filefabric.go:888 github.com/rclone/rclone/backend/filefabric.(*Fs).move /home/rclone/go/src/github.com/rclone/rclone/backend/filefabric/filefabric.go:943 github.com/rclone/rclone/backend/filefabric.(*Fs).DirMove /home/rclone/go/src/github.com/rclone/rclone/backend/filefabric/filefabric.go:1022 github.com/rclone/rclone/fs/operations.DirMove /home/rclone/go/src/github.com/rclone/rclone/fs/operations/operations.go:2005 github.com/rclone/rclone/vfs.(*Dir).Rename /home/rclone/go/src/github.com/rclone/rclone/vfs/dir.go:1019 github.com/rclone/rclone/vfs.TestDirRename /home/rclone/go/src/github.com/rclone/rclone/vfs/dir_test.go:581 testing.tRunner /usr/local/go/src/testing/testing.go:1123 runtime.goexit /usr/local/go/src/runtime/asm_amd64.s:1374 Test: TestDirRename dir_test.go:252: Error Trace: dir_test.go:252 dir_test.go:583 Error: Not equal: expected: []string{"dir2,0,true", "renamed empty directory,0,true"} actual : []string{"dir2,0,true", "empty directory,0,true"} Diff: --- Expected +++ Actual @@ -2,3 +2,3 @@ (string) (len=11) "dir2,0,true", - (string) (len=30) "renamed empty directory,0,true" + (string) (len=22) "empty directory,0,true" } Test: TestDirRename 2021/07/25 06:16:15 DEBUG : WaitForWriters: timeout=10s 2021/07/25 06:16:15 DEBUG : dir2: Looking for writers 2021/07/25 06:16:15 DEBUG : file3: reading active writers 2021/07/25 06:16:15 DEBUG : empty directory: Looking for writers 2021/07/25 06:16:15 DEBUG : : Looking for writers 2021/07/25 06:16:15 DEBUG : dir2: reading active writers 2021/07/25 06:16:15 DEBUG : empty directory: reading active writers 2021/07/25 06:16:15 DEBUG : >WaitForWriters: 2021/07/25 06:16:15 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: getFolderContents(map[count:1000 fi_pid:121000261 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:16:16 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:16:16 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: getFolderContents(map[count:1000 fi_pid:121000287 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:16:16 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: getFolderContents(map[count:1000 fi_pid:121000266 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:16:17 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:16:17 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: doDeleteFile(map[completedeletion:n fi_id:121000270]) options=[] 2021/07/25 06:16:18 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:16:34 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:16:34 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: getFolderContents(map[count:1000 fi_pid:121000287 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:16:36 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:16:36 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: doDeleteFolder(map[fi_id:121000287]) options=[] 2021/07/25 06:16:40 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:16:40 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: getFolderContents(map[count:1000 fi_pid:121000266 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:16:42 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:16:42 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: doDeleteFolder(map[fi_id:121000266]) options=[] 2021/07/25 06:16:46 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:16:46 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: getFolderContents(map[count:1000 fi_pid:121000261 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:16:46 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= --- FAIL: TestDirRename (259.07s) === RUN TestFileRename === RUN TestFileRename/minimal,forceCache=true run.go:176: Remote "filefabric root 'rclone-test-julejil3zikirov7labijum8'", Local "Local file system at /tmp/rclone416378569", Modify Window "1s" 2021/07/25 06:16:46 INFO : filefabric root 'rclone-test-julejil3zikirov7labijum8': poll-interval is not supported by this remote 2021/07/25 06:16:46 NOTICE: filefabric root 'rclone-test-julejil3zikirov7labijum8': --vfs-cache-mode writes or full is recommended for this remote as it can't stream 2021/07/25 06:16:46 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestFileFabric/rclone-test-julejil3zikirov7labijum8" 2021/07/25 06:16:46 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestFileFabric/rclone-test-julejil3zikirov7labijum8" 2021/07/25 06:16:46 DEBUG : Creating backend with remote "/home/rclone/.cache/rclone/vfs/TestFileFabric/rclone-test-julejil3zikirov7labijum8" 2021/07/25 06:16:46 DEBUG : Config file has changed externaly - reloading 2021/07/25 06:16:46 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: getFolderContents(map[count:1000 fi_pid:121000261 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:16:46 INFO : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) 2021/07/25 06:16:47 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:16:47 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: doCreateNewFolder(map[fi_name:dir fi_pid:121000261]) options=[] 2021/07/25 06:16:53 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:16:53 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': 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:121000291 fi_size:14 responsetype:json]) options=[] 2021/07/25 06:16:54 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:16:55 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: doCompleteUpload(map[fi_size:14 remotetime:2001-02-03 04:05:06 uploadcode:95f00484eb57711c3c9b834e2fd57242]) options=[] 2021/07/25 06:16:57 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:16:57 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: getFolderContents(map[count:1000 fi_pid:121000261 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:16:58 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:16:58 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: getFolderContents(map[count:1000 fi_pid:121000291 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:17:00 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:17:00 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: getFolderContents(map[count:1000 fi_pid:121000261 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:17:01 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:17:01 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: getFolderContents(map[count:1000 fi_pid:121000291 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:17:01 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:17:01 DEBUG : dir/file1: Open: flags=O_RDWR|O_CREATE|O_TRUNC 2021/07/25 06:17:01 DEBUG : dir/file1: newRWFileHandle: 2021/07/25 06:17:01 DEBUG : dir/file1(0xc0001e9540): openPending: 2021/07/25 06:17:01 DEBUG : dir/file1: vfs cache: checking remote fingerprint "14,2001-02-03 04:05:06 +0000 UTC" against cached fingerprint "" 2021/07/25 06:17:01 DEBUG : dir/file1: vfs cache: truncate to size=14 2021/07/25 06:17:01 DEBUG : dir: Added virtual directory entry vAddFile: "file1" 2021/07/25 06:17:01 DEBUG : dir/file1(0xc0001e9540): >openPending: err= 2021/07/25 06:17:01 DEBUG : dir/file1: vfs cache: truncate to size=0 2021/07/25 06:17:01 DEBUG : dir/file1: >newRWFileHandle: err= 2021/07/25 06:17:01 DEBUG : dir: Added virtual directory entry vAddFile: "file1" 2021/07/25 06:17:01 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2021/07/25 06:17:01 DEBUG : dir/file1(0xc0001e9540): _writeAt: size=14, off=0 2021/07/25 06:17:01 DEBUG : dir/file1(0xc0001e9540): >_writeAt: n=14, err= 2021/07/25 06:17:01 DEBUG : dir/file1: vfs cache: setting modification time to 2001-02-03 04:05:06.499999999 +0000 UTC 2021/07/25 06:17:01 DEBUG : dir/file1(0xc0001e9540): close: 2021/07/25 06:17:01 DEBUG : vfs cache: looking for range={Pos:0 Size:14} in [{Pos:0 Size:14}] - present true 2021/07/25 06:17:01 DEBUG : dir/file1: vfs cache: setting modification time to 2001-02-03 04:05:06.499999999 +0000 UTC 2021/07/25 06:17:01 INFO : dir/file1: vfs cache: queuing for upload in 100ms 2021/07/25 06:17:01 DEBUG : dir/file1(0xc0001e9540): >close: err= 2021/07/25 06:17:01 DEBUG : WaitForWriters: timeout=10s 2021/07/25 06:17:01 DEBUG : dir: Looking for writers 2021/07/25 06:17:01 DEBUG : file1: reading active writers 2021/07/25 06:17:01 DEBUG : : Looking for writers 2021/07/25 06:17:01 DEBUG : dir: reading active writers 2021/07/25 06:17:01 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms 2021/07/25 06:17:01 DEBUG : dir: Looking for writers 2021/07/25 06:17:01 DEBUG : file1: reading active writers 2021/07/25 06:17:01 DEBUG : : Looking for writers 2021/07/25 06:17:01 DEBUG : dir: reading active writers 2021/07/25 06:17:01 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms 2021/07/25 06:17:01 DEBUG : dir: Looking for writers 2021/07/25 06:17:01 DEBUG : file1: reading active writers 2021/07/25 06:17:01 DEBUG : : Looking for writers 2021/07/25 06:17:01 DEBUG : dir: reading active writers 2021/07/25 06:17:01 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms 2021/07/25 06:17:01 DEBUG : dir: Looking for writers 2021/07/25 06:17:01 DEBUG : file1: reading active writers 2021/07/25 06:17:01 DEBUG : : Looking for writers 2021/07/25 06:17:01 DEBUG : dir: reading active writers 2021/07/25 06:17:01 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms 2021/07/25 06:17:01 DEBUG : dir/file1: vfs cache: starting upload 2021/07/25 06:17:01 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': 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:121000291 fi_size:14 responsetype:json]) options=[] 2021/07/25 06:17:01 DEBUG : dir: Looking for writers 2021/07/25 06:17:01 DEBUG : file1: reading active writers 2021/07/25 06:17:01 DEBUG : : Looking for writers 2021/07/25 06:17:01 DEBUG : dir: reading active writers 2021/07/25 06:17:01 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms 2021/07/25 06:17:01 DEBUG : dir: Looking for writers 2021/07/25 06:17:01 DEBUG : file1: reading active writers 2021/07/25 06:17:01 DEBUG : : Looking for writers 2021/07/25 06:17:01 DEBUG : dir: reading active writers 2021/07/25 06:17:01 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms 2021/07/25 06:17:02 DEBUG : dir: Looking for writers 2021/07/25 06:17:02 DEBUG : file1: reading active writers 2021/07/25 06:17:02 DEBUG : : Looking for writers 2021/07/25 06:17:02 DEBUG : dir: reading active writers 2021/07/25 06:17:02 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms 2021/07/25 06:17:02 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:17:02 DEBUG : dir: Looking for writers 2021/07/25 06:17:02 DEBUG : file1: reading active writers 2021/07/25 06:17:02 DEBUG : : Looking for writers 2021/07/25 06:17:02 DEBUG : dir: reading active writers 2021/07/25 06:17:02 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/07/25 06:17:03 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: doCompleteUpload(map[fi_size:14 remotetime:2001-02-03 04:05:06 uploadcode:c4b1cb049ec149c9c6ca2588f7d3720e]) options=[] 2021/07/25 06:17:03 DEBUG : dir: Looking for writers 2021/07/25 06:17:03 DEBUG : file1: reading active writers 2021/07/25 06:17:03 DEBUG : : Looking for writers 2021/07/25 06:17:03 DEBUG : dir: reading active writers 2021/07/25 06:17:03 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/07/25 06:17:04 DEBUG : dir: Looking for writers 2021/07/25 06:17:04 DEBUG : file1: reading active writers 2021/07/25 06:17:04 DEBUG : : Looking for writers 2021/07/25 06:17:04 DEBUG : dir: reading active writers 2021/07/25 06:17:04 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/07/25 06:17:05 DEBUG : dir: Looking for writers 2021/07/25 06:17:05 DEBUG : file1: reading active writers 2021/07/25 06:17:05 DEBUG : : Looking for writers 2021/07/25 06:17:05 DEBUG : dir: reading active writers 2021/07/25 06:17:05 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/07/25 06:17:06 DEBUG : dir: Looking for writers 2021/07/25 06:17:06 DEBUG : file1: reading active writers 2021/07/25 06:17:06 DEBUG : : Looking for writers 2021/07/25 06:17:06 DEBUG : dir: reading active writers 2021/07/25 06:17:06 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/07/25 06:17:07 DEBUG : dir: Looking for writers 2021/07/25 06:17:07 DEBUG : file1: reading active writers 2021/07/25 06:17:07 DEBUG : : Looking for writers 2021/07/25 06:17:07 DEBUG : dir: reading active writers 2021/07/25 06:17:07 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/07/25 06:17:08 DEBUG : dir: Looking for writers 2021/07/25 06:17:08 DEBUG : file1: reading active writers 2021/07/25 06:17:08 DEBUG : : Looking for writers 2021/07/25 06:17:08 DEBUG : dir: reading active writers 2021/07/25 06:17:08 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/07/25 06:17:09 DEBUG : dir: Looking for writers 2021/07/25 06:17:09 DEBUG : file1: reading active writers 2021/07/25 06:17:09 DEBUG : : Looking for writers 2021/07/25 06:17:09 DEBUG : dir: reading active writers 2021/07/25 06:17:09 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/07/25 06:17:10 DEBUG : dir: Looking for writers 2021/07/25 06:17:10 DEBUG : file1: reading active writers 2021/07/25 06:17:10 DEBUG : : Looking for writers 2021/07/25 06:17:10 DEBUG : dir: reading active writers 2021/07/25 06:17:10 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/07/25 06:17:11 ERROR : Exiting even though 0 writers active and 1 cache items in use after 10s Cache{ "dir/file1": &{c:0xc0001a1140 mu:{state:0 sema:0} cond:0xc0001e94c0 name:dir/file1 opens:0 downloaders: o:0xc0008c9920 fd: modified:false info:{ModTime:{wall:499999999 ext:63116769906 loc:} ATime:{wall:13850642908501558827 ext:274149268468 loc:0x2b68fc0} Size:14 Rs:[{Pos:0 Size:14}] Fingerprint:14,2001-02-03 04:05:06 +0000 UTC Dirty:true} writeBackID:1 pendingAccesses:0 beingReset:false}, } 2021/07/25 06:17:11 DEBUG : >WaitForWriters: 2021/07/25 06:17:11 DEBUG : dir/file1: Open: flags=O_RDONLY 2021/07/25 06:17:11 DEBUG : dir/file1: newRWFileHandle: 2021/07/25 06:17:11 DEBUG : dir/file1: >newRWFileHandle: err= 2021/07/25 06:17:11 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2021/07/25 06:17:11 DEBUG : dir/file1(0xc0001e9c80): _readAt: size=512, off=0 2021/07/25 06:17:11 DEBUG : dir/file1(0xc0001e9c80): openPending: 2021/07/25 06:17:11 DEBUG : dir/file1: vfs cache: checking remote fingerprint "14,2001-02-03 04:05:06 +0000 UTC" against cached fingerprint "14,2001-02-03 04:05:06 +0000 UTC" 2021/07/25 06:17:11 DEBUG : dir/file1: vfs cache: truncate to size=14 2021/07/25 06:17:11 DEBUG : dir: Added virtual directory entry vAddFile: "file1" 2021/07/25 06:17:11 DEBUG : dir/file1(0xc0001e9c80): >openPending: err= 2021/07/25 06:17:11 DEBUG : vfs cache: looking for range={Pos:0 Size:14} in [{Pos:0 Size:14}] - present true 2021/07/25 06:17:11 DEBUG : dir/file1(0xc0001e9c80): >_readAt: n=14, err=EOF 2021/07/25 06:17:11 DEBUG : dir/file1(0xc0001e9c80): close: 2021/07/25 06:17:11 DEBUG : vfs cache: looking for range={Pos:0 Size:14} in [{Pos:0 Size:14}] - present true 2021/07/25 06:17:11 DEBUG : dir/file1: vfs cache: setting modification time to 2001-02-03 04:05:06.499999999 +0000 UTC 2021/07/25 06:17:11 INFO : dir/file1: vfs cache: queuing for upload in 100ms 2021/07/25 06:17:11 DEBUG : dir/file1(0xc0001e9c80): >close: err= 2021/07/25 06:17:11 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: getFolderContents(map[count:1000 fi_pid:121000261 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:17:14 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:17:14 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: getFolderContents(map[count:1000 fi_pid:121000291 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:17:18 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= fstest.go:299: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:302: Flushing the directory cache 2021/07/25 06:17:19 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: getFolderContents(map[count:1000 fi_pid:120673762 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:17:19 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:17:19 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: getFolderContents(map[count:1000 fi_pid:121000261 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:17:20 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:17:20 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: getFolderContents(map[count:1000 fi_pid:121000291 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:17:20 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= fstest.go:299: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:302: Flushing the directory cache 2021/07/25 06:17:22 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: getFolderContents(map[count:1000 fi_pid:120673762 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:17:22 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:17:22 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: getFolderContents(map[count:1000 fi_pid:121000261 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:17:22 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:17:22 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: getFolderContents(map[count:1000 fi_pid:121000291 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:17:23 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= fstest.go:299: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:302: Flushing the directory cache fstest.go:306: Error Trace: fstest.go:306 fstest.go:339 fstest.go:351 file_test.go:343 file_test.go:418 Error: Should be true Test: TestFileRename/minimal,forceCache=true Messages: listing wrong, want dir/file1 (14) got dir/file1 (14), dir/file1_2021-07-25_06-17-04 (14) fstest.go:192: Error Trace: fstest.go:192 fstest.go:309 fstest.go:339 fstest.go:351 file_test.go:343 file_test.go:418 Error: Should be true Test: TestFileRename/minimal,forceCache=true Messages: Unexpected file "dir/file1_2021-07-25_06-17-04" 2021/07/25 06:17:27 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: getFolderContents(map[count:1000 fi_pid:120673762 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:17:28 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:17:28 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: checkPathExists(map[path:newLeaf pid:121000261]) options=[] 2021/07/25 06:17:29 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:17:29 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: getFolderContents(map[count:1000 fi_pid:121000261 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:17:30 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:17:30 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: doRenameFile(map[fi_id:121000292 fi_name:newLeaf.pidafem8]) options=[] 2021/07/25 06:17:40 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:17:40 INFO : dir/file1: Copied (replaced existing) 2021/07/25 06:17:40 DEBUG : dir/file1: vfs cache: writeback object to VFS layer 2021/07/25 06:17:40 DEBUG : dir/file1: Not setting pending mod time 2001-02-03 04:05:06.499999999 +0000 UTC as it is already set 2021/07/25 06:17:40 DEBUG : : Added virtual directory entry vAddFile: "newLeaf" 2021/07/25 06:17:40 INFO : dir/file1: vfs cache: upload succeeded try #1 2021/07/25 06:17:45 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:17:45 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: doMoveFiles(map[dir_id:121000261 fi_ids:121000292]) options=[] 2021/07/25 06:17:46 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item dir/file1 not removed, freed 0 bytes 2021/07/25 06:17:46 INFO : vfs cache: cleaned: objects 1 (was 1) in use 0, to upload 0, uploading 0, total size 14 (was 14) 2021/07/25 06:17:49 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': Sleeping for 6s to wait for "error_background" error to clear 2021/07/25 06:17:55 DEBUG : pacer: low level retry 1/10 (error Can not move S3 Storage/smestoragencw/rclone-test-julejil3zikirov7labijum8/dir/newLeaf.pidafem8 now. We are not able to complete the requested operation. We are processing move folder in parent folder. Please try again later. (error_background)) 2021/07/25 06:17:55 DEBUG : pacer: Rate limited, increasing sleep to 40ms 2021/07/25 06:17:58 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': Sleeping for 6s to wait for "error_background" error to clear 2021/07/25 06:18:04 DEBUG : pacer: low level retry 2/10 (error Can not move S3 Storage/smestoragencw/rclone-test-julejil3zikirov7labijum8/dir/newLeaf.pidafem8 now. We are not able to complete the requested operation. We are processing move folder in parent folder. Please try again later. (error_background)) 2021/07/25 06:18:04 DEBUG : pacer: Rate limited, increasing sleep to 80ms 2021/07/25 06:18:06 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': Sleeping for 6s to wait for "error_background" error to clear 2021/07/25 06:18:12 DEBUG : pacer: low level retry 3/10 (error Can not move S3 Storage/smestoragencw/rclone-test-julejil3zikirov7labijum8/dir/newLeaf.pidafem8 now. We are not able to complete the requested operation. We are processing move folder in parent folder. Please try again later. (error_background)) 2021/07/25 06:18:12 DEBUG : pacer: Rate limited, increasing sleep to 160ms 2021/07/25 06:18:18 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': Sleeping for 6s to wait for "error_background" error to clear 2021/07/25 06:18:24 DEBUG : pacer: low level retry 4/10 (error Can not move S3 Storage/smestoragencw/rclone-test-julejil3zikirov7labijum8/dir/newLeaf.pidafem8 now. We are not able to complete the requested operation. We are processing move folder in parent folder. Please try again later. (error_background)) 2021/07/25 06:18:24 DEBUG : pacer: Rate limited, increasing sleep to 320ms 2021/07/25 06:18:27 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': Sleeping for 6s to wait for "error_background" error to clear 2021/07/25 06:18:33 DEBUG : pacer: low level retry 5/10 (error Can not move S3 Storage/smestoragencw/rclone-test-julejil3zikirov7labijum8/dir/newLeaf.pidafem8 now. We are not able to complete the requested operation. We are processing move folder in parent folder. Please try again later. (error_background)) 2021/07/25 06:18:33 DEBUG : pacer: Rate limited, increasing sleep to 640ms 2021/07/25 06:18:36 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': Sleeping for 6s to wait for "error_background" error to clear 2021/07/25 06:18:42 DEBUG : pacer: low level retry 6/10 (error Can not move S3 Storage/smestoragencw/rclone-test-julejil3zikirov7labijum8/dir/newLeaf.pidafem8 now. We are not able to complete the requested operation. We are processing move folder in parent folder. Please try again later. (error_background)) 2021/07/25 06:18:42 DEBUG : pacer: Rate limited, increasing sleep to 1.28s 2021/07/25 06:18:45 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': Sleeping for 6s to wait for "error_background" error to clear 2021/07/25 06:18:46 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item dir/file1 not removed, freed 0 bytes 2021/07/25 06:18:46 INFO : vfs cache: cleaned: objects 1 (was 1) in use 0, to upload 0, uploading 0, total size 14 (was 14) 2021/07/25 06:18:51 DEBUG : pacer: low level retry 7/10 (error Can not move S3 Storage/smestoragencw/rclone-test-julejil3zikirov7labijum8/dir/newLeaf.pidafem8 now. We are not able to complete the requested operation. We are processing move folder in parent folder. Please try again later. (error_background)) 2021/07/25 06:18:51 DEBUG : pacer: Rate limited, increasing sleep to 2.56s 2021/07/25 06:18:54 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': Sleeping for 6s to wait for "error_background" error to clear 2021/07/25 06:19:00 DEBUG : pacer: low level retry 8/10 (error Can not move S3 Storage/smestoragencw/rclone-test-julejil3zikirov7labijum8/dir/newLeaf.pidafem8 now. We are not able to complete the requested operation. We are processing move folder in parent folder. Please try again later. (error_background)) 2021/07/25 06:19:00 DEBUG : pacer: Rate limited, increasing sleep to 5.12s 2021/07/25 06:19:04 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': Sleeping for 6s to wait for "error_background" error to clear 2021/07/25 06:19:10 DEBUG : pacer: low level retry 9/10 (error Can not move S3 Storage/smestoragencw/rclone-test-julejil3zikirov7labijum8/dir/newLeaf.pidafem8 now. We are not able to complete the requested operation. We are processing move folder in parent folder. Please try again later. (error_background)) 2021/07/25 06:19:10 DEBUG : pacer: Rate limited, increasing sleep to 10s 2021/07/25 06:19:15 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': Sleeping for 6s to wait for "error_background" error to clear 2021/07/25 06:19:21 DEBUG : pacer: low level retry 10/10 (error Can not move S3 Storage/smestoragencw/rclone-test-julejil3zikirov7labijum8/dir/newLeaf.pidafem8 now. We are not able to complete the requested operation. We are processing move folder in parent folder. Please try again later. (error_background)) 2021/07/25 06:19:21 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Can not move S3 Storage/smestoragencw/rclone-test-julejil3zikirov7labijum8/dir/newLeaf.pidafem8 now. We are not able to complete the requested operation. We are processing move folder in parent folder. Please try again later. (error_background), err=Can not move S3 Storage/smestoragencw/rclone-test-julejil3zikirov7labijum8/dir/newLeaf.pidafem8 now. We are not able to complete the requested operation. We are processing move folder in parent folder. Please try again later. (error_background) 2021/07/25 06:19:21 ERROR : dir/file1: Couldn't move: failed to move file to new directory: Can not move S3 Storage/smestoragencw/rclone-test-julejil3zikirov7labijum8/dir/newLeaf.pidafem8 now. We are not able to complete the requested operation. We are processing move folder in parent folder. Please try again later. (error_background) 2021/07/25 06:19:21 ERROR : newLeaf: File.Rename error: failed to move file to new directory: Can not move S3 Storage/smestoragencw/rclone-test-julejil3zikirov7labijum8/dir/newLeaf.pidafem8 now. We are not able to complete the requested operation. We are processing move folder in parent folder. Please try again later. (error_background) 2021/07/25 06:19:21 ERROR : dir/file1: Dir.Rename error: failed to move file to new directory: Can not move S3 Storage/smestoragencw/rclone-test-julejil3zikirov7labijum8/dir/newLeaf.pidafem8 now. We are not able to complete the requested operation. We are processing move folder in parent folder. Please try again later. (error_background) file_test.go:347: Error Trace: file_test.go:347 file_test.go:418 Error: Received unexpected error: failed to move file to new directory: Can not move S3 Storage/smestoragencw/rclone-test-julejil3zikirov7labijum8/dir/newLeaf.pidafem8 now. We are not able to complete the requested operation. We are processing move folder in parent folder. Please try again later. (error_background) Test: TestFileRename/minimal,forceCache=true 2021/07/25 06:19:21 DEBUG : WaitForWriters: timeout=10s 2021/07/25 06:19:21 DEBUG : dir: Looking for writers 2021/07/25 06:19:21 DEBUG : file1: reading active writers 2021/07/25 06:19:21 DEBUG : : Looking for writers 2021/07/25 06:19:21 DEBUG : dir: reading active writers 2021/07/25 06:19:21 DEBUG : newLeaf: reading active writers 2021/07/25 06:19:21 DEBUG : >WaitForWriters: 2021/07/25 06:19:21 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: getFolderContents(map[count:1000 fi_pid:121000261 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:19:21 DEBUG : vfs cache: cleaner exiting 2021/07/25 06:19:22 DEBUG : pacer: Reducing sleep to 7.5s 2021/07/25 06:19:22 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:19:22 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: getFolderContents(map[count:1000 fi_pid:121000291 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:19:32 DEBUG : pacer: Reducing sleep to 5.625s 2021/07/25 06:19:32 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:19:32 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: doDeleteFile(map[completedeletion:n fi_id:121000292]) options=[] 2021/07/25 06:19:39 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': Sleeping for 6s to wait for "error_background" error to clear 2021/07/25 06:19:45 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)) 2021/07/25 06:19:45 DEBUG : pacer: Rate limited, increasing sleep to 10s 2021/07/25 06:19:56 DEBUG : pacer: Reducing sleep to 7.5s 2021/07/25 06:19:56 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:19:56 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: getFolderContents(map[count:1000 fi_pid:121000291 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:19:58 DEBUG : pacer: Reducing sleep to 5.625s 2021/07/25 06:19:58 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:19:58 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: doDeleteFolder(map[fi_id:121000291]) options=[] 2021/07/25 06:20:06 DEBUG : pacer: Reducing sleep to 4.21875s 2021/07/25 06:20:06 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:20:06 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: getFolderContents(map[count:1000 fi_pid:121000261 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:20:10 DEBUG : pacer: Reducing sleep to 3.1640625s 2021/07/25 06:20:10 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= === RUN TestFileRename/writes,forceCache=true run.go:176: Remote "filefabric root 'rclone-test-julejil3zikirov7labijum8'", Local "Local file system at /tmp/rclone416378569", Modify Window "1s" 2021/07/25 06:20:10 INFO : filefabric root 'rclone-test-julejil3zikirov7labijum8': poll-interval is not supported by this remote 2021/07/25 06:20:10 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestFileFabric/rclone-test-julejil3zikirov7labijum8" 2021/07/25 06:20:10 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestFileFabric/rclone-test-julejil3zikirov7labijum8" 2021/07/25 06:20:10 DEBUG : Creating backend with remote "/home/rclone/.cache/rclone/vfs/TestFileFabric/rclone-test-julejil3zikirov7labijum8" 2021/07/25 06:20:10 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: getFolderContents(map[count:1000 fi_pid:121000261 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:20:10 INFO : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) 2021/07/25 06:20:14 DEBUG : pacer: Reducing sleep to 2.373046875s 2021/07/25 06:20:14 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:20:14 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: doCreateNewFolder(map[fi_name:dir fi_pid:121000261]) options=[] 2021/07/25 06:20:17 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': Sleeping for 6s to wait for "error_background" error to clear 2021/07/25 06:20:23 DEBUG : pacer: low level retry 1/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background)) 2021/07/25 06:20:23 DEBUG : pacer: Rate limited, increasing sleep to 4.74609375s 2021/07/25 06:20:23 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': Sleeping for 6s to wait for "error_background" error to clear 2021/07/25 06:20:29 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)) 2021/07/25 06:20:29 DEBUG : pacer: Rate limited, increasing sleep to 9.4921875s 2021/07/25 06:20:29 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': Sleeping for 6s to wait for "error_background" error to clear 2021/07/25 06:20:35 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)) 2021/07/25 06:20:35 DEBUG : pacer: Rate limited, increasing sleep to 10s 2021/07/25 06:20:39 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': Sleeping for 6s to wait for "error_background" error to clear 2021/07/25 06:20:45 DEBUG : pacer: low level retry 4/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background)) 2021/07/25 06:20:49 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': Sleeping for 6s to wait for "error_background" error to clear 2021/07/25 06:20:55 DEBUG : pacer: low level retry 5/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background)) 2021/07/25 06:20:59 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': Sleeping for 6s to wait for "error_background" error to clear 2021/07/25 06:21:05 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)) 2021/07/25 06:21:09 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': Sleeping for 6s to wait for "error_background" error to clear 2021/07/25 06:21:10 INFO : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) 2021/07/25 06:21:15 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)) 2021/07/25 06:21:19 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': Sleeping for 6s to wait for "error_background" error to clear 2021/07/25 06:21:25 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)) 2021/07/25 06:21:29 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': Sleeping for 6s to wait for "error_background" error to clear 2021/07/25 06:21:35 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)) 2021/07/25 06:21:39 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': Sleeping for 6s to wait for "error_background" error to clear 2021/07/25 06:21:45 DEBUG : pacer: low level retry 10/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)) 2021/07/25 06:21:45 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=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), err=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) run.go:278: Retry Put of "dir/file1" to filefabric root 'rclone-test-julejil3zikirov7labijum8': 1/10 (failed to make directory: failed to create directory: 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)) 2021/07/25 06:21:47 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: getFolderContents(map[count:1000 fi_pid:121000261 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:21:49 DEBUG : pacer: Reducing sleep to 7.5s 2021/07/25 06:21:49 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:21:49 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: doCreateNewFolder(map[fi_name:dir fi_pid:121000261]) options=[] 2021/07/25 06:22:03 DEBUG : pacer: Reducing sleep to 5.625s 2021/07/25 06:22:03 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:22:03 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': 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:121000317 fi_size:14 responsetype:json]) options=[] 2021/07/25 06:22:07 DEBUG : pacer: Reducing sleep to 4.21875s 2021/07/25 06:22:07 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:22:10 INFO : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) 2021/07/25 06:22:13 DEBUG : pacer: Reducing sleep to 3.1640625s 2021/07/25 06:22:13 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: doCompleteUpload(map[fi_size:14 remotetime:2001-02-03 04:05:06 uploadcode:eebd6bc6f8a6681342720061379cd5b6]) options=[] 2021/07/25 06:22:18 DEBUG : pacer: Reducing sleep to 2.373046875s 2021/07/25 06:22:18 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:22:18 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: getFolderContents(map[count:1000 fi_pid:121000261 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:22:21 DEBUG : pacer: Reducing sleep to 1.779785156s 2021/07/25 06:22:21 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:22:21 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: getFolderContents(map[count:1000 fi_pid:121000317 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:22:24 DEBUG : pacer: Reducing sleep to 1.334838867s 2021/07/25 06:22:24 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:22:24 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: getFolderContents(map[count:1000 fi_pid:121000261 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:22:26 DEBUG : pacer: Reducing sleep to 1.00112915s 2021/07/25 06:22:26 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:22:26 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: getFolderContents(map[count:1000 fi_pid:121000317 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:22:27 DEBUG : pacer: Reducing sleep to 750.846862ms 2021/07/25 06:22:27 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:22:27 DEBUG : dir/file1: Open: flags=O_RDWR|O_CREATE|O_TRUNC 2021/07/25 06:22:27 DEBUG : dir/file1: newRWFileHandle: 2021/07/25 06:22:27 DEBUG : dir/file1(0xc000925a40): openPending: 2021/07/25 06:22:27 DEBUG : dir/file1: vfs cache: checking remote fingerprint "14,2001-02-03 04:05:06 +0000 UTC" against cached fingerprint "" 2021/07/25 06:22:27 DEBUG : dir/file1: vfs cache: truncate to size=14 2021/07/25 06:22:27 DEBUG : dir: Added virtual directory entry vAddFile: "file1" 2021/07/25 06:22:27 DEBUG : dir/file1(0xc000925a40): >openPending: err= 2021/07/25 06:22:27 DEBUG : dir/file1: vfs cache: truncate to size=0 2021/07/25 06:22:27 DEBUG : dir/file1: >newRWFileHandle: err= 2021/07/25 06:22:27 DEBUG : dir: Added virtual directory entry vAddFile: "file1" 2021/07/25 06:22:27 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2021/07/25 06:22:27 DEBUG : dir/file1(0xc000925a40): _writeAt: size=14, off=0 2021/07/25 06:22:27 DEBUG : dir/file1(0xc000925a40): >_writeAt: n=14, err= 2021/07/25 06:22:27 DEBUG : dir/file1: vfs cache: setting modification time to 2001-02-03 04:05:06.499999999 +0000 UTC 2021/07/25 06:22:27 DEBUG : dir/file1(0xc000925a40): close: 2021/07/25 06:22:27 DEBUG : vfs cache: looking for range={Pos:0 Size:14} in [{Pos:0 Size:14}] - present true 2021/07/25 06:22:27 DEBUG : dir/file1: vfs cache: setting modification time to 2001-02-03 04:05:06.499999999 +0000 UTC 2021/07/25 06:22:27 INFO : dir/file1: vfs cache: queuing for upload in 100ms 2021/07/25 06:22:27 DEBUG : dir/file1(0xc000925a40): >close: err= 2021/07/25 06:22:27 DEBUG : WaitForWriters: timeout=10s 2021/07/25 06:22:27 DEBUG : dir: Looking for writers 2021/07/25 06:22:27 DEBUG : file1: reading active writers 2021/07/25 06:22:27 DEBUG : : Looking for writers 2021/07/25 06:22:27 DEBUG : dir: reading active writers 2021/07/25 06:22:27 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms 2021/07/25 06:22:27 DEBUG : dir: Looking for writers 2021/07/25 06:22:27 DEBUG : file1: reading active writers 2021/07/25 06:22:27 DEBUG : : Looking for writers 2021/07/25 06:22:27 DEBUG : dir: reading active writers 2021/07/25 06:22:27 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms 2021/07/25 06:22:27 DEBUG : dir: Looking for writers 2021/07/25 06:22:27 DEBUG : file1: reading active writers 2021/07/25 06:22:27 DEBUG : : Looking for writers 2021/07/25 06:22:27 DEBUG : dir: reading active writers 2021/07/25 06:22:27 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms 2021/07/25 06:22:27 DEBUG : dir: Looking for writers 2021/07/25 06:22:27 DEBUG : file1: reading active writers 2021/07/25 06:22:27 DEBUG : : Looking for writers 2021/07/25 06:22:27 DEBUG : dir: reading active writers 2021/07/25 06:22:27 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms 2021/07/25 06:22:27 DEBUG : dir/file1: vfs cache: starting upload 2021/07/25 06:22:27 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': 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:121000317 fi_size:14 responsetype:json]) options=[] 2021/07/25 06:22:27 DEBUG : dir: Looking for writers 2021/07/25 06:22:27 DEBUG : file1: reading active writers 2021/07/25 06:22:27 DEBUG : : Looking for writers 2021/07/25 06:22:27 DEBUG : dir: reading active writers 2021/07/25 06:22:27 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms 2021/07/25 06:22:27 DEBUG : dir: Looking for writers 2021/07/25 06:22:27 DEBUG : file1: reading active writers 2021/07/25 06:22:27 DEBUG : : Looking for writers 2021/07/25 06:22:27 DEBUG : dir: reading active writers 2021/07/25 06:22:27 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms 2021/07/25 06:22:27 DEBUG : dir: Looking for writers 2021/07/25 06:22:27 DEBUG : file1: reading active writers 2021/07/25 06:22:27 DEBUG : : Looking for writers 2021/07/25 06:22:27 DEBUG : dir: reading active writers 2021/07/25 06:22:27 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms 2021/07/25 06:22:28 DEBUG : dir: Looking for writers 2021/07/25 06:22:28 DEBUG : file1: reading active writers 2021/07/25 06:22:28 DEBUG : : Looking for writers 2021/07/25 06:22:28 DEBUG : dir: reading active writers 2021/07/25 06:22:28 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/07/25 06:22:29 DEBUG : dir: Looking for writers 2021/07/25 06:22:29 DEBUG : file1: reading active writers 2021/07/25 06:22:29 DEBUG : : Looking for writers 2021/07/25 06:22:29 DEBUG : dir: reading active writers 2021/07/25 06:22:29 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/07/25 06:22:29 DEBUG : pacer: Reducing sleep to 563.135146ms 2021/07/25 06:22:29 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:22:30 DEBUG : dir: Looking for writers 2021/07/25 06:22:30 DEBUG : file1: reading active writers 2021/07/25 06:22:30 DEBUG : : Looking for writers 2021/07/25 06:22:30 DEBUG : dir: reading active writers 2021/07/25 06:22:30 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/07/25 06:22:30 DEBUG : pacer: Reducing sleep to 422.351359ms 2021/07/25 06:22:30 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: doCompleteUpload(map[fi_size:14 remotetime:2001-02-03 04:05:06 uploadcode:b95284de653783e4d39234fd7fb7f887]) options=[] 2021/07/25 06:22:31 DEBUG : dir: Looking for writers 2021/07/25 06:22:31 DEBUG : file1: reading active writers 2021/07/25 06:22:31 DEBUG : : Looking for writers 2021/07/25 06:22:31 DEBUG : dir: reading active writers 2021/07/25 06:22:31 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/07/25 06:22:32 DEBUG : dir: Looking for writers 2021/07/25 06:22:32 DEBUG : file1: reading active writers 2021/07/25 06:22:32 DEBUG : : Looking for writers 2021/07/25 06:22:32 DEBUG : dir: reading active writers 2021/07/25 06:22:32 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/07/25 06:22:33 DEBUG : dir: Looking for writers 2021/07/25 06:22:33 DEBUG : file1: reading active writers 2021/07/25 06:22:33 DEBUG : : Looking for writers 2021/07/25 06:22:33 DEBUG : dir: reading active writers 2021/07/25 06:22:33 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/07/25 06:22:34 DEBUG : dir: Looking for writers 2021/07/25 06:22:34 DEBUG : file1: reading active writers 2021/07/25 06:22:34 DEBUG : : Looking for writers 2021/07/25 06:22:34 DEBUG : dir: reading active writers 2021/07/25 06:22:34 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/07/25 06:22:35 DEBUG : dir: Looking for writers 2021/07/25 06:22:35 DEBUG : file1: reading active writers 2021/07/25 06:22:35 DEBUG : : Looking for writers 2021/07/25 06:22:35 DEBUG : dir: reading active writers 2021/07/25 06:22:35 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/07/25 06:22:36 DEBUG : dir: Looking for writers 2021/07/25 06:22:36 DEBUG : file1: reading active writers 2021/07/25 06:22:36 DEBUG : : Looking for writers 2021/07/25 06:22:36 DEBUG : dir: reading active writers 2021/07/25 06:22:36 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/07/25 06:22:37 ERROR : Exiting even though 0 writers active and 1 cache items in use after 10s Cache{ "dir/file1": &{c:0xc0001a1200 mu:{state:0 sema:0} cond:0xc000925a00 name:dir/file1 opens:0 downloaders: o:0xc0007cb620 fd: modified:false info:{ModTime:{wall:499999999 ext:63116769906 loc:} ATime:{wall:13850643257876634982 ext:599484509999 loc:0x2b68fc0} Size:14 Rs:[{Pos:0 Size:14}] Fingerprint:14,2001-02-03 04:05:06 +0000 UTC Dirty:true} writeBackID:1 pendingAccesses:0 beingReset:false}, } 2021/07/25 06:22:37 DEBUG : >WaitForWriters: 2021/07/25 06:22:37 DEBUG : dir/file1: Open: flags=O_RDONLY 2021/07/25 06:22:37 DEBUG : dir/file1: newRWFileHandle: 2021/07/25 06:22:37 DEBUG : dir/file1: >newRWFileHandle: err= 2021/07/25 06:22:37 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2021/07/25 06:22:37 DEBUG : dir/file1(0xc000150100): _readAt: size=512, off=0 2021/07/25 06:22:37 DEBUG : dir/file1(0xc000150100): openPending: 2021/07/25 06:22:37 DEBUG : dir/file1: vfs cache: checking remote fingerprint "14,2001-02-03 04:05:06 +0000 UTC" against cached fingerprint "14,2001-02-03 04:05:06 +0000 UTC" 2021/07/25 06:22:37 DEBUG : dir/file1: vfs cache: truncate to size=14 2021/07/25 06:22:37 DEBUG : dir: Added virtual directory entry vAddFile: "file1" 2021/07/25 06:22:37 DEBUG : dir/file1(0xc000150100): >openPending: err= 2021/07/25 06:22:37 DEBUG : vfs cache: looking for range={Pos:0 Size:14} in [{Pos:0 Size:14}] - present true 2021/07/25 06:22:37 DEBUG : dir/file1(0xc000150100): >_readAt: n=14, err=EOF 2021/07/25 06:22:37 DEBUG : dir/file1(0xc000150100): close: 2021/07/25 06:22:37 DEBUG : vfs cache: looking for range={Pos:0 Size:14} in [{Pos:0 Size:14}] - present true 2021/07/25 06:22:37 DEBUG : dir/file1: vfs cache: setting modification time to 2001-02-03 04:05:06.499999999 +0000 UTC 2021/07/25 06:22:37 INFO : dir/file1: vfs cache: queuing for upload in 100ms 2021/07/25 06:22:37 DEBUG : dir/file1(0xc000150100): >close: err= 2021/07/25 06:22:37 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: getFolderContents(map[count:1000 fi_pid:121000261 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:22:37 DEBUG : pacer: Reducing sleep to 316.763519ms 2021/07/25 06:22:37 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:22:37 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: getFolderContents(map[count:1000 fi_pid:121000317 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:22:39 DEBUG : pacer: Reducing sleep to 237.572639ms 2021/07/25 06:22:39 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= fstest.go:299: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:302: Flushing the directory cache 2021/07/25 06:22:40 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: getFolderContents(map[count:1000 fi_pid:120673762 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:22:40 DEBUG : pacer: Reducing sleep to 178.179479ms 2021/07/25 06:22:40 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:22:40 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: getFolderContents(map[count:1000 fi_pid:121000261 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:22:40 DEBUG : pacer: Reducing sleep to 133.634609ms 2021/07/25 06:22:40 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:22:40 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: getFolderContents(map[count:1000 fi_pid:121000317 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:22:41 DEBUG : pacer: Reducing sleep to 100.225956ms 2021/07/25 06:22:41 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= fstest.go:299: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:302: Flushing the directory cache 2021/07/25 06:22:43 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: getFolderContents(map[count:1000 fi_pid:120673762 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:22:43 DEBUG : pacer: Reducing sleep to 75.169467ms 2021/07/25 06:22:43 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:22:43 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: getFolderContents(map[count:1000 fi_pid:121000261 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:22:43 DEBUG : pacer: Reducing sleep to 56.3771ms 2021/07/25 06:22:43 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:22:43 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: getFolderContents(map[count:1000 fi_pid:121000317 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:22:45 DEBUG : pacer: Reducing sleep to 42.282825ms 2021/07/25 06:22:45 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= fstest.go:299: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:302: Flushing the directory cache fstest.go:306: Error Trace: fstest.go:306 fstest.go:339 fstest.go:351 file_test.go:343 file_test.go:418 Error: Should be true Test: TestFileRename/writes,forceCache=true Messages: listing wrong, want dir/file1 (14) got dir/file1 (14), dir/file1_2021-07-25_06-22-30 (14) fstest.go:192: Error Trace: fstest.go:192 fstest.go:309 fstest.go:339 fstest.go:351 file_test.go:343 file_test.go:418 Error: Should be true Test: TestFileRename/writes,forceCache=true Messages: Unexpected file "dir/file1_2021-07-25_06-22-30" 2021/07/25 06:22:49 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: getFolderContents(map[count:1000 fi_pid:120673762 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:22:51 DEBUG : pacer: Reducing sleep to 31.712118ms 2021/07/25 06:22:51 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:22:51 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: checkPathExists(map[path:newLeaf pid:121000261]) options=[] 2021/07/25 06:22:51 DEBUG : pacer: Reducing sleep to 23.784088ms 2021/07/25 06:22:51 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:22:51 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: getFolderContents(map[count:1000 fi_pid:121000261 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:22:53 DEBUG : pacer: Reducing sleep to 20ms 2021/07/25 06:22:53 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:22:53 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: doRenameFile(map[fi_id:121000319 fi_name:newLeaf.pujupon2]) options=[] 2021/07/25 06:22:58 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:22:58 INFO : dir/file1: Copied (replaced existing) 2021/07/25 06:22:58 DEBUG : dir/file1: vfs cache: writeback object to VFS layer 2021/07/25 06:22:58 DEBUG : dir/file1: Not setting pending mod time 2001-02-03 04:05:06.499999999 +0000 UTC as it is already set 2021/07/25 06:22:58 DEBUG : : Added virtual directory entry vAddFile: "newLeaf" 2021/07/25 06:22:58 INFO : dir/file1: vfs cache: upload succeeded try #1 2021/07/25 06:23:02 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:23:02 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: doMoveFiles(map[dir_id:121000261 fi_ids:121000319]) options=[] 2021/07/25 06:23:10 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item dir/file1 not removed, freed 0 bytes 2021/07/25 06:23:10 INFO : vfs cache: cleaned: objects 1 (was 1) in use 0, to upload 0, uploading 0, total size 14 (was 14) 2021/07/25 06:23:37 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Succcess. (ok), err= 2021/07/25 06:23:37 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: doRenameFile(map[fi_id:121000319 fi_name:newLeaf]) options=[] 2021/07/25 06:23:47 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:23:47 INFO : dir/file1: Moved (server-side) to: newLeaf 2021/07/25 06:23:47 INFO : dir/file1: vfs cache: renamed in cache to "newLeaf" 2021/07/25 06:23:47 DEBUG : newLeaf: Updating file with newLeaf 0xc0000d5740 2021/07/25 06:23:47 DEBUG : dir: Added virtual directory entry vDel: "file1" 2021/07/25 06:23:47 DEBUG : : Added virtual directory entry vAddFile: "newLeaf" 2021/07/25 06:23:47 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: getFolderContents(map[count:1000 fi_pid:121000261 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:23:48 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:23:48 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: getFolderContents(map[count:1000 fi_pid:121000317 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:23:50 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:23:50 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: checkPathExists(map[path:dir/file1 pid:121000261]) options=[] 2021/07/25 06:23:50 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:23:50 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: doRenameFile(map[fi_id:121000319 fi_name:file1.lacakup9]) options=[] 2021/07/25 06:24:01 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:24:01 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: doMoveFiles(map[dir_id:121000317 fi_ids:121000319]) options=[] 2021/07/25 06:24:10 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item newLeaf not removed, freed 0 bytes 2021/07/25 06:24:10 INFO : vfs cache: cleaned: objects 1 (was 1) in use 0, to upload 0, uploading 0, total size 14 (was 14) 2021/07/25 06:24:33 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Succcess. (ok), err= 2021/07/25 06:24:33 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: doRenameFile(map[fi_id:121000319 fi_name:file1]) options=[] 2021/07/25 06:24:43 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:24:43 INFO : newLeaf: Moved (server-side) to: dir/file1 2021/07/25 06:24:43 INFO : newLeaf: vfs cache: renamed in cache to "dir/file1" 2021/07/25 06:24:43 DEBUG : dir/file1: Updating file with dir/file1 0xc0000d5740 2021/07/25 06:24:43 DEBUG : : Added virtual directory entry vDel: "newLeaf" 2021/07/25 06:24:43 DEBUG : dir: Added virtual directory entry vAddFile: "file1" 2021/07/25 06:24:43 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: getFolderContents(map[count:1000 fi_pid:121000261 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:24:45 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:24:45 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: getFolderContents(map[count:1000 fi_pid:121000317 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:24:46 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:24:46 DEBUG : dir/file1: Open: flags=O_WRONLY|O_TRUNC 2021/07/25 06:24:46 DEBUG : dir/file1: newRWFileHandle: 2021/07/25 06:24:46 DEBUG : dir/file1(0xc0007e4440): openPending: 2021/07/25 06:24:46 DEBUG : dir/file1: vfs cache: checking remote fingerprint "14,2001-02-03 04:05:06 +0000 UTC" against cached fingerprint "14,2001-02-03 04:05:06 +0000 UTC" 2021/07/25 06:24:46 DEBUG : dir/file1: vfs cache: truncate to size=14 2021/07/25 06:24:46 DEBUG : dir: Added virtual directory entry vAddFile: "file1" 2021/07/25 06:24:46 DEBUG : dir/file1(0xc0007e4440): >openPending: err= 2021/07/25 06:24:46 DEBUG : dir/file1: vfs cache: truncate to size=0 2021/07/25 06:24:46 DEBUG : dir/file1: >newRWFileHandle: err= 2021/07/25 06:24:46 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2021/07/25 06:24:46 DEBUG : dir/file1(0xc0007e4440): _writeAt: size=25, off=0 2021/07/25 06:24:46 DEBUG : dir/file1(0xc0007e4440): >_writeAt: n=25, err= 2021/07/25 06:24:46 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: checkPathExists(map[path:newLeaf pid:121000261]) options=[] 2021/07/25 06:24:47 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:24:47 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: doRenameFile(map[fi_id:121000319 fi_name:newLeaf.menobah4]) options=[] 2021/07/25 06:24:58 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:24:58 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: doMoveFiles(map[dir_id:121000261 fi_ids:121000319]) options=[] 2021/07/25 06:25:10 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item dir/file1 not removed, freed 0 bytes 2021/07/25 06:25:10 INFO : vfs cache: cleaned: objects 1 (was 1) in use 1, to upload 0, uploading 0, total size 25 (was 25) 2021/07/25 06:25:32 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Succcess. (ok), err= 2021/07/25 06:25:32 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: doRenameFile(map[fi_id:121000319 fi_name:newLeaf]) options=[] 2021/07/25 06:25:44 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:25:44 INFO : dir/file1: Moved (server-side) to: newLeaf 2021/07/25 06:25:44 INFO : dir/file1: vfs cache: renamed in cache to "newLeaf" 2021/07/25 06:25:44 DEBUG : newLeaf: Updating file with newLeaf 0xc0000d5740 2021/07/25 06:25:44 DEBUG : dir: Added virtual directory entry vDel: "file1" 2021/07/25 06:25:44 DEBUG : : Added virtual directory entry vAddFile: "newLeaf" 2021/07/25 06:25:44 DEBUG : newLeaf(0xc0007e4440): close: 2021/07/25 06:25:44 DEBUG : vfs cache: looking for range={Pos:0 Size:25} in [{Pos:0 Size:25}] - present true 2021/07/25 06:25:44 DEBUG : newLeaf: vfs cache: setting modification time to 2021-07-25 06:24:46.946896796 +0000 UTC m=+739.424763761 2021/07/25 06:25:44 INFO : newLeaf: vfs cache: queuing for upload in 100ms 2021/07/25 06:25:44 DEBUG : newLeaf(0xc0007e4440): >close: err= 2021/07/25 06:25:44 DEBUG : WaitForWriters: timeout=10s 2021/07/25 06:25:44 DEBUG : dir: Looking for writers 2021/07/25 06:25:44 DEBUG : : Looking for writers 2021/07/25 06:25:44 DEBUG : dir: reading active writers 2021/07/25 06:25:44 DEBUG : newLeaf: reading active writers 2021/07/25 06:25:44 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms 2021/07/25 06:25:44 DEBUG : dir: Looking for writers 2021/07/25 06:25:44 DEBUG : : Looking for writers 2021/07/25 06:25:44 DEBUG : newLeaf: reading active writers 2021/07/25 06:25:44 DEBUG : dir: reading active writers 2021/07/25 06:25:44 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms 2021/07/25 06:25:44 DEBUG : dir: Looking for writers 2021/07/25 06:25:44 DEBUG : : Looking for writers 2021/07/25 06:25:44 DEBUG : dir: reading active writers 2021/07/25 06:25:44 DEBUG : newLeaf: reading active writers 2021/07/25 06:25:44 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms 2021/07/25 06:25:44 DEBUG : dir: Looking for writers 2021/07/25 06:25:44 DEBUG : : Looking for writers 2021/07/25 06:25:44 DEBUG : dir: reading active writers 2021/07/25 06:25:44 DEBUG : newLeaf: reading active writers 2021/07/25 06:25:44 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms 2021/07/25 06:25:44 DEBUG : newLeaf: vfs cache: starting upload 2021/07/25 06:25:44 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: doInitUpload(map[directuploadsupport:n fi_contenttype:application/octet-stream fi_filename:newLeaf fi_localtime:2021-07-25 06:24:46 fi_modified:2021-07-25 06:24:46 fi_name:newLeaf fi_pid:121000261 fi_size:25 responsetype:json]) options=[] 2021/07/25 06:25:44 DEBUG : dir: Looking for writers 2021/07/25 06:25:44 DEBUG : : Looking for writers 2021/07/25 06:25:44 DEBUG : dir: reading active writers 2021/07/25 06:25:44 DEBUG : newLeaf: reading active writers 2021/07/25 06:25:44 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms 2021/07/25 06:25:44 DEBUG : dir: Looking for writers 2021/07/25 06:25:44 DEBUG : : Looking for writers 2021/07/25 06:25:44 DEBUG : dir: reading active writers 2021/07/25 06:25:44 DEBUG : newLeaf: reading active writers 2021/07/25 06:25:44 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms 2021/07/25 06:25:45 DEBUG : dir: Looking for writers 2021/07/25 06:25:45 DEBUG : : Looking for writers 2021/07/25 06:25:45 DEBUG : dir: reading active writers 2021/07/25 06:25:45 DEBUG : newLeaf: reading active writers 2021/07/25 06:25:45 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms 2021/07/25 06:25:45 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:25:45 DEBUG : dir: Looking for writers 2021/07/25 06:25:45 DEBUG : : Looking for writers 2021/07/25 06:25:45 DEBUG : newLeaf: reading active writers 2021/07/25 06:25:45 DEBUG : dir: reading active writers 2021/07/25 06:25:45 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/07/25 06:25:46 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: doCompleteUpload(map[fi_size:25 remotetime:2021-07-25 06:24:46 uploadcode:82c50ad180995b8c545f60e4bb27287f]) options=[] 2021/07/25 06:25:46 DEBUG : dir: Looking for writers 2021/07/25 06:25:46 DEBUG : : Looking for writers 2021/07/25 06:25:46 DEBUG : dir: reading active writers 2021/07/25 06:25:46 DEBUG : newLeaf: reading active writers 2021/07/25 06:25:46 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/07/25 06:25:47 DEBUG : dir: Looking for writers 2021/07/25 06:25:47 DEBUG : : Looking for writers 2021/07/25 06:25:47 DEBUG : dir: reading active writers 2021/07/25 06:25:47 DEBUG : newLeaf: reading active writers 2021/07/25 06:25:47 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/07/25 06:25:48 DEBUG : dir: Looking for writers 2021/07/25 06:25:48 DEBUG : : Looking for writers 2021/07/25 06:25:48 DEBUG : dir: reading active writers 2021/07/25 06:25:48 DEBUG : newLeaf: reading active writers 2021/07/25 06:25:48 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/07/25 06:25:49 DEBUG : dir: Looking for writers 2021/07/25 06:25:49 DEBUG : : Looking for writers 2021/07/25 06:25:49 DEBUG : dir: reading active writers 2021/07/25 06:25:49 DEBUG : newLeaf: reading active writers 2021/07/25 06:25:49 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/07/25 06:25:50 DEBUG : dir: Looking for writers 2021/07/25 06:25:50 DEBUG : : Looking for writers 2021/07/25 06:25:50 DEBUG : newLeaf: reading active writers 2021/07/25 06:25:50 DEBUG : dir: reading active writers 2021/07/25 06:25:50 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/07/25 06:25:51 DEBUG : dir: Looking for writers 2021/07/25 06:25:51 DEBUG : : Looking for writers 2021/07/25 06:25:51 DEBUG : dir: reading active writers 2021/07/25 06:25:51 DEBUG : newLeaf: reading active writers 2021/07/25 06:25:51 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/07/25 06:25:52 DEBUG : dir: Looking for writers 2021/07/25 06:25:52 DEBUG : : Looking for writers 2021/07/25 06:25:52 DEBUG : dir: reading active writers 2021/07/25 06:25:52 DEBUG : newLeaf: reading active writers 2021/07/25 06:25:52 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/07/25 06:25:53 DEBUG : dir: Looking for writers 2021/07/25 06:25:53 DEBUG : : Looking for writers 2021/07/25 06:25:53 DEBUG : dir: reading active writers 2021/07/25 06:25:53 DEBUG : newLeaf: reading active writers 2021/07/25 06:25:53 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/07/25 06:25:54 ERROR : Exiting even though 0 writers active and 1 cache items in use after 10s Cache{ "newLeaf": &{c:0xc0001a1200 mu:{state:0 sema:0} cond:0xc000925a00 name:newLeaf opens:0 downloaders: o:0xc0007f6360 fd: modified:false info:{ModTime:{wall:13850643408067002268 ext:739424763761 loc:0x2b68fc0} ATime:{wall:13850643469974583826 ext:797055319531 loc:0x2b68fc0} Size:25 Rs:[{Pos:0 Size:25}] Fingerprint:14,2001-02-03 04:05:06 +0000 UTC Dirty:true} writeBackID:1 pendingAccesses:0 beingReset:false}, } 2021/07/25 06:25:54 DEBUG : >WaitForWriters: 2021/07/25 06:25:54 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: getFolderContents(map[count:1000 fi_pid:121000261 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:25:54 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:25:54 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: getFolderContents(map[count:1000 fi_pid:121000317 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:25:55 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= fstest.go:299: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:302: Flushing the directory cache 2021/07/25 06:25:56 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: getFolderContents(map[count:1000 fi_pid:120673762 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:25:56 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:25:56 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: getFolderContents(map[count:1000 fi_pid:121000261 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:25:56 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:25:56 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: getFolderContents(map[count:1000 fi_pid:121000317 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:25:57 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= fstest.go:299: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:302: Flushing the directory cache 2021/07/25 06:25:59 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: getFolderContents(map[count:1000 fi_pid:120673762 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:25:59 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:25:59 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: getFolderContents(map[count:1000 fi_pid:121000261 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:26:00 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:26:00 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: getFolderContents(map[count:1000 fi_pid:121000261 from:2 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:26:02 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:26:02 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: getFolderContents(map[count:1000 fi_pid:121000317 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:26:02 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= fstest.go:293: Sleeping for 7s just to make sure 2021/07/25 06:26:09 DEBUG : WaitForWriters: timeout=10s 2021/07/25 06:26:09 DEBUG : dir: Looking for writers 2021/07/25 06:26:09 DEBUG : : Looking for writers 2021/07/25 06:26:09 DEBUG : dir: reading active writers 2021/07/25 06:26:09 DEBUG : newLeaf: reading active writers 2021/07/25 06:26:09 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms 2021/07/25 06:26:09 DEBUG : dir: Looking for writers 2021/07/25 06:26:09 DEBUG : : Looking for writers 2021/07/25 06:26:09 DEBUG : dir: reading active writers 2021/07/25 06:26:09 DEBUG : newLeaf: reading active writers 2021/07/25 06:26:09 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms 2021/07/25 06:26:09 DEBUG : dir: Looking for writers 2021/07/25 06:26:09 DEBUG : : Looking for writers 2021/07/25 06:26:09 DEBUG : dir: reading active writers 2021/07/25 06:26:09 DEBUG : newLeaf: reading active writers 2021/07/25 06:26:09 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms 2021/07/25 06:26:09 DEBUG : dir: Looking for writers 2021/07/25 06:26:09 DEBUG : : Looking for writers 2021/07/25 06:26:09 DEBUG : dir: reading active writers 2021/07/25 06:26:09 DEBUG : newLeaf: reading active writers 2021/07/25 06:26:09 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms 2021/07/25 06:26:09 DEBUG : dir: Looking for writers 2021/07/25 06:26:09 DEBUG : : Looking for writers 2021/07/25 06:26:09 DEBUG : dir: reading active writers 2021/07/25 06:26:09 DEBUG : newLeaf: reading active writers 2021/07/25 06:26:09 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms 2021/07/25 06:26:09 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:26:09 INFO : newLeaf: Copied (replaced existing) 2021/07/25 06:26:09 DEBUG : newLeaf: vfs cache: fingerprint now "25,2021-07-25 06:24:46 +0000 UTC" 2021/07/25 06:26:09 DEBUG : newLeaf: vfs cache: writeback object to VFS layer 2021/07/25 06:26:09 DEBUG : : Added virtual directory entry vAddFile: "newLeaf" 2021/07/25 06:26:09 INFO : newLeaf: vfs cache: upload succeeded try #1 2021/07/25 06:26:09 DEBUG : dir: Looking for writers 2021/07/25 06:26:09 DEBUG : : Looking for writers 2021/07/25 06:26:09 DEBUG : dir: reading active writers 2021/07/25 06:26:09 DEBUG : newLeaf: reading active writers 2021/07/25 06:26:09 DEBUG : >WaitForWriters: 2021/07/25 06:26:09 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: getFolderContents(map[count:1000 fi_pid:121000261 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:26:09 DEBUG : vfs cache: cleaner exiting 2021/07/25 06:26:10 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:26:10 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: getFolderContents(map[count:1000 fi_pid:121000261 from:2 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:26:10 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:26:10 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: doDeleteFile(map[completedeletion:n fi_id:121000319]) options=[] 2021/07/25 06:26:10 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': Sleeping for 6s to wait for "error_background" error to clear 2021/07/25 06:26:16 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)) 2021/07/25 06:26:16 DEBUG : pacer: Rate limited, increasing sleep to 40ms 2021/07/25 06:26:17 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': Sleeping for 6s to wait for "error_background" error to clear 2021/07/25 06:26:23 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)) 2021/07/25 06:26:23 DEBUG : pacer: Rate limited, increasing sleep to 80ms 2021/07/25 06:26:23 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': Sleeping for 6s to wait for "error_background" error to clear 2021/07/25 06:26:29 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)) 2021/07/25 06:26:29 DEBUG : pacer: Rate limited, increasing sleep to 160ms 2021/07/25 06:26:30 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': Sleeping for 6s to wait for "error_background" error to clear 2021/07/25 06:26:36 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)) 2021/07/25 06:26:36 DEBUG : pacer: Rate limited, increasing sleep to 320ms 2021/07/25 06:26:37 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': Sleeping for 6s to wait for "error_background" error to clear 2021/07/25 06:26:43 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)) 2021/07/25 06:26:43 DEBUG : pacer: Rate limited, increasing sleep to 640ms 2021/07/25 06:26:43 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': Sleeping for 6s to wait for "error_background" error to clear 2021/07/25 06:26:49 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)) 2021/07/25 06:26:49 DEBUG : pacer: Rate limited, increasing sleep to 1.28s 2021/07/25 06:26:49 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': Sleeping for 6s to wait for "error_background" error to clear 2021/07/25 06:26:55 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)) 2021/07/25 06:26:55 DEBUG : pacer: Rate limited, increasing sleep to 2.56s 2021/07/25 06:26:56 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': Sleeping for 6s to wait for "error_background" error to clear 2021/07/25 06:27:02 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)) 2021/07/25 06:27:02 DEBUG : pacer: Rate limited, increasing sleep to 5.12s 2021/07/25 06:27:02 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': Sleeping for 6s to wait for "error_background" error to clear 2021/07/25 06:27:08 DEBUG : pacer: low level retry 9/10 (error We are not able to complete the requested operation. We are processing move folder in parent folder. Please try again later. (error_background)) 2021/07/25 06:27:08 DEBUG : pacer: Rate limited, increasing sleep to 10s 2021/07/25 06:27:09 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': Sleeping for 6s to wait for "error_background" error to clear 2021/07/25 06:27:15 DEBUG : pacer: low level retry 10/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)) 2021/07/25 06:27:15 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=We are not able to complete the requested operation. We are processing move folder in parent folder. Please try again later. (error_background), err=We are not able to complete the requested operation. We are processing move folder in parent folder. Please try again later. (error_background) run.go:121: removing file "newLeaf" failed - try 1/3: failed to delete file: We are not able to complete the requested operation. We are processing move folder in parent folder. Please try again later. (error_background) 2021/07/25 06:27:16 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: doDeleteFile(map[completedeletion:n fi_id:121000319]) options=[] 2021/07/25 06:27:19 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': Sleeping for 6s to wait for "error_background" error to clear 2021/07/25 06:27:25 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)) 2021/07/25 06:27:29 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': Sleeping for 6s to wait for "error_background" error to clear 2021/07/25 06:27:35 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)) 2021/07/25 06:27:55 DEBUG : pacer: Reducing sleep to 7.5s 2021/07/25 06:27:55 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:27:55 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: getFolderContents(map[count:1000 fi_pid:121000317 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:27:55 DEBUG : pacer: Reducing sleep to 5.625s 2021/07/25 06:27:55 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:27:55 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: getFolderContents(map[count:1000 fi_pid:121000317 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:28:03 DEBUG : pacer: Reducing sleep to 4.21875s 2021/07/25 06:28:03 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:28:03 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: doDeleteFolder(map[fi_id:121000317]) options=[] 2021/07/25 06:28:12 DEBUG : pacer: Reducing sleep to 3.1640625s 2021/07/25 06:28:12 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= 2021/07/25 06:28:12 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: getFolderContents(map[count:1000 fi_pid:121000261 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:28:13 DEBUG : pacer: Reducing sleep to 2.373046875s 2021/07/25 06:28:13 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= --- FAIL: TestFileRename (687.04s) --- FAIL: TestFileRename/minimal,forceCache=true (203.28s) --- FAIL: TestFileRename/writes,forceCache=true (483.75s) FAIL 2021/07/25 06:28:13 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': Purge remote 2021/07/25 06:28:13 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': rpc: doDeleteFolder(map[fi_id:121000261]) options=[] 2021/07/25 06:28:16 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': Sleeping for 6s to wait for "error_background" error to clear 2021/07/25 06:28: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)) 2021/07/25 06:28:22 DEBUG : pacer: Rate limited, increasing sleep to 4.74609375s 2021/07/25 06:28:23 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': Sleeping for 6s to wait for "error_background" error to clear 2021/07/25 06:28:29 DEBUG : pacer: low level retry 2/10 (error The requested operation cannot be completed. A delete operation is already being processed in this folder. Please try again later. (error_background)) 2021/07/25 06:28:29 DEBUG : pacer: Rate limited, increasing sleep to 9.4921875s 2021/07/25 06:28:29 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': Sleeping for 6s to wait for "error_background" error to clear 2021/07/25 06:28:35 DEBUG : pacer: low level retry 3/10 (error The requested operation cannot be completed. A delete operation is already being processed in this folder. Please try again later. (error_background)) 2021/07/25 06:28:35 DEBUG : pacer: Rate limited, increasing sleep to 10s 2021/07/25 06:28:39 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': Sleeping for 6s to wait for "error_background" error to clear 2021/07/25 06:28:45 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)) 2021/07/25 06:28:53 DEBUG : pacer: Reducing sleep to 7.5s 2021/07/25 06:28:53 DEBUG : filefabric root 'rclone-test-julejil3zikirov7labijum8': >rpc: result=Success (ok), err= "./vfs.test -test.v -test.timeout 1h0m0s -remote TestFileFabric: -verbose -test.run '^(TestDirRename|TestFileRename)$/^(minimal,forceCache=true|writes,forceCache=true)$'" - Finished ERROR in 16m25.603899166s (try 3/5): exit status 1: Failed [TestDirRename TestFileRename/minimal,forceCache=true TestFileRename/writes,forceCache=true]