"./vfs.test -test.v -test.timeout 1h0m0s -remote TestFileFabric: -verbose -test.run '^TestDirRename$'" - Starting (try 4/5) 2021/06/01 06:30:44 DEBUG : Creating backend with remote "TestFileFabric:rclone-test-dumonag9vikakeg8nudeqew5" 2021/06/01 06:30:44 DEBUG : Using config file from "/home/rclone/.rclone.conf" 2021/06/01 06:30:44 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': rpc: checkPathExists(map[path:rclone-test-dumonag9vikakeg8nudeqew5 pid:120673762]) options=[] 2021/06/01 06:30:45 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': >rpc: result=Success (ok), err= 2021/06/01 06:30:45 DEBUG : Creating backend with remote "/tmp/rclone143679086" === RUN TestDirRename run.go:176: Remote "filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5'", Local "Local file system at /tmp/rclone143679086", Modify Window "1s" 2021/06/01 06:30:45 INFO : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': poll-interval is not supported by this remote 2021/06/01 06:30:45 NOTICE: filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': --vfs-cache-mode writes or full is recommended for this remote as it can't stream 2021/06/01 06:30:45 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': 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:30:45 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': >rpc: result=Success (ok), err= 2021/06/01 06:30:45 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': rpc: doCreateNewFolder(map[fi_name:rclone-test-dumonag9vikakeg8nudeqew5 fi_pid:120673762]) options=[] 2021/06/01 06:30:50 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': >rpc: result=Success (ok), err= 2021/06/01 06:30:50 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': rpc: getFolderContents(map[count:1000 fi_pid:120933842 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:30:52 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': >rpc: result=Success (ok), err= 2021/06/01 06:30:52 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': rpc: doCreateNewFolder(map[fi_name:dir fi_pid:120933842]) options=[] 2021/06/01 06:30:56 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': >rpc: result=Success (ok), err= 2021/06/01 06:30:56 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': 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:120933844 fi_size:14 responsetype:json]) options=[] 2021/06/01 06:30:57 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': >rpc: result=Success (ok), err= 2021/06/01 06:30:58 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': rpc: doCompleteUpload(map[fi_size:14 remotetime:2001-02-03 04:05:06 uploadcode:5b788ed70fa25944040354368933e605]) options=[] 2021/06/01 06:31:00 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': >rpc: result=Success (ok), err= 2021/06/01 06:31:00 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': rpc: getFolderContents(map[count:1000 fi_pid:120933842 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:31:01 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': >rpc: result=Success (ok), err= 2021/06/01 06:31:01 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': rpc: getFolderContents(map[count:1000 fi_pid:120933844 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:31:03 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': >rpc: result=Success (ok), err= 2021/06/01 06:31:03 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': rpc: getFolderContents(map[count:1000 fi_pid:120933842 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:31:03 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': >rpc: result=Success (ok), err= 2021/06/01 06:31:03 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': 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:120933844 fi_size:15 responsetype:json]) options=[] 2021/06/01 06:31:05 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': >rpc: result=Success (ok), err= 2021/06/01 06:31:07 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': rpc: doCompleteUpload(map[fi_size:15 remotetime:2001-02-03 04:05:06 uploadcode:33f0d5ef2fc5f0d84131fa430a3392c1]) options=[] 2021/06/01 06:31:11 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': >rpc: result=Success (ok), err= 2021/06/01 06:31:11 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': rpc: getFolderContents(map[count:1000 fi_pid:120933842 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:31:14 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': >rpc: result=Success (ok), err= 2021/06/01 06:31:14 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': rpc: getFolderContents(map[count:1000 fi_pid:120933844 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:31:19 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': >rpc: result=Success (ok), err= 2021/06/01 06:31:19 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': rpc: getFolderContents(map[count:1000 fi_pid:120933844 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:31:20 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': >rpc: result=Success (ok), err= 2021/06/01 06:31:20 ERROR : dir/not found: Dir.Rename error: file does not exist 2021/06/01 06:31:20 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': rpc: getFolderContents(map[count:1000 fi_pid:120933842 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:31:20 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': >rpc: result=Success (ok), err= 2021/06/01 06:31:20 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': rpc: doRenameFolder(map[fi_id:120933844 fi_name:dir2]) options=[] 2021/06/01 06:31:37 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': >rpc: result=Success (ok), err= 2021/06/01 06:31:37 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': rpc: getUserBackgroundTasks(map[taskid:1195621]) options=[] 2021/06/01 06:31:38 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': >rpc: result=Success (ok), err= 2021/06/01 06:31:38 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': Waiting for task ID 1195621: Rename folder S3 Storage/smestoragencw/rclone-test-dumonag9vikakeg8nudeqew5/dir2: to completed for 1s - waited 1.174336569s already 2021/06/01 06:31:39 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': rpc: getUserBackgroundTasks(map[taskid:1195621]) options=[] 2021/06/01 06:31:40 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': >rpc: result=Success (ok), err= 2021/06/01 06:31:40 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': Waiting for task ID 1195621: Rename folder S3 Storage/smestoragencw/rclone-test-dumonag9vikakeg8nudeqew5/dir2: to completed for 1s - waited 3.812687953s already 2021/06/01 06:31:41 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': rpc: getUserBackgroundTasks(map[taskid:1195621]) options=[] 2021/06/01 06:31:43 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': >rpc: result=Success (ok), err= 2021/06/01 06:31:43 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': Waiting for task ID 1195621: Rename folder S3 Storage/smestoragencw/rclone-test-dumonag9vikakeg8nudeqew5/dir2: to completed for 1s - waited 5.887557154s already 2021/06/01 06:31:44 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': rpc: getUserBackgroundTasks(map[taskid:1195621]) options=[] 2021/06/01 06:31:46 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': >rpc: result=Success (ok), err= 2021/06/01 06:31:46 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': Waiting for task ID 1195621: Rename folder S3 Storage/smestoragencw/rclone-test-dumonag9vikakeg8nudeqew5/dir2: to completed for 1s - waited 9.286381193s already 2021/06/01 06:31:47 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': rpc: getUserBackgroundTasks(map[taskid:1195621]) options=[] 2021/06/01 06:31:48 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': >rpc: result=Success (ok), err= 2021/06/01 06:31:48 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': Waiting for task ID 1195621: Rename folder S3 Storage/smestoragencw/rclone-test-dumonag9vikakeg8nudeqew5/dir2: to completed for 1s - waited 11.339321481s already 2021/06/01 06:31:49 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': rpc: getUserBackgroundTasks(map[taskid:1195621]) options=[] 2021/06/01 06:31:50 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': >rpc: result=Success (ok), err= 2021/06/01 06:31:50 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': Waiting for task ID 1195621: Rename folder S3 Storage/smestoragencw/rclone-test-dumonag9vikakeg8nudeqew5/dir2: to completed for 1s - waited 13.534623208s already 2021/06/01 06:31:51 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': rpc: getUserBackgroundTasks(map[taskid:1195621]) options=[] 2021/06/01 06:31:54 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': >rpc: result=Success (ok), err= 2021/06/01 06:31:54 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': Waiting for task ID 1195621: Rename folder S3 Storage/smestoragencw/rclone-test-dumonag9vikakeg8nudeqew5/dir2: to completed for 1s - waited 16.836939303s already 2021/06/01 06:31:55 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': rpc: getUserBackgroundTasks(map[taskid:1195621]) options=[] 2021/06/01 06:31:55 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': >rpc: result=Success (ok), err= 2021/06/01 06:31:55 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': Waiting for task ID 1195621: Rename folder S3 Storage/smestoragencw/rclone-test-dumonag9vikakeg8nudeqew5/dir2: to completed for 1s - waited 18.801205738s already 2021/06/01 06:31:56 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': rpc: getUserBackgroundTasks(map[taskid:1195621]) options=[] 2021/06/01 06:31:58 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': >rpc: result=Success (ok), err= 2021/06/01 06:31:58 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': Waiting for task ID 1195621: Rename folder S3 Storage/smestoragencw/rclone-test-dumonag9vikakeg8nudeqew5/dir2: to completed for 1s - waited 21.108152538s already 2021/06/01 06:31:59 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': rpc: getUserBackgroundTasks(map[taskid:1195621]) options=[] 2021/06/01 06:32:00 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': >rpc: result=Success (ok), err= 2021/06/01 06:32:00 DEBUG : dir: Updating dir with dir2 0xc0001a0b40 2021/06/01 06:32:00 DEBUG : dir: forgetting directory cache 2021/06/01 06:32:00 DEBUG : : Added virtual directory entry vDel: "dir" 2021/06/01 06:32:00 DEBUG : : Added virtual directory entry vAddDir: "dir2" 2021/06/01 06:32:00 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': rpc: getFolderContents(map[count:1000 fi_pid:120933842 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:32:03 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': >rpc: result=Success (ok), err= 2021/06/01 06:32:03 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': rpc: getFolderContents(map[count:1000 fi_pid:120933844 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:32:05 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': >rpc: result=Success (ok), err= 2021/06/01 06:32:05 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': rpc: getFolderContents(map[count:1000 fi_pid:120933842 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:32:06 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': >rpc: result=Success (ok), err= 2021/06/01 06:32:06 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': rpc: getFolderContents(map[count:1000 fi_pid:120933844 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:32:06 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': >rpc: result=Success (ok), err= 2021/06/01 06:32:06 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': rpc: checkPathExists(map[path:file2 pid:120933842]) options=[] 2021/06/01 06:32:06 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': >rpc: result=Success (ok), err= 2021/06/01 06:32:06 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': rpc: doRenameFile(map[fi_id:120933845 fi_name:file2.vupowih9]) options=[] 2021/06/01 06:32:16 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': >rpc: result=Success (ok), err= 2021/06/01 06:32:16 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': rpc: doMoveFiles(map[dir_id:120933842 fi_ids:120933845]) options=[] 2021/06/01 06:32:51 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': >rpc: result=Succcess. (ok), err= 2021/06/01 06:32:51 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': rpc: doRenameFile(map[fi_id:120933845 fi_name:file2]) options=[] 2021/06/01 06:33:05 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': >rpc: result=Success (ok), err= 2021/06/01 06:33:05 INFO : dir2/file1: Moved (server-side) to: file2 2021/06/01 06:33:05 DEBUG : file2: Updating file with file2 0xc0001a0c00 2021/06/01 06:33:05 DEBUG : dir2: Added virtual directory entry vDel: "file1" 2021/06/01 06:33:05 DEBUG : : Added virtual directory entry vAddFile: "file2" 2021/06/01 06:33:05 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': rpc: getFolderContents(map[count:1000 fi_pid:120933842 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:33:07 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': >rpc: result=Success (ok), err= 2021/06/01 06:33:07 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': rpc: getFolderContents(map[count:1000 fi_pid:120933844 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:33:08 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': >rpc: result=Success (ok), err= 2021/06/01 06:33:08 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': rpc: checkPathExists(map[path:dir2/file3 pid:120933842]) options=[] 2021/06/01 06:33:08 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': >rpc: result=Success (ok), err= 2021/06/01 06:33:08 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': rpc: doDeleteFile(map[completedeletion:n fi_id:120933846]) options=[] 2021/06/01 06:33:20 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': >rpc: result=Success (ok), err= 2021/06/01 06:33:20 INFO : dir2/file3: Deleted 2021/06/01 06:33:20 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': rpc: doRenameFile(map[fi_id:120933845 fi_name:file3.doqisux6]) options=[] 2021/06/01 06:33:31 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': >rpc: result=Success (ok), err= 2021/06/01 06:33:31 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': rpc: doMoveFiles(map[dir_id:120933844 fi_ids:120933845]) options=[] 2021/06/01 06:34:02 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': >rpc: result=Succcess. (ok), err= 2021/06/01 06:34:02 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': rpc: doRenameFile(map[fi_id:120933845 fi_name:file3]) options=[] 2021/06/01 06:34:14 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': >rpc: result=Success (ok), err= 2021/06/01 06:34:14 INFO : file2: Moved (server-side) to: dir2/file3 2021/06/01 06:34:14 DEBUG : dir2/file3: Updating file with dir2/file3 0xc0001a0c00 2021/06/01 06:34:14 DEBUG : : Added virtual directory entry vDel: "file2" 2021/06/01 06:34:14 DEBUG : dir2: Added virtual directory entry vAddFile: "file3" 2021/06/01 06:34:14 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': rpc: getFolderContents(map[count:1000 fi_pid:120933842 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:34:16 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': >rpc: result=Success (ok), err= 2021/06/01 06:34:16 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': rpc: getFolderContents(map[count:1000 fi_pid:120933844 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:34:17 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': >rpc: result=Success (ok), err= 2021/06/01 06:34:17 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': rpc: getFolderContents(map[count:1000 fi_pid:120933842 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:34:17 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': >rpc: result=Success (ok), err= 2021/06/01 06:34:17 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': rpc: doCreateNewFolder(map[fi_name:empty directory fi_pid:120933842]) options=[] 2021/06/01 06:34:21 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': >rpc: result=Success (ok), err= 2021/06/01 06:34:21 DEBUG : : Added virtual directory entry vAddDir: "empty directory" 2021/06/01 06:34:21 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': rpc: getFolderContents(map[count:1000 fi_pid:120933842 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:34:22 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': >rpc: result=Success (ok), err= 2021/06/01 06:34:22 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': rpc: doRenameFolder(map[fi_id:120933876 fi_name:renamed empty directory]) options=[] 2021/06/01 06:34:33 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': >rpc: result=Success (ok), err=json: cannot unmarshal number into Go struct field FileResponse.taskid of type string 2021/06/01 06:34:33 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:34:33 DEBUG : WaitForWriters: timeout=10s 2021/06/01 06:34:33 DEBUG : dir2: Looking for writers 2021/06/01 06:34:33 DEBUG : file3: reading active writers 2021/06/01 06:34:33 DEBUG : empty directory: Looking for writers 2021/06/01 06:34:33 DEBUG : : Looking for writers 2021/06/01 06:34:33 DEBUG : dir2: reading active writers 2021/06/01 06:34:33 DEBUG : empty directory: reading active writers 2021/06/01 06:34:33 DEBUG : >WaitForWriters: 2021/06/01 06:34:33 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': rpc: getFolderContents(map[count:1000 fi_pid:120933842 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:34:34 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': >rpc: result=Success (ok), err= 2021/06/01 06:34:34 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': rpc: getFolderContents(map[count:1000 fi_pid:120933876 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:34:34 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': rpc: getFolderContents(map[count:1000 fi_pid:120933844 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:34:34 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': >rpc: result=Success (ok), err= 2021/06/01 06:34:34 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': rpc: doDeleteFile(map[completedeletion:n fi_id:120933845]) options=[] 2021/06/01 06:34:36 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': >rpc: result=Success (ok), err= 2021/06/01 06:34:52 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': >rpc: result=Success (ok), err= 2021/06/01 06:34:52 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': rpc: getFolderContents(map[count:1000 fi_pid:120933876 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:34:53 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': >rpc: result=Success (ok), err= 2021/06/01 06:34:53 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': rpc: doDeleteFolder(map[fi_id:120933876]) options=[] 2021/06/01 06:34:56 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': >rpc: result=Success (ok), err= 2021/06/01 06:34:56 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': rpc: getFolderContents(map[count:1000 fi_pid:120933844 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:34:57 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': >rpc: result=Success (ok), err= 2021/06/01 06:34:57 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': rpc: doDeleteFolder(map[fi_id:120933844]) options=[] 2021/06/01 06:35:00 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': >rpc: result=Success (ok), err= 2021/06/01 06:35:00 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': rpc: getFolderContents(map[count:1000 fi_pid:120933842 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:01 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': >rpc: result=Success (ok), err= --- FAIL: TestDirRename (256.03s) FAIL 2021/06/01 06:35:01 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': Purge remote 2021/06/01 06:35:01 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': rpc: doDeleteFolder(map[fi_id:120933842]) options=[] 2021/06/01 06:35:01 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': Sleeping for 6s to wait for "error_background" error to clear 2021/06/01 06:35:07 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:35:07 DEBUG : pacer: Rate limited, increasing sleep to 40ms 2021/06/01 06:35:08 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': Sleeping for 6s to wait for "error_background" error to clear 2021/06/01 06:35:14 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:35:14 DEBUG : pacer: Rate limited, increasing sleep to 80ms 2021/06/01 06:35:14 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': Sleeping for 6s to wait for "error_background" error to clear 2021/06/01 06:35:20 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:35:20 DEBUG : pacer: Rate limited, increasing sleep to 160ms 2021/06/01 06:35:20 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': Sleeping for 6s to wait for "error_background" error to clear 2021/06/01 06:35:26 DEBUG : pacer: low level retry 4/10 (error The requested operation cannot be completed. A delete operation is already being processed in this folder. Please try again later. (error_background)) 2021/06/01 06:35:26 DEBUG : pacer: Rate limited, increasing sleep to 320ms 2021/06/01 06:35:27 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': Sleeping for 6s to wait for "error_background" error to clear 2021/06/01 06:35:33 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:35:33 DEBUG : pacer: Rate limited, increasing sleep to 640ms 2021/06/01 06:35:36 DEBUG : pacer: Reducing sleep to 480ms 2021/06/01 06:35:36 DEBUG : filefabric root 'rclone-test-dumonag9vikakeg8nudeqew5': >rpc: result=Success (ok), err= "./vfs.test -test.v -test.timeout 1h0m0s -remote TestFileFabric: -verbose -test.run '^TestDirRename$'" - Finished ERROR in 4m51.850815143s (try 4/5): exit status 1: Failed [TestDirRename]