"./vfs.test -test.v -test.timeout 1h0m0s -remote TestFileFabric: -verbose -test.run '^TestDirRename$'" - Starting (try 5/5) 2021/06/01 06:35:36 DEBUG : Creating backend with remote "TestFileFabric:rclone-test-fetayaz7guzexod7lagiqaf0" 2021/06/01 06:35:36 DEBUG : Using config file from "/home/rclone/.rclone.conf" 2021/06/01 06:35:36 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': rpc: checkPathExists(map[path:rclone-test-fetayaz7guzexod7lagiqaf0 pid:120673762]) options=[] 2021/06/01 06:35:37 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': >rpc: result=Success (ok), err= 2021/06/01 06:35:37 DEBUG : Creating backend with remote "/tmp/rclone093428445" === RUN TestDirRename run.go:176: Remote "filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0'", Local "Local file system at /tmp/rclone093428445", Modify Window "1s" 2021/06/01 06:35:37 INFO : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': poll-interval is not supported by this remote 2021/06/01 06:35:37 NOTICE: filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': --vfs-cache-mode writes or full is recommended for this remote as it can't stream 2021/06/01 06:35:37 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': 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/06/01 06:35:37 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': >rpc: result=Success (ok), err= 2021/06/01 06:35:37 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': rpc: doCreateNewFolder(map[fi_name:rclone-test-fetayaz7guzexod7lagiqaf0 fi_pid:120673762]) options=[] 2021/06/01 06:35:41 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': >rpc: result=Success (ok), err= 2021/06/01 06:35:41 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': rpc: getFolderContents(map[count:1000 fi_pid:120933889 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/06/01 06:35:42 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': >rpc: result=Success (ok), err= 2021/06/01 06:35:42 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': rpc: doCreateNewFolder(map[fi_name:dir fi_pid:120933889]) options=[] 2021/06/01 06:35:46 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': >rpc: result=Success (ok), err= 2021/06/01 06:35:46 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': 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:120933891 fi_size:14 responsetype:json]) options=[] 2021/06/01 06:35:47 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': >rpc: result=Success (ok), err= 2021/06/01 06:35:48 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': rpc: doCompleteUpload(map[fi_size:14 remotetime:2001-02-03 04:05:06 uploadcode:169ce1f844294592322ee6e57b22f46b]) options=[] 2021/06/01 06:35:50 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': >rpc: result=Success (ok), err= 2021/06/01 06:35:50 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': rpc: getFolderContents(map[count:1000 fi_pid:120933889 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/06/01 06:35:51 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': >rpc: result=Success (ok), err= 2021/06/01 06:35:51 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': rpc: getFolderContents(map[count:1000 fi_pid:120933891 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/06/01 06:35:53 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': >rpc: result=Success (ok), err= 2021/06/01 06:35:53 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': rpc: getFolderContents(map[count:1000 fi_pid:120933889 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/06/01 06:35:56 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': >rpc: result=Success (ok), err= 2021/06/01 06:35:56 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': 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:120933891 fi_size:15 responsetype:json]) options=[] 2021/06/01 06:35:57 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': >rpc: result=Success (ok), err= 2021/06/01 06:35:58 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': rpc: doCompleteUpload(map[fi_size:15 remotetime:2001-02-03 04:05:06 uploadcode:3b99b11e031b5d1806c407da3a15b228]) options=[] 2021/06/01 06:36:00 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': >rpc: result=Success (ok), err= 2021/06/01 06:36:00 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': rpc: getFolderContents(map[count:1000 fi_pid:120933889 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/06/01 06:36:00 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': >rpc: result=Success (ok), err= 2021/06/01 06:36:00 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': rpc: getFolderContents(map[count:1000 fi_pid:120933891 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/06/01 06:36:01 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': >rpc: result=Success (ok), err= 2021/06/01 06:36:01 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': rpc: getFolderContents(map[count:1000 fi_pid:120933891 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/06/01 06:36:02 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': >rpc: result=Success (ok), err= 2021/06/01 06:36:02 ERROR : dir/not found: Dir.Rename error: file does not exist 2021/06/01 06:36:02 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': rpc: getFolderContents(map[count:1000 fi_pid:120933889 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/06/01 06:36:02 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': >rpc: result=Success (ok), err= 2021/06/01 06:36:02 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': rpc: doRenameFolder(map[fi_id:120933891 fi_name:dir2]) options=[] 2021/06/01 06:36:21 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': >rpc: result=Success (ok), err= 2021/06/01 06:36:21 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': rpc: getUserBackgroundTasks(map[taskid:1195662]) options=[] 2021/06/01 06:36:22 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': >rpc: result=Success (ok), err= 2021/06/01 06:36:22 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': Waiting for task ID 1195662: Rename folder S3 Storage/smestoragencw/rclone-test-fetayaz7guzexod7lagiqaf0/dir2: to completed for 1s - waited 1.130121368s already 2021/06/01 06:36:23 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': rpc: getUserBackgroundTasks(map[taskid:1195662]) options=[] 2021/06/01 06:36:24 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': >rpc: result=Success (ok), err= 2021/06/01 06:36:24 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': Waiting for task ID 1195662: Rename folder S3 Storage/smestoragencw/rclone-test-fetayaz7guzexod7lagiqaf0/dir2: to completed for 1s - waited 3.076199914s already 2021/06/01 06:36:25 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': rpc: getUserBackgroundTasks(map[taskid:1195662]) options=[] 2021/06/01 06:36:26 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': >rpc: result=Success (ok), err= 2021/06/01 06:36:26 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': Waiting for task ID 1195662: Rename folder S3 Storage/smestoragencw/rclone-test-fetayaz7guzexod7lagiqaf0/dir2: to completed for 1s - waited 5.000220941s already 2021/06/01 06:36:27 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': rpc: getUserBackgroundTasks(map[taskid:1195662]) options=[] 2021/06/01 06:36:28 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': >rpc: result=Success (ok), err= 2021/06/01 06:36:28 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': Waiting for task ID 1195662: Rename folder S3 Storage/smestoragencw/rclone-test-fetayaz7guzexod7lagiqaf0/dir2: to completed for 1s - waited 7.106837326s already 2021/06/01 06:36:29 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': rpc: getUserBackgroundTasks(map[taskid:1195662]) options=[] 2021/06/01 06:36:31 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': >rpc: result=Success (ok), err= 2021/06/01 06:36:31 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': Waiting for task ID 1195662: Rename folder S3 Storage/smestoragencw/rclone-test-fetayaz7guzexod7lagiqaf0/dir2: to completed for 1s - waited 10.502346279s already 2021/06/01 06:36:32 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': rpc: getUserBackgroundTasks(map[taskid:1195662]) options=[] 2021/06/01 06:36:33 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': >rpc: result=Success (ok), err= 2021/06/01 06:36:33 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': Waiting for task ID 1195662: Rename folder S3 Storage/smestoragencw/rclone-test-fetayaz7guzexod7lagiqaf0/dir2: to completed for 1s - waited 12.600884603s already 2021/06/01 06:36:34 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': rpc: getUserBackgroundTasks(map[taskid:1195662]) options=[] 2021/06/01 06:36:36 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': >rpc: result=Success (ok), err= 2021/06/01 06:36:36 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': Waiting for task ID 1195662: Rename folder S3 Storage/smestoragencw/rclone-test-fetayaz7guzexod7lagiqaf0/dir2: to completed for 1s - waited 15.334025531s already 2021/06/01 06:36:37 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': rpc: getUserBackgroundTasks(map[taskid:1195662]) options=[] 2021/06/01 06:36:38 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': >rpc: result=Success (ok), err= 2021/06/01 06:36:38 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': Waiting for task ID 1195662: Rename folder S3 Storage/smestoragencw/rclone-test-fetayaz7guzexod7lagiqaf0/dir2: to completed for 1s - waited 17.852887784s already 2021/06/01 06:36:39 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': rpc: getUserBackgroundTasks(map[taskid:1195662]) options=[] 2021/06/01 06:36:42 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': >rpc: result=Success (ok), err= 2021/06/01 06:36:42 DEBUG : dir: Updating dir with dir2 0xc0000d5e00 2021/06/01 06:36:42 DEBUG : dir: forgetting directory cache 2021/06/01 06:36:42 DEBUG : : Added virtual directory entry vDel: "dir" 2021/06/01 06:36:42 DEBUG : : Added virtual directory entry vAddDir: "dir2" 2021/06/01 06:36:42 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': rpc: getFolderContents(map[count:1000 fi_pid:120933889 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/06/01 06:36:44 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': >rpc: result=Success (ok), err= 2021/06/01 06:36:44 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': rpc: getFolderContents(map[count:1000 fi_pid:120933891 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/06/01 06:36:45 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': >rpc: result=Success (ok), err= 2021/06/01 06:36:45 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': rpc: getFolderContents(map[count:1000 fi_pid:120933889 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/06/01 06:36:46 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': >rpc: result=Success (ok), err= 2021/06/01 06:36:46 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': rpc: getFolderContents(map[count:1000 fi_pid:120933891 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/06/01 06:36:46 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': >rpc: result=Success (ok), err= 2021/06/01 06:36:46 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': rpc: checkPathExists(map[path:file2 pid:120933889]) options=[] 2021/06/01 06:36:46 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': >rpc: result=Success (ok), err= 2021/06/01 06:36:46 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': rpc: doRenameFile(map[fi_id:120933893 fi_name:file2.jitufoy6]) options=[] 2021/06/01 06:36:56 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': >rpc: result=Success (ok), err= 2021/06/01 06:36:56 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': rpc: doMoveFiles(map[dir_id:120933889 fi_ids:120933893]) options=[] 2021/06/01 06:37:28 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': >rpc: result=Succcess. (ok), err= 2021/06/01 06:37:28 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': rpc: doRenameFile(map[fi_id:120933893 fi_name:file2]) options=[] 2021/06/01 06:37:39 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': >rpc: result=Success (ok), err= 2021/06/01 06:37:39 INFO : dir2/file1: Moved (server-side) to: file2 2021/06/01 06:37:39 DEBUG : file2: Updating file with file2 0xc000844480 2021/06/01 06:37:39 DEBUG : dir2: Added virtual directory entry vDel: "file1" 2021/06/01 06:37:39 DEBUG : : Added virtual directory entry vAddFile: "file2" 2021/06/01 06:37:39 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': rpc: getFolderContents(map[count:1000 fi_pid:120933889 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/06/01 06:37:40 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': >rpc: result=Success (ok), err= 2021/06/01 06:37:40 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': rpc: getFolderContents(map[count:1000 fi_pid:120933891 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/06/01 06:37:42 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': >rpc: result=Success (ok), err= 2021/06/01 06:37:42 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': rpc: checkPathExists(map[path:dir2/file3 pid:120933889]) options=[] 2021/06/01 06:37:42 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': >rpc: result=Success (ok), err= 2021/06/01 06:37:42 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': rpc: doDeleteFile(map[completedeletion:n fi_id:120933895]) options=[] 2021/06/01 06:37:53 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': >rpc: result=Success (ok), err= 2021/06/01 06:37:53 INFO : dir2/file3: Deleted 2021/06/01 06:37:53 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': rpc: doRenameFile(map[fi_id:120933893 fi_name:file3.gobiket1]) options=[] 2021/06/01 06:38:06 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': >rpc: result=Success (ok), err= 2021/06/01 06:38:06 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': rpc: doMoveFiles(map[dir_id:120933891 fi_ids:120933893]) options=[] 2021/06/01 06:38:36 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': >rpc: result=Succcess. (ok), err= 2021/06/01 06:38:36 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': rpc: doRenameFile(map[fi_id:120933893 fi_name:file3]) options=[] 2021/06/01 06:38:45 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': >rpc: result=Success (ok), err= 2021/06/01 06:38:45 INFO : file2: Moved (server-side) to: dir2/file3 2021/06/01 06:38:45 DEBUG : dir2/file3: Updating file with dir2/file3 0xc000844480 2021/06/01 06:38:45 DEBUG : : Added virtual directory entry vDel: "file2" 2021/06/01 06:38:45 DEBUG : dir2: Added virtual directory entry vAddFile: "file3" 2021/06/01 06:38:45 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': rpc: getFolderContents(map[count:1000 fi_pid:120933889 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/06/01 06:38:46 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': >rpc: result=Success (ok), err= 2021/06/01 06:38:46 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': rpc: getFolderContents(map[count:1000 fi_pid:120933891 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/06/01 06:38:48 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': >rpc: result=Success (ok), err= 2021/06/01 06:38:48 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': rpc: getFolderContents(map[count:1000 fi_pid:120933889 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/06/01 06:38:49 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': >rpc: result=Success (ok), err= 2021/06/01 06:38:49 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': rpc: doCreateNewFolder(map[fi_name:empty directory fi_pid:120933889]) options=[] 2021/06/01 06:38:53 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': >rpc: result=Success (ok), err= 2021/06/01 06:38:53 DEBUG : : Added virtual directory entry vAddDir: "empty directory" 2021/06/01 06:38:53 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': rpc: getFolderContents(map[count:1000 fi_pid:120933889 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/06/01 06:38:54 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': >rpc: result=Success (ok), err= 2021/06/01 06:38:54 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': rpc: doRenameFolder(map[fi_id:120933919 fi_name:renamed empty directory]) options=[] 2021/06/01 06:39:05 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': >rpc: result=Success (ok), err=json: cannot unmarshal number into Go struct field FileResponse.taskid of type string 2021/06/01 06:39:05 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:2003 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/06/01 06:39:05 DEBUG : WaitForWriters: timeout=10s 2021/06/01 06:39:05 DEBUG : dir2: Looking for writers 2021/06/01 06:39:05 DEBUG : file3: reading active writers 2021/06/01 06:39:05 DEBUG : empty directory: Looking for writers 2021/06/01 06:39:05 DEBUG : : Looking for writers 2021/06/01 06:39:05 DEBUG : dir2: reading active writers 2021/06/01 06:39:05 DEBUG : empty directory: reading active writers 2021/06/01 06:39:05 DEBUG : >WaitForWriters: 2021/06/01 06:39:05 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': rpc: getFolderContents(map[count:1000 fi_pid:120933889 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/06/01 06:39:06 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': >rpc: result=Success (ok), err= 2021/06/01 06:39:06 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': rpc: getFolderContents(map[count:1000 fi_pid:120933919 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/06/01 06:39:06 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': rpc: getFolderContents(map[count:1000 fi_pid:120933891 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/06/01 06:39:06 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': >rpc: result=Success (ok), err= 2021/06/01 06:39:06 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': rpc: doDeleteFile(map[completedeletion:n fi_id:120933893]) options=[] 2021/06/01 06:39:07 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': >rpc: result=Success (ok), err= 2021/06/01 06:39:21 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': >rpc: result=Success (ok), err= 2021/06/01 06:39:21 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': rpc: getFolderContents(map[count:1000 fi_pid:120933919 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/06/01 06:39:22 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': >rpc: result=Success (ok), err= 2021/06/01 06:39:22 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': rpc: doDeleteFolder(map[fi_id:120933919]) options=[] 2021/06/01 06:39:26 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': >rpc: result=Success (ok), err= 2021/06/01 06:39:26 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': rpc: getFolderContents(map[count:1000 fi_pid:120933891 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/06/01 06:39:28 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': >rpc: result=Success (ok), err= 2021/06/01 06:39:28 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': rpc: doDeleteFolder(map[fi_id:120933891]) options=[] 2021/06/01 06:39:32 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': >rpc: result=Success (ok), err= 2021/06/01 06:39:32 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': rpc: getFolderContents(map[count:1000 fi_pid:120933889 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/06/01 06:39:33 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': >rpc: result=Success (ok), err= --- FAIL: TestDirRename (236.09s) FAIL 2021/06/01 06:39:33 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': Purge remote 2021/06/01 06:39:33 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': rpc: doDeleteFolder(map[fi_id:120933889]) options=[] 2021/06/01 06:39:33 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': Sleeping for 6s to wait for "error_background" error to clear 2021/06/01 06:39:39 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/06/01 06:39:39 DEBUG : pacer: Rate limited, increasing sleep to 40ms 2021/06/01 06:39:39 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': Sleeping for 6s to wait for "error_background" error to clear 2021/06/01 06:39:45 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/06/01 06:39:45 DEBUG : pacer: Rate limited, increasing sleep to 80ms 2021/06/01 06:39:46 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': Sleeping for 6s to wait for "error_background" error to clear 2021/06/01 06:39:52 DEBUG : pacer: low level retry 3/10 (error The requested operation cannot be completed. A delete operation is already being processed in this folder. Please try again later. (error_background)) 2021/06/01 06:39:52 DEBUG : pacer: Rate limited, increasing sleep to 160ms 2021/06/01 06:39:53 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': Sleeping for 6s to wait for "error_background" error to clear 2021/06/01 06:39:59 DEBUG : pacer: low level retry 4/10 (error The requested operation cannot be completed. A delete operation is already being processed in this folder. Please try again later. (error_background)) 2021/06/01 06:39:59 DEBUG : pacer: Rate limited, increasing sleep to 320ms 2021/06/01 06:39:59 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': Sleeping for 6s to wait for "error_background" error to clear 2021/06/01 06:40:05 DEBUG : pacer: low level retry 5/10 (error The requested operation cannot be completed. A delete operation is already being processed in this folder. Please try again later. (error_background)) 2021/06/01 06:40:05 DEBUG : pacer: Rate limited, increasing sleep to 640ms 2021/06/01 06:40:06 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': Sleeping for 6s to wait for "error_background" error to clear 2021/06/01 06:40:12 DEBUG : pacer: low level retry 6/10 (error The requested operation cannot be completed. A delete operation is already being processed in this folder. Please try again later. (error_background)) 2021/06/01 06:40:12 DEBUG : pacer: Rate limited, increasing sleep to 1.28s 2021/06/01 06:40:12 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': Sleeping for 6s to wait for "error_background" error to clear 2021/06/01 06:40:18 DEBUG : pacer: low level retry 7/10 (error The requested operation cannot be completed. A delete operation is already being processed in this folder. Please try again later. (error_background)) 2021/06/01 06:40:18 DEBUG : pacer: Rate limited, increasing sleep to 2.56s 2021/06/01 06:40:18 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': Sleeping for 6s to wait for "error_background" error to clear 2021/06/01 06:40:24 DEBUG : pacer: low level retry 8/10 (error The requested operation cannot be completed. A delete operation is already being processed in this folder. Please try again later. (error_background)) 2021/06/01 06:40:24 DEBUG : pacer: Rate limited, increasing sleep to 5.12s 2021/06/01 06:40:24 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': Sleeping for 6s to wait for "error_background" error to clear 2021/06/01 06:40:30 DEBUG : pacer: low level retry 9/10 (error We are not able to complete the requested operation. We are processing move folder in parent folder. Please try again later. (error_background)) 2021/06/01 06:40:30 DEBUG : pacer: Rate limited, increasing sleep to 10s 2021/06/01 06:40:31 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': Sleeping for 6s to wait for "error_background" error to clear 2021/06/01 06:40:37 DEBUG : pacer: low level retry 10/10 (error We are not able to complete the requested operation. We are processing move folder in parent folder. Please try again later. (error_background)) 2021/06/01 06:40:37 DEBUG : filefabric root 'rclone-test-fetayaz7guzexod7lagiqaf0': >rpc: result=We are not able to complete the requested operation. We are processing move folder in parent folder. Please try again later. (error_background), err=We are not able to complete the requested operation. We are processing move folder in parent folder. Please try again later. (error_background) 2021/06/01 06:40:37 purge failed: failed to remove directory: We are not able to complete the requested operation. We are processing move folder in parent folder. Please try again later. (error_background) "./vfs.test -test.v -test.timeout 1h0m0s -remote TestFileFabric: -verbose -test.run '^TestDirRename$'" - Finished ERROR in 5m0.447870934s (try 5/5): exit status 1: Failed [TestDirRename]