"./sync.test -test.v -test.timeout 1h0m0s -remote TestFilesCom: -verbose -test.run '^(TestMoveOverSelf|TestMoveWithoutDeleteEmptySrcDirs|TestNothingToTransferWithoutEmptyDirs|TestSyncCopyDest|TestSyncReplaceDirModTimeWithEmptyDirs)$'" - Starting (try 2/5)
2026/05/29 03:00:00 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-popakis9nine"
2026/05/29 03:00:00 DEBUG : Using config file from "/home/rclone/.rclone.conf"
2026/05/29 03:00:01 DEBUG : Creating backend with remote "/tmp/rclone3134105528"
=== RUN   TestMoveOverSelf
    run.go:198: Remote "files root 'rclone-test-popakis9nine'", Local "Local file system at /tmp/rclone3134105528", Modify Window "1s"
2026/05/29 03:00:05 INFO  : sub dir: Set directory modification time (using DirSetModTime)
2026/05/29 03:00:05 DEBUG : Added delayed dir = "sub dir", newDst=sub dir
2026/05/29 03:00:06 DEBUG : sub dir/hello world: size = 17 (Local file system at /tmp/rclone3134105528)
2026/05/29 03:00:06 DEBUG : sub dir/hello world: size = 11 (files root 'rclone-test-popakis9nine')
2026/05/29 03:00:06 DEBUG : sub dir/hello world: Sizes differ
2026/05/29 03:00:06 DEBUG : files root 'rclone-test-popakis9nine': Waiting for checks to finish
2026/05/29 03:00:06 DEBUG : files root 'rclone-test-popakis9nine': Waiting for transfers to finish
2026/05/29 03:00:07 DEBUG : sub dir/hello world: size = 17 OK
2026/05/29 03:00:07 DEBUG : sub dir/hello world: Dst hash empty - aborting Src hash check
2026/05/29 03:00:07 INFO  : sub dir/hello world: Copied (replaced existing)
2026/05/29 03:00:07 INFO  : sub dir/hello world: Deleted
2026/05/29 03:00:07 INFO  : sub dir: Set directory modification time (using DirSetModTime)
--- PASS: TestMoveOverSelf (8.15s)
=== RUN   TestMoveWithoutDeleteEmptySrcDirs
    run.go:198: Remote "files root 'rclone-test-popakis9nine'", Local "Local file system at /tmp/rclone3134105528", Modify Window "1s"
2026/05/29 03:00:10 DEBUG : Added delayed dir = "nested", newDst=<nil>
2026/05/29 03:00:10 DEBUG : Added delayed dir = "sub dir", newDst=<nil>
2026/05/29 03:00:10 DEBUG : Added delayed dir = "nested/sub dir", newDst=<nil>
2026/05/29 03:00:10 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination
2026/05/29 03:00:10 DEBUG : nested/sub dir/file: Need to transfer - File not found at Destination
2026/05/29 03:00:10 DEBUG : files root 'rclone-test-popakis9nine': Waiting for checks to finish
2026/05/29 03:00:10 DEBUG : files root 'rclone-test-popakis9nine': Waiting for transfers to finish
2026/05/29 03:00:11 DEBUG : sub dir/hello world: size = 11 OK
2026/05/29 03:00:11 DEBUG : sub dir/hello world: Dst hash empty - aborting Src hash check
2026/05/29 03:00:11 INFO  : sub dir/hello world: Copied (new)
2026/05/29 03:00:11 INFO  : sub dir/hello world: Deleted
2026/05/29 03:00:11 DEBUG : nested/sub dir/file: size = 6 OK
2026/05/29 03:00:11 DEBUG : nested/sub dir/file: md5 = 83d3784ea62518eafc60e98d84f877ad OK
2026/05/29 03:00:11 INFO  : nested/sub dir/file: Copied (new)
2026/05/29 03:00:11 INFO  : nested/sub dir/file: Deleted
2026/05/29 03:00:11 INFO  : nested/sub dir: Set directory modification time (using DirSetModTime)
2026/05/29 03:00:11 INFO  : sub dir: Set directory modification time (using DirSetModTime)
2026/05/29 03:00:11 INFO  : nested: Set directory modification time (using DirSetModTime)
2026/05/29 03:00:14 DEBUG : pacer: low level retry 1/10 (error Folder Not Empty - `Folder rclone-test-popakis9nine/nested not empty`)
2026/05/29 03:00:14 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2026/05/29 03:00:14 DEBUG : pacer: low level retry 2/10 (error Folder Not Empty - `Folder rclone-test-popakis9nine/nested not empty`)
2026/05/29 03:00:14 DEBUG : pacer: Rate limited, increasing sleep to 40ms
2026/05/29 03:00:14 DEBUG : pacer: low level retry 3/10 (error Folder Not Empty - `Folder rclone-test-popakis9nine/nested not empty`)
2026/05/29 03:00:14 DEBUG : pacer: Rate limited, increasing sleep to 80ms
2026/05/29 03:00:14 DEBUG : pacer: Reducing sleep to 60ms
2026/05/29 03:00:14 DEBUG : pacer: Reducing sleep to 45ms
--- PASS: TestMoveWithoutDeleteEmptySrcDirs (5.46s)
=== RUN   TestSyncCopyDest
    run.go:198: Remote "files root 'rclone-test-popakis9nine'", Local "Local file system at /tmp/rclone3134105528", Modify Window "1s"
2026/05/29 03:00:15 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-popakis9nine/dst"
2026/05/29 03:00:15 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-popakis9nine/CopyDest"
2026/05/29 03:00:16 DEBUG : one: Need to transfer - File not found at Destination
2026/05/29 03:00:16 DEBUG : files root 'rclone-test-popakis9nine/dst': Waiting for checks to finish
2026/05/29 03:00:16 DEBUG : files root 'rclone-test-popakis9nine/dst': Waiting for transfers to finish
2026/05/29 03:00:18 DEBUG : one: size = 3 OK
2026/05/29 03:00:18 DEBUG : one: Dst hash empty - aborting Src hash check
2026/05/29 03:00:18 INFO  : one: Copied (new)
2026/05/29 03:00:18 DEBUG : Waiting for deletions to finish
2026/05/29 03:00:18 DEBUG : pacer: Reducing sleep to 33.75ms
2026/05/29 03:00:18 DEBUG : pacer: Reducing sleep to 25.3125ms
2026/05/29 03:00:18 DEBUG : pacer: Reducing sleep to 18.984375ms
2026/05/29 03:00:18 DEBUG : pacer: Reducing sleep to 14.238281ms
2026/05/29 03:00:19 DEBUG : one: size = 5 (Local file system at /tmp/rclone3134105528)
2026/05/29 03:00:19 DEBUG : one: size = 3 (files root 'rclone-test-popakis9nine/dst')
2026/05/29 03:00:19 DEBUG : one: Sizes differ
2026/05/29 03:00:19 DEBUG : files root 'rclone-test-popakis9nine/dst': Waiting for checks to finish
2026/05/29 03:00:19 DEBUG : files root 'rclone-test-popakis9nine/dst': Waiting for transfers to finish
2026/05/29 03:00:20 DEBUG : one: size = 5 OK
2026/05/29 03:00:20 DEBUG : one: Dst hash empty - aborting Src hash check
2026/05/29 03:00:20 INFO  : one: Copied (replaced existing)
2026/05/29 03:00:20 DEBUG : Waiting for deletions to finish
2026/05/29 03:00:20 DEBUG : pacer: Reducing sleep to 10.67871ms
2026/05/29 03:00:20 DEBUG : pacer: Reducing sleep to 10ms
2026/05/29 03:00:22 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-popakis9nine/BackupDir"
2026/05/29 03:00:23 DEBUG : files root 'rclone-test-popakis9nine/dst': Waiting for checks to finish
2026/05/29 03:00:23 DEBUG : one: size = 5 (Local file system at /tmp/rclone3134105528)
2026/05/29 03:00:23 DEBUG : one: size = 3 (files root 'rclone-test-popakis9nine/dst')
2026/05/29 03:00:23 DEBUG : one: Sizes differ
2026/05/29 03:00:23 DEBUG : one: size = 5 OK
2026/05/29 03:00:23 DEBUG : one: Size and modification time the same (differ by -123.456789ms, within tolerance 1s)
2026/05/29 03:00:23 DEBUG : one: size = 5 (Local file system at /tmp/rclone3134105528)
2026/05/29 03:00:23 DEBUG : one: size = 3 (files root 'rclone-test-popakis9nine/dst')
2026/05/29 03:00:23 DEBUG : one: Sizes differ
2026/05/29 03:00:25 INFO  : one: Moved (server-side)
2026/05/29 03:00:27 DEBUG : one: size = 5 OK
2026/05/29 03:00:27 DEBUG : one: md5 = 07912d142f5d63ee918b34796b5a2432 OK
2026/05/29 03:00:27 INFO  : one: Copied (server-side copy)
2026/05/29 03:00:27 DEBUG : one: Destination found in --copy-dest, using server-side copy
2026/05/29 03:00:27 DEBUG : files root 'rclone-test-popakis9nine/dst': Waiting for transfers to finish
2026/05/29 03:00:27 DEBUG : Waiting for deletions to finish
2026/05/29 03:00:29 DEBUG : one: size = 5 OK
2026/05/29 03:00:29 DEBUG : one: Size and modification time the same (differ by -123.456789ms, within tolerance 1s)
2026/05/29 03:00:29 DEBUG : one: Unchanged skipping
2026/05/29 03:00:29 DEBUG : two: size = 3 OK
2026/05/29 03:00:29 DEBUG : two: Size and modification time the same (differ by -123.456789ms, within tolerance 1s)
2026/05/29 03:00:31 DEBUG : two: size = 3 OK
2026/05/29 03:00:31 DEBUG : two: md5 = b8a9f715dbb64fd5c56e7783c6820a61 OK
2026/05/29 03:00:31 INFO  : two: Copied (server-side copy)
2026/05/29 03:00:31 DEBUG : two: Destination found in --copy-dest, using server-side copy
2026/05/29 03:00:31 DEBUG : files root 'rclone-test-popakis9nine/dst': Waiting for checks to finish
2026/05/29 03:00:31 DEBUG : files root 'rclone-test-popakis9nine/dst': Waiting for transfers to finish
2026/05/29 03:00:31 DEBUG : Waiting for deletions to finish
2026/05/29 03:00:31 DEBUG : one: size = 5 OK
2026/05/29 03:00:31 DEBUG : one: Size and modification time the same (differ by -123.456789ms, within tolerance 1s)
2026/05/29 03:00:31 DEBUG : one: Unchanged skipping
2026/05/29 03:00:31 DEBUG : two: size = 3 OK
2026/05/29 03:00:31 DEBUG : two: Size and modification time the same (differ by -123.456789ms, within tolerance 1s)
2026/05/29 03:00:31 DEBUG : two: Unchanged skipping
2026/05/29 03:00:31 DEBUG : files root 'rclone-test-popakis9nine/dst': Waiting for checks to finish
2026/05/29 03:00:31 DEBUG : files root 'rclone-test-popakis9nine/dst': Waiting for transfers to finish
2026/05/29 03:00:31 DEBUG : Waiting for deletions to finish
2026/05/29 03:00:31 INFO  : There was nothing to transfer
2026/05/29 03:00:33 DEBUG : one: size = 5 OK
2026/05/29 03:00:33 DEBUG : one: Size and modification time the same (differ by -123.456789ms, within tolerance 1s)
2026/05/29 03:00:33 DEBUG : one: Unchanged skipping
2026/05/29 03:00:33 DEBUG : three: size = 7 (Local file system at /tmp/rclone3134105528)
2026/05/29 03:00:33 DEBUG : three: size = 5 (files root 'rclone-test-popakis9nine/CopyDest')
2026/05/29 03:00:33 DEBUG : three: Sizes differ
2026/05/29 03:00:33 DEBUG : three: Destination not found in --copy-dest
2026/05/29 03:00:33 DEBUG : three: Need to transfer - File not found at Destination
2026/05/29 03:00:33 DEBUG : two: size = 3 OK
2026/05/29 03:00:33 DEBUG : two: Size and modification time the same (differ by -123.456789ms, within tolerance 1s)
2026/05/29 03:00:33 DEBUG : two: Unchanged skipping
2026/05/29 03:00:33 DEBUG : files root 'rclone-test-popakis9nine/dst': Waiting for checks to finish
2026/05/29 03:00:33 DEBUG : files root 'rclone-test-popakis9nine/dst': Waiting for transfers to finish
2026/05/29 03:00:34 DEBUG : three: size = 7 OK
2026/05/29 03:00:34 DEBUG : three: Dst hash empty - aborting Src hash check
2026/05/29 03:00:34 INFO  : three: Copied (new)
2026/05/29 03:00:34 DEBUG : Waiting for deletions to finish
--- PASS: TestSyncCopyDest (22.86s)
=== RUN   TestSyncReplaceDirModTimeWithEmptyDirs
    run.go:198: Remote "files root 'rclone-test-popakis9nine'", Local "Local file system at /tmp/rclone3134105528", Modify Window "1s"
2026/05/29 03:00:38 DEBUG : empty_dir: Making directory with metadata
2026/05/29 03:00:38 INFO  : empty_dir: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z)
2026/05/29 03:00:38 DEBUG : empty_on_remote: Making directory with metadata
2026/05/29 03:00:38 INFO  : empty_on_remote: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z)
2026/05/29 03:00:38 INFO  : empty_on_remote: Making directory
2026/05/29 03:00:38 INFO  : empty_on_remote: Made directory with modification time 2011-12-25 12:59:59.123456789 +0000 UTC
2026/05/29 03:00:41 INFO  : test_dir1: Set directory modification time (using DirSetModTime)
2026/05/29 03:00:41 INFO  : test_dir2: Set directory modification time (using DirSetModTime)
2026/05/29 03:00:41 INFO  : test_dir2/sub_dir: Set directory modification time (using DirSetModTime)
2026/05/29 03:00:41 INFO  : empty_on_remote: Set directory modification time (using DirSetModTime)
2026/05/29 03:00:41 INFO  : empty_dir: Set directory modification time (using DirSetModTime)
--- PASS: TestSyncReplaceDirModTimeWithEmptyDirs (8.73s)
=== RUN   TestNothingToTransferWithoutEmptyDirs
    run.go:198: Remote "files root 'rclone-test-popakis9nine'", Local "Local file system at /tmp/rclone3134105528", Modify Window "1s"
2026/05/29 03:00:46 INFO  : sub dir: Set directory modification time (using DirSetModTime)
2026/05/29 03:00:46 INFO  : sub dir: Making directory
2026/05/29 03:00:47 INFO  : sub dir: Made directory with modification time 2011-12-30 12:59:59 +0000 UTC
2026/05/29 03:00:56 INFO  : sub dir2: Set directory modification time (using DirSetModTime)
2026/05/29 03:00:56 INFO  : sub dir2: Set directory modification time (using DirSetModTime)
2026/05/29 03:00:56 INFO  : sub dirEmpty/sub dirEmpty2: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z)
2026/05/29 03:00:56 INFO  : sub dirEmpty: Set directory modification time (using DirSetModTime)
2026/05/29 03:01:02 DEBUG : pacer: low level retry 1/10 (error Folder Not Empty - `Folder rclone-test-popakis9nine/sub dir2/very/very/very/very not empty`)
2026/05/29 03:01:02 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2026/05/29 03:01:02 DEBUG : pacer: Reducing sleep to 15ms
2026/05/29 03:01:02 DEBUG : pacer: low level retry 1/10 (error Folder Not Empty - `Folder rclone-test-popakis9nine/sub dir2/very/very/very not empty`)
2026/05/29 03:01:02 DEBUG : pacer: Rate limited, increasing sleep to 30ms
2026/05/29 03:01:02 DEBUG : pacer: Reducing sleep to 22.5ms
2026/05/29 03:01:02 DEBUG : pacer: low level retry 1/10 (error Folder Not Empty - `Folder rclone-test-popakis9nine/sub dir2/very/very not empty`)
2026/05/29 03:01:02 DEBUG : pacer: Rate limited, increasing sleep to 45ms
2026/05/29 03:01:03 DEBUG : pacer: Reducing sleep to 33.75ms
2026/05/29 03:01:03 DEBUG : pacer: Reducing sleep to 25.3125ms
2026/05/29 03:01:03 DEBUG : pacer: Reducing sleep to 18.984375ms
2026/05/29 03:01:03 DEBUG : pacer: low level retry 1/10 (error Folder Not Empty - `Folder rclone-test-popakis9nine/sub dir2 not empty`)
2026/05/29 03:01:03 DEBUG : pacer: Rate limited, increasing sleep to 37.96875ms
2026/05/29 03:01:03 DEBUG : pacer: Reducing sleep to 28.476562ms
2026/05/29 03:01:03 DEBUG : pacer: Reducing sleep to 21.357421ms
2026/05/29 03:01:03 DEBUG : pacer: Reducing sleep to 16.018065ms
--- PASS: TestNothingToTransferWithoutEmptyDirs (17.27s)
PASS
2026/05/29 03:01:04 DEBUG : files root 'rclone-test-popakis9nine': Purge remote
2026/05/29 03:01:04 DEBUG : pacer: Reducing sleep to 12.013548ms
"./sync.test -test.v -test.timeout 1h0m0s -remote TestFilesCom: -verbose -test.run '^(TestMoveOverSelf|TestMoveWithoutDeleteEmptySrcDirs|TestNothingToTransferWithoutEmptyDirs|TestSyncCopyDest|TestSyncReplaceDirModTimeWithEmptyDirs)$'" - Finished OK in 1m3.369691591s (try 2/5)