"./sync.test -test.v -test.timeout 2h0m0s -remote TestFileFabric: -verbose" - Starting (try 1/5)
2022/03/15 07:00:59 DEBUG : Creating backend with remote "TestFileFabric:rclone-test-cipebig3rahekoz0qogedis9"
2022/03/15 07:00:59 DEBUG : Using config file from "/home/rclone/.rclone.conf"
2022/03/15 07:00:59 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: checkPathExists(map[path:rclone-test-cipebig3rahekoz0qogedis9 pid:120673762]) options=[]
2022/03/15 07:00:59 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:00:59 DEBUG : Creating backend with remote "/tmp/rclone1921185003"
=== RUN   TestPipe
--- PASS: TestPipe (0.00s)
=== RUN   TestPipeConcurrent
--- PASS: TestPipeConcurrent (0.02s)
=== 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-cipebig3rahekoz0qogedis9'", Local "Local file system at /tmp/rclone1921185003", Modify Window "1s"
2022/03/15 07:00:59 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': 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/15 07:01:01 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:01:01 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doCreateNewFolder(map[fi_name:rclone-test-cipebig3rahekoz0qogedis9 fi_pid:120673762]) options=[]
2022/03/15 07:01:14 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:01:14 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 07:01:27 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:01:27 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Waiting for checks to finish
2022/03/15 07:01:27 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Waiting for transfers to finish
2022/03/15 07:01:27 NOTICE: sub dir/hello world: Skipped copy as --dry-run is set (size 11)
2022/03/15 07:01:27 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 07:01:28 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:01:28 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 07:01:29 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:01:29 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 07:01:29 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
--- PASS: TestCopyWithDryRun (29.85s)
=== RUN   TestCopy
    run.go:181: Remote "filefabric root 'rclone-test-cipebig3rahekoz0qogedis9'", Local "Local file system at /tmp/rclone1921185003", Modify Window "1s"
2022/03/15 07:01:29 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 07:01:30 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:01:30 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 07:01:30 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Waiting for checks to finish
2022/03/15 07:01:30 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Waiting for transfers to finish
2022/03/15 07:01:30 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:01:30 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doCreateNewFolder(map[fi_name:sub dir fi_pid:121408854]) options=[]
2022/03/15 07:01:53 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:01:53 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': 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:121408856 fi_size:11 responsetype:json]) options=[]
2022/03/15 07:01:58 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:02:00 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doCompleteUpload(map[fi_size:11 remotetime:2001-02-03 04:05:06 uploadcode:70104e801720b3b71177d56f0e6a20ac]) options=[]
2022/03/15 07:02:06 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:02:06 INFO  : sub dir/hello world: Copied (new)
2022/03/15 07:02:06 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 07:02:19 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:02:19 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408856 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/15 07:02:35 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:02:35 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 07:02:36 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:02:36 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408856 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/15 07:02:36 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:02:36 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doDeleteFile(map[completedeletion:n fi_id:121408858]) options=[]
2022/03/15 07:03:42 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:03:42 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408856 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/15 07:03:51 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:03:51 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doDeleteFolder(map[fi_id:121408856]) options=[]
2022/03/15 07:04:00 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:04:00 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 07:04:01 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
--- PASS: TestCopy (151.53s)
=== RUN   TestCopyMissingDirectory
    run.go:181: Remote "filefabric root 'rclone-test-cipebig3rahekoz0qogedis9'", Local "Local file system at /tmp/rclone1921185003", Modify Window "1s"
2022/03/15 07:04:01 DEBUG : Creating backend with remote "/non-existing"
2022/03/15 07:04:01 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 07:04:01 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:04:01 ERROR : Local file system at /non-existing: error reading source root directory: directory not found
2022/03/15 07:04:01 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Waiting for checks to finish
2022/03/15 07:04:01 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Waiting for transfers to finish
2022/03/15 07:04:01 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 07:04:02 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:04:02 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 07:04:03 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
--- PASS: TestCopyMissingDirectory (2.02s)
=== RUN   TestCopyNoTraverse
    run.go:181: Remote "filefabric root 'rclone-test-cipebig3rahekoz0qogedis9'", Local "Local file system at /tmp/rclone1921185003", Modify Window "1s"
2022/03/15 07:04:03 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: checkPathExists(map[path:sub dir/hello world pid:121408854]) options=[]
2022/03/15 07:04:03 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:04:03 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Waiting for checks to finish
2022/03/15 07:04:03 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 07:04:03 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Waiting for transfers to finish
2022/03/15 07:04:04 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:04:04 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doCreateNewFolder(map[fi_name:sub dir fi_pid:121408854]) options=[]
2022/03/15 07:04:05 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Sleeping for 1s to wait for "error_background" error to clear
2022/03/15 07:04:06 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/15 07:04:06 DEBUG : pacer: Rate limited, increasing sleep to 40ms
2022/03/15 07:04:09 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Sleeping for 2s to wait for "error_background" error to clear
2022/03/15 07:04: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/15 07:04:11 DEBUG : pacer: Rate limited, increasing sleep to 80ms
2022/03/15 07:04:14 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Sleeping for 4s to wait for "error_background" error to clear
2022/03/15 07:04:18 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/15 07:04:18 DEBUG : pacer: Rate limited, increasing sleep to 160ms
2022/03/15 07:04:18 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Sleeping for 8s to wait for "error_background" error to clear
2022/03/15 07:04: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/15 07:04:26 DEBUG : pacer: Rate limited, increasing sleep to 320ms
2022/03/15 07:04:27 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Sleeping for 16s to wait for "error_background" error to clear
2022/03/15 07:04: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/15 07:04:43 DEBUG : pacer: Rate limited, increasing sleep to 640ms
2022/03/15 07:04:47 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Sleeping for 32s to wait for "error_background" error to clear
2022/03/15 07:05:19 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/15 07:05:19 DEBUG : pacer: Rate limited, increasing sleep to 1.28s
2022/03/15 07:05:22 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Sleeping for 1m4s to wait for "error_background" error to clear
2022/03/15 07:06:26 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/15 07:06:26 DEBUG : pacer: Rate limited, increasing sleep to 2.56s
2022/03/15 07:06:30 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Sleeping for 2m8s to wait for "error_background" error to clear
2022/03/15 07:08:38 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/15 07:08:38 DEBUG : pacer: Rate limited, increasing sleep to 5.12s
2022/03/15 07:08:41 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Sleeping for 4m16s to wait for "error_background" error to clear
2022/03/15 07:12:57 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/15 07:12:57 DEBUG : pacer: Rate limited, increasing sleep to 10s
2022/03/15 07:13:22 DEBUG : pacer: Reducing sleep to 7.5s
2022/03/15 07:13:22 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:13:22 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': 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:121408895 fi_size:11 responsetype:json]) options=[]
2022/03/15 07:13:27 DEBUG : pacer: Reducing sleep to 5.625s
2022/03/15 07:13:27 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:13:31 DEBUG : pacer: Reducing sleep to 4.21875s
2022/03/15 07:13:31 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doCompleteUpload(map[fi_size:11 remotetime:2001-02-03 04:05:06 uploadcode:b063ec3a25acca2ac3c05f525a97c88a]) options=[]
2022/03/15 07:13:42 DEBUG : pacer: Reducing sleep to 3.1640625s
2022/03/15 07:13:42 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:13:42 INFO  : sub dir/hello world: Copied (new)
2022/03/15 07:13:42 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 07:14:03 DEBUG : pacer: Reducing sleep to 2.373046875s
2022/03/15 07:14:03 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:14:03 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408895 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/15 07:14:28 DEBUG : pacer: Reducing sleep to 1.779785156s
2022/03/15 07:14:28 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:14:28 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 07:14:28 DEBUG : pacer: Reducing sleep to 1.334838867s
2022/03/15 07:14:28 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:14:28 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408895 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/15 07:14:30 DEBUG : pacer: Reducing sleep to 1.00112915s
2022/03/15 07:14:30 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:14:30 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doDeleteFile(map[completedeletion:n fi_id:121408897]) options=[]
2022/03/15 07:15:14 DEBUG : pacer: Reducing sleep to 750.846862ms
2022/03/15 07:15:14 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:15:14 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408895 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/15 07:15:30 DEBUG : pacer: Reducing sleep to 563.135146ms
2022/03/15 07:15:30 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:15:30 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doDeleteFolder(map[fi_id:121408895]) options=[]
2022/03/15 07:15:47 DEBUG : pacer: Reducing sleep to 422.351359ms
2022/03/15 07:15:47 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:15:47 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 07:15:48 DEBUG : pacer: Reducing sleep to 316.763519ms
2022/03/15 07:15:48 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
--- PASS: TestCopyNoTraverse (705.11s)
=== RUN   TestCopyCheckFirst
    run.go:181: Remote "filefabric root 'rclone-test-cipebig3rahekoz0qogedis9'", Local "Local file system at /tmp/rclone1921185003", Modify Window "1s"
2022/03/15 07:15:48 INFO  : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Running all checks before starting transfers
2022/03/15 07:15:48 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 07:15:48 DEBUG : pacer: Reducing sleep to 237.572639ms
2022/03/15 07:15:48 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:15:48 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Waiting for checks to finish
2022/03/15 07:15:48 INFO  : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Checks finished, now starting transfers
2022/03/15 07:15:48 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Waiting for transfers to finish
2022/03/15 07:15:48 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 07:15:49 DEBUG : pacer: Reducing sleep to 178.179479ms
2022/03/15 07:15:49 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:15:49 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doCreateNewFolder(map[fi_name:sub dir fi_pid:121408854]) options=[]
2022/03/15 07:15:53 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Sleeping for 1s to wait for "error_background" error to clear
2022/03/15 07:15:54 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/15 07:15:54 DEBUG : pacer: Rate limited, increasing sleep to 356.358958ms
2022/03/15 07:15:56 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Sleeping for 2s to wait for "error_background" error to clear
2022/03/15 07:15:58 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/15 07:15:58 DEBUG : pacer: Rate limited, increasing sleep to 712.717916ms
2022/03/15 07:16:01 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Sleeping for 4s to wait for "error_background" error to clear
2022/03/15 07:16:05 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/15 07:16:05 DEBUG : pacer: Rate limited, increasing sleep to 1.425435832s
2022/03/15 07:16:05 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Sleeping for 8s to wait for "error_background" error to clear
2022/03/15 07:16: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/15 07:16:13 DEBUG : pacer: Rate limited, increasing sleep to 2.850871664s
2022/03/15 07:16:14 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Sleeping for 16s to wait for "error_background" error to clear
2022/03/15 07:16:30 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/15 07:16:30 DEBUG : pacer: Rate limited, increasing sleep to 5.701743328s
2022/03/15 07:16:31 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Sleeping for 32s to wait for "error_background" error to clear
2022/03/15 07:17:03 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/15 07:17:03 DEBUG : pacer: Rate limited, increasing sleep to 10s
2022/03/15 07:17:04 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Sleeping for 1m4s to wait for "error_background" error to clear
2022/03/15 07:18:08 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/15 07:18:11 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Sleeping for 2m8s to wait for "error_background" error to clear
2022/03/15 07:20:19 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/15 07:20:40 DEBUG : pacer: Reducing sleep to 7.5s
2022/03/15 07:20:40 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:20:40 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': 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:121408914 fi_size:11 responsetype:json]) options=[]
2022/03/15 07:20:41 DEBUG : pacer: Reducing sleep to 5.625s
2022/03/15 07:20:41 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:20:49 DEBUG : pacer: Reducing sleep to 4.21875s
2022/03/15 07:20:49 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doCompleteUpload(map[fi_size:11 remotetime:2001-02-03 04:05:06 uploadcode:e135fdab38be9608a4b2c9abc035a930]) options=[]
2022/03/15 07:21:02 DEBUG : pacer: Reducing sleep to 3.1640625s
2022/03/15 07:21:02 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:21:02 INFO  : sub dir/hello world: Copied (new)
2022/03/15 07:21:02 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 07:21:11 DEBUG : pacer: Reducing sleep to 2.373046875s
2022/03/15 07:21:11 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:21:11 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408914 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/15 07:21:20 DEBUG : pacer: Reducing sleep to 1.779785156s
2022/03/15 07:21:20 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:21:20 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 07:21:21 DEBUG : pacer: Reducing sleep to 1.334838867s
2022/03/15 07:21:21 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:21:21 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408914 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/15 07:21:23 DEBUG : pacer: Reducing sleep to 1.00112915s
2022/03/15 07:21:23 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:21:23 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doDeleteFile(map[completedeletion:n fi_id:121408915]) options=[]
2022/03/15 07:22:07 DEBUG : pacer: Reducing sleep to 750.846862ms
2022/03/15 07:22:07 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:22:07 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408914 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/15 07:22:20 DEBUG : pacer: Reducing sleep to 563.135146ms
2022/03/15 07:22:20 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:22:20 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doDeleteFolder(map[fi_id:121408914]) options=[]
2022/03/15 07:22:38 DEBUG : pacer: Reducing sleep to 422.351359ms
2022/03/15 07:22:38 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:22:38 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 07:22:42 DEBUG : pacer: Reducing sleep to 316.763519ms
2022/03/15 07:22:42 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
--- PASS: TestCopyCheckFirst (414.04s)
=== RUN   TestSyncNoTraverse
    run.go:181: Remote "filefabric root 'rclone-test-cipebig3rahekoz0qogedis9'", Local "Local file system at /tmp/rclone1921185003", Modify Window "1s"
2022/03/15 07:22:42 ERROR : Ignoring --no-traverse with sync
2022/03/15 07:22:42 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 07:22:42 DEBUG : pacer: Reducing sleep to 237.572639ms
2022/03/15 07:22:42 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:22:42 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Waiting for checks to finish
2022/03/15 07:22:42 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 07:22:42 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Waiting for transfers to finish
2022/03/15 07:22:43 DEBUG : pacer: Reducing sleep to 178.179479ms
2022/03/15 07:22:43 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:22:43 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doCreateNewFolder(map[fi_name:sub dir fi_pid:121408854]) options=[]
2022/03/15 07:22:47 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Sleeping for 1s to wait for "error_background" error to clear
2022/03/15 07:22:48 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/15 07:22:48 DEBUG : pacer: Rate limited, increasing sleep to 356.358958ms
2022/03/15 07:22:51 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Sleeping for 2s to wait for "error_background" error to clear
2022/03/15 07:22:53 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/15 07:22:53 DEBUG : pacer: Rate limited, increasing sleep to 712.717916ms
2022/03/15 07:22:56 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Sleeping for 4s to wait for "error_background" error to clear
2022/03/15 07:23:00 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/15 07:23:00 DEBUG : pacer: Rate limited, increasing sleep to 1.425435832s
2022/03/15 07:23:04 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Sleeping for 8s to wait for "error_background" error to clear
2022/03/15 07:23:12 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/15 07:23:12 DEBUG : pacer: Rate limited, increasing sleep to 2.850871664s
2022/03/15 07:23:12 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Sleeping for 16s to wait for "error_background" error to clear
2022/03/15 07:23:28 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/15 07:23:28 DEBUG : pacer: Rate limited, increasing sleep to 5.701743328s
2022/03/15 07:23:29 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Sleeping for 32s to wait for "error_background" error to clear
2022/03/15 07:24:01 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/15 07:24:01 DEBUG : pacer: Rate limited, increasing sleep to 10s
2022/03/15 07:24:02 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Sleeping for 1m4s to wait for "error_background" error to clear
2022/03/15 07:25:06 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/15 07:25:08 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Sleeping for 2m8s to wait for "error_background" error to clear
2022/03/15 07:27:16 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/15 07:27:33 DEBUG : pacer: Reducing sleep to 7.5s
2022/03/15 07:27:33 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:27:33 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': 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:121408930 fi_size:11 responsetype:json]) options=[]
2022/03/15 07:27:38 DEBUG : pacer: Reducing sleep to 5.625s
2022/03/15 07:27:38 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:27:42 DEBUG : pacer: Reducing sleep to 4.21875s
2022/03/15 07:27:42 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doCompleteUpload(map[fi_size:11 remotetime:2001-02-03 04:05:06 uploadcode:39652a874bbf39cbcb93032e2b9745df]) options=[]
2022/03/15 07:27:53 DEBUG : pacer: Reducing sleep to 3.1640625s
2022/03/15 07:27:53 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:27:53 INFO  : sub dir/hello world: Copied (new)
2022/03/15 07:27:53 DEBUG : Waiting for deletions to finish
2022/03/15 07:27:53 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 07:28:13 DEBUG : pacer: Reducing sleep to 2.373046875s
2022/03/15 07:28:13 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:28:13 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408930 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/15 07:28:22 DEBUG : pacer: Reducing sleep to 1.779785156s
2022/03/15 07:28:22 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:28:22 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 07:28:22 DEBUG : pacer: Reducing sleep to 1.334838867s
2022/03/15 07:28:22 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:28:22 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408930 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/15 07:28:24 DEBUG : pacer: Reducing sleep to 1.00112915s
2022/03/15 07:28:24 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:28:24 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doDeleteFile(map[completedeletion:n fi_id:121408932]) options=[]
2022/03/15 07:29:20 DEBUG : pacer: Reducing sleep to 750.846862ms
2022/03/15 07:29:20 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:29:20 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408930 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/15 07:29:44 DEBUG : pacer: Reducing sleep to 563.135146ms
2022/03/15 07:29:44 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:29:44 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doDeleteFolder(map[fi_id:121408930]) options=[]
2022/03/15 07:30:05 DEBUG : pacer: Reducing sleep to 422.351359ms
2022/03/15 07:30:05 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:30:05 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 07:30:09 DEBUG : pacer: Reducing sleep to 316.763519ms
2022/03/15 07:30:09 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
--- PASS: TestSyncNoTraverse (447.48s)
=== RUN   TestCopyWithDepth
    run.go:181: Remote "filefabric root 'rclone-test-cipebig3rahekoz0qogedis9'", Local "Local file system at /tmp/rclone1921185003", Modify Window "1s"
2022/03/15 07:30:09 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 07:30:10 DEBUG : pacer: Reducing sleep to 237.572639ms
2022/03/15 07:30:10 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:30:10 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': 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:121408854 fi_size:12 responsetype:json]) options=[]
2022/03/15 07:30:10 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Waiting for checks to finish
2022/03/15 07:30:10 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Waiting for transfers to finish
2022/03/15 07:30:15 DEBUG : pacer: Reducing sleep to 178.179479ms
2022/03/15 07:30:15 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:30:16 DEBUG : pacer: Reducing sleep to 133.634609ms
2022/03/15 07:30:16 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doCompleteUpload(map[fi_size:12 remotetime:2011-12-25 12:59:59 uploadcode:63e1c3a0e6f1ed6e1b2c3e655df4b6ed]) options=[]
2022/03/15 07:30:26 DEBUG : pacer: Reducing sleep to 100.225956ms
2022/03/15 07:30:26 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:30:26 INFO  : hello world2: Copied (new)
2022/03/15 07:30:26 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 07:30:31 DEBUG : pacer: Reducing sleep to 75.169467ms
2022/03/15 07:30:31 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:30:31 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 07:30:31 DEBUG : pacer: Reducing sleep to 56.3771ms
2022/03/15 07:30:31 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:30:31 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doDeleteFile(map[completedeletion:n fi_id:121408936]) options=[]
2022/03/15 07:31:10 DEBUG : pacer: Reducing sleep to 42.282825ms
2022/03/15 07:31:10 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:31:10 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 07:31:10 DEBUG : pacer: Reducing sleep to 31.712118ms
2022/03/15 07:31:10 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
--- PASS: TestCopyWithDepth (60.89s)
=== RUN   TestCopyWithFilesFrom
    run.go:181: Remote "filefabric root 'rclone-test-cipebig3rahekoz0qogedis9'", Local "Local file system at /tmp/rclone1921185003", Modify Window "1s"
2022/03/15 07:31:10 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 07:31:10 DEBUG : hello world2: Excluded
2022/03/15 07:31:11 DEBUG : pacer: Reducing sleep to 23.784088ms
2022/03/15 07:31:11 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:31:11 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Waiting for checks to finish
2022/03/15 07:31:11 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Waiting for transfers to finish
2022/03/15 07:31:11 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': 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:121408854 fi_size:11 responsetype:json]) options=[]
2022/03/15 07:31:16 DEBUG : pacer: Reducing sleep to 20ms
2022/03/15 07:31:16 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:31:17 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doCompleteUpload(map[fi_size:11 remotetime:2001-02-03 04:05:06 uploadcode:a0347a989732f3a7b8a1c67f593ce388]) options=[]
2022/03/15 07:31:23 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:31:23 INFO  : potato2: Copied (new)
2022/03/15 07:31:23 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 07:31:27 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:31:27 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 07:31:28 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:31:28 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doDeleteFile(map[completedeletion:n fi_id:121408938]) options=[]
2022/03/15 07:32:22 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:32:22 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 07:32:26 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
--- PASS: TestCopyWithFilesFrom (76.21s)
=== RUN   TestCopyWithFilesFromAndNoTraverse
    run.go:181: Remote "filefabric root 'rclone-test-cipebig3rahekoz0qogedis9'", Local "Local file system at /tmp/rclone1921185003", Modify Window "1s"
2022/03/15 07:32:26 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: checkPathExists(map[path:potato2 pid:121408854]) options=[]
2022/03/15 07:32:27 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:32:27 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Waiting for checks to finish
2022/03/15 07:32:27 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Waiting for transfers to finish
2022/03/15 07:32:27 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': 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:121408854 fi_size:11 responsetype:json]) options=[]
2022/03/15 07:32:31 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:32:33 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doCompleteUpload(map[fi_size:11 remotetime:2001-02-03 04:05:06 uploadcode:19883c981c049cc38c21dc29f60dd806]) options=[]
2022/03/15 07:32:39 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:32:39 INFO  : potato2: Copied (new)
2022/03/15 07:32:39 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 07:32:40 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:32:40 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 07:32:40 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:32:40 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doDeleteFile(map[completedeletion:n fi_id:121408944]) options=[]
2022/03/15 07:33:37 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:33:37 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 07:34:01 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
--- PASS: TestCopyWithFilesFromAndNoTraverse (95.03s)
=== RUN   TestCopyEmptyDirectories
    run.go:181: Remote "filefabric root 'rclone-test-cipebig3rahekoz0qogedis9'", Local "Local file system at /tmp/rclone1921185003", Modify Window "1s"
2022/03/15 07:34:01 DEBUG : sub dir2: Making directory
2022/03/15 07:34:01 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 07:34:02 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:34:02 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Waiting for checks to finish
2022/03/15 07:34:02 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Waiting for transfers to finish
2022/03/15 07:34:02 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 07:34:03 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:34:03 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doCreateNewFolder(map[fi_name:sub dir fi_pid:121408854]) options=[]
2022/03/15 07:34:18 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:34:18 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': 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:121408946 fi_size:11 responsetype:json]) options=[]
2022/03/15 07:34:23 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:34:25 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doCompleteUpload(map[fi_size:11 remotetime:2001-02-03 04:05:06 uploadcode:e634d0c3283eaf3095fae625608ccce4]) options=[]
2022/03/15 07:34:31 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:34:31 INFO  : sub dir/hello world: Copied (new)
2022/03/15 07:34:31 DEBUG : sub dir2: Making directory
2022/03/15 07:34:31 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 07:34:47 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:34:47 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doCreateNewFolder(map[fi_name:sub dir2 fi_pid:121408854]) options=[]
2022/03/15 07:35:08 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:35:08 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': copied 1 directories
2022/03/15 07:35:08 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 07:35:21 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:35:21 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408948 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/15 07:35:21 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408946 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/15 07:35:30 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:35:30 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:35:30 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 07:35:31 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:35:31 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408948 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/15 07:35:31 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408946 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/15 07:35:31 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:35:31 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doDeleteFile(map[completedeletion:n fi_id:121408947]) options=[]
2022/03/15 07:35:31 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:36:26 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:36:26 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408948 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/15 07:36:27 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:36:27 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doDeleteFolder(map[fi_id:121408948]) options=[]
2022/03/15 07:36:47 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:36:47 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408946 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/15 07:37:04 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:37:04 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doDeleteFolder(map[fi_id:121408946]) options=[]
2022/03/15 07:37:24 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:37:24 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 07:37:28 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
--- PASS: TestCopyEmptyDirectories (206.59s)
=== RUN   TestMoveEmptyDirectories
    run.go:181: Remote "filefabric root 'rclone-test-cipebig3rahekoz0qogedis9'", Local "Local file system at /tmp/rclone1921185003", Modify Window "1s"
2022/03/15 07:37:28 DEBUG : sub dir2: Making directory
2022/03/15 07:37:28 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 07:37:29 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:37:29 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Waiting for checks to finish
2022/03/15 07:37:29 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Waiting for transfers to finish
2022/03/15 07:37:29 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 07:37:29 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:37:29 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doCreateNewFolder(map[fi_name:sub dir fi_pid:121408854]) options=[]
2022/03/15 07:37:32 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Sleeping for 1s to wait for "error_background" error to clear
2022/03/15 07:37: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/15 07:37:33 DEBUG : pacer: Rate limited, increasing sleep to 40ms
2022/03/15 07:37:36 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Sleeping for 2s to wait for "error_background" error to clear
2022/03/15 07:37:38 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/15 07:37:38 DEBUG : pacer: Rate limited, increasing sleep to 80ms
2022/03/15 07:37:41 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Sleeping for 4s to wait for "error_background" error to clear
2022/03/15 07:37:45 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/15 07:37:45 DEBUG : pacer: Rate limited, increasing sleep to 160ms
2022/03/15 07:37:49 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Sleeping for 8s to wait for "error_background" error to clear
2022/03/15 07:37:57 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/15 07:37:57 DEBUG : pacer: Rate limited, increasing sleep to 320ms
2022/03/15 07:37:58 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Sleeping for 16s to wait for "error_background" error to clear
2022/03/15 07:38: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/15 07:38:14 DEBUG : pacer: Rate limited, increasing sleep to 640ms
2022/03/15 07:38:15 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Sleeping for 32s to wait for "error_background" error to clear
2022/03/15 07:38:47 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/15 07:38:47 DEBUG : pacer: Rate limited, increasing sleep to 1.28s
2022/03/15 07:38:50 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Sleeping for 1m4s to wait for "error_background" error to clear
2022/03/15 07:39:54 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/15 07:39:54 DEBUG : pacer: Rate limited, increasing sleep to 2.56s
2022/03/15 07:39:56 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Sleeping for 2m8s to wait for "error_background" error to clear
2022/03/15 07:42:04 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/15 07:42:04 DEBUG : pacer: Rate limited, increasing sleep to 5.12s
2022/03/15 07:42:25 DEBUG : pacer: Reducing sleep to 3.84s
2022/03/15 07:42:25 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:42:25 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': 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:121408971 fi_size:11 responsetype:json]) options=[]
2022/03/15 07:42:31 DEBUG : pacer: Reducing sleep to 2.88s
2022/03/15 07:42:31 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:42:32 DEBUG : pacer: Reducing sleep to 2.16s
2022/03/15 07:42:32 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doCompleteUpload(map[fi_size:11 remotetime:2001-02-03 04:05:06 uploadcode:e14ca43600941c4a3f8906a059b4f6a4]) options=[]
2022/03/15 07:42:55 DEBUG : pacer: Reducing sleep to 1.62s
2022/03/15 07:42:55 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:42:55 INFO  : sub dir/hello world: Copied (new)
2022/03/15 07:42:55 INFO  : sub dir/hello world: Deleted
2022/03/15 07:42:55 DEBUG : sub dir: Making directory
2022/03/15 07:42:55 DEBUG : sub dir2: Making directory
2022/03/15 07:42:55 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 07:43:11 DEBUG : pacer: Reducing sleep to 1.215s
2022/03/15 07:43:11 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:43:11 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doCreateNewFolder(map[fi_name:sub dir2 fi_pid:121408854]) options=[]
2022/03/15 07:43:25 DEBUG : pacer: Reducing sleep to 911.25ms
2022/03/15 07:43:25 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:43:25 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': copied 2 directories
2022/03/15 07:43:25 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 07:43:38 DEBUG : pacer: Reducing sleep to 683.4375ms
2022/03/15 07:43:38 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:43:38 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408974 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/15 07:43:38 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408971 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/15 07:43:54 DEBUG : pacer: Reducing sleep to 512.578125ms
2022/03/15 07:43:54 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:43:54 DEBUG : pacer: Reducing sleep to 384.433593ms
2022/03/15 07:43:54 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:43:54 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 07:43:55 DEBUG : pacer: Reducing sleep to 288.325194ms
2022/03/15 07:43:55 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:43:55 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408974 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/15 07:43:55 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408971 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/15 07:43:56 DEBUG : pacer: Reducing sleep to 216.243895ms
2022/03/15 07:43:56 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:43:56 DEBUG : pacer: Reducing sleep to 162.182921ms
2022/03/15 07:43:56 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:43:56 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doDeleteFile(map[completedeletion:n fi_id:121408973]) options=[]
2022/03/15 07:44:45 DEBUG : pacer: Reducing sleep to 121.63719ms
2022/03/15 07:44:45 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:44:45 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408974 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/15 07:44:46 DEBUG : pacer: Reducing sleep to 91.227892ms
2022/03/15 07:44:46 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:44:46 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doDeleteFolder(map[fi_id:121408974]) options=[]
2022/03/15 07:44:58 DEBUG : pacer: Reducing sleep to 68.420919ms
2022/03/15 07:44:58 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:44:58 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408971 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/15 07:45:15 DEBUG : pacer: Reducing sleep to 51.315689ms
2022/03/15 07:45:15 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:45:15 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doDeleteFolder(map[fi_id:121408971]) options=[]
2022/03/15 07:45:28 DEBUG : pacer: Reducing sleep to 38.486766ms
2022/03/15 07:45:28 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=We are not able to complete the requested operation. We are processing move folder in parent folder. Please try again later. (file_error), err=We are not able to complete the requested operation. We are processing move folder in parent folder. Please try again later. (file_error)
    run.go:126: removing dir "sub dir" failed - try 1/3: failed to remove directory: We are not able to complete the requested operation. We are processing move folder in parent folder. Please try again later. (file_error)
2022/03/15 07:45:29 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 07:45:32 DEBUG : pacer: Reducing sleep to 28.865074ms
2022/03/15 07:45:32 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:45:32 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408971 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/15 07:45:33 DEBUG : pacer: Reducing sleep to 21.648805ms
2022/03/15 07:45:33 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:45:33 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doDeleteFolder(map[fi_id:121408971]) options=[]
2022/03/15 07:45:33 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Sleeping for 1s to wait for "error_background" error to clear
2022/03/15 07:45:34 DEBUG : pacer: low level retry 1/10 (error We are not able to complete the requested operation. We are processing move folder in parent folder. Please try again later. (error_background))
2022/03/15 07:45:34 DEBUG : pacer: Rate limited, increasing sleep to 43.29761ms
2022/03/15 07:45:37 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Sleeping for 2s to wait for "error_background" error to clear
2022/03/15 07:45:39 DEBUG : pacer: low level retry 2/10 (error We are not able to complete the requested operation. We are processing move folder in parent folder. Please try again later. (error_background))
2022/03/15 07:45:39 DEBUG : pacer: Rate limited, increasing sleep to 86.59522ms
2022/03/15 07:45:41 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Sleeping for 4s to wait for "error_background" error to clear
2022/03/15 07:45:45 DEBUG : pacer: low level retry 3/10 (error We are not able to complete the requested operation. We are processing move folder in parent folder. Please try again later. (error_background))
2022/03/15 07:45:45 DEBUG : pacer: Rate limited, increasing sleep to 173.19044ms
2022/03/15 07:45:49 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Sleeping for 8s to wait for "error_background" error to clear
2022/03/15 07:45:57 DEBUG : pacer: low level retry 4/10 (error We are not able to complete the requested operation. We are processing move folder in parent folder. Please try again later. (error_background))
2022/03/15 07:45:57 DEBUG : pacer: Rate limited, increasing sleep to 346.38088ms
2022/03/15 07:46:02 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Sleeping for 16s to wait for "error_background" error to clear
2022/03/15 07:46:18 DEBUG : pacer: low level retry 5/10 (error We are not able to complete the requested operation. We are processing move folder in parent folder. Please try again later. (error_background))
2022/03/15 07:46:18 DEBUG : pacer: Rate limited, increasing sleep to 692.76176ms
2022/03/15 07:46:20 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Sleeping for 32s to wait for "error_background" error to clear
2022/03/15 07:46:52 DEBUG : pacer: low level retry 6/10 (error We are not able to complete the requested operation. We are processing move folder in parent folder. Please try again later. (error_background))
2022/03/15 07:46:52 DEBUG : pacer: Rate limited, increasing sleep to 1.38552352s
2022/03/15 07:46:55 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Sleeping for 1m4s to wait for "error_background" error to clear
2022/03/15 07:47:59 DEBUG : pacer: low level retry 7/10 (error We are not able to complete the requested operation. We are processing move folder in parent folder. Please try again later. (error_background))
2022/03/15 07:47:59 DEBUG : pacer: Rate limited, increasing sleep to 2.77104704s
2022/03/15 07:48:00 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Sleeping for 2m8s to wait for "error_background" error to clear
2022/03/15 07:50:08 DEBUG : pacer: low level retry 8/10 (error We are not able to complete the requested operation. We are processing move folder in parent folder. Please try again later. (error_background))
2022/03/15 07:50:08 DEBUG : pacer: Rate limited, increasing sleep to 5.54209408s
2022/03/15 07:50:09 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Sleeping for 4m16s to wait for "error_background" error to clear
2022/03/15 07:54:25 DEBUG : pacer: low level retry 9/10 (error We are not able to complete the requested operation. We are processing move folder in parent folder. Please try again later. (error_background))
2022/03/15 07:54:25 DEBUG : pacer: Rate limited, increasing sleep to 10s
2022/03/15 07:54:43 DEBUG : pacer: Reducing sleep to 7.5s
2022/03/15 07:54:43 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:54:43 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 07:54:43 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Token expired - refreshing
2022/03/15 07:54:43 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getTokenByAuthToken(map[authtoken:622506e6346e7ad6-c48bf9558d23a2ae token:*]) options=[]
2022/03/15 07:54:44 DEBUG : pacer: Reducing sleep to 5.625s
2022/03/15 07:54:44 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:54:44 DEBUG : Saving config "token" in section "TestFileFabric" of the config file
2022/03/15 07:54:44 DEBUG : Config file has changed externaly - reloading
2022/03/15 07:54:44 DEBUG : Saving config "token_expiry" in section "TestFileFabric" of the config file
2022/03/15 07:54:44 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getApplianceInfo(map[token:*]) options=[]
2022/03/15 07:54:51 DEBUG : pacer: Reducing sleep to 4.21875s
2022/03/15 07:54:51 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:54:51 DEBUG : Saving config "version" in section "TestFileFabric" of the config file
2022/03/15 07:54:57 DEBUG : pacer: Reducing sleep to 3.1640625s
2022/03/15 07:54:57 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
--- PASS: TestMoveEmptyDirectories (1048.76s)
=== RUN   TestSyncEmptyDirectories
    run.go:181: Remote "filefabric root 'rclone-test-cipebig3rahekoz0qogedis9'", Local "Local file system at /tmp/rclone1921185003", Modify Window "1s"
2022/03/15 07:54:57 DEBUG : sub dir2: Making directory
2022/03/15 07:54:57 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 07:55:01 DEBUG : pacer: Reducing sleep to 2.373046875s
2022/03/15 07:55:01 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:55:01 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Waiting for checks to finish
2022/03/15 07:55:01 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Waiting for transfers to finish
2022/03/15 07:55:01 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 07:55:04 DEBUG : pacer: Reducing sleep to 1.779785156s
2022/03/15 07:55:04 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:55:04 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doCreateNewFolder(map[fi_name:sub dir fi_pid:121408854]) options=[]
2022/03/15 07:55:10 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Sleeping for 1s to wait for "error_background" error to clear
2022/03/15 07:55: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/15 07:55:11 DEBUG : pacer: Rate limited, increasing sleep to 3.559570312s
2022/03/15 07:55:11 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Sleeping for 2s to wait for "error_background" error to clear
2022/03/15 07:55:13 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/15 07:55:13 DEBUG : pacer: Rate limited, increasing sleep to 7.119140624s
2022/03/15 07:55:29 DEBUG : pacer: Reducing sleep to 5.339355468s
2022/03/15 07:55:29 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:55:29 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': 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:121408993 fi_size:11 responsetype:json]) options=[]
2022/03/15 07:55:31 DEBUG : pacer: Reducing sleep to 4.004516601s
2022/03/15 07:55:31 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:55:36 DEBUG : pacer: Reducing sleep to 3.00338745s
2022/03/15 07:55:36 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doCompleteUpload(map[fi_size:11 remotetime:2001-02-03 04:05:06 uploadcode:cfacd31ff5e69e8862a2044b16dc0895]) options=[]
2022/03/15 07:55:47 DEBUG : pacer: Reducing sleep to 2.252540587s
2022/03/15 07:55:47 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:55:47 INFO  : sub dir/hello world: Copied (new)
2022/03/15 07:55:47 DEBUG : sub dir2: Making directory
2022/03/15 07:55:47 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 07:55:59 DEBUG : pacer: Reducing sleep to 1.68940544s
2022/03/15 07:55:59 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:55:59 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doCreateNewFolder(map[fi_name:sub dir2 fi_pid:121408854]) options=[]
2022/03/15 07:56:16 DEBUG : pacer: Reducing sleep to 1.26705408s
2022/03/15 07:56:16 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:56:16 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': copied 1 directories
2022/03/15 07:56:16 DEBUG : Waiting for deletions to finish
2022/03/15 07:56:16 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 07:56:25 DEBUG : pacer: Reducing sleep to 950.29056ms
2022/03/15 07:56:25 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:56:25 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408995 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/15 07:56:25 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408993 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/15 07:56:42 DEBUG : pacer: Reducing sleep to 712.71792ms
2022/03/15 07:56:42 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:56:42 DEBUG : pacer: Reducing sleep to 534.53844ms
2022/03/15 07:56:42 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:56:42 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 07:56:42 DEBUG : pacer: Reducing sleep to 400.90383ms
2022/03/15 07:56:42 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:56:42 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408995 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/15 07:56:42 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408993 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/15 07:56:43 DEBUG : pacer: Reducing sleep to 300.677872ms
2022/03/15 07:56:43 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:56:43 DEBUG : pacer: Reducing sleep to 225.508404ms
2022/03/15 07:56:43 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:56:43 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doDeleteFile(map[completedeletion:n fi_id:121408994]) options=[]
2022/03/15 07:57:50 DEBUG : pacer: Reducing sleep to 169.131303ms
2022/03/15 07:57:50 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:57:50 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408995 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/15 07:57:50 DEBUG : pacer: Reducing sleep to 126.848477ms
2022/03/15 07:57:50 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:57:50 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doDeleteFolder(map[fi_id:121408995]) options=[]
2022/03/15 07:58:10 DEBUG : pacer: Reducing sleep to 95.136357ms
2022/03/15 07:58:10 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:58:10 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408993 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/15 07:58:35 DEBUG : pacer: Reducing sleep to 71.352267ms
2022/03/15 07:58:35 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 07:58:35 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doDeleteFolder(map[fi_id:121408993]) options=[]
2022/03/15 07:58:35 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Sleeping for 1s to wait for "error_background" error to clear
2022/03/15 07:58:36 DEBUG : pacer: low level retry 1/10 (error We are not able to complete the requested operation. We are processing move folder in parent folder. Please try again later. (error_background))
2022/03/15 07:58:36 DEBUG : pacer: Rate limited, increasing sleep to 142.704534ms
2022/03/15 07:58:39 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Sleeping for 2s to wait for "error_background" error to clear
2022/03/15 07:58:41 DEBUG : pacer: low level retry 2/10 (error We are not able to complete the requested operation. We are processing move folder in parent folder. Please try again later. (error_background))
2022/03/15 07:58:41 DEBUG : pacer: Rate limited, increasing sleep to 285.409068ms
2022/03/15 07:58:43 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Sleeping for 4s to wait for "error_background" error to clear
2022/03/15 07:58:47 DEBUG : pacer: low level retry 3/10 (error We are not able to complete the requested operation. We are processing move folder in parent folder. Please try again later. (error_background))
2022/03/15 07:58:47 DEBUG : pacer: Rate limited, increasing sleep to 570.818136ms
2022/03/15 07:58:48 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Sleeping for 8s to wait for "error_background" error to clear
2022/03/15 07:58:56 DEBUG : pacer: low level retry 4/10 (error We are not able to complete the requested operation. We are processing move folder in parent folder. Please try again later. (error_background))
2022/03/15 07:58:56 DEBUG : pacer: Rate limited, increasing sleep to 1.141636272s
2022/03/15 07:58:57 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Sleeping for 16s to wait for "error_background" error to clear
2022/03/15 07:59:13 DEBUG : pacer: low level retry 5/10 (error We are not able to complete the requested operation. We are processing move folder in parent folder. Please try again later. (error_background))
2022/03/15 07:59:13 DEBUG : pacer: Rate limited, increasing sleep to 2.283272544s
2022/03/15 07:59:16 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Sleeping for 32s to wait for "error_background" error to clear
2022/03/15 07:59:48 DEBUG : pacer: low level retry 6/10 (error We are not able to complete the requested operation. We are processing move folder in parent folder. Please try again later. (error_background))
2022/03/15 07:59:48 DEBUG : pacer: Rate limited, increasing sleep to 4.566545088s
2022/03/15 07:59:49 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Sleeping for 1m4s to wait for "error_background" error to clear
2022/03/15 08:00:53 DEBUG : pacer: low level retry 7/10 (error We are not able to complete the requested operation. We are processing move folder in parent folder. Please try again later. (error_background))
2022/03/15 08:00:53 DEBUG : pacer: Rate limited, increasing sleep to 9.133090176s
2022/03/15 08:00:56 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Sleeping for 2m8s to wait for "error_background" error to clear
2022/03/15 08:03:04 DEBUG : pacer: low level retry 8/10 (error We are not able to complete the requested operation. We are processing move folder in parent folder. Please try again later. (error_background))
2022/03/15 08:03:04 DEBUG : pacer: Rate limited, increasing sleep to 10s
2022/03/15 08:03:13 DEBUG : pacer: Reducing sleep to 7.5s
2022/03/15 08:03:13 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:03:13 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:03:15 DEBUG : pacer: Reducing sleep to 5.625s
2022/03/15 08:03:15 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
--- PASS: TestSyncEmptyDirectories (497.71s)
=== RUN   TestServerSideCopy
    run.go:181: Remote "filefabric root 'rclone-test-cipebig3rahekoz0qogedis9'", Local "Local file system at /tmp/rclone1921185003", Modify Window "1s"
2022/03/15 08:03:15 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:03:22 DEBUG : pacer: Reducing sleep to 4.21875s
2022/03/15 08:03:22 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:03:22 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doCreateNewFolder(map[fi_name:sub dir fi_pid:121408854]) options=[]
2022/03/15 08:03:30 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Sleeping for 1s to wait for "error_background" error to clear
2022/03/15 08:03:31 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/15 08:03:31 DEBUG : pacer: Rate limited, increasing sleep to 8.4375s
2022/03/15 08:03:34 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Sleeping for 2s to wait for "error_background" error to clear
2022/03/15 08:03: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/15 08:03:36 DEBUG : pacer: Rate limited, increasing sleep to 10s
2022/03/15 08:03:43 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Sleeping for 4s to wait for "error_background" error to clear
2022/03/15 08:03: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/15 08:03:50 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Sleeping for 8s to wait for "error_background" error to clear
2022/03/15 08:03:58 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/15 08:04:03 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Sleeping for 16s to wait for "error_background" error to clear
2022/03/15 08:04:19 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/15 08:04:20 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Sleeping for 32s to wait for "error_background" error to clear
2022/03/15 08:04: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/15 08:04:53 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Sleeping for 1m4s to wait for "error_background" error to clear
2022/03/15 08:05:57 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/15 08:06:00 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Sleeping for 2m8s to wait for "error_background" error to clear
2022/03/15 08:08:08 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/15 08:08:26 DEBUG : pacer: Reducing sleep to 7.5s
2022/03/15 08:08:26 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:08:26 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': 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:121409023 fi_size:11 responsetype:json]) options=[]
2022/03/15 08:08:27 DEBUG : pacer: Reducing sleep to 5.625s
2022/03/15 08:08:27 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:08:35 DEBUG : pacer: Reducing sleep to 4.21875s
2022/03/15 08:08:35 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doCompleteUpload(map[fi_size:11 remotetime:2001-02-03 04:05:06 uploadcode:2ebfd617b47bb00d5258d0e73eb0ffdc]) options=[]
2022/03/15 08:08:50 DEBUG : pacer: Reducing sleep to 3.1640625s
2022/03/15 08:08:50 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:08:50 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:09:04 DEBUG : pacer: Reducing sleep to 2.373046875s
2022/03/15 08:09:04 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:09:04 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121409023 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/15 08:09:13 DEBUG : pacer: Reducing sleep to 1.779785156s
2022/03/15 08:09:13 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:09:13 DEBUG : Creating backend with remote "TestFileFabric:rclone-test-ruseyil5xexepev6kobapaw8"
2022/03/15 08:09:13 DEBUG : Config file has changed externaly - reloading
2022/03/15 08:09:13 DEBUG : filefabric root 'rclone-test-ruseyil5xexepev6kobapaw8': rpc: checkPathExists(map[path:rclone-test-ruseyil5xexepev6kobapaw8 pid:120673762]) options=[]
2022/03/15 08:09:14 DEBUG : filefabric root 'rclone-test-ruseyil5xexepev6kobapaw8': >rpc: result=Success (ok), err=<nil>
    sync_test.go:275: Server side copy (if possible) filefabric root 'rclone-test-cipebig3rahekoz0qogedis9' -> filefabric root 'rclone-test-ruseyil5xexepev6kobapaw8'
2022/03/15 08:09:14 DEBUG : filefabric root 'rclone-test-ruseyil5xexepev6kobapaw8': 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/15 08:09:14 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:09:18 DEBUG : filefabric root 'rclone-test-ruseyil5xexepev6kobapaw8': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:09:26 DEBUG : pacer: Reducing sleep to 1.334838867s
2022/03/15 08:09:26 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:09:26 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121409023 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/15 08:09:46 DEBUG : pacer: Reducing sleep to 1.00112915s
2022/03/15 08:09:46 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:09:46 DEBUG : filefabric root 'rclone-test-ruseyil5xexepev6kobapaw8': Waiting for checks to finish
2022/03/15 08:09:46 DEBUG : filefabric root 'rclone-test-ruseyil5xexepev6kobapaw8': Waiting for transfers to finish
2022/03/15 08:09:46 DEBUG : filefabric root 'rclone-test-ruseyil5xexepev6kobapaw8': 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/15 08:09:47 DEBUG : filefabric root 'rclone-test-ruseyil5xexepev6kobapaw8': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:09:47 DEBUG : filefabric root 'rclone-test-ruseyil5xexepev6kobapaw8': rpc: doCreateNewFolder(map[fi_name:rclone-test-ruseyil5xexepev6kobapaw8 fi_pid:120673762]) options=[]
2022/03/15 08:10:10 DEBUG : filefabric root 'rclone-test-ruseyil5xexepev6kobapaw8': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:10:10 DEBUG : filefabric root 'rclone-test-ruseyil5xexepev6kobapaw8': rpc: getFolderContents(map[count:1000 fi_pid:121409029 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/15 08:10:23 DEBUG : filefabric root 'rclone-test-ruseyil5xexepev6kobapaw8': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:10:23 DEBUG : filefabric root 'rclone-test-ruseyil5xexepev6kobapaw8': rpc: doCreateNewFolder(map[fi_name:sub dir fi_pid:121409029]) options=[]
2022/03/15 08:10:47 DEBUG : filefabric root 'rclone-test-ruseyil5xexepev6kobapaw8': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:10:47 DEBUG : filefabric root 'rclone-test-ruseyil5xexepev6kobapaw8': rpc: doCopyFile(map[fi_id:121409025 fi_name:hello world fi_pid:121409031 force:y options:allownoextension]) options=[]
2022/03/15 08:11:07 DEBUG : filefabric root 'rclone-test-ruseyil5xexepev6kobapaw8': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:11:07 INFO  : sub dir/hello world: Copied (server-side copy)
2022/03/15 08:11:07 DEBUG : filefabric root 'rclone-test-ruseyil5xexepev6kobapaw8': rpc: getFolderContents(map[count:1000 fi_pid:121409029 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/15 08:11:32 DEBUG : filefabric root 'rclone-test-ruseyil5xexepev6kobapaw8': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:11:32 DEBUG : filefabric root 'rclone-test-ruseyil5xexepev6kobapaw8': rpc: getFolderContents(map[count:1000 fi_pid:121409031 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/15 08:11:58 DEBUG : filefabric root 'rclone-test-ruseyil5xexepev6kobapaw8': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:11:58 DEBUG : filefabric root 'rclone-test-ruseyil5xexepev6kobapaw8': Purge remote
2022/03/15 08:11:58 DEBUG : filefabric root 'rclone-test-ruseyil5xexepev6kobapaw8': rpc: doDeleteFolder(map[fi_id:121409029]) options=[]
2022/03/15 08:12:15 DEBUG : filefabric root 'rclone-test-ruseyil5xexepev6kobapaw8': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:12:15 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:12:15 DEBUG : pacer: Reducing sleep to 750.846862ms
2022/03/15 08:12:15 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:12:15 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121409023 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/15 08:12:16 DEBUG : pacer: Reducing sleep to 563.135146ms
2022/03/15 08:12:16 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:12:16 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doDeleteFile(map[completedeletion:n fi_id:121409025]) options=[]
2022/03/15 08:13:03 DEBUG : pacer: Reducing sleep to 422.351359ms
2022/03/15 08:13:03 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:13:03 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121409023 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/15 08:13:24 DEBUG : pacer: Reducing sleep to 316.763519ms
2022/03/15 08:13:24 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:13:24 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doDeleteFolder(map[fi_id:121409023]) options=[]
2022/03/15 08:13:46 DEBUG : pacer: Reducing sleep to 237.572639ms
2022/03/15 08:13:46 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:13:46 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:13:50 DEBUG : pacer: Reducing sleep to 178.179479ms
2022/03/15 08:13:50 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
--- PASS: TestServerSideCopy (635.56s)
=== RUN   TestCopyAfterDelete
    run.go:181: Remote "filefabric root 'rclone-test-cipebig3rahekoz0qogedis9'", Local "Local file system at /tmp/rclone1921185003", Modify Window "1s"
2022/03/15 08:13:50 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:13:51 DEBUG : pacer: Reducing sleep to 133.634609ms
2022/03/15 08:13:51 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:13:51 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doCreateNewFolder(map[fi_name:sub dir fi_pid:121408854]) options=[]
2022/03/15 08:13:55 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Sleeping for 1s to wait for "error_background" error to clear
2022/03/15 08:13:56 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/15 08:13:56 DEBUG : pacer: Rate limited, increasing sleep to 267.269218ms
2022/03/15 08:13:59 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Sleeping for 2s to wait for "error_background" error to clear
2022/03/15 08:14:01 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/15 08:14:01 DEBUG : pacer: Rate limited, increasing sleep to 534.538436ms
2022/03/15 08:14:03 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Sleeping for 4s to wait for "error_background" error to clear
2022/03/15 08:14:07 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/15 08:14:07 DEBUG : pacer: Rate limited, increasing sleep to 1.069076872s
2022/03/15 08:14:11 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Sleeping for 8s to wait for "error_background" error to clear
2022/03/15 08:14:19 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/15 08:14:19 DEBUG : pacer: Rate limited, increasing sleep to 2.138153744s
2022/03/15 08:14:20 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Sleeping for 16s to wait for "error_background" error to clear
2022/03/15 08:14:36 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/15 08:14:36 DEBUG : pacer: Rate limited, increasing sleep to 4.276307488s
2022/03/15 08:14:38 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Sleeping for 32s to wait for "error_background" error to clear
2022/03/15 08:15:10 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/15 08:15:10 DEBUG : pacer: Rate limited, increasing sleep to 8.552614976s
2022/03/15 08:15:13 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Sleeping for 1m4s to wait for "error_background" error to clear
2022/03/15 08:16:17 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/15 08:16:17 DEBUG : pacer: Rate limited, increasing sleep to 10s
2022/03/15 08:16:39 DEBUG : pacer: Reducing sleep to 7.5s
2022/03/15 08:16:39 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:16:39 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': 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:121409050 fi_size:11 responsetype:json]) options=[]
2022/03/15 08:16:41 DEBUG : pacer: Reducing sleep to 5.625s
2022/03/15 08:16:41 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:16:49 DEBUG : pacer: Reducing sleep to 4.21875s
2022/03/15 08:16:49 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doCompleteUpload(map[fi_size:11 remotetime:2001-02-03 04:05:06 uploadcode:67990062a20769d99eb7a381944821b5]) options=[]
2022/03/15 08:17:03 DEBUG : pacer: Reducing sleep to 3.1640625s
2022/03/15 08:17:03 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:17:03 ERROR : : error listing: directory not found
2022/03/15 08:17:03 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:17:11 DEBUG : pacer: Reducing sleep to 2.373046875s
2022/03/15 08:17:11 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:17:11 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121409050 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/15 08:17:31 DEBUG : pacer: Reducing sleep to 1.779785156s
2022/03/15 08:17:31 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:17:31 DEBUG : Local file system at /tmp/rclone1921185003: Making directory
2022/03/15 08:17:31 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:17:32 DEBUG : pacer: Reducing sleep to 1.334838867s
2022/03/15 08:17:32 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:17:32 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Waiting for checks to finish
2022/03/15 08:17:32 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Waiting for transfers to finish
2022/03/15 08:17:32 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:17:34 DEBUG : pacer: Reducing sleep to 1.00112915s
2022/03/15 08:17:34 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:17:34 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121409050 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/15 08:17:35 DEBUG : pacer: Reducing sleep to 750.846862ms
2022/03/15 08:17:35 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:17:35 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:17:36 DEBUG : pacer: Reducing sleep to 563.135146ms
2022/03/15 08:17:36 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:17:36 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121409050 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/15 08:17:37 DEBUG : pacer: Reducing sleep to 422.351359ms
2022/03/15 08:17:37 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:17:37 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doDeleteFile(map[completedeletion:n fi_id:121409051]) options=[]
2022/03/15 08:18:30 DEBUG : pacer: Reducing sleep to 316.763519ms
2022/03/15 08:18:30 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:18:30 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121409050 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/15 08:18:47 DEBUG : pacer: Reducing sleep to 237.572639ms
2022/03/15 08:18:47 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:18:47 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doDeleteFolder(map[fi_id:121409050]) options=[]
2022/03/15 08:19:03 DEBUG : pacer: Reducing sleep to 178.179479ms
2022/03/15 08:19:03 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:19:03 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:19:04 DEBUG : pacer: Reducing sleep to 133.634609ms
2022/03/15 08:19:04 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
--- PASS: TestCopyAfterDelete (313.80s)
=== RUN   TestCopyRedownload
    run.go:181: Remote "filefabric root 'rclone-test-cipebig3rahekoz0qogedis9'", Local "Local file system at /tmp/rclone1921185003", Modify Window "1s"
2022/03/15 08:19:04 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:19:04 DEBUG : pacer: Reducing sleep to 100.225956ms
2022/03/15 08:19:04 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:19:04 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doCreateNewFolder(map[fi_name:sub dir fi_pid:121408854]) options=[]
2022/03/15 08:19:08 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Sleeping for 1s to wait for "error_background" error to clear
2022/03/15 08:19:09 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/15 08:19:09 DEBUG : pacer: Rate limited, increasing sleep to 200.451912ms
2022/03/15 08:19:12 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Sleeping for 2s to wait for "error_background" error to clear
2022/03/15 08:19:14 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/15 08:19:14 DEBUG : pacer: Rate limited, increasing sleep to 400.903824ms
2022/03/15 08:19:16 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Sleeping for 4s to wait for "error_background" error to clear
2022/03/15 08:19:20 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/15 08:19:20 DEBUG : pacer: Rate limited, increasing sleep to 801.807648ms
2022/03/15 08:19:20 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Sleeping for 8s to wait for "error_background" error to clear
2022/03/15 08:19:28 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/15 08:19:28 DEBUG : pacer: Rate limited, increasing sleep to 1.603615296s
2022/03/15 08:19:30 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Sleeping for 16s to wait for "error_background" error to clear
2022/03/15 08:19:46 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/15 08:19:46 DEBUG : pacer: Rate limited, increasing sleep to 3.207230592s
2022/03/15 08:19:47 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Sleeping for 32s to wait for "error_background" error to clear
2022/03/15 08:20:19 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/15 08:20:19 DEBUG : pacer: Rate limited, increasing sleep to 6.414461184s
2022/03/15 08:20:20 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Sleeping for 1m4s to wait for "error_background" error to clear
2022/03/15 08:21:24 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/15 08:21:24 DEBUG : pacer: Rate limited, increasing sleep to 10s
2022/03/15 08:21:28 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Sleeping for 2m8s to wait for "error_background" error to clear
2022/03/15 08:23:36 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/15 08:23:49 DEBUG : pacer: Reducing sleep to 7.5s
2022/03/15 08:23:49 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:23:49 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': 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:121409067 fi_size:11 responsetype:json]) options=[]
2022/03/15 08:23:50 DEBUG : pacer: Reducing sleep to 5.625s
2022/03/15 08:23:50 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:23:58 DEBUG : pacer: Reducing sleep to 4.21875s
2022/03/15 08:23:58 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doCompleteUpload(map[fi_size:11 remotetime:2001-02-03 04:05:06 uploadcode:2b2a5a52c3aa54a0d31c7ee7ceb99af1]) options=[]
2022/03/15 08:24:07 DEBUG : pacer: Reducing sleep to 3.1640625s
2022/03/15 08:24:07 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:24:07 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:24:16 DEBUG : pacer: Reducing sleep to 2.373046875s
2022/03/15 08:24:16 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:24:16 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121409067 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/15 08:24:26 DEBUG : pacer: Reducing sleep to 1.779785156s
2022/03/15 08:24:26 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:24:26 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:24:27 DEBUG : pacer: Reducing sleep to 1.334838867s
2022/03/15 08:24:27 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:24:27 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121409067 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/15 08:24:42 DEBUG : pacer: Reducing sleep to 1.00112915s
2022/03/15 08:24:42 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:24:42 DEBUG : Local file system at /tmp/rclone1921185003: Waiting for checks to finish
2022/03/15 08:24:42 DEBUG : Local file system at /tmp/rclone1921185003: Waiting for transfers to finish
2022/03/15 08:24:42 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFile(map[fi_id:121409068]) options=[HashesOption([])]
2022/03/15 08:24:45 DEBUG : pacer: Reducing sleep to 750.846862ms
2022/03/15 08:24:45 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=<nil>, err=<nil>
2022/03/15 08:24:45 INFO  : sub dir/hello world: Copied (new)
2022/03/15 08:24:45 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:24:54 DEBUG : pacer: Reducing sleep to 563.135146ms
2022/03/15 08:24:54 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:24:54 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121409067 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/15 08:24:55 DEBUG : pacer: Reducing sleep to 422.351359ms
2022/03/15 08:24:55 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:24:55 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doDeleteFile(map[completedeletion:n fi_id:121409068]) options=[]
2022/03/15 08:25:31 DEBUG : pacer: Reducing sleep to 316.763519ms
2022/03/15 08:25:31 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:25:31 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121409067 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/15 08:25:44 DEBUG : pacer: Reducing sleep to 237.572639ms
2022/03/15 08:25:44 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:25:44 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doDeleteFolder(map[fi_id:121409067]) options=[]
2022/03/15 08:25:53 DEBUG : pacer: Reducing sleep to 178.179479ms
2022/03/15 08:25:53 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:25:53 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:25:54 DEBUG : pacer: Reducing sleep to 133.634609ms
2022/03/15 08:25:54 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
--- PASS: TestCopyRedownload (409.65s)
=== RUN   TestSyncBasedOnCheckSum
    run.go:181: Remote "filefabric root 'rclone-test-cipebig3rahekoz0qogedis9'", Local "Local file system at /tmp/rclone1921185003", Modify Window "1s"
2022/03/15 08:25:54 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:25:54 DEBUG : pacer: Reducing sleep to 100.225956ms
2022/03/15 08:25:54 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:25:54 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Waiting for checks to finish
2022/03/15 08:25:54 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Waiting for transfers to finish
2022/03/15 08:25:54 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': 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:121408854 fi_size:1 responsetype:json]) options=[]
2022/03/15 08:25:56 DEBUG : pacer: Reducing sleep to 75.169467ms
2022/03/15 08:25:56 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:25:57 DEBUG : pacer: Reducing sleep to 56.3771ms
2022/03/15 08:25:57 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doCompleteUpload(map[fi_size:1 remotetime:2001-02-03 04:05:06 uploadcode:d04adbff680ee89183b7a53700501eb2]) options=[]
2022/03/15 08:26:02 DEBUG : pacer: Reducing sleep to 42.282825ms
2022/03/15 08:26:02 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:26:02 INFO  : check sum: Copied (new)
2022/03/15 08:26:02 DEBUG : Waiting for deletions to finish
2022/03/15 08:26:02 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:26:03 DEBUG : pacer: Reducing sleep to 31.712118ms
2022/03/15 08:26:03 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:26:03 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:26:04 DEBUG : pacer: Reducing sleep to 23.784088ms
2022/03/15 08:26:04 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:26:04 NOTICE: filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': --checksum is in use but the source and destination have no hashes in common; falling back to --size-only
2022/03/15 08:26:04 DEBUG : check sum: Size of src and dst objects identical
2022/03/15 08:26:04 DEBUG : check sum: Unchanged skipping
2022/03/15 08:26:04 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Waiting for checks to finish
2022/03/15 08:26:04 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Waiting for transfers to finish
2022/03/15 08:26:04 DEBUG : Waiting for deletions to finish
2022/03/15 08:26:04 INFO  : There was nothing to transfer
2022/03/15 08:26:04 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:26:04 DEBUG : pacer: Reducing sleep to 20ms
2022/03/15 08:26:04 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:26:04 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:26:05 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:26:05 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doDeleteFile(map[completedeletion:n fi_id:121409073]) options=[]
2022/03/15 08:26:34 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:26:34 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:26:35 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
--- PASS: TestSyncBasedOnCheckSum (41.61s)
=== RUN   TestSyncSizeOnly
    run.go:181: Remote "filefabric root 'rclone-test-cipebig3rahekoz0qogedis9'", Local "Local file system at /tmp/rclone1921185003", Modify Window "1s"
2022/03/15 08:26:35 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:26:36 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:26:36 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Waiting for checks to finish
2022/03/15 08:26:36 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': 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:121408854 fi_size:6 responsetype:json]) options=[]
2022/03/15 08:26:36 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Waiting for transfers to finish
2022/03/15 08:26:40 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:26:42 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doCompleteUpload(map[fi_size:6 remotetime:2001-02-03 04:05:06 uploadcode:be925adff2555dd0779a8caf7f172e90]) options=[]
2022/03/15 08:26:47 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:26:47 INFO  : sizeonly: Copied (new)
2022/03/15 08:26:47 DEBUG : Waiting for deletions to finish
2022/03/15 08:26:47 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:26:51 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:26:51 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:26:52 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:26:52 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Waiting for checks to finish
2022/03/15 08:26:52 DEBUG : sizeonly: Sizes identical
2022/03/15 08:26:52 DEBUG : sizeonly: Unchanged skipping
2022/03/15 08:26:52 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Waiting for transfers to finish
2022/03/15 08:26:52 DEBUG : Waiting for deletions to finish
2022/03/15 08:26:52 INFO  : There was nothing to transfer
2022/03/15 08:26:52 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:26:56 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:26:56 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:26:56 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:26:56 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doDeleteFile(map[completedeletion:n fi_id:121409076]) options=[]
2022/03/15 08:27:25 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:27:25 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:27:26 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
--- PASS: TestSyncSizeOnly (50.70s)
=== RUN   TestSyncIgnoreSize
    run.go:181: Remote "filefabric root 'rclone-test-cipebig3rahekoz0qogedis9'", Local "Local file system at /tmp/rclone1921185003", Modify Window "1s"
2022/03/15 08:27:26 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:27:26 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:27:26 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Waiting for checks to finish
2022/03/15 08:27:26 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Waiting for transfers to finish
2022/03/15 08:27:26 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': 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:121408854 fi_size:8 responsetype:json]) options=[]
2022/03/15 08:27:31 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:27:33 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doCompleteUpload(map[fi_size:8 remotetime:2001-02-03 04:05:06 uploadcode:841acfafb120d96690864cfeb165fd92]) options=[]
2022/03/15 08:27:39 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:27:39 INFO  : ignore-size: Copied (new)
2022/03/15 08:27:39 DEBUG : Waiting for deletions to finish
2022/03/15 08:27:39 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:27:39 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:27:39 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:27:40 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:27:40 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Waiting for checks to finish
2022/03/15 08:27:40 DEBUG : ignore-size: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2022/03/15 08:27:40 DEBUG : ignore-size: Unchanged skipping
2022/03/15 08:27:40 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Waiting for transfers to finish
2022/03/15 08:27:40 DEBUG : Waiting for deletions to finish
2022/03/15 08:27:40 INFO  : There was nothing to transfer
2022/03/15 08:27:40 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:27:41 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:27:41 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:27:41 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:27:41 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doDeleteFile(map[completedeletion:n fi_id:121409077]) options=[]
2022/03/15 08:28:08 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:28:08 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:28:09 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
--- PASS: TestSyncIgnoreSize (42.93s)
=== RUN   TestSyncIgnoreTimes
    run.go:181: Remote "filefabric root 'rclone-test-cipebig3rahekoz0qogedis9'", Local "Local file system at /tmp/rclone1921185003", Modify Window "1s"
2022/03/15 08:28:09 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': 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:121408854 fi_size:6 responsetype:json]) options=[]
2022/03/15 08:28:10 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:28:12 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doCompleteUpload(map[fi_size:6 remotetime:2001-02-03 04:05:06 uploadcode:f77f75a2fa647f56cc13b8a80570b465]) options=[]
2022/03/15 08:28:21 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:28:21 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:28:22 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:28:22 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:28:23 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:28:23 DEBUG : existing: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2022/03/15 08:28:23 DEBUG : existing: Unchanged skipping
2022/03/15 08:28:23 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Waiting for checks to finish
2022/03/15 08:28:23 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Waiting for transfers to finish
2022/03/15 08:28:23 DEBUG : Waiting for deletions to finish
2022/03/15 08:28:23 INFO  : There was nothing to transfer
2022/03/15 08:28:23 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:28:23 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:28:23 DEBUG : existing: Transferring unconditionally as --ignore-times is in use
2022/03/15 08:28:23 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Waiting for checks to finish
2022/03/15 08:28:23 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Waiting for transfers to finish
2022/03/15 08:28:23 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': 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:121408854 fi_size:6 responsetype:json]) options=[]
2022/03/15 08:28:25 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:28:26 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doCompleteUpload(map[fi_size:6 remotetime:2001-02-03 04:05:06 uploadcode:1fc742bda0fcd8fda1ba38781166e8ca]) options=[]
2022/03/15 08:29:38 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:29:38 INFO  : existing: Copied (replaced existing)
2022/03/15 08:29:38 DEBUG : Waiting for deletions to finish
2022/03/15 08:29:38 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:29:51 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:29:51 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:29:51 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:29:51 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doDeleteFile(map[completedeletion:n fi_id:121409078]) options=[]
2022/03/15 08:30:20 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:30:20 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:30:40 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
--- PASS: TestSyncIgnoreTimes (151.65s)
=== RUN   TestSyncIgnoreExisting
    run.go:181: Remote "filefabric root 'rclone-test-cipebig3rahekoz0qogedis9'", Local "Local file system at /tmp/rclone1921185003", Modify Window "1s"
2022/03/15 08:30:40 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:30:41 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:30:41 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Waiting for checks to finish
2022/03/15 08:30:41 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Waiting for transfers to finish
2022/03/15 08:30:41 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': 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:121408854 fi_size:6 responsetype:json]) options=[]
2022/03/15 08:30:45 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:30:47 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doCompleteUpload(map[fi_size:6 remotetime:2001-02-03 04:05:06 uploadcode:49827162a16b037789fdaada4d6a8593]) options=[]
2022/03/15 08:30:53 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:30:53 INFO  : existing: Copied (new)
2022/03/15 08:30:53 DEBUG : Waiting for deletions to finish
2022/03/15 08:30:53 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:31:13 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:31:13 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:31:14 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:31:14 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Waiting for checks to finish
2022/03/15 08:31:14 DEBUG : existing: Destination exists, skipping
2022/03/15 08:31:14 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Waiting for transfers to finish
2022/03/15 08:31:14 DEBUG : Waiting for deletions to finish
2022/03/15 08:31:14 INFO  : There was nothing to transfer
2022/03/15 08:31:14 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:31:14 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:31:14 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:31:15 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:31:15 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doDeleteFile(map[completedeletion:n fi_id:121409084]) options=[]
2022/03/15 08:31:45 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:31:45 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:31:54 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
--- PASS: TestSyncIgnoreExisting (73.74s)
=== RUN   TestSyncIgnoreErrors
    run.go:181: Remote "filefabric root 'rclone-test-cipebig3rahekoz0qogedis9'", Local "Local file system at /tmp/rclone1921185003", Modify Window "1s"
2022/03/15 08:31:54 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:31:55 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:31:55 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doCreateNewFolder(map[fi_name:b fi_pid:121408854]) options=[]
2022/03/15 08:32:08 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:32:08 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': 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:121409085 fi_size:21 responsetype:json]) options=[]
2022/03/15 08:32:09 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:32:11 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doCompleteUpload(map[fi_size:21 remotetime:2011-12-25 12:59:59 uploadcode:8f4a4510568230ed80e9d302e75d947e]) options=[]
2022/03/15 08:32:16 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:32:16 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:32:29 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:32:29 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doCreateNewFolder(map[fi_name:c fi_pid:121408854]) options=[]
2022/03/15 08:32:42 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:32:42 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': 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:121409089 fi_size:5 responsetype:json]) options=[]
2022/03/15 08:32:43 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:32:45 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doCompleteUpload(map[fi_size:5 remotetime:2011-12-25 12:59:59 uploadcode:0dfb12c787f306a531bdf15695c30ef5]) options=[]
2022/03/15 08:32:50 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:32:50 DEBUG : d: Making directory
2022/03/15 08:32:50 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:33:04 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:33:04 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doCreateNewFolder(map[fi_name:d fi_pid:121408854]) options=[]
2022/03/15 08:33:21 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:33:21 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:33:34 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:33:34 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121409091 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/15 08:33:34 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121409089 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/15 08:33:34 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121409085 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/15 08:33:43 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:33:43 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:33:43 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:33:43 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:33:44 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:33:44 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121409089 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/15 08:33:44 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:33:45 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:33:45 DEBUG : c/non empty space: Size and modification time the same (differ by -123.456789ms, within tolerance 1s)
2022/03/15 08:33:45 DEBUG : c/non empty space: Unchanged skipping
2022/03/15 08:33:45 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:33:45 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doCreateNewFolder(map[fi_name:a fi_pid:121408854]) options=[]
2022/03/15 08:34:00 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:34:00 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': 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:121409094 fi_size:60 responsetype:json]) options=[]
2022/03/15 08:34:00 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121409085 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/15 08:34:00 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121409091 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/15 08:34:01 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:34:01 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:34:01 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Waiting for checks to finish
2022/03/15 08:34:01 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Waiting for transfers to finish
2022/03/15 08:34:05 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:34:07 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doCompleteUpload(map[fi_size:60 remotetime:2001-02-03 04:05:06 uploadcode:50b8e5c714a59b97aacbc346d212c39c]) options=[]
2022/03/15 08:34:17 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:34:17 INFO  : a/potato2: Copied (new)
2022/03/15 08:34:17 DEBUG : Waiting for deletions to finish
2022/03/15 08:34:17 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doDeleteFile(map[completedeletion:n fi_id:121409088]) options=[]
2022/03/15 08:35:00 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:35:00 INFO  : b/potato: Deleted
2022/03/15 08:35:00 INFO  : d: Removing directory
2022/03/15 08:35:00 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121409091 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/15 08:35:00 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:35:00 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doDeleteFolder(map[fi_id:121409091]) options=[]
2022/03/15 08:35:20 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:35:20 INFO  : b: Removing directory
2022/03/15 08:35:20 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121409085 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/15 08:35:33 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:35:33 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doDeleteFolder(map[fi_id:121409085]) options=[]
2022/03/15 08:35:46 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:35:46 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': deleted 2 directories
2022/03/15 08:35:46 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:35:47 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:35:47 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121409089 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/15 08:35:47 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121409094 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/15 08:35:48 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:36:07 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:36:07 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:36:08 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:36:08 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121409089 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/15 08:36:08 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121409094 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/15 08:36:08 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:36:08 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doDeleteFile(map[completedeletion:n fi_id:121409090]) options=[]
2022/03/15 08:36:08 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:36:56 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:36:56 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doDeleteFile(map[completedeletion:n fi_id:121409095]) options=[]
2022/03/15 08:37:39 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:37:39 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121409089 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/15 08:37:51 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:37:51 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doDeleteFolder(map[fi_id:121409089]) options=[]
2022/03/15 08:38:05 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:38:05 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121409094 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/15 08:38:29 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:38:29 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doDeleteFolder(map[fi_id:121409094]) options=[]
2022/03/15 08:38:45 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:38:45 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:38:46 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
--- PASS: TestSyncIgnoreErrors (411.61s)
=== RUN   TestSyncAfterChangingModtimeOnly
    run.go:181: Remote "filefabric root 'rclone-test-cipebig3rahekoz0qogedis9'", Local "Local file system at /tmp/rclone1921185003", Modify Window "1s"
2022/03/15 08:38:46 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': 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:121408854 fi_size:1 responsetype:json]) options=[]
2022/03/15 08:38:47 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:38:49 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doCompleteUpload(map[fi_size:1 remotetime:2001-02-03 04:05:06 uploadcode:4423feda22eee3503c40128bd9f565b5]) options=[]
2022/03/15 08:38:58 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:38:58 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:38:59 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:38:59 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:39:03 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:39:03 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Waiting for checks to finish
2022/03/15 08:39:03 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/15 08:39:03 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Waiting for transfers to finish
2022/03/15 08:39:03 NOTICE: empty space: Skipped copy as --dry-run is set (size 1)
2022/03/15 08:39:03 DEBUG : Waiting for deletions to finish
2022/03/15 08:39:03 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:39:04 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:39:04 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:39:04 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:39:04 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Waiting for checks to finish
2022/03/15 08:39:04 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/15 08:39:04 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Waiting for transfers to finish
2022/03/15 08:39:04 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': 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:121408854 fi_size:1 responsetype:json]) options=[]
2022/03/15 08:39:08 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:39:10 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doCompleteUpload(map[fi_size:1 remotetime:2011-12-25 12:59:59 uploadcode:a003a119fdaa4764cba4a3f3df7ead22]) options=[]
2022/03/15 08:40:30 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:40:30 INFO  : empty space: Copied (replaced existing)
2022/03/15 08:40:30 DEBUG : Waiting for deletions to finish
2022/03/15 08:40:30 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:40:31 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:40:31 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:40:31 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:40:31 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doDeleteFile(map[completedeletion:n fi_id:121409107]) options=[]
2022/03/15 08:40:57 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:40:57 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:41:18 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
--- PASS: TestSyncAfterChangingModtimeOnly (151.81s)
=== RUN   TestSyncAfterChangingModtimeOnlyWithNoUpdateModTime
    run.go:181: Remote "filefabric root 'rclone-test-cipebig3rahekoz0qogedis9'", Local "Local file system at /tmp/rclone1921185003", Modify Window "1s"
    sync_test.go:577: Can't check this if no hashes supported
2022/03/15 08:41:18 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:41:18 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:41:18 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:41:19 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
--- PASS: TestSyncAfterChangingModtimeOnlyWithNoUpdateModTime (1.19s)
=== RUN   TestSyncDoesntUpdateModtime
    run.go:181: Remote "filefabric root 'rclone-test-cipebig3rahekoz0qogedis9'", Local "Local file system at /tmp/rclone1921185003", Modify Window "1s"
2022/03/15 08:41:19 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': 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:121408854 fi_size:3 responsetype:json]) options=[]
2022/03/15 08:41:23 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:41:25 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doCompleteUpload(map[fi_size:3 remotetime:2001-02-03 04:05:06 uploadcode:b12ad223f3442cd7cb0d3380a663ec04]) options=[]
2022/03/15 08:41:31 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:41:31 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:41:43 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:41:43 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:41:44 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:41:44 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/15 08:41:44 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Waiting for checks to finish
2022/03/15 08:41:44 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Waiting for transfers to finish
2022/03/15 08:41:44 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': 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:121408854 fi_size:3 responsetype:json]) options=[]
2022/03/15 08:41:45 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:41:47 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doCompleteUpload(map[fi_size:3 remotetime:2011-12-25 12:59:59 uploadcode:717a33c0318c89e7cab0aa89f2db830f]) options=[]
2022/03/15 08:43:13 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:43:13 INFO  : foo: Copied (replaced existing)
2022/03/15 08:43:13 DEBUG : Waiting for deletions to finish
2022/03/15 08:43:13 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:43:34 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:43:34 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:43:35 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:43:35 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doDeleteFile(map[completedeletion:n fi_id:121409113]) options=[]
2022/03/15 08:44:13 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:44:13 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:44:23 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
--- PASS: TestSyncDoesntUpdateModtime (184.21s)
=== RUN   TestSyncAfterAddingAFile
    run.go:181: Remote "filefabric root 'rclone-test-cipebig3rahekoz0qogedis9'", Local "Local file system at /tmp/rclone1921185003", Modify Window "1s"
2022/03/15 08:44:23 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': 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:121408854 fi_size:1 responsetype:json]) options=[]
2022/03/15 08:44:24 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:44:26 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doCompleteUpload(map[fi_size:1 remotetime:2011-12-25 12:59:59 uploadcode:285b8c084a3a8d990e154c6e3641825e]) options=[]
2022/03/15 08:44:32 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:44:32 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:44:44 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:44:44 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:44:45 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:44:45 DEBUG : empty space: Size and modification time the same (differ by -123.456789ms, within tolerance 1s)
2022/03/15 08:44:45 DEBUG : empty space: Unchanged skipping
2022/03/15 08:44:45 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': 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:121408854 fi_size:60 responsetype:json]) options=[]
2022/03/15 08:44:45 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Waiting for checks to finish
2022/03/15 08:44:45 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Waiting for transfers to finish
2022/03/15 08:44:49 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:44:51 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doCompleteUpload(map[fi_size:60 remotetime:2011-12-30 12:59:59 uploadcode:324b8d1f8db58fc319732387894e69fb]) options=[]
2022/03/15 08:44:58 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:44:58 INFO  : potato: Copied (new)
2022/03/15 08:44:58 DEBUG : Waiting for deletions to finish
2022/03/15 08:44:58 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:45:11 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:45:11 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:45:11 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:45:11 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doDeleteFile(map[completedeletion:n fi_id:121409122]) options=[]
2022/03/15 08:45:54 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:45:54 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doDeleteFile(map[completedeletion:n fi_id:121409124]) options=[]
2022/03/15 08:46:33 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:46:33 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:46:45 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
--- PASS: TestSyncAfterAddingAFile (142.43s)
=== RUN   TestSyncAfterChangingFilesSizeOnly
    run.go:181: Remote "filefabric root 'rclone-test-cipebig3rahekoz0qogedis9'", Local "Local file system at /tmp/rclone1921185003", Modify Window "1s"
2022/03/15 08:46:45 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': 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:121408854 fi_size:60 responsetype:json]) options=[]
2022/03/15 08:46:51 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:46:52 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doCompleteUpload(map[fi_size:60 remotetime:2011-12-30 12:59:59 uploadcode:d8e8e47466eee4a0a2b3197b300c906b]) options=[]
2022/03/15 08:46:58 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:46:58 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:47:07 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:47:07 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:47:08 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:47:08 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Waiting for checks to finish
2022/03/15 08:47:08 DEBUG : potato: Sizes differ (src 21 vs dst 60)
2022/03/15 08:47:08 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Waiting for transfers to finish
2022/03/15 08:47:08 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': 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:121408854 fi_size:21 responsetype:json]) options=[]
2022/03/15 08:47:12 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:47:14 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doCompleteUpload(map[fi_size:21 remotetime:2011-12-30 12:59:59 uploadcode:8556a50cc1f3b633253fd045b7a26b21]) options=[]
2022/03/15 08:48:22 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:48:22 INFO  : potato: Copied (replaced existing)
2022/03/15 08:48:22 DEBUG : Waiting for deletions to finish
2022/03/15 08:48:22 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:48:47 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:48:47 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:48:48 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:48:48 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doDeleteFile(map[completedeletion:n fi_id:121409127]) options=[]
2022/03/15 08:49:23 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:49:23 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:49:32 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
--- PASS: TestSyncAfterChangingFilesSizeOnly (166.75s)
=== RUN   TestSyncAfterChangingContentsOnly
    run.go:181: Remote "filefabric root 'rclone-test-cipebig3rahekoz0qogedis9'", Local "Local file system at /tmp/rclone1921185003", Modify Window "1s"
2022/03/15 08:49:32 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': 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:121408854 fi_size:21 responsetype:json]) options=[]
2022/03/15 08:49:37 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:49:39 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doCompleteUpload(map[fi_size:21 remotetime:2011-12-30 12:59:59 uploadcode:b8b178cef12b21d53e0e9b059b6902ce]) options=[]
2022/03/15 08:49:45 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:49:45 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:49:45 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Token expired - refreshing
2022/03/15 08:49:45 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getTokenByAuthToken(map[authtoken:622506e6346e7ad6-c48bf9558d23a2ae token:*]) options=[]
2022/03/15 08:49:47 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:49:47 DEBUG : Saving config "token" in section "TestFileFabric" of the config file
2022/03/15 08:49:47 DEBUG : Saving config "token_expiry" in section "TestFileFabric" of the config file
2022/03/15 08:49:47 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getApplianceInfo(map[token:*]) options=[]
2022/03/15 08:49:47 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:49:47 DEBUG : Saving config "version" in section "TestFileFabric" of the config file
2022/03/15 08:49:47 DEBUG : Config file has changed externaly - reloading
2022/03/15 08:49:56 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:49:56 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:49:57 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:49:57 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Waiting for checks to finish
2022/03/15 08:49:57 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/15 08:49:57 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Waiting for transfers to finish
2022/03/15 08:49:57 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': 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:121408854 fi_size:21 responsetype:json]) options=[]
2022/03/15 08:49:58 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:50:00 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doCompleteUpload(map[fi_size:21 remotetime:2011-12-25 12:59:59 uploadcode:b156c2fb4782992c9e51239b323459b7]) options=[]
2022/03/15 08:51:22 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:51:22 INFO  : potato: Copied (replaced existing)
2022/03/15 08:51:22 DEBUG : Waiting for deletions to finish
2022/03/15 08:51:22 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:51:35 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:51:35 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:51:36 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:51:36 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doDeleteFile(map[completedeletion:n fi_id:121409133]) options=[]
2022/03/15 08:52:26 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:52:26 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:52:40 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
--- PASS: TestSyncAfterChangingContentsOnly (187.69s)
=== RUN   TestSyncAfterRemovingAFileAndAddingAFileDryRun
    run.go:181: Remote "filefabric root 'rclone-test-cipebig3rahekoz0qogedis9'", Local "Local file system at /tmp/rclone1921185003", Modify Window "1s"
2022/03/15 08:52:40 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': 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:121408854 fi_size:21 responsetype:json]) options=[]
2022/03/15 08:52:41 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:52:43 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doCompleteUpload(map[fi_size:21 remotetime:2011-12-25 12:59:59 uploadcode:a9e7ac0f954be75a08d85a8de0289554]) options=[]
2022/03/15 08:52:53 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:52:53 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': 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:121408854 fi_size:1 responsetype:json]) options=[]
2022/03/15 08:52:55 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:52:56 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doCompleteUpload(map[fi_size:1 remotetime:2011-12-25 12:59:59 uploadcode:43c34aadd964fe4951a982aa79eddbd2]) options=[]
2022/03/15 08:53:06 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:53:06 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:53:18 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:53:18 NOTICE: potato2: Skipped copy as --dry-run is set (size 60)
2022/03/15 08:53:18 DEBUG : empty space: Size and modification time the same (differ by -123.456789ms, within tolerance 1s)
2022/03/15 08:53:18 DEBUG : empty space: Unchanged skipping
2022/03/15 08:53:18 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Waiting for checks to finish
2022/03/15 08:53:18 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Waiting for transfers to finish
2022/03/15 08:53:18 DEBUG : Waiting for deletions to finish
2022/03/15 08:53:18 NOTICE: potato: Skipped delete as --dry-run is set (size 21)
2022/03/15 08:53:18 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:53:19 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:53:19 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:53:19 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:53:19 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doDeleteFile(map[completedeletion:n fi_id:121409139]) options=[]
2022/03/15 08:54:14 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:54:14 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doDeleteFile(map[completedeletion:n fi_id:121409138]) options=[]
2022/03/15 08:54:55 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:54:55 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:55:08 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
--- PASS: TestSyncAfterRemovingAFileAndAddingAFileDryRun (148.32s)
=== RUN   TestSyncAfterRemovingAFileAndAddingAFile
    run.go:181: Remote "filefabric root 'rclone-test-cipebig3rahekoz0qogedis9'", Local "Local file system at /tmp/rclone1921185003", Modify Window "1s"
2022/03/15 08:55:08 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': 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:121408854 fi_size:21 responsetype:json]) options=[]
2022/03/15 08:55:10 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:55:11 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doCompleteUpload(map[fi_size:21 remotetime:2011-12-25 12:59:59 uploadcode:b070fa1acc905ed9d465e0d8bbfcd50b]) options=[]
2022/03/15 08:55:17 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:55:17 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': 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:121408854 fi_size:1 responsetype:json]) options=[]
2022/03/15 08:55:19 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:55:20 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doCompleteUpload(map[fi_size:1 remotetime:2011-12-25 12:59:59 uploadcode:72dfd978cd3c5c797bb34372115b3f63]) options=[]
2022/03/15 08:55:30 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:55:30 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:55:43 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:55:43 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:55:44 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:55:44 DEBUG : empty space: Size and modification time the same (differ by -123.456789ms, within tolerance 1s)
2022/03/15 08:55:44 DEBUG : empty space: Unchanged skipping
2022/03/15 08:55:44 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Waiting for checks to finish
2022/03/15 08:55:44 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': Waiting for transfers to finish
2022/03/15 08:55:44 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': 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:121408854 fi_size:60 responsetype:json]) options=[]
2022/03/15 08:55:48 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:55:50 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doCompleteUpload(map[fi_size:60 remotetime:2001-02-03 04:05:06 uploadcode:0a5b111b74d921469ae0484aea92c061]) options=[]
2022/03/15 08:56:03 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:56:03 INFO  : potato2: Copied (new)
2022/03/15 08:56:03 DEBUG : Waiting for deletions to finish
2022/03/15 08:56:03 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doDeleteFile(map[completedeletion:n fi_id:121409148]) options=[]
2022/03/15 08:56:54 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:56:54 INFO  : potato: Deleted
2022/03/15 08:56:54 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:57:07 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:57:07 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:57:07 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:57:07 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doDeleteFile(map[completedeletion:n fi_id:121409149]) options=[]
2022/03/15 08:57:49 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:57:49 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doDeleteFile(map[completedeletion:n fi_id:121409151]) options=[]
2022/03/15 08:58:43 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:58:43 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:59:04 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
--- PASS: TestSyncAfterRemovingAFileAndAddingAFile (235.50s)
=== RUN   TestSyncAfterRemovingAFileAndAddingAFileSubDir
    run.go:181: Remote "filefabric root 'rclone-test-cipebig3rahekoz0qogedis9'", Local "Local file system at /tmp/rclone1921185003", Modify Window "1s"
2022/03/15 08:59:04 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:59:04 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:59:04 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doCreateNewFolder(map[fi_name:b fi_pid:121408854]) options=[]
2022/03/15 08:59:33 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:59:33 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': 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:121409159 fi_size:21 responsetype:json]) options=[]
2022/03/15 08:59:38 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:59:40 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doCompleteUpload(map[fi_size:21 remotetime:2011-12-25 12:59:59 uploadcode:8de51e894a212f299fa7ce070537c6de]) options=[]
2022/03/15 08:59:46 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:59:46 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 08:59:55 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 08:59:55 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doCreateNewFolder(map[fi_name:c fi_pid:121408854]) options=[]
2022/03/15 09:00:16 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 09:00:16 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': 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:121409163 fi_size:5 responsetype:json]) options=[]
2022/03/15 09:00:21 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 09:00:23 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doCompleteUpload(map[fi_size:5 remotetime:2011-12-25 12:59:59 uploadcode:38cff309c033697517fda0c58e82f88f]) options=[]
2022/03/15 09:00:29 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 09:00:29 DEBUG : d: Making directory
2022/03/15 09:00:29 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: getFolderContents(map[count:1000 fi_pid:121408854 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/15 09:00:45 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': >rpc: result=Success (ok), err=<nil>
2022/03/15 09:00:45 DEBUG : filefabric root 'rclone-test-cipebig3rahekoz0qogedis9': rpc: doCreateNewFolder(map[fi_name:d fi_pid:121408854]) options=[]
panic: test timed out after 2h0m0s

goroutine 6728 [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(0xc000304d00, {0x191b34c, 0x46d533}, 0x196d300)
	/usr/local/go/src/testing/testing.go:1307 +0x375
testing.runTests.func1(0xc00094e780)
	/usr/local/go/src/testing/testing.go:1598 +0x6e
testing.tRunner(0xc000304d00, 0xc0006fbca0)
	/usr/local/go/src/testing/testing.go:1259 +0x102
testing.runTests(0xc0000f7080, {0x28c2fa0, 0x4a, 0x4a}, {0xead840, 0xc000336330, 0x28d0040})
	/usr/local/go/src/testing/testing.go:1596 +0x43f
testing.(*M).Run(0xc0000f7080)
	/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 18 [select]:
go.opencensus.io/stats/view.(*worker).start(0xc00015e780)
	/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 6642 [select]:
net/http.(*persistConn).roundTrip(0xc000746d80, 0xc000994640)
	/usr/local/go/src/net/http/transport.go:2614 +0x97d
net/http.(*Transport).roundTrip(0xc000335900, 0xc00033cd00)
	/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(0xc0000959f0, 0xc00033cd00)
	/home/rclone/go/src/github.com/rclone/rclone/fs/fshttp/http.go:274 +0x4c8
net/http.send(0xc00033cd00, {0x1c38f20, 0xc0000959f0}, {0x187fa00, 0x1, 0x0})
	/usr/local/go/src/net/http/client.go:252 +0x5d8
net/http.(*Client).send(0xc000124630, 0xc00033cd00, {0xc00069cab0, 0x2f, 0x0})
	/usr/local/go/src/net/http/client.go:176 +0x9b
net/http.(*Client).do(0xc000124630, 0xc00033cd00)
	/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(0xc000095a40, {0x1c6e450, 0xc000040058}, 0xc000746c60)
	/home/rclone/go/src/github.com/rclone/rclone/lib/rest/rest.go:288 +0xc45
github.com/rclone/rclone/lib/rest.(*Client).callCodec(0x283fb60, {0x1c6e450, 0xc000040058}, 0xc000734a00, {0x0, 0x0}, {0x1655280, 0xc000265140}, 0xc00069ca20, 0x196d490, ...)
	/home/rclone/go/src/github.com/rclone/rclone/lib/rest/rest.go:485 +0x465
github.com/rclone/rclone/lib/rest.(*Client).CallJSON(...)
	/home/rclone/go/src/github.com/rclone/rclone/lib/rest/rest.go:428
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(0xc00008afc0, 0x10000c0002b3698, 0x100000000000000)
	/home/rclone/go/src/github.com/rclone/rclone/fs/pacer.go:88 +0x38
github.com/rclone/rclone/lib/pacer.(*Pacer).call(0xc00008afc0, 0xc0002b36e0, 0xa)
	/home/rclone/go/src/github.com/rclone/rclone/lib/pacer/pacer.go:197 +0x85
github.com/rclone/rclone/lib/pacer.(*Pacer).Call(0xc00008afc0, 0xc00069ca50)
	/home/rclone/go/src/github.com/rclone/rclone/lib/pacer/pacer.go:216 +0x90
github.com/rclone/rclone/backend/filefabric.(*Fs).rpc(0xc00022b300, {0x1c6e450, 0xc000040058}, {0x18d215e, 0x9}, 0xc00069c930, {0x1c599f0, 0xc000265140}, {0x0, 0x0, ...})
	/home/rclone/go/src/github.com/rclone/rclone/backend/filefabric/filefabric.go:407 +0x90b
github.com/rclone/rclone/backend/filefabric.(*Fs).CreateDir(0xc00022b300, {0x1c6e450, 0xc000040058}, {0xc0002d1707, 0x9}, {0x1c11c30, 0x1})
	/home/rclone/go/src/github.com/rclone/rclone/backend/filefabric/filefabric.go:560 +0x1ad
github.com/rclone/rclone/lib/dircache.(*DirCache)._findDir(0xc00074a990, {0x1c6e450, 0xc000040058}, {0x1c11c30, 0xc000364230}, 0x1)
	/home/rclone/go/src/github.com/rclone/rclone/lib/dircache/dircache.go:242 +0x189
github.com/rclone/rclone/lib/dircache.(*DirCache).FindDir(0xc00074a990, {0x1c6e450, 0xc000040058}, {0x1c11c30, 0x1}, 0x1)
	/home/rclone/go/src/github.com/rclone/rclone/lib/dircache/dircache.go:205 +0x15a
github.com/rclone/rclone/backend/filefabric.(*Fs).Mkdir(0x15637a0, {0x1c6e450, 0xc000040058}, {0x1c11c30, 0x0})
	/home/rclone/go/src/github.com/rclone/rclone/backend/filefabric/filefabric.go:717 +0x35
github.com/rclone/rclone/fs/operations.Mkdir({0x1c6e450, 0xc000040058}, {0x1c9d078, 0xc00022b300}, {0x1c11c30, 0xc000040058})
	/home/rclone/go/src/github.com/rclone/rclone/fs/operations/operations.go:1113 +0x113
github.com/rclone/rclone/fs/sync.testSyncAfterRemovingAFileAndAddingAFileSubDir({0x1c6e450, 0xc000040058}, 0x48de17)
	/home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync_test.go:727 +0x36f
github.com/rclone/rclone/fs/sync.TestSyncAfterRemovingAFileAndAddingAFileSubDir(0xc0003a4e00)
	/home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync_test.go:784 +0x2a
testing.tRunner(0xc000304b60, 0x196d300)
	/usr/local/go/src/testing/testing.go:1259 +0x102
created by testing.(*T).Run
	/usr/local/go/src/testing/testing.go:1306 +0x35a

goroutine 6718 [IO wait]:
internal/poll.runtime_pollWait(0x7f065d440e48, 0x72)
	/usr/local/go/src/runtime/netpoll.go:234 +0x89
internal/poll.(*pollDesc).wait(0xc0005fe480, 0xc000755500, 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(0xc0005fe480, {0xc000755500, 0x1481, 0x1481})
	/usr/local/go/src/internal/poll/fd_unix.go:167 +0x25a
net.(*netFD).Read(0xc0005fe480, {0xc000755500, 0x4fce78, 0x61})
	/usr/local/go/src/net/fd_posix.go:56 +0x29
net.(*conn).Read(0xc00031c0a0, {0xc000755500, 0x681cc5, 0xc0006a4a80})
	/usr/local/go/src/net/net.go:183 +0x45
github.com/rclone/rclone/fs/fshttp.(*timeoutConn).Read(0xc0001175d8, {0xc000755500, 0xc00087b260, 0x100000000000000})
	/home/rclone/go/src/github.com/rclone/rclone/fs/fshttp/dialer.go:104 +0x32
crypto/tls.(*atLeastReader).Read(0xc000850768, {0xc000755500, 0x0, 0x40ba4d})
	/usr/local/go/src/crypto/tls/conn.go:777 +0x3d
bytes.(*Buffer).ReadFrom(0xc0006a53f8, {0x1c35c40, 0xc000850768})
	/usr/local/go/src/bytes/buffer.go:204 +0x98
crypto/tls.(*Conn).readFromUntil(0xc0006a5180, {0x7f065c229918, 0xc0001175d8}, 0x346cd480853ab59)
	/usr/local/go/src/crypto/tls/conn.go:799 +0xe5
crypto/tls.(*Conn).readRecordOrCCS(0xc0006a5180, 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(0xc0006a5180, {0xc000484000, 0x1000, 0x101000000203000})
	/usr/local/go/src/crypto/tls/conn.go:1277 +0x16f
net/http.(*persistConn).Read(0xc000746d80, {0xc000484000, 0x406f1d, 0x60})
	/usr/local/go/src/net/http/transport.go:1926 +0x4e
bufio.(*Reader).fill(0xc0003e8ae0)
	/usr/local/go/src/bufio/bufio.go:101 +0x103
bufio.(*Reader).Peek(0xc0003e8ae0, 0x1)
	/usr/local/go/src/bufio/bufio.go:139 +0x5d
net/http.(*persistConn).readLoop(0xc000746d80)
	/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 276 [syscall, 119 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 277 [chan receive, 119 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 6719 [select]:
net/http.(*persistConn).writeLoop(0xc000746d80)
	/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
"./sync.test -test.v -test.timeout 2h0m0s -remote TestFileFabric: -verbose" - Finished ERROR in 2h0m0.530467358s (try 1/5): exit status 2: Failed []