"./sync.test -test.v -test.timeout 1h0m0s -remote TestCryptDrive: -verbose -fast-list" - Starting (try 1/5) 2022/03/15 05:47:48 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5" 2022/03/15 05:47:48 DEBUG : Using config file from "/home/rclone/.rclone.conf" 2022/03/15 05:47:48 DEBUG : Creating backend with remote "TestDrive:crypt/728kds3mq75c78rvf3qlm1l12dibr01rft25rdpgmiklo90h7o08uece3pjg2bd6dr2evim9rfch0" 2022/03/15 05:47:49 DEBUG : Creating backend with remote "/tmp/rclone267558022" === RUN TestPipe --- PASS: TestPipe (0.00s) === RUN TestPipeConcurrent --- PASS: TestPipeConcurrent (0.02s) === RUN TestPipeOrderBy === RUN TestPipeOrderBy/#00 === RUN TestPipeOrderBy/size === RUN TestPipeOrderBy/name === RUN TestPipeOrderBy/modtime === RUN TestPipeOrderBy/size,ascending === RUN TestPipeOrderBy/name,asc === RUN TestPipeOrderBy/modtime,ascending === RUN TestPipeOrderBy/size,descending === RUN TestPipeOrderBy/name,desc === RUN TestPipeOrderBy/modtime,descending === RUN TestPipeOrderBy/size,mixed,50 === RUN TestPipeOrderBy/size,mixed,51 --- PASS: TestPipeOrderBy (0.00s) --- PASS: TestPipeOrderBy/#00 (0.00s) --- PASS: TestPipeOrderBy/size (0.00s) --- PASS: TestPipeOrderBy/name (0.00s) --- PASS: TestPipeOrderBy/modtime (0.00s) --- PASS: TestPipeOrderBy/size,ascending (0.00s) --- PASS: TestPipeOrderBy/name,asc (0.00s) --- PASS: TestPipeOrderBy/modtime,ascending (0.00s) --- PASS: TestPipeOrderBy/size,descending (0.00s) --- PASS: TestPipeOrderBy/name,desc (0.00s) --- PASS: TestPipeOrderBy/modtime,descending (0.00s) --- PASS: TestPipeOrderBy/size,mixed,50 (0.00s) --- PASS: TestPipeOrderBy/size,mixed,51 (0.00s) === RUN TestNewLess === RUN TestNewLess/blankOK === RUN TestNewLess/tooManyParts === RUN TestNewLess/tooManyParts2 === RUN TestNewLess/badMixed === RUN TestNewLess/unknownComparison === RUN TestNewLess/unknownSortDirection === RUN TestNewLess/size === RUN TestNewLess/name === RUN TestNewLess/modtime === RUN TestNewLess/size,ascending === RUN TestNewLess/name,asc === RUN TestNewLess/modtime,ascending === RUN TestNewLess/size,descending === RUN TestNewLess/name,desc === RUN TestNewLess/modtime,descending === RUN TestNewLess/modtime,mixed === RUN TestNewLess/modtime,mixed,30 --- PASS: TestNewLess (0.00s) --- PASS: TestNewLess/blankOK (0.00s) --- PASS: TestNewLess/tooManyParts (0.00s) --- PASS: TestNewLess/tooManyParts2 (0.00s) --- PASS: TestNewLess/badMixed (0.00s) --- PASS: TestNewLess/unknownComparison (0.00s) --- PASS: TestNewLess/unknownSortDirection (0.00s) --- PASS: TestNewLess/size (0.00s) --- PASS: TestNewLess/name (0.00s) --- PASS: TestNewLess/modtime (0.00s) --- PASS: TestNewLess/size,ascending (0.00s) --- PASS: TestNewLess/name,asc (0.00s) --- PASS: TestNewLess/modtime,ascending (0.00s) --- PASS: TestNewLess/size,descending (0.00s) --- PASS: TestNewLess/name,desc (0.00s) --- PASS: TestNewLess/modtime,descending (0.00s) --- PASS: TestNewLess/modtime,mixed (0.00s) --- PASS: TestNewLess/modtime,mixed,30 (0.00s) === RUN TestRcCopy rc_test.go:16: Skipping test on non local remote --- SKIP: TestRcCopy (0.00s) === RUN TestRcMove rc_test.go:16: Skipping test on non local remote --- SKIP: TestRcMove (0.00s) === RUN TestRcSync rc_test.go:16: Skipping test on non local remote --- SKIP: TestRcSync (0.00s) === RUN TestCopyWithDryRun run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5'", Local "Local file system at /tmp/rclone267558022", Modify Window "1ms" 2022/03/15 05:47:50 NOTICE: sub dir/hello world: Skipped copy as --dry-run is set (size 11) 2022/03/15 05:47:50 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for checks to finish 2022/03/15 05:47:50 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for transfers to finish --- PASS: TestCopyWithDryRun (1.92s) === RUN TestCopy run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5'", Local "Local file system at /tmp/rclone267558022", Modify Window "1ms" 2022/03/15 05:47:51 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for checks to finish 2022/03/15 05:47:51 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for transfers to finish 2022/03/15 05:47:53 DEBUG : sub dir/hello world: md5 = 07cb3e7aeef1d1fbe4b5e718a52e9bd2 OK 2022/03/15 05:47:53 INFO : sub dir/hello world: Copied (new) 2022/03/15 05:47:55 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestCopy (5.25s) === RUN TestCopyMissingDirectory run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5'", Local "Local file system at /tmp/rclone267558022", Modify Window "1ms" 2022/03/15 05:47:56 DEBUG : Creating backend with remote "/non-existing" 2022/03/15 05:47:56 ERROR : Local file system at /non-existing: error reading source root directory: directory not found 2022/03/15 05:47:56 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for checks to finish 2022/03/15 05:47:56 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for transfers to finish --- PASS: TestCopyMissingDirectory (0.79s) === RUN TestCopyNoTraverse run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5'", Local "Local file system at /tmp/rclone267558022", Modify Window "1ms" 2022/03/15 05:47:57 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for checks to finish 2022/03/15 05:47:57 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for transfers to finish 2022/03/15 05:47:59 DEBUG : sub dir/hello world: md5 = 48cb1c4cdc3ce0e901df913c3bc164d8 OK 2022/03/15 05:47:59 INFO : sub dir/hello world: Copied (new) 2022/03/15 05:48:02 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestCopyNoTraverse (5.62s) === RUN TestCopyCheckFirst run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5'", Local "Local file system at /tmp/rclone267558022", Modify Window "1ms" 2022/03/15 05:48:02 INFO : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Running all checks before starting transfers 2022/03/15 05:48:03 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for checks to finish 2022/03/15 05:48:03 INFO : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Checks finished, now starting transfers 2022/03/15 05:48:03 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for transfers to finish 2022/03/15 05:48:05 DEBUG : sub dir/hello world: md5 = 517e1a306e4557d58a8fc08a4c3b5054 OK 2022/03/15 05:48:05 INFO : sub dir/hello world: Copied (new) 2022/03/15 05:48:07 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestCopyCheckFirst (5.63s) === RUN TestSyncNoTraverse run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5'", Local "Local file system at /tmp/rclone267558022", Modify Window "1ms" 2022/03/15 05:48:08 ERROR : Ignoring --no-traverse with sync 2022/03/15 05:48:08 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for checks to finish 2022/03/15 05:48:08 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for transfers to finish 2022/03/15 05:48:11 DEBUG : sub dir/hello world: md5 = 6acefebe023dd07fb1d329bbf29fc34c OK 2022/03/15 05:48:11 INFO : sub dir/hello world: Copied (new) 2022/03/15 05:48:11 DEBUG : Waiting for deletions to finish 2022/03/15 05:48:13 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestSyncNoTraverse (5.31s) === RUN TestCopyWithDepth run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5'", Local "Local file system at /tmp/rclone267558022", Modify Window "1ms" 2022/03/15 05:48:14 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for checks to finish 2022/03/15 05:48:14 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for transfers to finish 2022/03/15 05:48:15 DEBUG : hello world2: md5 = 94356d729059798b752e8da96b2a7224 OK 2022/03/15 05:48:15 INFO : hello world2: Copied (new) --- PASS: TestCopyWithDepth (3.08s) === RUN TestCopyWithFilesFrom run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5'", Local "Local file system at /tmp/rclone267558022", Modify Window "1ms" 2022/03/15 05:48:16 DEBUG : hello world2: Excluded 2022/03/15 05:48:17 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for checks to finish 2022/03/15 05:48:17 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for transfers to finish 2022/03/15 05:48:18 DEBUG : potato2: md5 = d8f1630b1cb85111ea25d8fe76447ec7 OK 2022/03/15 05:48:18 INFO : potato2: Copied (new) --- PASS: TestCopyWithFilesFrom (3.34s) === RUN TestCopyWithFilesFromAndNoTraverse run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5'", Local "Local file system at /tmp/rclone267558022", Modify Window "1ms" 2022/03/15 05:48:20 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for checks to finish 2022/03/15 05:48:20 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for transfers to finish 2022/03/15 05:48:22 DEBUG : potato2: md5 = 4151415076dc639d4c2ee783fe61724d OK 2022/03/15 05:48:22 INFO : potato2: Copied (new) --- PASS: TestCopyWithFilesFromAndNoTraverse (3.15s) === RUN TestCopyEmptyDirectories run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5'", Local "Local file system at /tmp/rclone267558022", Modify Window "1ms" 2022/03/15 05:48:23 DEBUG : sub dir2: Making directory 2022/03/15 05:48:23 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for checks to finish 2022/03/15 05:48:23 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for transfers to finish 2022/03/15 05:48:25 DEBUG : sub dir/hello world: md5 = 6423b993b3241e346aacad829731aedd OK 2022/03/15 05:48:25 INFO : sub dir/hello world: Copied (new) 2022/03/15 05:48:25 DEBUG : sub dir2: Making directory 2022/03/15 05:48:26 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': copied 1 directories 2022/03/15 05:48:29 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestCopyEmptyDirectories (7.19s) === RUN TestMoveEmptyDirectories run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5'", Local "Local file system at /tmp/rclone267558022", Modify Window "1ms" 2022/03/15 05:48:30 DEBUG : sub dir2: Making directory 2022/03/15 05:48:30 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for checks to finish 2022/03/15 05:48:30 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for transfers to finish 2022/03/15 05:48:33 DEBUG : sub dir/hello world: md5 = fc15f9f8b3eada7231ee5622d8e069b5 OK 2022/03/15 05:48:33 INFO : sub dir/hello world: Copied (new) 2022/03/15 05:48:33 INFO : sub dir/hello world: Deleted 2022/03/15 05:48:33 DEBUG : sub dir: Making directory 2022/03/15 05:48:33 DEBUG : sub dir2: Making directory 2022/03/15 05:48:34 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': copied 2 directories 2022/03/15 05:48:36 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestMoveEmptyDirectories (7.21s) === RUN TestSyncEmptyDirectories run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5'", Local "Local file system at /tmp/rclone267558022", Modify Window "1ms" 2022/03/15 05:48:37 DEBUG : sub dir2: Making directory 2022/03/15 05:48:38 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for checks to finish 2022/03/15 05:48:38 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for transfers to finish 2022/03/15 05:48:40 DEBUG : sub dir/hello world: md5 = d021521d851320b0f6ce982bf5603fed OK 2022/03/15 05:48:40 INFO : sub dir/hello world: Copied (new) 2022/03/15 05:48:40 DEBUG : sub dir2: Making directory 2022/03/15 05:48:41 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': copied 1 directories 2022/03/15 05:48:41 DEBUG : Waiting for deletions to finish 2022/03/15 05:48:44 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestSyncEmptyDirectories (7.38s) === RUN TestServerSideCopy run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5'", Local "Local file system at /tmp/rclone267558022", Modify Window "1ms" 2022/03/15 05:48:47 DEBUG : sub dir/hello world: md5 = 21a9f9569d34d34787b2aa3e29dfb17b OK 2022/03/15 05:48:48 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-rejuvay2jonokaw2natugeh0" 2022/03/15 05:48:48 DEBUG : Creating backend with remote "TestDrive:crypt/gcic5lt5l9tpgn68kfpckahloc398rk1cs8cou7qed174191gud855pe0p9bfgkt33q6g5q0tbnq6" sync_test.go:275: Server side copy (if possible) Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5' -> Encrypted drive 'TestCryptDrive:rclone-test-rejuvay2jonokaw2natugeh0' 2022/03/15 05:48:49 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-rejuvay2jonokaw2natugeh0': Waiting for checks to finish 2022/03/15 05:48:49 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-rejuvay2jonokaw2natugeh0': Waiting for transfers to finish 2022/03/15 05:48:52 INFO : sub dir/hello world: Copied (server-side copy) 2022/03/15 05:48:53 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-rejuvay2jonokaw2natugeh0': Purge remote 2022/03/15 05:48:55 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestServerSideCopy (11.28s) === RUN TestCopyAfterDelete run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5'", Local "Local file system at /tmp/rclone267558022", Modify Window "1ms" 2022/03/15 05:48:58 DEBUG : sub dir/hello world: md5 = faaafb6c9ec3202b7b0db869d8840e65 OK 2022/03/15 05:48:58 ERROR : : error listing: directory not found 2022/03/15 05:48:59 DEBUG : Local file system at /tmp/rclone267558022: Making directory 2022/03/15 05:49:00 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for checks to finish 2022/03/15 05:49:00 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for transfers to finish 2022/03/15 05:49:02 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestCopyAfterDelete (6.65s) === RUN TestCopyRedownload run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5'", Local "Local file system at /tmp/rclone267558022", Modify Window "1ms" 2022/03/15 05:49:05 DEBUG : sub dir/hello world: md5 = ba6be7a77f5d319c55b6971c1fb7df98 OK 2022/03/15 05:49:06 DEBUG : Local file system at /tmp/rclone267558022: Waiting for checks to finish 2022/03/15 05:49:06 DEBUG : Local file system at /tmp/rclone267558022: Waiting for transfers to finish 2022/03/15 05:49:07 INFO : sub dir/hello world: Copied (new) 2022/03/15 05:49:09 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestCopyRedownload (8.18s) === RUN TestSyncBasedOnCheckSum run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5'", Local "Local file system at /tmp/rclone267558022", Modify Window "1ms" 2022/03/15 05:49:11 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for checks to finish 2022/03/15 05:49:11 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for transfers to finish 2022/03/15 05:49:13 DEBUG : check sum: md5 = 8f63760684b9a60f010f04ac3f526f3b OK 2022/03/15 05:49:13 INFO : check sum: Copied (new) 2022/03/15 05:49:13 DEBUG : Waiting for deletions to finish 2022/03/15 05:49:13 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for checks to finish 2022/03/15 05:49:13 NOTICE: Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': --checksum is in use but the source and destination have no hashes in common; falling back to --size-only 2022/03/15 05:49:13 DEBUG : check sum: Size of src and dst objects identical 2022/03/15 05:49:13 DEBUG : check sum: Unchanged skipping 2022/03/15 05:49:13 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for transfers to finish 2022/03/15 05:49:13 DEBUG : Waiting for deletions to finish 2022/03/15 05:49:13 INFO : There was nothing to transfer --- PASS: TestSyncBasedOnCheckSum (3.84s) === RUN TestSyncSizeOnly run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5'", Local "Local file system at /tmp/rclone267558022", Modify Window "1ms" 2022/03/15 05:49:15 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for checks to finish 2022/03/15 05:49:15 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for transfers to finish 2022/03/15 05:49:16 DEBUG : sizeonly: md5 = 6c2cf2d516296c6d795c00215c6ed57c OK 2022/03/15 05:49:16 INFO : sizeonly: Copied (new) 2022/03/15 05:49:16 DEBUG : Waiting for deletions to finish 2022/03/15 05:49:17 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for checks to finish 2022/03/15 05:49:17 DEBUG : sizeonly: Sizes identical 2022/03/15 05:49:17 DEBUG : sizeonly: Unchanged skipping 2022/03/15 05:49:17 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for transfers to finish 2022/03/15 05:49:17 DEBUG : Waiting for deletions to finish 2022/03/15 05:49:17 INFO : There was nothing to transfer --- PASS: TestSyncSizeOnly (3.68s) === RUN TestSyncIgnoreSize run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5'", Local "Local file system at /tmp/rclone267558022", Modify Window "1ms" 2022/03/15 05:49:19 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for checks to finish 2022/03/15 05:49:19 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for transfers to finish 2022/03/15 05:49:20 DEBUG : ignore-size: md5 = e2fa7d64a2b792332061ed7f70c12bce OK 2022/03/15 05:49:20 INFO : ignore-size: Copied (new) 2022/03/15 05:49:20 DEBUG : Waiting for deletions to finish 2022/03/15 05:49:21 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for checks to finish 2022/03/15 05:49:21 DEBUG : ignore-size: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/15 05:49:21 DEBUG : ignore-size: Unchanged skipping 2022/03/15 05:49:21 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for transfers to finish 2022/03/15 05:49:21 DEBUG : Waiting for deletions to finish 2022/03/15 05:49:21 INFO : There was nothing to transfer --- PASS: TestSyncIgnoreSize (3.95s) === RUN TestSyncIgnoreTimes run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5'", Local "Local file system at /tmp/rclone267558022", Modify Window "1ms" 2022/03/15 05:49:24 DEBUG : existing: md5 = fd9bcefa501c3fc8e13c0b73be92b013 OK 2022/03/15 05:49:24 DEBUG : existing: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/15 05:49:24 DEBUG : existing: Unchanged skipping 2022/03/15 05:49:24 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for checks to finish 2022/03/15 05:49:24 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for transfers to finish 2022/03/15 05:49:24 DEBUG : Waiting for deletions to finish 2022/03/15 05:49:24 INFO : There was nothing to transfer 2022/03/15 05:49:25 DEBUG : existing: Transferring unconditionally as --ignore-times is in use 2022/03/15 05:49:25 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for checks to finish 2022/03/15 05:49:25 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for transfers to finish 2022/03/15 05:49:26 DEBUG : existing: md5 = b0652e145186743c2aee373deee8f5fb OK 2022/03/15 05:49:26 INFO : existing: Copied (replaced existing) 2022/03/15 05:49:26 DEBUG : Waiting for deletions to finish --- PASS: TestSyncIgnoreTimes (5.04s) === RUN TestSyncIgnoreExisting run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5'", Local "Local file system at /tmp/rclone267558022", Modify Window "1ms" 2022/03/15 05:49:28 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for checks to finish 2022/03/15 05:49:28 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for transfers to finish 2022/03/15 05:49:29 DEBUG : existing: md5 = 9504db37d3e7fcbdd2004b8ca6d31dec OK 2022/03/15 05:49:29 INFO : existing: Copied (new) 2022/03/15 05:49:29 DEBUG : Waiting for deletions to finish 2022/03/15 05:49:30 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for checks to finish 2022/03/15 05:49:30 DEBUG : existing: Destination exists, skipping 2022/03/15 05:49:30 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for transfers to finish 2022/03/15 05:49:30 DEBUG : Waiting for deletions to finish 2022/03/15 05:49:30 INFO : There was nothing to transfer --- PASS: TestSyncIgnoreExisting (3.80s) === RUN TestSyncIgnoreErrors run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5'", Local "Local file system at /tmp/rclone267558022", Modify Window "1ms" 2022/03/15 05:49:33 DEBUG : b/potato: md5 = 590a742f80b33d4e0c2b13e16b0f980a OK 2022/03/15 05:49:36 DEBUG : c/non empty space: md5 = 8148d75874e983e32630cde71a44714e OK 2022/03/15 05:49:36 DEBUG : d: Making directory 2022/03/15 05:49:38 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for checks to finish 2022/03/15 05:49:38 DEBUG : c/non empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/15 05:49:38 DEBUG : c/non empty space: Unchanged skipping 2022/03/15 05:49:38 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for transfers to finish 2022/03/15 05:49:40 DEBUG : a/potato2: md5 = 8dcbb6a4cd7015286e0c39d02e04fe8d OK 2022/03/15 05:49:40 INFO : a/potato2: Copied (new) 2022/03/15 05:49:40 DEBUG : Waiting for deletions to finish 2022/03/15 05:49:41 INFO : b/potato: Deleted 2022/03/15 05:49:41 INFO : d: Removing directory 2022/03/15 05:49:42 INFO : b: Removing directory 2022/03/15 05:49:42 DEBUG : 32d8ua6196mc1r7qkfog53rkg0: Rmdir: contains trashed file: "2m507n64kafsi59v9q71r281a4" 2022/03/15 05:49:43 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': deleted 2 directories 2022/03/15 05:49:46 DEBUG : 3i9du405pfogq3ncai6pg7ouio: Rmdir: contains trashed file: "982d3pss7t5pn0il16r2foj31s" 2022/03/15 05:49:47 DEBUG : 2bsvlrk2ne1lfitm6tttcu0qt8: Rmdir: contains trashed file: "89l8renevh3mji1c8r1p7qn6tg" --- PASS: TestSyncIgnoreErrors (16.39s) === RUN TestSyncAfterChangingModtimeOnly run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5'", Local "Local file system at /tmp/rclone267558022", Modify Window "1ms" 2022/03/15 05:49:49 DEBUG : empty space: md5 = bc3f9f06900f21c702f08e5e6f625213 OK 2022/03/15 05:49:50 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for checks to finish 2022/03/15 05:49:50 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 2022/03/15 05:49:50 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for transfers to finish 2022/03/15 05:49:50 NOTICE: empty space: Skipped copy as --dry-run is set (size 1) 2022/03/15 05:49:50 DEBUG : Waiting for deletions to finish 2022/03/15 05:49:50 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for checks to finish 2022/03/15 05:49:50 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 2022/03/15 05:49:50 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for transfers to finish 2022/03/15 05:49:51 DEBUG : empty space: md5 = e5acf1a8eaf155116793406f163735ab OK 2022/03/15 05:49:51 INFO : empty space: Copied (replaced existing) 2022/03/15 05:49:51 DEBUG : Waiting for deletions to finish --- PASS: TestSyncAfterChangingModtimeOnly (5.36s) === RUN TestSyncAfterChangingModtimeOnlyWithNoUpdateModTime run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5'", Local "Local file system at /tmp/rclone267558022", Modify Window "1ms" sync_test.go:577: Can't check this if no hashes supported --- PASS: TestSyncAfterChangingModtimeOnlyWithNoUpdateModTime (0.47s) === RUN TestSyncDoesntUpdateModtime run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5'", Local "Local file system at /tmp/rclone267558022", Modify Window "1ms" 2022/03/15 05:49:55 DEBUG : foo: md5 = 4a69699829553fe2ecaba98bfff438ec OK 2022/03/15 05:49:55 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for checks to finish 2022/03/15 05:49:55 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 2022/03/15 05:49:55 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for transfers to finish 2022/03/15 05:49:57 DEBUG : foo: md5 = 91adc3a322637cf895a869dc031a42b1 OK 2022/03/15 05:49:57 INFO : foo: Copied (replaced existing) 2022/03/15 05:49:57 DEBUG : Waiting for deletions to finish --- PASS: TestSyncDoesntUpdateModtime (4.64s) === RUN TestSyncAfterAddingAFile run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5'", Local "Local file system at /tmp/rclone267558022", Modify Window "1ms" 2022/03/15 05:49:59 DEBUG : empty space: md5 = 8808f2da843694f10f7a6683178ec0d1 OK 2022/03/15 05:50:00 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for checks to finish 2022/03/15 05:50:00 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/15 05:50:00 DEBUG : empty space: Unchanged skipping 2022/03/15 05:50:00 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for transfers to finish 2022/03/15 05:50:01 DEBUG : potato: md5 = 29f07347f3aab06d2c978e6de553f46c OK 2022/03/15 05:50:01 INFO : potato: Copied (new) 2022/03/15 05:50:01 DEBUG : Waiting for deletions to finish --- PASS: TestSyncAfterAddingAFile (5.45s) === RUN TestSyncAfterChangingFilesSizeOnly run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5'", Local "Local file system at /tmp/rclone267558022", Modify Window "1ms" 2022/03/15 05:50:05 DEBUG : potato: md5 = a9438eba4284c4d37a9f889461d6c7c5 OK 2022/03/15 05:50:05 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for checks to finish 2022/03/15 05:50:05 DEBUG : potato: Sizes differ (src 21 vs dst 60) 2022/03/15 05:50:05 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for transfers to finish 2022/03/15 05:50:07 DEBUG : potato: md5 = 67ef93d39258ae0c969c6f4d655fe3c0 OK 2022/03/15 05:50:07 INFO : potato: Copied (replaced existing) 2022/03/15 05:50:07 DEBUG : Waiting for deletions to finish --- PASS: TestSyncAfterChangingFilesSizeOnly (4.76s) === RUN TestSyncAfterChangingContentsOnly run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5'", Local "Local file system at /tmp/rclone267558022", Modify Window "1ms" 2022/03/15 05:50:10 DEBUG : potato: md5 = 36688d92f3dbaf4c6c021cad3b54c021 OK 2022/03/15 05:50:10 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 2022/03/15 05:50:10 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for checks to finish 2022/03/15 05:50:10 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for transfers to finish 2022/03/15 05:50:11 DEBUG : potato: md5 = e4c677317392f6b7926ee6b17ce4449d OK 2022/03/15 05:50:11 INFO : potato: Copied (replaced existing) 2022/03/15 05:50:11 DEBUG : Waiting for deletions to finish --- PASS: TestSyncAfterChangingContentsOnly (4.71s) === RUN TestSyncAfterRemovingAFileAndAddingAFileDryRun run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5'", Local "Local file system at /tmp/rclone267558022", Modify Window "1ms" 2022/03/15 05:50:14 DEBUG : potato: md5 = d9ff4ed3b92ddbe93b0486e9daf7af47 OK 2022/03/15 05:50:16 DEBUG : empty space: md5 = 134a3bfe18f51d4e5d366b7bc9a18b4b OK 2022/03/15 05:50:16 NOTICE: potato2: Skipped copy as --dry-run is set (size 60) 2022/03/15 05:50:16 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for checks to finish 2022/03/15 05:50:16 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/15 05:50:16 DEBUG : empty space: Unchanged skipping 2022/03/15 05:50:16 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for transfers to finish 2022/03/15 05:50:16 DEBUG : Waiting for deletions to finish 2022/03/15 05:50:16 NOTICE: potato: Skipped delete as --dry-run is set (size 21) --- PASS: TestSyncAfterRemovingAFileAndAddingAFileDryRun (5.03s) === RUN TestSyncAfterRemovingAFileAndAddingAFile run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5'", Local "Local file system at /tmp/rclone267558022", Modify Window "1ms" 2022/03/15 05:50:19 DEBUG : potato: md5 = 6ca82d6d9606bf8d739ddd956773fcb5 OK 2022/03/15 05:50:21 DEBUG : empty space: md5 = 454273912b0203b12f3058e0166e1dd4 OK 2022/03/15 05:50:21 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for checks to finish 2022/03/15 05:50:21 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/15 05:50:21 DEBUG : empty space: Unchanged skipping 2022/03/15 05:50:21 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for transfers to finish 2022/03/15 05:50:23 DEBUG : potato2: md5 = 67ab7ba6bd2ba131e0d45f2fb74da6ee OK 2022/03/15 05:50:23 INFO : potato2: Copied (new) 2022/03/15 05:50:23 DEBUG : Waiting for deletions to finish 2022/03/15 05:50:23 INFO : potato: Deleted --- PASS: TestSyncAfterRemovingAFileAndAddingAFile (7.30s) === RUN TestSyncAfterRemovingAFileAndAddingAFileSubDir run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5'", Local "Local file system at /tmp/rclone267558022", Modify Window "1ms" 2022/03/15 05:50:27 DEBUG : b/potato: md5 = f5a80629a1361ac89afd3d2fa65c88ea OK 2022/03/15 05:50:30 DEBUG : c/non empty space: md5 = fb2a5b655a0a5c09c0079e6bc0e05fc8 OK 2022/03/15 05:50:30 DEBUG : d: Making directory 2022/03/15 05:50:30 DEBUG : d/e: Making directory 2022/03/15 05:50:33 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for checks to finish 2022/03/15 05:50:33 DEBUG : c/non empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/15 05:50:33 DEBUG : c/non empty space: Unchanged skipping 2022/03/15 05:50:33 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for transfers to finish 2022/03/15 05:50:35 DEBUG : a/potato2: md5 = da6ce2603d4dbd7b165a47ce813f57e0 OK 2022/03/15 05:50:35 INFO : a/potato2: Copied (new) 2022/03/15 05:50:35 DEBUG : Waiting for deletions to finish 2022/03/15 05:50:36 INFO : b/potato: Deleted 2022/03/15 05:50:36 INFO : d/e: Removing directory 2022/03/15 05:50:37 INFO : d: Removing directory 2022/03/15 05:50:37 DEBUG : ka6id8d20d3s5ktapedlphgta8: Rmdir: contains trashed file: "r8sppajuabeak3sbgj2ak8vuf8" 2022/03/15 05:50:38 INFO : b: Removing directory 2022/03/15 05:50:38 DEBUG : 32d8ua6196mc1r7qkfog53rkg0: Rmdir: contains trashed file: "2m507n64kafsi59v9q71r281a4" 2022/03/15 05:50:39 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': deleted 3 directories 2022/03/15 05:50:41 DEBUG : 3i9du405pfogq3ncai6pg7ouio: Rmdir: contains trashed file: "982d3pss7t5pn0il16r2foj31s" 2022/03/15 05:50:42 DEBUG : 2bsvlrk2ne1lfitm6tttcu0qt8: Rmdir: contains trashed file: "89l8renevh3mji1c8r1p7qn6tg" --- PASS: TestSyncAfterRemovingAFileAndAddingAFileSubDir (17.60s) === RUN TestSyncAfterRemovingAFileAndAddingAFileSubDirWithErrors run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5'", Local "Local file system at /tmp/rclone267558022", Modify Window "1ms" 2022/03/15 05:50:45 DEBUG : b/potato: md5 = aaec770f9a19d09512ef7e91150f3a2f OK 2022/03/15 05:50:47 DEBUG : c/non empty space: md5 = ee1bacbd962a35a6b71377884a743584 OK 2022/03/15 05:50:47 DEBUG : d: Making directory 2022/03/15 05:50:49 DEBUG : c/non empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/15 05:50:49 DEBUG : c/non empty space: Unchanged skipping 2022/03/15 05:50:49 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for checks to finish 2022/03/15 05:50:49 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for transfers to finish 2022/03/15 05:50:52 DEBUG : a/potato2: md5 = 2da7dbb59ea362646e4036cd97fd1852 OK 2022/03/15 05:50:52 INFO : a/potato2: Copied (new) 2022/03/15 05:50:52 ERROR : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': not deleting files as there were IO errors 2022/03/15 05:50:52 ERROR : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': not deleting directories as there were IO errors 2022/03/15 05:50:56 DEBUG : 3i9du405pfogq3ncai6pg7ouio: Rmdir: contains trashed file: "982d3pss7t5pn0il16r2foj31s" 2022/03/15 05:50:57 DEBUG : 32d8ua6196mc1r7qkfog53rkg0: Rmdir: contains trashed file: "2m507n64kafsi59v9q71r281a4" 2022/03/15 05:50:57 DEBUG : 2bsvlrk2ne1lfitm6tttcu0qt8: Rmdir: contains trashed file: "89l8renevh3mji1c8r1p7qn6tg" --- PASS: TestSyncAfterRemovingAFileAndAddingAFileSubDirWithErrors (15.49s) === RUN TestSyncDeleteAfter --- PASS: TestSyncDeleteAfter (0.00s) === RUN TestSyncDeleteDuring run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5'", Local "Local file system at /tmp/rclone267558022", Modify Window "1ms" 2022/03/15 05:51:00 DEBUG : potato: md5 = 536274881553548a5a2221e471f8a202 OK 2022/03/15 05:51:01 DEBUG : empty space: md5 = aa12c8cf7b60a72c2313d7770a81468a OK 2022/03/15 05:51:02 DEBUG : Waiting for deletions to finish 2022/03/15 05:51:02 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/15 05:51:02 DEBUG : empty space: Unchanged skipping 2022/03/15 05:51:02 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for checks to finish 2022/03/15 05:51:02 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for transfers to finish 2022/03/15 05:51:03 INFO : potato: Deleted 2022/03/15 05:51:03 DEBUG : potato2: md5 = f5552c86eac9d27a49a548d75ced0768 OK 2022/03/15 05:51:03 INFO : potato2: Copied (new) --- PASS: TestSyncDeleteDuring (7.02s) === RUN TestSyncDeleteBefore run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5'", Local "Local file system at /tmp/rclone267558022", Modify Window "1ms" 2022/03/15 05:51:07 DEBUG : potato: md5 = 1b44834803658e2f0aa3979dc16867e0 OK 2022/03/15 05:51:08 DEBUG : empty space: md5 = 04d1c596b316a0f221b87a3c0fd1efc9 OK 2022/03/15 05:51:09 DEBUG : Waiting for deletions to finish 2022/03/15 05:51:09 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for checks to finish 2022/03/15 05:51:09 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for transfers to finish 2022/03/15 05:51:09 INFO : potato: Deleted 2022/03/15 05:51:10 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/15 05:51:10 DEBUG : empty space: Unchanged skipping 2022/03/15 05:51:10 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for checks to finish 2022/03/15 05:51:10 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for transfers to finish 2022/03/15 05:51:11 DEBUG : potato2: md5 = 6486808760b6e156a4f10dd20bbf27ed OK 2022/03/15 05:51:11 INFO : potato2: Copied (new) --- PASS: TestSyncDeleteBefore (7.98s) === RUN TestCopyDeleteBefore run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5'", Local "Local file system at /tmp/rclone267558022", Modify Window "1ms" 2022/03/15 05:51:15 DEBUG : potato: md5 = fe038d29a07994f44a9d1e1b2b21de6d OK 2022/03/15 05:51:15 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for checks to finish 2022/03/15 05:51:15 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for transfers to finish 2022/03/15 05:51:17 DEBUG : potato2: md5 = 697bdeb4065a46f819f4403cb8917761 OK 2022/03/15 05:51:17 INFO : potato2: Copied (new) --- PASS: TestCopyDeleteBefore (5.68s) === RUN TestSyncWithExclude run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5'", Local "Local file system at /tmp/rclone267558022", Modify Window "1ms" 2022/03/15 05:51:20 DEBUG : potato2: md5 = dd60fe74176dee458da7ff15a4bd392f OK 2022/03/15 05:51:22 DEBUG : empty space: md5 = 766b4fe4a1732924b35e132692e4a3db OK 2022/03/15 05:51:22 DEBUG : enormous: Excluded 2022/03/15 05:51:22 DEBUG : potato2: Excluded 2022/03/15 05:51:22 DEBUG : potato2: Excluded from sync (and deletion) 2022/03/15 05:51:22 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for checks to finish 2022/03/15 05:51:22 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/15 05:51:22 DEBUG : empty space: Unchanged skipping 2022/03/15 05:51:22 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for transfers to finish 2022/03/15 05:51:22 DEBUG : Waiting for deletions to finish 2022/03/15 05:51:22 INFO : There was nothing to transfer 2022/03/15 05:51:23 DEBUG : enormous: Excluded 2022/03/15 05:51:23 DEBUG : potato2: Excluded 2022/03/15 05:51:23 DEBUG : potato2: Excluded from sync (and deletion) 2022/03/15 05:51:23 DEBUG : empty space: Size and modification time the same (differ by 456.789µs, within tolerance 1ms) 2022/03/15 05:51:23 DEBUG : empty space: Unchanged skipping 2022/03/15 05:51:23 DEBUG : Local file system at /tmp/rclone267558022: Waiting for checks to finish 2022/03/15 05:51:23 DEBUG : Local file system at /tmp/rclone267558022: Waiting for transfers to finish 2022/03/15 05:51:23 DEBUG : Waiting for deletions to finish 2022/03/15 05:51:23 INFO : There was nothing to transfer --- PASS: TestSyncWithExclude (5.64s) === RUN TestSyncWithExcludeAndDeleteExcluded run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5'", Local "Local file system at /tmp/rclone267558022", Modify Window "1ms" 2022/03/15 05:51:26 DEBUG : potato2: md5 = 07b6f48bd489464c1e30003f61c863cc OK 2022/03/15 05:51:27 DEBUG : empty space: md5 = 8cc32e53afce1287f23afc5e245192d4 OK 2022/03/15 05:51:29 DEBUG : enormous: md5 = ceef01842ccc151fb6490a9fbe2c277c OK 2022/03/15 05:51:29 DEBUG : enormous: Excluded 2022/03/15 05:51:29 DEBUG : potato2: Excluded 2022/03/15 05:51:29 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for checks to finish 2022/03/15 05:51:29 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/15 05:51:29 DEBUG : empty space: Unchanged skipping 2022/03/15 05:51:29 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for transfers to finish 2022/03/15 05:51:29 DEBUG : Waiting for deletions to finish 2022/03/15 05:51:30 INFO : potato2: Deleted 2022/03/15 05:51:30 INFO : enormous: Deleted 2022/03/15 05:51:30 INFO : There was nothing to transfer 2022/03/15 05:51:31 DEBUG : Local file system at /tmp/rclone267558022: Waiting for checks to finish 2022/03/15 05:51:31 DEBUG : empty space: Size and modification time the same (differ by 456.789µs, within tolerance 1ms) 2022/03/15 05:51:31 DEBUG : empty space: Unchanged skipping 2022/03/15 05:51:31 DEBUG : Local file system at /tmp/rclone267558022: Waiting for transfers to finish 2022/03/15 05:51:31 DEBUG : Waiting for deletions to finish 2022/03/15 05:51:31 INFO : enormous: Deleted 2022/03/15 05:51:31 INFO : potato2: Deleted 2022/03/15 05:51:31 INFO : There was nothing to transfer --- PASS: TestSyncWithExcludeAndDeleteExcluded (7.24s) === RUN TestSyncWithUpdateOlder run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5'", Local "Local file system at /tmp/rclone267558022", Modify Window "1ms" 2022/03/15 05:51:33 DEBUG : one: md5 = 53b2786e20179c905f60ebceb231118e OK 2022/03/15 05:51:35 DEBUG : two: md5 = c7bf1cc1e6c6d5b1840957defdd89c00 OK 2022/03/15 05:51:36 DEBUG : three: md5 = 597dee9bc09f512acd0bc1c91a4075d8 OK 2022/03/15 05:51:38 DEBUG : four: md5 = 9617304c9397bdb7842d0147b286423f OK 2022/03/15 05:51:38 DEBUG : four: Sizes differ (src 4 vs dst 8) 2022/03/15 05:51:38 DEBUG : four: Destination mod time is within 1s of source but files differ, transferring 2022/03/15 05:51:38 DEBUG : three: Sizes identical 2022/03/15 05:51:38 DEBUG : three: Destination mod time is within 1s of source and files identical, skipping 2022/03/15 05:51:38 DEBUG : one: Destination is newer than source, skipping 2022/03/15 05:51:38 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for checks to finish 2022/03/15 05:51:38 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for transfers to finish 2022/03/15 05:51:40 DEBUG : two: md5 = 0c57fe93fe42ffb7d89b4c8f4a34f107 OK 2022/03/15 05:51:40 INFO : two: Copied (replaced existing) 2022/03/15 05:51:40 DEBUG : four: md5 = d5802236eefda0c23a0d4a8f7a5afcd8 OK 2022/03/15 05:51:40 INFO : four: Copied (replaced existing) 2022/03/15 05:51:40 DEBUG : five: md5 = 38c43b3e0011bc888499599d8977660a OK 2022/03/15 05:51:40 INFO : five: Copied (new) 2022/03/15 05:51:40 DEBUG : Waiting for deletions to finish sync_test.go:992: Skip test with --checksum as no hashes supported --- PASS: TestSyncWithUpdateOlder (11.73s) === RUN TestSyncWithMaxDuration sync_test.go:1009: Skipping test on non local remote --- SKIP: TestSyncWithMaxDuration (0.00s) === RUN TestSyncWithTrackRenames run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5'", Local "Local file system at /tmp/rclone267558022", Modify Window "1ms" sync_test.go:1058: Can track renames: false 2022/03/15 05:51:44 ERROR : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Ignoring --track-renames as the source and destination do not have a common hash 2022/03/15 05:51:44 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for checks to finish 2022/03/15 05:51:44 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for transfers to finish 2022/03/15 05:51:45 DEBUG : potato: md5 = dc5aa84d705643e4786033d9dc81fef6 OK 2022/03/15 05:51:45 INFO : potato: Copied (new) 2022/03/15 05:51:46 DEBUG : yam: md5 = 270bb31a5b0dfd8e4dc131845ff58949 OK 2022/03/15 05:51:46 INFO : yam: Copied (new) 2022/03/15 05:51:46 DEBUG : Waiting for deletions to finish 2022/03/15 05:51:46 ERROR : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Ignoring --track-renames as the source and destination do not have a common hash 2022/03/15 05:51:46 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for checks to finish 2022/03/15 05:51:46 DEBUG : potato: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/15 05:51:46 DEBUG : potato: Unchanged skipping 2022/03/15 05:51:46 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for transfers to finish 2022/03/15 05:51:48 DEBUG : yaml: md5 = 913ecfeac4a71a47338d153f82fcf333 OK 2022/03/15 05:51:48 INFO : yaml: Copied (new) 2022/03/15 05:51:48 DEBUG : Waiting for deletions to finish 2022/03/15 05:51:48 INFO : yam: Deleted --- PASS: TestSyncWithTrackRenames (7.01s) === RUN TestParseRenamesStrategyModtime --- PASS: TestParseRenamesStrategyModtime (0.00s) === RUN TestRenamesStrategyModtime --- PASS: TestRenamesStrategyModtime (0.00s) === RUN TestSyncWithTrackRenamesStrategyModtime run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5'", Local "Local file system at /tmp/rclone267558022", Modify Window "1ms" sync_test.go:1127: Can track renames: true 2022/03/15 05:51:51 INFO : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Making map for --track-renames 2022/03/15 05:51:51 INFO : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Finished making map for --track-renames 2022/03/15 05:51:51 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for checks to finish 2022/03/15 05:51:51 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for renames to finish 2022/03/15 05:51:51 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for transfers to finish 2022/03/15 05:51:52 DEBUG : potato: md5 = da9300f0c0b088e485dc57aba373234a OK 2022/03/15 05:51:52 INFO : potato: Copied (new) 2022/03/15 05:51:53 DEBUG : yam: md5 = 33d9488cd5682fef31430b58fdf8d0a1 OK 2022/03/15 05:51:53 INFO : yam: Copied (new) 2022/03/15 05:51:53 DEBUG : Waiting for deletions to finish 2022/03/15 05:51:53 DEBUG : potato: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/15 05:51:53 DEBUG : potato: Unchanged skipping 2022/03/15 05:51:53 INFO : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Making map for --track-renames 2022/03/15 05:51:53 INFO : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Finished making map for --track-renames 2022/03/15 05:51:53 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for checks to finish 2022/03/15 05:51:53 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for renames to finish 2022/03/15 05:51:54 INFO : yam: Moved (server-side) to: yaml 2022/03/15 05:51:54 INFO : yaml: Renamed from "yam" 2022/03/15 05:51:54 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for transfers to finish 2022/03/15 05:51:54 DEBUG : Waiting for deletions to finish 2022/03/15 05:51:54 INFO : There was nothing to transfer --- PASS: TestSyncWithTrackRenamesStrategyModtime (5.83s) === RUN TestSyncWithTrackRenamesStrategyLeaf run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5'", Local "Local file system at /tmp/rclone267558022", Modify Window "1ms" sync_test.go:1163: Can track renames: true 2022/03/15 05:51:57 INFO : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Making map for --track-renames 2022/03/15 05:51:57 INFO : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Finished making map for --track-renames 2022/03/15 05:51:57 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for checks to finish 2022/03/15 05:51:57 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for renames to finish 2022/03/15 05:51:57 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for transfers to finish 2022/03/15 05:51:59 DEBUG : potato: md5 = d74a3375f6bb5ca62ae1c92c43877d73 OK 2022/03/15 05:51:59 INFO : potato: Copied (new) 2022/03/15 05:51:59 DEBUG : sub/yam: md5 = 689370ed221abd6fbde55f9044a98d99 OK 2022/03/15 05:51:59 INFO : sub/yam: Copied (new) 2022/03/15 05:51:59 DEBUG : Waiting for deletions to finish 2022/03/15 05:52:00 DEBUG : potato: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/15 05:52:00 DEBUG : potato: Unchanged skipping 2022/03/15 05:52:00 INFO : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Making map for --track-renames 2022/03/15 05:52:00 INFO : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Finished making map for --track-renames 2022/03/15 05:52:00 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for checks to finish 2022/03/15 05:52:00 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for renames to finish 2022/03/15 05:52:01 INFO : sub/yam: Moved (server-side) to: yam 2022/03/15 05:52:01 INFO : yam: Renamed from "sub/yam" 2022/03/15 05:52:01 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for transfers to finish 2022/03/15 05:52:01 DEBUG : Waiting for deletions to finish 2022/03/15 05:52:01 INFO : There was nothing to transfer --- PASS: TestSyncWithTrackRenamesStrategyLeaf (7.99s) === RUN TestMoveWithDeleteEmptySrcDirs run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5'", Local "Local file system at /tmp/rclone267558022", Modify Window "1ms" 2022/03/15 05:52:05 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for checks to finish 2022/03/15 05:52:05 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for transfers to finish 2022/03/15 05:52:07 DEBUG : sub dir/hello world: md5 = 1272f16f59fd79147c1c114cc4b266b3 OK 2022/03/15 05:52:07 INFO : sub dir/hello world: Copied (new) 2022/03/15 05:52:07 INFO : sub dir/hello world: Deleted 2022/03/15 05:52:09 DEBUG : nested/sub dir/file: md5 = ad2e0460d27e7f00f836ebdb060989d9 OK 2022/03/15 05:52:09 INFO : nested/sub dir/file: Copied (new) 2022/03/15 05:52:09 INFO : nested/sub dir/file: Deleted 2022/03/15 05:52:09 INFO : sub dir: Removing directory 2022/03/15 05:52:09 INFO : nested/sub dir: Removing directory 2022/03/15 05:52:09 INFO : nested: Removing directory 2022/03/15 05:52:09 DEBUG : Local file system at /tmp/rclone267558022: deleted 3 directories 2022/03/15 05:52:12 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" 2022/03/15 05:52:13 DEBUG : 37qp6d1gohacv723ij3brofbu8/14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "ftp4kuv8se7tqduu6pmmcvjsmk" 2022/03/15 05:52:14 DEBUG : 37qp6d1gohacv723ij3brofbu8: Rmdir: contains trashed file: "14begaa36ih249fgrnfk6nulg0" --- PASS: TestMoveWithDeleteEmptySrcDirs (10.62s) === RUN TestMoveWithoutDeleteEmptySrcDirs run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5'", Local "Local file system at /tmp/rclone267558022", Modify Window "1ms" 2022/03/15 05:52:15 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for checks to finish 2022/03/15 05:52:15 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for transfers to finish 2022/03/15 05:52:18 DEBUG : sub dir/hello world: md5 = e6d036d37d8aa3cb4e9f1d68d6adeb85 OK 2022/03/15 05:52:18 INFO : sub dir/hello world: Copied (new) 2022/03/15 05:52:18 INFO : sub dir/hello world: Deleted 2022/03/15 05:52:20 DEBUG : nested/sub dir/file: md5 = f0266b9e14a9f1492c731251aed7c851 OK 2022/03/15 05:52:20 INFO : nested/sub dir/file: Copied (new) 2022/03/15 05:52:20 INFO : nested/sub dir/file: Deleted 2022/03/15 05:52:23 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" 2022/03/15 05:52:24 DEBUG : 37qp6d1gohacv723ij3brofbu8/14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "ftp4kuv8se7tqduu6pmmcvjsmk" 2022/03/15 05:52:25 DEBUG : 37qp6d1gohacv723ij3brofbu8: Rmdir: contains trashed file: "14begaa36ih249fgrnfk6nulg0" --- PASS: TestMoveWithoutDeleteEmptySrcDirs (10.45s) === RUN TestMoveWithIgnoreExisting run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5'", Local "Local file system at /tmp/rclone267558022", Modify Window "1ms" 2022/03/15 05:52:26 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for checks to finish 2022/03/15 05:52:26 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for transfers to finish 2022/03/15 05:52:27 DEBUG : existing: md5 = 8b27abe32778e7635ec344dbe6814712 OK 2022/03/15 05:52:27 INFO : existing: Copied (new) 2022/03/15 05:52:27 INFO : existing: Deleted 2022/03/15 05:52:28 DEBUG : existing-b: md5 = 333cb3160ef6fb481c3ec4ea30ed09b5 OK 2022/03/15 05:52:28 INFO : existing-b: Copied (new) 2022/03/15 05:52:28 INFO : existing-b: Deleted 2022/03/15 05:52:28 DEBUG : existing: Destination exists, skipping 2022/03/15 05:52:28 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for checks to finish 2022/03/15 05:52:28 DEBUG : existing: Not removing source file as destination file exists and --ignore-existing is set 2022/03/15 05:52:28 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for transfers to finish 2022/03/15 05:52:28 INFO : There was nothing to transfer --- PASS: TestMoveWithIgnoreExisting (4.78s) === RUN TestServerSideMove run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5'", Local "Local file system at /tmp/rclone267558022", Modify Window "1ms" 2022/03/15 05:52:30 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-denijur4famaxuz2soxajuf4" 2022/03/15 05:52:30 DEBUG : Config file has changed externaly - reloading 2022/03/15 05:52:30 DEBUG : Creating backend with remote "TestDrive:crypt/q7m06jnksqar5tdor57c8fru0i3klmckjjf27b7bm8fgr5e4jtk7d47pkbb732kph4u5c7nd1u39a" 2022/03/15 05:52:33 DEBUG : potato2: md5 = 189034eb1ed1da88ad16e4792d4f099a OK 2022/03/15 05:52:34 DEBUG : empty space: md5 = cbf5501cc02978058d88083b36c06926 OK 2022/03/15 05:52:36 DEBUG : potato3: md5 = 3769d499dc4bdcaa22b2b8680c75707a OK sync_test.go:1215: Server side move (if possible) Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5' -> Encrypted drive 'TestCryptDrive:rclone-test-denijur4famaxuz2soxajuf4' 2022/03/15 05:52:39 DEBUG : empty space: md5 = d242c509d9ece05097354e170fcd7999 OK 2022/03/15 05:52:40 DEBUG : potato3: md5 = fc2b332acbc2a2f6453a7004f7c28f32 OK 2022/03/15 05:52:40 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-denijur4famaxuz2soxajuf4': Using server-side directory move 2022/03/15 05:52:40 INFO : Encrypted drive 'TestCryptDrive:rclone-test-denijur4famaxuz2soxajuf4': Server side directory move failed - fallback to file moves: can't copy directory - destination already exists 2022/03/15 05:52:41 DEBUG : potato3: Sizes differ (src 68 vs dst 60) 2022/03/15 05:52:41 DEBUG : empty space: Size and modification time the same (differ by 0s, within tolerance 1ms) 2022/03/15 05:52:41 DEBUG : empty space: Unchanged skipping 2022/03/15 05:52:41 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-denijur4famaxuz2soxajuf4': Waiting for checks to finish 2022/03/15 05:52:41 INFO : empty space: Deleted 2022/03/15 05:52:41 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-denijur4famaxuz2soxajuf4': Waiting for transfers to finish 2022/03/15 05:52:42 INFO : potato3: Deleted 2022/03/15 05:52:42 INFO : potato2: Moved (server-side) 2022/03/15 05:52:42 INFO : potato3: Moved (server-side) 2022/03/15 05:52:42 INFO : There was nothing to transfer 2022/03/15 05:52:43 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-pulobuc7vikufos9muzugah7" 2022/03/15 05:52:43 DEBUG : Creating backend with remote "TestDrive:crypt/nd3mls0oon42i0n5urm1obggt4vbfiiq6u8tm5ijgsn3jn5ts3vivhojdvhuhkos2k6be6g72rfek" 2022/03/15 05:52:44 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-pulobuc7vikufos9muzugah7': Using server-side directory move 2022/03/15 05:52:45 INFO : Encrypted drive 'TestCryptDrive:rclone-test-pulobuc7vikufos9muzugah7': Server side directory move succeeded 2022/03/15 05:52:47 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-pulobuc7vikufos9muzugah7': Purge remote 2022/03/15 05:52:47 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-denijur4famaxuz2soxajuf4': Purge remote 2022/03/15 05:52:47 purge failed: directory not found --- PASS: TestServerSideMove (17.68s) === RUN TestServerSideMoveWithFilter run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5'", Local "Local file system at /tmp/rclone267558022", Modify Window "1ms" 2022/03/15 05:52:48 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-danuruf0cibeney0hotazir9" 2022/03/15 05:52:48 DEBUG : Creating backend with remote "TestDrive:crypt/t4a5l089ptthc0ha9qnddmt9q7r9c1gkrbj7imki6otigtcvds5or11bkp51n5o7oufop6j5pqfh6" 2022/03/15 05:52:51 DEBUG : potato2: md5 = 99582bfa6bc17c0ba2bae73b26343952 OK 2022/03/15 05:52:52 DEBUG : empty space: md5 = 2125fe0565174a36886859d02da07b4c OK 2022/03/15 05:52:54 DEBUG : potato3: md5 = c3e38a5a98f7c8fe6773485df86f8776 OK sync_test.go:1215: Server side move (if possible) Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5' -> Encrypted drive 'TestCryptDrive:rclone-test-danuruf0cibeney0hotazir9' 2022/03/15 05:52:57 DEBUG : empty space: md5 = beba4a10a1b7813acf88a85f21546c67 OK 2022/03/15 05:52:58 DEBUG : potato3: md5 = a8b673459ccd1dc7c7328340948a7e99 OK 2022/03/15 05:52:59 DEBUG : empty space: Excluded from sync (and deletion) 2022/03/15 05:52:59 DEBUG : empty space: Excluded from sync (and deletion) 2022/03/15 05:52:59 DEBUG : potato3: Sizes differ (src 68 vs dst 60) 2022/03/15 05:52:59 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-danuruf0cibeney0hotazir9': Waiting for checks to finish 2022/03/15 05:52:59 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-danuruf0cibeney0hotazir9': Waiting for transfers to finish 2022/03/15 05:53:00 INFO : potato3: Deleted 2022/03/15 05:53:00 INFO : potato2: Moved (server-side) 2022/03/15 05:53:01 INFO : potato3: Moved (server-side) 2022/03/15 05:53:01 INFO : There was nothing to transfer 2022/03/15 05:53:01 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-quwoqiv9meqojup5yiyecog8" 2022/03/15 05:53:01 DEBUG : Creating backend with remote "TestDrive:crypt/ishefbu9kdj32ujgl6us5oek54ll509abpk301q3skuk0694200hcvs83pa2069po990p3teq7mla" 2022/03/15 05:53:03 DEBUG : empty space: Excluded from sync (and deletion) 2022/03/15 05:53:03 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-quwoqiv9meqojup5yiyecog8': Waiting for checks to finish 2022/03/15 05:53:03 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-quwoqiv9meqojup5yiyecog8': Waiting for transfers to finish 2022/03/15 05:53:05 INFO : potato3: Moved (server-side) 2022/03/15 05:53:05 INFO : potato2: Moved (server-side) 2022/03/15 05:53:05 INFO : There was nothing to transfer 2022/03/15 05:53:06 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-quwoqiv9meqojup5yiyecog8': Purge remote 2022/03/15 05:53:07 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-danuruf0cibeney0hotazir9': Purge remote --- PASS: TestServerSideMoveWithFilter (20.34s) === RUN TestServerSideMoveDeleteEmptySourceDirs run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5'", Local "Local file system at /tmp/rclone267558022", Modify Window "1ms" 2022/03/15 05:53:08 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-duqiniz3tazulip7xedetum9" 2022/03/15 05:53:08 DEBUG : Creating backend with remote "TestDrive:crypt/g3adk82d6517mi27an8l2q0crecv7pda960pg7ch0ffc8un4ombiaj2kukqu2s75401c4uebv80h0" 2022/03/15 05:53:11 DEBUG : potato2: md5 = e3c048ebc21a6c95ad2a15ae613673f4 OK 2022/03/15 05:53:12 DEBUG : empty space: md5 = c3dfbac730feda62b714de4358fcfc83 OK 2022/03/15 05:53:14 DEBUG : potato3: md5 = dc3d364cb93822f4a5dc4f33b5ab417e OK 2022/03/15 05:53:14 DEBUG : tomatoDir: Making directory sync_test.go:1215: Server side move (if possible) Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5' -> Encrypted drive 'TestCryptDrive:rclone-test-duqiniz3tazulip7xedetum9' 2022/03/15 05:53:18 DEBUG : empty space: md5 = 2c1e0dd1fe1831fe1f29852e5b3fa555 OK 2022/03/15 05:53:19 DEBUG : potato3: md5 = 3f682d52ec4eefbd95d1c1e15132fa6e OK 2022/03/15 05:53:20 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-duqiniz3tazulip7xedetum9': Using server-side directory move 2022/03/15 05:53:20 INFO : Encrypted drive 'TestCryptDrive:rclone-test-duqiniz3tazulip7xedetum9': Server side directory move failed - fallback to file moves: can't copy directory - destination already exists 2022/03/15 05:53:20 DEBUG : empty space: Size and modification time the same (differ by 0s, within tolerance 1ms) 2022/03/15 05:53:20 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-duqiniz3tazulip7xedetum9': Waiting for checks to finish 2022/03/15 05:53:20 DEBUG : empty space: Unchanged skipping 2022/03/15 05:53:20 DEBUG : potato3: Sizes differ (src 68 vs dst 60) 2022/03/15 05:53:21 INFO : empty space: Deleted 2022/03/15 05:53:21 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-duqiniz3tazulip7xedetum9': Waiting for transfers to finish 2022/03/15 05:53:21 INFO : potato3: Deleted 2022/03/15 05:53:21 INFO : potato2: Moved (server-side) 2022/03/15 05:53:22 INFO : potato3: Moved (server-side) 2022/03/15 05:53:22 INFO : tomatoDir: Removing directory 2022/03/15 05:53:23 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': deleted 1 directories 2022/03/15 05:53:23 INFO : There was nothing to transfer 2022/03/15 05:53:24 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-ciqadec7fuvenik7haheheb8" 2022/03/15 05:53:24 DEBUG : Config file has changed externaly - reloading 2022/03/15 05:53:24 DEBUG : Creating backend with remote "TestDrive:crypt/apiug5e67n649vmmr69u5jv2c1276utkgfkk2vfk7btonglf6fmq43cff4tqt9dbgrfpnlea6pbjo" 2022/03/15 05:53:25 DEBUG : tomatoDir: Making directory 2022/03/15 05:53:26 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-ciqadec7fuvenik7haheheb8': Using server-side directory move 2022/03/15 05:53:27 INFO : Encrypted drive 'TestCryptDrive:rclone-test-ciqadec7fuvenik7haheheb8': Server side directory move succeeded 2022/03/15 05:53:29 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-ciqadec7fuvenik7haheheb8': Purge remote 2022/03/15 05:53:29 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-duqiniz3tazulip7xedetum9': Purge remote 2022/03/15 05:53:30 purge failed: directory not found --- PASS: TestServerSideMoveDeleteEmptySourceDirs (21.89s) === RUN TestServerSideMoveOverlap run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5'", Local "Local file system at /tmp/rclone267558022", Modify Window "1ms" sync_test.go:1399: Skipping test as remote supports DirMove --- SKIP: TestServerSideMoveOverlap (0.45s) === RUN TestSyncOverlap run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5'", Local "Local file system at /tmp/rclone267558022", Modify Window "1ms" 2022/03/15 05:53:31 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5/rclone-sync-test" 2022/03/15 05:53:31 DEBUG : Creating backend with remote "TestDrive:crypt/728kds3mq75c78rvf3qlm1l12dibr01rft25rdpgmiklo90h7o08uece3pjg2bd6dr2evim9rfch0/i7355aa0sb89uagn75vfjqr6s3e3e1h2et8in57abn1fe8qfego0" --- PASS: TestSyncOverlap (2.41s) === RUN TestSyncCompareDest run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5'", Local "Local file system at /tmp/rclone267558022", Modify Window "1ms" 2022/03/15 05:53:33 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5/dst" 2022/03/15 05:53:33 DEBUG : Creating backend with remote "TestDrive:crypt/728kds3mq75c78rvf3qlm1l12dibr01rft25rdpgmiklo90h7o08uece3pjg2bd6dr2evim9rfch0/31u3jie661vd5p8j7rtc3hgbh0" 2022/03/15 05:53:35 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5/CompareDest" 2022/03/15 05:53:35 DEBUG : Creating backend with remote "TestDrive:crypt/728kds3mq75c78rvf3qlm1l12dibr01rft25rdpgmiklo90h7o08uece3pjg2bd6dr2evim9rfch0/gveqi14airsml4bgu7krj116o8" 2022/03/15 05:53:37 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5/dst': Waiting for checks to finish 2022/03/15 05:53:37 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5/dst': Waiting for transfers to finish 2022/03/15 05:53:40 DEBUG : one: md5 = 279113b9c274c13a4a3382d1a9edec24 OK 2022/03/15 05:53:40 INFO : one: Copied (new) 2022/03/15 05:53:40 DEBUG : Waiting for deletions to finish 2022/03/15 05:53:41 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5/dst': Waiting for checks to finish 2022/03/15 05:53:41 DEBUG : one: Sizes differ (src 5 vs dst 3) 2022/03/15 05:53:41 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5/dst': Waiting for transfers to finish 2022/03/15 05:53:43 DEBUG : one: md5 = d751588cc3ca38ec9a358c08fecbaab2 OK 2022/03/15 05:53:43 INFO : one: Copied (replaced existing) 2022/03/15 05:53:43 DEBUG : Waiting for deletions to finish 2022/03/15 05:53:45 DEBUG : dst/one: md5 = 3f9de2a6dc7580c65c1f10446c20574e OK 2022/03/15 05:53:47 DEBUG : CompareDest/one: md5 = cce10879959be95561640acca1f1385d OK 2022/03/15 05:53:48 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5/dst': Waiting for checks to finish 2022/03/15 05:53:49 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/15 05:53:49 DEBUG : one: Destination found in --compare-dest, skipping 2022/03/15 05:53:49 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5/dst': Waiting for transfers to finish 2022/03/15 05:53:49 DEBUG : Waiting for deletions to finish 2022/03/15 05:53:49 INFO : There was nothing to transfer 2022/03/15 05:53:51 DEBUG : CompareDest/two: md5 = 2c010567e4ce99c6e118bc788642c7ab OK 2022/03/15 05:53:52 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/15 05:53:52 DEBUG : two: Destination found in --compare-dest, skipping 2022/03/15 05:53:52 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5/dst': Waiting for checks to finish 2022/03/15 05:53:52 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/15 05:53:52 DEBUG : one: Destination found in --compare-dest, skipping 2022/03/15 05:53:52 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5/dst': Waiting for transfers to finish 2022/03/15 05:53:52 DEBUG : Waiting for deletions to finish 2022/03/15 05:53:52 INFO : There was nothing to transfer 2022/03/15 05:53:54 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/15 05:53:54 DEBUG : two: Destination found in --compare-dest, skipping 2022/03/15 05:53:54 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5/dst': Waiting for checks to finish 2022/03/15 05:53:54 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/15 05:53:54 DEBUG : one: Destination found in --compare-dest, skipping 2022/03/15 05:53:54 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5/dst': Waiting for transfers to finish 2022/03/15 05:53:54 DEBUG : Waiting for deletions to finish 2022/03/15 05:53:54 INFO : There was nothing to transfer sync_test.go:1543: No hash on uploaded file so skipping compare timestamp test 2022/03/15 05:53:56 DEBUG : two: Sizes differ (src 5 vs dst 3) 2022/03/15 05:53:56 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5/dst': Waiting for checks to finish 2022/03/15 05:53:56 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/15 05:53:56 DEBUG : one: Destination found in --compare-dest, skipping 2022/03/15 05:53:56 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5/dst': Waiting for transfers to finish 2022/03/15 05:53:57 DEBUG : two: md5 = 6480998e69f6eecbc9f071463a258140 OK 2022/03/15 05:53:57 INFO : two: Copied (new) 2022/03/15 05:53:57 DEBUG : Waiting for deletions to finish 2022/03/15 05:54:01 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" 2022/03/15 05:54:01 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2022/03/15 05:54:03 DEBUG : gveqi14airsml4bgu7krj116o8: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2022/03/15 05:54:03 DEBUG : gveqi14airsml4bgu7krj116o8: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" --- PASS: TestSyncCompareDest (30.53s) === RUN TestSyncMultipleCompareDest run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5'", Local "Local file system at /tmp/rclone267558022", Modify Window "1ms" 2022/03/15 05:54:06 DEBUG : pre-dest1/1: md5 = 7b86897faca28001f9a7dc8f5ab4a440 OK 2022/03/15 05:54:09 DEBUG : pre-dest2/2: md5 = 6169867a21f334db28535b614001253a OK 2022/03/15 05:54:09 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5/dest" 2022/03/15 05:54:09 DEBUG : Creating backend with remote "TestDrive:crypt/728kds3mq75c78rvf3qlm1l12dibr01rft25rdpgmiklo90h7o08uece3pjg2bd6dr2evim9rfch0/rg03c1jvnehrrc617i0lnqjddc" 2022/03/15 05:54:11 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5/pre-dest1" 2022/03/15 05:54:11 DEBUG : Creating backend with remote "TestDrive:crypt/728kds3mq75c78rvf3qlm1l12dibr01rft25rdpgmiklo90h7o08uece3pjg2bd6dr2evim9rfch0/bbnblvh6k061ssopqrp18kd7gc" 2022/03/15 05:54:12 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5/pre-dest2" 2022/03/15 05:54:12 DEBUG : Creating backend with remote "TestDrive:crypt/728kds3mq75c78rvf3qlm1l12dibr01rft25rdpgmiklo90h7o08uece3pjg2bd6dr2evim9rfch0/dgicm1h6b5ejvlltm8eeif0bnk" 2022/03/15 05:54:14 DEBUG : 1: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/15 05:54:14 DEBUG : 1: Destination found in --compare-dest, skipping 2022/03/15 05:54:14 DEBUG : 2: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/15 05:54:14 DEBUG : 2: Destination found in --compare-dest, skipping 2022/03/15 05:54:15 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5/dest': Waiting for checks to finish 2022/03/15 05:54:15 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5/dest': Waiting for transfers to finish 2022/03/15 05:54:17 DEBUG : 3: md5 = 184c90dcb05fc98603500ce501b6131b OK 2022/03/15 05:54:17 INFO : 3: Copied (new) 2022/03/15 05:54:17 DEBUG : Waiting for deletions to finish 2022/03/15 05:54:21 DEBUG : dgicm1h6b5ejvlltm8eeif0bnk: Rmdir: contains trashed file: "1ghu8geql9vrl726n32nrf65bc" 2022/03/15 05:54:22 DEBUG : bbnblvh6k061ssopqrp18kd7gc: Rmdir: contains trashed file: "skbfko3oil7es0lj68ob574sro" 2022/03/15 05:54:23 DEBUG : rg03c1jvnehrrc617i0lnqjddc: Rmdir: contains trashed file: "g072p7hmjchlnj0gibe64c1epg" --- PASS: TestSyncMultipleCompareDest (20.76s) === RUN TestSyncCopyDest run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5'", Local "Local file system at /tmp/rclone267558022", Modify Window "1ms" 2022/03/15 05:54:24 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5/dst" 2022/03/15 05:54:24 DEBUG : Creating backend with remote "TestDrive:crypt/728kds3mq75c78rvf3qlm1l12dibr01rft25rdpgmiklo90h7o08uece3pjg2bd6dr2evim9rfch0/31u3jie661vd5p8j7rtc3hgbh0" 2022/03/15 05:54:26 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5/CopyDest" 2022/03/15 05:54:26 DEBUG : Creating backend with remote "TestDrive:crypt/728kds3mq75c78rvf3qlm1l12dibr01rft25rdpgmiklo90h7o08uece3pjg2bd6dr2evim9rfch0/d09o6po3f7bm6ce32vdgs8h9ls" 2022/03/15 05:54:29 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5/dst': Waiting for checks to finish 2022/03/15 05:54:29 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5/dst': Waiting for transfers to finish 2022/03/15 05:54:31 DEBUG : one: md5 = 1c26956436ade773a125ce9c87067d46 OK 2022/03/15 05:54:31 INFO : one: Copied (new) 2022/03/15 05:54:31 DEBUG : Waiting for deletions to finish 2022/03/15 05:54:33 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5/dst': Waiting for checks to finish 2022/03/15 05:54:33 DEBUG : one: Sizes differ (src 5 vs dst 3) 2022/03/15 05:54:33 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5/dst': Waiting for transfers to finish 2022/03/15 05:54:34 DEBUG : one: md5 = 8e8d7f170c41db6c16508e5571dec6d9 OK 2022/03/15 05:54:34 INFO : one: Copied (replaced existing) 2022/03/15 05:54:34 DEBUG : Waiting for deletions to finish 2022/03/15 05:54:36 DEBUG : dst/one: md5 = e089bfbfef975cad30e04d8ea942c2ed OK 2022/03/15 05:54:39 DEBUG : CopyDest/one: md5 = 68dbc6c1af854f3662efcc46abe18770 OK 2022/03/15 05:54:39 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5/BackupDir" 2022/03/15 05:54:39 DEBUG : Creating backend with remote "TestDrive:crypt/728kds3mq75c78rvf3qlm1l12dibr01rft25rdpgmiklo90h7o08uece3pjg2bd6dr2evim9rfch0/s6dbk3lfi7c9kfvo6j7bla9m0g" 2022/03/15 05:54:41 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5/dst': Waiting for checks to finish 2022/03/15 05:54:42 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/15 05:54:42 DEBUG : one: Sizes differ (src 5 vs dst 3) 2022/03/15 05:54:44 INFO : one: Moved (server-side) 2022/03/15 05:54:45 INFO : one: Copied (server-side copy) 2022/03/15 05:54:45 DEBUG : one: Destination found in --copy-dest, using server-side copy 2022/03/15 05:54:45 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5/dst': Waiting for transfers to finish 2022/03/15 05:54:45 DEBUG : Waiting for deletions to finish 2022/03/15 05:54:48 DEBUG : CopyDest/two: md5 = 7974a3c5ad22e08ab29f0387498ccdc4 OK 2022/03/15 05:54:49 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/15 05:54:50 INFO : two: Copied (server-side copy) 2022/03/15 05:54:50 DEBUG : two: Destination found in --copy-dest, using server-side copy 2022/03/15 05:54:50 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5/dst': Waiting for checks to finish 2022/03/15 05:54:51 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/15 05:54:51 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/15 05:54:51 DEBUG : one: Unchanged skipping 2022/03/15 05:54:51 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5/dst': Waiting for transfers to finish 2022/03/15 05:54:51 DEBUG : Waiting for deletions to finish 2022/03/15 05:54:52 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5/dst': Waiting for checks to finish 2022/03/15 05:54:52 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/15 05:54:52 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/15 05:54:52 DEBUG : two: Unchanged skipping 2022/03/15 05:54:52 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/15 05:54:52 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/15 05:54:52 DEBUG : one: Unchanged skipping 2022/03/15 05:54:52 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5/dst': Waiting for transfers to finish 2022/03/15 05:54:52 DEBUG : Waiting for deletions to finish 2022/03/15 05:54:52 INFO : There was nothing to transfer 2022/03/15 05:54:54 DEBUG : CopyDest/three: md5 = 17b5081e12e2c6793b5bb4aa48fa85f2 OK 2022/03/15 05:54:56 DEBUG : three: Sizes differ (src 7 vs dst 5) 2022/03/15 05:54:56 DEBUG : three: Destination not found in --copy-dest 2022/03/15 05:54:56 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5/dst': Waiting for checks to finish 2022/03/15 05:54:56 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/15 05:54:56 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/15 05:54:56 DEBUG : two: Unchanged skipping 2022/03/15 05:54:56 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/15 05:54:56 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/15 05:54:56 DEBUG : one: Unchanged skipping 2022/03/15 05:54:56 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5/dst': Waiting for transfers to finish 2022/03/15 05:54:57 DEBUG : three: md5 = 6566315c03d1560e821b01dd6960f064 OK 2022/03/15 05:54:57 INFO : three: Copied (new) 2022/03/15 05:54:57 DEBUG : Waiting for deletions to finish 2022/03/15 05:55:04 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "b6jdmn2b1adrhc8vikh7edr9os" 2022/03/15 05:55:04 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2022/03/15 05:55:04 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" 2022/03/15 05:55:05 DEBUG : d09o6po3f7bm6ce32vdgs8h9ls: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2022/03/15 05:55:05 DEBUG : d09o6po3f7bm6ce32vdgs8h9ls: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" 2022/03/15 05:55:05 DEBUG : d09o6po3f7bm6ce32vdgs8h9ls: Rmdir: contains trashed file: "b6jdmn2b1adrhc8vikh7edr9os" 2022/03/15 05:55:06 DEBUG : s6dbk3lfi7c9kfvo6j7bla9m0g: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" --- PASS: TestSyncCopyDest (42.39s) === RUN TestSyncBackupDir run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5'", Local "Local file system at /tmp/rclone267558022", Modify Window "1ms" 2022/03/15 05:55:09 DEBUG : dst/one: md5 = 3214990b5a1dd0fd5e3c64fddb7ad53e OK 2022/03/15 05:55:11 DEBUG : dst/two: md5 = e5a033f160b7f399afddb6a22e903123 OK 2022/03/15 05:55:12 DEBUG : dst/three.txt: md5 = d72991de614960b7b12cec1fb5b0c5d5 OK 2022/03/15 05:55:13 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5/dst" 2022/03/15 05:55:13 DEBUG : Creating backend with remote "TestDrive:crypt/728kds3mq75c78rvf3qlm1l12dibr01rft25rdpgmiklo90h7o08uece3pjg2bd6dr2evim9rfch0/31u3jie661vd5p8j7rtc3hgbh0" 2022/03/15 05:55:14 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5/backup" 2022/03/15 05:55:14 DEBUG : Creating backend with remote "TestDrive:crypt/728kds3mq75c78rvf3qlm1l12dibr01rft25rdpgmiklo90h7o08uece3pjg2bd6dr2evim9rfch0/1nrff024r7pq65ecp72fc28jb0" 2022/03/15 05:55:16 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/15 05:55:16 DEBUG : two: Unchanged skipping 2022/03/15 05:55:16 DEBUG : one: Sizes differ (src 4 vs dst 3) 2022/03/15 05:55:16 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5/dst': Waiting for checks to finish 2022/03/15 05:55:18 INFO : one: Moved (server-side) 2022/03/15 05:55:18 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5/dst': Waiting for transfers to finish 2022/03/15 05:55:20 DEBUG : one: md5 = 736facf9d635642adc8a960f52441c6d OK 2022/03/15 05:55:20 INFO : one: Copied (new) 2022/03/15 05:55:20 DEBUG : Waiting for deletions to finish 2022/03/15 05:55:21 INFO : three.txt: Moved (server-side) 2022/03/15 05:55:21 INFO : three.txt: Moved into backup dir 2022/03/15 05:55:23 DEBUG : dst/three.txt: md5 = e99896686ad6829b7137b0003939ae39 OK 2022/03/15 05:55:24 DEBUG : one: Sizes differ (src 5 vs dst 4) 2022/03/15 05:55:24 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/15 05:55:24 DEBUG : two: Unchanged skipping 2022/03/15 05:55:24 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5/dst': Waiting for checks to finish 2022/03/15 05:55:25 INFO : one: Deleted 2022/03/15 05:55:26 INFO : one: Moved (server-side) 2022/03/15 05:55:26 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5/dst': Waiting for transfers to finish 2022/03/15 05:55:27 DEBUG : one: md5 = 4e08bba47fb4d0b4a075ff74f85a89fd OK 2022/03/15 05:55:27 INFO : one: Copied (new) 2022/03/15 05:55:27 DEBUG : Waiting for deletions to finish 2022/03/15 05:55:28 INFO : three.txt: Deleted 2022/03/15 05:55:29 INFO : three.txt: Moved (server-side) 2022/03/15 05:55:29 INFO : three.txt: Moved into backup dir 2022/03/15 05:55:33 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2022/03/15 05:55:33 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" 2022/03/15 05:55:34 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2022/03/15 05:55:34 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "tr2hj63d80ftlmvm6a952snjcc" 2022/03/15 05:55:34 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "tr2hj63d80ftlmvm6a952snjcc" 2022/03/15 05:55:34 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" --- PASS: TestSyncBackupDir (28.73s) === RUN TestSyncBackupDirWithSuffix run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5'", Local "Local file system at /tmp/rclone267558022", Modify Window "1ms" 2022/03/15 05:55:38 DEBUG : dst/one: md5 = 6ba74b2b7c701782aee5e227b3961409 OK 2022/03/15 05:55:40 DEBUG : dst/two: md5 = 34e247076afe2ee53ce1fc894ae5321e OK 2022/03/15 05:55:41 DEBUG : dst/three.txt: md5 = e7e903d598a602b6646c1c7d584311d8 OK 2022/03/15 05:55:42 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5/dst" 2022/03/15 05:55:42 DEBUG : Creating backend with remote "TestDrive:crypt/728kds3mq75c78rvf3qlm1l12dibr01rft25rdpgmiklo90h7o08uece3pjg2bd6dr2evim9rfch0/31u3jie661vd5p8j7rtc3hgbh0" 2022/03/15 05:55:43 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5/backup" 2022/03/15 05:55:43 DEBUG : Creating backend with remote "TestDrive:crypt/728kds3mq75c78rvf3qlm1l12dibr01rft25rdpgmiklo90h7o08uece3pjg2bd6dr2evim9rfch0/1nrff024r7pq65ecp72fc28jb0" 2022/03/15 05:55:45 DEBUG : one: Sizes differ (src 4 vs dst 3) 2022/03/15 05:55:45 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/15 05:55:45 DEBUG : two: Unchanged skipping 2022/03/15 05:55:45 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5/dst': Waiting for checks to finish 2022/03/15 05:55:47 INFO : one: Moved (server-side) to: one.bak 2022/03/15 05:55:47 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5/dst': Waiting for transfers to finish 2022/03/15 05:55:49 DEBUG : one: md5 = ae03fc9f0d71902d539fcaee54878b95 OK 2022/03/15 05:55:49 INFO : one: Copied (new) 2022/03/15 05:55:49 DEBUG : Waiting for deletions to finish 2022/03/15 05:55:50 INFO : three.txt: Moved (server-side) to: three.txt.bak 2022/03/15 05:55:50 INFO : three.txt: Moved into backup dir 2022/03/15 05:55:52 DEBUG : dst/three.txt: md5 = bc37f4906c7cc65977ec87cdc51fee4f OK 2022/03/15 05:55:53 DEBUG : one: Sizes differ (src 5 vs dst 4) 2022/03/15 05:55:53 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5/dst': Waiting for checks to finish 2022/03/15 05:55:53 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/15 05:55:53 DEBUG : two: Unchanged skipping 2022/03/15 05:55:54 INFO : one.bak: Deleted 2022/03/15 05:55:55 INFO : one: Moved (server-side) to: one.bak 2022/03/15 05:55:55 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5/dst': Waiting for transfers to finish 2022/03/15 05:55:57 DEBUG : one: md5 = 06e6c8c134dabf7222fbe3641e269534 OK 2022/03/15 05:55:57 INFO : one: Copied (new) 2022/03/15 05:55:57 DEBUG : Waiting for deletions to finish 2022/03/15 05:55:58 INFO : three.txt.bak: Deleted 2022/03/15 05:55:59 INFO : three.txt: Moved (server-side) to: three.txt.bak 2022/03/15 05:55:59 INFO : three.txt: Moved into backup dir 2022/03/15 05:56:03 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2022/03/15 05:56:03 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" 2022/03/15 05:56:04 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "sk91qgsqfn0r271r2ehsaoc20c" 2022/03/15 05:56:04 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "qltcak2uaegtmcoa8vijdppbp8" 2022/03/15 05:56:04 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "sk91qgsqfn0r271r2ehsaoc20c" 2022/03/15 05:56:04 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "qltcak2uaegtmcoa8vijdppbp8" --- PASS: TestSyncBackupDirWithSuffix (29.32s) === RUN TestSyncBackupDirWithSuffixKeepExtension run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5'", Local "Local file system at /tmp/rclone267558022", Modify Window "1ms" 2022/03/15 05:56:07 DEBUG : dst/one: md5 = b43648e683bb86142b814cc28d54f804 OK 2022/03/15 05:56:09 DEBUG : dst/two: md5 = 64be361c4eb81a84b2eba85bb4c202db OK 2022/03/15 05:56:11 DEBUG : dst/three.txt: md5 = 11d84bb2a2a50a447e8e9da2874bbab2 OK 2022/03/15 05:56:11 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5/dst" 2022/03/15 05:56:11 DEBUG : Creating backend with remote "TestDrive:crypt/728kds3mq75c78rvf3qlm1l12dibr01rft25rdpgmiklo90h7o08uece3pjg2bd6dr2evim9rfch0/31u3jie661vd5p8j7rtc3hgbh0" 2022/03/15 05:56:12 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5/backup" 2022/03/15 05:56:12 DEBUG : Creating backend with remote "TestDrive:crypt/728kds3mq75c78rvf3qlm1l12dibr01rft25rdpgmiklo90h7o08uece3pjg2bd6dr2evim9rfch0/1nrff024r7pq65ecp72fc28jb0" 2022/03/15 05:56:15 DEBUG : one: Sizes differ (src 4 vs dst 3) 2022/03/15 05:56:15 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/15 05:56:15 DEBUG : two: Unchanged skipping 2022/03/15 05:56:15 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5/dst': Waiting for checks to finish 2022/03/15 05:56:17 INFO : one: Moved (server-side) to: one-2019-01-01 2022/03/15 05:56:17 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5/dst': Waiting for transfers to finish 2022/03/15 05:56:19 DEBUG : one: md5 = fe4fe070f6bd9afeab0191988cafe3bb OK 2022/03/15 05:56:19 INFO : one: Copied (new) 2022/03/15 05:56:19 DEBUG : Waiting for deletions to finish 2022/03/15 05:56:20 INFO : three.txt: Moved (server-side) to: three-2019-01-01.txt 2022/03/15 05:56:20 INFO : three.txt: Moved into backup dir 2022/03/15 05:56:22 DEBUG : dst/three.txt: md5 = e80c53edeefe65630060036ca0537211 OK 2022/03/15 05:56:23 DEBUG : one: Sizes differ (src 5 vs dst 4) 2022/03/15 05:56:23 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5/dst': Waiting for checks to finish 2022/03/15 05:56:23 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/15 05:56:23 DEBUG : two: Unchanged skipping 2022/03/15 05:56:24 INFO : one-2019-01-01: Deleted 2022/03/15 05:56:25 INFO : one: Moved (server-side) to: one-2019-01-01 2022/03/15 05:56:25 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5/dst': Waiting for transfers to finish 2022/03/15 05:56:27 DEBUG : one: md5 = 46fddbfe42d980ee89df727d4e6e258a OK 2022/03/15 05:56:27 INFO : one: Copied (new) 2022/03/15 05:56:27 DEBUG : Waiting for deletions to finish 2022/03/15 05:56:28 INFO : three-2019-01-01.txt: Deleted 2022/03/15 05:56:29 INFO : three.txt: Moved (server-side) to: three-2019-01-01.txt 2022/03/15 05:56:29 INFO : three.txt: Moved into backup dir 2022/03/15 05:56:33 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2022/03/15 05:56:33 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" 2022/03/15 05:56:34 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "jcjl1bv3ep0v8kt35lqql1co90" 2022/03/15 05:56:34 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "qtq2f6qq4lgpsmj88vb7147qje3prudmtfdtr2342fth58vo9a50" 2022/03/15 05:56:34 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "jcjl1bv3ep0v8kt35lqql1co90" 2022/03/15 05:56:34 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "qtq2f6qq4lgpsmj88vb7147qje3prudmtfdtr2342fth58vo9a50" --- PASS: TestSyncBackupDirWithSuffixKeepExtension (30.56s) === RUN TestSyncBackupDirSuffixOnly run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5'", Local "Local file system at /tmp/rclone267558022", Modify Window "1ms" 2022/03/15 05:56:38 DEBUG : dst/one: md5 = 745eaee12942bfe79153f8dd4ad700bc OK 2022/03/15 05:56:39 DEBUG : dst/two: md5 = 287dcec7aeb96431e03109be4ccd1753 OK 2022/03/15 05:56:41 DEBUG : dst/three.txt: md5 = 575ab3650c0ac415b4a6e37d95d8ecbf OK 2022/03/15 05:56:42 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5/dst" 2022/03/15 05:56:42 DEBUG : Creating backend with remote "TestDrive:crypt/728kds3mq75c78rvf3qlm1l12dibr01rft25rdpgmiklo90h7o08uece3pjg2bd6dr2evim9rfch0/31u3jie661vd5p8j7rtc3hgbh0" 2022/03/15 05:56:43 DEBUG : one: Sizes differ (src 4 vs dst 3) 2022/03/15 05:56:43 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/15 05:56:43 DEBUG : two: Unchanged skipping 2022/03/15 05:56:43 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5/dst': Waiting for checks to finish 2022/03/15 05:56:44 INFO : one: Moved (server-side) to: one.bak 2022/03/15 05:56:44 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5/dst': Waiting for transfers to finish 2022/03/15 05:56:45 DEBUG : one: md5 = 578b3a2005001d9891d76da521c60069 OK 2022/03/15 05:56:45 INFO : one: Copied (new) 2022/03/15 05:56:45 DEBUG : Waiting for deletions to finish 2022/03/15 05:56:46 INFO : three.txt: Moved (server-side) to: three.txt.bak 2022/03/15 05:56:46 INFO : three.txt: Moved into backup dir 2022/03/15 05:56:49 DEBUG : dst/three.txt: md5 = ded0bc6904703983040b8527d50393a1 OK 2022/03/15 05:56:50 DEBUG : one.bak: Excluded from sync (and deletion) 2022/03/15 05:56:50 DEBUG : three.txt.bak: Excluded from sync (and deletion) 2022/03/15 05:56:50 DEBUG : one: Sizes differ (src 5 vs dst 4) 2022/03/15 05:56:50 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/15 05:56:50 DEBUG : two: Unchanged skipping 2022/03/15 05:56:50 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5/dst': Waiting for checks to finish 2022/03/15 05:56:51 INFO : one.bak: Deleted 2022/03/15 05:56:51 INFO : one: Moved (server-side) to: one.bak 2022/03/15 05:56:51 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5/dst': Waiting for transfers to finish 2022/03/15 05:56:53 DEBUG : one: md5 = 3356cf817da15bbdb33abd3b28130696 OK 2022/03/15 05:56:53 INFO : one: Copied (new) 2022/03/15 05:56:53 DEBUG : Waiting for deletions to finish 2022/03/15 05:56:54 INFO : three.txt.bak: Deleted 2022/03/15 05:56:55 INFO : three.txt: Moved (server-side) to: three.txt.bak 2022/03/15 05:56:55 INFO : three.txt: Moved into backup dir 2022/03/15 05:56:59 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2022/03/15 05:56:59 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "sk91qgsqfn0r271r2ehsaoc20c" 2022/03/15 05:56:59 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "qltcak2uaegtmcoa8vijdppbp8" 2022/03/15 05:56:59 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "qltcak2uaegtmcoa8vijdppbp8" 2022/03/15 05:56:59 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" 2022/03/15 05:56:59 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "sk91qgsqfn0r271r2ehsaoc20c" --- PASS: TestSyncBackupDirSuffixOnly (24.85s) === RUN TestSyncSuffix run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5'", Local "Local file system at /tmp/rclone267558022", Modify Window "1ms" 2022/03/15 05:57:03 DEBUG : dst/one: md5 = ea16fc64d93f8a19260bac148b379b14 OK 2022/03/15 05:57:04 DEBUG : dst/two: md5 = 2bc29bb9931e7722915078a15e570f7d OK 2022/03/15 05:57:06 DEBUG : dst/three.txt: md5 = 3e98e77a3671ccc88324b93a60d54be5 OK 2022/03/15 05:57:07 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5/dst" 2022/03/15 05:57:07 DEBUG : Creating backend with remote "TestDrive:crypt/728kds3mq75c78rvf3qlm1l12dibr01rft25rdpgmiklo90h7o08uece3pjg2bd6dr2evim9rfch0/31u3jie661vd5p8j7rtc3hgbh0" 2022/03/15 05:57:08 DEBUG : one: Sizes differ (src 4 vs dst 3) 2022/03/15 05:57:09 INFO : one: Moved (server-side) to: one.bak 2022/03/15 05:57:10 DEBUG : one: md5 = d4a6bb36bdfbc860fe1c29c3b8cc476d OK 2022/03/15 05:57:10 INFO : one: Copied (new) 2022/03/15 05:57:11 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/15 05:57:11 DEBUG : two: Unchanged skipping 2022/03/15 05:57:11 DEBUG : three.txt: Sizes differ (src 6 vs dst 5) 2022/03/15 05:57:12 INFO : three.txt: Moved (server-side) to: three.txt.bak 2022/03/15 05:57:13 DEBUG : three.txt: md5 = b977c01b329ef38d02b6f4d84d0d4988 OK 2022/03/15 05:57:13 INFO : three.txt: Copied (new) 2022/03/15 05:57:15 DEBUG : one: Sizes differ (src 5 vs dst 4) 2022/03/15 05:57:16 INFO : one.bak: Deleted 2022/03/15 05:57:17 INFO : one: Moved (server-side) to: one.bak 2022/03/15 05:57:18 DEBUG : one: md5 = d907550a8e166bcabfd18e89f1f91223 OK 2022/03/15 05:57:18 INFO : one: Copied (new) 2022/03/15 05:57:19 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/15 05:57:19 DEBUG : two: Unchanged skipping 2022/03/15 05:57:19 DEBUG : three.txt: Sizes differ (src 19 vs dst 6) 2022/03/15 05:57:20 INFO : three.txt.bak: Deleted 2022/03/15 05:57:20 INFO : three.txt: Moved (server-side) to: three.txt.bak 2022/03/15 05:57:22 DEBUG : three.txt: md5 = 6469efc671f20e640ac96e6ed0e81cfd OK 2022/03/15 05:57:22 INFO : three.txt: Copied (new) 2022/03/15 05:57:27 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2022/03/15 05:57:27 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "tr2hj63d80ftlmvm6a952snjcc" 2022/03/15 05:57:27 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "qltcak2uaegtmcoa8vijdppbp8" 2022/03/15 05:57:27 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "sk91qgsqfn0r271r2ehsaoc20c" 2022/03/15 05:57:27 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" 2022/03/15 05:57:27 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "sk91qgsqfn0r271r2ehsaoc20c" 2022/03/15 05:57:27 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "qltcak2uaegtmcoa8vijdppbp8" --- PASS: TestSyncSuffix (28.03s) === RUN TestSyncSuffixKeepExtension run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5'", Local "Local file system at /tmp/rclone267558022", Modify Window "1ms" 2022/03/15 05:57:31 DEBUG : dst/one: md5 = ea431909ec43d57d0204100002efa47c OK 2022/03/15 05:57:32 DEBUG : dst/two: md5 = e35e29f570bb6f2379187365ed042d18 OK 2022/03/15 05:57:34 DEBUG : dst/three.txt: md5 = 80353a88d94b209d6e22a17e28d1d5d6 OK 2022/03/15 05:57:34 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5/dst" 2022/03/15 05:57:34 DEBUG : Creating backend with remote "TestDrive:crypt/728kds3mq75c78rvf3qlm1l12dibr01rft25rdpgmiklo90h7o08uece3pjg2bd6dr2evim9rfch0/31u3jie661vd5p8j7rtc3hgbh0" 2022/03/15 05:57:36 DEBUG : one: Sizes differ (src 4 vs dst 3) 2022/03/15 05:57:36 INFO : one: Moved (server-side) to: one-2019-01-01 2022/03/15 05:57:38 DEBUG : one: md5 = 4846c9d7c52aa40703ab66e7084d61dc OK 2022/03/15 05:57:38 INFO : one: Copied (new) 2022/03/15 05:57:38 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/15 05:57:38 DEBUG : two: Unchanged skipping 2022/03/15 05:57:39 DEBUG : three.txt: Sizes differ (src 6 vs dst 5) 2022/03/15 05:57:40 INFO : three.txt: Moved (server-side) to: three-2019-01-01.txt 2022/03/15 05:57:41 DEBUG : three.txt: md5 = c19f76f775bd0d7feb7d033d979a809e OK 2022/03/15 05:57:41 INFO : three.txt: Copied (new) 2022/03/15 05:57:43 DEBUG : one: Sizes differ (src 5 vs dst 4) 2022/03/15 05:57:44 INFO : one-2019-01-01: Deleted 2022/03/15 05:57:44 INFO : one: Moved (server-side) to: one-2019-01-01 2022/03/15 05:57:46 DEBUG : one: md5 = 7bf8fcb32a8bc9157b2f865c487a8184 OK 2022/03/15 05:57:46 INFO : one: Copied (new) 2022/03/15 05:57:46 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/15 05:57:46 DEBUG : two: Unchanged skipping 2022/03/15 05:57:46 DEBUG : three.txt: Sizes differ (src 19 vs dst 6) 2022/03/15 05:57:47 INFO : three-2019-01-01.txt: Deleted 2022/03/15 05:57:48 INFO : three.txt: Moved (server-side) to: three-2019-01-01.txt 2022/03/15 05:57:50 DEBUG : three.txt: md5 = b6c3b5d4d472d2b4ca7cd896440c69fc OK 2022/03/15 05:57:50 INFO : three.txt: Copied (new) 2022/03/15 05:57:55 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2022/03/15 05:57:55 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "tr2hj63d80ftlmvm6a952snjcc" 2022/03/15 05:57:55 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "jcjl1bv3ep0v8kt35lqql1co90" 2022/03/15 05:57:55 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "qtq2f6qq4lgpsmj88vb7147qje3prudmtfdtr2342fth58vo9a50" 2022/03/15 05:57:55 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "qtq2f6qq4lgpsmj88vb7147qje3prudmtfdtr2342fth58vo9a50" 2022/03/15 05:57:55 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "jcjl1bv3ep0v8kt35lqql1co90" 2022/03/15 05:57:55 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" --- PASS: TestSyncSuffixKeepExtension (27.55s) === RUN TestSyncUTFNorm run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5'", Local "Local file system at /tmp/rclone267558022", Modify Window "1ms" 2022/03/15 05:57:58 DEBUG : Testêé: md5 = 22b3d4ebd2280d0b769ac6ddbb7b224a OK 2022/03/15 05:57:58 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for checks to finish 2022/03/15 05:57:58 DEBUG : Testêé: Sizes differ (src 14 vs dst 18) 2022/03/15 05:57:58 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for transfers to finish 2022/03/15 05:57:59 DEBUG : Testêé: md5 = e36df8898266e1f0f2c1a3105601fdcd OK 2022/03/15 05:57:59 INFO : Testêé: Copied (replaced existing) 2022/03/15 05:57:59 DEBUG : Waiting for deletions to finish --- PASS: TestSyncUTFNorm (5.30s) === RUN TestSyncImmutable run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5'", Local "Local file system at /tmp/rclone267558022", Modify Window "1ms" 2022/03/15 05:58:02 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for checks to finish 2022/03/15 05:58:02 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for transfers to finish 2022/03/15 05:58:03 DEBUG : existing: md5 = 01ccbb4b0b8ee639388ce1d46b5391eb OK 2022/03/15 05:58:03 INFO : existing: Copied (new) 2022/03/15 05:58:03 DEBUG : Waiting for deletions to finish 2022/03/15 05:58:04 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for checks to finish 2022/03/15 05:58:04 DEBUG : existing: Sizes differ (src 8 vs dst 6) 2022/03/15 05:58:04 ERROR : existing: Source and destination exist but do not match: immutable file modified 2022/03/15 05:58:04 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for transfers to finish 2022/03/15 05:58:04 ERROR : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': not deleting files as there were IO errors 2022/03/15 05:58:04 ERROR : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': not deleting directories as there were IO errors --- PASS: TestSyncImmutable (4.68s) === RUN TestSyncIgnoreCase run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5'", Local "Local file system at /tmp/rclone267558022", Modify Window "1ms" 2022/03/15 05:58:07 DEBUG : EXISTING: md5 = 49a4b79ba8ddf02b1c3babf2f7709fe2 OK 2022/03/15 05:58:08 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for checks to finish 2022/03/15 05:58:08 DEBUG : existing: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/15 05:58:08 DEBUG : existing: Unchanged skipping 2022/03/15 05:58:08 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for transfers to finish 2022/03/15 05:58:08 DEBUG : Waiting for deletions to finish 2022/03/15 05:58:08 INFO : There was nothing to transfer --- PASS: TestSyncIgnoreCase (3.87s) === RUN TestMaxTransfer === RUN TestMaxTransfer/Hard run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5'", Local "Local file system at /tmp/rclone267558022", Modify Window "1ms" sync_test.go:1989: This test only runs on local === RUN TestMaxTransfer/Soft run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5'", Local "Local file system at /tmp/rclone267558022", Modify Window "1ms" sync_test.go:1989: This test only runs on local === RUN TestMaxTransfer/Cautious run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5'", Local "Local file system at /tmp/rclone267558022", Modify Window "1ms" sync_test.go:1989: This test only runs on local --- PASS: TestMaxTransfer (1.57s) --- SKIP: TestMaxTransfer/Hard (0.52s) --- SKIP: TestMaxTransfer/Soft (0.51s) --- SKIP: TestMaxTransfer/Cautious (0.54s) === RUN TestSyncConcurrentDelete run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5'", Local "Local file system at /tmp/rclone267558022", Modify Window "1ms" 2022/03/15 05:58:13 DEBUG : both0: md5 = 065d48dbdc6b1de2bf27815f2bd1cbcd OK 2022/03/15 05:58:14 DEBUG : only0: md5 = 4c97cdbc31e16ec6f2642d27ff96c2b2 OK 2022/03/15 05:58:16 DEBUG : both1: md5 = c583aa32ad1f6054de7d6e077d7022f9 OK 2022/03/15 05:58:17 DEBUG : only1: md5 = 1d510e6d4ac83815bc1f63e3f815c6b3 OK 2022/03/15 05:58:19 DEBUG : both2: md5 = c2d433897af3ac00d9cf0a6817239706 OK 2022/03/15 05:58:20 DEBUG : only2: md5 = 4055263c888cb085f018b19bf1bbb3f0 OK 2022/03/15 05:58:22 DEBUG : both3: md5 = e3256f922966431d566485e0e293e973 OK 2022/03/15 05:58:23 DEBUG : only3: md5 = 81241d2cfe3a2e388b62ca7c9ccd13e7 OK 2022/03/15 05:58:25 DEBUG : both4: md5 = 9ef98b7e754adbce37fd1b876892f5fb OK 2022/03/15 05:58:26 DEBUG : only4: md5 = eef193957f0d95de215ca45fb42deb4e OK 2022/03/15 05:58:28 DEBUG : both5: md5 = 46df1ae8add63160e6801d6f16f7547c OK 2022/03/15 05:58:29 DEBUG : only5: md5 = 8bad369befa11dcbc018d55a6a034d18 OK 2022/03/15 05:58:31 DEBUG : both6: md5 = f3301e5139a7be4be5c31619f9270bad OK 2022/03/15 05:58:32 DEBUG : only6: md5 = a06dac34fad8d299e7ac7dee968924a3 OK 2022/03/15 05:58:34 DEBUG : both7: md5 = 2881afdf97771cf7ee77091b41f4366f OK 2022/03/15 05:58:35 DEBUG : only7: md5 = 9cd8caed8a21c795088ca1d3883e46a5 OK 2022/03/15 05:58:37 DEBUG : both8: md5 = 5e6ca834d9c226bdbfcd8871e17ab291 OK 2022/03/15 05:58:38 DEBUG : only8: md5 = 46694798c7c3b89b4c8d87b01249b706 OK 2022/03/15 05:58:40 DEBUG : both9: md5 = 8f9590e627995d7cbc7c1f138b9dcedb OK 2022/03/15 05:58:41 DEBUG : only9: md5 = 26eeace86091ff6c2b707e3538896492 OK 2022/03/15 05:58:43 DEBUG : both10: md5 = f41ecca1dcde216d15934b880d60906f OK 2022/03/15 05:58:44 DEBUG : only10: md5 = 02cceffc1debb320504368ab91ec6e90 OK 2022/03/15 05:58:46 DEBUG : both11: md5 = a306e7775044dfeb94c5e92ffe319055 OK 2022/03/15 05:58:47 DEBUG : only11: md5 = 3c545d0a947e55abb8ae0c0fa1b2812d OK 2022/03/15 05:58:49 DEBUG : both12: md5 = e21ceef780856effd5d084118b716629 OK 2022/03/15 05:58:50 DEBUG : only12: md5 = 9729b5a4016d6119980cdb24643c1e84 OK 2022/03/15 05:58:52 DEBUG : both13: md5 = 239cccc61918eff60789cf0c75fb7403 OK 2022/03/15 05:58:53 DEBUG : only13: md5 = 12f83061ae0c042f4a4ca6a23c51da67 OK 2022/03/15 05:58:55 DEBUG : both14: md5 = 09ca5738110c0d2085e8aa7ff50ba38c OK 2022/03/15 05:58:56 DEBUG : only14: md5 = b788ff5f7db987b62b85268875050d37 OK 2022/03/15 05:58:58 DEBUG : both15: md5 = 4ca69fff266f20d15549f9ad4f6d7ed1 OK 2022/03/15 05:58:59 DEBUG : only15: md5 = 3fdcabf3495037636c4ac2ce371e3416 OK 2022/03/15 05:59:01 DEBUG : both16: md5 = a1e99b82d638166968bc7a03ad63559e OK 2022/03/15 05:59:02 DEBUG : only16: md5 = 4cb861e67a7958114c41739915485734 OK 2022/03/15 05:59:04 DEBUG : both17: md5 = 138f6fbe841744da10c028ce58f2a229 OK 2022/03/15 05:59:05 DEBUG : only17: md5 = f48626af43527f7030164a76bd414f01 OK 2022/03/15 05:59:07 DEBUG : both18: md5 = b20172f06262e7fc27a2fe0855d548fd OK 2022/03/15 05:59:08 DEBUG : only18: md5 = fb3b0b88536df4541bfbc8bb567a3783 OK 2022/03/15 05:59:10 DEBUG : both19: md5 = 7a2329278eac83c73fb747eceeff23fb OK 2022/03/15 05:59:11 DEBUG : only19: md5 = a3962b1c166336ab6a57f790270901e3 OK 2022/03/15 05:59:12 DEBUG : both0: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/15 05:59:12 DEBUG : both0: Unchanged skipping 2022/03/15 05:59:12 DEBUG : both1: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/15 05:59:12 DEBUG : both1: Unchanged skipping 2022/03/15 05:59:12 DEBUG : both10: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/15 05:59:12 DEBUG : both10: Unchanged skipping 2022/03/15 05:59:12 DEBUG : both11: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/15 05:59:12 DEBUG : both11: Unchanged skipping 2022/03/15 05:59:12 DEBUG : both12: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/15 05:59:12 DEBUG : both12: Unchanged skipping 2022/03/15 05:59:12 DEBUG : both13: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/15 05:59:12 DEBUG : both13: Unchanged skipping 2022/03/15 05:59:12 DEBUG : both14: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/15 05:59:12 DEBUG : both14: Unchanged skipping 2022/03/15 05:59:12 DEBUG : both15: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/15 05:59:12 DEBUG : both15: Unchanged skipping 2022/03/15 05:59:12 DEBUG : both16: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/15 05:59:12 DEBUG : both16: Unchanged skipping 2022/03/15 05:59:12 DEBUG : both17: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/15 05:59:12 DEBUG : both17: Unchanged skipping 2022/03/15 05:59:12 DEBUG : both18: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/15 05:59:12 DEBUG : both18: Unchanged skipping 2022/03/15 05:59:12 DEBUG : both19: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/15 05:59:12 DEBUG : both19: Unchanged skipping 2022/03/15 05:59:12 DEBUG : both2: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/15 05:59:12 DEBUG : both2: Unchanged skipping 2022/03/15 05:59:12 DEBUG : both3: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/15 05:59:12 DEBUG : both3: Unchanged skipping 2022/03/15 05:59:12 DEBUG : both4: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/15 05:59:12 DEBUG : both4: Unchanged skipping 2022/03/15 05:59:12 DEBUG : both5: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/15 05:59:12 DEBUG : both5: Unchanged skipping 2022/03/15 05:59:12 DEBUG : both6: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/15 05:59:12 DEBUG : both6: Unchanged skipping 2022/03/15 05:59:12 DEBUG : both7: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/15 05:59:12 DEBUG : both7: Unchanged skipping 2022/03/15 05:59:12 DEBUG : both8: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/15 05:59:12 DEBUG : both8: Unchanged skipping 2022/03/15 05:59:12 DEBUG : both9: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/15 05:59:12 DEBUG : both9: Unchanged skipping 2022/03/15 05:59:12 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for checks to finish 2022/03/15 05:59:12 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for transfers to finish 2022/03/15 05:59:12 DEBUG : Waiting for deletions to finish 2022/03/15 05:59:13 INFO : only10: Deleted 2022/03/15 05:59:13 INFO : only5: Deleted 2022/03/15 05:59:13 INFO : only3: Deleted 2022/03/15 05:59:13 INFO : only16: Deleted 2022/03/15 05:59:13 INFO : only19: Deleted 2022/03/15 05:59:14 INFO : only6: Deleted 2022/03/15 05:59:14 INFO : only14: Deleted 2022/03/15 05:59:14 INFO : only15: Deleted 2022/03/15 05:59:14 INFO : only18: Deleted 2022/03/15 05:59:14 INFO : only4: Deleted 2022/03/15 05:59:14 INFO : only7: Deleted 2022/03/15 05:59:14 INFO : only8: Deleted 2022/03/15 05:59:15 INFO : only1: Deleted 2022/03/15 05:59:15 INFO : only13: Deleted 2022/03/15 05:59:15 INFO : only17: Deleted 2022/03/15 05:59:15 INFO : only12: Deleted 2022/03/15 05:59:16 INFO : only2: Deleted 2022/03/15 05:59:16 INFO : only9: Deleted 2022/03/15 05:59:16 INFO : only0: Deleted 2022/03/15 05:59:16 INFO : only11: Deleted 2022/03/15 05:59:16 INFO : There was nothing to transfer --- PASS: TestSyncConcurrentDelete (79.50s) === RUN TestSyncConcurrentTruncate run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5'", Local "Local file system at /tmp/rclone267558022", Modify Window "1ms" 2022/03/15 05:59:32 DEBUG : both0: md5 = 62c1d1d7760dda575aa28cd847a9b9e6 OK 2022/03/15 05:59:34 DEBUG : only0: md5 = f844657b137fb31c313dd3ce013873ff OK 2022/03/15 05:59:35 DEBUG : both1: md5 = cc7336bb82272f8ca655e1fb4f9cadfa OK 2022/03/15 05:59:37 DEBUG : only1: md5 = 58860d9cfd3e4bb77465cf8c931f1590 OK 2022/03/15 05:59:38 DEBUG : both2: md5 = aa8fa4eae475c26952688bd27193a4f6 OK 2022/03/15 05:59:40 DEBUG : only2: md5 = 6a613975bba1fd1e10a34eb57c06b278 OK 2022/03/15 05:59:41 DEBUG : both3: md5 = 166a93d7a96ef24977abad7ca43fa54e OK 2022/03/15 05:59:43 DEBUG : only3: md5 = 46f037a5a1d208e06ebe2be73a811a93 OK 2022/03/15 05:59:44 DEBUG : both4: md5 = df13ff9d924a916c29a29662bd5e010d OK 2022/03/15 05:59:46 DEBUG : only4: md5 = 70876b08d9b58e72af4c8112679caa6f OK 2022/03/15 05:59:47 DEBUG : both5: md5 = e4971e13c47994d82eb4a9f52a9eee18 OK 2022/03/15 05:59:49 DEBUG : only5: md5 = f8369e3dfa2afb7d138350e5ce14ad3d OK 2022/03/15 05:59:50 DEBUG : both6: md5 = 73589107919c0f96de0f890854448391 OK 2022/03/15 05:59:52 DEBUG : only6: md5 = 73a17bf1fdc4f093a411b635edf1e73a OK 2022/03/15 05:59:53 DEBUG : both7: md5 = 62d0f5ef21205495106c18db94e2fe0c OK 2022/03/15 05:59:55 DEBUG : only7: md5 = 2560027b725d7919175b531bd3398a53 OK 2022/03/15 05:59:56 DEBUG : both8: md5 = 6bd323b247000cb2c65a5f2641f7bea2 OK 2022/03/15 05:59:58 DEBUG : only8: md5 = 17671e217eb95e723513ea4d018091da OK 2022/03/15 05:59:59 DEBUG : both9: md5 = f3ffa2299cbc8c6f9ab0a8378bea19dd OK 2022/03/15 06:00:01 DEBUG : only9: md5 = e547bc24ce5eb486848715b47a895e7c OK 2022/03/15 06:00:02 DEBUG : both10: md5 = 26e072a72dada19b113506ed6435ebc2 OK 2022/03/15 06:00:03 DEBUG : only10: md5 = 7b96ac785533fdb8c4b5f18b67f60f3a OK 2022/03/15 06:00:05 DEBUG : both11: md5 = eb0f262dc8c8e0ddd0df5a4a4eddd64e OK 2022/03/15 06:00:06 DEBUG : only11: md5 = 5aab0dc2fb8a6790221ce50250642ea1 OK 2022/03/15 06:00:08 DEBUG : both12: md5 = 5172bf3c9599af7f86e6e1465091f6a4 OK 2022/03/15 06:00:09 DEBUG : only12: md5 = 65fa96150e3357a007187593cd092cff OK 2022/03/15 06:00:11 DEBUG : both13: md5 = 3189e9d897291586cbf9ea6eeedbf393 OK 2022/03/15 06:00:11 DEBUG : Config file has changed externaly - reloading 2022/03/15 06:00:11 DEBUG : TestDrive: Loaded invalid token from config file - ignoring 2022/03/15 06:00:11 DEBUG : Saving config "token" in section "TestDrive" of the config file 2022/03/15 06:00:11 DEBUG : TestDrive: Saved new token in config file 2022/03/15 06:00:12 DEBUG : only13: md5 = 33f0750a37963824f343d7cdef038ac6 OK 2022/03/15 06:00:14 DEBUG : both14: md5 = 8eda4e1d73c8f29b46f5fdcf0d99f759 OK 2022/03/15 06:00:15 DEBUG : only14: md5 = baa231221bd7345e01aac4a67a5fa1d5 OK 2022/03/15 06:00:17 DEBUG : both15: md5 = b75a3e6b97a577791afded2ea7100561 OK 2022/03/15 06:00:19 DEBUG : only15: md5 = a2280b3e016aa3c685a4f6627bd67194 OK 2022/03/15 06:00:20 DEBUG : both16: md5 = 0ac4a7300789d7c9135cdb1187becfa4 OK 2022/03/15 06:00:22 DEBUG : only16: md5 = 6acebce4e3d487a08191a3701b7f5ca2 OK 2022/03/15 06:00:24 DEBUG : both17: md5 = e4a1d6081892483078a0328aa7d61241 OK 2022/03/15 06:00:25 DEBUG : only17: md5 = cd18acb48861e29e4c61e6c7aa345452 OK 2022/03/15 06:00:27 DEBUG : both18: md5 = 5270f24aadafab64fac5ec2cad820092 OK 2022/03/15 06:00:28 DEBUG : only18: md5 = 4821f5f4dfcfd92af0fc40ee939dada6 OK 2022/03/15 06:00:30 DEBUG : both19: md5 = 845f2401ec71167a3bf21c509763fb22 OK 2022/03/15 06:00:31 DEBUG : only19: md5 = 5b03b233cbf482552f7ab4cd8ae50ff8 OK 2022/03/15 06:00:32 DEBUG : both0: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/15 06:00:32 DEBUG : both0: Unchanged skipping 2022/03/15 06:00:32 DEBUG : both1: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/15 06:00:32 DEBUG : both1: Unchanged skipping 2022/03/15 06:00:32 DEBUG : both10: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/15 06:00:32 DEBUG : both10: Unchanged skipping 2022/03/15 06:00:32 DEBUG : both11: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/15 06:00:32 DEBUG : both11: Unchanged skipping 2022/03/15 06:00:32 DEBUG : both12: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/15 06:00:32 DEBUG : both12: Unchanged skipping 2022/03/15 06:00:32 DEBUG : both13: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/15 06:00:32 DEBUG : both13: Unchanged skipping 2022/03/15 06:00:32 DEBUG : both14: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/15 06:00:32 DEBUG : both14: Unchanged skipping 2022/03/15 06:00:32 DEBUG : both15: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/15 06:00:32 DEBUG : both15: Unchanged skipping 2022/03/15 06:00:32 DEBUG : both16: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/15 06:00:32 DEBUG : both16: Unchanged skipping 2022/03/15 06:00:32 DEBUG : both17: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/15 06:00:32 DEBUG : both17: Unchanged skipping 2022/03/15 06:00:32 DEBUG : both18: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/15 06:00:32 DEBUG : both18: Unchanged skipping 2022/03/15 06:00:32 DEBUG : both19: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/15 06:00:32 DEBUG : both19: Unchanged skipping 2022/03/15 06:00:32 DEBUG : both2: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/15 06:00:32 DEBUG : both2: Unchanged skipping 2022/03/15 06:00:32 DEBUG : both6: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/15 06:00:32 DEBUG : both6: Unchanged skipping 2022/03/15 06:00:32 DEBUG : both7: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/15 06:00:32 DEBUG : both7: Unchanged skipping 2022/03/15 06:00:32 DEBUG : both8: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/15 06:00:32 DEBUG : both3: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/15 06:00:32 DEBUG : both8: Unchanged skipping 2022/03/15 06:00:32 DEBUG : both9: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/15 06:00:32 DEBUG : both3: Unchanged skipping 2022/03/15 06:00:32 DEBUG : only0: Sizes differ (src 0 vs dst 6) 2022/03/15 06:00:32 DEBUG : only1: Sizes differ (src 0 vs dst 6) 2022/03/15 06:00:32 DEBUG : only10: Sizes differ (src 0 vs dst 6) 2022/03/15 06:00:32 DEBUG : only11: Sizes differ (src 0 vs dst 6) 2022/03/15 06:00:32 DEBUG : only12: Sizes differ (src 0 vs dst 6) 2022/03/15 06:00:32 DEBUG : only13: Sizes differ (src 0 vs dst 6) 2022/03/15 06:00:32 DEBUG : only14: Sizes differ (src 0 vs dst 6) 2022/03/15 06:00:32 DEBUG : only15: Sizes differ (src 0 vs dst 6) 2022/03/15 06:00:32 DEBUG : only16: Sizes differ (src 0 vs dst 6) 2022/03/15 06:00:32 DEBUG : only17: Sizes differ (src 0 vs dst 6) 2022/03/15 06:00:32 DEBUG : only18: Sizes differ (src 0 vs dst 6) 2022/03/15 06:00:32 DEBUG : only19: Sizes differ (src 0 vs dst 6) 2022/03/15 06:00:32 DEBUG : only2: Sizes differ (src 0 vs dst 6) 2022/03/15 06:00:32 DEBUG : only3: Sizes differ (src 0 vs dst 6) 2022/03/15 06:00:32 DEBUG : only4: Sizes differ (src 0 vs dst 6) 2022/03/15 06:00:32 DEBUG : only5: Sizes differ (src 0 vs dst 6) 2022/03/15 06:00:32 DEBUG : only6: Sizes differ (src 0 vs dst 6) 2022/03/15 06:00:32 DEBUG : only7: Sizes differ (src 0 vs dst 6) 2022/03/15 06:00:32 DEBUG : only8: Sizes differ (src 0 vs dst 6) 2022/03/15 06:00:32 DEBUG : only9: Sizes differ (src 0 vs dst 6) 2022/03/15 06:00:32 DEBUG : both9: Unchanged skipping 2022/03/15 06:00:32 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for checks to finish 2022/03/15 06:00:32 DEBUG : both5: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/15 06:00:32 DEBUG : both5: Unchanged skipping 2022/03/15 06:00:32 DEBUG : both4: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/15 06:00:32 DEBUG : both4: Unchanged skipping 2022/03/15 06:00:32 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Waiting for transfers to finish 2022/03/15 06:00:34 DEBUG : only0: md5 = f8cb2215eb09bd164ce4d0e1f3fb27f7 OK 2022/03/15 06:00:34 INFO : only0: Copied (replaced existing) 2022/03/15 06:00:34 DEBUG : only1: md5 = 60be50d505faef6dde5fc6420f2a5c82 OK 2022/03/15 06:00:34 INFO : only1: Copied (replaced existing) 2022/03/15 06:00:34 DEBUG : only11: md5 = 695a6522c9d5801b039534c938fd5af3 OK 2022/03/15 06:00:34 INFO : only11: Copied (replaced existing) 2022/03/15 06:00:34 DEBUG : only10: md5 = 20222573e93ebc0227eeeb74e3660a22 OK 2022/03/15 06:00:34 INFO : only10: Copied (replaced existing) 2022/03/15 06:00:35 DEBUG : only12: md5 = 5ecce90baa77e7abb63cd8e27fe4b7b7 OK 2022/03/15 06:00:35 INFO : only12: Copied (replaced existing) 2022/03/15 06:00:35 DEBUG : only13: md5 = 74d01874bd2b176fa1071575b9780156 OK 2022/03/15 06:00:35 INFO : only13: Copied (replaced existing) 2022/03/15 06:00:35 DEBUG : only14: md5 = e85a8a002f4b3cf0e239e298f1ac9923 OK 2022/03/15 06:00:35 INFO : only14: Copied (replaced existing) 2022/03/15 06:00:35 DEBUG : only15: md5 = ca0e28608a31844e7045f53d8f9ee865 OK 2022/03/15 06:00:35 INFO : only15: Copied (replaced existing) 2022/03/15 06:00:36 DEBUG : only16: md5 = 0d211ae61664c3830a8031d266477576 OK 2022/03/15 06:00:36 INFO : only16: Copied (replaced existing) 2022/03/15 06:00:36 DEBUG : only17: md5 = cbf0bf99d8368041d01a696147793f78 OK 2022/03/15 06:00:36 INFO : only17: Copied (replaced existing) 2022/03/15 06:00:36 DEBUG : only19: md5 = c09497f1164c2ae9514d82f0aec0e056 OK 2022/03/15 06:00:36 INFO : only19: Copied (replaced existing) 2022/03/15 06:00:36 DEBUG : only18: md5 = 51a4c29a5e4e628e536542f2ba4baf7d OK 2022/03/15 06:00:36 INFO : only18: Copied (replaced existing) 2022/03/15 06:00:37 DEBUG : only2: md5 = d0946cbca4c09601933a3d033cb779e8 OK 2022/03/15 06:00:37 INFO : only2: Copied (replaced existing) 2022/03/15 06:00:38 DEBUG : only3: md5 = 5a06bcd9c5f2124d5554ed6ae62eae6a OK 2022/03/15 06:00:38 INFO : only3: Copied (replaced existing) 2022/03/15 06:00:38 DEBUG : only5: md5 = d6813437142218705470bf8e5be97d7b OK 2022/03/15 06:00:38 INFO : only5: Copied (replaced existing) 2022/03/15 06:00:38 DEBUG : only4: md5 = 1e82137dfb33b4c61b13740d616bbd0a OK 2022/03/15 06:00:38 INFO : only4: Copied (replaced existing) 2022/03/15 06:00:39 DEBUG : only6: md5 = 010431df407b02c9f9d96d69467b5b8c OK 2022/03/15 06:00:39 INFO : only6: Copied (replaced existing) 2022/03/15 06:00:39 DEBUG : only7: md5 = 0a2861685847d2bf41bbde543125a006 OK 2022/03/15 06:00:39 INFO : only7: Copied (replaced existing) 2022/03/15 06:00:39 DEBUG : only8: md5 = 1335600b2d3619d001f4ddce74856b20 OK 2022/03/15 06:00:39 INFO : only8: Copied (replaced existing) 2022/03/15 06:00:39 DEBUG : only9: md5 = cf71945a85cb74c3017acecdd8d0664a OK 2022/03/15 06:00:39 INFO : only9: Copied (replaced existing) 2022/03/15 06:00:39 DEBUG : Waiting for deletions to finish --- PASS: TestSyncConcurrentTruncate (98.88s) PASS 2022/03/15 06:01:10 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuqiwon0vozopah6gipuvad5': Purge remote "./sync.test -test.v -test.timeout 1h0m0s -remote TestCryptDrive: -verbose -fast-list" - Finished OK in 13m22.835064277s (try 1/5)