"./sync.test -test.v -test.timeout 1h0m0s -remote TestFilesCom: -verbose -test.run '^(TestServerSideCopyOverSelf|TestSyncAfterChangingModtimeOnlyWithNoUpdateModTime|TestSyncCopyDest|TestSyncEmptyDirectories|TestSyncNoEmptyDirectories|TestSyncNoTraverse|TestSyncNoUpdateDirModtime|TestSyncReplaceDirModTimeWithEmptyDirs|TestSyncSetDelayedModTimes)$'" - Starting (try 2/5)
2025/11/10 05:30:46 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-vibawux9hemi"
2025/11/10 05:30:46 DEBUG : Using config file from "/home/rclone/.rclone.conf"
2025/11/10 05:30:47 DEBUG : Creating backend with remote "/tmp/rclone1449452982"
=== RUN   TestSyncNoTraverse
    run.go:185: Remote "files root 'rclone-test-vibawux9hemi'", Local "Local file system at /tmp/rclone1449452982", Modify Window "1s"
2025/11/10 05:30:47 ERROR : Ignoring --no-traverse with sync
2025/11/10 05:30:47 DEBUG : Added delayed dir = "sub dir", newDst=<nil>
2025/11/10 05:30:47 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination
2025/11/10 05:30:47 DEBUG : files root 'rclone-test-vibawux9hemi': Waiting for checks to finish
2025/11/10 05:30:47 DEBUG : files root 'rclone-test-vibawux9hemi': Waiting for transfers to finish
2025/11/10 05:30:48 DEBUG : sub dir/hello world: size = 11 OK
2025/11/10 05:30:48 DEBUG : sub dir/hello world: md5 = 5eb63bbbe01eeed093cb22bb8f5acdc3 OK
2025/11/10 05:30:48 INFO  : sub dir/hello world: Copied (new)
2025/11/10 05:30:48 DEBUG : Waiting for deletions to finish
2025/11/10 05:30:48 INFO  : sub dir: Set directory modification time (using DirSetModTime)
--- PASS: TestSyncNoTraverse (2.54s)
=== RUN   TestSyncNoUpdateDirModtime
    run.go:185: Remote "files root 'rclone-test-vibawux9hemi'", Local "Local file system at /tmp/rclone1449452982", Modify Window "1s"
2025/11/10 05:30:49 DEBUG : sub dir no update dir modtime: Making directory with metadata
2025/11/10 05:30:49 INFO  : sub dir no update dir modtime: Made directory with metadata (mtime=2001-02-03T04:05:06.499999999Z)
2025/11/10 05:30:50 DEBUG : files root 'rclone-test-vibawux9hemi': Waiting for checks to finish
2025/11/10 05:30:50 DEBUG : files root 'rclone-test-vibawux9hemi': Waiting for transfers to finish
2025/11/10 05:30:50 DEBUG : Waiting for deletions to finish
--- PASS: TestSyncNoUpdateDirModtime (1.64s)
=== RUN   TestSyncEmptyDirectories
    run.go:185: Remote "files root 'rclone-test-vibawux9hemi'", Local "Local file system at /tmp/rclone1449452982", Modify Window "1s"
2025/11/10 05:30:51 DEBUG : sub dir2: Making directory with metadata
2025/11/10 05:30:51 INFO  : sub dir2: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z)
2025/11/10 05:30:51 INFO  : sub dir: Set directory modification time (using DirSetModTime)
2025/11/10 05:30:51 INFO  : sub dir2: Making directory
2025/11/10 05:30:52 INFO  : sub dir2: Made directory with modification time 2011-12-25 12:59:59.123456789 +0000 UTC
2025/11/10 05:30:52 DEBUG : Added delayed dir = "sub dir2", newDst=<nil>
2025/11/10 05:30:52 INFO  : sub dir: Making directory
2025/11/10 05:30:52 INFO  : sub dir: Made directory with modification time 2001-02-03 04:05:06.499999999 +0000 UTC
2025/11/10 05:30:52 DEBUG : Added delayed dir = "sub dir", newDst=<nil>
2025/11/10 05:30:52 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination
2025/11/10 05:30:52 DEBUG : files root 'rclone-test-vibawux9hemi': Waiting for checks to finish
2025/11/10 05:30:52 DEBUG : files root 'rclone-test-vibawux9hemi': Waiting for transfers to finish
2025/11/10 05:30:53 DEBUG : sub dir/hello world: size = 11 OK
2025/11/10 05:30:53 DEBUG : sub dir/hello world: Dst hash empty - aborting Src hash check
2025/11/10 05:30:53 INFO  : sub dir/hello world: Copied (new)
2025/11/10 05:30:53 DEBUG : Waiting for deletions to finish
2025/11/10 05:30:53 INFO  : sub dir: Set directory modification time (using DirSetModTime)
2025/11/10 05:30:53 INFO  : sub dir2: Set directory modification time (using DirSetModTime)
--- PASS: TestSyncEmptyDirectories (3.51s)
=== RUN   TestSyncSetDelayedModTimes
    run.go:185: Remote "files root 'rclone-test-vibawux9hemi'", Local "Local file system at /tmp/rclone1449452982", Modify Window "1s"
2025/11/10 05:30:54 INFO  : a1/b2/c1/d1/e1/f1: Set directory modification time (using DirSetModTime)
2025/11/10 05:30:54 INFO  : a1/b2/c1/d1/e1: Set directory modification time (using DirSetModTime)
2025/11/10 05:30:54 INFO  : a1/b2/c1/d1: Set directory modification time (using DirSetModTime)
2025/11/10 05:30:54 INFO  : a1/b2/c1: Set directory modification time (using DirSetModTime)
2025/11/10 05:30:54 INFO  : a1/b2: Set directory modification time (using DirSetModTime)
2025/11/10 05:30:54 INFO  : a1/b1/c1/d2/e1/f2: Set directory modification time (using DirSetModTime)
2025/11/10 05:30:54 INFO  : a1/b1/c1/d2/e1/f1: Set directory modification time (using DirSetModTime)
2025/11/10 05:30:54 INFO  : a1/b1/c1/d2/e1: Set directory modification time (using DirSetModTime)
2025/11/10 05:30:54 INFO  : a1/b1/c1/d2: Set directory modification time (using DirSetModTime)
2025/11/10 05:30:54 INFO  : a1/b1/c1/d1/e1/f1: Set directory modification time (using DirSetModTime)
2025/11/10 05:30:54 INFO  : a1/b1/c1/d1/e1: Set directory modification time (using DirSetModTime)
2025/11/10 05:30:54 INFO  : a1/b1/c1/d1: Set directory modification time (using DirSetModTime)
2025/11/10 05:30:54 INFO  : a1/b1/c1: Set directory modification time (using DirSetModTime)
2025/11/10 05:30:54 INFO  : a1/b1: Set directory modification time (using DirSetModTime)
2025/11/10 05:30:54 INFO  : a1: Set directory modification time (using DirSetModTime)
2025/11/10 05:30:55 INFO  : a1: Making directory
2025/11/10 05:30:55 INFO  : a1: Made directory with modification time 2001-02-03 04:19:06.499999999 +0000 UTC
2025/11/10 05:30:55 DEBUG : Added delayed dir = "a1", newDst=<nil>
2025/11/10 05:30:55 INFO  : a1/b1: Making directory
2025/11/10 05:30:55 INFO  : a1/b1: Made directory with modification time 2001-02-03 04:18:06.499999999 +0000 UTC
2025/11/10 05:30:55 DEBUG : Added delayed dir = "a1/b1", newDst=<nil>
2025/11/10 05:30:55 INFO  : a1/b2: Making directory
2025/11/10 05:30:56 INFO  : a1/b2: Made directory with modification time 2001-02-03 04:09:06.499999999 +0000 UTC
2025/11/10 05:30:56 DEBUG : Added delayed dir = "a1/b2", newDst=<nil>
2025/11/10 05:30:56 INFO  : a1/b1/c1: Making directory
2025/11/10 05:30:56 INFO  : a1/b2/c1: Making directory
2025/11/10 05:30:56 INFO  : a1/b1/c1: Made directory with modification time 2001-02-03 04:17:06.499999999 +0000 UTC
2025/11/10 05:30:56 DEBUG : Added delayed dir = "a1/b1/c1", newDst=<nil>
2025/11/10 05:30:56 INFO  : a1/b1/c1/d1: Making directory
2025/11/10 05:30:56 INFO  : a1/b2/c1: Made directory with modification time 2001-02-03 04:08:06.499999999 +0000 UTC
2025/11/10 05:30:56 DEBUG : Added delayed dir = "a1/b2/c1", newDst=<nil>
2025/11/10 05:30:56 INFO  : a1/b2/c1/d1: Making directory
2025/11/10 05:30:56 INFO  : a1/b1/c1/d1: Made directory with modification time 2001-02-03 04:16:06.499999999 +0000 UTC
2025/11/10 05:30:56 DEBUG : Added delayed dir = "a1/b1/c1/d1", newDst=<nil>
2025/11/10 05:30:56 INFO  : a1/b1/c1/d2: Making directory
2025/11/10 05:30:56 INFO  : a1/b2/c1/d1: Made directory with modification time 2001-02-03 04:07:06.499999999 +0000 UTC
2025/11/10 05:30:56 DEBUG : Added delayed dir = "a1/b2/c1/d1", newDst=<nil>
2025/11/10 05:30:56 INFO  : a1/b2/c1/d1/e1: Making directory
2025/11/10 05:30:57 INFO  : a1/b1/c1/d2: Made directory with modification time 2001-02-03 04:13:06.499999999 +0000 UTC
2025/11/10 05:30:57 DEBUG : Added delayed dir = "a1/b1/c1/d2", newDst=<nil>
2025/11/10 05:30:57 INFO  : a1/b1/c1/d2/e1: Making directory
2025/11/10 05:30:57 INFO  : a1/b1/c1/d1/e1: Making directory
2025/11/10 05:30:57 INFO  : a1/b2/c1/d1/e1: Made directory with modification time 2001-02-03 04:06:06.499999999 +0000 UTC
2025/11/10 05:30:57 DEBUG : Added delayed dir = "a1/b2/c1/d1/e1", newDst=<nil>
2025/11/10 05:30:57 INFO  : a1/b2/c1/d1/e1/f1: Making directory
2025/11/10 05:30:57 INFO  : a1/b1/c1/d2/e1: Made directory with modification time 2001-02-03 04:12:06.499999999 +0000 UTC
2025/11/10 05:30:57 DEBUG : Added delayed dir = "a1/b1/c1/d2/e1", newDst=<nil>
2025/11/10 05:30:57 INFO  : a1/b1/c1/d2/e1/f1: Making directory
2025/11/10 05:30:57 INFO  : a1/b1/c1/d1/e1: Made directory with modification time 2001-02-03 04:15:06.499999999 +0000 UTC
2025/11/10 05:30:57 DEBUG : Added delayed dir = "a1/b1/c1/d1/e1", newDst=<nil>
2025/11/10 05:30:57 INFO  : a1/b1/c1/d1/e1/f1: Making directory
2025/11/10 05:30:57 INFO  : a1/b2/c1/d1/e1/f1: Made directory with modification time 2001-02-03 04:05:06.499999999 +0000 UTC
2025/11/10 05:30:57 DEBUG : Added delayed dir = "a1/b2/c1/d1/e1/f1", newDst=<nil>
2025/11/10 05:30:57 INFO  : a1/b1/c1/d1/e1/f1: Made directory with modification time 2001-02-03 04:14:06.499999999 +0000 UTC
2025/11/10 05:30:57 DEBUG : Added delayed dir = "a1/b1/c1/d1/e1/f1", newDst=<nil>
2025/11/10 05:30:57 INFO  : a1/b1/c1/d2/e1/f1: Made directory with modification time 2001-02-03 04:11:06.499999999 +0000 UTC
2025/11/10 05:30:57 DEBUG : Added delayed dir = "a1/b1/c1/d2/e1/f1", newDst=<nil>
2025/11/10 05:30:57 INFO  : a1/b1/c1/d2/e1/f2: Making directory
2025/11/10 05:30:58 INFO  : a1/b1/c1/d2/e1/f2: Made directory with modification time 2001-02-03 04:10:06.499999999 +0000 UTC
2025/11/10 05:30:58 DEBUG : Added delayed dir = "a1/b1/c1/d2/e1/f2", newDst=<nil>
2025/11/10 05:30:58 DEBUG : files root 'rclone-test-vibawux9hemi': Waiting for checks to finish
2025/11/10 05:30:58 DEBUG : files root 'rclone-test-vibawux9hemi': Waiting for transfers to finish
2025/11/10 05:30:58 DEBUG : Waiting for deletions to finish
2025/11/10 05:30:58 INFO  : a1/b2/c1/d1/e1/f1: Set directory modification time (using DirSetModTime)
2025/11/10 05:30:58 INFO  : a1/b1/c1/d2/e1/f2: Set directory modification time (using DirSetModTime)
2025/11/10 05:30:58 INFO  : a1/b1/c1/d1/e1/f1: Set directory modification time (using DirSetModTime)
2025/11/10 05:30:58 INFO  : a1/b1/c1/d2/e1/f1: Set directory modification time (using DirSetModTime)
2025/11/10 05:30:58 INFO  : a1/b1/c1/d1/e1: Set directory modification time (using DirSetModTime)
2025/11/10 05:30:58 INFO  : a1/b2/c1/d1/e1: Set directory modification time (using DirSetModTime)
2025/11/10 05:30:58 INFO  : a1/b1/c1/d2/e1: Set directory modification time (using DirSetModTime)
2025/11/10 05:30:58 INFO  : a1/b1/c1/d2: Set directory modification time (using DirSetModTime)
2025/11/10 05:30:58 INFO  : a1/b1/c1/d1: Set directory modification time (using DirSetModTime)
2025/11/10 05:30:58 INFO  : a1/b2/c1/d1: Set directory modification time (using DirSetModTime)
2025/11/10 05:30:58 INFO  : a1/b1/c1: Set directory modification time (using DirSetModTime)
2025/11/10 05:30:58 INFO  : a1/b2/c1: Set directory modification time (using DirSetModTime)
2025/11/10 05:30:59 INFO  : a1/b2: Set directory modification time (using DirSetModTime)
2025/11/10 05:30:59 INFO  : a1/b1: Set directory modification time (using DirSetModTime)
2025/11/10 05:30:59 INFO  : a1: Set directory modification time (using DirSetModTime)
2025/11/10 05:31:03 DEBUG : pacer: low level retry 1/10 (error Folder Not Empty - `Folder rclone-test-vibawux9hemi/a1/b2/c1/d1/e1 not empty`)
2025/11/10 05:31:03 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2025/11/10 05:31:03 DEBUG : pacer: Reducing sleep to 15ms
2025/11/10 05:31:04 DEBUG : pacer: low level retry 1/10 (error Folder Not Empty - `Folder rclone-test-vibawux9hemi/a1/b2/c1/d1 not empty`)
2025/11/10 05:31:04 DEBUG : pacer: Rate limited, increasing sleep to 30ms
2025/11/10 05:31:04 DEBUG : pacer: Reducing sleep to 22.5ms
2025/11/10 05:31:04 DEBUG : pacer: Reducing sleep to 16.875ms
2025/11/10 05:31:04 DEBUG : pacer: Reducing sleep to 12.65625ms
2025/11/10 05:31:04 DEBUG : pacer: Reducing sleep to 10ms
2025/11/10 05:31:04 DEBUG : pacer: low level retry 1/10 (error Folder Not Empty - `Folder rclone-test-vibawux9hemi/a1/b1/c1/d2/e1 not empty`)
2025/11/10 05:31:04 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2025/11/10 05:31:05 DEBUG : pacer: low level retry 2/10 (error Folder Not Empty - `Folder rclone-test-vibawux9hemi/a1/b1/c1/d2/e1 not empty`)
2025/11/10 05:31:05 DEBUG : pacer: Rate limited, increasing sleep to 40ms
2025/11/10 05:31:05 DEBUG : pacer: low level retry 3/10 (error Folder Not Empty - `Folder rclone-test-vibawux9hemi/a1/b1/c1/d2/e1 not empty`)
2025/11/10 05:31:05 DEBUG : pacer: Rate limited, increasing sleep to 80ms
2025/11/10 05:31:05 DEBUG : pacer: Reducing sleep to 60ms
2025/11/10 05:31:05 DEBUG : pacer: Reducing sleep to 45ms
2025/11/10 05:31:05 DEBUG : pacer: Reducing sleep to 33.75ms
2025/11/10 05:31:05 DEBUG : pacer: low level retry 1/10 (error Folder Not Empty - `Folder rclone-test-vibawux9hemi/a1/b1/c1/d1/e1 not empty`)
2025/11/10 05:31:05 DEBUG : pacer: Rate limited, increasing sleep to 67.5ms
2025/11/10 05:31:06 DEBUG : pacer: low level retry 2/10 (error Folder Not Empty - `Folder rclone-test-vibawux9hemi/a1/b1/c1/d1/e1 not empty`)
2025/11/10 05:31:06 DEBUG : pacer: Rate limited, increasing sleep to 135ms
2025/11/10 05:31:06 DEBUG : pacer: Reducing sleep to 101.25ms
2025/11/10 05:31:06 DEBUG : pacer: low level retry 1/10 (error Folder Not Empty - `Folder rclone-test-vibawux9hemi/a1/b1/c1/d1 not empty`)
2025/11/10 05:31:06 DEBUG : pacer: Rate limited, increasing sleep to 202.5ms
2025/11/10 05:31:06 DEBUG : pacer: Reducing sleep to 151.875ms
2025/11/10 05:31:06 DEBUG : pacer: low level retry 1/10 (error Folder Not Empty - `Folder rclone-test-vibawux9hemi/a1/b1/c1 not empty`)
2025/11/10 05:31:06 DEBUG : pacer: Rate limited, increasing sleep to 303.75ms
2025/11/10 05:31:06 DEBUG : pacer: Reducing sleep to 227.8125ms
2025/11/10 05:31:07 DEBUG : pacer: Reducing sleep to 170.859375ms
2025/11/10 05:31:07 DEBUG : pacer: low level retry 1/10 (error Folder Not Empty - `Folder rclone-test-vibawux9hemi/a1 not empty`)
2025/11/10 05:31:07 DEBUG : pacer: Rate limited, increasing sleep to 341.71875ms
2025/11/10 05:31:07 DEBUG : pacer: Reducing sleep to 256.289062ms
2025/11/10 05:31:07 DEBUG : pacer: Reducing sleep to 192.216796ms
--- PASS: TestSyncSetDelayedModTimes (12.98s)
=== RUN   TestSyncNoEmptyDirectories
    run.go:185: Remote "files root 'rclone-test-vibawux9hemi'", Local "Local file system at /tmp/rclone1449452982", Modify Window "1s"
2025/11/10 05:31:07 INFO  : sub dir2: Making directory
2025/11/10 05:31:08 DEBUG : pacer: Reducing sleep to 144.162597ms
2025/11/10 05:31:08 DEBUG : Added delayed dir = "sub dir2", newDst=<nil>
2025/11/10 05:31:08 DEBUG : Added delayed dir = "sub dir", newDst=<nil>
2025/11/10 05:31:08 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination
2025/11/10 05:31:08 DEBUG : files root 'rclone-test-vibawux9hemi': Waiting for checks to finish
2025/11/10 05:31:08 DEBUG : files root 'rclone-test-vibawux9hemi': Waiting for transfers to finish
2025/11/10 05:31:09 DEBUG : pacer: Reducing sleep to 108.121947ms
2025/11/10 05:31:09 DEBUG : pacer: Reducing sleep to 81.09146ms
2025/11/10 05:31:09 DEBUG : sub dir/hello world: size = 11 OK
2025/11/10 05:31:09 DEBUG : sub dir/hello world: Dst hash empty - aborting Src hash check
2025/11/10 05:31:09 INFO  : sub dir/hello world: Copied (new)
2025/11/10 05:31:09 DEBUG : Waiting for deletions to finish
2025/11/10 05:31:09 DEBUG : pacer: Reducing sleep to 60.818595ms
2025/11/10 05:31:09 INFO  : sub dir: Set directory modification time (using DirSetModTime)
2025/11/10 05:31:09 DEBUG : pacer: Reducing sleep to 45.613946ms
2025/11/10 05:31:09 DEBUG : pacer: Reducing sleep to 34.210459ms
2025/11/10 05:31:09 DEBUG : pacer: Reducing sleep to 25.657844ms
2025/11/10 05:31:09 DEBUG : pacer: Reducing sleep to 19.243383ms
2025/11/10 05:31:10 DEBUG : pacer: Reducing sleep to 14.432537ms
2025/11/10 05:31:10 DEBUG : pacer: Reducing sleep to 10.824402ms
2025/11/10 05:31:10 DEBUG : pacer: Reducing sleep to 10ms
--- PASS: TestSyncNoEmptyDirectories (2.50s)
=== RUN   TestServerSideCopyOverSelf
    run.go:185: Remote "files root 'rclone-test-vibawux9hemi'", Local "Local file system at /tmp/rclone1449452982", Modify Window "1s"
2025/11/10 05:31:11 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-zeviped6tuha"
    sync_test.go:656: Server side copy (if possible) files root 'rclone-test-vibawux9hemi' -> files root 'rclone-test-zeviped6tuha'
2025/11/10 05:31:12 DEBUG : Added delayed dir = "sub dir", newDst=<nil>
2025/11/10 05:31:12 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination
2025/11/10 05:31:12 DEBUG : files root 'rclone-test-zeviped6tuha': Waiting for checks to finish
2025/11/10 05:31:12 DEBUG : files root 'rclone-test-zeviped6tuha': Waiting for transfers to finish
2025/11/10 05:31:14 DEBUG : sub dir/hello world: size = 11 OK
2025/11/10 05:31:14 DEBUG : sub dir/hello world: md5 = 5eb63bbbe01eeed093cb22bb8f5acdc3 OK
2025/11/10 05:31:14 INFO  : sub dir/hello world: Copied (server-side copy)
2025/11/10 05:31:14 INFO  : sub dir: Set directory modification time (using DirSetModTime)
2025/11/10 05:31:20 INFO  : sub dir: Set directory modification time (using DirSetModTime)
2025/11/10 05:31:20 DEBUG : Added delayed dir = "sub dir", newDst=sub dir
2025/11/10 05:31:20 DEBUG : sub dir/hello world: size = 17 (files root 'rclone-test-vibawux9hemi')
2025/11/10 05:31:20 DEBUG : sub dir/hello world: size = 11 (files root 'rclone-test-zeviped6tuha')
2025/11/10 05:31:20 DEBUG : sub dir/hello world: Sizes differ
2025/11/10 05:31:20 DEBUG : files root 'rclone-test-zeviped6tuha': Waiting for checks to finish
2025/11/10 05:31:20 DEBUG : files root 'rclone-test-zeviped6tuha': Waiting for transfers to finish
2025/11/10 05:31:22 DEBUG : sub dir/hello world: size = 17 OK
2025/11/10 05:31:22 DEBUG : sub dir/hello world: md5 = 00321a507bdb420dbbd4f53c733b1505 OK
2025/11/10 05:31:22 INFO  : sub dir/hello world: Copied (server-side copy)
2025/11/10 05:31:22 INFO  : sub dir: Set directory modification time (using DirSetModTime)
2025/11/10 05:31:22 DEBUG : files root 'rclone-test-zeviped6tuha': Purge remote
--- PASS: TestServerSideCopyOverSelf (13.32s)
=== RUN   TestSyncAfterChangingModtimeOnlyWithNoUpdateModTime
    run.go:185: Remote "files root 'rclone-test-vibawux9hemi'", Local "Local file system at /tmp/rclone1449452982", Modify Window "1s"
2025/11/10 05:31:24 DEBUG : empty space: size = 1 OK
2025/11/10 05:31:24 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/11/10 05:31:24 DEBUG : files root 'rclone-test-vibawux9hemi': Waiting for checks to finish
2025/11/10 05:31:24 DEBUG : empty space: md5 = 336d5ebc5436534e61d16e63ddfca327 OK
2025/11/10 05:31:24 DEBUG : empty space: Unchanged skipping
2025/11/10 05:31:24 DEBUG : files root 'rclone-test-vibawux9hemi': Waiting for transfers to finish
2025/11/10 05:31:24 DEBUG : Waiting for deletions to finish
2025/11/10 05:31:24 INFO  : There was nothing to transfer
--- PASS: TestSyncAfterChangingModtimeOnlyWithNoUpdateModTime (1.66s)
=== RUN   TestSyncCopyDest
    run.go:185: Remote "files root 'rclone-test-vibawux9hemi'", Local "Local file system at /tmp/rclone1449452982", Modify Window "1s"
2025/11/10 05:31:25 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-vibawux9hemi/dst"
2025/11/10 05:31:25 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-vibawux9hemi/CopyDest"
2025/11/10 05:31:27 DEBUG : one: Need to transfer - File not found at Destination
2025/11/10 05:31:27 DEBUG : files root 'rclone-test-vibawux9hemi/dst': Waiting for checks to finish
2025/11/10 05:31:27 DEBUG : files root 'rclone-test-vibawux9hemi/dst': Waiting for transfers to finish
2025/11/10 05:31:28 DEBUG : one: size = 3 OK
2025/11/10 05:31:28 DEBUG : one: Dst hash empty - aborting Src hash check
2025/11/10 05:31:28 INFO  : one: Copied (new)
2025/11/10 05:31:28 DEBUG : Waiting for deletions to finish
2025/11/10 05:31:28 DEBUG : one: size = 5 (Local file system at /tmp/rclone1449452982)
2025/11/10 05:31:28 DEBUG : one: size = 3 (files root 'rclone-test-vibawux9hemi/dst')
2025/11/10 05:31:28 DEBUG : one: Sizes differ
2025/11/10 05:31:28 DEBUG : files root 'rclone-test-vibawux9hemi/dst': Waiting for checks to finish
2025/11/10 05:31:29 DEBUG : files root 'rclone-test-vibawux9hemi/dst': Waiting for transfers to finish
2025/11/10 05:31:29 DEBUG : one: size = 5 OK
2025/11/10 05:31:29 DEBUG : one: Dst hash empty - aborting Src hash check
2025/11/10 05:31:29 INFO  : one: Copied (replaced existing)
2025/11/10 05:31:29 DEBUG : Waiting for deletions to finish
2025/11/10 05:31:32 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-vibawux9hemi/BackupDir"
2025/11/10 05:31:33 DEBUG : files root 'rclone-test-vibawux9hemi/dst': Waiting for checks to finish
2025/11/10 05:31:33 DEBUG : one: size = 5 (Local file system at /tmp/rclone1449452982)
2025/11/10 05:31:33 DEBUG : one: size = 3 (files root 'rclone-test-vibawux9hemi/dst')
2025/11/10 05:31:33 DEBUG : one: Sizes differ
2025/11/10 05:31:33 DEBUG : one: size = 5 OK
2025/11/10 05:31:33 DEBUG : one: Size and modification time the same (differ by -123.456789ms, within tolerance 1s)
2025/11/10 05:31:33 DEBUG : one: size = 5 (Local file system at /tmp/rclone1449452982)
2025/11/10 05:31:33 DEBUG : one: size = 3 (files root 'rclone-test-vibawux9hemi/dst')
2025/11/10 05:31:33 DEBUG : one: Sizes differ
2025/11/10 05:31:33 INFO  : one: Moved (server-side)
2025/11/10 05:31:35 DEBUG : one: size = 5 OK
2025/11/10 05:31:35 DEBUG : one: md5 = 07912d142f5d63ee918b34796b5a2432 OK
2025/11/10 05:31:35 INFO  : one: Copied (server-side copy)
2025/11/10 05:31:35 DEBUG : one: Destination found in --copy-dest, using server-side copy
2025/11/10 05:31:35 DEBUG : files root 'rclone-test-vibawux9hemi/dst': Waiting for transfers to finish
2025/11/10 05:31:35 DEBUG : Waiting for deletions to finish
2025/11/10 05:31:37 DEBUG : one: size = 5 OK
2025/11/10 05:31:37 DEBUG : one: Size and modification time the same (differ by -123.456789ms, within tolerance 1s)
2025/11/10 05:31:37 DEBUG : one: Unchanged skipping
2025/11/10 05:31:37 DEBUG : two: size = 3 OK
2025/11/10 05:31:37 DEBUG : two: Size and modification time the same (differ by -123.456789ms, within tolerance 1s)
2025/11/10 05:31:39 DEBUG : two: size = 3 OK
2025/11/10 05:31:39 DEBUG : two: md5 = b8a9f715dbb64fd5c56e7783c6820a61 OK
2025/11/10 05:31:39 INFO  : two: Copied (server-side copy)
2025/11/10 05:31:39 DEBUG : two: Destination found in --copy-dest, using server-side copy
2025/11/10 05:31:39 DEBUG : files root 'rclone-test-vibawux9hemi/dst': Waiting for checks to finish
2025/11/10 05:31:39 DEBUG : files root 'rclone-test-vibawux9hemi/dst': Waiting for transfers to finish
2025/11/10 05:31:39 DEBUG : Waiting for deletions to finish
2025/11/10 05:31:39 DEBUG : one: size = 5 OK
2025/11/10 05:31:39 DEBUG : one: Size and modification time the same (differ by -123.456789ms, within tolerance 1s)
2025/11/10 05:31:39 DEBUG : one: Unchanged skipping
2025/11/10 05:31:39 DEBUG : two: size = 3 OK
2025/11/10 05:31:39 DEBUG : two: Size and modification time the same (differ by -123.456789ms, within tolerance 1s)
2025/11/10 05:31:39 DEBUG : two: Unchanged skipping
2025/11/10 05:31:39 DEBUG : files root 'rclone-test-vibawux9hemi/dst': Waiting for checks to finish
2025/11/10 05:31:39 DEBUG : files root 'rclone-test-vibawux9hemi/dst': Waiting for transfers to finish
2025/11/10 05:31:39 DEBUG : Waiting for deletions to finish
2025/11/10 05:31:39 INFO  : There was nothing to transfer
2025/11/10 05:31:41 DEBUG : one: size = 5 OK
2025/11/10 05:31:41 DEBUG : one: Size and modification time the same (differ by -123.456789ms, within tolerance 1s)
2025/11/10 05:31:41 DEBUG : one: Unchanged skipping
2025/11/10 05:31:41 DEBUG : three: size = 7 (Local file system at /tmp/rclone1449452982)
2025/11/10 05:31:41 DEBUG : three: size = 5 (files root 'rclone-test-vibawux9hemi/CopyDest')
2025/11/10 05:31:41 DEBUG : three: Sizes differ
2025/11/10 05:31:41 DEBUG : three: Destination not found in --copy-dest
2025/11/10 05:31:41 DEBUG : three: Need to transfer - File not found at Destination
2025/11/10 05:31:41 DEBUG : two: size = 3 OK
2025/11/10 05:31:41 DEBUG : files root 'rclone-test-vibawux9hemi/dst': Waiting for checks to finish
2025/11/10 05:31:41 DEBUG : two: Size and modification time the same (differ by -123.456789ms, within tolerance 1s)
2025/11/10 05:31:41 DEBUG : two: Unchanged skipping
2025/11/10 05:31:41 DEBUG : files root 'rclone-test-vibawux9hemi/dst': Waiting for transfers to finish
2025/11/10 05:31:42 DEBUG : three: size = 7 OK
2025/11/10 05:31:42 DEBUG : three: Dst hash empty - aborting Src hash check
2025/11/10 05:31:42 INFO  : three: Copied (new)
2025/11/10 05:31:42 DEBUG : Waiting for deletions to finish
--- PASS: TestSyncCopyDest (19.52s)
=== RUN   TestSyncReplaceDirModTimeWithEmptyDirs
    run.go:185: Remote "files root 'rclone-test-vibawux9hemi'", Local "Local file system at /tmp/rclone1449452982", Modify Window "1s"
2025/11/10 05:31:44 DEBUG : empty_dir: Making directory with metadata
2025/11/10 05:31:44 INFO  : empty_dir: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z)
2025/11/10 05:31:44 DEBUG : empty_on_remote: Making directory with metadata
2025/11/10 05:31:44 INFO  : empty_on_remote: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z)
2025/11/10 05:31:44 INFO  : empty_on_remote: Making directory
2025/11/10 05:31:45 INFO  : empty_on_remote: Made directory with modification time 2011-12-25 12:59:59.123456789 +0000 UTC
2025/11/10 05:31:47 INFO  : test_dir1: Set directory modification time (using DirSetModTime)
2025/11/10 05:31:47 INFO  : test_dir2: Set directory modification time (using DirSetModTime)
2025/11/10 05:31:47 INFO  : test_dir2/sub_dir: Set directory modification time (using DirSetModTime)
2025/11/10 05:31:47 INFO  : empty_on_remote: Set directory modification time (using DirSetModTime)
2025/11/10 05:31:47 INFO  : empty_dir: Set directory modification time (using DirSetModTime)
--- PASS: TestSyncReplaceDirModTimeWithEmptyDirs (7.20s)
PASS
2025/11/10 05:31:52 DEBUG : files root 'rclone-test-vibawux9hemi': Purge remote
"./sync.test -test.v -test.timeout 1h0m0s -remote TestFilesCom: -verbose -test.run '^(TestServerSideCopyOverSelf|TestSyncAfterChangingModtimeOnlyWithNoUpdateModTime|TestSyncCopyDest|TestSyncEmptyDirectories|TestSyncNoEmptyDirectories|TestSyncNoTraverse|TestSyncNoUpdateDirModtime|TestSyncReplaceDirModTimeWithEmptyDirs|TestSyncSetDelayedModTimes)$'" - Finished OK in 1m6.081178637s (try 2/5)