"./sync.test -test.v -test.timeout 1h0m0s -remote TestCryptDrive: -verbose" - Starting (try 1/5) 2024/04/26 01:37:14 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7" 2024/04/26 01:37:14 DEBUG : Using config file from "/home/rclone/.rclone.conf" 2024/04/26 01:37:14 DEBUG : Creating backend with remote "TestDrive:crypt/i82nm4fm1mic70fi1jf5dgvps1ph404sg69dve7khefh6dplf6dl19cul3rrof4h01l559enj97tc" 2024/04/26 01:37:15 DEBUG : Creating backend with remote "/tmp/rclone1262246716" === RUN TestPipe --- PASS: TestPipe (0.00s) === RUN TestPipeConcurrent --- PASS: TestPipeConcurrent (0.03s) === RUN TestPipeOrderBy === RUN TestPipeOrderBy/#00 === RUN TestPipeOrderBy/size === RUN TestPipeOrderBy/name === RUN TestPipeOrderBy/modtime === RUN TestPipeOrderBy/size,ascending === RUN TestPipeOrderBy/name,asc === RUN TestPipeOrderBy/modtime,ascending === RUN TestPipeOrderBy/size,descending === RUN TestPipeOrderBy/name,desc === RUN TestPipeOrderBy/modtime,descending === RUN TestPipeOrderBy/size,mixed,50 === RUN TestPipeOrderBy/size,mixed,51 --- PASS: TestPipeOrderBy (0.00s) --- PASS: TestPipeOrderBy/#00 (0.00s) --- PASS: TestPipeOrderBy/size (0.00s) --- PASS: TestPipeOrderBy/name (0.00s) --- PASS: TestPipeOrderBy/modtime (0.00s) --- PASS: TestPipeOrderBy/size,ascending (0.00s) --- PASS: TestPipeOrderBy/name,asc (0.00s) --- PASS: TestPipeOrderBy/modtime,ascending (0.00s) --- PASS: TestPipeOrderBy/size,descending (0.00s) --- PASS: TestPipeOrderBy/name,desc (0.00s) --- PASS: TestPipeOrderBy/modtime,descending (0.00s) --- PASS: TestPipeOrderBy/size,mixed,50 (0.00s) --- PASS: TestPipeOrderBy/size,mixed,51 (0.00s) === RUN TestNewLess === RUN TestNewLess/blankOK === RUN TestNewLess/tooManyParts === RUN TestNewLess/tooManyParts2 === RUN TestNewLess/badMixed === RUN TestNewLess/unknownComparison === RUN TestNewLess/unknownSortDirection === RUN TestNewLess/size === RUN TestNewLess/name === RUN TestNewLess/modtime === RUN TestNewLess/size,ascending === RUN TestNewLess/name,asc === RUN TestNewLess/modtime,ascending === RUN TestNewLess/size,descending === RUN TestNewLess/name,desc === RUN TestNewLess/modtime,descending === RUN TestNewLess/modtime,mixed === RUN TestNewLess/modtime,mixed,30 --- PASS: TestNewLess (0.00s) --- PASS: TestNewLess/blankOK (0.00s) --- PASS: TestNewLess/tooManyParts (0.00s) --- PASS: TestNewLess/tooManyParts2 (0.00s) --- PASS: TestNewLess/badMixed (0.00s) --- PASS: TestNewLess/unknownComparison (0.00s) --- PASS: TestNewLess/unknownSortDirection (0.00s) --- PASS: TestNewLess/size (0.00s) --- PASS: TestNewLess/name (0.00s) --- PASS: TestNewLess/modtime (0.00s) --- PASS: TestNewLess/size,ascending (0.00s) --- PASS: TestNewLess/name,asc (0.00s) --- PASS: TestNewLess/modtime,ascending (0.00s) --- PASS: TestNewLess/size,descending (0.00s) --- PASS: TestNewLess/name,desc (0.00s) --- PASS: TestNewLess/modtime,descending (0.00s) --- PASS: TestNewLess/modtime,mixed (0.00s) --- PASS: TestNewLess/modtime,mixed,30 (0.00s) === RUN TestRcCopy rc_test.go:16: Skipping test on non local remote --- SKIP: TestRcCopy (0.00s) === RUN TestRcMove rc_test.go:16: Skipping test on non local remote --- SKIP: TestRcMove (0.00s) === RUN TestRcSync rc_test.go:16: Skipping test on non local remote --- SKIP: TestRcSync (0.00s) === RUN TestCopyWithDryRun run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:37:17 NOTICE: sub dir: Skipped make directory as --dry-run is set 2024/04/26 01:37:17 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2024/04/26 01:37:17 NOTICE: sub dir/hello world: Skipped copy as --dry-run is set (size 11) 2024/04/26 01:37:17 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for checks to finish 2024/04/26 01:37:17 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for transfers to finish run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" --- PASS: TestCopyWithDryRun (2.88s) === RUN TestCopy run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:37:18 INFO : sub dir: Set directory modification time (using DirSetModTime) 2024/04/26 01:37:18 DEBUG : sub dir: Making directory with metadata 2024/04/26 01:37:19 INFO : sub dir: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z) 2024/04/26 01:37:19 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2024/04/26 01:37:19 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for checks to finish 2024/04/26 01:37:19 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for transfers to finish 2024/04/26 01:37:21 DEBUG : sub dir/hello world: md5 = a68d60a111bba9f5a5dd734d4edb4f75 OK 2024/04/26 01:37:21 INFO : sub dir/hello world: Copied (new) run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:37:24 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestCopy (7.87s) === RUN TestCopyMetadata run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:37:26 DEBUG : metadata sub dir: Making directory with metadata 2024/04/26 01:37:26 INFO : metadata sub dir: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z) 2024/04/26 01:37:26 DEBUG : Local file system at /tmp/rclone1262246716: File to upload is small (21 bytes), uploading instead of streaming 2024/04/26 01:37:26 DEBUG : metadata sub dir/hello metadata world: md5 = baa7a013449dbba2b1ed02b5cfb4e1a2 OK 2024/04/26 01:37:26 DEBUG : metadata sub dir/hello metadata world.mahewek0.partial: renamed to: metadata sub dir/hello metadata world 2024/04/26 01:37:26 INFO : metadata sub dir/hello metadata world: Copied (new) 2024/04/26 01:37:26 INFO : metadata sub dir: Set directory modification time (using DirSetModTime) 2024/04/26 01:37:26 DEBUG : Google drive root 'crypt/i82nm4fm1mic70fi1jf5dgvps1ph404sg69dve7khefh6dplf6dl19cul3rrof4h01l559enj97tc': Skipping btime metadata as can't update it on an existing file: 2024-04-26T01:37:26.268028313Z 2024/04/26 01:37:27 INFO : metadata sub dir: Updated directory metadata 2024/04/26 01:37:27 DEBUG : metadata sub dir/hello metadata world: Need to transfer - File not found at Destination 2024/04/26 01:37:27 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for checks to finish 2024/04/26 01:37:27 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for transfers to finish 2024/04/26 01:37:29 DEBUG : metadata sub dir/hello metadata world: md5 = d3cf2633991030f8464ed6de3de4e5ee OK 2024/04/26 01:37:29 INFO : metadata sub dir/hello metadata world: Copied (new) run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:37:32 DEBUG : fg45q1rm3kh00nmmkk4m6ihmrcnel1p7551kqhjr9bk2gtd2gbf0: Rmdir: contains trashed file: "dmuvulfij81f693ur0f1vvbvq9v6iscp56daas3m51n9li5e3470" --- PASS: TestCopyMetadata (8.16s) === RUN TestCopyMissingDirectory run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:37:34 DEBUG : Creating backend with remote "/non-existing" 2024/04/26 01:37:34 ERROR : Local file system at /non-existing: error reading source root directory: directory not found 2024/04/26 01:37:34 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for checks to finish 2024/04/26 01:37:34 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for transfers to finish run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" --- PASS: TestCopyMissingDirectory (1.42s) === RUN TestCopyNoTraverse run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:37:35 DEBUG : sub dir: Making directory with metadata 2024/04/26 01:37:37 INFO : sub dir: Made directory with metadata (mtime=2024-04-26T01:37:35.85203056Z) 2024/04/26 01:37:37 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2024/04/26 01:37:37 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for checks to finish 2024/04/26 01:37:37 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for transfers to finish 2024/04/26 01:37:39 DEBUG : sub dir/hello world: md5 = 436d866be7660e1c48e32e801fd900c1 OK 2024/04/26 01:37:39 INFO : sub dir/hello world: Copied (new) run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:37:41 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestCopyNoTraverse (7.28s) === RUN TestCopyCheckFirst run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:37:43 INFO : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Running all checks before starting transfers 2024/04/26 01:37:43 DEBUG : sub dir: Making directory with metadata 2024/04/26 01:37:44 INFO : sub dir: Made directory with metadata (mtime=2024-04-26T01:37:43.13603225Z) 2024/04/26 01:37:44 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2024/04/26 01:37:44 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for checks to finish 2024/04/26 01:37:44 INFO : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Checks finished, now starting transfers 2024/04/26 01:37:44 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for transfers to finish 2024/04/26 01:37:46 DEBUG : sub dir/hello world: md5 = 3a96a2c4fb2f2832d1ec217923bf4eac OK 2024/04/26 01:37:46 INFO : sub dir/hello world: Copied (new) run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:37:48 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestCopyCheckFirst (7.32s) === RUN TestSyncNoTraverse run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:37:50 ERROR : Ignoring --no-traverse with sync 2024/04/26 01:37:50 DEBUG : sub dir: Making directory with metadata 2024/04/26 01:37:52 INFO : sub dir: Made directory with metadata (mtime=2024-04-26T01:37:50.460033936Z) 2024/04/26 01:37:52 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2024/04/26 01:37:52 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for checks to finish 2024/04/26 01:37:52 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for transfers to finish 2024/04/26 01:37:53 DEBUG : sub dir/hello world: md5 = 070e1983e88fe4642acf7e6919822070 OK 2024/04/26 01:37:53 INFO : sub dir/hello world: Copied (new) 2024/04/26 01:37:53 DEBUG : Waiting for deletions to finish run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:37:55 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestSyncNoTraverse (6.98s) === RUN TestCopyWithDepth run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:37:57 DEBUG : hello world2: Need to transfer - File not found at Destination 2024/04/26 01:37:57 DEBUG : sub dir: Making directory with metadata 2024/04/26 01:37:59 INFO : sub dir: Made directory with metadata (mtime=2024-04-26T01:37:57.436035529Z) 2024/04/26 01:37:59 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for checks to finish 2024/04/26 01:37:59 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for transfers to finish 2024/04/26 01:38:00 DEBUG : hello world2: md5 = 18aba0bdb338f1ee23c5734680643b5c OK 2024/04/26 01:38:00 INFO : hello world2: Copied (new) run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" --- PASS: TestCopyWithDepth (6.16s) === RUN TestCopyWithFilesFrom run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:38:03 DEBUG : potato2: Need to transfer - File not found at Destination 2024/04/26 01:38:03 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for checks to finish 2024/04/26 01:38:03 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for transfers to finish 2024/04/26 01:38:05 DEBUG : potato2: md5 = 7018d7ae67ad55840a7748b36403632b OK 2024/04/26 01:38:05 INFO : potato2: Copied (new) run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" --- PASS: TestCopyWithFilesFrom (4.34s) === RUN TestCopyWithFilesFromAndNoTraverse run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:38:08 DEBUG : potato2: Need to transfer - File not found at Destination 2024/04/26 01:38:08 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for checks to finish 2024/04/26 01:38:08 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for transfers to finish 2024/04/26 01:38:10 DEBUG : potato2: md5 = 583ed545308343f22e3ee0aeac06c35b OK 2024/04/26 01:38:10 INFO : potato2: Copied (new) run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" --- PASS: TestCopyWithFilesFromAndNoTraverse (4.93s) === RUN TestCopyEmptyDirectories run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:38:12 DEBUG : sub dir2: Making directory with metadata 2024/04/26 01:38:12 INFO : sub dir2: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z) 2024/04/26 01:38:12 INFO : sub dir: Set directory modification time (using DirSetModTime) 2024/04/26 01:38:13 DEBUG : sub dir: Making directory with metadata 2024/04/26 01:38:14 INFO : sub dir: Made directory with metadata (mtime=2001-02-03T04:05:06.499999999Z) 2024/04/26 01:38:14 DEBUG : sub dir2: Making directory with metadata 2024/04/26 01:38:15 INFO : sub dir2: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z) 2024/04/26 01:38:15 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2024/04/26 01:38:15 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for checks to finish 2024/04/26 01:38:15 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for transfers to finish 2024/04/26 01:38:17 DEBUG : sub dir/hello world: md5 = 24dca3caac4f567c2384b35f799ef591 OK 2024/04/26 01:38:17 INFO : sub dir/hello world: Copied (new) 2024/04/26 01:38:17 DEBUG : sub dir2: Making directory 2024/04/26 01:38:17 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': copied 1 directories run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:38:21 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestCopyEmptyDirectories (10.80s) === RUN TestMoveEmptyDirectories run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:38:23 DEBUG : sub dir2: Making directory with metadata 2024/04/26 01:38:23 INFO : sub dir2: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z) 2024/04/26 01:38:23 DEBUG : sub dir: Making directory with metadata 2024/04/26 01:38:25 INFO : sub dir: Made directory with metadata (mtime=2024-04-26T01:38:23.652041407Z) 2024/04/26 01:38:25 DEBUG : sub dir2: Making directory with metadata 2024/04/26 01:38:26 INFO : sub dir2: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z) 2024/04/26 01:38:26 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2024/04/26 01:38:26 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for checks to finish 2024/04/26 01:38:26 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for transfers to finish 2024/04/26 01:38:28 DEBUG : sub dir/hello world: md5 = 9cdb41812f311b4e30360a048976b17a OK 2024/04/26 01:38:28 INFO : sub dir/hello world: Copied (new) 2024/04/26 01:38:28 INFO : sub dir/hello world: Deleted 2024/04/26 01:38:28 DEBUG : sub dir: Making directory 2024/04/26 01:38:28 DEBUG : sub dir2: Making directory 2024/04/26 01:38:28 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': copied 2 directories run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:38:31 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestMoveEmptyDirectories (9.77s) === RUN TestSyncNoUpdateDirModtime run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:38:33 DEBUG : sub dir no update dir modtime: Making directory with metadata 2024/04/26 01:38:33 INFO : sub dir no update dir modtime: Made directory with metadata (mtime=2001-02-03T04:05:06.499999999Z) 2024/04/26 01:38:35 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for checks to finish 2024/04/26 01:38:35 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for transfers to finish 2024/04/26 01:38:35 DEBUG : Waiting for deletions to finish run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" --- PASS: TestSyncNoUpdateDirModtime (5.14s) === RUN TestSyncEmptyDirectories run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:38:38 DEBUG : sub dir2: Making directory with metadata 2024/04/26 01:38:38 INFO : sub dir2: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z) 2024/04/26 01:38:38 INFO : sub dir: Set directory modification time (using DirSetModTime) 2024/04/26 01:38:38 DEBUG : sub dir: Making directory with metadata 2024/04/26 01:38:40 INFO : sub dir: Made directory with metadata (mtime=2001-02-03T04:05:06.499999999Z) 2024/04/26 01:38:40 DEBUG : sub dir2: Making directory with metadata 2024/04/26 01:38:41 INFO : sub dir2: Made directory with metadata (mtime=2011-12-25T12:59:59.123456789Z) 2024/04/26 01:38:41 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2024/04/26 01:38:41 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for checks to finish 2024/04/26 01:38:41 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for transfers to finish 2024/04/26 01:38:43 DEBUG : sub dir/hello world: md5 = a4d3d7e8850c4a5102bbc11e01df3aba OK 2024/04/26 01:38:43 INFO : sub dir/hello world: Copied (new) 2024/04/26 01:38:43 DEBUG : sub dir2: Making directory 2024/04/26 01:38:43 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': copied 1 directories 2024/04/26 01:38:43 DEBUG : Waiting for deletions to finish run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:38:47 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestSyncEmptyDirectories (10.85s) === RUN TestSyncSetDelayedModTimes run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" sync_test.go:427: Backend doesn't have DirModTimeUpdatesOnWrite set --- SKIP: TestSyncSetDelayedModTimes (0.52s) === RUN TestServerSideCopy run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:38:53 DEBUG : sub dir/hello world: md5 = b03822cdaa8bfb990bd83cdd4241ca34 OK 2024/04/26 01:38:53 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-suzokog4poduqux5tokiwiq4" 2024/04/26 01:38:53 DEBUG : Creating backend with remote "TestDrive:crypt/q4die7l0et5uh1inrmg25a2jeitkekr4n1jtd3pbo7dkujri7n6tdep2kvlocipjbd4km0vt98tve" sync_test.go:487: Server side copy (if possible) Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7' -> Encrypted drive 'TestCryptDrive:rclone-test-suzokog4poduqux5tokiwiq4' 2024/04/26 01:38:55 DEBUG : sub dir: Making directory with metadata 2024/04/26 01:38:57 INFO : sub dir: Made directory with metadata (mtime=2024-04-26T01:38:50.551Z) 2024/04/26 01:38:57 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2024/04/26 01:38:57 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-suzokog4poduqux5tokiwiq4': Waiting for checks to finish 2024/04/26 01:38:57 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-suzokog4poduqux5tokiwiq4': Waiting for transfers to finish 2024/04/26 01:38:59 INFO : sub dir/hello world: Copied (server-side copy) run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:39:00 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-suzokog4poduqux5tokiwiq4': Purge remote 2024/04/26 01:39:02 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestServerSideCopy (14.27s) === RUN TestCopyAfterDelete run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:39:07 DEBUG : sub dir/hello world: md5 = d3a6aedc05b5dada05c5c03c19273e0b OK 2024/04/26 01:39:07 ERROR : : error listing: directory not found 2024/04/26 01:39:07 DEBUG : Local file system at /tmp/rclone1262246716: Making directory 2024/04/26 01:39:08 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for checks to finish 2024/04/26 01:39:08 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for transfers to finish run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:39:10 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestCopyAfterDelete (7.94s) === RUN TestCopyRedownload run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:39:15 DEBUG : sub dir/hello world: md5 = 5e6ddd4c961cb5a4255200a831c58d6e OK 2024/04/26 01:39:16 DEBUG : sub dir: Making directory with metadata 2024/04/26 01:39:16 INFO : sub dir: Made directory with metadata (mtime=2024-04-26T01:39:12.742Z) 2024/04/26 01:39:16 DEBUG : Added delayed dir = "sub dir", newDst=sub dir 2024/04/26 01:39:16 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2024/04/26 01:39:16 DEBUG : Local file system at /tmp/rclone1262246716: Waiting for checks to finish 2024/04/26 01:39:16 DEBUG : Local file system at /tmp/rclone1262246716: Waiting for transfers to finish 2024/04/26 01:39:17 DEBUG : sub dir/hello world.cayobox8.partial: renamed to: sub dir/hello world 2024/04/26 01:39:17 INFO : sub dir/hello world: Copied (new) 2024/04/26 01:39:17 INFO : sub dir: Set directory modification time (using SetModTime) run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:39:19 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestCopyRedownload (8.85s) === RUN TestSyncBasedOnCheckSum run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:39:21 DEBUG : check sum: Need to transfer - File not found at Destination 2024/04/26 01:39:21 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for checks to finish 2024/04/26 01:39:21 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for transfers to finish 2024/04/26 01:39:23 DEBUG : check sum: md5 = a322e4107ed2c118e935a2e381ebadb8 OK 2024/04/26 01:39:23 INFO : check sum: Copied (new) 2024/04/26 01:39:23 DEBUG : Waiting for deletions to finish run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:39:23 NOTICE: Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': --checksum is in use but the source and destination have no hashes in common; falling back to --size-only 2024/04/26 01:39:23 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for checks to finish 2024/04/26 01:39:23 DEBUG : check sum: Size of src and dst objects identical 2024/04/26 01:39:23 DEBUG : check sum: Unchanged skipping 2024/04/26 01:39:23 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for transfers to finish 2024/04/26 01:39:23 DEBUG : Waiting for deletions to finish 2024/04/26 01:39:23 INFO : There was nothing to transfer run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" --- PASS: TestSyncBasedOnCheckSum (5.55s) === RUN TestSyncSizeOnly run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:39:26 DEBUG : sizeonly: Need to transfer - File not found at Destination 2024/04/26 01:39:26 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for checks to finish 2024/04/26 01:39:26 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for transfers to finish 2024/04/26 01:39:28 DEBUG : sizeonly: md5 = dfcfa833fa172c58ae863470c6a3a9b7 OK 2024/04/26 01:39:28 INFO : sizeonly: Copied (new) 2024/04/26 01:39:28 DEBUG : Waiting for deletions to finish run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:39:29 DEBUG : sizeonly: Sizes identical 2024/04/26 01:39:29 DEBUG : sizeonly: Unchanged skipping 2024/04/26 01:39:29 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for checks to finish 2024/04/26 01:39:29 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for transfers to finish 2024/04/26 01:39:29 DEBUG : Waiting for deletions to finish 2024/04/26 01:39:29 INFO : There was nothing to transfer run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" --- PASS: TestSyncSizeOnly (5.48s) === RUN TestSyncIgnoreSize run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:39:32 DEBUG : ignore-size: Need to transfer - File not found at Destination 2024/04/26 01:39:32 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for checks to finish 2024/04/26 01:39:32 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for transfers to finish 2024/04/26 01:39:34 DEBUG : ignore-size: md5 = 446558e109b725e4ba53050823aa0cd2 OK 2024/04/26 01:39:34 INFO : ignore-size: Copied (new) 2024/04/26 01:39:34 DEBUG : Waiting for deletions to finish run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:39:34 DEBUG : ignore-size: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/26 01:39:34 DEBUG : ignore-size: Unchanged skipping 2024/04/26 01:39:34 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for checks to finish 2024/04/26 01:39:34 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for transfers to finish 2024/04/26 01:39:34 DEBUG : Waiting for deletions to finish 2024/04/26 01:39:34 INFO : There was nothing to transfer run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" --- PASS: TestSyncIgnoreSize (5.59s) === RUN TestSyncIgnoreTimes run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:39:39 DEBUG : existing: md5 = 0ccbf83f3fa8aaf30e07b1e0880a69d2 OK 2024/04/26 01:39:40 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for checks to finish 2024/04/26 01:39:40 DEBUG : existing: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/26 01:39:40 DEBUG : existing: Unchanged skipping 2024/04/26 01:39:40 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for transfers to finish 2024/04/26 01:39:40 DEBUG : Waiting for deletions to finish 2024/04/26 01:39:40 INFO : There was nothing to transfer run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:39:40 DEBUG : existing: Transferring unconditionally as --ignore-times is in use 2024/04/26 01:39:40 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for checks to finish 2024/04/26 01:39:40 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for transfers to finish 2024/04/26 01:39:42 DEBUG : existing: md5 = c806cbba799ede30ca87eb4362c9ba4e OK 2024/04/26 01:39:42 INFO : existing: Copied (replaced existing) 2024/04/26 01:39:42 DEBUG : Waiting for deletions to finish run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" --- PASS: TestSyncIgnoreTimes (7.17s) === RUN TestSyncIgnoreExisting run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:39:45 DEBUG : existing: Need to transfer - File not found at Destination 2024/04/26 01:39:45 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for checks to finish 2024/04/26 01:39:45 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for transfers to finish 2024/04/26 01:39:46 DEBUG : existing: md5 = 972dff71f314db69341510759028e4de OK 2024/04/26 01:39:46 INFO : existing: Copied (new) 2024/04/26 01:39:46 DEBUG : Waiting for deletions to finish run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:39:47 DEBUG : existing: Destination exists, skipping 2024/04/26 01:39:47 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for checks to finish 2024/04/26 01:39:47 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for transfers to finish 2024/04/26 01:39:47 DEBUG : Waiting for deletions to finish 2024/04/26 01:39:47 INFO : There was nothing to transfer run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" --- PASS: TestSyncIgnoreExisting (5.57s) === RUN TestSyncIgnoreErrors run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:39:53 DEBUG : b/potato: md5 = dcfc20a5445b1c4fb9f9f10977663d54 OK 2024/04/26 01:39:56 DEBUG : c/non empty space: md5 = 5b4afbae6aa1b44937873f794f9652fd OK 2024/04/26 01:39:56 DEBUG : d: Making directory 2024/04/26 01:39:59 DEBUG : a: Making directory with metadata 2024/04/26 01:40:00 INFO : a: Made directory with metadata (mtime=2024-04-26T01:39:50.352059698Z) 2024/04/26 01:40:01 INFO : c: Set directory modification time (using SetModTime) 2024/04/26 01:40:01 DEBUG : a/potato2: Need to transfer - File not found at Destination 2024/04/26 01:40:01 DEBUG : c/non empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2024/04/26 01:40:01 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for checks to finish 2024/04/26 01:40:01 DEBUG : c/non empty space: Unchanged skipping 2024/04/26 01:40:01 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for transfers to finish 2024/04/26 01:40:03 DEBUG : a/potato2: md5 = 4a403e6af325785c6707340d90d0e5af OK 2024/04/26 01:40:03 INFO : a/potato2: Copied (new) 2024/04/26 01:40:03 DEBUG : Waiting for deletions to finish 2024/04/26 01:40:03 INFO : b/potato: Deleted 2024/04/26 01:40:03 INFO : d: Removing directory 2024/04/26 01:40:04 INFO : b: Removing directory 2024/04/26 01:40:05 DEBUG : 32d8ua6196mc1r7qkfog53rkg0: Rmdir: contains trashed file: "2m507n64kafsi59v9q71r281a4" 2024/04/26 01:40:05 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': deleted 2 directories run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:40:08 DEBUG : 3i9du405pfogq3ncai6pg7ouio: Rmdir: contains trashed file: "982d3pss7t5pn0il16r2foj31s" 2024/04/26 01:40:09 DEBUG : 2bsvlrk2ne1lfitm6tttcu0qt8: Rmdir: contains trashed file: "89l8renevh3mji1c8r1p7qn6tg" --- PASS: TestSyncIgnoreErrors (21.19s) === RUN TestSyncAfterChangingModtimeOnly run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:40:13 DEBUG : empty space: md5 = fbb606b0098a4a4a86e022711377fb4f OK 2024/04/26 01:40:13 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for checks to finish 2024/04/26 01:40:13 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 2024/04/26 01:40:13 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for transfers to finish 2024/04/26 01:40:13 NOTICE: empty space: Skipped copy as --dry-run is set (size 1) 2024/04/26 01:40:13 DEBUG : Waiting for deletions to finish run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:40:14 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for checks to finish 2024/04/26 01:40:14 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 2024/04/26 01:40:14 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for transfers to finish 2024/04/26 01:40:16 DEBUG : empty space: md5 = 243788e4e9f3b7c6cb167c74146205e2 OK 2024/04/26 01:40:16 INFO : empty space: Copied (replaced existing) 2024/04/26 01:40:16 DEBUG : Waiting for deletions to finish run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" --- PASS: TestSyncAfterChangingModtimeOnly (7.39s) === RUN TestSyncAfterChangingModtimeOnlyWithNoUpdateModTime run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" sync_test.go:811: Can't check this if no hashes supported --- PASS: TestSyncAfterChangingModtimeOnlyWithNoUpdateModTime (0.57s) === RUN TestSyncDoesntUpdateModtime run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:40:21 DEBUG : foo: md5 = 07d88a521f9dd399c04a2f1a2b5d5475 OK 2024/04/26 01:40:21 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for checks to finish 2024/04/26 01:40:21 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 2024/04/26 01:40:21 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for transfers to finish 2024/04/26 01:40:23 DEBUG : foo: md5 = 1ecc0f51da2da632eb3af0c94acfa326 OK 2024/04/26 01:40:23 INFO : foo: Copied (replaced existing) 2024/04/26 01:40:23 DEBUG : Waiting for deletions to finish run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" --- PASS: TestSyncDoesntUpdateModtime (6.37s) === RUN TestSyncAfterAddingAFile run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:40:27 DEBUG : empty space: md5 = 06e04e8038c24a6c639c9da6fae24f3f OK 2024/04/26 01:40:28 DEBUG : potato: Need to transfer - File not found at Destination 2024/04/26 01:40:28 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for checks to finish 2024/04/26 01:40:28 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2024/04/26 01:40:28 DEBUG : empty space: Unchanged skipping 2024/04/26 01:40:28 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for transfers to finish 2024/04/26 01:40:30 DEBUG : potato: md5 = 762d571fcddcd094f03e91fdfbb903d8 OK 2024/04/26 01:40:30 INFO : potato: Copied (new) 2024/04/26 01:40:30 DEBUG : Waiting for deletions to finish run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" --- PASS: TestSyncAfterAddingAFile (7.07s) === RUN TestSyncAfterChangingFilesSizeOnly run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:40:34 DEBUG : potato: md5 = fd7bbb08c8a711f7ce6cee3f4751e48b OK 2024/04/26 01:40:35 DEBUG : potato: Sizes differ (src 21 vs dst 60) 2024/04/26 01:40:35 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for checks to finish 2024/04/26 01:40:35 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for transfers to finish 2024/04/26 01:40:37 DEBUG : potato: md5 = e54ec56e6e5bf54ad02bcd97609f804b OK 2024/04/26 01:40:37 INFO : potato: Copied (replaced existing) 2024/04/26 01:40:37 DEBUG : Waiting for deletions to finish run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" --- PASS: TestSyncAfterChangingFilesSizeOnly (6.23s) === RUN TestSyncAfterChangingContentsOnly run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:40:41 DEBUG : potato: md5 = a8fd2d950795e48ba15014ccb019c7d4 OK 2024/04/26 01:40:41 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for checks to finish 2024/04/26 01:40:41 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 2024/04/26 01:40:41 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for transfers to finish 2024/04/26 01:40:43 DEBUG : potato: md5 = be061972c09cb053c87723b711de988f OK 2024/04/26 01:40:43 INFO : potato: Copied (replaced existing) 2024/04/26 01:40:43 DEBUG : Waiting for deletions to finish run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" --- PASS: TestSyncAfterChangingContentsOnly (6.28s) === RUN TestSyncAfterRemovingAFileAndAddingAFileDryRun run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:40:47 DEBUG : potato: md5 = 01a048dc43a80ad011b772d3d9c1be8c OK 2024/04/26 01:40:49 DEBUG : empty space: md5 = 34ec3badcc00a30fd7befbb8cdad28b3 OK 2024/04/26 01:40:49 DEBUG : potato2: Need to transfer - File not found at Destination 2024/04/26 01:40:49 NOTICE: potato2: Skipped copy as --dry-run is set (size 60) 2024/04/26 01:40:49 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for checks to finish 2024/04/26 01:40:49 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2024/04/26 01:40:49 DEBUG : empty space: Unchanged skipping 2024/04/26 01:40:49 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for transfers to finish 2024/04/26 01:40:49 DEBUG : Waiting for deletions to finish 2024/04/26 01:40:49 NOTICE: potato: Skipped delete as --dry-run is set (size 21) run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" --- PASS: TestSyncAfterRemovingAFileAndAddingAFileDryRun (6.94s) === RUN TestSyncAfterRemovingAFileAndAddingAFile run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:40:54 DEBUG : potato: md5 = bfd381e6f2823e6ee6ad643c8d1c6bf2 OK 2024/04/26 01:40:56 DEBUG : empty space: md5 = f8959a05acb8efbbec9a140e2e8fc015 OK 2024/04/26 01:40:56 DEBUG : potato2: Need to transfer - File not found at Destination 2024/04/26 01:40:56 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for checks to finish 2024/04/26 01:40:56 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2024/04/26 01:40:56 DEBUG : empty space: Unchanged skipping 2024/04/26 01:40:56 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for transfers to finish 2024/04/26 01:40:58 DEBUG : potato2: md5 = 2663055105804c8f060b207787af242a OK 2024/04/26 01:40:58 INFO : potato2: Copied (new) 2024/04/26 01:40:58 DEBUG : Waiting for deletions to finish 2024/04/26 01:40:59 INFO : potato: Deleted run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" --- PASS: TestSyncAfterRemovingAFileAndAddingAFile (10.13s) === RUN TestSyncAfterRemovingAFileAndAddingAFileSubDir run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:41:05 DEBUG : b/potato: md5 = b684d1ada67d27bf3744aaecee9772e9 OK 2024/04/26 01:41:08 DEBUG : c/non empty space: md5 = 74c333ba835a8ff420c0b7af244d2801 OK 2024/04/26 01:41:08 DEBUG : d: Making directory 2024/04/26 01:41:09 DEBUG : d/e: Making directory 2024/04/26 01:41:12 DEBUG : a: Making directory with metadata 2024/04/26 01:41:13 INFO : a: Made directory with metadata (mtime=2024-04-26T01:41:02.51607374Z) 2024/04/26 01:41:14 INFO : c: Set directory modification time (using SetModTime) 2024/04/26 01:41:14 DEBUG : a/potato2: Need to transfer - File not found at Destination 2024/04/26 01:41:14 DEBUG : c/non empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2024/04/26 01:41:14 DEBUG : c/non empty space: Unchanged skipping 2024/04/26 01:41:14 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for checks to finish 2024/04/26 01:41:14 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for transfers to finish 2024/04/26 01:41:15 DEBUG : a/potato2: md5 = 2fcd64788fdd40da16a8fa0d85a62474 OK 2024/04/26 01:41:15 INFO : a/potato2: Copied (new) 2024/04/26 01:41:15 DEBUG : Waiting for deletions to finish 2024/04/26 01:41:16 INFO : b/potato: Deleted 2024/04/26 01:41:16 INFO : d/e: Removing directory 2024/04/26 01:41:17 INFO : d: Removing directory 2024/04/26 01:41:17 DEBUG : ka6id8d20d3s5ktapedlphgta8: Rmdir: contains trashed file: "r8sppajuabeak3sbgj2ak8vuf8" 2024/04/26 01:41:18 INFO : b: Removing directory 2024/04/26 01:41:18 DEBUG : 32d8ua6196mc1r7qkfog53rkg0: Rmdir: contains trashed file: "2m507n64kafsi59v9q71r281a4" 2024/04/26 01:41:19 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': deleted 3 directories run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:41:22 DEBUG : 3i9du405pfogq3ncai6pg7ouio: Rmdir: contains trashed file: "982d3pss7t5pn0il16r2foj31s" 2024/04/26 01:41:23 DEBUG : 2bsvlrk2ne1lfitm6tttcu0qt8: Rmdir: contains trashed file: "89l8renevh3mji1c8r1p7qn6tg" --- PASS: TestSyncAfterRemovingAFileAndAddingAFileSubDir (22.77s) === RUN TestSyncAfterRemovingAFileAndAddingAFileSubDirWithErrors run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:41:28 DEBUG : b/potato: md5 = 65439951617f7b00e61d73b04de1e06f OK 2024/04/26 01:41:31 DEBUG : c/non empty space: md5 = d0d85c87c3645b43dea3a066dfbdf955 OK 2024/04/26 01:41:31 DEBUG : d: Making directory 2024/04/26 01:41:33 DEBUG : a: Making directory with metadata 2024/04/26 01:41:35 INFO : a: Made directory with metadata (mtime=2024-04-26T01:41:25.284077972Z) 2024/04/26 01:41:36 INFO : c: Set directory modification time (using SetModTime) 2024/04/26 01:41:36 DEBUG : a/potato2: Need to transfer - File not found at Destination 2024/04/26 01:41:36 DEBUG : c/non empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2024/04/26 01:41:36 DEBUG : c/non empty space: Unchanged skipping 2024/04/26 01:41:36 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for checks to finish 2024/04/26 01:41:36 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for transfers to finish 2024/04/26 01:41:38 DEBUG : a/potato2: md5 = 163327f256cafff42e8b0b1d47991321 OK 2024/04/26 01:41:38 INFO : a/potato2: Copied (new) 2024/04/26 01:41:38 ERROR : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': not deleting files as there were IO errors 2024/04/26 01:41:38 ERROR : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': not deleting directories as there were IO errors run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:41:43 DEBUG : 3i9du405pfogq3ncai6pg7ouio: Rmdir: contains trashed file: "982d3pss7t5pn0il16r2foj31s" 2024/04/26 01:41:44 DEBUG : 32d8ua6196mc1r7qkfog53rkg0: Rmdir: contains trashed file: "2m507n64kafsi59v9q71r281a4" 2024/04/26 01:41:45 DEBUG : 2bsvlrk2ne1lfitm6tttcu0qt8: Rmdir: contains trashed file: "89l8renevh3mji1c8r1p7qn6tg" --- PASS: TestSyncAfterRemovingAFileAndAddingAFileSubDirWithErrors (22.42s) === RUN TestSyncDeleteAfter --- PASS: TestSyncDeleteAfter (0.00s) === RUN TestSyncDeleteDuring run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:41:49 DEBUG : potato: md5 = 6a8177741d10c5c901784157a3730894 OK 2024/04/26 01:41:51 DEBUG : empty space: md5 = 2f2eea51b0d0eb5c0113d2c4afc134e5 OK 2024/04/26 01:41:51 DEBUG : Waiting for deletions to finish 2024/04/26 01:41:52 DEBUG : potato2: Need to transfer - File not found at Destination 2024/04/26 01:41:52 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2024/04/26 01:41:52 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for checks to finish 2024/04/26 01:41:52 DEBUG : empty space: Unchanged skipping 2024/04/26 01:41:52 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for transfers to finish 2024/04/26 01:41:52 INFO : potato: Deleted 2024/04/26 01:41:53 DEBUG : potato2: md5 = 93746b2a7a4523579cc9d7a264d26b09 OK 2024/04/26 01:41:53 INFO : potato2: Copied (new) run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" --- PASS: TestSyncDeleteDuring (9.02s) === RUN TestSyncDeleteBefore run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:41:58 DEBUG : potato: md5 = 37855d172367046822440aab76688188 OK 2024/04/26 01:42:00 DEBUG : empty space: md5 = 3cd8a7ffe58c4c3a2d4281ddbb842c33 OK 2024/04/26 01:42:00 DEBUG : Waiting for deletions to finish 2024/04/26 01:42:01 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for checks to finish 2024/04/26 01:42:01 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for transfers to finish 2024/04/26 01:42:01 INFO : potato: Deleted 2024/04/26 01:42:02 DEBUG : potato2: Need to transfer - File not found at Destination 2024/04/26 01:42:02 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2024/04/26 01:42:02 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for checks to finish 2024/04/26 01:42:02 DEBUG : empty space: Unchanged skipping 2024/04/26 01:42:02 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for transfers to finish 2024/04/26 01:42:03 DEBUG : potato2: md5 = 2a09af9c49c477fb5bbf835d41f90826 OK 2024/04/26 01:42:03 INFO : potato2: Copied (new) run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" --- PASS: TestSyncDeleteBefore (10.53s) === RUN TestCopyDeleteBefore run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:42:09 DEBUG : potato: md5 = e4c4a0bfe564e4a9b899f46da09caea9 OK 2024/04/26 01:42:09 DEBUG : potato2: Need to transfer - File not found at Destination 2024/04/26 01:42:09 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for checks to finish 2024/04/26 01:42:09 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for transfers to finish 2024/04/26 01:42:11 DEBUG : potato2: md5 = fbae83092f3e4fcd11749c7fd6a5b7d7 OK 2024/04/26 01:42:11 INFO : potato2: Copied (new) run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" --- PASS: TestCopyDeleteBefore (7.01s) === RUN TestSyncWithExclude run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:42:16 DEBUG : potato2: md5 = 9371170b62348a21b9f07db5c8498859 OK 2024/04/26 01:42:18 DEBUG : empty space: md5 = ba8318def9eca744230730049a200027 OK 2024/04/26 01:42:18 DEBUG : enormous: Excluded (Size Filter) 2024/04/26 01:42:18 DEBUG : enormous: Excluded 2024/04/26 01:42:18 DEBUG : potato2: Excluded (Size Filter) 2024/04/26 01:42:18 DEBUG : potato2: Excluded 2024/04/26 01:42:18 DEBUG : potato2: Excluded (Size Filter) 2024/04/26 01:42:18 DEBUG : potato2: Excluded 2024/04/26 01:42:18 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2024/04/26 01:42:18 DEBUG : empty space: Unchanged skipping 2024/04/26 01:42:18 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for checks to finish 2024/04/26 01:42:18 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for transfers to finish 2024/04/26 01:42:18 DEBUG : Waiting for deletions to finish 2024/04/26 01:42:18 INFO : There was nothing to transfer run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:42:19 DEBUG : enormous: Excluded (Size Filter) 2024/04/26 01:42:19 DEBUG : enormous: Excluded 2024/04/26 01:42:19 DEBUG : potato2: Excluded (Size Filter) 2024/04/26 01:42:19 DEBUG : potato2: Excluded 2024/04/26 01:42:19 DEBUG : potato2: Excluded (Size Filter) 2024/04/26 01:42:19 DEBUG : potato2: Excluded 2024/04/26 01:42:19 DEBUG : Local file system at /tmp/rclone1262246716: Waiting for checks to finish 2024/04/26 01:42:19 DEBUG : empty space: Size and modification time the same (differ by 456.789µs, within tolerance 1ms) 2024/04/26 01:42:19 DEBUG : empty space: Unchanged skipping 2024/04/26 01:42:19 DEBUG : Local file system at /tmp/rclone1262246716: Waiting for transfers to finish 2024/04/26 01:42:19 DEBUG : Waiting for deletions to finish 2024/04/26 01:42:19 INFO : There was nothing to transfer run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" --- PASS: TestSyncWithExclude (8.36s) === RUN TestSyncWithExcludeAndDeleteExcluded run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:42:24 DEBUG : potato2: md5 = ad0e9ec870663febdab9d9ef87b8b4be OK 2024/04/26 01:42:26 DEBUG : empty space: md5 = 011148d7eb433d5f1828326c3211decf OK 2024/04/26 01:42:28 DEBUG : enormous: md5 = 6cfb6fa1b1ceccbba93295409fd07fa5 OK 2024/04/26 01:42:28 DEBUG : enormous: Excluded (Size Filter) 2024/04/26 01:42:28 DEBUG : enormous: Excluded 2024/04/26 01:42:28 DEBUG : potato2: Excluded (Size Filter) 2024/04/26 01:42:28 DEBUG : potato2: Excluded 2024/04/26 01:42:29 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for checks to finish 2024/04/26 01:42:29 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2024/04/26 01:42:29 DEBUG : empty space: Unchanged skipping 2024/04/26 01:42:29 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for transfers to finish 2024/04/26 01:42:29 DEBUG : Waiting for deletions to finish 2024/04/26 01:42:29 INFO : potato2: Deleted 2024/04/26 01:42:29 INFO : enormous: Deleted 2024/04/26 01:42:29 INFO : There was nothing to transfer run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:42:30 DEBUG : empty space: Size and modification time the same (differ by 456.789µs, within tolerance 1ms) 2024/04/26 01:42:30 DEBUG : empty space: Unchanged skipping 2024/04/26 01:42:30 DEBUG : Local file system at /tmp/rclone1262246716: Waiting for checks to finish 2024/04/26 01:42:30 DEBUG : Local file system at /tmp/rclone1262246716: Waiting for transfers to finish 2024/04/26 01:42:30 DEBUG : Waiting for deletions to finish 2024/04/26 01:42:30 INFO : potato2: Deleted 2024/04/26 01:42:30 INFO : enormous: Deleted 2024/04/26 01:42:30 INFO : There was nothing to transfer run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" --- PASS: TestSyncWithExcludeAndDeleteExcluded (10.13s) === RUN TestSyncWithUpdateOlder run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:42:36 DEBUG : one: md5 = 613d4e72e42220fb81f1187fceb11de1 OK 2024/04/26 01:42:38 DEBUG : two: md5 = 9ad131f3534e1cc5acb220734484744e OK 2024/04/26 01:42:40 DEBUG : three: md5 = aaada4fc83a8fe8e0af90f4bfb76a82f OK 2024/04/26 01:42:41 DEBUG : four: md5 = 2ad1d5c970646b74497b38cb2e18e70f OK 2024/04/26 01:42:42 DEBUG : five: Need to transfer - File not found at Destination 2024/04/26 01:42:42 DEBUG : four: Sizes differ (src 4 vs dst 8) 2024/04/26 01:42:42 DEBUG : one: Destination is newer than source, skipping 2024/04/26 01:42:42 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for checks to finish 2024/04/26 01:42:42 DEBUG : three: Sizes identical 2024/04/26 01:42:42 DEBUG : four: Destination mod time is within 1s of source but files differ, transferring 2024/04/26 01:42:42 DEBUG : three: Destination mod time is within 1s of source and files identical, skipping 2024/04/26 01:42:42 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for transfers to finish 2024/04/26 01:42:44 DEBUG : two: md5 = 265856864be25412d99982c1d5ced81d OK 2024/04/26 01:42:44 INFO : two: Copied (replaced existing) 2024/04/26 01:42:44 DEBUG : four: md5 = fe3d40a664415a1ac5b290ab30392a88 OK 2024/04/26 01:42:44 INFO : four: Copied (replaced existing) 2024/04/26 01:42:44 DEBUG : five: md5 = 1c7346b7dd6c5bf5eace8e4f83a40340 OK 2024/04/26 01:42:44 INFO : five: Copied (new) 2024/04/26 01:42:44 DEBUG : Waiting for deletions to finish sync_test.go:1244: Skip test with --checksum as no hashes supported --- PASS: TestSyncWithUpdateOlder (16.36s) === RUN TestSyncWithMaxDuration === RUN TestSyncWithMaxDuration/Hard sync_test.go:1261: Skipping test on non local remote === RUN TestSyncWithMaxDuration/Soft sync_test.go:1261: 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-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" sync_test.go:1327: Can track renames: false 2024/04/26 01:42:49 ERROR : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Ignoring --track-renames as the source and destination do not have a common hash 2024/04/26 01:42:49 DEBUG : potato: Need to transfer - File not found at Destination 2024/04/26 01:42:49 DEBUG : yam: Need to transfer - File not found at Destination 2024/04/26 01:42:49 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for checks to finish 2024/04/26 01:42:49 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for transfers to finish 2024/04/26 01:42:51 DEBUG : yam: md5 = 9f9678379e2c3e72b22dc3b0452f497c OK 2024/04/26 01:42:51 INFO : yam: Copied (new) 2024/04/26 01:42:51 DEBUG : potato: md5 = c33518915d10a8298426a21c646d2c71 OK 2024/04/26 01:42:51 INFO : potato: Copied (new) 2024/04/26 01:42:51 DEBUG : Waiting for deletions to finish run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:42:52 ERROR : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Ignoring --track-renames as the source and destination do not have a common hash 2024/04/26 01:42:52 DEBUG : yaml: Need to transfer - File not found at Destination 2024/04/26 01:42:52 DEBUG : potato: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/26 01:42:52 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for checks to finish 2024/04/26 01:42:52 DEBUG : potato: Unchanged skipping 2024/04/26 01:42:52 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for transfers to finish 2024/04/26 01:42:54 DEBUG : yaml: md5 = 4dea660ab4da8ff64e41ea4bbe166d57 OK 2024/04/26 01:42:54 INFO : yaml: Copied (new) 2024/04/26 01:42:54 DEBUG : Waiting for deletions to finish 2024/04/26 01:42:54 INFO : yam: Deleted run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" --- PASS: TestSyncWithTrackRenames (9.43s) === RUN TestParseRenamesStrategyModtime --- PASS: TestParseRenamesStrategyModtime (0.00s) === RUN TestRenamesStrategyModtime --- PASS: TestRenamesStrategyModtime (0.00s) === RUN TestSyncWithTrackRenamesStrategyModtime run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" sync_test.go:1399: Can track renames: true 2024/04/26 01:42:58 INFO : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Making map for --track-renames 2024/04/26 01:42:58 INFO : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Finished making map for --track-renames 2024/04/26 01:42:58 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for checks to finish 2024/04/26 01:42:58 DEBUG : potato: Need to transfer - No matching file found at Destination 2024/04/26 01:42:58 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for renames to finish 2024/04/26 01:42:58 DEBUG : yam: Need to transfer - No matching file found at Destination 2024/04/26 01:42:58 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for transfers to finish 2024/04/26 01:43:00 DEBUG : potato: md5 = aaa38ffff3c104df8ff02cb80b372614 OK 2024/04/26 01:43:00 INFO : potato: Copied (new) 2024/04/26 01:43:01 DEBUG : yam: md5 = a9b6d139a1aedb126bc240a0d582ea31 OK 2024/04/26 01:43:01 INFO : yam: Copied (new) 2024/04/26 01:43:01 DEBUG : Waiting for deletions to finish run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:43:01 INFO : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Making map for --track-renames 2024/04/26 01:43:01 DEBUG : potato: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/26 01:43:01 INFO : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Finished making map for --track-renames 2024/04/26 01:43:01 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for checks to finish 2024/04/26 01:43:01 DEBUG : potato: Unchanged skipping 2024/04/26 01:43:01 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for renames to finish 2024/04/26 01:43:02 INFO : yam: Moved (server-side) to: yaml 2024/04/26 01:43:02 INFO : yaml: Renamed from "yam" 2024/04/26 01:43:02 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for transfers to finish 2024/04/26 01:43:02 DEBUG : Waiting for deletions to finish 2024/04/26 01:43:02 INFO : There was nothing to transfer run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" --- PASS: TestSyncWithTrackRenamesStrategyModtime (7.84s) === RUN TestSyncWithTrackRenamesStrategyLeaf run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" sync_test.go:1438: Can track renames: true 2024/04/26 01:43:06 DEBUG : sub: Making directory with metadata 2024/04/26 01:43:07 INFO : sub: Made directory with metadata (mtime=2024-04-26T01:43:06.388095772Z) 2024/04/26 01:43:07 INFO : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Making map for --track-renames 2024/04/26 01:43:07 INFO : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Finished making map for --track-renames 2024/04/26 01:43:07 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for checks to finish 2024/04/26 01:43:07 DEBUG : potato: Need to transfer - No matching file found at Destination 2024/04/26 01:43:07 DEBUG : sub/yam: Need to transfer - No matching file found at Destination 2024/04/26 01:43:07 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for renames to finish 2024/04/26 01:43:07 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for transfers to finish 2024/04/26 01:43:09 DEBUG : sub/yam: md5 = bdebb794755f68e58e6d8a172bf12488 OK 2024/04/26 01:43:09 INFO : sub/yam: Copied (new) 2024/04/26 01:43:09 DEBUG : potato: md5 = c7c3b5bc41426cfe5f568dcc1bcd8fcc OK 2024/04/26 01:43:09 INFO : potato: Copied (new) 2024/04/26 01:43:09 DEBUG : Waiting for deletions to finish run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:43:10 DEBUG : potato: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/26 01:43:10 DEBUG : potato: Unchanged skipping 2024/04/26 01:43:11 INFO : sub: Set directory modification time (using SetModTime) 2024/04/26 01:43:11 INFO : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Making map for --track-renames 2024/04/26 01:43:11 INFO : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Finished making map for --track-renames 2024/04/26 01:43:11 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for checks to finish 2024/04/26 01:43:11 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for renames to finish 2024/04/26 01:43:13 INFO : sub/yam: Moved (server-side) to: yam 2024/04/26 01:43:13 INFO : yam: Renamed from "sub/yam" 2024/04/26 01:43:13 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for transfers to finish 2024/04/26 01:43:13 DEBUG : Waiting for deletions to finish 2024/04/26 01:43:13 INFO : There was nothing to transfer run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" --- PASS: TestSyncWithTrackRenamesStrategyLeaf (11.59s) === RUN TestServerSideMoveLocal run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:43:17 DEBUG : Creating backend with remote "/tmp/rclone1262246716/dir1" 2024/04/26 01:43:17 DEBUG : Creating backend with remote "/tmp/rclone1262246716/dir2" 2024/04/26 01:43:17 DEBUG : Local file system at /tmp/rclone1262246716/dir2: Using server-side directory move 2024/04/26 01:43:17 INFO : Local file system at /tmp/rclone1262246716/dir2: Server side directory move failed - fallback to file moves: can't copy directory - destination already exists 2024/04/26 01:43:17 DEBUG : file1.txt: Need to transfer - File not found at Destination 2024/04/26 01:43:17 INFO : file1.txt: Moved (server-side) 2024/04/26 01:43:17 DEBUG : Local file system at /tmp/rclone1262246716/dir2: Waiting for checks to finish 2024/04/26 01:43:17 DEBUG : Local file system at /tmp/rclone1262246716/dir2: Waiting for transfers to finish --- PASS: TestServerSideMoveLocal (0.56s) === RUN TestMoveWithDeleteEmptySrcDirs run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:43:18 DEBUG : nested: Making directory with metadata 2024/04/26 01:43:20 INFO : nested: Made directory with metadata (mtime=2024-04-26T01:43:18.53609781Z) 2024/04/26 01:43:20 DEBUG : sub dir: Making directory with metadata 2024/04/26 01:43:21 INFO : sub dir: Made directory with metadata (mtime=2024-04-26T01:43:18.53609781Z) 2024/04/26 01:43:21 DEBUG : nested/sub dir: Making directory with metadata 2024/04/26 01:43:21 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2024/04/26 01:43:22 INFO : nested/sub dir: Made directory with metadata (mtime=2024-04-26T01:43:18.53609781Z) 2024/04/26 01:43:22 DEBUG : nested/sub dir/file: Need to transfer - File not found at Destination 2024/04/26 01:43:22 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for checks to finish 2024/04/26 01:43:22 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for transfers to finish 2024/04/26 01:43:23 DEBUG : sub dir/hello world: md5 = 69604a98e803628e24eda7d6ad3c33e2 OK 2024/04/26 01:43:23 INFO : sub dir/hello world: Copied (new) 2024/04/26 01:43:23 INFO : sub dir/hello world: Deleted 2024/04/26 01:43:24 DEBUG : nested/sub dir/file: md5 = e93693fb09cb73b6498f4a5a6a34f294 OK 2024/04/26 01:43:24 INFO : nested/sub dir/file: Copied (new) 2024/04/26 01:43:24 INFO : nested/sub dir/file: Deleted 2024/04/26 01:43:24 INFO : sub dir: Removing directory 2024/04/26 01:43:24 INFO : nested/sub dir: Removing directory 2024/04/26 01:43:24 INFO : nested: Removing directory 2024/04/26 01:43:24 DEBUG : Local file system at /tmp/rclone1262246716: deleted 3 directories run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:43:27 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" 2024/04/26 01:43:28 DEBUG : 37qp6d1gohacv723ij3brofbu8/14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "ftp4kuv8se7tqduu6pmmcvjsmk" 2024/04/26 01:43:30 DEBUG : 37qp6d1gohacv723ij3brofbu8: Rmdir: contains trashed file: "14begaa36ih249fgrnfk6nulg0" --- PASS: TestMoveWithDeleteEmptySrcDirs (13.05s) === RUN TestMoveWithoutDeleteEmptySrcDirs run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:43:31 DEBUG : nested: Making directory with metadata 2024/04/26 01:43:33 INFO : nested: Made directory with metadata (mtime=2024-04-26T01:43:31.584099976Z) 2024/04/26 01:43:33 DEBUG : sub dir: Making directory with metadata 2024/04/26 01:43:34 INFO : sub dir: Made directory with metadata (mtime=2024-04-26T01:43:31.584099976Z) 2024/04/26 01:43:34 DEBUG : nested/sub dir: Making directory with metadata 2024/04/26 01:43:34 DEBUG : sub dir/hello world: Need to transfer - File not found at Destination 2024/04/26 01:43:35 INFO : nested/sub dir: Made directory with metadata (mtime=2024-04-26T01:43:31.584099976Z) 2024/04/26 01:43:35 DEBUG : nested/sub dir/file: Need to transfer - File not found at Destination 2024/04/26 01:43:35 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for checks to finish 2024/04/26 01:43:35 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for transfers to finish 2024/04/26 01:43:37 DEBUG : sub dir/hello world: md5 = a5498d23ec0d52e66536e90a031b8c9b OK 2024/04/26 01:43:37 INFO : sub dir/hello world: Copied (new) 2024/04/26 01:43:37 INFO : sub dir/hello world: Deleted 2024/04/26 01:43:37 DEBUG : nested/sub dir/file: md5 = 17744f39a728866903e7ca2508b29894 OK 2024/04/26 01:43:37 INFO : nested/sub dir/file: Copied (new) 2024/04/26 01:43:37 INFO : nested/sub dir/file: Deleted run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:43:40 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" 2024/04/26 01:43:41 DEBUG : 37qp6d1gohacv723ij3brofbu8/14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "ftp4kuv8se7tqduu6pmmcvjsmk" 2024/04/26 01:43:42 DEBUG : 37qp6d1gohacv723ij3brofbu8: Rmdir: contains trashed file: "14begaa36ih249fgrnfk6nulg0" --- PASS: TestMoveWithoutDeleteEmptySrcDirs (12.90s) === RUN TestMoveWithIgnoreExisting run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:43:44 DEBUG : existing: Need to transfer - File not found at Destination 2024/04/26 01:43:44 DEBUG : existing-b: Need to transfer - File not found at Destination 2024/04/26 01:43:44 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for checks to finish 2024/04/26 01:43:44 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for transfers to finish 2024/04/26 01:43:46 DEBUG : existing-b: md5 = dba2c20d1f106bcf4f4e7abea0f25f23 OK 2024/04/26 01:43:46 INFO : existing-b: Copied (new) 2024/04/26 01:43:46 INFO : existing-b: Deleted 2024/04/26 01:43:47 DEBUG : existing: md5 = 7efac47d49402b4dc9d3d47ded17a523 OK 2024/04/26 01:43:47 INFO : existing: Copied (new) 2024/04/26 01:43:47 INFO : existing: Deleted 2024/04/26 01:43:47 DEBUG : existing: Destination exists, skipping 2024/04/26 01:43:47 DEBUG : existing: Not removing source file as destination file exists and --ignore-existing is set 2024/04/26 01:43:47 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for checks to finish 2024/04/26 01:43:47 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for transfers to finish 2024/04/26 01:43:47 INFO : There was nothing to transfer run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" --- PASS: TestMoveWithIgnoreExisting (6.27s) === RUN TestServerSideMove run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:43:50 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-zobajec3fudutij6lixetax5" 2024/04/26 01:43:50 DEBUG : Creating backend with remote "TestDrive:crypt/g4f6arha5oehikp5dt8u0a6lf3vuekf7nte55ri1dpmu2jrscf2nom73h22snnqvh562bdt0k2h28" 2024/04/26 01:43:53 DEBUG : potato2: md5 = 59ef9bfe2ce479fd2020aef5772da00b OK 2024/04/26 01:43:55 DEBUG : empty space: md5 = a33ad632107643749d31423b17ef5320 OK 2024/04/26 01:43:57 DEBUG : potato3: md5 = 104009adfe62c6b10e8f572cfff92821 OK sync_test.go:1494: Server side move (if possible) Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7' -> Encrypted drive 'TestCryptDrive:rclone-test-zobajec3fudutij6lixetax5' 2024/04/26 01:44:00 DEBUG : empty space: md5 = e8ff2cc3472a82047c7fbed26d456d75 OK 2024/04/26 01:44:02 DEBUG : potato3: md5 = f9c32adde2676f81fc65e3a80fa42f38 OK 2024/04/26 01:44:03 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-zobajec3fudutij6lixetax5': Using server-side directory move 2024/04/26 01:44:03 INFO : Encrypted drive 'TestCryptDrive:rclone-test-zobajec3fudutij6lixetax5': Server side directory move failed - fallback to file moves: can't copy directory - destination already exists 2024/04/26 01:44:03 DEBUG : potato2: Need to transfer - File not found at Destination 2024/04/26 01:44:03 DEBUG : potato3: Sizes differ (src 68 vs dst 60) 2024/04/26 01:44:03 DEBUG : empty space: Size and modification time the same (differ by 0s, within tolerance 1ms) 2024/04/26 01:44:03 DEBUG : empty space: Unchanged skipping 2024/04/26 01:44:03 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-zobajec3fudutij6lixetax5': Waiting for checks to finish 2024/04/26 01:44:04 INFO : empty space: Deleted 2024/04/26 01:44:04 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-zobajec3fudutij6lixetax5': Waiting for transfers to finish 2024/04/26 01:44:04 INFO : potato3: Deleted 2024/04/26 01:44:04 INFO : potato2: Moved (server-side) 2024/04/26 01:44:05 INFO : potato3: Moved (server-side) 2024/04/26 01:44:06 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-nibewud6xobebiz7womelob2" 2024/04/26 01:44:06 DEBUG : Creating backend with remote "TestDrive:crypt/blj7p8nbs3cgtp6bed02h8ufnfmv8l4cj24orn13hi3jss3ugui05e51vj8ac47mnji8b8oh52e2o" 2024/04/26 01:44:07 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-nibewud6xobebiz7womelob2': Using server-side directory move 2024/04/26 01:44:08 INFO : Encrypted drive 'TestCryptDrive:rclone-test-nibewud6xobebiz7womelob2': Server side directory move succeeded 2024/04/26 01:44:09 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-nibewud6xobebiz7womelob2': Purge remote 2024/04/26 01:44:10 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-zobajec3fudutij6lixetax5': Purge remote 2024/04/26 01:44:10 purge failed: directory not found --- PASS: TestServerSideMove (20.29s) === RUN TestServerSideMoveWithFilter run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:44:11 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-lorazas1nusinoy6kawanif0" 2024/04/26 01:44:11 DEBUG : Creating backend with remote "TestDrive:crypt/ej0ni5hldil4dks5elvk7rrva947jk73mrnh6k4284bknj8pph0pqbujeabqn0bo7fvl7uv7hspak" 2024/04/26 01:44:14 DEBUG : potato2: md5 = 48d2e4fc06a898cafe144c670a03ce6d OK 2024/04/26 01:44:16 DEBUG : empty space: md5 = fd1ea0a7a8ccbe3ca10be55ea52fad7d OK 2024/04/26 01:44:17 DEBUG : potato3: md5 = 4a97af2ce809334c1453c16ec3bfb71e OK sync_test.go:1494: Server side move (if possible) Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7' -> Encrypted drive 'TestCryptDrive:rclone-test-lorazas1nusinoy6kawanif0' 2024/04/26 01:44:21 DEBUG : empty space: md5 = bcd8019a43891d5098b49e890d2416f0 OK 2024/04/26 01:44:23 DEBUG : potato3: md5 = 5c6158843a441bafcf9ef926c5fd8100 OK 2024/04/26 01:44:23 DEBUG : empty space: Excluded (Size Filter) 2024/04/26 01:44:23 DEBUG : empty space: Excluded 2024/04/26 01:44:23 DEBUG : empty space: Excluded (Size Filter) 2024/04/26 01:44:23 DEBUG : empty space: Excluded 2024/04/26 01:44:23 DEBUG : potato2: Need to transfer - File not found at Destination 2024/04/26 01:44:23 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-lorazas1nusinoy6kawanif0': Waiting for checks to finish 2024/04/26 01:44:23 DEBUG : potato3: Sizes differ (src 68 vs dst 60) 2024/04/26 01:44:23 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-lorazas1nusinoy6kawanif0': Waiting for transfers to finish 2024/04/26 01:44:24 INFO : potato3: Deleted 2024/04/26 01:44:25 INFO : potato2: Moved (server-side) 2024/04/26 01:44:26 INFO : potato3: Moved (server-side) 2024/04/26 01:44:27 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-ticibus6qoposuq4wabaxuy8" 2024/04/26 01:44:27 DEBUG : Creating backend with remote "TestDrive:crypt/a9l151dr3rggqp11ohb9lheenkupcksptt9eioui0a0v6henon9d21502u1orl9ge6ki5sbd4k30s" 2024/04/26 01:44:28 DEBUG : empty space: Excluded (Size Filter) 2024/04/26 01:44:28 DEBUG : empty space: Excluded 2024/04/26 01:44:28 DEBUG : potato2: Need to transfer - File not found at Destination 2024/04/26 01:44:28 DEBUG : potato3: Need to transfer - File not found at Destination 2024/04/26 01:44:28 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-ticibus6qoposuq4wabaxuy8': Waiting for checks to finish 2024/04/26 01:44:28 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-ticibus6qoposuq4wabaxuy8': Waiting for transfers to finish 2024/04/26 01:44:30 INFO : potato3: Moved (server-side) 2024/04/26 01:44:31 INFO : potato2: Moved (server-side) 2024/04/26 01:44:32 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-ticibus6qoposuq4wabaxuy8': Purge remote 2024/04/26 01:44:32 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-lorazas1nusinoy6kawanif0': Purge remote --- PASS: TestServerSideMoveWithFilter (23.80s) === RUN TestServerSideMoveDeleteEmptySourceDirs run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:44:34 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-qusufem7bokexef0newivab6" 2024/04/26 01:44:34 DEBUG : Creating backend with remote "TestDrive:crypt/b8o1cedmp0u4gr7ufcnudqgtjlm9f0uckqr9dht0sniq1edcje67pr1khkdii6i5k9urifug7jk1c" 2024/04/26 01:44:41 DEBUG : potato2: md5 = 0eb9cc46c4b7a9d5dc6d5c26759ae223 OK 2024/04/26 01:44:43 DEBUG : empty space: md5 = 71e2cff99ab303eedd806d60d1dd37e9 OK 2024/04/26 01:44:45 DEBUG : potato3: md5 = 89bf97b0c8f361bdfe642cab228a4f5e OK 2024/04/26 01:44:45 DEBUG : tomatoDir: Making directory sync_test.go:1494: Server side move (if possible) Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7' -> Encrypted drive 'TestCryptDrive:rclone-test-qusufem7bokexef0newivab6' 2024/04/26 01:44:50 DEBUG : empty space: md5 = a0dba5bc58f6a0a49ac417bd07e6556a OK 2024/04/26 01:44:52 DEBUG : potato3: md5 = 0761ad033e53c1e039fee93332d7f9a5 OK 2024/04/26 01:44:52 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-qusufem7bokexef0newivab6': Using server-side directory move 2024/04/26 01:44:52 INFO : Encrypted drive 'TestCryptDrive:rclone-test-qusufem7bokexef0newivab6': Server side directory move failed - fallback to file moves: can't copy directory - destination already exists 2024/04/26 01:44:52 DEBUG : potato2: Need to transfer - File not found at Destination 2024/04/26 01:44:52 DEBUG : tomatoDir: Making directory with metadata 2024/04/26 01:44:53 INFO : tomatoDir: Made directory with metadata (mtime=2024-04-26T01:44:45.837Z) 2024/04/26 01:44:53 DEBUG : empty space: Size and modification time the same (differ by 0s, within tolerance 1ms) 2024/04/26 01:44:53 DEBUG : potato3: Sizes differ (src 68 vs dst 60) 2024/04/26 01:44:53 DEBUG : empty space: Unchanged skipping 2024/04/26 01:44:54 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-qusufem7bokexef0newivab6': Waiting for checks to finish 2024/04/26 01:44:54 INFO : potato2: Moved (server-side) 2024/04/26 01:44:54 INFO : potato3: Deleted 2024/04/26 01:44:54 INFO : empty space: Deleted 2024/04/26 01:44:54 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-qusufem7bokexef0newivab6': Waiting for transfers to finish 2024/04/26 01:44:55 INFO : potato3: Moved (server-side) 2024/04/26 01:44:55 INFO : tomatoDir: Removing directory 2024/04/26 01:44:57 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': deleted 1 directories 2024/04/26 01:44:58 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-dijehey8fikejux0tebemig8" 2024/04/26 01:44:58 DEBUG : Creating backend with remote "TestDrive:crypt/4rbk1hpbc9ngbecuds5qgcncforsfmqc2a9ourom6qohacnvrq1vb86qu3hvd28pojm4frdnmqo56" 2024/04/26 01:44:59 DEBUG : tomatoDir: Making directory 2024/04/26 01:44:59 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-dijehey8fikejux0tebemig8': Using server-side directory move 2024/04/26 01:45:00 INFO : Encrypted drive 'TestCryptDrive:rclone-test-dijehey8fikejux0tebemig8': Server side directory move succeeded 2024/04/26 01:45:02 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-dijehey8fikejux0tebemig8': Purge remote 2024/04/26 01:45:03 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-qusufem7bokexef0newivab6': Purge remote 2024/04/26 01:45:03 purge failed: directory not found --- PASS: TestServerSideMoveDeleteEmptySourceDirs (29.37s) === RUN TestServerSideMoveOverlap run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" sync_test.go:1699: Skipping test as remote supports DirMove --- SKIP: TestServerSideMoveOverlap (0.54s) === RUN TestSyncOverlap run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:45:04 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7/rclone-sync-test" 2024/04/26 01:45:04 DEBUG : Creating backend with remote "TestDrive:crypt/i82nm4fm1mic70fi1jf5dgvps1ph404sg69dve7khefh6dplf6dl19cul3rrof4h01l559enj97tc/i7355aa0sb89uagn75vfjqr6s3e3e1h2et8in57abn1fe8qfego0" run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" --- PASS: TestSyncOverlap (4.62s) === RUN TestSyncOverlapWithFilter run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:45:09 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7/rclone-sync-test" 2024/04/26 01:45:09 DEBUG : Creating backend with remote "TestDrive:crypt/i82nm4fm1mic70fi1jf5dgvps1ph404sg69dve7khefh6dplf6dl19cul3rrof4h01l559enj97tc/i7355aa0sb89uagn75vfjqr6s3e3e1h2et8in57abn1fe8qfego0" 2024/04/26 01:45:12 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7/rclone-sync-test-include/layer2" 2024/04/26 01:45:12 DEBUG : Creating backend with remote "TestDrive:crypt/i82nm4fm1mic70fi1jf5dgvps1ph404sg69dve7khefh6dplf6dl19cul3rrof4h01l559enj97tc/khf2vlblvnbf9ftevqm0htmss73hj1j5a7q328e4ohrgs7e2loe0/n01jpl9202nn9ec1rb75h0f1c4" 2024/04/26 01:45:16 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7/rclone-sync-test-ignore-file" 2024/04/26 01:45:16 DEBUG : Creating backend with remote "TestDrive:crypt/i82nm4fm1mic70fi1jf5dgvps1ph404sg69dve7khefh6dplf6dl19cul3rrof4h01l559enj97tc/kmf11jujl9uha3tjganvgpkn45bu778hb5vb5riug1c26b38k7sg" 2024/04/26 01:45:21 DEBUG : rclone-sync-test-ignore-file/.ignore: md5 = fe0396be11ae2e98b00a1b3e801103f5 OK 2024/04/26 01:45:22 DEBUG : rclone-sync-test-ignore-file: Excluded 2024/04/26 01:45:23 DEBUG : rclone-sync-test: Excluded 2024/04/26 01:45:23 DEBUG : rclone-sync-test-include: Making directory with metadata 2024/04/26 01:45:24 INFO : rclone-sync-test-include: Made directory with metadata (mtime=2024-04-26T01:45:14.586Z) 2024/04/26 01:45:25 DEBUG : rclone-sync-test-include/layer2: Excluded 2024/04/26 01:45:25 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7/rclone-sync-test': Waiting for checks to finish 2024/04/26 01:45:25 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7/rclone-sync-test': Waiting for transfers to finish 2024/04/26 01:45:25 DEBUG : Waiting for deletions to finish 2024/04/26 01:45:25 INFO : There was nothing to transfer 2024/04/26 01:45:26 DEBUG : rclone-sync-test-ignore-file: Excluded 2024/04/26 01:45:26 DEBUG : rclone-sync-test: Excluded 2024/04/26 01:45:26 DEBUG : rclone-sync-test-include: Directory modification time the same (differ by 0s, within tolerance 1ms) 2024/04/26 01:45:27 DEBUG : rclone-sync-test-include/layer2: Excluded 2024/04/26 01:45:27 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for checks to finish 2024/04/26 01:45:27 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for transfers to finish 2024/04/26 01:45:27 DEBUG : Waiting for deletions to finish 2024/04/26 01:45:27 INFO : There was nothing to transfer run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:45:28 DEBUG : rclone-sync-test-ignore-file: Excluded 2024/04/26 01:45:28 DEBUG : rclone-sync-test: Excluded 2024/04/26 01:45:28 DEBUG : rclone-sync-test-include: Making directory with metadata 2024/04/26 01:45:29 INFO : rclone-sync-test-include: Made directory with metadata (mtime=2024-04-26T01:45:14.586Z) 2024/04/26 01:45:30 DEBUG : rclone-sync-test-include/layer2: Excluded 2024/04/26 01:45:30 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7/rclone-sync-test-include/layer2': Waiting for checks to finish 2024/04/26 01:45:30 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7/rclone-sync-test-include/layer2': Waiting for transfers to finish 2024/04/26 01:45:30 DEBUG : Waiting for deletions to finish 2024/04/26 01:45:30 INFO : There was nothing to transfer run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:45:31 DEBUG : rclone-sync-test-ignore-file: Excluded 2024/04/26 01:45:31 DEBUG : rclone-sync-test: Excluded 2024/04/26 01:45:31 DEBUG : rclone-sync-test-include: Directory modification time the same (differ by 0s, within tolerance 1ms) 2024/04/26 01:45:32 DEBUG : rclone-sync-test-include/layer2: Excluded 2024/04/26 01:45:32 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for checks to finish 2024/04/26 01:45:32 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for transfers to finish 2024/04/26 01:45:32 DEBUG : Waiting for deletions to finish 2024/04/26 01:45:32 INFO : There was nothing to transfer run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:45:33 DEBUG : : Excluded 2024/04/26 01:45:33 DEBUG : rclone-sync-test-ignore-file: Excluded 2024/04/26 01:45:33 DEBUG : rclone-sync-test: Excluded 2024/04/26 01:45:33 DEBUG : rclone-sync-test-include: Making directory with metadata 2024/04/26 01:45:35 INFO : rclone-sync-test-include: Made directory with metadata (mtime=2024-04-26T01:45:14.586Z) 2024/04/26 01:45:35 DEBUG : rclone-sync-test-include/layer2: Excluded 2024/04/26 01:45:35 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7/rclone-sync-test-ignore-file': Waiting for checks to finish 2024/04/26 01:45:35 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7/rclone-sync-test-ignore-file': Waiting for transfers to finish 2024/04/26 01:45:35 DEBUG : Waiting for deletions to finish 2024/04/26 01:45:35 INFO : There was nothing to transfer run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:45:40 DEBUG : khf2vlblvnbf9ftevqm0htmss73hj1j5a7q328e4ohrgs7e2loe0/n01jpl9202nn9ec1rb75h0f1c4: Rmdir: contains trashed file: "khf2vlblvnbf9ftevqm0htmss73hj1j5a7q328e4ohrgs7e2loe0" 2024/04/26 01:45:41 DEBUG : khf2vlblvnbf9ftevqm0htmss73hj1j5a7q328e4ohrgs7e2loe0: Rmdir: contains trashed file: "n01jpl9202nn9ec1rb75h0f1c4" 2024/04/26 01:45:43 DEBUG : kmf11jujl9uha3tjganvgpkn45bu778hb5vb5riug1c26b38k7sg: Rmdir: contains trashed file: "khf2vlblvnbf9ftevqm0htmss73hj1j5a7q328e4ohrgs7e2loe0" 2024/04/26 01:45:43 DEBUG : kmf11jujl9uha3tjganvgpkn45bu778hb5vb5riug1c26b38k7sg: Rmdir: contains trashed file: "i0t74httmdlljg425j6tg570d8" 2024/04/26 01:45:44 DEBUG : i7355aa0sb89uagn75vfjqr6s3e3e1h2et8in57abn1fe8qfego0: Rmdir: contains trashed file: "khf2vlblvnbf9ftevqm0htmss73hj1j5a7q328e4ohrgs7e2loe0" --- PASS: TestSyncOverlapWithFilter (45.76s) === RUN TestSyncCompareDest run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:45:55 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7/dst" 2024/04/26 01:45:55 DEBUG : Creating backend with remote "TestDrive:crypt/i82nm4fm1mic70fi1jf5dgvps1ph404sg69dve7khefh6dplf6dl19cul3rrof4h01l559enj97tc/31u3jie661vd5p8j7rtc3hgbh0" 2024/04/26 01:45:56 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7/CompareDest" 2024/04/26 01:45:56 DEBUG : Creating backend with remote "TestDrive:crypt/i82nm4fm1mic70fi1jf5dgvps1ph404sg69dve7khefh6dplf6dl19cul3rrof4h01l559enj97tc/gveqi14airsml4bgu7krj116o8" 2024/04/26 01:45:59 DEBUG : one: Need to transfer - File not found at Destination 2024/04/26 01:45:59 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7/dst': Waiting for checks to finish 2024/04/26 01:45:59 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7/dst': Waiting for transfers to finish 2024/04/26 01:46:02 DEBUG : one: md5 = 77711650d9b5762e455afd17039585e5 OK 2024/04/26 01:46:02 INFO : one: Copied (new) 2024/04/26 01:46:02 DEBUG : Waiting for deletions to finish 2024/04/26 01:46:04 DEBUG : one: Sizes differ (src 5 vs dst 3) 2024/04/26 01:46:04 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7/dst': Waiting for checks to finish 2024/04/26 01:46:04 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7/dst': Waiting for transfers to finish 2024/04/26 01:46:05 DEBUG : one: md5 = 9a98734820cb518cdcf84860d81ab71b OK 2024/04/26 01:46:05 INFO : one: Copied (replaced existing) 2024/04/26 01:46:05 DEBUG : Waiting for deletions to finish 2024/04/26 01:46:08 DEBUG : dst/one: md5 = 7bd08a2c6b1d32c38f0af9fb30b4d07f OK 2024/04/26 01:46:11 DEBUG : CompareDest/one: md5 = 481b16b8a1595929c2bd145c7cd47fd4 OK 2024/04/26 01:46:12 DEBUG : one: Sizes differ (src 5 vs dst 3) 2024/04/26 01:46:12 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7/dst': Waiting for checks to finish 2024/04/26 01:46:13 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2024/04/26 01:46:13 DEBUG : one: Destination found in --compare-dest, skipping 2024/04/26 01:46:13 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7/dst': Waiting for transfers to finish 2024/04/26 01:46:13 DEBUG : Waiting for deletions to finish 2024/04/26 01:46:13 INFO : There was nothing to transfer 2024/04/26 01:46:15 DEBUG : CompareDest/two: md5 = c4c19fd481ce34585a2ae0b5eab87959 OK 2024/04/26 01:46:16 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2024/04/26 01:46:16 DEBUG : two: Destination found in --compare-dest, skipping 2024/04/26 01:46:16 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7/dst': Waiting for checks to finish 2024/04/26 01:46:16 DEBUG : one: Sizes differ (src 5 vs dst 3) 2024/04/26 01:46:17 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2024/04/26 01:46:17 DEBUG : one: Destination found in --compare-dest, skipping 2024/04/26 01:46:17 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7/dst': Waiting for transfers to finish 2024/04/26 01:46:17 DEBUG : Waiting for deletions to finish 2024/04/26 01:46:17 INFO : There was nothing to transfer 2024/04/26 01:46:18 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2024/04/26 01:46:18 DEBUG : two: Destination found in --compare-dest, skipping 2024/04/26 01:46:18 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7/dst': Waiting for checks to finish 2024/04/26 01:46:18 DEBUG : one: Sizes differ (src 5 vs dst 3) 2024/04/26 01:46:18 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2024/04/26 01:46:18 DEBUG : one: Destination found in --compare-dest, skipping 2024/04/26 01:46:18 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7/dst': Waiting for transfers to finish 2024/04/26 01:46:18 DEBUG : Waiting for deletions to finish 2024/04/26 01:46:18 INFO : There was nothing to transfer sync_test.go:1964: No hash on uploaded file so skipping compare timestamp test 2024/04/26 01:46:20 DEBUG : two: Sizes differ (src 5 vs dst 3) 2024/04/26 01:46:20 DEBUG : two: Need to transfer - File not found at Destination 2024/04/26 01:46:20 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7/dst': Waiting for checks to finish 2024/04/26 01:46:20 DEBUG : one: Sizes differ (src 5 vs dst 3) 2024/04/26 01:46:20 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2024/04/26 01:46:20 DEBUG : one: Destination found in --compare-dest, skipping 2024/04/26 01:46:20 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7/dst': Waiting for transfers to finish 2024/04/26 01:46:22 DEBUG : two: md5 = 77c956e322956f203fc90cdd6336042b OK 2024/04/26 01:46:22 INFO : two: Copied (new) 2024/04/26 01:46:22 DEBUG : Waiting for deletions to finish 2024/04/26 01:46:26 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" 2024/04/26 01:46:26 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2024/04/26 01:46:27 DEBUG : gveqi14airsml4bgu7krj116o8: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2024/04/26 01:46:27 DEBUG : gveqi14airsml4bgu7krj116o8: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" --- PASS: TestSyncCompareDest (33.72s) === RUN TestSyncMultipleCompareDest run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:46:31 DEBUG : pre-dest1/1: md5 = c79d811d4b022ac6e745904dffb588ef OK 2024/04/26 01:46:35 DEBUG : pre-dest2/2: md5 = 225fde2ad1a723c85a59fd93ddb58624 OK 2024/04/26 01:46:35 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7/dest" 2024/04/26 01:46:36 DEBUG : Creating backend with remote "TestDrive:crypt/i82nm4fm1mic70fi1jf5dgvps1ph404sg69dve7khefh6dplf6dl19cul3rrof4h01l559enj97tc/rg03c1jvnehrrc617i0lnqjddc" 2024/04/26 01:46:37 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7/pre-dest1" 2024/04/26 01:46:37 DEBUG : Creating backend with remote "TestDrive:crypt/i82nm4fm1mic70fi1jf5dgvps1ph404sg69dve7khefh6dplf6dl19cul3rrof4h01l559enj97tc/bbnblvh6k061ssopqrp18kd7gc" 2024/04/26 01:46:38 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7/pre-dest2" 2024/04/26 01:46:38 DEBUG : Creating backend with remote "TestDrive:crypt/i82nm4fm1mic70fi1jf5dgvps1ph404sg69dve7khefh6dplf6dl19cul3rrof4h01l559enj97tc/dgicm1h6b5ejvlltm8eeif0bnk" 2024/04/26 01:46:40 DEBUG : 1: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/26 01:46:40 DEBUG : 1: Destination found in --compare-dest, skipping 2024/04/26 01:46:40 DEBUG : 2: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/26 01:46:40 DEBUG : 2: Destination found in --compare-dest, skipping 2024/04/26 01:46:41 DEBUG : 3: Need to transfer - File not found at Destination 2024/04/26 01:46:41 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7/dest': Waiting for checks to finish 2024/04/26 01:46:41 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7/dest': Waiting for transfers to finish 2024/04/26 01:46:44 DEBUG : 3: md5 = 3d4e7b49b3d4c43fb803fc58eb000f98 OK 2024/04/26 01:46:44 INFO : 3: Copied (new) 2024/04/26 01:46:44 DEBUG : Waiting for deletions to finish 2024/04/26 01:46:48 DEBUG : dgicm1h6b5ejvlltm8eeif0bnk: Rmdir: contains trashed file: "1ghu8geql9vrl726n32nrf65bc" 2024/04/26 01:46:49 DEBUG : bbnblvh6k061ssopqrp18kd7gc: Rmdir: contains trashed file: "skbfko3oil7es0lj68ob574sro" 2024/04/26 01:46:51 DEBUG : rg03c1jvnehrrc617i0lnqjddc: Rmdir: contains trashed file: "g072p7hmjchlnj0gibe64c1epg" --- PASS: TestSyncMultipleCompareDest (23.22s) === RUN TestSyncCopyDest run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:46:52 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7/dst" 2024/04/26 01:46:52 DEBUG : Creating backend with remote "TestDrive:crypt/i82nm4fm1mic70fi1jf5dgvps1ph404sg69dve7khefh6dplf6dl19cul3rrof4h01l559enj97tc/31u3jie661vd5p8j7rtc3hgbh0" 2024/04/26 01:46:53 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7/CopyDest" 2024/04/26 01:46:53 DEBUG : Creating backend with remote "TestDrive:crypt/i82nm4fm1mic70fi1jf5dgvps1ph404sg69dve7khefh6dplf6dl19cul3rrof4h01l559enj97tc/d09o6po3f7bm6ce32vdgs8h9ls" 2024/04/26 01:46:56 DEBUG : one: Need to transfer - File not found at Destination 2024/04/26 01:46:56 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7/dst': Waiting for checks to finish 2024/04/26 01:46:56 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7/dst': Waiting for transfers to finish 2024/04/26 01:46:59 DEBUG : one: md5 = 902aec04bfde8ba3e31c78cd47d6d70e OK 2024/04/26 01:46:59 INFO : one: Copied (new) 2024/04/26 01:46:59 DEBUG : Waiting for deletions to finish 2024/04/26 01:47:00 DEBUG : one: Sizes differ (src 5 vs dst 3) 2024/04/26 01:47:00 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7/dst': Waiting for checks to finish 2024/04/26 01:47:01 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7/dst': Waiting for transfers to finish 2024/04/26 01:47:02 DEBUG : one: md5 = cfcac4d380da4e9a4ec2af8972079f49 OK 2024/04/26 01:47:02 INFO : one: Copied (replaced existing) 2024/04/26 01:47:02 DEBUG : Waiting for deletions to finish 2024/04/26 01:47:05 DEBUG : dst/one: md5 = 80aba345fc8c4afbce24f071f7c2af87 OK 2024/04/26 01:47:08 DEBUG : CopyDest/one: md5 = 3f13313f8254d908e40be76b38d986ee OK 2024/04/26 01:47:09 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7/BackupDir" 2024/04/26 01:47:09 DEBUG : Creating backend with remote "TestDrive:crypt/i82nm4fm1mic70fi1jf5dgvps1ph404sg69dve7khefh6dplf6dl19cul3rrof4h01l559enj97tc/s6dbk3lfi7c9kfvo6j7bla9m0g" 2024/04/26 01:47:11 DEBUG : one: Sizes differ (src 5 vs dst 3) 2024/04/26 01:47:11 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7/dst': Waiting for checks to finish 2024/04/26 01:47:11 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2024/04/26 01:47:11 DEBUG : one: Sizes differ (src 5 vs dst 3) 2024/04/26 01:47:14 INFO : one: Moved (server-side) 2024/04/26 01:47:16 INFO : one: Copied (server-side copy) 2024/04/26 01:47:16 DEBUG : one: Destination found in --copy-dest, using server-side copy 2024/04/26 01:47:16 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7/dst': Waiting for transfers to finish 2024/04/26 01:47:16 DEBUG : Waiting for deletions to finish 2024/04/26 01:47:18 DEBUG : CopyDest/two: md5 = 2da8c82fe5c45c2633b22cefc6d605c7 OK 2024/04/26 01:47:20 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2024/04/26 01:47:21 INFO : two: Copied (server-side copy) 2024/04/26 01:47:21 DEBUG : two: Destination found in --copy-dest, using server-side copy 2024/04/26 01:47:21 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2024/04/26 01:47:21 DEBUG : one: Unchanged skipping 2024/04/26 01:47:21 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7/dst': Waiting for checks to finish 2024/04/26 01:47:21 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7/dst': Waiting for transfers to finish 2024/04/26 01:47:21 DEBUG : Waiting for deletions to finish 2024/04/26 01:47:22 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7/dst': Waiting for checks to finish 2024/04/26 01:47:22 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2024/04/26 01:47:22 DEBUG : one: Unchanged skipping 2024/04/26 01:47:22 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2024/04/26 01:47:22 DEBUG : two: Unchanged skipping 2024/04/26 01:47:22 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7/dst': Waiting for transfers to finish 2024/04/26 01:47:22 DEBUG : Waiting for deletions to finish 2024/04/26 01:47:22 INFO : There was nothing to transfer 2024/04/26 01:47:25 DEBUG : CopyDest/three: md5 = 842f41b55e240921425b37999371a9c8 OK 2024/04/26 01:47:26 DEBUG : three: Sizes differ (src 7 vs dst 5) 2024/04/26 01:47:26 DEBUG : three: Destination not found in --copy-dest 2024/04/26 01:47:26 DEBUG : three: Need to transfer - File not found at Destination 2024/04/26 01:47:26 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2024/04/26 01:47:26 DEBUG : two: Unchanged skipping 2024/04/26 01:47:26 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7/dst': Waiting for checks to finish 2024/04/26 01:47:26 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2024/04/26 01:47:26 DEBUG : one: Unchanged skipping 2024/04/26 01:47:26 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7/dst': Waiting for transfers to finish 2024/04/26 01:47:28 DEBUG : three: md5 = 2b801f0538340cd9738aa1c28d740672 OK 2024/04/26 01:47:28 INFO : three: Copied (new) 2024/04/26 01:47:28 DEBUG : Waiting for deletions to finish 2024/04/26 01:47:35 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "b6jdmn2b1adrhc8vikh7edr9os" 2024/04/26 01:47:35 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" 2024/04/26 01:47:35 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2024/04/26 01:47:36 DEBUG : d09o6po3f7bm6ce32vdgs8h9ls: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2024/04/26 01:47:36 DEBUG : d09o6po3f7bm6ce32vdgs8h9ls: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" 2024/04/26 01:47:36 DEBUG : d09o6po3f7bm6ce32vdgs8h9ls: Rmdir: contains trashed file: "b6jdmn2b1adrhc8vikh7edr9os" 2024/04/26 01:47:37 DEBUG : s6dbk3lfi7c9kfvo6j7bla9m0g: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" --- PASS: TestSyncCopyDest (46.28s) === RUN TestSyncBackupDir run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:47:41 DEBUG : dst/one: md5 = 1776c58b15b2104c51f525edaceb0c81 OK 2024/04/26 01:47:43 DEBUG : dst/two: md5 = a5f73aa87505e2003d24d06c9bf163fc OK 2024/04/26 01:47:45 DEBUG : dst/three.txt: md5 = 3a3240515e0d73b10df75c7d8cbffd7f OK 2024/04/26 01:47:45 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7/dst" 2024/04/26 01:47:45 DEBUG : Creating backend with remote "TestDrive:crypt/i82nm4fm1mic70fi1jf5dgvps1ph404sg69dve7khefh6dplf6dl19cul3rrof4h01l559enj97tc/31u3jie661vd5p8j7rtc3hgbh0" 2024/04/26 01:47:46 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7/backup" 2024/04/26 01:47:46 DEBUG : Creating backend with remote "TestDrive:crypt/i82nm4fm1mic70fi1jf5dgvps1ph404sg69dve7khefh6dplf6dl19cul3rrof4h01l559enj97tc/1nrff024r7pq65ecp72fc28jb0" 2024/04/26 01:47:48 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7/dst': Waiting for checks to finish 2024/04/26 01:47:48 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/26 01:47:48 DEBUG : one: Sizes differ (src 4 vs dst 3) 2024/04/26 01:47:48 DEBUG : two: Unchanged skipping 2024/04/26 01:47:51 INFO : one: Moved (server-side) 2024/04/26 01:47:51 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7/dst': Waiting for transfers to finish 2024/04/26 01:47:53 DEBUG : one: md5 = 1df0dc0f9be8f6ba214a187ba12a394b OK 2024/04/26 01:47:53 INFO : one: Copied (new) 2024/04/26 01:47:53 DEBUG : Waiting for deletions to finish 2024/04/26 01:47:54 INFO : three.txt: Moved (server-side) 2024/04/26 01:47:54 INFO : three.txt: Moved into backup dir 2024/04/26 01:47:57 DEBUG : dst/three.txt: md5 = c317744ebdf3e7ca6ebb00fe21827f01 OK 2024/04/26 01:47:58 DEBUG : one: Sizes differ (src 5 vs dst 4) 2024/04/26 01:47:58 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/26 01:47:58 DEBUG : two: Unchanged skipping 2024/04/26 01:47:58 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7/dst': Waiting for checks to finish 2024/04/26 01:47:59 INFO : one: Deleted 2024/04/26 01:48:00 INFO : one: Moved (server-side) 2024/04/26 01:48:00 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7/dst': Waiting for transfers to finish 2024/04/26 01:48:02 DEBUG : one: md5 = 30f36ccadd8517cb9ccb2ff8456b0aee OK 2024/04/26 01:48:02 INFO : one: Copied (new) 2024/04/26 01:48:02 DEBUG : Waiting for deletions to finish 2024/04/26 01:48:03 INFO : three.txt: Deleted 2024/04/26 01:48:04 INFO : three.txt: Moved (server-side) 2024/04/26 01:48:04 INFO : three.txt: Moved into backup dir 2024/04/26 01:48:09 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2024/04/26 01:48:09 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" 2024/04/26 01:48:10 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2024/04/26 01:48:10 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "tr2hj63d80ftlmvm6a952snjcc" 2024/04/26 01:48:10 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "tr2hj63d80ftlmvm6a952snjcc" 2024/04/26 01:48:10 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" --- PASS: TestSyncBackupDir (33.52s) === RUN TestSyncBackupDirWithSuffix run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:48:14 DEBUG : dst/one: md5 = a219c7682a5f826268d8efb5c853041f OK 2024/04/26 01:48:16 DEBUG : dst/two: md5 = 3d233f30ca3da44b45255ddb2c6f36bb OK 2024/04/26 01:48:18 DEBUG : dst/three.txt: md5 = de0ffaa500128aacd0933b3603f9d9b1 OK 2024/04/26 01:48:18 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7/dst" 2024/04/26 01:48:18 DEBUG : Creating backend with remote "TestDrive:crypt/i82nm4fm1mic70fi1jf5dgvps1ph404sg69dve7khefh6dplf6dl19cul3rrof4h01l559enj97tc/31u3jie661vd5p8j7rtc3hgbh0" 2024/04/26 01:48:19 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7/backup" 2024/04/26 01:48:19 DEBUG : Creating backend with remote "TestDrive:crypt/i82nm4fm1mic70fi1jf5dgvps1ph404sg69dve7khefh6dplf6dl19cul3rrof4h01l559enj97tc/1nrff024r7pq65ecp72fc28jb0" 2024/04/26 01:48:22 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7/dst': Waiting for checks to finish 2024/04/26 01:48:22 DEBUG : one: Sizes differ (src 4 vs dst 3) 2024/04/26 01:48:22 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/26 01:48:22 DEBUG : two: Unchanged skipping 2024/04/26 01:48:27 INFO : one: Moved (server-side) to: one.bak 2024/04/26 01:48:27 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7/dst': Waiting for transfers to finish 2024/04/26 01:48:29 DEBUG : one: md5 = 27524e1e18422687c383d51542b63e38 OK 2024/04/26 01:48:29 INFO : one: Copied (new) 2024/04/26 01:48:29 DEBUG : Waiting for deletions to finish 2024/04/26 01:48:30 INFO : three.txt: Moved (server-side) to: three.txt.bak 2024/04/26 01:48:30 INFO : three.txt: Moved into backup dir 2024/04/26 01:48:32 DEBUG : dst/three.txt: md5 = 4d4a54b004beca078a5efe4a5abe057e OK 2024/04/26 01:48:33 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7/dst': Waiting for checks to finish 2024/04/26 01:48:33 DEBUG : one: Sizes differ (src 5 vs dst 4) 2024/04/26 01:48:33 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/26 01:48:33 DEBUG : two: Unchanged skipping 2024/04/26 01:48:34 INFO : one.bak: Deleted 2024/04/26 01:48:35 INFO : one: Moved (server-side) to: one.bak 2024/04/26 01:48:35 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7/dst': Waiting for transfers to finish 2024/04/26 01:48:37 DEBUG : one: md5 = 4385f2600d38beec02f75c5d4771d06d OK 2024/04/26 01:48:37 INFO : one: Copied (new) 2024/04/26 01:48:37 DEBUG : Waiting for deletions to finish 2024/04/26 01:48:39 INFO : three.txt.bak: Deleted 2024/04/26 01:48:40 INFO : three.txt: Moved (server-side) to: three.txt.bak 2024/04/26 01:48:40 INFO : three.txt: Moved into backup dir 2024/04/26 01:48:44 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2024/04/26 01:48:44 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" 2024/04/26 01:48:46 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "sk91qgsqfn0r271r2ehsaoc20c" 2024/04/26 01:48:46 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "qltcak2uaegtmcoa8vijdppbp8" 2024/04/26 01:48:46 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "qltcak2uaegtmcoa8vijdppbp8" 2024/04/26 01:48:46 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "sk91qgsqfn0r271r2ehsaoc20c" --- PASS: TestSyncBackupDirWithSuffix (35.50s) === RUN TestSyncBackupDirWithSuffixKeepExtension run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:48:50 DEBUG : dst/one: md5 = 19222a7a0ee873003077acc3e56fc1a8 OK 2024/04/26 01:48:52 DEBUG : dst/two: md5 = be9e1d906891a187c25c12e5e046d9a3 OK 2024/04/26 01:48:54 DEBUG : dst/three.txt: md5 = 72fc64dd6f0b39b1907e8b7c0fd9ab33 OK 2024/04/26 01:48:54 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7/dst" 2024/04/26 01:48:54 DEBUG : Creating backend with remote "TestDrive:crypt/i82nm4fm1mic70fi1jf5dgvps1ph404sg69dve7khefh6dplf6dl19cul3rrof4h01l559enj97tc/31u3jie661vd5p8j7rtc3hgbh0" 2024/04/26 01:48:56 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7/backup" 2024/04/26 01:48:56 DEBUG : Creating backend with remote "TestDrive:crypt/i82nm4fm1mic70fi1jf5dgvps1ph404sg69dve7khefh6dplf6dl19cul3rrof4h01l559enj97tc/1nrff024r7pq65ecp72fc28jb0" 2024/04/26 01:48:58 DEBUG : one: Sizes differ (src 4 vs dst 3) 2024/04/26 01:48:58 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/26 01:48:58 DEBUG : two: Unchanged skipping 2024/04/26 01:48:58 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7/dst': Waiting for checks to finish 2024/04/26 01:49:01 INFO : one: Moved (server-side) to: one-2019-01-01 2024/04/26 01:49:01 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7/dst': Waiting for transfers to finish 2024/04/26 01:49:03 DEBUG : one: md5 = f296f9d5c0af41c20dacced3421a6d5b OK 2024/04/26 01:49:03 INFO : one: Copied (new) 2024/04/26 01:49:03 DEBUG : Waiting for deletions to finish 2024/04/26 01:49:04 INFO : three.txt: Moved (server-side) to: three-2019-01-01.txt 2024/04/26 01:49:04 INFO : three.txt: Moved into backup dir 2024/04/26 01:49:07 DEBUG : dst/three.txt: md5 = d191f410563cd28d166de216d0d4def4 OK 2024/04/26 01:49:08 DEBUG : one: Sizes differ (src 5 vs dst 4) 2024/04/26 01:49:08 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/26 01:49:08 DEBUG : two: Unchanged skipping 2024/04/26 01:49:08 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7/dst': Waiting for checks to finish 2024/04/26 01:49:09 INFO : one-2019-01-01: Deleted 2024/04/26 01:49:10 INFO : one: Moved (server-side) to: one-2019-01-01 2024/04/26 01:49:10 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7/dst': Waiting for transfers to finish 2024/04/26 01:49:12 DEBUG : one: md5 = ff917081b683871674038a36ca864c9c OK 2024/04/26 01:49:12 INFO : one: Copied (new) 2024/04/26 01:49:12 DEBUG : Waiting for deletions to finish 2024/04/26 01:49:13 INFO : three-2019-01-01.txt: Deleted 2024/04/26 01:49:14 INFO : three.txt: Moved (server-side) to: three-2019-01-01.txt 2024/04/26 01:49:14 INFO : three.txt: Moved into backup dir 2024/04/26 01:49:19 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2024/04/26 01:49:19 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" 2024/04/26 01:49:20 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "qtq2f6qq4lgpsmj88vb7147qje3prudmtfdtr2342fth58vo9a50" 2024/04/26 01:49:20 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "jcjl1bv3ep0v8kt35lqql1co90" 2024/04/26 01:49:20 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "jcjl1bv3ep0v8kt35lqql1co90" 2024/04/26 01:49:20 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "qtq2f6qq4lgpsmj88vb7147qje3prudmtfdtr2342fth58vo9a50" --- PASS: TestSyncBackupDirWithSuffixKeepExtension (33.93s) === RUN TestSyncBackupDirSuffixOnly run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:49:24 DEBUG : dst/one: md5 = f88412efe02a6747143cf96e07669935 OK 2024/04/26 01:49:26 DEBUG : dst/two: md5 = 6eeec6f52f3fc15f1b42d3b193e91910 OK 2024/04/26 01:49:28 DEBUG : dst/three.txt: md5 = 0b477aba373c278abd95e001b6fa3a98 OK 2024/04/26 01:49:28 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7/dst" 2024/04/26 01:49:28 DEBUG : Creating backend with remote "TestDrive:crypt/i82nm4fm1mic70fi1jf5dgvps1ph404sg69dve7khefh6dplf6dl19cul3rrof4h01l559enj97tc/31u3jie661vd5p8j7rtc3hgbh0" 2024/04/26 01:49:30 DEBUG : one: Sizes differ (src 4 vs dst 3) 2024/04/26 01:49:30 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7/dst': Waiting for checks to finish 2024/04/26 01:49:30 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/26 01:49:30 DEBUG : two: Unchanged skipping 2024/04/26 01:49:31 INFO : one: Moved (server-side) to: one.bak 2024/04/26 01:49:31 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7/dst': Waiting for transfers to finish 2024/04/26 01:49:33 DEBUG : one: md5 = 3842082afa9743a994ca88f21ef7def3 OK 2024/04/26 01:49:33 INFO : one: Copied (new) 2024/04/26 01:49:33 DEBUG : Waiting for deletions to finish 2024/04/26 01:49:34 INFO : three.txt: Moved (server-side) to: three.txt.bak 2024/04/26 01:49:34 INFO : three.txt: Moved into backup dir 2024/04/26 01:49:37 DEBUG : dst/three.txt: md5 = a34999c6daf06744498a0c911ba2bdae OK 2024/04/26 01:49:38 DEBUG : one.bak: Excluded (Path Filter) 2024/04/26 01:49:38 DEBUG : one.bak: Excluded 2024/04/26 01:49:38 DEBUG : three.txt.bak: Excluded (Path Filter) 2024/04/26 01:49:38 DEBUG : three.txt.bak: Excluded 2024/04/26 01:49:38 DEBUG : one: Sizes differ (src 5 vs dst 4) 2024/04/26 01:49:38 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/26 01:49:38 DEBUG : two: Unchanged skipping 2024/04/26 01:49:38 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7/dst': Waiting for checks to finish 2024/04/26 01:49:39 INFO : one.bak: Deleted 2024/04/26 01:49:40 INFO : one: Moved (server-side) to: one.bak 2024/04/26 01:49:40 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7/dst': Waiting for transfers to finish 2024/04/26 01:49:42 DEBUG : one: md5 = 85d264b337f6fb842f8b28853566f38c OK 2024/04/26 01:49:42 INFO : one: Copied (new) 2024/04/26 01:49:42 DEBUG : Waiting for deletions to finish 2024/04/26 01:49:43 INFO : three.txt.bak: Deleted 2024/04/26 01:49:44 INFO : three.txt: Moved (server-side) to: three.txt.bak 2024/04/26 01:49:44 INFO : three.txt: Moved into backup dir 2024/04/26 01:49:49 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2024/04/26 01:49:49 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "qltcak2uaegtmcoa8vijdppbp8" 2024/04/26 01:49:49 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "sk91qgsqfn0r271r2ehsaoc20c" 2024/04/26 01:49:49 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "qltcak2uaegtmcoa8vijdppbp8" 2024/04/26 01:49:49 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "sk91qgsqfn0r271r2ehsaoc20c" 2024/04/26 01:49:49 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" --- PASS: TestSyncBackupDirSuffixOnly (28.90s) === RUN TestSyncSuffix run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:49:53 DEBUG : dst/one: md5 = 5c6e5029b65543f43a91a879a1c20ade OK 2024/04/26 01:49:55 DEBUG : dst/two: md5 = 29ceaa4cb937ae0ec0952f25c521f9ec OK 2024/04/26 01:49:56 DEBUG : dst/three.txt: md5 = 170e3981d14a5a20ece28562b8c8e017 OK 2024/04/26 01:49:57 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7/dst" 2024/04/26 01:49:57 DEBUG : Creating backend with remote "TestDrive:crypt/i82nm4fm1mic70fi1jf5dgvps1ph404sg69dve7khefh6dplf6dl19cul3rrof4h01l559enj97tc/31u3jie661vd5p8j7rtc3hgbh0" 2024/04/26 01:49:58 DEBUG : one: Sizes differ (src 4 vs dst 3) 2024/04/26 01:49:59 INFO : one: Moved (server-side) to: one.bak 2024/04/26 01:50:01 DEBUG : one: md5 = cdb68e0b573f1f37a92315393cf60079 OK 2024/04/26 01:50:01 INFO : one: Copied (new) 2024/04/26 01:50:02 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/26 01:50:02 DEBUG : two: Unchanged skipping 2024/04/26 01:50:02 DEBUG : three.txt: Sizes differ (src 6 vs dst 5) 2024/04/26 01:50:03 INFO : three.txt: Moved (server-side) to: three.txt.bak 2024/04/26 01:50:05 DEBUG : three.txt: md5 = 6e4dbf37dff8c9c9fb3c4c8e1fd51fb8 OK 2024/04/26 01:50:05 INFO : three.txt: Copied (new) 2024/04/26 01:50:07 DEBUG : one: Sizes differ (src 5 vs dst 4) 2024/04/26 01:50:08 INFO : one.bak: Deleted 2024/04/26 01:50:09 INFO : one: Moved (server-side) to: one.bak 2024/04/26 01:50:10 DEBUG : one: md5 = ef83f42a0add04108c000dbd36a92b89 OK 2024/04/26 01:50:10 INFO : one: Copied (new) 2024/04/26 01:50:11 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/26 01:50:11 DEBUG : two: Unchanged skipping 2024/04/26 01:50:11 DEBUG : three.txt: Sizes differ (src 19 vs dst 6) 2024/04/26 01:50:12 INFO : three.txt.bak: Deleted 2024/04/26 01:50:13 INFO : three.txt: Moved (server-side) to: three.txt.bak 2024/04/26 01:50:15 DEBUG : three.txt: md5 = e988e24cd6c2c64a42c669008d9cc383 OK 2024/04/26 01:50:15 INFO : three.txt: Copied (new) 2024/04/26 01:50:22 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "tr2hj63d80ftlmvm6a952snjcc" 2024/04/26 01:50:22 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2024/04/26 01:50:22 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "qltcak2uaegtmcoa8vijdppbp8" 2024/04/26 01:50:22 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" 2024/04/26 01:50:22 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "qltcak2uaegtmcoa8vijdppbp8" 2024/04/26 01:50:22 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "sk91qgsqfn0r271r2ehsaoc20c" 2024/04/26 01:50:22 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "sk91qgsqfn0r271r2ehsaoc20c" --- PASS: TestSyncSuffix (33.46s) === RUN TestSyncSuffixKeepExtension run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:50:26 DEBUG : dst/one: md5 = 2d517e3da9ddb7d2f4a01d955199cbaf OK 2024/04/26 01:50:28 DEBUG : dst/two: md5 = ef49fd90c8e4a8428e92ba4ecf483a05 OK 2024/04/26 01:50:30 DEBUG : dst/three.txt: md5 = 8dece91ed4254f703de770f9ee82b9e0 OK 2024/04/26 01:50:30 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7/dst" 2024/04/26 01:50:31 DEBUG : Creating backend with remote "TestDrive:crypt/i82nm4fm1mic70fi1jf5dgvps1ph404sg69dve7khefh6dplf6dl19cul3rrof4h01l559enj97tc/31u3jie661vd5p8j7rtc3hgbh0" 2024/04/26 01:50:32 DEBUG : one: Sizes differ (src 4 vs dst 3) 2024/04/26 01:50:33 INFO : one: Moved (server-side) to: one-2019-01-01 2024/04/26 01:50:35 DEBUG : one: md5 = eca2d7ddf80a0fd9961a66796b9a7948 OK 2024/04/26 01:50:35 INFO : one: Copied (new) 2024/04/26 01:50:35 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/26 01:50:35 DEBUG : two: Unchanged skipping 2024/04/26 01:50:35 DEBUG : three.txt: Sizes differ (src 6 vs dst 5) 2024/04/26 01:50:36 INFO : three.txt: Moved (server-side) to: three-2019-01-01.txt 2024/04/26 01:50:38 DEBUG : three.txt: md5 = baed7c79cd88d6ee2b5107a60813ebf0 OK 2024/04/26 01:50:38 INFO : three.txt: Copied (new) 2024/04/26 01:50:40 DEBUG : one: Sizes differ (src 5 vs dst 4) 2024/04/26 01:50:41 INFO : one-2019-01-01: Deleted 2024/04/26 01:50:41 INFO : one: Moved (server-side) to: one-2019-01-01 2024/04/26 01:50:43 DEBUG : one: md5 = 6eca46f1ae19c76d624596c9e1effea2 OK 2024/04/26 01:50:43 INFO : one: Copied (new) 2024/04/26 01:50:43 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/26 01:50:43 DEBUG : two: Unchanged skipping 2024/04/26 01:50:44 DEBUG : three.txt: Sizes differ (src 19 vs dst 6) 2024/04/26 01:50:45 INFO : three-2019-01-01.txt: Deleted 2024/04/26 01:50:46 INFO : three.txt: Moved (server-side) to: three-2019-01-01.txt 2024/04/26 01:50:47 DEBUG : three.txt: md5 = 8ada5f284ac731e667ea8bc596711e16 OK 2024/04/26 01:50:47 INFO : three.txt: Copied (new) 2024/04/26 01:50:52 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2024/04/26 01:50:52 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "tr2hj63d80ftlmvm6a952snjcc" 2024/04/26 01:50:52 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "jcjl1bv3ep0v8kt35lqql1co90" 2024/04/26 01:50:52 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "jcjl1bv3ep0v8kt35lqql1co90" 2024/04/26 01:50:52 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "qtq2f6qq4lgpsmj88vb7147qje3prudmtfdtr2342fth58vo9a50" 2024/04/26 01:50:52 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "qtq2f6qq4lgpsmj88vb7147qje3prudmtfdtr2342fth58vo9a50" 2024/04/26 01:50:52 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" --- PASS: TestSyncSuffixKeepExtension (30.20s) === RUN TestSyncUTFNorm run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:50:55 DEBUG : Testêé: md5 = 380b0bbf9fa3bd444a7405ff4c592d4b OK 2024/04/26 01:50:56 DEBUG : Testêé: Sizes differ (src 14 vs dst 18) 2024/04/26 01:50:56 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for checks to finish 2024/04/26 01:50:56 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for transfers to finish 2024/04/26 01:50:57 DEBUG : Testêé: md5 = 5ae2bce9c6294059a2bd1ed5fd4932d6 OK 2024/04/26 01:50:57 INFO : Testêé: Copied (replaced existing) to: Testêé 2024/04/26 01:50:57 DEBUG : Waiting for deletions to finish --- PASS: TestSyncUTFNorm (5.43s) === RUN TestSyncImmutable run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:50:59 DEBUG : existing: Need to transfer - File not found at Destination 2024/04/26 01:50:59 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for checks to finish 2024/04/26 01:50:59 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for transfers to finish 2024/04/26 01:51:01 DEBUG : existing: md5 = 6835e8e8dcd5363ab855b4570a077ee2 OK 2024/04/26 01:51:01 INFO : existing: Copied (new) 2024/04/26 01:51:01 DEBUG : Waiting for deletions to finish run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:51:02 DEBUG : existing: Sizes differ (src 8 vs dst 6) 2024/04/26 01:51:02 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for checks to finish 2024/04/26 01:51:02 ERROR : existing: Source and destination exist but do not match: immutable file modified 2024/04/26 01:51:02 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for transfers to finish 2024/04/26 01:51:02 ERROR : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': not deleting files as there were IO errors 2024/04/26 01:51:02 ERROR : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': not deleting directories as there were IO errors run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" --- PASS: TestSyncImmutable (5.87s) === RUN TestSyncIgnoreCase run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:51:07 DEBUG : EXISTING: md5 = b8e30520bdb3ff40b5895f4b4c7fff44 OK 2024/04/26 01:51:07 DEBUG : existing: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/26 01:51:07 DEBUG : existing: Unchanged skipping 2024/04/26 01:51:07 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for checks to finish 2024/04/26 01:51:07 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for transfers to finish 2024/04/26 01:51:07 DEBUG : Waiting for deletions to finish 2024/04/26 01:51:07 INFO : There was nothing to transfer --- PASS: TestSyncIgnoreCase (4.13s) === RUN TestFixCase run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" sync_test.go:2420: Skipping test as local or remote are case-sensitive --- SKIP: TestFixCase (0.55s) === RUN TestMaxTransfer === RUN TestMaxTransfer/Hard run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" sync_test.go:2459: This test only runs on local === RUN TestMaxTransfer/Soft run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" sync_test.go:2459: This test only runs on local === RUN TestMaxTransfer/Cautious run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" sync_test.go:2459: This test only runs on local --- PASS: TestMaxTransfer (1.58s) --- SKIP: TestMaxTransfer/Hard (0.53s) --- SKIP: TestMaxTransfer/Soft (0.52s) --- SKIP: TestMaxTransfer/Cautious (0.53s) === RUN TestSyncConcurrentDelete run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:51:13 DEBUG : both0: md5 = 222e9efd6979a36684a9b7e418cf97f8 OK 2024/04/26 01:51:14 DEBUG : only0: md5 = a2e37140bbeb85524ddc97c5e5b4427d OK 2024/04/26 01:51:16 DEBUG : both1: md5 = 7faba8d567db5f1320534e2ce917dda9 OK 2024/04/26 01:51:18 DEBUG : only1: md5 = 6c6369b59b9f038889aaa3507b063ef5 OK 2024/04/26 01:51:20 DEBUG : both2: md5 = 3267695b1db39daa26a1eed16983bc2c OK 2024/04/26 01:51:21 DEBUG : only2: md5 = 879cc04cc4066042b07a46a3d6114fcf OK 2024/04/26 01:51:23 DEBUG : both3: md5 = ffd2ccbd87652143485a18867ddd6045 OK 2024/04/26 01:51:25 DEBUG : only3: md5 = e9ab24b81538dc830c5865b0f3538592 OK 2024/04/26 01:51:27 DEBUG : both4: md5 = 2b3802375e9f764aaeae0b71d7c34698 OK 2024/04/26 01:51:28 DEBUG : only4: md5 = 96a88496df6e4fe356b00b6a6a0d1c61 OK 2024/04/26 01:51:30 DEBUG : both5: md5 = 2aec4475c4dbae630353a705d5e2f86e OK 2024/04/26 01:51:32 DEBUG : only5: md5 = fae6611dcd546082071bcb05726f8833 OK 2024/04/26 01:51:33 DEBUG : both6: md5 = 9465778ee32ee06491f0538db89d04dd OK 2024/04/26 01:51:35 DEBUG : only6: md5 = 5ed8c945c1a289af2d58a05a6c71ae6c OK 2024/04/26 01:51:37 DEBUG : both7: md5 = 5dc68fb5a181e6f000d198ce13a7c131 OK 2024/04/26 01:51:39 DEBUG : only7: md5 = fc62628773b19b729697e9b48f95a65c OK 2024/04/26 01:51:41 DEBUG : both8: md5 = 5d39dd9dcaa1aac40c7d7b3b87b0e986 OK 2024/04/26 01:51:42 DEBUG : only8: md5 = 7c205361e960d844186530111bf24374 OK 2024/04/26 01:51:44 DEBUG : both9: md5 = 83c89b8ed5de105a7b94a91d88fa8c4f OK 2024/04/26 01:51:46 DEBUG : only9: md5 = 8329c6e49ef4597f31069470cbca0182 OK 2024/04/26 01:51:48 DEBUG : both10: md5 = a9818066bf8d38fd90ecf5058326fabd OK 2024/04/26 01:51:49 DEBUG : only10: md5 = ccc57f7758ad2b730adb4bfff6f598b8 OK 2024/04/26 01:51:51 DEBUG : both11: md5 = ccca793819f5ecae98caa100f8942935 OK 2024/04/26 01:51:53 DEBUG : only11: md5 = 21135ec0b2bd9f70c9815b24cc3d3490 OK 2024/04/26 01:51:55 DEBUG : both12: md5 = dd54ac332a38f20798f93b2bea9a841f OK 2024/04/26 01:51:56 DEBUG : only12: md5 = 6a20d34f243362f32bb0de9503bb10d8 OK 2024/04/26 01:51:58 DEBUG : both13: md5 = 88ef986e57d7ee72a52927f59a67be4e OK 2024/04/26 01:52:00 DEBUG : only13: md5 = 9e597ce6f96c0f45718cbd9c14965524 OK 2024/04/26 01:52:02 DEBUG : both14: md5 = 7bf715d41e3e04690f5b40956504d722 OK 2024/04/26 01:52:04 DEBUG : only14: md5 = be583dee0a248cb85c92984ae9d198da OK 2024/04/26 01:52:06 DEBUG : both15: md5 = d848b81df513e5e76c65cdf496b4bef2 OK 2024/04/26 01:52:07 DEBUG : only15: md5 = 93364b200df97caca1478cf2cabd5812 OK 2024/04/26 01:52:09 DEBUG : both16: md5 = 0ff7948e03bb389298e279b13d1f3a12 OK 2024/04/26 01:52:11 DEBUG : only16: md5 = b9eddbdeba3468b892d542dee9e44dae OK 2024/04/26 01:52:12 DEBUG : both17: md5 = e416a82a67437310ba33d00e1e102ef3 OK 2024/04/26 01:52:14 DEBUG : only17: md5 = 6a13d822e201890cdd8726eaae6e6971 OK 2024/04/26 01:52:16 DEBUG : both18: md5 = 1f8282201e576eed46c3e6926dd84ed3 OK 2024/04/26 01:52:18 DEBUG : only18: md5 = e97f5b17c1de7ff85ecb0ae62db549e6 OK 2024/04/26 01:52:20 DEBUG : both19: md5 = 1104b9e4aef42cd8f39e29b330aa8b7d OK 2024/04/26 01:52:22 DEBUG : only19: md5 = b464fb3f4236deb5ed5e53bc01edfea4 OK 2024/04/26 01:52:22 DEBUG : both0: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/26 01:52:22 DEBUG : both1: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/26 01:52:22 DEBUG : both0: Unchanged skipping 2024/04/26 01:52:22 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for checks to finish 2024/04/26 01:52:22 DEBUG : both11: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/26 01:52:22 DEBUG : both12: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/26 01:52:22 DEBUG : both10: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/26 01:52:22 DEBUG : both11: Unchanged skipping 2024/04/26 01:52:22 DEBUG : both13: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/26 01:52:22 DEBUG : both13: Unchanged skipping 2024/04/26 01:52:22 DEBUG : both14: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/26 01:52:22 DEBUG : both14: Unchanged skipping 2024/04/26 01:52:22 DEBUG : both15: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/26 01:52:22 DEBUG : both12: Unchanged skipping 2024/04/26 01:52:22 DEBUG : both16: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/26 01:52:22 DEBUG : both16: Unchanged skipping 2024/04/26 01:52:22 DEBUG : both17: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/26 01:52:22 DEBUG : both17: Unchanged skipping 2024/04/26 01:52:22 DEBUG : both18: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/26 01:52:22 DEBUG : both1: Unchanged skipping 2024/04/26 01:52:22 DEBUG : both19: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/26 01:52:22 DEBUG : both10: Unchanged skipping 2024/04/26 01:52:22 DEBUG : both2: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/26 01:52:22 DEBUG : both15: Unchanged skipping 2024/04/26 01:52:22 DEBUG : both3: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/26 01:52:22 DEBUG : both18: Unchanged skipping 2024/04/26 01:52:22 DEBUG : both4: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/26 01:52:22 DEBUG : both4: Unchanged skipping 2024/04/26 01:52:22 DEBUG : both5: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/26 01:52:22 DEBUG : both5: Unchanged skipping 2024/04/26 01:52:22 DEBUG : both6: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/26 01:52:22 DEBUG : both6: Unchanged skipping 2024/04/26 01:52:22 DEBUG : both7: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/26 01:52:22 DEBUG : both19: Unchanged skipping 2024/04/26 01:52:22 DEBUG : both8: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/26 01:52:22 DEBUG : both2: Unchanged skipping 2024/04/26 01:52:22 DEBUG : both9: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/26 01:52:22 DEBUG : both3: Unchanged skipping 2024/04/26 01:52:22 DEBUG : both7: Unchanged skipping 2024/04/26 01:52:22 DEBUG : both8: Unchanged skipping 2024/04/26 01:52:22 DEBUG : both9: Unchanged skipping 2024/04/26 01:52:22 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for transfers to finish 2024/04/26 01:52:22 DEBUG : Waiting for deletions to finish 2024/04/26 01:52:23 INFO : only14: Deleted 2024/04/26 01:52:23 INFO : only3: Deleted 2024/04/26 01:52:23 INFO : only6: Deleted 2024/04/26 01:52:23 INFO : only13: Deleted 2024/04/26 01:52:24 INFO : only4: Deleted 2024/04/26 01:52:24 INFO : only0: Deleted 2024/04/26 01:52:24 INFO : only1: Deleted 2024/04/26 01:52:24 INFO : only11: Deleted 2024/04/26 01:52:24 INFO : only12: Deleted 2024/04/26 01:52:25 INFO : only15: Deleted 2024/04/26 01:52:25 INFO : only16: Deleted 2024/04/26 01:52:25 INFO : only5: Deleted 2024/04/26 01:52:25 INFO : only7: Deleted 2024/04/26 01:52:25 INFO : only8: Deleted 2024/04/26 01:52:25 INFO : only10: Deleted 2024/04/26 01:52:26 INFO : only9: Deleted 2024/04/26 01:52:26 INFO : only18: Deleted 2024/04/26 01:52:26 INFO : only2: Deleted 2024/04/26 01:52:26 INFO : only17: Deleted 2024/04/26 01:52:26 INFO : only19: Deleted 2024/04/26 01:52:26 INFO : There was nothing to transfer run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" --- PASS: TestSyncConcurrentDelete (91.10s) === RUN TestSyncConcurrentTruncate run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:52:44 DEBUG : both0: md5 = cde65ab18087a4b2a28a5ea36bdb257a OK 2024/04/26 01:52:46 DEBUG : only0: md5 = 1ee476a4e566c698893458495a554eb4 OK 2024/04/26 01:52:48 DEBUG : both1: md5 = 1084aacb4d12314c4f25edd5feb13300 OK 2024/04/26 01:52:50 DEBUG : only1: md5 = a4cd8541de40bd3fff67bedecdd05adb OK 2024/04/26 01:52:52 DEBUG : both2: md5 = e5211daf821665f9ce89094da2c2f47b OK 2024/04/26 01:52:54 DEBUG : only2: md5 = 5286ee4a1fafd8d7b155de84d075da73 OK 2024/04/26 01:52:56 DEBUG : both3: md5 = eccc53bbd9df664df0352ea7544aded1 OK 2024/04/26 01:52:58 DEBUG : only3: md5 = c4824e3763863c97e59279da4dcdec89 OK 2024/04/26 01:52:59 DEBUG : both4: md5 = 81c2847d4c64410e1d67397f75bcb993 OK 2024/04/26 01:53:02 DEBUG : only4: md5 = 4eb9b2b90581a530605650421a9e4d04 OK 2024/04/26 01:53:04 DEBUG : both5: md5 = 859fa0a47c70a4d9aea8cc9110e083c3 OK 2024/04/26 01:53:05 DEBUG : only5: md5 = 08e4c56f0d48b47ac39ca686ebb36a77 OK 2024/04/26 01:53:07 DEBUG : both6: md5 = 1f72f2bca78c4bf21a8c9321038fd451 OK 2024/04/26 01:53:09 DEBUG : only6: md5 = 91a1955e1875f6775a39b6f8c5a1ffbd OK 2024/04/26 01:53:11 DEBUG : both7: md5 = 209acacfa36a7b13d24c5091ab940610 OK 2024/04/26 01:53:13 DEBUG : only7: md5 = 5ed730bb2b0847b6be0caaf0f5b59cb5 OK 2024/04/26 01:53:15 DEBUG : both8: md5 = d36761d20396fb9819fa69ab828f283b OK 2024/04/26 01:53:16 DEBUG : only8: md5 = 5524dee51634aabb57acc5095d7e6866 OK 2024/04/26 01:53:18 DEBUG : both9: md5 = 2df025cef6c61cd7a869d14b7179476b OK 2024/04/26 01:53:21 DEBUG : only9: md5 = c8b3654dfbb393bb584938e1cbd2af96 OK 2024/04/26 01:53:22 DEBUG : both10: md5 = 54f7c27727ebfe957b0cc1e38d4563f4 OK 2024/04/26 01:53:24 DEBUG : only10: md5 = 2d8e4db8bba7b54ad4d079c1fa97b44e OK 2024/04/26 01:53:26 DEBUG : both11: md5 = 56496d672fcba0386d80519f9e639275 OK 2024/04/26 01:53:28 DEBUG : only11: md5 = 9dd27281083b31035f7fdb887f4e4bdd OK 2024/04/26 01:53:29 DEBUG : both12: md5 = e200fff02485e326f5a711bae80f0691 OK 2024/04/26 01:53:31 DEBUG : only12: md5 = 5ab8df414fb929a1bd121abfacec8e90 OK 2024/04/26 01:53:33 DEBUG : both13: md5 = bd96061dee161141392e5b8a1697b625 OK 2024/04/26 01:53:35 DEBUG : only13: md5 = 5317b52ff754eeaa77bed5605266223f OK 2024/04/26 01:53:36 DEBUG : both14: md5 = 8d8324b81240468e5f471c82ae08b0d5 OK 2024/04/26 01:53:38 DEBUG : only14: md5 = 0bc6d4fbe18f23978a52c205aebb4f09 OK 2024/04/26 01:53:40 DEBUG : both15: md5 = b2497d8ba26137f49c03c74af0b6aa12 OK 2024/04/26 01:53:42 DEBUG : only15: md5 = df03ebaa32e2ecc6f38bc7c3dfd7802b OK 2024/04/26 01:53:44 DEBUG : both16: md5 = ab2ff6e2e44e94b87ffc5f3e8ac93882 OK 2024/04/26 01:53:46 DEBUG : only16: md5 = 34d64c3c9bceb37c1359e82db1302125 OK 2024/04/26 01:53:47 DEBUG : both17: md5 = f4a069689516dda46778e881557bd35e OK 2024/04/26 01:53:49 DEBUG : only17: md5 = a75a9952abcbf663e9befcf6d09d2432 OK 2024/04/26 01:53:51 DEBUG : both18: md5 = eb251155c612c82476c90d7a8e74552b OK 2024/04/26 01:53:53 DEBUG : only18: md5 = b80c7314e8feec4d22c5a92241cdf332 OK 2024/04/26 01:53:55 DEBUG : both19: md5 = 5acb1abe08838e70716c26a79a51e599 OK 2024/04/26 01:53:56 DEBUG : only19: md5 = a2a0e3ac0c80ff1c1802128315785b48 OK 2024/04/26 01:53:57 DEBUG : both1: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/26 01:53:57 DEBUG : both0: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/26 01:53:57 DEBUG : both10: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/26 01:53:57 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for checks to finish 2024/04/26 01:53:57 DEBUG : both11: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/26 01:53:57 DEBUG : both1: Unchanged skipping 2024/04/26 01:53:57 DEBUG : both12: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/26 01:53:57 DEBUG : both0: Unchanged skipping 2024/04/26 01:53:57 DEBUG : both13: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/26 01:53:57 DEBUG : both12: Unchanged skipping 2024/04/26 01:53:57 DEBUG : both14: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/26 01:53:57 DEBUG : both14: Unchanged skipping 2024/04/26 01:53:57 DEBUG : both15: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/26 01:53:57 DEBUG : both10: Unchanged skipping 2024/04/26 01:53:57 DEBUG : both16: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/26 01:53:57 DEBUG : both11: Unchanged skipping 2024/04/26 01:53:57 DEBUG : both17: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/26 01:53:57 DEBUG : both17: Unchanged skipping 2024/04/26 01:53:57 DEBUG : both18: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/26 01:53:57 DEBUG : both13: Unchanged skipping 2024/04/26 01:53:57 DEBUG : both19: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/26 01:53:57 DEBUG : both19: Unchanged skipping 2024/04/26 01:53:57 DEBUG : both2: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/26 01:53:57 DEBUG : both15: Unchanged skipping 2024/04/26 01:53:57 DEBUG : both3: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/26 01:53:57 DEBUG : both3: Unchanged skipping 2024/04/26 01:53:57 DEBUG : both4: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/26 01:53:57 DEBUG : both16: Unchanged skipping 2024/04/26 01:53:57 DEBUG : both5: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/26 01:53:57 DEBUG : both5: Unchanged skipping 2024/04/26 01:53:57 DEBUG : both6: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/26 01:53:57 DEBUG : both6: Unchanged skipping 2024/04/26 01:53:57 DEBUG : both7: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/26 01:53:57 DEBUG : both18: Unchanged skipping 2024/04/26 01:53:57 DEBUG : both8: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/26 01:53:57 DEBUG : both8: Unchanged skipping 2024/04/26 01:53:57 DEBUG : both9: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2024/04/26 01:53:57 DEBUG : both9: Unchanged skipping 2024/04/26 01:53:57 DEBUG : only0: Sizes differ (src 0 vs dst 6) 2024/04/26 01:53:57 DEBUG : only1: Sizes differ (src 0 vs dst 6) 2024/04/26 01:53:57 DEBUG : only10: Sizes differ (src 0 vs dst 6) 2024/04/26 01:53:57 DEBUG : only11: Sizes differ (src 0 vs dst 6) 2024/04/26 01:53:57 DEBUG : only12: Sizes differ (src 0 vs dst 6) 2024/04/26 01:53:57 DEBUG : only13: Sizes differ (src 0 vs dst 6) 2024/04/26 01:53:57 DEBUG : only14: Sizes differ (src 0 vs dst 6) 2024/04/26 01:53:57 DEBUG : only15: Sizes differ (src 0 vs dst 6) 2024/04/26 01:53:57 DEBUG : only16: Sizes differ (src 0 vs dst 6) 2024/04/26 01:53:57 DEBUG : only17: Sizes differ (src 0 vs dst 6) 2024/04/26 01:53:57 DEBUG : only18: Sizes differ (src 0 vs dst 6) 2024/04/26 01:53:57 DEBUG : only19: Sizes differ (src 0 vs dst 6) 2024/04/26 01:53:57 DEBUG : only2: Sizes differ (src 0 vs dst 6) 2024/04/26 01:53:57 DEBUG : only3: Sizes differ (src 0 vs dst 6) 2024/04/26 01:53:57 DEBUG : only4: Sizes differ (src 0 vs dst 6) 2024/04/26 01:53:57 DEBUG : only5: Sizes differ (src 0 vs dst 6) 2024/04/26 01:53:57 DEBUG : only6: Sizes differ (src 0 vs dst 6) 2024/04/26 01:53:57 DEBUG : only7: Sizes differ (src 0 vs dst 6) 2024/04/26 01:53:57 DEBUG : only8: Sizes differ (src 0 vs dst 6) 2024/04/26 01:53:57 DEBUG : only9: Sizes differ (src 0 vs dst 6) 2024/04/26 01:53:57 DEBUG : both2: Unchanged skipping 2024/04/26 01:53:57 DEBUG : both4: Unchanged skipping 2024/04/26 01:53:57 DEBUG : both7: Unchanged skipping 2024/04/26 01:53:57 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Waiting for transfers to finish 2024/04/26 01:53:59 DEBUG : only0: md5 = 3239b648ff809674a0645094a41000cf OK 2024/04/26 01:53:59 INFO : only0: Copied (replaced existing) 2024/04/26 01:53:59 DEBUG : only11: md5 = 2d2fda16f73f390ea79befae27b1729b OK 2024/04/26 01:53:59 INFO : only11: Copied (replaced existing) 2024/04/26 01:53:59 DEBUG : only1: md5 = 256af8f5d65a3f0cd82f7a047b71a5f1 OK 2024/04/26 01:53:59 INFO : only1: Copied (replaced existing) 2024/04/26 01:53:59 DEBUG : only10: md5 = 352f8f0c881171ce5240e8b71012359d OK 2024/04/26 01:53:59 INFO : only10: Copied (replaced existing) 2024/04/26 01:54:00 DEBUG : only12: md5 = 0e94ed0c53a6a18e03203bc52da5d403 OK 2024/04/26 01:54:00 INFO : only12: Copied (replaced existing) 2024/04/26 01:54:00 DEBUG : only13: md5 = 00d65c41f5814f7ebc6ea5de586626d4 OK 2024/04/26 01:54:00 INFO : only13: Copied (replaced existing) 2024/04/26 01:54:00 DEBUG : only14: md5 = a6717383a2f6940e9e1c8f27da879e46 OK 2024/04/26 01:54:00 INFO : only14: Copied (replaced existing) 2024/04/26 01:54:00 DEBUG : only15: md5 = 0f86b248b0ea22e3e325195f1f11bc89 OK 2024/04/26 01:54:00 INFO : only15: Copied (replaced existing) 2024/04/26 01:54:02 DEBUG : only17: md5 = e16af0449c49f8d39fdcd795386d63c7 OK 2024/04/26 01:54:02 INFO : only17: Copied (replaced existing) 2024/04/26 01:54:02 DEBUG : only18: md5 = 06729c66666506eec27e62c229d60331 OK 2024/04/26 01:54:02 INFO : only18: Copied (replaced existing) 2024/04/26 01:54:02 DEBUG : only16: md5 = 52645b10b652452a8c95127be97285c0 OK 2024/04/26 01:54:02 INFO : only16: Copied (replaced existing) 2024/04/26 01:54:02 DEBUG : only19: md5 = b92b1b8ec5c1f8dcf7f6dd6cb438875b OK 2024/04/26 01:54:02 INFO : only19: Copied (replaced existing) 2024/04/26 01:54:04 DEBUG : only2: md5 = 03b07b710b2ec7c3348824429f304e5b OK 2024/04/26 01:54:04 INFO : only2: Copied (replaced existing) 2024/04/26 01:54:04 DEBUG : only5: md5 = cbd36eb91767fd7eb16cf8c4369ed560 OK 2024/04/26 01:54:04 INFO : only5: Copied (replaced existing) 2024/04/26 01:54:04 DEBUG : only4: md5 = 7096839527e9a4167527cfd7b67d3817 OK 2024/04/26 01:54:04 INFO : only4: Copied (replaced existing) 2024/04/26 01:54:04 DEBUG : only3: md5 = c0b3233936c717770d647a29232a7421 OK 2024/04/26 01:54:04 INFO : only3: Copied (replaced existing) 2024/04/26 01:54:05 DEBUG : only6: md5 = 4ddbd377c4a78a54026c6ef6439c3e17 OK 2024/04/26 01:54:05 INFO : only6: Copied (replaced existing) 2024/04/26 01:54:05 DEBUG : only7: md5 = f035ddc39469ff54389c8a6eced9d108 OK 2024/04/26 01:54:05 INFO : only7: Copied (replaced existing) 2024/04/26 01:54:05 DEBUG : only8: md5 = 0090e0adccb90769a96f7976f242c14c OK 2024/04/26 01:54:05 INFO : only8: Copied (replaced existing) 2024/04/26 01:54:05 DEBUG : only9: md5 = 2dbaa21db8cb2d133ac75c37eb45605a OK 2024/04/26 01:54:05 INFO : only9: Copied (replaced existing) 2024/04/26 01:54:05 DEBUG : Waiting for deletions to finish run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" --- PASS: TestSyncConcurrentTruncate (110.97s) === RUN TestNothingToTransfer run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:54:33 INFO : sub dir: Set directory modification time (using DirSetModTime) 2024/04/26 01:54:33 DEBUG : sub dir: Making directory with metadata 2024/04/26 01:54:34 INFO : sub dir: Made directory with metadata (mtime=2011-12-30T12:59:59Z) run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" run.go:180: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7'", Local "Local file system at /tmp/rclone1262246716", Modify Window "1ms" 2024/04/26 01:55:02 DEBUG : s0tvtpcbgsp8ufdmedqtvlq3hc/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak/37qp6d1gohacv723ij3brofbu8/i24n0ln37pa2hv8pctddeuh73o: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" 2024/04/26 01:55:03 DEBUG : s0tvtpcbgsp8ufdmedqtvlq3hc/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak/37qp6d1gohacv723ij3brofbu8: Rmdir: contains trashed file: "i24n0ln37pa2hv8pctddeuh73o" 2024/04/26 01:55:04 DEBUG : s0tvtpcbgsp8ufdmedqtvlq3hc/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak: Rmdir: contains trashed file: "37qp6d1gohacv723ij3brofbu8" 2024/04/26 01:55:05 DEBUG : s0tvtpcbgsp8ufdmedqtvlq3hc/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak: Rmdir: contains trashed file: "jefmjbgpu25gb7gcub4i80nlak" 2024/04/26 01:55:06 DEBUG : s0tvtpcbgsp8ufdmedqtvlq3hc/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak: Rmdir: contains trashed file: "jefmjbgpu25gb7gcub4i80nlak" 2024/04/26 01:55:07 DEBUG : s0tvtpcbgsp8ufdmedqtvlq3hc/jefmjbgpu25gb7gcub4i80nlak/jefmjbgpu25gb7gcub4i80nlak: Rmdir: contains trashed file: "jefmjbgpu25gb7gcub4i80nlak" 2024/04/26 01:55:08 DEBUG : s0tvtpcbgsp8ufdmedqtvlq3hc/jefmjbgpu25gb7gcub4i80nlak: Rmdir: contains trashed file: "jefmjbgpu25gb7gcub4i80nlak" 2024/04/26 01:55:09 DEBUG : s0tvtpcbgsp8ufdmedqtvlq3hc: Rmdir: contains trashed file: "jefmjbgpu25gb7gcub4i80nlak" 2024/04/26 01:55:10 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestNothingToTransfer (39.43s) PASS 2024/04/26 01:55:12 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xokaziw2leyolak4vewatov7': Purge remote "./sync.test -test.v -test.timeout 1h0m0s -remote TestCryptDrive: -verbose" - Finished OK in 17m59.487833982s (try 1/5)