"./sync.test -test.v -test.timeout 1h0m0s -remote TestFilesCom: -verbose -test.run '^(TestSyncAfterChangingModtimeOnlyWithNoUpdateModTime|TestSyncBackupDirWithSuffix|TestSyncBackupDirWithSuffixKeepExtension|TestSyncMultipleCompareDest|TestSyncReplaceDirModTimeWithEmptyDirs|TestSyncWithTrackRenames)$'" - Starting (try 2/5)
2025/02/21 01:25:16 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-vekoruy8mexe"
2025/02/21 01:25:16 DEBUG : Using config file from "/home/rclone/.rclone.conf"
2025/02/21 01:25:17 DEBUG : Creating backend with remote "/tmp/rclone1595415929"
=== RUN   TestSyncAfterChangingModtimeOnlyWithNoUpdateModTime
    run.go:180: Remote "files root 'rclone-test-vekoruy8mexe'", Local "Local file system at /tmp/rclone1595415929", Modify Window "1s"
2025/02/21 01:25:18 DEBUG : files root 'rclone-test-vekoruy8mexe': Waiting for checks to finish
2025/02/21 01:25:18 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/02/21 01:25:18 DEBUG : empty space: Dst hash empty - aborting Src hash check
2025/02/21 01:25:18 DEBUG : files root 'rclone-test-vekoruy8mexe': Waiting for transfers to finish
2025/02/21 01:25:19 DEBUG : empty space: Dst hash empty - aborting Src hash check
2025/02/21 01:25:19 INFO  : empty space: Copied (replaced existing)
2025/02/21 01:25:19 DEBUG : Waiting for deletions to finish
    run.go:180: Remote "files root 'rclone-test-vekoruy8mexe'", Local "Local file system at /tmp/rclone1595415929", 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 (3.59s)
=== RUN   TestSyncWithTrackRenames
    run.go:180: Remote "files root 'rclone-test-vekoruy8mexe'", Local "Local file system at /tmp/rclone1595415929", Modify Window "1s"
    sync_test.go:1538: Can track renames: true
2025/02/21 01:25:20 INFO  : files root 'rclone-test-vekoruy8mexe': Making map for --track-renames
2025/02/21 01:25:20 INFO  : files root 'rclone-test-vekoruy8mexe': Finished making map for --track-renames
2025/02/21 01:25:20 DEBUG : files root 'rclone-test-vekoruy8mexe': Waiting for checks to finish
2025/02/21 01:25:20 DEBUG : potato: Need to transfer - No matching file found at Destination
2025/02/21 01:25:20 DEBUG : yam: Need to transfer - No matching file found at Destination
2025/02/21 01:25:20 DEBUG : files root 'rclone-test-vekoruy8mexe': Waiting for renames to finish
2025/02/21 01:25:20 DEBUG : files root 'rclone-test-vekoruy8mexe': Waiting for transfers to finish
2025/02/21 01:25:21 DEBUG : yam: Dst hash empty - aborting Src hash check
2025/02/21 01:25:21 INFO  : yam: Copied (new)
2025/02/21 01:25:21 DEBUG : potato: Dst hash empty - aborting Src hash check
2025/02/21 01:25:21 INFO  : potato: Copied (new)
2025/02/21 01:25:21 DEBUG : Waiting for deletions to finish
    run.go:180: Remote "files root 'rclone-test-vekoruy8mexe'", Local "Local file system at /tmp/rclone1595415929", Modify Window "1s"
2025/02/21 01:25:21 DEBUG : potato: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/02/21 01:25:21 INFO  : files root 'rclone-test-vekoruy8mexe': Making map for --track-renames
2025/02/21 01:25:21 INFO  : files root 'rclone-test-vekoruy8mexe': Finished making map for --track-renames
2025/02/21 01:25:21 DEBUG : files root 'rclone-test-vekoruy8mexe': Waiting for checks to finish
2025/02/21 01:25:21 DEBUG : yaml: Need to transfer - No matching file found at Destination
2025/02/21 01:25:21 DEBUG : potato: Unchanged skipping
2025/02/21 01:25:21 DEBUG : files root 'rclone-test-vekoruy8mexe': Waiting for renames to finish
2025/02/21 01:25:21 DEBUG : files root 'rclone-test-vekoruy8mexe': Waiting for transfers to finish
2025/02/21 01:25:22 DEBUG : yaml: Dst hash empty - aborting Src hash check
2025/02/21 01:25:22 INFO  : yaml: Copied (new)
2025/02/21 01:25:22 DEBUG : Waiting for deletions to finish
2025/02/21 01:25:22 INFO  : yam: Deleted
    run.go:180: Remote "files root 'rclone-test-vekoruy8mexe'", Local "Local file system at /tmp/rclone1595415929", 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.46s)
=== RUN   TestSyncMultipleCompareDest
    run.go:180: Remote "files root 'rclone-test-vekoruy8mexe'", Local "Local file system at /tmp/rclone1595415929", Modify Window "1s"
2025/02/21 01:25:26 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-vekoruy8mexe/dest"
2025/02/21 01:25:26 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-vekoruy8mexe/pre-dest1"
2025/02/21 01:25:27 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-vekoruy8mexe/pre-dest2"
2025/02/21 01:25:28 DEBUG : 1: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/02/21 01:25:28 DEBUG : 1: Destination found in --compare-dest, skipping
2025/02/21 01:25:29 DEBUG : 2: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/02/21 01:25:29 DEBUG : 2: Destination found in --compare-dest, skipping
2025/02/21 01:25:29 DEBUG : 3: Need to transfer - File not found at Destination
2025/02/21 01:25:29 DEBUG : files root 'rclone-test-vekoruy8mexe/dest': Waiting for checks to finish
2025/02/21 01:25:29 DEBUG : files root 'rclone-test-vekoruy8mexe/dest': Waiting for transfers to finish
2025/02/21 01:25:31 DEBUG : 3: Dst hash empty - aborting Src hash check
2025/02/21 01:25:31 INFO  : 3: Copied (new)
2025/02/21 01:25:31 DEBUG : Waiting for deletions to finish
--- PASS: TestSyncMultipleCompareDest (8.97s)
=== RUN   TestSyncBackupDirWithSuffix
    run.go:180: Remote "files root 'rclone-test-vekoruy8mexe'", Local "Local file system at /tmp/rclone1595415929", Modify Window "1s"
2025/02/21 01:25:35 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-vekoruy8mexe/dst"
2025/02/21 01:25:36 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-vekoruy8mexe/backup"
2025/02/21 01:25:37 DEBUG : one: Sizes differ (src 4 vs dst 3)
2025/02/21 01:25:37 DEBUG : files root 'rclone-test-vekoruy8mexe/dst': Waiting for checks to finish
2025/02/21 01:25:37 DEBUG : two: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/02/21 01:25:37 DEBUG : two: Unchanged skipping
2025/02/21 01:25:37 INFO  : one: Moved (server-side) to: one.bak
2025/02/21 01:25:37 DEBUG : files root 'rclone-test-vekoruy8mexe/dst': Waiting for transfers to finish
2025/02/21 01:25:38 DEBUG : one: Dst hash empty - aborting Src hash check
2025/02/21 01:25:38 INFO  : one: Copied (new)
2025/02/21 01:25:38 DEBUG : Waiting for deletions to finish
2025/02/21 01:25:39 INFO  : three.txt: Moved (server-side) to: three.txt.bak
2025/02/21 01:25:39 INFO  : three.txt: Moved into backup dir
2025/02/21 01:25:40 DEBUG : one: Sizes differ (src 5 vs dst 4)
2025/02/21 01:25:40 DEBUG : two: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/02/21 01:25:40 DEBUG : two: Unchanged skipping
2025/02/21 01:25:40 DEBUG : files root 'rclone-test-vekoruy8mexe/dst': Waiting for checks to finish
2025/02/21 01:25:41 INFO  : one.bak: Deleted
2025/02/21 01:25:41 INFO  : one: Moved (server-side) to: one.bak
2025/02/21 01:25:41 DEBUG : files root 'rclone-test-vekoruy8mexe/dst': Waiting for transfers to finish
2025/02/21 01:25:42 DEBUG : one: Dst hash empty - aborting Src hash check
2025/02/21 01:25:42 INFO  : one: Copied (new)
2025/02/21 01:25:42 DEBUG : Waiting for deletions to finish
2025/02/21 01:25:42 INFO  : three.txt.bak: Deleted
2025/02/21 01:25:43 INFO  : three.txt: Moved (server-side) to: three.txt.bak
2025/02/21 01:25:43 INFO  : three.txt: Moved into backup dir
--- PASS: TestSyncBackupDirWithSuffix (11.69s)
=== RUN   TestSyncBackupDirWithSuffixKeepExtension
    run.go:180: Remote "files root 'rclone-test-vekoruy8mexe'", Local "Local file system at /tmp/rclone1595415929", Modify Window "1s"
2025/02/21 01:25:47 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-vekoruy8mexe/dst"
2025/02/21 01:25:47 DEBUG : Config file has changed externally - reloading
2025/02/21 01:25:47 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-vekoruy8mexe/backup"
2025/02/21 01:25:48 DEBUG : one: Sizes differ (src 4 vs dst 3)
2025/02/21 01:25:48 DEBUG : files root 'rclone-test-vekoruy8mexe/dst': Waiting for checks to finish
2025/02/21 01:25:48 DEBUG : two: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/02/21 01:25:48 DEBUG : two: Unchanged skipping
2025/02/21 01:25:50 INFO  : one: Moved (server-side) to: one-2019-01-01
2025/02/21 01:25:50 DEBUG : files root 'rclone-test-vekoruy8mexe/dst': Waiting for transfers to finish
2025/02/21 01:25:51 DEBUG : one: Dst hash empty - aborting Src hash check
2025/02/21 01:25:51 INFO  : one: Copied (new)
2025/02/21 01:25:51 DEBUG : Waiting for deletions to finish
2025/02/21 01:25:52 INFO  : three.txt: Moved (server-side) to: three-2019-01-01.txt
2025/02/21 01:25:52 INFO  : three.txt: Moved into backup dir
2025/02/21 01:25:54 DEBUG : one: Sizes differ (src 5 vs dst 4)
2025/02/21 01:25:54 DEBUG : two: Size and modification time the same (differ by -499.999999ms, within tolerance 1s)
2025/02/21 01:25:54 DEBUG : two: Unchanged skipping
2025/02/21 01:25:54 DEBUG : files root 'rclone-test-vekoruy8mexe/dst': Waiting for checks to finish
2025/02/21 01:25:54 INFO  : one-2019-01-01: Deleted
2025/02/21 01:25:55 INFO  : one: Moved (server-side) to: one-2019-01-01
2025/02/21 01:25:55 DEBUG : files root 'rclone-test-vekoruy8mexe/dst': Waiting for transfers to finish
2025/02/21 01:25:55 DEBUG : one: Dst hash empty - aborting Src hash check
2025/02/21 01:25:55 INFO  : one: Copied (new)
2025/02/21 01:25:55 DEBUG : Waiting for deletions to finish
2025/02/21 01:25:56 INFO  : three-2019-01-01.txt: Deleted
2025/02/21 01:25:56 INFO  : three.txt: Moved (server-side) to: three-2019-01-01.txt
2025/02/21 01:25:56 INFO  : three.txt: Moved into backup dir
--- PASS: TestSyncBackupDirWithSuffixKeepExtension (13.62s)
=== RUN   TestSyncReplaceDirModTimeWithEmptyDirs
    run.go:180: Remote "files root 'rclone-test-vekoruy8mexe'", Local "Local file system at /tmp/rclone1595415929", Modify Window "1s"
2025/02/21 01:25:58 DEBUG : empty_dir: Making directory with metadata
2025/02/21 01:25:58 INFO  : empty_dir: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z)
2025/02/21 01:25:58 DEBUG : empty_on_remote: Making directory with metadata
2025/02/21 01:25:58 INFO  : empty_on_remote: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z)
2025/02/21 01:25:58 INFO  : empty_on_remote: Making directory
2025/02/21 01:25:58 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-vekoruy8mexe'", Local "Local file system at /tmp/rclone1595415929", Modify Window "1s"
2025/02/21 01:26:01 INFO  : test_dir1: Set directory modification time (using DirSetModTime)
2025/02/21 01:26:01 INFO  : test_dir2: Set directory modification time (using DirSetModTime)
2025/02/21 01:26:01 INFO  : test_dir2/sub_dir: Set directory modification time (using DirSetModTime)
2025/02/21 01:26:01 INFO  : empty_on_remote: Set directory modification time (using DirSetModTime)
2025/02/21 01:26:01 INFO  : empty_dir: Set directory modification time (using DirSetModTime)
    run.go:180: Remote "files root 'rclone-test-vekoruy8mexe'", Local "Local file system at /tmp/rclone1595415929", Modify Window "1s"
2025/02/21 01:26:04 DEBUG : pacer: low level retry 1/10 (error Folder Not Empty - `Folder rclone-test-vekoruy8mexe/test_dir2 not empty`)
2025/02/21 01:26:04 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2025/02/21 01:26:04 DEBUG : pacer: low level retry 2/10 (error Folder Not Empty - `Folder rclone-test-vekoruy8mexe/test_dir2 not empty`)
2025/02/21 01:26:04 DEBUG : pacer: Rate limited, increasing sleep to 40ms
2025/02/21 01:26:04 DEBUG : pacer: low level retry 3/10 (error Folder Not Empty - `Folder rclone-test-vekoruy8mexe/test_dir2 not empty`)
2025/02/21 01:26:04 DEBUG : pacer: Rate limited, increasing sleep to 80ms
2025/02/21 01:26:04 DEBUG : pacer: low level retry 4/10 (error Folder Not Empty - `Folder rclone-test-vekoruy8mexe/test_dir2 not empty`)
2025/02/21 01:26:04 DEBUG : pacer: Rate limited, increasing sleep to 160ms
2025/02/21 01:26:04 DEBUG : pacer: low level retry 5/10 (error Folder Not Empty - `Folder rclone-test-vekoruy8mexe/test_dir2 not empty`)
2025/02/21 01:26:04 DEBUG : pacer: Rate limited, increasing sleep to 320ms
2025/02/21 01:26:05 DEBUG : pacer: Reducing sleep to 240ms
2025/02/21 01:26:05 DEBUG : pacer: Reducing sleep to 180ms
2025/02/21 01:26:05 DEBUG : pacer: Reducing sleep to 135ms
2025/02/21 01:26:05 DEBUG : pacer: Reducing sleep to 101.25ms
2025/02/21 01:26:05 DEBUG : pacer: Reducing sleep to 75.9375ms
2025/02/21 01:26:06 DEBUG : pacer: Reducing sleep to 56.953125ms
2025/02/21 01:26:06 DEBUG : pacer: Reducing sleep to 42.714843ms
2025/02/21 01:26:06 DEBUG : pacer: Reducing sleep to 32.036132ms
2025/02/21 01:26:06 DEBUG : pacer: Reducing sleep to 24.027099ms
--- PASS: TestSyncReplaceDirModTimeWithEmptyDirs (8.21s)
FAIL
2025/02/21 01:26:06 DEBUG : files root 'rclone-test-vekoruy8mexe': Purge remote
2025/02/21 01:26:06 DEBUG : pacer: Reducing sleep to 18.020324ms
"./sync.test -test.v -test.timeout 1h0m0s -remote TestFilesCom: -verbose -test.run '^(TestSyncAfterChangingModtimeOnlyWithNoUpdateModTime|TestSyncBackupDirWithSuffix|TestSyncBackupDirWithSuffixKeepExtension|TestSyncMultipleCompareDest|TestSyncReplaceDirModTimeWithEmptyDirs|TestSyncWithTrackRenames)$'" - Finished ERROR in 50.490350855s (try 2/5): exit status 1: Failed [TestSyncAfterChangingModtimeOnlyWithNoUpdateModTime TestSyncWithTrackRenames]