"./sync.test -test.v -test.timeout 1h0m0s -remote TestFilesCom: -verbose -test.run '^(TestCopyNoEmptyDirectories|TestCopyOverSelf|TestFixCase|TestSyncConcurrentTruncate|TestSyncEmptyDirectories|TestSyncNoEmptyDirectories|TestSyncNoUpdateDirModtime|TestSyncSetDelayedModTimes|TestSyncWithTrackRenames)$'" - Starting (try 2/5)
2025/10/16 01:18:59 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-sepetav6roho"
2025/10/16 01:18:59 DEBUG : Using config file from "/home/rclone/.rclone.conf"
2025/10/16 01:19:01 DEBUG : Creating backend with remote "/tmp/rclone3480439315"
=== RUN   TestCopyNoEmptyDirectories
    run.go:180: Remote "files root 'rclone-test-sepetav6roho'", Local "Local file system at /tmp/rclone3480439315", Modify Window "1s"
2025/10/16 01:19:01 INFO  : sub dir2: Making directory
2025/10/16 01:19:01 DEBUG : sub dir2/sub sub dir2: Making directory with metadata
2025/10/16 01:19:01 INFO  : sub dir2/sub sub dir2: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z)
2025/10/16 01:19:01 DEBUG : Added delayed dir = "sub dir2", newDst=<nil>
2025/10/16 01:19:01 DEBUG : Added delayed dir = "sub dir", newDst=<nil>
2025/10/16 01:19:01 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination
2025/10/16 01:19:01 DEBUG : Added delayed dir = "sub dir2/sub sub dir2", newDst=<nil>
2025/10/16 01:19:01 DEBUG : files root 'rclone-test-sepetav6roho': Waiting for checks to finish
2025/10/16 01:19:01 DEBUG : files root 'rclone-test-sepetav6roho': Waiting for transfers to finish
2025/10/16 01:19:03 DEBUG : sub dir/hello world: Dst hash empty - aborting Src hash check
2025/10/16 01:19:03 INFO  : sub dir/hello world: Copied (new)
2025/10/16 01:19:03 INFO  : sub dir: Set directory modification time (using DirSetModTime)
--- PASS: TestCopyNoEmptyDirectories (3.55s)
=== RUN   TestSyncNoUpdateDirModtime
    run.go:180: Remote "files root 'rclone-test-sepetav6roho'", Local "Local file system at /tmp/rclone3480439315", Modify Window "1s"
2025/10/16 01:19:04 DEBUG : sub dir no update dir modtime: Making directory with metadata
2025/10/16 01:19:04 INFO  : sub dir no update dir modtime: Made directory with metadata (mtime=2001-02-03T04:05:06.499999999Z)
2025/10/16 01:19:05 DEBUG : files root 'rclone-test-sepetav6roho': Waiting for checks to finish
2025/10/16 01:19:05 DEBUG : files root 'rclone-test-sepetav6roho': Waiting for transfers to finish
2025/10/16 01:19:05 DEBUG : Waiting for deletions to finish
--- PASS: TestSyncNoUpdateDirModtime (1.52s)
=== RUN   TestSyncEmptyDirectories
    run.go:180: Remote "files root 'rclone-test-sepetav6roho'", Local "Local file system at /tmp/rclone3480439315", Modify Window "1s"
2025/10/16 01:19:06 DEBUG : sub dir2: Making directory with metadata
2025/10/16 01:19:06 INFO  : sub dir2: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z)
2025/10/16 01:19:06 INFO  : sub dir: Set directory modification time (using DirSetModTime)
2025/10/16 01:19:06 INFO  : sub dir2: Making directory
2025/10/16 01:19:06 INFO  : sub dir2: Made directory with modification time 2011-12-25 12:59:59.123456789 +0000 UTC
2025/10/16 01:19:06 DEBUG : Added delayed dir = "sub dir2", newDst=<nil>
2025/10/16 01:19:06 INFO  : sub dir: Making directory
2025/10/16 01:19:07 INFO  : sub dir: Made directory with modification time 2001-02-03 04:05:06.499999999 +0000 UTC
2025/10/16 01:19:07 DEBUG : Added delayed dir = "sub dir", newDst=<nil>
2025/10/16 01:19:07 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination
2025/10/16 01:19:07 DEBUG : files root 'rclone-test-sepetav6roho': Waiting for checks to finish
2025/10/16 01:19:07 DEBUG : files root 'rclone-test-sepetav6roho': Waiting for transfers to finish
2025/10/16 01:19:07 DEBUG : sub dir/hello world: Dst hash empty - aborting Src hash check
2025/10/16 01:19:07 INFO  : sub dir/hello world: Copied (new)
2025/10/16 01:19:07 DEBUG : Waiting for deletions to finish
2025/10/16 01:19:07 INFO  : sub dir: Set directory modification time (using DirSetModTime)
2025/10/16 01:19:07 INFO  : sub dir2: Set directory modification time (using DirSetModTime)
--- PASS: TestSyncEmptyDirectories (3.08s)
=== RUN   TestSyncSetDelayedModTimes
    run.go:180: Remote "files root 'rclone-test-sepetav6roho'", Local "Local file system at /tmp/rclone3480439315", Modify Window "1s"
2025/10/16 01:19:09 INFO  : a1/b2/c1/d1/e1/f1: Set directory modification time (using DirSetModTime)
2025/10/16 01:19:09 INFO  : a1/b2/c1/d1/e1: Set directory modification time (using DirSetModTime)
2025/10/16 01:19:09 INFO  : a1/b2/c1/d1: Set directory modification time (using DirSetModTime)
2025/10/16 01:19:09 INFO  : a1/b2/c1: Set directory modification time (using DirSetModTime)
2025/10/16 01:19:09 INFO  : a1/b2: Set directory modification time (using DirSetModTime)
2025/10/16 01:19:09 INFO  : a1/b1/c1/d2/e1/f2: Set directory modification time (using DirSetModTime)
2025/10/16 01:19:09 INFO  : a1/b1/c1/d2/e1/f1: Set directory modification time (using DirSetModTime)
2025/10/16 01:19:09 INFO  : a1/b1/c1/d2/e1: Set directory modification time (using DirSetModTime)
2025/10/16 01:19:09 INFO  : a1/b1/c1/d2: Set directory modification time (using DirSetModTime)
2025/10/16 01:19:09 INFO  : a1/b1/c1/d1/e1/f1: Set directory modification time (using DirSetModTime)
2025/10/16 01:19:09 INFO  : a1/b1/c1/d1/e1: Set directory modification time (using DirSetModTime)
2025/10/16 01:19:09 INFO  : a1/b1/c1/d1: Set directory modification time (using DirSetModTime)
2025/10/16 01:19:09 INFO  : a1/b1/c1: Set directory modification time (using DirSetModTime)
2025/10/16 01:19:09 INFO  : a1/b1: Set directory modification time (using DirSetModTime)
2025/10/16 01:19:09 INFO  : a1: Set directory modification time (using DirSetModTime)
2025/10/16 01:19:09 INFO  : a1: Making directory
2025/10/16 01:19:09 INFO  : a1: Made directory with modification time 2001-02-03 04:19:06.499999999 +0000 UTC
2025/10/16 01:19:09 DEBUG : Added delayed dir = "a1", newDst=<nil>
2025/10/16 01:19:09 INFO  : a1/b1: Making directory
2025/10/16 01:19:10 INFO  : a1/b1: Made directory with modification time 2001-02-03 04:18:06.499999999 +0000 UTC
2025/10/16 01:19:10 DEBUG : Added delayed dir = "a1/b1", newDst=<nil>
2025/10/16 01:19:10 INFO  : a1/b2: Making directory
2025/10/16 01:19:10 INFO  : a1/b2: Made directory with modification time 2001-02-03 04:09:06.499999999 +0000 UTC
2025/10/16 01:19:10 DEBUG : Added delayed dir = "a1/b2", newDst=<nil>
2025/10/16 01:19:10 INFO  : a1/b2/c1: Making directory
2025/10/16 01:19:10 INFO  : a1/b1/c1: Making directory
2025/10/16 01:19:10 INFO  : a1/b2/c1: Made directory with modification time 2001-02-03 04:08:06.499999999 +0000 UTC
2025/10/16 01:19:10 DEBUG : Added delayed dir = "a1/b2/c1", newDst=<nil>
2025/10/16 01:19:10 INFO  : a1/b2/c1/d1: Making directory
2025/10/16 01:19:10 INFO  : a1/b1/c1: Made directory with modification time 2001-02-03 04:17:06.499999999 +0000 UTC
2025/10/16 01:19:10 DEBUG : Added delayed dir = "a1/b1/c1", newDst=<nil>
2025/10/16 01:19:10 INFO  : a1/b1/c1/d1: Making directory
2025/10/16 01:19:11 INFO  : a1/b2/c1/d1: Made directory with modification time 2001-02-03 04:07:06.499999999 +0000 UTC
2025/10/16 01:19:11 DEBUG : Added delayed dir = "a1/b2/c1/d1", newDst=<nil>
2025/10/16 01:19:11 INFO  : a1/b2/c1/d1/e1: Making directory
2025/10/16 01:19:11 INFO  : a1/b1/c1/d1: Made directory with modification time 2001-02-03 04:16:06.499999999 +0000 UTC
2025/10/16 01:19:11 DEBUG : Added delayed dir = "a1/b1/c1/d1", newDst=<nil>
2025/10/16 01:19:11 INFO  : a1/b1/c1/d2: Making directory
2025/10/16 01:19:11 INFO  : a1/b1/c1/d2: Made directory with modification time 2001-02-03 04:13:06.499999999 +0000 UTC
2025/10/16 01:19:11 DEBUG : Added delayed dir = "a1/b1/c1/d2", newDst=<nil>
2025/10/16 01:19:11 INFO  : a1/b1/c1/d2/e1: Making directory
2025/10/16 01:19:11 INFO  : a1/b1/c1/d1/e1: Making directory
2025/10/16 01:19:11 INFO  : a1/b2/c1/d1/e1: Made directory with modification time 2001-02-03 04:06:06.499999999 +0000 UTC
2025/10/16 01:19:11 DEBUG : Added delayed dir = "a1/b2/c1/d1/e1", newDst=<nil>
2025/10/16 01:19:11 INFO  : a1/b2/c1/d1/e1/f1: Making directory
2025/10/16 01:19:11 INFO  : a1/b1/c1/d2/e1: Made directory with modification time 2001-02-03 04:12:06.499999999 +0000 UTC
2025/10/16 01:19:11 DEBUG : Added delayed dir = "a1/b1/c1/d2/e1", newDst=<nil>
2025/10/16 01:19:11 INFO  : a1/b1/c1/d2/e1/f1: Making directory
2025/10/16 01:19:11 INFO  : a1/b2/c1/d1/e1/f1: Made directory with modification time 2001-02-03 04:05:06.499999999 +0000 UTC
2025/10/16 01:19:11 DEBUG : Added delayed dir = "a1/b2/c1/d1/e1/f1", newDst=<nil>
2025/10/16 01:19:11 INFO  : a1/b1/c1/d1/e1: Made directory with modification time 2001-02-03 04:15:06.499999999 +0000 UTC
2025/10/16 01:19:11 DEBUG : Added delayed dir = "a1/b1/c1/d1/e1", newDst=<nil>
2025/10/16 01:19:11 INFO  : a1/b1/c1/d1/e1/f1: Making directory
2025/10/16 01:19:12 INFO  : a1/b1/c1/d2/e1/f1: Made directory with modification time 2001-02-03 04:11:06.499999999 +0000 UTC
2025/10/16 01:19:12 DEBUG : Added delayed dir = "a1/b1/c1/d2/e1/f1", newDst=<nil>
2025/10/16 01:19:12 INFO  : a1/b1/c1/d2/e1/f2: Making directory
2025/10/16 01:19:12 INFO  : a1/b1/c1/d1/e1/f1: Made directory with modification time 2001-02-03 04:14:06.499999999 +0000 UTC
2025/10/16 01:19:12 DEBUG : Added delayed dir = "a1/b1/c1/d1/e1/f1", newDst=<nil>
2025/10/16 01:19:12 INFO  : a1/b1/c1/d2/e1/f2: Made directory with modification time 2001-02-03 04:10:06.499999999 +0000 UTC
2025/10/16 01:19:12 DEBUG : Added delayed dir = "a1/b1/c1/d2/e1/f2", newDst=<nil>
2025/10/16 01:19:12 DEBUG : files root 'rclone-test-sepetav6roho': Waiting for checks to finish
2025/10/16 01:19:12 DEBUG : files root 'rclone-test-sepetav6roho': Waiting for transfers to finish
2025/10/16 01:19:12 DEBUG : Waiting for deletions to finish
2025/10/16 01:19:12 INFO  : a1/b1/c1/d2/e1/f2: Set directory modification time (using DirSetModTime)
2025/10/16 01:19:12 INFO  : a1/b2/c1/d1/e1/f1: Set directory modification time (using DirSetModTime)
2025/10/16 01:19:12 INFO  : a1/b1/c1/d2/e1/f1: Set directory modification time (using DirSetModTime)
2025/10/16 01:19:12 INFO  : a1/b1/c1/d1/e1/f1: Set directory modification time (using DirSetModTime)
2025/10/16 01:19:12 INFO  : a1/b1/c1/d1/e1: Set directory modification time (using DirSetModTime)
2025/10/16 01:19:12 INFO  : a1/b1/c1/d2/e1: Set directory modification time (using DirSetModTime)
2025/10/16 01:19:12 INFO  : a1/b2/c1/d1/e1: Set directory modification time (using DirSetModTime)
2025/10/16 01:19:12 INFO  : a1/b1/c1/d2: Set directory modification time (using DirSetModTime)
2025/10/16 01:19:12 INFO  : a1/b2/c1/d1: Set directory modification time (using DirSetModTime)
2025/10/16 01:19:12 INFO  : a1/b1/c1/d1: Set directory modification time (using DirSetModTime)
2025/10/16 01:19:13 INFO  : a1/b1/c1: Set directory modification time (using DirSetModTime)
2025/10/16 01:19:13 INFO  : a1/b2/c1: Set directory modification time (using DirSetModTime)
2025/10/16 01:19:13 INFO  : a1/b2: Set directory modification time (using DirSetModTime)
2025/10/16 01:19:13 INFO  : a1/b1: Set directory modification time (using DirSetModTime)
2025/10/16 01:19:13 INFO  : a1: Set directory modification time (using DirSetModTime)
2025/10/16 01:19:17 DEBUG : pacer: low level retry 1/10 (error Folder Not Empty - `Folder rclone-test-sepetav6roho/a1/b2/c1/d1 not empty`)
2025/10/16 01:19:17 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2025/10/16 01:19:17 DEBUG : pacer: low level retry 2/10 (error Folder Not Empty - `Folder rclone-test-sepetav6roho/a1/b2/c1/d1 not empty`)
2025/10/16 01:19:17 DEBUG : pacer: Rate limited, increasing sleep to 40ms
2025/10/16 01:19:18 DEBUG : pacer: low level retry 3/10 (error Folder Not Empty - `Folder rclone-test-sepetav6roho/a1/b2/c1/d1 not empty`)
2025/10/16 01:19:18 DEBUG : pacer: Rate limited, increasing sleep to 80ms
2025/10/16 01:19:18 DEBUG : pacer: low level retry 4/10 (error Folder Not Empty - `Folder rclone-test-sepetav6roho/a1/b2/c1/d1 not empty`)
2025/10/16 01:19:18 DEBUG : pacer: Rate limited, increasing sleep to 160ms
2025/10/16 01:19:18 DEBUG : pacer: Reducing sleep to 120ms
2025/10/16 01:19:18 DEBUG : pacer: Reducing sleep to 90ms
2025/10/16 01:19:18 DEBUG : pacer: Reducing sleep to 67.5ms
2025/10/16 01:19:18 DEBUG : pacer: Reducing sleep to 50.625ms
2025/10/16 01:19:19 DEBUG : pacer: Reducing sleep to 37.96875ms
2025/10/16 01:19:19 DEBUG : pacer: low level retry 1/10 (error Folder Not Empty - `Folder rclone-test-sepetav6roho/a1/b1/c1/d2/e1 not empty`)
2025/10/16 01:19:19 DEBUG : pacer: Rate limited, increasing sleep to 75.9375ms
2025/10/16 01:19:19 DEBUG : pacer: low level retry 2/10 (error Folder Not Empty - `Folder rclone-test-sepetav6roho/a1/b1/c1/d2/e1 not empty`)
2025/10/16 01:19:19 DEBUG : pacer: Rate limited, increasing sleep to 151.875ms
2025/10/16 01:19:19 DEBUG : pacer: low level retry 3/10 (error Folder Not Empty - `Folder rclone-test-sepetav6roho/a1/b1/c1/d2/e1 not empty`)
2025/10/16 01:19:19 DEBUG : pacer: Rate limited, increasing sleep to 303.75ms
2025/10/16 01:19:19 DEBUG : pacer: low level retry 4/10 (error Folder Not Empty - `Folder rclone-test-sepetav6roho/a1/b1/c1/d2/e1 not empty`)
2025/10/16 01:19:19 DEBUG : pacer: Rate limited, increasing sleep to 607.5ms
2025/10/16 01:19:19 DEBUG : pacer: Reducing sleep to 455.625ms
2025/10/16 01:19:20 DEBUG : pacer: Reducing sleep to 341.71875ms
2025/10/16 01:19:20 DEBUG : pacer: Reducing sleep to 256.289062ms
2025/10/16 01:19:21 DEBUG : pacer: low level retry 1/10 (error Folder Not Empty - `Folder rclone-test-sepetav6roho/a1/b1/c1/d1/e1 not empty`)
2025/10/16 01:19:21 DEBUG : pacer: Rate limited, increasing sleep to 512.578124ms
2025/10/16 01:19:21 DEBUG : pacer: low level retry 2/10 (error Folder Not Empty - `Folder rclone-test-sepetav6roho/a1/b1/c1/d1/e1 not empty`)
2025/10/16 01:19:21 DEBUG : pacer: Rate limited, increasing sleep to 1.025156248s
2025/10/16 01:19:22 DEBUG : pacer: Reducing sleep to 768.867186ms
2025/10/16 01:19:23 DEBUG : pacer: Reducing sleep to 576.650389ms
2025/10/16 01:19:23 DEBUG : pacer: Reducing sleep to 432.487791ms
2025/10/16 01:19:24 DEBUG : pacer: Reducing sleep to 324.365843ms
2025/10/16 01:19:25 DEBUG : pacer: Reducing sleep to 243.274382ms
2025/10/16 01:19:25 DEBUG : pacer: Reducing sleep to 182.455786ms
--- PASS: TestSyncSetDelayedModTimes (15.94s)
=== RUN   TestSyncNoEmptyDirectories
    run.go:180: Remote "files root 'rclone-test-sepetav6roho'", Local "Local file system at /tmp/rclone3480439315", Modify Window "1s"
2025/10/16 01:19:25 INFO  : sub dir2: Making directory
2025/10/16 01:19:25 DEBUG : pacer: Reducing sleep to 136.841839ms
2025/10/16 01:19:25 DEBUG : Added delayed dir = "sub dir2", newDst=<nil>
2025/10/16 01:19:25 DEBUG : Added delayed dir = "sub dir", newDst=<nil>
2025/10/16 01:19:25 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination
2025/10/16 01:19:25 DEBUG : files root 'rclone-test-sepetav6roho': Waiting for checks to finish
2025/10/16 01:19:25 DEBUG : files root 'rclone-test-sepetav6roho': Waiting for transfers to finish
2025/10/16 01:19:26 DEBUG : pacer: Reducing sleep to 102.631379ms
2025/10/16 01:19:27 DEBUG : pacer: Reducing sleep to 76.973534ms
2025/10/16 01:19:27 DEBUG : sub dir/hello world: md5 = 5eb63bbbe01eeed093cb22bb8f5acdc3 OK
2025/10/16 01:19:27 INFO  : sub dir/hello world: Copied (new)
2025/10/16 01:19:27 DEBUG : Waiting for deletions to finish
2025/10/16 01:19:27 DEBUG : pacer: Reducing sleep to 57.73015ms
2025/10/16 01:19:27 INFO  : sub dir: Set directory modification time (using DirSetModTime)
2025/10/16 01:19:27 DEBUG : pacer: Reducing sleep to 43.297612ms
2025/10/16 01:19:27 DEBUG : pacer: Reducing sleep to 32.473209ms
2025/10/16 01:19:27 DEBUG : pacer: Reducing sleep to 24.354906ms
2025/10/16 01:19:28 DEBUG : pacer: Reducing sleep to 18.266179ms
2025/10/16 01:19:28 DEBUG : pacer: Reducing sleep to 13.699634ms
2025/10/16 01:19:28 DEBUG : pacer: Reducing sleep to 10.274725ms
2025/10/16 01:19:28 DEBUG : pacer: Reducing sleep to 10ms
--- PASS: TestSyncNoEmptyDirectories (3.35s)
=== RUN   TestCopyOverSelf
    run.go:180: Remote "files root 'rclone-test-sepetav6roho'", Local "Local file system at /tmp/rclone3480439315", Modify Window "1s"
2025/10/16 01:19:30 INFO  : sub dir: Set directory modification time (using DirSetModTime)
2025/10/16 01:19:30 DEBUG : Added delayed dir = "sub dir", newDst=sub dir
2025/10/16 01:19:30 DEBUG : sub dir/hello world: Sizes differ (src 17 vs dst 11)
2025/10/16 01:19:30 DEBUG : files root 'rclone-test-sepetav6roho': Waiting for checks to finish
2025/10/16 01:19:30 DEBUG : files root 'rclone-test-sepetav6roho': Waiting for transfers to finish
2025/10/16 01:19:31 DEBUG : sub dir/hello world: Dst hash empty - aborting Src hash check
2025/10/16 01:19:31 INFO  : sub dir/hello world: Copied (replaced existing)
2025/10/16 01:19:31 INFO  : sub dir: Set directory modification time (using DirSetModTime)
--- PASS: TestCopyOverSelf (3.87s)
=== RUN   TestSyncWithTrackRenames
    run.go:180: Remote "files root 'rclone-test-sepetav6roho'", Local "Local file system at /tmp/rclone3480439315", Modify Window "1s"
    sync_test.go:1568: Can track renames: true
2025/10/16 01:19:32 INFO  : files root 'rclone-test-sepetav6roho': Making map for --track-renames
2025/10/16 01:19:32 INFO  : files root 'rclone-test-sepetav6roho': Finished making map for --track-renames
2025/10/16 01:19:32 DEBUG : files root 'rclone-test-sepetav6roho': Waiting for checks to finish
2025/10/16 01:19:32 DEBUG : potato: Need to transfer - No matching file found at Destination
2025/10/16 01:19:32 DEBUG : files root 'rclone-test-sepetav6roho': Waiting for renames to finish
2025/10/16 01:19:32 DEBUG : yam: Need to transfer - No matching file found at Destination
2025/10/16 01:19:32 DEBUG : files root 'rclone-test-sepetav6roho': Waiting for transfers to finish
2025/10/16 01:19:33 DEBUG : yam: Dst hash empty - aborting Src hash check
2025/10/16 01:19:33 INFO  : yam: Copied (new)
2025/10/16 01:19:34 DEBUG : potato: Dst hash empty - aborting Src hash check
2025/10/16 01:19:34 INFO  : potato: Copied (new)
2025/10/16 01:19:34 DEBUG : Waiting for deletions to finish
2025/10/16 01:19:34 DEBUG : potato: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/10/16 01:19:34 INFO  : files root 'rclone-test-sepetav6roho': Making map for --track-renames
2025/10/16 01:19:34 INFO  : files root 'rclone-test-sepetav6roho': Finished making map for --track-renames
2025/10/16 01:19:34 DEBUG : files root 'rclone-test-sepetav6roho': Waiting for checks to finish
2025/10/16 01:19:34 DEBUG : potato: Unchanged skipping
2025/10/16 01:19:34 DEBUG : files root 'rclone-test-sepetav6roho': Waiting for renames to finish
2025/10/16 01:19:34 INFO  : yam: Moved (server-side) to: yaml
2025/10/16 01:19:34 INFO  : yaml: Renamed from "yam"
2025/10/16 01:19:34 DEBUG : files root 'rclone-test-sepetav6roho': Waiting for transfers to finish
2025/10/16 01:19:34 DEBUG : Waiting for deletions to finish
2025/10/16 01:19:34 INFO  : There was nothing to transfer
--- PASS: TestSyncWithTrackRenames (3.10s)
=== RUN   TestFixCase
    run.go:180: Remote "files root 'rclone-test-sepetav6roho'", Local "Local file system at /tmp/rclone3480439315", Modify Window "1s"
2025/10/16 01:19:39 DEBUG : existing: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/10/16 01:19:39 DEBUG : existing: Unchanged skipping
2025/10/16 01:19:39 DEBUG : existingbutdifferent: Sizes differ (src 5 vs dst 8)
2025/10/16 01:19:39 DEBUG : EXISTING: moving to existing-rclone-move-lifiyid0
2025/10/16 01:19:39 INFO  : SUBDIRA: Set directory modification time (using DirSetModTime)
2025/10/16 01:19:39 DEBUG : Added delayed dir = "SUBDIRA", newDst=SUBDIRA
2025/10/16 01:19:39 DEBUG : EXISTINGBUTDIFFERENT: moving to existingbutdifferent-rclone-move-sitakiz5
2025/10/16 01:19:40 INFO  : EXISTING: Moved (server-side) to: existing-rclone-move-lifiyid0
2025/10/16 01:19:40 DEBUG : EXISTING: moving to existing
2025/10/16 01:19:40 INFO  : EXISTINGBUTDIFFERENT: Moved (server-side) to: existingbutdifferent-rclone-move-sitakiz5
2025/10/16 01:19:40 DEBUG : EXISTINGBUTDIFFERENT: moving to existingbutdifferent
2025/10/16 01:19:40 INFO  : existing-rclone-move-lifiyid0: Moved (server-side) to: existing
2025/10/16 01:19:40 INFO  : EXISTING: Moved (server-side) to: existing
2025/10/16 01:19:40 INFO  : EXISTING: Fixed case by renaming to: existing
2025/10/16 01:19:40 INFO  : existingbutdifferent-rclone-move-sitakiz5: Moved (server-side) to: existingbutdifferent
2025/10/16 01:19:40 INFO  : EXISTINGBUTDIFFERENT: Moved (server-side) to: existingbutdifferent
2025/10/16 01:19:40 INFO  : EXISTINGBUTDIFFERENT: Fixed case by renaming to: existingbutdifferent
2025/10/16 01:19:41 INFO  : SUBDIRA: Fixed case by renaming to: subdira
2025/10/16 01:19:41 INFO  : SUBDIRA/subdirb: Set directory modification time (using DirSetModTime)
2025/10/16 01:19:41 DEBUG : Added delayed dir = "SUBDIRA/subdirb", newDst=SUBDIRA/subdirb
2025/10/16 01:19:41 DEBUG : existingbutdifferent: Dst hash empty - aborting Src hash check
2025/10/16 01:19:41 INFO  : existingbutdifferent: Copied (replaced existing)
2025/10/16 01:19:42 INFO  : SUBDIRA/subdirb: Fixed case by renaming to: subdira/subdirb
2025/10/16 01:19:42 INFO  : SUBDIRA/subdirb/SUBDIRC: Set directory modification time (using DirSetModTime)
2025/10/16 01:19:42 DEBUG : Added delayed dir = "SUBDIRA/subdirb/SUBDIRC", newDst=SUBDIRA/subdirb/SUBDIRC
2025/10/16 01:19:43 INFO  : SUBDIRA/subdirb/SUBDIRC: Fixed case by renaming to: subdira/subdirb/subdirc
2025/10/16 01:19:44 DEBUG : subdira/subdirb/subdirc/hello: Sizes differ (src 5 vs dst 8)
2025/10/16 01:19:44 DEBUG : SUBDIRA/subdirb/SUBDIRC/HELLO: moving to subdira/subdirb/subdirc/hello-rclone-move-qadagok7
2025/10/16 01:19:44 ERROR : SUBDIRA/subdirb/SUBDIRC/HELLO: Couldn't move: Not Found - `Not Found.  This may be related to your permissions.`
2025/10/16 01:19:44 ERROR : SUBDIRA/subdirb/SUBDIRC/HELLO: Couldn't move: error while moving file to temporary location: Not Found - `Not Found.  This may be related to your permissions.`
2025/10/16 01:19:44 ERROR : SUBDIRA/subdirb/SUBDIRC/HELLO: Error while attempting to rename to subdira/subdirb/subdirc/hello: error while moving file to temporary location: Not Found - `Not Found.  This may be related to your permissions.`
2025/10/16 01:19:45 DEBUG : SUBDIRA/subdirb/SUBDIRC/HELLO: Dst hash empty - aborting Src hash check
2025/10/16 01:19:45 INFO  : subdira/subdirb/subdirc/hello: Copied (replaced existing) to: SUBDIRA/subdirb/SUBDIRC/HELLO
2025/10/16 01:19:45 INFO  : SUBDIRA/subdirb/SUBDIRC/subdird: Fixed case by renaming to: subdira/subdirb/subdirc/subdird
2025/10/16 01:19:46 DEBUG : subdira/subdirb/subdirc/subdird/filewithoutcasedifferences: Sizes differ (src 5 vs dst 8)
2025/10/16 01:19:46 DEBUG : files root 'rclone-test-sepetav6roho': Waiting for checks to finish
2025/10/16 01:19:46 DEBUG : SUBDIRA/subdirb/SUBDIRC/subdird/filewithoutcasedifferences: moving to subdira/subdirb/subdirc/subdird/filewithoutcasedifferences-rclone-move-doralow9
2025/10/16 01:19:46 INFO  : SUBDIRA/subdirb/SUBDIRC/subdird/filewithoutcasedifferences: Moved (server-side) to: subdira/subdirb/subdirc/subdird/filewithoutcasedifferences-rclone-move-doralow9
2025/10/16 01:19:46 DEBUG : SUBDIRA/subdirb/SUBDIRC/subdird/filewithoutcasedifferences: moving to subdira/subdirb/subdirc/subdird/filewithoutcasedifferences
2025/10/16 01:19:47 INFO  : subdira/subdirb/subdirc/subdird/filewithoutcasedifferences-rclone-move-doralow9: Moved (server-side) to: subdira/subdirb/subdirc/subdird/filewithoutcasedifferences
2025/10/16 01:19:47 INFO  : SUBDIRA/subdirb/SUBDIRC/subdird/filewithoutcasedifferences: Moved (server-side) to: subdira/subdirb/subdirc/subdird/filewithoutcasedifferences
2025/10/16 01:19:47 INFO  : SUBDIRA/subdirb/SUBDIRC/subdird/filewithoutcasedifferences: Fixed case by renaming to: subdira/subdirb/subdirc/subdird/filewithoutcasedifferences
2025/10/16 01:19:47 DEBUG : files root 'rclone-test-sepetav6roho': Waiting for transfers to finish
2025/10/16 01:19:48 DEBUG : subdira/subdirb/subdirc/subdird/filewithoutcasedifferences: Dst hash empty - aborting Src hash check
2025/10/16 01:19:48 INFO  : subdira/subdirb/subdirc/subdird/filewithoutcasedifferences: Copied (replaced existing)
2025/10/16 01:19:48 ERROR : files root 'rclone-test-sepetav6roho': not deleting files as there were IO errors
2025/10/16 01:19:48 INFO  : SUBDIRA/subdirb/SUBDIRC: Set directory modification time (using DirSetModTime)
2025/10/16 01:19:48 INFO  : SUBDIRA/subdirb: Set directory modification time (using DirSetModTime)
2025/10/16 01:19:48 INFO  : SUBDIRA: Set directory modification time (using DirSetModTime)
2025/10/16 01:19:48 ERROR : files root 'rclone-test-sepetav6roho': not deleting directories as there were IO errors
    sync_test.go:2685: 
        	Error Trace:	/home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync_test.go:2685
        	Error:      	Received unexpected error:
        	            	error while moving file to temporary location: Not Found - `Not Found.  This may be related to your permissions.`
        	Test:       	TestFixCase
2025/10/16 01:19:50 DEBUG : pacer: low level retry 1/10 (error Folder Not Empty - `Folder rclone-test-sepetav6roho/subdira/subdirb not empty`)
2025/10/16 01:19:50 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2025/10/16 01:19:50 DEBUG : pacer: low level retry 2/10 (error Folder Not Empty - `Folder rclone-test-sepetav6roho/subdira/subdirb not empty`)
2025/10/16 01:19:50 DEBUG : pacer: Rate limited, increasing sleep to 40ms
2025/10/16 01:19:50 DEBUG : pacer: low level retry 3/10 (error Folder Not Empty - `Folder rclone-test-sepetav6roho/subdira/subdirb not empty`)
2025/10/16 01:19:50 DEBUG : pacer: Rate limited, increasing sleep to 80ms
2025/10/16 01:19:50 DEBUG : pacer: Reducing sleep to 60ms
2025/10/16 01:19:51 DEBUG : pacer: low level retry 1/10 (error Folder Not Empty - `Folder rclone-test-sepetav6roho/subdira not empty`)
2025/10/16 01:19:51 DEBUG : pacer: Rate limited, increasing sleep to 120ms
2025/10/16 01:19:51 DEBUG : pacer: Reducing sleep to 90ms
2025/10/16 01:19:51 DEBUG : pacer: Reducing sleep to 67.5ms
--- FAIL: TestFixCase (15.69s)
=== RUN   TestSyncConcurrentTruncate
    run.go:180: Remote "files root 'rclone-test-sepetav6roho'", Local "Local file system at /tmp/rclone3480439315", Modify Window "1s"
2025/10/16 01:19:51 DEBUG : pacer: Reducing sleep to 50.625ms
2025/10/16 01:19:52 DEBUG : pacer: Reducing sleep to 37.96875ms
2025/10/16 01:19:52 DEBUG : pacer: Reducing sleep to 28.476562ms
2025/10/16 01:19:52 DEBUG : pacer: Reducing sleep to 21.357421ms
2025/10/16 01:19:53 DEBUG : pacer: Reducing sleep to 16.018065ms
2025/10/16 01:19:53 DEBUG : pacer: Reducing sleep to 12.013548ms
2025/10/16 01:19:54 DEBUG : pacer: Reducing sleep to 10ms
2025/10/16 01:20:23 DEBUG : both10: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/10/16 01:20:23 DEBUG : both0: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/10/16 01:20:23 DEBUG : both10: Unchanged skipping
2025/10/16 01:20:23 DEBUG : both12: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/10/16 01:20:23 DEBUG : both11: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/10/16 01:20:23 DEBUG : files root 'rclone-test-sepetav6roho': Waiting for checks to finish
2025/10/16 01:20:23 DEBUG : both12: Unchanged skipping
2025/10/16 01:20:23 DEBUG : both14: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/10/16 01:20:23 DEBUG : both13: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/10/16 01:20:23 DEBUG : both14: Unchanged skipping
2025/10/16 01:20:23 DEBUG : both15: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/10/16 01:20:23 DEBUG : both13: Unchanged skipping
2025/10/16 01:20:23 DEBUG : both16: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/10/16 01:20:23 DEBUG : both16: Unchanged skipping
2025/10/16 01:20:23 DEBUG : both17: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/10/16 01:20:23 DEBUG : both17: Unchanged skipping
2025/10/16 01:20:23 DEBUG : both18: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/10/16 01:20:23 DEBUG : both18: Unchanged skipping
2025/10/16 01:20:23 DEBUG : both19: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/10/16 01:20:23 DEBUG : both19: Unchanged skipping
2025/10/16 01:20:23 DEBUG : both1: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/10/16 01:20:23 DEBUG : both1: Unchanged skipping
2025/10/16 01:20:23 DEBUG : both2: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/10/16 01:20:23 DEBUG : both2: Unchanged skipping
2025/10/16 01:20:23 DEBUG : both3: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/10/16 01:20:23 DEBUG : both3: Unchanged skipping
2025/10/16 01:20:23 DEBUG : both4: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/10/16 01:20:23 DEBUG : both4: Unchanged skipping
2025/10/16 01:20:23 DEBUG : both5: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/10/16 01:20:23 DEBUG : both5: Unchanged skipping
2025/10/16 01:20:23 DEBUG : both6: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/10/16 01:20:23 DEBUG : both6: Unchanged skipping
2025/10/16 01:20:23 DEBUG : both7: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/10/16 01:20:23 DEBUG : both7: Unchanged skipping
2025/10/16 01:20:23 DEBUG : both8: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/10/16 01:20:23 DEBUG : both8: Unchanged skipping
2025/10/16 01:20:23 DEBUG : both9: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/10/16 01:20:23 DEBUG : both9: Unchanged skipping
2025/10/16 01:20:23 DEBUG : only0: Sizes differ (src 0 vs dst 6)
2025/10/16 01:20:23 DEBUG : both11: Unchanged skipping
2025/10/16 01:20:23 DEBUG : only10: Sizes differ (src 0 vs dst 6)
2025/10/16 01:20:23 DEBUG : only11: Sizes differ (src 0 vs dst 6)
2025/10/16 01:20:23 DEBUG : only12: Sizes differ (src 0 vs dst 6)
2025/10/16 01:20:23 DEBUG : only13: Sizes differ (src 0 vs dst 6)
2025/10/16 01:20:23 DEBUG : only14: Sizes differ (src 0 vs dst 6)
2025/10/16 01:20:23 DEBUG : only15: Sizes differ (src 0 vs dst 6)
2025/10/16 01:20:23 DEBUG : only16: Sizes differ (src 0 vs dst 6)
2025/10/16 01:20:23 DEBUG : only17: Sizes differ (src 0 vs dst 6)
2025/10/16 01:20:23 DEBUG : only18: Sizes differ (src 0 vs dst 6)
2025/10/16 01:20:23 DEBUG : both15: Unchanged skipping
2025/10/16 01:20:23 DEBUG : both0: Unchanged skipping
2025/10/16 01:20:23 DEBUG : only19: Sizes differ (src 0 vs dst 6)
2025/10/16 01:20:23 DEBUG : only4: Sizes differ (src 0 vs dst 6)
2025/10/16 01:20:23 DEBUG : only5: Sizes differ (src 0 vs dst 6)
2025/10/16 01:20:23 DEBUG : only6: Sizes differ (src 0 vs dst 6)
2025/10/16 01:20:23 DEBUG : only3: Sizes differ (src 0 vs dst 6)
2025/10/16 01:20:23 DEBUG : only1: Sizes differ (src 0 vs dst 6)
2025/10/16 01:20:23 DEBUG : only2: Sizes differ (src 0 vs dst 6)
2025/10/16 01:20:23 DEBUG : only7: Sizes differ (src 0 vs dst 6)
2025/10/16 01:20:23 DEBUG : only8: Sizes differ (src 0 vs dst 6)
2025/10/16 01:20:23 DEBUG : only9: Sizes differ (src 0 vs dst 6)
2025/10/16 01:20:23 DEBUG : files root 'rclone-test-sepetav6roho': Waiting for transfers to finish
2025/10/16 01:20:24 DEBUG : only0: Dst hash empty - aborting Src hash check
2025/10/16 01:20:24 INFO  : only0: Copied (replaced existing)
2025/10/16 01:20:24 DEBUG : only12: Dst hash empty - aborting Src hash check
2025/10/16 01:20:24 INFO  : only12: Copied (replaced existing)
2025/10/16 01:20:24 DEBUG : only13: Dst hash empty - aborting Src hash check
2025/10/16 01:20:24 INFO  : only13: Copied (replaced existing)
2025/10/16 01:20:24 DEBUG : only11: Dst hash empty - aborting Src hash check
2025/10/16 01:20:24 INFO  : only11: Copied (replaced existing)
2025/10/16 01:20:25 DEBUG : only14: Dst hash empty - aborting Src hash check
2025/10/16 01:20:25 INFO  : only14: Copied (replaced existing)
2025/10/16 01:20:25 DEBUG : only16: Dst hash empty - aborting Src hash check
2025/10/16 01:20:25 INFO  : only16: Copied (replaced existing)
2025/10/16 01:20:25 DEBUG : only17: Dst hash empty - aborting Src hash check
2025/10/16 01:20:25 INFO  : only17: Copied (replaced existing)
2025/10/16 01:20:25 DEBUG : only15: Dst hash empty - aborting Src hash check
2025/10/16 01:20:25 INFO  : only15: Copied (replaced existing)
2025/10/16 01:20:25 DEBUG : only18: md5 = d41d8cd98f00b204e9800998ecf8427e OK
2025/10/16 01:20:25 INFO  : only18: Copied (replaced existing)
2025/10/16 01:20:26 DEBUG : only19: md5 = d41d8cd98f00b204e9800998ecf8427e OK
2025/10/16 01:20:26 INFO  : only19: Copied (replaced existing)
2025/10/16 01:20:26 DEBUG : only4: Dst hash empty - aborting Src hash check
2025/10/16 01:20:26 INFO  : only4: Copied (replaced existing)
2025/10/16 01:20:26 DEBUG : only10: Dst hash empty - aborting Src hash check
2025/10/16 01:20:26 INFO  : only10: Copied (replaced existing)
2025/10/16 01:20:26 DEBUG : only5: Dst hash empty - aborting Src hash check
2025/10/16 01:20:26 INFO  : only5: Copied (replaced existing)
2025/10/16 01:20:27 DEBUG : only8: Dst hash empty - aborting Src hash check
2025/10/16 01:20:27 INFO  : only8: Copied (replaced existing)
2025/10/16 01:20:27 DEBUG : only6: Dst hash empty - aborting Src hash check
2025/10/16 01:20:27 INFO  : only6: Copied (replaced existing)
2025/10/16 01:20:27 DEBUG : only7: Dst hash empty - aborting Src hash check
2025/10/16 01:20:27 INFO  : only7: Copied (replaced existing)
2025/10/16 01:20:27 DEBUG : only9: Dst hash empty - aborting Src hash check
2025/10/16 01:20:27 INFO  : only9: Copied (replaced existing)
2025/10/16 01:20:27 DEBUG : only3: Dst hash empty - aborting Src hash check
2025/10/16 01:20:27 INFO  : only3: Copied (replaced existing)
2025/10/16 01:20:27 DEBUG : only1: Dst hash empty - aborting Src hash check
2025/10/16 01:20:27 INFO  : only1: Copied (replaced existing)
2025/10/16 01:20:27 DEBUG : only2: Dst hash empty - aborting Src hash check
2025/10/16 01:20:27 INFO  : only2: Copied (replaced existing)
2025/10/16 01:20:27 DEBUG : Waiting for deletions to finish
--- PASS: TestSyncConcurrentTruncate (43.79s)
FAIL
2025/10/16 01:20:35 DEBUG : files root 'rclone-test-sepetav6roho': Purge remote
"./sync.test -test.v -test.timeout 1h0m0s -remote TestFilesCom: -verbose -test.run '^(TestCopyNoEmptyDirectories|TestCopyOverSelf|TestFixCase|TestSyncConcurrentTruncate|TestSyncEmptyDirectories|TestSyncNoEmptyDirectories|TestSyncNoUpdateDirModtime|TestSyncSetDelayedModTimes|TestSyncWithTrackRenames)$'" - Finished ERROR in 1m35.874037498s (try 2/5): exit status 1: Failed [TestFixCase]