"./sync.test -test.v -test.timeout 1h0m0s -remote TestCryptDrive: -verbose" - Starting (try 1/5) 2025/03/16 06:37:39 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-wixuyiv3lumu" 2025/03/16 06:37:39 DEBUG : Using config file from "/home/rclone/.rclone.conf" 2025/03/16 06:37:39 DEBUG : Creating backend with remote "TestDrive:crypt/n3ncf6nbor1b3s3vkpig0sf40id8nuidr6khhvfpotbv0gp72c00" 2025/03/16 06:37:40 DEBUG : Creating backend with remote "/tmp/rclone1589196380" === 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 "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:37:41 DEBUG : Added delayed dir = "sub dir", newDst= 2025/03/16 06:37:41 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2025/03/16 06:37:41 NOTICE: sub dir/hello world: Skipped copy as --dry-run is set (size 11) 2025/03/16 06:37:41 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for checks to finish 2025/03/16 06:37:41 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for transfers to finish 2025/03/16 06:37:41 NOTICE: sub dir: Skipped set directory modification time as --dry-run is set run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" --- PASS: TestCopyWithDryRun (2.25s) === RUN TestCopy run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:37:42 INFO : sub dir: Set directory modification time (using DirSetModTime) 2025/03/16 06:37:42 DEBUG : Added delayed dir = "sub dir", newDst= 2025/03/16 06:37:42 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2025/03/16 06:37:42 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for checks to finish 2025/03/16 06:37:42 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for transfers to finish 2025/03/16 06:37:45 DEBUG : sub dir/hello world: md5 = 824f1f0f2938c3eb83e2eb684f3cec4b OK 2025/03/16 06:37:45 INFO : sub dir/hello world: Copied (new) 2025/03/16 06:37:45 INFO : sub dir: Set directory modification time (using DirSetModTime) run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:37:47 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestCopy (5.98s) === RUN TestCopyMetadata run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:37:48 DEBUG : metadata sub dir: Making directory with metadata 2025/03/16 06:37:48 INFO : metadata sub dir: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z) 2025/03/16 06:37:48 DEBUG : empty metadata sub dir: Making directory with metadata 2025/03/16 06:37:48 INFO : empty metadata sub dir: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z) 2025/03/16 06:37:48 DEBUG : Local file system at /tmp/rclone1589196380: File to upload is small (21 bytes), uploading instead of streaming 2025/03/16 06:37:48 DEBUG : metadata sub dir/hello metadata world: md5 = baa7a013449dbba2b1ed02b5cfb4e1a2 OK 2025/03/16 06:37:48 DEBUG : metadata sub dir/hello metadata world: Size and md5 of src and dst objects identical 2025/03/16 06:37:48 INFO : metadata sub dir: Set directory modification time (using DirSetModTime) 2025/03/16 06:37:49 DEBUG : Google drive root 'crypt/n3ncf6nbor1b3s3vkpig0sf40id8nuidr6khhvfpotbv0gp72c00': Skipping btime metadata as can't update it on an existing file: 2025-03-16T06:37:48.620048363Z 2025/03/16 06:37:49 INFO : empty metadata sub dir: Updated directory metadata 2025/03/16 06:37:49 DEBUG : Google drive root 'crypt/n3ncf6nbor1b3s3vkpig0sf40id8nuidr6khhvfpotbv0gp72c00': Skipping btime metadata as can't update it on an existing file: 2025-03-16T06:37:48.620048363Z 2025/03/16 06:37:50 INFO : metadata sub dir: Updated directory metadata 2025/03/16 06:37:50 DEBUG : metadata sub dir/hello metadata world: Need to transfer - File not found at Destination 2025/03/16 06:37:50 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for checks to finish 2025/03/16 06:37:50 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for transfers to finish 2025/03/16 06:37:51 DEBUG : metadata sub dir/hello metadata world: md5 = 10681cb79f6dd80017a45db690820903 OK 2025/03/16 06:37:51 INFO : metadata sub dir/hello metadata world: Copied (new) run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:37:54 DEBUG : fg45q1rm3kh00nmmkk4m6ihmrcnel1p7551kqhjr9bk2gtd2gbf0: Rmdir: contains trashed file: "dmuvulfij81f693ur0f1vvbvq9v6iscp56daas3m51n9li5e3470" --- PASS: TestCopyMetadata (7.39s) === RUN TestCopyMetadataNoEmptyDirs run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:37:56 DEBUG : metadata sub dir: Making directory with metadata 2025/03/16 06:37:56 INFO : metadata sub dir: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z) 2025/03/16 06:37:56 DEBUG : empty metadata sub dir: Making directory with metadata 2025/03/16 06:37:56 INFO : empty metadata sub dir: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z) 2025/03/16 06:37:56 DEBUG : Local file system at /tmp/rclone1589196380: File to upload is small (21 bytes), uploading instead of streaming 2025/03/16 06:37:56 DEBUG : metadata sub dir/hello metadata world: md5 = baa7a013449dbba2b1ed02b5cfb4e1a2 OK 2025/03/16 06:37:56 DEBUG : metadata sub dir/hello metadata world: Size and md5 of src and dst objects identical 2025/03/16 06:37:56 INFO : metadata sub dir: Set directory modification time (using DirSetModTime) 2025/03/16 06:37:56 DEBUG : Added delayed dir = "empty metadata sub dir", newDst= 2025/03/16 06:37:56 DEBUG : Added delayed dir = "metadata sub dir", newDst= 2025/03/16 06:37:56 DEBUG : metadata sub dir/hello metadata world: Need to transfer - File not found at Destination 2025/03/16 06:37:56 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for checks to finish 2025/03/16 06:37:56 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for transfers to finish 2025/03/16 06:37:58 DEBUG : metadata sub dir/hello metadata world: md5 = ae8118e51b45dcf2524885b292089d5a OK 2025/03/16 06:37:58 INFO : metadata sub dir/hello metadata world: Copied (new) 2025/03/16 06:37:58 DEBUG : Google drive root 'crypt/n3ncf6nbor1b3s3vkpig0sf40id8nuidr6khhvfpotbv0gp72c00': Skipping btime metadata as can't update it on an existing file: 2025-03-16T06:37:56.015994191Z 2025/03/16 06:37:58 INFO : metadata sub dir: Updated directory metadata run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:38:01 DEBUG : fg45q1rm3kh00nmmkk4m6ihmrcnel1p7551kqhjr9bk2gtd2gbf0: Rmdir: contains trashed file: "dmuvulfij81f693ur0f1vvbvq9v6iscp56daas3m51n9li5e3470" --- PASS: TestCopyMetadataNoEmptyDirs (6.40s) === RUN TestCopyMissingDirectory run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:38:02 DEBUG : Creating backend with remote "/non-existing" 2025/03/16 06:38:02 ERROR : Local file system at /non-existing: error reading source root directory: directory not found 2025/03/16 06:38:02 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for checks to finish 2025/03/16 06:38:02 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for transfers to finish run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" --- PASS: TestCopyMissingDirectory (1.06s) === RUN TestCopyNoTraverse run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:38:03 DEBUG : Added delayed dir = "sub dir", newDst= 2025/03/16 06:38:03 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2025/03/16 06:38:03 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for checks to finish 2025/03/16 06:38:03 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for transfers to finish 2025/03/16 06:38:05 DEBUG : sub dir/hello world: md5 = 82b3e4921cecd47aae2a669e8176c44f OK 2025/03/16 06:38:05 INFO : sub dir/hello world: Copied (new) 2025/03/16 06:38:06 INFO : sub dir: Set directory modification time (using DirSetModTime) run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:38:07 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestCopyNoTraverse (5.38s) === RUN TestCopyCheckFirst run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:38:08 INFO : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Running all checks before starting transfers 2025/03/16 06:38:09 DEBUG : Added delayed dir = "sub dir", newDst= 2025/03/16 06:38:09 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2025/03/16 06:38:09 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for checks to finish 2025/03/16 06:38:09 INFO : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Checks finished, now starting transfers 2025/03/16 06:38:09 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for transfers to finish 2025/03/16 06:38:11 DEBUG : sub dir/hello world: md5 = 22fd0ef799eef88680702be47267a89f OK 2025/03/16 06:38:11 INFO : sub dir/hello world: Copied (new) 2025/03/16 06:38:11 INFO : sub dir: Set directory modification time (using DirSetModTime) run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:38:13 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestCopyCheckFirst (5.77s) === RUN TestSyncNoTraverse run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:38:14 ERROR : Ignoring --no-traverse with sync 2025/03/16 06:38:14 DEBUG : Added delayed dir = "sub dir", newDst= 2025/03/16 06:38:14 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2025/03/16 06:38:14 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for checks to finish 2025/03/16 06:38:14 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for transfers to finish 2025/03/16 06:38:16 DEBUG : sub dir/hello world: md5 = 24bffacfe140d9f0baf2039e1074a8a4 OK 2025/03/16 06:38:16 INFO : sub dir/hello world: Copied (new) 2025/03/16 06:38:16 DEBUG : Waiting for deletions to finish 2025/03/16 06:38:17 INFO : sub dir: Set directory modification time (using DirSetModTime) run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:38:18 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestSyncNoTraverse (5.47s) === RUN TestCopyWithDepth run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:38:20 DEBUG : hello world2: Need to transfer - File not found at Destination 2025/03/16 06:38:20 DEBUG : Added delayed dir = "sub dir", newDst= 2025/03/16 06:38:20 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for checks to finish 2025/03/16 06:38:20 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for transfers to finish 2025/03/16 06:38:21 DEBUG : hello world2: md5 = 65c255501a35b783d268bccfcaf45990 OK 2025/03/16 06:38:21 INFO : hello world2: Copied (new) run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" --- PASS: TestCopyWithDepth (3.07s) === RUN TestCopyWithFilesFrom run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:38:23 DEBUG : potato2: Need to transfer - File not found at Destination 2025/03/16 06:38:23 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for checks to finish 2025/03/16 06:38:23 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for transfers to finish 2025/03/16 06:38:24 DEBUG : potato2: md5 = 9d97aece2aff9271c3790fc705f354f1 OK 2025/03/16 06:38:24 INFO : potato2: Copied (new) run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" --- PASS: TestCopyWithFilesFrom (3.06s) === RUN TestCopyWithFilesFromAndNoTraverse run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:38:26 DEBUG : potato2: Need to transfer - File not found at Destination 2025/03/16 06:38:26 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for checks to finish 2025/03/16 06:38:26 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for transfers to finish 2025/03/16 06:38:27 DEBUG : potato2: md5 = f7cfb1cc6a504e9b36dc86828bbd4907 OK 2025/03/16 06:38:27 INFO : potato2: Copied (new) run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" --- PASS: TestCopyWithFilesFromAndNoTraverse (3.20s) === RUN TestCopyEmptyDirectories run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:38:29 DEBUG : sub dir2/sub sub dir2: Making directory with metadata 2025/03/16 06:38:29 INFO : sub dir2/sub sub dir2: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z) 2025/03/16 06:38:29 INFO : sub dir2: Set directory modification time (using DirSetModTime) 2025/03/16 06:38:29 INFO : sub dir: Set directory modification time (using DirSetModTime) 2025/03/16 06:38:29 DEBUG : sub dir: Making directory with metadata 2025/03/16 06:38:30 INFO : sub dir: Made directory with metadata (mtime=2001-02-03T04:05:06.499999999Z) 2025/03/16 06:38:30 DEBUG : sub dir2: Making directory with metadata 2025/03/16 06:38:31 INFO : sub dir2: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z) 2025/03/16 06:38:31 DEBUG : sub dir2/sub sub dir2: Making directory with metadata 2025/03/16 06:38:31 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2025/03/16 06:38:32 INFO : sub dir2/sub sub dir2: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z) 2025/03/16 06:38:32 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for checks to finish 2025/03/16 06:38:32 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for transfers to finish 2025/03/16 06:38:32 DEBUG : sub dir/hello world: md5 = f02f59d89e2a3fadedfdac14408f0e41 OK 2025/03/16 06:38:32 INFO : sub dir/hello world: Copied (new) run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:38:36 DEBUG : s0tvtpcbgsp8ufdmedqtvlq3hc: Rmdir: contains trashed file: "cv6a9uf28ngrajena8kt5ijjn0" 2025/03/16 06:38:36 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestCopyEmptyDirectories (8.65s) === RUN TestCopyNoEmptyDirectories run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:38:38 INFO : sub dir2: Making directory 2025/03/16 06:38:38 DEBUG : sub dir2/sub sub dir2: Making directory with metadata 2025/03/16 06:38:38 INFO : sub dir2/sub sub dir2: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z) 2025/03/16 06:38:38 DEBUG : Added delayed dir = "sub dir", newDst= 2025/03/16 06:38:38 DEBUG : Added delayed dir = "sub dir2", newDst= 2025/03/16 06:38:38 DEBUG : Added delayed dir = "sub dir2/sub sub dir2", newDst= 2025/03/16 06:38:38 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2025/03/16 06:38:38 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for checks to finish 2025/03/16 06:38:38 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for transfers to finish 2025/03/16 06:38:40 DEBUG : sub dir/hello world: md5 = 407990ed7b399535b5a36ad834ae1797 OK 2025/03/16 06:38:40 INFO : sub dir/hello world: Copied (new) 2025/03/16 06:38:41 INFO : sub dir: Set directory modification time (using DirSetModTime) 2025/03/16 06:38:42 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestCopyNoEmptyDirectories (5.38s) === RUN TestMoveEmptyDirectories run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:38:43 DEBUG : sub dir2: Making directory with metadata 2025/03/16 06:38:43 INFO : sub dir2: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z) 2025/03/16 06:38:43 DEBUG : sub dir: Making directory with metadata 2025/03/16 06:38:44 INFO : sub dir: Made directory with metadata (mtime=2025-03-16T06:38:43.447647096Z) 2025/03/16 06:38:44 DEBUG : sub dir2: Making directory with metadata 2025/03/16 06:38:45 INFO : sub dir2: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z) 2025/03/16 06:38:45 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2025/03/16 06:38:45 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for checks to finish 2025/03/16 06:38:45 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for transfers to finish 2025/03/16 06:38:46 DEBUG : sub dir/hello world: md5 = eebfa3ee3d8e75e32b480649aef5a355 OK 2025/03/16 06:38:46 INFO : sub dir/hello world: Copied (new) 2025/03/16 06:38:46 INFO : sub dir/hello world: Deleted run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:38:49 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestMoveEmptyDirectories (6.83s) === RUN TestSyncNoUpdateDirModtime run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:38:50 DEBUG : sub dir no update dir modtime: Making directory with metadata 2025/03/16 06:38:50 INFO : sub dir no update dir modtime: Made directory with metadata (mtime=2001-02-03T04:05:06.499999999Z) 2025/03/16 06:38:51 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for checks to finish 2025/03/16 06:38:51 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for transfers to finish 2025/03/16 06:38:51 DEBUG : Waiting for deletions to finish run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" --- PASS: TestSyncNoUpdateDirModtime (3.83s) === RUN TestMoveNoEmptyDirectories run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:38:54 INFO : sub dir2: Making directory 2025/03/16 06:38:54 DEBUG : Added delayed dir = "sub dir", newDst= 2025/03/16 06:38:54 DEBUG : Added delayed dir = "sub dir2", newDst= 2025/03/16 06:38:54 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2025/03/16 06:38:54 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for checks to finish 2025/03/16 06:38:54 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for transfers to finish 2025/03/16 06:38:56 DEBUG : sub dir/hello world: md5 = 9984eecaa04cf6db9bd4103e32caf13c OK 2025/03/16 06:38:56 INFO : sub dir/hello world: Copied (new) 2025/03/16 06:38:56 INFO : sub dir/hello world: Deleted 2025/03/16 06:38:56 INFO : sub dir: Set directory modification time (using DirSetModTime) 2025/03/16 06:38:58 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestMoveNoEmptyDirectories (5.11s) === RUN TestSyncEmptyDirectories run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:38:59 DEBUG : sub dir2: Making directory with metadata 2025/03/16 06:38:59 INFO : sub dir2: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z) 2025/03/16 06:38:59 INFO : sub dir: Set directory modification time (using DirSetModTime) 2025/03/16 06:38:59 DEBUG : sub dir: Making directory with metadata 2025/03/16 06:39:00 INFO : sub dir: Made directory with metadata (mtime=2001-02-03T04:05:06.499999999Z) 2025/03/16 06:39:00 DEBUG : sub dir2: Making directory with metadata 2025/03/16 06:39:00 INFO : sub dir2: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z) 2025/03/16 06:39:00 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2025/03/16 06:39:00 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for checks to finish 2025/03/16 06:39:00 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for transfers to finish 2025/03/16 06:39:02 DEBUG : sub dir/hello world: md5 = a69d263a175fc0c5e6f5faecdb6badb9 OK 2025/03/16 06:39:02 INFO : sub dir/hello world: Copied (new) 2025/03/16 06:39:02 DEBUG : Waiting for deletions to finish run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:39:05 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestSyncEmptyDirectories (6.86s) === RUN TestSyncSetDelayedModTimes run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" sync_test.go:507: Backend doesn't have DirModTimeUpdatesOnWrite set --- SKIP: TestSyncSetDelayedModTimes (0.42s) === RUN TestSyncNoEmptyDirectories run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:39:06 INFO : sub dir2: Making directory 2025/03/16 06:39:06 DEBUG : Added delayed dir = "sub dir", newDst= 2025/03/16 06:39:06 DEBUG : Added delayed dir = "sub dir2", newDst= 2025/03/16 06:39:06 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2025/03/16 06:39:06 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for checks to finish 2025/03/16 06:39:06 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for transfers to finish 2025/03/16 06:39:08 DEBUG : sub dir/hello world: md5 = 1f24348ed5bbd20a0d6e1aa517eb817e OK 2025/03/16 06:39:08 INFO : sub dir/hello world: Copied (new) 2025/03/16 06:39:08 DEBUG : Waiting for deletions to finish 2025/03/16 06:39:09 INFO : sub dir: Set directory modification time (using DirSetModTime) 2025/03/16 06:39:10 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestSyncNoEmptyDirectories (4.97s) === RUN TestServerSideCopy run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:39:13 DEBUG : sub dir/hello world: md5 = 78f4e48be8bbf34b99c2e3fb6beb0a0c OK 2025/03/16 06:39:13 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-yuzozac7fewi" 2025/03/16 06:39:13 DEBUG : Creating backend with remote "TestDrive:crypt/1dop0gebu913i7q61d7ij021jgalgf7qfio7uk7vs6eb5go7joe0" sync_test.go:590: Server side copy (if possible) Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu' -> Encrypted drive 'TestCryptDrive:rclone-test-yuzozac7fewi' 2025/03/16 06:39:15 DEBUG : Added delayed dir = "sub dir", newDst= 2025/03/16 06:39:15 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2025/03/16 06:39:15 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-yuzozac7fewi': Waiting for checks to finish 2025/03/16 06:39:15 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-yuzozac7fewi': Waiting for transfers to finish 2025/03/16 06:39:17 INFO : sub dir/hello world: Copied (server-side copy) 2025/03/16 06:39:18 INFO : sub dir: Set directory modification time (using DirSetModTime) run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:39:18 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-yuzozac7fewi': Purge remote 2025/03/16 06:39:20 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestServerSideCopy (10.19s) === RUN TestCopyOverSelf run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:39:23 DEBUG : sub dir/hello world: md5 = bd2757189bbb7824e99a10a32ada5de0 OK 2025/03/16 06:39:24 INFO : sub dir: Set directory modification time (using SetModTime) 2025/03/16 06:39:24 DEBUG : Added delayed dir = "sub dir", newDst=sub dir 2025/03/16 06:39:25 DEBUG : sub dir/hello world: Sizes differ (src 17 vs dst 11) 2025/03/16 06:39:25 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for checks to finish 2025/03/16 06:39:25 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for transfers to finish 2025/03/16 06:39:26 DEBUG : sub dir/hello world: md5 = 74e2de7b3bd315a14bb11483452c87c5 OK 2025/03/16 06:39:26 INFO : sub dir/hello world: Copied (replaced existing) 2025/03/16 06:39:26 INFO : sub dir: Set directory modification time (using SetModTime) run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:39:28 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestCopyOverSelf (7.80s) === RUN TestServerSideCopyOverSelf run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:39:31 DEBUG : sub dir/hello world: md5 = 4bb21168b1a7e45fb3136719a6638c34 OK 2025/03/16 06:39:32 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-sisozin1howo" 2025/03/16 06:39:32 DEBUG : Creating backend with remote "TestDrive:crypt/cotd2n9q778vp29n8niifu3qc0cq73pfclkfnbp55nkp3sfvk9h0" sync_test.go:626: Server side copy (if possible) Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu' -> Encrypted drive 'TestCryptDrive:rclone-test-sisozin1howo' 2025/03/16 06:39:33 DEBUG : Added delayed dir = "sub dir", newDst= 2025/03/16 06:39:33 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2025/03/16 06:39:33 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sisozin1howo': Waiting for checks to finish 2025/03/16 06:39:33 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sisozin1howo': Waiting for transfers to finish 2025/03/16 06:39:35 INFO : sub dir/hello world: Copied (server-side copy) 2025/03/16 06:39:36 INFO : sub dir: Set directory modification time (using DirSetModTime) run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:39:38 DEBUG : sub dir/hello world: md5 = adee6b791e251e8249f3f20da7b0f1af OK 2025/03/16 06:39:39 DEBUG : sub dir: Directory modification time the same (differ by 0s, within tolerance 1ms) 2025/03/16 06:39:39 DEBUG : Added delayed dir = "sub dir", newDst=sub dir 2025/03/16 06:39:39 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sisozin1howo': Waiting for checks to finish 2025/03/16 06:39:39 DEBUG : sub dir/hello world: Sizes differ (src 17 vs dst 11) 2025/03/16 06:39:39 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sisozin1howo': Waiting for transfers to finish 2025/03/16 06:39:40 INFO : sub dir/hello world: Copied (server-side copy) 2025/03/16 06:39:41 INFO : sub dir: Set directory modification time (using SetModTime) run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:39:41 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sisozin1howo': Purge remote 2025/03/16 06:39:43 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestServerSideCopyOverSelf (15.62s) === RUN TestMoveOverSelf run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:39:47 DEBUG : sub dir/hello world: md5 = a4b1789774d5835c10416a89e5eab7c4 OK 2025/03/16 06:39:48 INFO : sub dir: Set directory modification time (using SetModTime) 2025/03/16 06:39:48 DEBUG : Added delayed dir = "sub dir", newDst=sub dir 2025/03/16 06:39:48 DEBUG : sub dir/hello world: Sizes differ (src 17 vs dst 11) 2025/03/16 06:39:48 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for checks to finish 2025/03/16 06:39:48 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for transfers to finish 2025/03/16 06:39:49 DEBUG : sub dir/hello world: md5 = 67290ed5c73b27399cc0c86e3d45f480 OK 2025/03/16 06:39:49 INFO : sub dir/hello world: Copied (replaced existing) 2025/03/16 06:39:49 INFO : sub dir/hello world: Deleted 2025/03/16 06:39:50 INFO : sub dir: Set directory modification time (using SetModTime) run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:39:51 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestMoveOverSelf (7.85s) === RUN TestServerSideMoveOverSelf run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:39:55 DEBUG : sub dir/hello world: md5 = 3f1c5252dcbded1f05f054c039a787c4 OK 2025/03/16 06:39:55 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-vujolev6zuje" 2025/03/16 06:39:55 DEBUG : Creating backend with remote "TestDrive:crypt/rdovhl6t5ekgr67o8s6l198vc9saot19k78bvjee96k1ke3pehl0" sync_test.go:671: Server side copy (if possible) Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu' -> Encrypted drive 'TestCryptDrive:rclone-test-vujolev6zuje' 2025/03/16 06:39:56 DEBUG : Added delayed dir = "sub dir", newDst= 2025/03/16 06:39:57 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2025/03/16 06:39:57 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vujolev6zuje': Waiting for checks to finish 2025/03/16 06:39:57 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vujolev6zuje': Waiting for transfers to finish 2025/03/16 06:39:59 INFO : sub dir/hello world: Copied (server-side copy) 2025/03/16 06:40:00 INFO : sub dir: Set directory modification time (using DirSetModTime) run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:40:01 DEBUG : sub dir/hello world: md5 = 18173d523941f18b8bebb5a610f1bef2 OK 2025/03/16 06:40:02 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vujolev6zuje': Using server-side directory move 2025/03/16 06:40:02 INFO : Encrypted drive 'TestCryptDrive:rclone-test-vujolev6zuje': Server side directory move failed - fallback to file moves: can't copy directory - destination already exists 2025/03/16 06:40:02 DEBUG : sub dir: Directory modification time the same (differ by 0s, within tolerance 1ms) 2025/03/16 06:40:02 DEBUG : Added delayed dir = "sub dir", newDst=sub dir 2025/03/16 06:40:02 DEBUG : sub dir/hello world: Sizes differ (src 17 vs dst 11) 2025/03/16 06:40:02 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vujolev6zuje': Waiting for checks to finish 2025/03/16 06:40:02 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vujolev6zuje': Waiting for transfers to finish 2025/03/16 06:40:03 INFO : sub dir/hello world: Deleted 2025/03/16 06:40:03 INFO : sub dir/hello world: Moved (server-side) 2025/03/16 06:40:04 INFO : sub dir: Set directory modification time (using SetModTime) 2025/03/16 06:40:06 DEBUG : sub dir/hello world: md5 = 8f616cf03314ead4bbdbd1f276f2e89d OK 2025/03/16 06:40:07 DEBUG : testing file moves 2025/03/16 06:40:07 DEBUG : sub dir: Directory modification time the same (differ by 0s, within tolerance 1ms) 2025/03/16 06:40:07 DEBUG : Added delayed dir = "sub dir", newDst=sub dir 2025/03/16 06:40:07 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vujolev6zuje': Waiting for checks to finish 2025/03/16 06:40:07 DEBUG : sub dir/hello world: Sizes differ (src 24 vs dst 17) 2025/03/16 06:40:07 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vujolev6zuje': Waiting for transfers to finish 2025/03/16 06:40:07 INFO : sub dir/hello world: Deleted 2025/03/16 06:40:08 INFO : sub dir/hello world: Moved (server-side) 2025/03/16 06:40:08 INFO : sub dir: Set directory modification time (using SetModTime) run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:40:09 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vujolev6zuje': Purge remote --- PASS: TestServerSideMoveOverSelf (19.68s) === RUN TestCopyAfterDelete run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:40:14 DEBUG : sub dir/hello world: md5 = 90cff7193bd8ffac41ad6543b32c7a99 OK 2025/03/16 06:40:14 ERROR : : error listing: directory not found 2025/03/16 06:40:15 INFO : Local file system at /tmp/rclone1589196380: Making directory 2025/03/16 06:40:15 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for checks to finish 2025/03/16 06:40:15 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for transfers to finish run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:40:17 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestCopyAfterDelete (5.80s) === RUN TestCopyRedownload run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:40:20 DEBUG : sub dir/hello world: md5 = 7eaed5a1935fa0c795787a014f78a280 OK 2025/03/16 06:40:21 DEBUG : Added delayed dir = "sub dir", newDst= 2025/03/16 06:40:21 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2025/03/16 06:40:21 DEBUG : Local file system at /tmp/rclone1589196380: Waiting for checks to finish 2025/03/16 06:40:21 DEBUG : Local file system at /tmp/rclone1589196380: Waiting for transfers to finish 2025/03/16 06:40:22 DEBUG : sub dir/hello world.285f0a30.partial: renamed to: sub dir/hello world 2025/03/16 06:40:22 INFO : sub dir/hello world: Copied (new) 2025/03/16 06:40:22 INFO : sub dir: Set directory modification time (using DirSetModTime) run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:40:23 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestCopyRedownload (6.20s) === RUN TestSyncBasedOnCheckSum run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:40:24 DEBUG : check sum: Need to transfer - File not found at Destination 2025/03/16 06:40:24 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for checks to finish 2025/03/16 06:40:24 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for transfers to finish 2025/03/16 06:40:26 DEBUG : check sum: md5 = 780cf897a4bd9435ae21b56c01088c71 OK 2025/03/16 06:40:26 INFO : check sum: Copied (new) 2025/03/16 06:40:26 DEBUG : Waiting for deletions to finish run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:40:26 NOTICE: Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': --checksum is in use but the source and destination have no hashes in common; falling back to --size-only 2025/03/16 06:40:26 DEBUG : check sum: Size of src and dst objects identical 2025/03/16 06:40:26 DEBUG : check sum: Unchanged skipping 2025/03/16 06:40:26 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for checks to finish 2025/03/16 06:40:26 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for transfers to finish 2025/03/16 06:40:26 DEBUG : Waiting for deletions to finish 2025/03/16 06:40:26 INFO : There was nothing to transfer run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" --- PASS: TestSyncBasedOnCheckSum (4.31s) === RUN TestSyncSizeOnly run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:40:29 DEBUG : sizeonly: Need to transfer - File not found at Destination 2025/03/16 06:40:29 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for checks to finish 2025/03/16 06:40:29 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for transfers to finish 2025/03/16 06:40:30 DEBUG : sizeonly: md5 = 0860a03ab4372387d61ae2faa1ea569f OK 2025/03/16 06:40:30 INFO : sizeonly: Copied (new) 2025/03/16 06:40:30 DEBUG : Waiting for deletions to finish run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:40:31 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for checks to finish 2025/03/16 06:40:31 DEBUG : sizeonly: Sizes identical 2025/03/16 06:40:31 DEBUG : sizeonly: Unchanged skipping 2025/03/16 06:40:31 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for transfers to finish 2025/03/16 06:40:31 DEBUG : Waiting for deletions to finish 2025/03/16 06:40:31 INFO : There was nothing to transfer run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" --- PASS: TestSyncSizeOnly (4.31s) === RUN TestSyncIgnoreSize run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:40:33 DEBUG : ignore-size: Need to transfer - File not found at Destination 2025/03/16 06:40:33 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for checks to finish 2025/03/16 06:40:33 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for transfers to finish 2025/03/16 06:40:34 DEBUG : ignore-size: md5 = f0630eed4333475df13759fb5a3d80be OK 2025/03/16 06:40:34 INFO : ignore-size: Copied (new) 2025/03/16 06:40:34 DEBUG : Waiting for deletions to finish run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:40:35 DEBUG : ignore-size: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/16 06:40:35 DEBUG : ignore-size: Unchanged skipping 2025/03/16 06:40:35 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for checks to finish 2025/03/16 06:40:35 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for transfers to finish 2025/03/16 06:40:35 DEBUG : Waiting for deletions to finish 2025/03/16 06:40:35 INFO : There was nothing to transfer run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" --- PASS: TestSyncIgnoreSize (4.29s) === RUN TestSyncIgnoreTimes run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:40:38 DEBUG : existing: md5 = dab8861d89a9e1dd293cf3ed73fe2c59 OK 2025/03/16 06:40:39 DEBUG : existing: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/16 06:40:39 DEBUG : existing: Unchanged skipping 2025/03/16 06:40:39 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for checks to finish 2025/03/16 06:40:39 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for transfers to finish 2025/03/16 06:40:39 DEBUG : Waiting for deletions to finish 2025/03/16 06:40:39 INFO : There was nothing to transfer run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:40:39 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for checks to finish 2025/03/16 06:40:39 DEBUG : existing: Transferring unconditionally as --ignore-times is in use 2025/03/16 06:40:39 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for transfers to finish 2025/03/16 06:40:40 DEBUG : existing: md5 = 5e07ca4a20321fc03c5ab587909a8320 OK 2025/03/16 06:40:40 INFO : existing: Copied (replaced existing) 2025/03/16 06:40:40 DEBUG : Waiting for deletions to finish run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" --- PASS: TestSyncIgnoreTimes (5.16s) === RUN TestSyncIgnoreExisting run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:40:42 DEBUG : existing: Need to transfer - File not found at Destination 2025/03/16 06:40:42 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for checks to finish 2025/03/16 06:40:42 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for transfers to finish 2025/03/16 06:40:44 DEBUG : existing: md5 = ec324d45e34a3d2d352baf73f19c2923 OK 2025/03/16 06:40:44 INFO : existing: Copied (new) 2025/03/16 06:40:44 DEBUG : Waiting for deletions to finish run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:40:44 DEBUG : existing: Destination exists, skipping 2025/03/16 06:40:44 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for checks to finish 2025/03/16 06:40:44 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for transfers to finish 2025/03/16 06:40:44 DEBUG : Waiting for deletions to finish 2025/03/16 06:40:44 INFO : There was nothing to transfer run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" --- PASS: TestSyncIgnoreExisting (4.10s) === RUN TestSyncIgnoreErrors run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:40:49 DEBUG : b/potato: md5 = 5236d80eb065aa345575a103627dcd7b OK 2025/03/16 06:40:51 DEBUG : c/non empty space: md5 = ad12a3312f143fe0404a316cd4bcf490 OK 2025/03/16 06:40:51 INFO : d: Making directory 2025/03/16 06:40:52 DEBUG : Added delayed dir = "a", newDst= 2025/03/16 06:40:52 INFO : c: Set directory modification time (using SetModTime) 2025/03/16 06:40:52 DEBUG : Added delayed dir = "c", newDst=c 2025/03/16 06:40:52 DEBUG : a/potato2: Need to transfer - File not found at Destination 2025/03/16 06:40:53 DEBUG : c/non empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2025/03/16 06:40:53 DEBUG : c/non empty space: Unchanged skipping 2025/03/16 06:40:53 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for checks to finish 2025/03/16 06:40:53 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for transfers to finish 2025/03/16 06:40:55 DEBUG : a/potato2: md5 = 6280777543b3c3bf8073f37c8b3046e8 OK 2025/03/16 06:40:55 INFO : a/potato2: Copied (new) 2025/03/16 06:40:55 DEBUG : Waiting for deletions to finish 2025/03/16 06:40:55 INFO : b/potato: Deleted 2025/03/16 06:40:56 INFO : a: Set directory modification time (using DirSetModTime) 2025/03/16 06:40:56 INFO : d: Removing directory 2025/03/16 06:40:56 INFO : b: Removing directory 2025/03/16 06:40:56 DEBUG : 32d8ua6196mc1r7qkfog53rkg0: Rmdir: contains trashed file: "2m507n64kafsi59v9q71r281a4" 2025/03/16 06:40:57 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': deleted 2 directories run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:40:59 DEBUG : 3i9du405pfogq3ncai6pg7ouio: Rmdir: contains trashed file: "982d3pss7t5pn0il16r2foj31s" 2025/03/16 06:41:00 DEBUG : 2bsvlrk2ne1lfitm6tttcu0qt8: Rmdir: contains trashed file: "89l8renevh3mji1c8r1p7qn6tg" --- PASS: TestSyncIgnoreErrors (14.67s) === RUN TestSyncAfterChangingModtimeOnly run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:41:02 DEBUG : empty space: md5 = 14679cb118224ebcce0f7e607cbecfb4 OK 2025/03/16 06:41:03 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for checks to finish 2025/03/16 06:41:03 DEBUG : empty space: Modification times differ by -95456h54m52.624456789s: 2011-12-25 12:59:59.123456789 +0000 UTC, 2001-02-03 04:05:06.499 +0000 UTC 2025/03/16 06:41:03 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for transfers to finish 2025/03/16 06:41:03 NOTICE: empty space: Skipped copy as --dry-run is set (size 1) 2025/03/16 06:41:03 DEBUG : Waiting for deletions to finish run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:41:03 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for checks to finish 2025/03/16 06:41:03 DEBUG : empty space: Modification times differ by -95456h54m52.624456789s: 2011-12-25 12:59:59.123456789 +0000 UTC, 2001-02-03 04:05:06.499 +0000 UTC 2025/03/16 06:41:03 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for transfers to finish 2025/03/16 06:41:04 DEBUG : empty space: md5 = 944bb0038b14c78883c2c856e76564d5 OK 2025/03/16 06:41:04 INFO : empty space: Copied (replaced existing) 2025/03/16 06:41:04 DEBUG : Waiting for deletions to finish run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" --- PASS: TestSyncAfterChangingModtimeOnly (5.48s) === RUN TestSyncAfterChangingModtimeOnlyWithNoUpdateModTime run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" sync_test.go:1016: Can't check this if no hashes supported --- PASS: TestSyncAfterChangingModtimeOnlyWithNoUpdateModTime (0.44s) === RUN TestSyncDoesntUpdateModtime run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:41:08 DEBUG : foo: md5 = ec8dc5937ff9c5ab1fb7b418a6ac7211 OK 2025/03/16 06:41:09 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for checks to finish 2025/03/16 06:41:09 DEBUG : foo: Modification times differ by -95456h54m52.624456789s: 2011-12-25 12:59:59.123456789 +0000 UTC, 2001-02-03 04:05:06.499 +0000 UTC 2025/03/16 06:41:09 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for transfers to finish 2025/03/16 06:41:10 DEBUG : foo: md5 = 3abcc9274a6547dad4762996deb63363 OK 2025/03/16 06:41:10 INFO : foo: Copied (replaced existing) 2025/03/16 06:41:10 DEBUG : Waiting for deletions to finish run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" --- PASS: TestSyncDoesntUpdateModtime (4.47s) === RUN TestSyncAfterAddingAFile run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:41:13 DEBUG : empty space: md5 = 682f88d203b91aaa7e2a893615dd75cc OK 2025/03/16 06:41:13 DEBUG : potato: Need to transfer - File not found at Destination 2025/03/16 06:41:13 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2025/03/16 06:41:13 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for checks to finish 2025/03/16 06:41:13 DEBUG : empty space: Unchanged skipping 2025/03/16 06:41:13 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for transfers to finish 2025/03/16 06:41:15 DEBUG : potato: md5 = 0dd7e2af7c321c3191ef24a7f127c038 OK 2025/03/16 06:41:15 INFO : potato: Copied (new) 2025/03/16 06:41:15 DEBUG : Waiting for deletions to finish run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" --- PASS: TestSyncAfterAddingAFile (5.24s) === RUN TestSyncAfterChangingFilesSizeOnly run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:41:18 DEBUG : potato: md5 = edaa3e24c8921942ea933bc5b2ee77c5 OK 2025/03/16 06:41:18 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for checks to finish 2025/03/16 06:41:18 DEBUG : potato: Sizes differ (src 21 vs dst 60) 2025/03/16 06:41:18 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for transfers to finish 2025/03/16 06:41:20 DEBUG : potato: md5 = 58338273726f86c5103f896e1a52e783 OK 2025/03/16 06:41:20 INFO : potato: Copied (replaced existing) 2025/03/16 06:41:20 DEBUG : Waiting for deletions to finish run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" --- PASS: TestSyncAfterChangingFilesSizeOnly (4.66s) === RUN TestSyncAfterChangingContentsOnly run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:41:23 DEBUG : potato: md5 = 7dee5465220bc9de44adf44c8aed9734 OK 2025/03/16 06:41:23 DEBUG : potato: Modification times differ by 119h59m59.876543211s: 2011-12-25 12:59:59.123456789 +0000 UTC, 2011-12-30 12:59:59 +0000 UTC 2025/03/16 06:41:23 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for checks to finish 2025/03/16 06:41:23 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for transfers to finish 2025/03/16 06:41:24 DEBUG : potato: md5 = d7403212242fc48236a7c142bfca5924 OK 2025/03/16 06:41:24 INFO : potato: Copied (replaced existing) 2025/03/16 06:41:24 DEBUG : Waiting for deletions to finish run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" --- PASS: TestSyncAfterChangingContentsOnly (4.66s) === RUN TestSyncAfterRemovingAFileAndAddingAFileDryRun run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:41:27 DEBUG : potato: md5 = c1de17c515daf249fdd642257211773c OK 2025/03/16 06:41:29 DEBUG : empty space: md5 = 50f5cbfdbdeb8dc29c004f380aec7f39 OK 2025/03/16 06:41:29 DEBUG : potato2: Need to transfer - File not found at Destination 2025/03/16 06:41:29 NOTICE: potato2: Skipped copy as --dry-run is set (size 60) 2025/03/16 06:41:29 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for checks to finish 2025/03/16 06:41:29 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2025/03/16 06:41:29 DEBUG : empty space: Unchanged skipping 2025/03/16 06:41:29 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for transfers to finish 2025/03/16 06:41:29 DEBUG : Waiting for deletions to finish 2025/03/16 06:41:29 NOTICE: potato: Skipped delete as --dry-run is set (size 21) run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" --- PASS: TestSyncAfterRemovingAFileAndAddingAFileDryRun (4.97s) === RUN TestSyncAfterRemovingAFileAndAddingAFile run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:41:32 DEBUG : potato: md5 = 9aabbd6efe9e1332d742968d2ea8f5ff OK 2025/03/16 06:41:33 DEBUG : empty space: md5 = 87116d9b6fb11e47d005ec5460a3ca46 OK 2025/03/16 06:41:34 DEBUG : potato2: Need to transfer - File not found at Destination 2025/03/16 06:41:34 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2025/03/16 06:41:34 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for checks to finish 2025/03/16 06:41:34 DEBUG : empty space: Unchanged skipping 2025/03/16 06:41:34 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for transfers to finish 2025/03/16 06:41:35 DEBUG : potato2: md5 = 96f6e3f5877dacf604ec18fdb0332692 OK 2025/03/16 06:41:35 INFO : potato2: Copied (new) 2025/03/16 06:41:35 DEBUG : Waiting for deletions to finish 2025/03/16 06:41:36 INFO : potato: Deleted run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" --- PASS: TestSyncAfterRemovingAFileAndAddingAFile (6.89s) === RUN TestSyncAfterRemovingAFileAndAddingAFileSubDir run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:41:40 DEBUG : b/potato: md5 = 007832aa35cffa3dcc418fd939e3afc3 OK 2025/03/16 06:41:42 DEBUG : c/non empty space: md5 = 0a619b89982337229f99e751e4b5dd5a OK 2025/03/16 06:41:42 INFO : d: Making directory 2025/03/16 06:41:43 INFO : d/e: Making directory 2025/03/16 06:41:45 DEBUG : Added delayed dir = "a", newDst= 2025/03/16 06:41:45 INFO : c: Set directory modification time (using SetModTime) 2025/03/16 06:41:45 DEBUG : Added delayed dir = "c", newDst=c 2025/03/16 06:41:45 DEBUG : a/potato2: Need to transfer - File not found at Destination 2025/03/16 06:41:45 DEBUG : c/non empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2025/03/16 06:41:45 DEBUG : c/non empty space: Unchanged skipping 2025/03/16 06:41:46 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for checks to finish 2025/03/16 06:41:46 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for transfers to finish 2025/03/16 06:41:47 DEBUG : a/potato2: md5 = dec6bf826845390ba8440f5d635b325d OK 2025/03/16 06:41:47 INFO : a/potato2: Copied (new) 2025/03/16 06:41:47 DEBUG : Waiting for deletions to finish 2025/03/16 06:41:47 INFO : b/potato: Deleted 2025/03/16 06:41:48 INFO : a: Set directory modification time (using DirSetModTime) 2025/03/16 06:41:48 INFO : d/e: Removing directory 2025/03/16 06:41:48 INFO : d: Removing directory 2025/03/16 06:41:49 DEBUG : ka6id8d20d3s5ktapedlphgta8: Rmdir: contains trashed file: "r8sppajuabeak3sbgj2ak8vuf8" 2025/03/16 06:41:49 INFO : b: Removing directory 2025/03/16 06:41:49 DEBUG : 32d8ua6196mc1r7qkfog53rkg0: Rmdir: contains trashed file: "2m507n64kafsi59v9q71r281a4" 2025/03/16 06:41:50 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': deleted 3 directories run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:41:52 DEBUG : 3i9du405pfogq3ncai6pg7ouio: Rmdir: contains trashed file: "982d3pss7t5pn0il16r2foj31s" 2025/03/16 06:41:52 DEBUG : 2bsvlrk2ne1lfitm6tttcu0qt8: Rmdir: contains trashed file: "89l8renevh3mji1c8r1p7qn6tg" --- PASS: TestSyncAfterRemovingAFileAndAddingAFileSubDir (15.81s) === RUN TestSyncAfterRemovingAFileAndAddingAFileSubDirWithErrors run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:41:56 DEBUG : b/potato: md5 = d1a6949256996fddf674b4b0207a4b1f OK 2025/03/16 06:41:58 DEBUG : c/non empty space: md5 = c976e2d81435d8ef0222daf934ab6a6f OK 2025/03/16 06:41:58 INFO : d: Making directory 2025/03/16 06:41:59 DEBUG : Added delayed dir = "a", newDst= 2025/03/16 06:42:00 INFO : c: Set directory modification time (using SetModTime) 2025/03/16 06:42:00 DEBUG : Added delayed dir = "c", newDst=c 2025/03/16 06:42:00 DEBUG : a/potato2: Need to transfer - File not found at Destination 2025/03/16 06:42:00 DEBUG : c/non empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2025/03/16 06:42:00 DEBUG : c/non empty space: Unchanged skipping 2025/03/16 06:42:00 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for checks to finish 2025/03/16 06:42:00 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for transfers to finish 2025/03/16 06:42:02 DEBUG : a/potato2: md5 = 56b383c739847124d0e9d229f6e4b3ae OK 2025/03/16 06:42:02 INFO : a/potato2: Copied (new) 2025/03/16 06:42:02 ERROR : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': not deleting files as there were IO errors 2025/03/16 06:42:02 INFO : a: Set directory modification time (using DirSetModTime) 2025/03/16 06:42:02 ERROR : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': not deleting directories as there were IO errors run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:42:05 DEBUG : 3i9du405pfogq3ncai6pg7ouio: Rmdir: contains trashed file: "982d3pss7t5pn0il16r2foj31s" 2025/03/16 06:42:06 DEBUG : 32d8ua6196mc1r7qkfog53rkg0: Rmdir: contains trashed file: "2m507n64kafsi59v9q71r281a4" 2025/03/16 06:42:07 DEBUG : 2bsvlrk2ne1lfitm6tttcu0qt8: Rmdir: contains trashed file: "89l8renevh3mji1c8r1p7qn6tg" --- PASS: TestSyncAfterRemovingAFileAndAddingAFileSubDirWithErrors (14.14s) === RUN TestSyncDeleteAfter --- PASS: TestSyncDeleteAfter (0.00s) === RUN TestSyncDeleteDuring run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:42:09 DEBUG : potato: md5 = e691eb5b2a81ca1e2d9bea76e389acb9 OK 2025/03/16 06:42:10 DEBUG : empty space: md5 = 7606d1d77645a3ad6969f989f647fbd4 OK 2025/03/16 06:42:11 DEBUG : Waiting for deletions to finish 2025/03/16 06:42:11 DEBUG : potato2: Need to transfer - File not found at Destination 2025/03/16 06:42:11 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2025/03/16 06:42:11 DEBUG : empty space: Unchanged skipping 2025/03/16 06:42:11 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for checks to finish 2025/03/16 06:42:11 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for transfers to finish 2025/03/16 06:42:11 INFO : potato: Deleted 2025/03/16 06:42:12 DEBUG : potato2: md5 = 2e2cf7fd8ae4683e9d36510f6aa39121 OK 2025/03/16 06:42:12 INFO : potato2: Copied (new) run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" --- PASS: TestSyncDeleteDuring (6.80s) === RUN TestSyncDeleteBefore run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:42:16 DEBUG : potato: md5 = f0e3dcf2fa2dbdd5dd8144245dbfaff3 OK 2025/03/16 06:42:17 DEBUG : empty space: md5 = faf43a9f19c8c7300ddfb4cb29c6dd56 OK 2025/03/16 06:42:17 DEBUG : Waiting for deletions to finish 2025/03/16 06:42:18 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for checks to finish 2025/03/16 06:42:18 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for transfers to finish 2025/03/16 06:42:18 INFO : potato: Deleted 2025/03/16 06:42:18 DEBUG : potato2: Need to transfer - File not found at Destination 2025/03/16 06:42:18 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2025/03/16 06:42:18 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for checks to finish 2025/03/16 06:42:18 DEBUG : empty space: Unchanged skipping 2025/03/16 06:42:18 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for transfers to finish 2025/03/16 06:42:20 DEBUG : potato2: md5 = 79cd93af5be14c390e2fa40ce668bcac OK 2025/03/16 06:42:20 INFO : potato2: Copied (new) run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" --- PASS: TestSyncDeleteBefore (7.39s) === RUN TestCopyDeleteBefore run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:42:23 DEBUG : potato: md5 = 1c830b1b4c197a5299510fd01b1ca3c1 OK 2025/03/16 06:42:24 DEBUG : potato2: Need to transfer - File not found at Destination 2025/03/16 06:42:24 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for checks to finish 2025/03/16 06:42:24 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for transfers to finish 2025/03/16 06:42:25 DEBUG : potato2: md5 = a4c2158db34ea466b53e8b57c7dbb239 OK 2025/03/16 06:42:25 INFO : potato2: Copied (new) run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" --- PASS: TestCopyDeleteBefore (5.10s) === RUN TestSyncWithExclude run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:42:28 DEBUG : potato2: md5 = 987a8181e3800ea44d335b1f6c2c9284 OK 2025/03/16 06:42:30 DEBUG : empty space: md5 = cd7c73ba0d247bd6d39cd8179187da5a OK 2025/03/16 06:42:30 DEBUG : enormous: Excluded (Size Filter) 2025/03/16 06:42:30 DEBUG : enormous: Excluded 2025/03/16 06:42:30 DEBUG : potato2: Excluded (Size Filter) 2025/03/16 06:42:30 DEBUG : potato2: Excluded 2025/03/16 06:42:30 DEBUG : potato2: Excluded (Size Filter) 2025/03/16 06:42:30 DEBUG : potato2: Excluded 2025/03/16 06:42:30 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2025/03/16 06:42:30 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for checks to finish 2025/03/16 06:42:30 DEBUG : empty space: Unchanged skipping 2025/03/16 06:42:30 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for transfers to finish 2025/03/16 06:42:30 DEBUG : Waiting for deletions to finish 2025/03/16 06:42:30 INFO : There was nothing to transfer run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:42:31 DEBUG : enormous: Excluded (Size Filter) 2025/03/16 06:42:31 DEBUG : enormous: Excluded 2025/03/16 06:42:31 DEBUG : potato2: Excluded (Size Filter) 2025/03/16 06:42:31 DEBUG : potato2: Excluded 2025/03/16 06:42:31 DEBUG : potato2: Excluded (Size Filter) 2025/03/16 06:42:31 DEBUG : potato2: Excluded 2025/03/16 06:42:31 DEBUG : empty space: Size and modification time the same (differ by 456.789µs, within tolerance 1ms) 2025/03/16 06:42:31 DEBUG : empty space: Unchanged skipping 2025/03/16 06:42:31 DEBUG : Local file system at /tmp/rclone1589196380: Waiting for checks to finish 2025/03/16 06:42:31 DEBUG : Local file system at /tmp/rclone1589196380: Waiting for transfers to finish 2025/03/16 06:42:31 DEBUG : Waiting for deletions to finish 2025/03/16 06:42:31 INFO : There was nothing to transfer run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" --- PASS: TestSyncWithExclude (6.12s) === RUN TestSyncWithExcludeAndDeleteExcluded run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:42:34 DEBUG : potato2: md5 = 69c88959875ba115af637a8997133048 OK 2025/03/16 06:42:36 DEBUG : empty space: md5 = 968858508b91f3e194c724a065c7f1d5 OK 2025/03/16 06:42:37 DEBUG : enormous: md5 = f9299d93986f6882255626021382f7b1 OK 2025/03/16 06:42:37 DEBUG : enormous: Excluded (Size Filter) 2025/03/16 06:42:37 DEBUG : enormous: Excluded 2025/03/16 06:42:37 DEBUG : potato2: Excluded (Size Filter) 2025/03/16 06:42:37 DEBUG : potato2: Excluded 2025/03/16 06:42:38 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2025/03/16 06:42:38 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for checks to finish 2025/03/16 06:42:38 DEBUG : empty space: Unchanged skipping 2025/03/16 06:42:38 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for transfers to finish 2025/03/16 06:42:38 DEBUG : Waiting for deletions to finish 2025/03/16 06:42:38 INFO : enormous: Deleted 2025/03/16 06:42:38 INFO : potato2: Deleted 2025/03/16 06:42:38 INFO : There was nothing to transfer run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:42:38 DEBUG : empty space: Size and modification time the same (differ by 456.789µs, within tolerance 1ms) 2025/03/16 06:42:38 DEBUG : empty space: Unchanged skipping 2025/03/16 06:42:38 DEBUG : Local file system at /tmp/rclone1589196380: Waiting for checks to finish 2025/03/16 06:42:38 DEBUG : Local file system at /tmp/rclone1589196380: Waiting for transfers to finish 2025/03/16 06:42:38 DEBUG : Waiting for deletions to finish 2025/03/16 06:42:38 INFO : potato2: Deleted 2025/03/16 06:42:38 INFO : enormous: Deleted 2025/03/16 06:42:38 INFO : There was nothing to transfer run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" --- PASS: TestSyncWithExcludeAndDeleteExcluded (7.10s) === RUN TestSyncWithUpdateOlder run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:42:42 DEBUG : one: md5 = 3852ae872a1f97debd0825ae1fe45073 OK 2025/03/16 06:42:43 DEBUG : two: md5 = cca40a84ddf35ac52ea1769869da60b3 OK 2025/03/16 06:42:44 DEBUG : three: md5 = c7e492d3d42359e358851b0a702a8c0f OK 2025/03/16 06:42:46 DEBUG : four: md5 = b384348a53a3d79d0631b74c25c70138 OK 2025/03/16 06:42:46 DEBUG : five: Need to transfer - File not found at Destination 2025/03/16 06:42:46 DEBUG : four: Sizes differ (src 4 vs dst 8) 2025/03/16 06:42:46 DEBUG : one: Destination is newer than source, skipping 2025/03/16 06:42:46 DEBUG : three: Sizes identical 2025/03/16 06:42:46 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for checks to finish 2025/03/16 06:42:46 DEBUG : four: Destination mod time is within 1s of source but files differ, transferring 2025/03/16 06:42:46 DEBUG : three: Destination mod time is within 1s of source and files identical, skipping 2025/03/16 06:42:46 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for transfers to finish 2025/03/16 06:42:47 DEBUG : two: md5 = 5c043bd6ae073a71fbb310209771dfac OK 2025/03/16 06:42:47 INFO : two: Copied (replaced existing) 2025/03/16 06:42:48 DEBUG : four: md5 = 35ef1cf30e5861088723accb3cb42ae6 OK 2025/03/16 06:42:48 INFO : four: Copied (replaced existing) 2025/03/16 06:42:48 DEBUG : five: md5 = 55c83cef49a68da6e7f0cb4a398c773e OK 2025/03/16 06:42:48 INFO : five: Copied (new) 2025/03/16 06:42:48 DEBUG : Waiting for deletions to finish sync_test.go:1449: Skip test with --checksum as no hashes supported --- PASS: TestSyncWithUpdateOlder (10.56s) === 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 "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" sync_test.go:1538: Can track renames: false 2025/03/16 06:42:51 ERROR : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Ignoring --track-renames as the source and destination do not have a common hash 2025/03/16 06:42:51 DEBUG : potato: Need to transfer - File not found at Destination 2025/03/16 06:42:51 DEBUG : yam: Need to transfer - File not found at Destination 2025/03/16 06:42:51 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for checks to finish 2025/03/16 06:42:51 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for transfers to finish 2025/03/16 06:42:52 DEBUG : yam: md5 = 83283d6ea5d012940d42abbf852da22d OK 2025/03/16 06:42:52 INFO : yam: Copied (new) 2025/03/16 06:42:52 DEBUG : potato: md5 = 3059bf0c8dd526b6cf849b4c9a35b016 OK 2025/03/16 06:42:52 INFO : potato: Copied (new) 2025/03/16 06:42:52 DEBUG : Waiting for deletions to finish run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:42:53 ERROR : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Ignoring --track-renames as the source and destination do not have a common hash 2025/03/16 06:42:53 DEBUG : yaml: Need to transfer - File not found at Destination 2025/03/16 06:42:53 DEBUG : potato: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/16 06:42:53 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for checks to finish 2025/03/16 06:42:53 DEBUG : potato: Unchanged skipping 2025/03/16 06:42:53 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for transfers to finish 2025/03/16 06:42:54 DEBUG : yaml: md5 = 05993a576bad9ceffd647f2c7cca1f46 OK 2025/03/16 06:42:54 INFO : yaml: Copied (new) 2025/03/16 06:42:54 DEBUG : Waiting for deletions to finish 2025/03/16 06:42:54 INFO : yam: Deleted run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" --- PASS: TestSyncWithTrackRenames (6.15s) === RUN TestParseRenamesStrategyModtime --- PASS: TestParseRenamesStrategyModtime (0.00s) === RUN TestRenamesStrategyModtime --- PASS: TestRenamesStrategyModtime (0.00s) === RUN TestSyncWithTrackRenamesStrategyModtime run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" sync_test.go:1610: Can track renames: true 2025/03/16 06:42:57 INFO : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Making map for --track-renames 2025/03/16 06:42:57 INFO : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Finished making map for --track-renames 2025/03/16 06:42:57 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for checks to finish 2025/03/16 06:42:57 DEBUG : potato: Need to transfer - No matching file found at Destination 2025/03/16 06:42:57 DEBUG : yam: Need to transfer - No matching file found at Destination 2025/03/16 06:42:57 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for renames to finish 2025/03/16 06:42:57 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for transfers to finish 2025/03/16 06:42:59 DEBUG : potato: md5 = 8246afbb13c71c36145016b82ca23dfe OK 2025/03/16 06:42:59 INFO : potato: Copied (new) 2025/03/16 06:42:59 DEBUG : yam: md5 = ba43e4b59ba5f929cdb8ec1ae7916f5f OK 2025/03/16 06:42:59 INFO : yam: Copied (new) 2025/03/16 06:42:59 DEBUG : Waiting for deletions to finish run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:42:59 DEBUG : potato: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/16 06:42:59 INFO : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Making map for --track-renames 2025/03/16 06:42:59 INFO : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Finished making map for --track-renames 2025/03/16 06:42:59 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for checks to finish 2025/03/16 06:42:59 DEBUG : potato: Unchanged skipping 2025/03/16 06:42:59 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for renames to finish 2025/03/16 06:43:00 INFO : yam: Moved (server-side) to: yaml 2025/03/16 06:43:00 INFO : yaml: Renamed from "yam" 2025/03/16 06:43:00 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for transfers to finish 2025/03/16 06:43:00 DEBUG : Waiting for deletions to finish 2025/03/16 06:43:00 INFO : There was nothing to transfer run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" --- PASS: TestSyncWithTrackRenamesStrategyModtime (5.39s) === RUN TestSyncWithTrackRenamesStrategyLeaf run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" sync_test.go:1649: Can track renames: true 2025/03/16 06:43:03 DEBUG : Added delayed dir = "sub", newDst= 2025/03/16 06:43:03 INFO : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Making map for --track-renames 2025/03/16 06:43:03 INFO : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Finished making map for --track-renames 2025/03/16 06:43:03 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for checks to finish 2025/03/16 06:43:03 DEBUG : potato: Need to transfer - No matching file found at Destination 2025/03/16 06:43:03 DEBUG : sub/yam: Need to transfer - No matching file found at Destination 2025/03/16 06:43:03 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for renames to finish 2025/03/16 06:43:03 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for transfers to finish 2025/03/16 06:43:05 DEBUG : sub/yam: md5 = e95a330ed92a74be2e929fb1232fa553 OK 2025/03/16 06:43:05 INFO : sub/yam: Copied (new) 2025/03/16 06:43:05 DEBUG : potato: md5 = 374f94039ed8117f84227d8c72d38b6d OK 2025/03/16 06:43:05 INFO : potato: Copied (new) 2025/03/16 06:43:05 DEBUG : Waiting for deletions to finish 2025/03/16 06:43:05 INFO : sub: Set directory modification time (using DirSetModTime) run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:43:06 DEBUG : potato: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/16 06:43:06 DEBUG : potato: Unchanged skipping 2025/03/16 06:43:06 INFO : sub: Set directory modification time (using SetModTime) 2025/03/16 06:43:06 DEBUG : Added delayed dir = "sub", newDst=sub 2025/03/16 06:43:07 INFO : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Making map for --track-renames 2025/03/16 06:43:07 INFO : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Finished making map for --track-renames 2025/03/16 06:43:07 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for checks to finish 2025/03/16 06:43:07 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for renames to finish 2025/03/16 06:43:07 INFO : sub/yam: Moved (server-side) to: yam 2025/03/16 06:43:07 INFO : yam: Renamed from "sub/yam" 2025/03/16 06:43:07 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for transfers to finish 2025/03/16 06:43:07 DEBUG : Waiting for deletions to finish 2025/03/16 06:43:07 INFO : There was nothing to transfer run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" --- PASS: TestSyncWithTrackRenamesStrategyLeaf (8.75s) === RUN TestServerSideMoveLocal run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:43:11 DEBUG : Creating backend with remote "/tmp/rclone1589196380/dir1" 2025/03/16 06:43:11 DEBUG : Creating backend with remote "/tmp/rclone1589196380/dir2" 2025/03/16 06:43:11 DEBUG : Local file system at /tmp/rclone1589196380/dir2: Using server-side directory move 2025/03/16 06:43:11 INFO : Local file system at /tmp/rclone1589196380/dir2: Server side directory move failed - fallback to file moves: can't copy directory - destination already exists 2025/03/16 06:43:11 DEBUG : file1.txt: Need to transfer - File not found at Destination 2025/03/16 06:43:11 INFO : file1.txt: Moved (server-side) 2025/03/16 06:43:11 DEBUG : Local file system at /tmp/rclone1589196380/dir2: Waiting for checks to finish 2025/03/16 06:43:11 DEBUG : Local file system at /tmp/rclone1589196380/dir2: Waiting for transfers to finish --- PASS: TestServerSideMoveLocal (0.48s) === RUN TestMoveWithDeleteEmptySrcDirs run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:43:12 DEBUG : Added delayed dir = "nested", newDst= 2025/03/16 06:43:12 DEBUG : Added delayed dir = "sub dir", newDst= 2025/03/16 06:43:12 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2025/03/16 06:43:12 DEBUG : Added delayed dir = "nested/sub dir", newDst= 2025/03/16 06:43:12 DEBUG : nested/sub dir/file: Need to transfer - File not found at Destination 2025/03/16 06:43:12 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for checks to finish 2025/03/16 06:43:12 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for transfers to finish 2025/03/16 06:43:14 DEBUG : sub dir/hello world: md5 = d9c8c2405896327b881b59fc864f28ac OK 2025/03/16 06:43:14 INFO : sub dir/hello world: Copied (new) 2025/03/16 06:43:14 INFO : sub dir/hello world: Deleted 2025/03/16 06:43:16 DEBUG : nested/sub dir/file: md5 = a58199d2b725b922dada511f2ea7acde OK 2025/03/16 06:43:16 INFO : nested/sub dir/file: Copied (new) 2025/03/16 06:43:16 INFO : nested/sub dir/file: Deleted 2025/03/16 06:43:16 INFO : nested/sub dir: Set directory modification time (using DirSetModTime) 2025/03/16 06:43:16 INFO : nested: Set directory modification time (using DirSetModTime) 2025/03/16 06:43:16 INFO : sub dir: Set directory modification time (using DirSetModTime) 2025/03/16 06:43:16 INFO : sub dir: Removing directory 2025/03/16 06:43:16 INFO : nested/sub dir: Removing directory 2025/03/16 06:43:16 INFO : nested: Removing directory 2025/03/16 06:43:16 DEBUG : Local file system at /tmp/rclone1589196380: deleted 3 directories run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:43:19 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" 2025/03/16 06:43:20 DEBUG : 37qp6d1gohacv723ij3brofbu8/14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "ftp4kuv8se7tqduu6pmmcvjsmk" 2025/03/16 06:43:20 DEBUG : 37qp6d1gohacv723ij3brofbu8: Rmdir: contains trashed file: "14begaa36ih249fgrnfk6nulg0" --- PASS: TestMoveWithDeleteEmptySrcDirs (10.04s) === RUN TestMoveWithoutDeleteEmptySrcDirs run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:43:22 DEBUG : Added delayed dir = "nested", newDst= 2025/03/16 06:43:22 DEBUG : Added delayed dir = "sub dir", newDst= 2025/03/16 06:43:22 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2025/03/16 06:43:22 DEBUG : Added delayed dir = "nested/sub dir", newDst= 2025/03/16 06:43:22 DEBUG : nested/sub dir/file: Need to transfer - File not found at Destination 2025/03/16 06:43:22 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for checks to finish 2025/03/16 06:43:22 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for transfers to finish 2025/03/16 06:43:24 DEBUG : sub dir/hello world: md5 = 7d3b6ac9b47665d7bea766499603f871 OK 2025/03/16 06:43:24 INFO : sub dir/hello world: Copied (new) 2025/03/16 06:43:24 INFO : sub dir/hello world: Deleted 2025/03/16 06:43:26 DEBUG : nested/sub dir/file: md5 = 9c5db40d146acbcf5e0c0d3d089834fb OK 2025/03/16 06:43:26 INFO : nested/sub dir/file: Copied (new) 2025/03/16 06:43:26 INFO : nested/sub dir/file: Deleted 2025/03/16 06:43:26 INFO : nested/sub dir: Set directory modification time (using DirSetModTime) 2025/03/16 06:43:27 INFO : nested: Set directory modification time (using DirSetModTime) 2025/03/16 06:43:27 INFO : sub dir: Set directory modification time (using DirSetModTime) run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:43:29 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" 2025/03/16 06:43:30 DEBUG : 37qp6d1gohacv723ij3brofbu8/14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "ftp4kuv8se7tqduu6pmmcvjsmk" 2025/03/16 06:43:31 DEBUG : 37qp6d1gohacv723ij3brofbu8: Rmdir: contains trashed file: "14begaa36ih249fgrnfk6nulg0" --- PASS: TestMoveWithoutDeleteEmptySrcDirs (10.11s) === RUN TestMoveWithIgnoreExisting run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:43:32 DEBUG : existing: Need to transfer - File not found at Destination 2025/03/16 06:43:32 DEBUG : existing-b: Need to transfer - File not found at Destination 2025/03/16 06:43:32 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for checks to finish 2025/03/16 06:43:32 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for transfers to finish 2025/03/16 06:43:33 DEBUG : existing-b: md5 = b44ea123084c4f30bbfbf0b4f0291d37 OK 2025/03/16 06:43:33 INFO : existing-b: Copied (new) 2025/03/16 06:43:33 INFO : existing-b: Deleted 2025/03/16 06:43:33 DEBUG : existing: md5 = 052f96e8e0b2d9fc40b93cdd5068766e OK 2025/03/16 06:43:33 INFO : existing: Copied (new) 2025/03/16 06:43:33 INFO : existing: Deleted 2025/03/16 06:43:34 DEBUG : existing: Destination exists, skipping 2025/03/16 06:43:34 DEBUG : existing: Not removing source file as destination file exists and --ignore-existing is set 2025/03/16 06:43:34 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for checks to finish 2025/03/16 06:43:34 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for transfers to finish 2025/03/16 06:43:34 INFO : There was nothing to transfer run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" --- PASS: TestMoveWithIgnoreExisting (3.99s) === RUN TestServerSideMove run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:43:36 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-sihokof5fata" 2025/03/16 06:43:36 DEBUG : Creating backend with remote "TestDrive:crypt/kqrvk0u9t2if6ogpb3gdbo6phe88g28k374koge7boq7pmo98ui0" 2025/03/16 06:43:38 DEBUG : potato2: md5 = bca0f7a75562d6dea55548facd6682f0 OK 2025/03/16 06:43:39 DEBUG : empty space: md5 = 8bbbf8216ceea89992bec2afb9a5e015 OK 2025/03/16 06:43:41 DEBUG : potato3: md5 = abf2d4bbbb0341c883d19df9ed002d84 OK sync_test.go:1705: Server side move (if possible) Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu' -> Encrypted drive 'TestCryptDrive:rclone-test-sihokof5fata' 2025/03/16 06:43:43 DEBUG : empty space: md5 = 6cb14494536b59daf84c89b642871eda OK 2025/03/16 06:43:44 DEBUG : potato3: md5 = 3630808a8d46408559f81deef7b5534e OK 2025/03/16 06:43:45 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sihokof5fata': Using server-side directory move 2025/03/16 06:43:45 INFO : Encrypted drive 'TestCryptDrive:rclone-test-sihokof5fata': Server side directory move failed - fallback to file moves: can't copy directory - destination already exists 2025/03/16 06:43:45 DEBUG : potato2: Need to transfer - File not found at Destination 2025/03/16 06:43:45 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sihokof5fata': Waiting for checks to finish 2025/03/16 06:43:45 DEBUG : empty space: Size and modification time the same (differ by 0s, within tolerance 1ms) 2025/03/16 06:43:45 DEBUG : empty space: Unchanged skipping 2025/03/16 06:43:45 DEBUG : potato3: Sizes differ (src 68 vs dst 60) 2025/03/16 06:43:45 INFO : potato3: Deleted 2025/03/16 06:43:45 INFO : empty space: Deleted 2025/03/16 06:43:45 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sihokof5fata': Waiting for transfers to finish 2025/03/16 06:43:45 INFO : potato2: Moved (server-side) 2025/03/16 06:43:46 INFO : potato3: Moved (server-side) 2025/03/16 06:43:46 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-yaqosum2tefe" 2025/03/16 06:43:46 DEBUG : Creating backend with remote "TestDrive:crypt/53a4hc7frtci9ovkba0o8q2csmv6ptuhhdlsg02bv09u9novk3l0" 2025/03/16 06:43:47 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-yaqosum2tefe': Using server-side directory move 2025/03/16 06:43:48 INFO : Encrypted drive 'TestCryptDrive:rclone-test-yaqosum2tefe': Server side directory move succeeded 2025/03/16 06:43:49 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-yaqosum2tefe': Purge remote 2025/03/16 06:43:49 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sihokof5fata': Purge remote 2025/03/16 06:43:49 NOTICE: purge failed: directory not found --- PASS: TestServerSideMove (14.17s) === RUN TestServerSideMoveWithFilter run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:43:50 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-wefumol4puli" 2025/03/16 06:43:50 DEBUG : Creating backend with remote "TestDrive:crypt/b0sqohc6qvuet2lo15pb4vokut0up4iuk4ehraapobq7mnncv760" 2025/03/16 06:43:52 DEBUG : potato2: md5 = de5c652b5e701378f76ad75c6294225e OK 2025/03/16 06:43:54 DEBUG : empty space: md5 = 271f2f9dadde66fddc4ef29b03db2be8 OK 2025/03/16 06:43:55 DEBUG : potato3: md5 = 97a449baaaa410ca5f52e1aa00c0e9ad OK sync_test.go:1705: Server side move (if possible) Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu' -> Encrypted drive 'TestCryptDrive:rclone-test-wefumol4puli' 2025/03/16 06:43:57 DEBUG : empty space: md5 = c2ff9e1943354fc9fd6339d3f9d4403e OK 2025/03/16 06:43:59 DEBUG : potato3: md5 = a6ea52cfefe620e8725895c607a8af09 OK 2025/03/16 06:43:59 DEBUG : empty space: Excluded (Size Filter) 2025/03/16 06:43:59 DEBUG : empty space: Excluded 2025/03/16 06:43:59 DEBUG : empty space: Excluded (Size Filter) 2025/03/16 06:43:59 DEBUG : empty space: Excluded 2025/03/16 06:43:59 DEBUG : potato2: Need to transfer - File not found at Destination 2025/03/16 06:43:59 DEBUG : potato3: Sizes differ (src 68 vs dst 60) 2025/03/16 06:43:59 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wefumol4puli': Waiting for checks to finish 2025/03/16 06:43:59 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wefumol4puli': Waiting for transfers to finish 2025/03/16 06:44:00 INFO : potato3: Deleted 2025/03/16 06:44:00 INFO : potato2: Moved (server-side) 2025/03/16 06:44:00 INFO : potato3: Moved (server-side) 2025/03/16 06:44:01 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-tayuxuv9biho" 2025/03/16 06:44:01 DEBUG : Creating backend with remote "TestDrive:crypt/egnes8teke8kb25r7uleffuvpibub0ug82714rbtvh6tndugk4vg" 2025/03/16 06:44:02 DEBUG : empty space: Excluded (Size Filter) 2025/03/16 06:44:02 DEBUG : empty space: Excluded 2025/03/16 06:44:02 DEBUG : potato2: Need to transfer - File not found at Destination 2025/03/16 06:44:02 DEBUG : potato3: Need to transfer - File not found at Destination 2025/03/16 06:44:02 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tayuxuv9biho': Waiting for checks to finish 2025/03/16 06:44:02 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tayuxuv9biho': Waiting for transfers to finish 2025/03/16 06:44:03 INFO : potato3: Moved (server-side) 2025/03/16 06:44:04 INFO : potato2: Moved (server-side) 2025/03/16 06:44:04 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tayuxuv9biho': Purge remote 2025/03/16 06:44:05 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wefumol4puli': Purge remote --- PASS: TestServerSideMoveWithFilter (16.14s) === RUN TestServerSideMoveDeleteEmptySourceDirs run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:44:06 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-fafajal9meyo" 2025/03/16 06:44:06 DEBUG : Creating backend with remote "TestDrive:crypt/cgo4hp92qaf2g4ah9bsagig1ev4v296j8frkoge5d2rdl6sggihg" 2025/03/16 06:44:08 DEBUG : potato2: md5 = 7aeef2756393d286b873e6b74a811ffc OK 2025/03/16 06:44:10 DEBUG : empty space: md5 = 4a76c3daacf503b13bc76bb93c7505b7 OK 2025/03/16 06:44:11 DEBUG : potato3: md5 = 0d0da6ec586e43b27d3d5c820236c026 OK 2025/03/16 06:44:11 INFO : tomatoDir: Making directory sync_test.go:1705: Server side move (if possible) Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu' -> Encrypted drive 'TestCryptDrive:rclone-test-fafajal9meyo' 2025/03/16 06:44:14 DEBUG : empty space: md5 = c870ea1a695e283562021814ef9b0c8a OK 2025/03/16 06:44:16 DEBUG : potato3: md5 = 5385c2f443a67a9150e8a061819e726d OK 2025/03/16 06:44:16 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-fafajal9meyo': Using server-side directory move 2025/03/16 06:44:16 INFO : Encrypted drive 'TestCryptDrive:rclone-test-fafajal9meyo': Server side directory move failed - fallback to file moves: can't copy directory - destination already exists 2025/03/16 06:44:16 DEBUG : potato2: Need to transfer - File not found at Destination 2025/03/16 06:44:16 DEBUG : Added delayed dir = "tomatoDir", newDst= 2025/03/16 06:44:16 DEBUG : empty space: Size and modification time the same (differ by 0s, within tolerance 1ms) 2025/03/16 06:44:16 DEBUG : empty space: Unchanged skipping 2025/03/16 06:44:16 DEBUG : potato3: Sizes differ (src 68 vs dst 60) 2025/03/16 06:44:16 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-fafajal9meyo': Waiting for checks to finish 2025/03/16 06:44:16 INFO : empty space: Deleted 2025/03/16 06:44:16 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-fafajal9meyo': Waiting for transfers to finish 2025/03/16 06:44:16 INFO : potato3: Deleted 2025/03/16 06:44:17 INFO : potato2: Moved (server-side) 2025/03/16 06:44:17 INFO : potato3: Moved (server-side) 2025/03/16 06:44:17 INFO : tomatoDir: Removing directory 2025/03/16 06:44:18 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': deleted 1 directories 2025/03/16 06:44:18 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-loqogiq0wawi" 2025/03/16 06:44:18 DEBUG : Creating backend with remote "TestDrive:crypt/415o6v9pspddd3pi24b29p00rplcjmb64vn7v7v4jmjth3v6n1p0" 2025/03/16 06:44:19 INFO : tomatoDir: Making directory 2025/03/16 06:44:20 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-loqogiq0wawi': Using server-side directory move 2025/03/16 06:44:21 INFO : Encrypted drive 'TestCryptDrive:rclone-test-loqogiq0wawi': Server side directory move succeeded 2025/03/16 06:44:22 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-loqogiq0wawi': Purge remote 2025/03/16 06:44:22 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-fafajal9meyo': Purge remote 2025/03/16 06:44:23 NOTICE: purge failed: directory not found --- PASS: TestServerSideMoveDeleteEmptySourceDirs (17.17s) === RUN TestServerSideMoveOverlap run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" sync_test.go:1910: Skipping test as remote supports DirMove --- SKIP: TestServerSideMoveOverlap (0.45s) === RUN TestSyncOverlap run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:44:24 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-wixuyiv3lumu/rclone-sync-test" 2025/03/16 06:44:24 DEBUG : Creating backend with remote "TestDrive:crypt/n3ncf6nbor1b3s3vkpig0sf40id8nuidr6khhvfpotbv0gp72c00/i7355aa0sb89uagn75vfjqr6s3e3e1h2et8in57abn1fe8qfego0" run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" --- PASS: TestSyncOverlap (3.64s) === RUN TestSyncOverlapWithFilter run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:44:27 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-wixuyiv3lumu/rclone-sync-test" 2025/03/16 06:44:27 DEBUG : Creating backend with remote "TestDrive:crypt/n3ncf6nbor1b3s3vkpig0sf40id8nuidr6khhvfpotbv0gp72c00/i7355aa0sb89uagn75vfjqr6s3e3e1h2et8in57abn1fe8qfego0" 2025/03/16 06:44:29 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-wixuyiv3lumu/rclone-sync-test-include/layer2" 2025/03/16 06:44:29 DEBUG : Creating backend with remote "TestDrive:crypt/n3ncf6nbor1b3s3vkpig0sf40id8nuidr6khhvfpotbv0gp72c00/khf2vlblvnbf9ftevqm0htmss73hj1j5a7q328e4ohrgs7e2loe0/n01jpl9202nn9ec1rb75h0f1c4" 2025/03/16 06:44:32 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-wixuyiv3lumu/rclone-sync-test-ignore-file" 2025/03/16 06:44:32 DEBUG : Creating backend with remote "TestDrive:crypt/n3ncf6nbor1b3s3vkpig0sf40id8nuidr6khhvfpotbv0gp72c00/kmf11jujl9uha3tjganvgpkn45bu778hb5vb5riug1c26b38k7sg" 2025/03/16 06:44:36 DEBUG : rclone-sync-test-ignore-file/.ignore: md5 = 38e65bb3b51d19e8e176ed90b5229676 OK 2025/03/16 06:44:37 DEBUG : rclone-sync-test-ignore-file: Excluded 2025/03/16 06:44:38 DEBUG : rclone-sync-test: Excluded 2025/03/16 06:44:38 DEBUG : Added delayed dir = "rclone-sync-test-include", newDst= 2025/03/16 06:44:38 DEBUG : rclone-sync-test-include/layer2: Excluded 2025/03/16 06:44:38 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu/rclone-sync-test': Waiting for checks to finish 2025/03/16 06:44:38 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu/rclone-sync-test': Waiting for transfers to finish 2025/03/16 06:44:38 DEBUG : Waiting for deletions to finish 2025/03/16 06:44:38 INFO : There was nothing to transfer 2025/03/16 06:44:39 DEBUG : rclone-sync-test-ignore-file: Excluded 2025/03/16 06:44:39 DEBUG : rclone-sync-test: Excluded 2025/03/16 06:44:40 DEBUG : rclone-sync-test-include/layer2: Excluded 2025/03/16 06:44:40 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for checks to finish 2025/03/16 06:44:40 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for transfers to finish 2025/03/16 06:44:40 DEBUG : Waiting for deletions to finish 2025/03/16 06:44:40 INFO : rclone-sync-test-include: Removing directory 2025/03/16 06:44:40 DEBUG : khf2vlblvnbf9ftevqm0htmss73hj1j5a7q328e4ohrgs7e2loe0: Rmdir: contains file: "n01jpl9202nn9ec1rb75h0f1c4" 2025/03/16 06:44:40 DEBUG : rclone-sync-test-include: Failed to Rmdir: directory not empty 2025/03/16 06:44:40 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': failed to delete 1 directories 2025/03/16 06:44:40 INFO : There was nothing to transfer run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:44:41 DEBUG : rclone-sync-test-ignore-file: Excluded 2025/03/16 06:44:41 DEBUG : rclone-sync-test: Excluded 2025/03/16 06:44:41 DEBUG : Added delayed dir = "rclone-sync-test-include", newDst= 2025/03/16 06:44:41 DEBUG : rclone-sync-test-include/layer2: Excluded 2025/03/16 06:44:41 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu/rclone-sync-test-include/layer2': Waiting for checks to finish 2025/03/16 06:44:41 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu/rclone-sync-test-include/layer2': Waiting for transfers to finish 2025/03/16 06:44:41 DEBUG : Waiting for deletions to finish 2025/03/16 06:44:41 INFO : There was nothing to transfer run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:44:42 DEBUG : rclone-sync-test-ignore-file: Excluded 2025/03/16 06:44:43 DEBUG : rclone-sync-test: Excluded 2025/03/16 06:44:43 DEBUG : rclone-sync-test-include/layer2: Excluded 2025/03/16 06:44:43 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for checks to finish 2025/03/16 06:44:43 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for transfers to finish 2025/03/16 06:44:43 DEBUG : Waiting for deletions to finish 2025/03/16 06:44:43 INFO : rclone-sync-test-include: Removing directory 2025/03/16 06:44:43 DEBUG : khf2vlblvnbf9ftevqm0htmss73hj1j5a7q328e4ohrgs7e2loe0: Rmdir: contains file: "n01jpl9202nn9ec1rb75h0f1c4" 2025/03/16 06:44:43 DEBUG : rclone-sync-test-include: Failed to Rmdir: directory not empty 2025/03/16 06:44:43 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': failed to delete 1 directories 2025/03/16 06:44:43 INFO : There was nothing to transfer run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:44:44 DEBUG : : Excluded 2025/03/16 06:44:44 DEBUG : rclone-sync-test-ignore-file: Excluded 2025/03/16 06:44:44 DEBUG : rclone-sync-test: Excluded 2025/03/16 06:44:44 DEBUG : Added delayed dir = "rclone-sync-test-include", newDst= 2025/03/16 06:44:45 DEBUG : rclone-sync-test-include/layer2: Excluded 2025/03/16 06:44:45 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu/rclone-sync-test-ignore-file': Waiting for checks to finish 2025/03/16 06:44:45 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu/rclone-sync-test-ignore-file': Waiting for transfers to finish 2025/03/16 06:44:45 DEBUG : Waiting for deletions to finish 2025/03/16 06:44:45 INFO : There was nothing to transfer run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:44:47 DEBUG : khf2vlblvnbf9ftevqm0htmss73hj1j5a7q328e4ohrgs7e2loe0: Rmdir: contains trashed file: "n01jpl9202nn9ec1rb75h0f1c4" 2025/03/16 06:44:48 DEBUG : kmf11jujl9uha3tjganvgpkn45bu778hb5vb5riug1c26b38k7sg: Rmdir: contains trashed file: "i0t74httmdlljg425j6tg570d8" --- PASS: TestSyncOverlapWithFilter (29.22s) === RUN TestSyncCompareDest run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:44:56 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-wixuyiv3lumu/dst" 2025/03/16 06:44:57 DEBUG : Creating backend with remote "TestDrive:crypt/n3ncf6nbor1b3s3vkpig0sf40id8nuidr6khhvfpotbv0gp72c00/31u3jie661vd5p8j7rtc3hgbh0" 2025/03/16 06:44:58 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-wixuyiv3lumu/CompareDest" 2025/03/16 06:44:58 DEBUG : Creating backend with remote "TestDrive:crypt/n3ncf6nbor1b3s3vkpig0sf40id8nuidr6khhvfpotbv0gp72c00/gveqi14airsml4bgu7krj116o8" 2025/03/16 06:45:00 DEBUG : one: Need to transfer - File not found at Destination 2025/03/16 06:45:00 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu/dst': Waiting for checks to finish 2025/03/16 06:45:00 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu/dst': Waiting for transfers to finish 2025/03/16 06:45:02 DEBUG : one: md5 = 8b1c15c987038312cc8f8ee0a3e66f2f OK 2025/03/16 06:45:02 INFO : one: Copied (new) 2025/03/16 06:45:02 DEBUG : Waiting for deletions to finish 2025/03/16 06:45:03 DEBUG : one: Sizes differ (src 5 vs dst 3) 2025/03/16 06:45:03 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu/dst': Waiting for checks to finish 2025/03/16 06:45:03 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu/dst': Waiting for transfers to finish 2025/03/16 06:45:04 DEBUG : one: md5 = 2fbde8dec8fa07c48ee9a9816a03d3fb OK 2025/03/16 06:45:04 INFO : one: Copied (replaced existing) 2025/03/16 06:45:04 DEBUG : Waiting for deletions to finish 2025/03/16 06:45:06 DEBUG : dst/one: md5 = 02777939b3838c9adb8d02eb8acbc6c0 OK 2025/03/16 06:45:08 DEBUG : CompareDest/one: md5 = 8c48d1bdfa10286e9638a8da3a1bca8a OK 2025/03/16 06:45:09 DEBUG : one: Sizes differ (src 5 vs dst 3) 2025/03/16 06:45:09 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu/dst': Waiting for checks to finish 2025/03/16 06:45:10 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2025/03/16 06:45:10 DEBUG : one: Destination found in --compare-dest, skipping 2025/03/16 06:45:10 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu/dst': Waiting for transfers to finish 2025/03/16 06:45:10 DEBUG : Waiting for deletions to finish 2025/03/16 06:45:10 INFO : There was nothing to transfer 2025/03/16 06:45:12 DEBUG : CompareDest/two: md5 = 06b73addacb467c6f0fa789f07ac119d OK 2025/03/16 06:45:13 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2025/03/16 06:45:13 DEBUG : two: Destination found in --compare-dest, skipping 2025/03/16 06:45:13 DEBUG : one: Sizes differ (src 5 vs dst 3) 2025/03/16 06:45:13 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu/dst': Waiting for checks to finish 2025/03/16 06:45:13 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2025/03/16 06:45:13 DEBUG : one: Destination found in --compare-dest, skipping 2025/03/16 06:45:13 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu/dst': Waiting for transfers to finish 2025/03/16 06:45:13 DEBUG : Waiting for deletions to finish 2025/03/16 06:45:13 INFO : There was nothing to transfer 2025/03/16 06:45:14 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2025/03/16 06:45:14 DEBUG : two: Destination found in --compare-dest, skipping 2025/03/16 06:45:14 DEBUG : one: Sizes differ (src 5 vs dst 3) 2025/03/16 06:45:14 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu/dst': Waiting for checks to finish 2025/03/16 06:45:14 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2025/03/16 06:45:14 DEBUG : one: Destination found in --compare-dest, skipping 2025/03/16 06:45:14 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu/dst': Waiting for transfers to finish 2025/03/16 06:45:14 DEBUG : Waiting for deletions to finish 2025/03/16 06:45:14 INFO : There was nothing to transfer sync_test.go:2175: No hash on uploaded file so skipping compare timestamp test 2025/03/16 06:45:16 DEBUG : two: Sizes differ (src 5 vs dst 3) 2025/03/16 06:45:16 DEBUG : two: Need to transfer - File not found at Destination 2025/03/16 06:45:16 DEBUG : one: Sizes differ (src 5 vs dst 3) 2025/03/16 06:45:16 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu/dst': Waiting for checks to finish 2025/03/16 06:45:16 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2025/03/16 06:45:16 DEBUG : one: Destination found in --compare-dest, skipping 2025/03/16 06:45:16 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu/dst': Waiting for transfers to finish 2025/03/16 06:45:17 DEBUG : two: md5 = 93fdcee9ba64211bd459f0ae8eb6e12c OK 2025/03/16 06:45:17 INFO : two: Copied (new) 2025/03/16 06:45:17 DEBUG : Waiting for deletions to finish 2025/03/16 06:45:20 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" 2025/03/16 06:45:20 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2025/03/16 06:45:21 DEBUG : gveqi14airsml4bgu7krj116o8: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" 2025/03/16 06:45:21 DEBUG : gveqi14airsml4bgu7krj116o8: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" --- PASS: TestSyncCompareDest (25.00s) === RUN TestSyncMultipleCompareDest run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:45:24 DEBUG : pre-dest1/1: md5 = 837285b0950c4660f8cbfa7a8d30b426 OK 2025/03/16 06:45:26 DEBUG : pre-dest2/2: md5 = ebe1025078ebd57e20a5763c1ca9ffd3 OK 2025/03/16 06:45:26 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-wixuyiv3lumu/dest" 2025/03/16 06:45:26 DEBUG : Creating backend with remote "TestDrive:crypt/n3ncf6nbor1b3s3vkpig0sf40id8nuidr6khhvfpotbv0gp72c00/rg03c1jvnehrrc617i0lnqjddc" 2025/03/16 06:45:28 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-wixuyiv3lumu/pre-dest1" 2025/03/16 06:45:28 DEBUG : Creating backend with remote "TestDrive:crypt/n3ncf6nbor1b3s3vkpig0sf40id8nuidr6khhvfpotbv0gp72c00/bbnblvh6k061ssopqrp18kd7gc" 2025/03/16 06:45:28 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-wixuyiv3lumu/pre-dest2" 2025/03/16 06:45:28 DEBUG : Creating backend with remote "TestDrive:crypt/n3ncf6nbor1b3s3vkpig0sf40id8nuidr6khhvfpotbv0gp72c00/dgicm1h6b5ejvlltm8eeif0bnk" 2025/03/16 06:45:30 DEBUG : 1: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/16 06:45:30 DEBUG : 1: Destination found in --compare-dest, skipping 2025/03/16 06:45:30 DEBUG : 2: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/16 06:45:30 DEBUG : 2: Destination found in --compare-dest, skipping 2025/03/16 06:45:30 DEBUG : 3: Need to transfer - File not found at Destination 2025/03/16 06:45:30 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu/dest': Waiting for checks to finish 2025/03/16 06:45:30 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu/dest': Waiting for transfers to finish 2025/03/16 06:45:33 DEBUG : 3: md5 = 3562553ff7e785e6fc27b6a5697c7b67 OK 2025/03/16 06:45:33 INFO : 3: Copied (new) 2025/03/16 06:45:33 DEBUG : Waiting for deletions to finish 2025/03/16 06:45:35 DEBUG : dgicm1h6b5ejvlltm8eeif0bnk: Rmdir: contains trashed file: "1ghu8geql9vrl726n32nrf65bc" 2025/03/16 06:45:36 DEBUG : bbnblvh6k061ssopqrp18kd7gc: Rmdir: contains trashed file: "skbfko3oil7es0lj68ob574sro" 2025/03/16 06:45:37 DEBUG : rg03c1jvnehrrc617i0lnqjddc: Rmdir: contains trashed file: "g072p7hmjchlnj0gibe64c1epg" --- PASS: TestSyncMultipleCompareDest (16.03s) === RUN TestSyncCopyDest run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:45:37 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-wixuyiv3lumu/dst" 2025/03/16 06:45:38 DEBUG : Creating backend with remote "TestDrive:crypt/n3ncf6nbor1b3s3vkpig0sf40id8nuidr6khhvfpotbv0gp72c00/31u3jie661vd5p8j7rtc3hgbh0" 2025/03/16 06:45:39 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-wixuyiv3lumu/CopyDest" 2025/03/16 06:45:39 DEBUG : Creating backend with remote "TestDrive:crypt/n3ncf6nbor1b3s3vkpig0sf40id8nuidr6khhvfpotbv0gp72c00/d09o6po3f7bm6ce32vdgs8h9ls" 2025/03/16 06:45:41 DEBUG : one: Need to transfer - File not found at Destination 2025/03/16 06:45:41 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu/dst': Waiting for checks to finish 2025/03/16 06:45:41 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu/dst': Waiting for transfers to finish 2025/03/16 06:45:43 DEBUG : one: md5 = 2fd278e2f3e0af0d12b1cd20988e5fb6 OK 2025/03/16 06:45:43 INFO : one: Copied (new) 2025/03/16 06:45:43 DEBUG : Waiting for deletions to finish 2025/03/16 06:45:44 DEBUG : one: Sizes differ (src 5 vs dst 3) 2025/03/16 06:45:44 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu/dst': Waiting for checks to finish 2025/03/16 06:45:44 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu/dst': Waiting for transfers to finish 2025/03/16 06:45:45 DEBUG : one: md5 = 730fc1072b933a606a90ba189794fa39 OK 2025/03/16 06:45:45 INFO : one: Copied (replaced existing) 2025/03/16 06:45:45 DEBUG : Waiting for deletions to finish 2025/03/16 06:45:47 DEBUG : dst/one: md5 = c704b8493629fa34741081fb20aeb3fb OK 2025/03/16 06:45:49 DEBUG : CopyDest/one: md5 = 0aecca717df1dbb42020a8aed88fd702 OK 2025/03/16 06:45:50 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-wixuyiv3lumu/BackupDir" 2025/03/16 06:45:50 DEBUG : Creating backend with remote "TestDrive:crypt/n3ncf6nbor1b3s3vkpig0sf40id8nuidr6khhvfpotbv0gp72c00/s6dbk3lfi7c9kfvo6j7bla9m0g" 2025/03/16 06:45:52 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu/dst': Waiting for checks to finish 2025/03/16 06:45:52 DEBUG : one: Sizes differ (src 5 vs dst 3) 2025/03/16 06:45:52 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2025/03/16 06:45:52 DEBUG : one: Sizes differ (src 5 vs dst 3) 2025/03/16 06:45:54 INFO : one: Moved (server-side) 2025/03/16 06:45:54 INFO : one: Copied (server-side copy) 2025/03/16 06:45:54 DEBUG : one: Destination found in --copy-dest, using server-side copy 2025/03/16 06:45:54 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu/dst': Waiting for transfers to finish 2025/03/16 06:45:54 DEBUG : Waiting for deletions to finish 2025/03/16 06:45:56 DEBUG : CopyDest/two: md5 = 9e9223abd9f70225a69a9175cd3ae9ec OK 2025/03/16 06:45:57 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2025/03/16 06:45:58 INFO : two: Copied (server-side copy) 2025/03/16 06:45:58 DEBUG : two: Destination found in --copy-dest, using server-side copy 2025/03/16 06:45:58 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu/dst': Waiting for checks to finish 2025/03/16 06:45:58 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2025/03/16 06:45:58 DEBUG : one: Unchanged skipping 2025/03/16 06:45:58 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu/dst': Waiting for transfers to finish 2025/03/16 06:45:58 DEBUG : Waiting for deletions to finish 2025/03/16 06:45:59 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2025/03/16 06:45:59 DEBUG : one: Unchanged skipping 2025/03/16 06:45:59 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2025/03/16 06:45:59 DEBUG : two: Unchanged skipping 2025/03/16 06:45:59 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu/dst': Waiting for checks to finish 2025/03/16 06:45:59 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu/dst': Waiting for transfers to finish 2025/03/16 06:45:59 DEBUG : Waiting for deletions to finish 2025/03/16 06:45:59 INFO : There was nothing to transfer 2025/03/16 06:46:01 DEBUG : CopyDest/three: md5 = b3786b7c85af07139690547ff2957aec OK 2025/03/16 06:46:02 DEBUG : three: Sizes differ (src 7 vs dst 5) 2025/03/16 06:46:02 DEBUG : three: Destination not found in --copy-dest 2025/03/16 06:46:02 DEBUG : three: Need to transfer - File not found at Destination 2025/03/16 06:46:02 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2025/03/16 06:46:02 DEBUG : one: Unchanged skipping 2025/03/16 06:46:02 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2025/03/16 06:46:02 DEBUG : two: Unchanged skipping 2025/03/16 06:46:02 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu/dst': Waiting for checks to finish 2025/03/16 06:46:02 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu/dst': Waiting for transfers to finish 2025/03/16 06:46:03 DEBUG : three: md5 = 1d949499e1ccd5e2e9e533331170ac76 OK 2025/03/16 06:46:03 INFO : three: Copied (new) 2025/03/16 06:46:03 DEBUG : Waiting for deletions to finish 2025/03/16 06:46:07 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "b6jdmn2b1adrhc8vikh7edr9os" 2025/03/16 06:46:07 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" 2025/03/16 06:46:07 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2025/03/16 06:46:08 DEBUG : d09o6po3f7bm6ce32vdgs8h9ls: Rmdir: contains trashed file: "b6jdmn2b1adrhc8vikh7edr9os" 2025/03/16 06:46:08 DEBUG : d09o6po3f7bm6ce32vdgs8h9ls: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" 2025/03/16 06:46:08 DEBUG : d09o6po3f7bm6ce32vdgs8h9ls: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2025/03/16 06:46:08 DEBUG : s6dbk3lfi7c9kfvo6j7bla9m0g: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" --- PASS: TestSyncCopyDest (31.59s) === RUN TestSyncBackupDir run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:46:11 DEBUG : dst/one: md5 = 7893874c1cfe21beb6140f5c3fc91184 OK 2025/03/16 06:46:12 DEBUG : dst/two: md5 = 54bcc2c8916a247bf9929855a71844f3 OK 2025/03/16 06:46:14 DEBUG : dst/three.txt: md5 = 952d6d6c6ebc47785d9d806b3e7b741c OK 2025/03/16 06:46:14 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-wixuyiv3lumu/dst" 2025/03/16 06:46:14 DEBUG : Creating backend with remote "TestDrive:crypt/n3ncf6nbor1b3s3vkpig0sf40id8nuidr6khhvfpotbv0gp72c00/31u3jie661vd5p8j7rtc3hgbh0" 2025/03/16 06:46:15 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-wixuyiv3lumu/backup" 2025/03/16 06:46:15 DEBUG : Creating backend with remote "TestDrive:crypt/n3ncf6nbor1b3s3vkpig0sf40id8nuidr6khhvfpotbv0gp72c00/1nrff024r7pq65ecp72fc28jb0" 2025/03/16 06:46:17 DEBUG : one: Sizes differ (src 4 vs dst 3) 2025/03/16 06:46:17 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/16 06:46:17 DEBUG : two: Unchanged skipping 2025/03/16 06:46:17 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu/dst': Waiting for checks to finish 2025/03/16 06:46:18 INFO : one: Moved (server-side) 2025/03/16 06:46:18 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu/dst': Waiting for transfers to finish 2025/03/16 06:46:19 DEBUG : one: md5 = 760b28e4ff42a8af824c915d2abb1731 OK 2025/03/16 06:46:19 INFO : one: Copied (new) 2025/03/16 06:46:19 DEBUG : Waiting for deletions to finish 2025/03/16 06:46:20 INFO : three.txt: Moved (server-side) 2025/03/16 06:46:20 INFO : three.txt: Moved into backup dir 2025/03/16 06:46:22 DEBUG : dst/three.txt: md5 = 02b217509b72f6ebdd50cfc85ed77411 OK 2025/03/16 06:46:23 DEBUG : one: Sizes differ (src 5 vs dst 4) 2025/03/16 06:46:23 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/16 06:46:23 DEBUG : two: Unchanged skipping 2025/03/16 06:46:23 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu/dst': Waiting for checks to finish 2025/03/16 06:46:23 INFO : one: Deleted 2025/03/16 06:46:24 INFO : one: Moved (server-side) 2025/03/16 06:46:24 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu/dst': Waiting for transfers to finish 2025/03/16 06:46:25 DEBUG : one: md5 = ac16b576f6a6b2f5d0b252598faf5fdb OK 2025/03/16 06:46:25 INFO : one: Copied (new) 2025/03/16 06:46:25 DEBUG : Waiting for deletions to finish 2025/03/16 06:46:26 INFO : three.txt: Deleted 2025/03/16 06:46:26 INFO : three.txt: Moved (server-side) 2025/03/16 06:46:26 INFO : three.txt: Moved into backup dir 2025/03/16 06:46:29 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2025/03/16 06:46:29 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" 2025/03/16 06:46:30 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2025/03/16 06:46:30 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "tr2hj63d80ftlmvm6a952snjcc" 2025/03/16 06:46:30 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "tr2hj63d80ftlmvm6a952snjcc" 2025/03/16 06:46:30 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" --- PASS: TestSyncBackupDir (21.43s) === RUN TestSyncBackupDirWithSuffix run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:46:33 DEBUG : dst/one: md5 = bdeca9536f8a4732e9ae19dd06fb281b OK 2025/03/16 06:46:34 DEBUG : dst/two: md5 = 9485f4c1591a17efb2f5cb4921f94c82 OK 2025/03/16 06:46:35 DEBUG : dst/three.txt: md5 = 34125ff7764b80fad94c87c5f6d0251d OK 2025/03/16 06:46:36 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-wixuyiv3lumu/dst" 2025/03/16 06:46:36 DEBUG : Creating backend with remote "TestDrive:crypt/n3ncf6nbor1b3s3vkpig0sf40id8nuidr6khhvfpotbv0gp72c00/31u3jie661vd5p8j7rtc3hgbh0" 2025/03/16 06:46:37 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-wixuyiv3lumu/backup" 2025/03/16 06:46:37 DEBUG : Creating backend with remote "TestDrive:crypt/n3ncf6nbor1b3s3vkpig0sf40id8nuidr6khhvfpotbv0gp72c00/1nrff024r7pq65ecp72fc28jb0" 2025/03/16 06:46:38 DEBUG : one: Sizes differ (src 4 vs dst 3) 2025/03/16 06:46:38 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/16 06:46:38 DEBUG : two: Unchanged skipping 2025/03/16 06:46:38 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu/dst': Waiting for checks to finish 2025/03/16 06:46:40 INFO : one: Moved (server-side) to: one.bak 2025/03/16 06:46:40 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu/dst': Waiting for transfers to finish 2025/03/16 06:46:41 DEBUG : one: md5 = 5e7fa8aa70f10a563eb97f8d1b1be688 OK 2025/03/16 06:46:41 INFO : one: Copied (new) 2025/03/16 06:46:41 DEBUG : Waiting for deletions to finish 2025/03/16 06:46:42 INFO : three.txt: Moved (server-side) to: three.txt.bak 2025/03/16 06:46:42 INFO : three.txt: Moved into backup dir 2025/03/16 06:46:44 DEBUG : dst/three.txt: md5 = c9a9ec0529ac9318ca8075962b183d91 OK 2025/03/16 06:46:44 DEBUG : one: Sizes differ (src 5 vs dst 4) 2025/03/16 06:46:44 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/16 06:46:44 DEBUG : two: Unchanged skipping 2025/03/16 06:46:44 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu/dst': Waiting for checks to finish 2025/03/16 06:46:45 INFO : one.bak: Deleted 2025/03/16 06:46:46 INFO : one: Moved (server-side) to: one.bak 2025/03/16 06:46:46 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu/dst': Waiting for transfers to finish 2025/03/16 06:46:47 DEBUG : one: md5 = 3766e97be2b8862a0377570b03f27cc5 OK 2025/03/16 06:46:47 INFO : one: Copied (new) 2025/03/16 06:46:47 DEBUG : Waiting for deletions to finish 2025/03/16 06:46:48 INFO : three.txt.bak: Deleted 2025/03/16 06:46:48 INFO : three.txt: Moved (server-side) to: three.txt.bak 2025/03/16 06:46:48 INFO : three.txt: Moved into backup dir 2025/03/16 06:46:51 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2025/03/16 06:46:51 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" 2025/03/16 06:46:52 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "qltcak2uaegtmcoa8vijdppbp8" 2025/03/16 06:46:52 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "sk91qgsqfn0r271r2ehsaoc20c" 2025/03/16 06:46:52 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "sk91qgsqfn0r271r2ehsaoc20c" 2025/03/16 06:46:52 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "qltcak2uaegtmcoa8vijdppbp8" --- PASS: TestSyncBackupDirWithSuffix (21.95s) === RUN TestSyncBackupDirWithSuffixKeepExtension run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:46:55 DEBUG : dst/one: md5 = 3720e7baa24770359ffbd6dce7f7b976 OK 2025/03/16 06:46:56 DEBUG : dst/two: md5 = d0b2e829ff7f9b4a1846c7d61880bfcc OK 2025/03/16 06:46:57 DEBUG : dst/three.txt: md5 = 0e5557f12d52abdb5e198c19d9ef08b4 OK 2025/03/16 06:46:58 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-wixuyiv3lumu/dst" 2025/03/16 06:46:58 DEBUG : Creating backend with remote "TestDrive:crypt/n3ncf6nbor1b3s3vkpig0sf40id8nuidr6khhvfpotbv0gp72c00/31u3jie661vd5p8j7rtc3hgbh0" 2025/03/16 06:46:58 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-wixuyiv3lumu/backup" 2025/03/16 06:46:58 DEBUG : Creating backend with remote "TestDrive:crypt/n3ncf6nbor1b3s3vkpig0sf40id8nuidr6khhvfpotbv0gp72c00/1nrff024r7pq65ecp72fc28jb0" 2025/03/16 06:47:00 DEBUG : one: Sizes differ (src 4 vs dst 3) 2025/03/16 06:47:00 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/16 06:47:00 DEBUG : two: Unchanged skipping 2025/03/16 06:47:00 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu/dst': Waiting for checks to finish 2025/03/16 06:47:02 INFO : one: Moved (server-side) to: one-2019-01-01 2025/03/16 06:47:02 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu/dst': Waiting for transfers to finish 2025/03/16 06:47:03 DEBUG : one: md5 = 9f0d4e2a41dcae391fb344216de09cd3 OK 2025/03/16 06:47:03 INFO : one: Copied (new) 2025/03/16 06:47:03 DEBUG : Waiting for deletions to finish 2025/03/16 06:47:04 INFO : three.txt: Moved (server-side) to: three-2019-01-01.txt 2025/03/16 06:47:04 INFO : three.txt: Moved into backup dir 2025/03/16 06:47:06 DEBUG : dst/three.txt: md5 = 2ed13ab382986c9e73151422a4fa535b OK 2025/03/16 06:47:07 DEBUG : one: Sizes differ (src 5 vs dst 4) 2025/03/16 06:47:07 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/16 06:47:07 DEBUG : two: Unchanged skipping 2025/03/16 06:47:07 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu/dst': Waiting for checks to finish 2025/03/16 06:47:07 INFO : one-2019-01-01: Deleted 2025/03/16 06:47:08 INFO : one: Moved (server-side) to: one-2019-01-01 2025/03/16 06:47:08 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu/dst': Waiting for transfers to finish 2025/03/16 06:47:09 DEBUG : one: md5 = e5c2faa02f7f4783abd4cd081e39bd3b OK 2025/03/16 06:47:09 INFO : one: Copied (new) 2025/03/16 06:47:09 DEBUG : Waiting for deletions to finish 2025/03/16 06:47:10 INFO : three-2019-01-01.txt: Deleted 2025/03/16 06:47:10 INFO : three.txt: Moved (server-side) to: three-2019-01-01.txt 2025/03/16 06:47:10 INFO : three.txt: Moved into backup dir 2025/03/16 06:47:13 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2025/03/16 06:47:13 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" 2025/03/16 06:47:14 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "jcjl1bv3ep0v8kt35lqql1co90" 2025/03/16 06:47:14 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "qtq2f6qq4lgpsmj88vb7147qje3prudmtfdtr2342fth58vo9a50" 2025/03/16 06:47:14 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "qtq2f6qq4lgpsmj88vb7147qje3prudmtfdtr2342fth58vo9a50" 2025/03/16 06:47:14 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "jcjl1bv3ep0v8kt35lqql1co90" --- PASS: TestSyncBackupDirWithSuffixKeepExtension (21.92s) === RUN TestSyncBackupDirSuffixOnly run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:47:16 DEBUG : dst/one: md5 = 05c8878d0c126dba22669e3076eadb08 OK 2025/03/16 06:47:18 DEBUG : dst/two: md5 = be62710be6be4d7e7827b1d5c0e9d14f OK 2025/03/16 06:47:19 DEBUG : dst/three.txt: md5 = e02f8c8ea55e18da8018e03bc4a34626 OK 2025/03/16 06:47:20 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-wixuyiv3lumu/dst" 2025/03/16 06:47:20 DEBUG : Creating backend with remote "TestDrive:crypt/n3ncf6nbor1b3s3vkpig0sf40id8nuidr6khhvfpotbv0gp72c00/31u3jie661vd5p8j7rtc3hgbh0" 2025/03/16 06:47:21 DEBUG : one: Sizes differ (src 4 vs dst 3) 2025/03/16 06:47:21 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/16 06:47:21 DEBUG : two: Unchanged skipping 2025/03/16 06:47:21 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu/dst': Waiting for checks to finish 2025/03/16 06:47:21 INFO : one: Moved (server-side) to: one.bak 2025/03/16 06:47:21 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu/dst': Waiting for transfers to finish 2025/03/16 06:47:23 DEBUG : one: md5 = cb14bef7ca5a480b7dd9448e2af4c80a OK 2025/03/16 06:47:23 INFO : one: Copied (new) 2025/03/16 06:47:23 DEBUG : Waiting for deletions to finish 2025/03/16 06:47:23 INFO : three.txt: Moved (server-side) to: three.txt.bak 2025/03/16 06:47:23 INFO : three.txt: Moved into backup dir 2025/03/16 06:47:25 DEBUG : dst/three.txt: md5 = ff992f513f9fac37f9a7d76e613b848a OK 2025/03/16 06:47:26 DEBUG : one.bak: Excluded (Path Filter) 2025/03/16 06:47:26 DEBUG : one.bak: Excluded 2025/03/16 06:47:26 DEBUG : three.txt.bak: Excluded (Path Filter) 2025/03/16 06:47:26 DEBUG : three.txt.bak: Excluded 2025/03/16 06:47:26 DEBUG : one: Sizes differ (src 5 vs dst 4) 2025/03/16 06:47:26 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/16 06:47:26 DEBUG : two: Unchanged skipping 2025/03/16 06:47:26 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu/dst': Waiting for checks to finish 2025/03/16 06:47:27 INFO : one.bak: Deleted 2025/03/16 06:47:27 INFO : one: Moved (server-side) to: one.bak 2025/03/16 06:47:27 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu/dst': Waiting for transfers to finish 2025/03/16 06:47:28 DEBUG : one: md5 = 5e0cfa84970eaf45446fa0998c77da61 OK 2025/03/16 06:47:28 INFO : one: Copied (new) 2025/03/16 06:47:28 DEBUG : Waiting for deletions to finish 2025/03/16 06:47:29 INFO : three.txt.bak: Deleted 2025/03/16 06:47:30 INFO : three.txt: Moved (server-side) to: three.txt.bak 2025/03/16 06:47:30 INFO : three.txt: Moved into backup dir 2025/03/16 06:47:33 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2025/03/16 06:47:33 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "sk91qgsqfn0r271r2ehsaoc20c" 2025/03/16 06:47:33 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "qltcak2uaegtmcoa8vijdppbp8" 2025/03/16 06:47:33 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "qltcak2uaegtmcoa8vijdppbp8" 2025/03/16 06:47:33 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" 2025/03/16 06:47:33 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "sk91qgsqfn0r271r2ehsaoc20c" --- PASS: TestSyncBackupDirSuffixOnly (18.92s) === RUN TestSyncSuffix run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:47:35 DEBUG : dst/one: md5 = b404bfd6f0693a6a9a40c7ba938e3e04 OK 2025/03/16 06:47:37 DEBUG : dst/two: md5 = f33560fc1ca1ab66c2348065dcb831f9 OK 2025/03/16 06:47:38 DEBUG : dst/three.txt: md5 = 18b48fefe640010d3dec5c984e2580b7 OK 2025/03/16 06:47:39 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-wixuyiv3lumu/dst" 2025/03/16 06:47:39 DEBUG : Creating backend with remote "TestDrive:crypt/n3ncf6nbor1b3s3vkpig0sf40id8nuidr6khhvfpotbv0gp72c00/31u3jie661vd5p8j7rtc3hgbh0" 2025/03/16 06:47:40 DEBUG : one: Sizes differ (src 4 vs dst 3) 2025/03/16 06:47:40 INFO : one: Moved (server-side) to: one.bak 2025/03/16 06:47:42 DEBUG : one: md5 = 44b57e827886b6d43ca607be49cbb1cc OK 2025/03/16 06:47:42 INFO : one: Copied (new) 2025/03/16 06:47:42 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/16 06:47:42 DEBUG : two: Unchanged skipping 2025/03/16 06:47:42 DEBUG : three.txt: Sizes differ (src 6 vs dst 5) 2025/03/16 06:47:43 INFO : three.txt: Moved (server-side) to: three.txt.bak 2025/03/16 06:47:44 DEBUG : three.txt: md5 = 95a92d882c094b7cf4fecc1991f415ff OK 2025/03/16 06:47:44 INFO : three.txt: Copied (new) 2025/03/16 06:47:45 DEBUG : one: Sizes differ (src 5 vs dst 4) 2025/03/16 06:47:46 INFO : one.bak: Deleted 2025/03/16 06:47:47 INFO : one: Moved (server-side) to: one.bak 2025/03/16 06:47:48 DEBUG : one: md5 = 9e807eb945dacd7ba24eda0a25a9b584 OK 2025/03/16 06:47:48 INFO : one: Copied (new) 2025/03/16 06:47:48 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/16 06:47:48 DEBUG : two: Unchanged skipping 2025/03/16 06:47:48 DEBUG : three.txt: Sizes differ (src 19 vs dst 6) 2025/03/16 06:47:49 INFO : three.txt.bak: Deleted 2025/03/16 06:47:49 INFO : three.txt: Moved (server-side) to: three.txt.bak 2025/03/16 06:47:51 DEBUG : three.txt: md5 = ce2cee724c24537192a15adce7346a87 OK 2025/03/16 06:47:51 INFO : three.txt: Copied (new) 2025/03/16 06:47:54 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2025/03/16 06:47:54 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "tr2hj63d80ftlmvm6a952snjcc" 2025/03/16 06:47:54 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "qltcak2uaegtmcoa8vijdppbp8" 2025/03/16 06:47:54 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "sk91qgsqfn0r271r2ehsaoc20c" 2025/03/16 06:47:54 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" 2025/03/16 06:47:54 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "sk91qgsqfn0r271r2ehsaoc20c" 2025/03/16 06:47:54 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "qltcak2uaegtmcoa8vijdppbp8" --- PASS: TestSyncSuffix (21.32s) === RUN TestSyncSuffixKeepExtension run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:47:57 DEBUG : dst/one: md5 = f51cf902802e9ba63c5fd3399fee7447 OK 2025/03/16 06:47:58 DEBUG : dst/two: md5 = 32408a1c20f951c0ece1c801cfcbabdd OK 2025/03/16 06:47:59 DEBUG : dst/three.txt: md5 = d3663b3caefdf3060eb488b8ee43b893 OK 2025/03/16 06:48:00 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-wixuyiv3lumu/dst" 2025/03/16 06:48:00 DEBUG : Creating backend with remote "TestDrive:crypt/n3ncf6nbor1b3s3vkpig0sf40id8nuidr6khhvfpotbv0gp72c00/31u3jie661vd5p8j7rtc3hgbh0" 2025/03/16 06:48:01 DEBUG : one: Sizes differ (src 4 vs dst 3) 2025/03/16 06:48:02 INFO : one: Moved (server-side) to: one-2019-01-01 2025/03/16 06:48:03 DEBUG : one: md5 = fba17e048a28d401be2f825972c44543 OK 2025/03/16 06:48:03 INFO : one: Copied (new) 2025/03/16 06:48:03 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/16 06:48:03 DEBUG : two: Unchanged skipping 2025/03/16 06:48:03 DEBUG : three.txt: Sizes differ (src 6 vs dst 5) 2025/03/16 06:48:04 INFO : three.txt: Moved (server-side) to: three-2019-01-01.txt 2025/03/16 06:48:05 DEBUG : three.txt: md5 = a2165abd1c029cfd3b9d0e088edd3013 OK 2025/03/16 06:48:05 INFO : three.txt: Copied (new) 2025/03/16 06:48:06 DEBUG : one: Sizes differ (src 5 vs dst 4) 2025/03/16 06:48:07 INFO : one-2019-01-01: Deleted 2025/03/16 06:48:07 INFO : one: Moved (server-side) to: one-2019-01-01 2025/03/16 06:48:09 DEBUG : one: md5 = f4bfa9f7219ae901c2c4dcd8eb004362 OK 2025/03/16 06:48:09 INFO : one: Copied (new) 2025/03/16 06:48:09 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/16 06:48:09 DEBUG : two: Unchanged skipping 2025/03/16 06:48:09 DEBUG : three.txt: Sizes differ (src 19 vs dst 6) 2025/03/16 06:48:10 INFO : three-2019-01-01.txt: Deleted 2025/03/16 06:48:10 INFO : three.txt: Moved (server-side) to: three-2019-01-01.txt 2025/03/16 06:48:12 DEBUG : three.txt: md5 = ad880ee6b8ab363faf4adcfbaefd061c OK 2025/03/16 06:48:12 INFO : three.txt: Copied (new) 2025/03/16 06:48:15 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2025/03/16 06:48:15 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "tr2hj63d80ftlmvm6a952snjcc" 2025/03/16 06:48:15 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "jcjl1bv3ep0v8kt35lqql1co90" 2025/03/16 06:48:15 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "jcjl1bv3ep0v8kt35lqql1co90" 2025/03/16 06:48:15 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "qtq2f6qq4lgpsmj88vb7147qje3prudmtfdtr2342fth58vo9a50" 2025/03/16 06:48:15 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "qtq2f6qq4lgpsmj88vb7147qje3prudmtfdtr2342fth58vo9a50" 2025/03/16 06:48:15 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" --- PASS: TestSyncSuffixKeepExtension (21.05s) === RUN TestSyncUTFNorm run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:48:17 DEBUG : Testêé: md5 = f674512cc84089794d5730e0c6146373 OK 2025/03/16 06:48:18 DEBUG : Testêé: Sizes differ (src 14 vs dst 18) 2025/03/16 06:48:18 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for checks to finish 2025/03/16 06:48:18 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for transfers to finish 2025/03/16 06:48:19 DEBUG : Testêé: md5 = 1b90a70ec856bbc1f6efb1c1740f78d8 OK 2025/03/16 06:48:19 INFO : Testêé: Copied (replaced existing) to: Testêé 2025/03/16 06:48:19 DEBUG : Waiting for deletions to finish --- PASS: TestSyncUTFNorm (4.24s) === RUN TestSyncImmutable run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:48:20 DEBUG : existing: Need to transfer - File not found at Destination 2025/03/16 06:48:20 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for checks to finish 2025/03/16 06:48:20 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for transfers to finish 2025/03/16 06:48:22 DEBUG : existing: md5 = ea01e5ad995dfea686317f37c795d0a5 OK 2025/03/16 06:48:22 INFO : existing: Copied (new) 2025/03/16 06:48:22 DEBUG : Waiting for deletions to finish run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:48:22 DEBUG : existing: Sizes differ (src 8 vs dst 6) 2025/03/16 06:48:22 ERROR : existing: Source and destination exist but do not match: immutable file modified 2025/03/16 06:48:22 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for checks to finish 2025/03/16 06:48:22 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for transfers to finish 2025/03/16 06:48:22 ERROR : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': not deleting files as there were IO errors 2025/03/16 06:48:22 ERROR : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': not deleting directories as there were IO errors run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" --- PASS: TestSyncImmutable (4.53s) === RUN TestSyncIgnoreCase run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:48:26 DEBUG : EXISTING: md5 = a783edaac161deefb394e957ba1f7ffc OK 2025/03/16 06:48:26 DEBUG : existing: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/16 06:48:26 DEBUG : existing: Unchanged skipping 2025/03/16 06:48:26 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for checks to finish 2025/03/16 06:48:26 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for transfers to finish 2025/03/16 06:48:26 DEBUG : Waiting for deletions to finish 2025/03/16 06:48:26 INFO : There was nothing to transfer --- PASS: TestSyncIgnoreCase (2.93s) === RUN TestFixCase run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" sync_test.go:2635: Skipping test as local or remote are case-sensitive --- SKIP: TestFixCase (0.48s) === RUN TestMaxTransfer === RUN TestMaxTransfer/Hard run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" sync_test.go:2674: This test only runs on local === RUN TestMaxTransfer/Soft run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" sync_test.go:2674: This test only runs on local === RUN TestMaxTransfer/Cautious run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" sync_test.go:2674: This test only runs on local --- PASS: TestMaxTransfer (1.33s) --- SKIP: TestMaxTransfer/Hard (0.44s) --- SKIP: TestMaxTransfer/Soft (0.45s) --- SKIP: TestMaxTransfer/Cautious (0.44s) === RUN TestSyncConcurrentDelete run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:48:31 DEBUG : both0: md5 = 14bbae09bf094d1dfff8ca698ca1dfbf OK 2025/03/16 06:48:32 DEBUG : only0: md5 = 4972216a401f312cfc74eecd35cc80fd OK 2025/03/16 06:48:33 DEBUG : both1: md5 = 36b1df697e3cc079f36ee24953e144c8 OK 2025/03/16 06:48:34 DEBUG : only1: md5 = 1c5a41de006dfba317bb30d14d878220 OK 2025/03/16 06:48:36 DEBUG : both2: md5 = 05750450e82453b40ea2c5f4b9c2e8a0 OK 2025/03/16 06:48:37 DEBUG : only2: md5 = f3521fa02bc329eb528ee590308c98ce OK 2025/03/16 06:48:38 DEBUG : both3: md5 = b1ec360846b7a1dd03c13ada128acf75 OK 2025/03/16 06:48:40 DEBUG : only3: md5 = 40341a732a36c6e15c8c0fe7ffec3e70 OK 2025/03/16 06:48:41 DEBUG : both4: md5 = 09fcfc76087c48ebcf70a449558f6a43 OK 2025/03/16 06:48:42 DEBUG : only4: md5 = 5f9ae366e200beae4d3c6c89db0e2d5e OK 2025/03/16 06:48:44 DEBUG : both5: md5 = df5e09efce93f33e790e799348da4004 OK 2025/03/16 06:48:45 DEBUG : only5: md5 = 4aface996165d50ea1e7334abb031266 OK 2025/03/16 06:48:46 DEBUG : both6: md5 = 49a8ab17a831797f6dbef0f6d23988bf OK 2025/03/16 06:48:48 DEBUG : only6: md5 = 3b93a63cb4484def15338ed7afba3e2b OK 2025/03/16 06:48:49 DEBUG : both7: md5 = 3b6c1cf14695fb217aa2a721d2aa25a1 OK 2025/03/16 06:48:51 DEBUG : only7: md5 = cd0380289ee5f5b12180e46296984d1f OK 2025/03/16 06:48:52 DEBUG : both8: md5 = 2fb8356c96ba392ab0c819db865d00f4 OK 2025/03/16 06:48:53 DEBUG : only8: md5 = e577187dedfc21f6b239efe4fa39b84c OK 2025/03/16 06:48:55 DEBUG : both9: md5 = e61da8f36bbdaf3b1393e4301a6dd351 OK 2025/03/16 06:48:56 DEBUG : only9: md5 = f979f8ee5f8c7f5cfa049c5d072fd787 OK 2025/03/16 06:48:57 DEBUG : both10: md5 = f5c6e9edb9baee81d62f3060a8ef9be1 OK 2025/03/16 06:48:59 DEBUG : only10: md5 = 0ac85fb414b783620b73ef100e5f2c9b OK 2025/03/16 06:49:00 DEBUG : both11: md5 = 0723acc429eb54b84e32a76c52e10cad OK 2025/03/16 06:49:01 DEBUG : only11: md5 = b0f54a98aaded3b3c721f1ae11dd6bf2 OK 2025/03/16 06:49:03 DEBUG : both12: md5 = 08e2b6750a6b24a0d923f97c63920f49 OK 2025/03/16 06:49:04 DEBUG : only12: md5 = e96df92c420a5978820a0f78f270ae6c OK 2025/03/16 06:49:05 DEBUG : both13: md5 = 0dfacb1108ac396dae87faa623a399ae OK 2025/03/16 06:49:06 DEBUG : only13: md5 = 1436725ede5ccd4c541f87d66bc2496c OK 2025/03/16 06:49:08 DEBUG : both14: md5 = 1bd966757d04966e68302ac4b50b3c33 OK 2025/03/16 06:49:09 DEBUG : only14: md5 = 3e0035729ab24f44eb5ed99c732f73a8 OK 2025/03/16 06:49:10 DEBUG : both15: md5 = 0ee175086a4dec23479e35df6e9289e0 OK 2025/03/16 06:49:12 DEBUG : only15: md5 = 0f2f9e9b74a4e4454d1af2e5fdc6e963 OK 2025/03/16 06:49:13 DEBUG : both16: md5 = 5a36ee2f46fb82a2e81e529537ff34be OK 2025/03/16 06:49:14 DEBUG : only16: md5 = 17062d65ae6a044c6f1ca104ab253644 OK 2025/03/16 06:49:16 DEBUG : both17: md5 = bdddb43d2e784b4222f85c8fb9d82416 OK 2025/03/16 06:49:17 DEBUG : only17: md5 = d54ae1c4b2409c93a450f19b53f17f4b OK 2025/03/16 06:49:18 DEBUG : both18: md5 = c77a0cf4e3a70bfff9fef5c2ed85464f OK 2025/03/16 06:49:20 DEBUG : only18: md5 = b828108fc573ae1af9594f528ff05982 OK 2025/03/16 06:49:21 DEBUG : both19: md5 = 099e9186d70dd85871dd1898d6989dd8 OK 2025/03/16 06:49:22 DEBUG : only19: md5 = c30cdffd97e4be1f29b5944b688dffaf OK 2025/03/16 06:49:23 DEBUG : both0: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/16 06:49:23 DEBUG : both0: Unchanged skipping 2025/03/16 06:49:23 DEBUG : both1: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/16 06:49:23 DEBUG : both1: Unchanged skipping 2025/03/16 06:49:23 DEBUG : both10: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/16 06:49:23 DEBUG : both10: Unchanged skipping 2025/03/16 06:49:23 DEBUG : both11: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/16 06:49:23 DEBUG : both11: Unchanged skipping 2025/03/16 06:49:23 DEBUG : both12: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/16 06:49:23 DEBUG : both12: Unchanged skipping 2025/03/16 06:49:23 DEBUG : both13: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/16 06:49:23 DEBUG : both13: Unchanged skipping 2025/03/16 06:49:23 DEBUG : both14: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/16 06:49:23 DEBUG : both14: Unchanged skipping 2025/03/16 06:49:23 DEBUG : both15: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/16 06:49:23 DEBUG : both15: Unchanged skipping 2025/03/16 06:49:23 DEBUG : both16: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/16 06:49:23 DEBUG : both16: Unchanged skipping 2025/03/16 06:49:23 DEBUG : both17: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/16 06:49:23 DEBUG : both17: Unchanged skipping 2025/03/16 06:49:23 DEBUG : both18: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/16 06:49:23 DEBUG : both18: Unchanged skipping 2025/03/16 06:49:23 DEBUG : both19: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/16 06:49:23 DEBUG : both19: Unchanged skipping 2025/03/16 06:49:23 DEBUG : both2: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/16 06:49:23 DEBUG : both2: Unchanged skipping 2025/03/16 06:49:23 DEBUG : both3: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/16 06:49:23 DEBUG : both3: Unchanged skipping 2025/03/16 06:49:23 DEBUG : both4: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/16 06:49:23 DEBUG : both4: Unchanged skipping 2025/03/16 06:49:23 DEBUG : both5: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/16 06:49:23 DEBUG : both5: Unchanged skipping 2025/03/16 06:49:23 DEBUG : both6: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/16 06:49:23 DEBUG : both6: Unchanged skipping 2025/03/16 06:49:23 DEBUG : both7: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/16 06:49:23 DEBUG : both7: Unchanged skipping 2025/03/16 06:49:23 DEBUG : both8: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/16 06:49:23 DEBUG : both8: Unchanged skipping 2025/03/16 06:49:23 DEBUG : both9: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/16 06:49:23 DEBUG : both9: Unchanged skipping 2025/03/16 06:49:23 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for checks to finish 2025/03/16 06:49:23 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for transfers to finish 2025/03/16 06:49:23 DEBUG : Waiting for deletions to finish 2025/03/16 06:49:23 INFO : only11: Deleted 2025/03/16 06:49:23 INFO : only0: Deleted 2025/03/16 06:49:23 INFO : only5: Deleted 2025/03/16 06:49:24 INFO : only3: Deleted 2025/03/16 06:49:24 INFO : only7: Deleted 2025/03/16 06:49:24 INFO : only9: Deleted 2025/03/16 06:49:24 INFO : only10: Deleted 2025/03/16 06:49:24 INFO : only15: Deleted 2025/03/16 06:49:24 INFO : only2: Deleted 2025/03/16 06:49:24 INFO : only18: Deleted 2025/03/16 06:49:24 INFO : only1: Deleted 2025/03/16 06:49:24 INFO : only12: Deleted 2025/03/16 06:49:25 INFO : only17: Deleted 2025/03/16 06:49:25 INFO : only8: Deleted 2025/03/16 06:49:25 INFO : only13: Deleted 2025/03/16 06:49:25 INFO : only14: Deleted 2025/03/16 06:49:25 INFO : only16: Deleted 2025/03/16 06:49:25 INFO : only19: Deleted 2025/03/16 06:49:25 INFO : only6: Deleted 2025/03/16 06:49:25 INFO : only4: Deleted 2025/03/16 06:49:25 INFO : There was nothing to transfer run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" --- PASS: TestSyncConcurrentDelete (65.91s) === RUN TestSyncConcurrentTruncate run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:49:36 DEBUG : both0: md5 = 8246b1663f872106748265e0e948fdd5 OK 2025/03/16 06:49:38 DEBUG : only0: md5 = 53f055572876f7c9e32306b9173e8256 OK 2025/03/16 06:49:39 DEBUG : both1: md5 = 346847b914594fbc576109bb91378b67 OK 2025/03/16 06:49:40 DEBUG : only1: md5 = ddf03e1d93a2416219dc6db13983c56f OK 2025/03/16 06:49:42 DEBUG : both2: md5 = ee049e68bd79e795d1b02b3e196f2447 OK 2025/03/16 06:49:43 DEBUG : only2: md5 = 127ef0e0e2bbcfdd14e5e93926748a83 OK 2025/03/16 06:49:44 DEBUG : both3: md5 = ed330f4d98d9bb3dc9f315a1b0a05375 OK 2025/03/16 06:49:46 DEBUG : only3: md5 = ffd7120cb0e316cf53a333290e02dc3b OK 2025/03/16 06:49:47 DEBUG : both4: md5 = c12393b6a07b47f14a52c1117cc4c052 OK 2025/03/16 06:49:48 DEBUG : only4: md5 = cf12fd7dced51b27f36916c68cebf340 OK 2025/03/16 06:49:50 DEBUG : both5: md5 = 968aed8bf7c4b57fe8b646cf7e1a0f95 OK 2025/03/16 06:49:51 DEBUG : only5: md5 = 9982136d35822fa83028b032366565d3 OK 2025/03/16 06:49:52 DEBUG : both6: md5 = 737b0d3018cda5777f766122676879f1 OK 2025/03/16 06:49:54 DEBUG : only6: md5 = b36c82ebff64e0d3baf4de0c85e95804 OK 2025/03/16 06:49:55 DEBUG : both7: md5 = 66cb1f17a2b3114ec2080011d7c9473c OK 2025/03/16 06:49:56 DEBUG : only7: md5 = a69c3afe0bf47d78e6b9b3132461b377 OK 2025/03/16 06:49:58 DEBUG : both8: md5 = 0c8210f91b251801bc57c0f6599deba2 OK 2025/03/16 06:49:59 DEBUG : only8: md5 = 6573f1204921b050099f1c5ceaec9d46 OK 2025/03/16 06:50:01 DEBUG : both9: md5 = 8fa975a698b8d67cd06dc2e8d22c8ed9 OK 2025/03/16 06:50:02 DEBUG : only9: md5 = 313e8301f18be1b1310779b93051e717 OK 2025/03/16 06:50:03 DEBUG : both10: md5 = 6d35c0d052ddc5a908d27329ac01a9f7 OK 2025/03/16 06:50:04 DEBUG : only10: md5 = 57cd9771fc5080f952314870943f4ba9 OK 2025/03/16 06:50:06 DEBUG : both11: md5 = cff97135cefc10f27a491b9bd85a6e3c OK 2025/03/16 06:50:07 DEBUG : only11: md5 = 69fd47ab19b3791900d82ba7c698a008 OK 2025/03/16 06:50:08 DEBUG : both12: md5 = e2731a5223664e6dd3fb6d5026ccd68e OK 2025/03/16 06:50:10 DEBUG : only12: md5 = 5351b3c7328affdc0f8743fce1f00435 OK 2025/03/16 06:50:11 DEBUG : both13: md5 = 5bd1e292fda62cba84c623cab5aceb59 OK 2025/03/16 06:50:12 DEBUG : only13: md5 = 0316131d77b02d133b7ceea37221d75c OK 2025/03/16 06:50:14 DEBUG : both14: md5 = 3f78ba892d0460702d26489eddb184ec OK 2025/03/16 06:50:15 DEBUG : only14: md5 = c55bc6a2e90fd6da8cea96038b3fbab3 OK 2025/03/16 06:50:16 DEBUG : both15: md5 = 3ef4fb048960e0e12239186271294a0c OK 2025/03/16 06:50:18 DEBUG : only15: md5 = b55538e199964bcaaa351918ba49dc3d OK 2025/03/16 06:50:19 DEBUG : both16: md5 = 429ad67387629c271ef6a9d908d02497 OK 2025/03/16 06:50:21 DEBUG : only16: md5 = 6493d27457605df8f42e29cfaf3c238d OK 2025/03/16 06:50:22 DEBUG : both17: md5 = 0dcadddd40f17b2c1f7d8cf9dfbd8915 OK 2025/03/16 06:50:23 DEBUG : only17: md5 = 1d5c22cfe70ef3c52be017633cc0f048 OK 2025/03/16 06:50:25 DEBUG : both18: md5 = 5b80e9b55fde2e2ecb6c312d85237dcf OK 2025/03/16 06:50:26 DEBUG : only18: md5 = 0396884dd2908261d4d6c680bb8fe7f9 OK 2025/03/16 06:50:27 DEBUG : both19: md5 = aaf398bb826b5a45685e7b20326913ca OK 2025/03/16 06:50:29 DEBUG : only19: md5 = fad8224c842331686bb53c770b814359 OK 2025/03/16 06:50:29 DEBUG : both0: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/16 06:50:29 DEBUG : both1: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/16 06:50:29 DEBUG : both10: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/16 06:50:29 DEBUG : both11: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/16 06:50:29 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for checks to finish 2025/03/16 06:50:29 DEBUG : both0: Unchanged skipping 2025/03/16 06:50:29 DEBUG : both12: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/16 06:50:29 DEBUG : both12: Unchanged skipping 2025/03/16 06:50:29 DEBUG : both13: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/16 06:50:29 DEBUG : both13: Unchanged skipping 2025/03/16 06:50:29 DEBUG : both14: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/16 06:50:29 DEBUG : both14: Unchanged skipping 2025/03/16 06:50:29 DEBUG : both15: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/16 06:50:29 DEBUG : both15: Unchanged skipping 2025/03/16 06:50:29 DEBUG : both16: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/16 06:50:29 DEBUG : both16: Unchanged skipping 2025/03/16 06:50:29 DEBUG : both17: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/16 06:50:29 DEBUG : both17: Unchanged skipping 2025/03/16 06:50:29 DEBUG : both18: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/16 06:50:29 DEBUG : both18: Unchanged skipping 2025/03/16 06:50:29 DEBUG : both19: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/16 06:50:29 DEBUG : both19: Unchanged skipping 2025/03/16 06:50:29 DEBUG : both2: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/16 06:50:29 DEBUG : both2: Unchanged skipping 2025/03/16 06:50:29 DEBUG : both3: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/16 06:50:29 DEBUG : both3: Unchanged skipping 2025/03/16 06:50:29 DEBUG : both4: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/16 06:50:29 DEBUG : both4: Unchanged skipping 2025/03/16 06:50:29 DEBUG : both5: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/16 06:50:29 DEBUG : both5: Unchanged skipping 2025/03/16 06:50:29 DEBUG : both6: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/16 06:50:29 DEBUG : both6: Unchanged skipping 2025/03/16 06:50:29 DEBUG : both7: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/16 06:50:29 DEBUG : both7: Unchanged skipping 2025/03/16 06:50:29 DEBUG : both8: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/16 06:50:29 DEBUG : both8: Unchanged skipping 2025/03/16 06:50:29 DEBUG : both9: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/16 06:50:29 DEBUG : both9: Unchanged skipping 2025/03/16 06:50:29 DEBUG : only0: Sizes differ (src 0 vs dst 6) 2025/03/16 06:50:29 DEBUG : only1: Sizes differ (src 0 vs dst 6) 2025/03/16 06:50:29 DEBUG : only10: Sizes differ (src 0 vs dst 6) 2025/03/16 06:50:29 DEBUG : only11: Sizes differ (src 0 vs dst 6) 2025/03/16 06:50:29 DEBUG : only12: Sizes differ (src 0 vs dst 6) 2025/03/16 06:50:29 DEBUG : only13: Sizes differ (src 0 vs dst 6) 2025/03/16 06:50:29 DEBUG : only14: Sizes differ (src 0 vs dst 6) 2025/03/16 06:50:29 DEBUG : only15: Sizes differ (src 0 vs dst 6) 2025/03/16 06:50:29 DEBUG : only16: Sizes differ (src 0 vs dst 6) 2025/03/16 06:50:29 DEBUG : only17: Sizes differ (src 0 vs dst 6) 2025/03/16 06:50:29 DEBUG : only18: Sizes differ (src 0 vs dst 6) 2025/03/16 06:50:29 DEBUG : only19: Sizes differ (src 0 vs dst 6) 2025/03/16 06:50:29 DEBUG : only2: Sizes differ (src 0 vs dst 6) 2025/03/16 06:50:29 DEBUG : only3: Sizes differ (src 0 vs dst 6) 2025/03/16 06:50:29 DEBUG : only4: Sizes differ (src 0 vs dst 6) 2025/03/16 06:50:29 DEBUG : only5: Sizes differ (src 0 vs dst 6) 2025/03/16 06:50:29 DEBUG : only6: Sizes differ (src 0 vs dst 6) 2025/03/16 06:50:29 DEBUG : only7: Sizes differ (src 0 vs dst 6) 2025/03/16 06:50:29 DEBUG : only8: Sizes differ (src 0 vs dst 6) 2025/03/16 06:50:29 DEBUG : only9: Sizes differ (src 0 vs dst 6) 2025/03/16 06:50:29 DEBUG : both1: Unchanged skipping 2025/03/16 06:50:29 DEBUG : both10: Unchanged skipping 2025/03/16 06:50:29 DEBUG : both11: Unchanged skipping 2025/03/16 06:50:29 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Waiting for transfers to finish 2025/03/16 06:50:30 DEBUG : only10: md5 = 17a3797ee2fa742ee50832a52492fa0d OK 2025/03/16 06:50:30 INFO : only10: Copied (replaced existing) 2025/03/16 06:50:30 DEBUG : only0: md5 = 9c9dbea3e50cf40d147a523e5fc7ed47 OK 2025/03/16 06:50:30 INFO : only0: Copied (replaced existing) 2025/03/16 06:50:30 DEBUG : only11: md5 = 6a91d745872b430e36fc14c8e0bdcc96 OK 2025/03/16 06:50:30 INFO : only11: Copied (replaced existing) 2025/03/16 06:50:30 DEBUG : only1: md5 = 0e25bde7875b027b936ca784738627b3 OK 2025/03/16 06:50:30 INFO : only1: Copied (replaced existing) 2025/03/16 06:50:31 DEBUG : only12: md5 = c5e45370590e3669dcdf19b4c42737e7 OK 2025/03/16 06:50:31 INFO : only12: Copied (replaced existing) 2025/03/16 06:50:32 DEBUG : only14: md5 = 0ab29d7388400beea5cab315e3b7b843 OK 2025/03/16 06:50:32 INFO : only14: Copied (replaced existing) 2025/03/16 06:50:32 DEBUG : only13: md5 = 4c4f947180d7c70ae3a7228457e1b0a9 OK 2025/03/16 06:50:32 INFO : only13: Copied (replaced existing) 2025/03/16 06:50:32 DEBUG : only15: md5 = 4a432422d5bab4329f32aef5ede57c6e OK 2025/03/16 06:50:32 INFO : only15: Copied (replaced existing) 2025/03/16 06:50:32 DEBUG : only16: md5 = cc839c17a8ff4132582376a573dfdb42 OK 2025/03/16 06:50:32 INFO : only16: Copied (replaced existing) 2025/03/16 06:50:33 DEBUG : only18: md5 = 516c5f352bb1ae85a648196487eaed63 OK 2025/03/16 06:50:33 INFO : only18: Copied (replaced existing) 2025/03/16 06:50:33 DEBUG : only17: md5 = 6c11421970b1bcac0ebded5726441af1 OK 2025/03/16 06:50:33 INFO : only17: Copied (replaced existing) 2025/03/16 06:50:33 DEBUG : only19: md5 = 2e38cb1985587f215396cac5a5019b18 OK 2025/03/16 06:50:33 INFO : only19: Copied (replaced existing) 2025/03/16 06:50:33 DEBUG : only2: md5 = b1f9d13c3e9455dec564e278ccd18598 OK 2025/03/16 06:50:33 INFO : only2: Copied (replaced existing) 2025/03/16 06:50:34 DEBUG : only3: md5 = a9c8e37bf80dfd3cadb1d4926deedea2 OK 2025/03/16 06:50:34 INFO : only3: Copied (replaced existing) 2025/03/16 06:50:34 DEBUG : only5: md5 = 8948647179dbbf845099362f46d5cf77 OK 2025/03/16 06:50:34 INFO : only5: Copied (replaced existing) 2025/03/16 06:50:34 DEBUG : only4: md5 = 807c5b9e0c1c2a7324fe690583a8e0d8 OK 2025/03/16 06:50:34 INFO : only4: Copied (replaced existing) 2025/03/16 06:50:34 DEBUG : only6: md5 = f88b59b2d57e612976dfc97dda8301d1 OK 2025/03/16 06:50:34 INFO : only6: Copied (replaced existing) 2025/03/16 06:50:35 DEBUG : only7: md5 = a1ab672b99abf123621023e713ece4e9 OK 2025/03/16 06:50:35 INFO : only7: Copied (replaced existing) 2025/03/16 06:50:35 DEBUG : only9: md5 = d2ef988d2301981d1101f0b3b9b2077b OK 2025/03/16 06:50:35 INFO : only9: Copied (replaced existing) 2025/03/16 06:50:35 DEBUG : only8: md5 = 0b4860528932aaabfab85d8b2ddd74d6 OK 2025/03/16 06:50:35 INFO : only8: Copied (replaced existing) 2025/03/16 06:50:35 DEBUG : Waiting for deletions to finish run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" --- PASS: TestSyncConcurrentTruncate (78.51s) === RUN TestSyncReplaceDirModTime run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:50:54 DEBUG : empty_dir: Making directory with metadata 2025/03/16 06:50:54 INFO : empty_dir: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z) 2025/03/16 06:50:54 DEBUG : empty_on_remote: Making directory with metadata 2025/03/16 06:50:54 INFO : empty_on_remote: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z) 2025/03/16 06:50:54 DEBUG : empty_on_remote: Making directory with metadata 2025/03/16 06:50:54 INFO : empty_on_remote: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z) run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:50:59 INFO : test_dir1: Set directory modification time (using DirSetModTime) 2025/03/16 06:50:59 INFO : test_dir2: Set directory modification time (using DirSetModTime) 2025/03/16 06:50:59 INFO : test_dir2/sub_dir: Set directory modification time (using DirSetModTime) 2025/03/16 06:50:59 INFO : empty_on_remote: Set directory modification time (using DirSetModTime) run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:51:06 DEBUG : heqj02jg0dcqlem7gl0500bvp0/24g2k8bseitblkmqnie1ibl2s8: Rmdir: contains trashed file: "633fmaa0qic3kv3cladnu11pto" 2025/03/16 06:51:06 DEBUG : heqj02jg0dcqlem7gl0500bvp0: Rmdir: contains trashed file: "24g2k8bseitblkmqnie1ibl2s8" 2025/03/16 06:51:07 DEBUG : gq68srrpl0nnf394bgf7dbu9kc: Rmdir: contains trashed file: "d26uovf0miqhd1mu3c9jbseq00" --- PASS: TestSyncReplaceDirModTime (15.50s) === RUN TestSyncReplaceDirModTimeWithEmptyDirs run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:51:09 DEBUG : empty_dir: Making directory with metadata 2025/03/16 06:51:09 INFO : empty_dir: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z) 2025/03/16 06:51:09 DEBUG : empty_on_remote: Making directory with metadata 2025/03/16 06:51:09 INFO : empty_on_remote: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z) 2025/03/16 06:51:09 DEBUG : empty_on_remote: Making directory with metadata 2025/03/16 06:51:10 INFO : empty_on_remote: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z) run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:51:14 INFO : test_dir1: Set directory modification time (using DirSetModTime) 2025/03/16 06:51:14 INFO : test_dir2: Set directory modification time (using DirSetModTime) 2025/03/16 06:51:14 INFO : test_dir2/sub_dir: Set directory modification time (using DirSetModTime) 2025/03/16 06:51:14 INFO : empty_on_remote: Set directory modification time (using DirSetModTime) 2025/03/16 06:51:14 INFO : empty_dir: Set directory modification time (using DirSetModTime) run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:51:22 DEBUG : heqj02jg0dcqlem7gl0500bvp0/24g2k8bseitblkmqnie1ibl2s8: Rmdir: contains trashed file: "633fmaa0qic3kv3cladnu11pto" 2025/03/16 06:51:22 DEBUG : heqj02jg0dcqlem7gl0500bvp0: Rmdir: contains trashed file: "24g2k8bseitblkmqnie1ibl2s8" 2025/03/16 06:51:23 DEBUG : gq68srrpl0nnf394bgf7dbu9kc: Rmdir: contains trashed file: "d26uovf0miqhd1mu3c9jbseq00" --- PASS: TestSyncReplaceDirModTimeWithEmptyDirs (16.75s) === RUN TestNothingToTransferWithEmptyDirs run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:51:26 INFO : sub dir: Set directory modification time (using DirSetModTime) 2025/03/16 06:51:26 DEBUG : sub dir: Making directory with metadata 2025/03/16 06:51:27 INFO : sub dir: Made directory with metadata (mtime=2011-12-30T12:59:59Z) run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:51:43 INFO : sub dir2: Set directory modification time (using DirSetModTime) 2025/03/16 06:51:44 INFO : sub dir2: Set directory modification time (using DirSetModTime) 2025/03/16 06:51:44 INFO : sub dirEmpty/sub dirEmpty2: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z) 2025/03/16 06:51:44 INFO : sub dirEmpty: Set directory modification time (using DirSetModTime) run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:51:55 DEBUG : gcsdkq814sbtppue42dpsbg8ug: Rmdir: contains trashed file: "sjuo65gk5q3r1199jselk9k9o0" 2025/03/16 06:51:56 DEBUG : s0tvtpcbgsp8ufdmedqtvlq3hc/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak/37qp6d1gohacv723ij3brofbu8/i24n0ln37pa2hv8pctddeuh73o: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" 2025/03/16 06:51:57 DEBUG : s0tvtpcbgsp8ufdmedqtvlq3hc/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak/37qp6d1gohacv723ij3brofbu8: Rmdir: contains trashed file: "i24n0ln37pa2hv8pctddeuh73o" 2025/03/16 06:51:57 DEBUG : s0tvtpcbgsp8ufdmedqtvlq3hc/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak: Rmdir: contains trashed file: "37qp6d1gohacv723ij3brofbu8" 2025/03/16 06:51:58 DEBUG : s0tvtpcbgsp8ufdmedqtvlq3hc/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak: Rmdir: contains trashed file: "jefmjbgpu25gb7gcub4i80nlak" 2025/03/16 06:51:59 DEBUG : s0tvtpcbgsp8ufdmedqtvlq3hc/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak: Rmdir: contains trashed file: "jefmjbgpu25gb7gcub4i80nlak" 2025/03/16 06:51:59 DEBUG : s0tvtpcbgsp8ufdmedqtvlq3hc/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak: Rmdir: contains trashed file: "jefmjbgpu25gb7gcub4i80nlak" 2025/03/16 06:52:00 DEBUG : s0tvtpcbgsp8ufdmedqtvlq3hc/jefmjbgpu25gb7gcub4i80nlak: Rmdir: contains trashed file: "jefmjbgpu25gb7gcub4i80nlak" 2025/03/16 06:52:01 DEBUG : s0tvtpcbgsp8ufdmedqtvlq3hc/4r13oncfa2rsrr82oqhsqv24ns: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" 2025/03/16 06:52:01 DEBUG : s0tvtpcbgsp8ufdmedqtvlq3hc: Rmdir: contains trashed file: "4r13oncfa2rsrr82oqhsqv24ns" 2025/03/16 06:52:01 DEBUG : s0tvtpcbgsp8ufdmedqtvlq3hc: Rmdir: contains trashed file: "jefmjbgpu25gb7gcub4i80nlak" 2025/03/16 06:52:02 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestNothingToTransferWithEmptyDirs (38.07s) === RUN TestNothingToTransferWithoutEmptyDirs run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:52:04 INFO : sub dir: Set directory modification time (using DirSetModTime) 2025/03/16 06:52:04 DEBUG : sub dir: Making directory with metadata 2025/03/16 06:52:05 INFO : sub dir: Made directory with metadata (mtime=2011-12-30T12:59:59Z) run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:52:26 INFO : sub dir2: Set directory modification time (using DirSetModTime) 2025/03/16 06:52:26 INFO : sub dir2: Set directory modification time (using DirSetModTime) 2025/03/16 06:52:26 INFO : sub dirEmpty/sub dirEmpty2: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z) 2025/03/16 06:52:26 INFO : sub dirEmpty: Set directory modification time (using DirSetModTime) run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu'", Local "Local file system at /tmp/rclone1589196380", Modify Window "1ms" 2025/03/16 06:52:37 DEBUG : s0tvtpcbgsp8ufdmedqtvlq3hc/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak/37qp6d1gohacv723ij3brofbu8/i24n0ln37pa2hv8pctddeuh73o: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" 2025/03/16 06:52:38 DEBUG : s0tvtpcbgsp8ufdmedqtvlq3hc/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak/37qp6d1gohacv723ij3brofbu8: Rmdir: contains trashed file: "i24n0ln37pa2hv8pctddeuh73o" 2025/03/16 06:52:39 DEBUG : s0tvtpcbgsp8ufdmedqtvlq3hc/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak: Rmdir: contains trashed file: "37qp6d1gohacv723ij3brofbu8" 2025/03/16 06:52:39 DEBUG : s0tvtpcbgsp8ufdmedqtvlq3hc/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak: Rmdir: contains trashed file: "jefmjbgpu25gb7gcub4i80nlak" 2025/03/16 06:52:40 DEBUG : s0tvtpcbgsp8ufdmedqtvlq3hc/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak: Rmdir: contains trashed file: "jefmjbgpu25gb7gcub4i80nlak" 2025/03/16 06:52:41 DEBUG : s0tvtpcbgsp8ufdmedqtvlq3hc/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak: Rmdir: contains trashed file: "jefmjbgpu25gb7gcub4i80nlak" 2025/03/16 06:52:41 DEBUG : s0tvtpcbgsp8ufdmedqtvlq3hc/jefmjbgpu25gb7gcub4i80nlak: Rmdir: contains trashed file: "jefmjbgpu25gb7gcub4i80nlak" 2025/03/16 06:52:42 DEBUG : s0tvtpcbgsp8ufdmedqtvlq3hc/4r13oncfa2rsrr82oqhsqv24ns: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" 2025/03/16 06:52:43 DEBUG : s0tvtpcbgsp8ufdmedqtvlq3hc: Rmdir: contains trashed file: "4r13oncfa2rsrr82oqhsqv24ns" 2025/03/16 06:52:43 DEBUG : s0tvtpcbgsp8ufdmedqtvlq3hc: Rmdir: contains trashed file: "jefmjbgpu25gb7gcub4i80nlak" 2025/03/16 06:52:43 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestNothingToTransferWithoutEmptyDirs (41.51s) PASS 2025/03/16 06:52:45 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wixuyiv3lumu': Purge remote "./sync.test -test.v -test.timeout 1h0m0s -remote TestCryptDrive: -verbose" - Finished OK in 15m7.089368569s (try 1/5)