"./vfs.test -test.v -test.timeout 1h0m0s -remote TestFileFabric: -verbose -test.run '^TestDirRename$'" - Starting (try 3/5) 2021/06/01 06:24:59 DEBUG : Creating backend with remote "TestFileFabric:rclone-test-yanunuh2wozavag9titakow3" 2021/06/01 06:24:59 DEBUG : Using config file from "/home/rclone/.rclone.conf" 2021/06/01 06:24:59 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': rpc: checkPathExists(map[path:rclone-test-yanunuh2wozavag9titakow3 pid:120673762]) options=[] 2021/06/01 06:24:59 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': >rpc: result=Success (ok), err= 2021/06/01 06:24:59 DEBUG : Creating backend with remote "/tmp/rclone921612418" === RUN TestDirRename run.go:176: Remote "filefabric root 'rclone-test-yanunuh2wozavag9titakow3'", Local "Local file system at /tmp/rclone921612418", Modify Window "1s" 2021/06/01 06:24:59 INFO : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': poll-interval is not supported by this remote 2021/06/01 06:24:59 NOTICE: filefabric root 'rclone-test-yanunuh2wozavag9titakow3': --vfs-cache-mode writes or full is recommended for this remote as it can't stream 2021/06/01 06:24:59 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': 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:25:00 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': >rpc: result=Success (ok), err= 2021/06/01 06:25:00 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': rpc: doCreateNewFolder(map[fi_name:rclone-test-yanunuh2wozavag9titakow3 fi_pid:120673762]) options=[] 2021/06/01 06:25:05 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': >rpc: result=Success (ok), err= 2021/06/01 06:25:05 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': rpc: getFolderContents(map[count:1000 fi_pid:120933774 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:25:07 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': >rpc: result=Success (ok), err= 2021/06/01 06:25:07 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': rpc: doCreateNewFolder(map[fi_name:dir fi_pid:120933774]) options=[] 2021/06/01 06:25:12 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': >rpc: result=Success (ok), err= 2021/06/01 06:25:12 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': 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:120933776 fi_size:14 responsetype:json]) options=[] 2021/06/01 06:25:13 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': >rpc: result=Success (ok), err= 2021/06/01 06:25:14 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': rpc: doCompleteUpload(map[fi_size:14 remotetime:2001-02-03 04:05:06 uploadcode:344f151e1e9e3ed9c05119e772dce1b4]) options=[] 2021/06/01 06:25:16 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': >rpc: result=Success (ok), err= 2021/06/01 06:25:16 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': rpc: getFolderContents(map[count:1000 fi_pid:120933774 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:25:18 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': >rpc: result=Success (ok), err= 2021/06/01 06:25:18 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': rpc: getFolderContents(map[count:1000 fi_pid:120933776 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:25:20 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': >rpc: result=Success (ok), err= 2021/06/01 06:25:20 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': rpc: getFolderContents(map[count:1000 fi_pid:120933774 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:25:20 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': >rpc: result=Success (ok), err= 2021/06/01 06:25:20 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': 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:120933776 fi_size:15 responsetype:json]) options=[] 2021/06/01 06:25:22 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': >rpc: result=Success (ok), err= 2021/06/01 06:25:23 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': rpc: doCompleteUpload(map[fi_size:15 remotetime:2001-02-03 04:05:06 uploadcode:1326a24972e5cc143aab6521407129b9]) options=[] 2021/06/01 06:25:26 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': >rpc: result=Success (ok), err= 2021/06/01 06:25:26 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': rpc: getFolderContents(map[count:1000 fi_pid:120933774 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:25:26 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': >rpc: result=Success (ok), err= 2021/06/01 06:25:26 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': rpc: getFolderContents(map[count:1000 fi_pid:120933776 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:25:27 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': >rpc: result=Success (ok), err= 2021/06/01 06:25:27 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': rpc: getFolderContents(map[count:1000 fi_pid:120933776 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:25:27 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': >rpc: result=Success (ok), err= 2021/06/01 06:25:27 ERROR : dir/not found: Dir.Rename error: file does not exist 2021/06/01 06:25:27 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': rpc: getFolderContents(map[count:1000 fi_pid:120933774 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:25:28 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': >rpc: result=Success (ok), err= 2021/06/01 06:25:28 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': rpc: doRenameFolder(map[fi_id:120933776 fi_name:dir2]) options=[] 2021/06/01 06:25:45 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': >rpc: result=Success (ok), err= 2021/06/01 06:25:45 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': rpc: getUserBackgroundTasks(map[taskid:1195581]) options=[] 2021/06/01 06:25:46 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': >rpc: result=Success (ok), err= 2021/06/01 06:25:46 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': Waiting for task ID 1195581: Rename folder S3 Storage/smestoragencw/rclone-test-yanunuh2wozavag9titakow3/dir2: to completed for 1s - waited 972.180426ms already 2021/06/01 06:25:47 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': rpc: getUserBackgroundTasks(map[taskid:1195581]) options=[] 2021/06/01 06:25:48 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': >rpc: result=Success (ok), err= 2021/06/01 06:25:48 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': Waiting for task ID 1195581: Rename folder S3 Storage/smestoragencw/rclone-test-yanunuh2wozavag9titakow3/dir2: to completed for 1s - waited 2.910073821s already 2021/06/01 06:25:49 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': rpc: getUserBackgroundTasks(map[taskid:1195581]) options=[] 2021/06/01 06:25:51 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': >rpc: result=Success (ok), err= 2021/06/01 06:25:51 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': Waiting for task ID 1195581: Rename folder S3 Storage/smestoragencw/rclone-test-yanunuh2wozavag9titakow3/dir2: to completed for 1s - waited 6.296256531s already 2021/06/01 06:25:52 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': rpc: getUserBackgroundTasks(map[taskid:1195581]) options=[] 2021/06/01 06:25:53 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': >rpc: result=Success (ok), err= 2021/06/01 06:25:53 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': Waiting for task ID 1195581: Rename folder S3 Storage/smestoragencw/rclone-test-yanunuh2wozavag9titakow3/dir2: to completed for 1s - waited 8.259431837s already 2021/06/01 06:25:54 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': rpc: getUserBackgroundTasks(map[taskid:1195581]) options=[] 2021/06/01 06:25:57 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': >rpc: result=Success (ok), err= 2021/06/01 06:25:57 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': Waiting for task ID 1195581: Rename folder S3 Storage/smestoragencw/rclone-test-yanunuh2wozavag9titakow3/dir2: to completed for 1s - waited 11.962463663s already 2021/06/01 06:25:58 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': rpc: getUserBackgroundTasks(map[taskid:1195581]) options=[] 2021/06/01 06:26:00 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': >rpc: result=Success (ok), err= 2021/06/01 06:26:00 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': Waiting for task ID 1195581: Rename folder S3 Storage/smestoragencw/rclone-test-yanunuh2wozavag9titakow3/dir2: to completed for 1s - waited 14.556694031s already 2021/06/01 06:26:01 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': rpc: getUserBackgroundTasks(map[taskid:1195581]) options=[] 2021/06/01 06:26:02 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': >rpc: result=Success (ok), err= 2021/06/01 06:26:02 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': Waiting for task ID 1195581: Rename folder S3 Storage/smestoragencw/rclone-test-yanunuh2wozavag9titakow3/dir2: to completed for 1s - waited 16.563999538s already 2021/06/01 06:26:03 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': rpc: getUserBackgroundTasks(map[taskid:1195581]) options=[] 2021/06/01 06:26:04 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': >rpc: result=Success (ok), err= 2021/06/01 06:26:04 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': Waiting for task ID 1195581: Rename folder S3 Storage/smestoragencw/rclone-test-yanunuh2wozavag9titakow3/dir2: to completed for 1s - waited 18.560759866s already 2021/06/01 06:26:05 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': rpc: getUserBackgroundTasks(map[taskid:1195581]) options=[] 2021/06/01 06:26:06 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': >rpc: result=Success (ok), err= 2021/06/01 06:26:06 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': Waiting for task ID 1195581: Rename folder S3 Storage/smestoragencw/rclone-test-yanunuh2wozavag9titakow3/dir2: to completed for 1s - waited 20.548571334s already 2021/06/01 06:26:07 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': rpc: getUserBackgroundTasks(map[taskid:1195581]) options=[] 2021/06/01 06:26:08 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': >rpc: result=Success (ok), err= 2021/06/01 06:26:08 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': Waiting for task ID 1195581: Rename folder S3 Storage/smestoragencw/rclone-test-yanunuh2wozavag9titakow3/dir2: to completed for 1s - waited 22.500291814s already 2021/06/01 06:26:09 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': rpc: getUserBackgroundTasks(map[taskid:1195581]) options=[] 2021/06/01 06:26:10 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': >rpc: result=Success (ok), err= 2021/06/01 06:26:10 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': Waiting for task ID 1195581: Rename folder S3 Storage/smestoragencw/rclone-test-yanunuh2wozavag9titakow3/dir2: to completed for 1s - waited 24.457219107s already 2021/06/01 06:26:11 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': rpc: getUserBackgroundTasks(map[taskid:1195581]) options=[] 2021/06/01 06:26:12 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': >rpc: result=Success (ok), err= 2021/06/01 06:26:12 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': Waiting for task ID 1195581: Rename folder S3 Storage/smestoragencw/rclone-test-yanunuh2wozavag9titakow3/dir2: to completed for 1s - waited 26.598799578s already 2021/06/01 06:26:13 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': rpc: getUserBackgroundTasks(map[taskid:1195581]) options=[] 2021/06/01 06:26:14 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': >rpc: result=Success (ok), err= 2021/06/01 06:26:14 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': Waiting for task ID 1195581: Rename folder S3 Storage/smestoragencw/rclone-test-yanunuh2wozavag9titakow3/dir2: to completed for 1s - waited 28.549523382s already 2021/06/01 06:26:15 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': rpc: getUserBackgroundTasks(map[taskid:1195581]) options=[] 2021/06/01 06:26:16 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': >rpc: result=Success (ok), err= 2021/06/01 06:26:16 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': Waiting for task ID 1195581: Rename folder S3 Storage/smestoragencw/rclone-test-yanunuh2wozavag9titakow3/dir2: to completed for 1s - waited 30.497572808s already 2021/06/01 06:26:17 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': rpc: getUserBackgroundTasks(map[taskid:1195581]) options=[] 2021/06/01 06:26:18 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': >rpc: result=Success (ok), err= 2021/06/01 06:26:18 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': Waiting for task ID 1195581: Rename folder S3 Storage/smestoragencw/rclone-test-yanunuh2wozavag9titakow3/dir2: to completed for 1s - waited 32.434965309s already 2021/06/01 06:26:19 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': rpc: getUserBackgroundTasks(map[taskid:1195581]) options=[] 2021/06/01 06:26:21 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': >rpc: result=Success (ok), err= 2021/06/01 06:26:21 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': Waiting for task ID 1195581: Rename folder S3 Storage/smestoragencw/rclone-test-yanunuh2wozavag9titakow3/dir2: to completed for 1s - waited 35.717673113s already 2021/06/01 06:26:22 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': rpc: getUserBackgroundTasks(map[taskid:1195581]) options=[] 2021/06/01 06:26:24 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': >rpc: result=Success (ok), err= 2021/06/01 06:26:24 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': Waiting for task ID 1195581: Rename folder S3 Storage/smestoragencw/rclone-test-yanunuh2wozavag9titakow3/dir2: to completed for 1s - waited 38.469538239s already 2021/06/01 06:26:25 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': rpc: getUserBackgroundTasks(map[taskid:1195581]) options=[] 2021/06/01 06:26:26 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': >rpc: result=Success (ok), err= 2021/06/01 06:26:26 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': Waiting for task ID 1195581: Rename folder S3 Storage/smestoragencw/rclone-test-yanunuh2wozavag9titakow3/dir2: to completed for 1s - waited 40.82765823s already 2021/06/01 06:26:27 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': rpc: getUserBackgroundTasks(map[taskid:1195581]) options=[] 2021/06/01 06:26:28 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': >rpc: result=Success (ok), err= 2021/06/01 06:26:28 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': Waiting for task ID 1195581: Rename folder S3 Storage/smestoragencw/rclone-test-yanunuh2wozavag9titakow3/dir2: to completed for 1s - waited 42.99327727s already 2021/06/01 06:26:29 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': rpc: getUserBackgroundTasks(map[taskid:1195581]) options=[] 2021/06/01 06:26:30 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': >rpc: result=Success (ok), err= 2021/06/01 06:26:30 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': Waiting for task ID 1195581: Rename folder S3 Storage/smestoragencw/rclone-test-yanunuh2wozavag9titakow3/dir2: to completed for 1s - waited 45.028133032s already 2021/06/01 06:26:31 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': rpc: getUserBackgroundTasks(map[taskid:1195581]) options=[] 2021/06/01 06:26:34 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': >rpc: result=Success (ok), err= 2021/06/01 06:26:34 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': Waiting for task ID 1195581: Rename folder S3 Storage/smestoragencw/rclone-test-yanunuh2wozavag9titakow3/dir2: to completed for 1s - waited 48.70832761s already 2021/06/01 06:26:35 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': rpc: getUserBackgroundTasks(map[taskid:1195581]) options=[] 2021/06/01 06:26:36 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': >rpc: result=Success (ok), err= 2021/06/01 06:26:36 DEBUG : dir: Updating dir with dir2 0xc000111a40 2021/06/01 06:26:36 DEBUG : dir: forgetting directory cache 2021/06/01 06:26:36 DEBUG : : Added virtual directory entry vDel: "dir" 2021/06/01 06:26:36 DEBUG : : Added virtual directory entry vAddDir: "dir2" 2021/06/01 06:26:36 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': rpc: getFolderContents(map[count:1000 fi_pid:120933774 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:26:37 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': >rpc: result=Success (ok), err= 2021/06/01 06:26:37 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': rpc: getFolderContents(map[count:1000 fi_pid:120933776 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:26:39 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': >rpc: result=Success (ok), err= 2021/06/01 06:26:39 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': rpc: getFolderContents(map[count:1000 fi_pid:120933774 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:26:39 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': >rpc: result=Success (ok), err= 2021/06/01 06:26:39 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': rpc: getFolderContents(map[count:1000 fi_pid:120933776 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:26:39 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': >rpc: result=Success (ok), err= 2021/06/01 06:26:39 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': rpc: checkPathExists(map[path:file2 pid:120933774]) options=[] 2021/06/01 06:26:40 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': >rpc: result=Success (ok), err= 2021/06/01 06:26:40 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': rpc: doRenameFile(map[fi_id:120933777 fi_name:file2.tonesig2]) options=[] 2021/06/01 06:26:51 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': >rpc: result=Success (ok), err= 2021/06/01 06:26:51 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': rpc: doMoveFiles(map[dir_id:120933774 fi_ids:120933777]) options=[] 2021/06/01 06:27:29 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': >rpc: result=Succcess. (ok), err= 2021/06/01 06:27:29 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': rpc: doRenameFile(map[fi_id:120933777 fi_name:file2]) options=[] 2021/06/01 06:27:41 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': >rpc: result=Success (ok), err= 2021/06/01 06:27:41 INFO : dir2/file1: Moved (server-side) to: file2 2021/06/01 06:27:41 DEBUG : file2: Updating file with file2 0xc000111d40 2021/06/01 06:27:41 DEBUG : dir2: Added virtual directory entry vDel: "file1" 2021/06/01 06:27:41 DEBUG : : Added virtual directory entry vAddFile: "file2" 2021/06/01 06:27:41 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': rpc: getFolderContents(map[count:1000 fi_pid:120933774 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:27:43 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': >rpc: result=Success (ok), err= 2021/06/01 06:27:43 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': rpc: getFolderContents(map[count:1000 fi_pid:120933776 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:27:45 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': >rpc: result=Success (ok), err= 2021/06/01 06:27:45 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': rpc: checkPathExists(map[path:dir2/file3 pid:120933774]) options=[] 2021/06/01 06:27:45 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': >rpc: result=Success (ok), err= 2021/06/01 06:27:45 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': rpc: doDeleteFile(map[completedeletion:n fi_id:120933780]) options=[] 2021/06/01 06:27:56 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': >rpc: result=Success (ok), err= 2021/06/01 06:27:56 INFO : dir2/file3: Deleted 2021/06/01 06:27:56 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': rpc: doRenameFile(map[fi_id:120933777 fi_name:file3.tewakiq0]) options=[] 2021/06/01 06:28:06 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': >rpc: result=Success (ok), err= 2021/06/01 06:28:06 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': rpc: doMoveFiles(map[dir_id:120933776 fi_ids:120933777]) options=[] 2021/06/01 06:28:36 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': >rpc: result=Succcess. (ok), err= 2021/06/01 06:28:36 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': rpc: doRenameFile(map[fi_id:120933777 fi_name:file3]) options=[] 2021/06/01 06:28:45 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': >rpc: result=Success (ok), err= 2021/06/01 06:28:45 INFO : file2: Moved (server-side) to: dir2/file3 2021/06/01 06:28:45 DEBUG : dir2/file3: Updating file with dir2/file3 0xc000111d40 2021/06/01 06:28:45 DEBUG : : Added virtual directory entry vDel: "file2" 2021/06/01 06:28:45 DEBUG : dir2: Added virtual directory entry vAddFile: "file3" 2021/06/01 06:28:45 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': rpc: getFolderContents(map[count:1000 fi_pid:120933774 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:28:48 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': >rpc: result=Success (ok), err= 2021/06/01 06:28:48 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': rpc: getFolderContents(map[count:1000 fi_pid:120933776 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:28:50 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': >rpc: result=Success (ok), err= 2021/06/01 06:28:50 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': rpc: getFolderContents(map[count:1000 fi_pid:120933774 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:28:50 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': >rpc: result=Success (ok), err= 2021/06/01 06:28:50 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': rpc: doCreateNewFolder(map[fi_name:empty directory fi_pid:120933774]) options=[] 2021/06/01 06:28:53 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': >rpc: result=Success (ok), err= 2021/06/01 06:28:53 DEBUG : : Added virtual directory entry vAddDir: "empty directory" 2021/06/01 06:28:53 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': rpc: getFolderContents(map[count:1000 fi_pid:120933774 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:28:55 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': >rpc: result=Success (ok), err= 2021/06/01 06:28:55 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': rpc: doRenameFolder(map[fi_id:120933826 fi_name:renamed empty directory]) options=[] 2021/06/01 06:29:07 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': >rpc: result=Success (ok), err=json: cannot unmarshal number into Go struct field FileResponse.taskid of type string 2021/06/01 06:29:07 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:29:07 DEBUG : WaitForWriters: timeout=10s 2021/06/01 06:29:07 DEBUG : dir2: Looking for writers 2021/06/01 06:29:07 DEBUG : file3: reading active writers 2021/06/01 06:29:07 DEBUG : empty directory: Looking for writers 2021/06/01 06:29:07 DEBUG : : Looking for writers 2021/06/01 06:29:07 DEBUG : dir2: reading active writers 2021/06/01 06:29:07 DEBUG : empty directory: reading active writers 2021/06/01 06:29:07 DEBUG : >WaitForWriters: 2021/06/01 06:29:07 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': rpc: getFolderContents(map[count:1000 fi_pid:120933774 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:29:10 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': >rpc: result=Success (ok), err= 2021/06/01 06:29:10 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': rpc: getFolderContents(map[count:1000 fi_pid:120933826 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:29:10 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': rpc: getFolderContents(map[count:1000 fi_pid:120933776 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:29:10 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': >rpc: result=Success (ok), err= 2021/06/01 06:29:10 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': rpc: doDeleteFile(map[completedeletion:n fi_id:120933777]) options=[] 2021/06/01 06:29:11 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': >rpc: result=Success (ok), err= 2021/06/01 06:29:31 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': >rpc: result=Success (ok), err= 2021/06/01 06:29:31 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': rpc: getFolderContents(map[count:1000 fi_pid:120933826 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:29:31 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': >rpc: result=Success (ok), err= 2021/06/01 06:29:31 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': rpc: doDeleteFolder(map[fi_id:120933826]) options=[] 2021/06/01 06:29:34 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': >rpc: result=Success (ok), err= 2021/06/01 06:29:34 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': rpc: getFolderContents(map[count:1000 fi_pid:120933776 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:29:36 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': >rpc: result=Success (ok), err= 2021/06/01 06:29:36 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': rpc: doDeleteFolder(map[fi_id:120933776]) options=[] 2021/06/01 06:29:40 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': >rpc: result=Success (ok), err= 2021/06/01 06:29:40 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': rpc: getFolderContents(map[count:1000 fi_pid:120933774 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:29:40 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': >rpc: result=Success (ok), err= --- FAIL: TestDirRename (280.84s) FAIL 2021/06/01 06:29:40 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': Purge remote 2021/06/01 06:29:40 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': rpc: doDeleteFolder(map[fi_id:120933774]) options=[] 2021/06/01 06:29:41 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': Sleeping for 6s to wait for "error_background" error to clear 2021/06/01 06:29:47 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:29:47 DEBUG : pacer: Rate limited, increasing sleep to 40ms 2021/06/01 06:29:47 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': Sleeping for 6s to wait for "error_background" error to clear 2021/06/01 06:29:53 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:29:53 DEBUG : pacer: Rate limited, increasing sleep to 80ms 2021/06/01 06:29:54 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': Sleeping for 6s to wait for "error_background" error to clear 2021/06/01 06:30:00 DEBUG : pacer: low level retry 3/10 (error The requested operation cannot be completed. A delete operation is already being processed in this folder. Please try again later. (error_background)) 2021/06/01 06:30:00 DEBUG : pacer: Rate limited, increasing sleep to 160ms 2021/06/01 06:30:00 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': Sleeping for 6s to wait for "error_background" error to clear 2021/06/01 06:30:06 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:30:06 DEBUG : pacer: Rate limited, increasing sleep to 320ms 2021/06/01 06:30:07 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': Sleeping for 6s to wait for "error_background" error to clear 2021/06/01 06:30:13 DEBUG : pacer: low level retry 5/10 (error The requested operation cannot be completed. A delete operation is already being processed in this folder. Please try again later. (error_background)) 2021/06/01 06:30:13 DEBUG : pacer: Rate limited, increasing sleep to 640ms 2021/06/01 06:30:13 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': Sleeping for 6s to wait for "error_background" error to clear 2021/06/01 06:30:19 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:30:19 DEBUG : pacer: Rate limited, increasing sleep to 1.28s 2021/06/01 06:30:20 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': Sleeping for 6s to wait for "error_background" error to clear 2021/06/01 06:30:26 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:30:26 DEBUG : pacer: Rate limited, increasing sleep to 2.56s 2021/06/01 06:30:26 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': Sleeping for 6s to wait for "error_background" error to clear 2021/06/01 06:30:32 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:30:32 DEBUG : pacer: Rate limited, increasing sleep to 5.12s 2021/06/01 06:30:32 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': Sleeping for 6s to wait for "error_background" error to clear 2021/06/01 06:30:38 DEBUG : pacer: low level retry 9/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:30:38 DEBUG : pacer: Rate limited, increasing sleep to 10s 2021/06/01 06:30:38 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': Sleeping for 6s to wait for "error_background" error to clear 2021/06/01 06:30:44 DEBUG : pacer: low level retry 10/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:30:44 DEBUG : filefabric root 'rclone-test-yanunuh2wozavag9titakow3': >rpc: result=The requested operation cannot be completed. A delete operation is already being processed in this folder. Please try again later. (error_background), err=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:30:44 purge failed: failed to remove directory: The requested operation cannot be completed. A delete operation is already being processed in this folder. Please try again later. (error_background) "./vfs.test -test.v -test.timeout 1h0m0s -remote TestFileFabric: -verbose -test.run '^TestDirRename$'" - Finished ERROR in 5m45.482278095s (try 3/5): exit status 1: Failed [TestDirRename]