"./sync.test -test.v -test.timeout 1h0m0s -remote TestGoFile: -verbose -test.run '^(TestServerSideCopyOverSelf|TestServerSideMoveWithFilter|TestSyncAfterRemovingAFileAndAddingAFileSubDir|TestSyncSetDelayedModTimes|TestSyncSuffix)$'" - Starting (try 2/5) 2025/01/15 02:13:41 DEBUG : Creating backend with remote "TestGoFile:rclone-test-howipaw3wiyi" 2025/01/15 02:13:41 DEBUG : Using config file from "/home/rclone/.rclone.conf" 2025/01/15 02:13:42 DEBUG : Creating backend with remote "/tmp/rclone4101559309" === RUN TestSyncSetDelayedModTimes run.go:180: Remote "gofile root 'rclone-test-howipaw3wiyi'", Local "Local file system at /tmp/rclone4101559309", Modify Window "1s" 2025/01/15 02:13:42 INFO : a1/b2/c1/d1/e1/f1: Set directory modification time (using DirSetModTime) 2025/01/15 02:13:42 INFO : a1/b2/c1/d1/e1: Set directory modification time (using DirSetModTime) 2025/01/15 02:13:42 INFO : a1/b2/c1/d1: Set directory modification time (using DirSetModTime) 2025/01/15 02:13:42 INFO : a1/b2/c1: Set directory modification time (using DirSetModTime) 2025/01/15 02:13:42 INFO : a1/b2: Set directory modification time (using DirSetModTime) 2025/01/15 02:13:42 INFO : a1/b1/c1/d2/e1/f2: Set directory modification time (using DirSetModTime) 2025/01/15 02:13:42 INFO : a1/b1/c1/d2/e1/f1: Set directory modification time (using DirSetModTime) 2025/01/15 02:13:42 INFO : a1/b1/c1/d2/e1: Set directory modification time (using DirSetModTime) 2025/01/15 02:13:42 INFO : a1/b1/c1/d2: Set directory modification time (using DirSetModTime) 2025/01/15 02:13:42 INFO : a1/b1/c1/d1/e1/f1: Set directory modification time (using DirSetModTime) 2025/01/15 02:13:42 INFO : a1/b1/c1/d1/e1: Set directory modification time (using DirSetModTime) 2025/01/15 02:13:42 INFO : a1/b1/c1/d1: Set directory modification time (using DirSetModTime) 2025/01/15 02:13:42 INFO : a1/b1/c1: Set directory modification time (using DirSetModTime) 2025/01/15 02:13:42 INFO : a1/b1: Set directory modification time (using DirSetModTime) 2025/01/15 02:13:42 INFO : a1: Set directory modification time (using DirSetModTime) 2025/01/15 02:13:43 INFO : a1: Making directory 2025/01/15 02:13:44 INFO : a1: Made directory with modification time 2001-02-03 04:19:06.499999999 +0000 UTC 2025/01/15 02:13:44 DEBUG : Added delayed dir = "a1", newDst= 2025/01/15 02:13:44 INFO : a1/b1: Making directory 2025/01/15 02:13:45 INFO : a1/b1: Made directory with modification time 2001-02-03 04:18:06.499999999 +0000 UTC 2025/01/15 02:13:45 DEBUG : Added delayed dir = "a1/b1", newDst= 2025/01/15 02:13:45 INFO : a1/b2: Making directory 2025/01/15 02:13:46 INFO : a1/b2: Made directory with modification time 2001-02-03 04:09:06.499999999 +0000 UTC 2025/01/15 02:13:46 DEBUG : Added delayed dir = "a1/b2", newDst= 2025/01/15 02:13:46 INFO : a1/b2/c1: Making directory 2025/01/15 02:13:46 INFO : a1/b1/c1: Making directory 2025/01/15 02:13:47 INFO : a1/b2/c1: Made directory with modification time 2001-02-03 04:08:06.499999999 +0000 UTC 2025/01/15 02:13:47 DEBUG : Added delayed dir = "a1/b2/c1", newDst= 2025/01/15 02:13:47 INFO : a1/b2/c1/d1: Making directory 2025/01/15 02:13:48 INFO : a1/b1/c1: Made directory with modification time 2001-02-03 04:17:06.499999999 +0000 UTC 2025/01/15 02:13:48 DEBUG : Added delayed dir = "a1/b1/c1", newDst= 2025/01/15 02:13:48 INFO : a1/b1/c1/d1: Making directory 2025/01/15 02:13:49 INFO : a1/b2/c1/d1: Made directory with modification time 2001-02-03 04:07:06.499999999 +0000 UTC 2025/01/15 02:13:49 DEBUG : Added delayed dir = "a1/b2/c1/d1", newDst= 2025/01/15 02:13:49 INFO : a1/b2/c1/d1/e1: Making directory 2025/01/15 02:13:50 INFO : a1/b1/c1/d1: Made directory with modification time 2001-02-03 04:16:06.499999999 +0000 UTC 2025/01/15 02:13:50 DEBUG : Added delayed dir = "a1/b1/c1/d1", newDst= 2025/01/15 02:13:50 INFO : a1/b1/c1/d2: Making directory 2025/01/15 02:13:50 INFO : a1/b2/c1/d1/e1: Made directory with modification time 2001-02-03 04:06:06.499999999 +0000 UTC 2025/01/15 02:13:50 DEBUG : Added delayed dir = "a1/b2/c1/d1/e1", newDst= 2025/01/15 02:13:50 INFO : a1/b2/c1/d1/e1/f1: Making directory 2025/01/15 02:13:51 DEBUG : Rate limited, sleep for 5s 2025/01/15 02:13:51 INFO : a1/b1/c1/d2: Made directory with modification time 2001-02-03 04:13:06.499999999 +0000 UTC 2025/01/15 02:13:51 DEBUG : Added delayed dir = "a1/b1/c1/d2", newDst= 2025/01/15 02:13:51 INFO : a1/b1/c1/d2/e1: Making directory 2025/01/15 02:13:51 INFO : a1/b1/c1/d1/e1: Making directory 2025/01/15 02:13:56 DEBUG : pacer: low level retry 1/10 (error Error "error-rateLimit") 2025/01/15 02:13:56 DEBUG : pacer: Rate limited, increasing sleep to 20ms 2025/01/15 02:13:57 DEBUG : pacer: Reducing sleep to 10ms 2025/01/15 02:13:57 INFO : a1/b2/c1/d1/e1/f1: Made directory with modification time 2001-02-03 04:05:06.499999999 +0000 UTC 2025/01/15 02:13:57 DEBUG : Added delayed dir = "a1/b2/c1/d1/e1/f1", newDst= 2025/01/15 02:13:58 INFO : a1/b1/c1/d2/e1: Made directory with modification time 2001-02-03 04:12:06.499999999 +0000 UTC 2025/01/15 02:13:58 DEBUG : Added delayed dir = "a1/b1/c1/d2/e1", newDst= 2025/01/15 02:13:58 INFO : a1/b1/c1/d2/e1/f1: Making directory 2025/01/15 02:13:58 INFO : a1/b1/c1/d1/e1: Made directory with modification time 2001-02-03 04:15:06.499999999 +0000 UTC 2025/01/15 02:13:58 DEBUG : Added delayed dir = "a1/b1/c1/d1/e1", newDst= 2025/01/15 02:13:58 INFO : a1/b1/c1/d1/e1/f1: Making directory 2025/01/15 02:13:59 INFO : a1/b1/c1/d2/e1/f1: Made directory with modification time 2001-02-03 04:11:06.499999999 +0000 UTC 2025/01/15 02:13:59 DEBUG : Added delayed dir = "a1/b1/c1/d2/e1/f1", newDst= 2025/01/15 02:13:59 INFO : a1/b1/c1/d2/e1/f2: Making directory 2025/01/15 02:14:00 INFO : a1/b1/c1/d1/e1/f1: Made directory with modification time 2001-02-03 04:14:06.499999999 +0000 UTC 2025/01/15 02:14:00 DEBUG : Added delayed dir = "a1/b1/c1/d1/e1/f1", newDst= 2025/01/15 02:14:01 INFO : a1/b1/c1/d2/e1/f2: Made directory with modification time 2001-02-03 04:10:06.499999999 +0000 UTC 2025/01/15 02:14:01 DEBUG : Added delayed dir = "a1/b1/c1/d2/e1/f2", newDst= 2025/01/15 02:14:01 DEBUG : gofile root 'rclone-test-howipaw3wiyi': Waiting for checks to finish 2025/01/15 02:14:01 DEBUG : gofile root 'rclone-test-howipaw3wiyi': Waiting for transfers to finish 2025/01/15 02:14:01 DEBUG : Waiting for deletions to finish 2025/01/15 02:14:01 INFO : a1/b1/c1/d2/e1/f2: Set directory modification time (using DirSetModTime) 2025/01/15 02:14:01 INFO : a1/b2/c1/d1/e1/f1: Set directory modification time (using DirSetModTime) 2025/01/15 02:14:01 INFO : a1/b1/c1/d1/e1/f1: Set directory modification time (using DirSetModTime) 2025/01/15 02:14:01 INFO : a1/b1/c1/d2/e1/f1: Set directory modification time (using DirSetModTime) 2025/01/15 02:14:01 INFO : a1/b1/c1/d1/e1: Set directory modification time (using DirSetModTime) 2025/01/15 02:14:01 INFO : a1/b2/c1/d1/e1: Set directory modification time (using DirSetModTime) 2025/01/15 02:14:01 INFO : a1/b1/c1/d2/e1: Set directory modification time (using DirSetModTime) 2025/01/15 02:14:01 INFO : a1/b1/c1/d2: Set directory modification time (using DirSetModTime) 2025/01/15 02:14:01 INFO : a1/b2/c1/d1: Set directory modification time (using DirSetModTime) 2025/01/15 02:14:01 INFO : a1/b1/c1/d1: Set directory modification time (using DirSetModTime) 2025/01/15 02:14:02 INFO : a1/b1/c1: Set directory modification time (using DirSetModTime) 2025/01/15 02:14:02 INFO : a1/b2/c1: Set directory modification time (using DirSetModTime) 2025/01/15 02:14:02 INFO : a1/b1: Set directory modification time (using DirSetModTime) 2025/01/15 02:14:02 INFO : a1/b2: Set directory modification time (using DirSetModTime) 2025/01/15 02:14:02 INFO : a1: Set directory modification time (using DirSetModTime) 2025/01/15 02:14:02 INFO : There was nothing to transfer run.go:180: Remote "gofile root 'rclone-test-howipaw3wiyi'", Local "Local file system at /tmp/rclone4101559309", Modify Window "1s" --- PASS: TestSyncSetDelayedModTimes (41.50s) === RUN TestServerSideCopyOverSelf run.go:180: Remote "gofile root 'rclone-test-howipaw3wiyi'", Local "Local file system at /tmp/rclone4101559309", Modify Window "1s" 2025/01/15 02:14:24 DEBUG : Upload server store-eu-par-3 (eu) responded in 130.341033ms 2025/01/15 02:14:24 DEBUG : Upload server store-eu-par-4 (eu) responded in 135.957831ms 2025/01/15 02:14:24 DEBUG : sub dir/hello world: Using upload server store-eu-par-4 (eu) 2025/01/15 02:14:25 DEBUG : Creating backend with remote "TestGoFile:rclone-test-levejev7havi" sync_test.go:626: Server side copy (if possible) gofile root 'rclone-test-howipaw3wiyi' -> gofile root 'rclone-test-levejev7havi' 2025/01/15 02:14:26 DEBUG : Added delayed dir = "sub dir", newDst= 2025/01/15 02:14:26 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2025/01/15 02:14:26 DEBUG : gofile root 'rclone-test-levejev7havi': Waiting for checks to finish 2025/01/15 02:14:26 DEBUG : gofile root 'rclone-test-levejev7havi': Waiting for transfers to finish 2025/01/15 02:14:28 DEBUG : sub dir/hello world: md5 = 5eb63bbbe01eeed093cb22bb8f5acdc3 OK 2025/01/15 02:14:28 INFO : sub dir/hello world: Copied (server-side copy) 2025/01/15 02:14:28 INFO : sub dir: Set directory modification time (using DirSetModTime) run.go:180: Remote "gofile root 'rclone-test-howipaw3wiyi'", Local "Local file system at /tmp/rclone4101559309", Modify Window "1s" 2025/01/15 02:14:29 DEBUG : sub dir/hello world: Using upload server store-eu-par-3 (eu) 2025/01/15 02:14:29 DEBUG : sub dir/hello world: Removing old object on successful upload 2025/01/15 02:14:30 DEBUG : Added delayed dir = "sub dir", newDst=sub dir 2025/01/15 02:14:31 DEBUG : gofile root 'rclone-test-levejev7havi': Waiting for checks to finish 2025/01/15 02:14:31 DEBUG : sub dir/hello world: Sizes differ (src 17 vs dst 11) 2025/01/15 02:14:31 DEBUG : gofile root 'rclone-test-levejev7havi': Waiting for transfers to finish 2025/01/15 02:14:32 DEBUG : sub dir/hello world: Server side copy: removing existing object after successful copy 2025/01/15 02:14:32 DEBUG : sub dir/hello world: md5 = 00321a507bdb420dbbd4f53c733b1505 OK 2025/01/15 02:14:32 INFO : sub dir/hello world: Copied (server-side copy) 2025/01/15 02:14:32 INFO : sub dir: Set directory modification time (using SetModTime) run.go:180: Remote "gofile root 'rclone-test-howipaw3wiyi'", Local "Local file system at /tmp/rclone4101559309", Modify Window "1s" 2025/01/15 02:14:32 DEBUG : gofile root 'rclone-test-levejev7havi': Purge remote --- PASS: TestServerSideCopyOverSelf (12.61s) === RUN TestSyncAfterRemovingAFileAndAddingAFileSubDir run.go:180: Remote "gofile root 'rclone-test-howipaw3wiyi'", Local "Local file system at /tmp/rclone4101559309", Modify Window "1s" 2025/01/15 02:14:37 DEBUG : b/potato: Using upload server store-eu-par-4 (eu) 2025/01/15 02:14:38 DEBUG : c/non empty space: Using upload server store-eu-par-4 (eu) 2025/01/15 02:14:39 INFO : d: Making directory 2025/01/15 02:14:39 INFO : d/e: Making directory 2025/01/15 02:14:41 DEBUG : Added delayed dir = "a", newDst= 2025/01/15 02:14:41 DEBUG : c: Directory modification time the same (differ by 373.234113ms, within tolerance 1s) 2025/01/15 02:14:41 DEBUG : Added delayed dir = "c", newDst=c 2025/01/15 02:14:41 DEBUG : a/potato2: Need to transfer - File not found at Destination 2025/01/15 02:14:41 DEBUG : c/non empty space: Size and modification time the same (differ by -123.456789ms, within tolerance 1s) 2025/01/15 02:14:41 DEBUG : c/non empty space: Unchanged skipping 2025/01/15 02:14:42 DEBUG : a/potato2: Using upload server store-eu-par-4 (eu) 2025/01/15 02:14:42 DEBUG : a/potato2: md5 = d6548b156ea68a4e003e786df99eee76 OK 2025/01/15 02:14:42 INFO : a/potato2: Copied (new) 2025/01/15 02:14:42 DEBUG : gofile root 'rclone-test-howipaw3wiyi': Waiting for checks to finish 2025/01/15 02:14:42 DEBUG : gofile root 'rclone-test-howipaw3wiyi': Waiting for transfers to finish 2025/01/15 02:14:42 DEBUG : Waiting for deletions to finish 2025/01/15 02:14:43 INFO : b/potato: Deleted 2025/01/15 02:14:43 INFO : a: Set directory modification time (using DirSetModTime) 2025/01/15 02:14:43 INFO : d/e: Removing directory 2025/01/15 02:14:44 INFO : d: Removing directory 2025/01/15 02:14:45 INFO : b: Removing directory 2025/01/15 02:14:45 DEBUG : gofile root 'rclone-test-howipaw3wiyi': deleted 3 directories run.go:180: Remote "gofile root 'rclone-test-howipaw3wiyi'", Local "Local file system at /tmp/rclone4101559309", Modify Window "1s" --- PASS: TestSyncAfterRemovingAFileAndAddingAFileSubDir (13.99s) === RUN TestServerSideMoveWithFilter run.go:180: Remote "gofile root 'rclone-test-howipaw3wiyi'", Local "Local file system at /tmp/rclone4101559309", Modify Window "1s" 2025/01/15 02:14:50 DEBUG : Creating backend with remote "TestGoFile:rclone-test-xatibic5juhu" 2025/01/15 02:14:50 DEBUG : potato2: Using upload server store-eu-par-4 (eu) 2025/01/15 02:14:51 DEBUG : empty space: Using upload server store-eu-par-4 (eu) 2025/01/15 02:14:51 DEBUG : potato3: Using upload server store-eu-par-3 (eu) sync_test.go:1705: Server side move (if possible) gofile root 'rclone-test-howipaw3wiyi' -> gofile root 'rclone-test-xatibic5juhu' 2025/01/15 02:14:53 DEBUG : Upload server store-eu-par-4 (eu) responded in 126.793436ms 2025/01/15 02:14:53 DEBUG : Upload server store-eu-par-3 (eu) responded in 130.659781ms 2025/01/15 02:14:53 DEBUG : empty space: Using upload server store-eu-par-4 (eu) 2025/01/15 02:14:53 DEBUG : potato3: Using upload server store-eu-par-4 (eu) 2025/01/15 02:14:54 DEBUG : empty space: Excluded (Size Filter) 2025/01/15 02:14:54 DEBUG : empty space: Excluded 2025/01/15 02:14:54 DEBUG : empty space: Excluded (Size Filter) 2025/01/15 02:14:54 DEBUG : empty space: Excluded 2025/01/15 02:14:54 DEBUG : potato2: Need to transfer - File not found at Destination 2025/01/15 02:14:54 DEBUG : potato3: Sizes differ (src 68 vs dst 60) 2025/01/15 02:14:54 DEBUG : gofile root 'rclone-test-xatibic5juhu': Waiting for checks to finish 2025/01/15 02:14:54 DEBUG : gofile root 'rclone-test-xatibic5juhu': Waiting for transfers to finish 2025/01/15 02:14:54 INFO : potato3: Deleted 2025/01/15 02:14:54 INFO : potato2: Moved (server-side) 2025/01/15 02:14:55 INFO : potato3: Moved (server-side) 2025/01/15 02:14:55 DEBUG : Creating backend with remote "TestGoFile:rclone-test-bojozij8suve" 2025/01/15 02:14:56 DEBUG : empty space: Excluded (Size Filter) 2025/01/15 02:14:56 DEBUG : empty space: Excluded 2025/01/15 02:14:56 DEBUG : potato2: Need to transfer - File not found at Destination 2025/01/15 02:14:56 DEBUG : potato3: Need to transfer - File not found at Destination 2025/01/15 02:14:56 DEBUG : gofile root 'rclone-test-bojozij8suve': Waiting for checks to finish 2025/01/15 02:14:56 DEBUG : gofile root 'rclone-test-bojozij8suve': Waiting for transfers to finish 2025/01/15 02:14:57 INFO : potato2: Moved (server-side) 2025/01/15 02:14:57 INFO : potato3: Moved (server-side) 2025/01/15 02:14:58 DEBUG : gofile root 'rclone-test-bojozij8suve': Purge remote 2025/01/15 02:14:59 DEBUG : gofile root 'rclone-test-xatibic5juhu': Purge remote --- PASS: TestServerSideMoveWithFilter (10.37s) === RUN TestSyncSuffix run.go:180: Remote "gofile root 'rclone-test-howipaw3wiyi'", Local "Local file system at /tmp/rclone4101559309", Modify Window "1s" 2025/01/15 02:15:01 DEBUG : dst/one: Using upload server store-eu-par-3 (eu) 2025/01/15 02:15:02 DEBUG : dst/two: Using upload server store-eu-par-3 (eu) 2025/01/15 02:15:02 DEBUG : dst/three.txt: Using upload server store-eu-par-3 (eu) 2025/01/15 02:15:03 DEBUG : Creating backend with remote "TestGoFile:rclone-test-howipaw3wiyi/dst" 2025/01/15 02:15:04 DEBUG : one: Sizes differ (src 4 vs dst 3) 2025/01/15 02:15:04 INFO : one: Moved (server-side) to: one.bak 2025/01/15 02:15:04 DEBUG : Upload server store-eu-par-4 (eu) responded in 120.719873ms 2025/01/15 02:15:04 DEBUG : Upload server store-eu-par-3 (eu) responded in 123.806644ms 2025/01/15 02:15:04 DEBUG : one: Using upload server store-eu-par-4 (eu) 2025/01/15 02:15:04 DEBUG : one: md5 = c7957179c41f69d44f217a108c7915d8 OK 2025/01/15 02:15:04 INFO : one: Copied (new) 2025/01/15 02:15:05 DEBUG : two: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2025/01/15 02:15:05 DEBUG : two: Unchanged skipping 2025/01/15 02:15:05 DEBUG : three.txt: Sizes differ (src 6 vs dst 5) 2025/01/15 02:15:06 INFO : three.txt: Moved (server-side) to: three.txt.bak 2025/01/15 02:15:06 DEBUG : three.txt: Using upload server store-eu-par-3 (eu) 2025/01/15 02:15:06 DEBUG : three.txt: md5 = 91341eed84691a83caea73aa785736d5 OK 2025/01/15 02:15:06 INFO : three.txt: Copied (new) 2025/01/15 02:15:08 DEBUG : one: Sizes differ (src 5 vs dst 4) 2025/01/15 02:15:08 INFO : one.bak: Deleted 2025/01/15 02:15:09 INFO : one: Moved (server-side) to: one.bak 2025/01/15 02:15:09 DEBUG : one: Using upload server store-eu-par-4 (eu) 2025/01/15 02:15:09 DEBUG : one: md5 = 0f93e81041f0cab37c37a05ae998b219 OK 2025/01/15 02:15:09 INFO : one: Copied (new) 2025/01/15 02:15:09 DEBUG : two: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2025/01/15 02:15:09 DEBUG : two: Unchanged skipping 2025/01/15 02:15:09 DEBUG : three.txt: Sizes differ (src 19 vs dst 6) 2025/01/15 02:15:10 INFO : three.txt.bak: Deleted 2025/01/15 02:15:10 INFO : three.txt: Moved (server-side) to: three.txt.bak 2025/01/15 02:15:10 DEBUG : three.txt: Using upload server store-eu-par-3 (eu) 2025/01/15 02:15:10 DEBUG : three.txt: md5 = 423e01c5e84a30d129b97aedb6e219a9 OK 2025/01/15 02:15:10 INFO : three.txt: Copied (new) --- PASS: TestSyncSuffix (14.24s) PASS 2025/01/15 02:15:14 DEBUG : gofile root 'rclone-test-howipaw3wiyi': Purge remote "./sync.test -test.v -test.timeout 1h0m0s -remote TestGoFile: -verbose -test.run '^(TestServerSideCopyOverSelf|TestServerSideMoveWithFilter|TestSyncAfterRemovingAFileAndAddingAFileSubDir|TestSyncSetDelayedModTimes|TestSyncSuffix)$'" - Finished OK in 1m34.254554404s (try 2/5)