"go test -v -timeout 1h0m0s -remote TestFileFabric: -verbose -test.run '^TestIntegration$/^FsMkdir$/^(FsPutFiles|FsUploadUnknownSize)$/^(FromRoot|FsDirMove|FsIsFile|FsPutUnknownSize|FsUpdateUnknownSize|ObjectMimeType|ObjectRemove|ObjectUpdate)$/^(List|ListEntries|Put)$/^Remove$'" - Starting (try 2/5) === RUN TestIntegration fstests.go:418: Using remote "TestFileFabric:" 2021/07/25 06:06:29 DEBUG : Creating backend with remote "TestFileFabric:rclone-test-fesecim1nawusoj7qiyarez4" 2021/07/25 06:06:29 DEBUG : Using config file from "/home/rclone/.rclone.conf" 2021/07/25 06:06:29 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': rpc: checkPathExists(map[path:rclone-test-fesecim1nawusoj7qiyarez4 pid:120673762]) options=[] 2021/07/25 06:06:29 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': >rpc: result=Success (ok), err= 2021/07/25 06:06:29 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': rpc: getFolderContents(map[count:1000 fi_pid:120673762 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:06:30 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': >rpc: result=Success (ok), err= 2021/07/25 06:06:30 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': rpc: doCreateNewFolder(map[fi_name:rclone-test-fesecim1nawusoj7qiyarez4 fi_pid:120673762]) options=[] 2021/07/25 06:06:34 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': >rpc: result=Success (ok), err= 2021/07/25 06:06:34 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': rpc: getFolderContents(map[count:1000 fi_pid:121000231 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:06:37 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': >rpc: result=Success (ok), err= === RUN TestIntegration/FsMkdir 2021/07/25 06:06:37 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': rpc: getFolderContents(map[count:1000 fi_pid:121000231 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:06:37 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': >rpc: result=Success (ok), err= === RUN TestIntegration/FsMkdir/FsPutFiles 2021/07/25 06:06:37 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': rpc: doInitUpload(map[directuploadsupport:n fi_contenttype:text/plain; charset=utf-8 fi_filename:file name.txt fi_localtime:2001-02-03 04:05:06 fi_modified:2001-02-03 04:05:06 fi_name:file name.txt fi_pid:121000231 fi_size:100 responsetype:json]) options=[] 2021/07/25 06:06:38 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': >rpc: result=Success (ok), err= 2021/07/25 06:06:39 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': rpc: doCompleteUpload(map[fi_size:100 remotetime:2001-02-03 04:05:06 uploadcode:d2cf5819309f0cbd1eb7df19e21fa0e3]) options=[] 2021/07/25 06:06:43 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': >rpc: result=Success (ok), err= 2021/07/25 06:06:43 DEBUG : file name.txt: Correcting mime type from "text/plain" to "text/plain; charset=utf-8" 2021/07/25 06:06:43 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': rpc: doModifyFile(map[data:fi_contenttype=text/plain; charset=utf-8 fi_id:121000232]) options=[] 2021/07/25 06:06:43 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': >rpc: result=Success (ok), err= 2021/07/25 06:06:43 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': rpc: checkPathExists(map[path:file name.txt pid:121000231]) options=[] 2021/07/25 06:06:44 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': >rpc: result=Success (ok), err= 2021/07/25 06:06:44 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': rpc: getFolderContents(map[count:1000 fi_pid:121000231 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:06:46 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': >rpc: result=Success (ok), err= 2021/07/25 06:06:46 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': rpc: doCreateNewFolder(map[fi_name:hello? sausage fi_pid:121000231]) options=[] 2021/07/25 06:06:51 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': >rpc: result=Success (ok), err= 2021/07/25 06:06:51 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': rpc: getFolderContents(map[count:1000 fi_pid:121000233 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:06:52 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': >rpc: result=Success (ok), err= 2021/07/25 06:06:52 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': rpc: doCreateNewFolder(map[fi_name:êé fi_pid:121000233]) options=[] 2021/07/25 06:06:57 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': >rpc: result=Success (ok), err= 2021/07/25 06:06:57 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': rpc: getFolderContents(map[count:1000 fi_pid:121000234 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:07:00 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': >rpc: result=Success (ok), err= 2021/07/25 06:07:00 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': rpc: doCreateNewFolder(map[fi_name:Hello, 世界 fi_pid:121000234]) options=[] 2021/07/25 06:07:05 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': >rpc: result=Success (ok), err= 2021/07/25 06:07:05 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': rpc: getFolderContents(map[count:1000 fi_pid:121000235 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:07:06 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': >rpc: result=Success (ok), err= 2021/07/25 06:07:06 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': rpc: doCreateNewFolder(map[fi_name: " ' @ < > & ? + ≠ fi_pid:121000235]) options=[] 2021/07/25 06:07:14 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': >rpc: result=Success (ok), err= 2021/07/25 06:07:14 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': rpc: doInitUpload(map[directuploadsupport:n fi_contenttype:text/plain; charset=utf-8 fi_filename:z.txt fi_localtime:2001-02-03 04:05:10 fi_modified:2001-02-03 04:05:10 fi_name:z.txt fi_pid:121000237 fi_size:100 responsetype:json]) options=[] 2021/07/25 06:07:16 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': >rpc: result=Success (ok), err= 2021/07/25 06:07:17 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': rpc: doCompleteUpload(map[fi_size:100 remotetime:2001-02-03 04:05:10 uploadcode:bac39c660229ec8954b116aac4cbaff4]) options=[] 2021/07/25 06:07:21 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': >rpc: result=Success (ok), err= 2021/07/25 06:07:21 DEBUG : hello? sausage/êé/Hello, 世界/ " ' @ < > & ? + ≠/z.txt: Correcting mime type from "text/plain" to "text/plain; charset=utf-8" 2021/07/25 06:07:21 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': rpc: doModifyFile(map[data:fi_contenttype=text/plain; charset=utf-8 fi_id:121000238]) options=[] 2021/07/25 06:07:21 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': >rpc: result=Success (ok), err= 2021/07/25 06:07:21 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': rpc: checkPathExists(map[path:hello? sausage/êé/Hello, 世界/ " ' @ < > & ? + ≠/z.txt pid:121000231]) options=[] 2021/07/25 06:07:21 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': >rpc: result=Success (ok), err= 2021/07/25 06:07:21 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': rpc: doInitUpload(map[directuploadsupport:n fi_contenttype:text/csv fi_filename:file name.txt fi_localtime:2001-02-03 04:05:06 fi_modified:2001-02-03 04:05:06 fi_name:file name.txt fi_pid:121000231 fi_size:100 responsetype:json]) options=[] 2021/07/25 06:07:23 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': >rpc: result=Success (ok), err= 2021/07/25 06:07:25 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': rpc: doCompleteUpload(map[fi_size:100 remotetime:2001-02-03 04:05:06 uploadcode:ad5a01d703a2a6cd3b3d4c4a5a03c35c]) options=[] 2021/07/25 06:07:53 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': >rpc: result=Success (ok), err= 2021/07/25 06:07:53 DEBUG : file name.txt: Correcting mime type from "text/plain" to "text/csv" 2021/07/25 06:07:53 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': rpc: doModifyFile(map[data:fi_contenttype=text/csv fi_id:121000232]) options=[] 2021/07/25 06:07:53 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': >rpc: result=Success (ok), err= 2021/07/25 06:07:53 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': rpc: checkPathExists(map[path:file name.txt pid:121000231]) options=[] 2021/07/25 06:07:53 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': >rpc: result=Success (ok), err= === RUN TestIntegration/FsMkdir/FsPutFiles/FsDirMove 2021/07/25 06:07:53 DEBUG : Creating backend with remote "TestFileFabric:rclone-test-qotehok6zokupac1liduhaj4" 2021/07/25 06:07:53 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': rpc: checkPathExists(map[path:rclone-test-qotehok6zokupac1liduhaj4 pid:120673762]) options=[] 2021/07/25 06:07:54 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': >rpc: result=Success (ok), err= 2021/07/25 06:07:54 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': rpc: getFolderContents(map[count:1000 fi_pid:120673762 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:07:54 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': >rpc: result=Success (ok), err= 2021/07/25 06:07:54 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': rpc: doCreateNewFolder(map[fi_name:rclone-test-qotehok6zokupac1liduhaj4 fi_pid:120673762]) options=[] 2021/07/25 06:07:59 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': >rpc: result=Success (ok), err= 2021/07/25 06:07:59 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': rpc: getFolderContents(map[count:1000 fi_pid:121000242 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:08:01 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': >rpc: result=Success (ok), err= 2021/07/25 06:08:01 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': rpc: doCreateNewFolder(map[fi_name:new_name fi_pid:121000242]) options=[] 2021/07/25 06:08:05 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': >rpc: result=Success (ok), err= 2021/07/25 06:08:05 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': rpc: getFolderContents(map[count:1000 fi_pid:121000243 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:08:07 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': >rpc: result=Success (ok), err= 2021/07/25 06:08:07 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': rpc: doRenameFolder(map[fi_id:121000231 fi_name:sub_new_name.xinegin5]) options=[] 2021/07/25 06:08:23 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': >rpc: result=Success (ok), err= 2021/07/25 06:08:23 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': rpc: getUserBackgroundTasks(map[taskid:1277122]) options=[] 2021/07/25 06:08:25 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': >rpc: result=Success (ok), err= 2021/07/25 06:08:25 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': Waiting for task ID 1277122: Rename folder 'S3 Storage/smestoragencw/sub_new_name.xinegin5': to completed for 1s - waited 1.522134936s already 2021/07/25 06:08:26 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': rpc: getUserBackgroundTasks(map[taskid:1277122]) options=[] 2021/07/25 06:08:28 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': >rpc: result=Success (ok), err= 2021/07/25 06:08:28 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': Waiting for task ID 1277122: Rename folder 'S3 Storage/smestoragencw/sub_new_name.xinegin5': to completed for 1s - waited 4.817456262s already 2021/07/25 06:08:29 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': rpc: getUserBackgroundTasks(map[taskid:1277122]) options=[] 2021/07/25 06:08:30 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': >rpc: result=Success (ok), err= 2021/07/25 06:08:30 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': Waiting for task ID 1277122: Rename folder 'S3 Storage/smestoragencw/sub_new_name.xinegin5': to completed for 1s - waited 7.177221984s already 2021/07/25 06:08:31 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': rpc: getUserBackgroundTasks(map[taskid:1277122]) options=[] 2021/07/25 06:08:33 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': >rpc: result=Success (ok), err= 2021/07/25 06:08:33 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': Waiting for task ID 1277122: Rename folder 'S3 Storage/smestoragencw/sub_new_name.xinegin5': to completed for 1s - waited 9.72900844s already 2021/07/25 06:08:34 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': rpc: getUserBackgroundTasks(map[taskid:1277122]) options=[] 2021/07/25 06:08:35 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': >rpc: result=Success (ok), err= 2021/07/25 06:08:35 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': Waiting for task ID 1277122: Rename folder 'S3 Storage/smestoragencw/sub_new_name.xinegin5': to completed for 1s - waited 12.130112284s already 2021/07/25 06:08:36 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': rpc: getUserBackgroundTasks(map[taskid:1277122]) options=[] 2021/07/25 06:08:38 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': >rpc: result=Success (ok), err= 2021/07/25 06:08:38 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': Waiting for task ID 1277122: Rename folder 'S3 Storage/smestoragencw/sub_new_name.xinegin5': to completed for 1s - waited 14.458957413s already 2021/07/25 06:08:39 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': rpc: getUserBackgroundTasks(map[taskid:1277122]) options=[] 2021/07/25 06:08:41 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': >rpc: result=Success (ok), err= 2021/07/25 06:08:41 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': Waiting for task ID 1277122: Rename folder 'S3 Storage/smestoragencw/sub_new_name.xinegin5': to completed for 1s - waited 18.189125696s already 2021/07/25 06:08:42 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': rpc: getUserBackgroundTasks(map[taskid:1277122]) options=[] 2021/07/25 06:08:45 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': >rpc: result=Success (ok), err= 2021/07/25 06:08:45 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': Waiting for task ID 1277122: Rename folder 'S3 Storage/smestoragencw/sub_new_name.xinegin5': to completed for 1s - waited 21.610307362s already 2021/07/25 06:08:46 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': rpc: getUserBackgroundTasks(map[taskid:1277122]) options=[] 2021/07/25 06:08:47 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': >rpc: result=Success (ok), err= 2021/07/25 06:08:47 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': Waiting for task ID 1277122: Rename folder 'S3 Storage/smestoragencw/sub_new_name.xinegin5': to completed for 1s - waited 24.143985758s already 2021/07/25 06:08:48 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': rpc: getUserBackgroundTasks(map[taskid:1277122]) options=[] 2021/07/25 06:08:51 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': >rpc: result=Success (ok), err= 2021/07/25 06:08:51 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': Waiting for task ID 1277122: Rename folder 'S3 Storage/smestoragencw/sub_new_name.xinegin5': to completed for 1s - waited 28.09557527s already 2021/07/25 06:08:52 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': rpc: getUserBackgroundTasks(map[taskid:1277122]) options=[] 2021/07/25 06:08:54 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': >rpc: result=Success (ok), err= 2021/07/25 06:08:54 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': Waiting for task ID 1277122: Rename folder 'S3 Storage/smestoragencw/sub_new_name.xinegin5': to completed for 1s - waited 30.620238208s already 2021/07/25 06:08:55 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': rpc: getUserBackgroundTasks(map[taskid:1277122]) options=[] 2021/07/25 06:08:56 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': >rpc: result=Success (ok), err= 2021/07/25 06:08:56 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': Waiting for task ID 1277122: Rename folder 'S3 Storage/smestoragencw/sub_new_name.xinegin5': to completed for 1s - waited 33.117129907s already 2021/07/25 06:08:57 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': rpc: getUserBackgroundTasks(map[taskid:1277122]) options=[] 2021/07/25 06:08:59 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': >rpc: result=Success (ok), err= 2021/07/25 06:08:59 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': Waiting for task ID 1277122: Rename folder 'S3 Storage/smestoragencw/sub_new_name.xinegin5': to completed for 1s - waited 35.844645797s already 2021/07/25 06:09:00 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': rpc: getUserBackgroundTasks(map[taskid:1277122]) options=[] 2021/07/25 06:09:03 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': >rpc: result=Success (ok), err= 2021/07/25 06:09:03 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': Waiting for task ID 1277122: Rename folder 'S3 Storage/smestoragencw/sub_new_name.xinegin5': to completed for 1s - waited 39.390512015s already 2021/07/25 06:09:04 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': rpc: getUserBackgroundTasks(map[taskid:1277122]) options=[] 2021/07/25 06:09:05 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': >rpc: result=Success (ok), err= 2021/07/25 06:09:05 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': Waiting for task ID 1277122: Rename folder 'S3 Storage/smestoragencw/sub_new_name.xinegin5': to completed for 1s - waited 41.771307202s already 2021/07/25 06:09:06 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': rpc: getUserBackgroundTasks(map[taskid:1277122]) options=[] 2021/07/25 06:09:08 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': >rpc: result=Success (ok), err= 2021/07/25 06:09:08 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': Waiting for task ID 1277122: Rename folder 'S3 Storage/smestoragencw/sub_new_name.xinegin5': to completed for 1s - waited 44.29623587s already 2021/07/25 06:09:09 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': rpc: getUserBackgroundTasks(map[taskid:1277122]) options=[] 2021/07/25 06:09:10 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': >rpc: result=Success (ok), err= 2021/07/25 06:09:10 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': Waiting for task ID 1277122: Rename folder 'S3 Storage/smestoragencw/sub_new_name.xinegin5': to completed for 1s - waited 46.757055682s already 2021/07/25 06:09:11 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': rpc: getUserBackgroundTasks(map[taskid:1277122]) options=[] 2021/07/25 06:09:12 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': >rpc: result=Success (ok), err= 2021/07/25 06:09:12 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': Waiting for task ID 1277122: Rename folder 'S3 Storage/smestoragencw/sub_new_name.xinegin5': to completed for 1s - waited 49.077155226s already 2021/07/25 06:09:13 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': rpc: getUserBackgroundTasks(map[taskid:1277122]) options=[] 2021/07/25 06:09:16 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': >rpc: result=Success (ok), err= 2021/07/25 06:09:16 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': Waiting for task ID 1277122: Rename folder 'S3 Storage/smestoragencw/sub_new_name.xinegin5': to completed for 1s - waited 52.776899083s already 2021/07/25 06:09:17 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': rpc: getUserBackgroundTasks(map[taskid:1277122]) options=[] 2021/07/25 06:09:19 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': >rpc: result=Success (ok), err= 2021/07/25 06:09:19 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': Waiting for task ID 1277122: Rename folder 'S3 Storage/smestoragencw/sub_new_name.xinegin5': to completed for 1s - waited 55.419321825s already 2021/07/25 06:09:20 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': rpc: getUserBackgroundTasks(map[taskid:1277122]) options=[] 2021/07/25 06:09:21 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': >rpc: result=Success (ok), err= 2021/07/25 06:09:21 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': rpc: doMoveFolders(map[dir_id:121000243 fi_ids:121000231]) options=[] 2021/07/25 06:09:31 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': >rpc: result=Succcess. (ok), err= 2021/07/25 06:09:31 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': rpc: doRenameFolder(map[fi_id:121000231 fi_name:sub_new_name]) options=[] 2021/07/25 06:09:35 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': Sleeping for 6s to wait for "error_background" error to clear 2021/07/25 06:09:41 DEBUG : pacer: low level retry 1/10 (error Can not rename folder now. We are not able to complete the requested operation. We are processing move folder in parent folder. Please try again later. (error_background)) 2021/07/25 06:09:41 DEBUG : pacer: Rate limited, increasing sleep to 40ms 2021/07/25 06:09:47 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': Sleeping for 6s to wait for "error_background" error to clear 2021/07/25 06:09:53 DEBUG : pacer: low level retry 2/10 (error Can not rename folder now. We are not able to complete the requested operation. We are processing move folder in parent folder. Please try again later. (error_background)) 2021/07/25 06:09:53 DEBUG : pacer: Rate limited, increasing sleep to 80ms 2021/07/25 06:09:57 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': Sleeping for 6s to wait for "error_background" error to clear 2021/07/25 06:10:03 DEBUG : pacer: low level retry 3/10 (error Can not rename folder now. We are not able to complete the requested operation. We are processing move folder in parent folder. Please try again later. (error_background)) 2021/07/25 06:10:03 DEBUG : pacer: Rate limited, increasing sleep to 160ms 2021/07/25 06:10:07 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': Sleeping for 6s to wait for "error_background" error to clear 2021/07/25 06:10:13 DEBUG : pacer: low level retry 4/10 (error Can not rename folder now. We are not able to complete the requested operation. We are processing move folder in parent folder. Please try again later. (error_background)) 2021/07/25 06:10:13 DEBUG : pacer: Rate limited, increasing sleep to 320ms 2021/07/25 06:10:17 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': Sleeping for 6s to wait for "error_background" error to clear 2021/07/25 06:10:23 DEBUG : pacer: low level retry 5/10 (error Can not rename folder now. We are not able to complete the requested operation. We are processing move folder in parent folder. Please try again later. (error_background)) 2021/07/25 06:10:23 DEBUG : pacer: Rate limited, increasing sleep to 640ms 2021/07/25 06:10:27 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': Sleeping for 6s to wait for "error_background" error to clear 2021/07/25 06:10:33 DEBUG : pacer: low level retry 6/10 (error Can not rename folder now. We are not able to complete the requested operation. We are processing move folder in parent folder. Please try again later. (error_background)) 2021/07/25 06:10:33 DEBUG : pacer: Rate limited, increasing sleep to 1.28s 2021/07/25 06:10:37 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': Sleeping for 6s to wait for "error_background" error to clear 2021/07/25 06:10:43 DEBUG : pacer: low level retry 7/10 (error Can not rename folder now. We are not able to complete the requested operation. We are processing move folder in parent folder. Please try again later. (error_background)) 2021/07/25 06:10:43 DEBUG : pacer: Rate limited, increasing sleep to 2.56s 2021/07/25 06:10:48 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': Sleeping for 6s to wait for "error_background" error to clear 2021/07/25 06:10:54 DEBUG : pacer: low level retry 8/10 (error Can not rename folder now. We are not able to complete the requested operation. We are processing move folder in parent folder. Please try again later. (error_background)) 2021/07/25 06:10:54 DEBUG : pacer: Rate limited, increasing sleep to 5.12s 2021/07/25 06:10:58 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': Sleeping for 6s to wait for "error_background" error to clear 2021/07/25 06:11:04 DEBUG : pacer: low level retry 9/10 (error Can not rename folder now. We are not able to complete the requested operation. We are processing move folder in parent folder. Please try again later. (error_background)) 2021/07/25 06:11:04 DEBUG : pacer: Rate limited, increasing sleep to 10s 2021/07/25 06:11:08 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': Sleeping for 6s to wait for "error_background" error to clear 2021/07/25 06:11:14 DEBUG : pacer: low level retry 10/10 (error Can not rename folder now. We are not able to complete the requested operation. We are processing move folder in parent folder. Please try again later. (error_background)) 2021/07/25 06:11:14 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': >rpc: result=Can not rename folder now. We are not able to complete the requested operation. We are processing move folder in parent folder. Please try again later. (error_background), err=Can not rename folder now. We are not able to complete the requested operation. We are processing move folder in parent folder. Please try again later. (error_background) fstests.go:1220: Error Trace: fstests.go:1220 Error: Received unexpected error: Can not rename folder now. We are not able to complete the requested operation. We are processing move folder in parent folder. Please try again later. (error_background) 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/fstest/fstests.Run.func13.13.19 /home/rclone/go/src/github.com/rclone/rclone/fstest/fstests/fstests.go:1219 testing.tRunner /usr/local/go/src/testing/testing.go:1123 runtime.goexit /usr/local/go/src/runtime/asm_amd64.s:1374 Test: TestIntegration/FsMkdir/FsPutFiles/FsDirMove 2021/07/25 06:11:14 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': Purge remote 2021/07/25 06:11:14 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': rpc: doDeleteFolder(map[fi_id:121000242]) options=[] 2021/07/25 06:11:15 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': Sleeping for 6s to wait for "error_background" error to clear 2021/07/25 06:11:21 DEBUG : pacer: low level retry 1/10 (error We are not able to complete the requested operation. We are processing move folder in parent folder. Please try again later. (error_background)) 2021/07/25 06:11:27 DEBUG : pacer: Reducing sleep to 7.5s 2021/07/25 06:11:27 DEBUG : filefabric root 'rclone-test-qotehok6zokupac1liduhaj4': >rpc: result=Success (ok), err= === RUN TestIntegration/FsMkdir/FsPutFiles/ObjectMimeType 2021/07/25 06:11:27 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': rpc: checkPathExists(map[path:file name.txt pid:121000231]) options=[] 2021/07/25 06:11:27 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': >rpc: result=Success (ok), err= fstests.go:1342: Error Trace: fstests.go:1342 Error: Not equal: expected: "text/csv" actual : "text/plain" Diff: --- Expected +++ Actual @@ -1 +1 @@ -text/csv +text/plain Test: TestIntegration/FsMkdir/FsPutFiles/ObjectMimeType Messages: can read and write mime types but failed === RUN TestIntegration/FsMkdir/FsPutFiles/ObjectUpdate 2021/07/25 06:11:27 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': rpc: checkPathExists(map[path:file name.txt pid:121000231]) options=[] 2021/07/25 06:11:28 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': >rpc: result=Success (ok), err= 2021/07/25 06:11:28 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': rpc: doInitUpload(map[directuploadsupport:n fi_contenttype:text/plain; charset=utf-8 fi_filename:file name.txt fi_localtime:2001-02-03 04:05:06 fi_modified:2001-02-03 04:05:06 fi_name:file name.txt fi_pid:121000231 fi_size:200 responsetype:json]) options=[] 2021/07/25 06:11:28 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': >rpc: result=Can not upload file now. We are not able to complete the requested operation. We are processing delete in parent folder. Please try again later. (error_locked), err=Can not upload file now. We are not able to complete the requested operation. We are processing delete in parent folder. Please try again later. (error_locked) fstests.go:1432: Error Trace: fstests.go:1432 Error: Received unexpected error: Can not upload file now. We are not able to complete the requested operation. We are processing delete in parent folder. Please try again later. (error_locked) failed to initialize upload github.com/rclone/rclone/backend/filefabric.(*Object).Update /home/rclone/go/src/github.com/rclone/rclone/backend/filefabric/filefabric.go:1245 github.com/rclone/rclone/fstest/fstests.Run.func13.13.34 /home/rclone/go/src/github.com/rclone/rclone/fstest/fstests/fstests.go:1431 testing.tRunner /usr/local/go/src/testing/testing.go:1123 runtime.goexit /usr/local/go/src/runtime/asm_amd64.s:1374 Test: TestIntegration/FsMkdir/FsPutFiles/ObjectUpdate === RUN TestIntegration/FsMkdir/FsPutFiles/FsIsFile 2021/07/25 06:11:28 DEBUG : Creating backend with remote "TestFileFabric:rclone-test-fesecim1nawusoj7qiyarez4/hello? sausage/êé/Hello, 世界/ \" ' @ < > & ? + ≠/z.txt" 2021/07/25 06:11:28 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4/hello? sausage/êé/Hello, 世界/ " ' @ < > & ? + ≠/z.txt': rpc: checkPathExists(map[path:rclone-test-fesecim1nawusoj7qiyarez4/hello? sausage/êé/Hello, 世界/ " ' @ < > & ? + ≠/z.txt pid:120673762]) options=[] 2021/07/25 06:11:28 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4/hello? sausage/êé/Hello, 世界/ " ' @ < > & ? + ≠/z.txt': >rpc: result=Success (ok), err= fstests.go:1463: Error Trace: fstests.go:1463 Error: Not equal: expected: *errors.fundamental(is a file not a directory) actual : () Test: TestIntegration/FsMkdir/FsPutFiles/FsIsFile 2021/07/25 06:11:28 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4/hello? sausage/êé/Hello, 世界/ " ' @ < > & ? + ≠/z.txt': rpc: getFolderContents(map[count:1000 fi_pid:120673762 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:11:29 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4/hello? sausage/êé/Hello, 世界/ " ' @ < > & ? + ≠/z.txt': >rpc: result=Success (ok), err= 2021/07/25 06:11:29 ERROR : : error listing: directory not found fstest.go:299: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:302: Flushing the directory cache 2021/07/25 06:11:30 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4/hello? sausage/êé/Hello, 世界/ " ' @ < > & ? + ≠/z.txt': rpc: getFolderContents(map[count:1000 fi_pid:120673762 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:11:30 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4/hello? sausage/êé/Hello, 世界/ " ' @ < > & ? + ≠/z.txt': >rpc: result=Success (ok), err= 2021/07/25 06:11:30 ERROR : : error listing: directory not found fstest.go:299: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:302: Flushing the directory cache 2021/07/25 06:11:32 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4/hello? sausage/êé/Hello, 世界/ " ' @ < > & ? + ≠/z.txt': rpc: getFolderContents(map[count:1000 fi_pid:120673762 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:11:32 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4/hello? sausage/êé/Hello, 世界/ " ' @ < > & ? + ≠/z.txt': >rpc: result=Success (ok), err= 2021/07/25 06:11:32 ERROR : : error listing: directory not found fstest.go:299: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:302: Flushing the directory cache fstest.go:306: Error Trace: fstest.go:306 fstest.go:339 fstest.go:345 fstests.go:1470 Error: Should be true Test: TestIntegration/FsMkdir/FsPutFiles/FsIsFile Messages: listing wrong, want z.txt (100) got fstest.go:204: Not found "z.txt" fstest.go:207: Error Trace: fstest.go:207 fstest.go:311 fstest.go:339 fstest.go:345 fstests.go:1470 Error: Not equal: expected: 0 actual : 1 Test: TestIntegration/FsMkdir/FsPutFiles/FsIsFile Messages: 1 objects not found === RUN TestIntegration/FsMkdir/FsPutFiles/FromRoot fstests.go:1496: Opening root remote "TestFileFabric:" path "rclone-test-fesecim1nawusoj7qiyarez4" from "TestFileFabric:rclone-test-fesecim1nawusoj7qiyarez4" 2021/07/25 06:11:36 DEBUG : Creating backend with remote "TestFileFabric:" === RUN TestIntegration/FsMkdir/FsPutFiles/FromRoot/List 2021/07/25 06:11:36 DEBUG : filefabric root '': rpc: getFolderContents(map[count:1000 fi_pid:120673762 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:11:37 DEBUG : filefabric root '': >rpc: result=Success (ok), err= 2021/07/25 06:11:37 ERROR : rclone-test-fesecim1nawusoj7qiyarez4: error listing: directory not found fstest.go:299: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:302: Flushing the directory cache 2021/07/25 06:11:38 DEBUG : filefabric root '': rpc: getFolderContents(map[count:1000 fi_pid:120673762 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:11:38 DEBUG : filefabric root '': >rpc: result=Success (ok), err= 2021/07/25 06:11:38 ERROR : rclone-test-fesecim1nawusoj7qiyarez4: error listing: directory not found fstest.go:299: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:302: Flushing the directory cache 2021/07/25 06:11:40 DEBUG : filefabric root '': rpc: getFolderContents(map[count:1000 fi_pid:120673762 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:11:40 DEBUG : filefabric root '': >rpc: result=Success (ok), err= 2021/07/25 06:11:40 ERROR : rclone-test-fesecim1nawusoj7qiyarez4: error listing: directory not found fstest.go:299: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:302: Flushing the directory cache fstest.go:306: Error Trace: fstest.go:306 fstests.go:1516 Error: Should be true Test: TestIntegration/FsMkdir/FsPutFiles/FromRoot/List Messages: listing wrong, want rclone-test-fesecim1nawusoj7qiyarez4/file name.txt (200), rclone-test-fesecim1nawusoj7qiyarez4/hello? sausage/êé/Hello, 世界/ " ' @ < > & ? + ≠/z.txt (100) got fstest.go:204: Not found "rclone-test-fesecim1nawusoj7qiyarez4/file name.txt" fstest.go:204: Not found "rclone-test-fesecim1nawusoj7qiyarez4/hello? sausage/êé/Hello, 世界/ \" ' @ < > & ? + ≠/z.txt" fstest.go:207: Error Trace: fstest.go:207 fstest.go:311 fstests.go:1516 Error: Not equal: expected: 0 actual : 2 Test: TestIntegration/FsMkdir/FsPutFiles/FromRoot/List Messages: 2 objects not found fstest.go:328: Error Trace: fstest.go:328 fstests.go:1516 Error: Not equal: expected: []string{"rclone-test-fesecim1nawusoj7qiyarez4/hello? sausage", "rclone-test-fesecim1nawusoj7qiyarez4/hello? sausage/êé", "rclone-test-fesecim1nawusoj7qiyarez4/hello? sausage/êé/Hello, 世界", "rclone-test-fesecim1nawusoj7qiyarez4/hello? sausage/êé/Hello, 世界/ \" ' @ < > & ? + ≠"} actual : []string{} Diff: --- Expected +++ Actual @@ -1,6 +1,2 @@ -([]string) (len=4) { - (string) (len=51) "rclone-test-fesecim1nawusoj7qiyarez4/hello? sausage", - (string) (len=56) "rclone-test-fesecim1nawusoj7qiyarez4/hello? sausage/êé", - (string) (len=70) "rclone-test-fesecim1nawusoj7qiyarez4/hello? sausage/êé/Hello, 世界", - (string) (len=91) "rclone-test-fesecim1nawusoj7qiyarez4/hello? sausage/êé/Hello, 世界/ \" ' @ < > & ? + ≠" +([]string) { } Test: TestIntegration/FsMkdir/FsPutFiles/FromRoot/List Messages: directories === RUN TestIntegration/FsMkdir/FsPutFiles/FromRoot/ListEntries 2021/07/25 06:11:44 DEBUG : filefabric root '': rpc: getFolderContents(map[count:1000 fi_pid:120673762 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:11:44 DEBUG : filefabric root '': >rpc: result=Success (ok), err= fstests.go:1522: Error Trace: fstests.go:1522 Error: Received unexpected error: directory not found github.com/rclone/rclone/fs.init /home/rclone/go/src/github.com/rclone/rclone/fs/fs.go:34 runtime.doInit /usr/local/go/src/runtime/proc.go:5625 runtime.doInit /usr/local/go/src/runtime/proc.go:5620 runtime.doInit /usr/local/go/src/runtime/proc.go:5620 runtime.doInit /usr/local/go/src/runtime/proc.go:5620 runtime.main /usr/local/go/src/runtime/proc.go:191 runtime.goexit /usr/local/go/src/runtime/asm_amd64.s:1374 Test: TestIntegration/FsMkdir/FsPutFiles/FromRoot/ListEntries === RUN TestIntegration/FsMkdir/FsPutFiles/FromRoot/Put 2021/07/25 06:11:44 DEBUG : filefabric root '': rpc: getFolderContents(map[count:1000 fi_pid:120673762 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:11:45 DEBUG : filefabric root '': >rpc: result=Success (ok), err= 2021/07/25 06:11:45 DEBUG : filefabric root '': rpc: doCreateNewFolder(map[fi_name:rclone-test-fesecim1nawusoj7qiyarez4 fi_pid:120673762]) options=[] 2021/07/25 06:11:49 DEBUG : filefabric root '': >rpc: result=Success (ok), err= 2021/07/25 06:11:49 DEBUG : filefabric root '': rpc: doInitUpload(map[directuploadsupport:n fi_contenttype:text/plain; charset=utf-8 fi_filename:created from root.txt fi_localtime:2021-07-25 06:11:44 fi_modified:2021-07-25 06:11:44 fi_name:created from root.txt fi_pid:121000259 fi_size:100 responsetype:json]) options=[] 2021/07/25 06:11:50 DEBUG : filefabric root '': >rpc: result=Success (ok), err= 2021/07/25 06:11:51 DEBUG : filefabric root '': rpc: doCompleteUpload(map[fi_size:100 remotetime:2021-07-25 06:11:44 uploadcode:832ef2bdb224c3410537bf530f78746e]) options=[] 2021/07/25 06:11:53 DEBUG : filefabric root '': >rpc: result=Success (ok), err= 2021/07/25 06:11:53 DEBUG : rclone-test-fesecim1nawusoj7qiyarez4/created from root.txt: Correcting mime type from "text/plain" to "text/plain; charset=utf-8" 2021/07/25 06:11:53 DEBUG : filefabric root '': rpc: doModifyFile(map[data:fi_contenttype=text/plain; charset=utf-8 fi_id:121000260]) options=[] 2021/07/25 06:11:53 DEBUG : filefabric root '': >rpc: result=Success (ok), err= 2021/07/25 06:11:53 DEBUG : filefabric root '': rpc: checkPathExists(map[path:rclone-test-fesecim1nawusoj7qiyarez4/created from root.txt pid:120673762]) options=[] 2021/07/25 06:11:54 DEBUG : filefabric root '': >rpc: result=Success (ok), err= 2021/07/25 06:11:54 DEBUG : filefabric root '': rpc: getFolderContents(map[count:1000 fi_pid:121000259 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:11:56 DEBUG : filefabric root '': >rpc: result=Success (ok), err= fstest.go:299: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:302: Flushing the directory cache 2021/07/25 06:11:57 DEBUG : filefabric root '': rpc: getFolderContents(map[count:1000 fi_pid:120673762 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:11:58 DEBUG : filefabric root '': >rpc: result=Success (ok), err= 2021/07/25 06:11:58 DEBUG : filefabric root '': rpc: getFolderContents(map[count:1000 fi_pid:121000259 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:11:59 DEBUG : filefabric root '': >rpc: result=Success (ok), err= fstest.go:299: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:302: Flushing the directory cache 2021/07/25 06:12:01 DEBUG : filefabric root '': rpc: getFolderContents(map[count:1000 fi_pid:120673762 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:12:02 DEBUG : filefabric root '': >rpc: result=Success (ok), err= 2021/07/25 06:12:02 DEBUG : filefabric root '': rpc: getFolderContents(map[count:1000 fi_pid:121000259 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:12:02 DEBUG : filefabric root '': >rpc: result=Success (ok), err= fstest.go:299: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:302: Flushing the directory cache fstest.go:306: Error Trace: fstest.go:306 fstests.go:1572 Error: Should be true Test: TestIntegration/FsMkdir/FsPutFiles/FromRoot/Put Messages: listing wrong, want rclone-test-fesecim1nawusoj7qiyarez4/created from root.txt (100), rclone-test-fesecim1nawusoj7qiyarez4/file name.txt (200), rclone-test-fesecim1nawusoj7qiyarez4/hello? sausage/êé/Hello, 世界/ " ' @ < > & ? + ≠/z.txt (100) got rclone-test-fesecim1nawusoj7qiyarez4/created from root.txt (100) fstest.go:204: Not found "rclone-test-fesecim1nawusoj7qiyarez4/file name.txt" fstest.go:204: Not found "rclone-test-fesecim1nawusoj7qiyarez4/hello? sausage/êé/Hello, 世界/ \" ' @ < > & ? + ≠/z.txt" fstest.go:207: Error Trace: fstest.go:207 fstest.go:311 fstests.go:1572 Error: Not equal: expected: 0 actual : 2 Test: TestIntegration/FsMkdir/FsPutFiles/FromRoot/Put Messages: 2 objects not found === RUN TestIntegration/FsMkdir/FsPutFiles/FromRoot/Put/Remove 2021/07/25 06:12:06 DEBUG : filefabric root '': rpc: doDeleteFile(map[completedeletion:n fi_id:121000260]) options=[] 2021/07/25 06:12:16 DEBUG : filefabric root '': >rpc: result=Success (ok), err= 2021/07/25 06:12:16 DEBUG : filefabric root '': rpc: getFolderContents(map[count:1000 fi_pid:120673762 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:12:16 DEBUG : filefabric root '': >rpc: result=Success (ok), err= 2021/07/25 06:12:16 DEBUG : filefabric root '': rpc: getFolderContents(map[count:1000 fi_pid:121000259 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:12:18 DEBUG : filefabric root '': >rpc: result=Success (ok), err= fstest.go:299: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:302: Flushing the directory cache 2021/07/25 06:12:19 DEBUG : filefabric root '': rpc: getFolderContents(map[count:1000 fi_pid:120673762 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:12:19 DEBUG : filefabric root '': >rpc: result=Success (ok), err= 2021/07/25 06:12:19 DEBUG : filefabric root '': rpc: getFolderContents(map[count:1000 fi_pid:121000259 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:12:20 DEBUG : filefabric root '': >rpc: result=Success (ok), err= fstest.go:299: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:302: Flushing the directory cache 2021/07/25 06:12:22 DEBUG : filefabric root '': rpc: getFolderContents(map[count:1000 fi_pid:120673762 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:12:22 DEBUG : filefabric root '': >rpc: result=Success (ok), err= 2021/07/25 06:12:22 DEBUG : filefabric root '': rpc: getFolderContents(map[count:1000 fi_pid:121000259 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:12:23 DEBUG : filefabric root '': >rpc: result=Success (ok), err= fstest.go:299: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:302: Flushing the directory cache fstest.go:306: Error Trace: fstest.go:306 fstests.go:1577 Error: Should be true Test: TestIntegration/FsMkdir/FsPutFiles/FromRoot/Put/Remove Messages: listing wrong, want rclone-test-fesecim1nawusoj7qiyarez4/file name.txt (200), rclone-test-fesecim1nawusoj7qiyarez4/hello? sausage/êé/Hello, 世界/ " ' @ < > & ? + ≠/z.txt (100) got fstest.go:204: Not found "rclone-test-fesecim1nawusoj7qiyarez4/file name.txt" fstest.go:204: Not found "rclone-test-fesecim1nawusoj7qiyarez4/hello? sausage/êé/Hello, 世界/ \" ' @ < > & ? + ≠/z.txt" fstest.go:207: Error Trace: fstest.go:207 fstest.go:311 fstests.go:1577 Error: Not equal: expected: 0 actual : 2 Test: TestIntegration/FsMkdir/FsPutFiles/FromRoot/Put/Remove Messages: 2 objects not found === RUN TestIntegration/FsMkdir/FsPutFiles/ObjectRemove 2021/07/25 06:12:27 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': rpc: checkPathExists(map[path:file name.txt pid:121000231]) options=[] 2021/07/25 06:12:27 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': >rpc: result=Success (ok), err= 2021/07/25 06:12:27 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': rpc: doDeleteFile(map[completedeletion:n fi_id:121000232]) options=[] 2021/07/25 06:12:27 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': Sleeping for 6s to wait for "error_background" error to clear 2021/07/25 06:12:33 DEBUG : pacer: low level retry 1/10 (error We are not able to complete the requested operation. We are processing delete in parent folder. Please try again later. (error_background)) 2021/07/25 06:12:33 DEBUG : pacer: Rate limited, increasing sleep to 40ms 2021/07/25 06:12:34 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': Sleeping for 6s to wait for "error_background" error to clear 2021/07/25 06:12:40 DEBUG : pacer: low level retry 2/10 (error We are not able to complete the requested operation. We are processing delete in parent folder. Please try again later. (error_background)) 2021/07/25 06:12:40 DEBUG : pacer: Rate limited, increasing sleep to 80ms 2021/07/25 06:12:40 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': Sleeping for 6s to wait for "error_background" error to clear 2021/07/25 06:12:46 DEBUG : pacer: low level retry 3/10 (error We are not able to complete the requested operation. We are processing delete in parent folder. Please try again later. (error_background)) 2021/07/25 06:12:46 DEBUG : pacer: Rate limited, increasing sleep to 160ms 2021/07/25 06:12:46 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': Sleeping for 6s to wait for "error_background" error to clear 2021/07/25 06:12:52 DEBUG : pacer: low level retry 4/10 (error We are not able to complete the requested operation. We are processing delete in parent folder. Please try again later. (error_background)) 2021/07/25 06:12:52 DEBUG : pacer: Rate limited, increasing sleep to 320ms 2021/07/25 06:12:53 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': Sleeping for 6s to wait for "error_background" error to clear 2021/07/25 06:12:59 DEBUG : pacer: low level retry 5/10 (error We are not able to complete the requested operation. We are processing delete in parent folder. Please try again later. (error_background)) 2021/07/25 06:12:59 DEBUG : pacer: Rate limited, increasing sleep to 640ms 2021/07/25 06:13:00 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': Sleeping for 6s to wait for "error_background" error to clear 2021/07/25 06:13:06 DEBUG : pacer: low level retry 6/10 (error We are not able to complete the requested operation. We are processing delete in parent folder. Please try again later. (error_background)) 2021/07/25 06:13:06 DEBUG : pacer: Rate limited, increasing sleep to 1.28s 2021/07/25 06:13:06 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': Sleeping for 6s to wait for "error_background" error to clear 2021/07/25 06:13:12 DEBUG : pacer: low level retry 7/10 (error We are not able to complete the requested operation. We are processing delete in parent folder. Please try again later. (error_background)) 2021/07/25 06:13:12 DEBUG : pacer: Rate limited, increasing sleep to 2.56s 2021/07/25 06:13:13 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': Sleeping for 6s to wait for "error_background" error to clear 2021/07/25 06:13:19 DEBUG : pacer: low level retry 8/10 (error We are not able to complete the requested operation. We are processing delete in parent folder. Please try again later. (error_background)) 2021/07/25 06:13:19 DEBUG : pacer: Rate limited, increasing sleep to 5.12s 2021/07/25 06:13:20 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': Sleeping for 6s to wait for "error_background" error to clear 2021/07/25 06:13:26 DEBUG : pacer: low level retry 9/10 (error We are not able to complete the requested operation. We are processing delete in parent folder. Please try again later. (error_background)) 2021/07/25 06:13:26 DEBUG : pacer: Rate limited, increasing sleep to 10s 2021/07/25 06:13:26 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': Sleeping for 6s to wait for "error_background" error to clear 2021/07/25 06:13:32 DEBUG : pacer: low level retry 10/10 (error We are not able to complete the requested operation. We are processing delete in parent folder. Please try again later. (error_background)) 2021/07/25 06:13:32 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': >rpc: result=We are not able to complete the requested operation. We are processing delete in parent folder. Please try again later. (error_background), err=We are not able to complete the requested operation. We are processing delete in parent folder. Please try again later. (error_background) fstests.go:1691: Error Trace: fstests.go:1691 Error: Received unexpected error: We are not able to complete the requested operation. We are processing delete in parent folder. Please try again later. (error_background) failed to delete file github.com/rclone/rclone/backend/filefabric.(*Fs).deleteObject /home/rclone/go/src/github.com/rclone/rclone/backend/filefabric/filefabric.go:724 github.com/rclone/rclone/backend/filefabric.(*Object).Remove /home/rclone/go/src/github.com/rclone/rclone/backend/filefabric/filefabric.go:1326 github.com/rclone/rclone/fstest/fstests.Run.func13.13.42 /home/rclone/go/src/github.com/rclone/rclone/fstest/fstests/fstests.go:1690 testing.tRunner /usr/local/go/src/testing/testing.go:1123 runtime.goexit /usr/local/go/src/runtime/asm_amd64.s:1374 Test: TestIntegration/FsMkdir/FsPutFiles/ObjectRemove === RUN TestIntegration/FsMkdir/FsUploadUnknownSize === RUN TestIntegration/FsMkdir/FsUploadUnknownSize/FsPutUnknownSize 2021/07/25 06:13:32 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': rpc: doInitUpload(map[directuploadsupport:n fi_contenttype:text/plain; charset=utf-8 fi_filename:unknown-size-put.txt fi_localtime:2002-02-03 04:05:06 fi_modified:2002-02-03 04:05:06 fi_name:unknown-size-put.txt fi_pid:121000231 responsetype:json]) options=[] 2021/07/25 06:13:36 DEBUG : pacer: Reducing sleep to 7.5s 2021/07/25 06:13:36 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': >rpc: result=Can not upload file now. We are not able to complete the requested operation. We are processing delete in parent folder. Please try again later. (error_locked), err=Can not upload file now. We are not able to complete the requested operation. We are processing delete in parent folder. Please try again later. (error_locked) === RUN TestIntegration/FsMkdir/FsUploadUnknownSize/FsUpdateUnknownSize 2021/07/25 06:13:36 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': rpc: doInitUpload(map[directuploadsupport:n fi_contenttype:text/plain; charset=utf-8 fi_filename:unknown-size-update.txt fi_localtime:2002-02-03 04:05:06 fi_modified:2002-02-03 04:05:06 fi_name:unknown-size-update.txt fi_pid:121000231 fi_size:100 responsetype:json]) options=[] 2021/07/25 06:13:47 DEBUG : pacer: Reducing sleep to 5.625s 2021/07/25 06:13:47 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': >rpc: result=Success (ok), err= 2021/07/25 06:13:54 DEBUG : pacer: Reducing sleep to 4.21875s 2021/07/25 06:13:54 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': rpc: doCompleteUpload(map[fi_size:100 remotetime:2002-02-03 04:05:06 uploadcode:edc27687a717fc9f10a128e285e39862]) options=[] 2021/07/25 06:14:01 DEBUG : pacer: Reducing sleep to 3.1640625s 2021/07/25 06:14:01 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': >rpc: result=Success (ok), err= 2021/07/25 06:14:01 DEBUG : unknown-size-update.txt: Correcting mime type from "text/plain" to "text/plain; charset=utf-8" 2021/07/25 06:14:01 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': rpc: doModifyFile(map[data:fi_contenttype=text/plain; charset=utf-8 fi_id:121000272]) options=[] 2021/07/25 06:14:04 DEBUG : pacer: Reducing sleep to 2.373046875s 2021/07/25 06:14:04 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': >rpc: result=Success (ok), err= 2021/07/25 06:14:04 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': rpc: checkPathExists(map[path:unknown-size-update.txt pid:121000231]) options=[] 2021/07/25 06:14:07 DEBUG : pacer: Reducing sleep to 1.779785156s 2021/07/25 06:14:07 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': >rpc: result=Success (ok), err= 2021/07/25 06:14:07 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': rpc: checkPathExists(map[path:unknown-size-update.txt pid:121000231]) options=[] 2021/07/25 06:14:09 DEBUG : pacer: Reducing sleep to 1.334838867s 2021/07/25 06:14:09 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': >rpc: result=Success (ok), err= 2021/07/25 06:14:09 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': rpc: doInitUpload(map[directuploadsupport:n fi_contenttype:text/plain; charset=utf-8 fi_filename:unknown-size-update.txt fi_localtime:2002-02-03 04:05:06 fi_modified:2002-02-03 04:05:06 fi_name:unknown-size-update.txt fi_pid:121000231 responsetype:json]) options=[] 2021/07/25 06:14:12 DEBUG : pacer: Reducing sleep to 1.00112915s 2021/07/25 06:14:12 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': >rpc: result=Success (ok), err= 2021/07/25 06:14:13 DEBUG : pacer: Reducing sleep to 750.846862ms 2021/07/25 06:14:13 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': rpc: doCompleteUpload(map[fi_size:200 remotetime:2002-02-03 04:05:06 uploadcode:88e37b846eea7773d5b0dc143022579b]) options=[] 2021/07/25 06:14:35 DEBUG : pacer: Reducing sleep to 563.135146ms 2021/07/25 06:14:35 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': >rpc: result=Success (ok), err= 2021/07/25 06:14:35 DEBUG : unknown-size-update.txt: Correcting mime type from "text/plain" to "text/plain; charset=utf-8" 2021/07/25 06:14:35 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': rpc: doModifyFile(map[data:fi_contenttype=text/plain; charset=utf-8 fi_id:121000272]) options=[] 2021/07/25 06:14:35 DEBUG : pacer: Reducing sleep to 422.351359ms 2021/07/25 06:14:35 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': >rpc: result=Success (ok), err= 2021/07/25 06:14:35 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': rpc: doDeleteFile(map[completedeletion:n fi_id:121000272]) options=[] 2021/07/25 06:14:39 DEBUG : pacer: Reducing sleep to 316.763519ms 2021/07/25 06:14:39 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': >rpc: result=File unknown-size-update.txt is already in trash. To delete it permanently use the DeleteFromTrash function. (file_error), err=File unknown-size-update.txt is already in trash. To delete it permanently use the DeleteFromTrash function. (file_error) fstests.go:1923: Error Trace: fstests.go:1923 Error: Received unexpected error: File unknown-size-update.txt is already in trash. To delete it permanently use the DeleteFromTrash function. (file_error) failed to delete file github.com/rclone/rclone/backend/filefabric.(*Fs).deleteObject /home/rclone/go/src/github.com/rclone/rclone/backend/filefabric/filefabric.go:724 github.com/rclone/rclone/backend/filefabric.(*Object).Remove /home/rclone/go/src/github.com/rclone/rclone/backend/filefabric/filefabric.go:1326 github.com/rclone/rclone/fstest/fstests.Run.func13.15.2 /home/rclone/go/src/github.com/rclone/rclone/fstest/fstests/fstests.go:1923 testing.tRunner /usr/local/go/src/testing/testing.go:1123 runtime.goexit /usr/local/go/src/runtime/asm_amd64.s:1374 Test: TestIntegration/FsMkdir/FsUploadUnknownSize/FsUpdateUnknownSize Messages: successfully updated object with unknown-sized source but failed to remove 2021/07/25 06:14:39 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': rpc: doDeleteFolder(map[fi_id:121000231]) options=[] 2021/07/25 06:14:41 DEBUG : pacer: Reducing sleep to 237.572639ms 2021/07/25 06:14:41 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': >rpc: result=Folder sub_new_name.xinegin5 is already in trash. To delete it permanently use the DeleteFromTrash function. (file_error), err=Folder sub_new_name.xinegin5 is already in trash. To delete it permanently use the DeleteFromTrash function. (file_error) === CONT TestIntegration/FsMkdir fstests.go:1954: Error Trace: fstests.go:1954 Error: Received unexpected error: failed to remove directory: Folder sub_new_name.xinegin5 is already in trash. To delete it permanently use the DeleteFromTrash function. (file_error) Test: TestIntegration/FsMkdir 2021/07/25 06:14:41 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': rpc: getFolderContents(map[count:1000 fi_pid:120673762 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[] 2021/07/25 06:14:43 DEBUG : pacer: Reducing sleep to 178.179479ms 2021/07/25 06:14:43 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': >rpc: result=Success (ok), err= 2021/07/25 06:14:43 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': rpc: doDeleteFolder(map[fi_id:121000259]) options=[] 2021/07/25 06:14:46 DEBUG : pacer: Reducing sleep to 133.634609ms 2021/07/25 06:14:46 DEBUG : filefabric root 'rclone-test-fesecim1nawusoj7qiyarez4': >rpc: result=Success (ok), err= --- FAIL: TestIntegration (497.39s) --- FAIL: TestIntegration/FsMkdir (484.43s) --- FAIL: TestIntegration/FsMkdir/FsPutFiles (414.98s) --- FAIL: TestIntegration/FsMkdir/FsPutFiles/FsDirMove (213.59s) --- FAIL: TestIntegration/FsMkdir/FsPutFiles/ObjectMimeType (0.42s) --- FAIL: TestIntegration/FsMkdir/FsPutFiles/ObjectUpdate (0.54s) --- FAIL: TestIntegration/FsMkdir/FsPutFiles/FsIsFile (8.10s) --- FAIL: TestIntegration/FsMkdir/FsPutFiles/FromRoot (50.46s) --- FAIL: TestIntegration/FsMkdir/FsPutFiles/FromRoot/List (8.12s) --- FAIL: TestIntegration/FsMkdir/FsPutFiles/FromRoot/ListEntries (0.25s) --- FAIL: TestIntegration/FsMkdir/FsPutFiles/FromRoot/Put (42.09s) --- FAIL: TestIntegration/FsMkdir/FsPutFiles/FromRoot/Put/Remove (20.60s) --- FAIL: TestIntegration/FsMkdir/FsPutFiles/ObjectRemove (65.48s) --- FAIL: TestIntegration/FsMkdir/FsUploadUnknownSize (66.54s) --- PASS: TestIntegration/FsMkdir/FsUploadUnknownSize/FsPutUnknownSize (4.13s) --- FAIL: TestIntegration/FsMkdir/FsUploadUnknownSize/FsUpdateUnknownSize (62.40s) FAIL exit status 1 FAIL github.com/rclone/rclone/backend/filefabric 497.395s "go test -v -timeout 1h0m0s -remote TestFileFabric: -verbose -test.run '^TestIntegration$/^FsMkdir$/^(FsPutFiles|FsUploadUnknownSize)$/^(FromRoot|FsDirMove|FsIsFile|FsPutUnknownSize|FsUpdateUnknownSize|ObjectMimeType|ObjectRemove|ObjectUpdate)$/^(List|ListEntries|Put)$/^Remove$'" - Finished ERROR in 8m19.010927686s (try 2/5): exit status 1: Failed [TestIntegration/FsMkdir/FsPutFiles/FsDirMove TestIntegration/FsMkdir/FsPutFiles/ObjectMimeType TestIntegration/FsMkdir/FsPutFiles/ObjectUpdate TestIntegration/FsMkdir/FsPutFiles/FsIsFile TestIntegration/FsMkdir/FsPutFiles/FromRoot/List TestIntegration/FsMkdir/FsPutFiles/FromRoot/ListEntries TestIntegration/FsMkdir/FsPutFiles/FromRoot/Put/Remove TestIntegration/FsMkdir/FsPutFiles/ObjectRemove TestIntegration/FsMkdir/FsUploadUnknownSize/FsUpdateUnknownSize]