"./sync.test -test.v -test.timeout 2h0m0s -remote TestFileFabric: -verbose" - Starting (try 2/5)
2022/03/02 08:40:01 DEBUG : Creating backend with remote "TestFileFabric:rclone-test-duzipet7zovasul4tijatet2"
2022/03/02 08:40:01 DEBUG : Using config file from "/home/rclone/.rclone.conf"
2022/03/02 08:40:01 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: checkPathExists(map[path:rclone-test-duzipet7zovasul4tijatet2 pid:120673762]) options=[]
2022/03/02 08:40:01 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 08:40:01 DEBUG : Creating backend with remote "/tmp/rclone3003306651"
=== RUN   TestPipe
--- PASS: TestPipe (0.00s)
=== RUN   TestPipeConcurrent
--- PASS: TestPipeConcurrent (0.03s)
=== RUN   TestPipeOrderBy
=== RUN   TestPipeOrderBy/#00
=== RUN   TestPipeOrderBy/size
=== RUN   TestPipeOrderBy/name
=== RUN   TestPipeOrderBy/modtime
=== RUN   TestPipeOrderBy/size,ascending
=== RUN   TestPipeOrderBy/name,asc
=== RUN   TestPipeOrderBy/modtime,ascending
=== RUN   TestPipeOrderBy/size,descending
=== RUN   TestPipeOrderBy/name,desc
=== RUN   TestPipeOrderBy/modtime,descending
=== RUN   TestPipeOrderBy/size,mixed,50
=== RUN   TestPipeOrderBy/size,mixed,51
--- PASS: TestPipeOrderBy (0.00s)
    --- PASS: TestPipeOrderBy/#00 (0.00s)
    --- PASS: TestPipeOrderBy/size (0.00s)
    --- PASS: TestPipeOrderBy/name (0.00s)
    --- PASS: TestPipeOrderBy/modtime (0.00s)
    --- PASS: TestPipeOrderBy/size,ascending (0.00s)
    --- PASS: TestPipeOrderBy/name,asc (0.00s)
    --- PASS: TestPipeOrderBy/modtime,ascending (0.00s)
    --- PASS: TestPipeOrderBy/size,descending (0.00s)
    --- PASS: TestPipeOrderBy/name,desc (0.00s)
    --- PASS: TestPipeOrderBy/modtime,descending (0.00s)
    --- PASS: TestPipeOrderBy/size,mixed,50 (0.00s)
    --- PASS: TestPipeOrderBy/size,mixed,51 (0.00s)
=== RUN   TestNewLess
=== RUN   TestNewLess/blankOK
=== RUN   TestNewLess/tooManyParts
=== RUN   TestNewLess/tooManyParts2
=== RUN   TestNewLess/badMixed
=== RUN   TestNewLess/unknownComparison
=== RUN   TestNewLess/unknownSortDirection
=== RUN   TestNewLess/size
=== RUN   TestNewLess/name
=== RUN   TestNewLess/modtime
=== RUN   TestNewLess/size,ascending
=== RUN   TestNewLess/name,asc
=== RUN   TestNewLess/modtime,ascending
=== RUN   TestNewLess/size,descending
=== RUN   TestNewLess/name,desc
=== RUN   TestNewLess/modtime,descending
=== RUN   TestNewLess/modtime,mixed
=== RUN   TestNewLess/modtime,mixed,30
--- PASS: TestNewLess (0.00s)
    --- PASS: TestNewLess/blankOK (0.00s)
    --- PASS: TestNewLess/tooManyParts (0.00s)
    --- PASS: TestNewLess/tooManyParts2 (0.00s)
    --- PASS: TestNewLess/badMixed (0.00s)
    --- PASS: TestNewLess/unknownComparison (0.00s)
    --- PASS: TestNewLess/unknownSortDirection (0.00s)
    --- PASS: TestNewLess/size (0.00s)
    --- PASS: TestNewLess/name (0.00s)
    --- PASS: TestNewLess/modtime (0.00s)
    --- PASS: TestNewLess/size,ascending (0.00s)
    --- PASS: TestNewLess/name,asc (0.00s)
    --- PASS: TestNewLess/modtime,ascending (0.00s)
    --- PASS: TestNewLess/size,descending (0.00s)
    --- PASS: TestNewLess/name,desc (0.00s)
    --- PASS: TestNewLess/modtime,descending (0.00s)
    --- PASS: TestNewLess/modtime,mixed (0.00s)
    --- PASS: TestNewLess/modtime,mixed,30 (0.00s)
=== RUN   TestRcCopy
    rc_test.go:16: Skipping test on non local remote
--- SKIP: TestRcCopy (0.00s)
=== RUN   TestRcMove
    rc_test.go:16: Skipping test on non local remote
--- SKIP: TestRcMove (0.00s)
=== RUN   TestRcSync
    rc_test.go:16: Skipping test on non local remote
--- SKIP: TestRcSync (0.00s)
=== RUN   TestCopyWithDryRun
    run.go:181: Remote "filefabric root 'rclone-test-duzipet7zovasul4tijatet2'", Local "Local file system at /tmp/rclone3003306651", Modify Window "1s"
2022/03/02 08:40:01 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': 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=[]
2022/03/02 08:40:10 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 08:40:10 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doCreateNewFolder(map[fi_name:rclone-test-duzipet7zovasul4tijatet2 fi_pid:120673762]) options=[]
2022/03/02 08:40:57 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 08:40:57 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 08:41:24 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 08:41:24 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Waiting for checks to finish
2022/03/02 08:41:24 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Waiting for transfers to finish
2022/03/02 08:41:24 NOTICE: sub dir/hello world: Skipped copy as --dry-run is set (size 11)
2022/03/02 08:41:24 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 08:41:24 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 08:41:24 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 08:41:25 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 08:41:25 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 08:41:26 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
--- PASS: TestCopyWithDryRun (84.31s)
=== RUN   TestCopy
    run.go:181: Remote "filefabric root 'rclone-test-duzipet7zovasul4tijatet2'", Local "Local file system at /tmp/rclone3003306651", Modify Window "1s"
2022/03/02 08:41:26 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 08:41:26 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 08:41:26 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Waiting for checks to finish
2022/03/02 08:41:26 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Waiting for transfers to finish
2022/03/02 08:41:26 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 08:41:27 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 08:41:27 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doCreateNewFolder(map[fi_name:sub dir fi_pid:121389188]) options=[]
2022/03/02 08:42:09 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 08:42:09 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doInitUpload(map[directuploadsupport:n fi_contenttype:application/octet-stream fi_filename:hello world fi_localtime:2001-02-03 04:05:06 fi_modified:2001-02-03 04:05:06 fi_name:hello world fi_pid:121389189 fi_size:11 responsetype:json]) options=[]
2022/03/02 08:42:15 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 08:42:17 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doCompleteUpload(map[fi_size:11 remotetime:2001-02-03 04:05:06 uploadcode:cdbc64aa48207a363b3ed7c0172dfa89]) options=[]
2022/03/02 08:42:57 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 08:42:57 INFO  : sub dir/hello world: Copied (new)
2022/03/02 08:42:57 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 08:43:32 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 08:43:32 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389189 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 08:44:06 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 08:44:06 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 08:44:07 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 08:44:07 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389189 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 08:44:08 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 08:44:08 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doDeleteFile(map[completedeletion:n fi_id:121389190]) options=[]
2022/03/02 08:46:58 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 08:46:58 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389189 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 08:47:33 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 08:47:33 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doDeleteFolder(map[fi_id:121389189]) options=[]
2022/03/02 08:48:12 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 08:48:12 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 08:48:21 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
--- PASS: TestCopy (415.71s)
=== RUN   TestCopyMissingDirectory
    run.go:181: Remote "filefabric root 'rclone-test-duzipet7zovasul4tijatet2'", Local "Local file system at /tmp/rclone3003306651", Modify Window "1s"
2022/03/02 08:48:21 DEBUG : Creating backend with remote "/non-existing"
2022/03/02 08:48:21 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 08:48:22 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 08:48:22 ERROR : Local file system at /non-existing: error reading source root directory: directory not found
2022/03/02 08:48:22 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Waiting for checks to finish
2022/03/02 08:48:22 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Waiting for transfers to finish
2022/03/02 08:48:22 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 08:48:22 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 08:48:22 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 08:48:23 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
--- PASS: TestCopyMissingDirectory (1.73s)
=== RUN   TestCopyNoTraverse
    run.go:181: Remote "filefabric root 'rclone-test-duzipet7zovasul4tijatet2'", Local "Local file system at /tmp/rclone3003306651", Modify Window "1s"
2022/03/02 08:48:23 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: checkPathExists(map[path:sub dir/hello world pid:121389188]) options=[]
2022/03/02 08:48:23 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 08:48:23 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Waiting for checks to finish
2022/03/02 08:48:23 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 08:48:23 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Waiting for transfers to finish
2022/03/02 08:48:24 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 08:48:24 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doCreateNewFolder(map[fi_name:sub dir fi_pid:121389188]) options=[]
2022/03/02 08:48:26 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Sleeping for 1s to wait for "error_background" error to clear
2022/03/02 08:48:27 DEBUG : pacer: low level retry 1/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/02 08:48:27 DEBUG : pacer: Rate limited, increasing sleep to 40ms
2022/03/02 08:48:35 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Sleeping for 2s to wait for "error_background" error to clear
2022/03/02 08:48:37 DEBUG : pacer: low level retry 2/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/02 08:48:37 DEBUG : pacer: Rate limited, increasing sleep to 80ms
2022/03/02 08:48:43 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Sleeping for 4s to wait for "error_background" error to clear
2022/03/02 08:48:47 DEBUG : pacer: low level retry 3/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/02 08:48:47 DEBUG : pacer: Rate limited, increasing sleep to 160ms
2022/03/02 08:48:48 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Sleeping for 8s to wait for "error_background" error to clear
2022/03/02 08:48:56 DEBUG : pacer: low level retry 4/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/02 08:48:56 DEBUG : pacer: Rate limited, increasing sleep to 320ms
2022/03/02 08:48:58 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Sleeping for 16s to wait for "error_background" error to clear
2022/03/02 08:49:14 DEBUG : pacer: low level retry 5/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/02 08:49:14 DEBUG : pacer: Rate limited, increasing sleep to 640ms
2022/03/02 08:49:20 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Sleeping for 32s to wait for "error_background" error to clear
2022/03/02 08:49:52 DEBUG : pacer: low level retry 6/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/02 08:49:52 DEBUG : pacer: Rate limited, increasing sleep to 1.28s
2022/03/02 08:49:52 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Sleeping for 1m4s to wait for "error_background" error to clear
2022/03/02 08:50:56 DEBUG : pacer: low level retry 7/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/02 08:50:56 DEBUG : pacer: Rate limited, increasing sleep to 2.56s
2022/03/02 08:51:05 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Sleeping for 2m8s to wait for "error_background" error to clear
2022/03/02 08:53:13 DEBUG : pacer: low level retry 8/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/02 08:53:13 DEBUG : pacer: Rate limited, increasing sleep to 5.12s
2022/03/02 08:53:19 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Sleeping for 4m16s to wait for "error_background" error to clear
2022/03/02 08:57:35 DEBUG : pacer: low level retry 9/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/02 08:57:35 DEBUG : pacer: Rate limited, increasing sleep to 10s
2022/03/02 08:57:43 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Sleeping for 8m32s to wait for "error_background" error to clear
2022/03/02 09:06:15 DEBUG : pacer: low level retry 10/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/02 09:06:15 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background), err=Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background)
2022/03/02 09:06:15 DEBUG : sub dir/hello world: Received error: failed to make directory: failed to create directory: Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background) - low level retry 1/10
2022/03/02 09:06:15 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 09:06:49 DEBUG : pacer: Reducing sleep to 7.5s
2022/03/02 09:06:49 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:06:49 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doCreateNewFolder(map[fi_name:sub dir fi_pid:121389188]) options=[]
2022/03/02 09:07:49 DEBUG : pacer: Reducing sleep to 5.625s
2022/03/02 09:07:49 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:07:49 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doInitUpload(map[directuploadsupport:n fi_contenttype:application/octet-stream fi_filename:hello world fi_localtime:2001-02-03 04:05:06 fi_modified:2001-02-03 04:05:06 fi_name:hello world fi_pid:121389213 fi_size:11 responsetype:json]) options=[]
2022/03/02 09:07:56 DEBUG : pacer: Reducing sleep to 4.21875s
2022/03/02 09:07:56 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:07:57 DEBUG : pacer: Reducing sleep to 3.1640625s
2022/03/02 09:07:57 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doCompleteUpload(map[fi_size:11 remotetime:2001-02-03 04:05:06 uploadcode:1599b37f324a5de581fd39a2cad5355b]) options=[]
2022/03/02 09:08:23 DEBUG : pacer: Reducing sleep to 2.373046875s
2022/03/02 09:08:23 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:08:23 INFO  : sub dir/hello world: Copied (new)
2022/03/02 09:08:23 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 09:08:59 DEBUG : pacer: Reducing sleep to 1.779785156s
2022/03/02 09:08:59 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:08:59 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389213 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 09:09:35 DEBUG : pacer: Reducing sleep to 1.334838867s
2022/03/02 09:09:35 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:09:35 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 09:09:36 DEBUG : pacer: Reducing sleep to 1.00112915s
2022/03/02 09:09:36 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:09:36 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389213 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 09:09:37 DEBUG : pacer: Reducing sleep to 750.846862ms
2022/03/02 09:09:37 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:09:37 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doDeleteFile(map[completedeletion:n fi_id:121389214]) options=[]
2022/03/02 09:11:51 DEBUG : pacer: Reducing sleep to 563.135146ms
2022/03/02 09:11:51 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:11:51 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389213 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 09:12:25 DEBUG : pacer: Reducing sleep to 422.351359ms
2022/03/02 09:12:25 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:12:25 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doDeleteFolder(map[fi_id:121389213]) options=[]
2022/03/02 09:13:09 DEBUG : pacer: Reducing sleep to 316.763519ms
2022/03/02 09:13:09 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:13:09 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 09:13:20 DEBUG : pacer: Reducing sleep to 237.572639ms
2022/03/02 09:13:20 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
--- PASS: TestCopyNoTraverse (1497.24s)
=== RUN   TestCopyCheckFirst
    run.go:181: Remote "filefabric root 'rclone-test-duzipet7zovasul4tijatet2'", Local "Local file system at /tmp/rclone3003306651", Modify Window "1s"
2022/03/02 09:13:20 INFO  : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Running all checks before starting transfers
2022/03/02 09:13:20 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 09:13:21 DEBUG : pacer: Reducing sleep to 178.179479ms
2022/03/02 09:13:21 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:13:21 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Waiting for checks to finish
2022/03/02 09:13:21 INFO  : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Checks finished, now starting transfers
2022/03/02 09:13:21 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Waiting for transfers to finish
2022/03/02 09:13:21 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 09:13:22 DEBUG : pacer: Reducing sleep to 133.634609ms
2022/03/02 09:13:22 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:13:22 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doCreateNewFolder(map[fi_name:sub dir fi_pid:121389188]) options=[]
2022/03/02 09:13:31 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Sleeping for 1s to wait for "error_background" error to clear
2022/03/02 09:13:32 DEBUG : pacer: low level retry 1/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/02 09:13:32 DEBUG : pacer: Rate limited, increasing sleep to 267.269218ms
2022/03/02 09:13:37 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Sleeping for 2s to wait for "error_background" error to clear
2022/03/02 09:13:39 DEBUG : pacer: low level retry 2/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/02 09:13:39 DEBUG : pacer: Rate limited, increasing sleep to 534.538436ms
2022/03/02 09:13:47 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Sleeping for 4s to wait for "error_background" error to clear
2022/03/02 09:13:51 DEBUG : pacer: low level retry 3/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/02 09:13:51 DEBUG : pacer: Rate limited, increasing sleep to 1.069076872s
2022/03/02 09:13:53 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Sleeping for 8s to wait for "error_background" error to clear
2022/03/02 09:14:01 DEBUG : pacer: low level retry 4/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/02 09:14:01 DEBUG : pacer: Rate limited, increasing sleep to 2.138153744s
2022/03/02 09:14:06 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Sleeping for 16s to wait for "error_background" error to clear
2022/03/02 09:14:22 DEBUG : pacer: low level retry 5/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/02 09:14:22 DEBUG : pacer: Rate limited, increasing sleep to 4.276307488s
2022/03/02 09:14:26 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Sleeping for 32s to wait for "error_background" error to clear
2022/03/02 09:14:58 DEBUG : pacer: low level retry 6/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/02 09:14:58 DEBUG : pacer: Rate limited, increasing sleep to 8.552614976s
2022/03/02 09:15:01 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Sleeping for 1m4s to wait for "error_background" error to clear
2022/03/02 09:16:05 DEBUG : pacer: low level retry 7/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/02 09:16:05 DEBUG : pacer: Rate limited, increasing sleep to 10s
2022/03/02 09:16:07 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Sleeping for 2m8s to wait for "error_background" error to clear
2022/03/02 09:18:15 DEBUG : pacer: low level retry 8/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/02 09:18:16 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Sleeping for 4m16s to wait for "error_background" error to clear
2022/03/02 09:22:32 DEBUG : pacer: low level retry 9/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/02 09:22:41 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Sleeping for 8m32s to wait for "error_background" error to clear
2022/03/02 09:31:13 DEBUG : pacer: low level retry 10/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/02 09:31:13 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background), err=Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background)
2022/03/02 09:31:13 DEBUG : sub dir/hello world: Received error: failed to make directory: failed to create directory: Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background) - low level retry 1/10
2022/03/02 09:31:13 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 09:31:13 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Token expired - refreshing
2022/03/02 09:31:13 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getTokenByAuthToken(map[authtoken:622506e6346e7ad6-c48bf9558d23a2ae token:*]) options=[]
2022/03/02 09:31:13 DEBUG : pacer: Reducing sleep to 7.5s
2022/03/02 09:31:13 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:31:13 DEBUG : Saving config "token" in section "TestFileFabric" of the config file
2022/03/02 09:31:13 DEBUG : Config file has changed externaly - reloading
2022/03/02 09:31:13 DEBUG : Saving config "token_expiry" in section "TestFileFabric" of the config file
2022/03/02 09:31:13 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getApplianceInfo(map[token:*]) options=[]
2022/03/02 09:31:23 DEBUG : pacer: Reducing sleep to 5.625s
2022/03/02 09:31:23 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:31:23 DEBUG : Saving config "version" in section "TestFileFabric" of the config file
2022/03/02 09:31:39 DEBUG : pacer: Reducing sleep to 4.21875s
2022/03/02 09:31:39 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:31:39 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doCreateNewFolder(map[fi_name:sub dir fi_pid:121389188]) options=[]
2022/03/02 09:31:50 DEBUG : pacer: Reducing sleep to 3.1640625s
2022/03/02 09:31:50 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:31:50 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doInitUpload(map[directuploadsupport:n fi_contenttype:application/octet-stream fi_filename:hello world fi_localtime:2001-02-03 04:05:06 fi_modified:2001-02-03 04:05:06 fi_name:hello world fi_pid:121389247 fi_size:11 responsetype:json]) options=[]
2022/03/02 09:31:55 DEBUG : pacer: Reducing sleep to 2.373046875s
2022/03/02 09:31:55 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:31:57 DEBUG : pacer: Reducing sleep to 1.779785156s
2022/03/02 09:31:57 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doCompleteUpload(map[fi_size:11 remotetime:2001-02-03 04:05:06 uploadcode:f4aec6f8ac5de75441626427de965e1e]) options=[]
2022/03/02 09:32:07 DEBUG : pacer: Reducing sleep to 1.334838867s
2022/03/02 09:32:07 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:32:07 INFO  : sub dir/hello world: Copied (new)
2022/03/02 09:32:07 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 09:32:19 DEBUG : pacer: Reducing sleep to 1.00112915s
2022/03/02 09:32:19 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:32:19 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389247 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 09:32:31 DEBUG : pacer: Reducing sleep to 750.846862ms
2022/03/02 09:32:31 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:32:31 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 09:32:31 DEBUG : pacer: Reducing sleep to 563.135146ms
2022/03/02 09:32:31 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:32:31 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389247 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 09:32:32 DEBUG : pacer: Reducing sleep to 422.351359ms
2022/03/02 09:32:32 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:32:32 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doDeleteFile(map[completedeletion:n fi_id:121389249]) options=[]
2022/03/02 09:33:16 DEBUG : pacer: Reducing sleep to 316.763519ms
2022/03/02 09:33:16 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:33:16 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389247 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 09:33:38 DEBUG : pacer: Reducing sleep to 237.572639ms
2022/03/02 09:33:38 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:33:38 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doDeleteFolder(map[fi_id:121389247]) options=[]
2022/03/02 09:33:55 DEBUG : pacer: Reducing sleep to 178.179479ms
2022/03/02 09:33:55 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:33:55 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 09:34:00 DEBUG : pacer: Reducing sleep to 133.634609ms
2022/03/02 09:34:00 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
--- PASS: TestCopyCheckFirst (1239.44s)
=== RUN   TestSyncNoTraverse
    run.go:181: Remote "filefabric root 'rclone-test-duzipet7zovasul4tijatet2'", Local "Local file system at /tmp/rclone3003306651", Modify Window "1s"
2022/03/02 09:34:00 ERROR : Ignoring --no-traverse with sync
2022/03/02 09:34:00 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 09:34:00 DEBUG : pacer: Reducing sleep to 100.225956ms
2022/03/02 09:34:00 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:34:00 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Waiting for checks to finish
2022/03/02 09:34:00 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Waiting for transfers to finish
2022/03/02 09:34:00 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 09:34:01 DEBUG : pacer: Reducing sleep to 75.169467ms
2022/03/02 09:34:01 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:34:01 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doCreateNewFolder(map[fi_name:sub dir fi_pid:121389188]) options=[]
2022/03/02 09:34:04 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Sleeping for 1s to wait for "error_background" error to clear
2022/03/02 09:34:05 DEBUG : pacer: low level retry 1/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/02 09:34:05 DEBUG : pacer: Rate limited, increasing sleep to 150.338934ms
2022/03/02 09:34:09 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Sleeping for 2s to wait for "error_background" error to clear
2022/03/02 09:34:11 DEBUG : pacer: low level retry 2/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/02 09:34:11 DEBUG : pacer: Rate limited, increasing sleep to 300.677868ms
2022/03/02 09:34:13 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Sleeping for 4s to wait for "error_background" error to clear
2022/03/02 09:34:17 DEBUG : pacer: low level retry 3/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/02 09:34:17 DEBUG : pacer: Rate limited, increasing sleep to 601.355736ms
2022/03/02 09:34:18 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Sleeping for 8s to wait for "error_background" error to clear
2022/03/02 09:34:26 DEBUG : pacer: low level retry 4/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/02 09:34:26 DEBUG : pacer: Rate limited, increasing sleep to 1.202711472s
2022/03/02 09:34:27 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Sleeping for 16s to wait for "error_background" error to clear
2022/03/02 09:34:43 DEBUG : pacer: low level retry 5/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/02 09:34:43 DEBUG : pacer: Rate limited, increasing sleep to 2.405422944s
2022/03/02 09:34:59 DEBUG : pacer: Reducing sleep to 1.804067208s
2022/03/02 09:34:59 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:34:59 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doInitUpload(map[directuploadsupport:n fi_contenttype:application/octet-stream fi_filename:hello world fi_localtime:2001-02-03 04:05:06 fi_modified:2001-02-03 04:05:06 fi_name:hello world fi_pid:121389257 fi_size:11 responsetype:json]) options=[]
2022/03/02 09:35:04 DEBUG : pacer: Reducing sleep to 1.353050406s
2022/03/02 09:35:04 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:35:06 DEBUG : pacer: Reducing sleep to 1.014787804s
2022/03/02 09:35:06 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doCompleteUpload(map[fi_size:11 remotetime:2001-02-03 04:05:06 uploadcode:32f4dc7ce387059614aeb37dc2d15f5e]) options=[]
2022/03/02 09:35:15 DEBUG : pacer: Reducing sleep to 761.090853ms
2022/03/02 09:35:15 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:35:15 INFO  : sub dir/hello world: Copied (new)
2022/03/02 09:35:15 DEBUG : Waiting for deletions to finish
2022/03/02 09:35:15 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 09:35:26 DEBUG : pacer: Reducing sleep to 570.818139ms
2022/03/02 09:35:26 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:35:26 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389257 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 09:35:39 DEBUG : pacer: Reducing sleep to 428.113604ms
2022/03/02 09:35:39 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:35:39 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 09:35:40 DEBUG : pacer: Reducing sleep to 321.085203ms
2022/03/02 09:35:40 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:35:40 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389257 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 09:35:40 DEBUG : pacer: Reducing sleep to 240.813902ms
2022/03/02 09:35:40 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:35:40 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doDeleteFile(map[completedeletion:n fi_id:121389258]) options=[]
2022/03/02 09:36:20 DEBUG : pacer: Reducing sleep to 180.610426ms
2022/03/02 09:36:20 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:36:20 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389257 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 09:36:44 DEBUG : pacer: Reducing sleep to 135.457819ms
2022/03/02 09:36:44 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:36:44 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doDeleteFolder(map[fi_id:121389257]) options=[]
2022/03/02 09:36:56 DEBUG : pacer: Reducing sleep to 101.593364ms
2022/03/02 09:36:56 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:36:56 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 09:36:57 DEBUG : pacer: Reducing sleep to 76.195023ms
2022/03/02 09:36:57 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
--- PASS: TestSyncNoTraverse (177.40s)
=== RUN   TestCopyWithDepth
    run.go:181: Remote "filefabric root 'rclone-test-duzipet7zovasul4tijatet2'", Local "Local file system at /tmp/rclone3003306651", Modify Window "1s"
2022/03/02 09:36:57 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 09:36:58 DEBUG : pacer: Reducing sleep to 57.146267ms
2022/03/02 09:36:58 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:36:58 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Waiting for checks to finish
2022/03/02 09:36:58 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Waiting for transfers to finish
2022/03/02 09:36:58 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doInitUpload(map[directuploadsupport:n fi_contenttype:application/octet-stream fi_filename:hello world2 fi_localtime:2011-12-25 12:59:59 fi_modified:2011-12-25 12:59:59 fi_name:hello world2 fi_pid:121389188 fi_size:12 responsetype:json]) options=[]
2022/03/02 09:36:59 DEBUG : pacer: Reducing sleep to 42.8597ms
2022/03/02 09:36:59 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:37:01 DEBUG : pacer: Reducing sleep to 32.144775ms
2022/03/02 09:37:01 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doCompleteUpload(map[fi_size:12 remotetime:2011-12-25 12:59:59 uploadcode:88ae1bd13e96edc96e85b6034f6b3c05]) options=[]
2022/03/02 09:37:07 DEBUG : pacer: Reducing sleep to 24.108581ms
2022/03/02 09:37:07 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:37:07 INFO  : hello world2: Copied (new)
2022/03/02 09:37:07 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 09:37:08 DEBUG : pacer: Reducing sleep to 20ms
2022/03/02 09:37:08 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:37:08 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 09:37:08 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:37:08 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doDeleteFile(map[completedeletion:n fi_id:121389263]) options=[]
2022/03/02 09:37:39 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:37:39 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 09:37:52 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
--- PASS: TestCopyWithDepth (54.96s)
=== RUN   TestCopyWithFilesFrom
    run.go:181: Remote "filefabric root 'rclone-test-duzipet7zovasul4tijatet2'", Local "Local file system at /tmp/rclone3003306651", Modify Window "1s"
2022/03/02 09:37:52 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 09:37:52 DEBUG : hello world2: Excluded
2022/03/02 09:37:53 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:37:53 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Waiting for checks to finish
2022/03/02 09:37:53 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doInitUpload(map[directuploadsupport:n fi_contenttype:application/octet-stream fi_filename:potato2 fi_localtime:2001-02-03 04:05:06 fi_modified:2001-02-03 04:05:06 fi_name:potato2 fi_pid:121389188 fi_size:11 responsetype:json]) options=[]
2022/03/02 09:37:53 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Waiting for transfers to finish
2022/03/02 09:37:58 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:37:59 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doCompleteUpload(map[fi_size:11 remotetime:2001-02-03 04:05:06 uploadcode:43a551ae78970335c0bda611e0825370]) options=[]
2022/03/02 09:38:05 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:38:05 INFO  : potato2: Copied (new)
2022/03/02 09:38:05 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 09:38:14 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:38:14 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 09:38:15 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:38:15 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doDeleteFile(map[completedeletion:n fi_id:121389268]) options=[]
2022/03/02 09:38:40 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:38:40 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 09:39:00 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
--- PASS: TestCopyWithFilesFrom (67.68s)
=== RUN   TestCopyWithFilesFromAndNoTraverse
    run.go:181: Remote "filefabric root 'rclone-test-duzipet7zovasul4tijatet2'", Local "Local file system at /tmp/rclone3003306651", Modify Window "1s"
2022/03/02 09:39:00 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: checkPathExists(map[path:potato2 pid:121389188]) options=[]
2022/03/02 09:39:00 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:39:00 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Waiting for checks to finish
2022/03/02 09:39:00 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doInitUpload(map[directuploadsupport:n fi_contenttype:application/octet-stream fi_filename:potato2 fi_localtime:2001-02-03 04:05:06 fi_modified:2001-02-03 04:05:06 fi_name:potato2 fi_pid:121389188 fi_size:11 responsetype:json]) options=[]
2022/03/02 09:39:00 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Waiting for transfers to finish
2022/03/02 09:39:06 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:39:08 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doCompleteUpload(map[fi_size:11 remotetime:2001-02-03 04:05:06 uploadcode:aa2e405a10b5efdd8a484da1c7ce1882]) options=[]
2022/03/02 09:39:20 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:39:20 INFO  : potato2: Copied (new)
2022/03/02 09:39:20 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 09:39:33 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:39:33 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 09:39:34 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:39:34 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doDeleteFile(map[completedeletion:n fi_id:121389272]) options=[]
2022/03/02 09:40:31 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:40:31 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 09:40:39 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
--- PASS: TestCopyWithFilesFromAndNoTraverse (99.44s)
=== RUN   TestCopyEmptyDirectories
    run.go:181: Remote "filefabric root 'rclone-test-duzipet7zovasul4tijatet2'", Local "Local file system at /tmp/rclone3003306651", Modify Window "1s"
2022/03/02 09:40:39 DEBUG : sub dir2: Making directory
2022/03/02 09:40:39 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 09:40:40 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:40:40 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Waiting for checks to finish
2022/03/02 09:40:40 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Waiting for transfers to finish
2022/03/02 09:40:40 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 09:40:40 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:40:40 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doCreateNewFolder(map[fi_name:sub dir fi_pid:121389188]) options=[]
2022/03/02 09:41:10 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:41:10 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doInitUpload(map[directuploadsupport:n fi_contenttype:application/octet-stream fi_filename:hello world fi_localtime:2001-02-03 04:05:06 fi_modified:2001-02-03 04:05:06 fi_name:hello world fi_pid:121389274 fi_size:11 responsetype:json]) options=[]
2022/03/02 09:41:15 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:41:16 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doCompleteUpload(map[fi_size:11 remotetime:2001-02-03 04:05:06 uploadcode:f9fab3e96a3e9818f2c9511270c8a5a6]) options=[]
2022/03/02 09:41:21 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:41:21 INFO  : sub dir/hello world: Copied (new)
2022/03/02 09:41:21 DEBUG : sub dir2: Making directory
2022/03/02 09:41:21 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 09:41:42 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:41:42 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doCreateNewFolder(map[fi_name:sub dir2 fi_pid:121389188]) options=[]
2022/03/02 09:42:11 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:42:11 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': copied 1 directories
2022/03/02 09:42:11 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 09:42:23 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:42:23 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389279 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 09:42:23 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389274 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 09:42:33 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:42:33 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:42:33 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 09:42:34 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:42:34 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389279 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 09:42:34 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389274 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 09:42:35 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:42:35 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doDeleteFile(map[completedeletion:n fi_id:121389276]) options=[]
2022/03/02 09:42:35 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:43:25 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:43:25 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389279 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 09:43:25 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:43:25 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doDeleteFolder(map[fi_id:121389279]) options=[]
2022/03/02 09:43:38 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:43:38 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389274 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 09:43:46 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:43:46 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doDeleteFolder(map[fi_id:121389274]) options=[]
2022/03/02 09:44:02 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:44:02 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 09:44:06 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
--- PASS: TestCopyEmptyDirectories (206.82s)
=== RUN   TestMoveEmptyDirectories
    run.go:181: Remote "filefabric root 'rclone-test-duzipet7zovasul4tijatet2'", Local "Local file system at /tmp/rclone3003306651", Modify Window "1s"
2022/03/02 09:44:06 DEBUG : sub dir2: Making directory
2022/03/02 09:44:06 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 09:44:07 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:44:07 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Waiting for checks to finish
2022/03/02 09:44:07 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Waiting for transfers to finish
2022/03/02 09:44:07 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 09:44:07 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:44:07 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doCreateNewFolder(map[fi_name:sub dir fi_pid:121389188]) options=[]
2022/03/02 09:44:10 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Sleeping for 1s to wait for "error_background" error to clear
2022/03/02 09:44:11 DEBUG : pacer: low level retry 1/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/02 09:44:11 DEBUG : pacer: Rate limited, increasing sleep to 40ms
2022/03/02 09:44:14 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Sleeping for 2s to wait for "error_background" error to clear
2022/03/02 09:44:16 DEBUG : pacer: low level retry 2/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/02 09:44:16 DEBUG : pacer: Rate limited, increasing sleep to 80ms
2022/03/02 09:44:17 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Sleeping for 4s to wait for "error_background" error to clear
2022/03/02 09:44:21 DEBUG : pacer: low level retry 3/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/02 09:44:21 DEBUG : pacer: Rate limited, increasing sleep to 160ms
2022/03/02 09:44:25 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Sleeping for 8s to wait for "error_background" error to clear
2022/03/02 09:44:33 DEBUG : pacer: low level retry 4/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/02 09:44:33 DEBUG : pacer: Rate limited, increasing sleep to 320ms
2022/03/02 09:44:34 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Sleeping for 16s to wait for "error_background" error to clear
2022/03/02 09:44:50 DEBUG : pacer: low level retry 5/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/02 09:44:50 DEBUG : pacer: Rate limited, increasing sleep to 640ms
2022/03/02 09:44:52 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Sleeping for 32s to wait for "error_background" error to clear
2022/03/02 09:45:24 DEBUG : pacer: low level retry 6/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/02 09:45:24 DEBUG : pacer: Rate limited, increasing sleep to 1.28s
2022/03/02 09:45:45 DEBUG : pacer: Reducing sleep to 960ms
2022/03/02 09:45:45 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:45:45 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doInitUpload(map[directuploadsupport:n fi_contenttype:application/octet-stream fi_filename:hello world fi_localtime:2001-02-03 04:05:06 fi_modified:2001-02-03 04:05:06 fi_name:hello world fi_pid:121389289 fi_size:11 responsetype:json]) options=[]
2022/03/02 09:45:47 DEBUG : pacer: Reducing sleep to 720ms
2022/03/02 09:45:47 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:45:49 DEBUG : pacer: Reducing sleep to 540ms
2022/03/02 09:45:49 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doCompleteUpload(map[fi_size:11 remotetime:2001-02-03 04:05:06 uploadcode:be0fbecc5b324fd9f6f66158c770b72f]) options=[]
2022/03/02 09:45:54 DEBUG : pacer: Reducing sleep to 405ms
2022/03/02 09:45:54 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:45:54 INFO  : sub dir/hello world: Copied (new)
2022/03/02 09:45:54 INFO  : sub dir/hello world: Deleted
2022/03/02 09:45:54 DEBUG : sub dir: Making directory
2022/03/02 09:45:54 DEBUG : sub dir2: Making directory
2022/03/02 09:45:54 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 09:46:07 DEBUG : pacer: Reducing sleep to 303.75ms
2022/03/02 09:46:07 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:46:07 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doCreateNewFolder(map[fi_name:sub dir2 fi_pid:121389188]) options=[]
2022/03/02 09:46:27 DEBUG : pacer: Reducing sleep to 227.8125ms
2022/03/02 09:46:27 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:46:27 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': copied 2 directories
2022/03/02 09:46:27 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 09:46:36 DEBUG : pacer: Reducing sleep to 170.859375ms
2022/03/02 09:46:36 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:46:36 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389292 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 09:46:36 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389289 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 09:46:45 DEBUG : pacer: Reducing sleep to 128.144531ms
2022/03/02 09:46:45 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:46:49 DEBUG : pacer: Reducing sleep to 96.108398ms
2022/03/02 09:46:49 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:46:49 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 09:46:49 DEBUG : pacer: Reducing sleep to 72.081298ms
2022/03/02 09:46:49 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:46:49 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389292 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 09:46:49 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389289 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 09:46:50 DEBUG : pacer: Reducing sleep to 54.060973ms
2022/03/02 09:46:50 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:46:50 DEBUG : pacer: Reducing sleep to 40.545729ms
2022/03/02 09:46:50 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:46:50 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doDeleteFile(map[completedeletion:n fi_id:121389290]) options=[]
2022/03/02 09:47:36 DEBUG : pacer: Reducing sleep to 30.409296ms
2022/03/02 09:47:36 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:47:36 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389292 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 09:47:37 DEBUG : pacer: Reducing sleep to 22.806972ms
2022/03/02 09:47:37 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:47:37 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doDeleteFolder(map[fi_id:121389292]) options=[]
2022/03/02 09:47:52 DEBUG : pacer: Reducing sleep to 20ms
2022/03/02 09:47:52 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:47:52 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389289 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 09:48:10 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:48:10 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doDeleteFolder(map[fi_id:121389289]) options=[]
2022/03/02 09:48:21 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:48:21 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 09:48:25 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
--- PASS: TestMoveEmptyDirectories (258.66s)
=== RUN   TestSyncEmptyDirectories
    run.go:181: Remote "filefabric root 'rclone-test-duzipet7zovasul4tijatet2'", Local "Local file system at /tmp/rclone3003306651", Modify Window "1s"
2022/03/02 09:48:25 DEBUG : sub dir2: Making directory
2022/03/02 09:48:25 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 09:48:25 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:48:25 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Waiting for checks to finish
2022/03/02 09:48:25 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Waiting for transfers to finish
2022/03/02 09:48:25 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 09:48:26 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:48:26 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doCreateNewFolder(map[fi_name:sub dir fi_pid:121389188]) options=[]
2022/03/02 09:48:29 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Sleeping for 1s to wait for "error_background" error to clear
2022/03/02 09:48:30 DEBUG : pacer: low level retry 1/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/02 09:48:30 DEBUG : pacer: Rate limited, increasing sleep to 40ms
2022/03/02 09:48:34 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Sleeping for 2s to wait for "error_background" error to clear
2022/03/02 09:48:36 DEBUG : pacer: low level retry 2/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/02 09:48:36 DEBUG : pacer: Rate limited, increasing sleep to 80ms
2022/03/02 09:48:38 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Sleeping for 4s to wait for "error_background" error to clear
2022/03/02 09:48:42 DEBUG : pacer: low level retry 3/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/02 09:48:42 DEBUG : pacer: Rate limited, increasing sleep to 160ms
2022/03/02 09:48:42 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Sleeping for 8s to wait for "error_background" error to clear
2022/03/02 09:48:50 DEBUG : pacer: low level retry 4/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/02 09:48:50 DEBUG : pacer: Rate limited, increasing sleep to 320ms
2022/03/02 09:48:51 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Sleeping for 16s to wait for "error_background" error to clear
2022/03/02 09:49:07 DEBUG : pacer: low level retry 5/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/02 09:49:07 DEBUG : pacer: Rate limited, increasing sleep to 640ms
2022/03/02 09:49:33 DEBUG : pacer: Reducing sleep to 480ms
2022/03/02 09:49:33 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:49:33 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doInitUpload(map[directuploadsupport:n fi_contenttype:application/octet-stream fi_filename:hello world fi_localtime:2001-02-03 04:05:06 fi_modified:2001-02-03 04:05:06 fi_name:hello world fi_pid:121389302 fi_size:11 responsetype:json]) options=[]
2022/03/02 09:49:38 DEBUG : pacer: Reducing sleep to 360ms
2022/03/02 09:49:38 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:49:40 DEBUG : pacer: Reducing sleep to 270ms
2022/03/02 09:49:40 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doCompleteUpload(map[fi_size:11 remotetime:2001-02-03 04:05:06 uploadcode:a323fc92485775bbd492447fd21418f6]) options=[]
2022/03/02 09:49:46 DEBUG : pacer: Reducing sleep to 202.5ms
2022/03/02 09:49:46 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:49:46 INFO  : sub dir/hello world: Copied (new)
2022/03/02 09:49:46 DEBUG : sub dir2: Making directory
2022/03/02 09:49:46 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 09:49:47 DEBUG : pacer: Reducing sleep to 151.875ms
2022/03/02 09:49:47 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:49:47 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doCreateNewFolder(map[fi_name:sub dir2 fi_pid:121389188]) options=[]
2022/03/02 09:49:50 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Sleeping for 1s to wait for "error_background" error to clear
2022/03/02 09:49:51 DEBUG : pacer: low level retry 1/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/02 09:49:51 DEBUG : pacer: Rate limited, increasing sleep to 303.75ms
2022/03/02 09:49:54 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Sleeping for 2s to wait for "error_background" error to clear
2022/03/02 09:49:56 DEBUG : pacer: low level retry 2/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/02 09:49:56 DEBUG : pacer: Rate limited, increasing sleep to 607.5ms
2022/03/02 09:49:59 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Sleeping for 4s to wait for "error_background" error to clear
2022/03/02 09:50:03 DEBUG : pacer: low level retry 3/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/02 09:50:03 DEBUG : pacer: Rate limited, increasing sleep to 1.215s
2022/03/02 09:50:05 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Sleeping for 8s to wait for "error_background" error to clear
2022/03/02 09:50:13 DEBUG : pacer: low level retry 4/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/02 09:50:13 DEBUG : pacer: Rate limited, increasing sleep to 2.43s
2022/03/02 09:50:13 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Sleeping for 16s to wait for "error_background" error to clear
2022/03/02 09:50:29 DEBUG : pacer: low level retry 5/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/02 09:50:29 DEBUG : pacer: Rate limited, increasing sleep to 4.86s
2022/03/02 09:50:55 DEBUG : pacer: Reducing sleep to 3.645s
2022/03/02 09:50:55 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:50:55 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': copied 1 directories
2022/03/02 09:50:55 DEBUG : Waiting for deletions to finish
2022/03/02 09:50:55 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 09:51:05 DEBUG : pacer: Reducing sleep to 2.73375s
2022/03/02 09:51:05 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:51:05 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389306 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 09:51:05 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389302 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 09:51:19 DEBUG : pacer: Reducing sleep to 2.0503125s
2022/03/02 09:51:19 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:51:23 DEBUG : pacer: Reducing sleep to 1.537734375s
2022/03/02 09:51:23 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:51:23 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 09:51:24 DEBUG : pacer: Reducing sleep to 1.153300781s
2022/03/02 09:51:24 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:51:24 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389306 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 09:51:24 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389302 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 09:51:25 DEBUG : pacer: Reducing sleep to 864.975585ms
2022/03/02 09:51:25 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:51:27 DEBUG : pacer: Reducing sleep to 648.731688ms
2022/03/02 09:51:27 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:51:27 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doDeleteFile(map[completedeletion:n fi_id:121389303]) options=[]
2022/03/02 09:52:31 DEBUG : pacer: Reducing sleep to 486.548766ms
2022/03/02 09:52:31 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:52:31 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389306 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 09:52:32 DEBUG : pacer: Reducing sleep to 364.911574ms
2022/03/02 09:52:32 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:52:32 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doDeleteFolder(map[fi_id:121389306]) options=[]
2022/03/02 09:52:49 DEBUG : pacer: Reducing sleep to 273.68368ms
2022/03/02 09:52:49 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:52:49 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389302 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 09:53:09 DEBUG : pacer: Reducing sleep to 205.26276ms
2022/03/02 09:53:09 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:53:09 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doDeleteFolder(map[fi_id:121389302]) options=[]
2022/03/02 09:53:30 DEBUG : pacer: Reducing sleep to 153.94707ms
2022/03/02 09:53:30 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:53:30 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 09:53:31 DEBUG : pacer: Reducing sleep to 115.460302ms
2022/03/02 09:53:31 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
--- PASS: TestSyncEmptyDirectories (306.12s)
=== RUN   TestServerSideCopy
    run.go:181: Remote "filefabric root 'rclone-test-duzipet7zovasul4tijatet2'", Local "Local file system at /tmp/rclone3003306651", Modify Window "1s"
2022/03/02 09:53:31 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 09:53:31 DEBUG : pacer: Reducing sleep to 86.595226ms
2022/03/02 09:53:31 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:53:31 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doCreateNewFolder(map[fi_name:sub dir fi_pid:121389188]) options=[]
2022/03/02 09:53:32 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Sleeping for 1s to wait for "error_background" error to clear
2022/03/02 09:53:33 DEBUG : pacer: low level retry 1/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/02 09:53:33 DEBUG : pacer: Rate limited, increasing sleep to 173.190452ms
2022/03/02 09:53:34 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Sleeping for 2s to wait for "error_background" error to clear
2022/03/02 09:53:36 DEBUG : pacer: low level retry 2/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/02 09:53:36 DEBUG : pacer: Rate limited, increasing sleep to 346.380904ms
2022/03/02 09:53:36 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Sleeping for 4s to wait for "error_background" error to clear
2022/03/02 09:53:41 DEBUG : pacer: low level retry 3/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/02 09:53:41 DEBUG : pacer: Rate limited, increasing sleep to 692.761808ms
2022/03/02 09:53:41 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Sleeping for 8s to wait for "error_background" error to clear
2022/03/02 09:53:49 DEBUG : pacer: low level retry 4/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/02 09:53:49 DEBUG : pacer: Rate limited, increasing sleep to 1.385523616s
2022/03/02 09:53:50 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Sleeping for 16s to wait for "error_background" error to clear
2022/03/02 09:54:06 DEBUG : pacer: low level retry 5/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/02 09:54:06 DEBUG : pacer: Rate limited, increasing sleep to 2.771047232s
2022/03/02 09:54:07 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Sleeping for 32s to wait for "error_background" error to clear
2022/03/02 09:54:39 DEBUG : pacer: low level retry 6/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/02 09:54:39 DEBUG : pacer: Rate limited, increasing sleep to 5.542094464s
2022/03/02 09:54:42 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Sleeping for 1m4s to wait for "error_background" error to clear
2022/03/02 09:55:46 DEBUG : pacer: low level retry 7/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/02 09:55:46 DEBUG : pacer: Rate limited, increasing sleep to 10s
2022/03/02 09:56:07 DEBUG : pacer: Reducing sleep to 7.5s
2022/03/02 09:56:07 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:56:07 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doInitUpload(map[directuploadsupport:n fi_contenttype:application/octet-stream fi_filename:hello world fi_localtime:2001-02-03 04:05:06 fi_modified:2001-02-03 04:05:06 fi_name:hello world fi_pid:121389319 fi_size:11 responsetype:json]) options=[]
2022/03/02 09:56:08 DEBUG : pacer: Reducing sleep to 5.625s
2022/03/02 09:56:08 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:56:16 DEBUG : pacer: Reducing sleep to 4.21875s
2022/03/02 09:56:16 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doCompleteUpload(map[fi_size:11 remotetime:2001-02-03 04:05:06 uploadcode:14e838e422e47ba350274da796e29b9b]) options=[]
2022/03/02 09:56:29 DEBUG : pacer: Reducing sleep to 3.1640625s
2022/03/02 09:56:29 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:56:29 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 09:56:39 DEBUG : pacer: Reducing sleep to 2.373046875s
2022/03/02 09:56:39 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:56:39 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389319 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 09:56:57 DEBUG : pacer: Reducing sleep to 1.779785156s
2022/03/02 09:56:57 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:56:57 DEBUG : Creating backend with remote "TestFileFabric:rclone-test-nocagel9witamim0hohuhis0"
2022/03/02 09:56:57 DEBUG : filefabric root 'rclone-test-nocagel9witamim0hohuhis0': rpc: checkPathExists(map[path:rclone-test-nocagel9witamim0hohuhis0 pid:120673762]) options=[]
2022/03/02 09:56:57 DEBUG : filefabric root 'rclone-test-nocagel9witamim0hohuhis0': >rpc: result=Success (ok), err=<nil>
    sync_test.go:275: Server side copy (if possible) filefabric root 'rclone-test-duzipet7zovasul4tijatet2' -> filefabric root 'rclone-test-nocagel9witamim0hohuhis0'
2022/03/02 09:56:57 DEBUG : filefabric root 'rclone-test-nocagel9witamim0hohuhis0': 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=[]
2022/03/02 09:56:57 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 09:56:58 DEBUG : filefabric root 'rclone-test-nocagel9witamim0hohuhis0': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:56:58 DEBUG : pacer: Reducing sleep to 1.334838867s
2022/03/02 09:56:58 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:56:58 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389319 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 09:57:00 DEBUG : pacer: Reducing sleep to 1.00112915s
2022/03/02 09:57:00 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:57:00 DEBUG : filefabric root 'rclone-test-nocagel9witamim0hohuhis0': Waiting for checks to finish
2022/03/02 09:57:00 DEBUG : filefabric root 'rclone-test-nocagel9witamim0hohuhis0': 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=[]
2022/03/02 09:57:00 DEBUG : filefabric root 'rclone-test-nocagel9witamim0hohuhis0': Waiting for transfers to finish
2022/03/02 09:57:00 DEBUG : filefabric root 'rclone-test-nocagel9witamim0hohuhis0': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:57:00 DEBUG : filefabric root 'rclone-test-nocagel9witamim0hohuhis0': rpc: doCreateNewFolder(map[fi_name:rclone-test-nocagel9witamim0hohuhis0 fi_pid:120673762]) options=[]
2022/03/02 09:57:20 DEBUG : filefabric root 'rclone-test-nocagel9witamim0hohuhis0': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:57:20 DEBUG : filefabric root 'rclone-test-nocagel9witamim0hohuhis0': rpc: getFolderContents(map[count:1000 fi_pid:121389324 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 09:57:36 DEBUG : filefabric root 'rclone-test-nocagel9witamim0hohuhis0': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:57:36 DEBUG : filefabric root 'rclone-test-nocagel9witamim0hohuhis0': rpc: doCreateNewFolder(map[fi_name:sub dir fi_pid:121389324]) options=[]
2022/03/02 09:57:56 DEBUG : filefabric root 'rclone-test-nocagel9witamim0hohuhis0': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:57:56 DEBUG : filefabric root 'rclone-test-nocagel9witamim0hohuhis0': rpc: doCopyFile(map[fi_id:121389321 fi_name:hello world fi_pid:121389326 force:y options:allownoextension]) options=[]
2022/03/02 09:58:06 DEBUG : filefabric root 'rclone-test-nocagel9witamim0hohuhis0': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:58:06 INFO  : sub dir/hello world: Copied (server-side copy)
2022/03/02 09:58:06 DEBUG : filefabric root 'rclone-test-nocagel9witamim0hohuhis0': rpc: getFolderContents(map[count:1000 fi_pid:121389324 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 09:58:19 DEBUG : filefabric root 'rclone-test-nocagel9witamim0hohuhis0': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:58:19 DEBUG : filefabric root 'rclone-test-nocagel9witamim0hohuhis0': rpc: getFolderContents(map[count:1000 fi_pid:121389326 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 09:58:38 DEBUG : filefabric root 'rclone-test-nocagel9witamim0hohuhis0': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:58:38 DEBUG : filefabric root 'rclone-test-nocagel9witamim0hohuhis0': Purge remote
2022/03/02 09:58:38 DEBUG : filefabric root 'rclone-test-nocagel9witamim0hohuhis0': rpc: doDeleteFolder(map[fi_id:121389324]) options=[]
2022/03/02 09:58:58 DEBUG : filefabric root 'rclone-test-nocagel9witamim0hohuhis0': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:58:58 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 09:58:59 DEBUG : pacer: Reducing sleep to 750.846862ms
2022/03/02 09:58:59 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:58:59 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389319 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 09:59:00 DEBUG : pacer: Reducing sleep to 563.135146ms
2022/03/02 09:59:00 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:59:00 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doDeleteFile(map[completedeletion:n fi_id:121389321]) options=[]
2022/03/02 09:59:44 DEBUG : pacer: Reducing sleep to 422.351359ms
2022/03/02 09:59:44 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:59:44 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389319 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 09:59:59 DEBUG : pacer: Reducing sleep to 316.763519ms
2022/03/02 09:59:59 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 09:59:59 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doDeleteFolder(map[fi_id:121389319]) options=[]
2022/03/02 10:00:22 DEBUG : pacer: Reducing sleep to 237.572639ms
2022/03/02 10:00:22 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:00:22 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:00:26 DEBUG : pacer: Reducing sleep to 178.179479ms
2022/03/02 10:00:26 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
--- PASS: TestServerSideCopy (415.47s)
=== RUN   TestCopyAfterDelete
    run.go:181: Remote "filefabric root 'rclone-test-duzipet7zovasul4tijatet2'", Local "Local file system at /tmp/rclone3003306651", Modify Window "1s"
2022/03/02 10:00:26 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:00:27 DEBUG : pacer: Reducing sleep to 133.634609ms
2022/03/02 10:00:27 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:00:27 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doCreateNewFolder(map[fi_name:sub dir fi_pid:121389188]) options=[]
2022/03/02 10:00:31 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Sleeping for 1s to wait for "error_background" error to clear
2022/03/02 10:00:32 DEBUG : pacer: low level retry 1/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/02 10:00:32 DEBUG : pacer: Rate limited, increasing sleep to 267.269218ms
2022/03/02 10:00:34 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Sleeping for 2s to wait for "error_background" error to clear
2022/03/02 10:00:36 DEBUG : pacer: low level retry 2/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/02 10:00:36 DEBUG : pacer: Rate limited, increasing sleep to 534.538436ms
2022/03/02 10:00:38 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Sleeping for 4s to wait for "error_background" error to clear
2022/03/02 10:00:42 DEBUG : pacer: low level retry 3/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/02 10:00:42 DEBUG : pacer: Rate limited, increasing sleep to 1.069076872s
2022/03/02 10:00:46 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Sleeping for 8s to wait for "error_background" error to clear
2022/03/02 10:00:54 DEBUG : pacer: low level retry 4/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/02 10:00:54 DEBUG : pacer: Rate limited, increasing sleep to 2.138153744s
2022/03/02 10:00:57 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Sleeping for 16s to wait for "error_background" error to clear
2022/03/02 10:01:13 DEBUG : pacer: low level retry 5/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/02 10:01:13 DEBUG : pacer: Rate limited, increasing sleep to 4.276307488s
2022/03/02 10:01:13 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Sleeping for 32s to wait for "error_background" error to clear
2022/03/02 10:01:45 DEBUG : pacer: low level retry 6/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/02 10:01:45 DEBUG : pacer: Rate limited, increasing sleep to 8.552614976s
2022/03/02 10:01:56 DEBUG : pacer: Reducing sleep to 6.414461232s
2022/03/02 10:01:56 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:01:56 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doInitUpload(map[directuploadsupport:n fi_contenttype:application/octet-stream fi_filename:hello world fi_localtime:2001-02-03 04:05:06 fi_modified:2001-02-03 04:05:06 fi_name:hello world fi_pid:121389341 fi_size:11 responsetype:json]) options=[]
2022/03/02 10:02:01 DEBUG : pacer: Reducing sleep to 4.810845924s
2022/03/02 10:02:01 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:02:04 DEBUG : pacer: Reducing sleep to 3.608134443s
2022/03/02 10:02:04 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doCompleteUpload(map[fi_size:11 remotetime:2001-02-03 04:05:06 uploadcode:18a308b6fa58fa2fd33b809acea2dfed]) options=[]
2022/03/02 10:02:19 DEBUG : pacer: Reducing sleep to 2.706100832s
2022/03/02 10:02:19 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:02:19 ERROR : : error listing: directory not found
2022/03/02 10:02:19 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:02:30 DEBUG : pacer: Reducing sleep to 2.029575624s
2022/03/02 10:02:30 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:02:30 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389341 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:02:49 DEBUG : pacer: Reducing sleep to 1.522181718s
2022/03/02 10:02:49 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:02:49 DEBUG : Local file system at /tmp/rclone3003306651: Making directory
2022/03/02 10:02:49 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:02:50 DEBUG : pacer: Reducing sleep to 1.141636288s
2022/03/02 10:02:50 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:02:50 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Waiting for checks to finish
2022/03/02 10:02:50 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Waiting for transfers to finish
2022/03/02 10:02:50 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:02:51 DEBUG : pacer: Reducing sleep to 856.227216ms
2022/03/02 10:02:51 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:02:51 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389341 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:02:52 DEBUG : pacer: Reducing sleep to 642.170412ms
2022/03/02 10:02:52 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:02:52 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:02:53 DEBUG : pacer: Reducing sleep to 481.627809ms
2022/03/02 10:02:53 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:02:53 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389341 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:02:54 DEBUG : pacer: Reducing sleep to 361.220856ms
2022/03/02 10:02:54 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:02:54 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doDeleteFile(map[completedeletion:n fi_id:121389343]) options=[]
2022/03/02 10:03:47 DEBUG : pacer: Reducing sleep to 270.915642ms
2022/03/02 10:03:47 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:03:47 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389341 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:03:59 DEBUG : pacer: Reducing sleep to 203.186731ms
2022/03/02 10:03:59 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:03:59 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doDeleteFolder(map[fi_id:121389341]) options=[]
2022/03/02 10:04:18 DEBUG : pacer: Reducing sleep to 152.390048ms
2022/03/02 10:04:18 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:04:18 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:04:22 DEBUG : pacer: Reducing sleep to 114.292536ms
2022/03/02 10:04:22 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
--- PASS: TestCopyAfterDelete (235.34s)
=== RUN   TestCopyRedownload
    run.go:181: Remote "filefabric root 'rclone-test-duzipet7zovasul4tijatet2'", Local "Local file system at /tmp/rclone3003306651", Modify Window "1s"
2022/03/02 10:04:22 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:04:22 DEBUG : pacer: Reducing sleep to 85.719402ms
2022/03/02 10:04:22 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:04:22 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doCreateNewFolder(map[fi_name:sub dir fi_pid:121389188]) options=[]
2022/03/02 10:04:25 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Sleeping for 1s to wait for "error_background" error to clear
2022/03/02 10:04:26 DEBUG : pacer: low level retry 1/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/02 10:04:26 DEBUG : pacer: Rate limited, increasing sleep to 171.438804ms
2022/03/02 10:04:29 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Sleeping for 2s to wait for "error_background" error to clear
2022/03/02 10:04:31 DEBUG : pacer: low level retry 2/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/02 10:04:31 DEBUG : pacer: Rate limited, increasing sleep to 342.877608ms
2022/03/02 10:04:32 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Sleeping for 4s to wait for "error_background" error to clear
2022/03/02 10:04:36 DEBUG : pacer: low level retry 3/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/02 10:04:36 DEBUG : pacer: Rate limited, increasing sleep to 685.755216ms
2022/03/02 10:04:40 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Sleeping for 8s to wait for "error_background" error to clear
2022/03/02 10:04:48 DEBUG : pacer: low level retry 4/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/02 10:04:48 DEBUG : pacer: Rate limited, increasing sleep to 1.371510432s
2022/03/02 10:04:48 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Sleeping for 16s to wait for "error_background" error to clear
2022/03/02 10:05:04 DEBUG : pacer: low level retry 5/10 (error Can not create folder now. We are not able to complete the requested operation with such name. We are processing delete in that folder. Please try again later or use another name. (error_background))
2022/03/02 10:05:04 DEBUG : pacer: Rate limited, increasing sleep to 2.743020864s
2022/03/02 10:05:17 DEBUG : pacer: Reducing sleep to 2.057265648s
2022/03/02 10:05:17 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:05:17 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doInitUpload(map[directuploadsupport:n fi_contenttype:application/octet-stream fi_filename:hello world fi_localtime:2001-02-03 04:05:06 fi_modified:2001-02-03 04:05:06 fi_name:hello world fi_pid:121389346 fi_size:11 responsetype:json]) options=[]
2022/03/02 10:05:18 DEBUG : pacer: Reducing sleep to 1.542949236s
2022/03/02 10:05:18 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:05:21 DEBUG : pacer: Reducing sleep to 1.157211927s
2022/03/02 10:05:21 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doCompleteUpload(map[fi_size:11 remotetime:2001-02-03 04:05:06 uploadcode:a96ee3c30e89f3e13bc80c4d70448c48]) options=[]
2022/03/02 10:05:33 DEBUG : pacer: Reducing sleep to 867.908945ms
2022/03/02 10:05:33 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:05:33 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:05:44 DEBUG : pacer: Reducing sleep to 650.931708ms
2022/03/02 10:05:44 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:05:44 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389346 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:05:55 DEBUG : pacer: Reducing sleep to 488.198781ms
2022/03/02 10:05:55 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:05:55 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:06:10 DEBUG : pacer: Reducing sleep to 366.149085ms
2022/03/02 10:06:10 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:06:10 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389346 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:06:11 DEBUG : pacer: Reducing sleep to 274.611813ms
2022/03/02 10:06:11 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:06:11 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFile(map[fi_id:121389348]) options=[HashesOption([])]
2022/03/02 10:06:11 DEBUG : Local file system at /tmp/rclone3003306651: Waiting for checks to finish
2022/03/02 10:06:11 DEBUG : Local file system at /tmp/rclone3003306651: Waiting for transfers to finish
2022/03/02 10:06:14 DEBUG : pacer: Reducing sleep to 205.958859ms
2022/03/02 10:06:14 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=<nil>, err=<nil>
2022/03/02 10:06:14 INFO  : sub dir/hello world: Copied (new)
2022/03/02 10:06:14 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:06:14 DEBUG : pacer: Reducing sleep to 154.469144ms
2022/03/02 10:06:14 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:06:14 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389346 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:06:15 DEBUG : pacer: Reducing sleep to 115.851858ms
2022/03/02 10:06:15 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:06:15 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doDeleteFile(map[completedeletion:n fi_id:121389348]) options=[]
2022/03/02 10:06:54 DEBUG : pacer: Reducing sleep to 86.888893ms
2022/03/02 10:06:54 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:06:54 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389346 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:07:06 DEBUG : pacer: Reducing sleep to 65.166669ms
2022/03/02 10:07:06 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:07:06 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doDeleteFolder(map[fi_id:121389346]) options=[]
2022/03/02 10:07:25 DEBUG : pacer: Reducing sleep to 48.875001ms
2022/03/02 10:07:25 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:07:25 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:07:30 DEBUG : pacer: Reducing sleep to 36.65625ms
2022/03/02 10:07:30 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
--- PASS: TestCopyRedownload (188.01s)
=== RUN   TestSyncBasedOnCheckSum
    run.go:181: Remote "filefabric root 'rclone-test-duzipet7zovasul4tijatet2'", Local "Local file system at /tmp/rclone3003306651", Modify Window "1s"
2022/03/02 10:07:30 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:07:30 DEBUG : pacer: Reducing sleep to 27.492187ms
2022/03/02 10:07:30 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:07:30 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Waiting for checks to finish
2022/03/02 10:07:30 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Waiting for transfers to finish
2022/03/02 10:07:30 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doInitUpload(map[directuploadsupport:n fi_contenttype:application/octet-stream fi_filename:check sum fi_localtime:2001-02-03 04:05:06 fi_modified:2001-02-03 04:05:06 fi_name:check sum fi_pid:121389188 fi_size:1 responsetype:json]) options=[]
2022/03/02 10:07:34 DEBUG : pacer: Reducing sleep to 20.61914ms
2022/03/02 10:07:34 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:07:36 DEBUG : pacer: Reducing sleep to 20ms
2022/03/02 10:07:36 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doCompleteUpload(map[fi_size:1 remotetime:2001-02-03 04:05:06 uploadcode:813b2377b9be9df0dca39c0cc6e8c0be]) options=[]
2022/03/02 10:07:41 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:07:41 INFO  : check sum: Copied (new)
2022/03/02 10:07:41 DEBUG : Waiting for deletions to finish
2022/03/02 10:07:41 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:07:45 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:07:45 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:07:46 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:07:46 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Waiting for checks to finish
2022/03/02 10:07:46 NOTICE: filefabric root 'rclone-test-duzipet7zovasul4tijatet2': --checksum is in use but the source and destination have no hashes in common; falling back to --size-only
2022/03/02 10:07:46 DEBUG : check sum: Size of src and dst objects identical
2022/03/02 10:07:46 DEBUG : check sum: Unchanged skipping
2022/03/02 10:07:46 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Waiting for transfers to finish
2022/03/02 10:07:46 DEBUG : Waiting for deletions to finish
2022/03/02 10:07:46 INFO  : There was nothing to transfer
2022/03/02 10:07:46 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:07:46 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:07:46 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:07:47 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:07:47 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doDeleteFile(map[completedeletion:n fi_id:121389355]) options=[]
2022/03/02 10:08:24 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:08:24 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:08:32 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
--- PASS: TestSyncBasedOnCheckSum (62.73s)
=== RUN   TestSyncSizeOnly
    run.go:181: Remote "filefabric root 'rclone-test-duzipet7zovasul4tijatet2'", Local "Local file system at /tmp/rclone3003306651", Modify Window "1s"
2022/03/02 10:08:32 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:08:33 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:08:33 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Waiting for checks to finish
2022/03/02 10:08:33 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doInitUpload(map[directuploadsupport:n fi_contenttype:application/octet-stream fi_filename:sizeonly fi_localtime:2001-02-03 04:05:06 fi_modified:2001-02-03 04:05:06 fi_name:sizeonly fi_pid:121389188 fi_size:6 responsetype:json]) options=[]
2022/03/02 10:08:33 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Waiting for transfers to finish
2022/03/02 10:08:34 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:08:36 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doCompleteUpload(map[fi_size:6 remotetime:2001-02-03 04:05:06 uploadcode:551d21cc2e3d5af0fbeacf57960d0324]) options=[]
2022/03/02 10:08:48 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:08:48 INFO  : sizeonly: Copied (new)
2022/03/02 10:08:48 DEBUG : Waiting for deletions to finish
2022/03/02 10:08:48 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:09:11 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:09:11 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:09:11 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:09:11 DEBUG : sizeonly: Sizes identical
2022/03/02 10:09:11 DEBUG : sizeonly: Unchanged skipping
2022/03/02 10:09:11 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Waiting for checks to finish
2022/03/02 10:09:11 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Waiting for transfers to finish
2022/03/02 10:09:11 DEBUG : Waiting for deletions to finish
2022/03/02 10:09:11 INFO  : There was nothing to transfer
2022/03/02 10:09:11 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:09:12 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:09:12 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:09:13 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:09:13 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doDeleteFile(map[completedeletion:n fi_id:121389359]) options=[]
2022/03/02 10:09:45 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:09:45 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:09:53 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
--- PASS: TestSyncSizeOnly (80.95s)
=== RUN   TestSyncIgnoreSize
    run.go:181: Remote "filefabric root 'rclone-test-duzipet7zovasul4tijatet2'", Local "Local file system at /tmp/rclone3003306651", Modify Window "1s"
2022/03/02 10:09:53 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:09:54 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:09:54 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Waiting for checks to finish
2022/03/02 10:09:54 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Waiting for transfers to finish
2022/03/02 10:09:54 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doInitUpload(map[directuploadsupport:n fi_contenttype:application/octet-stream fi_filename:ignore-size fi_localtime:2001-02-03 04:05:06 fi_modified:2001-02-03 04:05:06 fi_name:ignore-size fi_pid:121389188 fi_size:8 responsetype:json]) options=[]
2022/03/02 10:09:55 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:09:57 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doCompleteUpload(map[fi_size:8 remotetime:2001-02-03 04:05:06 uploadcode:a5e4dac712f236f681066d8b01bddc44]) options=[]
2022/03/02 10:10:03 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:10:03 INFO  : ignore-size: Copied (new)
2022/03/02 10:10:03 DEBUG : Waiting for deletions to finish
2022/03/02 10:10:03 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:10:25 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:10:25 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:10:26 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:10:26 DEBUG : ignore-size: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2022/03/02 10:10:26 DEBUG : ignore-size: Unchanged skipping
2022/03/02 10:10:26 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Waiting for checks to finish
2022/03/02 10:10:26 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Waiting for transfers to finish
2022/03/02 10:10:26 DEBUG : Waiting for deletions to finish
2022/03/02 10:10:26 INFO  : There was nothing to transfer
2022/03/02 10:10:26 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:10:26 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:10:26 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:10:27 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:10:27 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doDeleteFile(map[completedeletion:n fi_id:121389360]) options=[]
2022/03/02 10:10:53 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:10:53 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:11:05 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
--- PASS: TestSyncIgnoreSize (71.41s)
=== RUN   TestSyncIgnoreTimes
    run.go:181: Remote "filefabric root 'rclone-test-duzipet7zovasul4tijatet2'", Local "Local file system at /tmp/rclone3003306651", Modify Window "1s"
2022/03/02 10:11:05 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doInitUpload(map[directuploadsupport:n fi_contenttype:application/octet-stream fi_filename:existing fi_localtime:2001-02-03 04:05:06 fi_modified:2001-02-03 04:05:06 fi_name:existing fi_pid:121389188 fi_size:6 responsetype:json]) options=[]
2022/03/02 10:11:10 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:11:11 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doCompleteUpload(map[fi_size:6 remotetime:2001-02-03 04:05:06 uploadcode:f298620e978c844090318ac2e0dc09b3]) options=[]
2022/03/02 10:11:16 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:11:16 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:11:35 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:11:35 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:11:36 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:11:36 DEBUG : existing: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2022/03/02 10:11:36 DEBUG : existing: Unchanged skipping
2022/03/02 10:11:36 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Waiting for checks to finish
2022/03/02 10:11:36 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Waiting for transfers to finish
2022/03/02 10:11:36 DEBUG : Waiting for deletions to finish
2022/03/02 10:11:36 INFO  : There was nothing to transfer
2022/03/02 10:11:36 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:11:36 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:11:36 DEBUG : existing: Transferring unconditionally as --ignore-times is in use
2022/03/02 10:11:36 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Waiting for checks to finish
2022/03/02 10:11:36 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Waiting for transfers to finish
2022/03/02 10:11:36 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doInitUpload(map[directuploadsupport:n fi_contenttype:application/octet-stream fi_filename:existing fi_localtime:2001-02-03 04:05:06 fi_modified:2001-02-03 04:05:06 fi_name:existing fi_pid:121389188 fi_size:6 responsetype:json]) options=[]
2022/03/02 10:11:40 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:11:42 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doCompleteUpload(map[fi_size:6 remotetime:2001-02-03 04:05:06 uploadcode:4bbcd6ddba6168f5e709e19a674dd406]) options=[]
2022/03/02 10:13:09 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:13:09 INFO  : existing: Copied (replaced existing)
2022/03/02 10:13:09 DEBUG : Waiting for deletions to finish
2022/03/02 10:13:09 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:13:24 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:13:24 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:13:25 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:13:25 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doDeleteFile(map[completedeletion:n fi_id:121389365]) options=[]
2022/03/02 10:14:06 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:14:06 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:14:15 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
--- PASS: TestSyncIgnoreTimes (190.12s)
=== RUN   TestSyncIgnoreExisting
    run.go:181: Remote "filefabric root 'rclone-test-duzipet7zovasul4tijatet2'", Local "Local file system at /tmp/rclone3003306651", Modify Window "1s"
2022/03/02 10:14:15 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:14:15 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:14:15 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Waiting for checks to finish
2022/03/02 10:14:15 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Waiting for transfers to finish
2022/03/02 10:14:15 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doInitUpload(map[directuploadsupport:n fi_contenttype:application/octet-stream fi_filename:existing fi_localtime:2001-02-03 04:05:06 fi_modified:2001-02-03 04:05:06 fi_name:existing fi_pid:121389188 fi_size:6 responsetype:json]) options=[]
2022/03/02 10:14:20 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:14:21 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doCompleteUpload(map[fi_size:6 remotetime:2001-02-03 04:05:06 uploadcode:ebba83d5fcd90e73126206c531e847de]) options=[]
2022/03/02 10:14:31 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:14:31 INFO  : existing: Copied (new)
2022/03/02 10:14:31 DEBUG : Waiting for deletions to finish
2022/03/02 10:14:31 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:14:43 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:14:43 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:14:44 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:14:44 DEBUG : existing: Destination exists, skipping
2022/03/02 10:14:44 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Waiting for checks to finish
2022/03/02 10:14:44 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Waiting for transfers to finish
2022/03/02 10:14:44 DEBUG : Waiting for deletions to finish
2022/03/02 10:14:44 INFO  : There was nothing to transfer
2022/03/02 10:14:44 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:14:44 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:14:44 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:14:45 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:14:45 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doDeleteFile(map[completedeletion:n fi_id:121389375]) options=[]
2022/03/02 10:15:38 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:15:38 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:15:53 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
--- PASS: TestSyncIgnoreExisting (98.13s)
=== RUN   TestSyncIgnoreErrors
    run.go:181: Remote "filefabric root 'rclone-test-duzipet7zovasul4tijatet2'", Local "Local file system at /tmp/rclone3003306651", Modify Window "1s"
2022/03/02 10:15:53 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:15:54 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:15:54 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doCreateNewFolder(map[fi_name:b fi_pid:121389188]) options=[]
2022/03/02 10:16:16 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:16:16 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doInitUpload(map[directuploadsupport:n fi_contenttype:application/octet-stream fi_filename:potato fi_localtime:2011-12-25 12:59:59 fi_modified:2011-12-25 12:59:59 fi_name:potato fi_pid:121389388 fi_size:21 responsetype:json]) options=[]
2022/03/02 10:16:20 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:16:22 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doCompleteUpload(map[fi_size:21 remotetime:2011-12-25 12:59:59 uploadcode:bc9fb5c47e67a5350f6dfc0743215114]) options=[]
2022/03/02 10:16:27 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:16:27 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:16:35 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:16:35 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doCreateNewFolder(map[fi_name:c fi_pid:121389188]) options=[]
2022/03/02 10:16:50 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:16:50 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doInitUpload(map[directuploadsupport:n fi_contenttype:application/octet-stream fi_filename:non empty space fi_localtime:2011-12-25 12:59:59 fi_modified:2011-12-25 12:59:59 fi_name:non empty space fi_pid:121389393 fi_size:5 responsetype:json]) options=[]
2022/03/02 10:16:52 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:16:53 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doCompleteUpload(map[fi_size:5 remotetime:2011-12-25 12:59:59 uploadcode:67bd495b198f4b83fc25b473ef91cedd]) options=[]
2022/03/02 10:17:06 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:17:06 DEBUG : d: Making directory
2022/03/02 10:17:06 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:17:15 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:17:15 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doCreateNewFolder(map[fi_name:d fi_pid:121389188]) options=[]
2022/03/02 10:17:31 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:17:31 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:17:42 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:17:42 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389393 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:17:42 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389399 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:17:42 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389388 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:17:57 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:17:57 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:17:57 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:17:57 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:17:58 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:17:58 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389388 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:17:58 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:17:59 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:17:59 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:17:59 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doCreateNewFolder(map[fi_name:a fi_pid:121389188]) options=[]
2022/03/02 10:18:10 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:18:10 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doInitUpload(map[directuploadsupport:n fi_contenttype:application/octet-stream fi_filename:potato2 fi_localtime:2001-02-03 04:05:06 fi_modified:2001-02-03 04:05:06 fi_name:potato2 fi_pid:121389404 fi_size:60 responsetype:json]) options=[]
2022/03/02 10:18:10 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389399 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:18:10 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389393 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:18:11 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:18:11 DEBUG : c/non empty space: Size and modification time the same (differ by -123.456789ms, within tolerance 1s)
2022/03/02 10:18:11 DEBUG : c/non empty space: Unchanged skipping
2022/03/02 10:18:11 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:18:11 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Waiting for checks to finish
2022/03/02 10:18:11 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Waiting for transfers to finish
2022/03/02 10:18:12 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:18:13 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doCompleteUpload(map[fi_size:60 remotetime:2001-02-03 04:05:06 uploadcode:28dfd325d28b2f36aa67e52350656272]) options=[]
2022/03/02 10:18:25 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:18:25 INFO  : a/potato2: Copied (new)
2022/03/02 10:18:25 DEBUG : Waiting for deletions to finish
2022/03/02 10:18:25 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doDeleteFile(map[completedeletion:n fi_id:121389391]) options=[]
2022/03/02 10:19:22 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:19:22 INFO  : b/potato: Deleted
2022/03/02 10:19:22 INFO  : d: Removing directory
2022/03/02 10:19:22 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389399 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:19:23 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:19:23 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doDeleteFolder(map[fi_id:121389399]) options=[]
2022/03/02 10:19:37 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:19:37 INFO  : b: Removing directory
2022/03/02 10:19:37 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389388 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:20:00 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:20:00 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doDeleteFolder(map[fi_id:121389388]) options=[]
2022/03/02 10:20:16 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:20:16 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': deleted 2 directories
2022/03/02 10:20:16 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:20:20 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:20:20 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389393 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:20:20 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389404 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:20:20 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:20:32 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:20:32 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:20:33 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:20:33 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389393 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:20:33 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389404 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:20:33 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:20:33 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doDeleteFile(map[completedeletion:n fi_id:121389394]) options=[]
2022/03/02 10:20:33 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:21:18 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:21:18 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doDeleteFile(map[completedeletion:n fi_id:121389405]) options=[]
2022/03/02 10:22:19 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:22:19 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389393 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:22:28 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:22:28 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doDeleteFolder(map[fi_id:121389393]) options=[]
2022/03/02 10:22:43 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:22:43 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389404 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:22:55 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:22:55 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doDeleteFolder(map[fi_id:121389404]) options=[]
2022/03/02 10:23:10 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:23:10 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:23:11 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
--- PASS: TestSyncIgnoreErrors (438.25s)
=== RUN   TestSyncAfterChangingModtimeOnly
    run.go:181: Remote "filefabric root 'rclone-test-duzipet7zovasul4tijatet2'", Local "Local file system at /tmp/rclone3003306651", Modify Window "1s"
2022/03/02 10:23:11 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doInitUpload(map[directuploadsupport:n fi_contenttype:application/octet-stream fi_filename:empty space fi_localtime:2001-02-03 04:05:06 fi_modified:2001-02-03 04:05:06 fi_name:empty space fi_pid:121389188 fi_size:1 responsetype:json]) options=[]
2022/03/02 10:23:13 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:23:14 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doCompleteUpload(map[fi_size:1 remotetime:2001-02-03 04:05:06 uploadcode:4abdd3d1828b827509e8237c781636cf]) options=[]
2022/03/02 10:23:19 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:23:19 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:23:20 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:23:20 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:23:20 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:23:20 DEBUG : empty space: Modification times differ by -95456h54m53.123456789s: 2011-12-25 12:59:59.123456789 +0000 UTC, 2001-02-03 04:05:06 +0000 UTC
2022/03/02 10:23:20 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Waiting for checks to finish
2022/03/02 10:23:20 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Waiting for transfers to finish
2022/03/02 10:23:20 NOTICE: empty space: Skipped copy as --dry-run is set (size 1)
2022/03/02 10:23:20 DEBUG : Waiting for deletions to finish
2022/03/02 10:23:20 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:23:21 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:23:21 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:23:21 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:23:21 DEBUG : empty space: Modification times differ by -95456h54m53.123456789s: 2011-12-25 12:59:59.123456789 +0000 UTC, 2001-02-03 04:05:06 +0000 UTC
2022/03/02 10:23:21 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Waiting for checks to finish
2022/03/02 10:23:21 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Waiting for transfers to finish
2022/03/02 10:23:21 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doInitUpload(map[directuploadsupport:n fi_contenttype:application/octet-stream fi_filename:empty space fi_localtime:2011-12-25 12:59:59 fi_modified:2011-12-25 12:59:59 fi_name:empty space fi_pid:121389188 fi_size:1 responsetype:json]) options=[]
2022/03/02 10:23:24 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:23:25 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doCompleteUpload(map[fi_size:1 remotetime:2011-12-25 12:59:59 uploadcode:f68e7e05f7679a2fc889fe4e2aecae67]) options=[]
2022/03/02 10:24:51 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:24:51 INFO  : empty space: Copied (replaced existing)
2022/03/02 10:24:51 DEBUG : Waiting for deletions to finish
2022/03/02 10:24:51 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:24:52 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:24:52 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:24:53 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:24:53 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doDeleteFile(map[completedeletion:n fi_id:121389422]) options=[]
2022/03/02 10:25:19 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:25:19 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:25:20 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
--- PASS: TestSyncAfterChangingModtimeOnly (128.87s)
=== RUN   TestSyncAfterChangingModtimeOnlyWithNoUpdateModTime
    run.go:181: Remote "filefabric root 'rclone-test-duzipet7zovasul4tijatet2'", Local "Local file system at /tmp/rclone3003306651", Modify Window "1s"
    sync_test.go:577: Can't check this if no hashes supported
2022/03/02 10:25:20 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:25:21 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:25:21 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:25:21 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
--- PASS: TestSyncAfterChangingModtimeOnlyWithNoUpdateModTime (1.14s)
=== RUN   TestSyncDoesntUpdateModtime
    run.go:181: Remote "filefabric root 'rclone-test-duzipet7zovasul4tijatet2'", Local "Local file system at /tmp/rclone3003306651", Modify Window "1s"
2022/03/02 10:25:21 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doInitUpload(map[directuploadsupport:n fi_contenttype:application/octet-stream fi_filename:foo fi_localtime:2001-02-03 04:05:06 fi_modified:2001-02-03 04:05:06 fi_name:foo fi_pid:121389188 fi_size:3 responsetype:json]) options=[]
2022/03/02 10:25:23 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:25:24 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doCompleteUpload(map[fi_size:3 remotetime:2001-02-03 04:05:06 uploadcode:63a773cf7456835e7d33036e8523a9e8]) options=[]
2022/03/02 10:25:33 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:25:33 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:25:36 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:25:36 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:25:37 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:25:37 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Waiting for checks to finish
2022/03/02 10:25:37 DEBUG : foo: Modification times differ by -95456h54m53.123456789s: 2011-12-25 12:59:59.123456789 +0000 UTC, 2001-02-03 04:05:06 +0000 UTC
2022/03/02 10:25:37 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Waiting for transfers to finish
2022/03/02 10:25:37 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doInitUpload(map[directuploadsupport:n fi_contenttype:application/octet-stream fi_filename:foo fi_localtime:2011-12-25 12:59:59 fi_modified:2011-12-25 12:59:59 fi_name:foo fi_pid:121389188 fi_size:3 responsetype:json]) options=[]
2022/03/02 10:25:42 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:25:43 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doCompleteUpload(map[fi_size:3 remotetime:2011-12-25 12:59:59 uploadcode:16ee3ad6486a5c21ce723ec2e75ec0cf]) options=[]
2022/03/02 10:26:46 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:26:46 INFO  : foo: Copied (replaced existing)
2022/03/02 10:26:46 DEBUG : Waiting for deletions to finish
2022/03/02 10:26:46 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:26:46 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Token expired - refreshing
2022/03/02 10:26:46 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getTokenByAuthToken(map[authtoken:622506e6346e7ad6-c48bf9558d23a2ae token:*]) options=[]
2022/03/02 10:26:47 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:26:47 DEBUG : Saving config "token" in section "TestFileFabric" of the config file
2022/03/02 10:26:47 DEBUG : Config file has changed externaly - reloading
2022/03/02 10:26:47 DEBUG : Saving config "token_expiry" in section "TestFileFabric" of the config file
2022/03/02 10:26:47 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getApplianceInfo(map[token:*]) options=[]
2022/03/02 10:26:47 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:26:47 DEBUG : Saving config "version" in section "TestFileFabric" of the config file
2022/03/02 10:27:02 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:27:02 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:27:03 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:27:03 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doDeleteFile(map[completedeletion:n fi_id:121389427]) options=[]
2022/03/02 10:27:27 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:27:27 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:27:36 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
--- PASS: TestSyncDoesntUpdateModtime (134.76s)
=== RUN   TestSyncAfterAddingAFile
    run.go:181: Remote "filefabric root 'rclone-test-duzipet7zovasul4tijatet2'", Local "Local file system at /tmp/rclone3003306651", Modify Window "1s"
2022/03/02 10:27:36 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doInitUpload(map[directuploadsupport:n fi_contenttype:application/octet-stream fi_filename:empty space fi_localtime:2011-12-25 12:59:59 fi_modified:2011-12-25 12:59:59 fi_name:empty space fi_pid:121389188 fi_size:1 responsetype:json]) options=[]
2022/03/02 10:27:41 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:27:42 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doCompleteUpload(map[fi_size:1 remotetime:2011-12-25 12:59:59 uploadcode:181aa8fcccb5915ec1cab376089692c1]) options=[]
2022/03/02 10:27:55 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:27:55 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:28:07 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:28:07 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:28:08 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:28:08 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Waiting for checks to finish
2022/03/02 10:28:08 DEBUG : empty space: Size and modification time the same (differ by -123.456789ms, within tolerance 1s)
2022/03/02 10:28:08 DEBUG : empty space: Unchanged skipping
2022/03/02 10:28:08 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Waiting for transfers to finish
2022/03/02 10:28:08 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doInitUpload(map[directuploadsupport:n fi_contenttype:application/octet-stream fi_filename:potato fi_localtime:2011-12-30 12:59:59 fi_modified:2011-12-30 12:59:59 fi_name:potato fi_pid:121389188 fi_size:60 responsetype:json]) options=[]
2022/03/02 10:28:12 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:28:14 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doCompleteUpload(map[fi_size:60 remotetime:2011-12-30 12:59:59 uploadcode:35dc1927309d1332e17fb6bb8eecf9f5]) options=[]
2022/03/02 10:28:19 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:28:19 INFO  : potato: Copied (new)
2022/03/02 10:28:19 DEBUG : Waiting for deletions to finish
2022/03/02 10:28:19 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:28:31 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:28:31 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:28:31 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:28:31 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doDeleteFile(map[completedeletion:n fi_id:121389433]) options=[]
2022/03/02 10:29:21 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:29:21 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doDeleteFile(map[completedeletion:n fi_id:121389435]) options=[]
2022/03/02 10:29:45 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:29:45 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:29:57 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
--- PASS: TestSyncAfterAddingAFile (141.21s)
=== RUN   TestSyncAfterChangingFilesSizeOnly
    run.go:181: Remote "filefabric root 'rclone-test-duzipet7zovasul4tijatet2'", Local "Local file system at /tmp/rclone3003306651", Modify Window "1s"
2022/03/02 10:29:57 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doInitUpload(map[directuploadsupport:n fi_contenttype:application/octet-stream fi_filename:potato fi_localtime:2011-12-30 12:59:59 fi_modified:2011-12-30 12:59:59 fi_name:potato fi_pid:121389188 fi_size:60 responsetype:json]) options=[]
2022/03/02 10:29:59 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:30:00 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doCompleteUpload(map[fi_size:60 remotetime:2011-12-30 12:59:59 uploadcode:1bec60de101fb5876a64a5c9c7d53fd5]) options=[]
2022/03/02 10:30:10 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:30:10 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:30:18 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:30:18 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:30:19 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:30:19 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Waiting for checks to finish
2022/03/02 10:30:19 DEBUG : potato: Sizes differ (src 21 vs dst 60)
2022/03/02 10:30:19 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Waiting for transfers to finish
2022/03/02 10:30:19 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doInitUpload(map[directuploadsupport:n fi_contenttype:application/octet-stream fi_filename:potato fi_localtime:2011-12-30 12:59:59 fi_modified:2011-12-30 12:59:59 fi_name:potato fi_pid:121389188 fi_size:21 responsetype:json]) options=[]
2022/03/02 10:30:23 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:30:25 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doCompleteUpload(map[fi_size:21 remotetime:2011-12-30 12:59:59 uploadcode:6678a71fa932fe43dc9080140a3a7106]) options=[]
2022/03/02 10:31:45 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:31:45 INFO  : potato: Copied (replaced existing)
2022/03/02 10:31:45 DEBUG : Waiting for deletions to finish
2022/03/02 10:31:45 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:31:56 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:31:56 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:31:57 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:31:57 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doDeleteFile(map[completedeletion:n fi_id:121389441]) options=[]
2022/03/02 10:32:40 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:32:40 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:32:52 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
--- PASS: TestSyncAfterChangingFilesSizeOnly (174.87s)
=== RUN   TestSyncAfterChangingContentsOnly
    run.go:181: Remote "filefabric root 'rclone-test-duzipet7zovasul4tijatet2'", Local "Local file system at /tmp/rclone3003306651", Modify Window "1s"
2022/03/02 10:32:52 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doInitUpload(map[directuploadsupport:n fi_contenttype:application/octet-stream fi_filename:potato fi_localtime:2011-12-30 12:59:59 fi_modified:2011-12-30 12:59:59 fi_name:potato fi_pid:121389188 fi_size:21 responsetype:json]) options=[]
2022/03/02 10:32:57 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:32:58 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doCompleteUpload(map[fi_size:21 remotetime:2011-12-30 12:59:59 uploadcode:78ed41e33d67cf04c39e08e39dafd9fd]) options=[]
2022/03/02 10:33:07 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:33:07 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:33:19 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:33:19 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:33:19 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:33:19 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Waiting for checks to finish
2022/03/02 10:33:19 DEBUG : potato: Modification times differ by 119h59m59.876543211s: 2011-12-25 12:59:59.123456789 +0000 UTC, 2011-12-30 12:59:59 +0000 UTC
2022/03/02 10:33:19 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Waiting for transfers to finish
2022/03/02 10:33:19 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doInitUpload(map[directuploadsupport:n fi_contenttype:application/octet-stream fi_filename:potato fi_localtime:2011-12-25 12:59:59 fi_modified:2011-12-25 12:59:59 fi_name:potato fi_pid:121389188 fi_size:21 responsetype:json]) options=[]
2022/03/02 10:33:23 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:33:25 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doCompleteUpload(map[fi_size:21 remotetime:2011-12-25 12:59:59 uploadcode:718c76ec9642c42468aa34d1d662c4c5]) options=[]
2022/03/02 10:34:52 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:34:52 INFO  : potato: Copied (replaced existing)
2022/03/02 10:34:52 DEBUG : Waiting for deletions to finish
2022/03/02 10:34:52 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:35:00 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:35:00 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:35:00 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:35:00 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doDeleteFile(map[completedeletion:n fi_id:121389451]) options=[]
2022/03/02 10:35:52 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:35:52 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:36:04 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
--- PASS: TestSyncAfterChangingContentsOnly (191.77s)
=== RUN   TestSyncAfterRemovingAFileAndAddingAFileDryRun
    run.go:181: Remote "filefabric root 'rclone-test-duzipet7zovasul4tijatet2'", Local "Local file system at /tmp/rclone3003306651", Modify Window "1s"
2022/03/02 10:36:04 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doInitUpload(map[directuploadsupport:n fi_contenttype:application/octet-stream fi_filename:potato fi_localtime:2011-12-25 12:59:59 fi_modified:2011-12-25 12:59:59 fi_name:potato fi_pid:121389188 fi_size:21 responsetype:json]) options=[]
2022/03/02 10:36:05 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:36:07 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doCompleteUpload(map[fi_size:21 remotetime:2011-12-25 12:59:59 uploadcode:9fa183830f925174c0ae7f8aa4cf1885]) options=[]
2022/03/02 10:36:12 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:36:12 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doInitUpload(map[directuploadsupport:n fi_contenttype:application/octet-stream fi_filename:empty space fi_localtime:2011-12-25 12:59:59 fi_modified:2011-12-25 12:59:59 fi_name:empty space fi_pid:121389188 fi_size:1 responsetype:json]) options=[]
2022/03/02 10:36:14 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:36:15 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doCompleteUpload(map[fi_size:1 remotetime:2011-12-25 12:59:59 uploadcode:fccfc97b21ae039c2e64ec4cd7e53226]) options=[]
2022/03/02 10:36:20 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:36:20 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:36:32 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:36:32 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Waiting for checks to finish
2022/03/02 10:36:32 DEBUG : empty space: Size and modification time the same (differ by -123.456789ms, within tolerance 1s)
2022/03/02 10:36:32 DEBUG : empty space: Unchanged skipping
2022/03/02 10:36:32 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Waiting for transfers to finish
2022/03/02 10:36:32 NOTICE: potato2: Skipped copy as --dry-run is set (size 60)
2022/03/02 10:36:32 DEBUG : Waiting for deletions to finish
2022/03/02 10:36:32 NOTICE: potato: Skipped delete as --dry-run is set (size 21)
2022/03/02 10:36:32 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:36:33 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:36:33 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:36:33 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:36:33 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doDeleteFile(map[completedeletion:n fi_id:121389462]) options=[]
2022/03/02 10:37:21 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:37:21 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doDeleteFile(map[completedeletion:n fi_id:121389460]) options=[]
2022/03/02 10:38:02 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:38:02 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:38:10 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
--- PASS: TestSyncAfterRemovingAFileAndAddingAFileDryRun (126.65s)
=== RUN   TestSyncAfterRemovingAFileAndAddingAFile
    run.go:181: Remote "filefabric root 'rclone-test-duzipet7zovasul4tijatet2'", Local "Local file system at /tmp/rclone3003306651", Modify Window "1s"
2022/03/02 10:38:10 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doInitUpload(map[directuploadsupport:n fi_contenttype:application/octet-stream fi_filename:potato fi_localtime:2011-12-25 12:59:59 fi_modified:2011-12-25 12:59:59 fi_name:potato fi_pid:121389188 fi_size:21 responsetype:json]) options=[]
2022/03/02 10:38:12 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:38:13 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doCompleteUpload(map[fi_size:21 remotetime:2011-12-25 12:59:59 uploadcode:ca741878137e8c89e146b050549b306d]) options=[]
2022/03/02 10:38:22 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:38:22 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doInitUpload(map[directuploadsupport:n fi_contenttype:application/octet-stream fi_filename:empty space fi_localtime:2011-12-25 12:59:59 fi_modified:2011-12-25 12:59:59 fi_name:empty space fi_pid:121389188 fi_size:1 responsetype:json]) options=[]
2022/03/02 10:38:23 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:38:25 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doCompleteUpload(map[fi_size:1 remotetime:2011-12-25 12:59:59 uploadcode:eed8062019036b18d8f0f7e01d859cec]) options=[]
2022/03/02 10:38:38 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:38:38 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:38:56 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:38:56 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: getFolderContents(map[count:1000 fi_pid:121389188 options:filelist|fi_id|fi_pid|fi_name|fi_type|fi_size|fi_contenttype|fi_modified|fi_localtime|trash|subfolders subfolders:y]) options=[]
2022/03/02 10:38:57 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:38:57 DEBUG : empty space: Size and modification time the same (differ by -123.456789ms, within tolerance 1s)
2022/03/02 10:38:57 DEBUG : empty space: Unchanged skipping
2022/03/02 10:38:57 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Waiting for checks to finish
2022/03/02 10:38:57 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': Waiting for transfers to finish
2022/03/02 10:38:57 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doInitUpload(map[directuploadsupport:n fi_contenttype:application/octet-stream fi_filename:potato2 fi_localtime:2001-02-03 04:05:06 fi_modified:2001-02-03 04:05:06 fi_name:potato2 fi_pid:121389188 fi_size:60 responsetype:json]) options=[]
2022/03/02 10:39:00 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:39:02 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doCompleteUpload(map[fi_size:60 remotetime:2001-02-03 04:05:06 uploadcode:204f827d0419d39208b683cfcd2245ea]) options=[]
2022/03/02 10:39:11 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': >rpc: result=Success (ok), err=<nil>
2022/03/02 10:39:11 INFO  : potato2: Copied (new)
2022/03/02 10:39:11 DEBUG : Waiting for deletions to finish
2022/03/02 10:39:11 DEBUG : filefabric root 'rclone-test-duzipet7zovasul4tijatet2': rpc: doDeleteFile(map[completedeletion:n fi_id:121389470]) options=[]
panic: test timed out after 2h0m0s

goroutine 6430 [running]:
testing.(*M).startAlarm.func1()
	/usr/local/go/src/testing/testing.go:1788 +0x8e
created by time.goFunc
	/usr/local/go/src/time/sleep.go:180 +0x31

goroutine 1 [chan receive, 3 minutes]:
testing.(*T).Run(0xc000103380, {0x18ffab3, 0x46d533}, 0x195ef98)
	/usr/local/go/src/testing/testing.go:1307 +0x375
testing.runTests.func1(0xc0008e4540)
	/usr/local/go/src/testing/testing.go:1598 +0x6e
testing.tRunner(0xc000103380, 0xc000779ca0)
	/usr/local/go/src/testing/testing.go:1259 +0x102
testing.runTests(0xc000120b80, {0x28abd40, 0x4a, 0x4a}, {0xead6e0, 0xc00090eaf8, 0x28b8dc0})
	/usr/local/go/src/testing/testing.go:1596 +0x43f
testing.(*M).Run(0xc000120b80)
	/usr/local/go/src/testing/testing.go:1504 +0x51d
github.com/rclone/rclone/fstest.TestMain(0xc0000001a0)
	/home/rclone/go/src/github.com/rclone/rclone/fstest/run.go:70 +0x9e
github.com/rclone/rclone/fs/sync.TestMain(...)
	/home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync_test.go:36
main.main()
	_testmain.go:191 +0x166

goroutine 7 [select]:
go.opencensus.io/stats/view.(*worker).start(0xc0000f7980)
	/home/rclone/go/pkg/mod/go.opencensus.io@v0.23.0/stats/view/worker.go:276 +0xb9
created by go.opencensus.io/stats/view.init.0
	/home/rclone/go/pkg/mod/go.opencensus.io@v0.23.0/stats/view/worker.go:34 +0x92

goroutine 6250 [semacquire]:
sync.runtime_Semacquire(0x0)
	/usr/local/go/src/runtime/sema.go:56 +0x25
sync.(*WaitGroup).Wait(0x0)
	/usr/local/go/src/sync/waitgroup.go:130 +0x71
github.com/rclone/rclone/fs/operations.DeleteFilesWithBackupDir({0x1c5e6b8, 0xc0003b8a80}, 0xc000869bc0, {0x0, 0x0})
	/home/rclone/go/src/github.com/rclone/rclone/fs/operations/operations.go:733 +0x1f5
github.com/rclone/rclone/fs/sync.(*syncCopyMove).deleteFiles(0xc000518000, 0x0)
	/home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync.go:540 +0x17f
github.com/rclone/rclone/fs/sync.(*syncCopyMove).run(0xc000518000)
	/home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync.go:882 +0x456
github.com/rclone/rclone/fs/sync.runSyncCopyMove({0x1c5e6f0, 0xc000040058}, {0x1c8d138, 0xc00036ee00}, {0x1c8d988, 0xc000113290}, 0x3, 0x0, 0x2f, 0x0)
	/home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync.go:1083 +0x21f
github.com/rclone/rclone/fs/sync.Sync({0x1c5e6f0, 0xc000040058}, {0x1c8d138, 0xc00036ee00}, {0x1c8d988, 0xc000113290}, 0x0)
	/home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync.go:1089 +0x78
github.com/rclone/rclone/fs/sync.testSyncAfterRemovingAFileAndAddingAFile({0x1c5e6f0, 0xc000040058}, 0x48de17)
	/home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync_test.go:710 +0x6a5
github.com/rclone/rclone/fs/sync.TestSyncAfterRemovingAFileAndAddingAFile(0x1)
	/home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync_test.go:717 +0x2a
testing.tRunner(0xc000592d00, 0x195ef98)
	/usr/local/go/src/testing/testing.go:1259 +0x102
created by testing.(*T).Run
	/usr/local/go/src/testing/testing.go:1306 +0x35a

goroutine 6429 [select]:
net/http.(*persistConn).writeLoop(0xc0004ba7e0)
	/usr/local/go/src/net/http/transport.go:2386 +0xfb
created by net/http.(*Transport).dialConn
	/usr/local/go/src/net/http/transport.go:1748 +0x1e65

goroutine 262 [syscall, 118 minutes]:
os/signal.signal_recv()
	/usr/local/go/src/runtime/sigqueue.go:169 +0x98
os/signal.loop()
	/usr/local/go/src/os/signal/signal_unix.go:24 +0x19
created by os/signal.Notify.func1.1
	/usr/local/go/src/os/signal/signal.go:151 +0x2c

goroutine 275 [chan receive, 118 minutes]:
github.com/rclone/rclone/lib/atexit.Register.func1.1()
	/home/rclone/go/src/github.com/rclone/rclone/lib/atexit/atexit.go:45 +0x2f
created by github.com/rclone/rclone/lib/atexit.Register.func1
	/home/rclone/go/src/github.com/rclone/rclone/lib/atexit/atexit.go:44 +0x6d

goroutine 6428 [IO wait]:
internal/poll.runtime_pollWait(0x7ff943a4df30, 0x72)
	/usr/local/go/src/runtime/netpoll.go:234 +0x89
internal/poll.(*pollDesc).wait(0xc000832400, 0xc00071b500, 0x0)
	/usr/local/go/src/internal/poll/fd_poll_runtime.go:84 +0x32
internal/poll.(*pollDesc).waitRead(...)
	/usr/local/go/src/internal/poll/fd_poll_runtime.go:89
internal/poll.(*FD).Read(0xc000832400, {0xc00071b500, 0x1484, 0x1484})
	/usr/local/go/src/internal/poll/fd_unix.go:167 +0x25a
net.(*netFD).Read(0xc000832400, {0xc00071b500, 0xc00050e6f8, 0x4a3946})
	/usr/local/go/src/net/fd_posix.go:56 +0x29
net.(*conn).Read(0xc0002073e8, {0xc00071b500, 0xc00050e758, 0x0})
	/usr/local/go/src/net/net.go:183 +0x45
github.com/rclone/rclone/fs/fshttp.(*timeoutConn).Read(0xc000920540, {0xc00071b500, 0x2000, 0x100000000000000})
	/home/rclone/go/src/github.com/rclone/rclone/fs/fshttp/dialer.go:104 +0x32
crypto/tls.(*atLeastReader).Read(0xc000138ae0, {0xc00071b500, 0x0, 0x40ba4d})
	/usr/local/go/src/crypto/tls/conn.go:777 +0x3d
bytes.(*Buffer).ReadFrom(0xc0006e9e78, {0x1c26080, 0xc000138ae0})
	/usr/local/go/src/bytes/buffer.go:204 +0x98
crypto/tls.(*Conn).readFromUntil(0xc0006e9c00, {0x7ff9410b1ed8, 0xc000920540}, 0xc0007b0000)
	/usr/local/go/src/crypto/tls/conn.go:799 +0xe5
crypto/tls.(*Conn).readRecordOrCCS(0xc0006e9c00, 0x0)
	/usr/local/go/src/crypto/tls/conn.go:606 +0x112
crypto/tls.(*Conn).readRecord(...)
	/usr/local/go/src/crypto/tls/conn.go:574
crypto/tls.(*Conn).Read(0xc0006e9c00, {0xc000794000, 0x1000, 0x10100000044f2ea})
	/usr/local/go/src/crypto/tls/conn.go:1277 +0x16f
net/http.(*persistConn).Read(0xc0004ba7e0, {0xc000794000, 0x406f1d, 0x60})
	/usr/local/go/src/net/http/transport.go:1926 +0x4e
bufio.(*Reader).fill(0xc0009b90e0)
	/usr/local/go/src/bufio/bufio.go:101 +0x103
bufio.(*Reader).Peek(0xc0009b90e0, 0x1)
	/usr/local/go/src/bufio/bufio.go:139 +0x5d
net/http.(*persistConn).readLoop(0xc0004ba7e0)
	/usr/local/go/src/net/http/transport.go:2087 +0x1ac
created by net/http.(*Transport).dialConn
	/usr/local/go/src/net/http/transport.go:1747 +0x1e05

goroutine 6420 [select]:
net/http.(*persistConn).roundTrip(0xc0004ba7e0, 0xc0007b4780)
	/usr/local/go/src/net/http/transport.go:2614 +0x97d
net/http.(*Transport).roundTrip(0xc0002bd400, 0xc00036ed00)
	/usr/local/go/src/net/http/transport.go:594 +0x7d1
net/http.(*Transport).RoundTrip(...)
	/usr/local/go/src/net/http/roundtrip.go:18
github.com/rclone/rclone/fs/fshttp.(*Transport).RoundTrip(0xc000389d10, 0xc00036ed00)
	/home/rclone/go/src/github.com/rclone/rclone/fs/fshttp/http.go:274 +0x4c8
net/http.send(0xc00036ed00, {0x1c29360, 0xc000389d10}, {0x1872c60, 0x1, 0x0})
	/usr/local/go/src/net/http/client.go:252 +0x5d8
net/http.(*Client).send(0xc00023f050, 0xc00036ed00, {0xc0008305a0, 0x2f, 0x0})
	/usr/local/go/src/net/http/client.go:176 +0x9b
net/http.(*Client).do(0xc00023f050, 0xc00036ed00)
	/usr/local/go/src/net/http/client.go:725 +0x908
net/http.(*Client).Do(...)
	/usr/local/go/src/net/http/client.go:593
github.com/rclone/rclone/lib/rest.(*Client).Call(0xc000389d60, {0x1c5e6b8, 0xc0003b8a80}, 0xc0004ba6c0)
	/home/rclone/go/src/github.com/rclone/rclone/lib/rest/rest.go:284 +0xc05
github.com/rclone/rclone/lib/rest.(*Client).callCodec(0x2828a00, {0x1c5e6b8, 0xc0003b8a80}, 0x0, {0x0, 0x0}, {0x1649620, 0xc0008d0320}, 0x0, 0x195f120, ...)
	/home/rclone/go/src/github.com/rclone/rclone/lib/rest/rest.go:481 +0x485
github.com/rclone/rclone/lib/rest.(*Client).CallJSON(...)
	/home/rclone/go/src/github.com/rclone/rclone/lib/rest/rest.go:424
github.com/rclone/rclone/backend/filefabric.(*Fs).rpc.func1()
	/home/rclone/go/src/github.com/rclone/rclone/backend/filefabric/filefabric.go:411 +0x17b
github.com/rclone/rclone/fs.pacerInvoker(0xc000115860, 0x10000c0007279d8, 0x100000000000000)
	/home/rclone/go/src/github.com/rclone/rclone/fs/pacer.go:88 +0x38
github.com/rclone/rclone/lib/pacer.(*Pacer).call(0xc000115860, 0xc000727a20, 0xa)
	/home/rclone/go/src/github.com/rclone/rclone/lib/pacer/pacer.go:197 +0x85
github.com/rclone/rclone/lib/pacer.(*Pacer).Call(0xc000115860, 0xc000830540)
	/home/rclone/go/src/github.com/rclone/rclone/lib/pacer/pacer.go:216 +0x90
github.com/rclone/rclone/backend/filefabric.(*Fs).rpc(0xc00036ee00, {0x1c5e6b8, 0xc0003b8a80}, {0x18bb9d0, 0xc0002f01a0}, 0xc0008303f0, {0x1c49da8, 0xc0008d0320}, {0x0, 0x0, ...})
	/home/rclone/go/src/github.com/rclone/rclone/backend/filefabric/filefabric.go:407 +0x91c
github.com/rclone/rclone/backend/filefabric.(*Fs).deleteObject(0x8a0c7c, {0x1c5e6b8, 0xc0003b8a80}, {0xc000040850, 0x9})
	/home/rclone/go/src/github.com/rclone/rclone/backend/filefabric/filefabric.go:724 +0x165
github.com/rclone/rclone/backend/filefabric.(*Object).Remove(0x1c5e6b8, {0x1c5e6b8, 0xc0003b8a80})
	/home/rclone/go/src/github.com/rclone/rclone/backend/filefabric/filefabric.go:1333 +0x31
github.com/rclone/rclone/fs/operations.DeleteFileWithBackupDir({0x1c5e6b8, 0xc0003b8a80}, {0x1c8d1a8, 0xc000a0cb40}, {0x0, 0x0})
	/home/rclone/go/src/github.com/rclone/rclone/fs/operations/operations.go:685 +0x2b4
github.com/rclone/rclone/fs/operations.DeleteFilesWithBackupDir.func1()
	/home/rclone/go/src/github.com/rclone/rclone/fs/operations/operations.go:720 +0x10e
created by github.com/rclone/rclone/fs/operations.DeleteFilesWithBackupDir
	/home/rclone/go/src/github.com/rclone/rclone/fs/operations/operations.go:717 +0xbf

goroutine 6373 [chan receive]:
github.com/rclone/rclone/fs/march.(*March).Run.func2()
	/home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:208 +0x45
created by github.com/rclone/rclone/fs/march.(*March).Run
	/home/rclone/go/src/github.com/rclone/rclone/fs/march/march.go:206 +0x3a5

goroutine 6385 [select]:
github.com/rclone/rclone/fs/accounting.(*StatsInfo).averageLoop(0xc0002f01a0)
	/home/rclone/go/src/github.com/rclone/rclone/fs/accounting/stats.go:312 +0x16a
created by github.com/rclone/rclone/fs/accounting.(*StatsInfo).startAverageLoop.func1
	/home/rclone/go/src/github.com/rclone/rclone/fs/accounting/stats.go:341 +0x72
"./sync.test -test.v -test.timeout 2h0m0s -remote TestFileFabric: -verbose" - Finished ERROR in 2h0m0.548067278s (try 2/5): exit status 2: Failed []