"./sync.test -test.v -test.timeout 1h0m0s -remote TestGoFile: -verbose -fast-list -test.run '^(TestServerSideMoveDeleteEmptySourceDirs|TestSyncSetDelayedModTimes)$'" - Starting (try 2/5) 2024/12/22 01:17:22 DEBUG : Creating backend with remote "TestGoFile:rclone-test-gayaneg1xuji" 2024/12/22 01:17:22 DEBUG : Using config file from "/home/rclone/.rclone.conf" 2024/12/22 01:17:22 DEBUG : Creating backend with remote "/tmp/rclone2515412568" === RUN TestSyncSetDelayedModTimes run.go:180: Remote "gofile root 'rclone-test-gayaneg1xuji'", Local "Local file system at /tmp/rclone2515412568", Modify Window "1s" 2024/12/22 01:17:22 INFO : a1/b2/c1/d1/e1/f1: Set directory modification time (using DirSetModTime) 2024/12/22 01:17:22 INFO : a1/b2/c1/d1/e1: Set directory modification time (using DirSetModTime) 2024/12/22 01:17:22 INFO : a1/b2/c1/d1: Set directory modification time (using DirSetModTime) 2024/12/22 01:17:22 INFO : a1/b2/c1: Set directory modification time (using DirSetModTime) 2024/12/22 01:17:22 INFO : a1/b2: Set directory modification time (using DirSetModTime) 2024/12/22 01:17:22 INFO : a1/b1/c1/d2/e1/f2: Set directory modification time (using DirSetModTime) 2024/12/22 01:17:22 INFO : a1/b1/c1/d2/e1/f1: Set directory modification time (using DirSetModTime) 2024/12/22 01:17:22 INFO : a1/b1/c1/d2/e1: Set directory modification time (using DirSetModTime) 2024/12/22 01:17:22 INFO : a1/b1/c1/d2: Set directory modification time (using DirSetModTime) 2024/12/22 01:17:22 INFO : a1/b1/c1/d1/e1/f1: Set directory modification time (using DirSetModTime) 2024/12/22 01:17:22 INFO : a1/b1/c1/d1/e1: Set directory modification time (using DirSetModTime) 2024/12/22 01:17:22 INFO : a1/b1/c1/d1: Set directory modification time (using DirSetModTime) 2024/12/22 01:17:22 INFO : a1/b1/c1: Set directory modification time (using DirSetModTime) 2024/12/22 01:17:22 INFO : a1/b1: Set directory modification time (using DirSetModTime) 2024/12/22 01:17:22 INFO : a1: Set directory modification time (using DirSetModTime) 2024/12/22 01:17:23 DEBUG : a1: Making directory 2024/12/22 01:17:24 INFO : a1: Made directory with modification time 2001-02-03 04:19:06.499999999 +0000 UTC 2024/12/22 01:17:24 DEBUG : Added delayed dir = "a1", newDst= 2024/12/22 01:17:24 DEBUG : a1/b1: Making directory 2024/12/22 01:17:25 INFO : a1/b1: Made directory with modification time 2001-02-03 04:18:06.499999999 +0000 UTC 2024/12/22 01:17:25 DEBUG : Added delayed dir = "a1/b1", newDst= 2024/12/22 01:17:25 DEBUG : a1/b2: Making directory 2024/12/22 01:17:25 INFO : a1/b2: Made directory with modification time 2001-02-03 04:09:06.499999999 +0000 UTC 2024/12/22 01:17:25 DEBUG : Added delayed dir = "a1/b2", newDst= 2024/12/22 01:17:25 DEBUG : a1/b2/c1: Making directory 2024/12/22 01:17:25 DEBUG : a1/b1/c1: Making directory 2024/12/22 01:17:26 INFO : a1/b2/c1: Made directory with modification time 2001-02-03 04:08:06.499999999 +0000 UTC 2024/12/22 01:17:26 DEBUG : Added delayed dir = "a1/b2/c1", newDst= 2024/12/22 01:17:26 DEBUG : a1/b2/c1/d1: Making directory 2024/12/22 01:17:27 INFO : a1/b1/c1: Made directory with modification time 2001-02-03 04:17:06.499999999 +0000 UTC 2024/12/22 01:17:27 DEBUG : Added delayed dir = "a1/b1/c1", newDst= 2024/12/22 01:17:27 DEBUG : a1/b1/c1/d1: Making directory 2024/12/22 01:17:27 DEBUG : Rate limited, sleep for 5s 2024/12/22 01:17:27 INFO : a1/b2/c1/d1: Made directory with modification time 2001-02-03 04:07:06.499999999 +0000 UTC 2024/12/22 01:17:27 DEBUG : Added delayed dir = "a1/b2/c1/d1", newDst= 2024/12/22 01:17:27 DEBUG : a1/b2/c1/d1/e1: Making directory 2024/12/22 01:17:32 DEBUG : pacer: low level retry 1/10 (error Error "error-rateLimit") 2024/12/22 01:17:32 DEBUG : pacer: Rate limited, increasing sleep to 20ms 2024/12/22 01:17:32 DEBUG : Rate limited, sleep for 5s 2024/12/22 01:17:37 DEBUG : pacer: low level retry 2/10 (error Error "error-rateLimit") 2024/12/22 01:17:37 DEBUG : pacer: Rate limited, increasing sleep to 40ms 2024/12/22 01:17:38 DEBUG : pacer: Reducing sleep to 20ms 2024/12/22 01:17:38 DEBUG : pacer: Reducing sleep to 10ms 2024/12/22 01:17:38 INFO : a1/b1/c1/d1: Made directory with modification time 2001-02-03 04:16:06.499999999 +0000 UTC 2024/12/22 01:17:38 DEBUG : Added delayed dir = "a1/b1/c1/d1", newDst= 2024/12/22 01:17:38 DEBUG : a1/b1/c1/d2: Making directory 2024/12/22 01:17:39 INFO : a1/b2/c1/d1/e1: Made directory with modification time 2001-02-03 04:06:06.499999999 +0000 UTC 2024/12/22 01:17:39 DEBUG : Added delayed dir = "a1/b2/c1/d1/e1", newDst= 2024/12/22 01:17:39 DEBUG : a1/b2/c1/d1/e1/f1: Making directory 2024/12/22 01:17:39 INFO : a1/b1/c1/d2: Made directory with modification time 2001-02-03 04:13:06.499999999 +0000 UTC 2024/12/22 01:17:39 DEBUG : Added delayed dir = "a1/b1/c1/d2", newDst= 2024/12/22 01:17:39 DEBUG : a1/b1/c1/d2/e1: Making directory 2024/12/22 01:17:39 DEBUG : a1/b1/c1/d1/e1: Making directory 2024/12/22 01:17:40 INFO : a1/b2/c1/d1/e1/f1: Made directory with modification time 2001-02-03 04:05:06.499999999 +0000 UTC 2024/12/22 01:17:40 DEBUG : Added delayed dir = "a1/b2/c1/d1/e1/f1", newDst= 2024/12/22 01:17:40 INFO : a1/b1/c1/d2/e1: Made directory with modification time 2001-02-03 04:12:06.499999999 +0000 UTC 2024/12/22 01:17:40 DEBUG : Added delayed dir = "a1/b1/c1/d2/e1", newDst= 2024/12/22 01:17:40 DEBUG : a1/b1/c1/d2/e1/f1: Making directory 2024/12/22 01:17:41 INFO : a1/b1/c1/d1/e1: Made directory with modification time 2001-02-03 04:15:06.499999999 +0000 UTC 2024/12/22 01:17:41 DEBUG : Added delayed dir = "a1/b1/c1/d1/e1", newDst= 2024/12/22 01:17:41 DEBUG : a1/b1/c1/d1/e1/f1: Making directory 2024/12/22 01:17:41 DEBUG : Rate limited, sleep for 5s 2024/12/22 01:17:46 DEBUG : pacer: low level retry 1/10 (error Error "error-rateLimit") 2024/12/22 01:17:46 DEBUG : pacer: Rate limited, increasing sleep to 20ms 2024/12/22 01:17:47 DEBUG : pacer: Reducing sleep to 10ms 2024/12/22 01:17:47 INFO : a1/b1/c1/d2/e1/f1: Made directory with modification time 2001-02-03 04:11:06.499999999 +0000 UTC 2024/12/22 01:17:47 DEBUG : Added delayed dir = "a1/b1/c1/d2/e1/f1", newDst= 2024/12/22 01:17:47 DEBUG : a1/b1/c1/d2/e1/f2: Making directory 2024/12/22 01:17:47 INFO : a1/b1/c1/d1/e1/f1: Made directory with modification time 2001-02-03 04:14:06.499999999 +0000 UTC 2024/12/22 01:17:47 DEBUG : Added delayed dir = "a1/b1/c1/d1/e1/f1", newDst= 2024/12/22 01:17:48 INFO : a1/b1/c1/d2/e1/f2: Made directory with modification time 2001-02-03 04:10:06.499999999 +0000 UTC 2024/12/22 01:17:48 DEBUG : Added delayed dir = "a1/b1/c1/d2/e1/f2", newDst= 2024/12/22 01:17:48 DEBUG : gofile root 'rclone-test-gayaneg1xuji': Waiting for checks to finish 2024/12/22 01:17:48 DEBUG : gofile root 'rclone-test-gayaneg1xuji': Waiting for transfers to finish 2024/12/22 01:17:48 DEBUG : Waiting for deletions to finish 2024/12/22 01:17:48 INFO : a1/b1/c1/d2/e1/f2: Set directory modification time (using DirSetModTime) 2024/12/22 01:17:48 INFO : a1/b1/c1/d2/e1/f1: Set directory modification time (using DirSetModTime) 2024/12/22 01:17:48 INFO : a1/b2/c1/d1/e1/f1: Set directory modification time (using DirSetModTime) 2024/12/22 01:17:48 INFO : a1/b1/c1/d1/e1/f1: Set directory modification time (using DirSetModTime) 2024/12/22 01:17:48 INFO : a1/b1/c1/d1/e1: Set directory modification time (using DirSetModTime) 2024/12/22 01:17:48 INFO : a1/b1/c1/d2/e1: Set directory modification time (using DirSetModTime) 2024/12/22 01:17:49 INFO : a1/b2/c1/d1/e1: Set directory modification time (using DirSetModTime) 2024/12/22 01:17:49 INFO : a1/b2/c1/d1: Set directory modification time (using DirSetModTime) 2024/12/22 01:17:49 INFO : a1/b1/c1/d2: Set directory modification time (using DirSetModTime) 2024/12/22 01:17:49 INFO : a1/b1/c1/d1: Set directory modification time (using DirSetModTime) 2024/12/22 01:17:49 INFO : a1/b1/c1: Set directory modification time (using DirSetModTime) 2024/12/22 01:17:49 INFO : a1/b2/c1: Set directory modification time (using DirSetModTime) 2024/12/22 01:17:49 INFO : a1/b2: Set directory modification time (using DirSetModTime) 2024/12/22 01:17:49 INFO : a1/b1: Set directory modification time (using DirSetModTime) 2024/12/22 01:17:50 INFO : a1: Set directory modification time (using DirSetModTime) 2024/12/22 01:17:50 INFO : There was nothing to transfer run.go:180: Remote "gofile root 'rclone-test-gayaneg1xuji'", Local "Local file system at /tmp/rclone2515412568", Modify Window "1s" --- PASS: TestSyncSetDelayedModTimes (40.22s) === RUN TestServerSideMoveDeleteEmptySourceDirs run.go:180: Remote "gofile root 'rclone-test-gayaneg1xuji'", Local "Local file system at /tmp/rclone2515412568", Modify Window "1s" 2024/12/22 01:18:02 DEBUG : Creating backend with remote "TestGoFile:rclone-test-yapatin2cube" 2024/12/22 01:18:02 DEBUG : Config file has changed externally - reloading 2024/12/22 01:18:03 DEBUG : Upload server store-eu-par-2 (eu) responded in 124.144555ms 2024/12/22 01:18:03 DEBUG : Upload server store-eu-par-3 (eu) responded in 125.907919ms 2024/12/22 01:18:03 DEBUG : potato2: Using upload server store-eu-par-3 (eu) 2024/12/22 01:18:03 DEBUG : empty space: Using upload server store-eu-par-3 (eu) 2024/12/22 01:18:04 DEBUG : potato3: Using upload server store-eu-par-3 (eu) 2024/12/22 01:18:04 DEBUG : tomatoDir: Making directory sync_test.go:1705: Server side move (if possible) gofile root 'rclone-test-gayaneg1xuji' -> gofile root 'rclone-test-yapatin2cube' 2024/12/22 01:18:06 DEBUG : Upload server store7 (eu) responded in 126.048634ms 2024/12/22 01:18:06 DEBUG : Upload server store-eu-par-3 (eu) responded in 128.308997ms 2024/12/22 01:18:06 DEBUG : empty space: Using upload server store-eu-par-3 (eu) 2024/12/22 01:18:06 DEBUG : potato3: Using upload server store-eu-par-3 (eu) 2024/12/22 01:18:07 DEBUG : gofile root 'rclone-test-yapatin2cube': Using server-side directory move 2024/12/22 01:18:07 INFO : gofile root 'rclone-test-yapatin2cube': Server side directory move failed - fallback to file moves: can't copy directory - destination already exists 2024/12/22 01:18:07 DEBUG : potato2: Need to transfer - File not found at Destination 2024/12/22 01:18:07 DEBUG : Added delayed dir = "tomatoDir", newDst= 2024/12/22 01:18:07 DEBUG : empty space: Size and modification time the same (differ by 0s, within tolerance 1s) 2024/12/22 01:18:07 DEBUG : gofile root 'rclone-test-yapatin2cube': Waiting for checks to finish 2024/12/22 01:18:07 DEBUG : empty space: Unchanged skipping 2024/12/22 01:18:07 DEBUG : potato3: Sizes differ (src 68 vs dst 60) 2024/12/22 01:18:07 INFO : potato3: Deleted 2024/12/22 01:18:07 INFO : empty space: Deleted 2024/12/22 01:18:07 DEBUG : gofile root 'rclone-test-yapatin2cube': Waiting for transfers to finish 2024/12/22 01:18:08 INFO : potato2: Moved (server-side) 2024/12/22 01:18:08 INFO : potato3: Moved (server-side) 2024/12/22 01:18:08 INFO : tomatoDir: Removing directory 2024/12/22 01:18:08 DEBUG : gofile root 'rclone-test-gayaneg1xuji': deleted 1 directories 2024/12/22 01:18:09 DEBUG : Creating backend with remote "TestGoFile:rclone-test-duticam9pigu" 2024/12/22 01:18:09 DEBUG : tomatoDir: Making directory 2024/12/22 01:18:10 DEBUG : gofile root 'rclone-test-duticam9pigu': Using server-side directory move 2024/12/22 01:18:10 INFO : gofile root 'rclone-test-duticam9pigu': Server side directory move succeeded 2024/12/22 01:18:11 DEBUG : gofile root 'rclone-test-duticam9pigu': Purge remote 2024/12/22 01:18:12 DEBUG : gofile root 'rclone-test-yapatin2cube': Purge remote 2024/12/22 01:18:12 NOTICE: purge failed: directory not found --- PASS: TestServerSideMoveDeleteEmptySourceDirs (9.79s) PASS 2024/12/22 01:18:12 DEBUG : gofile root 'rclone-test-gayaneg1xuji': Purge remote "./sync.test -test.v -test.timeout 1h0m0s -remote TestGoFile: -verbose -fast-list -test.run '^(TestServerSideMoveDeleteEmptySourceDirs|TestSyncSetDelayedModTimes)$'" - Finished OK in 50.673120765s (try 2/5)