"./sync.test -test.v -test.timeout 1h0m0s -remote TestFilesCom: -verbose" - Starting (try 1/5)
2025/03/10 02:03:48 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-nikesix4yode"
2025/03/10 02:03:48 DEBUG : Using config file from "/home/rclone/.rclone.conf"
2025/03/10 02:03:49 DEBUG : Creating backend with remote "/tmp/rclone391858675"
=== RUN   TestPipe
--- PASS: TestPipe (0.00s)
=== RUN   TestPipeConcurrent
--- PASS: TestPipeConcurrent (0.03s)
=== RUN   TestPipeOrderBy
=== RUN   TestPipeOrderBy/#00
=== RUN   TestPipeOrderBy/size
=== RUN   TestPipeOrderBy/name
=== RUN   TestPipeOrderBy/modtime
=== RUN   TestPipeOrderBy/size,ascending
=== RUN   TestPipeOrderBy/name,asc
=== RUN   TestPipeOrderBy/modtime,ascending
=== RUN   TestPipeOrderBy/size,descending
=== RUN   TestPipeOrderBy/name,desc
=== RUN   TestPipeOrderBy/modtime,descending
=== RUN   TestPipeOrderBy/size,mixed,50
=== RUN   TestPipeOrderBy/size,mixed,51
--- PASS: TestPipeOrderBy (0.00s)
    --- PASS: TestPipeOrderBy/#00 (0.00s)
    --- PASS: TestPipeOrderBy/size (0.00s)
    --- PASS: TestPipeOrderBy/name (0.00s)
    --- PASS: TestPipeOrderBy/modtime (0.00s)
    --- PASS: TestPipeOrderBy/size,ascending (0.00s)
    --- PASS: TestPipeOrderBy/name,asc (0.00s)
    --- PASS: TestPipeOrderBy/modtime,ascending (0.00s)
    --- PASS: TestPipeOrderBy/size,descending (0.00s)
    --- PASS: TestPipeOrderBy/name,desc (0.00s)
    --- PASS: TestPipeOrderBy/modtime,descending (0.00s)
    --- PASS: TestPipeOrderBy/size,mixed,50 (0.00s)
    --- PASS: TestPipeOrderBy/size,mixed,51 (0.00s)
=== RUN   TestNewLess
=== RUN   TestNewLess/blankOK
=== RUN   TestNewLess/tooManyParts
=== RUN   TestNewLess/tooManyParts2
=== RUN   TestNewLess/badMixed
=== RUN   TestNewLess/unknownComparison
=== RUN   TestNewLess/unknownSortDirection
=== RUN   TestNewLess/size
=== RUN   TestNewLess/name
=== RUN   TestNewLess/modtime
=== RUN   TestNewLess/size,ascending
=== RUN   TestNewLess/name,asc
=== RUN   TestNewLess/modtime,ascending
=== RUN   TestNewLess/size,descending
=== RUN   TestNewLess/name,desc
=== RUN   TestNewLess/modtime,descending
=== RUN   TestNewLess/modtime,mixed
=== RUN   TestNewLess/modtime,mixed,30
--- PASS: TestNewLess (0.00s)
    --- PASS: TestNewLess/blankOK (0.00s)
    --- PASS: TestNewLess/tooManyParts (0.00s)
    --- PASS: TestNewLess/tooManyParts2 (0.00s)
    --- PASS: TestNewLess/badMixed (0.00s)
    --- PASS: TestNewLess/unknownComparison (0.00s)
    --- PASS: TestNewLess/unknownSortDirection (0.00s)
    --- PASS: TestNewLess/size (0.00s)
    --- PASS: TestNewLess/name (0.00s)
    --- PASS: TestNewLess/modtime (0.00s)
    --- PASS: TestNewLess/size,ascending (0.00s)
    --- PASS: TestNewLess/name,asc (0.00s)
    --- PASS: TestNewLess/modtime,ascending (0.00s)
    --- PASS: TestNewLess/size,descending (0.00s)
    --- PASS: TestNewLess/name,desc (0.00s)
    --- PASS: TestNewLess/modtime,descending (0.00s)
    --- PASS: TestNewLess/modtime,mixed (0.00s)
    --- PASS: TestNewLess/modtime,mixed,30 (0.00s)
=== RUN   TestRcCopy
    rc_test.go:16: Skipping test on non local remote
--- SKIP: TestRcCopy (0.00s)
=== RUN   TestRcMove
    rc_test.go:16: Skipping test on non local remote
--- SKIP: TestRcMove (0.00s)
=== RUN   TestRcSync
    rc_test.go:16: Skipping test on non local remote
--- SKIP: TestRcSync (0.00s)
=== RUN   TestCopyWithDryRun
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:03:49 DEBUG : Added delayed dir = "sub dir", newDst=<nil>
2025/03/10 02:03:49 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination
2025/03/10 02:03:49 NOTICE: sub dir/hello world: Skipped copy as --dry-run is set (size 11)
2025/03/10 02:03:49 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for checks to finish
2025/03/10 02:03:49 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for transfers to finish
2025/03/10 02:03:49 NOTICE: sub dir: Skipped set directory modification time as --dry-run is set
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
--- PASS: TestCopyWithDryRun (1.28s)
=== RUN   TestCopy
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:03:50 INFO  : sub dir: Set directory modification time (using DirSetModTime)
2025/03/10 02:03:50 DEBUG : Added delayed dir = "sub dir", newDst=<nil>
2025/03/10 02:03:50 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination
2025/03/10 02:03:50 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for checks to finish
2025/03/10 02:03:50 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for transfers to finish
2025/03/10 02:03:51 DEBUG : sub dir/hello world: Dst hash empty - aborting Src hash check
2025/03/10 02:03:51 INFO  : sub dir/hello world: Copied (new)
2025/03/10 02:03:51 INFO  : sub dir: Set directory modification time (using DirSetModTime)
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
--- PASS: TestCopy (2.63s)
=== RUN   TestCopyMetadata
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
    sync_test.go:97: Skipping as metadata not supported
--- SKIP: TestCopyMetadata (0.26s)
=== RUN   TestCopyMetadataNoEmptyDirs
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
    sync_test.go:97: Skipping as metadata not supported
--- SKIP: TestCopyMetadataNoEmptyDirs (0.25s)
=== RUN   TestCopyMissingDirectory
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:03:53 DEBUG : Creating backend with remote "/non-existing"
2025/03/10 02:03:53 ERROR : Local file system at /non-existing: error reading source root directory: directory not found
2025/03/10 02:03:53 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for checks to finish
2025/03/10 02:03:53 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for transfers to finish
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
--- PASS: TestCopyMissingDirectory (0.64s)
=== RUN   TestCopyNoTraverse
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:03:54 DEBUG : Added delayed dir = "sub dir", newDst=<nil>
2025/03/10 02:03:54 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination
2025/03/10 02:03:54 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for checks to finish
2025/03/10 02:03:54 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for transfers to finish
2025/03/10 02:03:55 DEBUG : sub dir/hello world: Dst hash empty - aborting Src hash check
2025/03/10 02:03:55 INFO  : sub dir/hello world: Copied (new)
2025/03/10 02:03:55 INFO  : sub dir: Set directory modification time (using DirSetModTime)
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
--- PASS: TestCopyNoTraverse (2.28s)
=== RUN   TestCopyCheckFirst
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:03:56 INFO  : files root 'rclone-test-nikesix4yode': Running all checks before starting transfers
2025/03/10 02:03:56 DEBUG : Added delayed dir = "sub dir", newDst=<nil>
2025/03/10 02:03:56 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination
2025/03/10 02:03:56 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for checks to finish
2025/03/10 02:03:56 INFO  : files root 'rclone-test-nikesix4yode': Checks finished, now starting transfers
2025/03/10 02:03:56 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for transfers to finish
2025/03/10 02:03:57 DEBUG : sub dir/hello world: Dst hash empty - aborting Src hash check
2025/03/10 02:03:57 INFO  : sub dir/hello world: Copied (new)
2025/03/10 02:03:57 INFO  : sub dir: Set directory modification time (using DirSetModTime)
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
--- PASS: TestCopyCheckFirst (2.29s)
=== RUN   TestSyncNoTraverse
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:03:58 ERROR : Ignoring --no-traverse with sync
2025/03/10 02:03:59 DEBUG : Added delayed dir = "sub dir", newDst=<nil>
2025/03/10 02:03:59 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination
2025/03/10 02:03:59 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for checks to finish
2025/03/10 02:03:59 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for transfers to finish
2025/03/10 02:03:59 DEBUG : sub dir/hello world: Dst hash empty - aborting Src hash check
2025/03/10 02:03:59 INFO  : sub dir/hello world: Copied (new)
2025/03/10 02:03:59 DEBUG : Waiting for deletions to finish
2025/03/10 02:03:59 INFO  : sub dir: Set directory modification time (using DirSetModTime)
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
--- PASS: TestSyncNoTraverse (2.29s)
=== RUN   TestCopyWithDepth
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:04:01 DEBUG : hello world2: Need to transfer - File not found at Destination
2025/03/10 02:04:01 DEBUG : Added delayed dir = "sub dir", newDst=<nil>
2025/03/10 02:04:01 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for checks to finish
2025/03/10 02:04:01 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for transfers to finish
2025/03/10 02:04:02 DEBUG : hello world2: Dst hash empty - aborting Src hash check
2025/03/10 02:04:02 INFO  : hello world2: Copied (new)
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
--- PASS: TestCopyWithDepth (1.65s)
=== RUN   TestCopyWithFilesFrom
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:04:02 DEBUG : potato2: Need to transfer - File not found at Destination
2025/03/10 02:04:02 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for checks to finish
2025/03/10 02:04:02 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for transfers to finish
2025/03/10 02:04:03 DEBUG : potato2: Dst hash empty - aborting Src hash check
2025/03/10 02:04:03 INFO  : potato2: Copied (new)
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
--- PASS: TestCopyWithFilesFrom (1.67s)
=== RUN   TestCopyWithFilesFromAndNoTraverse
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:04:04 DEBUG : potato2: Need to transfer - File not found at Destination
2025/03/10 02:04:04 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for checks to finish
2025/03/10 02:04:04 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for transfers to finish
2025/03/10 02:04:05 DEBUG : potato2: Dst hash empty - aborting Src hash check
2025/03/10 02:04:05 INFO  : potato2: Copied (new)
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
--- PASS: TestCopyWithFilesFromAndNoTraverse (1.71s)
=== RUN   TestCopyEmptyDirectories
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:04:06 DEBUG : sub dir2/sub sub dir2: Making directory with metadata
2025/03/10 02:04:06 INFO  : sub dir2/sub sub dir2: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z)
2025/03/10 02:04:06 INFO  : sub dir2: Set directory modification time (using DirSetModTime)
2025/03/10 02:04:06 INFO  : sub dir: Set directory modification time (using DirSetModTime)
2025/03/10 02:04:06 INFO  : sub dir: Making directory
2025/03/10 02:04:06 INFO  : sub dir: Made directory with modification time 2001-02-03 04:05:06.499999999 +0000 UTC
2025/03/10 02:04:06 DEBUG : Added delayed dir = "sub dir", newDst=<nil>
2025/03/10 02:04:06 INFO  : sub dir2: Making directory
2025/03/10 02:04:06 INFO  : sub dir2: Made directory with modification time 2011-12-25 12:59:59.123456789 +0000 UTC
2025/03/10 02:04:06 DEBUG : Added delayed dir = "sub dir2", newDst=<nil>
2025/03/10 02:04:06 INFO  : sub dir2/sub sub dir2: Making directory
2025/03/10 02:04:06 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination
2025/03/10 02:04:07 INFO  : sub dir2/sub sub dir2: Made directory with modification time 2011-12-25 12:59:59.123456789 +0000 UTC
2025/03/10 02:04:07 DEBUG : Added delayed dir = "sub dir2/sub sub dir2", newDst=<nil>
2025/03/10 02:04:07 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for checks to finish
2025/03/10 02:04:07 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for transfers to finish
2025/03/10 02:04:07 DEBUG : sub dir/hello world: Dst hash empty - aborting Src hash check
2025/03/10 02:04:07 INFO  : sub dir/hello world: Copied (new)
2025/03/10 02:04:07 INFO  : sub dir2/sub sub dir2: Set directory modification time (using DirSetModTime)
2025/03/10 02:04:08 INFO  : sub dir2: Set directory modification time (using DirSetModTime)
2025/03/10 02:04:08 INFO  : sub dir: Set directory modification time (using DirSetModTime)
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
--- PASS: TestCopyEmptyDirectories (3.83s)
=== RUN   TestCopyNoEmptyDirectories
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:04:10 INFO  : sub dir2: Making directory
2025/03/10 02:04:10 DEBUG : sub dir2/sub sub dir2: Making directory with metadata
2025/03/10 02:04:10 INFO  : sub dir2/sub sub dir2: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z)
2025/03/10 02:04:10 DEBUG : Added delayed dir = "sub dir", newDst=<nil>
2025/03/10 02:04:10 DEBUG : Added delayed dir = "sub dir2", newDst=<nil>
2025/03/10 02:04:10 DEBUG : Added delayed dir = "sub dir2/sub sub dir2", newDst=<nil>
2025/03/10 02:04:10 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination
2025/03/10 02:04:10 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for checks to finish
2025/03/10 02:04:10 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for transfers to finish
2025/03/10 02:04:11 DEBUG : sub dir/hello world: Dst hash empty - aborting Src hash check
2025/03/10 02:04:11 INFO  : sub dir/hello world: Copied (new)
2025/03/10 02:04:11 INFO  : sub dir: Set directory modification time (using DirSetModTime)
--- PASS: TestCopyNoEmptyDirectories (2.07s)
=== RUN   TestMoveEmptyDirectories
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:04:12 DEBUG : sub dir2: Making directory with metadata
2025/03/10 02:04:12 INFO  : sub dir2: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z)
2025/03/10 02:04:12 INFO  : sub dir: Making directory
2025/03/10 02:04:12 INFO  : sub dir: Made directory with modification time 2025-03-10 02:04:12.153123525 +0000 UTC
2025/03/10 02:04:12 DEBUG : Added delayed dir = "sub dir", newDst=<nil>
2025/03/10 02:04:12 INFO  : sub dir2: Making directory
2025/03/10 02:04:12 INFO  : sub dir2: Made directory with modification time 2011-12-25 12:59:59.123456789 +0000 UTC
2025/03/10 02:04:12 DEBUG : Added delayed dir = "sub dir2", newDst=<nil>
2025/03/10 02:04:12 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination
2025/03/10 02:04:12 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for checks to finish
2025/03/10 02:04:12 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for transfers to finish
2025/03/10 02:04:13 DEBUG : sub dir/hello world: Dst hash empty - aborting Src hash check
2025/03/10 02:04:13 INFO  : sub dir/hello world: Copied (new)
2025/03/10 02:04:13 INFO  : sub dir/hello world: Deleted
2025/03/10 02:04:13 INFO  : sub dir2: Set directory modification time (using DirSetModTime)
2025/03/10 02:04:13 INFO  : sub dir: Set directory modification time (using DirSetModTime)
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
--- PASS: TestMoveEmptyDirectories (3.31s)
=== RUN   TestSyncNoUpdateDirModtime
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:04:15 DEBUG : sub dir no update dir modtime: Making directory with metadata
2025/03/10 02:04:15 INFO  : sub dir no update dir modtime: Made directory with metadata (mtime=2001-02-03T04:05:06.499999999Z)
2025/03/10 02:04:16 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for checks to finish
2025/03/10 02:04:16 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for transfers to finish
2025/03/10 02:04:16 DEBUG : Waiting for deletions to finish
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
--- PASS: TestSyncNoUpdateDirModtime (1.78s)
=== RUN   TestMoveNoEmptyDirectories
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:04:17 INFO  : sub dir2: Making directory
2025/03/10 02:04:17 DEBUG : Added delayed dir = "sub dir", newDst=<nil>
2025/03/10 02:04:17 DEBUG : Added delayed dir = "sub dir2", newDst=<nil>
2025/03/10 02:04:17 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination
2025/03/10 02:04:17 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for checks to finish
2025/03/10 02:04:17 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for transfers to finish
2025/03/10 02:04:18 DEBUG : sub dir/hello world: Dst hash empty - aborting Src hash check
2025/03/10 02:04:18 INFO  : sub dir/hello world: Copied (new)
2025/03/10 02:04:18 INFO  : sub dir/hello world: Deleted
2025/03/10 02:04:18 INFO  : sub dir: Set directory modification time (using DirSetModTime)
--- PASS: TestMoveNoEmptyDirectories (2.03s)
=== RUN   TestSyncEmptyDirectories
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:04:19 DEBUG : sub dir2: Making directory with metadata
2025/03/10 02:04:19 INFO  : sub dir2: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z)
2025/03/10 02:04:19 INFO  : sub dir: Set directory modification time (using DirSetModTime)
2025/03/10 02:04:19 INFO  : sub dir: Making directory
2025/03/10 02:04:19 INFO  : sub dir: Made directory with modification time 2001-02-03 04:05:06.499999999 +0000 UTC
2025/03/10 02:04:19 INFO  : sub dir2: Making directory
2025/03/10 02:04:19 INFO  : sub dir2: Made directory with modification time 2011-12-25 12:59:59.123456789 +0000 UTC
2025/03/10 02:04:19 DEBUG : Added delayed dir = "sub dir2", newDst=<nil>
2025/03/10 02:04:19 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination
2025/03/10 02:04:19 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for checks to finish
2025/03/10 02:04:19 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for transfers to finish
2025/03/10 02:04:20 DEBUG : sub dir/hello world: Dst hash empty - aborting Src hash check
2025/03/10 02:04:20 INFO  : sub dir/hello world: Copied (new)
2025/03/10 02:04:20 ERROR : files root 'rclone-test-nikesix4yode': not deleting files as there were IO errors
2025/03/10 02:04:20 INFO  : sub dir2: Set directory modification time (using DirSetModTime)
2025/03/10 02:04:20 ERROR : files root 'rclone-test-nikesix4yode': not deleting directories as there were IO errors
    sync_test.go:483: 
        	Error Trace:	/home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync_test.go:483
        	Error:      	Received unexpected error:
        	            	Not Found - `Not Found.  This may be related to your permissions.`
        	Test:       	TestSyncEmptyDirectories
--- FAIL: TestSyncEmptyDirectories (2.49s)
=== RUN   TestSyncSetDelayedModTimes
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:04:21 INFO  : a1/b2/c1/d1/e1/f1: Set directory modification time (using DirSetModTime)
2025/03/10 02:04:21 INFO  : a1/b2/c1/d1/e1: Set directory modification time (using DirSetModTime)
2025/03/10 02:04:21 INFO  : a1/b2/c1/d1: Set directory modification time (using DirSetModTime)
2025/03/10 02:04:21 INFO  : a1/b2/c1: Set directory modification time (using DirSetModTime)
2025/03/10 02:04:21 INFO  : a1/b2: Set directory modification time (using DirSetModTime)
2025/03/10 02:04:21 INFO  : a1/b1/c1/d2/e1/f2: Set directory modification time (using DirSetModTime)
2025/03/10 02:04:21 INFO  : a1/b1/c1/d2/e1/f1: Set directory modification time (using DirSetModTime)
2025/03/10 02:04:21 INFO  : a1/b1/c1/d2/e1: Set directory modification time (using DirSetModTime)
2025/03/10 02:04:21 INFO  : a1/b1/c1/d2: Set directory modification time (using DirSetModTime)
2025/03/10 02:04:21 INFO  : a1/b1/c1/d1/e1/f1: Set directory modification time (using DirSetModTime)
2025/03/10 02:04:21 INFO  : a1/b1/c1/d1/e1: Set directory modification time (using DirSetModTime)
2025/03/10 02:04:21 INFO  : a1/b1/c1/d1: Set directory modification time (using DirSetModTime)
2025/03/10 02:04:21 INFO  : a1/b1/c1: Set directory modification time (using DirSetModTime)
2025/03/10 02:04:21 INFO  : a1/b1: Set directory modification time (using DirSetModTime)
2025/03/10 02:04:21 INFO  : a1: Set directory modification time (using DirSetModTime)
2025/03/10 02:04:21 INFO  : a1: Making directory
2025/03/10 02:04:22 INFO  : a1: Made directory with modification time 2001-02-03 04:19:06.499999999 +0000 UTC
2025/03/10 02:04:22 DEBUG : Added delayed dir = "a1", newDst=<nil>
2025/03/10 02:04:22 INFO  : a1/b1: Making directory
2025/03/10 02:04:22 INFO  : a1/b1: Made directory with modification time 2001-02-03 04:18:06.499999999 +0000 UTC
2025/03/10 02:04:22 DEBUG : Added delayed dir = "a1/b1", newDst=<nil>
2025/03/10 02:04:22 INFO  : a1/b2: Making directory
2025/03/10 02:04:22 INFO  : a1/b2: Made directory with modification time 2001-02-03 04:09:06.499999999 +0000 UTC
2025/03/10 02:04:22 DEBUG : Added delayed dir = "a1/b2", newDst=<nil>
2025/03/10 02:04:22 INFO  : a1/b2/c1: Making directory
2025/03/10 02:04:22 INFO  : a1/b1/c1: Making directory
2025/03/10 02:04:23 INFO  : a1/b2/c1: Made directory with modification time 2001-02-03 04:08:06.499999999 +0000 UTC
2025/03/10 02:04:23 DEBUG : Added delayed dir = "a1/b2/c1", newDst=<nil>
2025/03/10 02:04:23 INFO  : a1/b2/c1/d1: Making directory
2025/03/10 02:04:23 INFO  : a1/b1/c1: Made directory with modification time 2001-02-03 04:17:06.499999999 +0000 UTC
2025/03/10 02:04:23 DEBUG : Added delayed dir = "a1/b1/c1", newDst=<nil>
2025/03/10 02:04:23 INFO  : a1/b1/c1/d1: Making directory
2025/03/10 02:04:23 INFO  : a1/b2/c1/d1: Made directory with modification time 2001-02-03 04:07:06.499999999 +0000 UTC
2025/03/10 02:04:23 DEBUG : Added delayed dir = "a1/b2/c1/d1", newDst=<nil>
2025/03/10 02:04:23 INFO  : a1/b2/c1/d1/e1: Making directory
2025/03/10 02:04:23 INFO  : a1/b1/c1/d1: Made directory with modification time 2001-02-03 04:16:06.499999999 +0000 UTC
2025/03/10 02:04:23 DEBUG : Added delayed dir = "a1/b1/c1/d1", newDst=<nil>
2025/03/10 02:04:23 INFO  : a1/b1/c1/d2: Making directory
2025/03/10 02:04:23 INFO  : a1/b2/c1/d1/e1: Made directory with modification time 2001-02-03 04:06:06.499999999 +0000 UTC
2025/03/10 02:04:23 DEBUG : Added delayed dir = "a1/b2/c1/d1/e1", newDst=<nil>
2025/03/10 02:04:23 INFO  : a1/b2/c1/d1/e1/f1: Making directory
2025/03/10 02:04:23 INFO  : a1/b1/c1/d2: Made directory with modification time 2001-02-03 04:13:06.499999999 +0000 UTC
2025/03/10 02:04:23 DEBUG : Added delayed dir = "a1/b1/c1/d2", newDst=<nil>
2025/03/10 02:04:23 INFO  : a1/b1/c1/d2/e1: Making directory
2025/03/10 02:04:23 INFO  : a1/b1/c1/d1/e1: Making directory
2025/03/10 02:04:24 INFO  : a1/b2/c1/d1/e1/f1: Made directory with modification time 2001-02-03 04:05:06.499999999 +0000 UTC
2025/03/10 02:04:24 DEBUG : Added delayed dir = "a1/b2/c1/d1/e1/f1", newDst=<nil>
2025/03/10 02:04:24 INFO  : a1/b1/c1/d2/e1: Made directory with modification time 2001-02-03 04:12:06.499999999 +0000 UTC
2025/03/10 02:04:24 DEBUG : Added delayed dir = "a1/b1/c1/d2/e1", newDst=<nil>
2025/03/10 02:04:24 INFO  : a1/b1/c1/d2/e1/f1: Making directory
2025/03/10 02:04:24 INFO  : a1/b1/c1/d1/e1: Made directory with modification time 2001-02-03 04:15:06.499999999 +0000 UTC
2025/03/10 02:04:24 DEBUG : Added delayed dir = "a1/b1/c1/d1/e1", newDst=<nil>
2025/03/10 02:04:24 INFO  : a1/b1/c1/d1/e1/f1: Making directory
2025/03/10 02:04:24 INFO  : a1/b1/c1/d2/e1/f1: Made directory with modification time 2001-02-03 04:11:06.499999999 +0000 UTC
2025/03/10 02:04:24 DEBUG : Added delayed dir = "a1/b1/c1/d2/e1/f1", newDst=<nil>
2025/03/10 02:04:24 INFO  : a1/b1/c1/d2/e1/f2: Making directory
2025/03/10 02:04:24 INFO  : a1/b1/c1/d1/e1/f1: Made directory with modification time 2001-02-03 04:14:06.499999999 +0000 UTC
2025/03/10 02:04:24 DEBUG : Added delayed dir = "a1/b1/c1/d1/e1/f1", newDst=<nil>
2025/03/10 02:04:24 INFO  : a1/b1/c1/d2/e1/f2: Made directory with modification time 2001-02-03 04:10:06.499999999 +0000 UTC
2025/03/10 02:04:24 DEBUG : Added delayed dir = "a1/b1/c1/d2/e1/f2", newDst=<nil>
2025/03/10 02:04:24 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for checks to finish
2025/03/10 02:04:24 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for transfers to finish
2025/03/10 02:04:24 DEBUG : Waiting for deletions to finish
2025/03/10 02:04:24 INFO  : a1/b1/c1/d2/e1/f2: Set directory modification time (using DirSetModTime)
2025/03/10 02:04:24 INFO  : a1/b2/c1/d1/e1/f1: Set directory modification time (using DirSetModTime)
2025/03/10 02:04:24 INFO  : a1/b1/c1/d2/e1/f1: Set directory modification time (using DirSetModTime)
2025/03/10 02:04:25 INFO  : a1/b1/c1/d1/e1/f1: Set directory modification time (using DirSetModTime)
2025/03/10 02:04:25 INFO  : a1/b1/c1/d1/e1: Set directory modification time (using DirSetModTime)
2025/03/10 02:04:25 INFO  : a1/b2/c1/d1/e1: Set directory modification time (using DirSetModTime)
2025/03/10 02:04:25 INFO  : a1/b1/c1/d2/e1: Set directory modification time (using DirSetModTime)
2025/03/10 02:04:25 INFO  : a1/b1/c1/d2: Set directory modification time (using DirSetModTime)
2025/03/10 02:04:25 INFO  : a1/b2/c1/d1: Set directory modification time (using DirSetModTime)
2025/03/10 02:04:25 INFO  : a1/b1/c1/d1: Set directory modification time (using DirSetModTime)
2025/03/10 02:04:25 INFO  : a1/b1/c1: Set directory modification time (using DirSetModTime)
2025/03/10 02:04:25 INFO  : a1/b2/c1: Set directory modification time (using DirSetModTime)
2025/03/10 02:04:25 INFO  : a1/b2: Set directory modification time (using DirSetModTime)
2025/03/10 02:04:25 INFO  : a1/b1: Set directory modification time (using DirSetModTime)
2025/03/10 02:04:25 INFO  : a1: Set directory modification time (using DirSetModTime)
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:04:29 DEBUG : pacer: low level retry 1/10 (error Folder Not Empty - `Folder rclone-test-nikesix4yode/a1/b2/c1/d1/e1 not empty`)
2025/03/10 02:04:29 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2025/03/10 02:04:30 DEBUG : pacer: low level retry 2/10 (error Folder Not Empty - `Folder rclone-test-nikesix4yode/a1/b2/c1/d1/e1 not empty`)
2025/03/10 02:04:30 DEBUG : pacer: Rate limited, increasing sleep to 40ms
2025/03/10 02:04:30 DEBUG : pacer: low level retry 3/10 (error Folder Not Empty - `Folder rclone-test-nikesix4yode/a1/b2/c1/d1/e1 not empty`)
2025/03/10 02:04:30 DEBUG : pacer: Rate limited, increasing sleep to 80ms
2025/03/10 02:04:30 DEBUG : pacer: low level retry 4/10 (error Folder Not Empty - `Folder rclone-test-nikesix4yode/a1/b2/c1/d1/e1 not empty`)
2025/03/10 02:04:30 DEBUG : pacer: Rate limited, increasing sleep to 160ms
2025/03/10 02:04:30 DEBUG : pacer: low level retry 5/10 (error Folder Not Empty - `Folder rclone-test-nikesix4yode/a1/b2/c1/d1/e1 not empty`)
2025/03/10 02:04:30 DEBUG : pacer: Rate limited, increasing sleep to 320ms
2025/03/10 02:04:30 DEBUG : pacer: low level retry 6/10 (error Folder Not Empty - `Folder rclone-test-nikesix4yode/a1/b2/c1/d1/e1 not empty`)
2025/03/10 02:04:30 DEBUG : pacer: Rate limited, increasing sleep to 640ms
2025/03/10 02:04:30 DEBUG : pacer: Reducing sleep to 480ms
2025/03/10 02:04:31 DEBUG : pacer: Reducing sleep to 360ms
2025/03/10 02:04:31 DEBUG : pacer: low level retry 1/10 (error Folder Not Empty - `Folder rclone-test-nikesix4yode/a1/b2/c1 not empty`)
2025/03/10 02:04:31 DEBUG : pacer: Rate limited, increasing sleep to 720ms
2025/03/10 02:04:32 DEBUG : pacer: low level retry 2/10 (error Folder Not Empty - `Folder rclone-test-nikesix4yode/a1/b2/c1 not empty`)
2025/03/10 02:04:32 DEBUG : pacer: Rate limited, increasing sleep to 1.44s
2025/03/10 02:04:33 DEBUG : pacer: Reducing sleep to 1.08s
2025/03/10 02:04:34 DEBUG : pacer: Reducing sleep to 810ms
2025/03/10 02:04:35 DEBUG : pacer: Reducing sleep to 607.5ms
2025/03/10 02:04:36 DEBUG : pacer: Reducing sleep to 455.625ms
2025/03/10 02:04:37 DEBUG : pacer: Reducing sleep to 341.71875ms
2025/03/10 02:04:37 DEBUG : pacer: Reducing sleep to 256.289062ms
2025/03/10 02:04:37 DEBUG : pacer: Reducing sleep to 192.216796ms
2025/03/10 02:04:38 DEBUG : pacer: Reducing sleep to 144.162597ms
2025/03/10 02:04:38 DEBUG : pacer: low level retry 1/10 (error Folder Not Empty - `Folder rclone-test-nikesix4yode/a1/b1/c1/d1 not empty`)
2025/03/10 02:04:38 DEBUG : pacer: Rate limited, increasing sleep to 288.325194ms
2025/03/10 02:04:38 DEBUG : pacer: Reducing sleep to 216.243895ms
2025/03/10 02:04:38 DEBUG : pacer: Reducing sleep to 162.182921ms
2025/03/10 02:04:38 DEBUG : pacer: Reducing sleep to 121.63719ms
2025/03/10 02:04:39 DEBUG : pacer: low level retry 1/10 (error Folder Not Empty - `Folder rclone-test-nikesix4yode/a1 not empty`)
2025/03/10 02:04:39 DEBUG : pacer: Rate limited, increasing sleep to 243.27438ms
2025/03/10 02:04:39 DEBUG : pacer: low level retry 2/10 (error Folder Not Empty - `Folder rclone-test-nikesix4yode/a1 not empty`)
2025/03/10 02:04:39 DEBUG : pacer: Rate limited, increasing sleep to 486.54876ms
2025/03/10 02:04:39 DEBUG : pacer: Reducing sleep to 364.91157ms
2025/03/10 02:04:39 DEBUG : pacer: Reducing sleep to 273.683677ms
2025/03/10 02:04:40 DEBUG : pacer: Reducing sleep to 205.262757ms
2025/03/10 02:04:40 DEBUG : pacer: Reducing sleep to 153.947067ms
--- PASS: TestSyncSetDelayedModTimes (18.82s)
=== RUN   TestSyncNoEmptyDirectories
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:04:40 INFO  : sub dir2: Making directory
2025/03/10 02:04:40 DEBUG : pacer: Reducing sleep to 115.4603ms
2025/03/10 02:04:40 DEBUG : Added delayed dir = "sub dir", newDst=<nil>
2025/03/10 02:04:40 DEBUG : Added delayed dir = "sub dir2", newDst=<nil>
2025/03/10 02:04:40 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination
2025/03/10 02:04:40 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for checks to finish
2025/03/10 02:04:40 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for transfers to finish
2025/03/10 02:04:41 DEBUG : pacer: Reducing sleep to 86.595225ms
2025/03/10 02:04:41 DEBUG : pacer: Reducing sleep to 64.946418ms
2025/03/10 02:04:41 DEBUG : sub dir/hello world: Dst hash empty - aborting Src hash check
2025/03/10 02:04:41 INFO  : sub dir/hello world: Copied (new)
2025/03/10 02:04:41 DEBUG : Waiting for deletions to finish
2025/03/10 02:04:41 DEBUG : pacer: Reducing sleep to 48.709813ms
2025/03/10 02:04:41 INFO  : sub dir: Set directory modification time (using DirSetModTime)
2025/03/10 02:04:41 DEBUG : pacer: Reducing sleep to 36.532359ms
2025/03/10 02:04:42 DEBUG : pacer: Reducing sleep to 27.399269ms
2025/03/10 02:04:42 DEBUG : pacer: Reducing sleep to 20.549451ms
2025/03/10 02:04:42 DEBUG : pacer: Reducing sleep to 15.412088ms
2025/03/10 02:04:42 DEBUG : pacer: Reducing sleep to 11.559066ms
2025/03/10 02:04:42 DEBUG : pacer: Reducing sleep to 10ms
--- PASS: TestSyncNoEmptyDirectories (2.37s)
=== RUN   TestServerSideCopy
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:04:43 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-vagetek9cani"
    sync_test.go:590: Server side copy (if possible) files root 'rclone-test-nikesix4yode' -> files root 'rclone-test-vagetek9cani'
2025/03/10 02:04:45 DEBUG : Added delayed dir = "sub dir", newDst=<nil>
2025/03/10 02:04:45 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination
2025/03/10 02:04:45 DEBUG : files root 'rclone-test-vagetek9cani': Waiting for checks to finish
2025/03/10 02:04:45 DEBUG : files root 'rclone-test-vagetek9cani': Waiting for transfers to finish
2025/03/10 02:04:47 DEBUG : sub dir/hello world: Dst hash empty - aborting Src hash check
2025/03/10 02:04:47 DEBUG : sub dir/hello world: Src hash empty - aborting Dst hash check
2025/03/10 02:04:47 INFO  : sub dir/hello world: Copied (server-side copy)
2025/03/10 02:04:47 INFO  : sub dir: Set directory modification time (using DirSetModTime)
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:04:48 DEBUG : files root 'rclone-test-vagetek9cani': Purge remote
--- PASS: TestServerSideCopy (6.40s)
=== RUN   TestCopyOverSelf
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:04:50 DEBUG : sub dir: Directory modification time the same (differ by -632.839162ms, within tolerance 1s)
2025/03/10 02:04:50 DEBUG : Added delayed dir = "sub dir", newDst=sub dir
2025/03/10 02:04:50 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for checks to finish
2025/03/10 02:04:50 DEBUG : sub dir/hello world: Sizes differ (src 17 vs dst 11)
2025/03/10 02:04:50 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for transfers to finish
2025/03/10 02:04:51 DEBUG : sub dir/hello world: Dst hash empty - aborting Src hash check
2025/03/10 02:04:51 INFO  : sub dir/hello world: Copied (replaced existing)
2025/03/10 02:04:51 INFO  : sub dir: Set directory modification time (using DirSetModTime)
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
--- PASS: TestCopyOverSelf (3.65s)
=== RUN   TestServerSideCopyOverSelf
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:04:54 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-gidezoj1niji"
    sync_test.go:626: Server side copy (if possible) files root 'rclone-test-nikesix4yode' -> files root 'rclone-test-gidezoj1niji'
2025/03/10 02:04:55 DEBUG : Added delayed dir = "sub dir", newDst=<nil>
2025/03/10 02:04:55 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination
2025/03/10 02:04:55 DEBUG : files root 'rclone-test-gidezoj1niji': Waiting for checks to finish
2025/03/10 02:04:55 DEBUG : files root 'rclone-test-gidezoj1niji': Waiting for transfers to finish
2025/03/10 02:04:57 DEBUG : sub dir/hello world: Dst hash empty - aborting Src hash check
2025/03/10 02:04:57 DEBUG : sub dir/hello world: Src hash empty - aborting Dst hash check
2025/03/10 02:04:57 INFO  : sub dir/hello world: Copied (server-side copy)
2025/03/10 02:04:57 INFO  : sub dir: Set directory modification time (using DirSetModTime)
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:04:59 INFO  : sub dir: Set directory modification time (using DirSetModTime)
2025/03/10 02:04:59 DEBUG : Added delayed dir = "sub dir", newDst=sub dir
2025/03/10 02:04:59 DEBUG : sub dir/hello world: Sizes differ (src 17 vs dst 11)
2025/03/10 02:04:59 DEBUG : files root 'rclone-test-gidezoj1niji': Waiting for checks to finish
2025/03/10 02:04:59 DEBUG : files root 'rclone-test-gidezoj1niji': Waiting for transfers to finish
2025/03/10 02:05:01 DEBUG : sub dir/hello world: Dst hash empty - aborting Src hash check
2025/03/10 02:05:01 DEBUG : sub dir/hello world: Src hash empty - aborting Dst hash check
2025/03/10 02:05:01 INFO  : sub dir/hello world: Copied (server-side copy)
2025/03/10 02:05:01 INFO  : sub dir: Set directory modification time (using DirSetModTime)
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:05:01 DEBUG : files root 'rclone-test-gidezoj1niji': Purge remote
--- PASS: TestServerSideCopyOverSelf (10.12s)
=== RUN   TestMoveOverSelf
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:05:04 INFO  : sub dir: Set directory modification time (using DirSetModTime)
2025/03/10 02:05:04 DEBUG : Added delayed dir = "sub dir", newDst=sub dir
2025/03/10 02:05:04 DEBUG : sub dir/hello world: Sizes differ (src 17 vs dst 11)
2025/03/10 02:05:04 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for checks to finish
2025/03/10 02:05:04 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for transfers to finish
2025/03/10 02:05:05 DEBUG : sub dir/hello world: Dst hash empty - aborting Src hash check
2025/03/10 02:05:05 INFO  : sub dir/hello world: Copied (replaced existing)
2025/03/10 02:05:05 INFO  : sub dir/hello world: Deleted
2025/03/10 02:05:05 INFO  : sub dir: Set directory modification time (using DirSetModTime)
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
--- PASS: TestMoveOverSelf (3.75s)
=== RUN   TestServerSideMoveOverSelf
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:05:07 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-bevoyuk2humu"
    sync_test.go:671: Server side copy (if possible) files root 'rclone-test-nikesix4yode' -> files root 'rclone-test-bevoyuk2humu'
2025/03/10 02:05:08 DEBUG : Added delayed dir = "sub dir", newDst=<nil>
2025/03/10 02:05:08 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination
2025/03/10 02:05:08 DEBUG : files root 'rclone-test-bevoyuk2humu': Waiting for checks to finish
2025/03/10 02:05:08 DEBUG : files root 'rclone-test-bevoyuk2humu': Waiting for transfers to finish
2025/03/10 02:05:11 DEBUG : sub dir/hello world: Dst hash empty - aborting Src hash check
2025/03/10 02:05:11 DEBUG : sub dir/hello world: Src hash empty - aborting Dst hash check
2025/03/10 02:05:11 INFO  : sub dir/hello world: Copied (server-side copy)
2025/03/10 02:05:11 INFO  : sub dir: Set directory modification time (using DirSetModTime)
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:05:12 DEBUG : files root 'rclone-test-bevoyuk2humu': Using server-side directory move
2025/03/10 02:05:12 INFO  : files root 'rclone-test-bevoyuk2humu': Server side directory move failed - fallback to file moves: can't copy directory - destination already exists
2025/03/10 02:05:13 INFO  : sub dir: Set directory modification time (using DirSetModTime)
2025/03/10 02:05:13 DEBUG : Added delayed dir = "sub dir", newDst=sub dir
2025/03/10 02:05:13 DEBUG : sub dir/hello world: Sizes differ (src 17 vs dst 11)
2025/03/10 02:05:13 DEBUG : files root 'rclone-test-bevoyuk2humu': Waiting for checks to finish
2025/03/10 02:05:13 DEBUG : files root 'rclone-test-bevoyuk2humu': Waiting for transfers to finish
2025/03/10 02:05:13 INFO  : sub dir/hello world: Deleted
2025/03/10 02:05:14 INFO  : sub dir/hello world: Moved (server-side)
2025/03/10 02:05:14 INFO  : sub dir: Set directory modification time (using DirSetModTime)
2025/03/10 02:05:15 DEBUG : testing file moves
2025/03/10 02:05:16 INFO  : sub dir: Set directory modification time (using DirSetModTime)
2025/03/10 02:05:16 DEBUG : Added delayed dir = "sub dir", newDst=sub dir
2025/03/10 02:05:16 DEBUG : files root 'rclone-test-bevoyuk2humu': Waiting for checks to finish
2025/03/10 02:05:16 DEBUG : sub dir/hello world: Sizes differ (src 24 vs dst 17)
2025/03/10 02:05:16 DEBUG : files root 'rclone-test-bevoyuk2humu': Waiting for transfers to finish
2025/03/10 02:05:16 INFO  : sub dir/hello world: Deleted
2025/03/10 02:05:16 INFO  : sub dir/hello world: Moved (server-side)
2025/03/10 02:05:17 INFO  : sub dir: Set directory modification time (using DirSetModTime)
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:05:17 DEBUG : files root 'rclone-test-bevoyuk2humu': Purge remote
--- PASS: TestServerSideMoveOverSelf (11.95s)
=== RUN   TestCopyAfterDelete
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:05:19 ERROR : : error listing: directory not found
2025/03/10 02:05:19 INFO  : Local file system at /tmp/rclone391858675: Making directory
2025/03/10 02:05:20 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for checks to finish
2025/03/10 02:05:20 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for transfers to finish
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
--- PASS: TestCopyAfterDelete (2.53s)
=== RUN   TestCopyRedownload
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:05:22 DEBUG : Added delayed dir = "sub dir", newDst=<nil>
2025/03/10 02:05:22 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination
2025/03/10 02:05:22 DEBUG : Local file system at /tmp/rclone391858675: Waiting for checks to finish
2025/03/10 02:05:22 DEBUG : Local file system at /tmp/rclone391858675: Waiting for transfers to finish
2025/03/10 02:05:23 DEBUG : sub dir/hello world: Src hash empty - aborting Dst hash check
2025/03/10 02:05:23 DEBUG : sub dir/hello world.9e820094.partial: renamed to: sub dir/hello world
2025/03/10 02:05:23 INFO  : sub dir/hello world: Copied (new)
2025/03/10 02:05:23 INFO  : sub dir: Set directory modification time (using DirSetModTime)
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
--- PASS: TestCopyRedownload (2.77s)
=== RUN   TestSyncBasedOnCheckSum
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:05:24 DEBUG : check sum: Need to transfer - File not found at Destination
2025/03/10 02:05:24 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for checks to finish
2025/03/10 02:05:24 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for transfers to finish
2025/03/10 02:05:24 DEBUG : check sum: Dst hash empty - aborting Src hash check
2025/03/10 02:05:24 INFO  : check sum: Copied (new)
2025/03/10 02:05:24 DEBUG : Waiting for deletions to finish
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:05:25 DEBUG : check sum: Dst hash empty - aborting Src hash check
2025/03/10 02:05:25 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for checks to finish
2025/03/10 02:05:25 DEBUG : check sum: Size of src and dst objects identical
2025/03/10 02:05:25 DEBUG : check sum: Unchanged skipping
2025/03/10 02:05:25 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for transfers to finish
2025/03/10 02:05:25 DEBUG : Waiting for deletions to finish
2025/03/10 02:05:25 INFO  : There was nothing to transfer
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
--- PASS: TestSyncBasedOnCheckSum (2.16s)
=== RUN   TestSyncSizeOnly
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:05:26 DEBUG : sizeonly: Need to transfer - File not found at Destination
2025/03/10 02:05:26 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for checks to finish
2025/03/10 02:05:26 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for transfers to finish
2025/03/10 02:05:30 DEBUG : sizeonly: Dst hash empty - aborting Src hash check
2025/03/10 02:05:30 INFO  : sizeonly: Copied (new)
2025/03/10 02:05:30 DEBUG : Waiting for deletions to finish
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:05:30 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for checks to finish
2025/03/10 02:05:30 DEBUG : sizeonly: Sizes identical
2025/03/10 02:05:30 DEBUG : sizeonly: Unchanged skipping
2025/03/10 02:05:30 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for transfers to finish
2025/03/10 02:05:30 DEBUG : Waiting for deletions to finish
2025/03/10 02:05:30 INFO  : There was nothing to transfer
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
--- PASS: TestSyncSizeOnly (5.58s)
=== RUN   TestSyncIgnoreSize
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:05:31 DEBUG : ignore-size: Need to transfer - File not found at Destination
2025/03/10 02:05:31 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for checks to finish
2025/03/10 02:05:31 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for transfers to finish
2025/03/10 02:05:32 DEBUG : ignore-size: Dst hash empty - aborting Src hash check
2025/03/10 02:05:32 INFO  : ignore-size: Copied (new)
2025/03/10 02:05:32 DEBUG : Waiting for deletions to finish
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:05:32 DEBUG : ignore-size: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/03/10 02:05:32 DEBUG : ignore-size: Unchanged skipping
2025/03/10 02:05:32 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for checks to finish
2025/03/10 02:05:32 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for transfers to finish
2025/03/10 02:05:32 DEBUG : Waiting for deletions to finish
2025/03/10 02:05:32 INFO  : There was nothing to transfer
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
--- PASS: TestSyncIgnoreSize (2.15s)
=== RUN   TestSyncIgnoreTimes
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:05:35 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for checks to finish
2025/03/10 02:05:35 DEBUG : existing: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/03/10 02:05:35 DEBUG : existing: Unchanged skipping
2025/03/10 02:05:35 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for transfers to finish
2025/03/10 02:05:35 DEBUG : Waiting for deletions to finish
2025/03/10 02:05:35 INFO  : There was nothing to transfer
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:05:35 DEBUG : existing: Transferring unconditionally as --ignore-times is in use
2025/03/10 02:05:35 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for checks to finish
2025/03/10 02:05:35 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for transfers to finish
2025/03/10 02:05:35 DEBUG : existing: Dst hash empty - aborting Src hash check
2025/03/10 02:05:35 INFO  : existing: Copied (replaced existing)
2025/03/10 02:05:35 DEBUG : Waiting for deletions to finish
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
--- PASS: TestSyncIgnoreTimes (2.92s)
=== RUN   TestSyncIgnoreExisting
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:05:37 DEBUG : existing: Need to transfer - File not found at Destination
2025/03/10 02:05:37 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for checks to finish
2025/03/10 02:05:37 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for transfers to finish
2025/03/10 02:05:37 DEBUG : existing: Dst hash empty - aborting Src hash check
2025/03/10 02:05:37 INFO  : existing: Copied (new)
2025/03/10 02:05:37 DEBUG : Waiting for deletions to finish
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:05:38 DEBUG : existing: Destination exists, skipping
2025/03/10 02:05:38 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for checks to finish
2025/03/10 02:05:38 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for transfers to finish
2025/03/10 02:05:38 DEBUG : Waiting for deletions to finish
2025/03/10 02:05:38 INFO  : There was nothing to transfer
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
--- PASS: TestSyncIgnoreExisting (2.18s)
=== RUN   TestSyncIgnoreErrors
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:05:40 INFO  : d: Making directory
2025/03/10 02:05:41 DEBUG : Added delayed dir = "a", newDst=<nil>
2025/03/10 02:05:41 DEBUG : c: Directory modification time the same (differ by 139.523484ms, within tolerance 1s)
2025/03/10 02:05:41 DEBUG : Added delayed dir = "c", newDst=c
2025/03/10 02:05:41 DEBUG : a/potato2: Need to transfer - File not found at Destination
2025/03/10 02:05:41 DEBUG : c/non empty space: Size and modification time the same (differ by -123.456789ms, within tolerance 1s)
2025/03/10 02:05:41 DEBUG : c/non empty space: Unchanged skipping
2025/03/10 02:05:41 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for checks to finish
2025/03/10 02:05:41 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for transfers to finish
2025/03/10 02:05:42 DEBUG : a/potato2: Dst hash empty - aborting Src hash check
2025/03/10 02:05:42 INFO  : a/potato2: Copied (new)
2025/03/10 02:05:42 DEBUG : Waiting for deletions to finish
2025/03/10 02:05:42 INFO  : b/potato: Deleted
2025/03/10 02:05:42 INFO  : a: Set directory modification time (using DirSetModTime)
2025/03/10 02:05:42 INFO  : d: Removing directory
2025/03/10 02:05:42 INFO  : b: Removing directory
2025/03/10 02:05:42 DEBUG : files root 'rclone-test-nikesix4yode': deleted 2 directories
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
--- PASS: TestSyncIgnoreErrors (5.17s)
=== RUN   TestSyncAfterChangingModtimeOnly
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:05:45 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for checks to finish
2025/03/10 02:05:45 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/03/10 02:05:45 DEBUG : empty space: Dst hash empty - aborting Src hash check
2025/03/10 02:05:45 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for transfers to finish
2025/03/10 02:05:45 NOTICE: empty space: Skipped copy as --dry-run is set (size 1)
2025/03/10 02:05:45 DEBUG : Waiting for deletions to finish
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:05:45 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/03/10 02:05:45 DEBUG : empty space: Dst hash empty - aborting Src hash check
2025/03/10 02:05:45 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for checks to finish
2025/03/10 02:05:45 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for transfers to finish
2025/03/10 02:05:46 DEBUG : empty space: Dst hash empty - aborting Src hash check
2025/03/10 02:05:46 INFO  : empty space: Copied (replaced existing)
2025/03/10 02:05:46 DEBUG : Waiting for deletions to finish
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
--- PASS: TestSyncAfterChangingModtimeOnly (3.03s)
=== RUN   TestSyncAfterChangingModtimeOnlyWithNoUpdateModTime
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:05:48 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for checks to finish
2025/03/10 02:05:48 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/03/10 02:05:48 DEBUG : empty space: Dst hash empty - aborting Src hash check
2025/03/10 02:05:48 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for transfers to finish
2025/03/10 02:05:48 DEBUG : empty space: Dst hash empty - aborting Src hash check
2025/03/10 02:05:48 INFO  : empty space: Copied (replaced existing)
2025/03/10 02:05:48 DEBUG : Waiting for deletions to finish
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
    fstest.go:121: 
        	Error Trace:	/home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:121
        	            				/home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:126
        	            				/home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:145
        	            				/home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:189
        	            				/home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:302
        	            				/home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:332
        	            				/home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:344
        	            				/home/rclone/go/src/github.com/rclone/rclone/fstest/run.go:340
        	            				/home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync_test.go:1035
        	Error:      	Should be true
        	Test:       	TestSyncAfterChangingModtimeOnlyWithNoUpdateModTime
        	Messages:   	empty space: Modification time difference too big |-95456h54m52.500000001s| > 1s (want 2001-02-03 04:05:06.499999999 +0000 UTC vs got 2011-12-25 12:59:59 +0000 UTC) (precision 1s)
--- FAIL: TestSyncAfterChangingModtimeOnlyWithNoUpdateModTime (2.51s)
=== RUN   TestSyncDoesntUpdateModtime
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:05:50 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for checks to finish
2025/03/10 02:05:50 DEBUG : foo: Modification times differ by -95456h54m53.123456789s: 2011-12-25 12:59:59.123456789 +0000 UTC, 2001-02-03 04:05:06 +0000 UTC
2025/03/10 02:05:50 DEBUG : foo: Dst hash empty - aborting Src hash check
2025/03/10 02:05:50 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for transfers to finish
2025/03/10 02:05:51 DEBUG : foo: Dst hash empty - aborting Src hash check
2025/03/10 02:05:51 INFO  : foo: Copied (replaced existing)
2025/03/10 02:05:51 DEBUG : Waiting for deletions to finish
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
--- PASS: TestSyncDoesntUpdateModtime (2.50s)
=== RUN   TestSyncAfterAddingAFile
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:05:53 DEBUG : potato: Need to transfer - File not found at Destination
2025/03/10 02:05:53 DEBUG : empty space: Size and modification time the same (differ by -123.456789ms, within tolerance 1s)
2025/03/10 02:05:53 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for checks to finish
2025/03/10 02:05:53 DEBUG : empty space: Unchanged skipping
2025/03/10 02:05:53 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for transfers to finish
2025/03/10 02:05:54 DEBUG : potato: Dst hash empty - aborting Src hash check
2025/03/10 02:05:54 INFO  : potato: Copied (new)
2025/03/10 02:05:54 DEBUG : Waiting for deletions to finish
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
--- PASS: TestSyncAfterAddingAFile (2.73s)
=== RUN   TestSyncAfterChangingFilesSizeOnly
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:05:55 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for checks to finish
2025/03/10 02:05:55 DEBUG : potato: Sizes differ (src 21 vs dst 60)
2025/03/10 02:05:55 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for transfers to finish
2025/03/10 02:05:56 DEBUG : potato: Dst hash empty - aborting Src hash check
2025/03/10 02:05:56 INFO  : potato: Copied (replaced existing)
2025/03/10 02:05:56 DEBUG : Waiting for deletions to finish
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
--- PASS: TestSyncAfterChangingFilesSizeOnly (2.49s)
=== RUN   TestSyncAfterChangingContentsOnly
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:05:58 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for checks to finish
2025/03/10 02:05:58 DEBUG : potato: Modification times differ by 119h59m59.876543211s: 2011-12-25 12:59:59.123456789 +0000 UTC, 2011-12-30 12:59:59 +0000 UTC
2025/03/10 02:05:58 DEBUG : potato: Dst hash empty - aborting Src hash check
2025/03/10 02:05:58 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for transfers to finish
2025/03/10 02:05:59 DEBUG : potato: Dst hash empty - aborting Src hash check
2025/03/10 02:05:59 INFO  : potato: Copied (replaced existing)
2025/03/10 02:05:59 DEBUG : Waiting for deletions to finish
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
--- PASS: TestSyncAfterChangingContentsOnly (2.46s)
=== RUN   TestSyncAfterRemovingAFileAndAddingAFileDryRun
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:06:01 DEBUG : potato2: Need to transfer - File not found at Destination
2025/03/10 02:06:01 NOTICE: potato2: Skipped copy as --dry-run is set (size 60)
2025/03/10 02:06:01 DEBUG : empty space: Size and modification time the same (differ by -123.456789ms, within tolerance 1s)
2025/03/10 02:06:01 DEBUG : empty space: Unchanged skipping
2025/03/10 02:06:01 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for checks to finish
2025/03/10 02:06:01 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for transfers to finish
2025/03/10 02:06:01 DEBUG : Waiting for deletions to finish
2025/03/10 02:06:01 NOTICE: potato: Skipped delete as --dry-run is set (size 21)
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
--- PASS: TestSyncAfterRemovingAFileAndAddingAFileDryRun (2.73s)
=== RUN   TestSyncAfterRemovingAFileAndAddingAFile
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:06:04 DEBUG : potato2: Need to transfer - File not found at Destination
2025/03/10 02:06:04 DEBUG : empty space: Size and modification time the same (differ by -123.456789ms, within tolerance 1s)
2025/03/10 02:06:04 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for checks to finish
2025/03/10 02:06:04 DEBUG : empty space: Unchanged skipping
2025/03/10 02:06:04 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for transfers to finish
2025/03/10 02:06:05 DEBUG : potato2: Dst hash empty - aborting Src hash check
2025/03/10 02:06:05 INFO  : potato2: Copied (new)
2025/03/10 02:06:05 DEBUG : Waiting for deletions to finish
2025/03/10 02:06:05 INFO  : potato: Deleted
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
--- PASS: TestSyncAfterRemovingAFileAndAddingAFile (3.51s)
=== RUN   TestSyncAfterRemovingAFileAndAddingAFileSubDir
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:06:07 INFO  : d: Making directory
2025/03/10 02:06:07 INFO  : d/e: Making directory
2025/03/10 02:06:08 DEBUG : Added delayed dir = "a", newDst=<nil>
2025/03/10 02:06:08 DEBUG : c: Directory modification time the same (differ by -20.276951ms, within tolerance 1s)
2025/03/10 02:06:08 DEBUG : Added delayed dir = "c", newDst=c
2025/03/10 02:06:08 DEBUG : a/potato2: Need to transfer - File not found at Destination
2025/03/10 02:06:08 DEBUG : c/non empty space: Size and modification time the same (differ by -123.456789ms, within tolerance 1s)
2025/03/10 02:06:08 DEBUG : c/non empty space: Unchanged skipping
2025/03/10 02:06:09 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for checks to finish
2025/03/10 02:06:09 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for transfers to finish
2025/03/10 02:06:09 DEBUG : a/potato2: Dst hash empty - aborting Src hash check
2025/03/10 02:06:09 INFO  : a/potato2: Copied (new)
2025/03/10 02:06:09 DEBUG : Waiting for deletions to finish
2025/03/10 02:06:09 INFO  : b/potato: Deleted
2025/03/10 02:06:09 INFO  : a: Set directory modification time (using DirSetModTime)
2025/03/10 02:06:09 INFO  : d/e: Removing directory
2025/03/10 02:06:09 INFO  : d: Removing directory
2025/03/10 02:06:10 DEBUG : pacer: low level retry 1/10 (error Folder Not Empty - `Folder rclone-test-nikesix4yode/d not empty`)
2025/03/10 02:06:10 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2025/03/10 02:06:10 DEBUG : pacer: Reducing sleep to 15ms
2025/03/10 02:06:10 INFO  : b: Removing directory
2025/03/10 02:06:10 DEBUG : pacer: Reducing sleep to 11.25ms
2025/03/10 02:06:10 DEBUG : files root 'rclone-test-nikesix4yode': deleted 3 directories
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:06:10 DEBUG : pacer: Reducing sleep to 10ms
--- PASS: TestSyncAfterRemovingAFileAndAddingAFileSubDir (5.90s)
=== RUN   TestSyncAfterRemovingAFileAndAddingAFileSubDirWithErrors
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:06:13 INFO  : d: Making directory
2025/03/10 02:06:14 DEBUG : Added delayed dir = "a", newDst=<nil>
2025/03/10 02:06:14 DEBUG : c: Directory modification time the same (differ by 27.766738ms, within tolerance 1s)
2025/03/10 02:06:14 DEBUG : Added delayed dir = "c", newDst=c
2025/03/10 02:06:14 DEBUG : a/potato2: Need to transfer - File not found at Destination
2025/03/10 02:06:14 DEBUG : c/non empty space: Size and modification time the same (differ by -123.456789ms, within tolerance 1s)
2025/03/10 02:06:14 DEBUG : c/non empty space: Unchanged skipping
2025/03/10 02:06:14 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for checks to finish
2025/03/10 02:06:14 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for transfers to finish
2025/03/10 02:06:15 DEBUG : a/potato2: Dst hash empty - aborting Src hash check
2025/03/10 02:06:15 INFO  : a/potato2: Copied (new)
2025/03/10 02:06:15 ERROR : files root 'rclone-test-nikesix4yode': not deleting files as there were IO errors
2025/03/10 02:06:15 INFO  : a: Set directory modification time (using DirSetModTime)
2025/03/10 02:06:15 ERROR : files root 'rclone-test-nikesix4yode': not deleting directories as there were IO errors
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
--- PASS: TestSyncAfterRemovingAFileAndAddingAFileSubDirWithErrors (5.32s)
=== RUN   TestSyncDeleteAfter
--- PASS: TestSyncDeleteAfter (0.00s)
=== RUN   TestSyncDeleteDuring
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:06:19 DEBUG : Waiting for deletions to finish
2025/03/10 02:06:19 DEBUG : potato2: Need to transfer - File not found at Destination
2025/03/10 02:06:19 DEBUG : empty space: Size and modification time the same (differ by -123.456789ms, within tolerance 1s)
2025/03/10 02:06:19 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for checks to finish
2025/03/10 02:06:19 DEBUG : empty space: Unchanged skipping
2025/03/10 02:06:19 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for transfers to finish
2025/03/10 02:06:19 INFO  : potato: Deleted
2025/03/10 02:06:19 DEBUG : potato2: Dst hash empty - aborting Src hash check
2025/03/10 02:06:19 INFO  : potato2: Copied (new)
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
--- PASS: TestSyncDeleteDuring (3.41s)
=== RUN   TestSyncDeleteBefore
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:06:22 DEBUG : Waiting for deletions to finish
2025/03/10 02:06:22 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for checks to finish
2025/03/10 02:06:22 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for transfers to finish
2025/03/10 02:06:22 INFO  : potato: Deleted
2025/03/10 02:06:22 DEBUG : potato2: Need to transfer - File not found at Destination
2025/03/10 02:06:22 DEBUG : empty space: Size and modification time the same (differ by -123.456789ms, within tolerance 1s)
2025/03/10 02:06:22 DEBUG : empty space: Unchanged skipping
2025/03/10 02:06:22 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for checks to finish
2025/03/10 02:06:22 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for transfers to finish
2025/03/10 02:06:23 DEBUG : potato2: Dst hash empty - aborting Src hash check
2025/03/10 02:06:23 INFO  : potato2: Copied (new)
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
--- PASS: TestSyncDeleteBefore (3.68s)
=== RUN   TestCopyDeleteBefore
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:06:25 DEBUG : potato2: Need to transfer - File not found at Destination
2025/03/10 02:06:25 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for checks to finish
2025/03/10 02:06:25 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for transfers to finish
2025/03/10 02:06:26 DEBUG : potato2: Dst hash empty - aborting Src hash check
2025/03/10 02:06:26 INFO  : potato2: Copied (new)
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
--- PASS: TestCopyDeleteBefore (2.69s)
=== RUN   TestSyncWithExclude
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:06:28 DEBUG : enormous: Excluded (Size Filter)
2025/03/10 02:06:28 DEBUG : enormous: Excluded
2025/03/10 02:06:28 DEBUG : potato2: Excluded (Size Filter)
2025/03/10 02:06:28 DEBUG : potato2: Excluded
2025/03/10 02:06:29 DEBUG : potato2: Excluded (Size Filter)
2025/03/10 02:06:29 DEBUG : potato2: Excluded
2025/03/10 02:06:29 DEBUG : empty space: Size and modification time the same (differ by -123.456789ms, within tolerance 1s)
2025/03/10 02:06:29 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for checks to finish
2025/03/10 02:06:29 DEBUG : empty space: Unchanged skipping
2025/03/10 02:06:29 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for transfers to finish
2025/03/10 02:06:29 DEBUG : Waiting for deletions to finish
2025/03/10 02:06:29 INFO  : There was nothing to transfer
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:06:29 DEBUG : enormous: Excluded (Size Filter)
2025/03/10 02:06:29 DEBUG : enormous: Excluded
2025/03/10 02:06:29 DEBUG : potato2: Excluded (Size Filter)
2025/03/10 02:06:29 DEBUG : potato2: Excluded
2025/03/10 02:06:29 DEBUG : potato2: Excluded (Size Filter)
2025/03/10 02:06:29 DEBUG : potato2: Excluded
2025/03/10 02:06:29 DEBUG : empty space: Size and modification time the same (differ by 123.456789ms, within tolerance 1s)
2025/03/10 02:06:29 DEBUG : empty space: Unchanged skipping
2025/03/10 02:06:29 DEBUG : Local file system at /tmp/rclone391858675: Waiting for checks to finish
2025/03/10 02:06:29 DEBUG : Local file system at /tmp/rclone391858675: Waiting for transfers to finish
2025/03/10 02:06:29 DEBUG : Waiting for deletions to finish
2025/03/10 02:06:29 INFO  : There was nothing to transfer
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
--- PASS: TestSyncWithExclude (3.14s)
=== RUN   TestSyncWithExcludeAndDeleteExcluded
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:06:32 DEBUG : enormous: Excluded (Size Filter)
2025/03/10 02:06:32 DEBUG : enormous: Excluded
2025/03/10 02:06:32 DEBUG : potato2: Excluded (Size Filter)
2025/03/10 02:06:32 DEBUG : potato2: Excluded
2025/03/10 02:06:32 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for checks to finish
2025/03/10 02:06:32 DEBUG : empty space: Size and modification time the same (differ by -123.456789ms, within tolerance 1s)
2025/03/10 02:06:32 DEBUG : empty space: Unchanged skipping
2025/03/10 02:06:32 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for transfers to finish
2025/03/10 02:06:32 DEBUG : Waiting for deletions to finish
2025/03/10 02:06:33 INFO  : potato2: Deleted
2025/03/10 02:06:33 INFO  : enormous: Deleted
2025/03/10 02:06:33 INFO  : There was nothing to transfer
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:06:33 DEBUG : Local file system at /tmp/rclone391858675: Waiting for checks to finish
2025/03/10 02:06:33 DEBUG : empty space: Size and modification time the same (differ by 123.456789ms, within tolerance 1s)
2025/03/10 02:06:33 DEBUG : empty space: Unchanged skipping
2025/03/10 02:06:33 DEBUG : Local file system at /tmp/rclone391858675: Waiting for transfers to finish
2025/03/10 02:06:33 DEBUG : Waiting for deletions to finish
2025/03/10 02:06:33 INFO  : enormous: Deleted
2025/03/10 02:06:33 INFO  : potato2: Deleted
2025/03/10 02:06:33 INFO  : There was nothing to transfer
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
--- PASS: TestSyncWithExcludeAndDeleteExcluded (3.90s)
=== RUN   TestSyncWithUpdateOlder
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:06:37 DEBUG : five: Need to transfer - File not found at Destination
2025/03/10 02:06:37 DEBUG : four: Sizes differ (src 4 vs dst 8)
2025/03/10 02:06:37 DEBUG : three: Sizes identical
2025/03/10 02:06:37 DEBUG : one: Destination is newer than source, skipping
2025/03/10 02:06:37 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for checks to finish
2025/03/10 02:06:37 DEBUG : two: Dst hash empty - aborting Src hash check
2025/03/10 02:06:37 DEBUG : four: Destination mod time is within 1s of source but files differ, transferring
2025/03/10 02:06:37 DEBUG : three: Destination mod time is within 1s of source and files identical, skipping
2025/03/10 02:06:37 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for transfers to finish
2025/03/10 02:06:38 DEBUG : five: Dst hash empty - aborting Src hash check
2025/03/10 02:06:38 INFO  : five: Copied (new)
2025/03/10 02:06:38 DEBUG : four: Dst hash empty - aborting Src hash check
2025/03/10 02:06:38 INFO  : four: Copied (replaced existing)
2025/03/10 02:06:38 DEBUG : two: Dst hash empty - aborting Src hash check
2025/03/10 02:06:38 INFO  : two: Copied (replaced existing)
2025/03/10 02:06:38 DEBUG : Waiting for deletions to finish
2025/03/10 02:06:38 DEBUG : five: Dst hash empty - aborting Src hash check
2025/03/10 02:06:38 DEBUG : four: Dst hash empty - aborting Src hash check
2025/03/10 02:06:38 DEBUG : one: Destination is newer than source, skipping
2025/03/10 02:06:38 DEBUG : three: Dst hash empty - aborting Src hash check
2025/03/10 02:06:38 DEBUG : two: Dst hash empty - aborting Src hash check
2025/03/10 02:06:38 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for checks to finish
2025/03/10 02:06:38 DEBUG : five: Size of src and dst objects identical
2025/03/10 02:06:38 DEBUG : five: Destination mod time is within 1s of source and files identical, skipping
2025/03/10 02:06:38 DEBUG : four: Size of src and dst objects identical
2025/03/10 02:06:38 DEBUG : four: Destination mod time is within 1s of source and files identical, skipping
2025/03/10 02:06:38 DEBUG : three: Size of src and dst objects identical
2025/03/10 02:06:38 DEBUG : three: Destination mod time is within 1s of source and files identical, skipping
2025/03/10 02:06:38 DEBUG : two: Size of src and dst objects identical
2025/03/10 02:06:38 DEBUG : two: Destination mod time is within 1s of source and files identical, skipping
2025/03/10 02:06:38 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for transfers to finish
2025/03/10 02:06:38 DEBUG : Waiting for deletions to finish
--- PASS: TestSyncWithUpdateOlder (5.61s)
=== RUN   TestSyncWithMaxDuration
=== RUN   TestSyncWithMaxDuration/Hard
    sync_test.go:1466: Skipping test on non local remote
=== RUN   TestSyncWithMaxDuration/Soft
    sync_test.go:1466: Skipping test on non local remote
--- PASS: TestSyncWithMaxDuration (0.00s)
    --- SKIP: TestSyncWithMaxDuration/Hard (0.00s)
    --- SKIP: TestSyncWithMaxDuration/Soft (0.00s)
=== RUN   TestSyncWithTrackRenames
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
    sync_test.go:1538: Can track renames: true
2025/03/10 02:06:39 INFO  : files root 'rclone-test-nikesix4yode': Making map for --track-renames
2025/03/10 02:06:39 INFO  : files root 'rclone-test-nikesix4yode': Finished making map for --track-renames
2025/03/10 02:06:39 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for checks to finish
2025/03/10 02:06:39 DEBUG : potato: Need to transfer - No matching file found at Destination
2025/03/10 02:06:39 DEBUG : yam: Need to transfer - No matching file found at Destination
2025/03/10 02:06:39 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for renames to finish
2025/03/10 02:06:39 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for transfers to finish
2025/03/10 02:06:40 DEBUG : potato: Dst hash empty - aborting Src hash check
2025/03/10 02:06:40 INFO  : potato: Copied (new)
2025/03/10 02:06:40 DEBUG : yam: Dst hash empty - aborting Src hash check
2025/03/10 02:06:40 INFO  : yam: Copied (new)
2025/03/10 02:06:40 DEBUG : Waiting for deletions to finish
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:06:41 DEBUG : potato: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/03/10 02:06:41 INFO  : files root 'rclone-test-nikesix4yode': Making map for --track-renames
2025/03/10 02:06:41 INFO  : files root 'rclone-test-nikesix4yode': Finished making map for --track-renames
2025/03/10 02:06:41 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for checks to finish
2025/03/10 02:06:41 DEBUG : yaml: Need to transfer - No matching file found at Destination
2025/03/10 02:06:41 DEBUG : potato: Unchanged skipping
2025/03/10 02:06:41 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for renames to finish
2025/03/10 02:06:41 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for transfers to finish
2025/03/10 02:06:41 DEBUG : yaml: Dst hash empty - aborting Src hash check
2025/03/10 02:06:41 INFO  : yaml: Copied (new)
2025/03/10 02:06:41 DEBUG : Waiting for deletions to finish
2025/03/10 02:06:41 INFO  : yam: Deleted
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
    sync_test.go:1564: 
        	Error Trace:	/home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync_test.go:1564
        	Error:      	Not equal: 
        	            	expected: true
        	            	actual  : false
        	Test:       	TestSyncWithTrackRenames
        	Messages:   	canTrackRenames=true, renames=0
--- FAIL: TestSyncWithTrackRenames (3.31s)
=== RUN   TestParseRenamesStrategyModtime
--- PASS: TestParseRenamesStrategyModtime (0.00s)
=== RUN   TestRenamesStrategyModtime
--- PASS: TestRenamesStrategyModtime (0.00s)
=== RUN   TestSyncWithTrackRenamesStrategyModtime
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
    sync_test.go:1610: Can track renames: true
2025/03/10 02:06:43 INFO  : files root 'rclone-test-nikesix4yode': Making map for --track-renames
2025/03/10 02:06:43 INFO  : files root 'rclone-test-nikesix4yode': Finished making map for --track-renames
2025/03/10 02:06:43 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for checks to finish
2025/03/10 02:06:43 DEBUG : potato: Need to transfer - No matching file found at Destination
2025/03/10 02:06:43 DEBUG : yam: Need to transfer - No matching file found at Destination
2025/03/10 02:06:43 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for renames to finish
2025/03/10 02:06:43 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for transfers to finish
2025/03/10 02:06:44 DEBUG : potato: Dst hash empty - aborting Src hash check
2025/03/10 02:06:44 INFO  : potato: Copied (new)
2025/03/10 02:06:44 DEBUG : yam: Dst hash empty - aborting Src hash check
2025/03/10 02:06:44 INFO  : yam: Copied (new)
2025/03/10 02:06:44 DEBUG : Waiting for deletions to finish
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:06:44 DEBUG : potato: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/03/10 02:06:44 INFO  : files root 'rclone-test-nikesix4yode': Making map for --track-renames
2025/03/10 02:06:44 INFO  : files root 'rclone-test-nikesix4yode': Finished making map for --track-renames
2025/03/10 02:06:44 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for checks to finish
2025/03/10 02:06:44 DEBUG : potato: Unchanged skipping
2025/03/10 02:06:44 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for renames to finish
2025/03/10 02:06:44 INFO  : yam: Moved (server-side) to: yaml
2025/03/10 02:06:44 INFO  : yaml: Renamed from "yam"
2025/03/10 02:06:44 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for transfers to finish
2025/03/10 02:06:44 DEBUG : Waiting for deletions to finish
2025/03/10 02:06:44 INFO  : There was nothing to transfer
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
--- PASS: TestSyncWithTrackRenamesStrategyModtime (2.95s)
=== RUN   TestSyncWithTrackRenamesStrategyLeaf
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
    sync_test.go:1649: Can track renames: true
2025/03/10 02:06:46 DEBUG : Added delayed dir = "sub", newDst=<nil>
2025/03/10 02:06:46 INFO  : files root 'rclone-test-nikesix4yode': Making map for --track-renames
2025/03/10 02:06:46 INFO  : files root 'rclone-test-nikesix4yode': Finished making map for --track-renames
2025/03/10 02:06:46 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for checks to finish
2025/03/10 02:06:46 DEBUG : potato: Need to transfer - No matching file found at Destination
2025/03/10 02:06:46 DEBUG : sub/yam: Need to transfer - No matching file found at Destination
2025/03/10 02:06:46 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for renames to finish
2025/03/10 02:06:46 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for transfers to finish
2025/03/10 02:06:46 DEBUG : potato: Dst hash empty - aborting Src hash check
2025/03/10 02:06:46 INFO  : potato: Copied (new)
2025/03/10 02:06:47 DEBUG : sub/yam: Dst hash empty - aborting Src hash check
2025/03/10 02:06:47 INFO  : sub/yam: Copied (new)
2025/03/10 02:06:47 DEBUG : Waiting for deletions to finish
2025/03/10 02:06:47 INFO  : sub: Set directory modification time (using DirSetModTime)
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:06:47 DEBUG : potato: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/03/10 02:06:47 DEBUG : potato: Unchanged skipping
2025/03/10 02:06:47 INFO  : sub: Set directory modification time (using DirSetModTime)
2025/03/10 02:06:47 DEBUG : Added delayed dir = "sub", newDst=sub
2025/03/10 02:06:47 INFO  : files root 'rclone-test-nikesix4yode': Making map for --track-renames
2025/03/10 02:06:47 INFO  : files root 'rclone-test-nikesix4yode': Finished making map for --track-renames
2025/03/10 02:06:47 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for checks to finish
2025/03/10 02:06:47 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for renames to finish
2025/03/10 02:06:48 INFO  : sub/yam: Moved (server-side) to: yam
2025/03/10 02:06:48 INFO  : yam: Renamed from "sub/yam"
2025/03/10 02:06:48 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for transfers to finish
2025/03/10 02:06:48 DEBUG : Waiting for deletions to finish
2025/03/10 02:06:48 INFO  : There was nothing to transfer
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
--- PASS: TestSyncWithTrackRenamesStrategyLeaf (4.22s)
=== RUN   TestServerSideMoveLocal
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:06:50 DEBUG : Creating backend with remote "/tmp/rclone391858675/dir1"
2025/03/10 02:06:50 DEBUG : Creating backend with remote "/tmp/rclone391858675/dir2"
2025/03/10 02:06:50 DEBUG : Local file system at /tmp/rclone391858675/dir2: Using server-side directory move
2025/03/10 02:06:50 INFO  : Local file system at /tmp/rclone391858675/dir2: Server side directory move failed - fallback to file moves: can't copy directory - destination already exists
2025/03/10 02:06:50 DEBUG : file1.txt: Need to transfer - File not found at Destination
2025/03/10 02:06:50 DEBUG : Local file system at /tmp/rclone391858675/dir2: Waiting for checks to finish
2025/03/10 02:06:50 DEBUG : Local file system at /tmp/rclone391858675/dir2: Waiting for transfers to finish
2025/03/10 02:06:50 INFO  : file1.txt: Moved (server-side)
--- PASS: TestServerSideMoveLocal (0.26s)
=== RUN   TestMoveWithDeleteEmptySrcDirs
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:06:50 DEBUG : Added delayed dir = "nested", newDst=<nil>
2025/03/10 02:06:50 DEBUG : Added delayed dir = "sub dir", newDst=<nil>
2025/03/10 02:06:50 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination
2025/03/10 02:06:50 DEBUG : Added delayed dir = "nested/sub dir", newDst=<nil>
2025/03/10 02:06:50 DEBUG : nested/sub dir/file: Need to transfer - File not found at Destination
2025/03/10 02:06:50 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for checks to finish
2025/03/10 02:06:50 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for transfers to finish
2025/03/10 02:06:51 DEBUG : sub dir/hello world: Dst hash empty - aborting Src hash check
2025/03/10 02:06:51 INFO  : sub dir/hello world: Copied (new)
2025/03/10 02:06:51 INFO  : sub dir/hello world: Deleted
2025/03/10 02:06:51 DEBUG : nested/sub dir/file: Dst hash empty - aborting Src hash check
2025/03/10 02:06:51 INFO  : nested/sub dir/file: Copied (new)
2025/03/10 02:06:51 INFO  : nested/sub dir/file: Deleted
2025/03/10 02:06:51 INFO  : nested/sub dir: Set directory modification time (using DirSetModTime)
2025/03/10 02:06:51 INFO  : sub dir: Set directory modification time (using DirSetModTime)
2025/03/10 02:06:51 INFO  : nested: Set directory modification time (using DirSetModTime)
2025/03/10 02:06:51 INFO  : sub dir: Removing directory
2025/03/10 02:06:51 INFO  : nested/sub dir: Removing directory
2025/03/10 02:06:51 INFO  : nested: Removing directory
2025/03/10 02:06:51 DEBUG : Local file system at /tmp/rclone391858675: deleted 3 directories
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:06:53 DEBUG : pacer: low level retry 1/10 (error Folder Not Empty - `Folder rclone-test-nikesix4yode/nested not empty`)
2025/03/10 02:06:53 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2025/03/10 02:06:53 DEBUG : pacer: Reducing sleep to 15ms
2025/03/10 02:06:53 DEBUG : pacer: Reducing sleep to 11.25ms
2025/03/10 02:06:53 DEBUG : pacer: Reducing sleep to 10ms
--- PASS: TestMoveWithDeleteEmptySrcDirs (3.33s)
=== RUN   TestMoveWithoutDeleteEmptySrcDirs
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:06:54 DEBUG : Added delayed dir = "nested", newDst=<nil>
2025/03/10 02:06:54 DEBUG : Added delayed dir = "sub dir", newDst=<nil>
2025/03/10 02:06:54 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination
2025/03/10 02:06:54 DEBUG : Added delayed dir = "nested/sub dir", newDst=<nil>
2025/03/10 02:06:54 DEBUG : nested/sub dir/file: Need to transfer - File not found at Destination
2025/03/10 02:06:54 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for checks to finish
2025/03/10 02:06:54 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for transfers to finish
2025/03/10 02:06:54 DEBUG : sub dir/hello world: Dst hash empty - aborting Src hash check
2025/03/10 02:06:54 INFO  : sub dir/hello world: Copied (new)
2025/03/10 02:06:54 INFO  : sub dir/hello world: Deleted
2025/03/10 02:06:54 DEBUG : nested/sub dir/file: Dst hash empty - aborting Src hash check
2025/03/10 02:06:54 INFO  : nested/sub dir/file: Copied (new)
2025/03/10 02:06:54 INFO  : nested/sub dir/file: Deleted
2025/03/10 02:06:55 INFO  : nested/sub dir: Set directory modification time (using DirSetModTime)
2025/03/10 02:06:55 INFO  : sub dir: Set directory modification time (using DirSetModTime)
2025/03/10 02:06:55 INFO  : nested: Set directory modification time (using DirSetModTime)
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:06:56 DEBUG : pacer: low level retry 1/10 (error Folder Not Empty - `Folder rclone-test-nikesix4yode/nested not empty`)
2025/03/10 02:06:56 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2025/03/10 02:06:56 DEBUG : pacer: low level retry 2/10 (error Folder Not Empty - `Folder rclone-test-nikesix4yode/nested not empty`)
2025/03/10 02:06:56 DEBUG : pacer: Rate limited, increasing sleep to 40ms
2025/03/10 02:06:57 DEBUG : pacer: low level retry 3/10 (error Folder Not Empty - `Folder rclone-test-nikesix4yode/nested not empty`)
2025/03/10 02:06:57 DEBUG : pacer: Rate limited, increasing sleep to 80ms
2025/03/10 02:06:57 DEBUG : pacer: Reducing sleep to 60ms
2025/03/10 02:06:57 DEBUG : pacer: Reducing sleep to 45ms
2025/03/10 02:06:57 DEBUG : pacer: Reducing sleep to 33.75ms
2025/03/10 02:06:57 DEBUG : pacer: Reducing sleep to 25.3125ms
--- PASS: TestMoveWithoutDeleteEmptySrcDirs (3.62s)
=== RUN   TestMoveWithIgnoreExisting
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:06:57 DEBUG : pacer: Reducing sleep to 18.984375ms
2025/03/10 02:06:57 DEBUG : existing: Need to transfer - File not found at Destination
2025/03/10 02:06:57 DEBUG : existing-b: Need to transfer - File not found at Destination
2025/03/10 02:06:57 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for checks to finish
2025/03/10 02:06:57 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for transfers to finish
2025/03/10 02:06:58 DEBUG : pacer: Reducing sleep to 14.238281ms
2025/03/10 02:06:58 DEBUG : pacer: Reducing sleep to 10.67871ms
2025/03/10 02:06:58 DEBUG : pacer: Reducing sleep to 10ms
2025/03/10 02:06:58 DEBUG : existing: Dst hash empty - aborting Src hash check
2025/03/10 02:06:58 INFO  : existing: Copied (new)
2025/03/10 02:06:58 INFO  : existing: Deleted
2025/03/10 02:06:58 DEBUG : existing-b: Dst hash empty - aborting Src hash check
2025/03/10 02:06:58 INFO  : existing-b: Copied (new)
2025/03/10 02:06:58 INFO  : existing-b: Deleted
2025/03/10 02:06:58 DEBUG : existing: Destination exists, skipping
2025/03/10 02:06:58 DEBUG : existing: Not removing source file as destination file exists and --ignore-existing is set
2025/03/10 02:06:58 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for checks to finish
2025/03/10 02:06:58 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for transfers to finish
2025/03/10 02:06:58 INFO  : There was nothing to transfer
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
--- PASS: TestMoveWithIgnoreExisting (2.15s)
=== RUN   TestServerSideMove
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:06:59 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-wahudod6cohe"
    sync_test.go:1705: Server side move (if possible) files root 'rclone-test-nikesix4yode' -> files root 'rclone-test-wahudod6cohe'
2025/03/10 02:07:04 DEBUG : files root 'rclone-test-wahudod6cohe': Using server-side directory move
2025/03/10 02:07:04 INFO  : files root 'rclone-test-wahudod6cohe': Server side directory move failed - fallback to file moves: can't copy directory - destination already exists
2025/03/10 02:07:04 DEBUG : potato2: Need to transfer - File not found at Destination
2025/03/10 02:07:04 DEBUG : empty space: Size and modification time the same (differ by 0s, within tolerance 1s)
2025/03/10 02:07:04 DEBUG : empty space: Unchanged skipping
2025/03/10 02:07:04 DEBUG : potato3: Sizes differ (src 68 vs dst 60)
2025/03/10 02:07:04 DEBUG : files root 'rclone-test-wahudod6cohe': Waiting for checks to finish
2025/03/10 02:07:04 INFO  : empty space: Deleted
2025/03/10 02:07:04 DEBUG : files root 'rclone-test-wahudod6cohe': Waiting for transfers to finish
2025/03/10 02:07:04 INFO  : potato3: Deleted
2025/03/10 02:07:05 INFO  : potato2: Moved (server-side)
2025/03/10 02:07:05 INFO  : potato3: Moved (server-side)
2025/03/10 02:07:05 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-raveteg3baru"
2025/03/10 02:07:06 DEBUG : files root 'rclone-test-raveteg3baru': Using server-side directory move
2025/03/10 02:07:07 INFO  : files root 'rclone-test-raveteg3baru': Server side directory move succeeded
2025/03/10 02:07:07 ERROR : : error listing: directory not found
2025/03/10 02:07:07 DEBUG : files root 'rclone-test-raveteg3baru': Purge remote
2025/03/10 02:07:07 DEBUG : files root 'rclone-test-wahudod6cohe': Purge remote
2025/03/10 02:07:07 NOTICE: purge failed: directory not found
--- PASS: TestServerSideMove (8.42s)
=== RUN   TestServerSideMoveWithFilter
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:07:08 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-zuzokan7lebi"
    sync_test.go:1705: Server side move (if possible) files root 'rclone-test-nikesix4yode' -> files root 'rclone-test-zuzokan7lebi'
2025/03/10 02:07:14 DEBUG : empty space: Excluded (Size Filter)
2025/03/10 02:07:14 DEBUG : empty space: Excluded
2025/03/10 02:07:14 DEBUG : empty space: Excluded (Size Filter)
2025/03/10 02:07:14 DEBUG : empty space: Excluded
2025/03/10 02:07:14 DEBUG : potato2: Need to transfer - File not found at Destination
2025/03/10 02:07:14 DEBUG : files root 'rclone-test-zuzokan7lebi': Waiting for checks to finish
2025/03/10 02:07:14 DEBUG : potato3: Sizes differ (src 68 vs dst 60)
2025/03/10 02:07:14 DEBUG : files root 'rclone-test-zuzokan7lebi': Waiting for transfers to finish
2025/03/10 02:07:14 INFO  : potato3: Deleted
2025/03/10 02:07:14 INFO  : potato2: Moved (server-side)
2025/03/10 02:07:14 INFO  : potato3: Moved (server-side)
2025/03/10 02:07:15 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-najidix1fuvo"
2025/03/10 02:07:15 DEBUG : empty space: Excluded (Size Filter)
2025/03/10 02:07:15 DEBUG : empty space: Excluded
2025/03/10 02:07:15 DEBUG : potato2: Need to transfer - File not found at Destination
2025/03/10 02:07:15 DEBUG : potato3: Need to transfer - File not found at Destination
2025/03/10 02:07:15 DEBUG : files root 'rclone-test-najidix1fuvo': Waiting for checks to finish
2025/03/10 02:07:15 DEBUG : files root 'rclone-test-najidix1fuvo': Waiting for transfers to finish
2025/03/10 02:07:16 INFO  : potato2: Moved (server-side)
2025/03/10 02:07:16 INFO  : potato3: Moved (server-side)
2025/03/10 02:07:16 DEBUG : files root 'rclone-test-najidix1fuvo': Purge remote
2025/03/10 02:07:16 DEBUG : files root 'rclone-test-zuzokan7lebi': Purge remote
--- PASS: TestServerSideMoveWithFilter (9.36s)
=== RUN   TestServerSideMoveDeleteEmptySourceDirs
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:07:17 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-majugan7vune"
2025/03/10 02:07:20 INFO  : tomatoDir: Making directory
    sync_test.go:1705: Server side move (if possible) files root 'rclone-test-nikesix4yode' -> files root 'rclone-test-majugan7vune'
2025/03/10 02:07:23 DEBUG : files root 'rclone-test-majugan7vune': Using server-side directory move
2025/03/10 02:07:23 INFO  : files root 'rclone-test-majugan7vune': Server side directory move failed - fallback to file moves: can't copy directory - destination already exists
2025/03/10 02:07:23 DEBUG : potato2: Need to transfer - File not found at Destination
2025/03/10 02:07:23 DEBUG : Added delayed dir = "tomatoDir", newDst=<nil>
2025/03/10 02:07:23 DEBUG : potato3: Sizes differ (src 68 vs dst 60)
2025/03/10 02:07:23 DEBUG : empty space: Size and modification time the same (differ by 0s, within tolerance 1s)
2025/03/10 02:07:23 DEBUG : empty space: Unchanged skipping
2025/03/10 02:07:23 DEBUG : files root 'rclone-test-majugan7vune': Waiting for checks to finish
2025/03/10 02:07:23 INFO  : potato3: Deleted
2025/03/10 02:07:23 INFO  : empty space: Deleted
2025/03/10 02:07:23 DEBUG : files root 'rclone-test-majugan7vune': Waiting for transfers to finish
2025/03/10 02:07:24 INFO  : potato2: Moved (server-side)
2025/03/10 02:07:24 INFO  : potato3: Moved (server-side)
2025/03/10 02:07:24 INFO  : tomatoDir: Removing directory
2025/03/10 02:07:24 DEBUG : files root 'rclone-test-nikesix4yode': deleted 1 directories
2025/03/10 02:07:24 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-kusejom8xaru"
2025/03/10 02:07:25 INFO  : tomatoDir: Making directory
2025/03/10 02:07:25 DEBUG : files root 'rclone-test-kusejom8xaru': Using server-side directory move
2025/03/10 02:07:25 INFO  : files root 'rclone-test-kusejom8xaru': Server side directory move succeeded
2025/03/10 02:07:26 ERROR : : error listing: directory not found
2025/03/10 02:07:26 ERROR : : error listing: directory not found
2025/03/10 02:07:26 DEBUG : files root 'rclone-test-kusejom8xaru': Purge remote
2025/03/10 02:07:26 DEBUG : files root 'rclone-test-majugan7vune': Purge remote
2025/03/10 02:07:26 NOTICE: purge failed: directory not found
--- PASS: TestServerSideMoveDeleteEmptySourceDirs (9.40s)
=== RUN   TestServerSideMoveOverlap
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
    sync_test.go:1910: Skipping test as remote supports DirMove
--- SKIP: TestServerSideMoveOverlap (0.24s)
=== RUN   TestSyncOverlap
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:07:27 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-nikesix4yode/rclone-sync-test"
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
--- PASS: TestSyncOverlap (1.93s)
=== RUN   TestSyncOverlapWithFilter
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:07:29 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-nikesix4yode/rclone-sync-test"
2025/03/10 02:07:29 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-nikesix4yode/rclone-sync-test-include/layer2"
2025/03/10 02:07:30 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-nikesix4yode/rclone-sync-test-ignore-file"
2025/03/10 02:07:33 DEBUG : rclone-sync-test: Excluded
2025/03/10 02:07:33 DEBUG : rclone-sync-test-ignore-file: Excluded
2025/03/10 02:07:33 DEBUG : Added delayed dir = "rclone-sync-test-include", newDst=<nil>
2025/03/10 02:07:33 DEBUG : rclone-sync-test-include/layer2: Excluded
2025/03/10 02:07:33 DEBUG : files root 'rclone-test-nikesix4yode/rclone-sync-test': Waiting for checks to finish
2025/03/10 02:07:33 DEBUG : files root 'rclone-test-nikesix4yode/rclone-sync-test': Waiting for transfers to finish
2025/03/10 02:07:33 DEBUG : Waiting for deletions to finish
2025/03/10 02:07:33 INFO  : There was nothing to transfer
2025/03/10 02:07:33 DEBUG : rclone-sync-test: Excluded
2025/03/10 02:07:34 DEBUG : rclone-sync-test-ignore-file: Excluded
2025/03/10 02:07:34 DEBUG : rclone-sync-test-include/layer2: Excluded
2025/03/10 02:07:34 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for checks to finish
2025/03/10 02:07:34 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for transfers to finish
2025/03/10 02:07:34 DEBUG : Waiting for deletions to finish
2025/03/10 02:07:34 INFO  : rclone-sync-test-include: Removing directory
2025/03/10 02:07:34 DEBUG : pacer: low level retry 1/10 (error Folder Not Empty - `Folder rclone-test-nikesix4yode/rclone-sync-test-include not empty`)
2025/03/10 02:07:34 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2025/03/10 02:07:34 DEBUG : pacer: low level retry 2/10 (error Folder Not Empty - `Folder rclone-test-nikesix4yode/rclone-sync-test-include not empty`)
2025/03/10 02:07:34 DEBUG : pacer: Rate limited, increasing sleep to 40ms
2025/03/10 02:07:34 DEBUG : pacer: low level retry 3/10 (error Folder Not Empty - `Folder rclone-test-nikesix4yode/rclone-sync-test-include not empty`)
2025/03/10 02:07:34 DEBUG : pacer: Rate limited, increasing sleep to 80ms
2025/03/10 02:07:34 DEBUG : pacer: low level retry 4/10 (error Folder Not Empty - `Folder rclone-test-nikesix4yode/rclone-sync-test-include not empty`)
2025/03/10 02:07:34 DEBUG : pacer: Rate limited, increasing sleep to 160ms
2025/03/10 02:07:35 DEBUG : pacer: low level retry 5/10 (error Folder Not Empty - `Folder rclone-test-nikesix4yode/rclone-sync-test-include not empty`)
2025/03/10 02:07:35 DEBUG : pacer: Rate limited, increasing sleep to 320ms
2025/03/10 02:07:35 DEBUG : pacer: low level retry 6/10 (error Folder Not Empty - `Folder rclone-test-nikesix4yode/rclone-sync-test-include not empty`)
2025/03/10 02:07:35 DEBUG : pacer: Rate limited, increasing sleep to 640ms
2025/03/10 02:07:35 DEBUG : pacer: low level retry 7/10 (error Folder Not Empty - `Folder rclone-test-nikesix4yode/rclone-sync-test-include not empty`)
2025/03/10 02:07:35 DEBUG : pacer: Rate limited, increasing sleep to 1.28s
2025/03/10 02:07:36 DEBUG : pacer: low level retry 8/10 (error Folder Not Empty - `Folder rclone-test-nikesix4yode/rclone-sync-test-include not empty`)
2025/03/10 02:07:36 DEBUG : pacer: Rate limited, increasing sleep to 2s
2025/03/10 02:07:37 DEBUG : pacer: low level retry 9/10 (error Folder Not Empty - `Folder rclone-test-nikesix4yode/rclone-sync-test-include not empty`)
2025/03/10 02:07:39 DEBUG : pacer: low level retry 10/10 (error Folder Not Empty - `Folder rclone-test-nikesix4yode/rclone-sync-test-include not empty`)
2025/03/10 02:07:39 DEBUG : rclone-sync-test-include: Failed to Rmdir: directory not empty
2025/03/10 02:07:39 DEBUG : files root 'rclone-test-nikesix4yode': failed to delete 1 directories
2025/03/10 02:07:39 INFO  : There was nothing to transfer
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:07:41 DEBUG : pacer: Reducing sleep to 1.5s
2025/03/10 02:07:43 DEBUG : pacer: Reducing sleep to 1.125s
2025/03/10 02:07:44 DEBUG : pacer: Reducing sleep to 843.75ms
2025/03/10 02:07:44 DEBUG : rclone-sync-test: Excluded
2025/03/10 02:07:46 DEBUG : pacer: Reducing sleep to 632.8125ms
2025/03/10 02:07:46 DEBUG : rclone-sync-test-ignore-file: Excluded
2025/03/10 02:07:46 DEBUG : pacer: Reducing sleep to 474.609375ms
2025/03/10 02:07:46 DEBUG : Added delayed dir = "rclone-sync-test-include", newDst=<nil>
2025/03/10 02:07:47 DEBUG : pacer: Reducing sleep to 355.957031ms
2025/03/10 02:07:47 DEBUG : pacer: Reducing sleep to 266.967773ms
2025/03/10 02:07:47 DEBUG : rclone-sync-test-include/layer2: Excluded
2025/03/10 02:07:47 DEBUG : files root 'rclone-test-nikesix4yode/rclone-sync-test-include/layer2': Waiting for checks to finish
2025/03/10 02:07:47 DEBUG : files root 'rclone-test-nikesix4yode/rclone-sync-test-include/layer2': Waiting for transfers to finish
2025/03/10 02:07:47 DEBUG : Waiting for deletions to finish
2025/03/10 02:07:47 INFO  : There was nothing to transfer
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:07:48 DEBUG : pacer: Reducing sleep to 200.225829ms
2025/03/10 02:07:48 DEBUG : pacer: Reducing sleep to 150.169371ms
2025/03/10 02:07:48 DEBUG : pacer: Reducing sleep to 112.627028ms
2025/03/10 02:07:48 DEBUG : rclone-sync-test: Excluded
2025/03/10 02:07:48 DEBUG : pacer: Reducing sleep to 84.470271ms
2025/03/10 02:07:48 DEBUG : rclone-sync-test-ignore-file: Excluded
2025/03/10 02:07:49 DEBUG : pacer: Reducing sleep to 63.352703ms
2025/03/10 02:07:49 DEBUG : pacer: Reducing sleep to 47.514527ms
2025/03/10 02:07:49 DEBUG : pacer: Reducing sleep to 35.635895ms
2025/03/10 02:07:49 DEBUG : rclone-sync-test-include/layer2: Excluded
2025/03/10 02:07:49 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for checks to finish
2025/03/10 02:07:49 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for transfers to finish
2025/03/10 02:07:49 DEBUG : Waiting for deletions to finish
2025/03/10 02:07:49 INFO  : rclone-sync-test-include: Removing directory
2025/03/10 02:07:49 DEBUG : pacer: low level retry 1/10 (error Folder Not Empty - `Folder rclone-test-nikesix4yode/rclone-sync-test-include not empty`)
2025/03/10 02:07:49 DEBUG : pacer: Rate limited, increasing sleep to 71.27179ms
2025/03/10 02:07:49 DEBUG : pacer: low level retry 2/10 (error Folder Not Empty - `Folder rclone-test-nikesix4yode/rclone-sync-test-include not empty`)
2025/03/10 02:07:49 DEBUG : pacer: Rate limited, increasing sleep to 142.54358ms
2025/03/10 02:07:49 DEBUG : pacer: low level retry 3/10 (error Folder Not Empty - `Folder rclone-test-nikesix4yode/rclone-sync-test-include not empty`)
2025/03/10 02:07:49 DEBUG : pacer: Rate limited, increasing sleep to 285.08716ms
2025/03/10 02:07:49 DEBUG : pacer: low level retry 4/10 (error Folder Not Empty - `Folder rclone-test-nikesix4yode/rclone-sync-test-include not empty`)
2025/03/10 02:07:49 DEBUG : pacer: Rate limited, increasing sleep to 570.17432ms
2025/03/10 02:07:50 DEBUG : pacer: low level retry 5/10 (error Folder Not Empty - `Folder rclone-test-nikesix4yode/rclone-sync-test-include not empty`)
2025/03/10 02:07:50 DEBUG : pacer: Rate limited, increasing sleep to 1.14034864s
2025/03/10 02:07:50 DEBUG : pacer: low level retry 6/10 (error Folder Not Empty - `Folder rclone-test-nikesix4yode/rclone-sync-test-include not empty`)
2025/03/10 02:07:50 DEBUG : pacer: Rate limited, increasing sleep to 2s
2025/03/10 02:07:51 DEBUG : pacer: low level retry 7/10 (error Folder Not Empty - `Folder rclone-test-nikesix4yode/rclone-sync-test-include not empty`)
2025/03/10 02:07:53 DEBUG : pacer: low level retry 8/10 (error Folder Not Empty - `Folder rclone-test-nikesix4yode/rclone-sync-test-include not empty`)
2025/03/10 02:07:55 DEBUG : pacer: low level retry 9/10 (error Folder Not Empty - `Folder rclone-test-nikesix4yode/rclone-sync-test-include not empty`)
2025/03/10 02:07:57 DEBUG : pacer: low level retry 10/10 (error Folder Not Empty - `Folder rclone-test-nikesix4yode/rclone-sync-test-include not empty`)
2025/03/10 02:07:57 DEBUG : rclone-sync-test-include: Failed to Rmdir: directory not empty
2025/03/10 02:07:57 DEBUG : files root 'rclone-test-nikesix4yode': failed to delete 1 directories
2025/03/10 02:07:57 INFO  : There was nothing to transfer
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:07:59 DEBUG : pacer: Reducing sleep to 1.5s
2025/03/10 02:08:00 DEBUG : : Excluded
2025/03/10 02:08:01 DEBUG : pacer: Reducing sleep to 1.125s
2025/03/10 02:08:03 DEBUG : pacer: Reducing sleep to 843.75ms
2025/03/10 02:08:03 DEBUG : rclone-sync-test: Excluded
2025/03/10 02:08:04 DEBUG : pacer: Reducing sleep to 632.8125ms
2025/03/10 02:08:04 DEBUG : rclone-sync-test-ignore-file: Excluded
2025/03/10 02:08:05 DEBUG : pacer: Reducing sleep to 474.609375ms
2025/03/10 02:08:05 DEBUG : Added delayed dir = "rclone-sync-test-include", newDst=<nil>
2025/03/10 02:08:05 DEBUG : pacer: Reducing sleep to 355.957031ms
2025/03/10 02:08:06 DEBUG : pacer: Reducing sleep to 266.967773ms
2025/03/10 02:08:06 DEBUG : rclone-sync-test-include/layer2: Excluded
2025/03/10 02:08:06 DEBUG : files root 'rclone-test-nikesix4yode/rclone-sync-test-ignore-file': Waiting for checks to finish
2025/03/10 02:08:06 DEBUG : files root 'rclone-test-nikesix4yode/rclone-sync-test-ignore-file': Waiting for transfers to finish
2025/03/10 02:08:06 DEBUG : Waiting for deletions to finish
2025/03/10 02:08:06 INFO  : There was nothing to transfer
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:08:06 DEBUG : pacer: Reducing sleep to 200.225829ms
2025/03/10 02:08:06 DEBUG : pacer: Reducing sleep to 150.169371ms
2025/03/10 02:08:07 DEBUG : pacer: Reducing sleep to 112.627028ms
2025/03/10 02:08:07 DEBUG : pacer: Reducing sleep to 84.470271ms
2025/03/10 02:08:07 DEBUG : pacer: Reducing sleep to 63.352703ms
2025/03/10 02:08:07 DEBUG : pacer: Reducing sleep to 47.514527ms
2025/03/10 02:08:07 DEBUG : pacer: Reducing sleep to 35.635895ms
2025/03/10 02:08:07 DEBUG : pacer: low level retry 1/10 (error Folder Not Empty - `Folder rclone-test-nikesix4yode/rclone-sync-test-include not empty`)
2025/03/10 02:08:07 DEBUG : pacer: Rate limited, increasing sleep to 71.27179ms
2025/03/10 02:08:08 DEBUG : pacer: Reducing sleep to 53.453842ms
2025/03/10 02:08:08 DEBUG : pacer: Reducing sleep to 40.090381ms
2025/03/10 02:08:08 DEBUG : pacer: Reducing sleep to 30.067785ms
2025/03/10 02:08:08 DEBUG : pacer: Reducing sleep to 22.550838ms
2025/03/10 02:08:08 DEBUG : pacer: Reducing sleep to 16.913128ms
2025/03/10 02:08:08 DEBUG : pacer: Reducing sleep to 12.684846ms
2025/03/10 02:08:08 DEBUG : pacer: Reducing sleep to 10ms
--- PASS: TestSyncOverlapWithFilter (43.74s)
=== RUN   TestSyncCompareDest
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:08:12 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-nikesix4yode/dst"
2025/03/10 02:08:13 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-nikesix4yode/CompareDest"
2025/03/10 02:08:14 DEBUG : one: Need to transfer - File not found at Destination
2025/03/10 02:08:14 DEBUG : files root 'rclone-test-nikesix4yode/dst': Waiting for checks to finish
2025/03/10 02:08:14 DEBUG : files root 'rclone-test-nikesix4yode/dst': Waiting for transfers to finish
2025/03/10 02:08:15 DEBUG : one: Dst hash empty - aborting Src hash check
2025/03/10 02:08:15 INFO  : one: Copied (new)
2025/03/10 02:08:15 DEBUG : Waiting for deletions to finish
2025/03/10 02:08:16 DEBUG : one: Sizes differ (src 5 vs dst 3)
2025/03/10 02:08:16 DEBUG : files root 'rclone-test-nikesix4yode/dst': Waiting for checks to finish
2025/03/10 02:08:16 DEBUG : files root 'rclone-test-nikesix4yode/dst': Waiting for transfers to finish
2025/03/10 02:08:17 DEBUG : one: Dst hash empty - aborting Src hash check
2025/03/10 02:08:17 INFO  : one: Copied (replaced existing)
2025/03/10 02:08:17 DEBUG : Waiting for deletions to finish
2025/03/10 02:08:23 DEBUG : one: Sizes differ (src 5 vs dst 3)
2025/03/10 02:08:23 DEBUG : files root 'rclone-test-nikesix4yode/dst': Waiting for checks to finish
2025/03/10 02:08:23 DEBUG : one: Size and modification time the same (differ by -123.456789ms, within tolerance 1s)
2025/03/10 02:08:23 DEBUG : one: Destination found in --compare-dest, skipping
2025/03/10 02:08:23 DEBUG : files root 'rclone-test-nikesix4yode/dst': Waiting for transfers to finish
2025/03/10 02:08:23 DEBUG : Waiting for deletions to finish
2025/03/10 02:08:23 INFO  : There was nothing to transfer
2025/03/10 02:08:24 DEBUG : two: Size and modification time the same (differ by -123.456789ms, within tolerance 1s)
2025/03/10 02:08:24 DEBUG : two: Destination found in --compare-dest, skipping
2025/03/10 02:08:24 DEBUG : one: Sizes differ (src 5 vs dst 3)
2025/03/10 02:08:24 DEBUG : files root 'rclone-test-nikesix4yode/dst': Waiting for checks to finish
2025/03/10 02:08:25 DEBUG : one: Size and modification time the same (differ by -123.456789ms, within tolerance 1s)
2025/03/10 02:08:25 DEBUG : one: Destination found in --compare-dest, skipping
2025/03/10 02:08:25 DEBUG : files root 'rclone-test-nikesix4yode/dst': Waiting for transfers to finish
2025/03/10 02:08:25 DEBUG : Waiting for deletions to finish
2025/03/10 02:08:25 INFO  : There was nothing to transfer
2025/03/10 02:08:25 DEBUG : two: Size and modification time the same (differ by -123.456789ms, within tolerance 1s)
2025/03/10 02:08:25 DEBUG : two: Destination found in --compare-dest, skipping
2025/03/10 02:08:25 DEBUG : one: Sizes differ (src 5 vs dst 3)
2025/03/10 02:08:25 DEBUG : files root 'rclone-test-nikesix4yode/dst': Waiting for checks to finish
2025/03/10 02:08:25 DEBUG : one: Size and modification time the same (differ by -123.456789ms, within tolerance 1s)
2025/03/10 02:08:25 DEBUG : one: Destination found in --compare-dest, skipping
2025/03/10 02:08:25 DEBUG : files root 'rclone-test-nikesix4yode/dst': Waiting for transfers to finish
2025/03/10 02:08:25 DEBUG : Waiting for deletions to finish
2025/03/10 02:08:25 INFO  : There was nothing to transfer
    sync_test.go:2175: No hash on uploaded file so skipping compare timestamp test
2025/03/10 02:08:26 DEBUG : two: Sizes differ (src 5 vs dst 3)
2025/03/10 02:08:26 DEBUG : two: Need to transfer - File not found at Destination
2025/03/10 02:08:26 DEBUG : files root 'rclone-test-nikesix4yode/dst': Waiting for checks to finish
2025/03/10 02:08:26 DEBUG : one: Sizes differ (src 5 vs dst 3)
2025/03/10 02:08:26 DEBUG : one: Size and modification time the same (differ by -123.456789ms, within tolerance 1s)
2025/03/10 02:08:26 DEBUG : one: Destination found in --compare-dest, skipping
2025/03/10 02:08:26 DEBUG : files root 'rclone-test-nikesix4yode/dst': Waiting for transfers to finish
2025/03/10 02:08:30 DEBUG : two: Dst hash empty - aborting Src hash check
2025/03/10 02:08:30 INFO  : two: Copied (new)
2025/03/10 02:08:30 DEBUG : Waiting for deletions to finish
--- PASS: TestSyncCompareDest (19.94s)
=== RUN   TestSyncMultipleCompareDest
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:08:34 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-nikesix4yode/dest"
2025/03/10 02:08:35 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-nikesix4yode/pre-dest1"
2025/03/10 02:08:36 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-nikesix4yode/pre-dest2"
2025/03/10 02:08:37 DEBUG : 1: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/03/10 02:08:37 DEBUG : 1: Destination found in --compare-dest, skipping
2025/03/10 02:08:37 DEBUG : 2: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/03/10 02:08:37 DEBUG : 2: Destination found in --compare-dest, skipping
2025/03/10 02:08:38 DEBUG : 3: Need to transfer - File not found at Destination
2025/03/10 02:08:38 DEBUG : files root 'rclone-test-nikesix4yode/dest': Waiting for checks to finish
2025/03/10 02:08:38 DEBUG : files root 'rclone-test-nikesix4yode/dest': Waiting for transfers to finish
2025/03/10 02:08:39 DEBUG : 3: Dst hash empty - aborting Src hash check
2025/03/10 02:08:39 INFO  : 3: Copied (new)
2025/03/10 02:08:39 DEBUG : Waiting for deletions to finish
--- PASS: TestSyncMultipleCompareDest (8.63s)
=== RUN   TestSyncCopyDest
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:08:41 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-nikesix4yode/dst"
2025/03/10 02:08:42 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-nikesix4yode/CopyDest"
2025/03/10 02:08:43 DEBUG : one: Need to transfer - File not found at Destination
2025/03/10 02:08:43 DEBUG : files root 'rclone-test-nikesix4yode/dst': Waiting for checks to finish
2025/03/10 02:08:43 DEBUG : files root 'rclone-test-nikesix4yode/dst': Waiting for transfers to finish
2025/03/10 02:08:45 DEBUG : one: Dst hash empty - aborting Src hash check
2025/03/10 02:08:45 INFO  : one: Copied (new)
2025/03/10 02:08:45 DEBUG : Waiting for deletions to finish
2025/03/10 02:08:45 DEBUG : one: Sizes differ (src 5 vs dst 3)
2025/03/10 02:08:45 DEBUG : files root 'rclone-test-nikesix4yode/dst': Waiting for checks to finish
2025/03/10 02:08:46 DEBUG : files root 'rclone-test-nikesix4yode/dst': Waiting for transfers to finish
2025/03/10 02:08:46 DEBUG : one: Dst hash empty - aborting Src hash check
2025/03/10 02:08:46 INFO  : one: Copied (replaced existing)
2025/03/10 02:08:46 DEBUG : Waiting for deletions to finish
2025/03/10 02:08:49 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-nikesix4yode/BackupDir"
2025/03/10 02:08:49 DEBUG : files root 'rclone-test-nikesix4yode/dst': Waiting for checks to finish
2025/03/10 02:08:49 DEBUG : one: Sizes differ (src 5 vs dst 3)
2025/03/10 02:08:50 DEBUG : one: Size and modification time the same (differ by -123.456789ms, within tolerance 1s)
2025/03/10 02:08:50 DEBUG : one: Sizes differ (src 5 vs dst 3)
2025/03/10 02:08:51 INFO  : one: Moved (server-side)
2025/03/10 02:08:53 DEBUG : one: Dst hash empty - aborting Src hash check
2025/03/10 02:08:53 DEBUG : one: Src hash empty - aborting Dst hash check
2025/03/10 02:08:53 INFO  : one: Copied (server-side copy)
2025/03/10 02:08:53 DEBUG : one: Destination found in --copy-dest, using server-side copy
2025/03/10 02:08:53 DEBUG : files root 'rclone-test-nikesix4yode/dst': Waiting for transfers to finish
2025/03/10 02:08:53 DEBUG : Waiting for deletions to finish
2025/03/10 02:08:55 DEBUG : two: Size and modification time the same (differ by -123.456789ms, within tolerance 1s)
2025/03/10 02:08:56 DEBUG : two: Dst hash empty - aborting Src hash check
2025/03/10 02:08:56 DEBUG : two: Src hash empty - aborting Dst hash check
2025/03/10 02:08:56 INFO  : two: Copied (server-side copy)
2025/03/10 02:08:56 DEBUG : two: Destination found in --copy-dest, using server-side copy
2025/03/10 02:08:56 DEBUG : one: Size and modification time the same (differ by -123.456789ms, within tolerance 1s)
2025/03/10 02:08:56 DEBUG : one: Unchanged skipping
2025/03/10 02:08:56 DEBUG : files root 'rclone-test-nikesix4yode/dst': Waiting for checks to finish
2025/03/10 02:08:56 DEBUG : files root 'rclone-test-nikesix4yode/dst': Waiting for transfers to finish
2025/03/10 02:08:56 DEBUG : Waiting for deletions to finish
2025/03/10 02:08:57 DEBUG : files root 'rclone-test-nikesix4yode/dst': Waiting for checks to finish
2025/03/10 02:08:57 DEBUG : one: Size and modification time the same (differ by -123.456789ms, within tolerance 1s)
2025/03/10 02:08:57 DEBUG : one: Unchanged skipping
2025/03/10 02:08:57 DEBUG : two: Size and modification time the same (differ by -123.456789ms, within tolerance 1s)
2025/03/10 02:08:57 DEBUG : two: Unchanged skipping
2025/03/10 02:08:57 DEBUG : files root 'rclone-test-nikesix4yode/dst': Waiting for transfers to finish
2025/03/10 02:08:57 DEBUG : Waiting for deletions to finish
2025/03/10 02:08:57 INFO  : There was nothing to transfer
2025/03/10 02:08:59 DEBUG : three: Sizes differ (src 7 vs dst 5)
2025/03/10 02:08:59 DEBUG : three: Destination not found in --copy-dest
2025/03/10 02:08:59 DEBUG : three: Need to transfer - File not found at Destination
2025/03/10 02:08:59 DEBUG : one: Size and modification time the same (differ by -123.456789ms, within tolerance 1s)
2025/03/10 02:08:59 DEBUG : one: Unchanged skipping
2025/03/10 02:08:59 DEBUG : two: Size and modification time the same (differ by -123.456789ms, within tolerance 1s)
2025/03/10 02:08:59 DEBUG : two: Unchanged skipping
2025/03/10 02:08:59 DEBUG : files root 'rclone-test-nikesix4yode/dst': Waiting for checks to finish
2025/03/10 02:08:59 DEBUG : files root 'rclone-test-nikesix4yode/dst': Waiting for transfers to finish
2025/03/10 02:09:00 DEBUG : three: Dst hash empty - aborting Src hash check
2025/03/10 02:09:00 INFO  : three: Copied (new)
2025/03/10 02:09:00 DEBUG : Waiting for deletions to finish
--- PASS: TestSyncCopyDest (21.42s)
=== RUN   TestSyncBackupDir
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:09:05 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-nikesix4yode/dst"
2025/03/10 02:09:06 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-nikesix4yode/backup"
2025/03/10 02:09:07 DEBUG : one: Sizes differ (src 4 vs dst 3)
2025/03/10 02:09:07 DEBUG : files root 'rclone-test-nikesix4yode/dst': Waiting for checks to finish
2025/03/10 02:09:07 DEBUG : two: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/03/10 02:09:07 DEBUG : two: Unchanged skipping
2025/03/10 02:09:07 INFO  : one: Moved (server-side)
2025/03/10 02:09:07 DEBUG : files root 'rclone-test-nikesix4yode/dst': Waiting for transfers to finish
2025/03/10 02:09:09 DEBUG : one: Dst hash empty - aborting Src hash check
2025/03/10 02:09:09 INFO  : one: Copied (new)
2025/03/10 02:09:09 DEBUG : Waiting for deletions to finish
2025/03/10 02:09:09 INFO  : three.txt: Moved (server-side)
2025/03/10 02:09:09 INFO  : three.txt: Moved into backup dir
2025/03/10 02:09:14 DEBUG : one: Sizes differ (src 5 vs dst 4)
2025/03/10 02:09:14 DEBUG : files root 'rclone-test-nikesix4yode/dst': Waiting for checks to finish
2025/03/10 02:09:14 DEBUG : two: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/03/10 02:09:14 DEBUG : two: Unchanged skipping
2025/03/10 02:09:14 INFO  : one: Deleted
2025/03/10 02:09:15 INFO  : one: Moved (server-side)
2025/03/10 02:09:15 DEBUG : files root 'rclone-test-nikesix4yode/dst': Waiting for transfers to finish
2025/03/10 02:09:16 DEBUG : one: Dst hash empty - aborting Src hash check
2025/03/10 02:09:16 INFO  : one: Copied (new)
2025/03/10 02:09:16 DEBUG : Waiting for deletions to finish
2025/03/10 02:09:16 INFO  : three.txt: Deleted
2025/03/10 02:09:17 INFO  : three.txt: Moved (server-side)
2025/03/10 02:09:17 INFO  : three.txt: Moved into backup dir
--- PASS: TestSyncBackupDir (16.13s)
=== RUN   TestSyncBackupDirWithSuffix
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:09:21 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-nikesix4yode/dst"
2025/03/10 02:09:22 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-nikesix4yode/backup"
2025/03/10 02:09:22 DEBUG : one: Sizes differ (src 4 vs dst 3)
2025/03/10 02:09:22 DEBUG : two: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/03/10 02:09:22 DEBUG : two: Unchanged skipping
2025/03/10 02:09:22 DEBUG : files root 'rclone-test-nikesix4yode/dst': Waiting for checks to finish
2025/03/10 02:09:23 INFO  : one: Moved (server-side) to: one.bak
2025/03/10 02:09:23 DEBUG : files root 'rclone-test-nikesix4yode/dst': Waiting for transfers to finish
2025/03/10 02:09:24 DEBUG : one: Dst hash empty - aborting Src hash check
2025/03/10 02:09:24 INFO  : one: Copied (new)
2025/03/10 02:09:24 DEBUG : Waiting for deletions to finish
2025/03/10 02:09:25 INFO  : three.txt: Moved (server-side) to: three.txt.bak
2025/03/10 02:09:25 INFO  : three.txt: Moved into backup dir
2025/03/10 02:09:26 DEBUG : one: Sizes differ (src 5 vs dst 4)
2025/03/10 02:09:26 DEBUG : two: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/03/10 02:09:26 DEBUG : two: Unchanged skipping
2025/03/10 02:09:26 DEBUG : files root 'rclone-test-nikesix4yode/dst': Waiting for checks to finish
2025/03/10 02:09:27 INFO  : one.bak: Deleted
2025/03/10 02:09:27 INFO  : one: Moved (server-side) to: one.bak
2025/03/10 02:09:27 DEBUG : files root 'rclone-test-nikesix4yode/dst': Waiting for transfers to finish
2025/03/10 02:09:28 DEBUG : one: Dst hash empty - aborting Src hash check
2025/03/10 02:09:28 INFO  : one: Copied (new)
2025/03/10 02:09:28 DEBUG : Waiting for deletions to finish
2025/03/10 02:09:28 INFO  : three.txt.bak: Deleted
2025/03/10 02:09:29 INFO  : three.txt: Moved (server-side) to: three.txt.bak
2025/03/10 02:09:29 INFO  : three.txt: Moved into backup dir
--- PASS: TestSyncBackupDirWithSuffix (11.76s)
=== RUN   TestSyncBackupDirWithSuffixKeepExtension
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:09:33 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-nikesix4yode/dst"
2025/03/10 02:09:33 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-nikesix4yode/backup"
2025/03/10 02:09:34 DEBUG : two: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/03/10 02:09:34 DEBUG : two: Unchanged skipping
2025/03/10 02:09:34 DEBUG : one: Sizes differ (src 4 vs dst 3)
2025/03/10 02:09:34 DEBUG : files root 'rclone-test-nikesix4yode/dst': Waiting for checks to finish
2025/03/10 02:09:35 INFO  : one: Moved (server-side) to: one-2019-01-01
2025/03/10 02:09:35 DEBUG : files root 'rclone-test-nikesix4yode/dst': Waiting for transfers to finish
2025/03/10 02:09:37 DEBUG : one: Dst hash empty - aborting Src hash check
2025/03/10 02:09:37 INFO  : one: Copied (new)
2025/03/10 02:09:37 DEBUG : Waiting for deletions to finish
2025/03/10 02:09:38 INFO  : three.txt: Moved (server-side) to: three-2019-01-01.txt
2025/03/10 02:09:38 INFO  : three.txt: Moved into backup dir
2025/03/10 02:09:39 DEBUG : one: Sizes differ (src 5 vs dst 4)
2025/03/10 02:09:39 DEBUG : two: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/03/10 02:09:39 DEBUG : two: Unchanged skipping
2025/03/10 02:09:39 DEBUG : files root 'rclone-test-nikesix4yode/dst': Waiting for checks to finish
2025/03/10 02:09:40 INFO  : one-2019-01-01: Deleted
2025/03/10 02:09:40 INFO  : one: Moved (server-side) to: one-2019-01-01
2025/03/10 02:09:40 DEBUG : files root 'rclone-test-nikesix4yode/dst': Waiting for transfers to finish
2025/03/10 02:09:41 DEBUG : one: Dst hash empty - aborting Src hash check
2025/03/10 02:09:41 INFO  : one: Copied (new)
2025/03/10 02:09:41 DEBUG : Waiting for deletions to finish
2025/03/10 02:09:41 INFO  : three-2019-01-01.txt: Deleted
2025/03/10 02:09:42 INFO  : three.txt: Moved (server-side) to: three-2019-01-01.txt
2025/03/10 02:09:42 INFO  : three.txt: Moved into backup dir
--- PASS: TestSyncBackupDirWithSuffixKeepExtension (13.20s)
=== RUN   TestSyncBackupDirSuffixOnly
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:09:50 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-nikesix4yode/dst"
2025/03/10 02:09:51 DEBUG : files root 'rclone-test-nikesix4yode/dst': Waiting for checks to finish
2025/03/10 02:09:51 DEBUG : two: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/03/10 02:09:51 DEBUG : one: Sizes differ (src 4 vs dst 3)
2025/03/10 02:09:51 DEBUG : two: Unchanged skipping
2025/03/10 02:09:52 INFO  : one: Moved (server-side) to: one.bak
2025/03/10 02:09:52 DEBUG : files root 'rclone-test-nikesix4yode/dst': Waiting for transfers to finish
2025/03/10 02:09:53 DEBUG : one: Dst hash empty - aborting Src hash check
2025/03/10 02:09:53 INFO  : one: Copied (new)
2025/03/10 02:09:53 DEBUG : Waiting for deletions to finish
2025/03/10 02:09:54 INFO  : three.txt: Moved (server-side) to: three.txt.bak
2025/03/10 02:09:54 INFO  : three.txt: Moved into backup dir
2025/03/10 02:09:56 DEBUG : one.bak: Excluded (Path Filter)
2025/03/10 02:09:56 DEBUG : one.bak: Excluded
2025/03/10 02:09:56 DEBUG : three.txt.bak: Excluded (Path Filter)
2025/03/10 02:09:56 DEBUG : three.txt.bak: Excluded
2025/03/10 02:09:56 DEBUG : one: Sizes differ (src 5 vs dst 4)
2025/03/10 02:09:56 DEBUG : two: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/03/10 02:09:56 DEBUG : two: Unchanged skipping
2025/03/10 02:09:56 DEBUG : files root 'rclone-test-nikesix4yode/dst': Waiting for checks to finish
2025/03/10 02:09:56 INFO  : one.bak: Deleted
2025/03/10 02:09:56 INFO  : one: Moved (server-side) to: one.bak
2025/03/10 02:09:56 DEBUG : files root 'rclone-test-nikesix4yode/dst': Waiting for transfers to finish
2025/03/10 02:09:59 DEBUG : one: Dst hash empty - aborting Src hash check
2025/03/10 02:09:59 INFO  : one: Copied (new)
2025/03/10 02:09:59 DEBUG : Waiting for deletions to finish
2025/03/10 02:09:59 INFO  : three.txt.bak: Deleted
2025/03/10 02:10:00 INFO  : three.txt: Moved (server-side) to: three.txt.bak
2025/03/10 02:10:00 INFO  : three.txt: Moved into backup dir
--- PASS: TestSyncBackupDirSuffixOnly (18.21s)
=== RUN   TestSyncSuffix
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:10:05 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-nikesix4yode/dst"
2025/03/10 02:10:07 DEBUG : one: Sizes differ (src 4 vs dst 3)
2025/03/10 02:10:08 INFO  : one: Moved (server-side) to: one.bak
2025/03/10 02:10:09 DEBUG : one: Dst hash empty - aborting Src hash check
2025/03/10 02:10:09 INFO  : one: Copied (new)
2025/03/10 02:10:10 DEBUG : two: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/03/10 02:10:10 DEBUG : two: Unchanged skipping
2025/03/10 02:10:10 DEBUG : three.txt: Sizes differ (src 6 vs dst 5)
2025/03/10 02:10:10 INFO  : three.txt: Moved (server-side) to: three.txt.bak
2025/03/10 02:10:11 DEBUG : three.txt: Dst hash empty - aborting Src hash check
2025/03/10 02:10:11 INFO  : three.txt: Copied (new)
2025/03/10 02:10:12 DEBUG : one: Sizes differ (src 5 vs dst 4)
2025/03/10 02:10:12 INFO  : one.bak: Deleted
2025/03/10 02:10:13 INFO  : one: Moved (server-side) to: one.bak
2025/03/10 02:10:13 DEBUG : one: Dst hash empty - aborting Src hash check
2025/03/10 02:10:13 INFO  : one: Copied (new)
2025/03/10 02:10:14 DEBUG : two: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/03/10 02:10:14 DEBUG : two: Unchanged skipping
2025/03/10 02:10:14 DEBUG : three.txt: Sizes differ (src 19 vs dst 6)
2025/03/10 02:10:14 INFO  : three.txt.bak: Deleted
2025/03/10 02:10:14 INFO  : three.txt: Moved (server-side) to: three.txt.bak
2025/03/10 02:10:15 DEBUG : three.txt: Dst hash empty - aborting Src hash check
2025/03/10 02:10:15 INFO  : three.txt: Copied (new)
--- PASS: TestSyncSuffix (15.33s)
=== RUN   TestSyncSuffixKeepExtension
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
    fstest.go:292: Sleeping for 1s for list eventual consistency: 1/3
    fstest.go:292: Sleeping for 2s for list eventual consistency: 2/3
    fstest.go:292: Sleeping for 4s for list eventual consistency: 3/3
    fstest.go:299: 
        	Error Trace:	/home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:299
        	            				/home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:332
        	            				/home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:344
        	            				/home/rclone/go/src/github.com/rclone/rclone/fstest/run.go:340
        	            				/home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync_test.go:2465
        	            				/home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync_test.go:2524
        	Error:      	Should be true
        	Test:       	TestSyncSuffixKeepExtension
        	Messages:   	listing wrong, want
        	            	  dst/one (3), dst/three.txt (5), dst/two (3) got
        	            	  dst/three.txt (5), dst/two (3)
    fstest.go:197: Not found "dst/one"
    fstest.go:200: 
        	Error Trace:	/home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:200
        	            				/home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:304
        	            				/home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:332
        	            				/home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:344
        	            				/home/rclone/go/src/github.com/rclone/rclone/fstest/run.go:340
        	            				/home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync_test.go:2465
        	            				/home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync_test.go:2524
        	Error:      	Not equal: 
        	            	expected: 0
        	            	actual  : 1
        	Test:       	TestSyncSuffixKeepExtension
        	Messages:   	1 objects not found
2025/03/10 02:10:27 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-nikesix4yode/dst"
2025/03/10 02:10:28 DEBUG : one: Sizes differ (src 4 vs dst 3)
2025/03/10 02:10:29 INFO  : one: Moved (server-side) to: one-2019-01-01
2025/03/10 02:10:30 DEBUG : one: Dst hash empty - aborting Src hash check
2025/03/10 02:10:30 INFO  : one: Copied (new)
2025/03/10 02:10:30 DEBUG : two: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/03/10 02:10:30 DEBUG : two: Unchanged skipping
2025/03/10 02:10:30 DEBUG : three.txt: Sizes differ (src 6 vs dst 5)
2025/03/10 02:10:31 INFO  : three.txt: Moved (server-side) to: three-2019-01-01.txt
2025/03/10 02:10:32 DEBUG : three.txt: Dst hash empty - aborting Src hash check
2025/03/10 02:10:32 INFO  : three.txt: Copied (new)
2025/03/10 02:10:34 DEBUG : one: Sizes differ (src 5 vs dst 4)
2025/03/10 02:10:34 INFO  : one-2019-01-01: Deleted
2025/03/10 02:10:34 INFO  : one: Moved (server-side) to: one-2019-01-01
2025/03/10 02:10:35 DEBUG : one: Dst hash empty - aborting Src hash check
2025/03/10 02:10:35 INFO  : one: Copied (new)
2025/03/10 02:10:35 DEBUG : two: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/03/10 02:10:35 DEBUG : two: Unchanged skipping
2025/03/10 02:10:35 DEBUG : three.txt: Sizes differ (src 19 vs dst 6)
2025/03/10 02:10:36 INFO  : three-2019-01-01.txt: Deleted
2025/03/10 02:10:36 INFO  : three.txt: Moved (server-side) to: three-2019-01-01.txt
2025/03/10 02:10:37 DEBUG : three.txt: Dst hash empty - aborting Src hash check
2025/03/10 02:10:37 INFO  : three.txt: Copied (new)
--- FAIL: TestSyncSuffixKeepExtension (21.51s)
=== RUN   TestSyncUTFNorm
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:10:40 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for checks to finish
2025/03/10 02:10:40 DEBUG : Testêé: Sizes differ (src 14 vs dst 18)
2025/03/10 02:10:40 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for transfers to finish
2025/03/10 02:10:40 DEBUG : Testêé: Dst hash empty - aborting Src hash check
2025/03/10 02:10:40 INFO  : Testêé: Copied (replaced existing) to: Testêé
2025/03/10 02:10:40 DEBUG : Waiting for deletions to finish
--- PASS: TestSyncUTFNorm (2.47s)
=== RUN   TestSyncImmutable
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:10:41 DEBUG : existing: Need to transfer - File not found at Destination
2025/03/10 02:10:41 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for checks to finish
2025/03/10 02:10:41 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for transfers to finish
2025/03/10 02:10:42 DEBUG : existing: Dst hash empty - aborting Src hash check
2025/03/10 02:10:42 INFO  : existing: Copied (new)
2025/03/10 02:10:42 DEBUG : Waiting for deletions to finish
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:10:43 DEBUG : existing: Sizes differ (src 8 vs dst 6)
2025/03/10 02:10:43 ERROR : existing: Source and destination exist but do not match: immutable file modified
2025/03/10 02:10:43 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for checks to finish
2025/03/10 02:10:43 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for transfers to finish
2025/03/10 02:10:43 ERROR : files root 'rclone-test-nikesix4yode': not deleting files as there were IO errors
2025/03/10 02:10:43 ERROR : files root 'rclone-test-nikesix4yode': not deleting directories as there were IO errors
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
--- PASS: TestSyncImmutable (2.96s)
=== RUN   TestSyncIgnoreCase
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
    sync_test.go:2606: Skipping test as local or remote are case-insensitive
--- SKIP: TestSyncIgnoreCase (0.25s)
=== RUN   TestFixCase
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:10:49 DEBUG : existing: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/03/10 02:10:49 DEBUG : existing: Unchanged skipping
2025/03/10 02:10:49 DEBUG : existingbutdifferent: Sizes differ (src 5 vs dst 8)
2025/03/10 02:10:49 DEBUG : EXISTINGBUTDIFFERENT: moving to existingbutdifferent-rclone-move-vodumuy6
2025/03/10 02:10:49 DEBUG : EXISTING: moving to existing-rclone-move-tafogep5
2025/03/10 02:10:49 INFO  : SUBDIRA: Set directory modification time (using DirSetModTime)
2025/03/10 02:10:49 DEBUG : Added delayed dir = "SUBDIRA", newDst=SUBDIRA
2025/03/10 02:10:50 INFO  : EXISTING: Moved (server-side) to: existing-rclone-move-tafogep5
2025/03/10 02:10:50 DEBUG : EXISTING: moving to existing
2025/03/10 02:10:50 INFO  : EXISTINGBUTDIFFERENT: Moved (server-side) to: existingbutdifferent-rclone-move-vodumuy6
2025/03/10 02:10:50 DEBUG : EXISTINGBUTDIFFERENT: moving to existingbutdifferent
2025/03/10 02:10:50 INFO  : existing-rclone-move-tafogep5: Moved (server-side) to: existing
2025/03/10 02:10:50 INFO  : EXISTING: Moved (server-side) to: existing
2025/03/10 02:10:50 INFO  : EXISTING: Fixed case by renaming to: existing
2025/03/10 02:10:50 INFO  : existingbutdifferent-rclone-move-vodumuy6: Moved (server-side) to: existingbutdifferent
2025/03/10 02:10:50 INFO  : EXISTINGBUTDIFFERENT: Moved (server-side) to: existingbutdifferent
2025/03/10 02:10:50 INFO  : EXISTINGBUTDIFFERENT: Fixed case by renaming to: existingbutdifferent
2025/03/10 02:10:51 DEBUG : existingbutdifferent: Dst hash empty - aborting Src hash check
2025/03/10 02:10:51 INFO  : existingbutdifferent: Copied (replaced existing)
2025/03/10 02:10:51 INFO  : SUBDIRA: Fixed case by renaming to: subdira
2025/03/10 02:10:52 INFO  : SUBDIRA/subdirb: Set directory modification time (using DirSetModTime)
2025/03/10 02:10:52 DEBUG : Added delayed dir = "SUBDIRA/subdirb", newDst=SUBDIRA/subdirb
2025/03/10 02:10:53 INFO  : SUBDIRA/subdirb: Fixed case by renaming to: subdira/subdirb
2025/03/10 02:10:53 INFO  : SUBDIRA/subdirb/SUBDIRC: Set directory modification time (using DirSetModTime)
2025/03/10 02:10:53 DEBUG : Added delayed dir = "SUBDIRA/subdirb/SUBDIRC", newDst=SUBDIRA/subdirb/SUBDIRC
2025/03/10 02:10:54 INFO  : SUBDIRA/subdirb/SUBDIRC: Fixed case by renaming to: subdira/subdirb/subdirc
2025/03/10 02:10:55 DEBUG : subdira/subdirb/subdirc/hello: Sizes differ (src 5 vs dst 8)
2025/03/10 02:10:55 DEBUG : SUBDIRA/subdirb/SUBDIRC/HELLO: moving to subdira/subdirb/subdirc/hello-rclone-move-hikubow3
2025/03/10 02:10:55 INFO  : SUBDIRA/subdirb/SUBDIRC/subdird: Set directory modification time (using DirSetModTime)
2025/03/10 02:10:55 DEBUG : Added delayed dir = "SUBDIRA/subdirb/SUBDIRC/subdird", newDst=SUBDIRA/subdirb/SUBDIRC/subdird
2025/03/10 02:10:55 INFO  : SUBDIRA/subdirb/SUBDIRC/HELLO: Moved (server-side) to: subdira/subdirb/subdirc/hello-rclone-move-hikubow3
2025/03/10 02:10:55 DEBUG : SUBDIRA/subdirb/SUBDIRC/HELLO: moving to subdira/subdirb/subdirc/hello
2025/03/10 02:10:56 INFO  : SUBDIRA/subdirb/SUBDIRC/subdird: Fixed case by renaming to: subdira/subdirb/subdirc/subdird
2025/03/10 02:10:56 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for checks to finish
2025/03/10 02:10:56 DEBUG : subdira/subdirb/subdirc/subdird/filewithoutcasedifferences: Sizes differ (src 5 vs dst 8)
2025/03/10 02:10:56 DEBUG : SUBDIRA/subdirb/SUBDIRC/subdird/filewithoutcasedifferences: moving to subdira/subdirb/subdirc/subdird/filewithoutcasedifferences-rclone-move-nodocod9
2025/03/10 02:10:56 INFO  : subdira/subdirb/subdirc/hello-rclone-move-hikubow3: Moved (server-side) to: subdira/subdirb/subdirc/hello
2025/03/10 02:10:56 INFO  : SUBDIRA/subdirb/SUBDIRC/HELLO: Moved (server-side) to: subdira/subdirb/subdirc/hello
2025/03/10 02:10:56 INFO  : SUBDIRA/subdirb/SUBDIRC/HELLO: Fixed case by renaming to: subdira/subdirb/subdirc/hello
2025/03/10 02:10:57 DEBUG : subdira/subdirb/subdirc/hello: Dst hash empty - aborting Src hash check
2025/03/10 02:10:57 INFO  : subdira/subdirb/subdirc/hello: Copied (replaced existing)
2025/03/10 02:10:58 INFO  : SUBDIRA/subdirb/SUBDIRC/subdird/filewithoutcasedifferences: Moved (server-side) to: subdira/subdirb/subdirc/subdird/filewithoutcasedifferences-rclone-move-nodocod9
2025/03/10 02:10:58 DEBUG : SUBDIRA/subdirb/SUBDIRC/subdird/filewithoutcasedifferences: moving to subdira/subdirb/subdirc/subdird/filewithoutcasedifferences
2025/03/10 02:10:59 INFO  : subdira/subdirb/subdirc/subdird/filewithoutcasedifferences-rclone-move-nodocod9: Moved (server-side) to: subdira/subdirb/subdirc/subdird/filewithoutcasedifferences
2025/03/10 02:10:59 INFO  : SUBDIRA/subdirb/SUBDIRC/subdird/filewithoutcasedifferences: Moved (server-side) to: subdira/subdirb/subdirc/subdird/filewithoutcasedifferences
2025/03/10 02:10:59 INFO  : SUBDIRA/subdirb/SUBDIRC/subdird/filewithoutcasedifferences: Fixed case by renaming to: subdira/subdirb/subdirc/subdird/filewithoutcasedifferences
2025/03/10 02:10:59 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for transfers to finish
2025/03/10 02:11:00 DEBUG : subdira/subdirb/subdirc/subdird/filewithoutcasedifferences: Dst hash empty - aborting Src hash check
2025/03/10 02:11:00 INFO  : subdira/subdirb/subdirc/subdird/filewithoutcasedifferences: Copied (replaced existing)
2025/03/10 02:11:00 DEBUG : Waiting for deletions to finish
2025/03/10 02:11:02 DEBUG : pacer: low level retry 1/10 (error Folder Not Empty - `Folder rclone-test-nikesix4yode/subdira/subdirb/subdirc not empty`)
2025/03/10 02:11:02 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2025/03/10 02:11:02 DEBUG : pacer: Reducing sleep to 15ms
2025/03/10 02:11:02 DEBUG : pacer: low level retry 1/10 (error Folder Not Empty - `Folder rclone-test-nikesix4yode/subdira/subdirb not empty`)
2025/03/10 02:11:02 DEBUG : pacer: Rate limited, increasing sleep to 30ms
2025/03/10 02:11:02 DEBUG : pacer: low level retry 2/10 (error Folder Not Empty - `Folder rclone-test-nikesix4yode/subdira/subdirb not empty`)
2025/03/10 02:11:02 DEBUG : pacer: Rate limited, increasing sleep to 60ms
2025/03/10 02:11:03 DEBUG : pacer: low level retry 3/10 (error Folder Not Empty - `Folder rclone-test-nikesix4yode/subdira/subdirb not empty`)
2025/03/10 02:11:03 DEBUG : pacer: Rate limited, increasing sleep to 120ms
2025/03/10 02:11:03 DEBUG : pacer: Reducing sleep to 90ms
2025/03/10 02:11:03 DEBUG : pacer: Reducing sleep to 67.5ms
2025/03/10 02:11:03 DEBUG : pacer: Reducing sleep to 50.625ms
--- PASS: TestFixCase (18.95s)
=== RUN   TestMaxTransfer
=== RUN   TestMaxTransfer/Hard
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
    sync_test.go:2674: This test only runs on local
2025/03/10 02:11:03 DEBUG : pacer: Reducing sleep to 37.96875ms
2025/03/10 02:11:03 DEBUG : pacer: Reducing sleep to 28.476562ms
=== RUN   TestMaxTransfer/Soft
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
    sync_test.go:2674: This test only runs on local
2025/03/10 02:11:03 DEBUG : pacer: Reducing sleep to 21.357421ms
2025/03/10 02:11:03 DEBUG : pacer: Reducing sleep to 16.018065ms
=== RUN   TestMaxTransfer/Cautious
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
    sync_test.go:2674: This test only runs on local
2025/03/10 02:11:04 DEBUG : pacer: Reducing sleep to 12.013548ms
2025/03/10 02:11:04 DEBUG : pacer: Reducing sleep to 10ms
--- PASS: TestMaxTransfer (0.77s)
    --- SKIP: TestMaxTransfer/Hard (0.27s)
    --- SKIP: TestMaxTransfer/Soft (0.25s)
    --- SKIP: TestMaxTransfer/Cautious (0.25s)
=== RUN   TestSyncConcurrentDelete
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:11:38 DEBUG : both0: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/03/10 02:11:38 DEBUG : both0: Unchanged skipping
2025/03/10 02:11:38 DEBUG : both1: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/03/10 02:11:38 DEBUG : both1: Unchanged skipping
2025/03/10 02:11:38 DEBUG : both10: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/03/10 02:11:38 DEBUG : both10: Unchanged skipping
2025/03/10 02:11:38 DEBUG : both11: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/03/10 02:11:38 DEBUG : both11: Unchanged skipping
2025/03/10 02:11:38 DEBUG : both12: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/03/10 02:11:38 DEBUG : both12: Unchanged skipping
2025/03/10 02:11:38 DEBUG : both13: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/03/10 02:11:38 DEBUG : both13: Unchanged skipping
2025/03/10 02:11:38 DEBUG : both14: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/03/10 02:11:38 DEBUG : both14: Unchanged skipping
2025/03/10 02:11:38 DEBUG : both15: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/03/10 02:11:38 DEBUG : both15: Unchanged skipping
2025/03/10 02:11:38 DEBUG : both16: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/03/10 02:11:38 DEBUG : both17: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/03/10 02:11:38 DEBUG : both18: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/03/10 02:11:38 DEBUG : both19: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/03/10 02:11:38 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for checks to finish
2025/03/10 02:11:38 DEBUG : both16: Unchanged skipping
2025/03/10 02:11:38 DEBUG : both2: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/03/10 02:11:38 DEBUG : both2: Unchanged skipping
2025/03/10 02:11:38 DEBUG : both3: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/03/10 02:11:38 DEBUG : both17: Unchanged skipping
2025/03/10 02:11:38 DEBUG : both4: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/03/10 02:11:38 DEBUG : both4: Unchanged skipping
2025/03/10 02:11:38 DEBUG : both5: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/03/10 02:11:38 DEBUG : both18: Unchanged skipping
2025/03/10 02:11:38 DEBUG : both6: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/03/10 02:11:38 DEBUG : both6: Unchanged skipping
2025/03/10 02:11:38 DEBUG : both7: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/03/10 02:11:38 DEBUG : both7: Unchanged skipping
2025/03/10 02:11:38 DEBUG : both8: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/03/10 02:11:38 DEBUG : both8: Unchanged skipping
2025/03/10 02:11:38 DEBUG : both9: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/03/10 02:11:38 DEBUG : both9: Unchanged skipping
2025/03/10 02:11:38 DEBUG : both19: Unchanged skipping
2025/03/10 02:11:38 DEBUG : both3: Unchanged skipping
2025/03/10 02:11:38 DEBUG : both5: Unchanged skipping
2025/03/10 02:11:38 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for transfers to finish
2025/03/10 02:11:38 DEBUG : Waiting for deletions to finish
2025/03/10 02:11:38 INFO  : only10: Deleted
2025/03/10 02:11:38 INFO  : only11: Deleted
2025/03/10 02:11:38 INFO  : only12: Deleted
2025/03/10 02:11:38 INFO  : only5: Deleted
2025/03/10 02:11:38 INFO  : only6: Deleted
2025/03/10 02:11:38 INFO  : only7: Deleted
2025/03/10 02:11:38 INFO  : only15: Deleted
2025/03/10 02:11:38 INFO  : only14: Deleted
2025/03/10 02:11:38 INFO  : only0: Deleted
2025/03/10 02:11:38 INFO  : only13: Deleted
2025/03/10 02:11:39 INFO  : only17: Deleted
2025/03/10 02:11:39 INFO  : only19: Deleted
2025/03/10 02:11:39 INFO  : only9: Deleted
2025/03/10 02:11:39 INFO  : only1: Deleted
2025/03/10 02:11:39 INFO  : only16: Deleted
2025/03/10 02:11:39 INFO  : only18: Deleted
2025/03/10 02:11:39 INFO  : only2: Deleted
2025/03/10 02:11:39 INFO  : only3: Deleted
2025/03/10 02:11:39 INFO  : only4: Deleted
2025/03/10 02:11:39 INFO  : only8: Deleted
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
--- PASS: TestSyncConcurrentDelete (39.10s)
=== RUN   TestSyncConcurrentTruncate
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:11:44 DEBUG : pacer: low level retry 1/10 (error Put "https://s3.amazonaws.com/objects.brickftp.com/metadata/126732/f7efd265-3b98-4b72-a4de-2b02a60c6d86?X-Amz-Algorithm=AWS4-HMAC-SHA256&X-Amz-Credential=AKIAIEWLY3MN4YGZQOWA%2F20250310%2Fus-east-1%2Fs3%2Faws4_request&X-Amz-Date=20250310T021143Z&X-Amz-Expires=900&X-Amz-SignedHeaders=host&partNumber=1&response-content-type=application%2Foctet-stream&uploadId=7J37KXjhhOaPud4sw6iUufjrMTmQe_uqbobrDDgWc9QtkE1RdVnfu1VQnpqX0_wll5KbB1JmkmTI4rOgKpOvEusvYlETYLu4FrZcy5k3q8Hz9WrCPWGLx_FiQoVgh96L&X-Amz-Signature=70044f446a19f9faf7666d0eb2fe8c665e5fdd2f4b185c8047028bc91f41f67e": net/http: HTTP/1.x transport connection broken: http: ContentLength=6 with Body length 0)
2025/03/10 02:11:44 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2025/03/10 02:11:45 DEBUG : pacer: Reducing sleep to 15ms
2025/03/10 02:11:45 DEBUG : pacer: Reducing sleep to 11.25ms
2025/03/10 02:11:46 DEBUG : pacer: Reducing sleep to 10ms
    fstest.go:292: Sleeping for 1s for list eventual consistency: 1/3
    fstest.go:292: Sleeping for 2s for list eventual consistency: 2/3
    fstest.go:292: Sleeping for 4s for list eventual consistency: 3/3
    fstest.go:299: 
        	Error Trace:	/home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:299
        	            				/home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:332
        	            				/home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:344
        	            				/home/rclone/go/src/github.com/rclone/rclone/fstest/run.go:340
        	            				/home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync_test.go:2744
        	            				/home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync_test.go:2762
        	Error:      	Should be true
        	Test:       	TestSyncConcurrentTruncate
        	Messages:   	listing wrong, want
        	            	  both0 (6), both1 (6), both10 (6), both11 (6), both12 (6), both13 (6), both14 (6), both15 (6), both16 (6), both17 (6), both18 (6), both19 (6), both2 (6), both3 (6), both4 (6), both5 (6), both6 (6), both7 (6), both8 (6), both9 (6), only0 (6), only1 (6), only10 (6), only11 (6), only12 (6), only13 (6), only14 (6), only15 (6), only16 (6), only17 (6), only18 (6), only19 (6), only2 (6), only3 (6), only4 (6), only5 (6), only6 (6), only7 (6), only8 (6), only9 (6) got
        	            	  both0 (0), both1 (6), both10 (6), both11 (6), both12 (6), both13 (6), both14 (6), both15 (6), both16 (6), both17 (6), both18 (6), both19 (6), both2 (6), both3 (6), both4 (6), both5 (6), both6 (6), both7 (6), both8 (6), both9 (6), only0 (6), only1 (6), only10 (6), only11 (6), only12 (6), only13 (6), only14 (6), only15 (6), only16 (6), only17 (6), only18 (6), only19 (6), only2 (6), only3 (6), only4 (6), only5 (6), only6 (6), only7 (6), only8 (6), only9 (6)
    fstest.go:144: 
        	Error Trace:	/home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:144
        	            				/home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:189
        	            				/home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:302
        	            				/home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:332
        	            				/home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:344
        	            				/home/rclone/go/src/github.com/rclone/rclone/fstest/run.go:340
        	            				/home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync_test.go:2744
        	            				/home/rclone/go/src/github.com/rclone/rclone/fs/sync/sync_test.go:2762
        	Error:      	Not equal: 
        	            	expected: 6
        	            	actual  : 0
        	Test:       	TestSyncConcurrentTruncate
        	Messages:   	both0: size incorrect file=6 vs obj=0
2025/03/10 02:12:25 DEBUG : both1: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/03/10 02:12:25 DEBUG : both0: Sizes differ (src 6 vs dst 0)
2025/03/10 02:12:25 DEBUG : both10: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/03/10 02:12:25 DEBUG : both11: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/03/10 02:12:25 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for checks to finish
2025/03/10 02:12:25 DEBUG : both1: Unchanged skipping
2025/03/10 02:12:25 DEBUG : both12: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/03/10 02:12:25 DEBUG : both13: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/03/10 02:12:25 DEBUG : both10: Unchanged skipping
2025/03/10 02:12:25 DEBUG : both14: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/03/10 02:12:25 DEBUG : both14: Unchanged skipping
2025/03/10 02:12:25 DEBUG : both15: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/03/10 02:12:25 DEBUG : both11: Unchanged skipping
2025/03/10 02:12:25 DEBUG : both16: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/03/10 02:12:25 DEBUG : both12: Unchanged skipping
2025/03/10 02:12:25 DEBUG : both17: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/03/10 02:12:25 DEBUG : both13: Unchanged skipping
2025/03/10 02:12:25 DEBUG : both18: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/03/10 02:12:25 DEBUG : both18: Unchanged skipping
2025/03/10 02:12:25 DEBUG : both19: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/03/10 02:12:25 DEBUG : both19: Unchanged skipping
2025/03/10 02:12:25 DEBUG : both2: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/03/10 02:12:25 DEBUG : both15: Unchanged skipping
2025/03/10 02:12:25 DEBUG : both3: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/03/10 02:12:25 DEBUG : both3: Unchanged skipping
2025/03/10 02:12:25 DEBUG : both4: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/03/10 02:12:25 DEBUG : both16: Unchanged skipping
2025/03/10 02:12:25 DEBUG : both5: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/03/10 02:12:25 DEBUG : both5: Unchanged skipping
2025/03/10 02:12:25 DEBUG : both6: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/03/10 02:12:25 DEBUG : both17: Unchanged skipping
2025/03/10 02:12:25 DEBUG : both7: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/03/10 02:12:25 DEBUG : both7: Unchanged skipping
2025/03/10 02:12:25 DEBUG : both8: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/03/10 02:12:25 DEBUG : both2: Unchanged skipping
2025/03/10 02:12:25 DEBUG : both9: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/03/10 02:12:25 DEBUG : both4: Unchanged skipping
2025/03/10 02:12:25 DEBUG : only0: Sizes differ (src 0 vs dst 6)
2025/03/10 02:12:25 DEBUG : both6: Unchanged skipping
2025/03/10 02:12:25 DEBUG : only1: Sizes differ (src 0 vs dst 6)
2025/03/10 02:12:25 DEBUG : both8: Unchanged skipping
2025/03/10 02:12:25 DEBUG : only10: Sizes differ (src 0 vs dst 6)
2025/03/10 02:12:25 DEBUG : both9: Unchanged skipping
2025/03/10 02:12:25 DEBUG : only11: Sizes differ (src 0 vs dst 6)
2025/03/10 02:12:25 DEBUG : only12: Sizes differ (src 0 vs dst 6)
2025/03/10 02:12:25 DEBUG : only13: Sizes differ (src 0 vs dst 6)
2025/03/10 02:12:25 DEBUG : only14: Sizes differ (src 0 vs dst 6)
2025/03/10 02:12:25 DEBUG : only15: Sizes differ (src 0 vs dst 6)
2025/03/10 02:12:25 DEBUG : only16: Sizes differ (src 0 vs dst 6)
2025/03/10 02:12:25 DEBUG : only17: Sizes differ (src 0 vs dst 6)
2025/03/10 02:12:25 DEBUG : only18: Sizes differ (src 0 vs dst 6)
2025/03/10 02:12:25 DEBUG : only19: Sizes differ (src 0 vs dst 6)
2025/03/10 02:12:25 DEBUG : only2: Sizes differ (src 0 vs dst 6)
2025/03/10 02:12:25 DEBUG : only3: Sizes differ (src 0 vs dst 6)
2025/03/10 02:12:25 DEBUG : only4: Sizes differ (src 0 vs dst 6)
2025/03/10 02:12:25 DEBUG : only5: Sizes differ (src 0 vs dst 6)
2025/03/10 02:12:25 DEBUG : only6: Sizes differ (src 0 vs dst 6)
2025/03/10 02:12:25 DEBUG : only7: Sizes differ (src 0 vs dst 6)
2025/03/10 02:12:25 DEBUG : only8: Sizes differ (src 0 vs dst 6)
2025/03/10 02:12:25 DEBUG : only9: Sizes differ (src 0 vs dst 6)
2025/03/10 02:12:25 DEBUG : files root 'rclone-test-nikesix4yode': Waiting for transfers to finish
2025/03/10 02:12:26 DEBUG : both0: Dst hash empty - aborting Src hash check
2025/03/10 02:12:26 INFO  : both0: Copied (replaced existing)
2025/03/10 02:12:26 DEBUG : only0: Dst hash empty - aborting Src hash check
2025/03/10 02:12:26 INFO  : only0: Copied (replaced existing)
2025/03/10 02:12:26 DEBUG : only13: Dst hash empty - aborting Src hash check
2025/03/10 02:12:26 INFO  : only13: Copied (replaced existing)
2025/03/10 02:12:26 DEBUG : only12: Dst hash empty - aborting Src hash check
2025/03/10 02:12:26 INFO  : only12: Copied (replaced existing)
2025/03/10 02:12:27 DEBUG : only14: Dst hash empty - aborting Src hash check
2025/03/10 02:12:27 INFO  : only14: Copied (replaced existing)
2025/03/10 02:12:27 DEBUG : only10: Dst hash empty - aborting Src hash check
2025/03/10 02:12:27 INFO  : only10: Copied (replaced existing)
2025/03/10 02:12:27 DEBUG : only1: Dst hash empty - aborting Src hash check
2025/03/10 02:12:27 INFO  : only1: Copied (replaced existing)
2025/03/10 02:12:27 DEBUG : only15: Dst hash empty - aborting Src hash check
2025/03/10 02:12:27 INFO  : only15: Copied (replaced existing)
2025/03/10 02:12:27 DEBUG : only11: Dst hash empty - aborting Src hash check
2025/03/10 02:12:27 INFO  : only11: Copied (replaced existing)
2025/03/10 02:12:27 DEBUG : only17: Dst hash empty - aborting Src hash check
2025/03/10 02:12:27 INFO  : only17: Copied (replaced existing)
2025/03/10 02:12:28 DEBUG : only2: Dst hash empty - aborting Src hash check
2025/03/10 02:12:28 INFO  : only2: Copied (replaced existing)
2025/03/10 02:12:28 DEBUG : only3: Dst hash empty - aborting Src hash check
2025/03/10 02:12:28 INFO  : only3: Copied (replaced existing)
2025/03/10 02:12:28 DEBUG : only4: Dst hash empty - aborting Src hash check
2025/03/10 02:12:28 INFO  : only4: Copied (replaced existing)
2025/03/10 02:12:28 DEBUG : only6: Dst hash empty - aborting Src hash check
2025/03/10 02:12:28 INFO  : only6: Copied (replaced existing)
2025/03/10 02:12:29 DEBUG : only9: Dst hash empty - aborting Src hash check
2025/03/10 02:12:29 INFO  : only9: Copied (replaced existing)
2025/03/10 02:12:30 DEBUG : only16: Dst hash empty - aborting Src hash check
2025/03/10 02:12:30 INFO  : only16: Copied (replaced existing)
2025/03/10 02:12:31 DEBUG : only18: Dst hash empty - aborting Src hash check
2025/03/10 02:12:31 INFO  : only18: Copied (replaced existing)
2025/03/10 02:12:32 DEBUG : only5: Dst hash empty - aborting Src hash check
2025/03/10 02:12:32 INFO  : only5: Copied (replaced existing)
2025/03/10 02:12:32 DEBUG : only7: Dst hash empty - aborting Src hash check
2025/03/10 02:12:32 INFO  : only7: Copied (replaced existing)
2025/03/10 02:12:32 DEBUG : only8: Dst hash empty - aborting Src hash check
2025/03/10 02:12:32 INFO  : only8: Copied (replaced existing)
2025/03/10 02:12:35 DEBUG : only19: Dst hash empty - aborting Src hash check
2025/03/10 02:12:35 INFO  : only19: Copied (replaced existing)
2025/03/10 02:12:35 DEBUG : Waiting for deletions to finish
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
--- FAIL: TestSyncConcurrentTruncate (59.48s)
=== RUN   TestSyncReplaceDirModTime
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:12:42 DEBUG : empty_dir: Making directory with metadata
2025/03/10 02:12:42 INFO  : empty_dir: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z)
2025/03/10 02:12:42 DEBUG : empty_on_remote: Making directory with metadata
2025/03/10 02:12:42 INFO  : empty_on_remote: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z)
2025/03/10 02:12:42 INFO  : empty_on_remote: Making directory
2025/03/10 02:12:43 INFO  : empty_on_remote: Made directory with modification time 2011-12-25 12:59:59.123456789 +0000 UTC
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:12:44 INFO  : test_dir1: Set directory modification time (using DirSetModTime)
2025/03/10 02:12:44 INFO  : test_dir2: Set directory modification time (using DirSetModTime)
2025/03/10 02:12:44 INFO  : test_dir2/sub_dir: Set directory modification time (using DirSetModTime)
2025/03/10 02:12:44 INFO  : empty_on_remote: Set directory modification time (using DirSetModTime)
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:12:47 DEBUG : pacer: low level retry 1/10 (error Folder Not Empty - `Folder rclone-test-nikesix4yode/test_dir2 not empty`)
2025/03/10 02:12:47 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2025/03/10 02:12:47 DEBUG : pacer: Reducing sleep to 15ms
2025/03/10 02:12:48 DEBUG : pacer: Reducing sleep to 11.25ms
2025/03/10 02:12:48 DEBUG : pacer: Reducing sleep to 10ms
--- PASS: TestSyncReplaceDirModTime (6.06s)
=== RUN   TestSyncReplaceDirModTimeWithEmptyDirs
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:12:48 DEBUG : empty_dir: Making directory with metadata
2025/03/10 02:12:48 INFO  : empty_dir: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z)
2025/03/10 02:12:48 DEBUG : empty_on_remote: Making directory with metadata
2025/03/10 02:12:48 INFO  : empty_on_remote: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z)
2025/03/10 02:12:48 INFO  : empty_on_remote: Making directory
2025/03/10 02:12:49 INFO  : empty_on_remote: Made directory with modification time 2011-12-25 12:59:59.123456789 +0000 UTC
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:12:51 INFO  : test_dir1: Set directory modification time (using DirSetModTime)
2025/03/10 02:12:51 INFO  : test_dir2: Set directory modification time (using DirSetModTime)
2025/03/10 02:12:51 INFO  : test_dir2/sub_dir: Set directory modification time (using DirSetModTime)
2025/03/10 02:12:51 INFO  : empty_on_remote: Set directory modification time (using DirSetModTime)
2025/03/10 02:12:51 INFO  : empty_dir: Set directory modification time (using DirSetModTime)
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
--- PASS: TestSyncReplaceDirModTimeWithEmptyDirs (7.29s)
=== RUN   TestNothingToTransferWithEmptyDirs
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:12:56 INFO  : sub dir: Set directory modification time (using DirSetModTime)
2025/03/10 02:12:56 INFO  : sub dir: Making directory
2025/03/10 02:12:56 INFO  : sub dir: Made directory with modification time 2011-12-30 12:59:59 +0000 UTC
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:13:06 INFO  : sub dir2: Set directory modification time (using DirSetModTime)
2025/03/10 02:13:06 INFO  : sub dir2: Set directory modification time (using DirSetModTime)
2025/03/10 02:13:06 INFO  : sub dirEmpty/sub dirEmpty2: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z)
2025/03/10 02:13:06 INFO  : sub dirEmpty: Set directory modification time (using DirSetModTime)
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:13:12 DEBUG : pacer: low level retry 1/10 (error Folder Not Empty - `Folder rclone-test-nikesix4yode/sub dir2/very/very/very/very/very/nested not empty`)
2025/03/10 02:13:12 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2025/03/10 02:13:13 DEBUG : pacer: low level retry 2/10 (error Folder Not Empty - `Folder rclone-test-nikesix4yode/sub dir2/very/very/very/very/very/nested not empty`)
2025/03/10 02:13:13 DEBUG : pacer: Rate limited, increasing sleep to 40ms
2025/03/10 02:13:13 DEBUG : pacer: Reducing sleep to 30ms
2025/03/10 02:13:13 DEBUG : pacer: Reducing sleep to 22.5ms
2025/03/10 02:13:13 DEBUG : pacer: Reducing sleep to 16.875ms
2025/03/10 02:13:13 DEBUG : pacer: Reducing sleep to 12.65625ms
2025/03/10 02:13:13 DEBUG : pacer: Reducing sleep to 10ms
--- PASS: TestNothingToTransferWithEmptyDirs (19.07s)
=== RUN   TestNothingToTransferWithoutEmptyDirs
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:13:15 INFO  : sub dir: Set directory modification time (using DirSetModTime)
2025/03/10 02:13:15 INFO  : sub dir: Making directory
2025/03/10 02:13:15 INFO  : sub dir: Made directory with modification time 2011-12-30 12:59:59 +0000 UTC
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:13:23 INFO  : sub dir2: Set directory modification time (using DirSetModTime)
2025/03/10 02:13:23 INFO  : sub dir2: Set directory modification time (using DirSetModTime)
2025/03/10 02:13:23 INFO  : sub dirEmpty/sub dirEmpty2: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z)
2025/03/10 02:13:23 INFO  : sub dirEmpty: Set directory modification time (using DirSetModTime)
    run.go:180: Remote "files root 'rclone-test-nikesix4yode'", Local "Local file system at /tmp/rclone391858675", Modify Window "1s"
2025/03/10 02:13:28 DEBUG : pacer: low level retry 1/10 (error Folder Not Empty - `Folder rclone-test-nikesix4yode/sub dir2/very/very/very/very/very not empty`)
2025/03/10 02:13:28 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2025/03/10 02:13:28 DEBUG : pacer: Reducing sleep to 15ms
2025/03/10 02:13:28 DEBUG : pacer: Reducing sleep to 11.25ms
2025/03/10 02:13:29 DEBUG : pacer: low level retry 1/10 (error Folder Not Empty - `Folder rclone-test-nikesix4yode/sub dir2/very/very/very not empty`)
2025/03/10 02:13:29 DEBUG : pacer: Rate limited, increasing sleep to 22.5ms
2025/03/10 02:13:29 DEBUG : pacer: low level retry 2/10 (error Folder Not Empty - `Folder rclone-test-nikesix4yode/sub dir2/very/very/very not empty`)
2025/03/10 02:13:29 DEBUG : pacer: Rate limited, increasing sleep to 45ms
2025/03/10 02:13:29 DEBUG : pacer: Reducing sleep to 33.75ms
2025/03/10 02:13:29 DEBUG : pacer: low level retry 1/10 (error Folder Not Empty - `Folder rclone-test-nikesix4yode/sub dir2/very/very not empty`)
2025/03/10 02:13:29 DEBUG : pacer: Rate limited, increasing sleep to 67.5ms
2025/03/10 02:13:29 DEBUG : pacer: Reducing sleep to 50.625ms
2025/03/10 02:13:29 DEBUG : pacer: low level retry 1/10 (error Folder Not Empty - `Folder rclone-test-nikesix4yode/sub dir2/very not empty`)
2025/03/10 02:13:29 DEBUG : pacer: Rate limited, increasing sleep to 101.25ms
2025/03/10 02:13:29 DEBUG : pacer: Reducing sleep to 75.9375ms
2025/03/10 02:13:30 DEBUG : pacer: Reducing sleep to 56.953125ms
2025/03/10 02:13:30 DEBUG : pacer: Reducing sleep to 42.714843ms
2025/03/10 02:13:30 DEBUG : pacer: Reducing sleep to 32.036132ms
2025/03/10 02:13:30 DEBUG : pacer: Reducing sleep to 24.027099ms
2025/03/10 02:13:30 DEBUG : pacer: Reducing sleep to 18.020324ms
2025/03/10 02:13:30 DEBUG : pacer: Reducing sleep to 13.515243ms
2025/03/10 02:13:30 DEBUG : pacer: Reducing sleep to 10.136432ms
2025/03/10 02:13:30 DEBUG : pacer: Reducing sleep to 10ms
--- PASS: TestNothingToTransferWithoutEmptyDirs (15.93s)
FAIL
2025/03/10 02:13:31 DEBUG : files root 'rclone-test-nikesix4yode': Purge remote
"./sync.test -test.v -test.timeout 1h0m0s -remote TestFilesCom: -verbose" - Finished ERROR in 9m42.984849186s (try 1/5): exit status 1: Failed [TestSyncEmptyDirectories TestSyncAfterChangingModtimeOnlyWithNoUpdateModTime TestSyncWithTrackRenames TestSyncSuffixKeepExtension TestSyncConcurrentTruncate]