"./vfs.test -test.v -test.timeout 1h0m0s -remote TestFileFabric: -verbose -test.run '^(TestDirRename|TestFileRename)$/^(minimal,forceCache=true|writes,forceCache=true)$'" - Starting (try 4/5) 2021/07/25 06:28:53 DEBUG : Creating backend with remote "TestFileFabric:rclone-test-tavacug1tavuxun9tonilah2" 2021/07/25 06:28:53 DEBUG : Using config file from "/home/rclone/.rclone.conf" 2021/07/25 06:28:53 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: checkPathExists(map[path:rclone-test-tavacug1tavuxun9tonilah2 pid:120673762]) options=[] 2021/07/25 06:28:53 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:28:53 DEBUG : Creating backend with remote "/tmp/rclone872412738" === RUN TestDirRename run.go:176: Remote "filefabric root 'rclone-test-tavacug1tavuxun9tonilah2'", Local "Local file system at /tmp/rclone872412738", Modify Window "1s" 2021/07/25 06:28:53 INFO : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': poll-interval is not supported by this remote 2021/07/25 06:28:53 NOTICE: filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': --vfs-cache-mode writes or full is recommended for this remote as it can't stream 2021/07/25 06:28:53 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': 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:28:53 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:28:53 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: doCreateNewFolder(map[fi_name:rclone-test-tavacug1tavuxun9tonilah2 fi_pid:120673762]) options=[] 2021/07/25 06:28:59 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:28:59 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: getFolderContents(map[count:1000 fi_pid:121000361 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:29:02 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:29:02 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: doCreateNewFolder(map[fi_name:dir fi_pid:121000361]) options=[] 2021/07/25 06:29:06 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:29:06 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': 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:121000364 fi_size:14 responsetype:json]) options=[] 2021/07/25 06:29:07 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:29:08 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: doCompleteUpload(map[fi_size:14 remotetime:2001-02-03 04:05:06 uploadcode:dca91c367b414054128eb84fad389e40]) options=[] 2021/07/25 06:29:11 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:29:11 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: getFolderContents(map[count:1000 fi_pid:121000361 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:29:14 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:29:14 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: getFolderContents(map[count:1000 fi_pid:121000364 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:29:18 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:29:18 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: getFolderContents(map[count:1000 fi_pid:121000361 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:29:18 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:29:18 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': 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:121000364 fi_size:15 responsetype:json]) options=[] 2021/07/25 06:29:19 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:29:20 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: doCompleteUpload(map[fi_size:15 remotetime:2001-02-03 04:05:06 uploadcode:f282155ab9e7b384b29b72109fb2622e]) options=[] 2021/07/25 06:29:22 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:29:22 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: getFolderContents(map[count:1000 fi_pid:121000361 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:29:22 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:29:22 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: getFolderContents(map[count:1000 fi_pid:121000364 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:29:24 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:29:24 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: getFolderContents(map[count:1000 fi_pid:121000364 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:29:25 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:29:25 ERROR : dir/not found: Dir.Rename error: file does not exist 2021/07/25 06:29:25 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: getFolderContents(map[count:1000 fi_pid:121000361 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:29:25 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:29:25 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: doRenameFolder(map[fi_id:121000364 fi_name:dir2]) options=[] 2021/07/25 06:29:45 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:29:45 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: getUserBackgroundTasks(map[taskid:1277244]) options=[] 2021/07/25 06:29:47 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:29:47 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': Waiting for task ID 1277244: Rename folder 'S3 Storage/smestoragencw/rclone-test-tavacug1tavuxun9tonilah2/dir2': to completed for 1s - waited 2.191817793s already 2021/07/25 06:29:48 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: getUserBackgroundTasks(map[taskid:1277244]) options=[] 2021/07/25 06:29:49 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:29:49 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': Waiting for task ID 1277244: Rename folder 'S3 Storage/smestoragencw/rclone-test-tavacug1tavuxun9tonilah2/dir2': to completed for 1s - waited 4.72541274s already 2021/07/25 06:29:50 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: getUserBackgroundTasks(map[taskid:1277244]) options=[] 2021/07/25 06:29:52 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:29:52 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': Waiting for task ID 1277244: Rename folder 'S3 Storage/smestoragencw/rclone-test-tavacug1tavuxun9tonilah2/dir2': to completed for 1s - waited 7.529623618s already 2021/07/25 06:29:53 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: getUserBackgroundTasks(map[taskid:1277244]) options=[] 2021/07/25 06:29:55 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:29:55 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': Waiting for task ID 1277244: Rename folder 'S3 Storage/smestoragencw/rclone-test-tavacug1tavuxun9tonilah2/dir2': to completed for 1s - waited 9.901128637s already 2021/07/25 06:29:56 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: getUserBackgroundTasks(map[taskid:1277244]) options=[] 2021/07/25 06:29:57 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:29:57 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': Waiting for task ID 1277244: Rename folder 'S3 Storage/smestoragencw/rclone-test-tavacug1tavuxun9tonilah2/dir2': to completed for 1s - waited 12.456658124s already 2021/07/25 06:29:58 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: getUserBackgroundTasks(map[taskid:1277244]) options=[] 2021/07/25 06:30:00 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:30:00 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': Waiting for task ID 1277244: Rename folder 'S3 Storage/smestoragencw/rclone-test-tavacug1tavuxun9tonilah2/dir2': to completed for 1s - waited 14.800071826s already 2021/07/25 06:30:01 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: getUserBackgroundTasks(map[taskid:1277244]) options=[] 2021/07/25 06:30:02 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:30:02 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': Waiting for task ID 1277244: Rename folder 'S3 Storage/smestoragencw/rclone-test-tavacug1tavuxun9tonilah2/dir2': to completed for 1s - waited 17.227254664s already 2021/07/25 06:30:03 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: getUserBackgroundTasks(map[taskid:1277244]) options=[] 2021/07/25 06:30:06 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:30:06 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': Waiting for task ID 1277244: Rename folder 'S3 Storage/smestoragencw/rclone-test-tavacug1tavuxun9tonilah2/dir2': to completed for 1s - waited 20.891080294s already 2021/07/25 06:30:07 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: getUserBackgroundTasks(map[taskid:1277244]) options=[] 2021/07/25 06:30:08 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:30:08 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': Waiting for task ID 1277244: Rename folder 'S3 Storage/smestoragencw/rclone-test-tavacug1tavuxun9tonilah2/dir2': to completed for 1s - waited 23.514074762s already 2021/07/25 06:30:09 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: getUserBackgroundTasks(map[taskid:1277244]) options=[] 2021/07/25 06:30:11 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:30:11 DEBUG : dir: Updating dir with dir2 0xc0002bce40 2021/07/25 06:30:11 DEBUG : dir: forgetting directory cache 2021/07/25 06:30:11 DEBUG : : Added virtual directory entry vDel: "dir" 2021/07/25 06:30:11 DEBUG : : Added virtual directory entry vAddDir: "dir2" 2021/07/25 06:30:11 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: getFolderContents(map[count:1000 fi_pid:121000361 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:30:12 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:30:12 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: getFolderContents(map[count:1000 fi_pid:121000364 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:30:15 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:30:15 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: getFolderContents(map[count:1000 fi_pid:121000361 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:30:15 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:30:15 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: getFolderContents(map[count:1000 fi_pid:121000364 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:30:16 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:30:16 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: checkPathExists(map[path:file2 pid:121000361]) options=[] 2021/07/25 06:30:16 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:30:16 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: doRenameFile(map[fi_id:121000368 fi_name:file2.yarozer6]) options=[] 2021/07/25 06:30:27 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:30:27 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: doMoveFiles(map[dir_id:121000361 fi_ids:121000368]) options=[] 2021/07/25 06:31:14 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Succcess. (ok), err= 2021/07/25 06:31:14 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: doRenameFile(map[fi_id:121000368 fi_name:file2]) options=[] 2021/07/25 06:31:26 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:31:26 INFO : dir2/file1: Moved (server-side) to: file2 2021/07/25 06:31:26 DEBUG : file2: Updating file with file2 0xc0001a15c0 2021/07/25 06:31:26 DEBUG : dir2: Added virtual directory entry vDel: "file1" 2021/07/25 06:31:26 DEBUG : : Added virtual directory entry vAddFile: "file2" 2021/07/25 06:31:26 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: getFolderContents(map[count:1000 fi_pid:121000361 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:31:29 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:31:29 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: getFolderContents(map[count:1000 fi_pid:121000364 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:31:33 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:31:33 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: checkPathExists(map[path:dir2/file3 pid:121000361]) options=[] 2021/07/25 06:31:34 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:31:34 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: doDeleteFile(map[completedeletion:n fi_id:121000371]) options=[] 2021/07/25 06:31:46 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:31:46 INFO : dir2/file3: Deleted 2021/07/25 06:31:46 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: doRenameFile(map[fi_id:121000368 fi_name:file3.murucob9]) options=[] 2021/07/25 06:31:57 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:31:57 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: doMoveFiles(map[dir_id:121000364 fi_ids:121000368]) options=[] 2021/07/25 06:32:30 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Succcess. (ok), err= 2021/07/25 06:32:30 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: doRenameFile(map[fi_id:121000368 fi_name:file3]) options=[] 2021/07/25 06:32:45 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:32:45 INFO : file2: Moved (server-side) to: dir2/file3 2021/07/25 06:32:45 DEBUG : dir2/file3: Updating file with dir2/file3 0xc0001a15c0 2021/07/25 06:32:45 DEBUG : : Added virtual directory entry vDel: "file2" 2021/07/25 06:32:45 DEBUG : dir2: Added virtual directory entry vAddFile: "file3" 2021/07/25 06:32:45 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: getFolderContents(map[count:1000 fi_pid:121000361 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:32:46 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:32:46 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: getFolderContents(map[count:1000 fi_pid:121000364 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:32:48 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:32:48 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: getFolderContents(map[count:1000 fi_pid:121000361 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:32:49 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:32:49 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: doCreateNewFolder(map[fi_name:empty directory fi_pid:121000361]) options=[] 2021/07/25 06:32:55 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:32:55 DEBUG : : Added virtual directory entry vAddDir: "empty directory" 2021/07/25 06:32:55 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: getFolderContents(map[count:1000 fi_pid:121000361 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:32:56 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:32:56 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: doRenameFolder(map[fi_id:121000401 fi_name:renamed empty directory]) options=[] 2021/07/25 06:33:13 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err=json: cannot unmarshal number into Go struct field FileResponse.taskid of type string 2021/07/25 06:33:13 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:33:13 DEBUG : WaitForWriters: timeout=10s 2021/07/25 06:33:13 DEBUG : dir2: Looking for writers 2021/07/25 06:33:13 DEBUG : file3: reading active writers 2021/07/25 06:33:13 DEBUG : empty directory: Looking for writers 2021/07/25 06:33:13 DEBUG : : Looking for writers 2021/07/25 06:33:13 DEBUG : dir2: reading active writers 2021/07/25 06:33:13 DEBUG : empty directory: reading active writers 2021/07/25 06:33:13 DEBUG : >WaitForWriters: 2021/07/25 06:33:13 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: getFolderContents(map[count:1000 fi_pid:121000361 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:33:16 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:33:16 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: getFolderContents(map[count:1000 fi_pid:121000401 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:33:16 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: getFolderContents(map[count:1000 fi_pid:121000364 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:33:16 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:33:16 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: doDeleteFile(map[completedeletion:n fi_id:121000368]) options=[] 2021/07/25 06:33:21 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:33:42 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:33:42 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: getFolderContents(map[count:1000 fi_pid:121000401 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:33:43 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:33:43 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: doDeleteFolder(map[fi_id:121000401]) options=[] 2021/07/25 06:33:47 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:33:47 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: getFolderContents(map[count:1000 fi_pid:121000364 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:33:49 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:33:49 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: doDeleteFolder(map[fi_id:121000364]) options=[] 2021/07/25 06:33:53 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:33:53 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: getFolderContents(map[count:1000 fi_pid:121000361 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:33:54 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= --- FAIL: TestDirRename (301.09s) === RUN TestFileRename === RUN TestFileRename/minimal,forceCache=true run.go:176: Remote "filefabric root 'rclone-test-tavacug1tavuxun9tonilah2'", Local "Local file system at /tmp/rclone872412738", Modify Window "1s" 2021/07/25 06:33:54 INFO : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': poll-interval is not supported by this remote 2021/07/25 06:33:54 NOTICE: filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': --vfs-cache-mode writes or full is recommended for this remote as it can't stream 2021/07/25 06:33:54 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestFileFabric/rclone-test-tavacug1tavuxun9tonilah2" 2021/07/25 06:33:54 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestFileFabric/rclone-test-tavacug1tavuxun9tonilah2" 2021/07/25 06:33:54 DEBUG : Creating backend with remote "/home/rclone/.cache/rclone/vfs/TestFileFabric/rclone-test-tavacug1tavuxun9tonilah2" 2021/07/25 06:33:54 DEBUG : Config file has changed externaly - reloading 2021/07/25 06:33:54 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: getFolderContents(map[count:1000 fi_pid:121000361 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:33:54 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:33:54 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:33:54 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: doCreateNewFolder(map[fi_name:dir fi_pid:121000361]) options=[] 2021/07/25 06:33:59 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:33:59 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': 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:121000404 fi_size:14 responsetype:json]) options=[] 2021/07/25 06:34:00 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:34:02 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: doCompleteUpload(map[fi_size:14 remotetime:2001-02-03 04:05:06 uploadcode:562909f3d7d88f24a4df31dc3ba1129e]) options=[] 2021/07/25 06:34:04 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:34:04 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: getFolderContents(map[count:1000 fi_pid:121000361 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:34:06 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:34:06 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: getFolderContents(map[count:1000 fi_pid:121000404 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:34:09 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:34:09 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: getFolderContents(map[count:1000 fi_pid:121000361 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:34:09 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:34:09 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: getFolderContents(map[count:1000 fi_pid:121000404 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:34:10 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:34:10 DEBUG : dir/file1: Open: flags=O_RDWR|O_CREATE|O_TRUNC 2021/07/25 06:34:10 DEBUG : dir/file1: newRWFileHandle: 2021/07/25 06:34:10 DEBUG : dir/file1(0xc0002d9d00): openPending: 2021/07/25 06:34:10 DEBUG : dir/file1: vfs cache: checking remote fingerprint "14,2001-02-03 04:05:06 +0000 UTC" against cached fingerprint "" 2021/07/25 06:34:10 DEBUG : dir/file1: vfs cache: truncate to size=14 2021/07/25 06:34:10 DEBUG : dir: Added virtual directory entry vAddFile: "file1" 2021/07/25 06:34:10 DEBUG : dir/file1(0xc0002d9d00): >openPending: err= 2021/07/25 06:34:10 DEBUG : dir/file1: vfs cache: truncate to size=0 2021/07/25 06:34:10 DEBUG : dir/file1: >newRWFileHandle: err= 2021/07/25 06:34:10 DEBUG : dir: Added virtual directory entry vAddFile: "file1" 2021/07/25 06:34:10 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2021/07/25 06:34:10 DEBUG : dir/file1(0xc0002d9d00): _writeAt: size=14, off=0 2021/07/25 06:34:10 DEBUG : dir/file1(0xc0002d9d00): >_writeAt: n=14, err= 2021/07/25 06:34:10 DEBUG : dir/file1: vfs cache: setting modification time to 2001-02-03 04:05:06.499999999 +0000 UTC 2021/07/25 06:34:10 DEBUG : dir/file1(0xc0002d9d00): close: 2021/07/25 06:34:10 DEBUG : vfs cache: looking for range={Pos:0 Size:14} in [{Pos:0 Size:14}] - present true 2021/07/25 06:34:10 DEBUG : dir/file1: vfs cache: setting modification time to 2001-02-03 04:05:06.499999999 +0000 UTC 2021/07/25 06:34:10 INFO : dir/file1: vfs cache: queuing for upload in 100ms 2021/07/25 06:34:10 DEBUG : dir/file1(0xc0002d9d00): >close: err= 2021/07/25 06:34:10 DEBUG : WaitForWriters: timeout=10s 2021/07/25 06:34:10 DEBUG : dir: Looking for writers 2021/07/25 06:34:10 DEBUG : file1: reading active writers 2021/07/25 06:34:10 DEBUG : : Looking for writers 2021/07/25 06:34:10 DEBUG : dir: reading active writers 2021/07/25 06:34:10 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms 2021/07/25 06:34:10 DEBUG : dir: Looking for writers 2021/07/25 06:34:10 DEBUG : file1: reading active writers 2021/07/25 06:34:10 DEBUG : : Looking for writers 2021/07/25 06:34:10 DEBUG : dir: reading active writers 2021/07/25 06:34:10 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms 2021/07/25 06:34:10 DEBUG : dir: Looking for writers 2021/07/25 06:34:10 DEBUG : file1: reading active writers 2021/07/25 06:34:10 DEBUG : : Looking for writers 2021/07/25 06:34:10 DEBUG : dir: reading active writers 2021/07/25 06:34:10 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms 2021/07/25 06:34:10 DEBUG : dir: Looking for writers 2021/07/25 06:34:10 DEBUG : file1: reading active writers 2021/07/25 06:34:10 DEBUG : : Looking for writers 2021/07/25 06:34:10 DEBUG : dir: reading active writers 2021/07/25 06:34:10 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms 2021/07/25 06:34:10 DEBUG : dir/file1: vfs cache: starting upload 2021/07/25 06:34:10 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': 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:121000404 fi_size:14 responsetype:json]) options=[] 2021/07/25 06:34:10 DEBUG : dir: Looking for writers 2021/07/25 06:34:10 DEBUG : file1: reading active writers 2021/07/25 06:34:10 DEBUG : : Looking for writers 2021/07/25 06:34:10 DEBUG : dir: reading active writers 2021/07/25 06:34:10 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms 2021/07/25 06:34:10 DEBUG : dir: Looking for writers 2021/07/25 06:34:10 DEBUG : file1: reading active writers 2021/07/25 06:34:10 DEBUG : : Looking for writers 2021/07/25 06:34:10 DEBUG : dir: reading active writers 2021/07/25 06:34:10 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms 2021/07/25 06:34:10 DEBUG : dir: Looking for writers 2021/07/25 06:34:10 DEBUG : file1: reading active writers 2021/07/25 06:34:10 DEBUG : : Looking for writers 2021/07/25 06:34:10 DEBUG : dir: reading active writers 2021/07/25 06:34:10 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms 2021/07/25 06:34:11 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:34:11 DEBUG : dir: Looking for writers 2021/07/25 06:34:11 DEBUG : file1: reading active writers 2021/07/25 06:34:11 DEBUG : : Looking for writers 2021/07/25 06:34:11 DEBUG : dir: reading active writers 2021/07/25 06:34:11 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/07/25 06:34:12 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: doCompleteUpload(map[fi_size:14 remotetime:2001-02-03 04:05:06 uploadcode:ac746336bd5997f1e6b11c8bc89549a6]) options=[] 2021/07/25 06:34:12 DEBUG : dir: Looking for writers 2021/07/25 06:34:12 DEBUG : file1: reading active writers 2021/07/25 06:34:12 DEBUG : : Looking for writers 2021/07/25 06:34:12 DEBUG : dir: reading active writers 2021/07/25 06:34:12 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/07/25 06:34:13 DEBUG : dir: Looking for writers 2021/07/25 06:34:13 DEBUG : file1: reading active writers 2021/07/25 06:34:13 DEBUG : : Looking for writers 2021/07/25 06:34:13 DEBUG : dir: reading active writers 2021/07/25 06:34:13 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/07/25 06:34:14 DEBUG : dir: Looking for writers 2021/07/25 06:34:14 DEBUG : file1: reading active writers 2021/07/25 06:34:14 DEBUG : : Looking for writers 2021/07/25 06:34:14 DEBUG : dir: reading active writers 2021/07/25 06:34:14 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/07/25 06:34:15 DEBUG : dir: Looking for writers 2021/07/25 06:34:15 DEBUG : file1: reading active writers 2021/07/25 06:34:15 DEBUG : : Looking for writers 2021/07/25 06:34:15 DEBUG : dir: reading active writers 2021/07/25 06:34:15 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/07/25 06:34:16 DEBUG : dir: Looking for writers 2021/07/25 06:34:16 DEBUG : file1: reading active writers 2021/07/25 06:34:16 DEBUG : : Looking for writers 2021/07/25 06:34:16 DEBUG : dir: reading active writers 2021/07/25 06:34:16 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/07/25 06:34:17 DEBUG : dir: Looking for writers 2021/07/25 06:34:17 DEBUG : file1: reading active writers 2021/07/25 06:34:17 DEBUG : : Looking for writers 2021/07/25 06:34:17 DEBUG : dir: reading active writers 2021/07/25 06:34:17 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/07/25 06:34:18 DEBUG : dir: Looking for writers 2021/07/25 06:34:18 DEBUG : file1: reading active writers 2021/07/25 06:34:18 DEBUG : : Looking for writers 2021/07/25 06:34:18 DEBUG : dir: reading active writers 2021/07/25 06:34:18 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/07/25 06:34:19 DEBUG : dir: Looking for writers 2021/07/25 06:34:19 DEBUG : file1: reading active writers 2021/07/25 06:34:19 DEBUG : : Looking for writers 2021/07/25 06:34:19 DEBUG : dir: reading active writers 2021/07/25 06:34:19 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/07/25 06:34:20 ERROR : Exiting even though 0 writers active and 1 cache items in use after 10s Cache{ "dir/file1": &{c:0xc0001a1680 mu:{state:0 sema:0} cond:0xc0002d9cc0 name:dir/file1 opens:0 downloaders: o:0xc00072cae0 fd: modified:false info:{ModTime:{wall:499999999 ext:63116769906 loc:} ATime:{wall:13850644012830334525 ext:316986619305 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:34:20 DEBUG : >WaitForWriters: 2021/07/25 06:34:20 DEBUG : dir/file1: Open: flags=O_RDONLY 2021/07/25 06:34:20 DEBUG : dir/file1: newRWFileHandle: 2021/07/25 06:34:20 DEBUG : dir/file1: >newRWFileHandle: err= 2021/07/25 06:34:20 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2021/07/25 06:34:20 DEBUG : dir/file1(0xc00083ad80): _readAt: size=512, off=0 2021/07/25 06:34:20 DEBUG : dir/file1(0xc00083ad80): openPending: 2021/07/25 06:34:20 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:34:20 DEBUG : dir/file1: vfs cache: truncate to size=14 2021/07/25 06:34:20 DEBUG : dir: Added virtual directory entry vAddFile: "file1" 2021/07/25 06:34:20 DEBUG : dir/file1(0xc00083ad80): >openPending: err= 2021/07/25 06:34:20 DEBUG : vfs cache: looking for range={Pos:0 Size:14} in [{Pos:0 Size:14}] - present true 2021/07/25 06:34:20 DEBUG : dir/file1(0xc00083ad80): >_readAt: n=14, err=EOF 2021/07/25 06:34:20 DEBUG : dir/file1(0xc00083ad80): close: 2021/07/25 06:34:20 DEBUG : vfs cache: looking for range={Pos:0 Size:14} in [{Pos:0 Size:14}] - present true 2021/07/25 06:34:20 DEBUG : dir/file1: vfs cache: setting modification time to 2001-02-03 04:05:06.499999999 +0000 UTC 2021/07/25 06:34:20 INFO : dir/file1: vfs cache: queuing for upload in 100ms 2021/07/25 06:34:20 DEBUG : dir/file1(0xc00083ad80): >close: err= 2021/07/25 06:34:20 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: getFolderContents(map[count:1000 fi_pid:121000361 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:34:20 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:34:20 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: getFolderContents(map[count:1000 fi_pid:121000404 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:34:25 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >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:34:26 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': 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:34:26 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:34:26 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: getFolderContents(map[count:1000 fi_pid:121000361 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:34:26 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:34:26 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: getFolderContents(map[count:1000 fi_pid:121000404 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:34:26 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >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:34:28 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': 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:34:29 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:34:29 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: getFolderContents(map[count:1000 fi_pid:121000361 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:34:29 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:34:29 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: getFolderContents(map[count:1000 fi_pid:121000404 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:34:34 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >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-34-12 (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-34-12" 2021/07/25 06:34:38 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': 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:34:39 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:34:39 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: checkPathExists(map[path:newLeaf pid:121000361]) options=[] 2021/07/25 06:34:39 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:34:39 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: getFolderContents(map[count:1000 fi_pid:121000361 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:34:40 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:34:40 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: doRenameFile(map[fi_id:121000406 fi_name:newLeaf.sedumeq9]) options=[] 2021/07/25 06:34:48 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': Sleeping for 6s to wait for "error_background" error to clear 2021/07/25 06:34:51 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:34:51 INFO : dir/file1: Copied (replaced existing) 2021/07/25 06:34:51 DEBUG : dir/file1: vfs cache: writeback object to VFS layer 2021/07/25 06:34:51 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:34:51 DEBUG : : Added virtual directory entry vAddFile: "newLeaf" 2021/07/25 06:34:51 INFO : dir/file1: vfs cache: upload succeeded try #1 2021/07/25 06:34:54 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item dir/file1 not removed, freed 0 bytes 2021/07/25 06:34:54 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:34:54 DEBUG : pacer: low level retry 1/10 (error Can not rename file 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:34:54 DEBUG : pacer: Rate limited, increasing sleep to 40ms 2021/07/25 06:34:58 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': Sleeping for 6s to wait for "error_background" error to clear 2021/07/25 06:35:04 DEBUG : pacer: low level retry 2/10 (error Can not rename file 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:35:04 DEBUG : pacer: Rate limited, increasing sleep to 80ms 2021/07/25 06:35:08 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': Sleeping for 6s to wait for "error_background" error to clear 2021/07/25 06:35:14 DEBUG : pacer: low level retry 3/10 (error Can not rename file 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:35:14 DEBUG : pacer: Rate limited, increasing sleep to 160ms 2021/07/25 06:35:19 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': Sleeping for 6s to wait for "error_background" error to clear 2021/07/25 06:35:25 DEBUG : pacer: low level retry 4/10 (error Can not rename file 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:35:25 DEBUG : pacer: Rate limited, increasing sleep to 320ms 2021/07/25 06:35:29 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': Sleeping for 6s to wait for "error_background" error to clear 2021/07/25 06:35:35 DEBUG : pacer: low level retry 5/10 (error Can not rename file 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:35:35 DEBUG : pacer: Rate limited, increasing sleep to 640ms 2021/07/25 06:35:38 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': Sleeping for 6s to wait for "error_background" error to clear 2021/07/25 06:35:44 DEBUG : pacer: low level retry 6/10 (error Can not rename file 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:35:44 DEBUG : pacer: Rate limited, increasing sleep to 1.28s 2021/07/25 06:35:48 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': Sleeping for 6s to wait for "error_background" error to clear 2021/07/25 06:35:54 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item dir/file1 not removed, freed 0 bytes 2021/07/25 06:35:54 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:35:54 DEBUG : pacer: low level retry 7/10 (error Can not rename file 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:35:54 DEBUG : pacer: Rate limited, increasing sleep to 2.56s 2021/07/25 06:35:59 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': Sleeping for 6s to wait for "error_background" error to clear 2021/07/25 06:36:05 DEBUG : pacer: low level retry 8/10 (error Can not rename file 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:36:05 DEBUG : pacer: Rate limited, increasing sleep to 5.12s 2021/07/25 06:36:10 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': Sleeping for 6s to wait for "error_background" error to clear 2021/07/25 06:36:16 DEBUG : pacer: low level retry 9/10 (error Can not rename file 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:36:16 DEBUG : pacer: Rate limited, increasing sleep to 10s 2021/07/25 06:36:20 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': Sleeping for 6s to wait for "error_background" error to clear 2021/07/25 06:36:26 DEBUG : pacer: low level retry 10/10 (error Can not rename file 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:36:26 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Can not rename file 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 rename file 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:36:26 ERROR : dir/file1: Couldn't move: failed to rename leaf: Can not rename file 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:36:26 ERROR : newLeaf: File.Rename error: failed to rename leaf: Can not rename file 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:36:26 ERROR : dir/file1: Dir.Rename error: failed to rename leaf: Can not rename file 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 rename leaf: Can not rename file 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:36:26 DEBUG : WaitForWriters: timeout=10s 2021/07/25 06:36:26 DEBUG : dir: Looking for writers 2021/07/25 06:36:26 DEBUG : file1: reading active writers 2021/07/25 06:36:26 DEBUG : : Looking for writers 2021/07/25 06:36:26 DEBUG : dir: reading active writers 2021/07/25 06:36:26 DEBUG : newLeaf: reading active writers 2021/07/25 06:36:26 DEBUG : >WaitForWriters: 2021/07/25 06:36:26 DEBUG : vfs cache: cleaner exiting 2021/07/25 06:36:26 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: getFolderContents(map[count:1000 fi_pid:121000361 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:36:26 DEBUG : pacer: Reducing sleep to 7.5s 2021/07/25 06:36:26 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:36:26 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: getFolderContents(map[count:1000 fi_pid:121000404 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:36:38 DEBUG : pacer: Reducing sleep to 5.625s 2021/07/25 06:36:38 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:36:38 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: doDeleteFile(map[completedeletion:n fi_id:121000406]) options=[] 2021/07/25 06:37:07 DEBUG : pacer: Reducing sleep to 4.21875s 2021/07/25 06:37:07 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:37:07 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: getFolderContents(map[count:1000 fi_pid:121000404 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:37:09 DEBUG : pacer: Reducing sleep to 3.1640625s 2021/07/25 06:37:09 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:37:09 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: doDeleteFolder(map[fi_id:121000404]) options=[] 2021/07/25 06:37:17 DEBUG : pacer: Reducing sleep to 2.373046875s 2021/07/25 06:37:17 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:37:17 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: getFolderContents(map[count:1000 fi_pid:121000361 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:37:18 DEBUG : pacer: Reducing sleep to 1.779785156s 2021/07/25 06:37:18 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= === RUN TestFileRename/writes,forceCache=true run.go:176: Remote "filefabric root 'rclone-test-tavacug1tavuxun9tonilah2'", Local "Local file system at /tmp/rclone872412738", Modify Window "1s" 2021/07/25 06:37:18 INFO : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': poll-interval is not supported by this remote 2021/07/25 06:37:18 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestFileFabric/rclone-test-tavacug1tavuxun9tonilah2" 2021/07/25 06:37:18 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestFileFabric/rclone-test-tavacug1tavuxun9tonilah2" 2021/07/25 06:37:18 DEBUG : Creating backend with remote "/home/rclone/.cache/rclone/vfs/TestFileFabric/rclone-test-tavacug1tavuxun9tonilah2" 2021/07/25 06:37:18 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: getFolderContents(map[count:1000 fi_pid:121000361 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:37:18 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:37:20 DEBUG : pacer: Reducing sleep to 1.334838867s 2021/07/25 06:37:20 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:37:20 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: doCreateNewFolder(map[fi_name:dir fi_pid:121000361]) options=[] 2021/07/25 06:37:22 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': Sleeping for 6s to wait for "error_background" error to clear 2021/07/25 06:37:28 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:37:28 DEBUG : pacer: Rate limited, increasing sleep to 2.669677734s 2021/07/25 06:37:28 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': Sleeping for 6s to wait for "error_background" error to clear 2021/07/25 06:37:34 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:37:34 DEBUG : pacer: Rate limited, increasing sleep to 5.339355468s 2021/07/25 06:37:35 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': Sleeping for 6s to wait for "error_background" error to clear 2021/07/25 06:37:41 DEBUG : pacer: low level retry 3/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background)) 2021/07/25 06:37:41 DEBUG : pacer: Rate limited, increasing sleep to 10s 2021/07/25 06:37:41 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': Sleeping for 6s to wait for "error_background" error to clear 2021/07/25 06:37:47 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:37:51 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': Sleeping for 6s to wait for "error_background" error to clear 2021/07/25 06:37:57 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:38:02 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': Sleeping for 6s to wait for "error_background" error to clear 2021/07/25 06:38:08 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:38:11 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': Sleeping for 6s to wait for "error_background" error to clear 2021/07/25 06:38:17 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:38:18 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:38:21 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': Sleeping for 6s to wait for "error_background" error to clear 2021/07/25 06:38:27 DEBUG : pacer: low level retry 8/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background)) 2021/07/25 06:38:32 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': Sleeping for 6s to wait for "error_background" error to clear 2021/07/25 06:38:38 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:38:41 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': Sleeping for 6s to wait for "error_background" error to clear 2021/07/25 06:38:47 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:38:47 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >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-tavacug1tavuxun9tonilah2': 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:38:49 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: getFolderContents(map[count:1000 fi_pid:121000361 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:38:51 DEBUG : pacer: Reducing sleep to 7.5s 2021/07/25 06:38:51 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:38:51 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: doCreateNewFolder(map[fi_name:dir fi_pid:121000361]) options=[] 2021/07/25 06:39:01 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': Sleeping for 6s to wait for "error_background" error to clear 2021/07/25 06:39:07 DEBUG : pacer: low level retry 1/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background)) 2021/07/25 06:39:07 DEBUG : pacer: Rate limited, increasing sleep to 10s 2021/07/25 06:39:13 DEBUG : pacer: Reducing sleep to 7.5s 2021/07/25 06:39:13 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:39:13 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': 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:121000442 fi_size:14 responsetype:json]) options=[] 2021/07/25 06:39:18 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:39:19 DEBUG : pacer: Reducing sleep to 5.625s 2021/07/25 06:39:19 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:39:27 DEBUG : pacer: Reducing sleep to 4.21875s 2021/07/25 06:39:27 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: doCompleteUpload(map[fi_size:14 remotetime:2001-02-03 04:05:06 uploadcode:d36b04926d12a3dd4e38846300673693]) options=[] 2021/07/25 06:39:33 DEBUG : pacer: Reducing sleep to 3.1640625s 2021/07/25 06:39:33 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:39:33 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: getFolderContents(map[count:1000 fi_pid:121000361 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:39:41 DEBUG : pacer: Reducing sleep to 2.373046875s 2021/07/25 06:39:41 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:39:41 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: getFolderContents(map[count:1000 fi_pid:121000442 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:39:43 DEBUG : pacer: Reducing sleep to 1.779785156s 2021/07/25 06:39:43 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:39:43 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: getFolderContents(map[count:1000 fi_pid:121000361 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:39:44 DEBUG : pacer: Reducing sleep to 1.334838867s 2021/07/25 06:39:44 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:39:44 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: getFolderContents(map[count:1000 fi_pid:121000442 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:39:45 DEBUG : pacer: Reducing sleep to 1.00112915s 2021/07/25 06:39:45 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:39:45 DEBUG : dir/file1: Open: flags=O_RDWR|O_CREATE|O_TRUNC 2021/07/25 06:39:45 DEBUG : dir/file1: newRWFileHandle: 2021/07/25 06:39:45 DEBUG : dir/file1(0xc00083b8c0): openPending: 2021/07/25 06:39:45 DEBUG : dir/file1: vfs cache: checking remote fingerprint "14,2001-02-03 04:05:06 +0000 UTC" against cached fingerprint "" 2021/07/25 06:39:45 DEBUG : dir/file1: vfs cache: truncate to size=14 2021/07/25 06:39:45 DEBUG : dir: Added virtual directory entry vAddFile: "file1" 2021/07/25 06:39:45 DEBUG : dir/file1(0xc00083b8c0): >openPending: err= 2021/07/25 06:39:45 DEBUG : dir/file1: vfs cache: truncate to size=0 2021/07/25 06:39:45 DEBUG : dir/file1: >newRWFileHandle: err= 2021/07/25 06:39:45 DEBUG : dir: Added virtual directory entry vAddFile: "file1" 2021/07/25 06:39:45 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2021/07/25 06:39:45 DEBUG : dir/file1(0xc00083b8c0): _writeAt: size=14, off=0 2021/07/25 06:39:45 DEBUG : dir/file1(0xc00083b8c0): >_writeAt: n=14, err= 2021/07/25 06:39:45 DEBUG : dir/file1: vfs cache: setting modification time to 2001-02-03 04:05:06.499999999 +0000 UTC 2021/07/25 06:39:45 DEBUG : dir/file1(0xc00083b8c0): close: 2021/07/25 06:39:45 DEBUG : vfs cache: looking for range={Pos:0 Size:14} in [{Pos:0 Size:14}] - present true 2021/07/25 06:39:45 DEBUG : dir/file1: vfs cache: setting modification time to 2001-02-03 04:05:06.499999999 +0000 UTC 2021/07/25 06:39:45 INFO : dir/file1: vfs cache: queuing for upload in 100ms 2021/07/25 06:39:45 DEBUG : dir/file1(0xc00083b8c0): >close: err= 2021/07/25 06:39:45 DEBUG : WaitForWriters: timeout=10s 2021/07/25 06:39:45 DEBUG : dir: Looking for writers 2021/07/25 06:39:45 DEBUG : file1: reading active writers 2021/07/25 06:39:45 DEBUG : : Looking for writers 2021/07/25 06:39:45 DEBUG : dir: reading active writers 2021/07/25 06:39:45 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms 2021/07/25 06:39:45 DEBUG : dir: Looking for writers 2021/07/25 06:39:45 DEBUG : file1: reading active writers 2021/07/25 06:39:45 DEBUG : : Looking for writers 2021/07/25 06:39:45 DEBUG : dir: reading active writers 2021/07/25 06:39:45 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms 2021/07/25 06:39:45 DEBUG : dir: Looking for writers 2021/07/25 06:39:45 DEBUG : file1: reading active writers 2021/07/25 06:39:45 DEBUG : : Looking for writers 2021/07/25 06:39:45 DEBUG : dir: reading active writers 2021/07/25 06:39:45 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms 2021/07/25 06:39:45 DEBUG : dir: Looking for writers 2021/07/25 06:39:45 DEBUG : file1: reading active writers 2021/07/25 06:39:45 DEBUG : : Looking for writers 2021/07/25 06:39:45 DEBUG : dir: reading active writers 2021/07/25 06:39:45 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms 2021/07/25 06:39:45 DEBUG : dir/file1: vfs cache: starting upload 2021/07/25 06:39:45 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': 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:121000442 fi_size:14 responsetype:json]) options=[] 2021/07/25 06:39:46 DEBUG : dir: Looking for writers 2021/07/25 06:39:46 DEBUG : file1: reading active writers 2021/07/25 06:39:46 DEBUG : : Looking for writers 2021/07/25 06:39:46 DEBUG : dir: reading active writers 2021/07/25 06:39:46 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms 2021/07/25 06:39:46 DEBUG : dir: Looking for writers 2021/07/25 06:39:46 DEBUG : file1: reading active writers 2021/07/25 06:39:46 DEBUG : : Looking for writers 2021/07/25 06:39:46 DEBUG : dir: reading active writers 2021/07/25 06:39:46 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms 2021/07/25 06:39:46 DEBUG : dir: Looking for writers 2021/07/25 06:39:46 DEBUG : file1: reading active writers 2021/07/25 06:39:46 DEBUG : : Looking for writers 2021/07/25 06:39:46 DEBUG : dir: reading active writers 2021/07/25 06:39:46 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms 2021/07/25 06:39:47 DEBUG : dir: Looking for writers 2021/07/25 06:39:47 DEBUG : file1: reading active writers 2021/07/25 06:39:47 DEBUG : : Looking for writers 2021/07/25 06:39:47 DEBUG : dir: reading active writers 2021/07/25 06:39:47 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/07/25 06:39:48 DEBUG : dir: Looking for writers 2021/07/25 06:39:48 DEBUG : file1: reading active writers 2021/07/25 06:39:48 DEBUG : : Looking for writers 2021/07/25 06:39:48 DEBUG : dir: reading active writers 2021/07/25 06:39:48 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/07/25 06:39:48 DEBUG : pacer: Reducing sleep to 750.846862ms 2021/07/25 06:39:48 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:39:49 DEBUG : dir: Looking for writers 2021/07/25 06:39:49 DEBUG : file1: reading active writers 2021/07/25 06:39:49 DEBUG : : Looking for writers 2021/07/25 06:39:49 DEBUG : dir: reading active writers 2021/07/25 06:39:49 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/07/25 06:39:49 DEBUG : pacer: Reducing sleep to 563.135146ms 2021/07/25 06:39:49 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: doCompleteUpload(map[fi_size:14 remotetime:2001-02-03 04:05:06 uploadcode:cdbebb775f2ddd4b2da41dd8c3d44d49]) options=[] 2021/07/25 06:39:50 DEBUG : dir: Looking for writers 2021/07/25 06:39:50 DEBUG : file1: reading active writers 2021/07/25 06:39:50 DEBUG : : Looking for writers 2021/07/25 06:39:50 DEBUG : dir: reading active writers 2021/07/25 06:39:50 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/07/25 06:39:51 DEBUG : dir: Looking for writers 2021/07/25 06:39:51 DEBUG : file1: reading active writers 2021/07/25 06:39:51 DEBUG : : Looking for writers 2021/07/25 06:39:51 DEBUG : dir: reading active writers 2021/07/25 06:39:51 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/07/25 06:39:52 DEBUG : dir: Looking for writers 2021/07/25 06:39:52 DEBUG : file1: reading active writers 2021/07/25 06:39:52 DEBUG : : Looking for writers 2021/07/25 06:39:52 DEBUG : dir: reading active writers 2021/07/25 06:39:52 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/07/25 06:39:53 DEBUG : dir: Looking for writers 2021/07/25 06:39:53 DEBUG : file1: reading active writers 2021/07/25 06:39:53 DEBUG : : Looking for writers 2021/07/25 06:39:53 DEBUG : dir: reading active writers 2021/07/25 06:39:53 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/07/25 06:39:54 DEBUG : dir: Looking for writers 2021/07/25 06:39:54 DEBUG : file1: reading active writers 2021/07/25 06:39:54 DEBUG : : Looking for writers 2021/07/25 06:39:54 DEBUG : dir: reading active writers 2021/07/25 06:39:54 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/07/25 06:39:55 DEBUG : dir: Looking for writers 2021/07/25 06:39:55 DEBUG : file1: reading active writers 2021/07/25 06:39:55 DEBUG : : Looking for writers 2021/07/25 06:39:55 DEBUG : dir: reading active writers 2021/07/25 06:39:55 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/07/25 06:39:55 ERROR : Exiting even though 0 writers active and 1 cache items in use after 10s Cache{ "dir/file1": &{c:0xc0002bccc0 mu:{state:0 sema:0} cond:0xc00083b880 name:dir/file1 opens:0 downloaders: o:0xc0001275c0 fd: modified:false info:{ModTime:{wall:499999999 ext:63116769906 loc:} ATime:{wall:13850644373299341384 ext:652752115137 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:39:55 DEBUG : >WaitForWriters: 2021/07/25 06:39:55 DEBUG : dir/file1: Open: flags=O_RDONLY 2021/07/25 06:39:55 DEBUG : dir/file1: newRWFileHandle: 2021/07/25 06:39:55 DEBUG : dir/file1: >newRWFileHandle: err= 2021/07/25 06:39:55 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2021/07/25 06:39:55 DEBUG : dir/file1(0xc00007e040): _readAt: size=512, off=0 2021/07/25 06:39:55 DEBUG : dir/file1(0xc00007e040): openPending: 2021/07/25 06:39:55 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:39:55 DEBUG : dir/file1: vfs cache: truncate to size=14 2021/07/25 06:39:55 DEBUG : dir: Added virtual directory entry vAddFile: "file1" 2021/07/25 06:39:55 DEBUG : dir/file1(0xc00007e040): >openPending: err= 2021/07/25 06:39:55 DEBUG : vfs cache: looking for range={Pos:0 Size:14} in [{Pos:0 Size:14}] - present true 2021/07/25 06:39:55 DEBUG : dir/file1(0xc00007e040): >_readAt: n=14, err=EOF 2021/07/25 06:39:55 DEBUG : dir/file1(0xc00007e040): close: 2021/07/25 06:39:55 DEBUG : vfs cache: looking for range={Pos:0 Size:14} in [{Pos:0 Size:14}] - present true 2021/07/25 06:39:55 DEBUG : dir/file1: vfs cache: setting modification time to 2001-02-03 04:05:06.499999999 +0000 UTC 2021/07/25 06:39:55 INFO : dir/file1: vfs cache: queuing for upload in 100ms 2021/07/25 06:39:55 DEBUG : dir/file1(0xc00007e040): >close: err= 2021/07/25 06:39:55 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: getFolderContents(map[count:1000 fi_pid:121000361 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:39:56 DEBUG : pacer: Reducing sleep to 422.351359ms 2021/07/25 06:39:56 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:39:56 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: getFolderContents(map[count:1000 fi_pid:121000442 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:39:58 DEBUG : pacer: Reducing sleep to 316.763519ms 2021/07/25 06:39:58 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >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:39:59 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': 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:40:02 DEBUG : pacer: Reducing sleep to 237.572639ms 2021/07/25 06:40:02 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:40:02 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: getFolderContents(map[count:1000 fi_pid:121000361 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:40:02 DEBUG : pacer: Reducing sleep to 178.179479ms 2021/07/25 06:40:02 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:40:02 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: getFolderContents(map[count:1000 fi_pid:121000442 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:40:06 DEBUG : pacer: Reducing sleep to 133.634609ms 2021/07/25 06:40:06 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >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:40:08 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': 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:40:09 DEBUG : pacer: Reducing sleep to 100.225956ms 2021/07/25 06:40:09 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:40:09 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: getFolderContents(map[count:1000 fi_pid:121000361 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:40:09 DEBUG : pacer: Reducing sleep to 75.169467ms 2021/07/25 06:40:09 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:40:09 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: getFolderContents(map[count:1000 fi_pid:121000442 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:40:11 DEBUG : pacer: Reducing sleep to 56.3771ms 2021/07/25 06:40:11 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= fstest.go:293: Sleeping for 7s just to make sure 2021/07/25 06:40:18 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: checkPathExists(map[path:newLeaf pid:121000361]) options=[] 2021/07/25 06:40:18 DEBUG : pacer: Reducing sleep to 42.282825ms 2021/07/25 06:40:18 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:40:18 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: doRenameFile(map[fi_id:121000446 fi_name:newLeaf.dirakaf5]) options=[] 2021/07/25 06:40:18 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item dir/file1 not removed, freed 0 bytes 2021/07/25 06:40:18 INFO : vfs cache: cleaned: objects 1 (was 1) in use 1, to upload 0, uploading 1, total size 14 (was 14) 2021/07/25 06:40:27 DEBUG : pacer: Reducing sleep to 31.712118ms 2021/07/25 06:40:27 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:40:27 INFO : dir/file1: Copied (replaced existing) 2021/07/25 06:40:27 DEBUG : dir/file1: vfs cache: writeback object to VFS layer 2021/07/25 06:40:27 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:40:27 DEBUG : : Added virtual directory entry vAddFile: "newLeaf" 2021/07/25 06:40:27 INFO : dir/file1: vfs cache: upload succeeded try #1 2021/07/25 06:40:31 DEBUG : pacer: Reducing sleep to 23.784088ms 2021/07/25 06:40:31 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:40:31 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: doMoveFiles(map[dir_id:121000361 fi_ids:121000446]) options=[] 2021/07/25 06:41:05 DEBUG : pacer: Reducing sleep to 20ms 2021/07/25 06:41:05 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Succcess. (ok), err= 2021/07/25 06:41:05 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: doRenameFile(map[fi_id:121000446 fi_name:newLeaf]) options=[] 2021/07/25 06:41:17 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:41:17 INFO : dir/file1: Moved (server-side) to: newLeaf 2021/07/25 06:41:17 INFO : dir/file1: vfs cache: renamed in cache to "newLeaf" 2021/07/25 06:41:17 DEBUG : newLeaf: Updating file with newLeaf 0xc0001a1bc0 2021/07/25 06:41:17 DEBUG : dir: Added virtual directory entry vDel: "file1" 2021/07/25 06:41:17 DEBUG : : Added virtual directory entry vAddFile: "newLeaf" 2021/07/25 06:41:17 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: getFolderContents(map[count:1000 fi_pid:121000361 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:41:18 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item newLeaf not removed, freed 0 bytes 2021/07/25 06:41:18 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:41:19 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:41:19 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: getFolderContents(map[count:1000 fi_pid:121000442 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:41:20 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:41:20 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: checkPathExists(map[path:dir/file1 pid:121000361]) options=[] 2021/07/25 06:41:21 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:41:21 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: doRenameFile(map[fi_id:121000446 fi_name:file1.yirudon8]) options=[] 2021/07/25 06:41:31 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:41:31 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: doMoveFiles(map[dir_id:121000442 fi_ids:121000446]) options=[] 2021/07/25 06:42:08 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Succcess. (ok), err= 2021/07/25 06:42:08 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: doRenameFile(map[fi_id:121000446 fi_name:file1]) options=[] 2021/07/25 06:42:18 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item newLeaf not removed, freed 0 bytes 2021/07/25 06:42:18 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:42:20 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:42:20 INFO : newLeaf: Moved (server-side) to: dir/file1 2021/07/25 06:42:20 INFO : newLeaf: vfs cache: renamed in cache to "dir/file1" 2021/07/25 06:42:20 DEBUG : dir/file1: Updating file with dir/file1 0xc0001a1bc0 2021/07/25 06:42:20 DEBUG : : Added virtual directory entry vDel: "newLeaf" 2021/07/25 06:42:20 DEBUG : dir: Added virtual directory entry vAddFile: "file1" 2021/07/25 06:42:20 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: getFolderContents(map[count:1000 fi_pid:121000361 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:42:22 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:42:22 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: getFolderContents(map[count:1000 fi_pid:121000442 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:42:23 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:42:23 DEBUG : dir/file1: Open: flags=O_WRONLY|O_TRUNC 2021/07/25 06:42:23 DEBUG : dir/file1: newRWFileHandle: 2021/07/25 06:42:23 DEBUG : dir/file1(0xc0005ac100): openPending: 2021/07/25 06:42:23 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:42:23 DEBUG : dir/file1: vfs cache: truncate to size=14 2021/07/25 06:42:23 DEBUG : dir: Added virtual directory entry vAddFile: "file1" 2021/07/25 06:42:23 DEBUG : dir/file1(0xc0005ac100): >openPending: err= 2021/07/25 06:42:23 DEBUG : dir/file1: vfs cache: truncate to size=0 2021/07/25 06:42:23 DEBUG : dir/file1: >newRWFileHandle: err= 2021/07/25 06:42:23 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2021/07/25 06:42:23 DEBUG : dir/file1(0xc0005ac100): _writeAt: size=25, off=0 2021/07/25 06:42:23 DEBUG : dir/file1(0xc0005ac100): >_writeAt: n=25, err= 2021/07/25 06:42:23 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: checkPathExists(map[path:newLeaf pid:121000361]) options=[] 2021/07/25 06:42:24 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:42:24 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: doRenameFile(map[fi_id:121000446 fi_name:newLeaf.vugixeq3]) options=[] 2021/07/25 06:42:36 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:42:36 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: doMoveFiles(map[dir_id:121000361 fi_ids:121000446]) options=[] 2021/07/25 06:43:13 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Succcess. (ok), err= 2021/07/25 06:43:13 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: doRenameFile(map[fi_id:121000446 fi_name:newLeaf]) options=[] 2021/07/25 06:43:18 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item dir/file1 not removed, freed 0 bytes 2021/07/25 06:43:18 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:43:24 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:43:24 INFO : dir/file1: Moved (server-side) to: newLeaf 2021/07/25 06:43:24 INFO : dir/file1: vfs cache: renamed in cache to "newLeaf" 2021/07/25 06:43:24 DEBUG : newLeaf: Updating file with newLeaf 0xc0001a1bc0 2021/07/25 06:43:24 DEBUG : dir: Added virtual directory entry vDel: "file1" 2021/07/25 06:43:24 DEBUG : : Added virtual directory entry vAddFile: "newLeaf" 2021/07/25 06:43:24 DEBUG : newLeaf(0xc0005ac100): close: 2021/07/25 06:43:24 DEBUG : vfs cache: looking for range={Pos:0 Size:25} in [{Pos:0 Size:25}] - present true 2021/07/25 06:43:24 DEBUG : newLeaf: vfs cache: setting modification time to 2021-07-25 06:42:23.718165616 +0000 UTC m=+810.584944605 2021/07/25 06:43:24 INFO : newLeaf: vfs cache: queuing for upload in 100ms 2021/07/25 06:43:24 DEBUG : newLeaf(0xc0005ac100): >close: err= 2021/07/25 06:43:24 DEBUG : WaitForWriters: timeout=10s 2021/07/25 06:43:24 DEBUG : dir: Looking for writers 2021/07/25 06:43:24 DEBUG : : Looking for writers 2021/07/25 06:43:24 DEBUG : dir: reading active writers 2021/07/25 06:43:24 DEBUG : newLeaf: reading active writers 2021/07/25 06:43:24 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms 2021/07/25 06:43:24 DEBUG : dir: Looking for writers 2021/07/25 06:43:24 DEBUG : : Looking for writers 2021/07/25 06:43:24 DEBUG : dir: reading active writers 2021/07/25 06:43:24 DEBUG : newLeaf: reading active writers 2021/07/25 06:43:24 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms 2021/07/25 06:43:24 DEBUG : dir: Looking for writers 2021/07/25 06:43:24 DEBUG : : Looking for writers 2021/07/25 06:43:24 DEBUG : newLeaf: reading active writers 2021/07/25 06:43:24 DEBUG : dir: reading active writers 2021/07/25 06:43:24 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms 2021/07/25 06:43:24 DEBUG : dir: Looking for writers 2021/07/25 06:43:24 DEBUG : : Looking for writers 2021/07/25 06:43:24 DEBUG : dir: reading active writers 2021/07/25 06:43:24 DEBUG : newLeaf: reading active writers 2021/07/25 06:43:24 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms 2021/07/25 06:43:24 DEBUG : newLeaf: vfs cache: starting upload 2021/07/25 06:43:24 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: doInitUpload(map[directuploadsupport:n fi_contenttype:application/octet-stream fi_filename:newLeaf fi_localtime:2021-07-25 06:42:23 fi_modified:2021-07-25 06:42:23 fi_name:newLeaf fi_pid:121000361 fi_size:25 responsetype:json]) options=[] 2021/07/25 06:43:24 DEBUG : dir: Looking for writers 2021/07/25 06:43:24 DEBUG : : Looking for writers 2021/07/25 06:43:24 DEBUG : dir: reading active writers 2021/07/25 06:43:24 DEBUG : newLeaf: reading active writers 2021/07/25 06:43:24 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms 2021/07/25 06:43:24 DEBUG : dir: Looking for writers 2021/07/25 06:43:24 DEBUG : : Looking for writers 2021/07/25 06:43:24 DEBUG : dir: reading active writers 2021/07/25 06:43:24 DEBUG : newLeaf: reading active writers 2021/07/25 06:43:24 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms 2021/07/25 06:43:25 DEBUG : dir: Looking for writers 2021/07/25 06:43:25 DEBUG : : Looking for writers 2021/07/25 06:43:25 DEBUG : dir: reading active writers 2021/07/25 06:43:25 DEBUG : newLeaf: reading active writers 2021/07/25 06:43:25 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms 2021/07/25 06:43:25 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:43:25 DEBUG : dir: Looking for writers 2021/07/25 06:43:25 DEBUG : : Looking for writers 2021/07/25 06:43:25 DEBUG : dir: reading active writers 2021/07/25 06:43:25 DEBUG : newLeaf: reading active writers 2021/07/25 06:43:25 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/07/25 06:43:26 DEBUG : dir: Looking for writers 2021/07/25 06:43:26 DEBUG : : Looking for writers 2021/07/25 06:43:26 DEBUG : newLeaf: reading active writers 2021/07/25 06:43:26 DEBUG : dir: reading active writers 2021/07/25 06:43:26 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/07/25 06:43:26 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: doCompleteUpload(map[fi_size:25 remotetime:2021-07-25 06:42:23 uploadcode:df1eb65204d7eb7b985a08ee2a16793d]) options=[] 2021/07/25 06:43:27 DEBUG : dir: Looking for writers 2021/07/25 06:43:27 DEBUG : : Looking for writers 2021/07/25 06:43:27 DEBUG : dir: reading active writers 2021/07/25 06:43:27 DEBUG : newLeaf: reading active writers 2021/07/25 06:43:27 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/07/25 06:43:28 DEBUG : dir: Looking for writers 2021/07/25 06:43:28 DEBUG : : Looking for writers 2021/07/25 06:43:28 DEBUG : dir: reading active writers 2021/07/25 06:43:28 DEBUG : newLeaf: reading active writers 2021/07/25 06:43:28 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/07/25 06:43:29 DEBUG : dir: Looking for writers 2021/07/25 06:43:29 DEBUG : : Looking for writers 2021/07/25 06:43:29 DEBUG : dir: reading active writers 2021/07/25 06:43:29 DEBUG : newLeaf: reading active writers 2021/07/25 06:43:29 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/07/25 06:43:30 DEBUG : dir: Looking for writers 2021/07/25 06:43:30 DEBUG : : Looking for writers 2021/07/25 06:43:30 DEBUG : dir: reading active writers 2021/07/25 06:43:30 DEBUG : newLeaf: reading active writers 2021/07/25 06:43:30 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/07/25 06:43:31 DEBUG : dir: Looking for writers 2021/07/25 06:43:31 DEBUG : : Looking for writers 2021/07/25 06:43:31 DEBUG : dir: reading active writers 2021/07/25 06:43:31 DEBUG : newLeaf: reading active writers 2021/07/25 06:43:31 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/07/25 06:43:32 DEBUG : dir: Looking for writers 2021/07/25 06:43:32 DEBUG : : Looking for writers 2021/07/25 06:43:32 DEBUG : newLeaf: reading active writers 2021/07/25 06:43:32 DEBUG : dir: reading active writers 2021/07/25 06:43:32 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/07/25 06:43:33 DEBUG : dir: Looking for writers 2021/07/25 06:43:33 DEBUG : : Looking for writers 2021/07/25 06:43:33 DEBUG : newLeaf: reading active writers 2021/07/25 06:43:33 DEBUG : dir: reading active writers 2021/07/25 06:43:33 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/07/25 06:43:34 ERROR : Exiting even though 0 writers active and 1 cache items in use after 10s Cache{ "newLeaf": &{c:0xc0002bccc0 mu:{state:0 sema:0} cond:0xc00083b880 name:newLeaf opens:0 downloaders: o:0xc000940300 fd: modified:false info:{ModTime:{wall:13850644542783379056 ext:810584944605 loc:0x2b68fc0} ATime:{wall:13850644608133277083 ext:871436591360 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:43:34 DEBUG : >WaitForWriters: 2021/07/25 06:43:34 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: getFolderContents(map[count:1000 fi_pid:121000361 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:43:38 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:43:38 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: getFolderContents(map[count:1000 fi_pid:121000442 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:43:42 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >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:43:43 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': 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:43:43 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:43:43 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: getFolderContents(map[count:1000 fi_pid:121000361 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:43:47 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:43:47 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: getFolderContents(map[count:1000 fi_pid:121000442 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:43:47 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= fstest.go:293: Sleeping for 6s just to make sure 2021/07/25 06:43:53 DEBUG : WaitForWriters: timeout=10s 2021/07/25 06:43:53 DEBUG : dir: Looking for writers 2021/07/25 06:43:53 DEBUG : : Looking for writers 2021/07/25 06:43:53 DEBUG : dir: reading active writers 2021/07/25 06:43:53 DEBUG : newLeaf: reading active writers 2021/07/25 06:43:53 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms 2021/07/25 06:43:53 DEBUG : dir: Looking for writers 2021/07/25 06:43:53 DEBUG : : Looking for writers 2021/07/25 06:43:53 DEBUG : dir: reading active writers 2021/07/25 06:43:53 DEBUG : newLeaf: reading active writers 2021/07/25 06:43:53 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms 2021/07/25 06:43:53 DEBUG : dir: Looking for writers 2021/07/25 06:43:53 DEBUG : : Looking for writers 2021/07/25 06:43:53 DEBUG : dir: reading active writers 2021/07/25 06:43:53 DEBUG : newLeaf: reading active writers 2021/07/25 06:43:53 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms 2021/07/25 06:43:53 DEBUG : dir: Looking for writers 2021/07/25 06:43:53 DEBUG : : Looking for writers 2021/07/25 06:43:53 DEBUG : dir: reading active writers 2021/07/25 06:43:53 DEBUG : newLeaf: reading active writers 2021/07/25 06:43:53 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms 2021/07/25 06:43:53 DEBUG : dir: Looking for writers 2021/07/25 06:43:53 DEBUG : : Looking for writers 2021/07/25 06:43:53 DEBUG : dir: reading active writers 2021/07/25 06:43:53 DEBUG : newLeaf: reading active writers 2021/07/25 06:43:53 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms 2021/07/25 06:43:53 DEBUG : dir: Looking for writers 2021/07/25 06:43:53 DEBUG : : Looking for writers 2021/07/25 06:43:53 DEBUG : dir: reading active writers 2021/07/25 06:43:53 DEBUG : newLeaf: reading active writers 2021/07/25 06:43:53 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms 2021/07/25 06:43:54 DEBUG : dir: Looking for writers 2021/07/25 06:43:54 DEBUG : : Looking for writers 2021/07/25 06:43:54 DEBUG : dir: reading active writers 2021/07/25 06:43:54 DEBUG : newLeaf: reading active writers 2021/07/25 06:43:54 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms 2021/07/25 06:43:54 DEBUG : dir: Looking for writers 2021/07/25 06:43:54 DEBUG : : Looking for writers 2021/07/25 06:43:54 DEBUG : dir: reading active writers 2021/07/25 06:43:54 DEBUG : newLeaf: reading active writers 2021/07/25 06:43:54 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/07/25 06:43:55 DEBUG : dir: Looking for writers 2021/07/25 06:43:55 DEBUG : : Looking for writers 2021/07/25 06:43:55 DEBUG : dir: reading active writers 2021/07/25 06:43:55 DEBUG : newLeaf: reading active writers 2021/07/25 06:43:55 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/07/25 06:43:56 DEBUG : dir: Looking for writers 2021/07/25 06:43:56 DEBUG : : Looking for writers 2021/07/25 06:43:56 DEBUG : dir: reading active writers 2021/07/25 06:43:56 DEBUG : newLeaf: reading active writers 2021/07/25 06:43:56 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/07/25 06:43:57 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:43:57 INFO : newLeaf: Copied (replaced existing) 2021/07/25 06:43:57 DEBUG : newLeaf: vfs cache: fingerprint now "25,2021-07-25 06:42:23 +0000 UTC" 2021/07/25 06:43:57 DEBUG : newLeaf: vfs cache: writeback object to VFS layer 2021/07/25 06:43:57 DEBUG : : Added virtual directory entry vAddFile: "newLeaf" 2021/07/25 06:43:57 INFO : newLeaf: vfs cache: upload succeeded try #1 2021/07/25 06:43:57 DEBUG : dir: Looking for writers 2021/07/25 06:43:57 DEBUG : : Looking for writers 2021/07/25 06:43:57 DEBUG : dir: reading active writers 2021/07/25 06:43:57 DEBUG : newLeaf: reading active writers 2021/07/25 06:43:57 DEBUG : >WaitForWriters: 2021/07/25 06:43:57 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: getFolderContents(map[count:1000 fi_pid:121000361 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:43:57 DEBUG : vfs cache: cleaner exiting 2021/07/25 06:43:59 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:43:59 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: doDeleteFile(map[completedeletion:n fi_id:121000446]) options=[] 2021/07/25 06:44:15 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:44:15 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: getFolderContents(map[count:1000 fi_pid:121000442 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:44:16 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:44:16 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: getFolderContents(map[count:1000 fi_pid:121000442 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:44:16 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:44:16 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: doDeleteFolder(map[fi_id:121000442]) options=[] 2021/07/25 06:44:21 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= 2021/07/25 06:44:21 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: getFolderContents(map[count:1000 fi_pid:121000361 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:44:21 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >rpc: result=Success (ok), err= --- FAIL: TestFileRename (627.04s) --- FAIL: TestFileRename/minimal,forceCache=true (204.31s) --- PASS: TestFileRename/writes,forceCache=true (422.73s) FAIL 2021/07/25 06:44:21 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': Purge remote 2021/07/25 06:44:21 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': rpc: doDeleteFolder(map[fi_id:121000361]) options=[] 2021/07/25 06:44:21 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': Sleeping for 6s to wait for "error_background" error to clear 2021/07/25 06:44:27 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:44:27 DEBUG : pacer: Rate limited, increasing sleep to 40ms 2021/07/25 06:44:28 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': Sleeping for 6s to wait for "error_background" error to clear 2021/07/25 06:44:34 DEBUG : pacer: low level retry 2/10 (error The requested operation cannot be completed. A delete operation is already being processed in this folder. Please try again later. (error_background)) 2021/07/25 06:44:34 DEBUG : pacer: Rate limited, increasing sleep to 80ms 2021/07/25 06:44:38 DEBUG : pacer: Reducing sleep to 60ms 2021/07/25 06:44:38 DEBUG : filefabric root 'rclone-test-tavacug1tavuxun9tonilah2': >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 15m45.158516021s (try 4/5): exit status 1: Failed [TestDirRename TestFileRename/minimal,forceCache=true]