"./sync.test -test.v -test.timeout 1h0m0s -remote TestGoFile: -verbose -fast-list -test.run '^(TestSyncBackupDirWithSuffixKeepExtension|TestSyncSetDelayedModTimes|TestSyncSuffixKeepExtension)$'" - Starting (try 2/5) 2024/12/07 01:17:14 DEBUG : Creating backend with remote "TestGoFile:rclone-test-puwulif3qepu" 2024/12/07 01:17:14 DEBUG : Using config file from "/home/rclone/.rclone.conf" 2024/12/07 01:17:14 DEBUG : Creating backend with remote "/tmp/rclone3259066495" === RUN TestSyncSetDelayedModTimes run.go:180: Remote "gofile root 'rclone-test-puwulif3qepu'", Local "Local file system at /tmp/rclone3259066495", Modify Window "1s" 2024/12/07 01:17:14 INFO : a1/b2/c1/d1/e1/f1: Set directory modification time (using DirSetModTime) 2024/12/07 01:17:14 INFO : a1/b2/c1/d1/e1: Set directory modification time (using DirSetModTime) 2024/12/07 01:17:14 INFO : a1/b2/c1/d1: Set directory modification time (using DirSetModTime) 2024/12/07 01:17:14 INFO : a1/b2/c1: Set directory modification time (using DirSetModTime) 2024/12/07 01:17:14 INFO : a1/b2: Set directory modification time (using DirSetModTime) 2024/12/07 01:17:14 INFO : a1/b1/c1/d2/e1/f2: Set directory modification time (using DirSetModTime) 2024/12/07 01:17:14 INFO : a1/b1/c1/d2/e1/f1: Set directory modification time (using DirSetModTime) 2024/12/07 01:17:14 INFO : a1/b1/c1/d2/e1: Set directory modification time (using DirSetModTime) 2024/12/07 01:17:14 INFO : a1/b1/c1/d2: Set directory modification time (using DirSetModTime) 2024/12/07 01:17:14 INFO : a1/b1/c1/d1/e1/f1: Set directory modification time (using DirSetModTime) 2024/12/07 01:17:14 INFO : a1/b1/c1/d1/e1: Set directory modification time (using DirSetModTime) 2024/12/07 01:17:14 INFO : a1/b1/c1/d1: Set directory modification time (using DirSetModTime) 2024/12/07 01:17:14 INFO : a1/b1/c1: Set directory modification time (using DirSetModTime) 2024/12/07 01:17:14 INFO : a1/b1: Set directory modification time (using DirSetModTime) 2024/12/07 01:17:14 INFO : a1: Set directory modification time (using DirSetModTime) 2024/12/07 01:17:15 DEBUG : a1: Making directory 2024/12/07 01:17:16 INFO : a1: Made directory with modification time 2001-02-03 04:19:06.499999999 +0000 UTC 2024/12/07 01:17:16 DEBUG : Added delayed dir = "a1", newDst= 2024/12/07 01:17:16 DEBUG : a1/b1: Making directory 2024/12/07 01:17:16 INFO : a1/b1: Made directory with modification time 2001-02-03 04:18:06.499999999 +0000 UTC 2024/12/07 01:17:16 DEBUG : Added delayed dir = "a1/b1", newDst= 2024/12/07 01:17:16 DEBUG : a1/b2: Making directory 2024/12/07 01:17:16 DEBUG : Rate limited, sleep for 5s 2024/12/07 01:17:21 DEBUG : pacer: low level retry 1/10 (error Error "error-rateLimit") 2024/12/07 01:17:21 DEBUG : pacer: Rate limited, increasing sleep to 20ms 2024/12/07 01:17:21 DEBUG : Rate limited, sleep for 5s 2024/12/07 01:17:26 DEBUG : pacer: low level retry 2/10 (error Error "error-rateLimit") 2024/12/07 01:17:26 DEBUG : pacer: Rate limited, increasing sleep to 40ms 2024/12/07 01:17:27 DEBUG : pacer: Reducing sleep to 20ms 2024/12/07 01:17:27 DEBUG : pacer: Reducing sleep to 10ms 2024/12/07 01:17:27 INFO : a1/b2: Made directory with modification time 2001-02-03 04:09:06.499999999 +0000 UTC 2024/12/07 01:17:27 DEBUG : Added delayed dir = "a1/b2", newDst= 2024/12/07 01:17:27 DEBUG : a1/b2/c1: Making directory 2024/12/07 01:17:27 DEBUG : a1/b1/c1: Making directory 2024/12/07 01:17:28 INFO : a1/b2/c1: Made directory with modification time 2001-02-03 04:08:06.499999999 +0000 UTC 2024/12/07 01:17:28 DEBUG : Added delayed dir = "a1/b2/c1", newDst= 2024/12/07 01:17:28 DEBUG : a1/b2/c1/d1: Making directory 2024/12/07 01:17:28 INFO : a1/b1/c1: Made directory with modification time 2001-02-03 04:17:06.499999999 +0000 UTC 2024/12/07 01:17:28 DEBUG : a1/b1/c1/d1: Making directory 2024/12/07 01:17:29 INFO : a1/b2/c1/d1: Made directory with modification time 2001-02-03 04:07:06.499999999 +0000 UTC 2024/12/07 01:17:29 DEBUG : Added delayed dir = "a1/b2/c1/d1", newDst= 2024/12/07 01:17:29 DEBUG : a1/b2/c1/d1/e1: Making directory 2024/12/07 01:17:30 INFO : a1/b1/c1/d1: Made directory with modification time 2001-02-03 04:16:06.499999999 +0000 UTC 2024/12/07 01:17:30 DEBUG : Added delayed dir = "a1/b1/c1/d1", newDst= 2024/12/07 01:17:30 DEBUG : a1/b1/c1/d2: Making directory 2024/12/07 01:17:30 DEBUG : Rate limited, sleep for 5s 2024/12/07 01:17:30 INFO : a1/b2/c1/d1/e1: Made directory with modification time 2001-02-03 04:06:06.499999999 +0000 UTC 2024/12/07 01:17:30 DEBUG : Added delayed dir = "a1/b2/c1/d1/e1", newDst= 2024/12/07 01:17:30 DEBUG : a1/b2/c1/d1/e1/f1: Making directory 2024/12/07 01:17:35 DEBUG : pacer: low level retry 1/10 (error Error "error-rateLimit") 2024/12/07 01:17:35 DEBUG : pacer: Rate limited, increasing sleep to 20ms 2024/12/07 01:17:35 DEBUG : Rate limited, sleep for 5s 2024/12/07 01:17:40 DEBUG : pacer: low level retry 2/10 (error Error "error-rateLimit") 2024/12/07 01:17:40 DEBUG : pacer: Rate limited, increasing sleep to 40ms 2024/12/07 01:17:40 DEBUG : pacer: Reducing sleep to 20ms 2024/12/07 01:17:41 DEBUG : pacer: Reducing sleep to 10ms 2024/12/07 01:17:41 INFO : a1/b1/c1/d2: Made directory with modification time 2001-02-03 04:13:06.499999999 +0000 UTC 2024/12/07 01:17:41 DEBUG : Added delayed dir = "a1/b1/c1/d2", newDst= 2024/12/07 01:17:41 DEBUG : a1/b1/c1/d2/e1: Making directory 2024/12/07 01:17:41 DEBUG : a1/b1/c1/d1/e1: Making directory 2024/12/07 01:17:41 INFO : a1/b2/c1/d1/e1/f1: Made directory with modification time 2001-02-03 04:05:06.499999999 +0000 UTC 2024/12/07 01:17:41 DEBUG : Added delayed dir = "a1/b2/c1/d1/e1/f1", newDst= 2024/12/07 01:17:42 INFO : a1/b1/c1/d2/e1: Made directory with modification time 2001-02-03 04:12:06.499999999 +0000 UTC 2024/12/07 01:17:42 DEBUG : Added delayed dir = "a1/b1/c1/d2/e1", newDst= 2024/12/07 01:17:42 DEBUG : a1/b1/c1/d2/e1/f1: Making directory 2024/12/07 01:17:42 INFO : a1/b1/c1/d1/e1: Made directory with modification time 2001-02-03 04:15:06.499999999 +0000 UTC 2024/12/07 01:17:42 DEBUG : Added delayed dir = "a1/b1/c1/d1/e1", newDst= 2024/12/07 01:17:42 DEBUG : a1/b1/c1/d1/e1/f1: Making directory 2024/12/07 01:17:43 INFO : a1/b1/c1/d2/e1/f1: Made directory with modification time 2001-02-03 04:11:06.499999999 +0000 UTC 2024/12/07 01:17:43 DEBUG : Added delayed dir = "a1/b1/c1/d2/e1/f1", newDst= 2024/12/07 01:17:43 DEBUG : a1/b1/c1/d2/e1/f2: Making directory 2024/12/07 01:17:43 INFO : a1/b1/c1/d1/e1/f1: Made directory with modification time 2001-02-03 04:14:06.499999999 +0000 UTC 2024/12/07 01:17:43 DEBUG : Added delayed dir = "a1/b1/c1/d1/e1/f1", newDst= 2024/12/07 01:17:43 INFO : a1/b1/c1/d2/e1/f2: Made directory with modification time 2001-02-03 04:10:06.499999999 +0000 UTC 2024/12/07 01:17:43 DEBUG : Added delayed dir = "a1/b1/c1/d2/e1/f2", newDst= 2024/12/07 01:17:43 DEBUG : gofile root 'rclone-test-puwulif3qepu': Waiting for checks to finish 2024/12/07 01:17:43 DEBUG : gofile root 'rclone-test-puwulif3qepu': Waiting for transfers to finish 2024/12/07 01:17:43 ERROR : gofile root 'rclone-test-puwulif3qepu': not deleting files as there were IO errors 2024/12/07 01:17:44 INFO : a1/b1/c1/d2/e1/f2: Set directory modification time (using DirSetModTime) 2024/12/07 01:17:44 INFO : a1/b1/c1/d2/e1/f1: Set directory modification time (using DirSetModTime) 2024/12/07 01:17:44 INFO : a1/b1/c1/d1/e1/f1: Set directory modification time (using DirSetModTime) 2024/12/07 01:17:44 INFO : a1/b2/c1/d1/e1/f1: Set directory modification time (using DirSetModTime) 2024/12/07 01:17:44 INFO : a1/b1/c1/d1/e1: Set directory modification time (using DirSetModTime) 2024/12/07 01:17:44 INFO : a1/b2/c1/d1/e1: Set directory modification time (using DirSetModTime) 2024/12/07 01:17:44 INFO : a1/b1/c1/d2/e1: Set directory modification time (using DirSetModTime) 2024/12/07 01:17:44 INFO : a1/b1/c1/d2: Set directory modification time (using DirSetModTime) 2024/12/07 01:17:44 INFO : a1/b2/c1/d1: Set directory modification time (using DirSetModTime) 2024/12/07 01:17:44 INFO : a1/b1/c1/d1: Set directory modification time (using DirSetModTime) 2024/12/07 01:17:44 INFO : a1/b2/c1: Set directory modification time (using DirSetModTime) 2024/12/07 01:17:45 INFO : a1/b1: Set directory modification time (using DirSetModTime) 2024/12/07 01:17:45 INFO : a1/b2: Set directory modification time (using DirSetModTime) 2024/12/07 01:17:45 INFO : a1: Set directory modification time (using DirSetModTime) 2024/12/07 01:17:45 ERROR : gofile root 'rclone-test-puwulif3qepu': not deleting directories as there were IO errors sync_test.go:548: Error Trace: /home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync_test.go:548 Error: Received unexpected error: failed to patch item "modTime" to 981173826: Error "error-notFound" Test: TestSyncSetDelayedModTimes run.go:125: removing dir "a1/b1/c1/d1/e1" failed - try 1/3: directory not empty run.go:125: removing dir "a1" failed - try 1/3: directory not empty --- FAIL: TestSyncSetDelayedModTimes (40.63s) === RUN TestSyncBackupDirWithSuffixKeepExtension run.go:180: Remote "gofile root 'rclone-test-puwulif3qepu'", Local "Local file system at /tmp/rclone3259066495", Modify Window "1s" 2024/12/07 01:17:56 DEBUG : Upload server store-eu-par-1 (eu) responded in 124.721187ms 2024/12/07 01:17:56 DEBUG : Upload server store10 (eu) responded in 130.211831ms 2024/12/07 01:17:56 DEBUG : dst/one: Using upload server store10 (eu) 2024/12/07 01:17:56 DEBUG : dst/two: Using upload server store10 (eu) 2024/12/07 01:17:56 DEBUG : dst/three.txt: Using upload server store10 (eu) 2024/12/07 01:17:57 DEBUG : Creating backend with remote "TestGoFile:rclone-test-puwulif3qepu/dst" 2024/12/07 01:17:57 DEBUG : Creating backend with remote "TestGoFile:rclone-test-puwulif3qepu/backup" 2024/12/07 01:17:58 DEBUG : two: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2024/12/07 01:17:58 DEBUG : gofile root 'rclone-test-puwulif3qepu/dst': Waiting for checks to finish 2024/12/07 01:17:58 DEBUG : two: Unchanged skipping 2024/12/07 01:17:58 DEBUG : one: Sizes differ (src 4 vs dst 3) 2024/12/07 01:17:59 DEBUG : Rate limited, sleep for 5s 2024/12/07 01:18:04 DEBUG : pacer: low level retry 1/10 (error Error "error-rateLimit") 2024/12/07 01:18:04 DEBUG : pacer: Rate limited, increasing sleep to 20ms 2024/12/07 01:18:04 DEBUG : Rate limited, sleep for 5s 2024/12/07 01:18:09 DEBUG : pacer: low level retry 2/10 (error Error "error-rateLimit") 2024/12/07 01:18:09 DEBUG : pacer: Rate limited, increasing sleep to 40ms 2024/12/07 01:18:09 DEBUG : pacer: Reducing sleep to 20ms 2024/12/07 01:18:09 INFO : one: Moved (server-side) to: one-2019-01-01 2024/12/07 01:18:09 DEBUG : gofile root 'rclone-test-puwulif3qepu/dst': Waiting for transfers to finish 2024/12/07 01:18:09 DEBUG : Upload server store10 (eu) responded in 126.939148ms 2024/12/07 01:18:09 DEBUG : Upload server store-eu-par-1 (eu) responded in 137.373034ms 2024/12/07 01:18:09 DEBUG : one: Using upload server store10 (eu) 2024/12/07 01:18:10 DEBUG : one: md5 = c7957179c41f69d44f217a108c7915d8 OK 2024/12/07 01:18:10 INFO : one: Copied (new) 2024/12/07 01:18:10 DEBUG : Waiting for deletions to finish 2024/12/07 01:18:10 DEBUG : pacer: Reducing sleep to 10ms 2024/12/07 01:18:10 DEBUG : Rate limited, sleep for 5s 2024/12/07 01:18:15 DEBUG : pacer: low level retry 1/10 (error Error "error-rateLimit") 2024/12/07 01:18:15 DEBUG : pacer: Rate limited, increasing sleep to 20ms 2024/12/07 01:18:16 DEBUG : pacer: Reducing sleep to 10ms 2024/12/07 01:18:16 INFO : three.txt: Moved (server-side) to: three-2019-01-01.txt 2024/12/07 01:18:16 INFO : three.txt: Moved into backup dir 2024/12/07 01:18:16 DEBUG : dst/three.txt: Using upload server store-eu-par-1 (eu) 2024/12/07 01:18:17 DEBUG : one: Sizes differ (src 5 vs dst 4) 2024/12/07 01:18:17 DEBUG : two: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2024/12/07 01:18:17 DEBUG : two: Unchanged skipping 2024/12/07 01:18:17 DEBUG : gofile root 'rclone-test-puwulif3qepu/dst': Waiting for checks to finish 2024/12/07 01:18:17 INFO : one-2019-01-01: Deleted 2024/12/07 01:18:17 DEBUG : Rate limited, sleep for 5s 2024/12/07 01:18:22 DEBUG : pacer: low level retry 1/10 (error Error "error-rateLimit") 2024/12/07 01:18:22 DEBUG : pacer: Rate limited, increasing sleep to 20ms 2024/12/07 01:18:23 DEBUG : pacer: Reducing sleep to 10ms 2024/12/07 01:18:23 INFO : one: Moved (server-side) to: one-2019-01-01 2024/12/07 01:18:23 DEBUG : gofile root 'rclone-test-puwulif3qepu/dst': Waiting for transfers to finish 2024/12/07 01:18:23 DEBUG : one: Using upload server store10 (eu) 2024/12/07 01:18:23 DEBUG : one: md5 = 0f93e81041f0cab37c37a05ae998b219 OK 2024/12/07 01:18:23 INFO : one: Copied (new) 2024/12/07 01:18:23 DEBUG : Waiting for deletions to finish 2024/12/07 01:18:24 INFO : three-2019-01-01.txt: Deleted 2024/12/07 01:18:24 DEBUG : Rate limited, sleep for 5s 2024/12/07 01:18:29 DEBUG : pacer: low level retry 1/10 (error Error "error-rateLimit") 2024/12/07 01:18:29 DEBUG : pacer: Rate limited, increasing sleep to 20ms 2024/12/07 01:18:29 DEBUG : pacer: Reducing sleep to 10ms 2024/12/07 01:18:29 INFO : three.txt: Moved (server-side) to: three-2019-01-01.txt 2024/12/07 01:18:29 INFO : three.txt: Moved into backup dir --- PASS: TestSyncBackupDirWithSuffixKeepExtension (36.75s) === RUN TestSyncSuffixKeepExtension run.go:180: Remote "gofile root 'rclone-test-puwulif3qepu'", Local "Local file system at /tmp/rclone3259066495", Modify Window "1s" 2024/12/07 01:18:32 DEBUG : dst/one: Using upload server store10 (eu) 2024/12/07 01:18:33 DEBUG : dst/two: Using upload server store-eu-par-1 (eu) 2024/12/07 01:18:33 DEBUG : dst/three.txt: Using upload server store10 (eu) 2024/12/07 01:18:34 DEBUG : Creating backend with remote "TestGoFile:rclone-test-puwulif3qepu/dst" 2024/12/07 01:18:34 DEBUG : one: Sizes differ (src 4 vs dst 3) 2024/12/07 01:18:34 INFO : one: Moved (server-side) to: one-2019-01-01 2024/12/07 01:18:35 DEBUG : Upload server store-eu-par-1 (eu) responded in 124.451585ms 2024/12/07 01:18:35 DEBUG : Upload server store10 (eu) responded in 153.842548ms 2024/12/07 01:18:35 DEBUG : one: Using upload server store10 (eu) 2024/12/07 01:18:35 DEBUG : one: md5 = c7957179c41f69d44f217a108c7915d8 OK 2024/12/07 01:18:35 INFO : one: Copied (new) 2024/12/07 01:18:35 DEBUG : two: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2024/12/07 01:18:35 DEBUG : two: Unchanged skipping 2024/12/07 01:18:35 DEBUG : three.txt: Sizes differ (src 6 vs dst 5) 2024/12/07 01:18:36 INFO : three.txt: Moved (server-side) to: three-2019-01-01.txt 2024/12/07 01:18:36 DEBUG : three.txt: Using upload server store-eu-par-1 (eu) 2024/12/07 01:18:36 DEBUG : three.txt: md5 = 91341eed84691a83caea73aa785736d5 OK 2024/12/07 01:18:36 INFO : three.txt: Copied (new) 2024/12/07 01:18:37 DEBUG : one: Sizes differ (src 5 vs dst 4) 2024/12/07 01:18:37 INFO : one-2019-01-01: Deleted 2024/12/07 01:18:37 INFO : one: Moved (server-side) to: one-2019-01-01 2024/12/07 01:18:37 DEBUG : one: Using upload server store10 (eu) 2024/12/07 01:18:37 DEBUG : one: md5 = 0f93e81041f0cab37c37a05ae998b219 OK 2024/12/07 01:18:37 INFO : one: Copied (new) 2024/12/07 01:18:38 DEBUG : two: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2024/12/07 01:18:38 DEBUG : two: Unchanged skipping 2024/12/07 01:18:38 DEBUG : three.txt: Sizes differ (src 19 vs dst 6) 2024/12/07 01:18:38 INFO : three-2019-01-01.txt: Deleted 2024/12/07 01:18:38 INFO : three.txt: Moved (server-side) to: three-2019-01-01.txt 2024/12/07 01:18:38 DEBUG : three.txt: Using upload server store-eu-par-1 (eu) 2024/12/07 01:18:39 DEBUG : three.txt: md5 = 423e01c5e84a30d129b97aedb6e219a9 OK 2024/12/07 01:18:39 INFO : three.txt: Copied (new) --- PASS: TestSyncSuffixKeepExtension (9.33s) FAIL 2024/12/07 01:18:41 DEBUG : gofile root 'rclone-test-puwulif3qepu': Purge remote "./sync.test -test.v -test.timeout 1h0m0s -remote TestGoFile: -verbose -fast-list -test.run '^(TestSyncBackupDirWithSuffixKeepExtension|TestSyncSetDelayedModTimes|TestSyncSuffixKeepExtension)$'" - Finished ERROR in 1m27.448831102s (try 2/5): exit status 1: Failed [TestSyncSetDelayedModTimes]