"./operations.test -test.v -test.timeout 1h0m0s -remote TestFilesCom: -verbose -test.run '^(TestCopyFileCopyDest|TestDeduplicateNewestByHash|TestDirMove|TestRmdirsLeaveRoot|TestRmdirsWithFilter)$'" - Starting (try 2/5) 2025/10/28 04:50:47 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-xiwitat6bote" 2025/10/28 04:50:47 DEBUG : Using config file from "/home/rclone/.rclone.conf" 2025/10/28 04:50:49 DEBUG : Creating backend with remote "/tmp/rclone2588982656" === RUN TestCopyFileCopyDest run.go:180: Remote "files root 'rclone-test-xiwitat6bote'", Local "Local file system at /tmp/rclone2588982656", Modify Window "1s" 2025/10/28 04:50:49 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-xiwitat6bote/dst" 2025/10/28 04:50:50 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-xiwitat6bote/CopyDest" 2025/10/28 04:50:51 DEBUG : one: Need to transfer - File not found at Destination 2025/10/28 04:50:53 DEBUG : one: md5 = f97c5d29941bfb1b2fdab0874906ab82 OK 2025/10/28 04:50:53 INFO : one: Copied (new) 2025/10/28 04:50:54 DEBUG : one: Sizes differ (src 5 vs dst 3) 2025/10/28 04:50:55 DEBUG : one: Dst hash empty - aborting Src hash check 2025/10/28 04:50:55 INFO : one: Copied (replaced existing) 2025/10/28 04:50:59 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-xiwitat6bote/BackupDir" 2025/10/28 04:50:59 DEBUG : one: Sizes differ (src 5 vs dst 3) 2025/10/28 04:51:00 DEBUG : one: Size and modification time the same (differ by -123.456789ms, within tolerance 1s) 2025/10/28 04:51:00 DEBUG : one: Sizes differ (src 5 vs dst 3) 2025/10/28 04:51:01 INFO : one: Moved (server-side) 2025/10/28 04:51:04 DEBUG : one: md5 = 07912d142f5d63ee918b34796b5a2432 OK 2025/10/28 04:51:04 INFO : one: Copied (server-side copy) 2025/10/28 04:51:04 DEBUG : one: Destination found in --copy-dest, using server-side copy 2025/10/28 04:51:07 DEBUG : two: Need to transfer - File not found at Destination 2025/10/28 04:51:07 DEBUG : two: Size and modification time the same (differ by -123.456789ms, within tolerance 1s) 2025/10/28 04:51:10 DEBUG : two: md5 = b8a9f715dbb64fd5c56e7783c6820a61 OK 2025/10/28 04:51:10 INFO : two: Copied (server-side copy) 2025/10/28 04:51:10 DEBUG : two: Destination found in --copy-dest, using server-side copy 2025/10/28 04:51:11 DEBUG : two: Size and modification time the same (differ by -123.456789ms, within tolerance 1s) 2025/10/28 04:51:11 DEBUG : two: Unchanged skipping 2025/10/28 04:51:12 DEBUG : three: Need to transfer - File not found at Destination 2025/10/28 04:51:13 DEBUG : three: Sizes differ (src 7 vs dst 5) 2025/10/28 04:51:13 DEBUG : three: Destination not found in --copy-dest 2025/10/28 04:51:14 DEBUG : three: Dst hash empty - aborting Src hash check 2025/10/28 04:51:14 INFO : three: Copied (new) --- PASS: TestCopyFileCopyDest (27.50s) === RUN TestDeduplicateNewestByHash run.go:180: Remote "files root 'rclone-test-xiwitat6bote'", Local "Local file system at /tmp/rclone2588982656", Modify Window "1s" 2025/10/28 04:51:20 INFO : files root 'rclone-test-xiwitat6bote': Looking for duplicate md5 hashes using newest mode. 2025/10/28 04:51:20 NOTICE: e423c38704eb80e671efd54438bc07a1: Found 3 files with duplicate md5 hashes 2025/10/28 04:51:20 INFO : one: Deleted 2025/10/28 04:51:21 INFO : also/one: Deleted 2025/10/28 04:51:21 NOTICE: e423c38704eb80e671efd54438bc07a1: Deleted 2 extra copies --- PASS: TestDeduplicateNewestByHash (5.28s) === RUN TestRmdirsLeaveRoot run.go:180: Remote "files root 'rclone-test-xiwitat6bote'", Local "Local file system at /tmp/rclone2588982656", Modify Window "1s" 2025/10/28 04:51:22 INFO : A1: Making directory 2025/10/28 04:51:22 INFO : A1/B1: Making directory 2025/10/28 04:51:22 INFO : A1/B1/C1: Making directory 2025/10/28 04:51:23 DEBUG : removing 1 level 3 directories 2025/10/28 04:51:23 INFO : A1/B1/C1: Removing directory 2025/10/28 04:51:24 DEBUG : removing 1 level 2 directories 2025/10/28 04:51:24 INFO : A1/B1: Removing directory 2025/10/28 04:51:24 DEBUG : pacer: low level retry 1/10 (error Folder Not Empty - `Folder rclone-test-xiwitat6bote/A1/B1 not empty`) 2025/10/28 04:51:24 DEBUG : pacer: Rate limited, increasing sleep to 20ms 2025/10/28 04:51:24 DEBUG : pacer: Reducing sleep to 15ms 2025/10/28 04:51:24 DEBUG : pacer: Reducing sleep to 11.25ms 2025/10/28 04:51:24 DEBUG : pacer: Reducing sleep to 10ms 2025/10/28 04:51:25 DEBUG : pacer: low level retry 1/10 (error Folder Not Empty - `Folder rclone-test-xiwitat6bote/A1 not empty`) 2025/10/28 04:51:25 DEBUG : pacer: Rate limited, increasing sleep to 20ms 2025/10/28 04:51:25 DEBUG : pacer: Reducing sleep to 15ms 2025/10/28 04:51:25 DEBUG : pacer: Reducing sleep to 11.25ms --- PASS: TestRmdirsLeaveRoot (3.05s) === RUN TestRmdirsWithFilter run.go:180: Remote "files root 'rclone-test-xiwitat6bote'", Local "Local file system at /tmp/rclone2588982656", Modify Window "1s" 2025/10/28 04:51:25 DEBUG : pacer: Reducing sleep to 10ms 2025/10/28 04:51:25 INFO : A1: Making directory 2025/10/28 04:51:25 INFO : A1/B1: Making directory 2025/10/28 04:51:25 INFO : A1/B1/C1: Making directory 2025/10/28 04:51:27 DEBUG : removing 1 level 3 directories 2025/10/28 04:51:27 INFO : A1/B1/C1: Removing directory 2025/10/28 04:51:27 DEBUG : removing 1 level 2 directories 2025/10/28 04:51:27 INFO : A1/B1: Removing directory --- PASS: TestRmdirsWithFilter (2.96s) === RUN TestDirMove run.go:180: Remote "files root 'rclone-test-xiwitat6bote'", Local "Local file system at /tmp/rclone2588982656", Modify Window "1s" 2025/10/28 04:51:32 INFO : A1/B2: Making directory 2025/10/28 04:51:33 INFO : A1/B1/C3: Making directory 2025/10/28 04:51:37 INFO : A2/B1/three: Moved (server-side) to: A3/B1/three 2025/10/28 04:51:37 INFO : A2/B1/C1/four: Moved (server-side) to: A3/B1/C1/four 2025/10/28 04:51:37 INFO : A2/one: Moved (server-side) to: A3/one 2025/10/28 04:51:37 INFO : A2/B1/C2/five: Moved (server-side) to: A3/B1/C2/five 2025/10/28 04:51:37 INFO : A2/two: Moved (server-side) to: A3/two 2025/10/28 04:51:38 DEBUG : pacer: low level retry 1/10 (error Folder Not Empty - `Folder rclone-test-xiwitat6bote/A2/B1 not empty`) 2025/10/28 04:51:38 DEBUG : pacer: Rate limited, increasing sleep to 20ms 2025/10/28 04:51:38 DEBUG : pacer: low level retry 2/10 (error Folder Not Empty - `Folder rclone-test-xiwitat6bote/A2/B1 not empty`) 2025/10/28 04:51:38 DEBUG : pacer: Rate limited, increasing sleep to 40ms 2025/10/28 04:51:38 DEBUG : pacer: low level retry 3/10 (error Folder Not Empty - `Folder rclone-test-xiwitat6bote/A2/B1 not empty`) 2025/10/28 04:51:38 DEBUG : pacer: Rate limited, increasing sleep to 80ms 2025/10/28 04:51:38 DEBUG : pacer: low level retry 4/10 (error Folder Not Empty - `Folder rclone-test-xiwitat6bote/A2/B1 not empty`) 2025/10/28 04:51:38 DEBUG : pacer: Rate limited, increasing sleep to 160ms 2025/10/28 04:51:38 DEBUG : pacer: Reducing sleep to 120ms 2025/10/28 04:51:38 DEBUG : pacer: low level retry 1/10 (error Folder Not Empty - `Folder rclone-test-xiwitat6bote/A2 not empty`) 2025/10/28 04:51:38 DEBUG : pacer: Rate limited, increasing sleep to 240ms 2025/10/28 04:51:38 DEBUG : pacer: low level retry 2/10 (error Folder Not Empty - `Folder rclone-test-xiwitat6bote/A2 not empty`) 2025/10/28 04:51:38 DEBUG : pacer: Rate limited, increasing sleep to 480ms 2025/10/28 04:51:39 DEBUG : pacer: Reducing sleep to 360ms 2025/10/28 04:51:39 DEBUG : pacer: Reducing sleep to 270ms 2025/10/28 04:51:39 DEBUG : pacer: Reducing sleep to 202.5ms 2025/10/28 04:51:40 DEBUG : pacer: Reducing sleep to 151.875ms 2025/10/28 04:51:40 DEBUG : pacer: Reducing sleep to 113.90625ms 2025/10/28 04:51:40 DEBUG : pacer: Reducing sleep to 85.429687ms 2025/10/28 04:51:40 DEBUG : pacer: Reducing sleep to 64.072265ms 2025/10/28 04:51:40 DEBUG : pacer: Reducing sleep to 48.054198ms 2025/10/28 04:51:40 INFO : files root 'rclone-test-xiwitat6bote': Can't DirMove - falling back to file moves: can't move directory - incompatible remotes 2025/10/28 04:51:40 DEBUG : pacer: Reducing sleep to 36.040648ms 2025/10/28 04:51:40 DEBUG : pacer: Reducing sleep to 27.030486ms 2025/10/28 04:51:40 DEBUG : pacer: Reducing sleep to 20.272864ms 2025/10/28 04:51:41 DEBUG : pacer: Reducing sleep to 15.204648ms 2025/10/28 04:51:41 DEBUG : pacer: Reducing sleep to 11.403486ms 2025/10/28 04:51:41 DEBUG : pacer: Reducing sleep to 10ms 2025/10/28 04:51:42 INFO : A3/B1/three: Moved (server-side) to: A4/B1/three 2025/10/28 04:51:42 INFO : A3/B1/C1/four: Moved (server-side) to: A4/B1/C1/four 2025/10/28 04:51:42 INFO : A3/two: Moved (server-side) to: A4/two 2025/10/28 04:51:42 INFO : A3/one: Moved (server-side) to: A4/one 2025/10/28 04:51:43 INFO : A3/B1/C2/five: Moved (server-side) to: A4/B1/C2/five 2025/10/28 04:51:43 DEBUG : pacer: low level retry 1/10 (error Folder Not Empty - `Folder rclone-test-xiwitat6bote/A3/B1 not empty`) 2025/10/28 04:51:43 DEBUG : pacer: Rate limited, increasing sleep to 20ms 2025/10/28 04:51:43 DEBUG : pacer: Reducing sleep to 15ms 2025/10/28 04:51:44 DEBUG : pacer: low level retry 1/10 (error Folder Not Empty - `Folder rclone-test-xiwitat6bote/A3 not empty`) 2025/10/28 04:51:44 DEBUG : pacer: Rate limited, increasing sleep to 30ms 2025/10/28 04:51:44 DEBUG : pacer: low level retry 2/10 (error Folder Not Empty - `Folder rclone-test-xiwitat6bote/A3 not empty`) 2025/10/28 04:51:44 DEBUG : pacer: Rate limited, increasing sleep to 60ms 2025/10/28 04:51:44 DEBUG : pacer: low level retry 3/10 (error Folder Not Empty - `Folder rclone-test-xiwitat6bote/A3 not empty`) 2025/10/28 04:51:44 DEBUG : pacer: Rate limited, increasing sleep to 120ms 2025/10/28 04:51:44 DEBUG : pacer: low level retry 4/10 (error Folder Not Empty - `Folder rclone-test-xiwitat6bote/A3 not empty`) 2025/10/28 04:51:44 DEBUG : pacer: Rate limited, increasing sleep to 240ms 2025/10/28 04:51:44 DEBUG : pacer: low level retry 5/10 (error Folder Not Empty - `Folder rclone-test-xiwitat6bote/A3 not empty`) 2025/10/28 04:51:44 DEBUG : pacer: Rate limited, increasing sleep to 480ms 2025/10/28 04:51:44 DEBUG : pacer: Reducing sleep to 360ms 2025/10/28 04:51:45 DEBUG : pacer: Reducing sleep to 270ms 2025/10/28 04:51:45 DEBUG : pacer: Reducing sleep to 202.5ms 2025/10/28 04:51:45 DEBUG : pacer: Reducing sleep to 151.875ms 2025/10/28 04:51:46 DEBUG : pacer: Reducing sleep to 113.90625ms 2025/10/28 04:51:46 DEBUG : pacer: Reducing sleep to 85.429687ms 2025/10/28 04:51:46 DEBUG : pacer: Reducing sleep to 64.072265ms 2025/10/28 04:51:46 DEBUG : pacer: Reducing sleep to 48.054198ms 2025/10/28 04:51:46 DEBUG : pacer: Reducing sleep to 36.040648ms 2025/10/28 04:51:46 DEBUG : pacer: Reducing sleep to 27.030486ms 2025/10/28 04:51:46 DEBUG : pacer: Reducing sleep to 20.272864ms 2025/10/28 04:51:47 DEBUG : pacer: Reducing sleep to 15.204648ms 2025/10/28 04:51:47 DEBUG : pacer: Reducing sleep to 11.403486ms 2025/10/28 04:51:47 DEBUG : pacer: Reducing sleep to 10ms 2025/10/28 04:51:48 DEBUG : pacer: low level retry 1/10 (error Folder Not Empty - `Folder rclone-test-xiwitat6bote/A4/B1 not empty`) 2025/10/28 04:51:48 DEBUG : pacer: Rate limited, increasing sleep to 20ms 2025/10/28 04:51:48 DEBUG : pacer: low level retry 2/10 (error Folder Not Empty - `Folder rclone-test-xiwitat6bote/A4/B1 not empty`) 2025/10/28 04:51:48 DEBUG : pacer: Rate limited, increasing sleep to 40ms 2025/10/28 04:51:49 DEBUG : pacer: Reducing sleep to 30ms 2025/10/28 04:51:49 DEBUG : pacer: Reducing sleep to 22.5ms 2025/10/28 04:51:49 DEBUG : pacer: Reducing sleep to 16.875ms --- PASS: TestDirMove (21.02s) PASS 2025/10/28 04:51:49 DEBUG : files root 'rclone-test-xiwitat6bote': Purge remote 2025/10/28 04:51:49 DEBUG : pacer: Reducing sleep to 12.65625ms "./operations.test -test.v -test.timeout 1h0m0s -remote TestFilesCom: -verbose -test.run '^(TestCopyFileCopyDest|TestDeduplicateNewestByHash|TestDirMove|TestRmdirsLeaveRoot|TestRmdirsWithFilter)$'" - Finished OK in 1m1.862257636s (try 2/5)