"./sync.test -test.v -test.timeout 1h0m0s -remote TestCryptDrive: -verbose -fast-list" - Starting (try 1/5) 2025/03/10 07:46:08 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-vetikis9xude" 2025/03/10 07:46:08 DEBUG : Using config file from "/home/rclone/.rclone.conf" 2025/03/10 07:46:08 DEBUG : Creating backend with remote "TestDrive:crypt/4uhm8b1o03veh3kii1h5jvltpp56ei88ade8af4pm16ljbtk6hsg" 2025/03/10 07:46:09 DEBUG : Creating backend with remote "/tmp/rclone271460456" === RUN TestPipe --- PASS: TestPipe (0.00s) === RUN TestPipeConcurrent --- PASS: TestPipeConcurrent (0.02s) === 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-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:46:10 DEBUG : Added delayed dir = "sub dir", newDst= 2025/03/10 07:46:10 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2025/03/10 07:46:10 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for checks to finish 2025/03/10 07:46:10 NOTICE: sub dir/hello world: Skipped copy as --dry-run is set (size 11) 2025/03/10 07:46:10 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for transfers to finish 2025/03/10 07:46:10 NOTICE: sub dir: Skipped set directory modification time as --dry-run is set run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" --- PASS: TestCopyWithDryRun (2.16s) === RUN TestCopy run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:46:11 INFO : sub dir: Set directory modification time (using DirSetModTime) 2025/03/10 07:46:12 DEBUG : Added delayed dir = "sub dir", newDst= 2025/03/10 07:46:12 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2025/03/10 07:46:12 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for checks to finish 2025/03/10 07:46:12 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for transfers to finish 2025/03/10 07:46:14 DEBUG : sub dir/hello world: md5 = 8f6a4ba3eb71e0dd2f3b41f6615fd21e OK 2025/03/10 07:46:14 INFO : sub dir/hello world: Copied (new) 2025/03/10 07:46:14 INFO : sub dir: Set directory modification time (using DirSetModTime) run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:46:16 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestCopy (5.93s) === RUN TestCopyMetadata run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:46:17 DEBUG : metadata sub dir: Making directory with metadata 2025/03/10 07:46:17 INFO : metadata sub dir: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z) 2025/03/10 07:46:17 DEBUG : empty metadata sub dir: Making directory with metadata 2025/03/10 07:46:17 INFO : empty metadata sub dir: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z) 2025/03/10 07:46:17 DEBUG : Local file system at /tmp/rclone271460456: File to upload is small (21 bytes), uploading instead of streaming 2025/03/10 07:46:17 DEBUG : metadata sub dir/hello metadata world: md5 = baa7a013449dbba2b1ed02b5cfb4e1a2 OK 2025/03/10 07:46:17 DEBUG : metadata sub dir/hello metadata world: Size and md5 of src and dst objects identical 2025/03/10 07:46:17 INFO : metadata sub dir: Set directory modification time (using DirSetModTime) 2025/03/10 07:46:18 DEBUG : Google drive root 'crypt/4uhm8b1o03veh3kii1h5jvltpp56ei88ade8af4pm16ljbtk6hsg': Skipping btime metadata as can't update it on an existing file: 2025-03-10T07:46:17.811743421Z 2025/03/10 07:46:19 INFO : empty metadata sub dir: Updated directory metadata 2025/03/10 07:46:19 DEBUG : Google drive root 'crypt/4uhm8b1o03veh3kii1h5jvltpp56ei88ade8af4pm16ljbtk6hsg': Skipping btime metadata as can't update it on an existing file: 2025-03-10T07:46:17.811743421Z 2025/03/10 07:46:19 INFO : metadata sub dir: Updated directory metadata 2025/03/10 07:46:19 DEBUG : metadata sub dir/hello metadata world: Need to transfer - File not found at Destination 2025/03/10 07:46:19 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for checks to finish 2025/03/10 07:46:19 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for transfers to finish 2025/03/10 07:46:21 DEBUG : metadata sub dir/hello metadata world: md5 = 7673a59d6f9ed75ee37962a3c15e47a3 OK 2025/03/10 07:46:21 INFO : metadata sub dir/hello metadata world: Copied (new) run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:46:24 DEBUG : fg45q1rm3kh00nmmkk4m6ihmrcnel1p7551kqhjr9bk2gtd2gbf0: Rmdir: contains trashed file: "dmuvulfij81f693ur0f1vvbvq9v6iscp56daas3m51n9li5e3470" --- PASS: TestCopyMetadata (8.52s) === RUN TestCopyMetadataNoEmptyDirs run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:46:26 DEBUG : metadata sub dir: Making directory with metadata 2025/03/10 07:46:26 INFO : metadata sub dir: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z) 2025/03/10 07:46:26 DEBUG : empty metadata sub dir: Making directory with metadata 2025/03/10 07:46:26 INFO : empty metadata sub dir: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z) 2025/03/10 07:46:26 DEBUG : Local file system at /tmp/rclone271460456: File to upload is small (21 bytes), uploading instead of streaming 2025/03/10 07:46:26 DEBUG : metadata sub dir/hello metadata world: md5 = baa7a013449dbba2b1ed02b5cfb4e1a2 OK 2025/03/10 07:46:26 DEBUG : metadata sub dir/hello metadata world: Size and md5 of src and dst objects identical 2025/03/10 07:46:26 INFO : metadata sub dir: Set directory modification time (using DirSetModTime) 2025/03/10 07:46:26 DEBUG : Added delayed dir = "empty metadata sub dir", newDst= 2025/03/10 07:46:26 DEBUG : Added delayed dir = "metadata sub dir", newDst= 2025/03/10 07:46:26 DEBUG : metadata sub dir/hello metadata world: Need to transfer - File not found at Destination 2025/03/10 07:46:26 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for checks to finish 2025/03/10 07:46:26 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for transfers to finish 2025/03/10 07:46:28 DEBUG : metadata sub dir/hello metadata world: md5 = d3674b3e17141db0aed90e8bc80a0767 OK 2025/03/10 07:46:28 INFO : metadata sub dir/hello metadata world: Copied (new) 2025/03/10 07:46:28 DEBUG : Google drive root 'crypt/4uhm8b1o03veh3kii1h5jvltpp56ei88ade8af4pm16ljbtk6hsg': Skipping btime metadata as can't update it on an existing file: 2025-03-10T07:46:26.331700709Z 2025/03/10 07:46:29 INFO : metadata sub dir: Updated directory metadata run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:46:32 DEBUG : fg45q1rm3kh00nmmkk4m6ihmrcnel1p7551kqhjr9bk2gtd2gbf0: Rmdir: contains trashed file: "dmuvulfij81f693ur0f1vvbvq9v6iscp56daas3m51n9li5e3470" --- PASS: TestCopyMetadataNoEmptyDirs (7.05s) === RUN TestCopyMissingDirectory run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:46:33 DEBUG : Creating backend with remote "/non-existing" 2025/03/10 07:46:33 ERROR : Local file system at /non-existing: error reading source root directory: directory not found 2025/03/10 07:46:33 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for checks to finish 2025/03/10 07:46:33 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for transfers to finish run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" --- PASS: TestCopyMissingDirectory (1.18s) === RUN TestCopyNoTraverse run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:46:34 DEBUG : Added delayed dir = "sub dir", newDst= 2025/03/10 07:46:34 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2025/03/10 07:46:34 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for checks to finish 2025/03/10 07:46:34 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for transfers to finish 2025/03/10 07:46:36 DEBUG : sub dir/hello world: md5 = 374aad52cfe846763376c53f400d35d5 OK 2025/03/10 07:46:36 INFO : sub dir/hello world: Copied (new) 2025/03/10 07:46:37 INFO : sub dir: Set directory modification time (using DirSetModTime) run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:46:39 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestCopyNoTraverse (5.58s) === RUN TestCopyCheckFirst run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:46:40 INFO : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Running all checks before starting transfers 2025/03/10 07:46:40 DEBUG : Added delayed dir = "sub dir", newDst= 2025/03/10 07:46:40 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2025/03/10 07:46:40 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for checks to finish 2025/03/10 07:46:40 INFO : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Checks finished, now starting transfers 2025/03/10 07:46:40 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for transfers to finish 2025/03/10 07:46:42 DEBUG : sub dir/hello world: md5 = 20734ff55f42ec5b06f89000e3b6457c OK 2025/03/10 07:46:42 INFO : sub dir/hello world: Copied (new) 2025/03/10 07:46:42 INFO : sub dir: Set directory modification time (using DirSetModTime) run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:46:44 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestCopyCheckFirst (5.78s) === RUN TestSyncNoTraverse run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:46:45 ERROR : Ignoring --no-traverse with sync 2025/03/10 07:46:46 DEBUG : Added delayed dir = "sub dir", newDst= 2025/03/10 07:46:46 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2025/03/10 07:46:46 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for checks to finish 2025/03/10 07:46:46 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for transfers to finish 2025/03/10 07:46:48 DEBUG : sub dir/hello world: md5 = 08ceb7819fd01146d94d709038553cc3 OK 2025/03/10 07:46:48 INFO : sub dir/hello world: Copied (new) 2025/03/10 07:46:48 DEBUG : Waiting for deletions to finish 2025/03/10 07:46:48 INFO : sub dir: Set directory modification time (using DirSetModTime) run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:46:50 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestSyncNoTraverse (6.01s) === RUN TestCopyWithDepth run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:46:52 DEBUG : hello world2: Need to transfer - File not found at Destination 2025/03/10 07:46:52 DEBUG : Added delayed dir = "sub dir", newDst= 2025/03/10 07:46:52 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for checks to finish 2025/03/10 07:46:52 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for transfers to finish 2025/03/10 07:46:53 DEBUG : hello world2: md5 = 76f949b3ff53624830d969d67a12fe60 OK 2025/03/10 07:46:53 INFO : hello world2: Copied (new) run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" --- PASS: TestCopyWithDepth (3.28s) === RUN TestCopyWithFilesFrom run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:46:55 DEBUG : potato2: Need to transfer - File not found at Destination 2025/03/10 07:46:55 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for checks to finish 2025/03/10 07:46:55 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for transfers to finish 2025/03/10 07:46:56 DEBUG : potato2: md5 = aa9a4594c3bb99810dc94b76b20a59ec OK 2025/03/10 07:46:56 INFO : potato2: Copied (new) run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" --- PASS: TestCopyWithFilesFrom (3.29s) === RUN TestCopyWithFilesFromAndNoTraverse run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:46:58 DEBUG : potato2: Need to transfer - File not found at Destination 2025/03/10 07:46:58 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for checks to finish 2025/03/10 07:46:58 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for transfers to finish 2025/03/10 07:47:00 DEBUG : potato2: md5 = 551c63eb315a4698f57d9be5ac81ea1f OK 2025/03/10 07:47:00 INFO : potato2: Copied (new) run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" --- PASS: TestCopyWithFilesFromAndNoTraverse (3.28s) === RUN TestCopyEmptyDirectories run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:47:01 DEBUG : sub dir2/sub sub dir2: Making directory with metadata 2025/03/10 07:47:01 INFO : sub dir2/sub sub dir2: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z) 2025/03/10 07:47:01 INFO : sub dir2: Set directory modification time (using DirSetModTime) 2025/03/10 07:47:01 INFO : sub dir: Set directory modification time (using DirSetModTime) 2025/03/10 07:47:02 DEBUG : sub dir: Making directory with metadata 2025/03/10 07:47:02 INFO : sub dir: Made directory with metadata (mtime=2001-02-03T04:05:06.499999999Z) 2025/03/10 07:47:02 DEBUG : sub dir2: Making directory with metadata 2025/03/10 07:47:03 INFO : sub dir2: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z) 2025/03/10 07:47:03 DEBUG : sub dir2/sub sub dir2: Making directory with metadata 2025/03/10 07:47:03 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2025/03/10 07:47:04 INFO : sub dir2/sub sub dir2: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z) 2025/03/10 07:47:04 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for checks to finish 2025/03/10 07:47:04 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for transfers to finish 2025/03/10 07:47:05 DEBUG : sub dir/hello world: md5 = db90be50e1bbc6ea1f1df948128ba3c4 OK 2025/03/10 07:47:05 INFO : sub dir/hello world: Copied (new) run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:47:08 DEBUG : s0tvtpcbgsp8ufdmedqtvlq3hc: Rmdir: contains trashed file: "cv6a9uf28ngrajena8kt5ijjn0" 2025/03/10 07:47:09 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestCopyEmptyDirectories (8.79s) === RUN TestCopyNoEmptyDirectories run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:47:10 INFO : sub dir2: Making directory 2025/03/10 07:47:10 DEBUG : sub dir2/sub sub dir2: Making directory with metadata 2025/03/10 07:47:10 INFO : sub dir2/sub sub dir2: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z) 2025/03/10 07:47:10 DEBUG : Added delayed dir = "sub dir", newDst= 2025/03/10 07:47:10 DEBUG : Added delayed dir = "sub dir2", newDst= 2025/03/10 07:47:10 DEBUG : Added delayed dir = "sub dir2/sub sub dir2", newDst= 2025/03/10 07:47:10 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2025/03/10 07:47:10 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for checks to finish 2025/03/10 07:47:10 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for transfers to finish 2025/03/10 07:47:12 DEBUG : sub dir/hello world: md5 = e5a2f3169711a63b79950c569d52188a OK 2025/03/10 07:47:12 INFO : sub dir/hello world: Copied (new) 2025/03/10 07:47:13 INFO : sub dir: Set directory modification time (using DirSetModTime) 2025/03/10 07:47:15 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestCopyNoEmptyDirectories (5.16s) === RUN TestMoveEmptyDirectories run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:47:15 DEBUG : sub dir2: Making directory with metadata 2025/03/10 07:47:15 INFO : sub dir2: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z) 2025/03/10 07:47:15 DEBUG : sub dir: Making directory with metadata 2025/03/10 07:47:16 INFO : sub dir: Made directory with metadata (mtime=2025-03-10T07:47:15.735451753Z) 2025/03/10 07:47:16 DEBUG : sub dir2: Making directory with metadata 2025/03/10 07:47:17 INFO : sub dir2: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z) 2025/03/10 07:47:17 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2025/03/10 07:47:17 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for checks to finish 2025/03/10 07:47:17 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for transfers to finish 2025/03/10 07:47:18 DEBUG : sub dir/hello world: md5 = 37f8cb4bd7c226cd96a492fc15bc50ed OK 2025/03/10 07:47:18 INFO : sub dir/hello world: Copied (new) 2025/03/10 07:47:18 INFO : sub dir/hello world: Deleted run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:47:22 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestMoveEmptyDirectories (7.55s) === RUN TestSyncNoUpdateDirModtime run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:47:23 DEBUG : sub dir no update dir modtime: Making directory with metadata 2025/03/10 07:47:23 INFO : sub dir no update dir modtime: Made directory with metadata (mtime=2001-02-03T04:05:06.499999999Z) 2025/03/10 07:47:24 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for checks to finish 2025/03/10 07:47:24 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for transfers to finish 2025/03/10 07:47:24 DEBUG : Waiting for deletions to finish run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" --- PASS: TestSyncNoUpdateDirModtime (4.14s) === RUN TestMoveNoEmptyDirectories run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:47:27 INFO : sub dir2: Making directory 2025/03/10 07:47:27 DEBUG : Added delayed dir = "sub dir", newDst= 2025/03/10 07:47:27 DEBUG : Added delayed dir = "sub dir2", newDst= 2025/03/10 07:47:27 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2025/03/10 07:47:27 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for checks to finish 2025/03/10 07:47:27 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for transfers to finish 2025/03/10 07:47:29 DEBUG : sub dir/hello world: md5 = 82195a0e41ed27706cf1e440de238ce7 OK 2025/03/10 07:47:29 INFO : sub dir/hello world: Copied (new) 2025/03/10 07:47:29 INFO : sub dir/hello world: Deleted 2025/03/10 07:47:30 INFO : sub dir: Set directory modification time (using DirSetModTime) 2025/03/10 07:47:32 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestMoveNoEmptyDirectories (5.45s) === RUN TestSyncEmptyDirectories run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:47:32 DEBUG : sub dir2: Making directory with metadata 2025/03/10 07:47:32 INFO : sub dir2: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z) 2025/03/10 07:47:32 INFO : sub dir: Set directory modification time (using DirSetModTime) 2025/03/10 07:47:33 DEBUG : sub dir: Making directory with metadata 2025/03/10 07:47:33 INFO : sub dir: Made directory with metadata (mtime=2001-02-03T04:05:06.499999999Z) 2025/03/10 07:47:33 DEBUG : sub dir2: Making directory with metadata 2025/03/10 07:47:34 INFO : sub dir2: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z) 2025/03/10 07:47:34 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2025/03/10 07:47:34 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for checks to finish 2025/03/10 07:47:34 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for transfers to finish 2025/03/10 07:47:35 DEBUG : sub dir/hello world: md5 = 64f2c1c4a9164eedf45601f889ecaa4d OK 2025/03/10 07:47:35 INFO : sub dir/hello world: Copied (new) 2025/03/10 07:47:35 DEBUG : Waiting for deletions to finish run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:47:38 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestSyncEmptyDirectories (6.88s) === RUN TestSyncSetDelayedModTimes run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" sync_test.go:507: Backend doesn't have DirModTimeUpdatesOnWrite set --- SKIP: TestSyncSetDelayedModTimes (0.43s) === RUN TestSyncNoEmptyDirectories run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:47:40 INFO : sub dir2: Making directory 2025/03/10 07:47:40 DEBUG : Added delayed dir = "sub dir", newDst= 2025/03/10 07:47:40 DEBUG : Added delayed dir = "sub dir2", newDst= 2025/03/10 07:47:40 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2025/03/10 07:47:40 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for checks to finish 2025/03/10 07:47:40 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for transfers to finish 2025/03/10 07:47:42 DEBUG : sub dir/hello world: md5 = 7e4c08d8ed09e338029377374a244782 OK 2025/03/10 07:47:42 INFO : sub dir/hello world: Copied (new) 2025/03/10 07:47:42 DEBUG : Waiting for deletions to finish 2025/03/10 07:47:43 INFO : sub dir: Set directory modification time (using DirSetModTime) 2025/03/10 07:47:44 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestSyncNoEmptyDirectories (5.32s) === RUN TestServerSideCopy run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:47:47 DEBUG : sub dir/hello world: md5 = af0fc1847d33113cf47e894cb67e71a9 OK 2025/03/10 07:47:48 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-jijucok0tuxi" 2025/03/10 07:47:48 DEBUG : Creating backend with remote "TestDrive:crypt/p7sq0jircvcha7jqi7d2uieigjpj16bel8qgvukap1i5bl14ghvg" sync_test.go:590: Server side copy (if possible) Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude' -> Encrypted drive 'TestCryptDrive:rclone-test-jijucok0tuxi' 2025/03/10 07:47:49 DEBUG : Added delayed dir = "sub dir", newDst= 2025/03/10 07:47:49 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2025/03/10 07:47:49 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jijucok0tuxi': Waiting for checks to finish 2025/03/10 07:47:49 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jijucok0tuxi': Waiting for transfers to finish 2025/03/10 07:47:52 INFO : sub dir/hello world: Copied (server-side copy) 2025/03/10 07:47:52 INFO : sub dir: Set directory modification time (using DirSetModTime) run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:47:53 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jijucok0tuxi': Purge remote 2025/03/10 07:47:55 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestServerSideCopy (10.60s) === RUN TestCopyOverSelf run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:47:58 DEBUG : sub dir/hello world: md5 = 77fd19c450daa1ba5d309945cb9d707b OK 2025/03/10 07:47:59 INFO : sub dir: Set directory modification time (using SetModTime) 2025/03/10 07:47:59 DEBUG : Added delayed dir = "sub dir", newDst=sub dir 2025/03/10 07:47:59 DEBUG : sub dir/hello world: Sizes differ (src 17 vs dst 11) 2025/03/10 07:47:59 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for checks to finish 2025/03/10 07:47:59 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for transfers to finish 2025/03/10 07:48:00 DEBUG : sub dir/hello world: md5 = 01259a43ec90961f0b73e69c2f4f0f69 OK 2025/03/10 07:48:00 INFO : sub dir/hello world: Copied (replaced existing) 2025/03/10 07:48:01 INFO : sub dir: Set directory modification time (using SetModTime) run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:48:03 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestCopyOverSelf (8.14s) === RUN TestServerSideCopyOverSelf run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:48:06 DEBUG : sub dir/hello world: md5 = dbd2737650ab5cee32e441fdf4b4a2ce OK 2025/03/10 07:48:07 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-yijatoz3husa" 2025/03/10 07:48:07 DEBUG : Creating backend with remote "TestDrive:crypt/42s7ucqk71oupq895o3t81sk4j0in3tuvi64g437mav4hbnge42g" sync_test.go:626: Server side copy (if possible) Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude' -> Encrypted drive 'TestCryptDrive:rclone-test-yijatoz3husa' 2025/03/10 07:48:08 DEBUG : Added delayed dir = "sub dir", newDst= 2025/03/10 07:48:08 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2025/03/10 07:48:08 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-yijatoz3husa': Waiting for checks to finish 2025/03/10 07:48:08 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-yijatoz3husa': Waiting for transfers to finish 2025/03/10 07:48:11 INFO : sub dir/hello world: Copied (server-side copy) 2025/03/10 07:48:11 INFO : sub dir: Set directory modification time (using DirSetModTime) run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:48:13 DEBUG : sub dir/hello world: md5 = 42aa026a689000571291bcc2842524a7 OK 2025/03/10 07:48:14 DEBUG : sub dir: Directory modification time the same (differ by 0s, within tolerance 1ms) 2025/03/10 07:48:14 DEBUG : Added delayed dir = "sub dir", newDst=sub dir 2025/03/10 07:48:14 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-yijatoz3husa': Waiting for checks to finish 2025/03/10 07:48:14 DEBUG : sub dir/hello world: Sizes differ (src 17 vs dst 11) 2025/03/10 07:48:14 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-yijatoz3husa': Waiting for transfers to finish 2025/03/10 07:48:15 INFO : sub dir/hello world: Copied (server-side copy) 2025/03/10 07:48:16 INFO : sub dir: Set directory modification time (using SetModTime) run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:48:16 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-yijatoz3husa': Purge remote 2025/03/10 07:48:18 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestServerSideCopyOverSelf (15.79s) === RUN TestMoveOverSelf run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:48:22 DEBUG : sub dir/hello world: md5 = f8686782a1728795af00b0912f4aa000 OK 2025/03/10 07:48:23 INFO : sub dir: Set directory modification time (using SetModTime) 2025/03/10 07:48:23 DEBUG : Added delayed dir = "sub dir", newDst=sub dir 2025/03/10 07:48:23 DEBUG : sub dir/hello world: Sizes differ (src 17 vs dst 11) 2025/03/10 07:48:23 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for checks to finish 2025/03/10 07:48:23 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for transfers to finish 2025/03/10 07:48:24 DEBUG : sub dir/hello world: md5 = d7fbde6a4d9bff424a09e9d4581cdbce OK 2025/03/10 07:48:24 INFO : sub dir/hello world: Copied (replaced existing) 2025/03/10 07:48:24 INFO : sub dir/hello world: Deleted 2025/03/10 07:48:25 INFO : sub dir: Set directory modification time (using SetModTime) run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:48:26 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestMoveOverSelf (8.11s) === RUN TestServerSideMoveOverSelf run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:48:30 DEBUG : sub dir/hello world: md5 = 08771e175dff420c8352575423c46970 OK 2025/03/10 07:48:30 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-popedul7luji" 2025/03/10 07:48:30 DEBUG : Creating backend with remote "TestDrive:crypt/9ecpq02l5i47cg4mi00pr5c8tdhvhvssus0ii37r08i2u48iec70" sync_test.go:671: Server side copy (if possible) Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude' -> Encrypted drive 'TestCryptDrive:rclone-test-popedul7luji' 2025/03/10 07:48:32 DEBUG : Added delayed dir = "sub dir", newDst= 2025/03/10 07:48:32 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2025/03/10 07:48:32 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-popedul7luji': Waiting for checks to finish 2025/03/10 07:48:32 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-popedul7luji': Waiting for transfers to finish 2025/03/10 07:48:34 INFO : sub dir/hello world: Copied (server-side copy) 2025/03/10 07:48:35 INFO : sub dir: Set directory modification time (using DirSetModTime) run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:48:37 DEBUG : sub dir/hello world: md5 = 0fc4e6b61933bac59042227b7771c092 OK 2025/03/10 07:48:37 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-popedul7luji': Using server-side directory move 2025/03/10 07:48:37 INFO : Encrypted drive 'TestCryptDrive:rclone-test-popedul7luji': Server side directory move failed - fallback to file moves: can't copy directory - destination already exists 2025/03/10 07:48:38 DEBUG : sub dir: Directory modification time the same (differ by 0s, within tolerance 1ms) 2025/03/10 07:48:38 DEBUG : Added delayed dir = "sub dir", newDst=sub dir 2025/03/10 07:48:38 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-popedul7luji': Waiting for checks to finish 2025/03/10 07:48:38 DEBUG : sub dir/hello world: Sizes differ (src 17 vs dst 11) 2025/03/10 07:48:38 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-popedul7luji': Waiting for transfers to finish 2025/03/10 07:48:38 INFO : sub dir/hello world: Deleted 2025/03/10 07:48:39 INFO : sub dir/hello world: Moved (server-side) 2025/03/10 07:48:39 INFO : sub dir: Set directory modification time (using SetModTime) 2025/03/10 07:48:42 DEBUG : sub dir/hello world: md5 = f2e4bb9bd63540a37f4edc3ec8e244d7 OK 2025/03/10 07:48:42 DEBUG : testing file moves 2025/03/10 07:48:43 DEBUG : sub dir: Directory modification time the same (differ by 0s, within tolerance 1ms) 2025/03/10 07:48:43 DEBUG : Added delayed dir = "sub dir", newDst=sub dir 2025/03/10 07:48:43 DEBUG : sub dir/hello world: Sizes differ (src 24 vs dst 17) 2025/03/10 07:48:43 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-popedul7luji': Waiting for checks to finish 2025/03/10 07:48:43 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-popedul7luji': Waiting for transfers to finish 2025/03/10 07:48:43 INFO : sub dir/hello world: Deleted 2025/03/10 07:48:44 INFO : sub dir/hello world: Moved (server-side) 2025/03/10 07:48:44 INFO : sub dir: Set directory modification time (using SetModTime) run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:48:45 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-popedul7luji': Purge remote --- PASS: TestServerSideMoveOverSelf (20.34s) === RUN TestCopyAfterDelete run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:48:50 DEBUG : sub dir/hello world: md5 = f183748b50cedf50aa43a9526ad54cac OK 2025/03/10 07:48:50 ERROR : : error listing: directory not found 2025/03/10 07:48:51 INFO : Local file system at /tmp/rclone271460456: Making directory 2025/03/10 07:48:51 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for checks to finish 2025/03/10 07:48:51 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for transfers to finish run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:48:53 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestCopyAfterDelete (6.33s) === RUN TestCopyRedownload run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:48:56 DEBUG : sub dir/hello world: md5 = 06179162f7993d38c84d017bb8ff32f3 OK 2025/03/10 07:48:57 DEBUG : Added delayed dir = "sub dir", newDst= 2025/03/10 07:48:57 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2025/03/10 07:48:57 DEBUG : Local file system at /tmp/rclone271460456: Waiting for checks to finish 2025/03/10 07:48:57 DEBUG : Local file system at /tmp/rclone271460456: Waiting for transfers to finish 2025/03/10 07:48:58 DEBUG : sub dir/hello world.285f0a30.partial: renamed to: sub dir/hello world 2025/03/10 07:48:58 INFO : sub dir/hello world: Copied (new) 2025/03/10 07:48:58 INFO : sub dir: Set directory modification time (using DirSetModTime) run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:49:00 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestCopyRedownload (6.34s) === RUN TestSyncBasedOnCheckSum run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:49:01 DEBUG : check sum: Need to transfer - File not found at Destination 2025/03/10 07:49:01 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for checks to finish 2025/03/10 07:49:01 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for transfers to finish 2025/03/10 07:49:02 DEBUG : check sum: md5 = f48ae3c73a977173b31ffab200868d4f OK 2025/03/10 07:49:02 INFO : check sum: Copied (new) 2025/03/10 07:49:02 DEBUG : Waiting for deletions to finish run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:49:03 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for checks to finish 2025/03/10 07:49:03 NOTICE: Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': --checksum is in use but the source and destination have no hashes in common; falling back to --size-only 2025/03/10 07:49:03 DEBUG : check sum: Size of src and dst objects identical 2025/03/10 07:49:03 DEBUG : check sum: Unchanged skipping 2025/03/10 07:49:03 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for transfers to finish 2025/03/10 07:49:03 DEBUG : Waiting for deletions to finish 2025/03/10 07:49:03 INFO : There was nothing to transfer run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" --- PASS: TestSyncBasedOnCheckSum (4.13s) === RUN TestSyncSizeOnly run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:49:05 DEBUG : sizeonly: Need to transfer - File not found at Destination 2025/03/10 07:49:05 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for checks to finish 2025/03/10 07:49:05 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for transfers to finish 2025/03/10 07:49:06 DEBUG : sizeonly: md5 = 1ac9eaa768abbb6c8051b74790fd0ae1 OK 2025/03/10 07:49:06 INFO : sizeonly: Copied (new) 2025/03/10 07:49:06 DEBUG : Waiting for deletions to finish run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:49:07 DEBUG : sizeonly: Sizes identical 2025/03/10 07:49:07 DEBUG : sizeonly: Unchanged skipping 2025/03/10 07:49:07 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for checks to finish 2025/03/10 07:49:07 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for transfers to finish 2025/03/10 07:49:07 DEBUG : Waiting for deletions to finish 2025/03/10 07:49:07 INFO : There was nothing to transfer run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" --- PASS: TestSyncSizeOnly (4.38s) === RUN TestSyncIgnoreSize run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:49:09 DEBUG : ignore-size: Need to transfer - File not found at Destination 2025/03/10 07:49:09 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for checks to finish 2025/03/10 07:49:09 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for transfers to finish 2025/03/10 07:49:11 DEBUG : ignore-size: md5 = 11bfcf801ae83912c7e9ad2ba4375f47 OK 2025/03/10 07:49:11 INFO : ignore-size: Copied (new) 2025/03/10 07:49:11 DEBUG : Waiting for deletions to finish run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:49:11 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for checks to finish 2025/03/10 07:49:11 DEBUG : ignore-size: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/10 07:49:11 DEBUG : ignore-size: Unchanged skipping 2025/03/10 07:49:11 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for transfers to finish 2025/03/10 07:49:11 DEBUG : Waiting for deletions to finish 2025/03/10 07:49:11 INFO : There was nothing to transfer run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" --- PASS: TestSyncIgnoreSize (4.40s) === RUN TestSyncIgnoreTimes run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:49:15 DEBUG : existing: md5 = f51a99ae64f68be04ee86b09e3ec72d5 OK 2025/03/10 07:49:15 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for checks to finish 2025/03/10 07:49:15 DEBUG : existing: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/10 07:49:15 DEBUG : existing: Unchanged skipping 2025/03/10 07:49:15 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for transfers to finish 2025/03/10 07:49:15 DEBUG : Waiting for deletions to finish 2025/03/10 07:49:15 INFO : There was nothing to transfer run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:49:16 DEBUG : existing: Transferring unconditionally as --ignore-times is in use 2025/03/10 07:49:16 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for checks to finish 2025/03/10 07:49:16 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for transfers to finish 2025/03/10 07:49:17 DEBUG : existing: md5 = 43234143eaac6e2dc49fd71fd80be3b7 OK 2025/03/10 07:49:17 INFO : existing: Copied (replaced existing) 2025/03/10 07:49:17 DEBUG : Waiting for deletions to finish run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" --- PASS: TestSyncIgnoreTimes (5.29s) === RUN TestSyncIgnoreExisting run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:49:19 DEBUG : existing: Need to transfer - File not found at Destination 2025/03/10 07:49:19 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for checks to finish 2025/03/10 07:49:19 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for transfers to finish 2025/03/10 07:49:20 DEBUG : existing: md5 = 089948b14418d651c74a289bdaf9e236 OK 2025/03/10 07:49:20 INFO : existing: Copied (new) 2025/03/10 07:49:20 DEBUG : Waiting for deletions to finish run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:49:21 DEBUG : existing: Destination exists, skipping 2025/03/10 07:49:21 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for checks to finish 2025/03/10 07:49:21 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for transfers to finish 2025/03/10 07:49:21 DEBUG : Waiting for deletions to finish 2025/03/10 07:49:21 INFO : There was nothing to transfer run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" --- PASS: TestSyncIgnoreExisting (4.47s) === RUN TestSyncIgnoreErrors run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:49:25 DEBUG : b/potato: md5 = ac66c5fa979fb6b55bdae20cf5445c07 OK 2025/03/10 07:49:27 DEBUG : c/non empty space: md5 = 96862321dc17d227d19af3bed5327a4a OK 2025/03/10 07:49:27 INFO : d: Making directory 2025/03/10 07:49:29 DEBUG : Added delayed dir = "a", newDst= 2025/03/10 07:49:30 INFO : c: Set directory modification time (using SetModTime) 2025/03/10 07:49:30 DEBUG : Added delayed dir = "c", newDst=c 2025/03/10 07:49:30 DEBUG : c/non empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2025/03/10 07:49:30 DEBUG : a/potato2: Need to transfer - File not found at Destination 2025/03/10 07:49:30 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for checks to finish 2025/03/10 07:49:30 DEBUG : c/non empty space: Unchanged skipping 2025/03/10 07:49:30 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for transfers to finish 2025/03/10 07:49:32 DEBUG : a/potato2: md5 = c8060dbdabbd17784e3ff28b6157e3a6 OK 2025/03/10 07:49:32 INFO : a/potato2: Copied (new) 2025/03/10 07:49:32 DEBUG : Waiting for deletions to finish 2025/03/10 07:49:33 INFO : b/potato: Deleted 2025/03/10 07:49:33 INFO : a: Set directory modification time (using DirSetModTime) 2025/03/10 07:49:33 INFO : d: Removing directory 2025/03/10 07:49:34 INFO : b: Removing directory 2025/03/10 07:49:34 DEBUG : 32d8ua6196mc1r7qkfog53rkg0: Rmdir: contains trashed file: "2m507n64kafsi59v9q71r281a4" 2025/03/10 07:49:34 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': deleted 2 directories run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:49:36 DEBUG : 3i9du405pfogq3ncai6pg7ouio: Rmdir: contains trashed file: "982d3pss7t5pn0il16r2foj31s" 2025/03/10 07:49:37 DEBUG : 2bsvlrk2ne1lfitm6tttcu0qt8: Rmdir: contains trashed file: "89l8renevh3mji1c8r1p7qn6tg" --- PASS: TestSyncIgnoreErrors (15.01s) === RUN TestSyncAfterChangingModtimeOnly run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:49:40 DEBUG : empty space: md5 = 7502c5748df84287ba36e590f0e30620 OK 2025/03/10 07:49:40 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for checks to finish 2025/03/10 07:49:40 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/10 07:49:40 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for transfers to finish 2025/03/10 07:49:40 NOTICE: empty space: Skipped copy as --dry-run is set (size 1) 2025/03/10 07:49:40 DEBUG : Waiting for deletions to finish run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:49:41 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for checks to finish 2025/03/10 07:49:41 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/10 07:49:41 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for transfers to finish 2025/03/10 07:49:42 DEBUG : empty space: md5 = bfd01a25a871d79a5e58cd958080fcf5 OK 2025/03/10 07:49:42 INFO : empty space: Copied (replaced existing) 2025/03/10 07:49:42 DEBUG : Waiting for deletions to finish run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" --- PASS: TestSyncAfterChangingModtimeOnly (6.07s) === RUN TestSyncAfterChangingModtimeOnlyWithNoUpdateModTime run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", 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-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:49:46 DEBUG : foo: md5 = ce21de236c00fca491576bdd88ed7dbc OK 2025/03/10 07:49:47 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for checks to finish 2025/03/10 07:49:47 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/10 07:49:47 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for transfers to finish 2025/03/10 07:49:48 DEBUG : foo: md5 = c40af2872bba9181b09bd554610b6fdd OK 2025/03/10 07:49:48 INFO : foo: Copied (replaced existing) 2025/03/10 07:49:48 DEBUG : Waiting for deletions to finish run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" --- PASS: TestSyncDoesntUpdateModtime (4.89s) === RUN TestSyncAfterAddingAFile run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:49:51 DEBUG : empty space: md5 = e6871e1b6e426e70ed10ec5d65cbc2cc OK 2025/03/10 07:49:52 DEBUG : potato: Need to transfer - File not found at Destination 2025/03/10 07:49:52 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2025/03/10 07:49:52 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for checks to finish 2025/03/10 07:49:52 DEBUG : empty space: Unchanged skipping 2025/03/10 07:49:52 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for transfers to finish 2025/03/10 07:49:53 DEBUG : potato: md5 = 1c54ed657082690d3e7232848f35adb8 OK 2025/03/10 07:49:53 INFO : potato: Copied (new) 2025/03/10 07:49:53 DEBUG : Waiting for deletions to finish run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" --- PASS: TestSyncAfterAddingAFile (5.30s) === RUN TestSyncAfterChangingFilesSizeOnly run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:49:57 DEBUG : potato: md5 = 0eda344b5c5fca736e824f426315394c OK 2025/03/10 07:49:57 DEBUG : potato: Sizes differ (src 21 vs dst 60) 2025/03/10 07:49:57 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for checks to finish 2025/03/10 07:49:57 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for transfers to finish 2025/03/10 07:49:58 DEBUG : potato: md5 = a8cbf1337d42e88f26ab826f737c4054 OK 2025/03/10 07:49:58 INFO : potato: Copied (replaced existing) 2025/03/10 07:49:58 DEBUG : Waiting for deletions to finish run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" --- PASS: TestSyncAfterChangingFilesSizeOnly (4.96s) === RUN TestSyncAfterChangingContentsOnly run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:50:01 DEBUG : potato: md5 = d7344212a2b31b8f33c127c2b59a0feb OK 2025/03/10 07:50:02 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for checks to finish 2025/03/10 07:50:02 DEBUG : potato: Modification times differ by 119h59m59.876543211s: 2011-12-25 12:59:59.123456789 +0000 UTC, 2011-12-30 12:59:59 +0000 UTC 2025/03/10 07:50:02 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for transfers to finish 2025/03/10 07:50:03 DEBUG : potato: md5 = 4a44b9fe637df09f9e45d5e5459c2a05 OK 2025/03/10 07:50:03 INFO : potato: Copied (replaced existing) 2025/03/10 07:50:03 DEBUG : Waiting for deletions to finish run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" --- PASS: TestSyncAfterChangingContentsOnly (5.00s) === RUN TestSyncAfterRemovingAFileAndAddingAFileDryRun run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:50:07 DEBUG : potato: md5 = a13738a3df9deef67e6736c2e00a3d70 OK 2025/03/10 07:50:08 DEBUG : empty space: md5 = eeec3f8508bf661b02e341fd7ac8f694 OK 2025/03/10 07:50:08 DEBUG : potato2: Need to transfer - File not found at Destination 2025/03/10 07:50:08 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2025/03/10 07:50:08 DEBUG : empty space: Unchanged skipping 2025/03/10 07:50:08 NOTICE: potato2: Skipped copy as --dry-run is set (size 60) 2025/03/10 07:50:08 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for checks to finish 2025/03/10 07:50:08 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for transfers to finish 2025/03/10 07:50:08 DEBUG : Waiting for deletions to finish 2025/03/10 07:50:08 NOTICE: potato: Skipped delete as --dry-run is set (size 21) run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" --- PASS: TestSyncAfterRemovingAFileAndAddingAFileDryRun (5.25s) === RUN TestSyncAfterRemovingAFileAndAddingAFile run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:50:12 DEBUG : potato: md5 = e682d17e1dc3103151f78c1cc3a2a0ee OK 2025/03/10 07:50:13 DEBUG : empty space: md5 = 28e854ac6c2485052f673a07770ad7ed OK 2025/03/10 07:50:14 DEBUG : potato2: Need to transfer - File not found at Destination 2025/03/10 07:50:14 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2025/03/10 07:50:14 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for checks to finish 2025/03/10 07:50:14 DEBUG : empty space: Unchanged skipping 2025/03/10 07:50:14 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for transfers to finish 2025/03/10 07:50:15 DEBUG : potato2: md5 = 7fc6fbb1a1bd7b109591d580bcd2fcbe OK 2025/03/10 07:50:15 INFO : potato2: Copied (new) 2025/03/10 07:50:15 DEBUG : Waiting for deletions to finish 2025/03/10 07:50:16 INFO : potato: Deleted run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" --- PASS: TestSyncAfterRemovingAFileAndAddingAFile (7.71s) === RUN TestSyncAfterRemovingAFileAndAddingAFileSubDir run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:50:20 DEBUG : b/potato: md5 = 10f9cced17a04a422dce7e3e9240a0e6 OK 2025/03/10 07:50:22 DEBUG : c/non empty space: md5 = 813905c2b983fc69d1c71aa8a3c3a63f OK 2025/03/10 07:50:22 INFO : d: Making directory 2025/03/10 07:50:23 INFO : d/e: Making directory 2025/03/10 07:50:25 DEBUG : Added delayed dir = "a", newDst= 2025/03/10 07:50:26 INFO : c: Set directory modification time (using SetModTime) 2025/03/10 07:50:26 DEBUG : Added delayed dir = "c", newDst=c 2025/03/10 07:50:26 DEBUG : c/non empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2025/03/10 07:50:26 DEBUG : a/potato2: Need to transfer - File not found at Destination 2025/03/10 07:50:26 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for checks to finish 2025/03/10 07:50:26 DEBUG : c/non empty space: Unchanged skipping 2025/03/10 07:50:26 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for transfers to finish 2025/03/10 07:50:28 DEBUG : a/potato2: md5 = ba8e17e96ac8695e5d83b807be50e23c OK 2025/03/10 07:50:28 INFO : a/potato2: Copied (new) 2025/03/10 07:50:28 DEBUG : Waiting for deletions to finish 2025/03/10 07:50:28 INFO : b/potato: Deleted 2025/03/10 07:50:29 INFO : a: Set directory modification time (using DirSetModTime) 2025/03/10 07:50:29 INFO : d/e: Removing directory 2025/03/10 07:50:30 INFO : d: Removing directory 2025/03/10 07:50:30 DEBUG : ka6id8d20d3s5ktapedlphgta8: Rmdir: contains trashed file: "r8sppajuabeak3sbgj2ak8vuf8" 2025/03/10 07:50:30 INFO : b: Removing directory 2025/03/10 07:50:31 DEBUG : 32d8ua6196mc1r7qkfog53rkg0: Rmdir: contains trashed file: "2m507n64kafsi59v9q71r281a4" 2025/03/10 07:50:31 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': deleted 3 directories run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:50:33 DEBUG : 3i9du405pfogq3ncai6pg7ouio: Rmdir: contains trashed file: "982d3pss7t5pn0il16r2foj31s" 2025/03/10 07:50:34 DEBUG : 2bsvlrk2ne1lfitm6tttcu0qt8: Rmdir: contains trashed file: "89l8renevh3mji1c8r1p7qn6tg" --- PASS: TestSyncAfterRemovingAFileAndAddingAFileSubDir (17.25s) === RUN TestSyncAfterRemovingAFileAndAddingAFileSubDirWithErrors run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:50:37 DEBUG : b/potato: md5 = e13db8c797132f477a5852ec47b68be1 OK 2025/03/10 07:50:39 DEBUG : c/non empty space: md5 = f37080df46aa49e47d3957bd35a10599 OK 2025/03/10 07:50:39 INFO : d: Making directory 2025/03/10 07:50:41 DEBUG : Added delayed dir = "a", newDst= 2025/03/10 07:50:42 INFO : c: Set directory modification time (using SetModTime) 2025/03/10 07:50:42 DEBUG : Added delayed dir = "c", newDst=c 2025/03/10 07:50:42 DEBUG : c/non empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2025/03/10 07:50:42 DEBUG : a/potato2: Need to transfer - File not found at Destination 2025/03/10 07:50:42 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for checks to finish 2025/03/10 07:50:42 DEBUG : c/non empty space: Unchanged skipping 2025/03/10 07:50:42 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for transfers to finish 2025/03/10 07:50:44 DEBUG : a/potato2: md5 = f94c37212f87c185162604116c5631ca OK 2025/03/10 07:50:44 INFO : a/potato2: Copied (new) 2025/03/10 07:50:44 ERROR : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': not deleting files as there were IO errors 2025/03/10 07:50:44 INFO : a: Set directory modification time (using DirSetModTime) 2025/03/10 07:50:44 ERROR : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': not deleting directories as there were IO errors run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:50:48 DEBUG : 3i9du405pfogq3ncai6pg7ouio: Rmdir: contains trashed file: "982d3pss7t5pn0il16r2foj31s" 2025/03/10 07:50:48 DEBUG : 32d8ua6196mc1r7qkfog53rkg0: Rmdir: contains trashed file: "2m507n64kafsi59v9q71r281a4" 2025/03/10 07:50:49 DEBUG : 2bsvlrk2ne1lfitm6tttcu0qt8: Rmdir: contains trashed file: "89l8renevh3mji1c8r1p7qn6tg" --- PASS: TestSyncAfterRemovingAFileAndAddingAFileSubDirWithErrors (15.04s) === RUN TestSyncDeleteAfter --- PASS: TestSyncDeleteAfter (0.00s) === RUN TestSyncDeleteDuring run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:50:52 DEBUG : potato: md5 = ebc44955cc8b47dcdde98ba505a9210b OK 2025/03/10 07:50:53 DEBUG : empty space: md5 = f10895dcff23ca9cfb69c619b33a3c69 OK 2025/03/10 07:50:53 DEBUG : Waiting for deletions to finish 2025/03/10 07:50:53 DEBUG : potato2: Need to transfer - File not found at Destination 2025/03/10 07:50:53 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for checks to finish 2025/03/10 07:50:53 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2025/03/10 07:50:53 DEBUG : empty space: Unchanged skipping 2025/03/10 07:50:53 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for transfers to finish 2025/03/10 07:50:54 INFO : potato: Deleted 2025/03/10 07:50:55 DEBUG : potato2: md5 = acc434fb5ea11c0e6d3bb5f86afc3807 OK 2025/03/10 07:50:55 INFO : potato2: Copied (new) run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" --- PASS: TestSyncDeleteDuring (6.55s) === RUN TestSyncDeleteBefore run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:50:59 DEBUG : potato: md5 = 55a33247c524f61f265911a207d931b9 OK 2025/03/10 07:51:00 DEBUG : empty space: md5 = fe65e403f9a34d9df0f9a6ac064e8135 OK 2025/03/10 07:51:00 DEBUG : Waiting for deletions to finish 2025/03/10 07:51:00 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for checks to finish 2025/03/10 07:51:00 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for transfers to finish 2025/03/10 07:51:01 INFO : potato: Deleted 2025/03/10 07:51:01 DEBUG : potato2: Need to transfer - File not found at Destination 2025/03/10 07:51:01 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2025/03/10 07:51:01 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for checks to finish 2025/03/10 07:51:01 DEBUG : empty space: Unchanged skipping 2025/03/10 07:51:01 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for transfers to finish 2025/03/10 07:51:03 DEBUG : potato2: md5 = c1ffe3d47615209e2f62f8e40d2caecf OK 2025/03/10 07:51:03 INFO : potato2: Copied (new) run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" --- PASS: TestSyncDeleteBefore (8.31s) === RUN TestCopyDeleteBefore run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:51:06 DEBUG : potato: md5 = c393be640c3f6ae424211133596fdf92 OK 2025/03/10 07:51:07 DEBUG : potato2: Need to transfer - File not found at Destination 2025/03/10 07:51:07 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for checks to finish 2025/03/10 07:51:07 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for transfers to finish 2025/03/10 07:51:08 DEBUG : potato2: md5 = 7ca37128cc00e7201cc47e0e1268cc73 OK 2025/03/10 07:51:08 INFO : potato2: Copied (new) run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" --- PASS: TestCopyDeleteBefore (5.50s) === RUN TestSyncWithExclude run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:51:12 DEBUG : potato2: md5 = daedd0d5a274e15a06a0e20ed0851ca3 OK 2025/03/10 07:51:13 DEBUG : empty space: md5 = 5bcd72fc44cfa8ccc3342abdd006a7ef OK 2025/03/10 07:51:14 DEBUG : enormous: Excluded (Size Filter) 2025/03/10 07:51:14 DEBUG : enormous: Excluded 2025/03/10 07:51:14 DEBUG : potato2: Excluded (Size Filter) 2025/03/10 07:51:14 DEBUG : potato2: Excluded 2025/03/10 07:51:14 DEBUG : potato2: Excluded (Size Filter) 2025/03/10 07:51:14 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2025/03/10 07:51:14 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for checks to finish 2025/03/10 07:51:14 DEBUG : empty space: Unchanged skipping 2025/03/10 07:51:14 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for transfers to finish 2025/03/10 07:51:14 DEBUG : Waiting for deletions to finish 2025/03/10 07:51:14 INFO : There was nothing to transfer run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:51:14 DEBUG : enormous: Excluded (Size Filter) 2025/03/10 07:51:14 DEBUG : enormous: Excluded 2025/03/10 07:51:14 DEBUG : potato2: Excluded (Size Filter) 2025/03/10 07:51:14 DEBUG : potato2: Excluded 2025/03/10 07:51:14 DEBUG : potato2: Excluded (Size Filter) 2025/03/10 07:51:14 DEBUG : empty space: Size and modification time the same (differ by 456.789µs, within tolerance 1ms) 2025/03/10 07:51:14 DEBUG : Local file system at /tmp/rclone271460456: Waiting for checks to finish 2025/03/10 07:51:14 DEBUG : empty space: Unchanged skipping 2025/03/10 07:51:14 DEBUG : Local file system at /tmp/rclone271460456: Waiting for transfers to finish 2025/03/10 07:51:14 DEBUG : Waiting for deletions to finish 2025/03/10 07:51:14 INFO : There was nothing to transfer run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" --- PASS: TestSyncWithExclude (6.08s) === RUN TestSyncWithExcludeAndDeleteExcluded run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:51:18 DEBUG : potato2: md5 = 10ab580373c8722564430b235ae1f401 OK 2025/03/10 07:51:20 DEBUG : empty space: md5 = c09fd9a2298a0075bade75b248249511 OK 2025/03/10 07:51:21 DEBUG : enormous: md5 = d213c3425b2abdcfbf11f431e1598447 OK 2025/03/10 07:51:22 DEBUG : enormous: Excluded (Size Filter) 2025/03/10 07:51:22 DEBUG : enormous: Excluded 2025/03/10 07:51:22 DEBUG : potato2: Excluded (Size Filter) 2025/03/10 07:51:22 DEBUG : potato2: Excluded 2025/03/10 07:51:22 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for checks to finish 2025/03/10 07:51:22 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2025/03/10 07:51:22 DEBUG : empty space: Unchanged skipping 2025/03/10 07:51:22 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for transfers to finish 2025/03/10 07:51:22 DEBUG : Waiting for deletions to finish 2025/03/10 07:51:22 INFO : enormous: Deleted 2025/03/10 07:51:22 INFO : potato2: Deleted 2025/03/10 07:51:22 INFO : There was nothing to transfer run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:51:23 DEBUG : Local file system at /tmp/rclone271460456: Waiting for checks to finish 2025/03/10 07:51:23 DEBUG : empty space: Size and modification time the same (differ by 456.789µs, within tolerance 1ms) 2025/03/10 07:51:23 DEBUG : empty space: Unchanged skipping 2025/03/10 07:51:23 DEBUG : Local file system at /tmp/rclone271460456: Waiting for transfers to finish 2025/03/10 07:51:23 DEBUG : Waiting for deletions to finish 2025/03/10 07:51:23 INFO : enormous: Deleted 2025/03/10 07:51:23 INFO : potato2: Deleted 2025/03/10 07:51:23 INFO : There was nothing to transfer run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" --- PASS: TestSyncWithExcludeAndDeleteExcluded (7.97s) === RUN TestSyncWithUpdateOlder run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:51:26 DEBUG : one: md5 = f39510d5674b6a382637e7270f647a34 OK 2025/03/10 07:51:27 DEBUG : two: md5 = dea1420e378df9e4be38a907191286f1 OK 2025/03/10 07:51:29 DEBUG : three: md5 = 7d5ad7e0f65246325e69fcc95b256392 OK 2025/03/10 07:51:30 DEBUG : four: md5 = 2345fc1b9a8881ce7d1949a2090ee5ae OK 2025/03/10 07:51:31 DEBUG : five: Need to transfer - File not found at Destination 2025/03/10 07:51:31 DEBUG : four: Sizes differ (src 4 vs dst 8) 2025/03/10 07:51:31 DEBUG : one: Destination is newer than source, skipping 2025/03/10 07:51:31 DEBUG : three: Sizes identical 2025/03/10 07:51:31 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for checks to finish 2025/03/10 07:51:31 DEBUG : four: Destination mod time is within 1s of source but files differ, transferring 2025/03/10 07:51:31 DEBUG : three: Destination mod time is within 1s of source and files identical, skipping 2025/03/10 07:51:31 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for transfers to finish 2025/03/10 07:51:32 DEBUG : four: md5 = acf944c711125a2bbd8ffaccbb631754 OK 2025/03/10 07:51:32 INFO : four: Copied (replaced existing) 2025/03/10 07:51:32 DEBUG : two: md5 = 3686742a5268080cacc5846f5e47cbc7 OK 2025/03/10 07:51:32 INFO : two: Copied (replaced existing) 2025/03/10 07:51:32 DEBUG : five: md5 = c33e21404a0e2cd5e3a34abde0af6cc5 OK 2025/03/10 07:51:32 INFO : five: Copied (new) 2025/03/10 07:51:32 DEBUG : Waiting for deletions to finish sync_test.go:1449: Skip test with --checksum as no hashes supported --- PASS: TestSyncWithUpdateOlder (10.69s) === 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-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" sync_test.go:1538: Can track renames: false 2025/03/10 07:51:35 ERROR : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Ignoring --track-renames as the source and destination do not have a common hash 2025/03/10 07:51:36 DEBUG : potato: Need to transfer - File not found at Destination 2025/03/10 07:51:36 DEBUG : yam: Need to transfer - File not found at Destination 2025/03/10 07:51:36 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for checks to finish 2025/03/10 07:51:36 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for transfers to finish 2025/03/10 07:51:37 DEBUG : potato: md5 = 6b6efa16119f931582d3757b32dea392 OK 2025/03/10 07:51:37 INFO : potato: Copied (new) 2025/03/10 07:51:37 DEBUG : yam: md5 = ed982b3c04bf9ef0d614b7abe1bd7e0d OK 2025/03/10 07:51:37 INFO : yam: Copied (new) 2025/03/10 07:51:37 DEBUG : Waiting for deletions to finish run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:51:37 ERROR : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Ignoring --track-renames as the source and destination do not have a common hash 2025/03/10 07:51:38 DEBUG : yaml: Need to transfer - File not found at Destination 2025/03/10 07:51:38 DEBUG : potato: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/10 07:51:38 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for checks to finish 2025/03/10 07:51:38 DEBUG : potato: Unchanged skipping 2025/03/10 07:51:38 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for transfers to finish 2025/03/10 07:51:39 DEBUG : yaml: md5 = a8a24f93a3acf18774fa7305392caa91 OK 2025/03/10 07:51:39 INFO : yaml: Copied (new) 2025/03/10 07:51:39 DEBUG : Waiting for deletions to finish 2025/03/10 07:51:40 INFO : yam: Deleted run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" --- PASS: TestSyncWithTrackRenames (7.00s) === RUN TestParseRenamesStrategyModtime --- PASS: TestParseRenamesStrategyModtime (0.00s) === RUN TestRenamesStrategyModtime --- PASS: TestRenamesStrategyModtime (0.00s) === RUN TestSyncWithTrackRenamesStrategyModtime run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" sync_test.go:1610: Can track renames: true 2025/03/10 07:51:43 INFO : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Making map for --track-renames 2025/03/10 07:51:43 INFO : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Finished making map for --track-renames 2025/03/10 07:51:43 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for checks to finish 2025/03/10 07:51:43 DEBUG : potato: Need to transfer - No matching file found at Destination 2025/03/10 07:51:43 DEBUG : yam: Need to transfer - No matching file found at Destination 2025/03/10 07:51:43 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for renames to finish 2025/03/10 07:51:43 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for transfers to finish 2025/03/10 07:51:44 DEBUG : yam: md5 = 073d489d4cca290267ed685b6e0df196 OK 2025/03/10 07:51:44 INFO : yam: Copied (new) 2025/03/10 07:51:44 DEBUG : potato: md5 = 6a7e9ccc33f17905be0b0fbbcb490037 OK 2025/03/10 07:51:44 INFO : potato: Copied (new) 2025/03/10 07:51:44 DEBUG : Waiting for deletions to finish run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:51:44 DEBUG : potato: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/10 07:51:44 INFO : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Making map for --track-renames 2025/03/10 07:51:44 INFO : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Finished making map for --track-renames 2025/03/10 07:51:44 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for checks to finish 2025/03/10 07:51:44 DEBUG : potato: Unchanged skipping 2025/03/10 07:51:44 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for renames to finish 2025/03/10 07:51:45 INFO : yam: Moved (server-side) to: yaml 2025/03/10 07:51:45 INFO : yaml: Renamed from "yam" 2025/03/10 07:51:45 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for transfers to finish 2025/03/10 07:51:45 DEBUG : Waiting for deletions to finish 2025/03/10 07:51:45 INFO : There was nothing to transfer run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" --- PASS: TestSyncWithTrackRenamesStrategyModtime (5.25s) === RUN TestSyncWithTrackRenamesStrategyLeaf run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" sync_test.go:1649: Can track renames: true 2025/03/10 07:51:48 DEBUG : Added delayed dir = "sub", newDst= 2025/03/10 07:51:48 INFO : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Making map for --track-renames 2025/03/10 07:51:48 INFO : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Finished making map for --track-renames 2025/03/10 07:51:48 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for checks to finish 2025/03/10 07:51:48 DEBUG : potato: Need to transfer - No matching file found at Destination 2025/03/10 07:51:48 DEBUG : sub/yam: Need to transfer - No matching file found at Destination 2025/03/10 07:51:48 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for renames to finish 2025/03/10 07:51:48 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for transfers to finish 2025/03/10 07:51:50 DEBUG : potato: md5 = b1e18423ba370fd251c13ed5a6553cf8 OK 2025/03/10 07:51:50 INFO : potato: Copied (new) 2025/03/10 07:51:50 DEBUG : sub/yam: md5 = 1b8d92f5da8b73698256a1c572b0a199 OK 2025/03/10 07:51:50 INFO : sub/yam: Copied (new) 2025/03/10 07:51:50 DEBUG : Waiting for deletions to finish 2025/03/10 07:51:51 INFO : sub: Set directory modification time (using DirSetModTime) run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:51:51 DEBUG : potato: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/10 07:51:51 DEBUG : potato: Unchanged skipping 2025/03/10 07:51:52 INFO : sub: Set directory modification time (using SetModTime) 2025/03/10 07:51:52 DEBUG : Added delayed dir = "sub", newDst=sub 2025/03/10 07:51:52 INFO : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Making map for --track-renames 2025/03/10 07:51:52 INFO : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Finished making map for --track-renames 2025/03/10 07:51:52 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for checks to finish 2025/03/10 07:51:52 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for renames to finish 2025/03/10 07:51:53 INFO : sub/yam: Moved (server-side) to: yam 2025/03/10 07:51:53 INFO : yam: Renamed from "sub/yam" 2025/03/10 07:51:53 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for transfers to finish 2025/03/10 07:51:53 DEBUG : Waiting for deletions to finish 2025/03/10 07:51:53 INFO : There was nothing to transfer run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" --- PASS: TestSyncWithTrackRenamesStrategyLeaf (9.17s) === RUN TestServerSideMoveLocal run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:51:57 DEBUG : Creating backend with remote "/tmp/rclone271460456/dir1" 2025/03/10 07:51:57 DEBUG : Creating backend with remote "/tmp/rclone271460456/dir2" 2025/03/10 07:51:57 DEBUG : Local file system at /tmp/rclone271460456/dir2: Using server-side directory move 2025/03/10 07:51:57 INFO : Local file system at /tmp/rclone271460456/dir2: Server side directory move failed - fallback to file moves: can't copy directory - destination already exists 2025/03/10 07:51:57 DEBUG : file1.txt: Need to transfer - File not found at Destination 2025/03/10 07:51:57 INFO : file1.txt: Moved (server-side) 2025/03/10 07:51:57 DEBUG : Local file system at /tmp/rclone271460456/dir2: Waiting for checks to finish 2025/03/10 07:51:57 DEBUG : Local file system at /tmp/rclone271460456/dir2: Waiting for transfers to finish --- PASS: TestServerSideMoveLocal (0.44s) === RUN TestMoveWithDeleteEmptySrcDirs run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:51:57 DEBUG : Added delayed dir = "nested", newDst= 2025/03/10 07:51:57 DEBUG : Added delayed dir = "sub dir", newDst= 2025/03/10 07:51:57 DEBUG : Added delayed dir = "nested/sub dir", newDst= 2025/03/10 07:51:57 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2025/03/10 07:51:57 DEBUG : nested/sub dir/file: Need to transfer - File not found at Destination 2025/03/10 07:51:57 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for checks to finish 2025/03/10 07:51:57 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for transfers to finish 2025/03/10 07:52:00 DEBUG : sub dir/hello world: md5 = 32192cc32b50590e429ef2b7e4b76f0c OK 2025/03/10 07:52:00 INFO : sub dir/hello world: Copied (new) 2025/03/10 07:52:00 INFO : sub dir/hello world: Deleted 2025/03/10 07:52:02 DEBUG : nested/sub dir/file: md5 = 3149321ec045e6301dbe2b9cfd246e7c OK 2025/03/10 07:52:02 INFO : nested/sub dir/file: Copied (new) 2025/03/10 07:52:02 INFO : nested/sub dir/file: Deleted 2025/03/10 07:52:02 INFO : nested/sub dir: Set directory modification time (using DirSetModTime) 2025/03/10 07:52:03 INFO : nested: Set directory modification time (using DirSetModTime) 2025/03/10 07:52:03 INFO : sub dir: Set directory modification time (using DirSetModTime) 2025/03/10 07:52:03 INFO : sub dir: Removing directory 2025/03/10 07:52:03 INFO : nested/sub dir: Removing directory 2025/03/10 07:52:03 INFO : nested: Removing directory 2025/03/10 07:52:03 DEBUG : Local file system at /tmp/rclone271460456: deleted 3 directories run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:52:05 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" 2025/03/10 07:52:06 DEBUG : 37qp6d1gohacv723ij3brofbu8/14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "ftp4kuv8se7tqduu6pmmcvjsmk" 2025/03/10 07:52:07 DEBUG : 37qp6d1gohacv723ij3brofbu8: Rmdir: contains trashed file: "14begaa36ih249fgrnfk6nulg0" --- PASS: TestMoveWithDeleteEmptySrcDirs (10.81s) === RUN TestMoveWithoutDeleteEmptySrcDirs run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:52:08 DEBUG : Added delayed dir = "nested", newDst= 2025/03/10 07:52:08 DEBUG : Added delayed dir = "sub dir", newDst= 2025/03/10 07:52:08 DEBUG : Added delayed dir = "nested/sub dir", newDst= 2025/03/10 07:52:08 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2025/03/10 07:52:08 DEBUG : nested/sub dir/file: Need to transfer - File not found at Destination 2025/03/10 07:52:08 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for checks to finish 2025/03/10 07:52:08 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for transfers to finish 2025/03/10 07:52:10 DEBUG : sub dir/hello world: md5 = f1f9f09e3b9ea7fa6a6466a19772ed9a OK 2025/03/10 07:52:10 INFO : sub dir/hello world: Copied (new) 2025/03/10 07:52:10 INFO : sub dir/hello world: Deleted 2025/03/10 07:52:12 DEBUG : nested/sub dir/file: md5 = 00cee4a45603e34d923de0bbd1ed3382 OK 2025/03/10 07:52:12 INFO : nested/sub dir/file: Copied (new) 2025/03/10 07:52:12 INFO : nested/sub dir/file: Deleted 2025/03/10 07:52:12 INFO : nested/sub dir: Set directory modification time (using DirSetModTime) 2025/03/10 07:52:13 INFO : nested: Set directory modification time (using DirSetModTime) 2025/03/10 07:52:13 INFO : sub dir: Set directory modification time (using DirSetModTime) run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:52:15 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" 2025/03/10 07:52:16 DEBUG : 37qp6d1gohacv723ij3brofbu8/14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "ftp4kuv8se7tqduu6pmmcvjsmk" 2025/03/10 07:52:17 DEBUG : 37qp6d1gohacv723ij3brofbu8: Rmdir: contains trashed file: "14begaa36ih249fgrnfk6nulg0" --- PASS: TestMoveWithoutDeleteEmptySrcDirs (10.01s) === RUN TestMoveWithIgnoreExisting run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:52:18 DEBUG : existing: Need to transfer - File not found at Destination 2025/03/10 07:52:18 DEBUG : existing-b: Need to transfer - File not found at Destination 2025/03/10 07:52:18 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for checks to finish 2025/03/10 07:52:18 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for transfers to finish 2025/03/10 07:52:20 DEBUG : existing-b: md5 = f47bf67ae0ec5caf96ef52aeafba11be OK 2025/03/10 07:52:20 INFO : existing-b: Copied (new) 2025/03/10 07:52:20 INFO : existing-b: Deleted 2025/03/10 07:52:20 DEBUG : existing: md5 = fe5e30dc059b5d8022b6fb9c29379800 OK 2025/03/10 07:52:20 INFO : existing: Copied (new) 2025/03/10 07:52:20 INFO : existing: Deleted 2025/03/10 07:52:20 DEBUG : existing: Destination exists, skipping 2025/03/10 07:52:20 DEBUG : existing: Not removing source file as destination file exists and --ignore-existing is set 2025/03/10 07:52:20 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for checks to finish 2025/03/10 07:52:20 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for transfers to finish 2025/03/10 07:52:20 INFO : There was nothing to transfer run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" --- PASS: TestMoveWithIgnoreExisting (4.39s) === RUN TestServerSideMove run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:52:22 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-jibupeq5seze" 2025/03/10 07:52:22 DEBUG : Creating backend with remote "TestDrive:crypt/sbnpfp6ba4iff99d99nh2ma4ccfri8p8ql4bltbg7ob38otc3880" 2025/03/10 07:52:25 DEBUG : potato2: md5 = 599df9828c61d20fb69c140d34787556 OK 2025/03/10 07:52:26 DEBUG : empty space: md5 = 485d614ac45f48788bbdd8ec513165f4 OK 2025/03/10 07:52:28 DEBUG : potato3: md5 = f52716cae278ecc84271423e0ccbe232 OK sync_test.go:1705: Server side move (if possible) Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude' -> Encrypted drive 'TestCryptDrive:rclone-test-jibupeq5seze' 2025/03/10 07:52:30 DEBUG : empty space: md5 = 3dc83048cbba5b578da5dcced761480b OK 2025/03/10 07:52:31 DEBUG : potato3: md5 = 0767f1be42cfa63b21caad862114b87f OK 2025/03/10 07:52:32 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jibupeq5seze': Using server-side directory move 2025/03/10 07:52:32 INFO : Encrypted drive 'TestCryptDrive:rclone-test-jibupeq5seze': Server side directory move failed - fallback to file moves: can't copy directory - destination already exists 2025/03/10 07:52:32 DEBUG : potato2: Need to transfer - File not found at Destination 2025/03/10 07:52:32 DEBUG : empty space: Size and modification time the same (differ by 0s, within tolerance 1ms) 2025/03/10 07:52:32 DEBUG : empty space: Unchanged skipping 2025/03/10 07:52:32 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jibupeq5seze': Waiting for checks to finish 2025/03/10 07:52:32 DEBUG : potato3: Sizes differ (src 68 vs dst 60) 2025/03/10 07:52:32 INFO : empty space: Deleted 2025/03/10 07:52:32 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jibupeq5seze': Waiting for transfers to finish 2025/03/10 07:52:32 INFO : potato2: Moved (server-side) 2025/03/10 07:52:33 INFO : potato3: Deleted 2025/03/10 07:52:33 INFO : potato3: Moved (server-side) 2025/03/10 07:52:34 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-jofixep8veki" 2025/03/10 07:52:34 DEBUG : Creating backend with remote "TestDrive:crypt/kgmpdfbs2m8gmufks0krk6jini1vsp594l3rasu9ip0f7fsbhn30" 2025/03/10 07:52:35 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jofixep8veki': Using server-side directory move 2025/03/10 07:52:36 INFO : Encrypted drive 'TestCryptDrive:rclone-test-jofixep8veki': Server side directory move succeeded 2025/03/10 07:52:37 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jofixep8veki': Purge remote 2025/03/10 07:52:37 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jibupeq5seze': Purge remote 2025/03/10 07:52:37 NOTICE: purge failed: directory not found --- PASS: TestServerSideMove (15.34s) === RUN TestServerSideMoveWithFilter run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:52:38 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-qelebam3botu" 2025/03/10 07:52:38 DEBUG : Creating backend with remote "TestDrive:crypt/tsi5josq0ontbd3u1je7h3n6lli7lbh4th1crbmk1olsr03dfvs0" 2025/03/10 07:52:40 DEBUG : potato2: md5 = a78a614c56740398e85724d09412f044 OK 2025/03/10 07:52:41 DEBUG : empty space: md5 = afb89c4114060fbe138efe1cd8ffd2d6 OK 2025/03/10 07:52:43 DEBUG : potato3: md5 = 9d50ec4960e269f5dc0583347e72f2d1 OK sync_test.go:1705: Server side move (if possible) Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude' -> Encrypted drive 'TestCryptDrive:rclone-test-qelebam3botu' 2025/03/10 07:52:45 DEBUG : empty space: md5 = 774820a613b09d2a9028c37a201fc411 OK 2025/03/10 07:52:47 DEBUG : potato3: md5 = 4e382cfce11c1ef6845578ec811065a3 OK 2025/03/10 07:52:47 DEBUG : empty space: Excluded (Size Filter) 2025/03/10 07:52:47 DEBUG : empty space: Excluded (Size Filter) 2025/03/10 07:52:47 DEBUG : potato2: Need to transfer - File not found at Destination 2025/03/10 07:52:47 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-qelebam3botu': Waiting for checks to finish 2025/03/10 07:52:47 DEBUG : potato3: Sizes differ (src 68 vs dst 60) 2025/03/10 07:52:47 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-qelebam3botu': Waiting for transfers to finish 2025/03/10 07:52:48 INFO : potato3: Deleted 2025/03/10 07:52:48 INFO : potato2: Moved (server-side) 2025/03/10 07:52:48 INFO : potato3: Moved (server-side) 2025/03/10 07:52:49 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-fozedef8kada" 2025/03/10 07:52:49 DEBUG : Creating backend with remote "TestDrive:crypt/k3jr2ptu5464qr4vvb1h2b8tkt6uahescqbr126m43v4dcduouu0" 2025/03/10 07:52:50 DEBUG : empty space: Excluded (Size Filter) 2025/03/10 07:52:50 DEBUG : potato2: Need to transfer - File not found at Destination 2025/03/10 07:52:50 DEBUG : potato3: Need to transfer - File not found at Destination 2025/03/10 07:52:50 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-fozedef8kada': Waiting for checks to finish 2025/03/10 07:52:50 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-fozedef8kada': Waiting for transfers to finish 2025/03/10 07:52:51 INFO : potato2: Moved (server-side) 2025/03/10 07:52:52 INFO : potato3: Moved (server-side) 2025/03/10 07:52:52 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-fozedef8kada': Purge remote 2025/03/10 07:52:53 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-qelebam3botu': Purge remote --- PASS: TestServerSideMoveWithFilter (16.40s) === RUN TestServerSideMoveDeleteEmptySourceDirs run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:52:54 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-cijihej9fowe" 2025/03/10 07:52:54 DEBUG : Creating backend with remote "TestDrive:crypt/j72s43ns21msoe3t8601m99hhtoi63096psepphlf3ttrvtp8ce0" 2025/03/10 07:52:56 DEBUG : potato2: md5 = 7cffd727f5636eb56c6d6a84213b1142 OK 2025/03/10 07:52:58 DEBUG : empty space: md5 = 2def2a78874fe1db919e22651c9b62be OK 2025/03/10 07:52:59 DEBUG : potato3: md5 = 6ce14ce9d33e896043cd9bc9038c9da6 OK 2025/03/10 07:52:59 INFO : tomatoDir: Making directory sync_test.go:1705: Server side move (if possible) Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude' -> Encrypted drive 'TestCryptDrive:rclone-test-cijihej9fowe' 2025/03/10 07:53:03 DEBUG : empty space: md5 = 7a57a93f620e10969e639bd504774790 OK 2025/03/10 07:53:04 DEBUG : potato3: md5 = 128454e683649d00cf52986086d7012a OK 2025/03/10 07:53:04 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cijihej9fowe': Using server-side directory move 2025/03/10 07:53:04 INFO : Encrypted drive 'TestCryptDrive:rclone-test-cijihej9fowe': Server side directory move failed - fallback to file moves: can't copy directory - destination already exists 2025/03/10 07:53:05 DEBUG : potato2: Need to transfer - File not found at Destination 2025/03/10 07:53:05 DEBUG : Added delayed dir = "tomatoDir", newDst= 2025/03/10 07:53:05 DEBUG : potato3: Sizes differ (src 68 vs dst 60) 2025/03/10 07:53:05 DEBUG : empty space: Size and modification time the same (differ by 0s, within tolerance 1ms) 2025/03/10 07:53:05 DEBUG : empty space: Unchanged skipping 2025/03/10 07:53:05 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cijihej9fowe': Waiting for checks to finish 2025/03/10 07:53:05 INFO : empty space: Deleted 2025/03/10 07:53:05 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cijihej9fowe': Waiting for transfers to finish 2025/03/10 07:53:05 INFO : potato3: Deleted 2025/03/10 07:53:06 INFO : potato2: Moved (server-side) 2025/03/10 07:53:06 INFO : potato3: Moved (server-side) 2025/03/10 07:53:06 INFO : tomatoDir: Removing directory 2025/03/10 07:53:06 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': deleted 1 directories 2025/03/10 07:53:07 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-zicugit6yive" 2025/03/10 07:53:07 DEBUG : Creating backend with remote "TestDrive:crypt/145aomm5jp4durspj5hsj90mp5m9tboem0gu14vg6u95i6bejmkg" 2025/03/10 07:53:08 INFO : tomatoDir: Making directory 2025/03/10 07:53:09 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-zicugit6yive': Using server-side directory move 2025/03/10 07:53:10 INFO : Encrypted drive 'TestCryptDrive:rclone-test-zicugit6yive': Server side directory move succeeded 2025/03/10 07:53:11 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-zicugit6yive': Purge remote 2025/03/10 07:53:11 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cijihej9fowe': Purge remote 2025/03/10 07:53:12 NOTICE: purge failed: directory not found --- PASS: TestServerSideMoveDeleteEmptySourceDirs (17.92s) === RUN TestServerSideMoveOverlap run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" sync_test.go:1910: Skipping test as remote supports DirMove --- SKIP: TestServerSideMoveOverlap (0.67s) === RUN TestSyncOverlap run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:53:13 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-vetikis9xude/rclone-sync-test" 2025/03/10 07:53:13 DEBUG : Creating backend with remote "TestDrive:crypt/4uhm8b1o03veh3kii1h5jvltpp56ei88ade8af4pm16ljbtk6hsg/i7355aa0sb89uagn75vfjqr6s3e3e1h2et8in57abn1fe8qfego0" run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" --- PASS: TestSyncOverlap (3.67s) === RUN TestSyncOverlapWithFilter run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:53:16 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-vetikis9xude/rclone-sync-test" 2025/03/10 07:53:16 DEBUG : Creating backend with remote "TestDrive:crypt/4uhm8b1o03veh3kii1h5jvltpp56ei88ade8af4pm16ljbtk6hsg/i7355aa0sb89uagn75vfjqr6s3e3e1h2et8in57abn1fe8qfego0" 2025/03/10 07:53:19 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-vetikis9xude/rclone-sync-test-include/layer2" 2025/03/10 07:53:19 DEBUG : Creating backend with remote "TestDrive:crypt/4uhm8b1o03veh3kii1h5jvltpp56ei88ade8af4pm16ljbtk6hsg/khf2vlblvnbf9ftevqm0htmss73hj1j5a7q328e4ohrgs7e2loe0/n01jpl9202nn9ec1rb75h0f1c4" 2025/03/10 07:53:22 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-vetikis9xude/rclone-sync-test-ignore-file" 2025/03/10 07:53:22 DEBUG : Creating backend with remote "TestDrive:crypt/4uhm8b1o03veh3kii1h5jvltpp56ei88ade8af4pm16ljbtk6hsg/kmf11jujl9uha3tjganvgpkn45bu778hb5vb5riug1c26b38k7sg" 2025/03/10 07:53:26 DEBUG : rclone-sync-test-ignore-file/.ignore: md5 = 7ce6219fb199afe96a39239cd53ee4c1 OK 2025/03/10 07:53:28 DEBUG : Added delayed dir = "rclone-sync-test-include", newDst= 2025/03/10 07:53:28 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude/rclone-sync-test': Waiting for checks to finish 2025/03/10 07:53:28 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude/rclone-sync-test': Waiting for transfers to finish 2025/03/10 07:53:28 DEBUG : Waiting for deletions to finish 2025/03/10 07:53:28 INFO : There was nothing to transfer 2025/03/10 07:53:29 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for checks to finish 2025/03/10 07:53:29 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for transfers to finish 2025/03/10 07:53:29 DEBUG : Waiting for deletions to finish 2025/03/10 07:53:29 INFO : rclone-sync-test-include: Removing directory 2025/03/10 07:53:30 DEBUG : khf2vlblvnbf9ftevqm0htmss73hj1j5a7q328e4ohrgs7e2loe0: Rmdir: contains file: "n01jpl9202nn9ec1rb75h0f1c4" 2025/03/10 07:53:30 DEBUG : rclone-sync-test-include: Failed to Rmdir: directory not empty 2025/03/10 07:53:30 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': failed to delete 1 directories 2025/03/10 07:53:30 INFO : There was nothing to transfer run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:53:32 DEBUG : Added delayed dir = "rclone-sync-test-include", newDst= 2025/03/10 07:53:32 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude/rclone-sync-test-include/layer2': Waiting for checks to finish 2025/03/10 07:53:32 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude/rclone-sync-test-include/layer2': Waiting for transfers to finish 2025/03/10 07:53:32 DEBUG : Waiting for deletions to finish 2025/03/10 07:53:32 INFO : There was nothing to transfer run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:53:33 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for checks to finish 2025/03/10 07:53:33 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for transfers to finish 2025/03/10 07:53:33 DEBUG : Waiting for deletions to finish 2025/03/10 07:53:33 INFO : rclone-sync-test-include: Removing directory 2025/03/10 07:53:34 DEBUG : khf2vlblvnbf9ftevqm0htmss73hj1j5a7q328e4ohrgs7e2loe0: Rmdir: contains file: "n01jpl9202nn9ec1rb75h0f1c4" 2025/03/10 07:53:34 DEBUG : rclone-sync-test-include: Failed to Rmdir: directory not empty 2025/03/10 07:53:34 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': failed to delete 1 directories 2025/03/10 07:53:34 INFO : There was nothing to transfer run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:53:36 DEBUG : Added delayed dir = "rclone-sync-test-include", newDst= 2025/03/10 07:53:36 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude/rclone-sync-test-ignore-file': Waiting for checks to finish 2025/03/10 07:53:36 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude/rclone-sync-test-ignore-file': Waiting for transfers to finish 2025/03/10 07:53:36 DEBUG : Waiting for deletions to finish 2025/03/10 07:53:36 INFO : There was nothing to transfer run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:53:38 DEBUG : khf2vlblvnbf9ftevqm0htmss73hj1j5a7q328e4ohrgs7e2loe0: Rmdir: contains trashed file: "n01jpl9202nn9ec1rb75h0f1c4" 2025/03/10 07:53:38 DEBUG : kmf11jujl9uha3tjganvgpkn45bu778hb5vb5riug1c26b38k7sg: Rmdir: contains trashed file: "i0t74httmdlljg425j6tg570d8" --- PASS: TestSyncOverlapWithFilter (31.24s) === RUN TestSyncCompareDest run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:53:48 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-vetikis9xude/dst" 2025/03/10 07:53:48 DEBUG : Creating backend with remote "TestDrive:crypt/4uhm8b1o03veh3kii1h5jvltpp56ei88ade8af4pm16ljbtk6hsg/31u3jie661vd5p8j7rtc3hgbh0" 2025/03/10 07:53:49 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-vetikis9xude/CompareDest" 2025/03/10 07:53:49 DEBUG : Creating backend with remote "TestDrive:crypt/4uhm8b1o03veh3kii1h5jvltpp56ei88ade8af4pm16ljbtk6hsg/gveqi14airsml4bgu7krj116o8" 2025/03/10 07:53:51 DEBUG : one: Need to transfer - File not found at Destination 2025/03/10 07:53:51 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude/dst': Waiting for checks to finish 2025/03/10 07:53:51 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude/dst': Waiting for transfers to finish 2025/03/10 07:53:53 DEBUG : one: md5 = f1b37ee40e44820dcaf416657839d60e OK 2025/03/10 07:53:53 INFO : one: Copied (new) 2025/03/10 07:53:53 DEBUG : Waiting for deletions to finish 2025/03/10 07:53:54 DEBUG : one: Sizes differ (src 5 vs dst 3) 2025/03/10 07:53:54 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude/dst': Waiting for checks to finish 2025/03/10 07:53:55 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude/dst': Waiting for transfers to finish 2025/03/10 07:53:56 DEBUG : one: md5 = 00afea93a8eaa64b2d153234e6428bea OK 2025/03/10 07:53:56 INFO : one: Copied (replaced existing) 2025/03/10 07:53:56 DEBUG : Waiting for deletions to finish 2025/03/10 07:53:58 DEBUG : dst/one: md5 = 4be7e16c01971682d570e56cca813221 OK 2025/03/10 07:54:00 DEBUG : CompareDest/one: md5 = 9c5931946da2e404362747c55eed6599 OK 2025/03/10 07:54:01 DEBUG : one: Sizes differ (src 5 vs dst 3) 2025/03/10 07:54:01 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude/dst': Waiting for checks to finish 2025/03/10 07:54:02 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2025/03/10 07:54:02 DEBUG : one: Destination found in --compare-dest, skipping 2025/03/10 07:54:02 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude/dst': Waiting for transfers to finish 2025/03/10 07:54:02 DEBUG : Waiting for deletions to finish 2025/03/10 07:54:02 INFO : There was nothing to transfer 2025/03/10 07:54:04 DEBUG : CompareDest/two: md5 = 1eeab2044f19fd7941f9c9ff630eed83 OK 2025/03/10 07:54:05 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2025/03/10 07:54:05 DEBUG : two: Destination found in --compare-dest, skipping 2025/03/10 07:54:05 DEBUG : one: Sizes differ (src 5 vs dst 3) 2025/03/10 07:54:05 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude/dst': Waiting for checks to finish 2025/03/10 07:54:05 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2025/03/10 07:54:05 DEBUG : one: Destination found in --compare-dest, skipping 2025/03/10 07:54:05 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude/dst': Waiting for transfers to finish 2025/03/10 07:54:05 DEBUG : Waiting for deletions to finish 2025/03/10 07:54:05 INFO : There was nothing to transfer 2025/03/10 07:54:06 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2025/03/10 07:54:06 DEBUG : two: Destination found in --compare-dest, skipping 2025/03/10 07:54:06 DEBUG : one: Sizes differ (src 5 vs dst 3) 2025/03/10 07:54:06 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude/dst': Waiting for checks to finish 2025/03/10 07:54:06 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2025/03/10 07:54:06 DEBUG : one: Destination found in --compare-dest, skipping 2025/03/10 07:54:06 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude/dst': Waiting for transfers to finish 2025/03/10 07:54:06 DEBUG : Waiting for deletions to finish 2025/03/10 07:54:06 INFO : There was nothing to transfer sync_test.go:2175: No hash on uploaded file so skipping compare timestamp test 2025/03/10 07:54:08 DEBUG : two: Sizes differ (src 5 vs dst 3) 2025/03/10 07:54:08 DEBUG : two: Need to transfer - File not found at Destination 2025/03/10 07:54:08 DEBUG : one: Sizes differ (src 5 vs dst 3) 2025/03/10 07:54:08 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude/dst': Waiting for checks to finish 2025/03/10 07:54:08 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2025/03/10 07:54:08 DEBUG : one: Destination found in --compare-dest, skipping 2025/03/10 07:54:08 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude/dst': Waiting for transfers to finish 2025/03/10 07:54:09 DEBUG : two: md5 = 95f01389c3466df0d45c673e0a89a73b OK 2025/03/10 07:54:09 INFO : two: Copied (new) 2025/03/10 07:54:09 DEBUG : Waiting for deletions to finish 2025/03/10 07:54:12 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" 2025/03/10 07:54:12 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2025/03/10 07:54:13 DEBUG : gveqi14airsml4bgu7krj116o8: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" 2025/03/10 07:54:13 DEBUG : gveqi14airsml4bgu7krj116o8: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" --- PASS: TestSyncCompareDest (26.00s) === RUN TestSyncMultipleCompareDest run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:54:16 DEBUG : pre-dest1/1: md5 = 1ad8ef263e2e8d5fe846cc0b00bf6fab OK 2025/03/10 07:54:18 DEBUG : pre-dest2/2: md5 = 6a84dd3775076a91d44d8194956be923 OK 2025/03/10 07:54:19 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-vetikis9xude/dest" 2025/03/10 07:54:19 DEBUG : Creating backend with remote "TestDrive:crypt/4uhm8b1o03veh3kii1h5jvltpp56ei88ade8af4pm16ljbtk6hsg/rg03c1jvnehrrc617i0lnqjddc" 2025/03/10 07:54:20 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-vetikis9xude/pre-dest1" 2025/03/10 07:54:20 DEBUG : Creating backend with remote "TestDrive:crypt/4uhm8b1o03veh3kii1h5jvltpp56ei88ade8af4pm16ljbtk6hsg/bbnblvh6k061ssopqrp18kd7gc" 2025/03/10 07:54:21 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-vetikis9xude/pre-dest2" 2025/03/10 07:54:21 DEBUG : Creating backend with remote "TestDrive:crypt/4uhm8b1o03veh3kii1h5jvltpp56ei88ade8af4pm16ljbtk6hsg/dgicm1h6b5ejvlltm8eeif0bnk" 2025/03/10 07:54:22 DEBUG : 1: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/10 07:54:22 DEBUG : 1: Destination found in --compare-dest, skipping 2025/03/10 07:54:23 DEBUG : 2: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/10 07:54:23 DEBUG : 2: Destination found in --compare-dest, skipping 2025/03/10 07:54:23 DEBUG : 3: Need to transfer - File not found at Destination 2025/03/10 07:54:23 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude/dest': Waiting for checks to finish 2025/03/10 07:54:23 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude/dest': Waiting for transfers to finish 2025/03/10 07:54:26 DEBUG : 3: md5 = b8edfe284696f55868426fef469ad442 OK 2025/03/10 07:54:26 INFO : 3: Copied (new) 2025/03/10 07:54:26 DEBUG : Waiting for deletions to finish 2025/03/10 07:54:29 DEBUG : dgicm1h6b5ejvlltm8eeif0bnk: Rmdir: contains trashed file: "1ghu8geql9vrl726n32nrf65bc" 2025/03/10 07:54:29 DEBUG : bbnblvh6k061ssopqrp18kd7gc: Rmdir: contains trashed file: "skbfko3oil7es0lj68ob574sro" 2025/03/10 07:54:30 DEBUG : rg03c1jvnehrrc617i0lnqjddc: Rmdir: contains trashed file: "g072p7hmjchlnj0gibe64c1epg" --- PASS: TestSyncMultipleCompareDest (17.25s) === RUN TestSyncCopyDest run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:54:31 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-vetikis9xude/dst" 2025/03/10 07:54:31 DEBUG : Creating backend with remote "TestDrive:crypt/4uhm8b1o03veh3kii1h5jvltpp56ei88ade8af4pm16ljbtk6hsg/31u3jie661vd5p8j7rtc3hgbh0" 2025/03/10 07:54:32 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-vetikis9xude/CopyDest" 2025/03/10 07:54:32 DEBUG : Creating backend with remote "TestDrive:crypt/4uhm8b1o03veh3kii1h5jvltpp56ei88ade8af4pm16ljbtk6hsg/d09o6po3f7bm6ce32vdgs8h9ls" 2025/03/10 07:54:34 DEBUG : one: Need to transfer - File not found at Destination 2025/03/10 07:54:34 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude/dst': Waiting for checks to finish 2025/03/10 07:54:34 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude/dst': Waiting for transfers to finish 2025/03/10 07:54:37 DEBUG : one: md5 = 9b3fc603109915a66b155a42fd648fad OK 2025/03/10 07:54:37 INFO : one: Copied (new) 2025/03/10 07:54:37 DEBUG : Waiting for deletions to finish 2025/03/10 07:54:38 DEBUG : one: Sizes differ (src 5 vs dst 3) 2025/03/10 07:54:38 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude/dst': Waiting for checks to finish 2025/03/10 07:54:38 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude/dst': Waiting for transfers to finish 2025/03/10 07:54:39 DEBUG : one: md5 = b0a902fc7084323401bf4d9c539c659b OK 2025/03/10 07:54:39 INFO : one: Copied (replaced existing) 2025/03/10 07:54:39 DEBUG : Waiting for deletions to finish 2025/03/10 07:54:41 DEBUG : dst/one: md5 = 17ce3d66e8532b5449f29c19b50017c7 OK 2025/03/10 07:54:44 DEBUG : CopyDest/one: md5 = 80a27baa8a2ef0132bd60897ae931270 OK 2025/03/10 07:54:44 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-vetikis9xude/BackupDir" 2025/03/10 07:54:44 DEBUG : Creating backend with remote "TestDrive:crypt/4uhm8b1o03veh3kii1h5jvltpp56ei88ade8af4pm16ljbtk6hsg/s6dbk3lfi7c9kfvo6j7bla9m0g" 2025/03/10 07:54:46 DEBUG : one: Sizes differ (src 5 vs dst 3) 2025/03/10 07:54:46 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude/dst': Waiting for checks to finish 2025/03/10 07:54:46 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2025/03/10 07:54:46 DEBUG : one: Sizes differ (src 5 vs dst 3) 2025/03/10 07:54:48 INFO : one: Moved (server-side) 2025/03/10 07:54:49 INFO : one: Copied (server-side copy) 2025/03/10 07:54:49 DEBUG : one: Destination found in --copy-dest, using server-side copy 2025/03/10 07:54:49 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude/dst': Waiting for transfers to finish 2025/03/10 07:54:49 DEBUG : Waiting for deletions to finish 2025/03/10 07:54:51 DEBUG : CopyDest/two: md5 = 85b57cdd152e9dc94a7086de392bad66 OK 2025/03/10 07:54:52 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2025/03/10 07:54:53 INFO : two: Copied (server-side copy) 2025/03/10 07:54:53 DEBUG : two: Destination found in --copy-dest, using server-side copy 2025/03/10 07:54:53 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2025/03/10 07:54:53 DEBUG : one: Unchanged skipping 2025/03/10 07:54:53 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude/dst': Waiting for checks to finish 2025/03/10 07:54:53 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude/dst': Waiting for transfers to finish 2025/03/10 07:54:53 DEBUG : Waiting for deletions to finish 2025/03/10 07:54:54 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2025/03/10 07:54:54 DEBUG : one: Unchanged skipping 2025/03/10 07:54:54 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude/dst': Waiting for checks to finish 2025/03/10 07:54:54 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2025/03/10 07:54:54 DEBUG : two: Unchanged skipping 2025/03/10 07:54:54 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude/dst': Waiting for transfers to finish 2025/03/10 07:54:54 DEBUG : Waiting for deletions to finish 2025/03/10 07:54:54 INFO : There was nothing to transfer 2025/03/10 07:54:55 DEBUG : CopyDest/three: md5 = 0083fcca5914eeb382e4ea05233ad762 OK 2025/03/10 07:54:57 DEBUG : three: Sizes differ (src 7 vs dst 5) 2025/03/10 07:54:57 DEBUG : three: Destination not found in --copy-dest 2025/03/10 07:54:57 DEBUG : three: Need to transfer - File not found at Destination 2025/03/10 07:54:57 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2025/03/10 07:54:57 DEBUG : one: Unchanged skipping 2025/03/10 07:54:57 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude/dst': Waiting for checks to finish 2025/03/10 07:54:57 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2025/03/10 07:54:57 DEBUG : two: Unchanged skipping 2025/03/10 07:54:57 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude/dst': Waiting for transfers to finish 2025/03/10 07:54:58 DEBUG : three: md5 = c647ec3b4e6340425d6baee6c2f823c4 OK 2025/03/10 07:54:58 INFO : three: Copied (new) 2025/03/10 07:54:58 DEBUG : Waiting for deletions to finish 2025/03/10 07:55:03 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "b6jdmn2b1adrhc8vikh7edr9os" 2025/03/10 07:55:03 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" 2025/03/10 07:55:03 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2025/03/10 07:55:04 DEBUG : d09o6po3f7bm6ce32vdgs8h9ls: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" 2025/03/10 07:55:04 DEBUG : d09o6po3f7bm6ce32vdgs8h9ls: Rmdir: contains trashed file: "b6jdmn2b1adrhc8vikh7edr9os" 2025/03/10 07:55:04 DEBUG : d09o6po3f7bm6ce32vdgs8h9ls: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2025/03/10 07:55:04 DEBUG : s6dbk3lfi7c9kfvo6j7bla9m0g: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" --- PASS: TestSyncCopyDest (34.04s) === RUN TestSyncBackupDir run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:55:07 DEBUG : dst/one: md5 = 6108c81680c8b7bad6b41379ca370f43 OK 2025/03/10 07:55:08 DEBUG : dst/two: md5 = 529402b73046d15ab3af27ba54b7e6b2 OK 2025/03/10 07:55:10 DEBUG : dst/three.txt: md5 = 105310696389be3185639a353f4929bf OK 2025/03/10 07:55:10 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-vetikis9xude/dst" 2025/03/10 07:55:10 DEBUG : Creating backend with remote "TestDrive:crypt/4uhm8b1o03veh3kii1h5jvltpp56ei88ade8af4pm16ljbtk6hsg/31u3jie661vd5p8j7rtc3hgbh0" 2025/03/10 07:55:11 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-vetikis9xude/backup" 2025/03/10 07:55:11 DEBUG : Creating backend with remote "TestDrive:crypt/4uhm8b1o03veh3kii1h5jvltpp56ei88ade8af4pm16ljbtk6hsg/1nrff024r7pq65ecp72fc28jb0" 2025/03/10 07:55:13 DEBUG : one: Sizes differ (src 4 vs dst 3) 2025/03/10 07:55:13 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/10 07:55:13 DEBUG : two: Unchanged skipping 2025/03/10 07:55:13 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude/dst': Waiting for checks to finish 2025/03/10 07:55:14 INFO : one: Moved (server-side) 2025/03/10 07:55:14 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude/dst': Waiting for transfers to finish 2025/03/10 07:55:16 DEBUG : one: md5 = d1920f19effb3d0a2850d4f48403a5de OK 2025/03/10 07:55:16 INFO : one: Copied (new) 2025/03/10 07:55:16 DEBUG : Waiting for deletions to finish 2025/03/10 07:55:17 INFO : three.txt: Moved (server-side) 2025/03/10 07:55:17 INFO : three.txt: Moved into backup dir 2025/03/10 07:55:20 DEBUG : dst/three.txt: md5 = fbbd5a06e6b2f54d45f53512bd58c7bd OK 2025/03/10 07:55:20 DEBUG : one: Sizes differ (src 5 vs dst 4) 2025/03/10 07:55:20 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/10 07:55:20 DEBUG : two: Unchanged skipping 2025/03/10 07:55:20 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude/dst': Waiting for checks to finish 2025/03/10 07:55:21 INFO : one: Deleted 2025/03/10 07:55:22 INFO : one: Moved (server-side) 2025/03/10 07:55:22 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude/dst': Waiting for transfers to finish 2025/03/10 07:55:23 DEBUG : one: md5 = 733814c758dfdac9316ff65e7a766a9f OK 2025/03/10 07:55:23 INFO : one: Copied (new) 2025/03/10 07:55:23 DEBUG : Waiting for deletions to finish 2025/03/10 07:55:24 INFO : three.txt: Deleted 2025/03/10 07:55:24 INFO : three.txt: Moved (server-side) 2025/03/10 07:55:24 INFO : three.txt: Moved into backup dir 2025/03/10 07:55:27 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2025/03/10 07:55:27 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" 2025/03/10 07:55:28 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2025/03/10 07:55:28 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "tr2hj63d80ftlmvm6a952snjcc" 2025/03/10 07:55:28 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "tr2hj63d80ftlmvm6a952snjcc" 2025/03/10 07:55:28 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" --- PASS: TestSyncBackupDir (23.77s) === RUN TestSyncBackupDirWithSuffix run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:55:31 DEBUG : dst/one: md5 = b43699e7546cee967c297ce1c4d12714 OK 2025/03/10 07:55:32 DEBUG : dst/two: md5 = 416254743ed9d8adcbdca89f05e2d810 OK 2025/03/10 07:55:34 DEBUG : dst/three.txt: md5 = 70c21cec7a2aafaf6054e89aa680737c OK 2025/03/10 07:55:34 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-vetikis9xude/dst" 2025/03/10 07:55:34 DEBUG : Config file has changed externally - reloading 2025/03/10 07:55:34 DEBUG : Creating backend with remote "TestDrive:crypt/4uhm8b1o03veh3kii1h5jvltpp56ei88ade8af4pm16ljbtk6hsg/31u3jie661vd5p8j7rtc3hgbh0" 2025/03/10 07:55:35 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-vetikis9xude/backup" 2025/03/10 07:55:35 DEBUG : Creating backend with remote "TestDrive:crypt/4uhm8b1o03veh3kii1h5jvltpp56ei88ade8af4pm16ljbtk6hsg/1nrff024r7pq65ecp72fc28jb0" 2025/03/10 07:55:37 DEBUG : one: Sizes differ (src 4 vs dst 3) 2025/03/10 07:55:37 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/10 07:55:37 DEBUG : two: Unchanged skipping 2025/03/10 07:55:37 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude/dst': Waiting for checks to finish 2025/03/10 07:55:38 INFO : one: Moved (server-side) to: one.bak 2025/03/10 07:55:38 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude/dst': Waiting for transfers to finish 2025/03/10 07:55:40 DEBUG : one: md5 = dbeb3b12e6f96bcab2e8e3c60bce00b5 OK 2025/03/10 07:55:40 INFO : one: Copied (new) 2025/03/10 07:55:40 DEBUG : Waiting for deletions to finish 2025/03/10 07:55:40 INFO : three.txt: Moved (server-side) to: three.txt.bak 2025/03/10 07:55:40 INFO : three.txt: Moved into backup dir 2025/03/10 07:55:42 DEBUG : dst/three.txt: md5 = 954770d98597221df0dd7e39bf5d02b3 OK 2025/03/10 07:55:43 DEBUG : one: Sizes differ (src 5 vs dst 4) 2025/03/10 07:55:43 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/10 07:55:43 DEBUG : two: Unchanged skipping 2025/03/10 07:55:43 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude/dst': Waiting for checks to finish 2025/03/10 07:55:44 INFO : one.bak: Deleted 2025/03/10 07:55:44 INFO : one: Moved (server-side) to: one.bak 2025/03/10 07:55:44 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude/dst': Waiting for transfers to finish 2025/03/10 07:55:46 DEBUG : one: md5 = f14c599d1cf7d0071a5a5082312506eb OK 2025/03/10 07:55:46 INFO : one: Copied (new) 2025/03/10 07:55:46 DEBUG : Waiting for deletions to finish 2025/03/10 07:55:47 INFO : three.txt.bak: Deleted 2025/03/10 07:55:47 INFO : three.txt: Moved (server-side) to: three.txt.bak 2025/03/10 07:55:47 INFO : three.txt: Moved into backup dir 2025/03/10 07:55:50 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2025/03/10 07:55:50 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" 2025/03/10 07:55:51 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "qltcak2uaegtmcoa8vijdppbp8" 2025/03/10 07:55:51 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "sk91qgsqfn0r271r2ehsaoc20c" 2025/03/10 07:55:51 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "sk91qgsqfn0r271r2ehsaoc20c" 2025/03/10 07:55:51 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "qltcak2uaegtmcoa8vijdppbp8" --- PASS: TestSyncBackupDirWithSuffix (22.99s) === RUN TestSyncBackupDirWithSuffixKeepExtension run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:55:54 DEBUG : dst/one: md5 = a0f88d9d290c4dc93aeacb3cad5e21eb OK 2025/03/10 07:55:55 DEBUG : dst/two: md5 = ecff80bc3104037270ab0cab64a0c235 OK 2025/03/10 07:55:57 DEBUG : dst/three.txt: md5 = d03d2b7a8bc53508be09aad86e03fb27 OK 2025/03/10 07:55:57 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-vetikis9xude/dst" 2025/03/10 07:55:57 DEBUG : Creating backend with remote "TestDrive:crypt/4uhm8b1o03veh3kii1h5jvltpp56ei88ade8af4pm16ljbtk6hsg/31u3jie661vd5p8j7rtc3hgbh0" 2025/03/10 07:55:58 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-vetikis9xude/backup" 2025/03/10 07:55:58 DEBUG : Creating backend with remote "TestDrive:crypt/4uhm8b1o03veh3kii1h5jvltpp56ei88ade8af4pm16ljbtk6hsg/1nrff024r7pq65ecp72fc28jb0" 2025/03/10 07:56:00 DEBUG : one: Sizes differ (src 4 vs dst 3) 2025/03/10 07:56:00 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/10 07:56:00 DEBUG : two: Unchanged skipping 2025/03/10 07:56:00 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude/dst': Waiting for checks to finish 2025/03/10 07:56:01 INFO : one: Moved (server-side) to: one-2019-01-01 2025/03/10 07:56:01 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude/dst': Waiting for transfers to finish 2025/03/10 07:56:03 DEBUG : one: md5 = 7f579677b186126b9bfc0e8c6c858cf9 OK 2025/03/10 07:56:03 INFO : one: Copied (new) 2025/03/10 07:56:03 DEBUG : Waiting for deletions to finish 2025/03/10 07:56:04 INFO : three.txt: Moved (server-side) to: three-2019-01-01.txt 2025/03/10 07:56:04 INFO : three.txt: Moved into backup dir 2025/03/10 07:56:05 DEBUG : dst/three.txt: md5 = c722a30a6097fd95ac6bb0c43e100776 OK 2025/03/10 07:56:06 DEBUG : one: Sizes differ (src 5 vs dst 4) 2025/03/10 07:56:06 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/10 07:56:06 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude/dst': Waiting for checks to finish 2025/03/10 07:56:06 DEBUG : two: Unchanged skipping 2025/03/10 07:56:07 INFO : one-2019-01-01: Deleted 2025/03/10 07:56:07 INFO : one: Moved (server-side) to: one-2019-01-01 2025/03/10 07:56:07 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude/dst': Waiting for transfers to finish 2025/03/10 07:56:09 DEBUG : one: md5 = 29ae47c245f52ce6d6f790249a918651 OK 2025/03/10 07:56:09 INFO : one: Copied (new) 2025/03/10 07:56:09 DEBUG : Waiting for deletions to finish 2025/03/10 07:56:10 INFO : three-2019-01-01.txt: Deleted 2025/03/10 07:56:10 INFO : three.txt: Moved (server-side) to: three-2019-01-01.txt 2025/03/10 07:56:10 INFO : three.txt: Moved into backup dir 2025/03/10 07:56:13 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2025/03/10 07:56:13 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" 2025/03/10 07:56:14 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "qtq2f6qq4lgpsmj88vb7147qje3prudmtfdtr2342fth58vo9a50" 2025/03/10 07:56:14 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "jcjl1bv3ep0v8kt35lqql1co90" 2025/03/10 07:56:14 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "jcjl1bv3ep0v8kt35lqql1co90" 2025/03/10 07:56:14 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "qtq2f6qq4lgpsmj88vb7147qje3prudmtfdtr2342fth58vo9a50" --- PASS: TestSyncBackupDirWithSuffixKeepExtension (22.97s) === RUN TestSyncBackupDirSuffixOnly run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:56:17 DEBUG : dst/one: md5 = fc7b4ee5533e2771f084d2f0013f304b OK 2025/03/10 07:56:18 DEBUG : dst/two: md5 = 01c4752f23dd61f19ac0c6e4e553cc8e OK 2025/03/10 07:56:20 DEBUG : dst/three.txt: md5 = 3fafd3695d0dc7a544b3aeaacd0e937e OK 2025/03/10 07:56:20 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-vetikis9xude/dst" 2025/03/10 07:56:20 DEBUG : Creating backend with remote "TestDrive:crypt/4uhm8b1o03veh3kii1h5jvltpp56ei88ade8af4pm16ljbtk6hsg/31u3jie661vd5p8j7rtc3hgbh0" 2025/03/10 07:56:21 DEBUG : one: Sizes differ (src 4 vs dst 3) 2025/03/10 07:56:21 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/10 07:56:21 DEBUG : two: Unchanged skipping 2025/03/10 07:56:21 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude/dst': Waiting for checks to finish 2025/03/10 07:56:22 INFO : one: Moved (server-side) to: one.bak 2025/03/10 07:56:22 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude/dst': Waiting for transfers to finish 2025/03/10 07:56:23 DEBUG : one: md5 = 4dcc1034c937eba72ba0571845a0a449 OK 2025/03/10 07:56:23 INFO : one: Copied (new) 2025/03/10 07:56:23 DEBUG : Waiting for deletions to finish 2025/03/10 07:56:24 INFO : three.txt: Moved (server-side) to: three.txt.bak 2025/03/10 07:56:24 INFO : three.txt: Moved into backup dir 2025/03/10 07:56:26 DEBUG : dst/three.txt: md5 = e75891772489a4c7ff4fdcffa5a62ba2 OK 2025/03/10 07:56:27 DEBUG : one.bak: Excluded (Path Filter) 2025/03/10 07:56:27 DEBUG : three.txt.bak: Excluded (Path Filter) 2025/03/10 07:56:27 DEBUG : one: Sizes differ (src 5 vs dst 4) 2025/03/10 07:56:27 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/10 07:56:27 DEBUG : two: Unchanged skipping 2025/03/10 07:56:27 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude/dst': Waiting for checks to finish 2025/03/10 07:56:28 INFO : one.bak: Deleted 2025/03/10 07:56:28 INFO : one: Moved (server-side) to: one.bak 2025/03/10 07:56:28 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude/dst': Waiting for transfers to finish 2025/03/10 07:56:30 DEBUG : one: md5 = 6eaf75bd9e0894ec8d28acb1990ae939 OK 2025/03/10 07:56:30 INFO : one: Copied (new) 2025/03/10 07:56:30 DEBUG : Waiting for deletions to finish 2025/03/10 07:56:30 INFO : three.txt.bak: Deleted 2025/03/10 07:56:31 INFO : three.txt: Moved (server-side) to: three.txt.bak 2025/03/10 07:56:31 INFO : three.txt: Moved into backup dir 2025/03/10 07:56:34 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2025/03/10 07:56:34 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "qltcak2uaegtmcoa8vijdppbp8" 2025/03/10 07:56:34 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "sk91qgsqfn0r271r2ehsaoc20c" 2025/03/10 07:56:34 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "qltcak2uaegtmcoa8vijdppbp8" 2025/03/10 07:56:34 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "sk91qgsqfn0r271r2ehsaoc20c" 2025/03/10 07:56:34 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" --- PASS: TestSyncBackupDirSuffixOnly (19.80s) === RUN TestSyncSuffix run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:56:37 DEBUG : dst/one: md5 = e34c1f8e4728864c169e9c0b6c132ced OK 2025/03/10 07:56:38 DEBUG : dst/two: md5 = c65c22a225cd9face315c7026c662aa9 OK 2025/03/10 07:56:39 DEBUG : dst/three.txt: md5 = b13efa5e673fcd8322b209073aac7c48 OK 2025/03/10 07:56:40 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-vetikis9xude/dst" 2025/03/10 07:56:40 DEBUG : Creating backend with remote "TestDrive:crypt/4uhm8b1o03veh3kii1h5jvltpp56ei88ade8af4pm16ljbtk6hsg/31u3jie661vd5p8j7rtc3hgbh0" 2025/03/10 07:56:41 DEBUG : one: Sizes differ (src 4 vs dst 3) 2025/03/10 07:56:42 INFO : one: Moved (server-side) to: one.bak 2025/03/10 07:56:43 DEBUG : one: md5 = 6213f62c3990b1175e7b24f17fd103a8 OK 2025/03/10 07:56:43 INFO : one: Copied (new) 2025/03/10 07:56:43 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/10 07:56:43 DEBUG : two: Unchanged skipping 2025/03/10 07:56:43 DEBUG : three.txt: Sizes differ (src 6 vs dst 5) 2025/03/10 07:56:44 INFO : three.txt: Moved (server-side) to: three.txt.bak 2025/03/10 07:56:46 DEBUG : three.txt: md5 = 42a3eeb4d7e16a24d86b64ca34962ac1 OK 2025/03/10 07:56:46 INFO : three.txt: Copied (new) 2025/03/10 07:56:47 DEBUG : one: Sizes differ (src 5 vs dst 4) 2025/03/10 07:56:48 INFO : one.bak: Deleted 2025/03/10 07:56:48 INFO : one: Moved (server-side) to: one.bak 2025/03/10 07:56:50 DEBUG : one: md5 = 6bfdc456920f2a762ed2977eeedcd611 OK 2025/03/10 07:56:50 INFO : one: Copied (new) 2025/03/10 07:56:50 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/10 07:56:50 DEBUG : two: Unchanged skipping 2025/03/10 07:56:50 DEBUG : three.txt: Sizes differ (src 19 vs dst 6) 2025/03/10 07:56:51 INFO : three.txt.bak: Deleted 2025/03/10 07:56:51 INFO : three.txt: Moved (server-side) to: three.txt.bak 2025/03/10 07:56:53 DEBUG : three.txt: md5 = a028c66e05c90ec1f79c1018d2dbc5ce OK 2025/03/10 07:56:53 INFO : three.txt: Copied (new) 2025/03/10 07:56:56 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2025/03/10 07:56:56 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "tr2hj63d80ftlmvm6a952snjcc" 2025/03/10 07:56:56 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "qltcak2uaegtmcoa8vijdppbp8" 2025/03/10 07:56:56 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "qltcak2uaegtmcoa8vijdppbp8" 2025/03/10 07:56:56 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "sk91qgsqfn0r271r2ehsaoc20c" 2025/03/10 07:56:56 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "sk91qgsqfn0r271r2ehsaoc20c" 2025/03/10 07:56:56 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" --- PASS: TestSyncSuffix (22.54s) === RUN TestSyncSuffixKeepExtension run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:56:59 DEBUG : dst/one: md5 = 0b8a332ae68007495e44e3d6590e6152 OK 2025/03/10 07:57:00 DEBUG : dst/two: md5 = bfa1919aa69d8dbb86167c61206c2ad3 OK 2025/03/10 07:57:02 DEBUG : dst/three.txt: md5 = 61aa44b3e047655363febb3d78302c06 OK 2025/03/10 07:57:02 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-vetikis9xude/dst" 2025/03/10 07:57:02 DEBUG : Creating backend with remote "TestDrive:crypt/4uhm8b1o03veh3kii1h5jvltpp56ei88ade8af4pm16ljbtk6hsg/31u3jie661vd5p8j7rtc3hgbh0" 2025/03/10 07:57:03 DEBUG : one: Sizes differ (src 4 vs dst 3) 2025/03/10 07:57:04 INFO : one: Moved (server-side) to: one-2019-01-01 2025/03/10 07:57:05 DEBUG : one: md5 = 3bf0fd6ecaa3aea35bd6eb57f849dcf1 OK 2025/03/10 07:57:05 INFO : one: Copied (new) 2025/03/10 07:57:06 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/10 07:57:06 DEBUG : two: Unchanged skipping 2025/03/10 07:57:06 DEBUG : three.txt: Sizes differ (src 6 vs dst 5) 2025/03/10 07:57:07 INFO : three.txt: Moved (server-side) to: three-2019-01-01.txt 2025/03/10 07:57:08 DEBUG : three.txt: md5 = e93c28b25c04f33c39f470a9c6d547b8 OK 2025/03/10 07:57:08 INFO : three.txt: Copied (new) 2025/03/10 07:57:09 DEBUG : one: Sizes differ (src 5 vs dst 4) 2025/03/10 07:57:10 INFO : one-2019-01-01: Deleted 2025/03/10 07:57:11 INFO : one: Moved (server-side) to: one-2019-01-01 2025/03/10 07:57:12 DEBUG : one: md5 = 9cd3986d9dc115feaa38a8848d100e6c OK 2025/03/10 07:57:12 INFO : one: Copied (new) 2025/03/10 07:57:12 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/10 07:57:12 DEBUG : two: Unchanged skipping 2025/03/10 07:57:13 DEBUG : three.txt: Sizes differ (src 19 vs dst 6) 2025/03/10 07:57:13 INFO : three-2019-01-01.txt: Deleted 2025/03/10 07:57:14 INFO : three.txt: Moved (server-side) to: three-2019-01-01.txt 2025/03/10 07:57:15 DEBUG : three.txt: md5 = fe61dbf2dc0339cc57fe0eca910fe295 OK 2025/03/10 07:57:15 INFO : three.txt: Copied (new) 2025/03/10 07:57:19 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "tr2hj63d80ftlmvm6a952snjcc" 2025/03/10 07:57:19 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2025/03/10 07:57:19 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "jcjl1bv3ep0v8kt35lqql1co90" 2025/03/10 07:57:19 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" 2025/03/10 07:57:19 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "qtq2f6qq4lgpsmj88vb7147qje3prudmtfdtr2342fth58vo9a50" 2025/03/10 07:57:19 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "jcjl1bv3ep0v8kt35lqql1co90" 2025/03/10 07:57:19 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "qtq2f6qq4lgpsmj88vb7147qje3prudmtfdtr2342fth58vo9a50" --- PASS: TestSyncSuffixKeepExtension (22.55s) === RUN TestSyncUTFNorm run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:57:21 DEBUG : Testêé: md5 = d6b9c7235cbb73c2b817a8addfad393f OK 2025/03/10 07:57:22 DEBUG : Testêé: Sizes differ (src 14 vs dst 18) 2025/03/10 07:57:22 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for checks to finish 2025/03/10 07:57:22 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for transfers to finish 2025/03/10 07:57:23 DEBUG : Testêé: md5 = 2bad26d2d8a2dde4a5ccdbf728ac7f1a OK 2025/03/10 07:57:23 INFO : Testêé: Copied (replaced existing) to: Testêé 2025/03/10 07:57:23 DEBUG : Waiting for deletions to finish --- PASS: TestSyncUTFNorm (4.54s) === RUN TestSyncImmutable run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:57:25 DEBUG : existing: Need to transfer - File not found at Destination 2025/03/10 07:57:25 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for checks to finish 2025/03/10 07:57:25 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for transfers to finish 2025/03/10 07:57:26 DEBUG : existing: md5 = 104cd11941dcf7a2c6a343e62a0af93e OK 2025/03/10 07:57:26 INFO : existing: Copied (new) 2025/03/10 07:57:26 DEBUG : Waiting for deletions to finish run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:57:26 DEBUG : existing: Sizes differ (src 8 vs dst 6) 2025/03/10 07:57:26 ERROR : existing: Source and destination exist but do not match: immutable file modified 2025/03/10 07:57:26 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for checks to finish 2025/03/10 07:57:26 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for transfers to finish 2025/03/10 07:57:26 ERROR : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': not deleting files as there were IO errors 2025/03/10 07:57:26 ERROR : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': not deleting directories as there were IO errors run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" --- PASS: TestSyncImmutable (4.53s) === RUN TestSyncIgnoreCase run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:57:30 DEBUG : EXISTING: md5 = 4cc535cac597336be43ce90fa5ac95bb OK 2025/03/10 07:57:30 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for checks to finish 2025/03/10 07:57:30 DEBUG : existing: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/10 07:57:30 DEBUG : existing: Unchanged skipping 2025/03/10 07:57:30 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for transfers to finish 2025/03/10 07:57:30 DEBUG : Waiting for deletions to finish 2025/03/10 07:57:30 INFO : There was nothing to transfer --- PASS: TestSyncIgnoreCase (2.92s) === RUN TestFixCase run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" sync_test.go:2635: Skipping test as local or remote are case-sensitive --- SKIP: TestFixCase (0.45s) === RUN TestMaxTransfer === RUN TestMaxTransfer/Hard run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", 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-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", 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-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" sync_test.go:2674: This test only runs on local --- PASS: TestMaxTransfer (1.34s) --- SKIP: TestMaxTransfer/Hard (0.42s) --- SKIP: TestMaxTransfer/Soft (0.43s) --- SKIP: TestMaxTransfer/Cautious (0.49s) === RUN TestSyncConcurrentDelete run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:57:35 DEBUG : both0: md5 = 175409a877aefe8f6611d928d8225baf OK 2025/03/10 07:57:36 DEBUG : only0: md5 = ca883d84a4a9666a5f2e8c1e725c2f12 OK 2025/03/10 07:57:37 DEBUG : both1: md5 = 38f5513cf7dda3fb9c7ddb6d3c80bd5a OK 2025/03/10 07:57:39 DEBUG : only1: md5 = c14a6eefe3a237a9643cb4c53214a3d7 OK 2025/03/10 07:57:40 DEBUG : both2: md5 = ea5e0e2278ec6990794ddab5611ef941 OK 2025/03/10 07:57:42 DEBUG : only2: md5 = 8aee8a541ca0759eae8c39d3536e0463 OK 2025/03/10 07:57:43 DEBUG : both3: md5 = 20846d1e3e7eb08b24fdffcac6777b5c OK 2025/03/10 07:57:44 DEBUG : only3: md5 = 464183278c7e5690b73f73910a8c44d2 OK 2025/03/10 07:57:46 DEBUG : both4: md5 = 4dfa01b1cd392541b3de40cff5719f0f OK 2025/03/10 07:57:47 DEBUG : only4: md5 = 59625049ce469ab9e7c5c681323600f6 OK 2025/03/10 07:57:49 DEBUG : both5: md5 = 2260d4735bc9669675d377028b23c2fa OK 2025/03/10 07:57:50 DEBUG : only5: md5 = 430b70278ecff69a9db9e298b0859faf OK 2025/03/10 07:57:51 DEBUG : both6: md5 = 2c05a4dd94c062d9839a927ac4ea932a OK 2025/03/10 07:57:53 DEBUG : only6: md5 = ff426a4a6ac610d506ce4edf29b60acd OK 2025/03/10 07:57:54 DEBUG : both7: md5 = 88728b1d8dac758f9b1a5f47c6071518 OK 2025/03/10 07:57:56 DEBUG : only7: md5 = d0847f826cd3116fa5c7ff130441695b OK 2025/03/10 07:57:57 DEBUG : both8: md5 = fe2f6f55b9e4de81b5559be2528c8370 OK 2025/03/10 07:57:59 DEBUG : only8: md5 = 54a891c149c80d7f0c7689a7eca4ad72 OK 2025/03/10 07:58:00 DEBUG : both9: md5 = 26d34b40cee8c66fd363496c6d37f26d OK 2025/03/10 07:58:02 DEBUG : only9: md5 = 931028e6aba1df0265dc1305c94de342 OK 2025/03/10 07:58:03 DEBUG : both10: md5 = d0d7d14aca9c02ed05a80d2d2682602e OK 2025/03/10 07:58:04 DEBUG : only10: md5 = b96a4739c5f84f52d1aed9b4f7cb577e OK 2025/03/10 07:58:06 DEBUG : both11: md5 = 8ead395196cee307450a94a8521067de OK 2025/03/10 07:58:07 DEBUG : only11: md5 = e8a9c9477955c02630c0f58e3b761b41 OK 2025/03/10 07:58:09 DEBUG : both12: md5 = fc594be7dbb416932a6292887187cfe0 OK 2025/03/10 07:58:10 DEBUG : only12: md5 = 7a12ef5b99cd208f4173b541e49439cd OK 2025/03/10 07:58:12 DEBUG : both13: md5 = 04fd7f06b2ad7a45c14ee787044ebb05 OK 2025/03/10 07:58:13 DEBUG : only13: md5 = 396e0ebaed92406b3cd6a2715fb8015d OK 2025/03/10 07:58:14 DEBUG : both14: md5 = 01aff1e9330f446f45e77aac6124142e OK 2025/03/10 07:58:16 DEBUG : only14: md5 = 0edeef444e6b365cffdcb8e5be7d85fd OK 2025/03/10 07:58:17 DEBUG : both15: md5 = fc261c89ee33116ca24c1dcf5070127f OK 2025/03/10 07:58:18 DEBUG : only15: md5 = c5ce65333c4d2905ea51ee37e4aff2f6 OK 2025/03/10 07:58:20 DEBUG : both16: md5 = f3129f4da4bcf28592625d308ad313bf OK 2025/03/10 07:58:21 DEBUG : only16: md5 = 06a4c80c61872403f7bf0479e9c27d2f OK 2025/03/10 07:58:23 DEBUG : both17: md5 = aecd729fc4cde328f70c1d477d614ca9 OK 2025/03/10 07:58:24 DEBUG : only17: md5 = 804ba3aab577a58b5a27718c49ad54c1 OK 2025/03/10 07:58:25 DEBUG : both18: md5 = 8a6168e26873cd8568cbac80db67e5ca OK 2025/03/10 07:58:27 DEBUG : only18: md5 = d57ce2b21117132c3cb3098e59fb992c OK 2025/03/10 07:58:28 DEBUG : both19: md5 = 01730ff9cd9842b3df96c88bc68c5893 OK 2025/03/10 07:58:29 DEBUG : only19: md5 = 68ad2d3fb88d146a8e1770b90b39b70f OK 2025/03/10 07:58:30 DEBUG : both0: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/10 07:58:30 DEBUG : both11: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/10 07:58:30 DEBUG : both1: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/10 07:58:30 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for checks to finish 2025/03/10 07:58:30 DEBUG : both10: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/10 07:58:30 DEBUG : both0: Unchanged skipping 2025/03/10 07:58:30 DEBUG : both12: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/10 07:58:30 DEBUG : both12: Unchanged skipping 2025/03/10 07:58:30 DEBUG : both13: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/10 07:58:30 DEBUG : both13: Unchanged skipping 2025/03/10 07:58:30 DEBUG : both14: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/10 07:58:30 DEBUG : both11: Unchanged skipping 2025/03/10 07:58:30 DEBUG : both15: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/10 07:58:30 DEBUG : both1: Unchanged skipping 2025/03/10 07:58:30 DEBUG : both16: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/10 07:58:30 DEBUG : both16: Unchanged skipping 2025/03/10 07:58:30 DEBUG : both17: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/10 07:58:30 DEBUG : both17: Unchanged skipping 2025/03/10 07:58:30 DEBUG : both18: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/10 07:58:30 DEBUG : both10: Unchanged skipping 2025/03/10 07:58:30 DEBUG : both19: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/10 07:58:30 DEBUG : both19: Unchanged skipping 2025/03/10 07:58:30 DEBUG : both2: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/10 07:58:30 DEBUG : both2: Unchanged skipping 2025/03/10 07:58:30 DEBUG : both3: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/10 07:58:30 DEBUG : both3: Unchanged skipping 2025/03/10 07:58:30 DEBUG : both4: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/10 07:58:30 DEBUG : both4: Unchanged skipping 2025/03/10 07:58:30 DEBUG : both5: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/10 07:58:30 DEBUG : both14: Unchanged skipping 2025/03/10 07:58:30 DEBUG : both6: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/10 07:58:30 DEBUG : both6: Unchanged skipping 2025/03/10 07:58:30 DEBUG : both7: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/10 07:58:30 DEBUG : both7: Unchanged skipping 2025/03/10 07:58:30 DEBUG : both8: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/10 07:58:30 DEBUG : both15: Unchanged skipping 2025/03/10 07:58:30 DEBUG : both9: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/10 07:58:30 DEBUG : both9: Unchanged skipping 2025/03/10 07:58:30 DEBUG : both18: Unchanged skipping 2025/03/10 07:58:30 DEBUG : both5: Unchanged skipping 2025/03/10 07:58:30 DEBUG : both8: Unchanged skipping 2025/03/10 07:58:30 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for transfers to finish 2025/03/10 07:58:30 DEBUG : Waiting for deletions to finish 2025/03/10 07:58:30 INFO : only19: Deleted 2025/03/10 07:58:30 INFO : only5: Deleted 2025/03/10 07:58:30 INFO : only16: Deleted 2025/03/10 07:58:30 INFO : only3: Deleted 2025/03/10 07:58:31 INFO : only0: Deleted 2025/03/10 07:58:31 INFO : only10: Deleted 2025/03/10 07:58:31 INFO : only15: Deleted 2025/03/10 07:58:31 INFO : only11: Deleted 2025/03/10 07:58:31 INFO : only8: Deleted 2025/03/10 07:58:31 INFO : only7: Deleted 2025/03/10 07:58:31 INFO : only9: Deleted 2025/03/10 07:58:31 INFO : only6: Deleted 2025/03/10 07:58:32 INFO : only18: Deleted 2025/03/10 07:58:32 INFO : only12: Deleted 2025/03/10 07:58:32 INFO : only2: Deleted 2025/03/10 07:58:32 INFO : only4: Deleted 2025/03/10 07:58:32 INFO : only1: Deleted 2025/03/10 07:58:32 INFO : only13: Deleted 2025/03/10 07:58:32 INFO : only14: Deleted 2025/03/10 07:58:32 INFO : only17: Deleted 2025/03/10 07:58:32 INFO : There was nothing to transfer run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" --- PASS: TestSyncConcurrentDelete (69.87s) === RUN TestSyncConcurrentTruncate run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 07:58:45 DEBUG : both0: md5 = 67022604ec06c07a72a9dfac50c14cf7 OK 2025/03/10 07:58:46 DEBUG : only0: md5 = 9a5d8b19e3df55810baa04563304377f OK 2025/03/10 07:58:48 DEBUG : both1: md5 = e329c625b2dac361edfff4ff95b4d63d OK 2025/03/10 07:58:49 DEBUG : only1: md5 = 8ee984b37683ea419dfc9d60b2a7325c OK 2025/03/10 07:58:50 DEBUG : both2: md5 = 0555574596f816bc3723b0dac8823a52 OK 2025/03/10 07:58:52 DEBUG : only2: md5 = 0fd5f7f34628fd4b6603d55bc68725c8 OK 2025/03/10 07:58:53 DEBUG : both3: md5 = 8d717ad8e922f05db4aab138c61ae0b9 OK 2025/03/10 07:58:54 DEBUG : only3: md5 = 848b0e114aaec8287a2e59fffbad6cb8 OK 2025/03/10 07:58:56 DEBUG : both4: md5 = 968439a227cfcf245a52f43db63b4169 OK 2025/03/10 07:58:57 DEBUG : only4: md5 = 89ed0042d1b3c3044be25f0c108a965a OK 2025/03/10 07:58:59 DEBUG : both5: md5 = 715b3da600de06cad1dbc06baf8d6d3b OK 2025/03/10 07:59:00 DEBUG : only5: md5 = 8ca986a8acb69e287a8acb9b892cfb84 OK 2025/03/10 07:59:01 DEBUG : both6: md5 = 0e20cf5f409bc91ac3ddc684eea94e88 OK 2025/03/10 07:59:03 DEBUG : only6: md5 = ef223cc54e3b4cd6f0caa992559d580e OK 2025/03/10 07:59:04 DEBUG : both7: md5 = 3c325ef9be98d92374b550ec9d56a7fa OK 2025/03/10 07:59:06 DEBUG : only7: md5 = 70e164fe96664f113e08f3fe1ab437ab OK 2025/03/10 07:59:07 DEBUG : both8: md5 = 63fc3fef82624fad903e2733c21a3986 OK 2025/03/10 07:59:09 DEBUG : only8: md5 = f81dccd3bb2bf5c54016ef250b3aa108 OK 2025/03/10 07:59:10 DEBUG : both9: md5 = 99ed3026e31fe3f7b26f9ba1876c117a OK 2025/03/10 07:59:11 DEBUG : only9: md5 = 718856f70a152645b79b3bbad72d082e OK 2025/03/10 07:59:13 DEBUG : both10: md5 = 2872a213922e6dd9373ad0e4ec1331d8 OK 2025/03/10 07:59:14 DEBUG : only10: md5 = ed91f8e2955fac6b8f9c5a49d9d7cb36 OK 2025/03/10 07:59:16 DEBUG : both11: md5 = 33484a0aad38ebf433da1eb7107764d2 OK 2025/03/10 07:59:17 DEBUG : only11: md5 = 3a7f1b5bc8cc51aba45af521125525ea OK 2025/03/10 07:59:19 DEBUG : both12: md5 = 93e7edcb784d940c86445e7c7224b22b OK 2025/03/10 07:59:20 DEBUG : only12: md5 = 5a82cdddfc7b3a2db6e43098996076e4 OK 2025/03/10 07:59:21 DEBUG : both13: md5 = 7edc59dc482cc33f68c65e49403cb2ed OK 2025/03/10 07:59:23 DEBUG : only13: md5 = fc65ee54df548ce1d21398d803e74f08 OK 2025/03/10 07:59:24 DEBUG : both14: md5 = 08220cf1905ec601976cd9619f44354d OK 2025/03/10 07:59:26 DEBUG : only14: md5 = 0e7718a2e701a3a6076f9c59b968bf2f OK 2025/03/10 07:59:27 DEBUG : both15: md5 = 7cba0a3debea68ab16cdccd26c05182a OK 2025/03/10 07:59:29 DEBUG : only15: md5 = c093ee227393c83dece9167ad5f789d4 OK 2025/03/10 07:59:30 DEBUG : both16: md5 = 3c50a8d301bdefdd31596ca0e848cf87 OK 2025/03/10 07:59:31 DEBUG : only16: md5 = 1574ba58a33aa7d68b1d68d1d4c7a6d0 OK 2025/03/10 07:59:33 DEBUG : both17: md5 = b009bf3794428bfe78d04ea0e81305fa OK 2025/03/10 07:59:34 DEBUG : only17: md5 = ca9dee2e32af85b9cb40884b22b79400 OK 2025/03/10 07:59:36 DEBUG : both18: md5 = b3a81dac251b75cc7e5887221565c93e OK 2025/03/10 07:59:37 DEBUG : only18: md5 = 5fbb81439d51f587d5a272d89dfbd018 OK 2025/03/10 07:59:38 DEBUG : both19: md5 = 9ae5ff10a0947eff1742cf444023b004 OK 2025/03/10 07:59:40 DEBUG : only19: md5 = da7ac6d93a73d1a1dcb6a78730c3036f OK 2025/03/10 07:59:40 DEBUG : both0: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/10 07:59:40 DEBUG : both1: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/10 07:59:40 DEBUG : both10: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/10 07:59:40 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for checks to finish 2025/03/10 07:59:40 DEBUG : both11: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/10 07:59:40 DEBUG : both0: Unchanged skipping 2025/03/10 07:59:40 DEBUG : both12: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/10 07:59:40 DEBUG : both1: Unchanged skipping 2025/03/10 07:59:40 DEBUG : both13: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/10 07:59:40 DEBUG : both10: Unchanged skipping 2025/03/10 07:59:40 DEBUG : both14: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/10 07:59:40 DEBUG : both11: Unchanged skipping 2025/03/10 07:59:40 DEBUG : both15: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/10 07:59:40 DEBUG : both15: Unchanged skipping 2025/03/10 07:59:40 DEBUG : both16: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/10 07:59:40 DEBUG : both12: Unchanged skipping 2025/03/10 07:59:40 DEBUG : both17: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/10 07:59:40 DEBUG : both17: Unchanged skipping 2025/03/10 07:59:40 DEBUG : both18: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/10 07:59:40 DEBUG : both18: Unchanged skipping 2025/03/10 07:59:40 DEBUG : both19: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/10 07:59:40 DEBUG : both19: Unchanged skipping 2025/03/10 07:59:40 DEBUG : both2: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/10 07:59:40 DEBUG : both13: Unchanged skipping 2025/03/10 07:59:40 DEBUG : both3: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/10 07:59:40 DEBUG : both3: Unchanged skipping 2025/03/10 07:59:40 DEBUG : both4: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/10 07:59:40 DEBUG : both4: Unchanged skipping 2025/03/10 07:59:40 DEBUG : both5: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/10 07:59:40 DEBUG : both5: Unchanged skipping 2025/03/10 07:59:40 DEBUG : both6: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/10 07:59:40 DEBUG : both6: Unchanged skipping 2025/03/10 07:59:40 DEBUG : both7: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/10 07:59:40 DEBUG : both7: Unchanged skipping 2025/03/10 07:59:40 DEBUG : both8: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/10 07:59:40 DEBUG : both8: Unchanged skipping 2025/03/10 07:59:40 DEBUG : both9: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2025/03/10 07:59:40 DEBUG : both9: Unchanged skipping 2025/03/10 07:59:40 DEBUG : only0: Sizes differ (src 0 vs dst 6) 2025/03/10 07:59:40 DEBUG : only1: Sizes differ (src 0 vs dst 6) 2025/03/10 07:59:40 DEBUG : only10: Sizes differ (src 0 vs dst 6) 2025/03/10 07:59:40 DEBUG : only11: Sizes differ (src 0 vs dst 6) 2025/03/10 07:59:40 DEBUG : only12: Sizes differ (src 0 vs dst 6) 2025/03/10 07:59:40 DEBUG : only13: Sizes differ (src 0 vs dst 6) 2025/03/10 07:59:40 DEBUG : only14: Sizes differ (src 0 vs dst 6) 2025/03/10 07:59:40 DEBUG : only15: Sizes differ (src 0 vs dst 6) 2025/03/10 07:59:40 DEBUG : only16: Sizes differ (src 0 vs dst 6) 2025/03/10 07:59:40 DEBUG : only17: Sizes differ (src 0 vs dst 6) 2025/03/10 07:59:40 DEBUG : only18: Sizes differ (src 0 vs dst 6) 2025/03/10 07:59:40 DEBUG : only19: Sizes differ (src 0 vs dst 6) 2025/03/10 07:59:40 DEBUG : only2: Sizes differ (src 0 vs dst 6) 2025/03/10 07:59:40 DEBUG : only3: Sizes differ (src 0 vs dst 6) 2025/03/10 07:59:40 DEBUG : only4: Sizes differ (src 0 vs dst 6) 2025/03/10 07:59:40 DEBUG : only5: Sizes differ (src 0 vs dst 6) 2025/03/10 07:59:40 DEBUG : only6: Sizes differ (src 0 vs dst 6) 2025/03/10 07:59:40 DEBUG : only7: Sizes differ (src 0 vs dst 6) 2025/03/10 07:59:40 DEBUG : both14: Unchanged skipping 2025/03/10 07:59:40 DEBUG : only8: Sizes differ (src 0 vs dst 6) 2025/03/10 07:59:40 DEBUG : only9: Sizes differ (src 0 vs dst 6) 2025/03/10 07:59:40 DEBUG : both16: Unchanged skipping 2025/03/10 07:59:40 DEBUG : both2: Unchanged skipping 2025/03/10 07:59:40 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Waiting for transfers to finish 2025/03/10 07:59:41 DEBUG : only11: md5 = 75777d4f0cf146d8287a42f6d029b59b OK 2025/03/10 07:59:41 INFO : only11: Copied (replaced existing) 2025/03/10 07:59:41 DEBUG : only0: md5 = 0593057743ae74b5c8eb8b28032b5f98 OK 2025/03/10 07:59:41 INFO : only0: Copied (replaced existing) 2025/03/10 07:59:41 DEBUG : only10: md5 = 9ac8cd30fcd65dbd987fb52c7f4f7bc9 OK 2025/03/10 07:59:41 INFO : only10: Copied (replaced existing) 2025/03/10 07:59:41 DEBUG : only1: md5 = df551d1c9c5b67c134aa90d747a6cd00 OK 2025/03/10 07:59:41 INFO : only1: Copied (replaced existing) 2025/03/10 07:59:42 DEBUG : only13: md5 = b5f59dfde633f6c09291bd5810c3467b OK 2025/03/10 07:59:42 INFO : only13: Copied (replaced existing) 2025/03/10 07:59:43 DEBUG : only12: md5 = 26c8d8014a4d7ff73c237052b9961a32 OK 2025/03/10 07:59:43 INFO : only12: Copied (replaced existing) 2025/03/10 07:59:43 DEBUG : only15: md5 = 71e1442dcd3c6c67aaecbc009914f67e OK 2025/03/10 07:59:43 INFO : only15: Copied (replaced existing) 2025/03/10 07:59:43 DEBUG : only14: md5 = 99dd706d45cdfa91461eba8445114fa9 OK 2025/03/10 07:59:43 INFO : only14: Copied (replaced existing) 2025/03/10 07:59:44 DEBUG : only18: md5 = bd5129233947c35268cb9c4946f230f1 OK 2025/03/10 07:59:44 INFO : only18: Copied (replaced existing) 2025/03/10 07:59:44 DEBUG : only16: md5 = e7d14ea11ec0898db1c71730e56d918a OK 2025/03/10 07:59:44 INFO : only16: Copied (replaced existing) 2025/03/10 07:59:44 DEBUG : only17: md5 = 2d62906a8d48b8baab5afe416130878c OK 2025/03/10 07:59:44 INFO : only17: Copied (replaced existing) 2025/03/10 07:59:45 DEBUG : only19: md5 = 9b14686e8febfb839c2d98a4789ecd86 OK 2025/03/10 07:59:45 INFO : only19: Copied (replaced existing) 2025/03/10 07:59:45 DEBUG : only3: md5 = b69c7017290685ab559da525be463eb8 OK 2025/03/10 07:59:45 INFO : only3: Copied (replaced existing) 2025/03/10 07:59:45 DEBUG : only2: md5 = b3ee0d881c932c3201d484c0cc9f67bd OK 2025/03/10 07:59:45 INFO : only2: Copied (replaced existing) 2025/03/10 07:59:45 DEBUG : only4: md5 = 4145582a299373b3d4472c025f744b5c OK 2025/03/10 07:59:45 INFO : only4: Copied (replaced existing) 2025/03/10 07:59:46 DEBUG : only5: md5 = a2bccc1a9b6446fcb1ddf4382cb04046 OK 2025/03/10 07:59:46 INFO : only5: Copied (replaced existing) 2025/03/10 07:59:46 DEBUG : only6: md5 = e44af202b94ace7b0216955103bea227 OK 2025/03/10 07:59:46 INFO : only6: Copied (replaced existing) 2025/03/10 07:59:46 DEBUG : only7: md5 = cc082611c07eb6c5686ff4729fbb8417 OK 2025/03/10 07:59:46 INFO : only7: Copied (replaced existing) 2025/03/10 07:59:47 DEBUG : only8: md5 = e439d4bcb79bb935847f1deba1b8d158 OK 2025/03/10 07:59:47 INFO : only8: Copied (replaced existing) 2025/03/10 07:59:47 DEBUG : only9: md5 = d5cbedf37fd99e65ac06af10d3fae6f1 OK 2025/03/10 07:59:47 INFO : only9: Copied (replaced existing) 2025/03/10 07:59:47 DEBUG : Waiting for deletions to finish run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" --- PASS: TestSyncConcurrentTruncate (84.79s) === RUN TestSyncReplaceDirModTime run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 08:00:08 DEBUG : empty_dir: Making directory with metadata 2025/03/10 08:00:08 INFO : empty_dir: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z) 2025/03/10 08:00:08 DEBUG : empty_on_remote: Making directory with metadata 2025/03/10 08:00:08 INFO : empty_on_remote: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z) 2025/03/10 08:00:08 DEBUG : empty_on_remote: Making directory with metadata 2025/03/10 08:00:09 INFO : empty_on_remote: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z) run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 08:00:14 INFO : test_dir1: Set directory modification time (using DirSetModTime) 2025/03/10 08:00:14 INFO : test_dir2: Set directory modification time (using DirSetModTime) 2025/03/10 08:00:14 INFO : test_dir2/sub_dir: Set directory modification time (using DirSetModTime) 2025/03/10 08:00:14 INFO : empty_on_remote: Set directory modification time (using DirSetModTime) run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 08:00:22 DEBUG : heqj02jg0dcqlem7gl0500bvp0/24g2k8bseitblkmqnie1ibl2s8: Rmdir: contains trashed file: "633fmaa0qic3kv3cladnu11pto" 2025/03/10 08:00:22 DEBUG : heqj02jg0dcqlem7gl0500bvp0: Rmdir: contains trashed file: "24g2k8bseitblkmqnie1ibl2s8" 2025/03/10 08:00:23 DEBUG : gq68srrpl0nnf394bgf7dbu9kc: Rmdir: contains trashed file: "d26uovf0miqhd1mu3c9jbseq00" --- PASS: TestSyncReplaceDirModTime (17.27s) === RUN TestSyncReplaceDirModTimeWithEmptyDirs run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 08:00:25 DEBUG : empty_dir: Making directory with metadata 2025/03/10 08:00:25 INFO : empty_dir: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z) 2025/03/10 08:00:25 DEBUG : empty_on_remote: Making directory with metadata 2025/03/10 08:00:25 INFO : empty_on_remote: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z) 2025/03/10 08:00:25 DEBUG : empty_on_remote: Making directory with metadata 2025/03/10 08:00:26 INFO : empty_on_remote: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z) run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 08:00:31 INFO : test_dir1: Set directory modification time (using DirSetModTime) 2025/03/10 08:00:31 INFO : test_dir2: Set directory modification time (using DirSetModTime) 2025/03/10 08:00:31 INFO : test_dir2/sub_dir: Set directory modification time (using DirSetModTime) 2025/03/10 08:00:31 INFO : empty_on_remote: Set directory modification time (using DirSetModTime) 2025/03/10 08:00:31 INFO : empty_dir: Set directory modification time (using DirSetModTime) run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 08:00:39 DEBUG : heqj02jg0dcqlem7gl0500bvp0/24g2k8bseitblkmqnie1ibl2s8: Rmdir: contains trashed file: "633fmaa0qic3kv3cladnu11pto" 2025/03/10 08:00:40 DEBUG : heqj02jg0dcqlem7gl0500bvp0: Rmdir: contains trashed file: "24g2k8bseitblkmqnie1ibl2s8" 2025/03/10 08:00:40 DEBUG : gq68srrpl0nnf394bgf7dbu9kc: Rmdir: contains trashed file: "d26uovf0miqhd1mu3c9jbseq00" --- PASS: TestSyncReplaceDirModTimeWithEmptyDirs (18.17s) === RUN TestNothingToTransferWithEmptyDirs run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 08:00:43 INFO : sub dir: Set directory modification time (using DirSetModTime) 2025/03/10 08:00:43 DEBUG : sub dir: Making directory with metadata 2025/03/10 08:00:44 INFO : sub dir: Made directory with metadata (mtime=2011-12-30T12:59:59Z) run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 08:01:02 INFO : sub dir2: Set directory modification time (using DirSetModTime) 2025/03/10 08:01:03 INFO : sub dir2: Set directory modification time (using DirSetModTime) 2025/03/10 08:01:03 INFO : sub dirEmpty/sub dirEmpty2: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z) 2025/03/10 08:01:03 INFO : sub dirEmpty: Set directory modification time (using DirSetModTime) run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 08:01:17 DEBUG : gcsdkq814sbtppue42dpsbg8ug: Rmdir: contains trashed file: "sjuo65gk5q3r1199jselk9k9o0" 2025/03/10 08:01:19 DEBUG : s0tvtpcbgsp8ufdmedqtvlq3hc/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak/37qp6d1gohacv723ij3brofbu8/i24n0ln37pa2hv8pctddeuh73o: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" 2025/03/10 08:01:20 DEBUG : s0tvtpcbgsp8ufdmedqtvlq3hc/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak/37qp6d1gohacv723ij3brofbu8: Rmdir: contains trashed file: "i24n0ln37pa2hv8pctddeuh73o" 2025/03/10 08:01:20 DEBUG : s0tvtpcbgsp8ufdmedqtvlq3hc/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak: Rmdir: contains trashed file: "37qp6d1gohacv723ij3brofbu8" 2025/03/10 08:01:21 DEBUG : s0tvtpcbgsp8ufdmedqtvlq3hc/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak: Rmdir: contains trashed file: "jefmjbgpu25gb7gcub4i80nlak" 2025/03/10 08:01:22 DEBUG : s0tvtpcbgsp8ufdmedqtvlq3hc/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak: Rmdir: contains trashed file: "jefmjbgpu25gb7gcub4i80nlak" 2025/03/10 08:01:22 DEBUG : s0tvtpcbgsp8ufdmedqtvlq3hc/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak: Rmdir: contains trashed file: "jefmjbgpu25gb7gcub4i80nlak" 2025/03/10 08:01:23 DEBUG : s0tvtpcbgsp8ufdmedqtvlq3hc/jefmjbgpu25gb7gcub4i80nlak: Rmdir: contains trashed file: "jefmjbgpu25gb7gcub4i80nlak" 2025/03/10 08:01:24 DEBUG : s0tvtpcbgsp8ufdmedqtvlq3hc/4r13oncfa2rsrr82oqhsqv24ns: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" 2025/03/10 08:01:24 DEBUG : s0tvtpcbgsp8ufdmedqtvlq3hc: Rmdir: contains trashed file: "4r13oncfa2rsrr82oqhsqv24ns" 2025/03/10 08:01:24 DEBUG : s0tvtpcbgsp8ufdmedqtvlq3hc: Rmdir: contains trashed file: "jefmjbgpu25gb7gcub4i80nlak" 2025/03/10 08:01:25 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestNothingToTransferWithEmptyDirs (43.79s) === RUN TestNothingToTransferWithoutEmptyDirs run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 08:01:27 INFO : sub dir: Set directory modification time (using DirSetModTime) 2025/03/10 08:01:27 DEBUG : sub dir: Making directory with metadata 2025/03/10 08:01:28 INFO : sub dir: Made directory with metadata (mtime=2011-12-30T12:59:59Z) run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 08:01:50 INFO : sub dir2: Set directory modification time (using DirSetModTime) 2025/03/10 08:01:50 INFO : sub dir2: Set directory modification time (using DirSetModTime) 2025/03/10 08:01:50 INFO : sub dirEmpty/sub dirEmpty2: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z) 2025/03/10 08:01:50 INFO : sub dirEmpty: Set directory modification time (using DirSetModTime) run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude'", Local "Local file system at /tmp/rclone271460456", Modify Window "1ms" 2025/03/10 08:02:03 DEBUG : s0tvtpcbgsp8ufdmedqtvlq3hc/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak/37qp6d1gohacv723ij3brofbu8/i24n0ln37pa2hv8pctddeuh73o: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" 2025/03/10 08:02:04 DEBUG : s0tvtpcbgsp8ufdmedqtvlq3hc/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak/37qp6d1gohacv723ij3brofbu8: Rmdir: contains trashed file: "i24n0ln37pa2hv8pctddeuh73o" 2025/03/10 08:02:05 DEBUG : s0tvtpcbgsp8ufdmedqtvlq3hc/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak: Rmdir: contains trashed file: "37qp6d1gohacv723ij3brofbu8" 2025/03/10 08:02:05 DEBUG : s0tvtpcbgsp8ufdmedqtvlq3hc/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak: Rmdir: contains trashed file: "jefmjbgpu25gb7gcub4i80nlak" 2025/03/10 08:02:06 DEBUG : s0tvtpcbgsp8ufdmedqtvlq3hc/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak: Rmdir: contains trashed file: "jefmjbgpu25gb7gcub4i80nlak" 2025/03/10 08:02:07 DEBUG : s0tvtpcbgsp8ufdmedqtvlq3hc/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak: Rmdir: contains trashed file: "jefmjbgpu25gb7gcub4i80nlak" 2025/03/10 08:02:07 DEBUG : s0tvtpcbgsp8ufdmedqtvlq3hc/jefmjbgpu25gb7gcub4i80nlak: Rmdir: contains trashed file: "jefmjbgpu25gb7gcub4i80nlak" 2025/03/10 08:02:08 DEBUG : s0tvtpcbgsp8ufdmedqtvlq3hc/4r13oncfa2rsrr82oqhsqv24ns: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" 2025/03/10 08:02:09 DEBUG : s0tvtpcbgsp8ufdmedqtvlq3hc: Rmdir: contains trashed file: "4r13oncfa2rsrr82oqhsqv24ns" 2025/03/10 08:02:09 DEBUG : s0tvtpcbgsp8ufdmedqtvlq3hc: Rmdir: contains trashed file: "jefmjbgpu25gb7gcub4i80nlak" 2025/03/10 08:02:09 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestNothingToTransferWithoutEmptyDirs (44.25s) PASS 2025/03/10 08:02:11 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vetikis9xude': Purge remote "./sync.test -test.v -test.timeout 1h0m0s -remote TestCryptDrive: -verbose -fast-list" - Finished OK in 16m3.801367149s (try 1/5)