"./sync.test -test.v -test.timeout 1h0m0s -remote TestFilesCom: -verbose -test.run '^(TestNothingToTransferWithoutEmptyDirs|TestServerSideMoveOverSelf|TestSyncNoTraverse|TestSyncReplaceDirModTimeWithEmptyDirs|TestSyncWithTrackRenames)$'" - Starting (try 2/5) 2025/10/26 03:17:06 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-ciqupoh3hume" 2025/10/26 03:17:06 DEBUG : Using config file from "/home/rclone/.rclone.conf" 2025/10/26 03:17:07 DEBUG : Creating backend with remote "/tmp/rclone3364378083" === RUN TestSyncNoTraverse run.go:180: Remote "files root 'rclone-test-ciqupoh3hume'", Local "Local file system at /tmp/rclone3364378083", Modify Window "1s" 2025/10/26 03:17:07 ERROR : Ignoring --no-traverse with sync 2025/10/26 03:17:07 DEBUG : Added delayed dir = "sub dir", newDst= 2025/10/26 03:17:07 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2025/10/26 03:17:07 DEBUG : files root 'rclone-test-ciqupoh3hume': Waiting for checks to finish 2025/10/26 03:17:07 DEBUG : files root 'rclone-test-ciqupoh3hume': Waiting for transfers to finish 2025/10/26 03:17:09 DEBUG : sub dir/hello world: md5 = 5eb63bbbe01eeed093cb22bb8f5acdc3 OK 2025/10/26 03:17:09 INFO : sub dir/hello world: Copied (new) 2025/10/26 03:17:09 DEBUG : Waiting for deletions to finish 2025/10/26 03:17:09 INFO : sub dir: Set directory modification time (using DirSetModTime) --- PASS: TestSyncNoTraverse (3.74s) === RUN TestServerSideMoveOverSelf run.go:180: Remote "files root 'rclone-test-ciqupoh3hume'", Local "Local file system at /tmp/rclone3364378083", Modify Window "1s" 2025/10/26 03:17:12 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-rubohav2fufe" sync_test.go:701: Server side copy (if possible) files root 'rclone-test-ciqupoh3hume' -> files root 'rclone-test-rubohav2fufe' 2025/10/26 03:17:13 DEBUG : Added delayed dir = "sub dir", newDst= 2025/10/26 03:17:13 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2025/10/26 03:17:13 DEBUG : files root 'rclone-test-rubohav2fufe': Waiting for checks to finish 2025/10/26 03:17:13 DEBUG : files root 'rclone-test-rubohav2fufe': Waiting for transfers to finish 2025/10/26 03:17:16 DEBUG : sub dir/hello world: md5 = 5eb63bbbe01eeed093cb22bb8f5acdc3 OK 2025/10/26 03:17:16 INFO : sub dir/hello world: Copied (server-side copy) 2025/10/26 03:17:16 INFO : sub dir: Set directory modification time (using DirSetModTime) 2025/10/26 03:17:19 DEBUG : files root 'rclone-test-rubohav2fufe': Using server-side directory move 2025/10/26 03:17:19 INFO : files root 'rclone-test-rubohav2fufe': Server side directory move failed - fallback to file moves: can't copy directory - destination already exists 2025/10/26 03:17:20 INFO : sub dir: Set directory modification time (using DirSetModTime) 2025/10/26 03:17:20 DEBUG : Added delayed dir = "sub dir", newDst=sub dir 2025/10/26 03:17:20 DEBUG : files root 'rclone-test-rubohav2fufe': Waiting for checks to finish 2025/10/26 03:17:20 DEBUG : sub dir/hello world: Sizes differ (src 17 vs dst 11) 2025/10/26 03:17:20 DEBUG : files root 'rclone-test-rubohav2fufe': Waiting for transfers to finish 2025/10/26 03:17:20 INFO : sub dir/hello world: Deleted 2025/10/26 03:17:21 INFO : sub dir/hello world: Moved (server-side) 2025/10/26 03:17:21 INFO : sub dir: Set directory modification time (using DirSetModTime) 2025/10/26 03:17:23 DEBUG : testing file moves 2025/10/26 03:17:23 INFO : sub dir: Set directory modification time (using DirSetModTime) 2025/10/26 03:17:23 DEBUG : Added delayed dir = "sub dir", newDst=sub dir 2025/10/26 03:17:24 DEBUG : sub dir/hello world: Sizes differ (src 24 vs dst 17) 2025/10/26 03:17:24 DEBUG : files root 'rclone-test-rubohav2fufe': Waiting for checks to finish 2025/10/26 03:17:24 DEBUG : files root 'rclone-test-rubohav2fufe': Waiting for transfers to finish 2025/10/26 03:17:24 INFO : sub dir/hello world: Deleted 2025/10/26 03:17:24 INFO : sub dir/hello world: Moved (server-side) 2025/10/26 03:17:24 INFO : sub dir: Set directory modification time (using DirSetModTime) 2025/10/26 03:17:26 DEBUG : files root 'rclone-test-rubohav2fufe': Purge remote --- PASS: TestServerSideMoveOverSelf (15.92s) === RUN TestSyncWithTrackRenames run.go:180: Remote "files root 'rclone-test-ciqupoh3hume'", Local "Local file system at /tmp/rclone3364378083", Modify Window "1s" sync_test.go:1568: Can track renames: true 2025/10/26 03:17:26 INFO : files root 'rclone-test-ciqupoh3hume': Making map for --track-renames 2025/10/26 03:17:26 INFO : files root 'rclone-test-ciqupoh3hume': Finished making map for --track-renames 2025/10/26 03:17:26 DEBUG : files root 'rclone-test-ciqupoh3hume': Waiting for checks to finish 2025/10/26 03:17:26 DEBUG : potato: Need to transfer - No matching file found at Destination 2025/10/26 03:17:26 DEBUG : yam: Need to transfer - No matching file found at Destination 2025/10/26 03:17:26 DEBUG : files root 'rclone-test-ciqupoh3hume': Waiting for renames to finish 2025/10/26 03:17:26 DEBUG : files root 'rclone-test-ciqupoh3hume': Waiting for transfers to finish 2025/10/26 03:17:27 DEBUG : yam: Dst hash empty - aborting Src hash check 2025/10/26 03:17:27 INFO : yam: Copied (new) 2025/10/26 03:17:27 DEBUG : potato: Dst hash empty - aborting Src hash check 2025/10/26 03:17:27 INFO : potato: Copied (new) 2025/10/26 03:17:27 DEBUG : Waiting for deletions to finish 2025/10/26 03:17:28 DEBUG : potato: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2025/10/26 03:17:28 INFO : files root 'rclone-test-ciqupoh3hume': Making map for --track-renames 2025/10/26 03:17:28 INFO : files root 'rclone-test-ciqupoh3hume': Finished making map for --track-renames 2025/10/26 03:17:28 DEBUG : files root 'rclone-test-ciqupoh3hume': Waiting for checks to finish 2025/10/26 03:17:28 DEBUG : potato: Unchanged skipping 2025/10/26 03:17:28 DEBUG : files root 'rclone-test-ciqupoh3hume': Waiting for renames to finish 2025/10/26 03:17:28 INFO : yam: Moved (server-side) to: yaml 2025/10/26 03:17:28 INFO : yaml: Renamed from "yam" 2025/10/26 03:17:28 DEBUG : files root 'rclone-test-ciqupoh3hume': Waiting for transfers to finish 2025/10/26 03:17:28 DEBUG : Waiting for deletions to finish 2025/10/26 03:17:28 INFO : There was nothing to transfer --- PASS: TestSyncWithTrackRenames (2.63s) === RUN TestSyncReplaceDirModTimeWithEmptyDirs run.go:180: Remote "files root 'rclone-test-ciqupoh3hume'", Local "Local file system at /tmp/rclone3364378083", Modify Window "1s" 2025/10/26 03:17:29 DEBUG : empty_dir: Making directory with metadata 2025/10/26 03:17:29 INFO : empty_dir: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z) 2025/10/26 03:17:29 DEBUG : empty_on_remote: Making directory with metadata 2025/10/26 03:17:29 INFO : empty_on_remote: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z) 2025/10/26 03:17:29 INFO : empty_on_remote: Making directory 2025/10/26 03:17:29 INFO : empty_on_remote: Made directory with modification time 2011-12-25 12:59:59.123456789 +0000 UTC 2025/10/26 03:17:32 INFO : test_dir1: Set directory modification time (using DirSetModTime) 2025/10/26 03:17:32 INFO : test_dir2: Set directory modification time (using DirSetModTime) 2025/10/26 03:17:32 INFO : test_dir2/sub_dir: Set directory modification time (using DirSetModTime) 2025/10/26 03:17:32 INFO : empty_on_remote: Set directory modification time (using DirSetModTime) 2025/10/26 03:17:32 INFO : empty_dir: Set directory modification time (using DirSetModTime) 2025/10/26 03:17:35 DEBUG : pacer: low level retry 1/10 (error Folder Not Empty - `Folder rclone-test-ciqupoh3hume/test_dir2 not empty`) 2025/10/26 03:17:35 DEBUG : pacer: Rate limited, increasing sleep to 20ms 2025/10/26 03:17:35 DEBUG : pacer: Reducing sleep to 15ms 2025/10/26 03:17:35 DEBUG : pacer: Reducing sleep to 11.25ms 2025/10/26 03:17:36 DEBUG : pacer: Reducing sleep to 10ms --- PASS: TestSyncReplaceDirModTimeWithEmptyDirs (6.94s) === RUN TestNothingToTransferWithoutEmptyDirs run.go:180: Remote "files root 'rclone-test-ciqupoh3hume'", Local "Local file system at /tmp/rclone3364378083", Modify Window "1s" 2025/10/26 03:17:36 INFO : sub dir: Set directory modification time (using DirSetModTime) 2025/10/26 03:17:36 INFO : sub dir: Making directory 2025/10/26 03:17:36 INFO : sub dir: Made directory with modification time 2011-12-30 12:59:59 +0000 UTC 2025/10/26 03:17:44 INFO : sub dir2: Set directory modification time (using DirSetModTime) 2025/10/26 03:17:44 INFO : sub dir2: Set directory modification time (using DirSetModTime) 2025/10/26 03:17:44 INFO : sub dirEmpty/sub dirEmpty2: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z) 2025/10/26 03:17:44 INFO : sub dirEmpty: Set directory modification time (using DirSetModTime) 2025/10/26 03:17:49 DEBUG : pacer: low level retry 1/10 (error Folder Not Empty - `Folder rclone-test-ciqupoh3hume/sub dir2/very/very/very/very/very/nested not empty`) 2025/10/26 03:17:49 DEBUG : pacer: Rate limited, increasing sleep to 20ms 2025/10/26 03:17:50 DEBUG : pacer: Reducing sleep to 15ms 2025/10/26 03:17:50 DEBUG : pacer: low level retry 1/10 (error Folder Not Empty - `Folder rclone-test-ciqupoh3hume/sub dir2/very/very/very/very/very not empty`) 2025/10/26 03:17:50 DEBUG : pacer: Rate limited, increasing sleep to 30ms 2025/10/26 03:17:50 DEBUG : pacer: Reducing sleep to 22.5ms 2025/10/26 03:17:50 DEBUG : pacer: low level retry 1/10 (error Folder Not Empty - `Folder rclone-test-ciqupoh3hume/sub dir2/very/very/very/very not empty`) 2025/10/26 03:17:50 DEBUG : pacer: Rate limited, increasing sleep to 45ms 2025/10/26 03:17:50 DEBUG : pacer: Reducing sleep to 33.75ms 2025/10/26 03:17:50 DEBUG : pacer: low level retry 1/10 (error Folder Not Empty - `Folder rclone-test-ciqupoh3hume/sub dir2/very/very/very not empty`) 2025/10/26 03:17:50 DEBUG : pacer: Rate limited, increasing sleep to 67.5ms 2025/10/26 03:17:50 DEBUG : pacer: low level retry 2/10 (error Folder Not Empty - `Folder rclone-test-ciqupoh3hume/sub dir2/very/very/very not empty`) 2025/10/26 03:17:50 DEBUG : pacer: Rate limited, increasing sleep to 135ms 2025/10/26 03:17:51 DEBUG : pacer: low level retry 3/10 (error Folder Not Empty - `Folder rclone-test-ciqupoh3hume/sub dir2/very/very/very not empty`) 2025/10/26 03:17:51 DEBUG : pacer: Rate limited, increasing sleep to 270ms 2025/10/26 03:17:51 DEBUG : pacer: low level retry 4/10 (error Folder Not Empty - `Folder rclone-test-ciqupoh3hume/sub dir2/very/very/very not empty`) 2025/10/26 03:17:51 DEBUG : pacer: Rate limited, increasing sleep to 540ms 2025/10/26 03:17:51 DEBUG : pacer: Reducing sleep to 405ms 2025/10/26 03:17:52 DEBUG : pacer: Reducing sleep to 303.75ms 2025/10/26 03:17:52 DEBUG : pacer: Reducing sleep to 227.8125ms 2025/10/26 03:17:52 DEBUG : pacer: Reducing sleep to 170.859375ms 2025/10/26 03:17:52 DEBUG : pacer: low level retry 1/10 (error Folder Not Empty - `Folder rclone-test-ciqupoh3hume/sub dir2 not empty`) 2025/10/26 03:17:52 DEBUG : pacer: Rate limited, increasing sleep to 341.71875ms 2025/10/26 03:17:53 DEBUG : pacer: low level retry 2/10 (error Folder Not Empty - `Folder rclone-test-ciqupoh3hume/sub dir2 not empty`) 2025/10/26 03:17:53 DEBUG : pacer: Rate limited, increasing sleep to 683.4375ms 2025/10/26 03:17:53 DEBUG : pacer: Reducing sleep to 512.578125ms 2025/10/26 03:17:54 DEBUG : pacer: Reducing sleep to 384.433593ms 2025/10/26 03:17:54 DEBUG : pacer: Reducing sleep to 288.325194ms --- PASS: TestNothingToTransferWithoutEmptyDirs (18.24s) PASS 2025/10/26 03:17:54 DEBUG : files root 'rclone-test-ciqupoh3hume': Purge remote 2025/10/26 03:17:55 DEBUG : pacer: Reducing sleep to 216.243895ms "./sync.test -test.v -test.timeout 1h0m0s -remote TestFilesCom: -verbose -test.run '^(TestNothingToTransferWithoutEmptyDirs|TestServerSideMoveOverSelf|TestSyncNoTraverse|TestSyncReplaceDirModTimeWithEmptyDirs|TestSyncWithTrackRenames)$'" - Finished OK in 48.955196687s (try 2/5)