"./sync.test -test.v -test.timeout 1h0m0s -remote TestFilesCom: -verbose" - Starting (try 1/5) 2025/02/15 02:43:23 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-boxoxex3miye" 2025/02/15 02:43:23 DEBUG : Using config file from "/home/rclone/.rclone.conf" 2025/02/15 02:43:24 DEBUG : Creating backend with remote "/tmp/rclone1494077444" === RUN TestPipe --- PASS: TestPipe (0.00s) === RUN TestPipeConcurrent --- PASS: TestPipeConcurrent (0.01s) === 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-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:43:25 DEBUG : Added delayed dir = "sub dir", newDst= 2025/02/15 02:43:25 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2025/02/15 02:43:25 NOTICE: sub dir/hello world: Skipped copy as --dry-run is set (size 11) 2025/02/15 02:43:25 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for checks to finish 2025/02/15 02:43:25 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for transfers to finish 2025/02/15 02:43:25 NOTICE: sub dir: Skipped set directory modification time as --dry-run is set run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" --- PASS: TestCopyWithDryRun (1.35s) === RUN TestCopy run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:43:26 INFO : sub dir: Set directory modification time (using DirSetModTime) 2025/02/15 02:43:26 DEBUG : Added delayed dir = "sub dir", newDst= 2025/02/15 02:43:26 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2025/02/15 02:43:26 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for checks to finish 2025/02/15 02:43:26 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for transfers to finish 2025/02/15 02:43:27 DEBUG : sub dir/hello world: Dst hash empty - aborting Src hash check 2025/02/15 02:43:27 INFO : sub dir/hello world: Copied (new) 2025/02/15 02:43:27 INFO : sub dir: Set directory modification time (using DirSetModTime) run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" --- PASS: TestCopy (2.68s) === RUN TestCopyMetadata run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" sync_test.go:97: Skipping as metadata not supported --- SKIP: TestCopyMetadata (0.25s) === RUN TestCopyMetadataNoEmptyDirs run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" sync_test.go:97: Skipping as metadata not supported --- SKIP: TestCopyMetadataNoEmptyDirs (0.26s) === RUN TestCopyMissingDirectory run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:43:29 DEBUG : Creating backend with remote "/non-existing" 2025/02/15 02:43:29 ERROR : Local file system at /non-existing: error reading source root directory: directory not found 2025/02/15 02:43:29 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for checks to finish 2025/02/15 02:43:29 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for transfers to finish run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" --- PASS: TestCopyMissingDirectory (0.66s) === RUN TestCopyNoTraverse run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:43:29 DEBUG : Added delayed dir = "sub dir", newDst= 2025/02/15 02:43:29 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2025/02/15 02:43:29 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for checks to finish 2025/02/15 02:43:29 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for transfers to finish 2025/02/15 02:43:30 DEBUG : sub dir/hello world: Dst hash empty - aborting Src hash check 2025/02/15 02:43:30 INFO : sub dir/hello world: Copied (new) 2025/02/15 02:43:30 INFO : sub dir: Set directory modification time (using DirSetModTime) run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" --- PASS: TestCopyNoTraverse (2.26s) === RUN TestCopyCheckFirst run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:43:32 INFO : files root 'rclone-test-boxoxex3miye': Running all checks before starting transfers 2025/02/15 02:43:32 DEBUG : Added delayed dir = "sub dir", newDst= 2025/02/15 02:43:32 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2025/02/15 02:43:32 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for checks to finish 2025/02/15 02:43:32 INFO : files root 'rclone-test-boxoxex3miye': Checks finished, now starting transfers 2025/02/15 02:43:32 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for transfers to finish 2025/02/15 02:43:33 DEBUG : sub dir/hello world: Dst hash empty - aborting Src hash check 2025/02/15 02:43:33 INFO : sub dir/hello world: Copied (new) 2025/02/15 02:43:33 INFO : sub dir: Set directory modification time (using DirSetModTime) run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" --- PASS: TestCopyCheckFirst (2.30s) === RUN TestSyncNoTraverse run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:43:34 ERROR : Ignoring --no-traverse with sync 2025/02/15 02:43:34 DEBUG : Added delayed dir = "sub dir", newDst= 2025/02/15 02:43:34 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2025/02/15 02:43:34 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for checks to finish 2025/02/15 02:43:34 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for transfers to finish 2025/02/15 02:43:35 DEBUG : sub dir/hello world: Dst hash empty - aborting Src hash check 2025/02/15 02:43:35 INFO : sub dir/hello world: Copied (new) 2025/02/15 02:43:35 DEBUG : Waiting for deletions to finish 2025/02/15 02:43:35 INFO : sub dir: Set directory modification time (using DirSetModTime) run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" --- PASS: TestSyncNoTraverse (2.30s) === RUN TestCopyWithDepth run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:43:36 DEBUG : hello world2: Need to transfer - File not found at Destination 2025/02/15 02:43:36 DEBUG : Added delayed dir = "sub dir", newDst= 2025/02/15 02:43:36 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for checks to finish 2025/02/15 02:43:36 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for transfers to finish 2025/02/15 02:43:37 DEBUG : hello world2: Dst hash empty - aborting Src hash check 2025/02/15 02:43:37 INFO : hello world2: Copied (new) run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" --- PASS: TestCopyWithDepth (1.70s) === RUN TestCopyWithFilesFrom run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:43:38 DEBUG : potato2: Need to transfer - File not found at Destination 2025/02/15 02:43:38 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for checks to finish 2025/02/15 02:43:38 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for transfers to finish 2025/02/15 02:43:39 DEBUG : potato2: Dst hash empty - aborting Src hash check 2025/02/15 02:43:39 INFO : potato2: Copied (new) run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" --- PASS: TestCopyWithFilesFrom (1.72s) === RUN TestCopyWithFilesFromAndNoTraverse run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:43:40 DEBUG : potato2: Need to transfer - File not found at Destination 2025/02/15 02:43:40 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for checks to finish 2025/02/15 02:43:40 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for transfers to finish 2025/02/15 02:43:41 DEBUG : potato2: Dst hash empty - aborting Src hash check 2025/02/15 02:43:41 INFO : potato2: Copied (new) run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" --- PASS: TestCopyWithFilesFromAndNoTraverse (1.74s) === RUN TestCopyEmptyDirectories run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:43:41 DEBUG : sub dir2/sub sub dir2: Making directory with metadata 2025/02/15 02:43:41 INFO : sub dir2/sub sub dir2: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z) 2025/02/15 02:43:41 INFO : sub dir2: Set directory modification time (using DirSetModTime) 2025/02/15 02:43:41 INFO : sub dir: Set directory modification time (using DirSetModTime) 2025/02/15 02:43:42 INFO : sub dir: Making directory 2025/02/15 02:43:42 INFO : sub dir: Made directory with modification time 2001-02-03 04:05:06.499999999 +0000 UTC 2025/02/15 02:43:42 DEBUG : Added delayed dir = "sub dir", newDst= 2025/02/15 02:43:42 INFO : sub dir2: Making directory 2025/02/15 02:43:42 INFO : sub dir2: Made directory with modification time 2011-12-25 12:59:59.123456789 +0000 UTC 2025/02/15 02:43:42 DEBUG : Added delayed dir = "sub dir2", newDst= 2025/02/15 02:43:42 INFO : sub dir2/sub sub dir2: Making directory 2025/02/15 02:43:42 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2025/02/15 02:43:43 INFO : sub dir2/sub sub dir2: Made directory with modification time 2011-12-25 12:59:59.123456789 +0000 UTC 2025/02/15 02:43:43 DEBUG : Added delayed dir = "sub dir2/sub sub dir2", newDst= 2025/02/15 02:43:43 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for checks to finish 2025/02/15 02:43:43 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for transfers to finish 2025/02/15 02:43:43 DEBUG : sub dir/hello world: Dst hash empty - aborting Src hash check 2025/02/15 02:43:43 INFO : sub dir/hello world: Copied (new) 2025/02/15 02:43:43 INFO : sub dir2/sub sub dir2: Set directory modification time (using DirSetModTime) 2025/02/15 02:43:43 INFO : sub dir2: Set directory modification time (using DirSetModTime) 2025/02/15 02:43:43 INFO : sub dir: Set directory modification time (using DirSetModTime) run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:43:45 DEBUG : pacer: low level retry 1/10 (error Folder Not Empty - `Folder rclone-test-boxoxex3miye/sub dir2 not empty`) 2025/02/15 02:43:45 DEBUG : pacer: Rate limited, increasing sleep to 20ms 2025/02/15 02:43:45 DEBUG : pacer: low level retry 2/10 (error Folder Not Empty - `Folder rclone-test-boxoxex3miye/sub dir2 not empty`) 2025/02/15 02:43:45 DEBUG : pacer: Rate limited, increasing sleep to 40ms 2025/02/15 02:43:45 DEBUG : pacer: Reducing sleep to 30ms 2025/02/15 02:43:45 DEBUG : pacer: Reducing sleep to 22.5ms 2025/02/15 02:43:45 DEBUG : pacer: Reducing sleep to 16.875ms 2025/02/15 02:43:45 DEBUG : pacer: Reducing sleep to 12.65625ms 2025/02/15 02:43:46 DEBUG : pacer: Reducing sleep to 10ms --- PASS: TestCopyEmptyDirectories (4.28s) === RUN TestCopyNoEmptyDirectories run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:43:46 INFO : sub dir2: Making directory 2025/02/15 02:43:46 DEBUG : sub dir2/sub sub dir2: Making directory with metadata 2025/02/15 02:43:46 INFO : sub dir2/sub sub dir2: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z) 2025/02/15 02:43:46 DEBUG : Added delayed dir = "sub dir", newDst= 2025/02/15 02:43:46 DEBUG : Added delayed dir = "sub dir2", newDst= 2025/02/15 02:43:46 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2025/02/15 02:43:46 DEBUG : Added delayed dir = "sub dir2/sub sub dir2", newDst= 2025/02/15 02:43:46 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for checks to finish 2025/02/15 02:43:46 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for transfers to finish 2025/02/15 02:43:47 DEBUG : sub dir/hello world: Dst hash empty - aborting Src hash check 2025/02/15 02:43:47 INFO : sub dir/hello world: Copied (new) 2025/02/15 02:43:47 INFO : sub dir: Set directory modification time (using DirSetModTime) --- PASS: TestCopyNoEmptyDirectories (2.10s) === RUN TestMoveEmptyDirectories run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:43:48 DEBUG : sub dir2: Making directory with metadata 2025/02/15 02:43:48 INFO : sub dir2: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z) 2025/02/15 02:43:48 INFO : sub dir: Making directory 2025/02/15 02:43:48 INFO : sub dir: Made directory with modification time 2025-02-15 02:43:48.27360498 +0000 UTC 2025/02/15 02:43:48 DEBUG : Added delayed dir = "sub dir", newDst= 2025/02/15 02:43:48 INFO : sub dir2: Making directory 2025/02/15 02:43:49 INFO : sub dir2: Made directory with modification time 2011-12-25 12:59:59.123456789 +0000 UTC 2025/02/15 02:43:49 DEBUG : Added delayed dir = "sub dir2", newDst= 2025/02/15 02:43:49 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2025/02/15 02:43:49 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for checks to finish 2025/02/15 02:43:49 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for transfers to finish 2025/02/15 02:43:49 DEBUG : sub dir/hello world: Dst hash empty - aborting Src hash check 2025/02/15 02:43:49 INFO : sub dir/hello world: Copied (new) 2025/02/15 02:43:49 INFO : sub dir/hello world: Deleted 2025/02/15 02:43:49 INFO : sub dir2: Set directory modification time (using DirSetModTime) 2025/02/15 02:43:49 INFO : sub dir: Set directory modification time (using DirSetModTime) run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" --- PASS: TestMoveEmptyDirectories (3.38s) === RUN TestSyncNoUpdateDirModtime run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:43:51 DEBUG : sub dir no update dir modtime: Making directory with metadata 2025/02/15 02:43:51 INFO : sub dir no update dir modtime: Made directory with metadata (mtime=2001-02-03T04:05:06.499999999Z) 2025/02/15 02:43:52 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for checks to finish 2025/02/15 02:43:52 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for transfers to finish 2025/02/15 02:43:52 DEBUG : Waiting for deletions to finish run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" --- PASS: TestSyncNoUpdateDirModtime (1.80s) === RUN TestMoveNoEmptyDirectories run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:43:53 INFO : sub dir2: Making directory 2025/02/15 02:43:53 DEBUG : Added delayed dir = "sub dir", newDst= 2025/02/15 02:43:53 DEBUG : Added delayed dir = "sub dir2", newDst= 2025/02/15 02:43:53 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2025/02/15 02:43:53 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for checks to finish 2025/02/15 02:43:53 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for transfers to finish 2025/02/15 02:43:54 DEBUG : sub dir/hello world: Dst hash empty - aborting Src hash check 2025/02/15 02:43:54 INFO : sub dir/hello world: Copied (new) 2025/02/15 02:43:54 INFO : sub dir/hello world: Deleted 2025/02/15 02:43:54 INFO : sub dir: Set directory modification time (using DirSetModTime) --- PASS: TestMoveNoEmptyDirectories (2.02s) === RUN TestSyncEmptyDirectories run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:43:55 DEBUG : sub dir2: Making directory with metadata 2025/02/15 02:43:55 INFO : sub dir2: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z) 2025/02/15 02:43:55 INFO : sub dir: Set directory modification time (using DirSetModTime) 2025/02/15 02:43:55 INFO : sub dir: Making directory 2025/02/15 02:43:55 INFO : sub dir: Made directory with modification time 2001-02-03 04:05:06.499999999 +0000 UTC 2025/02/15 02:43:55 INFO : sub dir2: Making directory 2025/02/15 02:43:56 INFO : sub dir2: Made directory with modification time 2011-12-25 12:59:59.123456789 +0000 UTC 2025/02/15 02:43:56 DEBUG : Added delayed dir = "sub dir2", newDst= 2025/02/15 02:43:56 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2025/02/15 02:43:56 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for checks to finish 2025/02/15 02:43:56 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for transfers to finish 2025/02/15 02:43:56 DEBUG : sub dir/hello world: Dst hash empty - aborting Src hash check 2025/02/15 02:43:56 INFO : sub dir/hello world: Copied (new) 2025/02/15 02:43:56 ERROR : files root 'rclone-test-boxoxex3miye': not deleting files as there were IO errors 2025/02/15 02:43:57 INFO : sub dir2: Set directory modification time (using DirSetModTime) 2025/02/15 02:43:57 ERROR : files root 'rclone-test-boxoxex3miye': 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-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:43:57 INFO : a1/b2/c1/d1/e1/f1: Set directory modification time (using DirSetModTime) 2025/02/15 02:43:57 INFO : a1/b2/c1/d1/e1: Set directory modification time (using DirSetModTime) 2025/02/15 02:43:57 INFO : a1/b2/c1/d1: Set directory modification time (using DirSetModTime) 2025/02/15 02:43:57 INFO : a1/b2/c1: Set directory modification time (using DirSetModTime) 2025/02/15 02:43:57 INFO : a1/b2: Set directory modification time (using DirSetModTime) 2025/02/15 02:43:57 INFO : a1/b1/c1/d2/e1/f2: Set directory modification time (using DirSetModTime) 2025/02/15 02:43:57 INFO : a1/b1/c1/d2/e1/f1: Set directory modification time (using DirSetModTime) 2025/02/15 02:43:57 INFO : a1/b1/c1/d2/e1: Set directory modification time (using DirSetModTime) 2025/02/15 02:43:57 INFO : a1/b1/c1/d2: Set directory modification time (using DirSetModTime) 2025/02/15 02:43:57 INFO : a1/b1/c1/d1/e1/f1: Set directory modification time (using DirSetModTime) 2025/02/15 02:43:57 INFO : a1/b1/c1/d1/e1: Set directory modification time (using DirSetModTime) 2025/02/15 02:43:57 INFO : a1/b1/c1/d1: Set directory modification time (using DirSetModTime) 2025/02/15 02:43:57 INFO : a1/b1/c1: Set directory modification time (using DirSetModTime) 2025/02/15 02:43:57 INFO : a1/b1: Set directory modification time (using DirSetModTime) 2025/02/15 02:43:57 INFO : a1: Set directory modification time (using DirSetModTime) 2025/02/15 02:43:58 INFO : a1: Making directory 2025/02/15 02:43:58 INFO : a1: Made directory with modification time 2001-02-03 04:19:06.499999999 +0000 UTC 2025/02/15 02:43:58 DEBUG : Added delayed dir = "a1", newDst= 2025/02/15 02:43:58 INFO : a1/b1: Making directory 2025/02/15 02:43:58 INFO : a1/b1: Made directory with modification time 2001-02-03 04:18:06.499999999 +0000 UTC 2025/02/15 02:43:58 DEBUG : Added delayed dir = "a1/b1", newDst= 2025/02/15 02:43:58 INFO : a1/b2: Making directory 2025/02/15 02:43:59 INFO : a1/b2: Made directory with modification time 2001-02-03 04:09:06.499999999 +0000 UTC 2025/02/15 02:43:59 DEBUG : Added delayed dir = "a1/b2", newDst= 2025/02/15 02:43:59 INFO : a1/b2/c1: Making directory 2025/02/15 02:43:59 INFO : a1/b1/c1: Making directory 2025/02/15 02:43:59 INFO : a1/b2/c1: Made directory with modification time 2001-02-03 04:08:06.499999999 +0000 UTC 2025/02/15 02:43:59 DEBUG : Added delayed dir = "a1/b2/c1", newDst= 2025/02/15 02:43:59 INFO : a1/b2/c1/d1: Making directory 2025/02/15 02:43:59 INFO : a1/b1/c1: Made directory with modification time 2001-02-03 04:17:06.499999999 +0000 UTC 2025/02/15 02:43:59 DEBUG : Added delayed dir = "a1/b1/c1", newDst= 2025/02/15 02:43:59 INFO : a1/b1/c1/d1: Making directory 2025/02/15 02:43:59 INFO : a1/b2/c1/d1: Made directory with modification time 2001-02-03 04:07:06.499999999 +0000 UTC 2025/02/15 02:43:59 DEBUG : Added delayed dir = "a1/b2/c1/d1", newDst= 2025/02/15 02:43:59 INFO : a1/b2/c1/d1/e1: Making directory 2025/02/15 02:43:59 INFO : a1/b1/c1/d1: Made directory with modification time 2001-02-03 04:16:06.499999999 +0000 UTC 2025/02/15 02:43:59 DEBUG : Added delayed dir = "a1/b1/c1/d1", newDst= 2025/02/15 02:43:59 INFO : a1/b1/c1/d2: Making directory 2025/02/15 02:44:00 INFO : a1/b2/c1/d1/e1: Made directory with modification time 2001-02-03 04:06:06.499999999 +0000 UTC 2025/02/15 02:44:00 DEBUG : Added delayed dir = "a1/b2/c1/d1/e1", newDst= 2025/02/15 02:44:00 INFO : a1/b2/c1/d1/e1/f1: Making directory 2025/02/15 02:44:00 INFO : a1/b1/c1/d2: Made directory with modification time 2001-02-03 04:13:06.499999999 +0000 UTC 2025/02/15 02:44:00 DEBUG : Added delayed dir = "a1/b1/c1/d2", newDst= 2025/02/15 02:44:00 INFO : a1/b1/c1/d1/e1: Making directory 2025/02/15 02:44:00 INFO : a1/b1/c1/d2/e1: Making directory 2025/02/15 02:44:00 INFO : a1/b2/c1/d1/e1/f1: Made directory with modification time 2001-02-03 04:05:06.499999999 +0000 UTC 2025/02/15 02:44:00 DEBUG : Added delayed dir = "a1/b2/c1/d1/e1/f1", newDst= 2025/02/15 02:44:00 INFO : a1/b1/c1/d2/e1: Made directory with modification time 2001-02-03 04:12:06.499999999 +0000 UTC 2025/02/15 02:44:00 DEBUG : Added delayed dir = "a1/b1/c1/d2/e1", newDst= 2025/02/15 02:44:00 INFO : a1/b1/c1/d2/e1/f1: Making directory 2025/02/15 02:44:00 INFO : a1/b1/c1/d1/e1: Made directory with modification time 2001-02-03 04:15:06.499999999 +0000 UTC 2025/02/15 02:44:00 DEBUG : Added delayed dir = "a1/b1/c1/d1/e1", newDst= 2025/02/15 02:44:00 INFO : a1/b1/c1/d1/e1/f1: Making directory 2025/02/15 02:44:00 INFO : a1/b1/c1/d2/e1/f1: Made directory with modification time 2001-02-03 04:11:06.499999999 +0000 UTC 2025/02/15 02:44:00 DEBUG : Added delayed dir = "a1/b1/c1/d2/e1/f1", newDst= 2025/02/15 02:44:00 INFO : a1/b1/c1/d2/e1/f2: Making directory 2025/02/15 02:44:00 INFO : a1/b1/c1/d1/e1/f1: Made directory with modification time 2001-02-03 04:14:06.499999999 +0000 UTC 2025/02/15 02:44:00 DEBUG : Added delayed dir = "a1/b1/c1/d1/e1/f1", newDst= 2025/02/15 02:44:01 INFO : a1/b1/c1/d2/e1/f2: Made directory with modification time 2001-02-03 04:10:06.499999999 +0000 UTC 2025/02/15 02:44:01 DEBUG : Added delayed dir = "a1/b1/c1/d2/e1/f2", newDst= 2025/02/15 02:44:01 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for checks to finish 2025/02/15 02:44:01 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for transfers to finish 2025/02/15 02:44:01 DEBUG : Waiting for deletions to finish 2025/02/15 02:44:01 INFO : a1/b1/c1/d2/e1/f2: Set directory modification time (using DirSetModTime) 2025/02/15 02:44:01 INFO : a1/b1/c1/d2/e1/f1: Set directory modification time (using DirSetModTime) 2025/02/15 02:44:01 INFO : a1/b2/c1/d1/e1/f1: Set directory modification time (using DirSetModTime) 2025/02/15 02:44:01 INFO : a1/b1/c1/d1/e1/f1: Set directory modification time (using DirSetModTime) 2025/02/15 02:44:01 INFO : a1/b1/c1/d1/e1: Set directory modification time (using DirSetModTime) 2025/02/15 02:44:01 INFO : a1/b2/c1/d1/e1: Set directory modification time (using DirSetModTime) 2025/02/15 02:44:01 INFO : a1/b1/c1/d2/e1: Set directory modification time (using DirSetModTime) 2025/02/15 02:44:01 INFO : a1/b1/c1/d2: Set directory modification time (using DirSetModTime) 2025/02/15 02:44:01 INFO : a1/b2/c1/d1: Set directory modification time (using DirSetModTime) 2025/02/15 02:44:01 INFO : a1/b1/c1/d1: Set directory modification time (using DirSetModTime) 2025/02/15 02:44:01 INFO : a1/b1/c1: Set directory modification time (using DirSetModTime) 2025/02/15 02:44:01 INFO : a1/b2/c1: Set directory modification time (using DirSetModTime) 2025/02/15 02:44:01 INFO : a1/b2: Set directory modification time (using DirSetModTime) 2025/02/15 02:44:01 INFO : a1/b1: Set directory modification time (using DirSetModTime) 2025/02/15 02:44:01 INFO : a1: Set directory modification time (using DirSetModTime) run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:44:07 DEBUG : pacer: low level retry 1/10 (error Folder Not Empty - `Folder rclone-test-boxoxex3miye/a1/b1/c1/d2/e1 not empty`) 2025/02/15 02:44:07 DEBUG : pacer: Rate limited, increasing sleep to 20ms 2025/02/15 02:44:07 DEBUG : pacer: Reducing sleep to 15ms 2025/02/15 02:44:07 DEBUG : pacer: low level retry 1/10 (error Folder Not Empty - `Folder rclone-test-boxoxex3miye/a1/b1/c1/d2 not empty`) 2025/02/15 02:44:07 DEBUG : pacer: Rate limited, increasing sleep to 30ms 2025/02/15 02:44:07 DEBUG : pacer: Reducing sleep to 22.5ms 2025/02/15 02:44:07 DEBUG : pacer: Reducing sleep to 16.875ms 2025/02/15 02:44:07 DEBUG : pacer: Reducing sleep to 12.65625ms 2025/02/15 02:44:08 DEBUG : pacer: Reducing sleep to 10ms --- PASS: TestSyncSetDelayedModTimes (10.96s) === RUN TestSyncNoEmptyDirectories run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:44:08 INFO : sub dir2: Making directory 2025/02/15 02:44:09 DEBUG : Added delayed dir = "sub dir", newDst= 2025/02/15 02:44:09 DEBUG : Added delayed dir = "sub dir2", newDst= 2025/02/15 02:44:09 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2025/02/15 02:44:09 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for checks to finish 2025/02/15 02:44:09 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for transfers to finish 2025/02/15 02:44:10 DEBUG : sub dir/hello world: Dst hash empty - aborting Src hash check 2025/02/15 02:44:10 INFO : sub dir/hello world: Copied (new) 2025/02/15 02:44:10 DEBUG : Waiting for deletions to finish 2025/02/15 02:44:10 INFO : sub dir: Set directory modification time (using DirSetModTime) --- PASS: TestSyncNoEmptyDirectories (2.29s) === RUN TestServerSideCopy run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:44:12 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-qigimid6xuni" sync_test.go:590: Server side copy (if possible) files root 'rclone-test-boxoxex3miye' -> files root 'rclone-test-qigimid6xuni' 2025/02/15 02:44:12 DEBUG : Added delayed dir = "sub dir", newDst= 2025/02/15 02:44:12 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2025/02/15 02:44:12 DEBUG : files root 'rclone-test-qigimid6xuni': Waiting for checks to finish 2025/02/15 02:44:12 DEBUG : files root 'rclone-test-qigimid6xuni': Waiting for transfers to finish 2025/02/15 02:44:14 DEBUG : sub dir/hello world: Dst hash empty - aborting Src hash check 2025/02/15 02:44:14 DEBUG : sub dir/hello world: Src hash empty - aborting Dst hash check 2025/02/15 02:44:14 INFO : sub dir/hello world: Copied (server-side copy) 2025/02/15 02:44:15 INFO : sub dir: Set directory modification time (using DirSetModTime) run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:44:15 DEBUG : files root 'rclone-test-qigimid6xuni': Purge remote --- PASS: TestServerSideCopy (5.23s) === RUN TestCopyOverSelf run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:44:17 DEBUG : sub dir: Directory modification time the same (differ by -537.407745ms, within tolerance 1s) 2025/02/15 02:44:17 DEBUG : Added delayed dir = "sub dir", newDst=sub dir 2025/02/15 02:44:17 DEBUG : sub dir/hello world: Sizes differ (src 17 vs dst 11) 2025/02/15 02:44:17 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for checks to finish 2025/02/15 02:44:17 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for transfers to finish 2025/02/15 02:44:18 DEBUG : sub dir/hello world: Dst hash empty - aborting Src hash check 2025/02/15 02:44:18 INFO : sub dir/hello world: Copied (replaced existing) 2025/02/15 02:44:18 INFO : sub dir: Set directory modification time (using DirSetModTime) run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" --- PASS: TestCopyOverSelf (3.61s) === RUN TestServerSideCopyOverSelf run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:44:21 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-capuzoh0tavo" 2025/02/15 02:44:21 DEBUG : Config file has changed externally - reloading sync_test.go:626: Server side copy (if possible) files root 'rclone-test-boxoxex3miye' -> files root 'rclone-test-capuzoh0tavo' 2025/02/15 02:44:22 DEBUG : Added delayed dir = "sub dir", newDst= 2025/02/15 02:44:22 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2025/02/15 02:44:22 DEBUG : files root 'rclone-test-capuzoh0tavo': Waiting for checks to finish 2025/02/15 02:44:22 DEBUG : files root 'rclone-test-capuzoh0tavo': Waiting for transfers to finish 2025/02/15 02:44:24 DEBUG : sub dir/hello world: Dst hash empty - aborting Src hash check 2025/02/15 02:44:24 DEBUG : sub dir/hello world: Src hash empty - aborting Dst hash check 2025/02/15 02:44:24 INFO : sub dir/hello world: Copied (server-side copy) 2025/02/15 02:44:24 INFO : sub dir: Set directory modification time (using DirSetModTime) run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:44:26 INFO : sub dir: Set directory modification time (using DirSetModTime) 2025/02/15 02:44:26 DEBUG : Added delayed dir = "sub dir", newDst=sub dir 2025/02/15 02:44:26 DEBUG : sub dir/hello world: Sizes differ (src 17 vs dst 11) 2025/02/15 02:44:26 DEBUG : files root 'rclone-test-capuzoh0tavo': Waiting for checks to finish 2025/02/15 02:44:26 DEBUG : files root 'rclone-test-capuzoh0tavo': Waiting for transfers to finish 2025/02/15 02:44:31 DEBUG : sub dir/hello world: Dst hash empty - aborting Src hash check 2025/02/15 02:44:31 DEBUG : sub dir/hello world: Src hash empty - aborting Dst hash check 2025/02/15 02:44:31 INFO : sub dir/hello world: Copied (server-side copy) 2025/02/15 02:44:31 INFO : sub dir: Set directory modification time (using DirSetModTime) run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:44:32 DEBUG : files root 'rclone-test-capuzoh0tavo': Purge remote --- PASS: TestServerSideCopyOverSelf (13.50s) === RUN TestMoveOverSelf run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:44:34 DEBUG : sub dir: Directory modification time the same (differ by -789.29131ms, within tolerance 1s) 2025/02/15 02:44:34 DEBUG : Added delayed dir = "sub dir", newDst=sub dir 2025/02/15 02:44:35 DEBUG : sub dir/hello world: Sizes differ (src 17 vs dst 11) 2025/02/15 02:44:35 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for checks to finish 2025/02/15 02:44:35 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for transfers to finish 2025/02/15 02:44:35 DEBUG : sub dir/hello world: Dst hash empty - aborting Src hash check 2025/02/15 02:44:35 INFO : sub dir/hello world: Copied (replaced existing) 2025/02/15 02:44:35 INFO : sub dir/hello world: Deleted 2025/02/15 02:44:35 INFO : sub dir: Set directory modification time (using DirSetModTime) run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" --- PASS: TestMoveOverSelf (3.63s) === RUN TestServerSideMoveOverSelf run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:44:38 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-wuzunop3nufu" sync_test.go:671: Server side copy (if possible) files root 'rclone-test-boxoxex3miye' -> files root 'rclone-test-wuzunop3nufu' 2025/02/15 02:44:39 DEBUG : Added delayed dir = "sub dir", newDst= 2025/02/15 02:44:39 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2025/02/15 02:44:39 DEBUG : files root 'rclone-test-wuzunop3nufu': Waiting for checks to finish 2025/02/15 02:44:39 DEBUG : files root 'rclone-test-wuzunop3nufu': Waiting for transfers to finish 2025/02/15 02:44:40 DEBUG : sub dir/hello world: Dst hash empty - aborting Src hash check 2025/02/15 02:44:40 DEBUG : sub dir/hello world: Src hash empty - aborting Dst hash check 2025/02/15 02:44:40 INFO : sub dir/hello world: Copied (server-side copy) 2025/02/15 02:44:40 INFO : sub dir: Set directory modification time (using DirSetModTime) run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:44:42 DEBUG : files root 'rclone-test-wuzunop3nufu': Using server-side directory move 2025/02/15 02:44:42 INFO : files root 'rclone-test-wuzunop3nufu': Server side directory move failed - fallback to file moves: can't copy directory - destination already exists 2025/02/15 02:44:42 INFO : sub dir: Set directory modification time (using DirSetModTime) 2025/02/15 02:44:42 DEBUG : Added delayed dir = "sub dir", newDst=sub dir 2025/02/15 02:44:42 DEBUG : sub dir/hello world: Sizes differ (src 17 vs dst 11) 2025/02/15 02:44:42 DEBUG : files root 'rclone-test-wuzunop3nufu': Waiting for checks to finish 2025/02/15 02:44:42 DEBUG : files root 'rclone-test-wuzunop3nufu': Waiting for transfers to finish 2025/02/15 02:44:42 INFO : sub dir/hello world: Deleted 2025/02/15 02:44:43 INFO : sub dir/hello world: Moved (server-side) 2025/02/15 02:44:43 INFO : sub dir: Set directory modification time (using DirSetModTime) 2025/02/15 02:44:45 DEBUG : testing file moves 2025/02/15 02:44:45 INFO : sub dir: Set directory modification time (using DirSetModTime) 2025/02/15 02:44:45 DEBUG : Added delayed dir = "sub dir", newDst=sub dir 2025/02/15 02:44:45 DEBUG : sub dir/hello world: Sizes differ (src 24 vs dst 17) 2025/02/15 02:44:45 DEBUG : files root 'rclone-test-wuzunop3nufu': Waiting for checks to finish 2025/02/15 02:44:45 DEBUG : files root 'rclone-test-wuzunop3nufu': Waiting for transfers to finish 2025/02/15 02:44:45 INFO : sub dir/hello world: Deleted 2025/02/15 02:44:46 INFO : sub dir/hello world: Moved (server-side) 2025/02/15 02:44:46 INFO : sub dir: Set directory modification time (using DirSetModTime) run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:44:46 DEBUG : files root 'rclone-test-wuzunop3nufu': Purge remote --- PASS: TestServerSideMoveOverSelf (10.83s) === RUN TestCopyAfterDelete run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:44:48 ERROR : : error listing: directory not found 2025/02/15 02:44:49 INFO : Local file system at /tmp/rclone1494077444: Making directory 2025/02/15 02:44:49 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for checks to finish 2025/02/15 02:44:49 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for transfers to finish run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" --- PASS: TestCopyAfterDelete (2.57s) === RUN TestCopyRedownload run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:44:51 DEBUG : Added delayed dir = "sub dir", newDst= 2025/02/15 02:44:51 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2025/02/15 02:44:51 DEBUG : Local file system at /tmp/rclone1494077444: Waiting for checks to finish 2025/02/15 02:44:51 DEBUG : Local file system at /tmp/rclone1494077444: Waiting for transfers to finish 2025/02/15 02:44:52 DEBUG : sub dir/hello world: Src hash empty - aborting Dst hash check 2025/02/15 02:44:52 DEBUG : sub dir/hello world.9e820094.partial: renamed to: sub dir/hello world 2025/02/15 02:44:52 INFO : sub dir/hello world: Copied (new) 2025/02/15 02:44:52 INFO : sub dir: Set directory modification time (using DirSetModTime) run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" --- PASS: TestCopyRedownload (2.58s) === RUN TestSyncBasedOnCheckSum run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:44:53 DEBUG : check sum: Need to transfer - File not found at Destination 2025/02/15 02:44:53 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for checks to finish 2025/02/15 02:44:53 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for transfers to finish 2025/02/15 02:44:53 DEBUG : check sum: Dst hash empty - aborting Src hash check 2025/02/15 02:44:53 INFO : check sum: Copied (new) 2025/02/15 02:44:53 DEBUG : Waiting for deletions to finish run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:44:54 DEBUG : check sum: Dst hash empty - aborting Src hash check 2025/02/15 02:44:54 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for checks to finish 2025/02/15 02:44:54 DEBUG : check sum: Size of src and dst objects identical 2025/02/15 02:44:54 DEBUG : check sum: Unchanged skipping 2025/02/15 02:44:54 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for transfers to finish 2025/02/15 02:44:54 DEBUG : Waiting for deletions to finish 2025/02/15 02:44:54 INFO : There was nothing to transfer run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" --- PASS: TestSyncBasedOnCheckSum (2.18s) === RUN TestSyncSizeOnly run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:44:55 DEBUG : sizeonly: Need to transfer - File not found at Destination 2025/02/15 02:44:55 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for checks to finish 2025/02/15 02:44:55 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for transfers to finish 2025/02/15 02:44:56 DEBUG : sizeonly: Dst hash empty - aborting Src hash check 2025/02/15 02:44:56 INFO : sizeonly: Copied (new) 2025/02/15 02:44:56 DEBUG : Waiting for deletions to finish run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:44:56 DEBUG : sizeonly: Sizes identical 2025/02/15 02:44:56 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for checks to finish 2025/02/15 02:44:56 DEBUG : sizeonly: Unchanged skipping 2025/02/15 02:44:56 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for transfers to finish 2025/02/15 02:44:56 DEBUG : Waiting for deletions to finish 2025/02/15 02:44:56 INFO : There was nothing to transfer run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" --- PASS: TestSyncSizeOnly (2.18s) === RUN TestSyncIgnoreSize run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:44:57 DEBUG : ignore-size: Need to transfer - File not found at Destination 2025/02/15 02:44:57 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for checks to finish 2025/02/15 02:44:57 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for transfers to finish 2025/02/15 02:44:58 DEBUG : ignore-size: Dst hash empty - aborting Src hash check 2025/02/15 02:44:58 INFO : ignore-size: Copied (new) 2025/02/15 02:44:58 DEBUG : Waiting for deletions to finish run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:44:58 DEBUG : ignore-size: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2025/02/15 02:44:58 DEBUG : ignore-size: Unchanged skipping 2025/02/15 02:44:58 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for checks to finish 2025/02/15 02:44:58 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for transfers to finish 2025/02/15 02:44:58 DEBUG : Waiting for deletions to finish 2025/02/15 02:44:58 INFO : There was nothing to transfer run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" --- PASS: TestSyncIgnoreSize (2.18s) === RUN TestSyncIgnoreTimes run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:45:00 DEBUG : existing: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2025/02/15 02:45:00 DEBUG : existing: Unchanged skipping 2025/02/15 02:45:00 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for checks to finish 2025/02/15 02:45:00 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for transfers to finish 2025/02/15 02:45:00 DEBUG : Waiting for deletions to finish 2025/02/15 02:45:00 INFO : There was nothing to transfer run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:45:00 DEBUG : existing: Transferring unconditionally as --ignore-times is in use 2025/02/15 02:45:00 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for checks to finish 2025/02/15 02:45:00 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for transfers to finish 2025/02/15 02:45:01 DEBUG : existing: Dst hash empty - aborting Src hash check 2025/02/15 02:45:01 INFO : existing: Copied (replaced existing) 2025/02/15 02:45:01 DEBUG : Waiting for deletions to finish run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" --- PASS: TestSyncIgnoreTimes (3.75s) === RUN TestSyncIgnoreExisting run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:45:03 DEBUG : existing: Need to transfer - File not found at Destination 2025/02/15 02:45:03 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for checks to finish 2025/02/15 02:45:03 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for transfers to finish 2025/02/15 02:45:04 DEBUG : existing: Dst hash empty - aborting Src hash check 2025/02/15 02:45:04 INFO : existing: Copied (new) 2025/02/15 02:45:04 DEBUG : Waiting for deletions to finish run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:45:04 DEBUG : existing: Destination exists, skipping 2025/02/15 02:45:04 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for checks to finish 2025/02/15 02:45:04 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for transfers to finish 2025/02/15 02:45:04 DEBUG : Waiting for deletions to finish 2025/02/15 02:45:04 INFO : There was nothing to transfer run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" --- PASS: TestSyncIgnoreExisting (2.60s) === RUN TestSyncIgnoreErrors run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:45:07 INFO : d: Making directory 2025/02/15 02:45:08 DEBUG : Added delayed dir = "a", newDst= 2025/02/15 02:45:08 DEBUG : c: Directory modification time the same (differ by 154.925336ms, within tolerance 1s) 2025/02/15 02:45:08 DEBUG : Added delayed dir = "c", newDst=c 2025/02/15 02:45:08 DEBUG : a/potato2: Need to transfer - File not found at Destination 2025/02/15 02:45:08 DEBUG : c/non empty space: Size and modification time the same (differ by -123.456789ms, within tolerance 1s) 2025/02/15 02:45:08 DEBUG : c/non empty space: Unchanged skipping 2025/02/15 02:45:08 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for checks to finish 2025/02/15 02:45:08 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for transfers to finish 2025/02/15 02:45:09 DEBUG : a/potato2: Dst hash empty - aborting Src hash check 2025/02/15 02:45:09 INFO : a/potato2: Copied (new) 2025/02/15 02:45:09 DEBUG : Waiting for deletions to finish 2025/02/15 02:45:09 INFO : b/potato: Deleted 2025/02/15 02:45:09 INFO : a: Set directory modification time (using DirSetModTime) 2025/02/15 02:45:09 INFO : d: Removing directory 2025/02/15 02:45:09 INFO : b: Removing directory 2025/02/15 02:45:09 DEBUG : files root 'rclone-test-boxoxex3miye': deleted 2 directories run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" --- PASS: TestSyncIgnoreErrors (5.22s) === RUN TestSyncAfterChangingModtimeOnly run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:45:12 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for checks to finish 2025/02/15 02:45:12 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/15 02:45:12 DEBUG : empty space: Dst hash empty - aborting Src hash check 2025/02/15 02:45:12 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for transfers to finish 2025/02/15 02:45:12 NOTICE: empty space: Skipped copy as --dry-run is set (size 1) 2025/02/15 02:45:12 DEBUG : Waiting for deletions to finish run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:45:12 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/15 02:45:12 DEBUG : empty space: Dst hash empty - aborting Src hash check 2025/02/15 02:45:12 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for checks to finish 2025/02/15 02:45:12 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for transfers to finish 2025/02/15 02:45:13 DEBUG : empty space: Dst hash empty - aborting Src hash check 2025/02/15 02:45:13 INFO : empty space: Copied (replaced existing) 2025/02/15 02:45:13 DEBUG : Waiting for deletions to finish run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" --- PASS: TestSyncAfterChangingModtimeOnly (3.05s) === RUN TestSyncAfterChangingModtimeOnlyWithNoUpdateModTime run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:45:15 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/15 02:45:15 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for checks to finish 2025/02/15 02:45:15 DEBUG : empty space: Dst hash empty - aborting Src hash check 2025/02/15 02:45:15 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for transfers to finish 2025/02/15 02:45:16 DEBUG : empty space: Dst hash empty - aborting Src hash check 2025/02/15 02:45:16 INFO : empty space: Copied (replaced existing) 2025/02/15 02:45:16 DEBUG : Waiting for deletions to finish run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", 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.59s) === RUN TestSyncDoesntUpdateModtime run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:45:17 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for checks to finish 2025/02/15 02:45:17 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/02/15 02:45:17 DEBUG : foo: Dst hash empty - aborting Src hash check 2025/02/15 02:45:17 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for transfers to finish 2025/02/15 02:45:18 DEBUG : foo: Dst hash empty - aborting Src hash check 2025/02/15 02:45:18 INFO : foo: Copied (replaced existing) 2025/02/15 02:45:18 DEBUG : Waiting for deletions to finish run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" --- PASS: TestSyncDoesntUpdateModtime (2.53s) === RUN TestSyncAfterAddingAFile run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:45:20 DEBUG : potato: Need to transfer - File not found at Destination 2025/02/15 02:45:20 DEBUG : empty space: Size and modification time the same (differ by -123.456789ms, within tolerance 1s) 2025/02/15 02:45:20 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for checks to finish 2025/02/15 02:45:20 DEBUG : empty space: Unchanged skipping 2025/02/15 02:45:20 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for transfers to finish 2025/02/15 02:45:21 DEBUG : potato: Dst hash empty - aborting Src hash check 2025/02/15 02:45:21 INFO : potato: Copied (new) 2025/02/15 02:45:21 DEBUG : Waiting for deletions to finish run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" --- PASS: TestSyncAfterAddingAFile (2.64s) === RUN TestSyncAfterChangingFilesSizeOnly run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:45:23 DEBUG : potato: Sizes differ (src 21 vs dst 60) 2025/02/15 02:45:23 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for checks to finish 2025/02/15 02:45:23 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for transfers to finish 2025/02/15 02:45:23 DEBUG : potato: Dst hash empty - aborting Src hash check 2025/02/15 02:45:23 INFO : potato: Copied (replaced existing) 2025/02/15 02:45:23 DEBUG : Waiting for deletions to finish run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" --- PASS: TestSyncAfterChangingFilesSizeOnly (2.51s) === RUN TestSyncAfterChangingContentsOnly run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:45:25 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for checks to finish 2025/02/15 02:45:25 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/02/15 02:45:25 DEBUG : potato: Dst hash empty - aborting Src hash check 2025/02/15 02:45:25 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for transfers to finish 2025/02/15 02:45:26 DEBUG : potato: Dst hash empty - aborting Src hash check 2025/02/15 02:45:26 INFO : potato: Copied (replaced existing) 2025/02/15 02:45:26 DEBUG : Waiting for deletions to finish run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" --- PASS: TestSyncAfterChangingContentsOnly (2.57s) === RUN TestSyncAfterRemovingAFileAndAddingAFileDryRun run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:45:28 DEBUG : potato2: Need to transfer - File not found at Destination 2025/02/15 02:45:28 NOTICE: potato2: Skipped copy as --dry-run is set (size 60) 2025/02/15 02:45:28 DEBUG : empty space: Size and modification time the same (differ by -123.456789ms, within tolerance 1s) 2025/02/15 02:45:28 DEBUG : empty space: Unchanged skipping 2025/02/15 02:45:28 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for checks to finish 2025/02/15 02:45:28 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for transfers to finish 2025/02/15 02:45:28 DEBUG : Waiting for deletions to finish 2025/02/15 02:45:28 NOTICE: potato: Skipped delete as --dry-run is set (size 21) run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" --- PASS: TestSyncAfterRemovingAFileAndAddingAFileDryRun (2.50s) === RUN TestSyncAfterRemovingAFileAndAddingAFile run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:45:31 DEBUG : potato2: Need to transfer - File not found at Destination 2025/02/15 02:45:31 DEBUG : empty space: Size and modification time the same (differ by -123.456789ms, within tolerance 1s) 2025/02/15 02:45:31 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for checks to finish 2025/02/15 02:45:31 DEBUG : empty space: Unchanged skipping 2025/02/15 02:45:31 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for transfers to finish 2025/02/15 02:45:32 DEBUG : potato2: Dst hash empty - aborting Src hash check 2025/02/15 02:45:32 INFO : potato2: Copied (new) 2025/02/15 02:45:32 DEBUG : Waiting for deletions to finish 2025/02/15 02:45:32 INFO : potato: Deleted run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" --- PASS: TestSyncAfterRemovingAFileAndAddingAFile (3.64s) === RUN TestSyncAfterRemovingAFileAndAddingAFileSubDir run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:45:34 INFO : d: Making directory 2025/02/15 02:45:35 INFO : d/e: Making directory 2025/02/15 02:45:35 DEBUG : Added delayed dir = "a", newDst= 2025/02/15 02:45:35 DEBUG : c: Directory modification time the same (differ by -112.890088ms, within tolerance 1s) 2025/02/15 02:45:35 DEBUG : Added delayed dir = "c", newDst=c 2025/02/15 02:45:35 DEBUG : a/potato2: Need to transfer - File not found at Destination 2025/02/15 02:45:35 DEBUG : c/non empty space: Size and modification time the same (differ by -123.456789ms, within tolerance 1s) 2025/02/15 02:45:35 DEBUG : c/non empty space: Unchanged skipping 2025/02/15 02:45:36 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for checks to finish 2025/02/15 02:45:36 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for transfers to finish 2025/02/15 02:45:36 DEBUG : a/potato2: Dst hash empty - aborting Src hash check 2025/02/15 02:45:36 INFO : a/potato2: Copied (new) 2025/02/15 02:45:36 DEBUG : Waiting for deletions to finish 2025/02/15 02:45:36 INFO : b/potato: Deleted 2025/02/15 02:45:36 INFO : a: Set directory modification time (using DirSetModTime) 2025/02/15 02:45:36 INFO : d/e: Removing directory 2025/02/15 02:45:37 INFO : d: Removing directory 2025/02/15 02:45:37 INFO : b: Removing directory 2025/02/15 02:45:37 DEBUG : files root 'rclone-test-boxoxex3miye': deleted 3 directories run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" --- PASS: TestSyncAfterRemovingAFileAndAddingAFileSubDir (5.67s) === RUN TestSyncAfterRemovingAFileAndAddingAFileSubDirWithErrors run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:45:40 INFO : d: Making directory 2025/02/15 02:45:41 DEBUG : Added delayed dir = "a", newDst= 2025/02/15 02:45:41 DEBUG : c: Directory modification time the same (differ by 299.147768ms, within tolerance 1s) 2025/02/15 02:45:41 DEBUG : Added delayed dir = "c", newDst=c 2025/02/15 02:45:41 DEBUG : a/potato2: Need to transfer - File not found at Destination 2025/02/15 02:45:41 DEBUG : c/non empty space: Size and modification time the same (differ by -123.456789ms, within tolerance 1s) 2025/02/15 02:45:41 DEBUG : c/non empty space: Unchanged skipping 2025/02/15 02:45:41 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for checks to finish 2025/02/15 02:45:41 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for transfers to finish 2025/02/15 02:45:42 DEBUG : a/potato2: Dst hash empty - aborting Src hash check 2025/02/15 02:45:42 INFO : a/potato2: Copied (new) 2025/02/15 02:45:42 ERROR : files root 'rclone-test-boxoxex3miye': not deleting files as there were IO errors 2025/02/15 02:45:42 INFO : a: Set directory modification time (using DirSetModTime) 2025/02/15 02:45:42 ERROR : files root 'rclone-test-boxoxex3miye': not deleting directories as there were IO errors run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" --- PASS: TestSyncAfterRemovingAFileAndAddingAFileSubDirWithErrors (5.28s) === RUN TestSyncDeleteAfter --- PASS: TestSyncDeleteAfter (0.00s) === RUN TestSyncDeleteDuring run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:45:45 DEBUG : Waiting for deletions to finish 2025/02/15 02:45:45 DEBUG : potato2: Need to transfer - File not found at Destination 2025/02/15 02:45:45 DEBUG : empty space: Size and modification time the same (differ by -123.456789ms, within tolerance 1s) 2025/02/15 02:45:45 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for checks to finish 2025/02/15 02:45:45 DEBUG : empty space: Unchanged skipping 2025/02/15 02:45:45 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for transfers to finish 2025/02/15 02:45:46 INFO : potato: Deleted 2025/02/15 02:45:46 DEBUG : potato2: Dst hash empty - aborting Src hash check 2025/02/15 02:45:46 INFO : potato2: Copied (new) run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" --- PASS: TestSyncDeleteDuring (3.41s) === RUN TestSyncDeleteBefore run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:45:49 DEBUG : Waiting for deletions to finish 2025/02/15 02:45:49 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for checks to finish 2025/02/15 02:45:49 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for transfers to finish 2025/02/15 02:45:49 INFO : potato: Deleted 2025/02/15 02:45:49 DEBUG : potato2: Need to transfer - File not found at Destination 2025/02/15 02:45:49 DEBUG : empty space: Size and modification time the same (differ by -123.456789ms, within tolerance 1s) 2025/02/15 02:45:49 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for checks to finish 2025/02/15 02:45:49 DEBUG : empty space: Unchanged skipping 2025/02/15 02:45:49 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for transfers to finish 2025/02/15 02:45:50 DEBUG : potato2: Dst hash empty - aborting Src hash check 2025/02/15 02:45:50 INFO : potato2: Copied (new) run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" --- PASS: TestSyncDeleteBefore (3.75s) === RUN TestCopyDeleteBefore run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:45:52 DEBUG : potato2: Need to transfer - File not found at Destination 2025/02/15 02:45:52 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for checks to finish 2025/02/15 02:45:52 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for transfers to finish 2025/02/15 02:45:53 DEBUG : potato2: Dst hash empty - aborting Src hash check 2025/02/15 02:45:53 INFO : potato2: Copied (new) run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" --- PASS: TestCopyDeleteBefore (2.60s) === RUN TestSyncWithExclude run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:45:55 DEBUG : enormous: Excluded (Size Filter) 2025/02/15 02:45:55 DEBUG : enormous: Excluded 2025/02/15 02:45:55 DEBUG : potato2: Excluded (Size Filter) 2025/02/15 02:45:55 DEBUG : potato2: Excluded 2025/02/15 02:45:56 DEBUG : potato2: Excluded (Size Filter) 2025/02/15 02:45:56 DEBUG : potato2: Excluded 2025/02/15 02:45:56 DEBUG : empty space: Size and modification time the same (differ by -123.456789ms, within tolerance 1s) 2025/02/15 02:45:56 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for checks to finish 2025/02/15 02:45:56 DEBUG : empty space: Unchanged skipping 2025/02/15 02:45:56 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for transfers to finish 2025/02/15 02:45:56 DEBUG : Waiting for deletions to finish 2025/02/15 02:45:56 INFO : There was nothing to transfer run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:45:56 DEBUG : enormous: Excluded (Size Filter) 2025/02/15 02:45:56 DEBUG : enormous: Excluded 2025/02/15 02:45:56 DEBUG : potato2: Excluded (Size Filter) 2025/02/15 02:45:56 DEBUG : potato2: Excluded 2025/02/15 02:45:56 DEBUG : potato2: Excluded (Size Filter) 2025/02/15 02:45:56 DEBUG : potato2: Excluded 2025/02/15 02:45:56 DEBUG : empty space: Size and modification time the same (differ by 123.456789ms, within tolerance 1s) 2025/02/15 02:45:56 DEBUG : Local file system at /tmp/rclone1494077444: Waiting for checks to finish 2025/02/15 02:45:56 DEBUG : empty space: Unchanged skipping 2025/02/15 02:45:56 DEBUG : Local file system at /tmp/rclone1494077444: Waiting for transfers to finish 2025/02/15 02:45:56 DEBUG : Waiting for deletions to finish 2025/02/15 02:45:56 INFO : There was nothing to transfer run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" --- PASS: TestSyncWithExclude (3.39s) === RUN TestSyncWithExcludeAndDeleteExcluded run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:45:59 DEBUG : enormous: Excluded (Size Filter) 2025/02/15 02:45:59 DEBUG : enormous: Excluded 2025/02/15 02:45:59 DEBUG : potato2: Excluded (Size Filter) 2025/02/15 02:45:59 DEBUG : potato2: Excluded 2025/02/15 02:45:59 DEBUG : empty space: Size and modification time the same (differ by -123.456789ms, within tolerance 1s) 2025/02/15 02:45:59 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for checks to finish 2025/02/15 02:45:59 DEBUG : empty space: Unchanged skipping 2025/02/15 02:45:59 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for transfers to finish 2025/02/15 02:45:59 DEBUG : Waiting for deletions to finish 2025/02/15 02:45:59 INFO : enormous: Deleted 2025/02/15 02:45:59 INFO : potato2: Deleted 2025/02/15 02:45:59 INFO : There was nothing to transfer run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:46:00 DEBUG : empty space: Size and modification time the same (differ by 123.456789ms, within tolerance 1s) 2025/02/15 02:46:00 DEBUG : empty space: Unchanged skipping 2025/02/15 02:46:00 DEBUG : Local file system at /tmp/rclone1494077444: Waiting for checks to finish 2025/02/15 02:46:00 DEBUG : Local file system at /tmp/rclone1494077444: Waiting for transfers to finish 2025/02/15 02:46:00 DEBUG : Waiting for deletions to finish 2025/02/15 02:46:00 INFO : enormous: Deleted 2025/02/15 02:46:00 INFO : potato2: Deleted 2025/02/15 02:46:00 INFO : There was nothing to transfer run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" --- PASS: TestSyncWithExcludeAndDeleteExcluded (3.80s) === RUN TestSyncWithUpdateOlder run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:46:04 DEBUG : five: Need to transfer - File not found at Destination 2025/02/15 02:46:04 DEBUG : four: Sizes differ (src 4 vs dst 8) 2025/02/15 02:46:04 DEBUG : one: Destination is newer than source, skipping 2025/02/15 02:46:04 DEBUG : three: Sizes identical 2025/02/15 02:46:04 DEBUG : two: Dst hash empty - aborting Src hash check 2025/02/15 02:46:04 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for checks to finish 2025/02/15 02:46:04 DEBUG : four: Destination mod time is within 1s of source but files differ, transferring 2025/02/15 02:46:04 DEBUG : three: Destination mod time is within 1s of source and files identical, skipping 2025/02/15 02:46:04 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for transfers to finish 2025/02/15 02:46:04 DEBUG : five: Dst hash empty - aborting Src hash check 2025/02/15 02:46:04 INFO : five: Copied (new) 2025/02/15 02:46:05 DEBUG : four: Dst hash empty - aborting Src hash check 2025/02/15 02:46:05 INFO : four: Copied (replaced existing) 2025/02/15 02:46:05 DEBUG : two: Dst hash empty - aborting Src hash check 2025/02/15 02:46:05 INFO : two: Copied (replaced existing) 2025/02/15 02:46:05 DEBUG : Waiting for deletions to finish 2025/02/15 02:46:05 DEBUG : five: Dst hash empty - aborting Src hash check 2025/02/15 02:46:05 DEBUG : four: Dst hash empty - aborting Src hash check 2025/02/15 02:46:05 DEBUG : one: Destination is newer than source, skipping 2025/02/15 02:46:05 DEBUG : three: Dst hash empty - aborting Src hash check 2025/02/15 02:46:05 DEBUG : two: Dst hash empty - aborting Src hash check 2025/02/15 02:46:05 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for checks to finish 2025/02/15 02:46:05 DEBUG : five: Size of src and dst objects identical 2025/02/15 02:46:05 DEBUG : five: Destination mod time is within 1s of source and files identical, skipping 2025/02/15 02:46:05 DEBUG : four: Size of src and dst objects identical 2025/02/15 02:46:05 DEBUG : four: Destination mod time is within 1s of source and files identical, skipping 2025/02/15 02:46:05 DEBUG : three: Size of src and dst objects identical 2025/02/15 02:46:05 DEBUG : three: Destination mod time is within 1s of source and files identical, skipping 2025/02/15 02:46:05 DEBUG : two: Size of src and dst objects identical 2025/02/15 02:46:05 DEBUG : two: Destination mod time is within 1s of source and files identical, skipping 2025/02/15 02:46:05 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for transfers to finish 2025/02/15 02:46:05 DEBUG : Waiting for deletions to finish --- PASS: TestSyncWithUpdateOlder (5.54s) === 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-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" sync_test.go:1538: Can track renames: true 2025/02/15 02:46:06 INFO : files root 'rclone-test-boxoxex3miye': Making map for --track-renames 2025/02/15 02:46:06 INFO : files root 'rclone-test-boxoxex3miye': Finished making map for --track-renames 2025/02/15 02:46:06 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for checks to finish 2025/02/15 02:46:06 DEBUG : potato: Need to transfer - No matching file found at Destination 2025/02/15 02:46:06 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for renames to finish 2025/02/15 02:46:06 DEBUG : yam: Need to transfer - No matching file found at Destination 2025/02/15 02:46:06 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for transfers to finish 2025/02/15 02:46:07 DEBUG : potato: Dst hash empty - aborting Src hash check 2025/02/15 02:46:07 INFO : potato: Copied (new) 2025/02/15 02:46:07 DEBUG : yam: Dst hash empty - aborting Src hash check 2025/02/15 02:46:07 INFO : yam: Copied (new) 2025/02/15 02:46:07 DEBUG : Waiting for deletions to finish run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:46:07 DEBUG : potato: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2025/02/15 02:46:07 INFO : files root 'rclone-test-boxoxex3miye': Making map for --track-renames 2025/02/15 02:46:07 INFO : files root 'rclone-test-boxoxex3miye': Finished making map for --track-renames 2025/02/15 02:46:07 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for checks to finish 2025/02/15 02:46:07 DEBUG : yaml: Need to transfer - No matching file found at Destination 2025/02/15 02:46:07 DEBUG : potato: Unchanged skipping 2025/02/15 02:46:07 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for renames to finish 2025/02/15 02:46:07 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for transfers to finish 2025/02/15 02:46:08 DEBUG : yaml: Dst hash empty - aborting Src hash check 2025/02/15 02:46:08 INFO : yaml: Copied (new) 2025/02/15 02:46:08 DEBUG : Waiting for deletions to finish 2025/02/15 02:46:08 INFO : yam: Deleted run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", 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.23s) === RUN TestParseRenamesStrategyModtime --- PASS: TestParseRenamesStrategyModtime (0.00s) === RUN TestRenamesStrategyModtime --- PASS: TestRenamesStrategyModtime (0.00s) === RUN TestSyncWithTrackRenamesStrategyModtime run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" sync_test.go:1610: Can track renames: true 2025/02/15 02:46:10 INFO : files root 'rclone-test-boxoxex3miye': Making map for --track-renames 2025/02/15 02:46:10 INFO : files root 'rclone-test-boxoxex3miye': Finished making map for --track-renames 2025/02/15 02:46:10 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for checks to finish 2025/02/15 02:46:10 DEBUG : potato: Need to transfer - No matching file found at Destination 2025/02/15 02:46:10 DEBUG : yam: Need to transfer - No matching file found at Destination 2025/02/15 02:46:10 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for renames to finish 2025/02/15 02:46:10 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for transfers to finish 2025/02/15 02:46:10 DEBUG : potato: Dst hash empty - aborting Src hash check 2025/02/15 02:46:10 INFO : potato: Copied (new) 2025/02/15 02:46:10 DEBUG : yam: Dst hash empty - aborting Src hash check 2025/02/15 02:46:10 INFO : yam: Copied (new) 2025/02/15 02:46:10 DEBUG : Waiting for deletions to finish run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:46:11 DEBUG : potato: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2025/02/15 02:46:11 INFO : files root 'rclone-test-boxoxex3miye': Making map for --track-renames 2025/02/15 02:46:11 INFO : files root 'rclone-test-boxoxex3miye': Finished making map for --track-renames 2025/02/15 02:46:11 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for checks to finish 2025/02/15 02:46:11 DEBUG : potato: Unchanged skipping 2025/02/15 02:46:11 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for renames to finish 2025/02/15 02:46:11 INFO : yam: Moved (server-side) to: yaml 2025/02/15 02:46:11 INFO : yaml: Renamed from "yam" 2025/02/15 02:46:11 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for transfers to finish 2025/02/15 02:46:11 DEBUG : Waiting for deletions to finish 2025/02/15 02:46:11 INFO : There was nothing to transfer run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" --- PASS: TestSyncWithTrackRenamesStrategyModtime (2.99s) === RUN TestSyncWithTrackRenamesStrategyLeaf run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" sync_test.go:1649: Can track renames: true 2025/02/15 02:46:13 DEBUG : Added delayed dir = "sub", newDst= 2025/02/15 02:46:13 INFO : files root 'rclone-test-boxoxex3miye': Making map for --track-renames 2025/02/15 02:46:13 INFO : files root 'rclone-test-boxoxex3miye': Finished making map for --track-renames 2025/02/15 02:46:13 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for checks to finish 2025/02/15 02:46:13 DEBUG : potato: Need to transfer - No matching file found at Destination 2025/02/15 02:46:13 DEBUG : sub/yam: Need to transfer - No matching file found at Destination 2025/02/15 02:46:13 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for renames to finish 2025/02/15 02:46:13 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for transfers to finish 2025/02/15 02:46:13 DEBUG : potato: Dst hash empty - aborting Src hash check 2025/02/15 02:46:13 INFO : potato: Copied (new) 2025/02/15 02:46:13 DEBUG : sub/yam: Dst hash empty - aborting Src hash check 2025/02/15 02:46:13 INFO : sub/yam: Copied (new) 2025/02/15 02:46:13 DEBUG : Waiting for deletions to finish 2025/02/15 02:46:13 INFO : sub: Set directory modification time (using DirSetModTime) run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:46:14 DEBUG : potato: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2025/02/15 02:46:14 DEBUG : potato: Unchanged skipping 2025/02/15 02:46:14 INFO : sub: Set directory modification time (using DirSetModTime) 2025/02/15 02:46:14 DEBUG : Added delayed dir = "sub", newDst=sub 2025/02/15 02:46:14 INFO : files root 'rclone-test-boxoxex3miye': Making map for --track-renames 2025/02/15 02:46:14 INFO : files root 'rclone-test-boxoxex3miye': Finished making map for --track-renames 2025/02/15 02:46:14 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for checks to finish 2025/02/15 02:46:14 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for renames to finish 2025/02/15 02:46:15 INFO : sub/yam: Moved (server-side) to: yam 2025/02/15 02:46:15 INFO : yam: Renamed from "sub/yam" 2025/02/15 02:46:15 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for transfers to finish 2025/02/15 02:46:15 DEBUG : Waiting for deletions to finish 2025/02/15 02:46:15 INFO : There was nothing to transfer run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" --- PASS: TestSyncWithTrackRenamesStrategyLeaf (4.00s) === RUN TestServerSideMoveLocal run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:46:16 DEBUG : Creating backend with remote "/tmp/rclone1494077444/dir1" 2025/02/15 02:46:16 DEBUG : Config file has changed externally - reloading 2025/02/15 02:46:16 DEBUG : Creating backend with remote "/tmp/rclone1494077444/dir2" 2025/02/15 02:46:16 DEBUG : Local file system at /tmp/rclone1494077444/dir2: Using server-side directory move 2025/02/15 02:46:16 INFO : Local file system at /tmp/rclone1494077444/dir2: Server side directory move failed - fallback to file moves: can't copy directory - destination already exists 2025/02/15 02:46:16 DEBUG : file1.txt: Need to transfer - File not found at Destination 2025/02/15 02:46:16 INFO : file1.txt: Moved (server-side) 2025/02/15 02:46:16 DEBUG : Local file system at /tmp/rclone1494077444/dir2: Waiting for checks to finish 2025/02/15 02:46:16 DEBUG : Local file system at /tmp/rclone1494077444/dir2: Waiting for transfers to finish --- PASS: TestServerSideMoveLocal (0.26s) === RUN TestMoveWithDeleteEmptySrcDirs run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:46:17 DEBUG : Added delayed dir = "nested", newDst= 2025/02/15 02:46:17 DEBUG : Added delayed dir = "sub dir", newDst= 2025/02/15 02:46:17 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2025/02/15 02:46:17 DEBUG : Added delayed dir = "nested/sub dir", newDst= 2025/02/15 02:46:17 DEBUG : nested/sub dir/file: Need to transfer - File not found at Destination 2025/02/15 02:46:17 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for checks to finish 2025/02/15 02:46:17 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for transfers to finish 2025/02/15 02:46:18 DEBUG : nested/sub dir/file: Dst hash empty - aborting Src hash check 2025/02/15 02:46:18 INFO : nested/sub dir/file: Copied (new) 2025/02/15 02:46:18 INFO : nested/sub dir/file: Deleted 2025/02/15 02:46:18 DEBUG : sub dir/hello world: Dst hash empty - aborting Src hash check 2025/02/15 02:46:18 INFO : sub dir/hello world: Copied (new) 2025/02/15 02:46:18 INFO : sub dir/hello world: Deleted 2025/02/15 02:46:18 INFO : nested/sub dir: Set directory modification time (using DirSetModTime) 2025/02/15 02:46:19 INFO : sub dir: Set directory modification time (using DirSetModTime) 2025/02/15 02:46:19 INFO : nested: Set directory modification time (using DirSetModTime) 2025/02/15 02:46:19 INFO : sub dir: Removing directory 2025/02/15 02:46:19 INFO : nested/sub dir: Removing directory 2025/02/15 02:46:19 INFO : nested: Removing directory 2025/02/15 02:46:19 DEBUG : Local file system at /tmp/rclone1494077444: deleted 3 directories run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" --- PASS: TestMoveWithDeleteEmptySrcDirs (4.01s) === RUN TestMoveWithoutDeleteEmptySrcDirs run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:46:21 DEBUG : Added delayed dir = "nested", newDst= 2025/02/15 02:46:21 DEBUG : Added delayed dir = "sub dir", newDst= 2025/02/15 02:46:21 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2025/02/15 02:46:21 DEBUG : Added delayed dir = "nested/sub dir", newDst= 2025/02/15 02:46:21 DEBUG : nested/sub dir/file: Need to transfer - File not found at Destination 2025/02/15 02:46:21 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for checks to finish 2025/02/15 02:46:21 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for transfers to finish 2025/02/15 02:46:22 DEBUG : sub dir/hello world: Dst hash empty - aborting Src hash check 2025/02/15 02:46:22 INFO : sub dir/hello world: Copied (new) 2025/02/15 02:46:22 INFO : sub dir/hello world: Deleted 2025/02/15 02:46:22 DEBUG : nested/sub dir/file: Dst hash empty - aborting Src hash check 2025/02/15 02:46:22 INFO : nested/sub dir/file: Copied (new) 2025/02/15 02:46:22 INFO : nested/sub dir/file: Deleted 2025/02/15 02:46:22 INFO : nested/sub dir: Set directory modification time (using DirSetModTime) 2025/02/15 02:46:22 INFO : sub dir: Set directory modification time (using DirSetModTime) 2025/02/15 02:46:22 INFO : nested: Set directory modification time (using DirSetModTime) run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" --- PASS: TestMoveWithoutDeleteEmptySrcDirs (3.28s) === RUN TestMoveWithIgnoreExisting run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:46:24 DEBUG : existing: Need to transfer - File not found at Destination 2025/02/15 02:46:24 DEBUG : existing-b: Need to transfer - File not found at Destination 2025/02/15 02:46:24 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for checks to finish 2025/02/15 02:46:24 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for transfers to finish 2025/02/15 02:46:25 DEBUG : existing: Dst hash empty - aborting Src hash check 2025/02/15 02:46:25 INFO : existing: Copied (new) 2025/02/15 02:46:25 INFO : existing: Deleted 2025/02/15 02:46:25 DEBUG : existing-b: Dst hash empty - aborting Src hash check 2025/02/15 02:46:25 INFO : existing-b: Copied (new) 2025/02/15 02:46:25 INFO : existing-b: Deleted 2025/02/15 02:46:25 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for checks to finish 2025/02/15 02:46:25 DEBUG : existing: Destination exists, skipping 2025/02/15 02:46:25 DEBUG : existing: Not removing source file as destination file exists and --ignore-existing is set 2025/02/15 02:46:25 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for transfers to finish 2025/02/15 02:46:25 INFO : There was nothing to transfer run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" --- PASS: TestMoveWithIgnoreExisting (2.04s) === RUN TestServerSideMove run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:46:26 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-wafikav3kaco" sync_test.go:1705: Server side move (if possible) files root 'rclone-test-boxoxex3miye' -> files root 'rclone-test-wafikav3kaco' 2025/02/15 02:46:31 DEBUG : files root 'rclone-test-wafikav3kaco': Using server-side directory move 2025/02/15 02:46:31 INFO : files root 'rclone-test-wafikav3kaco': Server side directory move failed - fallback to file moves: can't copy directory - destination already exists 2025/02/15 02:46:32 DEBUG : potato2: Need to transfer - File not found at Destination 2025/02/15 02:46:32 DEBUG : empty space: Size and modification time the same (differ by 0s, within tolerance 1s) 2025/02/15 02:46:32 DEBUG : potato3: Sizes differ (src 68 vs dst 60) 2025/02/15 02:46:32 DEBUG : empty space: Unchanged skipping 2025/02/15 02:46:32 DEBUG : files root 'rclone-test-wafikav3kaco': Waiting for checks to finish 2025/02/15 02:46:32 INFO : empty space: Deleted 2025/02/15 02:46:32 DEBUG : files root 'rclone-test-wafikav3kaco': Waiting for transfers to finish 2025/02/15 02:46:32 INFO : potato3: Deleted 2025/02/15 02:46:32 INFO : potato2: Moved (server-side) 2025/02/15 02:46:32 INFO : potato3: Moved (server-side) 2025/02/15 02:46:33 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-puquziy7rihe" 2025/02/15 02:46:33 DEBUG : files root 'rclone-test-puquziy7rihe': Using server-side directory move 2025/02/15 02:46:34 INFO : files root 'rclone-test-puquziy7rihe': Server side directory move succeeded 2025/02/15 02:46:35 ERROR : : error listing: directory not found 2025/02/15 02:46:35 DEBUG : files root 'rclone-test-puquziy7rihe': Purge remote 2025/02/15 02:46:35 DEBUG : files root 'rclone-test-wafikav3kaco': Purge remote 2025/02/15 02:46:35 NOTICE: purge failed: directory not found --- PASS: TestServerSideMove (9.01s) === RUN TestServerSideMoveWithFilter run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:46:35 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-qowakik5xebu" sync_test.go:1705: Server side move (if possible) files root 'rclone-test-boxoxex3miye' -> files root 'rclone-test-qowakik5xebu' 2025/02/15 02:46:41 DEBUG : empty space: Excluded (Size Filter) 2025/02/15 02:46:41 DEBUG : empty space: Excluded 2025/02/15 02:46:41 DEBUG : empty space: Excluded (Size Filter) 2025/02/15 02:46:41 DEBUG : empty space: Excluded 2025/02/15 02:46:41 DEBUG : potato2: Need to transfer - File not found at Destination 2025/02/15 02:46:41 DEBUG : files root 'rclone-test-qowakik5xebu': Waiting for checks to finish 2025/02/15 02:46:41 DEBUG : potato3: Sizes differ (src 68 vs dst 60) 2025/02/15 02:46:41 DEBUG : files root 'rclone-test-qowakik5xebu': Waiting for transfers to finish 2025/02/15 02:46:41 INFO : potato3: Deleted 2025/02/15 02:46:41 INFO : potato2: Moved (server-side) 2025/02/15 02:46:41 INFO : potato3: Moved (server-side) 2025/02/15 02:46:42 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-dateveg0juti" 2025/02/15 02:46:42 DEBUG : empty space: Excluded (Size Filter) 2025/02/15 02:46:42 DEBUG : empty space: Excluded 2025/02/15 02:46:42 DEBUG : potato2: Need to transfer - File not found at Destination 2025/02/15 02:46:42 DEBUG : potato3: Need to transfer - File not found at Destination 2025/02/15 02:46:42 DEBUG : files root 'rclone-test-dateveg0juti': Waiting for checks to finish 2025/02/15 02:46:42 DEBUG : files root 'rclone-test-dateveg0juti': Waiting for transfers to finish 2025/02/15 02:46:43 INFO : potato2: Moved (server-side) 2025/02/15 02:46:43 INFO : potato3: Moved (server-side) 2025/02/15 02:46:43 DEBUG : files root 'rclone-test-dateveg0juti': Purge remote 2025/02/15 02:46:43 DEBUG : files root 'rclone-test-qowakik5xebu': Purge remote --- PASS: TestServerSideMoveWithFilter (8.62s) === RUN TestServerSideMoveDeleteEmptySourceDirs run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:46:44 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-cepovob0cofa" 2025/02/15 02:46:47 INFO : tomatoDir: Making directory sync_test.go:1705: Server side move (if possible) files root 'rclone-test-boxoxex3miye' -> files root 'rclone-test-cepovob0cofa' 2025/02/15 02:46:50 DEBUG : files root 'rclone-test-cepovob0cofa': Using server-side directory move 2025/02/15 02:46:50 INFO : files root 'rclone-test-cepovob0cofa': Server side directory move failed - fallback to file moves: can't copy directory - destination already exists 2025/02/15 02:46:50 DEBUG : potato2: Need to transfer - File not found at Destination 2025/02/15 02:46:50 DEBUG : Added delayed dir = "tomatoDir", newDst= 2025/02/15 02:46:50 DEBUG : empty space: Size and modification time the same (differ by 0s, within tolerance 1s) 2025/02/15 02:46:50 DEBUG : empty space: Unchanged skipping 2025/02/15 02:46:50 DEBUG : potato3: Sizes differ (src 68 vs dst 60) 2025/02/15 02:46:50 DEBUG : files root 'rclone-test-cepovob0cofa': Waiting for checks to finish 2025/02/15 02:46:50 INFO : empty space: Deleted 2025/02/15 02:46:50 DEBUG : files root 'rclone-test-cepovob0cofa': Waiting for transfers to finish 2025/02/15 02:46:50 INFO : potato3: Deleted 2025/02/15 02:46:51 INFO : potato2: Moved (server-side) 2025/02/15 02:46:51 INFO : potato3: Moved (server-side) 2025/02/15 02:46:51 INFO : tomatoDir: Removing directory 2025/02/15 02:46:51 DEBUG : files root 'rclone-test-boxoxex3miye': deleted 1 directories 2025/02/15 02:46:51 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-qaxumuc2hage" 2025/02/15 02:46:52 INFO : tomatoDir: Making directory 2025/02/15 02:46:52 DEBUG : files root 'rclone-test-qaxumuc2hage': Using server-side directory move 2025/02/15 02:46:53 INFO : files root 'rclone-test-qaxumuc2hage': Server side directory move succeeded 2025/02/15 02:46:54 ERROR : : error listing: directory not found 2025/02/15 02:46:54 ERROR : : error listing: directory not found 2025/02/15 02:46:54 DEBUG : files root 'rclone-test-qaxumuc2hage': Purge remote 2025/02/15 02:46:54 DEBUG : files root 'rclone-test-cepovob0cofa': Purge remote 2025/02/15 02:46:54 NOTICE: purge failed: directory not found --- PASS: TestServerSideMoveDeleteEmptySourceDirs (10.99s) === RUN TestServerSideMoveOverlap run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" sync_test.go:1910: Skipping test as remote supports DirMove --- SKIP: TestServerSideMoveOverlap (0.27s) === RUN TestSyncOverlap run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:46:55 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-boxoxex3miye/rclone-sync-test" run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" --- PASS: TestSyncOverlap (2.00s) === RUN TestSyncOverlapWithFilter run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:46:57 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-boxoxex3miye/rclone-sync-test" 2025/02/15 02:46:58 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-boxoxex3miye/rclone-sync-test-include/layer2" 2025/02/15 02:46:59 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-boxoxex3miye/rclone-sync-test-ignore-file" 2025/02/15 02:47:02 DEBUG : rclone-sync-test: Excluded 2025/02/15 02:47:02 DEBUG : rclone-sync-test-ignore-file: Excluded 2025/02/15 02:47:02 DEBUG : Added delayed dir = "rclone-sync-test-include", newDst= 2025/02/15 02:47:02 DEBUG : rclone-sync-test-include/layer2: Excluded 2025/02/15 02:47:02 DEBUG : files root 'rclone-test-boxoxex3miye/rclone-sync-test': Waiting for checks to finish 2025/02/15 02:47:02 DEBUG : files root 'rclone-test-boxoxex3miye/rclone-sync-test': Waiting for transfers to finish 2025/02/15 02:47:02 DEBUG : Waiting for deletions to finish 2025/02/15 02:47:02 INFO : There was nothing to transfer 2025/02/15 02:47:03 DEBUG : rclone-sync-test: Excluded 2025/02/15 02:47:03 DEBUG : rclone-sync-test-ignore-file: Excluded 2025/02/15 02:47:03 DEBUG : rclone-sync-test-include/layer2: Excluded 2025/02/15 02:47:03 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for checks to finish 2025/02/15 02:47:03 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for transfers to finish 2025/02/15 02:47:03 DEBUG : Waiting for deletions to finish 2025/02/15 02:47:03 INFO : rclone-sync-test-include: Removing directory 2025/02/15 02:47:03 DEBUG : pacer: low level retry 1/10 (error Folder Not Empty - `Folder rclone-test-boxoxex3miye/rclone-sync-test-include not empty`) 2025/02/15 02:47:03 DEBUG : pacer: Rate limited, increasing sleep to 20ms 2025/02/15 02:47:04 DEBUG : pacer: low level retry 2/10 (error Folder Not Empty - `Folder rclone-test-boxoxex3miye/rclone-sync-test-include not empty`) 2025/02/15 02:47:04 DEBUG : pacer: Rate limited, increasing sleep to 40ms 2025/02/15 02:47:04 DEBUG : pacer: low level retry 3/10 (error Folder Not Empty - `Folder rclone-test-boxoxex3miye/rclone-sync-test-include not empty`) 2025/02/15 02:47:04 DEBUG : pacer: Rate limited, increasing sleep to 80ms 2025/02/15 02:47:04 DEBUG : pacer: low level retry 4/10 (error Folder Not Empty - `Folder rclone-test-boxoxex3miye/rclone-sync-test-include not empty`) 2025/02/15 02:47:04 DEBUG : pacer: Rate limited, increasing sleep to 160ms 2025/02/15 02:47:04 DEBUG : pacer: low level retry 5/10 (error Folder Not Empty - `Folder rclone-test-boxoxex3miye/rclone-sync-test-include not empty`) 2025/02/15 02:47:04 DEBUG : pacer: Rate limited, increasing sleep to 320ms 2025/02/15 02:47:04 DEBUG : pacer: low level retry 6/10 (error Folder Not Empty - `Folder rclone-test-boxoxex3miye/rclone-sync-test-include not empty`) 2025/02/15 02:47:04 DEBUG : pacer: Rate limited, increasing sleep to 640ms 2025/02/15 02:47:05 DEBUG : pacer: low level retry 7/10 (error Folder Not Empty - `Folder rclone-test-boxoxex3miye/rclone-sync-test-include not empty`) 2025/02/15 02:47:05 DEBUG : pacer: Rate limited, increasing sleep to 1.28s 2025/02/15 02:47:05 DEBUG : pacer: low level retry 8/10 (error Folder Not Empty - `Folder rclone-test-boxoxex3miye/rclone-sync-test-include not empty`) 2025/02/15 02:47:05 DEBUG : pacer: Rate limited, increasing sleep to 2s 2025/02/15 02:47:07 DEBUG : pacer: low level retry 9/10 (error Folder Not Empty - `Folder rclone-test-boxoxex3miye/rclone-sync-test-include not empty`) 2025/02/15 02:47:09 DEBUG : pacer: low level retry 10/10 (error Folder Not Empty - `Folder rclone-test-boxoxex3miye/rclone-sync-test-include not empty`) 2025/02/15 02:47:09 DEBUG : rclone-sync-test-include: Failed to Rmdir: directory not empty 2025/02/15 02:47:09 DEBUG : files root 'rclone-test-boxoxex3miye': failed to delete 1 directories 2025/02/15 02:47:09 INFO : There was nothing to transfer run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:47:11 DEBUG : pacer: Reducing sleep to 1.5s 2025/02/15 02:47:12 DEBUG : pacer: Reducing sleep to 1.125s 2025/02/15 02:47:14 DEBUG : pacer: Reducing sleep to 843.75ms 2025/02/15 02:47:14 DEBUG : rclone-sync-test: Excluded 2025/02/15 02:47:15 DEBUG : pacer: Reducing sleep to 632.8125ms 2025/02/15 02:47:15 DEBUG : rclone-sync-test-ignore-file: Excluded 2025/02/15 02:47:16 DEBUG : pacer: Reducing sleep to 474.609375ms 2025/02/15 02:47:16 DEBUG : Added delayed dir = "rclone-sync-test-include", newDst= 2025/02/15 02:47:17 DEBUG : pacer: Reducing sleep to 355.957031ms 2025/02/15 02:47:17 DEBUG : pacer: Reducing sleep to 266.967773ms 2025/02/15 02:47:17 DEBUG : rclone-sync-test-include/layer2: Excluded 2025/02/15 02:47:17 DEBUG : files root 'rclone-test-boxoxex3miye/rclone-sync-test-include/layer2': Waiting for checks to finish 2025/02/15 02:47:17 DEBUG : files root 'rclone-test-boxoxex3miye/rclone-sync-test-include/layer2': Waiting for transfers to finish 2025/02/15 02:47:17 DEBUG : Waiting for deletions to finish 2025/02/15 02:47:17 INFO : There was nothing to transfer run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:47:18 DEBUG : pacer: Reducing sleep to 200.225829ms 2025/02/15 02:47:18 DEBUG : pacer: Reducing sleep to 150.169371ms 2025/02/15 02:47:18 DEBUG : pacer: Reducing sleep to 112.627028ms 2025/02/15 02:47:18 DEBUG : rclone-sync-test: Excluded 2025/02/15 02:47:18 DEBUG : pacer: Reducing sleep to 84.470271ms 2025/02/15 02:47:18 DEBUG : rclone-sync-test-ignore-file: Excluded 2025/02/15 02:47:18 DEBUG : pacer: Reducing sleep to 63.352703ms 2025/02/15 02:47:18 DEBUG : pacer: Reducing sleep to 47.514527ms 2025/02/15 02:47:19 DEBUG : pacer: Reducing sleep to 35.635895ms 2025/02/15 02:47:19 DEBUG : rclone-sync-test-include/layer2: Excluded 2025/02/15 02:47:19 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for checks to finish 2025/02/15 02:47:19 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for transfers to finish 2025/02/15 02:47:19 DEBUG : Waiting for deletions to finish 2025/02/15 02:47:19 INFO : rclone-sync-test-include: Removing directory 2025/02/15 02:47:19 DEBUG : pacer: low level retry 1/10 (error Folder Not Empty - `Folder rclone-test-boxoxex3miye/rclone-sync-test-include not empty`) 2025/02/15 02:47:19 DEBUG : pacer: Rate limited, increasing sleep to 71.27179ms 2025/02/15 02:47:19 DEBUG : pacer: low level retry 2/10 (error Folder Not Empty - `Folder rclone-test-boxoxex3miye/rclone-sync-test-include not empty`) 2025/02/15 02:47:19 DEBUG : pacer: Rate limited, increasing sleep to 142.54358ms 2025/02/15 02:47:19 DEBUG : pacer: low level retry 3/10 (error Folder Not Empty - `Folder rclone-test-boxoxex3miye/rclone-sync-test-include not empty`) 2025/02/15 02:47:19 DEBUG : pacer: Rate limited, increasing sleep to 285.08716ms 2025/02/15 02:47:19 DEBUG : pacer: low level retry 4/10 (error Folder Not Empty - `Folder rclone-test-boxoxex3miye/rclone-sync-test-include not empty`) 2025/02/15 02:47:19 DEBUG : pacer: Rate limited, increasing sleep to 570.17432ms 2025/02/15 02:47:19 DEBUG : pacer: low level retry 5/10 (error Folder Not Empty - `Folder rclone-test-boxoxex3miye/rclone-sync-test-include not empty`) 2025/02/15 02:47:19 DEBUG : pacer: Rate limited, increasing sleep to 1.14034864s 2025/02/15 02:47:20 DEBUG : pacer: low level retry 6/10 (error Folder Not Empty - `Folder rclone-test-boxoxex3miye/rclone-sync-test-include not empty`) 2025/02/15 02:47:20 DEBUG : pacer: Rate limited, increasing sleep to 2s 2025/02/15 02:47:21 DEBUG : pacer: low level retry 7/10 (error Folder Not Empty - `Folder rclone-test-boxoxex3miye/rclone-sync-test-include not empty`) 2025/02/15 02:47:23 DEBUG : pacer: low level retry 8/10 (error Folder Not Empty - `Folder rclone-test-boxoxex3miye/rclone-sync-test-include not empty`) 2025/02/15 02:47:25 DEBUG : pacer: low level retry 9/10 (error Folder Not Empty - `Folder rclone-test-boxoxex3miye/rclone-sync-test-include not empty`) 2025/02/15 02:47:27 DEBUG : pacer: low level retry 10/10 (error Folder Not Empty - `Folder rclone-test-boxoxex3miye/rclone-sync-test-include not empty`) 2025/02/15 02:47:27 DEBUG : rclone-sync-test-include: Failed to Rmdir: directory not empty 2025/02/15 02:47:27 DEBUG : files root 'rclone-test-boxoxex3miye': failed to delete 1 directories 2025/02/15 02:47:27 INFO : There was nothing to transfer run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:47:29 DEBUG : pacer: Reducing sleep to 1.5s 2025/02/15 02:47:30 DEBUG : : Excluded 2025/02/15 02:47:31 DEBUG : pacer: Reducing sleep to 1.125s 2025/02/15 02:47:33 DEBUG : pacer: Reducing sleep to 843.75ms 2025/02/15 02:47:33 DEBUG : rclone-sync-test: Excluded 2025/02/15 02:47:34 DEBUG : pacer: Reducing sleep to 632.8125ms 2025/02/15 02:47:34 DEBUG : rclone-sync-test-ignore-file: Excluded 2025/02/15 02:47:35 DEBUG : pacer: Reducing sleep to 474.609375ms 2025/02/15 02:47:35 DEBUG : Added delayed dir = "rclone-sync-test-include", newDst= 2025/02/15 02:47:35 DEBUG : pacer: Reducing sleep to 355.957031ms 2025/02/15 02:47:36 DEBUG : pacer: Reducing sleep to 266.967773ms 2025/02/15 02:47:36 DEBUG : rclone-sync-test-include/layer2: Excluded 2025/02/15 02:47:36 DEBUG : files root 'rclone-test-boxoxex3miye/rclone-sync-test-ignore-file': Waiting for checks to finish 2025/02/15 02:47:36 DEBUG : files root 'rclone-test-boxoxex3miye/rclone-sync-test-ignore-file': Waiting for transfers to finish 2025/02/15 02:47:36 DEBUG : Waiting for deletions to finish 2025/02/15 02:47:36 INFO : There was nothing to transfer run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:47:36 DEBUG : pacer: Reducing sleep to 200.225829ms 2025/02/15 02:47:36 DEBUG : pacer: Reducing sleep to 150.169371ms 2025/02/15 02:47:36 DEBUG : pacer: Reducing sleep to 112.627028ms 2025/02/15 02:47:36 DEBUG : pacer: Reducing sleep to 84.470271ms 2025/02/15 02:47:37 DEBUG : pacer: Reducing sleep to 63.352703ms 2025/02/15 02:47:37 DEBUG : pacer: Reducing sleep to 47.514527ms 2025/02/15 02:47:37 DEBUG : pacer: Reducing sleep to 35.635895ms 2025/02/15 02:47:37 DEBUG : pacer: low level retry 1/10 (error Folder Not Empty - `Folder rclone-test-boxoxex3miye/rclone-sync-test-include not empty`) 2025/02/15 02:47:37 DEBUG : pacer: Rate limited, increasing sleep to 71.27179ms 2025/02/15 02:47:37 DEBUG : pacer: low level retry 2/10 (error Folder Not Empty - `Folder rclone-test-boxoxex3miye/rclone-sync-test-include not empty`) 2025/02/15 02:47:37 DEBUG : pacer: Rate limited, increasing sleep to 142.54358ms 2025/02/15 02:47:37 DEBUG : pacer: low level retry 3/10 (error Folder Not Empty - `Folder rclone-test-boxoxex3miye/rclone-sync-test-include not empty`) 2025/02/15 02:47:37 DEBUG : pacer: Rate limited, increasing sleep to 285.08716ms 2025/02/15 02:47:38 DEBUG : pacer: Reducing sleep to 213.81537ms 2025/02/15 02:47:38 DEBUG : pacer: Reducing sleep to 160.361527ms 2025/02/15 02:47:38 DEBUG : pacer: Reducing sleep to 120.271145ms 2025/02/15 02:47:38 DEBUG : pacer: Reducing sleep to 90.203358ms 2025/02/15 02:47:38 DEBUG : pacer: Reducing sleep to 67.652518ms 2025/02/15 02:47:38 DEBUG : pacer: Reducing sleep to 50.739388ms 2025/02/15 02:47:38 DEBUG : pacer: Reducing sleep to 38.054541ms 2025/02/15 02:47:39 DEBUG : pacer: Reducing sleep to 28.540905ms 2025/02/15 02:47:39 DEBUG : pacer: Reducing sleep to 21.405678ms 2025/02/15 02:47:39 DEBUG : pacer: Reducing sleep to 16.054258ms 2025/02/15 02:47:39 DEBUG : pacer: Reducing sleep to 12.040693ms 2025/02/15 02:47:39 DEBUG : pacer: Reducing sleep to 10ms --- PASS: TestSyncOverlapWithFilter (45.53s) === RUN TestSyncCompareDest run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:47:42 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-boxoxex3miye/dst" 2025/02/15 02:47:43 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-boxoxex3miye/CompareDest" 2025/02/15 02:47:44 DEBUG : one: Need to transfer - File not found at Destination 2025/02/15 02:47:44 DEBUG : files root 'rclone-test-boxoxex3miye/dst': Waiting for checks to finish 2025/02/15 02:47:44 DEBUG : files root 'rclone-test-boxoxex3miye/dst': Waiting for transfers to finish 2025/02/15 02:47:46 DEBUG : one: Dst hash empty - aborting Src hash check 2025/02/15 02:47:46 INFO : one: Copied (new) 2025/02/15 02:47:46 DEBUG : Waiting for deletions to finish 2025/02/15 02:47:47 DEBUG : one: Sizes differ (src 5 vs dst 3) 2025/02/15 02:47:47 DEBUG : files root 'rclone-test-boxoxex3miye/dst': Waiting for checks to finish 2025/02/15 02:47:47 DEBUG : files root 'rclone-test-boxoxex3miye/dst': Waiting for transfers to finish 2025/02/15 02:47:48 DEBUG : one: Dst hash empty - aborting Src hash check 2025/02/15 02:47:48 INFO : one: Copied (replaced existing) 2025/02/15 02:47:48 DEBUG : Waiting for deletions to finish 2025/02/15 02:47:50 DEBUG : one: Sizes differ (src 5 vs dst 3) 2025/02/15 02:47:50 DEBUG : files root 'rclone-test-boxoxex3miye/dst': Waiting for checks to finish 2025/02/15 02:47:50 DEBUG : one: Size and modification time the same (differ by -123.456789ms, within tolerance 1s) 2025/02/15 02:47:50 DEBUG : one: Destination found in --compare-dest, skipping 2025/02/15 02:47:50 DEBUG : files root 'rclone-test-boxoxex3miye/dst': Waiting for transfers to finish 2025/02/15 02:47:50 DEBUG : Waiting for deletions to finish 2025/02/15 02:47:50 INFO : There was nothing to transfer 2025/02/15 02:47:52 DEBUG : two: Size and modification time the same (differ by -123.456789ms, within tolerance 1s) 2025/02/15 02:47:52 DEBUG : two: Destination found in --compare-dest, skipping 2025/02/15 02:47:52 DEBUG : one: Sizes differ (src 5 vs dst 3) 2025/02/15 02:47:52 DEBUG : files root 'rclone-test-boxoxex3miye/dst': Waiting for checks to finish 2025/02/15 02:47:52 DEBUG : one: Size and modification time the same (differ by -123.456789ms, within tolerance 1s) 2025/02/15 02:47:52 DEBUG : one: Destination found in --compare-dest, skipping 2025/02/15 02:47:52 DEBUG : files root 'rclone-test-boxoxex3miye/dst': Waiting for transfers to finish 2025/02/15 02:47:52 DEBUG : Waiting for deletions to finish 2025/02/15 02:47:52 INFO : There was nothing to transfer 2025/02/15 02:47:53 DEBUG : two: Size and modification time the same (differ by -123.456789ms, within tolerance 1s) 2025/02/15 02:47:53 DEBUG : two: Destination found in --compare-dest, skipping 2025/02/15 02:47:53 DEBUG : one: Sizes differ (src 5 vs dst 3) 2025/02/15 02:47:53 DEBUG : files root 'rclone-test-boxoxex3miye/dst': Waiting for checks to finish 2025/02/15 02:47:53 DEBUG : one: Size and modification time the same (differ by -123.456789ms, within tolerance 1s) 2025/02/15 02:47:53 DEBUG : one: Destination found in --compare-dest, skipping 2025/02/15 02:47:53 DEBUG : files root 'rclone-test-boxoxex3miye/dst': Waiting for transfers to finish 2025/02/15 02:47:53 DEBUG : Waiting for deletions to finish 2025/02/15 02:47:53 INFO : There was nothing to transfer sync_test.go:2175: No hash on uploaded file so skipping compare timestamp test 2025/02/15 02:47:54 DEBUG : two: Sizes differ (src 5 vs dst 3) 2025/02/15 02:47:54 DEBUG : two: Need to transfer - File not found at Destination 2025/02/15 02:47:54 DEBUG : one: Sizes differ (src 5 vs dst 3) 2025/02/15 02:47:54 DEBUG : files root 'rclone-test-boxoxex3miye/dst': Waiting for checks to finish 2025/02/15 02:47:54 DEBUG : one: Size and modification time the same (differ by -123.456789ms, within tolerance 1s) 2025/02/15 02:47:54 DEBUG : one: Destination found in --compare-dest, skipping 2025/02/15 02:47:54 DEBUG : files root 'rclone-test-boxoxex3miye/dst': Waiting for transfers to finish 2025/02/15 02:47:55 DEBUG : two: Dst hash empty - aborting Src hash check 2025/02/15 02:47:55 INFO : two: Copied (new) 2025/02/15 02:47:55 DEBUG : Waiting for deletions to finish --- PASS: TestSyncCompareDest (14.30s) === RUN TestSyncMultipleCompareDest run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:47:58 DEBUG : pacer: low level retry 1/10 (error Put "https://s3.amazonaws.com/objects.brickftp.com/metadata/126732/02a18c9a-1399-47d3-b2c8-2b2350f2d500?X-Amz-Algorithm=AWS4-HMAC-SHA256&X-Amz-Credential=AKIAIEWLY3MN4YGZQOWA%2F20250215%2Fus-east-1%2Fs3%2Faws4_request&X-Amz-Date=20250215T024757Z&X-Amz-Expires=900&X-Amz-SignedHeaders=host&partNumber=1&response-content-type=application%2Foctet-stream&uploadId=1NBkywwMZYC57hbYnKE2NV2YvBQnI32ftNjw_7GHDeHbTdbL7OfRHEyB65qWFO2glnKHSlwmpuPyfILgRt_HAISnboLrWVBiIXlLhmrHmDWIV65MObm1mVjbYg4YOEKX&X-Amz-Signature=a457976e9134905398f43e61af090f5778694a6d816bb8293072b57a702a2752": net/http: HTTP/1.x transport connection broken: http: ContentLength=1 with Body length 0) 2025/02/15 02:47:58 DEBUG : pacer: Rate limited, increasing sleep to 20ms 2025/02/15 02:47:59 DEBUG : pacer: Reducing sleep to 15ms 2025/02/15 02:47:59 DEBUG : pacer: Reducing sleep to 11.25ms 2025/02/15 02:48:00 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:2212 Error: Should be true Test: TestSyncMultipleCompareDest Messages: listing wrong, want pre-dest1/1 (1), pre-dest2/2 (1) got pre-dest1/1 (0), pre-dest2/2 (1) 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:2212 Error: Not equal: expected: 1 actual : 0 Test: TestSyncMultipleCompareDest Messages: pre-dest1/1: size incorrect file=1 vs obj=0 2025/02/15 02:48:08 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-boxoxex3miye/dest" 2025/02/15 02:48:09 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-boxoxex3miye/pre-dest1" 2025/02/15 02:48:09 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-boxoxex3miye/pre-dest2" 2025/02/15 02:48:11 DEBUG : 1: Sizes differ (src 1 vs dst 0) 2025/02/15 02:48:11 DEBUG : 1: Need to transfer - File not found at Destination 2025/02/15 02:48:11 DEBUG : 2: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2025/02/15 02:48:11 DEBUG : 2: Destination found in --compare-dest, skipping 2025/02/15 02:48:12 DEBUG : 3: Need to transfer - File not found at Destination 2025/02/15 02:48:12 DEBUG : files root 'rclone-test-boxoxex3miye/dest': Waiting for checks to finish 2025/02/15 02:48:12 DEBUG : files root 'rclone-test-boxoxex3miye/dest': Waiting for transfers to finish 2025/02/15 02:48:12 DEBUG : 1: Dst hash empty - aborting Src hash check 2025/02/15 02:48:12 INFO : 1: Copied (new) 2025/02/15 02:48:12 DEBUG : 3: Dst hash empty - aborting Src hash check 2025/02/15 02:48:12 INFO : 3: Copied (new) 2025/02/15 02:48:12 DEBUG : Waiting for deletions to finish 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/fs/sync/sync_test.go:2224 Error: Should be true Test: TestSyncMultipleCompareDest Messages: listing wrong, want 3 (1) got 1 (1), 3 (1) fstest.go:185: Error Trace: /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:185 /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/fs/sync/sync_test.go:2224 Error: Should be true Test: TestSyncMultipleCompareDest Messages: Unexpected file "1" 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:2225 Error: Should be true Test: TestSyncMultipleCompareDest Messages: listing wrong, want dest/3 (1), pre-dest1/1 (1), pre-dest2/2 (1) got dest/1 (1), dest/3 (1), pre-dest1/1 (0), pre-dest2/2 (1) fstest.go:185: Error Trace: /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:185 /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:2225 Error: Should be true Test: TestSyncMultipleCompareDest Messages: Unexpected file "dest/1" 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:2225 Error: Not equal: expected: 1 actual : 0 Test: TestSyncMultipleCompareDest Messages: pre-dest1/1: size incorrect file=1 vs obj=0 --- FAIL: TestSyncMultipleCompareDest (33.25s) === RUN TestSyncCopyDest run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:48:30 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-boxoxex3miye/dst" 2025/02/15 02:48:31 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-boxoxex3miye/CopyDest" 2025/02/15 02:48:32 DEBUG : one: Need to transfer - File not found at Destination 2025/02/15 02:48:32 DEBUG : files root 'rclone-test-boxoxex3miye/dst': Waiting for checks to finish 2025/02/15 02:48:32 DEBUG : files root 'rclone-test-boxoxex3miye/dst': Waiting for transfers to finish 2025/02/15 02:48:37 DEBUG : one: Dst hash empty - aborting Src hash check 2025/02/15 02:48:37 INFO : one: Copied (new) 2025/02/15 02:48:37 DEBUG : Waiting for deletions to finish 2025/02/15 02:48:37 DEBUG : one: Sizes differ (src 5 vs dst 3) 2025/02/15 02:48:37 DEBUG : files root 'rclone-test-boxoxex3miye/dst': Waiting for checks to finish 2025/02/15 02:48:38 DEBUG : files root 'rclone-test-boxoxex3miye/dst': Waiting for transfers to finish 2025/02/15 02:48:38 DEBUG : one: Dst hash empty - aborting Src hash check 2025/02/15 02:48:38 INFO : one: Copied (replaced existing) 2025/02/15 02:48:38 DEBUG : Waiting for deletions to finish 2025/02/15 02:48:41 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-boxoxex3miye/BackupDir" 2025/02/15 02:48:41 DEBUG : one: Sizes differ (src 5 vs dst 3) 2025/02/15 02:48:41 DEBUG : files root 'rclone-test-boxoxex3miye/dst': Waiting for checks to finish 2025/02/15 02:48:42 DEBUG : one: Size and modification time the same (differ by -123.456789ms, within tolerance 1s) 2025/02/15 02:48:42 DEBUG : one: Sizes differ (src 5 vs dst 3) 2025/02/15 02:48:43 INFO : one: Moved (server-side) 2025/02/15 02:48:45 DEBUG : one: Dst hash empty - aborting Src hash check 2025/02/15 02:48:45 DEBUG : one: Src hash empty - aborting Dst hash check 2025/02/15 02:48:45 INFO : one: Copied (server-side copy) 2025/02/15 02:48:45 DEBUG : one: Destination found in --copy-dest, using server-side copy 2025/02/15 02:48:45 DEBUG : files root 'rclone-test-boxoxex3miye/dst': Waiting for transfers to finish 2025/02/15 02:48:45 DEBUG : Waiting for deletions to finish 2025/02/15 02:48:46 DEBUG : two: Size and modification time the same (differ by -123.456789ms, within tolerance 1s) 2025/02/15 02:48:48 DEBUG : two: Dst hash empty - aborting Src hash check 2025/02/15 02:48:48 DEBUG : two: Src hash empty - aborting Dst hash check 2025/02/15 02:48:48 INFO : two: Copied (server-side copy) 2025/02/15 02:48:48 DEBUG : two: Destination found in --copy-dest, using server-side copy 2025/02/15 02:48:48 DEBUG : one: Size and modification time the same (differ by -123.456789ms, within tolerance 1s) 2025/02/15 02:48:48 DEBUG : one: Unchanged skipping 2025/02/15 02:48:48 DEBUG : files root 'rclone-test-boxoxex3miye/dst': Waiting for checks to finish 2025/02/15 02:48:48 DEBUG : files root 'rclone-test-boxoxex3miye/dst': Waiting for transfers to finish 2025/02/15 02:48:48 DEBUG : Waiting for deletions to finish 2025/02/15 02:48:49 DEBUG : one: Size and modification time the same (differ by -123.456789ms, within tolerance 1s) 2025/02/15 02:48:49 DEBUG : one: Unchanged skipping 2025/02/15 02:48:49 DEBUG : two: Size and modification time the same (differ by -123.456789ms, within tolerance 1s) 2025/02/15 02:48:49 DEBUG : two: Unchanged skipping 2025/02/15 02:48:49 DEBUG : files root 'rclone-test-boxoxex3miye/dst': Waiting for checks to finish 2025/02/15 02:48:49 DEBUG : files root 'rclone-test-boxoxex3miye/dst': Waiting for transfers to finish 2025/02/15 02:48:49 DEBUG : Waiting for deletions to finish 2025/02/15 02:48:49 INFO : There was nothing to transfer 2025/02/15 02:48:50 DEBUG : three: Sizes differ (src 7 vs dst 5) 2025/02/15 02:48:50 DEBUG : three: Destination not found in --copy-dest 2025/02/15 02:48:50 DEBUG : three: Need to transfer - File not found at Destination 2025/02/15 02:48:50 DEBUG : one: Size and modification time the same (differ by -123.456789ms, within tolerance 1s) 2025/02/15 02:48:50 DEBUG : one: Unchanged skipping 2025/02/15 02:48:50 DEBUG : two: Size and modification time the same (differ by -123.456789ms, within tolerance 1s) 2025/02/15 02:48:50 DEBUG : two: Unchanged skipping 2025/02/15 02:48:50 DEBUG : files root 'rclone-test-boxoxex3miye/dst': Waiting for checks to finish 2025/02/15 02:48:50 DEBUG : files root 'rclone-test-boxoxex3miye/dst': Waiting for transfers to finish 2025/02/15 02:48:51 DEBUG : three: Dst hash empty - aborting Src hash check 2025/02/15 02:48:51 INFO : three: Copied (new) 2025/02/15 02:48:51 DEBUG : Waiting for deletions to finish --- PASS: TestSyncCopyDest (23.94s) === RUN TestSyncBackupDir run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:48:57 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-boxoxex3miye/dst" 2025/02/15 02:48:57 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-boxoxex3miye/backup" 2025/02/15 02:48:58 DEBUG : one: Sizes differ (src 4 vs dst 3) 2025/02/15 02:48:58 DEBUG : two: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2025/02/15 02:48:58 DEBUG : two: Unchanged skipping 2025/02/15 02:48:58 DEBUG : files root 'rclone-test-boxoxex3miye/dst': Waiting for checks to finish 2025/02/15 02:49:00 INFO : one: Moved (server-side) 2025/02/15 02:49:00 DEBUG : files root 'rclone-test-boxoxex3miye/dst': Waiting for transfers to finish 2025/02/15 02:49:01 DEBUG : one: Dst hash empty - aborting Src hash check 2025/02/15 02:49:01 INFO : one: Copied (new) 2025/02/15 02:49:01 DEBUG : Waiting for deletions to finish 2025/02/15 02:49:02 INFO : three.txt: Moved (server-side) 2025/02/15 02:49:02 INFO : three.txt: Moved into backup dir 2025/02/15 02:49:03 DEBUG : one: Sizes differ (src 5 vs dst 4) 2025/02/15 02:49:03 DEBUG : two: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2025/02/15 02:49:03 DEBUG : two: Unchanged skipping 2025/02/15 02:49:03 DEBUG : files root 'rclone-test-boxoxex3miye/dst': Waiting for checks to finish 2025/02/15 02:49:04 INFO : one: Deleted 2025/02/15 02:49:04 INFO : one: Moved (server-side) 2025/02/15 02:49:04 DEBUG : files root 'rclone-test-boxoxex3miye/dst': Waiting for transfers to finish 2025/02/15 02:49:05 DEBUG : one: Dst hash empty - aborting Src hash check 2025/02/15 02:49:05 INFO : one: Copied (new) 2025/02/15 02:49:05 DEBUG : Waiting for deletions to finish 2025/02/15 02:49:05 INFO : three.txt: Deleted 2025/02/15 02:49:06 INFO : three.txt: Moved (server-side) 2025/02/15 02:49:06 INFO : three.txt: Moved into backup dir --- PASS: TestSyncBackupDir (13.29s) === RUN TestSyncBackupDirWithSuffix run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:49:10 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-boxoxex3miye/dst" 2025/02/15 02:49:11 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-boxoxex3miye/backup" 2025/02/15 02:49:11 DEBUG : one: Sizes differ (src 4 vs dst 3) 2025/02/15 02:49:11 DEBUG : two: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2025/02/15 02:49:11 DEBUG : two: Unchanged skipping 2025/02/15 02:49:11 DEBUG : files root 'rclone-test-boxoxex3miye/dst': Waiting for checks to finish 2025/02/15 02:49:12 INFO : one: Moved (server-side) to: one.bak 2025/02/15 02:49:12 DEBUG : files root 'rclone-test-boxoxex3miye/dst': Waiting for transfers to finish 2025/02/15 02:49:14 DEBUG : one: Dst hash empty - aborting Src hash check 2025/02/15 02:49:14 INFO : one: Copied (new) 2025/02/15 02:49:14 DEBUG : Waiting for deletions to finish 2025/02/15 02:49:14 INFO : three.txt: Moved (server-side) to: three.txt.bak 2025/02/15 02:49:14 INFO : three.txt: Moved into backup dir 2025/02/15 02:49:16 DEBUG : one: Sizes differ (src 5 vs dst 4) 2025/02/15 02:49:16 DEBUG : two: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2025/02/15 02:49:16 DEBUG : two: Unchanged skipping 2025/02/15 02:49:16 DEBUG : files root 'rclone-test-boxoxex3miye/dst': Waiting for checks to finish 2025/02/15 02:49:16 INFO : one.bak: Deleted 2025/02/15 02:49:16 INFO : one: Moved (server-side) to: one.bak 2025/02/15 02:49:16 DEBUG : files root 'rclone-test-boxoxex3miye/dst': Waiting for transfers to finish 2025/02/15 02:49:21 DEBUG : one: Dst hash empty - aborting Src hash check 2025/02/15 02:49:21 INFO : one: Copied (new) 2025/02/15 02:49:21 DEBUG : Waiting for deletions to finish 2025/02/15 02:49:21 INFO : three.txt.bak: Deleted 2025/02/15 02:49:21 INFO : three.txt: Moved (server-side) to: three.txt.bak 2025/02/15 02:49:21 INFO : three.txt: Moved into backup dir --- PASS: TestSyncBackupDirWithSuffix (15.83s) === RUN TestSyncBackupDirWithSuffixKeepExtension run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:49:29 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-boxoxex3miye/dst" 2025/02/15 02:49:30 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-boxoxex3miye/backup" 2025/02/15 02:49:31 DEBUG : one: Sizes differ (src 4 vs dst 3) 2025/02/15 02:49:31 DEBUG : two: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2025/02/15 02:49:31 DEBUG : two: Unchanged skipping 2025/02/15 02:49:31 DEBUG : files root 'rclone-test-boxoxex3miye/dst': Waiting for checks to finish 2025/02/15 02:49:33 INFO : one: Moved (server-side) to: one-2019-01-01 2025/02/15 02:49:33 DEBUG : files root 'rclone-test-boxoxex3miye/dst': Waiting for transfers to finish 2025/02/15 02:49:34 DEBUG : one: Dst hash empty - aborting Src hash check 2025/02/15 02:49:34 INFO : one: Copied (new) 2025/02/15 02:49:34 DEBUG : Waiting for deletions to finish 2025/02/15 02:49:35 INFO : three.txt: Moved (server-side) to: three-2019-01-01.txt 2025/02/15 02:49:35 INFO : three.txt: Moved into backup dir 2025/02/15 02:49:37 DEBUG : one: Sizes differ (src 5 vs dst 4) 2025/02/15 02:49:37 DEBUG : two: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2025/02/15 02:49:37 DEBUG : two: Unchanged skipping 2025/02/15 02:49:37 DEBUG : files root 'rclone-test-boxoxex3miye/dst': Waiting for checks to finish 2025/02/15 02:49:37 INFO : one-2019-01-01: Deleted 2025/02/15 02:49:38 INFO : one: Moved (server-side) to: one-2019-01-01 2025/02/15 02:49:38 DEBUG : files root 'rclone-test-boxoxex3miye/dst': Waiting for transfers to finish 2025/02/15 02:49:39 DEBUG : one: Dst hash empty - aborting Src hash check 2025/02/15 02:49:39 INFO : one: Copied (new) 2025/02/15 02:49:39 DEBUG : Waiting for deletions to finish 2025/02/15 02:49:39 INFO : three-2019-01-01.txt: Deleted 2025/02/15 02:49:39 INFO : three.txt: Moved (server-side) to: three-2019-01-01.txt 2025/02/15 02:49:39 INFO : three.txt: Moved into backup dir --- PASS: TestSyncBackupDirWithSuffixKeepExtension (17.82s) === RUN TestSyncBackupDirSuffixOnly run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:49:43 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-boxoxex3miye/dst" 2025/02/15 02:49:44 DEBUG : one: Sizes differ (src 4 vs dst 3) 2025/02/15 02:49:44 DEBUG : two: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2025/02/15 02:49:44 DEBUG : two: Unchanged skipping 2025/02/15 02:49:44 DEBUG : files root 'rclone-test-boxoxex3miye/dst': Waiting for checks to finish 2025/02/15 02:49:46 INFO : one: Moved (server-side) to: one.bak 2025/02/15 02:49:46 DEBUG : files root 'rclone-test-boxoxex3miye/dst': Waiting for transfers to finish 2025/02/15 02:49:47 DEBUG : one: Dst hash empty - aborting Src hash check 2025/02/15 02:49:47 INFO : one: Copied (new) 2025/02/15 02:49:47 DEBUG : Waiting for deletions to finish 2025/02/15 02:49:47 INFO : three.txt: Moved (server-side) to: three.txt.bak 2025/02/15 02:49:47 INFO : three.txt: Moved into backup dir 2025/02/15 02:49:49 DEBUG : one.bak: Excluded (Path Filter) 2025/02/15 02:49:49 DEBUG : one.bak: Excluded 2025/02/15 02:49:49 DEBUG : three.txt.bak: Excluded (Path Filter) 2025/02/15 02:49:49 DEBUG : three.txt.bak: Excluded 2025/02/15 02:49:49 DEBUG : one: Sizes differ (src 5 vs dst 4) 2025/02/15 02:49:49 DEBUG : two: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2025/02/15 02:49:49 DEBUG : two: Unchanged skipping 2025/02/15 02:49:49 DEBUG : files root 'rclone-test-boxoxex3miye/dst': Waiting for checks to finish 2025/02/15 02:49:49 INFO : one.bak: Deleted 2025/02/15 02:49:50 INFO : one: Moved (server-side) to: one.bak 2025/02/15 02:49:50 DEBUG : files root 'rclone-test-boxoxex3miye/dst': Waiting for transfers to finish 2025/02/15 02:49:50 DEBUG : one: Dst hash empty - aborting Src hash check 2025/02/15 02:49:50 INFO : one: Copied (new) 2025/02/15 02:49:50 DEBUG : Waiting for deletions to finish 2025/02/15 02:49:51 INFO : three.txt.bak: Deleted 2025/02/15 02:49:51 INFO : three.txt: Moved (server-side) to: three.txt.bak 2025/02/15 02:49:51 INFO : three.txt: Moved into backup dir --- PASS: TestSyncBackupDirSuffixOnly (11.59s) === RUN TestSyncSuffix run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:49:55 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-boxoxex3miye/dst" 2025/02/15 02:49:56 DEBUG : one: Sizes differ (src 4 vs dst 3) 2025/02/15 02:49:57 INFO : one: Moved (server-side) to: one.bak 2025/02/15 02:49:58 DEBUG : one: Dst hash empty - aborting Src hash check 2025/02/15 02:49:58 INFO : one: Copied (new) 2025/02/15 02:49:58 DEBUG : two: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2025/02/15 02:49:58 DEBUG : two: Unchanged skipping 2025/02/15 02:49:58 DEBUG : three.txt: Sizes differ (src 6 vs dst 5) 2025/02/15 02:49:59 INFO : three.txt: Moved (server-side) to: three.txt.bak 2025/02/15 02:50:00 DEBUG : three.txt: Dst hash empty - aborting Src hash check 2025/02/15 02:50:00 INFO : three.txt: Copied (new) 2025/02/15 02:50:00 DEBUG : one: Sizes differ (src 5 vs dst 4) 2025/02/15 02:50:01 INFO : one.bak: Deleted 2025/02/15 02:50:01 INFO : one: Moved (server-side) to: one.bak 2025/02/15 02:50:02 DEBUG : one: Dst hash empty - aborting Src hash check 2025/02/15 02:50:02 INFO : one: Copied (new) 2025/02/15 02:50:02 DEBUG : two: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2025/02/15 02:50:02 DEBUG : two: Unchanged skipping 2025/02/15 02:50:02 DEBUG : three.txt: Sizes differ (src 19 vs dst 6) 2025/02/15 02:50:03 INFO : three.txt.bak: Deleted 2025/02/15 02:50:03 INFO : three.txt: Moved (server-side) to: three.txt.bak 2025/02/15 02:50:04 DEBUG : three.txt: Dst hash empty - aborting Src hash check 2025/02/15 02:50:04 INFO : three.txt: Copied (new) --- PASS: TestSyncSuffix (12.95s) === RUN TestSyncSuffixKeepExtension run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:50:08 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-boxoxex3miye/dst" 2025/02/15 02:50:09 DEBUG : one: Sizes differ (src 4 vs dst 3) 2025/02/15 02:50:10 INFO : one: Moved (server-side) to: one-2019-01-01 2025/02/15 02:50:11 DEBUG : one: Dst hash empty - aborting Src hash check 2025/02/15 02:50:11 INFO : one: Copied (new) 2025/02/15 02:50:11 DEBUG : two: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2025/02/15 02:50:11 DEBUG : two: Unchanged skipping 2025/02/15 02:50:11 DEBUG : three.txt: Sizes differ (src 6 vs dst 5) 2025/02/15 02:50:12 INFO : three.txt: Moved (server-side) to: three-2019-01-01.txt 2025/02/15 02:50:13 DEBUG : three.txt: Dst hash empty - aborting Src hash check 2025/02/15 02:50:13 INFO : three.txt: Copied (new) 2025/02/15 02:50:13 DEBUG : one: Sizes differ (src 5 vs dst 4) 2025/02/15 02:50:14 INFO : one-2019-01-01: Deleted 2025/02/15 02:50:14 INFO : one: Moved (server-side) to: one-2019-01-01 2025/02/15 02:50:15 DEBUG : one: Dst hash empty - aborting Src hash check 2025/02/15 02:50:15 INFO : one: Copied (new) 2025/02/15 02:50:15 DEBUG : two: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2025/02/15 02:50:15 DEBUG : two: Unchanged skipping 2025/02/15 02:50:15 DEBUG : three.txt: Sizes differ (src 19 vs dst 6) 2025/02/15 02:50:16 INFO : three-2019-01-01.txt: Deleted 2025/02/15 02:50:16 INFO : three.txt: Moved (server-side) to: three-2019-01-01.txt 2025/02/15 02:50:17 DEBUG : three.txt: Dst hash empty - aborting Src hash check 2025/02/15 02:50:17 INFO : three.txt: Copied (new) --- PASS: TestSyncSuffixKeepExtension (13.11s) === RUN TestSyncUTFNorm run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:50:20 DEBUG : Testêé: Sizes differ (src 14 vs dst 18) 2025/02/15 02:50:20 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for checks to finish 2025/02/15 02:50:20 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for transfers to finish 2025/02/15 02:50:21 DEBUG : Testêé: Dst hash empty - aborting Src hash check 2025/02/15 02:50:21 INFO : Testêé: Copied (replaced existing) to: Testêé 2025/02/15 02:50:21 DEBUG : Waiting for deletions to finish --- PASS: TestSyncUTFNorm (2.60s) === RUN TestSyncImmutable run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:50:21 DEBUG : existing: Need to transfer - File not found at Destination 2025/02/15 02:50:21 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for checks to finish 2025/02/15 02:50:21 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for transfers to finish 2025/02/15 02:50:22 DEBUG : existing: Dst hash empty - aborting Src hash check 2025/02/15 02:50:22 INFO : existing: Copied (new) 2025/02/15 02:50:22 DEBUG : Waiting for deletions to finish run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:50:22 DEBUG : existing: Sizes differ (src 8 vs dst 6) 2025/02/15 02:50:22 ERROR : existing: Source and destination exist but do not match: immutable file modified 2025/02/15 02:50:22 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for checks to finish 2025/02/15 02:50:22 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for transfers to finish 2025/02/15 02:50:22 ERROR : files root 'rclone-test-boxoxex3miye': not deleting files as there were IO errors 2025/02/15 02:50:22 ERROR : files root 'rclone-test-boxoxex3miye': not deleting directories as there were IO errors run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" --- PASS: TestSyncImmutable (2.46s) === RUN TestSyncIgnoreCase run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" sync_test.go:2606: Skipping test as local or remote are case-insensitive --- SKIP: TestSyncIgnoreCase (0.26s) === RUN TestFixCase run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:50:28 DEBUG : existing: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2025/02/15 02:50:28 DEBUG : existing: Unchanged skipping 2025/02/15 02:50:28 DEBUG : existingbutdifferent: Sizes differ (src 5 vs dst 8) 2025/02/15 02:50:28 DEBUG : EXISTING: moving to existing-rclone-move-beqepeg7 2025/02/15 02:50:28 INFO : SUBDIRA: Set directory modification time (using DirSetModTime) 2025/02/15 02:50:28 DEBUG : Added delayed dir = "SUBDIRA", newDst=SUBDIRA 2025/02/15 02:50:28 DEBUG : EXISTINGBUTDIFFERENT: moving to existingbutdifferent-rclone-move-hopeneg8 2025/02/15 02:50:28 INFO : EXISTING: Moved (server-side) to: existing-rclone-move-beqepeg7 2025/02/15 02:50:28 DEBUG : EXISTING: moving to existing 2025/02/15 02:50:28 INFO : EXISTINGBUTDIFFERENT: Moved (server-side) to: existingbutdifferent-rclone-move-hopeneg8 2025/02/15 02:50:28 DEBUG : EXISTINGBUTDIFFERENT: moving to existingbutdifferent 2025/02/15 02:50:29 INFO : existingbutdifferent-rclone-move-hopeneg8: Moved (server-side) to: existingbutdifferent 2025/02/15 02:50:29 INFO : EXISTINGBUTDIFFERENT: Moved (server-side) to: existingbutdifferent 2025/02/15 02:50:29 INFO : EXISTINGBUTDIFFERENT: Fixed case by renaming to: existingbutdifferent 2025/02/15 02:50:29 INFO : existing-rclone-move-beqepeg7: Moved (server-side) to: existing 2025/02/15 02:50:29 INFO : EXISTING: Moved (server-side) to: existing 2025/02/15 02:50:29 INFO : EXISTING: Fixed case by renaming to: existing 2025/02/15 02:50:29 INFO : SUBDIRA: Fixed case by renaming to: subdira 2025/02/15 02:50:29 INFO : SUBDIRA/subdirb: Set directory modification time (using DirSetModTime) 2025/02/15 02:50:29 DEBUG : Added delayed dir = "SUBDIRA/subdirb", newDst=SUBDIRA/subdirb 2025/02/15 02:50:30 DEBUG : existingbutdifferent: Dst hash empty - aborting Src hash check 2025/02/15 02:50:30 INFO : existingbutdifferent: Copied (replaced existing) 2025/02/15 02:50:31 INFO : SUBDIRA/subdirb: Fixed case by renaming to: subdira/subdirb 2025/02/15 02:50:31 INFO : SUBDIRA/subdirb/SUBDIRC: Set directory modification time (using DirSetModTime) 2025/02/15 02:50:31 DEBUG : Added delayed dir = "SUBDIRA/subdirb/SUBDIRC", newDst=SUBDIRA/subdirb/SUBDIRC 2025/02/15 02:50:32 INFO : SUBDIRA/subdirb/SUBDIRC: Fixed case by renaming to: subdira/subdirb/subdirc 2025/02/15 02:50:32 DEBUG : subdira/subdirb/subdirc/hello: Sizes differ (src 5 vs dst 8) 2025/02/15 02:50:32 DEBUG : SUBDIRA/subdirb/SUBDIRC/HELLO: moving to subdira/subdirb/subdirc/hello-rclone-move-jofoxug6 2025/02/15 02:50:32 INFO : SUBDIRA/subdirb/SUBDIRC/subdird: Set directory modification time (using DirSetModTime) 2025/02/15 02:50:32 DEBUG : Added delayed dir = "SUBDIRA/subdirb/SUBDIRC/subdird", newDst=SUBDIRA/subdirb/SUBDIRC/subdird 2025/02/15 02:50:33 INFO : SUBDIRA/subdirb/SUBDIRC/HELLO: Moved (server-side) to: subdira/subdirb/subdirc/hello-rclone-move-jofoxug6 2025/02/15 02:50:33 DEBUG : SUBDIRA/subdirb/SUBDIRC/HELLO: moving to subdira/subdirb/subdirc/hello 2025/02/15 02:50:33 INFO : subdira/subdirb/subdirc/hello-rclone-move-jofoxug6: Moved (server-side) to: subdira/subdirb/subdirc/hello 2025/02/15 02:50:33 INFO : SUBDIRA/subdirb/SUBDIRC/HELLO: Moved (server-side) to: subdira/subdirb/subdirc/hello 2025/02/15 02:50:33 INFO : SUBDIRA/subdirb/SUBDIRC/HELLO: Fixed case by renaming to: subdira/subdirb/subdirc/hello 2025/02/15 02:50:34 INFO : SUBDIRA/subdirb/SUBDIRC/subdird: Fixed case by renaming to: subdira/subdirb/subdirc/subdird 2025/02/15 02:50:34 DEBUG : subdira/subdirb/subdirc/subdird/filewithoutcasedifferences: Sizes differ (src 5 vs dst 8) 2025/02/15 02:50:34 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for checks to finish 2025/02/15 02:50:34 DEBUG : SUBDIRA/subdirb/SUBDIRC/subdird/filewithoutcasedifferences: moving to subdira/subdirb/subdirc/subdird/filewithoutcasedifferences-rclone-move-lacopib6 2025/02/15 02:50:34 DEBUG : subdira/subdirb/subdirc/hello: Dst hash empty - aborting Src hash check 2025/02/15 02:50:34 INFO : subdira/subdirb/subdirc/hello: Copied (replaced existing) 2025/02/15 02:50:35 INFO : SUBDIRA/subdirb/SUBDIRC/subdird/filewithoutcasedifferences: Moved (server-side) to: subdira/subdirb/subdirc/subdird/filewithoutcasedifferences-rclone-move-lacopib6 2025/02/15 02:50:35 DEBUG : SUBDIRA/subdirb/SUBDIRC/subdird/filewithoutcasedifferences: moving to subdira/subdirb/subdirc/subdird/filewithoutcasedifferences 2025/02/15 02:50:35 INFO : subdira/subdirb/subdirc/subdird/filewithoutcasedifferences-rclone-move-lacopib6: Moved (server-side) to: subdira/subdirb/subdirc/subdird/filewithoutcasedifferences 2025/02/15 02:50:35 INFO : SUBDIRA/subdirb/SUBDIRC/subdird/filewithoutcasedifferences: Moved (server-side) to: subdira/subdirb/subdirc/subdird/filewithoutcasedifferences 2025/02/15 02:50:35 INFO : SUBDIRA/subdirb/SUBDIRC/subdird/filewithoutcasedifferences: Fixed case by renaming to: subdira/subdirb/subdirc/subdird/filewithoutcasedifferences 2025/02/15 02:50:35 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for transfers to finish 2025/02/15 02:50:36 DEBUG : subdira/subdirb/subdirc/subdird/filewithoutcasedifferences: Dst hash empty - aborting Src hash check 2025/02/15 02:50:36 INFO : subdira/subdirb/subdirc/subdird/filewithoutcasedifferences: Copied (replaced existing) 2025/02/15 02:50:36 DEBUG : Waiting for deletions to finish --- PASS: TestFixCase (14.93s) === RUN TestMaxTransfer === RUN TestMaxTransfer/Hard run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" sync_test.go:2674: This test only runs on local === RUN TestMaxTransfer/Soft run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" sync_test.go:2674: This test only runs on local === RUN TestMaxTransfer/Cautious run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" sync_test.go:2674: This test only runs on local --- PASS: TestMaxTransfer (0.76s) --- SKIP: TestMaxTransfer/Hard (0.25s) --- SKIP: TestMaxTransfer/Soft (0.26s) --- SKIP: TestMaxTransfer/Cautious (0.25s) === RUN TestSyncConcurrentDelete run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:51:10 DEBUG : both0: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2025/02/15 02:51:10 DEBUG : both0: Unchanged skipping 2025/02/15 02:51:10 DEBUG : both1: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2025/02/15 02:51:10 DEBUG : both1: Unchanged skipping 2025/02/15 02:51:10 DEBUG : both10: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2025/02/15 02:51:10 DEBUG : both10: Unchanged skipping 2025/02/15 02:51:10 DEBUG : both11: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2025/02/15 02:51:10 DEBUG : both11: Unchanged skipping 2025/02/15 02:51:10 DEBUG : both12: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2025/02/15 02:51:10 DEBUG : both12: Unchanged skipping 2025/02/15 02:51:10 DEBUG : both13: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2025/02/15 02:51:10 DEBUG : both14: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2025/02/15 02:51:10 DEBUG : both15: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2025/02/15 02:51:10 DEBUG : both16: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2025/02/15 02:51:10 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for checks to finish 2025/02/15 02:51:10 DEBUG : both13: Unchanged skipping 2025/02/15 02:51:10 DEBUG : both17: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2025/02/15 02:51:10 DEBUG : both17: Unchanged skipping 2025/02/15 02:51:10 DEBUG : both18: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2025/02/15 02:51:10 DEBUG : both18: Unchanged skipping 2025/02/15 02:51:10 DEBUG : both19: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2025/02/15 02:51:10 DEBUG : both19: Unchanged skipping 2025/02/15 02:51:10 DEBUG : both2: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2025/02/15 02:51:10 DEBUG : both2: Unchanged skipping 2025/02/15 02:51:10 DEBUG : both3: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2025/02/15 02:51:10 DEBUG : both3: Unchanged skipping 2025/02/15 02:51:10 DEBUG : both4: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2025/02/15 02:51:10 DEBUG : both4: Unchanged skipping 2025/02/15 02:51:10 DEBUG : both5: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2025/02/15 02:51:10 DEBUG : both5: Unchanged skipping 2025/02/15 02:51:10 DEBUG : both6: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2025/02/15 02:51:10 DEBUG : both6: Unchanged skipping 2025/02/15 02:51:10 DEBUG : both7: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2025/02/15 02:51:10 DEBUG : both7: Unchanged skipping 2025/02/15 02:51:10 DEBUG : both8: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2025/02/15 02:51:10 DEBUG : both8: Unchanged skipping 2025/02/15 02:51:10 DEBUG : both9: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2025/02/15 02:51:10 DEBUG : both9: Unchanged skipping 2025/02/15 02:51:10 DEBUG : both14: Unchanged skipping 2025/02/15 02:51:10 DEBUG : both15: Unchanged skipping 2025/02/15 02:51:10 DEBUG : both16: Unchanged skipping 2025/02/15 02:51:10 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for transfers to finish 2025/02/15 02:51:10 DEBUG : Waiting for deletions to finish 2025/02/15 02:51:10 INFO : only0: Deleted 2025/02/15 02:51:10 INFO : only15: Deleted 2025/02/15 02:51:10 INFO : only16: Deleted 2025/02/15 02:51:10 INFO : only17: Deleted 2025/02/15 02:51:10 INFO : only3: Deleted 2025/02/15 02:51:10 INFO : only4: Deleted 2025/02/15 02:51:10 INFO : only1: Deleted 2025/02/15 02:51:10 INFO : only12: Deleted 2025/02/15 02:51:10 INFO : only18: Deleted 2025/02/15 02:51:10 INFO : only8: Deleted 2025/02/15 02:51:10 INFO : only9: Deleted 2025/02/15 02:51:10 INFO : only10: Deleted 2025/02/15 02:51:10 INFO : only11: Deleted 2025/02/15 02:51:10 INFO : only14: Deleted 2025/02/15 02:51:10 INFO : only5: Deleted 2025/02/15 02:51:10 INFO : only19: Deleted 2025/02/15 02:51:10 INFO : only6: Deleted 2025/02/15 02:51:11 INFO : only13: Deleted 2025/02/15 02:51:11 INFO : only7: Deleted 2025/02/15 02:51:11 INFO : only2: Deleted run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" --- PASS: TestSyncConcurrentDelete (35.13s) === RUN TestSyncConcurrentTruncate run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:51:16 DEBUG : pacer: low level retry 1/10 (error Put "https://s3.amazonaws.com/objects.brickftp.com/metadata/126732/6c6a4975-b731-4bbb-9cae-3126e7085b11?X-Amz-Algorithm=AWS4-HMAC-SHA256&X-Amz-Credential=AKIAIEWLY3MN4YGZQOWA%2F20250215%2Fus-east-1%2Fs3%2Faws4_request&X-Amz-Date=20250215T025115Z&X-Amz-Expires=900&X-Amz-SignedHeaders=host&partNumber=1&response-content-type=application%2Foctet-stream&uploadId=8Rk1ZjCeMZdxeLRr_PSiEZlIKU5BVinguTL5qelqcSfHUYctzeLhTzYKxpx29VPGl.YXshBl2uBV_0.5vjLxTeEJCgvcIw1SBFO2_eZWmJl6ymwGoiPKoxAzE2ZVh8I6&X-Amz-Signature=e8a1497edf6d81d537a533a96ac3b0f4dd77c6ba8512d141a55bc3322d7211eb": net/http: HTTP/1.x transport connection broken: http: ContentLength=6 with Body length 0) 2025/02/15 02:51:16 DEBUG : pacer: Rate limited, increasing sleep to 20ms 2025/02/15 02:51:17 DEBUG : pacer: Reducing sleep to 15ms 2025/02/15 02:51:17 DEBUG : pacer: Reducing sleep to 11.25ms 2025/02/15 02:51:17 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/02/15 02:51:52 DEBUG : both0: Sizes differ (src 6 vs dst 0) 2025/02/15 02:51:52 DEBUG : both1: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2025/02/15 02:51:52 DEBUG : both10: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2025/02/15 02:51:52 DEBUG : both11: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2025/02/15 02:51:52 DEBUG : both12: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2025/02/15 02:51:52 DEBUG : both11: Unchanged skipping 2025/02/15 02:51:52 DEBUG : both13: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2025/02/15 02:51:52 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for checks to finish 2025/02/15 02:51:52 DEBUG : both13: Unchanged skipping 2025/02/15 02:51:52 DEBUG : both14: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2025/02/15 02:51:52 DEBUG : both14: Unchanged skipping 2025/02/15 02:51:52 DEBUG : both15: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2025/02/15 02:51:52 DEBUG : both15: Unchanged skipping 2025/02/15 02:51:52 DEBUG : both16: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2025/02/15 02:51:52 DEBUG : both16: Unchanged skipping 2025/02/15 02:51:52 DEBUG : both17: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2025/02/15 02:51:52 DEBUG : both17: Unchanged skipping 2025/02/15 02:51:52 DEBUG : both18: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2025/02/15 02:51:52 DEBUG : both18: Unchanged skipping 2025/02/15 02:51:52 DEBUG : both19: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2025/02/15 02:51:52 DEBUG : both19: Unchanged skipping 2025/02/15 02:51:52 DEBUG : both2: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2025/02/15 02:51:52 DEBUG : both2: Unchanged skipping 2025/02/15 02:51:52 DEBUG : both3: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2025/02/15 02:51:52 DEBUG : both3: Unchanged skipping 2025/02/15 02:51:52 DEBUG : both4: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2025/02/15 02:51:52 DEBUG : both4: Unchanged skipping 2025/02/15 02:51:52 DEBUG : both5: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2025/02/15 02:51:52 DEBUG : both5: Unchanged skipping 2025/02/15 02:51:52 DEBUG : both6: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2025/02/15 02:51:52 DEBUG : both6: Unchanged skipping 2025/02/15 02:51:52 DEBUG : both7: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2025/02/15 02:51:52 DEBUG : both7: Unchanged skipping 2025/02/15 02:51:52 DEBUG : both8: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2025/02/15 02:51:52 DEBUG : both8: Unchanged skipping 2025/02/15 02:51:52 DEBUG : both9: Size and modification time the same (differ by -499.999999ms, within tolerance 1s) 2025/02/15 02:51:52 DEBUG : both9: Unchanged skipping 2025/02/15 02:51:52 DEBUG : only0: Sizes differ (src 0 vs dst 6) 2025/02/15 02:51:52 DEBUG : only1: Sizes differ (src 0 vs dst 6) 2025/02/15 02:51:52 DEBUG : only10: Sizes differ (src 0 vs dst 6) 2025/02/15 02:51:52 DEBUG : only11: Sizes differ (src 0 vs dst 6) 2025/02/15 02:51:52 DEBUG : only12: Sizes differ (src 0 vs dst 6) 2025/02/15 02:51:52 DEBUG : only13: Sizes differ (src 0 vs dst 6) 2025/02/15 02:51:52 DEBUG : only14: Sizes differ (src 0 vs dst 6) 2025/02/15 02:51:52 DEBUG : only15: Sizes differ (src 0 vs dst 6) 2025/02/15 02:51:52 DEBUG : only16: Sizes differ (src 0 vs dst 6) 2025/02/15 02:51:52 DEBUG : only17: Sizes differ (src 0 vs dst 6) 2025/02/15 02:51:52 DEBUG : only18: Sizes differ (src 0 vs dst 6) 2025/02/15 02:51:52 DEBUG : only19: Sizes differ (src 0 vs dst 6) 2025/02/15 02:51:52 DEBUG : only2: Sizes differ (src 0 vs dst 6) 2025/02/15 02:51:52 DEBUG : only3: Sizes differ (src 0 vs dst 6) 2025/02/15 02:51:52 DEBUG : only4: Sizes differ (src 0 vs dst 6) 2025/02/15 02:51:52 DEBUG : only5: Sizes differ (src 0 vs dst 6) 2025/02/15 02:51:52 DEBUG : only6: Sizes differ (src 0 vs dst 6) 2025/02/15 02:51:52 DEBUG : only7: Sizes differ (src 0 vs dst 6) 2025/02/15 02:51:52 DEBUG : only8: Sizes differ (src 0 vs dst 6) 2025/02/15 02:51:52 DEBUG : only9: Sizes differ (src 0 vs dst 6) 2025/02/15 02:51:52 DEBUG : both12: Unchanged skipping 2025/02/15 02:51:52 DEBUG : both1: Unchanged skipping 2025/02/15 02:51:52 DEBUG : both10: Unchanged skipping 2025/02/15 02:51:52 DEBUG : files root 'rclone-test-boxoxex3miye': Waiting for transfers to finish 2025/02/15 02:51:53 DEBUG : both0: Dst hash empty - aborting Src hash check 2025/02/15 02:51:53 INFO : both0: Copied (replaced existing) 2025/02/15 02:51:53 DEBUG : only0: Dst hash empty - aborting Src hash check 2025/02/15 02:51:53 INFO : only0: Copied (replaced existing) 2025/02/15 02:51:54 DEBUG : only10: Dst hash empty - aborting Src hash check 2025/02/15 02:51:54 INFO : only10: Copied (replaced existing) 2025/02/15 02:51:54 DEBUG : only1: Dst hash empty - aborting Src hash check 2025/02/15 02:51:54 INFO : only1: Copied (replaced existing) 2025/02/15 02:51:54 DEBUG : only11: Dst hash empty - aborting Src hash check 2025/02/15 02:51:54 INFO : only11: Copied (replaced existing) 2025/02/15 02:51:54 DEBUG : only13: Dst hash empty - aborting Src hash check 2025/02/15 02:51:54 INFO : only13: Copied (replaced existing) 2025/02/15 02:51:54 DEBUG : only12: Dst hash empty - aborting Src hash check 2025/02/15 02:51:54 INFO : only12: Copied (replaced existing) 2025/02/15 02:51:54 DEBUG : only14: Dst hash empty - aborting Src hash check 2025/02/15 02:51:54 INFO : only14: Copied (replaced existing) 2025/02/15 02:51:55 DEBUG : only15: Dst hash empty - aborting Src hash check 2025/02/15 02:51:55 INFO : only15: Copied (replaced existing) 2025/02/15 02:51:55 DEBUG : only17: Dst hash empty - aborting Src hash check 2025/02/15 02:51:55 INFO : only17: Copied (replaced existing) 2025/02/15 02:51:55 DEBUG : only16: Dst hash empty - aborting Src hash check 2025/02/15 02:51:55 INFO : only16: Copied (replaced existing) 2025/02/15 02:51:55 DEBUG : only18: Dst hash empty - aborting Src hash check 2025/02/15 02:51:55 INFO : only18: Copied (replaced existing) 2025/02/15 02:51:56 DEBUG : only2: Dst hash empty - aborting Src hash check 2025/02/15 02:51:56 INFO : only2: Copied (replaced existing) 2025/02/15 02:51:56 DEBUG : only3: Dst hash empty - aborting Src hash check 2025/02/15 02:51:56 INFO : only3: Copied (replaced existing) 2025/02/15 02:51:56 DEBUG : only19: Dst hash empty - aborting Src hash check 2025/02/15 02:51:56 INFO : only19: Copied (replaced existing) 2025/02/15 02:51:56 DEBUG : only4: Dst hash empty - aborting Src hash check 2025/02/15 02:51:56 INFO : only4: Copied (replaced existing) 2025/02/15 02:51:57 DEBUG : only5: Dst hash empty - aborting Src hash check 2025/02/15 02:51:57 INFO : only5: Copied (replaced existing) 2025/02/15 02:51:57 DEBUG : only6: Dst hash empty - aborting Src hash check 2025/02/15 02:51:57 INFO : only6: Copied (replaced existing) 2025/02/15 02:51:57 DEBUG : only8: Dst hash empty - aborting Src hash check 2025/02/15 02:51:57 INFO : only8: Copied (replaced existing) 2025/02/15 02:51:57 DEBUG : only7: Dst hash empty - aborting Src hash check 2025/02/15 02:51:57 INFO : only7: Copied (replaced existing) 2025/02/15 02:51:57 DEBUG : only9: Dst hash empty - aborting Src hash check 2025/02/15 02:51:57 INFO : only9: Copied (replaced existing) 2025/02/15 02:51:57 DEBUG : Waiting for deletions to finish run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" --- FAIL: TestSyncConcurrentTruncate (49.84s) === RUN TestSyncReplaceDirModTime run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:52:05 DEBUG : empty_dir: Making directory with metadata 2025/02/15 02:52:05 INFO : empty_dir: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z) 2025/02/15 02:52:05 DEBUG : empty_on_remote: Making directory with metadata 2025/02/15 02:52:05 INFO : empty_on_remote: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z) 2025/02/15 02:52:05 INFO : empty_on_remote: Making directory 2025/02/15 02:52:05 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-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:52:06 INFO : test_dir1: Set directory modification time (using DirSetModTime) 2025/02/15 02:52:06 INFO : test_dir2: Set directory modification time (using DirSetModTime) 2025/02/15 02:52:06 INFO : test_dir2/sub_dir: Set directory modification time (using DirSetModTime) 2025/02/15 02:52:06 INFO : empty_on_remote: Set directory modification time (using DirSetModTime) run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" --- PASS: TestSyncReplaceDirModTime (6.18s) === RUN TestSyncReplaceDirModTimeWithEmptyDirs run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:52:11 DEBUG : empty_dir: Making directory with metadata 2025/02/15 02:52:11 INFO : empty_dir: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z) 2025/02/15 02:52:11 DEBUG : empty_on_remote: Making directory with metadata 2025/02/15 02:52:11 INFO : empty_on_remote: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z) 2025/02/15 02:52:11 INFO : empty_on_remote: Making directory 2025/02/15 02:52:11 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-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:52:14 INFO : test_dir1: Set directory modification time (using DirSetModTime) 2025/02/15 02:52:14 INFO : test_dir2: Set directory modification time (using DirSetModTime) 2025/02/15 02:52:14 INFO : test_dir2/sub_dir: Set directory modification time (using DirSetModTime) 2025/02/15 02:52:14 INFO : empty_on_remote: Set directory modification time (using DirSetModTime) 2025/02/15 02:52:14 INFO : empty_dir: Set directory modification time (using DirSetModTime) run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:52:17 DEBUG : pacer: low level retry 1/10 (error Folder Not Empty - `Folder rclone-test-boxoxex3miye/test_dir2 not empty`) 2025/02/15 02:52:17 DEBUG : pacer: Rate limited, increasing sleep to 20ms 2025/02/15 02:52:17 DEBUG : pacer: Reducing sleep to 15ms 2025/02/15 02:52:18 DEBUG : pacer: Reducing sleep to 11.25ms 2025/02/15 02:52:18 DEBUG : pacer: Reducing sleep to 10ms --- PASS: TestSyncReplaceDirModTimeWithEmptyDirs (7.80s) === RUN TestNothingToTransferWithEmptyDirs run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:52:19 INFO : sub dir: Set directory modification time (using DirSetModTime) 2025/02/15 02:52:19 INFO : sub dir: Making directory 2025/02/15 02:52:19 INFO : sub dir: Made directory with modification time 2011-12-30 12:59:59 +0000 UTC run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:52:29 INFO : sub dir2: Set directory modification time (using DirSetModTime) 2025/02/15 02:52:29 INFO : sub dir2: Set directory modification time (using DirSetModTime) 2025/02/15 02:52:29 INFO : sub dirEmpty/sub dirEmpty2: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z) 2025/02/15 02:52:29 INFO : sub dirEmpty: Set directory modification time (using DirSetModTime) run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:52:36 DEBUG : pacer: low level retry 1/10 (error Folder Not Empty - `Folder rclone-test-boxoxex3miye/sub dirEmpty not empty`) 2025/02/15 02:52:36 DEBUG : pacer: Rate limited, increasing sleep to 20ms 2025/02/15 02:52:36 DEBUG : pacer: low level retry 2/10 (error Folder Not Empty - `Folder rclone-test-boxoxex3miye/sub dirEmpty not empty`) 2025/02/15 02:52:36 DEBUG : pacer: Rate limited, increasing sleep to 40ms 2025/02/15 02:52:36 DEBUG : pacer: low level retry 3/10 (error Folder Not Empty - `Folder rclone-test-boxoxex3miye/sub dirEmpty not empty`) 2025/02/15 02:52:36 DEBUG : pacer: Rate limited, increasing sleep to 80ms 2025/02/15 02:52:36 DEBUG : pacer: low level retry 4/10 (error Folder Not Empty - `Folder rclone-test-boxoxex3miye/sub dirEmpty not empty`) 2025/02/15 02:52:36 DEBUG : pacer: Rate limited, increasing sleep to 160ms 2025/02/15 02:52:36 DEBUG : pacer: low level retry 5/10 (error Folder Not Empty - `Folder rclone-test-boxoxex3miye/sub dirEmpty not empty`) 2025/02/15 02:52:36 DEBUG : pacer: Rate limited, increasing sleep to 320ms 2025/02/15 02:52:36 DEBUG : pacer: low level retry 6/10 (error Folder Not Empty - `Folder rclone-test-boxoxex3miye/sub dirEmpty not empty`) 2025/02/15 02:52:36 DEBUG : pacer: Rate limited, increasing sleep to 640ms 2025/02/15 02:52:37 DEBUG : pacer: Reducing sleep to 480ms 2025/02/15 02:52:37 DEBUG : pacer: Reducing sleep to 360ms 2025/02/15 02:52:38 DEBUG : pacer: Reducing sleep to 270ms 2025/02/15 02:52:38 DEBUG : pacer: low level retry 1/10 (error Folder Not Empty - `Folder rclone-test-boxoxex3miye/sub dir2/very/very/very/very/very not empty`) 2025/02/15 02:52:38 DEBUG : pacer: Rate limited, increasing sleep to 540ms 2025/02/15 02:52:38 DEBUG : pacer: low level retry 2/10 (error Folder Not Empty - `Folder rclone-test-boxoxex3miye/sub dir2/very/very/very/very/very not empty`) 2025/02/15 02:52:38 DEBUG : pacer: Rate limited, increasing sleep to 1.08s 2025/02/15 02:52:39 DEBUG : pacer: Reducing sleep to 810ms 2025/02/15 02:52:40 DEBUG : pacer: Reducing sleep to 607.5ms 2025/02/15 02:52:41 DEBUG : pacer: Reducing sleep to 455.625ms 2025/02/15 02:52:41 DEBUG : pacer: Reducing sleep to 341.71875ms 2025/02/15 02:52:42 DEBUG : pacer: Reducing sleep to 256.289062ms 2025/02/15 02:52:42 DEBUG : pacer: Reducing sleep to 192.216796ms 2025/02/15 02:52:42 DEBUG : pacer: low level retry 1/10 (error Folder Not Empty - `Folder rclone-test-boxoxex3miye/sub dir2 not empty`) 2025/02/15 02:52:42 DEBUG : pacer: Rate limited, increasing sleep to 384.433592ms 2025/02/15 02:52:43 DEBUG : pacer: low level retry 2/10 (error Folder Not Empty - `Folder rclone-test-boxoxex3miye/sub dir2 not empty`) 2025/02/15 02:52:43 DEBUG : pacer: Rate limited, increasing sleep to 768.867184ms 2025/02/15 02:52:43 DEBUG : pacer: Reducing sleep to 576.650388ms 2025/02/15 02:52:44 DEBUG : pacer: Reducing sleep to 432.487791ms 2025/02/15 02:52:44 DEBUG : pacer: Reducing sleep to 324.365843ms 2025/02/15 02:52:45 DEBUG : pacer: Reducing sleep to 243.274382ms 2025/02/15 02:52:45 DEBUG : pacer: Reducing sleep to 182.455786ms 2025/02/15 02:52:45 DEBUG : pacer: Reducing sleep to 136.841839ms 2025/02/15 02:52:45 DEBUG : pacer: Reducing sleep to 102.631379ms 2025/02/15 02:52:46 DEBUG : pacer: Reducing sleep to 76.973534ms 2025/02/15 02:52:46 DEBUG : pacer: Reducing sleep to 57.73015ms --- PASS: TestNothingToTransferWithEmptyDirs (27.25s) === RUN TestNothingToTransferWithoutEmptyDirs run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:52:46 INFO : sub dir: Set directory modification time (using DirSetModTime) 2025/02/15 02:52:46 INFO : sub dir: Making directory 2025/02/15 02:52:46 DEBUG : pacer: Reducing sleep to 43.297612ms 2025/02/15 02:52:46 DEBUG : pacer: Reducing sleep to 32.473209ms 2025/02/15 02:52:46 INFO : sub dir: Made directory with modification time 2011-12-30 12:59:59 +0000 UTC run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:52:54 INFO : sub dir2: Set directory modification time (using DirSetModTime) 2025/02/15 02:52:54 INFO : sub dir2: Set directory modification time (using DirSetModTime) 2025/02/15 02:52:54 INFO : sub dirEmpty/sub dirEmpty2: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z) 2025/02/15 02:52:54 INFO : sub dirEmpty: Set directory modification time (using DirSetModTime) run.go:180: Remote "files root 'rclone-test-boxoxex3miye'", Local "Local file system at /tmp/rclone1494077444", Modify Window "1s" 2025/02/15 02:53:00 DEBUG : pacer: low level retry 1/10 (error Folder Not Empty - `Folder rclone-test-boxoxex3miye/sub dir2/very/very/very/very/very not empty`) 2025/02/15 02:53:00 DEBUG : pacer: Rate limited, increasing sleep to 20ms 2025/02/15 02:53:00 DEBUG : pacer: low level retry 2/10 (error Folder Not Empty - `Folder rclone-test-boxoxex3miye/sub dir2/very/very/very/very/very not empty`) 2025/02/15 02:53:00 DEBUG : pacer: Rate limited, increasing sleep to 40ms 2025/02/15 02:53:00 DEBUG : pacer: Reducing sleep to 30ms 2025/02/15 02:53:01 DEBUG : pacer: low level retry 1/10 (error Folder Not Empty - `Folder rclone-test-boxoxex3miye/sub dir2/very/very/very/very not empty`) 2025/02/15 02:53:01 DEBUG : pacer: Rate limited, increasing sleep to 60ms 2025/02/15 02:53:01 DEBUG : pacer: low level retry 2/10 (error Folder Not Empty - `Folder rclone-test-boxoxex3miye/sub dir2/very/very/very/very not empty`) 2025/02/15 02:53:01 DEBUG : pacer: Rate limited, increasing sleep to 120ms 2025/02/15 02:53:01 DEBUG : pacer: low level retry 3/10 (error Folder Not Empty - `Folder rclone-test-boxoxex3miye/sub dir2/very/very/very/very not empty`) 2025/02/15 02:53:01 DEBUG : pacer: Rate limited, increasing sleep to 240ms 2025/02/15 02:53:01 DEBUG : pacer: low level retry 4/10 (error Folder Not Empty - `Folder rclone-test-boxoxex3miye/sub dir2/very/very/very/very not empty`) 2025/02/15 02:53:01 DEBUG : pacer: Rate limited, increasing sleep to 480ms 2025/02/15 02:53:01 DEBUG : pacer: Reducing sleep to 360ms 2025/02/15 02:53:02 DEBUG : pacer: Reducing sleep to 270ms 2025/02/15 02:53:02 DEBUG : pacer: Reducing sleep to 202.5ms 2025/02/15 02:53:02 DEBUG : pacer: Reducing sleep to 151.875ms 2025/02/15 02:53:03 DEBUG : pacer: Reducing sleep to 113.90625ms 2025/02/15 02:53:03 DEBUG : pacer: low level retry 1/10 (error Folder Not Empty - `Folder rclone-test-boxoxex3miye/sub dir2 not empty`) 2025/02/15 02:53:03 DEBUG : pacer: Rate limited, increasing sleep to 227.8125ms 2025/02/15 02:53:03 DEBUG : pacer: Reducing sleep to 170.859375ms 2025/02/15 02:53:03 DEBUG : pacer: Reducing sleep to 128.144531ms 2025/02/15 02:53:03 DEBUG : pacer: Reducing sleep to 96.108398ms 2025/02/15 02:53:03 DEBUG : pacer: Reducing sleep to 72.081298ms 2025/02/15 02:53:03 DEBUG : pacer: Reducing sleep to 54.060973ms 2025/02/15 02:53:03 DEBUG : pacer: Reducing sleep to 40.545729ms 2025/02/15 02:53:04 DEBUG : pacer: Reducing sleep to 30.409296ms 2025/02/15 02:53:04 DEBUG : pacer: Reducing sleep to 22.806972ms 2025/02/15 02:53:04 DEBUG : pacer: Reducing sleep to 17.105229ms --- PASS: TestNothingToTransferWithoutEmptyDirs (18.33s) FAIL 2025/02/15 02:53:04 DEBUG : files root 'rclone-test-boxoxex3miye': Purge remote 2025/02/15 02:53:04 DEBUG : pacer: Reducing sleep to 12.828921ms "./sync.test -test.v -test.timeout 1h0m0s -remote TestFilesCom: -verbose" - Finished ERROR in 9m40.98660753s (try 1/5): exit status 1: Failed [TestSyncEmptyDirectories TestSyncAfterChangingModtimeOnlyWithNoUpdateModTime TestSyncWithTrackRenames TestSyncMultipleCompareDest TestSyncConcurrentTruncate]