"./sync.test -test.v -test.timeout 1h0m0s -remote TestGoFile: -verbose -test.run '^(TestServerSideMove|TestSyncNoEmptyDirectories|TestSyncSetDelayedModTimes)$'" - Starting (try 2/5) 2024/11/10 02:39:10 DEBUG : Creating backend with remote "TestGoFile:rclone-test-jiyumoy2kihi" 2024/11/10 02:39:10 DEBUG : Using config file from "/home/rclone/.rclone.conf" 2024/11/10 02:39:10 DEBUG : Creating backend with remote "/tmp/rclone336490371" === RUN TestSyncSetDelayedModTimes run.go:180: Remote "gofile root 'rclone-test-jiyumoy2kihi'", Local "Local file system at /tmp/rclone336490371", Modify Window "1s" 2024/11/10 02:39:10 INFO : a1/b2/c1/d1/e1/f1: Set directory modification time (using DirSetModTime) 2024/11/10 02:39:10 INFO : a1/b2/c1/d1/e1: Set directory modification time (using DirSetModTime) 2024/11/10 02:39:10 INFO : a1/b2/c1/d1: Set directory modification time (using DirSetModTime) 2024/11/10 02:39:10 INFO : a1/b2/c1: Set directory modification time (using DirSetModTime) 2024/11/10 02:39:10 INFO : a1/b2: Set directory modification time (using DirSetModTime) 2024/11/10 02:39:10 INFO : a1/b1/c1/d2/e1/f2: Set directory modification time (using DirSetModTime) 2024/11/10 02:39:10 INFO : a1/b1/c1/d2/e1/f1: Set directory modification time (using DirSetModTime) 2024/11/10 02:39:10 INFO : a1/b1/c1/d2/e1: Set directory modification time (using DirSetModTime) 2024/11/10 02:39:10 INFO : a1/b1/c1/d2: Set directory modification time (using DirSetModTime) 2024/11/10 02:39:10 INFO : a1/b1/c1/d1/e1/f1: Set directory modification time (using DirSetModTime) 2024/11/10 02:39:10 INFO : a1/b1/c1/d1/e1: Set directory modification time (using DirSetModTime) 2024/11/10 02:39:10 INFO : a1/b1/c1/d1: Set directory modification time (using DirSetModTime) 2024/11/10 02:39:10 INFO : a1/b1/c1: Set directory modification time (using DirSetModTime) 2024/11/10 02:39:10 INFO : a1/b1: Set directory modification time (using DirSetModTime) 2024/11/10 02:39:10 INFO : a1: Set directory modification time (using DirSetModTime) 2024/11/10 02:39:11 DEBUG : a1: Making directory 2024/11/10 02:39:11 INFO : a1: Made directory with modification time 2001-02-03 04:19:06.499999999 +0000 UTC 2024/11/10 02:39:11 DEBUG : Added delayed dir = "a1", newDst= 2024/11/10 02:39:11 DEBUG : a1/b1: Making directory 2024/11/10 02:39:12 INFO : a1/b1: Made directory with modification time 2001-02-03 04:18:06.499999999 +0000 UTC 2024/11/10 02:39:12 DEBUG : Added delayed dir = "a1/b1", newDst= 2024/11/10 02:39:12 DEBUG : a1/b2: Making directory 2024/11/10 02:39:13 INFO : a1/b2: Made directory with modification time 2001-02-03 04:09:06.499999999 +0000 UTC 2024/11/10 02:39:13 DEBUG : Added delayed dir = "a1/b2", newDst= 2024/11/10 02:39:13 DEBUG : a1/b2/c1: Making directory 2024/11/10 02:39:13 DEBUG : a1/b1/c1: Making directory 2024/11/10 02:39:13 INFO : a1/b2/c1: Made directory with modification time 2001-02-03 04:08:06.499999999 +0000 UTC 2024/11/10 02:39:13 DEBUG : Added delayed dir = "a1/b2/c1", newDst= 2024/11/10 02:39:13 DEBUG : a1/b2/c1/d1: Making directory 2024/11/10 02:39:14 INFO : a1/b1/c1: Made directory with modification time 2001-02-03 04:17:06.499999999 +0000 UTC 2024/11/10 02:39:14 DEBUG : Added delayed dir = "a1/b1/c1", newDst= 2024/11/10 02:39:14 DEBUG : a1/b1/c1/d1: Making directory 2024/11/10 02:39:14 INFO : a1/b2/c1/d1: Made directory with modification time 2001-02-03 04:07:06.499999999 +0000 UTC 2024/11/10 02:39:14 DEBUG : Added delayed dir = "a1/b2/c1/d1", newDst= 2024/11/10 02:39:14 DEBUG : a1/b2/c1/d1/e1: Making directory 2024/11/10 02:39:15 INFO : a1/b1/c1/d1: Made directory with modification time 2001-02-03 04:16:06.499999999 +0000 UTC 2024/11/10 02:39:15 DEBUG : Added delayed dir = "a1/b1/c1/d1", newDst= 2024/11/10 02:39:15 DEBUG : a1/b1/c1/d2: Making directory 2024/11/10 02:39:15 INFO : a1/b2/c1/d1/e1: Made directory with modification time 2001-02-03 04:06:06.499999999 +0000 UTC 2024/11/10 02:39:15 DEBUG : Added delayed dir = "a1/b2/c1/d1/e1", newDst= 2024/11/10 02:39:15 DEBUG : a1/b2/c1/d1/e1/f1: Making directory 2024/11/10 02:39:16 DEBUG : Rate limited, sleep for 5s 2024/11/10 02:39:16 INFO : a1/b1/c1/d2: Made directory with modification time 2001-02-03 04:13:06.499999999 +0000 UTC 2024/11/10 02:39:16 DEBUG : Added delayed dir = "a1/b1/c1/d2", newDst= 2024/11/10 02:39:16 DEBUG : a1/b1/c1/d1/e1: Making directory 2024/11/10 02:39:16 DEBUG : a1/b1/c1/d2/e1: Making directory 2024/11/10 02:39:21 DEBUG : pacer: low level retry 1/10 (error Error "error-rateLimit") 2024/11/10 02:39:21 DEBUG : pacer: Rate limited, increasing sleep to 20ms 2024/11/10 02:39:21 DEBUG : Rate limited, sleep for 5s 2024/11/10 02:39:26 DEBUG : pacer: low level retry 2/10 (error Error "error-rateLimit") 2024/11/10 02:39:26 DEBUG : pacer: Rate limited, increasing sleep to 40ms 2024/11/10 02:39:26 DEBUG : pacer: Reducing sleep to 20ms 2024/11/10 02:39:26 DEBUG : pacer: Reducing sleep to 10ms 2024/11/10 02:39:26 INFO : a1/b2/c1/d1/e1/f1: Made directory with modification time 2001-02-03 04:05:06.499999999 +0000 UTC 2024/11/10 02:39:26 DEBUG : Added delayed dir = "a1/b2/c1/d1/e1/f1", newDst= 2024/11/10 02:39:27 INFO : a1/b1/c1/d1/e1: Made directory with modification time 2001-02-03 04:15:06.499999999 +0000 UTC 2024/11/10 02:39:27 DEBUG : Added delayed dir = "a1/b1/c1/d1/e1", newDst= 2024/11/10 02:39:27 DEBUG : a1/b1/c1/d1/e1/f1: Making directory 2024/11/10 02:39:27 INFO : a1/b1/c1/d2/e1: Made directory with modification time 2001-02-03 04:12:06.499999999 +0000 UTC 2024/11/10 02:39:27 DEBUG : Added delayed dir = "a1/b1/c1/d2/e1", newDst= 2024/11/10 02:39:27 DEBUG : a1/b1/c1/d2/e1/f1: Making directory 2024/11/10 02:39:28 INFO : a1/b1/c1/d1/e1/f1: Made directory with modification time 2001-02-03 04:14:06.499999999 +0000 UTC 2024/11/10 02:39:28 DEBUG : Added delayed dir = "a1/b1/c1/d1/e1/f1", newDst= 2024/11/10 02:39:28 INFO : a1/b1/c1/d2/e1/f1: Made directory with modification time 2001-02-03 04:11:06.499999999 +0000 UTC 2024/11/10 02:39:28 DEBUG : Added delayed dir = "a1/b1/c1/d2/e1/f1", newDst= 2024/11/10 02:39:28 DEBUG : a1/b1/c1/d2/e1/f2: Making directory 2024/11/10 02:39:29 INFO : a1/b1/c1/d2/e1/f2: Made directory with modification time 2001-02-03 04:10:06.499999999 +0000 UTC 2024/11/10 02:39:29 DEBUG : Added delayed dir = "a1/b1/c1/d2/e1/f2", newDst= 2024/11/10 02:39:29 DEBUG : gofile root 'rclone-test-jiyumoy2kihi': Waiting for checks to finish 2024/11/10 02:39:29 DEBUG : gofile root 'rclone-test-jiyumoy2kihi': Waiting for transfers to finish 2024/11/10 02:39:29 DEBUG : Waiting for deletions to finish 2024/11/10 02:39:29 INFO : a1/b1/c1/d1/e1/f1: Set directory modification time (using DirSetModTime) 2024/11/10 02:39:29 INFO : a1/b2/c1/d1/e1/f1: Set directory modification time (using DirSetModTime) 2024/11/10 02:39:29 INFO : a1/b1/c1/d2/e1/f1: Set directory modification time (using DirSetModTime) 2024/11/10 02:39:29 INFO : a1/b1/c1/d2/e1/f2: Set directory modification time (using DirSetModTime) 2024/11/10 02:39:29 INFO : a1/b1/c1/d2/e1: Set directory modification time (using DirSetModTime) 2024/11/10 02:39:29 INFO : a1/b2/c1/d1/e1: Set directory modification time (using DirSetModTime) 2024/11/10 02:39:29 INFO : a1/b1/c1/d1/e1: Set directory modification time (using DirSetModTime) 2024/11/10 02:39:29 INFO : a1/b1/c1/d2: Set directory modification time (using DirSetModTime) 2024/11/10 02:39:29 INFO : a1/b2/c1/d1: Set directory modification time (using DirSetModTime) 2024/11/10 02:39:29 INFO : a1/b1/c1/d1: Set directory modification time (using DirSetModTime) 2024/11/10 02:39:30 INFO : a1/b1/c1: Set directory modification time (using DirSetModTime) 2024/11/10 02:39:30 INFO : a1/b2/c1: Set directory modification time (using DirSetModTime) 2024/11/10 02:39:30 INFO : a1/b2: Set directory modification time (using DirSetModTime) 2024/11/10 02:39:30 INFO : a1/b1: Set directory modification time (using DirSetModTime) 2024/11/10 02:39:30 INFO : a1: Set directory modification time (using DirSetModTime) 2024/11/10 02:39:30 INFO : There was nothing to transfer run.go:180: Remote "gofile root 'rclone-test-jiyumoy2kihi'", Local "Local file system at /tmp/rclone336490371", Modify Window "1s" run.go:125: removing dir "a1/b1/c1" failed - try 1/3: directory not empty --- PASS: TestSyncSetDelayedModTimes (33.47s) === RUN TestSyncNoEmptyDirectories run.go:180: Remote "gofile root 'rclone-test-jiyumoy2kihi'", Local "Local file system at /tmp/rclone336490371", Modify Window "1s" 2024/11/10 02:39:44 DEBUG : sub dir2: Making directory 2024/11/10 02:39:44 DEBUG : Added delayed dir = "sub dir", newDst= 2024/11/10 02:39:44 DEBUG : Added delayed dir = "sub dir2", newDst= 2024/11/10 02:39:44 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2024/11/10 02:39:44 DEBUG : gofile root 'rclone-test-jiyumoy2kihi': Waiting for checks to finish 2024/11/10 02:39:44 DEBUG : gofile root 'rclone-test-jiyumoy2kihi': Waiting for transfers to finish 2024/11/10 02:39:45 DEBUG : Upload server store7 (eu) responded in 125.355883ms 2024/11/10 02:39:45 DEBUG : Upload server store2 (eu) responded in 131.09964ms 2024/11/10 02:39:45 DEBUG : sub dir/hello world: Using upload server store2 (eu) 2024/11/10 02:39:45 DEBUG : sub dir/hello world: md5 = 5eb63bbbe01eeed093cb22bb8f5acdc3 OK 2024/11/10 02:39:45 INFO : sub dir/hello world: Copied (new) 2024/11/10 02:39:45 DEBUG : Waiting for deletions to finish 2024/11/10 02:39:45 INFO : sub dir: Set directory modification time (using DirSetModTime) --- PASS: TestSyncNoEmptyDirectories (2.52s) === RUN TestServerSideMove run.go:180: Remote "gofile root 'rclone-test-jiyumoy2kihi'", Local "Local file system at /tmp/rclone336490371", Modify Window "1s" 2024/11/10 02:39:46 DEBUG : Creating backend with remote "TestGoFile:rclone-test-cuyezig8gufa" 2024/11/10 02:39:47 DEBUG : potato2: Using upload server store2 (eu) 2024/11/10 02:39:47 DEBUG : empty space: Using upload server store7 (eu) 2024/11/10 02:39:48 DEBUG : potato3: Using upload server store7 (eu) sync_test.go:1705: Server side move (if possible) gofile root 'rclone-test-jiyumoy2kihi' -> gofile root 'rclone-test-cuyezig8gufa' 2024/11/10 02:39:49 DEBUG : Upload server store7 (eu) responded in 122.904114ms 2024/11/10 02:39:49 DEBUG : Upload server store5 (eu) responded in 125.068286ms 2024/11/10 02:39:49 DEBUG : empty space: Using upload server store7 (eu) 2024/11/10 02:39:49 DEBUG : potato3: Using upload server store5 (eu) 2024/11/10 02:39:49 DEBUG : gofile root 'rclone-test-cuyezig8gufa': Using server-side directory move 2024/11/10 02:39:49 INFO : gofile root 'rclone-test-cuyezig8gufa': Server side directory move failed - fallback to file moves: can't copy directory - destination already exists 2024/11/10 02:39:50 DEBUG : potato2: Need to transfer - File not found at Destination 2024/11/10 02:39:50 DEBUG : empty space: Size and modification time the same (differ by 0s, within tolerance 1s) 2024/11/10 02:39:50 DEBUG : empty space: Unchanged skipping 2024/11/10 02:39:50 DEBUG : potato3: Sizes differ (src 68 vs dst 60) 2024/11/10 02:39:50 DEBUG : gofile root 'rclone-test-cuyezig8gufa': Waiting for checks to finish 2024/11/10 02:39:50 INFO : empty space: Deleted 2024/11/10 02:39:50 DEBUG : gofile root 'rclone-test-cuyezig8gufa': Waiting for transfers to finish 2024/11/10 02:39:50 INFO : potato3: Deleted 2024/11/10 02:39:50 INFO : potato2: Moved (server-side) 2024/11/10 02:39:50 INFO : potato3: Moved (server-side) 2024/11/10 02:39:51 DEBUG : Creating backend with remote "TestGoFile:rclone-test-vakiwuq3qepa" 2024/11/10 02:39:51 DEBUG : gofile root 'rclone-test-vakiwuq3qepa': Using server-side directory move 2024/11/10 02:39:52 INFO : gofile root 'rclone-test-vakiwuq3qepa': Server side directory move succeeded 2024/11/10 02:39:52 DEBUG : gofile root 'rclone-test-vakiwuq3qepa': Purge remote 2024/11/10 02:39:53 DEBUG : gofile root 'rclone-test-cuyezig8gufa': Purge remote 2024/11/10 02:39:53 NOTICE: purge failed: directory not found --- PASS: TestServerSideMove (6.77s) PASS 2024/11/10 02:39:53 DEBUG : gofile root 'rclone-test-jiyumoy2kihi': Purge remote "./sync.test -test.v -test.timeout 1h0m0s -remote TestGoFile: -verbose -test.run '^(TestServerSideMove|TestSyncNoEmptyDirectories|TestSyncSetDelayedModTimes)$'" - Finished OK in 43.27389s (try 2/5)