"./sync.test -test.v -test.timeout 1h0m0s -remote TestFilesCom: -verbose -test.run '^(TestAllTag|TestCopyNoEmptyDirectories|TestSyncAfterChangingModtimeOnlyWithNoUpdateModTime|TestSyncCopyDest|TestSyncEmptyDirectories|TestSyncNoEmptyDirectories|TestSyncNoUpdateDirModtime|TestSyncReplaceDirModTimeWithEmptyDirs|TestSyncSetDelayedModTimes|TestTransformFile)$'" - Starting (try 2/5) 2025/12/17 04:55:50 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-kacecad2qoli" 2025/12/17 04:55:50 DEBUG : Using config file from "/home/rclone/.rclone.conf" 2025/12/17 04:55:51 DEBUG : Creating backend with remote "/tmp/rclone970591918" === RUN TestCopyNoEmptyDirectories run.go:185: Remote "files root 'rclone-test-kacecad2qoli'", Local "Local file system at /tmp/rclone970591918", Modify Window "1s" 2025/12/17 04:55:51 INFO : sub dir2: Making directory 2025/12/17 04:55:51 DEBUG : sub dir2/sub sub dir2: Making directory with metadata 2025/12/17 04:55:51 INFO : sub dir2/sub sub dir2: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z) 2025/12/17 04:55:52 DEBUG : Added delayed dir = "sub dir2", newDst= 2025/12/17 04:55:52 DEBUG : Added delayed dir = "sub dir", newDst= 2025/12/17 04:55:52 DEBUG : Added delayed dir = "sub dir2/sub sub dir2", newDst= 2025/12/17 04:55:52 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2025/12/17 04:55:52 DEBUG : files root 'rclone-test-kacecad2qoli': Waiting for checks to finish 2025/12/17 04:55:52 DEBUG : files root 'rclone-test-kacecad2qoli': Waiting for transfers to finish 2025/12/17 04:55:53 DEBUG : sub dir/hello world: size = 11 OK 2025/12/17 04:55:53 DEBUG : sub dir/hello world: md5 = 5eb63bbbe01eeed093cb22bb8f5acdc3 OK 2025/12/17 04:55:53 INFO : sub dir/hello world: Copied (new) 2025/12/17 04:55:54 INFO : sub dir: Set directory modification time (using DirSetModTime) --- PASS: TestCopyNoEmptyDirectories (3.98s) === RUN TestSyncNoUpdateDirModtime run.go:185: Remote "files root 'rclone-test-kacecad2qoli'", Local "Local file system at /tmp/rclone970591918", Modify Window "1s" 2025/12/17 04:55:55 DEBUG : sub dir no update dir modtime: Making directory with metadata 2025/12/17 04:55:55 INFO : sub dir no update dir modtime: Made directory with metadata (mtime=2001-02-03T04:05:06.499999999Z) 2025/12/17 04:55:56 DEBUG : files root 'rclone-test-kacecad2qoli': Waiting for checks to finish 2025/12/17 04:55:56 DEBUG : files root 'rclone-test-kacecad2qoli': Waiting for transfers to finish 2025/12/17 04:55:56 DEBUG : Waiting for deletions to finish --- PASS: TestSyncNoUpdateDirModtime (1.50s) === RUN TestSyncEmptyDirectories run.go:185: Remote "files root 'rclone-test-kacecad2qoli'", Local "Local file system at /tmp/rclone970591918", Modify Window "1s" 2025/12/17 04:55:57 DEBUG : sub dir2: Making directory with metadata 2025/12/17 04:55:57 INFO : sub dir2: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z) 2025/12/17 04:55:57 INFO : sub dir: Set directory modification time (using DirSetModTime) 2025/12/17 04:55:57 INFO : sub dir2: Making directory 2025/12/17 04:55:57 INFO : sub dir2: Made directory with modification time 2011-12-25 12:59:59.123456789 +0000 UTC 2025/12/17 04:55:57 DEBUG : Added delayed dir = "sub dir2", newDst= 2025/12/17 04:55:57 INFO : sub dir: Making directory 2025/12/17 04:55:57 INFO : sub dir: Made directory with modification time 2001-02-03 04:05:06.499999999 +0000 UTC 2025/12/17 04:55:57 DEBUG : Added delayed dir = "sub dir", newDst= 2025/12/17 04:55:57 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2025/12/17 04:55:57 DEBUG : files root 'rclone-test-kacecad2qoli': Waiting for checks to finish 2025/12/17 04:55:57 DEBUG : files root 'rclone-test-kacecad2qoli': Waiting for transfers to finish 2025/12/17 04:55:58 DEBUG : sub dir/hello world: size = 11 OK 2025/12/17 04:55:58 DEBUG : sub dir/hello world: md5 = 5eb63bbbe01eeed093cb22bb8f5acdc3 OK 2025/12/17 04:55:58 INFO : sub dir/hello world: Copied (new) 2025/12/17 04:55:58 DEBUG : Waiting for deletions to finish 2025/12/17 04:55:58 INFO : sub dir: Set directory modification time (using DirSetModTime) 2025/12/17 04:55:58 INFO : sub dir2: Set directory modification time (using DirSetModTime) --- PASS: TestSyncEmptyDirectories (3.07s) === RUN TestSyncSetDelayedModTimes run.go:185: Remote "files root 'rclone-test-kacecad2qoli'", Local "Local file system at /tmp/rclone970591918", Modify Window "1s" 2025/12/17 04:56:00 INFO : a1/b2/c1/d1/e1/f1: Set directory modification time (using DirSetModTime) 2025/12/17 04:56:00 INFO : a1/b2/c1/d1/e1: Set directory modification time (using DirSetModTime) 2025/12/17 04:56:00 INFO : a1/b2/c1/d1: Set directory modification time (using DirSetModTime) 2025/12/17 04:56:00 INFO : a1/b2/c1: Set directory modification time (using DirSetModTime) 2025/12/17 04:56:00 INFO : a1/b2: Set directory modification time (using DirSetModTime) 2025/12/17 04:56:00 INFO : a1/b1/c1/d2/e1/f2: Set directory modification time (using DirSetModTime) 2025/12/17 04:56:00 INFO : a1/b1/c1/d2/e1/f1: Set directory modification time (using DirSetModTime) 2025/12/17 04:56:00 INFO : a1/b1/c1/d2/e1: Set directory modification time (using DirSetModTime) 2025/12/17 04:56:00 INFO : a1/b1/c1/d2: Set directory modification time (using DirSetModTime) 2025/12/17 04:56:00 INFO : a1/b1/c1/d1/e1/f1: Set directory modification time (using DirSetModTime) 2025/12/17 04:56:00 INFO : a1/b1/c1/d1/e1: Set directory modification time (using DirSetModTime) 2025/12/17 04:56:00 INFO : a1/b1/c1/d1: Set directory modification time (using DirSetModTime) 2025/12/17 04:56:00 INFO : a1/b1/c1: Set directory modification time (using DirSetModTime) 2025/12/17 04:56:00 INFO : a1/b1: Set directory modification time (using DirSetModTime) 2025/12/17 04:56:00 INFO : a1: Set directory modification time (using DirSetModTime) 2025/12/17 04:56:00 INFO : a1: Making directory 2025/12/17 04:56:00 INFO : a1: Made directory with modification time 2001-02-03 04:19:06.499999999 +0000 UTC 2025/12/17 04:56:00 DEBUG : Added delayed dir = "a1", newDst= 2025/12/17 04:56:00 INFO : a1/b1: Making directory 2025/12/17 04:56:00 INFO : a1/b1: Made directory with modification time 2001-02-03 04:18:06.499999999 +0000 UTC 2025/12/17 04:56:00 DEBUG : Added delayed dir = "a1/b1", newDst= 2025/12/17 04:56:00 INFO : a1/b2: Making directory 2025/12/17 04:56:01 INFO : a1/b2: Made directory with modification time 2001-02-03 04:09:06.499999999 +0000 UTC 2025/12/17 04:56:01 DEBUG : Added delayed dir = "a1/b2", newDst= 2025/12/17 04:56:01 INFO : a1/b2/c1: Making directory 2025/12/17 04:56:01 INFO : a1/b1/c1: Making directory 2025/12/17 04:56:01 INFO : a1/b2/c1: Made directory with modification time 2001-02-03 04:08:06.499999999 +0000 UTC 2025/12/17 04:56:01 DEBUG : Added delayed dir = "a1/b2/c1", newDst= 2025/12/17 04:56:01 INFO : a1/b2/c1/d1: Making directory 2025/12/17 04:56:01 INFO : a1/b1/c1: Made directory with modification time 2001-02-03 04:17:06.499999999 +0000 UTC 2025/12/17 04:56:01 DEBUG : Added delayed dir = "a1/b1/c1", newDst= 2025/12/17 04:56:01 INFO : a1/b1/c1/d1: Making directory 2025/12/17 04:56:01 INFO : a1/b2/c1/d1: Made directory with modification time 2001-02-03 04:07:06.499999999 +0000 UTC 2025/12/17 04:56:01 DEBUG : Added delayed dir = "a1/b2/c1/d1", newDst= 2025/12/17 04:56:01 INFO : a1/b2/c1/d1/e1: Making directory 2025/12/17 04:56:01 INFO : a1/b1/c1/d1: Made directory with modification time 2001-02-03 04:16:06.499999999 +0000 UTC 2025/12/17 04:56:01 DEBUG : Added delayed dir = "a1/b1/c1/d1", newDst= 2025/12/17 04:56:01 INFO : a1/b1/c1/d2: Making directory 2025/12/17 04:56:02 INFO : a1/b2/c1/d1/e1: Made directory with modification time 2001-02-03 04:06:06.499999999 +0000 UTC 2025/12/17 04:56:02 DEBUG : Added delayed dir = "a1/b2/c1/d1/e1", newDst= 2025/12/17 04:56:02 INFO : a1/b2/c1/d1/e1/f1: Making directory 2025/12/17 04:56:02 INFO : a1/b1/c1/d2: Made directory with modification time 2001-02-03 04:13:06.499999999 +0000 UTC 2025/12/17 04:56:02 DEBUG : Added delayed dir = "a1/b1/c1/d2", newDst= 2025/12/17 04:56:02 INFO : a1/b1/c1/d2/e1: Making directory 2025/12/17 04:56:02 INFO : a1/b1/c1/d1/e1: Making directory 2025/12/17 04:56:02 INFO : a1/b1/c1/d1/e1: Made directory with modification time 2001-02-03 04:15:06.499999999 +0000 UTC 2025/12/17 04:56:02 DEBUG : Added delayed dir = "a1/b1/c1/d1/e1", newDst= 2025/12/17 04:56:02 INFO : a1/b1/c1/d1/e1/f1: Making directory 2025/12/17 04:56:02 INFO : a1/b1/c1/d2/e1: Made directory with modification time 2001-02-03 04:12:06.499999999 +0000 UTC 2025/12/17 04:56:02 DEBUG : Added delayed dir = "a1/b1/c1/d2/e1", newDst= 2025/12/17 04:56:02 INFO : a1/b1/c1/d2/e1/f1: Making directory 2025/12/17 04:56:02 INFO : a1/b2/c1/d1/e1/f1: Made directory with modification time 2001-02-03 04:05:06.499999999 +0000 UTC 2025/12/17 04:56:02 DEBUG : Added delayed dir = "a1/b2/c1/d1/e1/f1", newDst= 2025/12/17 04:56:02 INFO : a1/b1/c1/d1/e1/f1: Made directory with modification time 2001-02-03 04:14:06.499999999 +0000 UTC 2025/12/17 04:56:02 DEBUG : Added delayed dir = "a1/b1/c1/d1/e1/f1", newDst= 2025/12/17 04:56:02 INFO : a1/b1/c1/d2/e1/f1: Made directory with modification time 2001-02-03 04:11:06.499999999 +0000 UTC 2025/12/17 04:56:02 DEBUG : Added delayed dir = "a1/b1/c1/d2/e1/f1", newDst= 2025/12/17 04:56:02 INFO : a1/b1/c1/d2/e1/f2: Making directory 2025/12/17 04:56:03 INFO : a1/b1/c1/d2/e1/f2: Made directory with modification time 2001-02-03 04:10:06.499999999 +0000 UTC 2025/12/17 04:56:03 DEBUG : Added delayed dir = "a1/b1/c1/d2/e1/f2", newDst= 2025/12/17 04:56:03 DEBUG : files root 'rclone-test-kacecad2qoli': Waiting for checks to finish 2025/12/17 04:56:03 DEBUG : files root 'rclone-test-kacecad2qoli': Waiting for transfers to finish 2025/12/17 04:56:03 DEBUG : Waiting for deletions to finish 2025/12/17 04:56:03 INFO : a1/b1/c1/d1/e1/f1: Set directory modification time (using DirSetModTime) 2025/12/17 04:56:03 INFO : a1/b1/c1/d2/e1/f2: Set directory modification time (using DirSetModTime) 2025/12/17 04:56:03 INFO : a1/b1/c1/d2/e1/f1: Set directory modification time (using DirSetModTime) 2025/12/17 04:56:03 INFO : a1/b2/c1/d1/e1/f1: Set directory modification time (using DirSetModTime) 2025/12/17 04:56:03 INFO : a1/b2/c1/d1/e1: Set directory modification time (using DirSetModTime) 2025/12/17 04:56:03 INFO : a1/b1/c1/d1/e1: Set directory modification time (using DirSetModTime) 2025/12/17 04:56:03 INFO : a1/b1/c1/d2/e1: Set directory modification time (using DirSetModTime) 2025/12/17 04:56:03 INFO : a1/b1/c1/d2: Set directory modification time (using DirSetModTime) 2025/12/17 04:56:03 INFO : a1/b2/c1/d1: Set directory modification time (using DirSetModTime) 2025/12/17 04:56:03 INFO : a1/b1/c1/d1: Set directory modification time (using DirSetModTime) 2025/12/17 04:56:03 INFO : a1/b2/c1: Set directory modification time (using DirSetModTime) 2025/12/17 04:56:03 INFO : a1/b1/c1: Set directory modification time (using DirSetModTime) 2025/12/17 04:56:03 INFO : a1/b1: Set directory modification time (using DirSetModTime) 2025/12/17 04:56:03 INFO : a1/b2: Set directory modification time (using DirSetModTime) 2025/12/17 04:56:04 INFO : a1: Set directory modification time (using DirSetModTime) 2025/12/17 04:56:08 DEBUG : pacer: low level retry 1/10 (error Folder Not Empty - `Folder rclone-test-kacecad2qoli/a1/b2/c1/d1/e1 not empty`) 2025/12/17 04:56:08 DEBUG : pacer: Rate limited, increasing sleep to 20ms 2025/12/17 04:56:08 DEBUG : pacer: Reducing sleep to 15ms 2025/12/17 04:56:08 DEBUG : pacer: low level retry 1/10 (error Folder Not Empty - `Folder rclone-test-kacecad2qoli/a1/b2/c1/d1 not empty`) 2025/12/17 04:56:08 DEBUG : pacer: Rate limited, increasing sleep to 30ms 2025/12/17 04:56:08 DEBUG : pacer: Reducing sleep to 22.5ms 2025/12/17 04:56:08 DEBUG : pacer: low level retry 1/10 (error Folder Not Empty - `Folder rclone-test-kacecad2qoli/a1/b2/c1 not empty`) 2025/12/17 04:56:08 DEBUG : pacer: Rate limited, increasing sleep to 45ms 2025/12/17 04:56:08 DEBUG : pacer: low level retry 2/10 (error Folder Not Empty - `Folder rclone-test-kacecad2qoli/a1/b2/c1 not empty`) 2025/12/17 04:56:08 DEBUG : pacer: Rate limited, increasing sleep to 90ms 2025/12/17 04:56:08 DEBUG : pacer: low level retry 3/10 (error Folder Not Empty - `Folder rclone-test-kacecad2qoli/a1/b2/c1 not empty`) 2025/12/17 04:56:08 DEBUG : pacer: Rate limited, increasing sleep to 180ms 2025/12/17 04:56:09 DEBUG : pacer: low level retry 4/10 (error Folder Not Empty - `Folder rclone-test-kacecad2qoli/a1/b2/c1 not empty`) 2025/12/17 04:56:09 DEBUG : pacer: Rate limited, increasing sleep to 360ms 2025/12/17 04:56:09 DEBUG : pacer: low level retry 5/10 (error Folder Not Empty - `Folder rclone-test-kacecad2qoli/a1/b2/c1 not empty`) 2025/12/17 04:56:09 DEBUG : pacer: Rate limited, increasing sleep to 720ms 2025/12/17 04:56:09 DEBUG : pacer: Reducing sleep to 540ms 2025/12/17 04:56:10 DEBUG : pacer: Reducing sleep to 405ms 2025/12/17 04:56:10 DEBUG : pacer: Reducing sleep to 303.75ms 2025/12/17 04:56:11 DEBUG : pacer: Reducing sleep to 227.8125ms 2025/12/17 04:56:11 DEBUG : pacer: low level retry 1/10 (error Folder Not Empty - `Folder rclone-test-kacecad2qoli/a1/b1/c1/d2/e1 not empty`) 2025/12/17 04:56:11 DEBUG : pacer: Rate limited, increasing sleep to 455.625ms 2025/12/17 04:56:11 DEBUG : pacer: low level retry 2/10 (error Folder Not Empty - `Folder rclone-test-kacecad2qoli/a1/b1/c1/d2/e1 not empty`) 2025/12/17 04:56:11 DEBUG : pacer: Rate limited, increasing sleep to 911.25ms 2025/12/17 04:56:12 DEBUG : pacer: Reducing sleep to 683.4375ms 2025/12/17 04:56:13 DEBUG : pacer: low level retry 1/10 (error Folder Not Empty - `Folder rclone-test-kacecad2qoli/a1/b1/c1/d2 not empty`) 2025/12/17 04:56:13 DEBUG : pacer: Rate limited, increasing sleep to 1.366875s 2025/12/17 04:56:13 DEBUG : pacer: Reducing sleep to 1.02515625s 2025/12/17 04:56:15 DEBUG : pacer: Reducing sleep to 768.867187ms 2025/12/17 04:56:16 DEBUG : pacer: Reducing sleep to 576.65039ms 2025/12/17 04:56:17 DEBUG : pacer: Reducing sleep to 432.487792ms 2025/12/17 04:56:17 DEBUG : pacer: Reducing sleep to 324.365844ms 2025/12/17 04:56:18 DEBUG : pacer: Reducing sleep to 243.274383ms 2025/12/17 04:56:18 DEBUG : pacer: Reducing sleep to 182.455787ms 2025/12/17 04:56:18 DEBUG : pacer: Reducing sleep to 136.84184ms --- PASS: TestSyncSetDelayedModTimes (18.68s) === RUN TestSyncNoEmptyDirectories run.go:185: Remote "files root 'rclone-test-kacecad2qoli'", Local "Local file system at /tmp/rclone970591918", Modify Window "1s" 2025/12/17 04:56:18 INFO : sub dir2: Making directory 2025/12/17 04:56:18 DEBUG : pacer: Reducing sleep to 102.63138ms 2025/12/17 04:56:19 DEBUG : Added delayed dir = "sub dir2", newDst= 2025/12/17 04:56:19 DEBUG : Added delayed dir = "sub dir", newDst= 2025/12/17 04:56:19 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2025/12/17 04:56:19 DEBUG : files root 'rclone-test-kacecad2qoli': Waiting for checks to finish 2025/12/17 04:56:19 DEBUG : files root 'rclone-test-kacecad2qoli': Waiting for transfers to finish 2025/12/17 04:56:20 DEBUG : pacer: Reducing sleep to 76.973535ms 2025/12/17 04:56:20 DEBUG : pacer: Reducing sleep to 57.730151ms 2025/12/17 04:56:20 DEBUG : sub dir/hello world: size = 11 OK 2025/12/17 04:56:20 DEBUG : sub dir/hello world: Dst hash empty - aborting Src hash check 2025/12/17 04:56:20 INFO : sub dir/hello world: Copied (new) 2025/12/17 04:56:20 DEBUG : Waiting for deletions to finish 2025/12/17 04:56:20 DEBUG : pacer: Reducing sleep to 43.297613ms 2025/12/17 04:56:20 INFO : sub dir: Set directory modification time (using DirSetModTime) 2025/12/17 04:56:20 DEBUG : pacer: Reducing sleep to 32.473209ms 2025/12/17 04:56:21 DEBUG : pacer: Reducing sleep to 24.354906ms 2025/12/17 04:56:21 DEBUG : pacer: Reducing sleep to 18.266179ms 2025/12/17 04:56:21 DEBUG : pacer: Reducing sleep to 13.699634ms 2025/12/17 04:56:21 DEBUG : pacer: Reducing sleep to 10.274725ms 2025/12/17 04:56:21 DEBUG : pacer: Reducing sleep to 10ms --- PASS: TestSyncNoEmptyDirectories (3.06s) === RUN TestSyncAfterChangingModtimeOnlyWithNoUpdateModTime run.go:185: Remote "files root 'rclone-test-kacecad2qoli'", Local "Local file system at /tmp/rclone970591918", Modify Window "1s" 2025/12/17 04:56:23 DEBUG : empty space: size = 1 OK 2025/12/17 04:56:23 DEBUG : empty space: Modification times differ by -95456h54m53.123456789s: 2011-12-25 12:59:59.123456789 +0000 UTC, 2001-02-03 04:05:06 +0000 UTC 2025/12/17 04:56:23 DEBUG : files root 'rclone-test-kacecad2qoli': Waiting for checks to finish 2025/12/17 04:56:23 DEBUG : empty space: md5 = 336d5ebc5436534e61d16e63ddfca327 OK 2025/12/17 04:56:23 DEBUG : empty space: Unchanged skipping 2025/12/17 04:56:23 DEBUG : files root 'rclone-test-kacecad2qoli': Waiting for transfers to finish 2025/12/17 04:56:23 DEBUG : Waiting for deletions to finish 2025/12/17 04:56:23 INFO : There was nothing to transfer --- PASS: TestSyncAfterChangingModtimeOnlyWithNoUpdateModTime (1.63s) === RUN TestSyncCopyDest run.go:185: Remote "files root 'rclone-test-kacecad2qoli'", Local "Local file system at /tmp/rclone970591918", Modify Window "1s" 2025/12/17 04:56:23 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-kacecad2qoli/dst" 2025/12/17 04:56:24 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-kacecad2qoli/CopyDest" 2025/12/17 04:56:25 DEBUG : one: Need to transfer - File not found at Destination 2025/12/17 04:56:25 DEBUG : files root 'rclone-test-kacecad2qoli/dst': Waiting for checks to finish 2025/12/17 04:56:25 DEBUG : files root 'rclone-test-kacecad2qoli/dst': Waiting for transfers to finish 2025/12/17 04:56:26 DEBUG : one: size = 3 OK 2025/12/17 04:56:26 DEBUG : one: Dst hash empty - aborting Src hash check 2025/12/17 04:56:26 INFO : one: Copied (new) 2025/12/17 04:56:26 DEBUG : Waiting for deletions to finish 2025/12/17 04:56:28 DEBUG : files root 'rclone-test-kacecad2qoli/dst': Waiting for checks to finish 2025/12/17 04:56:28 DEBUG : one: size = 5 (Local file system at /tmp/rclone970591918) 2025/12/17 04:56:28 DEBUG : one: size = 3 (files root 'rclone-test-kacecad2qoli/dst') 2025/12/17 04:56:28 DEBUG : one: Sizes differ 2025/12/17 04:56:28 DEBUG : files root 'rclone-test-kacecad2qoli/dst': Waiting for transfers to finish 2025/12/17 04:56:29 DEBUG : one: size = 5 OK 2025/12/17 04:56:29 DEBUG : one: Dst hash empty - aborting Src hash check 2025/12/17 04:56:29 INFO : one: Copied (replaced existing) 2025/12/17 04:56:29 DEBUG : Waiting for deletions to finish 2025/12/17 04:56:33 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-kacecad2qoli/BackupDir" 2025/12/17 04:56:35 DEBUG : one: size = 5 (Local file system at /tmp/rclone970591918) 2025/12/17 04:56:35 DEBUG : one: size = 3 (files root 'rclone-test-kacecad2qoli/dst') 2025/12/17 04:56:35 DEBUG : one: Sizes differ 2025/12/17 04:56:35 DEBUG : files root 'rclone-test-kacecad2qoli/dst': Waiting for checks to finish 2025/12/17 04:56:35 DEBUG : one: size = 5 OK 2025/12/17 04:56:35 DEBUG : one: Size and modification time the same (differ by -123.456789ms, within tolerance 1s) 2025/12/17 04:56:35 DEBUG : one: size = 5 (Local file system at /tmp/rclone970591918) 2025/12/17 04:56:35 DEBUG : one: size = 3 (files root 'rclone-test-kacecad2qoli/dst') 2025/12/17 04:56:35 DEBUG : one: Sizes differ 2025/12/17 04:56:36 INFO : one: Moved (server-side) 2025/12/17 04:56:39 DEBUG : one: size = 5 OK 2025/12/17 04:56:39 DEBUG : one: md5 = 07912d142f5d63ee918b34796b5a2432 OK 2025/12/17 04:56:39 INFO : one: Copied (server-side copy) 2025/12/17 04:56:39 DEBUG : one: Destination found in --copy-dest, using server-side copy 2025/12/17 04:56:39 DEBUG : files root 'rclone-test-kacecad2qoli/dst': Waiting for transfers to finish 2025/12/17 04:56:39 DEBUG : Waiting for deletions to finish 2025/12/17 04:56:42 DEBUG : one: size = 5 OK 2025/12/17 04:56:42 DEBUG : one: Size and modification time the same (differ by -123.456789ms, within tolerance 1s) 2025/12/17 04:56:42 DEBUG : one: Unchanged skipping 2025/12/17 04:56:42 DEBUG : two: size = 3 OK 2025/12/17 04:56:42 DEBUG : two: Size and modification time the same (differ by -123.456789ms, within tolerance 1s) 2025/12/17 04:56:45 DEBUG : two: size = 3 OK 2025/12/17 04:56:45 DEBUG : two: md5 = b8a9f715dbb64fd5c56e7783c6820a61 OK 2025/12/17 04:56:45 INFO : two: Copied (server-side copy) 2025/12/17 04:56:45 DEBUG : two: Destination found in --copy-dest, using server-side copy 2025/12/17 04:56:45 DEBUG : files root 'rclone-test-kacecad2qoli/dst': Waiting for checks to finish 2025/12/17 04:56:45 DEBUG : files root 'rclone-test-kacecad2qoli/dst': Waiting for transfers to finish 2025/12/17 04:56:45 DEBUG : Waiting for deletions to finish 2025/12/17 04:56:46 DEBUG : one: size = 5 OK 2025/12/17 04:56:46 DEBUG : one: Size and modification time the same (differ by -123.456789ms, within tolerance 1s) 2025/12/17 04:56:46 DEBUG : one: Unchanged skipping 2025/12/17 04:56:46 DEBUG : two: size = 3 OK 2025/12/17 04:56:46 DEBUG : two: Size and modification time the same (differ by -123.456789ms, within tolerance 1s) 2025/12/17 04:56:46 DEBUG : two: Unchanged skipping 2025/12/17 04:56:46 DEBUG : files root 'rclone-test-kacecad2qoli/dst': Waiting for checks to finish 2025/12/17 04:56:46 DEBUG : files root 'rclone-test-kacecad2qoli/dst': Waiting for transfers to finish 2025/12/17 04:56:46 DEBUG : Waiting for deletions to finish 2025/12/17 04:56:46 INFO : There was nothing to transfer 2025/12/17 04:56:48 DEBUG : one: size = 5 OK 2025/12/17 04:56:48 DEBUG : one: Size and modification time the same (differ by -123.456789ms, within tolerance 1s) 2025/12/17 04:56:48 DEBUG : one: Unchanged skipping 2025/12/17 04:56:49 DEBUG : three: size = 7 (Local file system at /tmp/rclone970591918) 2025/12/17 04:56:49 DEBUG : three: size = 5 (files root 'rclone-test-kacecad2qoli/CopyDest') 2025/12/17 04:56:49 DEBUG : three: Sizes differ 2025/12/17 04:56:49 DEBUG : three: Destination not found in --copy-dest 2025/12/17 04:56:49 DEBUG : three: Need to transfer - File not found at Destination 2025/12/17 04:56:49 DEBUG : two: size = 3 OK 2025/12/17 04:56:49 DEBUG : two: Size and modification time the same (differ by -123.456789ms, within tolerance 1s) 2025/12/17 04:56:49 DEBUG : files root 'rclone-test-kacecad2qoli/dst': Waiting for checks to finish 2025/12/17 04:56:49 DEBUG : two: Unchanged skipping 2025/12/17 04:56:49 DEBUG : files root 'rclone-test-kacecad2qoli/dst': Waiting for transfers to finish 2025/12/17 04:56:50 DEBUG : three: size = 7 OK 2025/12/17 04:56:50 DEBUG : three: Dst hash empty - aborting Src hash check 2025/12/17 04:56:50 INFO : three: Copied (new) 2025/12/17 04:56:50 DEBUG : Waiting for deletions to finish --- PASS: TestSyncCopyDest (29.29s) === RUN TestSyncReplaceDirModTimeWithEmptyDirs run.go:185: Remote "files root 'rclone-test-kacecad2qoli'", Local "Local file system at /tmp/rclone970591918", Modify Window "1s" 2025/12/17 04:56:52 DEBUG : empty_dir: Making directory with metadata 2025/12/17 04:56:52 INFO : empty_dir: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z) 2025/12/17 04:56:52 DEBUG : empty_on_remote: Making directory with metadata 2025/12/17 04:56:52 INFO : empty_on_remote: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z) 2025/12/17 04:56:52 INFO : empty_on_remote: Making directory 2025/12/17 04:56:53 INFO : empty_on_remote: Made directory with modification time 2011-12-25 12:59:59.123456789 +0000 UTC 2025/12/17 04:56:55 INFO : test_dir1: Set directory modification time (using DirSetModTime) 2025/12/17 04:56:55 INFO : test_dir2: Set directory modification time (using DirSetModTime) 2025/12/17 04:56:55 INFO : test_dir2/sub_dir: Set directory modification time (using DirSetModTime) 2025/12/17 04:56:55 INFO : empty_on_remote: Set directory modification time (using DirSetModTime) 2025/12/17 04:56:55 INFO : empty_dir: Set directory modification time (using DirSetModTime) 2025/12/17 04:56:58 DEBUG : pacer: low level retry 1/10 (error Folder Not Empty - `Folder rclone-test-kacecad2qoli/test_dir2 not empty`) 2025/12/17 04:56:58 DEBUG : pacer: Rate limited, increasing sleep to 20ms 2025/12/17 04:56:59 DEBUG : pacer: low level retry 2/10 (error Folder Not Empty - `Folder rclone-test-kacecad2qoli/test_dir2 not empty`) 2025/12/17 04:56:59 DEBUG : pacer: Rate limited, increasing sleep to 40ms 2025/12/17 04:56:59 DEBUG : pacer: low level retry 3/10 (error Folder Not Empty - `Folder rclone-test-kacecad2qoli/test_dir2 not empty`) 2025/12/17 04:56:59 DEBUG : pacer: Rate limited, increasing sleep to 80ms 2025/12/17 04:56:59 DEBUG : pacer: Reducing sleep to 60ms 2025/12/17 04:56:59 DEBUG : pacer: Reducing sleep to 45ms 2025/12/17 04:56:59 DEBUG : pacer: Reducing sleep to 33.75ms 2025/12/17 04:56:59 DEBUG : pacer: Reducing sleep to 25.3125ms 2025/12/17 04:56:59 DEBUG : pacer: Reducing sleep to 18.984375ms --- PASS: TestSyncReplaceDirModTimeWithEmptyDirs (7.03s) === RUN TestAllTag run.go:185: Remote "files root 'rclone-test-kacecad2qoli'", Local "Local file system at /tmp/rclone970591918", Modify Window "1s" 2025/12/17 04:56:59 DEBUG : empty_dir: Making directory with metadata 2025/12/17 04:56:59 INFO : empty_dir: Made directory with metadata (mtime=2001-02-03T04:05:06.499999999Z) 2025/12/17 04:56:59 DEBUG : pacer: Reducing sleep to 14.238281ms 2025/12/17 04:56:59 DEBUG : toe: transformed to: tictactoe 2025/12/17 04:56:59 DEBUG : empty_dir: transformed to: tictacempty_dir 2025/12/17 04:56:59 DEBUG : empty_dir: transformed to: tictacempty_dir 2025/12/17 04:57:00 DEBUG : empty_dir: transformed to: tictacempty_dir 2025/12/17 04:57:00 INFO : tictacempty_dir: Making directory 2025/12/17 04:57:00 DEBUG : pacer: Reducing sleep to 10.67871ms 2025/12/17 04:57:00 DEBUG : pacer: Reducing sleep to 10ms 2025/12/17 04:57:00 INFO : tictacempty_dir: Made directory with modification time 2001-02-03 04:05:06.499999999 +0000 UTC 2025/12/17 04:57:00 DEBUG : Added delayed dir = "tictacempty_dir", newDst= 2025/12/17 04:57:00 DEBUG : empty_dir: transformed to: tictacempty_dir 2025/12/17 04:57:00 DEBUG : toe: transformed to: tictactoe 2025/12/17 04:57:00 DEBUG : toe: transformed to: tictactoe 2025/12/17 04:57:00 INFO : tictactoe: Making directory 2025/12/17 04:57:00 INFO : tictactoe: Made directory with modification time 2025-12-17 04:56:59.888608933 +0000 UTC 2025/12/17 04:57:00 DEBUG : Added delayed dir = "tictactoe", newDst= 2025/12/17 04:57:00 DEBUG : toe: transformed to: tictactoe 2025/12/17 04:57:00 DEBUG : toe: transformed to: tictactoe 2025/12/17 04:57:00 DEBUG : toe/toe: transformed to: tictactoe/tictactoe 2025/12/17 04:57:00 INFO : tictactoe/tictactoe: Making directory 2025/12/17 04:57:00 INFO : tictactoe/tictactoe: Made directory with modification time 2025-12-17 04:56:59.888608933 +0000 UTC 2025/12/17 04:57:00 DEBUG : Added delayed dir = "tictactoe/tictactoe", newDst= 2025/12/17 04:57:00 DEBUG : toe/toe: transformed to: tictactoe/tictactoe 2025/12/17 04:57:00 DEBUG : toe.txt: transformed to: tictactoe.txt 2025/12/17 04:57:00 DEBUG : toe/toe/toe.txt: transformed to: tictactoe/tictactoe/tictactoe.txt 2025/12/17 04:57:00 DEBUG : toe/toe/toe.txt: Need to transfer - File not found at Destination 2025/12/17 04:57:00 DEBUG : toe/toe/toe.txt: transformed to: tictactoe/tictactoe/tictactoe.txt 2025/12/17 04:57:00 DEBUG : files root 'rclone-test-kacecad2qoli': Waiting for checks to finish 2025/12/17 04:57:00 DEBUG : files root 'rclone-test-kacecad2qoli': Waiting for transfers to finish 2025/12/17 04:57:01 DEBUG : tictactoe/tictactoe/tictactoe.txt: size = 11 OK 2025/12/17 04:57:01 DEBUG : tictactoe/tictactoe/tictactoe.txt: Dst hash empty - aborting Src hash check 2025/12/17 04:57:01 INFO : toe/toe/toe.txt: Copied (new) to: tictactoe/tictactoe/tictactoe.txt 2025/12/17 04:57:01 DEBUG : Waiting for deletions to finish 2025/12/17 04:57:02 INFO : tictactoe/tictactoe: Set directory modification time (using DirSetModTime) 2025/12/17 04:57:02 INFO : tictactoe: Set directory modification time (using DirSetModTime) 2025/12/17 04:57:02 INFO : tictacempty_dir: Set directory modification time (using DirSetModTime) 2025/12/17 04:57:02 DEBUG : files root 'rclone-test-kacecad2qoli': Waiting for checks to finish 2025/12/17 04:57:02 DEBUG : toe: transformed to: tictactoe 2025/12/17 04:57:02 DEBUG : empty_dir: transformed to: tictacempty_dir 2025/12/17 04:57:02 DEBUG : empty_dir: transformed to: tictacempty_dir 2025/12/17 04:57:02 DEBUG : toe: transformed to: tictactoe 2025/12/17 04:57:02 DEBUG : toe: transformed to: tictactoe 2025/12/17 04:57:02 DEBUG : toe.txt: transformed to: tictactoe.txt 2025/12/17 04:57:02 DEBUG : tictactoe/tictactoe/tictactoe.txt: size = 11 OK 2025/12/17 04:57:02 DEBUG : toe/toe/toe.txt: md5 = 5eb63bbbe01eeed093cb22bb8f5acdc3 OK 2025/12/17 04:57:02 DEBUG : tictactoe/tictactoe/tictactoe.txt: OK 2025/12/17 04:57:02 NOTICE: files root 'rclone-test-kacecad2qoli': 0 differences found 2025/12/17 04:57:02 NOTICE: files root 'rclone-test-kacecad2qoli': 1 matching files --- PASS: TestAllTag (4.22s) === RUN TestTransformFile run.go:185: Remote "files root 'rclone-test-kacecad2qoli'", Local "Local file system at /tmp/rclone970591918", Modify Window "1s" 2025/12/17 04:57:04 DEBUG : empty_dir: Making directory with metadata 2025/12/17 04:57:04 INFO : empty_dir: Made directory with metadata (mtime=2001-02-03T04:05:06.499999999Z) 2025/12/17 04:57:04 DEBUG : toe: transformed to: tictactoe 2025/12/17 04:57:04 DEBUG : empty_dir: transformed to: tictacempty_dir 2025/12/17 04:57:04 DEBUG : empty_dir: transformed to: tictacempty_dir 2025/12/17 04:57:04 DEBUG : empty_dir: transformed to: tictacempty_dir 2025/12/17 04:57:04 INFO : tictacempty_dir: Making directory 2025/12/17 04:57:04 INFO : tictacempty_dir: Made directory with modification time 2001-02-03 04:05:06.499999999 +0000 UTC 2025/12/17 04:57:04 DEBUG : Added delayed dir = "tictacempty_dir", newDst= 2025/12/17 04:57:04 DEBUG : empty_dir: transformed to: tictacempty_dir 2025/12/17 04:57:04 DEBUG : toe: transformed to: tictactoe 2025/12/17 04:57:04 DEBUG : toe: transformed to: tictactoe 2025/12/17 04:57:04 INFO : tictactoe: Making directory 2025/12/17 04:57:04 INFO : tictactoe: Made directory with modification time 2025-12-17 04:57:04.113651016 +0000 UTC 2025/12/17 04:57:04 DEBUG : Added delayed dir = "tictactoe", newDst= 2025/12/17 04:57:04 DEBUG : toe: transformed to: tictactoe 2025/12/17 04:57:04 DEBUG : toe: transformed to: tictactoe 2025/12/17 04:57:04 DEBUG : toe/toe: transformed to: tictactoe/tictactoe 2025/12/17 04:57:04 INFO : tictactoe/tictactoe: Making directory 2025/12/17 04:57:05 INFO : tictactoe/tictactoe: Made directory with modification time 2025-12-17 04:57:04.113651016 +0000 UTC 2025/12/17 04:57:05 DEBUG : Added delayed dir = "tictactoe/tictactoe", newDst= 2025/12/17 04:57:05 DEBUG : toe/toe: transformed to: tictactoe/tictactoe 2025/12/17 04:57:05 DEBUG : toe.txt: transformed to: tictactoe.txt 2025/12/17 04:57:05 DEBUG : toe/toe/toe.txt: transformed to: tictactoe/tictactoe/tictactoe.txt 2025/12/17 04:57:05 DEBUG : toe/toe/toe.txt: Need to transfer - File not found at Destination 2025/12/17 04:57:05 DEBUG : toe/toe/toe.txt: transformed to: tictactoe/tictactoe/tictactoe.txt 2025/12/17 04:57:05 DEBUG : toe/toe/toe.txt: transformed to: tictactoe/tictactoe/tictactoe.txt 2025/12/17 04:57:05 DEBUG : files root 'rclone-test-kacecad2qoli': Waiting for checks to finish 2025/12/17 04:57:05 DEBUG : files root 'rclone-test-kacecad2qoli': Waiting for transfers to finish 2025/12/17 04:57:05 DEBUG : tictactoe/tictactoe/tictactoe.txt: size = 11 OK 2025/12/17 04:57:05 DEBUG : tictactoe/tictactoe/tictactoe.txt: Dst hash empty - aborting Src hash check 2025/12/17 04:57:05 INFO : toe/toe/toe.txt: Copied (new) to: tictactoe/tictactoe/tictactoe.txt 2025/12/17 04:57:05 INFO : toe/toe/toe.txt: Deleted 2025/12/17 04:57:06 INFO : tictactoe/tictactoe: Set directory modification time (using DirSetModTime) 2025/12/17 04:57:06 INFO : tictactoe: Set directory modification time (using DirSetModTime) 2025/12/17 04:57:06 INFO : tictacempty_dir: Set directory modification time (using DirSetModTime) 2025/12/17 04:57:06 INFO : toe/toe: Removing directory 2025/12/17 04:57:06 INFO : toe: Removing directory 2025/12/17 04:57:06 INFO : empty_dir: Removing directory 2025/12/17 04:57:06 DEBUG : Local file system at /tmp/rclone970591918: deleted 3 directories 2025/12/17 04:57:06 DEBUG : tictactoe/tictactoe/tictactoe.txt: size = 11 OK 2025/12/17 04:57:06 DEBUG : tictactoe/tictactoe/tictactoe.txt: Size and modification time the same (differ by 0s, within tolerance 1s) 2025/12/17 04:57:06 DEBUG : tictactoe/tictactoe/tictactoe.txt: transformed to: toe/toe/toe.txt 2025/12/17 04:57:06 DEBUG : tictactoe/tictactoe/tictactoe.txt: transformed to: toe/toe/toe.txt 2025/12/17 04:57:06 DEBUG : tictactoe/tictactoe/tictactoe.txt: transformed to: toe/toe/toe.txt 2025/12/17 04:57:07 INFO : tictactoe/tictactoe/tictactoe.txt: Moved (server-side) to: toe/toe/toe.txt 2025/12/17 04:57:08 DEBUG : pacer: low level retry 1/10 (error Folder Not Empty - `Folder rclone-test-kacecad2qoli/toe not empty`) 2025/12/17 04:57:08 DEBUG : pacer: Rate limited, increasing sleep to 20ms 2025/12/17 04:57:08 DEBUG : pacer: low level retry 2/10 (error Folder Not Empty - `Folder rclone-test-kacecad2qoli/toe not empty`) 2025/12/17 04:57:08 DEBUG : pacer: Rate limited, increasing sleep to 40ms 2025/12/17 04:57:08 DEBUG : pacer: low level retry 3/10 (error Folder Not Empty - `Folder rclone-test-kacecad2qoli/toe not empty`) 2025/12/17 04:57:08 DEBUG : pacer: Rate limited, increasing sleep to 80ms 2025/12/17 04:57:09 DEBUG : pacer: low level retry 4/10 (error Folder Not Empty - `Folder rclone-test-kacecad2qoli/toe not empty`) 2025/12/17 04:57:09 DEBUG : pacer: Rate limited, increasing sleep to 160ms 2025/12/17 04:57:09 DEBUG : pacer: low level retry 5/10 (error Folder Not Empty - `Folder rclone-test-kacecad2qoli/toe not empty`) 2025/12/17 04:57:09 DEBUG : pacer: Rate limited, increasing sleep to 320ms 2025/12/17 04:57:09 DEBUG : pacer: Reducing sleep to 240ms 2025/12/17 04:57:09 DEBUG : pacer: Reducing sleep to 180ms 2025/12/17 04:57:09 DEBUG : pacer: Reducing sleep to 135ms 2025/12/17 04:57:10 DEBUG : pacer: Reducing sleep to 101.25ms 2025/12/17 04:57:10 DEBUG : pacer: Reducing sleep to 75.9375ms --- PASS: TestTransformFile (6.19s) PASS 2025/12/17 04:57:10 DEBUG : files root 'rclone-test-kacecad2qoli': Purge remote 2025/12/17 04:57:10 DEBUG : pacer: Reducing sleep to 56.953125ms "./sync.test -test.v -test.timeout 1h0m0s -remote TestFilesCom: -verbose -test.run '^(TestAllTag|TestCopyNoEmptyDirectories|TestSyncAfterChangingModtimeOnlyWithNoUpdateModTime|TestSyncCopyDest|TestSyncEmptyDirectories|TestSyncNoEmptyDirectories|TestSyncNoUpdateDirModtime|TestSyncReplaceDirModTimeWithEmptyDirs|TestSyncSetDelayedModTimes|TestTransformFile)$'" - Finished OK in 1m19.540749329s (try 2/5)