"./sync.test -test.v -test.timeout 1h0m0s -remote TestFilesCom: -verbose -test.run '^(TestCopyNoEmptyDirectories|TestServerSideMoveWithFilter|TestSyncBackupDirSuffixOnly|TestSyncEmptyDirectories|TestSyncNoEmptyDirectories|TestSyncNoUpdateDirModtime|TestSyncSetDelayedModTimes)$'" - Starting (try 2/5) 2026/04/25 05:45:50 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-mecoqun8qana" 2026/04/25 05:45:50 DEBUG : Using config file from "/home/rclone/.rclone.conf" 2026/04/25 05:45:50 DEBUG : Creating backend with remote "/tmp/rclone3116109138" === RUN TestCopyNoEmptyDirectories run.go:185: Remote "files root 'rclone-test-mecoqun8qana'", Local "Local file system at /tmp/rclone3116109138", Modify Window "1s" 2026/04/25 05:45:50 INFO : sub dir2: Making directory 2026/04/25 05:45:50 DEBUG : sub dir2/sub sub dir2: Making directory with metadata 2026/04/25 05:45:50 INFO : sub dir2/sub sub dir2: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z) 2026/04/25 05:45:51 DEBUG : Added delayed dir = "sub dir2", newDst= 2026/04/25 05:45:51 DEBUG : Added delayed dir = "sub dir", newDst= 2026/04/25 05:45:51 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2026/04/25 05:45:51 DEBUG : Added delayed dir = "sub dir2/sub sub dir2", newDst= 2026/04/25 05:45:51 DEBUG : files root 'rclone-test-mecoqun8qana': Waiting for checks to finish 2026/04/25 05:45:51 DEBUG : files root 'rclone-test-mecoqun8qana': Waiting for transfers to finish 2026/04/25 05:45:52 DEBUG : sub dir/hello world: size = 11 OK 2026/04/25 05:45:52 DEBUG : sub dir/hello world: Dst hash empty - aborting Src hash check 2026/04/25 05:45:52 INFO : sub dir/hello world: Copied (new) 2026/04/25 05:45:53 INFO : sub dir: Set directory modification time (using DirSetModTime) --- PASS: TestCopyNoEmptyDirectories (3.77s) === RUN TestSyncNoUpdateDirModtime run.go:185: Remote "files root 'rclone-test-mecoqun8qana'", Local "Local file system at /tmp/rclone3116109138", Modify Window "1s" 2026/04/25 05:45:54 DEBUG : sub dir no update dir modtime: Making directory with metadata 2026/04/25 05:45:54 INFO : sub dir no update dir modtime: Made directory with metadata (mtime=2001-02-03T04:05:06.499999999Z) 2026/04/25 05:45:55 DEBUG : files root 'rclone-test-mecoqun8qana': Waiting for checks to finish 2026/04/25 05:45:55 DEBUG : files root 'rclone-test-mecoqun8qana': Waiting for transfers to finish 2026/04/25 05:45:55 DEBUG : Waiting for deletions to finish --- PASS: TestSyncNoUpdateDirModtime (1.47s) === RUN TestSyncEmptyDirectories run.go:185: Remote "files root 'rclone-test-mecoqun8qana'", Local "Local file system at /tmp/rclone3116109138", Modify Window "1s" 2026/04/25 05:45:55 DEBUG : sub dir2: Making directory with metadata 2026/04/25 05:45:55 INFO : sub dir2: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z) 2026/04/25 05:45:55 INFO : sub dir: Set directory modification time (using DirSetModTime) 2026/04/25 05:45:56 INFO : sub dir2: Making directory 2026/04/25 05:45:56 INFO : sub dir2: Made directory with modification time 2011-12-25 12:59:59.123456789 +0000 UTC 2026/04/25 05:45:56 DEBUG : Added delayed dir = "sub dir2", newDst= 2026/04/25 05:45:56 INFO : sub dir: Making directory 2026/04/25 05:45:56 INFO : sub dir: Made directory with modification time 2001-02-03 04:05:06.499999999 +0000 UTC 2026/04/25 05:45:56 DEBUG : Added delayed dir = "sub dir", newDst= 2026/04/25 05:45:56 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2026/04/25 05:45:56 DEBUG : files root 'rclone-test-mecoqun8qana': Waiting for checks to finish 2026/04/25 05:45:56 DEBUG : files root 'rclone-test-mecoqun8qana': Waiting for transfers to finish 2026/04/25 05:45:57 DEBUG : sub dir/hello world: size = 11 OK 2026/04/25 05:45:57 DEBUG : sub dir/hello world: Dst hash empty - aborting Src hash check 2026/04/25 05:45:57 INFO : sub dir/hello world: Copied (new) 2026/04/25 05:45:57 DEBUG : Waiting for deletions to finish 2026/04/25 05:45:57 INFO : sub dir: Set directory modification time (using DirSetModTime) 2026/04/25 05:45:57 INFO : sub dir2: Set directory modification time (using DirSetModTime) --- PASS: TestSyncEmptyDirectories (3.03s) === RUN TestSyncSetDelayedModTimes run.go:185: Remote "files root 'rclone-test-mecoqun8qana'", Local "Local file system at /tmp/rclone3116109138", Modify Window "1s" 2026/04/25 05:45:59 INFO : a1/b2/c1/d1/e1/f1: Set directory modification time (using DirSetModTime) 2026/04/25 05:45:59 INFO : a1/b2/c1/d1/e1: Set directory modification time (using DirSetModTime) 2026/04/25 05:45:59 INFO : a1/b2/c1/d1: Set directory modification time (using DirSetModTime) 2026/04/25 05:45:59 INFO : a1/b2/c1: Set directory modification time (using DirSetModTime) 2026/04/25 05:45:59 INFO : a1/b2: Set directory modification time (using DirSetModTime) 2026/04/25 05:45:59 INFO : a1/b1/c1/d2/e1/f2: Set directory modification time (using DirSetModTime) 2026/04/25 05:45:59 INFO : a1/b1/c1/d2/e1/f1: Set directory modification time (using DirSetModTime) 2026/04/25 05:45:59 INFO : a1/b1/c1/d2/e1: Set directory modification time (using DirSetModTime) 2026/04/25 05:45:59 INFO : a1/b1/c1/d2: Set directory modification time (using DirSetModTime) 2026/04/25 05:45:59 INFO : a1/b1/c1/d1/e1/f1: Set directory modification time (using DirSetModTime) 2026/04/25 05:45:59 INFO : a1/b1/c1/d1/e1: Set directory modification time (using DirSetModTime) 2026/04/25 05:45:59 INFO : a1/b1/c1/d1: Set directory modification time (using DirSetModTime) 2026/04/25 05:45:59 INFO : a1/b1/c1: Set directory modification time (using DirSetModTime) 2026/04/25 05:45:59 INFO : a1/b1: Set directory modification time (using DirSetModTime) 2026/04/25 05:45:59 INFO : a1: Set directory modification time (using DirSetModTime) 2026/04/25 05:45:59 INFO : a1: Making directory 2026/04/25 05:45:59 INFO : a1: Made directory with modification time 2001-02-03 04:19:06.499999999 +0000 UTC 2026/04/25 05:45:59 DEBUG : Added delayed dir = "a1", newDst= 2026/04/25 05:45:59 INFO : a1/b1: Making directory 2026/04/25 05:45:59 INFO : a1/b1: Made directory with modification time 2001-02-03 04:18:06.499999999 +0000 UTC 2026/04/25 05:45:59 DEBUG : Added delayed dir = "a1/b1", newDst= 2026/04/25 05:45:59 INFO : a1/b2: Making directory 2026/04/25 05:46:00 INFO : a1/b2: Made directory with modification time 2001-02-03 04:09:06.499999999 +0000 UTC 2026/04/25 05:46:00 DEBUG : Added delayed dir = "a1/b2", newDst= 2026/04/25 05:46:00 INFO : a1/b2/c1: Making directory 2026/04/25 05:46:00 INFO : a1/b1/c1: Making directory 2026/04/25 05:46:00 INFO : a1/b1/c1: Made directory with modification time 2001-02-03 04:17:06.499999999 +0000 UTC 2026/04/25 05:46:00 DEBUG : Added delayed dir = "a1/b1/c1", newDst= 2026/04/25 05:46:00 INFO : a1/b1/c1/d1: Making directory 2026/04/25 05:46:00 INFO : a1/b2/c1: Made directory with modification time 2001-02-03 04:08:06.499999999 +0000 UTC 2026/04/25 05:46:00 DEBUG : Added delayed dir = "a1/b2/c1", newDst= 2026/04/25 05:46:00 INFO : a1/b2/c1/d1: Making directory 2026/04/25 05:46:00 INFO : a1/b2/c1/d1: Made directory with modification time 2001-02-03 04:07:06.499999999 +0000 UTC 2026/04/25 05:46:00 DEBUG : Added delayed dir = "a1/b2/c1/d1", newDst= 2026/04/25 05:46:00 INFO : a1/b2/c1/d1/e1: Making directory 2026/04/25 05:46:00 INFO : a1/b1/c1/d1: Made directory with modification time 2001-02-03 04:16:06.499999999 +0000 UTC 2026/04/25 05:46:00 DEBUG : Added delayed dir = "a1/b1/c1/d1", newDst= 2026/04/25 05:46:00 INFO : a1/b1/c1/d2: Making directory 2026/04/25 05:46:00 INFO : a1/b2/c1/d1/e1: Made directory with modification time 2001-02-03 04:06:06.499999999 +0000 UTC 2026/04/25 05:46:00 DEBUG : Added delayed dir = "a1/b2/c1/d1/e1", newDst= 2026/04/25 05:46:00 INFO : a1/b2/c1/d1/e1/f1: Making directory 2026/04/25 05:46:01 INFO : a1/b1/c1/d2: Made directory with modification time 2001-02-03 04:13:06.499999999 +0000 UTC 2026/04/25 05:46:01 DEBUG : Added delayed dir = "a1/b1/c1/d2", newDst= 2026/04/25 05:46:01 INFO : a1/b1/c1/d2/e1: Making directory 2026/04/25 05:46:01 INFO : a1/b1/c1/d1/e1: Making directory 2026/04/25 05:46:01 INFO : a1/b2/c1/d1/e1/f1: Made directory with modification time 2001-02-03 04:05:06.499999999 +0000 UTC 2026/04/25 05:46:01 DEBUG : Added delayed dir = "a1/b2/c1/d1/e1/f1", newDst= 2026/04/25 05:46:01 INFO : a1/b1/c1/d2/e1: Made directory with modification time 2001-02-03 04:12:06.499999999 +0000 UTC 2026/04/25 05:46:01 DEBUG : Added delayed dir = "a1/b1/c1/d2/e1", newDst= 2026/04/25 05:46:01 INFO : a1/b1/c1/d2/e1/f1: Making directory 2026/04/25 05:46:01 INFO : a1/b1/c1/d1/e1: Made directory with modification time 2001-02-03 04:15:06.499999999 +0000 UTC 2026/04/25 05:46:01 DEBUG : Added delayed dir = "a1/b1/c1/d1/e1", newDst= 2026/04/25 05:46:01 INFO : a1/b1/c1/d1/e1/f1: Making directory 2026/04/25 05:46:01 INFO : a1/b1/c1/d2/e1/f1: Made directory with modification time 2001-02-03 04:11:06.499999999 +0000 UTC 2026/04/25 05:46:01 DEBUG : Added delayed dir = "a1/b1/c1/d2/e1/f1", newDst= 2026/04/25 05:46:01 INFO : a1/b1/c1/d2/e1/f2: Making directory 2026/04/25 05:46:01 INFO : a1/b1/c1/d1/e1/f1: Made directory with modification time 2001-02-03 04:14:06.499999999 +0000 UTC 2026/04/25 05:46:01 DEBUG : Added delayed dir = "a1/b1/c1/d1/e1/f1", newDst= 2026/04/25 05:46:01 INFO : a1/b1/c1/d2/e1/f2: Made directory with modification time 2001-02-03 04:10:06.499999999 +0000 UTC 2026/04/25 05:46:01 DEBUG : Added delayed dir = "a1/b1/c1/d2/e1/f2", newDst= 2026/04/25 05:46:01 DEBUG : files root 'rclone-test-mecoqun8qana': Waiting for checks to finish 2026/04/25 05:46:01 DEBUG : files root 'rclone-test-mecoqun8qana': Waiting for transfers to finish 2026/04/25 05:46:01 DEBUG : Waiting for deletions to finish 2026/04/25 05:46:02 INFO : a1/b1/c1/d2/e1/f2: Set directory modification time (using DirSetModTime) 2026/04/25 05:46:02 INFO : a1/b2/c1/d1/e1/f1: Set directory modification time (using DirSetModTime) 2026/04/25 05:46:02 INFO : a1/b1/c1/d2/e1/f1: Set directory modification time (using DirSetModTime) 2026/04/25 05:46:02 INFO : a1/b1/c1/d1/e1/f1: Set directory modification time (using DirSetModTime) 2026/04/25 05:46:02 INFO : a1/b2/c1/d1/e1: Set directory modification time (using DirSetModTime) 2026/04/25 05:46:02 INFO : a1/b1/c1/d1/e1: Set directory modification time (using DirSetModTime) 2026/04/25 05:46:02 INFO : a1/b1/c1/d2/e1: Set directory modification time (using DirSetModTime) 2026/04/25 05:46:02 INFO : a1/b2/c1/d1: Set directory modification time (using DirSetModTime) 2026/04/25 05:46:02 INFO : a1/b1/c1/d2: Set directory modification time (using DirSetModTime) 2026/04/25 05:46:02 INFO : a1/b1/c1/d1: Set directory modification time (using DirSetModTime) 2026/04/25 05:46:02 INFO : a1/b2/c1: Set directory modification time (using DirSetModTime) 2026/04/25 05:46:02 INFO : a1/b1/c1: Set directory modification time (using DirSetModTime) 2026/04/25 05:46:02 INFO : a1/b2: Set directory modification time (using DirSetModTime) 2026/04/25 05:46:02 INFO : a1/b1: Set directory modification time (using DirSetModTime) 2026/04/25 05:46:02 INFO : a1: Set directory modification time (using DirSetModTime) 2026/04/25 05:46:06 DEBUG : pacer: low level retry 1/10 (error Folder Not Empty - `Folder rclone-test-mecoqun8qana/a1/b2/c1/d1/e1 not empty`) 2026/04/25 05:46:06 DEBUG : pacer: Rate limited, increasing sleep to 20ms 2026/04/25 05:46:07 DEBUG : pacer: low level retry 2/10 (error Folder Not Empty - `Folder rclone-test-mecoqun8qana/a1/b2/c1/d1/e1 not empty`) 2026/04/25 05:46:07 DEBUG : pacer: Rate limited, increasing sleep to 40ms 2026/04/25 05:46:07 DEBUG : pacer: Reducing sleep to 30ms 2026/04/25 05:46:07 DEBUG : pacer: Reducing sleep to 22.5ms 2026/04/25 05:46:07 DEBUG : pacer: low level retry 1/10 (error Folder Not Empty - `Folder rclone-test-mecoqun8qana/a1/b2/c1 not empty`) 2026/04/25 05:46:07 DEBUG : pacer: Rate limited, increasing sleep to 45ms 2026/04/25 05:46:07 DEBUG : pacer: Reducing sleep to 33.75ms 2026/04/25 05:46:07 DEBUG : pacer: Reducing sleep to 25.3125ms 2026/04/25 05:46:07 DEBUG : pacer: Reducing sleep to 18.984375ms 2026/04/25 05:46:08 DEBUG : pacer: Reducing sleep to 14.238281ms 2026/04/25 05:46:08 DEBUG : pacer: low level retry 1/10 (error Folder Not Empty - `Folder rclone-test-mecoqun8qana/a1/b1/c1/d2/e1 not empty`) 2026/04/25 05:46:08 DEBUG : pacer: Rate limited, increasing sleep to 28.476562ms 2026/04/25 05:46:08 DEBUG : pacer: low level retry 2/10 (error Folder Not Empty - `Folder rclone-test-mecoqun8qana/a1/b1/c1/d2/e1 not empty`) 2026/04/25 05:46:08 DEBUG : pacer: Rate limited, increasing sleep to 56.953124ms 2026/04/25 05:46:08 DEBUG : pacer: Reducing sleep to 42.714843ms 2026/04/25 05:46:08 DEBUG : pacer: Reducing sleep to 32.036132ms 2026/04/25 05:46:08 DEBUG : pacer: Reducing sleep to 24.027099ms 2026/04/25 05:46:08 DEBUG : pacer: low level retry 1/10 (error Folder Not Empty - `Folder rclone-test-mecoqun8qana/a1/b1/c1/d1/e1 not empty`) 2026/04/25 05:46:08 DEBUG : pacer: Rate limited, increasing sleep to 48.054198ms 2026/04/25 05:46:09 DEBUG : pacer: low level retry 2/10 (error Folder Not Empty - `Folder rclone-test-mecoqun8qana/a1/b1/c1/d1/e1 not empty`) 2026/04/25 05:46:09 DEBUG : pacer: Rate limited, increasing sleep to 96.108396ms 2026/04/25 05:46:09 DEBUG : pacer: low level retry 3/10 (error Folder Not Empty - `Folder rclone-test-mecoqun8qana/a1/b1/c1/d1/e1 not empty`) 2026/04/25 05:46:09 DEBUG : pacer: Rate limited, increasing sleep to 192.216792ms 2026/04/25 05:46:09 DEBUG : pacer: Reducing sleep to 144.162594ms 2026/04/25 05:46:09 DEBUG : pacer: Reducing sleep to 108.121945ms 2026/04/25 05:46:09 DEBUG : pacer: Reducing sleep to 81.091458ms 2026/04/25 05:46:09 DEBUG : pacer: low level retry 1/10 (error Folder Not Empty - `Folder rclone-test-mecoqun8qana/a1/b1 not empty`) 2026/04/25 05:46:09 DEBUG : pacer: Rate limited, increasing sleep to 162.182916ms 2026/04/25 05:46:10 DEBUG : pacer: Reducing sleep to 121.637187ms 2026/04/25 05:46:10 DEBUG : pacer: low level retry 1/10 (error Folder Not Empty - `Folder rclone-test-mecoqun8qana/a1 not empty`) 2026/04/25 05:46:10 DEBUG : pacer: Rate limited, increasing sleep to 243.274374ms 2026/04/25 05:46:10 DEBUG : pacer: Reducing sleep to 182.45578ms 2026/04/25 05:46:10 DEBUG : pacer: Reducing sleep to 136.841835ms --- PASS: TestSyncSetDelayedModTimes (11.50s) === RUN TestSyncNoEmptyDirectories run.go:185: Remote "files root 'rclone-test-mecoqun8qana'", Local "Local file system at /tmp/rclone3116109138", Modify Window "1s" 2026/04/25 05:46:10 INFO : sub dir2: Making directory 2026/04/25 05:46:10 DEBUG : pacer: Reducing sleep to 102.631376ms 2026/04/25 05:46:10 DEBUG : Added delayed dir = "sub dir2", newDst= 2026/04/25 05:46:10 DEBUG : Added delayed dir = "sub dir", newDst= 2026/04/25 05:46:10 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2026/04/25 05:46:10 DEBUG : files root 'rclone-test-mecoqun8qana': Waiting for checks to finish 2026/04/25 05:46:10 DEBUG : files root 'rclone-test-mecoqun8qana': Waiting for transfers to finish 2026/04/25 05:46:11 DEBUG : pacer: Reducing sleep to 76.973532ms 2026/04/25 05:46:11 DEBUG : pacer: Reducing sleep to 57.730149ms 2026/04/25 05:46:11 DEBUG : sub dir/hello world: size = 11 OK 2026/04/25 05:46:11 DEBUG : sub dir/hello world: Dst hash empty - aborting Src hash check 2026/04/25 05:46:11 INFO : sub dir/hello world: Copied (new) 2026/04/25 05:46:11 DEBUG : Waiting for deletions to finish 2026/04/25 05:46:11 DEBUG : pacer: Reducing sleep to 43.297611ms 2026/04/25 05:46:11 INFO : sub dir: Set directory modification time (using DirSetModTime) 2026/04/25 05:46:11 DEBUG : pacer: Reducing sleep to 32.473208ms 2026/04/25 05:46:11 DEBUG : pacer: Reducing sleep to 24.354906ms 2026/04/25 05:46:12 DEBUG : pacer: Reducing sleep to 18.266179ms 2026/04/25 05:46:12 DEBUG : pacer: Reducing sleep to 13.699634ms 2026/04/25 05:46:12 DEBUG : pacer: Reducing sleep to 10.274725ms 2026/04/25 05:46:12 DEBUG : pacer: Reducing sleep to 10ms --- PASS: TestSyncNoEmptyDirectories (2.29s) === RUN TestServerSideMoveWithFilter run.go:185: Remote "files root 'rclone-test-mecoqun8qana'", Local "Local file system at /tmp/rclone3116109138", Modify Window "1s" 2026/04/25 05:46:12 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-zuyoqec5zayi" sync_test.go:1736: Server side move (if possible) files root 'rclone-test-mecoqun8qana' -> files root 'rclone-test-zuyoqec5zayi' 2026/04/25 05:46:18 DEBUG : empty space: Excluded (Size Filter) 2026/04/25 05:46:18 DEBUG : empty space: Excluded 2026/04/25 05:46:18 DEBUG : empty space: Excluded (Size Filter) 2026/04/25 05:46:18 DEBUG : empty space: Excluded 2026/04/25 05:46:18 DEBUG : potato2: Need to transfer - File not found at Destination 2026/04/25 05:46:18 DEBUG : potato3: size = 68 (files root 'rclone-test-mecoqun8qana') 2026/04/25 05:46:18 DEBUG : potato3: size = 60 (files root 'rclone-test-zuyoqec5zayi') 2026/04/25 05:46:18 DEBUG : potato3: Sizes differ 2026/04/25 05:46:18 DEBUG : files root 'rclone-test-zuyoqec5zayi': Waiting for checks to finish 2026/04/25 05:46:18 DEBUG : files root 'rclone-test-zuyoqec5zayi': Waiting for transfers to finish 2026/04/25 05:46:18 INFO : potato3: Deleted 2026/04/25 05:46:18 INFO : potato2: Moved (server-side) 2026/04/25 05:46:18 INFO : potato3: Moved (server-side) 2026/04/25 05:46:18 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-xabijut0toxo" 2026/04/25 05:46:19 DEBUG : empty space: Excluded (Size Filter) 2026/04/25 05:46:19 DEBUG : empty space: Excluded 2026/04/25 05:46:19 DEBUG : potato2: Need to transfer - File not found at Destination 2026/04/25 05:46:19 DEBUG : potato3: Need to transfer - File not found at Destination 2026/04/25 05:46:19 DEBUG : files root 'rclone-test-xabijut0toxo': Waiting for checks to finish 2026/04/25 05:46:19 DEBUG : files root 'rclone-test-xabijut0toxo': Waiting for transfers to finish 2026/04/25 05:46:20 INFO : potato3: Moved (server-side) 2026/04/25 05:46:20 INFO : potato2: Moved (server-side) 2026/04/25 05:46:21 DEBUG : files root 'rclone-test-xabijut0toxo': Purge remote 2026/04/25 05:46:21 DEBUG : files root 'rclone-test-zuyoqec5zayi': Purge remote --- PASS: TestServerSideMoveWithFilter (9.65s) === RUN TestSyncBackupDirSuffixOnly run.go:185: Remote "files root 'rclone-test-mecoqun8qana'", Local "Local file system at /tmp/rclone3116109138", Modify Window "1s" 2026/04/25 05:46:26 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-mecoqun8qana/dst" 2026/04/25 05:46:27 DEBUG : one: size = 4 (Local file system at /tmp/rclone3116109138) 2026/04/25 05:46:27 DEBUG : one: size = 3 (files root 'rclone-test-mecoqun8qana/dst') 2026/04/25 05:46:27 DEBUG : one: Sizes differ 2026/04/25 05:46:27 DEBUG : two: size = 3 OK 2026/04/25 05:46:27 DEBUG : two: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2026/04/25 05:46:27 DEBUG : two: Unchanged skipping 2026/04/25 05:46:27 DEBUG : files root 'rclone-test-mecoqun8qana/dst': Waiting for checks to finish 2026/04/25 05:46:28 INFO : one: Moved (server-side) to: one.bak 2026/04/25 05:46:28 DEBUG : files root 'rclone-test-mecoqun8qana/dst': Waiting for transfers to finish 2026/04/25 05:46:29 DEBUG : one: size = 4 OK 2026/04/25 05:46:29 DEBUG : one: md5 = c7957179c41f69d44f217a108c7915d8 OK 2026/04/25 05:46:29 INFO : one: Copied (new) 2026/04/25 05:46:29 DEBUG : Waiting for deletions to finish 2026/04/25 05:46:30 INFO : three.txt: Moved (server-side) to: three.txt.bak 2026/04/25 05:46:30 INFO : three.txt: Moved into backup dir 2026/04/25 05:46:32 DEBUG : pacer: low level retry 1/10 (error Put "https://s3.amazonaws.com/objects.brickftp.com/metadata/126732/d4842a40-23e5-4f4f-a11b-47fa76ae53ba?X-Amz-Algorithm=AWS4-HMAC-SHA256&X-Amz-Credential=AKIAU5E2BGFBKFOVPYNZ%2F20260425%2Fus-east-1%2Fs3%2Faws4_request&X-Amz-Date=20260425T054631Z&X-Amz-Expires=900&X-Amz-SignedHeaders=host&partNumber=1&response-content-type=application%2Foctet-stream&uploadId=cCp6Yq8OOhr.Lb0cuHWe8VnS5w96eBF7ts8Tay8HohPVR5O3L9GeAVaBZ62mMZ2VkQaFu7a6F_wCJXVJ0Dm4zCmKpJQNDu.RxJN1keKazJPoLtiiK8H11oWMDAXxFaqN&X-Amz-Signature=ae18d87fc98be37a6603955edeb87669ed542513ca830412a6026207cbc203ad": net/http: HTTP/1.x transport connection broken: http: ContentLength=6 with Body length 0) 2026/04/25 05:46:32 DEBUG : pacer: Rate limited, increasing sleep to 20ms 2026/04/25 05:46:33 DEBUG : pacer: Reducing sleep to 15ms 2026/04/25 05:46:33 DEBUG : pacer: Reducing sleep to 11.25ms 2026/04/25 05:46:33 DEBUG : pacer: Reducing sleep to 10ms fstest.go:298: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:298: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:298: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:305: Error Trace: /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:305 /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:338 /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:350 /home/rclone/go/src/github.com/rclone/rclone/fstest/run.go:345 /home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync_test.go:2435 /home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync_test.go:2470 /usr/local/go/src/runtime/asm_amd64.s:1771 Error: Should be true Test: TestSyncBackupDirSuffixOnly Messages: listing wrong, want dst/one (4), dst/one.bak (3), dst/three.txt (6), dst/three.txt.bak (5), dst/two (3) got dst/one (4), dst/one.bak (3), dst/three.txt (0), dst/three.txt.bak (5), dst/two (3) fstest.go:143: Error Trace: /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:143 /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:149 /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:195 /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:308 /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:338 /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:350 /home/rclone/go/src/github.com/rclone/rclone/fstest/run.go:345 /home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync_test.go:2435 /home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync_test.go:2470 Error: Should be true Test: TestSyncBackupDirSuffixOnly Messages: files root 'rclone-test-mecoqun8qana'/dst/three.txt: md5 hash incorrect - expecting "91341eed84691a83caea73aa785736d5" got "d41d8cd98f00b204e9800998ecf8427e" fstest.go:143: Error Trace: /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:143 /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:149 /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:195 /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:308 /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:338 /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:350 /home/rclone/go/src/github.com/rclone/rclone/fstest/run.go:345 /home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync_test.go:2435 /home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync_test.go:2470 Error: Should be true Test: TestSyncBackupDirSuffixOnly Messages: files root 'rclone-test-mecoqun8qana'/dst/three.txt: crc32 hash incorrect - expecting "1e485dc0" got "00000000" fstest.go:150: Error Trace: /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:150 /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:195 /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:308 /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:338 /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:350 /home/rclone/go/src/github.com/rclone/rclone/fstest/run.go:345 /home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync_test.go:2435 /home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync_test.go:2470 Error: Not equal: expected: 6 actual : 0 Test: TestSyncBackupDirSuffixOnly Messages: dst/three.txt: size incorrect file=6 vs obj=0 2026/04/25 05:46:42 DEBUG : one.bak: Excluded (Path Filter) 2026/04/25 05:46:42 DEBUG : one.bak: Excluded 2026/04/25 05:46:42 DEBUG : three.txt.bak: Excluded (Path Filter) 2026/04/25 05:46:42 DEBUG : three.txt.bak: Excluded 2026/04/25 05:46:42 DEBUG : one: size = 5 (Local file system at /tmp/rclone3116109138) 2026/04/25 05:46:42 DEBUG : one: size = 4 (files root 'rclone-test-mecoqun8qana/dst') 2026/04/25 05:46:42 DEBUG : one: Sizes differ 2026/04/25 05:46:42 DEBUG : two: size = 3 OK 2026/04/25 05:46:42 DEBUG : two: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2026/04/25 05:46:42 DEBUG : two: Unchanged skipping 2026/04/25 05:46:42 DEBUG : files root 'rclone-test-mecoqun8qana/dst': Waiting for checks to finish 2026/04/25 05:46:42 INFO : one.bak: Deleted 2026/04/25 05:46:43 INFO : one: Moved (server-side) to: one.bak 2026/04/25 05:46:43 DEBUG : files root 'rclone-test-mecoqun8qana/dst': Waiting for transfers to finish 2026/04/25 05:46:44 DEBUG : one: size = 5 OK 2026/04/25 05:46:44 DEBUG : one: Dst hash empty - aborting Src hash check 2026/04/25 05:46:44 INFO : one: Copied (new) 2026/04/25 05:46:44 DEBUG : Waiting for deletions to finish 2026/04/25 05:46:44 INFO : three.txt.bak: Deleted 2026/04/25 05:46:45 INFO : three.txt: Moved (server-side) to: three.txt.bak 2026/04/25 05:46:45 INFO : three.txt: Moved into backup dir fstest.go:298: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:298: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:298: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:305: Error Trace: /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:305 /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:338 /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:350 /home/rclone/go/src/github.com/rclone/rclone/fstest/run.go:345 /home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync_test.go:2454 /home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync_test.go:2470 /usr/local/go/src/runtime/asm_amd64.s:1771 Error: Should be true Test: TestSyncBackupDirSuffixOnly Messages: listing wrong, want dst/one (5), dst/one.bak (4), dst/three.txt.bak (6), dst/two (3) got dst/one (5), dst/one.bak (4), dst/three.txt.bak (0), dst/two (3) fstest.go:143: Error Trace: /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:143 /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:149 /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:195 /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:308 /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:338 /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:350 /home/rclone/go/src/github.com/rclone/rclone/fstest/run.go:345 /home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync_test.go:2454 /home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync_test.go:2470 Error: Should be true Test: TestSyncBackupDirSuffixOnly Messages: files root 'rclone-test-mecoqun8qana'/dst/three.txt.bak: md5 hash incorrect - expecting "91341eed84691a83caea73aa785736d5" got "d41d8cd98f00b204e9800998ecf8427e" fstest.go:143: Error Trace: /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:143 /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:149 /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:195 /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:308 /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:338 /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:350 /home/rclone/go/src/github.com/rclone/rclone/fstest/run.go:345 /home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync_test.go:2454 /home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync_test.go:2470 Error: Should be true Test: TestSyncBackupDirSuffixOnly Messages: files root 'rclone-test-mecoqun8qana'/dst/three.txt.bak: crc32 hash incorrect - expecting "1e485dc0" got "00000000" fstest.go:150: Error Trace: /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:150 /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:195 /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:308 /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:338 /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:350 /home/rclone/go/src/github.com/rclone/rclone/fstest/run.go:345 /home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync_test.go:2454 /home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync_test.go:2470 Error: Not equal: expected: 6 actual : 0 Test: TestSyncBackupDirSuffixOnly Messages: dst/three.txt.bak: size incorrect file=6 vs obj=0 --- FAIL: TestSyncBackupDirSuffixOnly (33.70s) FAIL 2026/04/25 05:46:56 DEBUG : files root 'rclone-test-mecoqun8qana': Purge remote "./sync.test -test.v -test.timeout 1h0m0s -remote TestFilesCom: -verbose -test.run '^(TestCopyNoEmptyDirectories|TestServerSideMoveWithFilter|TestSyncBackupDirSuffixOnly|TestSyncEmptyDirectories|TestSyncNoEmptyDirectories|TestSyncNoUpdateDirModtime|TestSyncSetDelayedModTimes)$'" - Finished ERROR in 1m6.472558484s (try 2/5): exit status 1: Failed [TestSyncBackupDirSuffixOnly]