"./sync.test -test.v -test.timeout 1h0m0s -remote TestCryptDrive: -verbose" - Starting (try 1/5) 2022/02/10 05:00:14 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7" 2022/02/10 05:00:14 DEBUG : Using config file from "/home/rclone/.rclone.conf" 2022/02/10 05:00:15 DEBUG : Creating backend with remote "TestDrive:crypt/mfah1qr4afpbqv8tfvs11nuv7150h8cq3888svjder49859i7b2d2jgq72hb2fsjp1r43m4c63dnc" 2022/02/10 05:00:15 DEBUG : Config file has changed externaly - reloading 2022/02/10 05:00:15 DEBUG : TestDrive: Loaded invalid token from config file - ignoring 2022/02/10 05:00:15 DEBUG : Config file has changed externaly - reloading 2022/02/10 05:00:15 DEBUG : Saving config "token" in section "TestDrive" of the config file 2022/02/10 05:00:15 DEBUG : TestDrive: Saved new token in config file 2022/02/10 05:00:17 DEBUG : Creating backend with remote "/tmp/rclone4068820260" === RUN TestPipe --- PASS: TestPipe (0.00s) === RUN TestPipeConcurrent --- PASS: TestPipeConcurrent (0.04s) === 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-tutitiw5bifilob4cahuyag7'", Local "Local file system at /tmp/rclone4068820260", Modify Window "1ms" 2022/02/10 05:00:19 NOTICE: sub dir/hello world: Skipped copy as --dry-run is set (size 11) 2022/02/10 05:00:19 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for checks to finish 2022/02/10 05:00:19 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for transfers to finish --- PASS: TestCopyWithDryRun (2.70s) === RUN TestCopy run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7'", Local "Local file system at /tmp/rclone4068820260", Modify Window "1ms" 2022/02/10 05:00:20 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for checks to finish 2022/02/10 05:00:20 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for transfers to finish 2022/02/10 05:00:23 DEBUG : sub dir/hello world: md5 = ae0b884e72e7f2ee697aeeb8ba001cf2 OK 2022/02/10 05:00:23 INFO : sub dir/hello world: Copied (new) 2022/02/10 05:00:25 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestCopy (6.47s) === RUN TestCopyMissingDirectory run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7'", Local "Local file system at /tmp/rclone4068820260", Modify Window "1ms" 2022/02/10 05:00:26 DEBUG : Creating backend with remote "/non-existing" 2022/02/10 05:00:26 DEBUG : Config file has changed externaly - reloading 2022/02/10 05:00:27 ERROR : Local file system at /non-existing: error reading source root directory: directory not found 2022/02/10 05:00:27 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for checks to finish 2022/02/10 05:00:27 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for transfers to finish --- PASS: TestCopyMissingDirectory (0.80s) === RUN TestCopyNoTraverse run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7'", Local "Local file system at /tmp/rclone4068820260", Modify Window "1ms" 2022/02/10 05:00:27 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for checks to finish 2022/02/10 05:00:27 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for transfers to finish 2022/02/10 05:00:30 DEBUG : sub dir/hello world: md5 = f4de2bbde8f8f1f2a3ca33d35b6b1e0f OK 2022/02/10 05:00:30 INFO : sub dir/hello world: Copied (new) 2022/02/10 05:00:32 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestCopyNoTraverse (6.07s) === RUN TestCopyCheckFirst run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7'", Local "Local file system at /tmp/rclone4068820260", Modify Window "1ms" 2022/02/10 05:00:33 INFO : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Running all checks before starting transfers 2022/02/10 05:00:33 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for checks to finish 2022/02/10 05:00:33 INFO : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Checks finished, now starting transfers 2022/02/10 05:00:33 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for transfers to finish 2022/02/10 05:00:36 DEBUG : sub dir/hello world: md5 = c63b7c6b0cb242f3e9a971c3994612b7 OK 2022/02/10 05:00:36 INFO : sub dir/hello world: Copied (new) 2022/02/10 05:00:38 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestCopyCheckFirst (6.16s) === RUN TestSyncNoTraverse run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7'", Local "Local file system at /tmp/rclone4068820260", Modify Window "1ms" 2022/02/10 05:00:39 ERROR : Ignoring --no-traverse with sync 2022/02/10 05:00:40 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for checks to finish 2022/02/10 05:00:40 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for transfers to finish 2022/02/10 05:00:42 DEBUG : sub dir/hello world: md5 = 5106509d0c54907010db025ae9b1fe96 OK 2022/02/10 05:00:42 INFO : sub dir/hello world: Copied (new) 2022/02/10 05:00:42 DEBUG : Waiting for deletions to finish 2022/02/10 05:00:44 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestSyncNoTraverse (5.84s) === RUN TestCopyWithDepth run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7'", Local "Local file system at /tmp/rclone4068820260", Modify Window "1ms" 2022/02/10 05:00:45 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for checks to finish 2022/02/10 05:00:45 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for transfers to finish 2022/02/10 05:00:47 DEBUG : hello world2: md5 = 9ffc158408d9dfa749aff7ccd2b990ea OK 2022/02/10 05:00:47 INFO : hello world2: Copied (new) --- PASS: TestCopyWithDepth (3.32s) === RUN TestCopyWithFilesFrom run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7'", Local "Local file system at /tmp/rclone4068820260", Modify Window "1ms" 2022/02/10 05:00:49 DEBUG : hello world2: Excluded 2022/02/10 05:00:49 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for checks to finish 2022/02/10 05:00:49 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for transfers to finish 2022/02/10 05:00:50 DEBUG : potato2: md5 = 520270b12e99871444ed24a5e79159af OK 2022/02/10 05:00:50 INFO : potato2: Copied (new) --- PASS: TestCopyWithFilesFrom (3.26s) === RUN TestCopyWithFilesFromAndNoTraverse run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7'", Local "Local file system at /tmp/rclone4068820260", Modify Window "1ms" 2022/02/10 05:00:52 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for checks to finish 2022/02/10 05:00:52 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for transfers to finish 2022/02/10 05:00:53 DEBUG : potato2: md5 = 884da858f49b7cb0d41df69ac0ba92f6 OK 2022/02/10 05:00:53 INFO : potato2: Copied (new) --- PASS: TestCopyWithFilesFromAndNoTraverse (3.16s) === RUN TestCopyEmptyDirectories run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7'", Local "Local file system at /tmp/rclone4068820260", Modify Window "1ms" 2022/02/10 05:00:55 DEBUG : sub dir2: Making directory 2022/02/10 05:00:55 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for checks to finish 2022/02/10 05:00:55 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for transfers to finish 2022/02/10 05:00:58 DEBUG : sub dir/hello world: md5 = 5ec379e4ce25fe0ba9e36405644664a4 OK 2022/02/10 05:00:58 INFO : sub dir/hello world: Copied (new) 2022/02/10 05:00:58 DEBUG : sub dir2: Making directory 2022/02/10 05:00:59 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': copied 1 directories 2022/02/10 05:01:02 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestCopyEmptyDirectories (7.62s) === RUN TestMoveEmptyDirectories run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7'", Local "Local file system at /tmp/rclone4068820260", Modify Window "1ms" 2022/02/10 05:01:03 DEBUG : sub dir2: Making directory 2022/02/10 05:01:03 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for checks to finish 2022/02/10 05:01:03 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for transfers to finish 2022/02/10 05:01:05 DEBUG : sub dir/hello world: md5 = a602434f6dea0b347e3982c2c1d3ff6c OK 2022/02/10 05:01:05 INFO : sub dir/hello world: Copied (new) 2022/02/10 05:01:05 INFO : sub dir/hello world: Deleted 2022/02/10 05:01:05 DEBUG : sub dir: Making directory 2022/02/10 05:01:05 DEBUG : sub dir2: Making directory 2022/02/10 05:01:06 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': copied 2 directories 2022/02/10 05:01:09 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestMoveEmptyDirectories (7.56s) === RUN TestSyncEmptyDirectories run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7'", Local "Local file system at /tmp/rclone4068820260", Modify Window "1ms" 2022/02/10 05:01:10 DEBUG : sub dir2: Making directory 2022/02/10 05:01:10 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for checks to finish 2022/02/10 05:01:10 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for transfers to finish 2022/02/10 05:01:13 DEBUG : sub dir/hello world: md5 = bc816f95ffbb9b4cf393c0a3b72851aa OK 2022/02/10 05:01:13 INFO : sub dir/hello world: Copied (new) 2022/02/10 05:01:13 DEBUG : sub dir2: Making directory 2022/02/10 05:01:14 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': copied 1 directories 2022/02/10 05:01:14 DEBUG : Waiting for deletions to finish 2022/02/10 05:01:17 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestSyncEmptyDirectories (7.69s) === RUN TestServerSideCopy run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7'", Local "Local file system at /tmp/rclone4068820260", Modify Window "1ms" 2022/02/10 05:01:20 DEBUG : sub dir/hello world: md5 = 4f1156724a711ddfa212cfb3f89862ce OK 2022/02/10 05:01:21 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-nezuxiy6zenabam9gidiqol8" 2022/02/10 05:01:21 DEBUG : Creating backend with remote "TestDrive:crypt/hkhsifdo1tkq7p0adti42ipl4i0h74kku3pf3gal8konfu4rif00vug98g8au09pmhj99p8gatlho" sync_test.go:275: Server side copy (if possible) Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7' -> Encrypted drive 'TestCryptDrive:rclone-test-nezuxiy6zenabam9gidiqol8' 2022/02/10 05:01:23 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-nezuxiy6zenabam9gidiqol8': Waiting for checks to finish 2022/02/10 05:01:23 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-nezuxiy6zenabam9gidiqol8': Waiting for transfers to finish 2022/02/10 05:01:26 INFO : sub dir/hello world: Copied (server-side copy) 2022/02/10 05:01:27 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-nezuxiy6zenabam9gidiqol8': Purge remote 2022/02/10 05:01:29 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestServerSideCopy (12.04s) === RUN TestCopyAfterDelete run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7'", Local "Local file system at /tmp/rclone4068820260", Modify Window "1ms" 2022/02/10 05:01:33 DEBUG : sub dir/hello world: md5 = ffa0727d1a26e25aa774d1456794cc84 OK 2022/02/10 05:01:33 ERROR : : error listing: directory not found 2022/02/10 05:01:33 DEBUG : Local file system at /tmp/rclone4068820260: Making directory 2022/02/10 05:01:33 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for checks to finish 2022/02/10 05:01:33 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for transfers to finish 2022/02/10 05:01:36 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestCopyAfterDelete (6.60s) === RUN TestCopyRedownload run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7'", Local "Local file system at /tmp/rclone4068820260", Modify Window "1ms" 2022/02/10 05:01:39 DEBUG : sub dir/hello world: md5 = 329f488a44eacafe934f20cb3222af78 OK 2022/02/10 05:01:40 DEBUG : Local file system at /tmp/rclone4068820260: Waiting for checks to finish 2022/02/10 05:01:40 DEBUG : Local file system at /tmp/rclone4068820260: Waiting for transfers to finish 2022/02/10 05:01:41 INFO : sub dir/hello world: Copied (new) 2022/02/10 05:01:42 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestCopyRedownload (6.97s) === RUN TestSyncBasedOnCheckSum run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7'", Local "Local file system at /tmp/rclone4068820260", Modify Window "1ms" 2022/02/10 05:01:44 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for checks to finish 2022/02/10 05:01:44 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for transfers to finish 2022/02/10 05:01:45 DEBUG : check sum: md5 = a1746c5cbf717c500c406842098836f0 OK 2022/02/10 05:01:45 INFO : check sum: Copied (new) 2022/02/10 05:01:45 DEBUG : Waiting for deletions to finish 2022/02/10 05:01:46 NOTICE: Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': --checksum is in use but the source and destination have no hashes in common; falling back to --size-only 2022/02/10 05:01:46 DEBUG : check sum: Size of src and dst objects identical 2022/02/10 05:01:46 DEBUG : check sum: Unchanged skipping 2022/02/10 05:01:46 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for checks to finish 2022/02/10 05:01:46 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for transfers to finish 2022/02/10 05:01:46 DEBUG : Waiting for deletions to finish 2022/02/10 05:01:46 INFO : There was nothing to transfer --- PASS: TestSyncBasedOnCheckSum (3.88s) === RUN TestSyncSizeOnly run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7'", Local "Local file system at /tmp/rclone4068820260", Modify Window "1ms" 2022/02/10 05:01:48 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for checks to finish 2022/02/10 05:01:48 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for transfers to finish 2022/02/10 05:01:49 DEBUG : sizeonly: md5 = 3660e96e8bc01cf90f32dece978651b1 OK 2022/02/10 05:01:49 INFO : sizeonly: Copied (new) 2022/02/10 05:01:49 DEBUG : Waiting for deletions to finish 2022/02/10 05:01:50 DEBUG : sizeonly: Sizes identical 2022/02/10 05:01:50 DEBUG : sizeonly: Unchanged skipping 2022/02/10 05:01:50 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for checks to finish 2022/02/10 05:01:50 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for transfers to finish 2022/02/10 05:01:50 DEBUG : Waiting for deletions to finish 2022/02/10 05:01:50 INFO : There was nothing to transfer --- PASS: TestSyncSizeOnly (3.83s) === RUN TestSyncIgnoreSize run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7'", Local "Local file system at /tmp/rclone4068820260", Modify Window "1ms" 2022/02/10 05:01:51 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for checks to finish 2022/02/10 05:01:51 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for transfers to finish 2022/02/10 05:01:53 DEBUG : ignore-size: md5 = 1ff859c5aba1aa9540adef3a00009f09 OK 2022/02/10 05:01:53 INFO : ignore-size: Copied (new) 2022/02/10 05:01:53 DEBUG : Waiting for deletions to finish 2022/02/10 05:01:53 DEBUG : ignore-size: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/02/10 05:01:53 DEBUG : ignore-size: Unchanged skipping 2022/02/10 05:01:53 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for checks to finish 2022/02/10 05:01:53 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for transfers to finish 2022/02/10 05:01:53 DEBUG : Waiting for deletions to finish 2022/02/10 05:01:53 INFO : There was nothing to transfer --- PASS: TestSyncIgnoreSize (3.78s) === RUN TestSyncIgnoreTimes run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7'", Local "Local file system at /tmp/rclone4068820260", Modify Window "1ms" 2022/02/10 05:01:57 DEBUG : existing: md5 = eb1266c21b565beac8e24749dc12c811 OK 2022/02/10 05:01:57 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for checks to finish 2022/02/10 05:01:57 DEBUG : existing: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/02/10 05:01:57 DEBUG : existing: Unchanged skipping 2022/02/10 05:01:57 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for transfers to finish 2022/02/10 05:01:57 DEBUG : Waiting for deletions to finish 2022/02/10 05:01:57 INFO : There was nothing to transfer 2022/02/10 05:01:57 DEBUG : existing: Transferring unconditionally as --ignore-times is in use 2022/02/10 05:01:57 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for checks to finish 2022/02/10 05:01:57 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for transfers to finish 2022/02/10 05:01:59 DEBUG : existing: md5 = b5748e641390538d48359f414b229cea OK 2022/02/10 05:01:59 INFO : existing: Copied (replaced existing) 2022/02/10 05:01:59 DEBUG : Waiting for deletions to finish --- PASS: TestSyncIgnoreTimes (5.15s) === RUN TestSyncIgnoreExisting run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7'", Local "Local file system at /tmp/rclone4068820260", Modify Window "1ms" 2022/02/10 05:02:00 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for checks to finish 2022/02/10 05:02:00 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for transfers to finish 2022/02/10 05:02:02 DEBUG : existing: md5 = a4ae63896db25e9b22538a319ec3bc1c OK 2022/02/10 05:02:02 INFO : existing: Copied (new) 2022/02/10 05:02:02 DEBUG : Waiting for deletions to finish 2022/02/10 05:02:02 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for checks to finish 2022/02/10 05:02:02 DEBUG : existing: Destination exists, skipping 2022/02/10 05:02:02 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for transfers to finish 2022/02/10 05:02:02 DEBUG : Waiting for deletions to finish 2022/02/10 05:02:02 INFO : There was nothing to transfer --- PASS: TestSyncIgnoreExisting (3.89s) === RUN TestSyncIgnoreErrors run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7'", Local "Local file system at /tmp/rclone4068820260", Modify Window "1ms" 2022/02/10 05:02:07 DEBUG : b/potato: md5 = 35e21dd9c5a83db75f7a41ea0fb936d4 OK 2022/02/10 05:02:09 DEBUG : c/non empty space: md5 = acfbd87332ff2a4ab04511f778486264 OK 2022/02/10 05:02:09 DEBUG : d: Making directory 2022/02/10 05:02:11 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for checks to finish 2022/02/10 05:02:11 DEBUG : c/non empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/02/10 05:02:11 DEBUG : c/non empty space: Unchanged skipping 2022/02/10 05:02:11 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for transfers to finish 2022/02/10 05:02:13 DEBUG : a/potato2: md5 = f368ca90ebcd2dc689b571cc6cc503fd OK 2022/02/10 05:02:13 INFO : a/potato2: Copied (new) 2022/02/10 05:02:13 DEBUG : Waiting for deletions to finish 2022/02/10 05:02:14 INFO : b/potato: Deleted 2022/02/10 05:02:14 INFO : d: Removing directory 2022/02/10 05:02:15 INFO : b: Removing directory 2022/02/10 05:02:15 DEBUG : 32d8ua6196mc1r7qkfog53rkg0: Rmdir: contains trashed file: "2m507n64kafsi59v9q71r281a4" 2022/02/10 05:02:16 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': deleted 2 directories 2022/02/10 05:02:18 DEBUG : 3i9du405pfogq3ncai6pg7ouio: Rmdir: contains trashed file: "982d3pss7t5pn0il16r2foj31s" 2022/02/10 05:02:19 DEBUG : 2bsvlrk2ne1lfitm6tttcu0qt8: Rmdir: contains trashed file: "89l8renevh3mji1c8r1p7qn6tg" --- PASS: TestSyncIgnoreErrors (16.00s) === RUN TestSyncAfterChangingModtimeOnly run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7'", Local "Local file system at /tmp/rclone4068820260", Modify Window "1ms" 2022/02/10 05:02:22 DEBUG : empty space: md5 = 4333aaf762552ada4477953fc6fb9369 OK 2022/02/10 05:02:22 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for checks to finish 2022/02/10 05:02:22 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/02/10 05:02:22 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for transfers to finish 2022/02/10 05:02:22 NOTICE: empty space: Skipped copy as --dry-run is set (size 1) 2022/02/10 05:02:22 DEBUG : Waiting for deletions to finish 2022/02/10 05:02:23 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for checks to finish 2022/02/10 05:02:23 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/02/10 05:02:23 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for transfers to finish 2022/02/10 05:02:24 DEBUG : empty space: md5 = 7c470e570728405892403257f86ad7ec OK 2022/02/10 05:02:24 INFO : empty space: Copied (replaced existing) 2022/02/10 05:02:24 DEBUG : Waiting for deletions to finish --- PASS: TestSyncAfterChangingModtimeOnly (5.35s) === RUN TestSyncAfterChangingModtimeOnlyWithNoUpdateModTime run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7'", Local "Local file system at /tmp/rclone4068820260", Modify Window "1ms" sync_test.go:577: Can't check this if no hashes supported --- PASS: TestSyncAfterChangingModtimeOnlyWithNoUpdateModTime (0.49s) === RUN TestSyncDoesntUpdateModtime run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7'", Local "Local file system at /tmp/rclone4068820260", Modify Window "1ms" 2022/02/10 05:02:27 DEBUG : foo: md5 = 1611b93a56e33e8f97da93ab53922931 OK 2022/02/10 05:02:28 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for checks to finish 2022/02/10 05:02:28 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/02/10 05:02:28 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for transfers to finish 2022/02/10 05:02:29 DEBUG : foo: md5 = 79a76a89b1836c15a5fe7420e655dde9 OK 2022/02/10 05:02:29 INFO : foo: Copied (replaced existing) 2022/02/10 05:02:29 DEBUG : Waiting for deletions to finish --- PASS: TestSyncDoesntUpdateModtime (4.62s) === RUN TestSyncAfterAddingAFile run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7'", Local "Local file system at /tmp/rclone4068820260", Modify Window "1ms" 2022/02/10 05:02:32 DEBUG : empty space: md5 = 40acc28b25bc045d74acc2c155aff4b7 OK 2022/02/10 05:02:32 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/02/10 05:02:32 DEBUG : empty space: Unchanged skipping 2022/02/10 05:02:32 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for checks to finish 2022/02/10 05:02:32 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for transfers to finish 2022/02/10 05:02:34 DEBUG : potato: md5 = df470397196b36cee01c515935d00cf8 OK 2022/02/10 05:02:34 INFO : potato: Copied (new) 2022/02/10 05:02:34 DEBUG : Waiting for deletions to finish --- PASS: TestSyncAfterAddingAFile (5.56s) === RUN TestSyncAfterChangingFilesSizeOnly run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7'", Local "Local file system at /tmp/rclone4068820260", Modify Window "1ms" 2022/02/10 05:02:37 DEBUG : potato: md5 = 0d13a279dea16af57c972f58c359bd54 OK 2022/02/10 05:02:38 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for checks to finish 2022/02/10 05:02:38 DEBUG : potato: Sizes differ (src 21 vs dst 60) 2022/02/10 05:02:38 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for transfers to finish 2022/02/10 05:02:39 DEBUG : potato: md5 = d28706e9c4b2e513876abb52e4269f0a OK 2022/02/10 05:02:39 INFO : potato: Copied (replaced existing) 2022/02/10 05:02:39 DEBUG : Waiting for deletions to finish --- PASS: TestSyncAfterChangingFilesSizeOnly (4.42s) === RUN TestSyncAfterChangingContentsOnly run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7'", Local "Local file system at /tmp/rclone4068820260", Modify Window "1ms" 2022/02/10 05:02:42 DEBUG : potato: md5 = dabcb02540ba091eee54ef9fdf387f3d OK 2022/02/10 05:02:42 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/02/10 05:02:42 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for checks to finish 2022/02/10 05:02:42 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for transfers to finish 2022/02/10 05:02:44 DEBUG : potato: md5 = 2cbd7a1ec53c5dcdb08a8d31c22c6c28 OK 2022/02/10 05:02:44 INFO : potato: Copied (replaced existing) 2022/02/10 05:02:44 DEBUG : Waiting for deletions to finish --- PASS: TestSyncAfterChangingContentsOnly (4.55s) === RUN TestSyncAfterRemovingAFileAndAddingAFileDryRun run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7'", Local "Local file system at /tmp/rclone4068820260", Modify Window "1ms" 2022/02/10 05:02:46 DEBUG : potato: md5 = 0068a14e94776314f8cf8e1d4ded6e4b OK 2022/02/10 05:02:48 DEBUG : empty space: md5 = d833699deaa08f39730f6881a7c0c953 OK 2022/02/10 05:02:48 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for checks to finish 2022/02/10 05:02:48 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/02/10 05:02:48 DEBUG : empty space: Unchanged skipping 2022/02/10 05:02:48 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for transfers to finish 2022/02/10 05:02:48 NOTICE: potato2: Skipped copy as --dry-run is set (size 60) 2022/02/10 05:02:48 DEBUG : Waiting for deletions to finish 2022/02/10 05:02:48 NOTICE: potato: Skipped delete as --dry-run is set (size 21) --- PASS: TestSyncAfterRemovingAFileAndAddingAFileDryRun (5.22s) === RUN TestSyncAfterRemovingAFileAndAddingAFile run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7'", Local "Local file system at /tmp/rclone4068820260", Modify Window "1ms" 2022/02/10 05:02:52 DEBUG : potato: md5 = f53254829a325d3f1fccb7c21ee5fd3e OK 2022/02/10 05:02:53 DEBUG : empty space: md5 = b73ec9491a0ef8258a469e63c6cdb978 OK 2022/02/10 05:02:54 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/02/10 05:02:54 DEBUG : empty space: Unchanged skipping 2022/02/10 05:02:54 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for checks to finish 2022/02/10 05:02:54 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for transfers to finish 2022/02/10 05:02:55 DEBUG : potato2: md5 = 2eaa4fd5a731f32f6758e202fa3dac5e OK 2022/02/10 05:02:55 INFO : potato2: Copied (new) 2022/02/10 05:02:55 DEBUG : Waiting for deletions to finish 2022/02/10 05:02:56 INFO : potato: Deleted --- PASS: TestSyncAfterRemovingAFileAndAddingAFile (7.67s) === RUN TestSyncAfterRemovingAFileAndAddingAFileSubDir run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7'", Local "Local file system at /tmp/rclone4068820260", Modify Window "1ms" 2022/02/10 05:03:00 DEBUG : b/potato: md5 = ffa05abb579c962eb80311f9c5b9b66d OK 2022/02/10 05:03:03 DEBUG : c/non empty space: md5 = 61aa5b2de963cff41832ce5598f8fa54 OK 2022/02/10 05:03:03 DEBUG : d: Making directory 2022/02/10 05:03:03 DEBUG : d/e: Making directory 2022/02/10 05:03:06 DEBUG : c/non empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/02/10 05:03:06 DEBUG : c/non empty space: Unchanged skipping 2022/02/10 05:03:07 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for checks to finish 2022/02/10 05:03:07 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for transfers to finish 2022/02/10 05:03:08 DEBUG : a/potato2: md5 = 0a76fcca0c55f30d49c4c11f48322013 OK 2022/02/10 05:03:08 INFO : a/potato2: Copied (new) 2022/02/10 05:03:08 DEBUG : Waiting for deletions to finish 2022/02/10 05:03:09 INFO : b/potato: Deleted 2022/02/10 05:03:09 INFO : d/e: Removing directory 2022/02/10 05:03:09 INFO : d: Removing directory 2022/02/10 05:03:10 DEBUG : ka6id8d20d3s5ktapedlphgta8: Rmdir: contains trashed file: "r8sppajuabeak3sbgj2ak8vuf8" 2022/02/10 05:03:10 INFO : b: Removing directory 2022/02/10 05:03:11 DEBUG : 32d8ua6196mc1r7qkfog53rkg0: Rmdir: contains trashed file: "2m507n64kafsi59v9q71r281a4" 2022/02/10 05:03:11 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': deleted 3 directories 2022/02/10 05:03:14 DEBUG : 3i9du405pfogq3ncai6pg7ouio: Rmdir: contains trashed file: "982d3pss7t5pn0il16r2foj31s" 2022/02/10 05:03:15 DEBUG : 2bsvlrk2ne1lfitm6tttcu0qt8: Rmdir: contains trashed file: "89l8renevh3mji1c8r1p7qn6tg" --- PASS: TestSyncAfterRemovingAFileAndAddingAFileSubDir (18.02s) === RUN TestSyncAfterRemovingAFileAndAddingAFileSubDirWithErrors run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7'", Local "Local file system at /tmp/rclone4068820260", Modify Window "1ms" 2022/02/10 05:03:18 DEBUG : b/potato: md5 = ef44d196ee50599d0cef6194b43e4f70 OK 2022/02/10 05:03:21 DEBUG : c/non empty space: md5 = 12a55f814270ba7ca4d066306a3b7852 OK 2022/02/10 05:03:21 DEBUG : d: Making directory 2022/02/10 05:03:23 DEBUG : c/non empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/02/10 05:03:23 DEBUG : c/non empty space: Unchanged skipping 2022/02/10 05:03:24 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for checks to finish 2022/02/10 05:03:24 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for transfers to finish 2022/02/10 05:03:25 DEBUG : a/potato2: md5 = 2db6604258ba25f2e6301db595fdfe2c OK 2022/02/10 05:03:25 INFO : a/potato2: Copied (new) 2022/02/10 05:03:25 ERROR : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': not deleting files as there were IO errors 2022/02/10 05:03:25 ERROR : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': not deleting directories as there were IO errors 2022/02/10 05:03:30 DEBUG : 3i9du405pfogq3ncai6pg7ouio: Rmdir: contains trashed file: "982d3pss7t5pn0il16r2foj31s" 2022/02/10 05:03:31 DEBUG : 32d8ua6196mc1r7qkfog53rkg0: Rmdir: contains trashed file: "2m507n64kafsi59v9q71r281a4" 2022/02/10 05:03:32 DEBUG : 2bsvlrk2ne1lfitm6tttcu0qt8: Rmdir: contains trashed file: "89l8renevh3mji1c8r1p7qn6tg" --- PASS: TestSyncAfterRemovingAFileAndAddingAFileSubDirWithErrors (16.61s) === RUN TestSyncDeleteAfter --- PASS: TestSyncDeleteAfter (0.00s) === RUN TestSyncDeleteDuring run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7'", Local "Local file system at /tmp/rclone4068820260", Modify Window "1ms" 2022/02/10 05:03:34 DEBUG : potato: md5 = 82a49c38f3705f834435a8fb32e111fd OK 2022/02/10 05:03:36 DEBUG : empty space: md5 = b7edbfce1acd666347be48979f70e369 OK 2022/02/10 05:03:36 DEBUG : Waiting for deletions to finish 2022/02/10 05:03:36 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/02/10 05:03:36 DEBUG : empty space: Unchanged skipping 2022/02/10 05:03:36 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for checks to finish 2022/02/10 05:03:36 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for transfers to finish 2022/02/10 05:03:37 INFO : potato: Deleted 2022/02/10 05:03:38 DEBUG : potato2: md5 = 7dbab76cd28afb01a0108f7177fa3334 OK 2022/02/10 05:03:38 INFO : potato2: Copied (new) --- PASS: TestSyncDeleteDuring (7.48s) === RUN TestSyncDeleteBefore run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7'", Local "Local file system at /tmp/rclone4068820260", Modify Window "1ms" 2022/02/10 05:03:41 DEBUG : potato: md5 = d5d20c6e107d2bd263e1d29d163d1585 OK 2022/02/10 05:03:43 DEBUG : empty space: md5 = 3edf84fb08ea6455116064796d152161 OK 2022/02/10 05:03:43 DEBUG : Waiting for deletions to finish 2022/02/10 05:03:43 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for checks to finish 2022/02/10 05:03:43 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for transfers to finish 2022/02/10 05:03:44 INFO : potato: Deleted 2022/02/10 05:03:44 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/02/10 05:03:44 DEBUG : empty space: Unchanged skipping 2022/02/10 05:03:44 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for checks to finish 2022/02/10 05:03:44 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for transfers to finish 2022/02/10 05:03:46 DEBUG : potato2: md5 = 948435bb0e46c424455c816769a1ef90 OK 2022/02/10 05:03:46 INFO : potato2: Copied (new) --- PASS: TestSyncDeleteBefore (8.10s) === RUN TestCopyDeleteBefore run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7'", Local "Local file system at /tmp/rclone4068820260", Modify Window "1ms" 2022/02/10 05:03:50 DEBUG : potato: md5 = 7731715288316ea2ded599619aa6f8bf OK 2022/02/10 05:03:50 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for checks to finish 2022/02/10 05:03:50 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for transfers to finish 2022/02/10 05:03:52 DEBUG : potato2: md5 = 1f0076634ba1f259f3eac582ad0e1199 OK 2022/02/10 05:03:52 INFO : potato2: Copied (new) --- PASS: TestCopyDeleteBefore (5.97s) === RUN TestSyncWithExclude run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7'", Local "Local file system at /tmp/rclone4068820260", Modify Window "1ms" 2022/02/10 05:03:56 DEBUG : potato2: md5 = 11d38e0665e12a0e95063cd5a6663ee4 OK 2022/02/10 05:03:57 DEBUG : empty space: md5 = 6c813a2db9269974e1559fbb65ade2df OK 2022/02/10 05:03:57 DEBUG : enormous: Excluded 2022/02/10 05:03:57 DEBUG : potato2: Excluded 2022/02/10 05:03:58 DEBUG : potato2: Excluded 2022/02/10 05:03:58 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/02/10 05:03:58 DEBUG : empty space: Unchanged skipping 2022/02/10 05:03:58 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for checks to finish 2022/02/10 05:03:58 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for transfers to finish 2022/02/10 05:03:58 DEBUG : Waiting for deletions to finish 2022/02/10 05:03:58 INFO : There was nothing to transfer 2022/02/10 05:03:58 DEBUG : enormous: Excluded 2022/02/10 05:03:58 DEBUG : potato2: Excluded 2022/02/10 05:03:58 DEBUG : potato2: Excluded 2022/02/10 05:03:58 DEBUG : empty space: Size and modification time the same (differ by 456.789µs, within tolerance 1ms) 2022/02/10 05:03:58 DEBUG : empty space: Unchanged skipping 2022/02/10 05:03:58 DEBUG : Local file system at /tmp/rclone4068820260: Waiting for checks to finish 2022/02/10 05:03:58 DEBUG : Local file system at /tmp/rclone4068820260: Waiting for transfers to finish 2022/02/10 05:03:58 DEBUG : Waiting for deletions to finish 2022/02/10 05:03:58 INFO : There was nothing to transfer --- PASS: TestSyncWithExclude (6.23s) === RUN TestSyncWithExcludeAndDeleteExcluded run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7'", Local "Local file system at /tmp/rclone4068820260", Modify Window "1ms" 2022/02/10 05:04:02 DEBUG : potato2: md5 = 7ee1a4f96b36f5c60e07e457ffd5a5c2 OK 2022/02/10 05:04:03 DEBUG : empty space: md5 = d17d78b5e940000b6f0233192d365b81 OK 2022/02/10 05:04:05 DEBUG : enormous: md5 = f90ce3fc2b1b22f4c65e0e49d6b54051 OK 2022/02/10 05:04:05 DEBUG : enormous: Excluded 2022/02/10 05:04:05 DEBUG : potato2: Excluded 2022/02/10 05:04:06 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/02/10 05:04:06 DEBUG : empty space: Unchanged skipping 2022/02/10 05:04:06 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for checks to finish 2022/02/10 05:04:06 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for transfers to finish 2022/02/10 05:04:06 DEBUG : Waiting for deletions to finish 2022/02/10 05:04:06 INFO : potato2: Deleted 2022/02/10 05:04:06 INFO : enormous: Deleted 2022/02/10 05:04:06 INFO : There was nothing to transfer 2022/02/10 05:04:07 DEBUG : Local file system at /tmp/rclone4068820260: Waiting for checks to finish 2022/02/10 05:04:07 DEBUG : empty space: Size and modification time the same (differ by 456.789µs, within tolerance 1ms) 2022/02/10 05:04:07 DEBUG : empty space: Unchanged skipping 2022/02/10 05:04:07 DEBUG : Local file system at /tmp/rclone4068820260: Waiting for transfers to finish 2022/02/10 05:04:07 DEBUG : Waiting for deletions to finish 2022/02/10 05:04:07 INFO : potato2: Deleted 2022/02/10 05:04:07 INFO : enormous: Deleted 2022/02/10 05:04:07 INFO : There was nothing to transfer --- PASS: TestSyncWithExcludeAndDeleteExcluded (7.86s) === RUN TestSyncWithUpdateOlder run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7'", Local "Local file system at /tmp/rclone4068820260", Modify Window "1ms" 2022/02/10 05:04:10 DEBUG : one: md5 = 94419a554fcf99dd073d62a03783e2eb OK 2022/02/10 05:04:11 DEBUG : two: md5 = 69b2143c6b776330601bf47a16d4f005 OK 2022/02/10 05:04:13 DEBUG : three: md5 = 56f37b741f79c1eb060ed2bad3a403b7 OK 2022/02/10 05:04:14 DEBUG : four: md5 = 9d9e7db36036baaea6fe448ab7fddb2f OK 2022/02/10 05:04:15 DEBUG : four: Sizes differ (src 4 vs dst 8) 2022/02/10 05:04:15 DEBUG : four: Destination mod time is within 1s of source but files differ, transferring 2022/02/10 05:04:15 DEBUG : one: Destination is newer than source, skipping 2022/02/10 05:04:15 DEBUG : three: Sizes identical 2022/02/10 05:04:15 DEBUG : three: Destination mod time is within 1s of source and files identical, skipping 2022/02/10 05:04:15 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for checks to finish 2022/02/10 05:04:15 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for transfers to finish 2022/02/10 05:04:16 DEBUG : four: md5 = c2f366e4fafbd506e780ff477bbde0c9 OK 2022/02/10 05:04:16 INFO : four: Copied (replaced existing) 2022/02/10 05:04:16 DEBUG : two: md5 = 64d328860d342ea1b5252e4314b4bb60 OK 2022/02/10 05:04:16 INFO : two: Copied (replaced existing) 2022/02/10 05:04:16 DEBUG : five: md5 = 9982b271e078337eb7d740a509988983 OK 2022/02/10 05:04:16 INFO : five: Copied (new) 2022/02/10 05:04:16 DEBUG : Waiting for deletions to finish sync_test.go:992: Skip test with --checksum as no hashes supported --- PASS: TestSyncWithUpdateOlder (12.10s) === 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-tutitiw5bifilob4cahuyag7'", Local "Local file system at /tmp/rclone4068820260", Modify Window "1ms" sync_test.go:1058: Can track renames: false 2022/02/10 05:04:20 ERROR : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Ignoring --track-renames as the source and destination do not have a common hash 2022/02/10 05:04:20 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for checks to finish 2022/02/10 05:04:20 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for transfers to finish 2022/02/10 05:04:22 DEBUG : potato: md5 = 26d7d32c1841b46dc4ca963aae907bd3 OK 2022/02/10 05:04:22 INFO : potato: Copied (new) 2022/02/10 05:04:22 DEBUG : yam: md5 = 24878eb188a913d5c63626577218be65 OK 2022/02/10 05:04:22 INFO : yam: Copied (new) 2022/02/10 05:04:22 DEBUG : Waiting for deletions to finish 2022/02/10 05:04:23 ERROR : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Ignoring --track-renames as the source and destination do not have a common hash 2022/02/10 05:04:23 DEBUG : potato: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/02/10 05:04:23 DEBUG : potato: Unchanged skipping 2022/02/10 05:04:23 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for checks to finish 2022/02/10 05:04:23 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for transfers to finish 2022/02/10 05:04:25 DEBUG : yaml: md5 = b3f5a87693015b30b87d47296f7f2ec3 OK 2022/02/10 05:04:25 INFO : yaml: Copied (new) 2022/02/10 05:04:25 DEBUG : Waiting for deletions to finish 2022/02/10 05:04:25 INFO : yam: Deleted --- PASS: TestSyncWithTrackRenames (6.93s) === RUN TestParseRenamesStrategyModtime --- PASS: TestParseRenamesStrategyModtime (0.00s) === RUN TestRenamesStrategyModtime --- PASS: TestRenamesStrategyModtime (0.00s) === RUN TestSyncWithTrackRenamesStrategyModtime run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7'", Local "Local file system at /tmp/rclone4068820260", Modify Window "1ms" sync_test.go:1127: Can track renames: true 2022/02/10 05:04:27 INFO : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Making map for --track-renames 2022/02/10 05:04:27 INFO : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Finished making map for --track-renames 2022/02/10 05:04:27 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for checks to finish 2022/02/10 05:04:27 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for renames to finish 2022/02/10 05:04:27 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for transfers to finish 2022/02/10 05:04:29 DEBUG : potato: md5 = 0b0213e3e05db11367ed4b68db5e04f7 OK 2022/02/10 05:04:29 INFO : potato: Copied (new) 2022/02/10 05:04:29 DEBUG : yam: md5 = ac198bd40b4503ba14adb7aad9694ec9 OK 2022/02/10 05:04:29 INFO : yam: Copied (new) 2022/02/10 05:04:29 DEBUG : Waiting for deletions to finish 2022/02/10 05:04:30 DEBUG : potato: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/02/10 05:04:30 DEBUG : potato: Unchanged skipping 2022/02/10 05:04:30 INFO : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Making map for --track-renames 2022/02/10 05:04:30 INFO : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Finished making map for --track-renames 2022/02/10 05:04:30 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for checks to finish 2022/02/10 05:04:30 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for renames to finish 2022/02/10 05:04:31 INFO : yam: Moved (server-side) to: yaml 2022/02/10 05:04:31 INFO : yaml: Renamed from "yam" 2022/02/10 05:04:31 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for transfers to finish 2022/02/10 05:04:31 DEBUG : Waiting for deletions to finish 2022/02/10 05:04:31 INFO : There was nothing to transfer --- PASS: TestSyncWithTrackRenamesStrategyModtime (5.70s) === RUN TestSyncWithTrackRenamesStrategyLeaf run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7'", Local "Local file system at /tmp/rclone4068820260", Modify Window "1ms" sync_test.go:1163: Can track renames: true 2022/02/10 05:04:33 INFO : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Making map for --track-renames 2022/02/10 05:04:33 INFO : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Finished making map for --track-renames 2022/02/10 05:04:33 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for checks to finish 2022/02/10 05:04:33 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for renames to finish 2022/02/10 05:04:33 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for transfers to finish 2022/02/10 05:04:36 DEBUG : potato: md5 = 2083ae1d707554a6979473a781635427 OK 2022/02/10 05:04:36 INFO : potato: Copied (new) 2022/02/10 05:04:36 DEBUG : sub/yam: md5 = 8e8755863d9440290c3c5e39f0effb33 OK 2022/02/10 05:04:36 INFO : sub/yam: Copied (new) 2022/02/10 05:04:36 DEBUG : Waiting for deletions to finish 2022/02/10 05:04:37 DEBUG : potato: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/02/10 05:04:37 DEBUG : potato: Unchanged skipping 2022/02/10 05:04:37 INFO : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Making map for --track-renames 2022/02/10 05:04:37 INFO : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Finished making map for --track-renames 2022/02/10 05:04:37 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for checks to finish 2022/02/10 05:04:37 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for renames to finish 2022/02/10 05:04:38 INFO : sub/yam: Moved (server-side) to: yam 2022/02/10 05:04:38 INFO : yam: Renamed from "sub/yam" 2022/02/10 05:04:38 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for transfers to finish 2022/02/10 05:04:38 DEBUG : Waiting for deletions to finish 2022/02/10 05:04:38 INFO : There was nothing to transfer --- PASS: TestSyncWithTrackRenamesStrategyLeaf (8.44s) === RUN TestMoveWithDeleteEmptySrcDirs run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7'", Local "Local file system at /tmp/rclone4068820260", Modify Window "1ms" 2022/02/10 05:04:42 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for checks to finish 2022/02/10 05:04:42 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for transfers to finish 2022/02/10 05:04:44 DEBUG : sub dir/hello world: md5 = 13b09d94af7aa38dcdb4dad3a40cd7f7 OK 2022/02/10 05:04:44 INFO : sub dir/hello world: Copied (new) 2022/02/10 05:04:44 INFO : sub dir/hello world: Deleted 2022/02/10 05:04:46 DEBUG : nested/sub dir/file: md5 = 5506e5f7b70937917ff243f50ab0b82a OK 2022/02/10 05:04:46 INFO : nested/sub dir/file: Copied (new) 2022/02/10 05:04:46 INFO : nested/sub dir/file: Deleted 2022/02/10 05:04:46 INFO : sub dir: Removing directory 2022/02/10 05:04:46 INFO : nested/sub dir: Removing directory 2022/02/10 05:04:46 INFO : nested: Removing directory 2022/02/10 05:04:46 DEBUG : Local file system at /tmp/rclone4068820260: deleted 3 directories 2022/02/10 05:04:50 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" 2022/02/10 05:04:51 DEBUG : 37qp6d1gohacv723ij3brofbu8/14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "ftp4kuv8se7tqduu6pmmcvjsmk" 2022/02/10 05:04:52 DEBUG : 37qp6d1gohacv723ij3brofbu8: Rmdir: contains trashed file: "14begaa36ih249fgrnfk6nulg0" --- PASS: TestMoveWithDeleteEmptySrcDirs (11.18s) === RUN TestMoveWithoutDeleteEmptySrcDirs run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7'", Local "Local file system at /tmp/rclone4068820260", Modify Window "1ms" 2022/02/10 05:04:53 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for checks to finish 2022/02/10 05:04:53 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for transfers to finish 2022/02/10 05:04:55 DEBUG : sub dir/hello world: md5 = 0b3e6d60dac32321588de4da9634c8dc OK 2022/02/10 05:04:55 INFO : sub dir/hello world: Copied (new) 2022/02/10 05:04:55 INFO : sub dir/hello world: Deleted 2022/02/10 05:04:57 DEBUG : nested/sub dir/file: md5 = 224e73f7f9495bbbda653e9adea0aeed OK 2022/02/10 05:04:57 INFO : nested/sub dir/file: Copied (new) 2022/02/10 05:04:57 INFO : nested/sub dir/file: Deleted 2022/02/10 05:05:01 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" 2022/02/10 05:05:02 DEBUG : 37qp6d1gohacv723ij3brofbu8/14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "ftp4kuv8se7tqduu6pmmcvjsmk" 2022/02/10 05:05:03 DEBUG : 37qp6d1gohacv723ij3brofbu8: Rmdir: contains trashed file: "14begaa36ih249fgrnfk6nulg0" --- PASS: TestMoveWithoutDeleteEmptySrcDirs (11.24s) === RUN TestMoveWithIgnoreExisting run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7'", Local "Local file system at /tmp/rclone4068820260", Modify Window "1ms" 2022/02/10 05:05:04 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for checks to finish 2022/02/10 05:05:04 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for transfers to finish 2022/02/10 05:05:05 DEBUG : existing: md5 = b03236d618a8131a5d91f7c6edcfc1e7 OK 2022/02/10 05:05:05 INFO : existing: Copied (new) 2022/02/10 05:05:05 INFO : existing: Deleted 2022/02/10 05:05:06 DEBUG : existing-b: md5 = cd6289a3418f3391418675581cc0a2ca OK 2022/02/10 05:05:06 INFO : existing-b: Copied (new) 2022/02/10 05:05:06 INFO : existing-b: Deleted 2022/02/10 05:05:06 DEBUG : existing: Destination exists, skipping 2022/02/10 05:05:06 DEBUG : existing: Not removing source file as destination file exists and --ignore-existing is set 2022/02/10 05:05:06 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for checks to finish 2022/02/10 05:05:06 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for transfers to finish 2022/02/10 05:05:06 INFO : There was nothing to transfer --- PASS: TestMoveWithIgnoreExisting (4.68s) === RUN TestServerSideMove run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7'", Local "Local file system at /tmp/rclone4068820260", Modify Window "1ms" 2022/02/10 05:05:08 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-kuducuq8luqofin0rihugug7" 2022/02/10 05:05:08 DEBUG : Config file has changed externaly - reloading 2022/02/10 05:05:08 DEBUG : Creating backend with remote "TestDrive:crypt/uiqn65rfnod95ksernl1ibnslkhtterthoaskugc3he2ffic5a6irohsldlf011i5300c391qojbq" 2022/02/10 05:05:11 DEBUG : potato2: md5 = 0d82f1b70710d8d0508c2ffe3ae297ed OK 2022/02/10 05:05:13 DEBUG : empty space: md5 = 4a06d370db3475c19bcee0e16814c76d OK 2022/02/10 05:05:14 DEBUG : potato3: md5 = 1b6789eb2c5b421090b13f4ce1df41f3 OK sync_test.go:1215: Server side move (if possible) Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7' -> Encrypted drive 'TestCryptDrive:rclone-test-kuducuq8luqofin0rihugug7' 2022/02/10 05:05:17 DEBUG : empty space: md5 = ede54eb105e68195a5abba2b59587082 OK 2022/02/10 05:05:18 DEBUG : potato3: md5 = e9d24f54d54ae48f8c80a7863f87304b OK 2022/02/10 05:05:19 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-kuducuq8luqofin0rihugug7': Using server-side directory move 2022/02/10 05:05:19 INFO : Encrypted drive 'TestCryptDrive:rclone-test-kuducuq8luqofin0rihugug7': Server side directory move failed - fallback to file moves: can't copy directory - destination already exists 2022/02/10 05:05:19 DEBUG : potato3: Sizes differ (src 68 vs dst 60) 2022/02/10 05:05:19 DEBUG : empty space: Size and modification time the same (differ by 0s, within tolerance 1ms) 2022/02/10 05:05:19 DEBUG : empty space: Unchanged skipping 2022/02/10 05:05:19 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-kuducuq8luqofin0rihugug7': Waiting for checks to finish 2022/02/10 05:05:20 INFO : empty space: Deleted 2022/02/10 05:05:20 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-kuducuq8luqofin0rihugug7': Waiting for transfers to finish 2022/02/10 05:05:20 INFO : potato2: Moved (server-side) 2022/02/10 05:05:20 INFO : potato3: Deleted 2022/02/10 05:05:21 INFO : potato3: Moved (server-side) 2022/02/10 05:05:21 INFO : There was nothing to transfer 2022/02/10 05:05:21 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-rutabaj4zotoyet5tejunis5" 2022/02/10 05:05:21 DEBUG : Creating backend with remote "TestDrive:crypt/pugj6shecrg1lp1iumomtcu212rrlrd4elhhotjnqiepq4584i5o8br5j9ma3fhbakan6s2t0e51q" 2022/02/10 05:05:23 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-rutabaj4zotoyet5tejunis5': Using server-side directory move 2022/02/10 05:05:23 INFO : Encrypted drive 'TestCryptDrive:rclone-test-rutabaj4zotoyet5tejunis5': Server side directory move succeeded 2022/02/10 05:05:25 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-rutabaj4zotoyet5tejunis5': Purge remote 2022/02/10 05:05:25 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-kuducuq8luqofin0rihugug7': Purge remote 2022/02/10 05:05:25 purge failed: directory not found --- PASS: TestServerSideMove (17.66s) === RUN TestServerSideMoveWithFilter run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7'", Local "Local file system at /tmp/rclone4068820260", Modify Window "1ms" 2022/02/10 05:05:26 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-javutes0fomowex5cijikar2" 2022/02/10 05:05:26 DEBUG : Creating backend with remote "TestDrive:crypt/m0vu4g9tk7c0fkpcd423uoaq9cvd59pqhsqsl85pbjfmfi52jma2tpq14b6dn0k5qq0a5omm6qavu" 2022/02/10 05:05:29 DEBUG : potato2: md5 = 3d32e9bbfbc6b5c3eee4602a3d5fc21c OK 2022/02/10 05:05:30 DEBUG : empty space: md5 = bc5c59b50e2db30560695378608acbb0 OK 2022/02/10 05:05:32 DEBUG : potato3: md5 = 49b64af3ea6949a205926b7596686f1c OK sync_test.go:1215: Server side move (if possible) Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7' -> Encrypted drive 'TestCryptDrive:rclone-test-javutes0fomowex5cijikar2' 2022/02/10 05:05:35 DEBUG : empty space: md5 = 0f278cdf58a64dbc856abbbe794140e6 OK 2022/02/10 05:05:36 DEBUG : potato3: md5 = 8281c98ec3b06b09d71d2352f5e2c280 OK 2022/02/10 05:05:37 DEBUG : empty space: Excluded 2022/02/10 05:05:37 DEBUG : empty space: Excluded 2022/02/10 05:05:37 DEBUG : potato3: Sizes differ (src 68 vs dst 60) 2022/02/10 05:05:37 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-javutes0fomowex5cijikar2': Waiting for checks to finish 2022/02/10 05:05:37 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-javutes0fomowex5cijikar2': Waiting for transfers to finish 2022/02/10 05:05:38 INFO : potato3: Deleted 2022/02/10 05:05:38 INFO : potato2: Moved (server-side) 2022/02/10 05:05:39 INFO : potato3: Moved (server-side) 2022/02/10 05:05:39 INFO : There was nothing to transfer 2022/02/10 05:05:39 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-sinesah3qayuqun4ruyuqiq3" 2022/02/10 05:05:39 DEBUG : Creating backend with remote "TestDrive:crypt/toe5vf9niqc9b023i9unumrpbbj0uutbjnijjfr708tfd0ugpe8ecanmtv2677ria1d42vnukf7b8" 2022/02/10 05:05:41 DEBUG : empty space: Excluded 2022/02/10 05:05:41 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sinesah3qayuqun4ruyuqiq3': Waiting for checks to finish 2022/02/10 05:05:41 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sinesah3qayuqun4ruyuqiq3': Waiting for transfers to finish 2022/02/10 05:05:43 INFO : potato2: Moved (server-side) 2022/02/10 05:05:43 INFO : potato3: Moved (server-side) 2022/02/10 05:05:43 INFO : There was nothing to transfer 2022/02/10 05:05:44 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-sinesah3qayuqun4ruyuqiq3': Purge remote 2022/02/10 05:05:44 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-javutes0fomowex5cijikar2': Purge remote --- PASS: TestServerSideMoveWithFilter (20.08s) === RUN TestServerSideMoveDeleteEmptySourceDirs run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7'", Local "Local file system at /tmp/rclone4068820260", Modify Window "1ms" 2022/02/10 05:05:46 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-pitutib8kepasuv0firujut9" 2022/02/10 05:05:46 DEBUG : Creating backend with remote "TestDrive:crypt/c0piq84rflc2poq7ke8mcc6mjbk0lod7lr16koogorjro8328v5idru3cle0tag9s1174ht54sv7e" 2022/02/10 05:05:49 DEBUG : potato2: md5 = 046287df70dc2b8f69e44bdcafa93124 OK 2022/02/10 05:05:50 DEBUG : empty space: md5 = c44caf44fe8b6e6da2469d5abb7f3c4d OK 2022/02/10 05:05:52 DEBUG : potato3: md5 = d72b98f44a5b5dc504edf38092c7e6b0 OK 2022/02/10 05:05:52 DEBUG : tomatoDir: Making directory sync_test.go:1215: Server side move (if possible) Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7' -> Encrypted drive 'TestCryptDrive:rclone-test-pitutib8kepasuv0firujut9' 2022/02/10 05:05:56 DEBUG : empty space: md5 = 4172674661ecb341b99208bc3e492b32 OK 2022/02/10 05:05:57 DEBUG : potato3: md5 = 7a77daf0b2e384d88ce69453bd73effe OK 2022/02/10 05:05:58 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-pitutib8kepasuv0firujut9': Using server-side directory move 2022/02/10 05:05:58 INFO : Encrypted drive 'TestCryptDrive:rclone-test-pitutib8kepasuv0firujut9': Server side directory move failed - fallback to file moves: can't copy directory - destination already exists 2022/02/10 05:05:58 DEBUG : empty space: Size and modification time the same (differ by 0s, within tolerance 1ms) 2022/02/10 05:05:58 DEBUG : empty space: Unchanged skipping 2022/02/10 05:05:58 DEBUG : potato3: Sizes differ (src 68 vs dst 60) 2022/02/10 05:05:58 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-pitutib8kepasuv0firujut9': Waiting for checks to finish 2022/02/10 05:05:59 INFO : empty space: Deleted 2022/02/10 05:05:59 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-pitutib8kepasuv0firujut9': Waiting for transfers to finish 2022/02/10 05:05:59 INFO : potato3: Deleted 2022/02/10 05:05:59 INFO : potato2: Moved (server-side) 2022/02/10 05:05:59 INFO : potato3: Moved (server-side) 2022/02/10 05:05:59 INFO : tomatoDir: Removing directory 2022/02/10 05:06:00 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': deleted 1 directories 2022/02/10 05:06:00 INFO : There was nothing to transfer 2022/02/10 05:06:01 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-lezaloz1lumejoc6pasusig7" 2022/02/10 05:06:01 DEBUG : Creating backend with remote "TestDrive:crypt/cg82fb546063djrbfvjap5mlhsnae67thmjemp0dare322mvgircn0i30sbv8g443nk0rms68ffhk" 2022/02/10 05:06:02 DEBUG : tomatoDir: Making directory 2022/02/10 05:06:03 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-lezaloz1lumejoc6pasusig7': Using server-side directory move 2022/02/10 05:06:04 INFO : Encrypted drive 'TestCryptDrive:rclone-test-lezaloz1lumejoc6pasusig7': Server side directory move succeeded 2022/02/10 05:06:06 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-lezaloz1lumejoc6pasusig7': Purge remote 2022/02/10 05:06:07 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-pitutib8kepasuv0firujut9': Purge remote 2022/02/10 05:06:07 purge failed: directory not found --- PASS: TestServerSideMoveDeleteEmptySourceDirs (21.39s) === RUN TestServerSideMoveOverlap run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7'", Local "Local file system at /tmp/rclone4068820260", Modify Window "1ms" sync_test.go:1399: Skipping test as remote supports DirMove --- SKIP: TestServerSideMoveOverlap (0.55s) === RUN TestSyncOverlap run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7'", Local "Local file system at /tmp/rclone4068820260", Modify Window "1ms" 2022/02/10 05:06:08 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7/rclone-sync-test" 2022/02/10 05:06:08 DEBUG : Creating backend with remote "TestDrive:crypt/mfah1qr4afpbqv8tfvs11nuv7150h8cq3888svjder49859i7b2d2jgq72hb2fsjp1r43m4c63dnc/i7355aa0sb89uagn75vfjqr6s3e3e1h2et8in57abn1fe8qfego0" --- PASS: TestSyncOverlap (2.53s) === RUN TestSyncCompareDest run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7'", Local "Local file system at /tmp/rclone4068820260", Modify Window "1ms" 2022/02/10 05:06:11 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7/dst" 2022/02/10 05:06:11 DEBUG : Creating backend with remote "TestDrive:crypt/mfah1qr4afpbqv8tfvs11nuv7150h8cq3888svjder49859i7b2d2jgq72hb2fsjp1r43m4c63dnc/31u3jie661vd5p8j7rtc3hgbh0" 2022/02/10 05:06:12 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7/CompareDest" 2022/02/10 05:06:12 DEBUG : Creating backend with remote "TestDrive:crypt/mfah1qr4afpbqv8tfvs11nuv7150h8cq3888svjder49859i7b2d2jgq72hb2fsjp1r43m4c63dnc/gveqi14airsml4bgu7krj116o8" 2022/02/10 05:06:15 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7/dst': Waiting for checks to finish 2022/02/10 05:06:15 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7/dst': Waiting for transfers to finish 2022/02/10 05:06:18 DEBUG : one: md5 = b832732e90f7d2a55db9525fc069950d OK 2022/02/10 05:06:18 INFO : one: Copied (new) 2022/02/10 05:06:18 DEBUG : Waiting for deletions to finish 2022/02/10 05:06:19 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7/dst': Waiting for checks to finish 2022/02/10 05:06:19 DEBUG : one: Sizes differ (src 5 vs dst 3) 2022/02/10 05:06:19 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7/dst': Waiting for transfers to finish 2022/02/10 05:06:21 DEBUG : one: md5 = 85e837cd3eadbe7477ff3bbd95ef58cc OK 2022/02/10 05:06:21 INFO : one: Copied (replaced existing) 2022/02/10 05:06:21 DEBUG : Waiting for deletions to finish 2022/02/10 05:06:23 DEBUG : dst/one: md5 = 15f3db114a8498e2c0405f517efdf5b0 OK 2022/02/10 05:06:25 DEBUG : CompareDest/one: md5 = 0a1b3f7d1c1a480582550ba3f36ef4e9 OK 2022/02/10 05:06:26 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7/dst': Waiting for checks to finish 2022/02/10 05:06:27 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/02/10 05:06:27 DEBUG : one: Destination found in --compare-dest, skipping 2022/02/10 05:06:27 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7/dst': Waiting for transfers to finish 2022/02/10 05:06:27 DEBUG : Waiting for deletions to finish 2022/02/10 05:06:27 INFO : There was nothing to transfer 2022/02/10 05:06:29 DEBUG : CompareDest/two: md5 = 2eeacf26761bfaaf0e88e36488f09ae0 OK 2022/02/10 05:06:30 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/02/10 05:06:30 DEBUG : two: Destination found in --compare-dest, skipping 2022/02/10 05:06:30 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7/dst': Waiting for checks to finish 2022/02/10 05:06:30 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/02/10 05:06:30 DEBUG : one: Destination found in --compare-dest, skipping 2022/02/10 05:06:30 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7/dst': Waiting for transfers to finish 2022/02/10 05:06:30 DEBUG : Waiting for deletions to finish 2022/02/10 05:06:30 INFO : There was nothing to transfer 2022/02/10 05:06:32 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/02/10 05:06:32 DEBUG : two: Destination found in --compare-dest, skipping 2022/02/10 05:06:32 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7/dst': Waiting for checks to finish 2022/02/10 05:06:32 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/02/10 05:06:32 DEBUG : one: Destination found in --compare-dest, skipping 2022/02/10 05:06:32 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7/dst': Waiting for transfers to finish 2022/02/10 05:06:32 DEBUG : Waiting for deletions to finish 2022/02/10 05:06:32 INFO : There was nothing to transfer sync_test.go:1543: No hash on uploaded file so skipping compare timestamp test 2022/02/10 05:06:34 DEBUG : two: Sizes differ (src 5 vs dst 3) 2022/02/10 05:06:34 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7/dst': Waiting for checks to finish 2022/02/10 05:06:34 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/02/10 05:06:34 DEBUG : one: Destination found in --compare-dest, skipping 2022/02/10 05:06:34 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7/dst': Waiting for transfers to finish 2022/02/10 05:06:35 DEBUG : two: md5 = d485c57852fc203be77658fb7d79f2ee OK 2022/02/10 05:06:35 INFO : two: Copied (new) 2022/02/10 05:06:35 DEBUG : Waiting for deletions to finish 2022/02/10 05:06:39 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" 2022/02/10 05:06:39 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2022/02/10 05:06:40 DEBUG : gveqi14airsml4bgu7krj116o8: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2022/02/10 05:06:40 DEBUG : gveqi14airsml4bgu7krj116o8: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" --- PASS: TestSyncCompareDest (30.54s) === RUN TestSyncMultipleCompareDest run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7'", Local "Local file system at /tmp/rclone4068820260", Modify Window "1ms" 2022/02/10 05:06:43 DEBUG : pre-dest1/1: md5 = 0186a7e1c06b626a56a7b9ec44b45aca OK 2022/02/10 05:06:47 DEBUG : pre-dest2/2: md5 = 5fa460a7510a3271f53fd302ba7aa0d4 OK 2022/02/10 05:06:47 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7/dest" 2022/02/10 05:06:47 DEBUG : Config file has changed externaly - reloading 2022/02/10 05:06:47 DEBUG : Creating backend with remote "TestDrive:crypt/mfah1qr4afpbqv8tfvs11nuv7150h8cq3888svjder49859i7b2d2jgq72hb2fsjp1r43m4c63dnc/rg03c1jvnehrrc617i0lnqjddc" 2022/02/10 05:06:49 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7/pre-dest1" 2022/02/10 05:06:49 DEBUG : Creating backend with remote "TestDrive:crypt/mfah1qr4afpbqv8tfvs11nuv7150h8cq3888svjder49859i7b2d2jgq72hb2fsjp1r43m4c63dnc/bbnblvh6k061ssopqrp18kd7gc" 2022/02/10 05:06:50 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7/pre-dest2" 2022/02/10 05:06:50 DEBUG : Creating backend with remote "TestDrive:crypt/mfah1qr4afpbqv8tfvs11nuv7150h8cq3888svjder49859i7b2d2jgq72hb2fsjp1r43m4c63dnc/dgicm1h6b5ejvlltm8eeif0bnk" 2022/02/10 05:06:52 DEBUG : 1: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/02/10 05:06:52 DEBUG : 1: Destination found in --compare-dest, skipping 2022/02/10 05:06:52 DEBUG : 2: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/02/10 05:06:52 DEBUG : 2: Destination found in --compare-dest, skipping 2022/02/10 05:06:53 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7/dest': Waiting for checks to finish 2022/02/10 05:06:53 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7/dest': Waiting for transfers to finish 2022/02/10 05:06:55 DEBUG : 3: md5 = 3f43d26d43b0d2435e03ab1f6a763925 OK 2022/02/10 05:06:55 INFO : 3: Copied (new) 2022/02/10 05:06:55 DEBUG : Waiting for deletions to finish 2022/02/10 05:06:59 DEBUG : dgicm1h6b5ejvlltm8eeif0bnk: Rmdir: contains trashed file: "1ghu8geql9vrl726n32nrf65bc" 2022/02/10 05:07:00 DEBUG : bbnblvh6k061ssopqrp18kd7gc: Rmdir: contains trashed file: "skbfko3oil7es0lj68ob574sro" 2022/02/10 05:07:01 DEBUG : rg03c1jvnehrrc617i0lnqjddc: Rmdir: contains trashed file: "g072p7hmjchlnj0gibe64c1epg" --- PASS: TestSyncMultipleCompareDest (20.52s) === RUN TestSyncCopyDest run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7'", Local "Local file system at /tmp/rclone4068820260", Modify Window "1ms" 2022/02/10 05:07:02 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7/dst" 2022/02/10 05:07:02 DEBUG : Creating backend with remote "TestDrive:crypt/mfah1qr4afpbqv8tfvs11nuv7150h8cq3888svjder49859i7b2d2jgq72hb2fsjp1r43m4c63dnc/31u3jie661vd5p8j7rtc3hgbh0" 2022/02/10 05:07:03 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7/CopyDest" 2022/02/10 05:07:03 DEBUG : Creating backend with remote "TestDrive:crypt/mfah1qr4afpbqv8tfvs11nuv7150h8cq3888svjder49859i7b2d2jgq72hb2fsjp1r43m4c63dnc/d09o6po3f7bm6ce32vdgs8h9ls" 2022/02/10 05:07:06 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7/dst': Waiting for checks to finish 2022/02/10 05:07:06 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7/dst': Waiting for transfers to finish 2022/02/10 05:07:08 DEBUG : one: md5 = 1addd18b70a48830aee0c8cf49b6a9c4 OK 2022/02/10 05:07:08 INFO : one: Copied (new) 2022/02/10 05:07:08 DEBUG : Waiting for deletions to finish 2022/02/10 05:07:10 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7/dst': Waiting for checks to finish 2022/02/10 05:07:10 DEBUG : one: Sizes differ (src 5 vs dst 3) 2022/02/10 05:07:10 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7/dst': Waiting for transfers to finish 2022/02/10 05:07:11 DEBUG : one: md5 = 969fbc947b12ba437b413ba7cc742130 OK 2022/02/10 05:07:11 INFO : one: Copied (replaced existing) 2022/02/10 05:07:11 DEBUG : Waiting for deletions to finish 2022/02/10 05:07:13 DEBUG : dst/one: md5 = f02fd8a619609386f5d8e11a4d053efe OK 2022/02/10 05:07:15 DEBUG : CopyDest/one: md5 = 04019c8f9d48b8c53998915c721866d4 OK 2022/02/10 05:07:16 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7/BackupDir" 2022/02/10 05:07:16 DEBUG : Creating backend with remote "TestDrive:crypt/mfah1qr4afpbqv8tfvs11nuv7150h8cq3888svjder49859i7b2d2jgq72hb2fsjp1r43m4c63dnc/s6dbk3lfi7c9kfvo6j7bla9m0g" 2022/02/10 05:07:18 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7/dst': Waiting for checks to finish 2022/02/10 05:07:19 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/02/10 05:07:19 DEBUG : one: Sizes differ (src 5 vs dst 3) 2022/02/10 05:07:21 INFO : one: Moved (server-side) 2022/02/10 05:07:22 INFO : one: Copied (server-side copy) 2022/02/10 05:07:22 DEBUG : one: Destination found in --copy-dest, using server-side copy 2022/02/10 05:07:22 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7/dst': Waiting for transfers to finish 2022/02/10 05:07:22 DEBUG : Waiting for deletions to finish 2022/02/10 05:07:24 DEBUG : CopyDest/two: md5 = ceff7b9542285b1b2d17d24582361924 OK 2022/02/10 05:07:26 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/02/10 05:07:27 INFO : two: Copied (server-side copy) 2022/02/10 05:07:27 DEBUG : two: Destination found in --copy-dest, using server-side copy 2022/02/10 05:07:27 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7/dst': Waiting for checks to finish 2022/02/10 05:07:28 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/02/10 05:07:28 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/02/10 05:07:28 DEBUG : one: Unchanged skipping 2022/02/10 05:07:28 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7/dst': Waiting for transfers to finish 2022/02/10 05:07:28 DEBUG : Waiting for deletions to finish 2022/02/10 05:07:29 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7/dst': Waiting for checks to finish 2022/02/10 05:07:29 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/02/10 05:07:29 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/02/10 05:07:29 DEBUG : one: Unchanged skipping 2022/02/10 05:07:29 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/02/10 05:07:29 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/02/10 05:07:29 DEBUG : two: Unchanged skipping 2022/02/10 05:07:29 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7/dst': Waiting for transfers to finish 2022/02/10 05:07:29 DEBUG : Waiting for deletions to finish 2022/02/10 05:07:29 INFO : There was nothing to transfer 2022/02/10 05:07:31 DEBUG : CopyDest/three: md5 = 46fe2c29291d9ccdc9900b33cba4fc46 OK 2022/02/10 05:07:32 DEBUG : three: Sizes differ (src 7 vs dst 5) 2022/02/10 05:07:32 DEBUG : three: Destination not found in --copy-dest 2022/02/10 05:07:32 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7/dst': Waiting for checks to finish 2022/02/10 05:07:33 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/02/10 05:07:33 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/02/10 05:07:33 DEBUG : one: Unchanged skipping 2022/02/10 05:07:33 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/02/10 05:07:33 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/02/10 05:07:33 DEBUG : two: Unchanged skipping 2022/02/10 05:07:33 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7/dst': Waiting for transfers to finish 2022/02/10 05:07:34 DEBUG : three: md5 = bff1483d0161c876523004d535df5e88 OK 2022/02/10 05:07:34 INFO : three: Copied (new) 2022/02/10 05:07:34 DEBUG : Waiting for deletions to finish 2022/02/10 05:07:39 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "b6jdmn2b1adrhc8vikh7edr9os" 2022/02/10 05:07:39 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" 2022/02/10 05:07:39 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2022/02/10 05:07:40 DEBUG : d09o6po3f7bm6ce32vdgs8h9ls: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" 2022/02/10 05:07:40 DEBUG : d09o6po3f7bm6ce32vdgs8h9ls: Rmdir: contains trashed file: "b6jdmn2b1adrhc8vikh7edr9os" 2022/02/10 05:07:40 DEBUG : d09o6po3f7bm6ce32vdgs8h9ls: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2022/02/10 05:07:41 DEBUG : s6dbk3lfi7c9kfvo6j7bla9m0g: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" --- PASS: TestSyncCopyDest (40.31s) === RUN TestSyncBackupDir run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7'", Local "Local file system at /tmp/rclone4068820260", Modify Window "1ms" 2022/02/10 05:07:45 DEBUG : dst/one: md5 = d48082deb69d6a2333dd4f8f3fa8048a OK 2022/02/10 05:07:46 DEBUG : dst/two: md5 = 87c1b91cadd515cdca3d4fa58c321bad OK 2022/02/10 05:07:48 DEBUG : dst/three.txt: md5 = d9ced66ad737226588d0ab391dce93a5 OK 2022/02/10 05:07:49 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7/dst" 2022/02/10 05:07:49 DEBUG : Creating backend with remote "TestDrive:crypt/mfah1qr4afpbqv8tfvs11nuv7150h8cq3888svjder49859i7b2d2jgq72hb2fsjp1r43m4c63dnc/31u3jie661vd5p8j7rtc3hgbh0" 2022/02/10 05:07:50 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7/backup" 2022/02/10 05:07:50 DEBUG : Creating backend with remote "TestDrive:crypt/mfah1qr4afpbqv8tfvs11nuv7150h8cq3888svjder49859i7b2d2jgq72hb2fsjp1r43m4c63dnc/1nrff024r7pq65ecp72fc28jb0" 2022/02/10 05:07:52 DEBUG : one: Sizes differ (src 4 vs dst 3) 2022/02/10 05:07:52 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/02/10 05:07:52 DEBUG : two: Unchanged skipping 2022/02/10 05:07:52 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7/dst': Waiting for checks to finish 2022/02/10 05:07:54 INFO : one: Moved (server-side) 2022/02/10 05:07:54 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7/dst': Waiting for transfers to finish 2022/02/10 05:07:55 DEBUG : one: md5 = 1f99a9454d83334662db5d190ee05c71 OK 2022/02/10 05:07:55 INFO : one: Copied (new) 2022/02/10 05:07:55 DEBUG : Waiting for deletions to finish 2022/02/10 05:07:56 INFO : three.txt: Moved (server-side) 2022/02/10 05:07:56 INFO : three.txt: Moved into backup dir 2022/02/10 05:07:59 DEBUG : dst/three.txt: md5 = 3c9e0123b39d43c0a0f3bb83f086e80b OK 2022/02/10 05:07:59 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7/dst': Waiting for checks to finish 2022/02/10 05:07:59 DEBUG : one: Sizes differ (src 5 vs dst 4) 2022/02/10 05:07:59 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/02/10 05:07:59 DEBUG : two: Unchanged skipping 2022/02/10 05:08:00 INFO : one: Deleted 2022/02/10 05:08:01 INFO : one: Moved (server-side) 2022/02/10 05:08:01 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7/dst': Waiting for transfers to finish 2022/02/10 05:08:03 DEBUG : one: md5 = 8f009d9d86ecee1e75cf77b972bd5e2c OK 2022/02/10 05:08:03 INFO : one: Copied (new) 2022/02/10 05:08:03 DEBUG : Waiting for deletions to finish 2022/02/10 05:08:03 INFO : three.txt: Deleted 2022/02/10 05:08:04 INFO : three.txt: Moved (server-side) 2022/02/10 05:08:04 INFO : three.txt: Moved into backup dir 2022/02/10 05:08:08 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2022/02/10 05:08:08 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" 2022/02/10 05:08:09 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "tr2hj63d80ftlmvm6a952snjcc" 2022/02/10 05:08:09 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2022/02/10 05:08:09 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2022/02/10 05:08:09 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "tr2hj63d80ftlmvm6a952snjcc" --- PASS: TestSyncBackupDir (27.61s) === RUN TestSyncBackupDirWithSuffix run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7'", Local "Local file system at /tmp/rclone4068820260", Modify Window "1ms" 2022/02/10 05:08:12 DEBUG : dst/one: md5 = 95d844ef321bcbb5250950d3731b3be3 OK 2022/02/10 05:08:14 DEBUG : dst/two: md5 = 79459b7b2157ed8c32022b24da63fff6 OK 2022/02/10 05:08:15 DEBUG : dst/three.txt: md5 = 8faf3816e2258f53fdcf806b14cfa9ec OK 2022/02/10 05:08:16 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7/dst" 2022/02/10 05:08:16 DEBUG : Creating backend with remote "TestDrive:crypt/mfah1qr4afpbqv8tfvs11nuv7150h8cq3888svjder49859i7b2d2jgq72hb2fsjp1r43m4c63dnc/31u3jie661vd5p8j7rtc3hgbh0" 2022/02/10 05:08:17 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/02/10 05:08:17 DEBUG : pacer: Rate limited, increasing sleep to 1.922988143s 2022/02/10 05:08:17 DEBUG : pacer: Reducing sleep to 0s 2022/02/10 05:08:17 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7/backup" 2022/02/10 05:08:17 DEBUG : Creating backend with remote "TestDrive:crypt/mfah1qr4afpbqv8tfvs11nuv7150h8cq3888svjder49859i7b2d2jgq72hb2fsjp1r43m4c63dnc/1nrff024r7pq65ecp72fc28jb0" 2022/02/10 05:08:19 DEBUG : one: Sizes differ (src 4 vs dst 3) 2022/02/10 05:08:19 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/02/10 05:08:19 DEBUG : two: Unchanged skipping 2022/02/10 05:08:19 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7/dst': Waiting for checks to finish 2022/02/10 05:08:21 INFO : one: Moved (server-side) to: one.bak 2022/02/10 05:08:21 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7/dst': Waiting for transfers to finish 2022/02/10 05:08:22 DEBUG : one: md5 = 1fdfec83d19275471c6bf571186755e4 OK 2022/02/10 05:08:22 INFO : one: Copied (new) 2022/02/10 05:08:22 DEBUG : Waiting for deletions to finish 2022/02/10 05:08:23 INFO : three.txt: Moved (server-side) to: three.txt.bak 2022/02/10 05:08:23 INFO : three.txt: Moved into backup dir 2022/02/10 05:08:25 DEBUG : dst/three.txt: md5 = ed4af0962b8938f0213347730e754d70 OK 2022/02/10 05:08:26 DEBUG : one: Sizes differ (src 5 vs dst 4) 2022/02/10 05:08:26 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/02/10 05:08:26 DEBUG : two: Unchanged skipping 2022/02/10 05:08:26 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7/dst': Waiting for checks to finish 2022/02/10 05:08:27 INFO : one.bak: Deleted 2022/02/10 05:08:28 INFO : one: Moved (server-side) to: one.bak 2022/02/10 05:08:28 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7/dst': Waiting for transfers to finish 2022/02/10 05:08:29 DEBUG : one: md5 = 6a9fa441f4d8bba876059b3bd1bf638b OK 2022/02/10 05:08:29 INFO : one: Copied (new) 2022/02/10 05:08:29 DEBUG : Waiting for deletions to finish 2022/02/10 05:08:30 INFO : three.txt.bak: Deleted 2022/02/10 05:08:31 INFO : three.txt: Moved (server-side) to: three.txt.bak 2022/02/10 05:08:31 INFO : three.txt: Moved into backup dir 2022/02/10 05:08:35 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2022/02/10 05:08:35 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" 2022/02/10 05:08:36 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "sk91qgsqfn0r271r2ehsaoc20c" 2022/02/10 05:08:36 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "qltcak2uaegtmcoa8vijdppbp8" 2022/02/10 05:08:36 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "sk91qgsqfn0r271r2ehsaoc20c" 2022/02/10 05:08:36 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "qltcak2uaegtmcoa8vijdppbp8" --- PASS: TestSyncBackupDirWithSuffix (26.92s) === RUN TestSyncBackupDirWithSuffixKeepExtension run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7'", Local "Local file system at /tmp/rclone4068820260", Modify Window "1ms" 2022/02/10 05:08:39 DEBUG : dst/one: md5 = ea6c54aee07e24f449850b3475e70679 OK 2022/02/10 05:08:41 DEBUG : dst/two: md5 = 231ca10a13b8e3f1bb9880f7a1820d2e OK 2022/02/10 05:08:43 DEBUG : dst/three.txt: md5 = 11146360e5d17f82106efc35c1586533 OK 2022/02/10 05:08:43 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7/dst" 2022/02/10 05:08:43 DEBUG : Creating backend with remote "TestDrive:crypt/mfah1qr4afpbqv8tfvs11nuv7150h8cq3888svjder49859i7b2d2jgq72hb2fsjp1r43m4c63dnc/31u3jie661vd5p8j7rtc3hgbh0" 2022/02/10 05:08:44 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7/backup" 2022/02/10 05:08:44 DEBUG : Creating backend with remote "TestDrive:crypt/mfah1qr4afpbqv8tfvs11nuv7150h8cq3888svjder49859i7b2d2jgq72hb2fsjp1r43m4c63dnc/1nrff024r7pq65ecp72fc28jb0" 2022/02/10 05:08:46 DEBUG : one: Sizes differ (src 4 vs dst 3) 2022/02/10 05:08:46 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7/dst': Waiting for checks to finish 2022/02/10 05:08:46 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/02/10 05:08:46 DEBUG : two: Unchanged skipping 2022/02/10 05:08:48 INFO : one: Moved (server-side) to: one-2019-01-01 2022/02/10 05:08:48 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7/dst': Waiting for transfers to finish 2022/02/10 05:08:50 DEBUG : one: md5 = 3ef844e4b2aeb1b032439a2390c13e99 OK 2022/02/10 05:08:50 INFO : one: Copied (new) 2022/02/10 05:08:50 DEBUG : Waiting for deletions to finish 2022/02/10 05:08:51 INFO : three.txt: Moved (server-side) to: three-2019-01-01.txt 2022/02/10 05:08:51 INFO : three.txt: Moved into backup dir 2022/02/10 05:08:53 DEBUG : dst/three.txt: md5 = 8cae99e551be485d1e7112581b7a559b OK 2022/02/10 05:08:54 DEBUG : one: Sizes differ (src 5 vs dst 4) 2022/02/10 05:08:54 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/02/10 05:08:54 DEBUG : two: Unchanged skipping 2022/02/10 05:08:54 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7/dst': Waiting for checks to finish 2022/02/10 05:08:55 INFO : one-2019-01-01: Deleted 2022/02/10 05:08:55 INFO : one: Moved (server-side) to: one-2019-01-01 2022/02/10 05:08:55 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7/dst': Waiting for transfers to finish 2022/02/10 05:08:57 DEBUG : one: md5 = 8f8204483c649db0957bd9cfc9c8d681 OK 2022/02/10 05:08:57 INFO : one: Copied (new) 2022/02/10 05:08:57 DEBUG : Waiting for deletions to finish 2022/02/10 05:08:58 INFO : three-2019-01-01.txt: Deleted 2022/02/10 05:08:59 INFO : three.txt: Moved (server-side) to: three-2019-01-01.txt 2022/02/10 05:08:59 INFO : three.txt: Moved into backup dir 2022/02/10 05:09:02 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2022/02/10 05:09:02 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" 2022/02/10 05:09:03 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "jcjl1bv3ep0v8kt35lqql1co90" 2022/02/10 05:09:03 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "qtq2f6qq4lgpsmj88vb7147qje3prudmtfdtr2342fth58vo9a50" 2022/02/10 05:09:03 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "jcjl1bv3ep0v8kt35lqql1co90" 2022/02/10 05:09:03 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "qtq2f6qq4lgpsmj88vb7147qje3prudmtfdtr2342fth58vo9a50" --- PASS: TestSyncBackupDirWithSuffixKeepExtension (27.56s) === RUN TestSyncBackupDirSuffixOnly run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7'", Local "Local file system at /tmp/rclone4068820260", Modify Window "1ms" 2022/02/10 05:09:07 DEBUG : dst/one: md5 = dd2703b91d83f5ba385b093ccefcb36f OK 2022/02/10 05:09:08 DEBUG : dst/two: md5 = 7a4fd40fde0d7b1a41047d508e26622f OK 2022/02/10 05:09:10 DEBUG : dst/three.txt: md5 = 2d5d37a8d162cb8e56bade708ccd461a OK 2022/02/10 05:09:11 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7/dst" 2022/02/10 05:09:11 DEBUG : Creating backend with remote "TestDrive:crypt/mfah1qr4afpbqv8tfvs11nuv7150h8cq3888svjder49859i7b2d2jgq72hb2fsjp1r43m4c63dnc/31u3jie661vd5p8j7rtc3hgbh0" 2022/02/10 05:09:12 DEBUG : one: Sizes differ (src 4 vs dst 3) 2022/02/10 05:09:12 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7/dst': Waiting for checks to finish 2022/02/10 05:09:12 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/02/10 05:09:12 DEBUG : two: Unchanged skipping 2022/02/10 05:09:13 INFO : one: Moved (server-side) to: one.bak 2022/02/10 05:09:13 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7/dst': Waiting for transfers to finish 2022/02/10 05:09:14 DEBUG : one: md5 = b46b47157b1589e796184af60d03fd3b OK 2022/02/10 05:09:14 INFO : one: Copied (new) 2022/02/10 05:09:14 DEBUG : Waiting for deletions to finish 2022/02/10 05:09:15 INFO : three.txt: Moved (server-side) to: three.txt.bak 2022/02/10 05:09:15 INFO : three.txt: Moved into backup dir 2022/02/10 05:09:17 DEBUG : dst/three.txt: md5 = 0c9c323e63b366b117cc07a7009f1ad1 OK 2022/02/10 05:09:18 DEBUG : three.txt.bak: Excluded 2022/02/10 05:09:18 DEBUG : one.bak: Excluded 2022/02/10 05:09:18 DEBUG : one: Sizes differ (src 5 vs dst 4) 2022/02/10 05:09:18 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/02/10 05:09:18 DEBUG : two: Unchanged skipping 2022/02/10 05:09:18 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7/dst': Waiting for checks to finish 2022/02/10 05:09:19 INFO : one.bak: Deleted 2022/02/10 05:09:19 INFO : one: Moved (server-side) to: one.bak 2022/02/10 05:09:19 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7/dst': Waiting for transfers to finish 2022/02/10 05:09:21 DEBUG : one: md5 = 01314c85b56c956f8167f8084b75da79 OK 2022/02/10 05:09:21 INFO : one: Copied (new) 2022/02/10 05:09:21 DEBUG : Waiting for deletions to finish 2022/02/10 05:09:22 INFO : three.txt.bak: Deleted 2022/02/10 05:09:22 INFO : three.txt: Moved (server-side) to: three.txt.bak 2022/02/10 05:09:22 INFO : three.txt: Moved into backup dir 2022/02/10 05:09:26 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2022/02/10 05:09:26 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "sk91qgsqfn0r271r2ehsaoc20c" 2022/02/10 05:09:26 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "qltcak2uaegtmcoa8vijdppbp8" 2022/02/10 05:09:26 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "sk91qgsqfn0r271r2ehsaoc20c" 2022/02/10 05:09:26 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "qltcak2uaegtmcoa8vijdppbp8" 2022/02/10 05:09:26 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" --- PASS: TestSyncBackupDirSuffixOnly (23.04s) === RUN TestSyncSuffix run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7'", Local "Local file system at /tmp/rclone4068820260", Modify Window "1ms" 2022/02/10 05:09:30 DEBUG : dst/one: md5 = 88c9dd9b7d85cbc415981001900f60ea OK 2022/02/10 05:09:31 DEBUG : dst/two: md5 = 42e49d40d5f67547c50e5daa1ea43b6d OK 2022/02/10 05:09:33 DEBUG : dst/three.txt: md5 = 581b1f3f5cd792baef2c383c995f12f6 OK 2022/02/10 05:09:33 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7/dst" 2022/02/10 05:09:33 DEBUG : Creating backend with remote "TestDrive:crypt/mfah1qr4afpbqv8tfvs11nuv7150h8cq3888svjder49859i7b2d2jgq72hb2fsjp1r43m4c63dnc/31u3jie661vd5p8j7rtc3hgbh0" 2022/02/10 05:09:35 DEBUG : one: Sizes differ (src 4 vs dst 3) 2022/02/10 05:09:35 INFO : one: Moved (server-side) to: one.bak 2022/02/10 05:09:37 DEBUG : one: md5 = 7bdbf3971cb0c90a09a75f0e3242349e OK 2022/02/10 05:09:37 INFO : one: Copied (new) 2022/02/10 05:09:37 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/02/10 05:09:37 DEBUG : two: Unchanged skipping 2022/02/10 05:09:37 DEBUG : three.txt: Sizes differ (src 6 vs dst 5) 2022/02/10 05:09:38 INFO : three.txt: Moved (server-side) to: three.txt.bak 2022/02/10 05:09:40 DEBUG : three.txt: md5 = 791e12e3609d3b44b5b0ba55fa034e73 OK 2022/02/10 05:09:40 INFO : three.txt: Copied (new) 2022/02/10 05:09:41 DEBUG : one: Sizes differ (src 5 vs dst 4) 2022/02/10 05:09:42 INFO : one.bak: Deleted 2022/02/10 05:09:43 INFO : one: Moved (server-side) to: one.bak 2022/02/10 05:09:44 DEBUG : one: md5 = 9e8b6791e7f238f00b69e1ac34a42267 OK 2022/02/10 05:09:44 INFO : one: Copied (new) 2022/02/10 05:09:44 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/02/10 05:09:44 DEBUG : two: Unchanged skipping 2022/02/10 05:09:45 DEBUG : three.txt: Sizes differ (src 19 vs dst 6) 2022/02/10 05:09:46 INFO : three.txt.bak: Deleted 2022/02/10 05:09:46 INFO : three.txt: Moved (server-side) to: three.txt.bak 2022/02/10 05:09:48 DEBUG : three.txt: md5 = 51b6d98adcf7a9a94712bef4c71f4b4b OK 2022/02/10 05:09:48 INFO : three.txt: Copied (new) 2022/02/10 05:09:52 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2022/02/10 05:09:52 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "tr2hj63d80ftlmvm6a952snjcc" 2022/02/10 05:09:52 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "qltcak2uaegtmcoa8vijdppbp8" 2022/02/10 05:09:52 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "sk91qgsqfn0r271r2ehsaoc20c" 2022/02/10 05:09:52 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "sk91qgsqfn0r271r2ehsaoc20c" 2022/02/10 05:09:52 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" 2022/02/10 05:09:52 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "qltcak2uaegtmcoa8vijdppbp8" --- PASS: TestSyncSuffix (25.72s) === RUN TestSyncSuffixKeepExtension run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7'", Local "Local file system at /tmp/rclone4068820260", Modify Window "1ms" 2022/02/10 05:09:55 DEBUG : dst/one: md5 = 4c4ee94f6c1d617859c40855ba4c5b2f OK 2022/02/10 05:09:57 DEBUG : dst/two: md5 = 0189ba014391f514c88f17c508378fd0 OK 2022/02/10 05:09:59 DEBUG : dst/three.txt: md5 = 612fd9f575f65c9966554d22f6aaae20 OK 2022/02/10 05:09:59 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7/dst" 2022/02/10 05:09:59 DEBUG : Creating backend with remote "TestDrive:crypt/mfah1qr4afpbqv8tfvs11nuv7150h8cq3888svjder49859i7b2d2jgq72hb2fsjp1r43m4c63dnc/31u3jie661vd5p8j7rtc3hgbh0" 2022/02/10 05:10:00 DEBUG : one: Sizes differ (src 4 vs dst 3) 2022/02/10 05:10:01 INFO : one: Moved (server-side) to: one-2019-01-01 2022/02/10 05:10:03 DEBUG : one: md5 = ed80ddea812f309eac100425bbe0edf5 OK 2022/02/10 05:10:03 INFO : one: Copied (new) 2022/02/10 05:10:03 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/02/10 05:10:03 DEBUG : two: Unchanged skipping 2022/02/10 05:10:03 DEBUG : three.txt: Sizes differ (src 6 vs dst 5) 2022/02/10 05:10:04 INFO : three.txt: Moved (server-side) to: three-2019-01-01.txt 2022/02/10 05:10:06 DEBUG : three.txt: md5 = 5cd0831bc3634aeb49cd864f7d05c6e6 OK 2022/02/10 05:10:06 INFO : three.txt: Copied (new) 2022/02/10 05:10:07 DEBUG : one: Sizes differ (src 5 vs dst 4) 2022/02/10 05:10:08 INFO : one-2019-01-01: Deleted 2022/02/10 05:10:09 INFO : one: Moved (server-side) to: one-2019-01-01 2022/02/10 05:10:10 DEBUG : one: md5 = 39477a6cca1c1802836966341b51dde5 OK 2022/02/10 05:10:10 INFO : one: Copied (new) 2022/02/10 05:10:11 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/02/10 05:10:11 DEBUG : two: Unchanged skipping 2022/02/10 05:10:11 DEBUG : three.txt: Sizes differ (src 19 vs dst 6) 2022/02/10 05:10:12 INFO : three-2019-01-01.txt: Deleted 2022/02/10 05:10:12 INFO : three.txt: Moved (server-side) to: three-2019-01-01.txt 2022/02/10 05:10:14 DEBUG : three.txt: md5 = 68210a91860f0ecb7bda991c72e40210 OK 2022/02/10 05:10:14 INFO : three.txt: Copied (new) 2022/02/10 05:10:18 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "tr2hj63d80ftlmvm6a952snjcc" 2022/02/10 05:10:18 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2022/02/10 05:10:18 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "jcjl1bv3ep0v8kt35lqql1co90" 2022/02/10 05:10:18 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "qtq2f6qq4lgpsmj88vb7147qje3prudmtfdtr2342fth58vo9a50" 2022/02/10 05:10:18 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "qtq2f6qq4lgpsmj88vb7147qje3prudmtfdtr2342fth58vo9a50" 2022/02/10 05:10:18 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "jcjl1bv3ep0v8kt35lqql1co90" 2022/02/10 05:10:18 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" --- PASS: TestSyncSuffixKeepExtension (26.46s) === RUN TestSyncUTFNorm run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7'", Local "Local file system at /tmp/rclone4068820260", Modify Window "1ms" 2022/02/10 05:10:21 DEBUG : Testêé: md5 = 20e32b4cc22b44aef5cbc2a14003ae4d OK 2022/02/10 05:10:21 DEBUG : Testêé: Sizes differ (src 14 vs dst 18) 2022/02/10 05:10:21 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for checks to finish 2022/02/10 05:10:21 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for transfers to finish 2022/02/10 05:10:22 DEBUG : Testêé: md5 = 643ad6accc535fbac3f4a5a774d0ce84 OK 2022/02/10 05:10:22 INFO : Testêé: Copied (replaced existing) 2022/02/10 05:10:22 DEBUG : Waiting for deletions to finish --- PASS: TestSyncUTFNorm (4.51s) === RUN TestSyncImmutable run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7'", Local "Local file system at /tmp/rclone4068820260", Modify Window "1ms" 2022/02/10 05:10:24 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for checks to finish 2022/02/10 05:10:24 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for transfers to finish 2022/02/10 05:10:26 DEBUG : existing: md5 = 029d7ce1f49c73dbcc4e25c6473755b7 OK 2022/02/10 05:10:26 INFO : existing: Copied (new) 2022/02/10 05:10:26 DEBUG : Waiting for deletions to finish 2022/02/10 05:10:27 DEBUG : existing: Sizes differ (src 8 vs dst 6) 2022/02/10 05:10:27 ERROR : existing: Source and destination exist but do not match: immutable file modified 2022/02/10 05:10:27 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for checks to finish 2022/02/10 05:10:27 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for transfers to finish 2022/02/10 05:10:27 ERROR : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': not deleting files as there were IO errors 2022/02/10 05:10:27 ERROR : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': not deleting directories as there were IO errors --- PASS: TestSyncImmutable (4.55s) === RUN TestSyncIgnoreCase run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7'", Local "Local file system at /tmp/rclone4068820260", Modify Window "1ms" 2022/02/10 05:10:30 DEBUG : EXISTING: md5 = 4673f25245562098eabdac6b3dd5fb94 OK 2022/02/10 05:10:30 DEBUG : existing: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/02/10 05:10:30 DEBUG : existing: Unchanged skipping 2022/02/10 05:10:30 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for checks to finish 2022/02/10 05:10:30 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for transfers to finish 2022/02/10 05:10:30 DEBUG : Waiting for deletions to finish 2022/02/10 05:10:30 INFO : There was nothing to transfer --- PASS: TestSyncIgnoreCase (3.59s) === RUN TestMaxTransfer === RUN TestMaxTransfer/Hard run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7'", Local "Local file system at /tmp/rclone4068820260", 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-tutitiw5bifilob4cahuyag7'", Local "Local file system at /tmp/rclone4068820260", 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-tutitiw5bifilob4cahuyag7'", Local "Local file system at /tmp/rclone4068820260", Modify Window "1ms" sync_test.go:1989: This test only runs on local --- PASS: TestMaxTransfer (1.52s) --- SKIP: TestMaxTransfer/Hard (0.52s) --- SKIP: TestMaxTransfer/Soft (0.49s) --- SKIP: TestMaxTransfer/Cautious (0.51s) === RUN TestSyncConcurrentDelete run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7'", Local "Local file system at /tmp/rclone4068820260", Modify Window "1ms" 2022/02/10 05:10:35 DEBUG : both0: md5 = 4843182d92098d1e634061c519f1309b OK 2022/02/10 05:10:36 DEBUG : only0: md5 = e0bb6b4a9758983fd8fa0b2cfb276431 OK 2022/02/10 05:10:38 DEBUG : both1: md5 = f64ffdef58d1c0be791c19490f7bbca4 OK 2022/02/10 05:10:39 DEBUG : only1: md5 = ba13e174817e92b14c8cf8535eadabf2 OK 2022/02/10 05:10:41 DEBUG : both2: md5 = 1b3aca433c34aa42213ffdfec830ccfc OK 2022/02/10 05:10:42 DEBUG : only2: md5 = a7444a5ee8ad88a0c21bb27bd55cd522 OK 2022/02/10 05:10:44 DEBUG : both3: md5 = ac5413970b04164fe8f9935f7fef3cd4 OK 2022/02/10 05:10:45 DEBUG : only3: md5 = fe4986aa3566ff668861fe9a6367f148 OK 2022/02/10 05:10:47 DEBUG : both4: md5 = bf5ed411c26806b540fb2c9fce2bdbc1 OK 2022/02/10 05:10:48 DEBUG : only4: md5 = 29341c1ddac9971af219bb46d48e1518 OK 2022/02/10 05:10:50 DEBUG : both5: md5 = cd573cd7f868cdd472eab9bb334f56c8 OK 2022/02/10 05:10:51 DEBUG : only5: md5 = 1ab5d9bb5055e072881d03e3ceae8e91 OK 2022/02/10 05:10:53 DEBUG : both6: md5 = dfacd9188e2a7f90d4f07b3fb5da68a0 OK 2022/02/10 05:10:54 DEBUG : only6: md5 = 6fb1ad51c7af718dbbec4c017d0dc9ab OK 2022/02/10 05:10:56 DEBUG : both7: md5 = 88bc160e322e5b037718a97b2e85eb03 OK 2022/02/10 05:10:57 DEBUG : only7: md5 = f5eafc0598415c6ef6b9bde66fc8c58b OK 2022/02/10 05:10:59 DEBUG : both8: md5 = 12821342a9b57401a6a5424d2f719e91 OK 2022/02/10 05:11:01 DEBUG : only8: md5 = 10087b5e4418b3d09d3551447d9c30cd OK 2022/02/10 05:11:02 DEBUG : both9: md5 = 6cd8e92f5233326f91acba3a0c22039c OK 2022/02/10 05:11:04 DEBUG : only9: md5 = 24a9a68f8196673d80f036ff9a6c7e13 OK 2022/02/10 05:11:05 DEBUG : both10: md5 = 5662a9b24dfb436cf72b2843ae72295b OK 2022/02/10 05:11:07 DEBUG : only10: md5 = 839556dbf87ce5b06bce3ac18bc16e9d OK 2022/02/10 05:11:08 DEBUG : both11: md5 = 15418d76e9dfefd85c46588e46fe540f OK 2022/02/10 05:11:10 DEBUG : only11: md5 = e3180f4b36f98a0b4716bbef3d739fb5 OK 2022/02/10 05:11:11 DEBUG : both12: md5 = 1cc29a5eb552b67ed6fd62a8c643a3e6 OK 2022/02/10 05:11:13 DEBUG : only12: md5 = 7bc6d8141ac823b3581baafe8e0c18f7 OK 2022/02/10 05:11:14 DEBUG : both13: md5 = a9994b4b34cb9acdc45b755d1ecb4baa OK 2022/02/10 05:11:15 DEBUG : only13: md5 = a305bd9c6fc085af4a9c549936eea678 OK 2022/02/10 05:11:17 DEBUG : both14: md5 = 225682340036825ffc60b131b6399821 OK 2022/02/10 05:11:18 DEBUG : only14: md5 = 867964296153899a5b1ec2531a351003 OK 2022/02/10 05:11:20 DEBUG : both15: md5 = 955f208c71dc1b1583aac6089cbec7e8 OK 2022/02/10 05:11:22 DEBUG : only15: md5 = 8dd65f43c6631c04d6d16751a0da7471 OK 2022/02/10 05:11:23 DEBUG : both16: md5 = cc511a15635cffe670b4737b5c433b29 OK 2022/02/10 05:11:24 DEBUG : only16: md5 = 8f6855b7a5238c2ff48a15b0b2990437 OK 2022/02/10 05:11:26 DEBUG : both17: md5 = b26d7367e5689d8f4a5576764f46ab2b OK 2022/02/10 05:11:28 DEBUG : only17: md5 = fd564a326dcb44fffb33fd9a3052e490 OK 2022/02/10 05:11:30 DEBUG : both18: md5 = 66fa3e5bc80765e4b5d44f54f6e1dd15 OK 2022/02/10 05:11:31 DEBUG : only18: md5 = df36a89c2629ad72ec4d5e7f0037be82 OK 2022/02/10 05:11:33 DEBUG : both19: md5 = 45c5c62262b064dd15bda672201a5a1d OK 2022/02/10 05:11:34 DEBUG : only19: md5 = fa9d9063fe5e4d1c892b20dbfba10b91 OK 2022/02/10 05:11:35 DEBUG : both0: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/02/10 05:11:35 DEBUG : both1: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/02/10 05:11:35 DEBUG : both10: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/02/10 05:11:35 DEBUG : both10: Unchanged skipping 2022/02/10 05:11:35 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for checks to finish 2022/02/10 05:11:35 DEBUG : both12: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/02/10 05:11:35 DEBUG : both11: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/02/10 05:11:35 DEBUG : both12: Unchanged skipping 2022/02/10 05:11:35 DEBUG : both11: Unchanged skipping 2022/02/10 05:11:35 DEBUG : both13: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/02/10 05:11:35 DEBUG : both14: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/02/10 05:11:35 DEBUG : both13: Unchanged skipping 2022/02/10 05:11:35 DEBUG : both15: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/02/10 05:11:35 DEBUG : both15: Unchanged skipping 2022/02/10 05:11:35 DEBUG : both16: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/02/10 05:11:35 DEBUG : both16: Unchanged skipping 2022/02/10 05:11:35 DEBUG : both17: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/02/10 05:11:35 DEBUG : both17: Unchanged skipping 2022/02/10 05:11:35 DEBUG : both14: Unchanged skipping 2022/02/10 05:11:35 DEBUG : both18: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/02/10 05:11:35 DEBUG : both18: Unchanged skipping 2022/02/10 05:11:35 DEBUG : both19: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/02/10 05:11:35 DEBUG : both2: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/02/10 05:11:35 DEBUG : both19: Unchanged skipping 2022/02/10 05:11:35 DEBUG : both0: Unchanged skipping 2022/02/10 05:11:35 DEBUG : both3: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/02/10 05:11:35 DEBUG : both1: Unchanged skipping 2022/02/10 05:11:35 DEBUG : both3: Unchanged skipping 2022/02/10 05:11:35 DEBUG : both6: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/02/10 05:11:35 DEBUG : both5: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/02/10 05:11:35 DEBUG : both4: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/02/10 05:11:35 DEBUG : both2: Unchanged skipping 2022/02/10 05:11:35 DEBUG : both5: Unchanged skipping 2022/02/10 05:11:35 DEBUG : both7: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/02/10 05:11:35 DEBUG : both4: Unchanged skipping 2022/02/10 05:11:35 DEBUG : both7: Unchanged skipping 2022/02/10 05:11:35 DEBUG : both9: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/02/10 05:11:35 DEBUG : both8: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/02/10 05:11:35 DEBUG : both9: Unchanged skipping 2022/02/10 05:11:35 DEBUG : both8: Unchanged skipping 2022/02/10 05:11:35 DEBUG : both6: Unchanged skipping 2022/02/10 05:11:35 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for transfers to finish 2022/02/10 05:11:35 DEBUG : Waiting for deletions to finish 2022/02/10 05:11:36 INFO : only0: Deleted 2022/02/10 05:11:36 INFO : only4: Deleted 2022/02/10 05:11:36 INFO : only9: Deleted 2022/02/10 05:11:36 INFO : only1: Deleted 2022/02/10 05:11:36 INFO : only10: Deleted 2022/02/10 05:11:36 INFO : only16: Deleted 2022/02/10 05:11:37 INFO : only19: Deleted 2022/02/10 05:11:37 INFO : only13: Deleted 2022/02/10 05:11:37 INFO : only2: Deleted 2022/02/10 05:11:37 INFO : only3: Deleted 2022/02/10 05:11:37 INFO : only6: Deleted 2022/02/10 05:11:37 INFO : only7: Deleted 2022/02/10 05:11:37 INFO : only11: Deleted 2022/02/10 05:11:38 INFO : only15: Deleted 2022/02/10 05:11:38 INFO : only17: Deleted 2022/02/10 05:11:38 INFO : only5: Deleted 2022/02/10 05:11:38 INFO : only12: Deleted 2022/02/10 05:11:38 INFO : only14: Deleted 2022/02/10 05:11:38 INFO : only8: Deleted 2022/02/10 05:11:38 INFO : only18: Deleted 2022/02/10 05:11:38 INFO : There was nothing to transfer --- PASS: TestSyncConcurrentDelete (77.25s) === RUN TestSyncConcurrentTruncate run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7'", Local "Local file system at /tmp/rclone4068820260", Modify Window "1ms" 2022/02/10 05:11:52 DEBUG : both0: md5 = b0ff79f3382987082b1cbdfdbfeadf11 OK 2022/02/10 05:11:54 DEBUG : only0: md5 = 0af5edef8be3a8900ee1e493fffa5a83 OK 2022/02/10 05:11:55 DEBUG : both1: md5 = 728cb9289c205760a288660a66f13112 OK 2022/02/10 05:11:56 DEBUG : only1: md5 = fd0f8f048a6052219a0d1adad6c8e903 OK 2022/02/10 05:11:58 DEBUG : both2: md5 = caf1c510dc497ed150f2b3a05a95f1bc OK 2022/02/10 05:12:00 DEBUG : only2: md5 = 476cc6cc1b8403623e7bf65b94f38700 OK 2022/02/10 05:12:01 DEBUG : both3: md5 = ac94f622bae2f12cd7a6e22442090386 OK 2022/02/10 05:12:03 DEBUG : only3: md5 = 320bc1043dcb255735c4ad760b91a57d OK 2022/02/10 05:12:04 DEBUG : both4: md5 = a4919c97a8c0c998f8dac5633643a01d OK 2022/02/10 05:12:06 DEBUG : only4: md5 = f152fb1cb3ddfddc1399a61e81bccec1 OK 2022/02/10 05:12:07 DEBUG : both5: md5 = 221fc5654a02ec1f46e8afbd281ec20f OK 2022/02/10 05:12:08 DEBUG : only5: md5 = b6f4dbcf4668484f86689b8a6629f044 OK 2022/02/10 05:12:10 DEBUG : both6: md5 = 6f8ce37f75b83885d01d4727cbf4ab8b OK 2022/02/10 05:12:12 DEBUG : only6: md5 = 0e382c369a751fe1412f9971191c1859 OK 2022/02/10 05:12:13 DEBUG : both7: md5 = 2889e9c58c7d5f29da2ec901601175bc OK 2022/02/10 05:12:15 DEBUG : only7: md5 = dce54e046fc9a281e369cbc326d2d766 OK 2022/02/10 05:12:16 DEBUG : both8: md5 = 86fcb65015018bb733d6b406a30e7e1b OK 2022/02/10 05:12:18 DEBUG : only8: md5 = 4c69617a39e14055f494e0bcfe694d37 OK 2022/02/10 05:12:19 DEBUG : both9: md5 = 51f832ebb8403181da436760f29664fa OK 2022/02/10 05:12:21 DEBUG : only9: md5 = 973a834b6e9920f07e77e4709b6c4731 OK 2022/02/10 05:12:22 DEBUG : both10: md5 = 60545b57f9f64ae78a77cb363bc32097 OK 2022/02/10 05:12:24 DEBUG : only10: md5 = 268faf5f92c99d5f3a580a8ded8062aa OK 2022/02/10 05:12:26 DEBUG : both11: md5 = 7d023aa37ddb35def0038228ad81bf2e OK 2022/02/10 05:12:27 DEBUG : only11: md5 = efec957f637a2a7aeafe69aa556e679b OK 2022/02/10 05:12:29 DEBUG : both12: md5 = 4662b1f9db9c7659c3efef05d0ce3f4a OK 2022/02/10 05:12:30 DEBUG : only12: md5 = 2c1a767e3ab418aaabf98ed8e82da00b OK 2022/02/10 05:12:32 DEBUG : both13: md5 = 5b76250eaeae01e86f617e64c746eb25 OK 2022/02/10 05:12:33 DEBUG : only13: md5 = 733f50748b098d871c6e7ab6d490cbac OK 2022/02/10 05:12:35 DEBUG : both14: md5 = 24db7fce52afde95b87f15d4e5d4c996 OK 2022/02/10 05:12:36 DEBUG : only14: md5 = 06cdd56875715baa7ef89ff132abc8e3 OK 2022/02/10 05:12:38 DEBUG : both15: md5 = 5ba972db81f1e1944a53e3fb60e750b2 OK 2022/02/10 05:12:39 DEBUG : only15: md5 = 031fec3aa3987896354968bb81e3a735 OK 2022/02/10 05:12:41 DEBUG : both16: md5 = 4d810183add195be348b3f23c028d217 OK 2022/02/10 05:12:42 DEBUG : only16: md5 = db06b74831cbd4a5abb9b96c11879aed OK 2022/02/10 05:12:43 DEBUG : both17: md5 = ad4eed649f8b8e766f34f3678e2ae8ef OK 2022/02/10 05:12:45 DEBUG : only17: md5 = 5527e836ca9fb1145bfdd1a66ca278ba OK 2022/02/10 05:12:46 DEBUG : both18: md5 = 6d07302536a15c7c56ef3013392c2481 OK 2022/02/10 05:12:48 DEBUG : only18: md5 = 274a53c97b7d801f54013bf36363ae2e OK 2022/02/10 05:12:49 DEBUG : both19: md5 = 3d7aeb3a7f8928ae7f8ebed82c5eaab8 OK 2022/02/10 05:12:51 DEBUG : only19: md5 = e0589d7ed4400b9cb4d21b00f6891af8 OK 2022/02/10 05:12:52 DEBUG : both0: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/02/10 05:12:52 DEBUG : both0: Unchanged skipping 2022/02/10 05:12:52 DEBUG : both10: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/02/10 05:12:52 DEBUG : both12: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/02/10 05:12:52 DEBUG : both12: Unchanged skipping 2022/02/10 05:12:52 DEBUG : both10: Unchanged skipping 2022/02/10 05:12:52 DEBUG : both13: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/02/10 05:12:52 DEBUG : both13: Unchanged skipping 2022/02/10 05:12:52 DEBUG : both14: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/02/10 05:12:52 DEBUG : both1: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/02/10 05:12:52 DEBUG : both15: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/02/10 05:12:52 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for checks to finish 2022/02/10 05:12:52 DEBUG : both15: Unchanged skipping 2022/02/10 05:12:52 DEBUG : both14: Unchanged skipping 2022/02/10 05:12:52 DEBUG : both16: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/02/10 05:12:52 DEBUG : both17: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/02/10 05:12:52 DEBUG : both11: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/02/10 05:12:52 DEBUG : both16: Unchanged skipping 2022/02/10 05:12:52 DEBUG : both11: Unchanged skipping 2022/02/10 05:12:52 DEBUG : both18: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/02/10 05:12:52 DEBUG : both18: Unchanged skipping 2022/02/10 05:12:52 DEBUG : both17: Unchanged skipping 2022/02/10 05:12:52 DEBUG : both2: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/02/10 05:12:52 DEBUG : both3: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/02/10 05:12:52 DEBUG : both3: Unchanged skipping 2022/02/10 05:12:52 DEBUG : both4: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/02/10 05:12:52 DEBUG : both4: Unchanged skipping 2022/02/10 05:12:52 DEBUG : both5: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/02/10 05:12:52 DEBUG : both5: Unchanged skipping 2022/02/10 05:12:52 DEBUG : both6: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/02/10 05:12:52 DEBUG : both6: Unchanged skipping 2022/02/10 05:12:52 DEBUG : both7: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/02/10 05:12:52 DEBUG : both7: Unchanged skipping 2022/02/10 05:12:52 DEBUG : both8: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/02/10 05:12:52 DEBUG : both8: Unchanged skipping 2022/02/10 05:12:52 DEBUG : both9: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/02/10 05:12:52 DEBUG : both9: Unchanged skipping 2022/02/10 05:12:52 DEBUG : only0: Sizes differ (src 0 vs dst 6) 2022/02/10 05:12:52 DEBUG : only1: Sizes differ (src 0 vs dst 6) 2022/02/10 05:12:52 DEBUG : only10: Sizes differ (src 0 vs dst 6) 2022/02/10 05:12:52 DEBUG : only11: Sizes differ (src 0 vs dst 6) 2022/02/10 05:12:52 DEBUG : only12: Sizes differ (src 0 vs dst 6) 2022/02/10 05:12:52 DEBUG : only13: Sizes differ (src 0 vs dst 6) 2022/02/10 05:12:52 DEBUG : only14: Sizes differ (src 0 vs dst 6) 2022/02/10 05:12:52 DEBUG : only15: Sizes differ (src 0 vs dst 6) 2022/02/10 05:12:52 DEBUG : only16: Sizes differ (src 0 vs dst 6) 2022/02/10 05:12:52 DEBUG : only17: Sizes differ (src 0 vs dst 6) 2022/02/10 05:12:52 DEBUG : only18: Sizes differ (src 0 vs dst 6) 2022/02/10 05:12:52 DEBUG : only19: Sizes differ (src 0 vs dst 6) 2022/02/10 05:12:52 DEBUG : only2: Sizes differ (src 0 vs dst 6) 2022/02/10 05:12:52 DEBUG : only3: Sizes differ (src 0 vs dst 6) 2022/02/10 05:12:52 DEBUG : both19: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/02/10 05:12:52 DEBUG : both19: Unchanged skipping 2022/02/10 05:12:52 DEBUG : only5: Sizes differ (src 0 vs dst 6) 2022/02/10 05:12:52 DEBUG : only6: Sizes differ (src 0 vs dst 6) 2022/02/10 05:12:52 DEBUG : only7: Sizes differ (src 0 vs dst 6) 2022/02/10 05:12:52 DEBUG : only8: Sizes differ (src 0 vs dst 6) 2022/02/10 05:12:52 DEBUG : only9: Sizes differ (src 0 vs dst 6) 2022/02/10 05:12:52 DEBUG : both2: Unchanged skipping 2022/02/10 05:12:52 DEBUG : both1: Unchanged skipping 2022/02/10 05:12:52 DEBUG : only4: Sizes differ (src 0 vs dst 6) 2022/02/10 05:12:52 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Waiting for transfers to finish 2022/02/10 05:12:53 DEBUG : only0: md5 = 4a39bccc029c3e5fec940a0c684059a7 OK 2022/02/10 05:12:53 INFO : only0: Copied (replaced existing) 2022/02/10 05:12:53 DEBUG : only11: md5 = 7d06c93ef7fb60c58d79b213842de88f OK 2022/02/10 05:12:53 INFO : only11: Copied (replaced existing) 2022/02/10 05:12:53 DEBUG : only1: md5 = 584ef70f486af946f7deec61b2c4b13f OK 2022/02/10 05:12:53 INFO : only1: Copied (replaced existing) 2022/02/10 05:12:53 DEBUG : only10: md5 = 0beae3c470e048c832d0757d76a7d714 OK 2022/02/10 05:12:53 INFO : only10: Copied (replaced existing) 2022/02/10 05:12:54 DEBUG : only12: md5 = ff5b73ca6295be46619c4de51299cd6c OK 2022/02/10 05:12:54 INFO : only12: Copied (replaced existing) 2022/02/10 05:12:54 DEBUG : only13: md5 = 6d9d4bc70c75a963f9a660bdcdbb4bef OK 2022/02/10 05:12:54 INFO : only13: Copied (replaced existing) 2022/02/10 05:12:54 DEBUG : only15: md5 = bb0c57788b5f04c5bfe6f4375a3973d0 OK 2022/02/10 05:12:54 INFO : only15: Copied (replaced existing) 2022/02/10 05:12:54 DEBUG : only14: md5 = a4acbdaf4f99b7424374b0a42e7058f2 OK 2022/02/10 05:12:54 INFO : only14: Copied (replaced existing) 2022/02/10 05:12:55 DEBUG : only16: md5 = 8c020cd82c56326bee355c38888ac1a2 OK 2022/02/10 05:12:55 INFO : only16: Copied (replaced existing) 2022/02/10 05:12:55 DEBUG : only17: md5 = 65724f3ad101656c600741bea2a8620d OK 2022/02/10 05:12:55 INFO : only17: Copied (replaced existing) 2022/02/10 05:12:55 DEBUG : only18: md5 = ba9da992bbc460c68b2d6a71de519687 OK 2022/02/10 05:12:55 INFO : only18: Copied (replaced existing) 2022/02/10 05:12:56 DEBUG : only19: md5 = eb02409287cbdd73218f3f8b7fc9ddd6 OK 2022/02/10 05:12:56 INFO : only19: Copied (replaced existing) 2022/02/10 05:12:56 DEBUG : only2: md5 = 5d515a8ef5bd979dfa3ad14802965a1a OK 2022/02/10 05:12:56 INFO : only2: Copied (replaced existing) 2022/02/10 05:12:56 DEBUG : only3: md5 = 87761e229a57846baf7c89e586529ada OK 2022/02/10 05:12:56 INFO : only3: Copied (replaced existing) 2022/02/10 05:12:57 DEBUG : only5: md5 = eb758a9019bb38ef864d01dd4013e78c OK 2022/02/10 05:12:57 INFO : only5: Copied (replaced existing) 2022/02/10 05:12:57 DEBUG : only6: md5 = a57f66e52e334315cb341b4373628c5d OK 2022/02/10 05:12:57 INFO : only6: Copied (replaced existing) 2022/02/10 05:12:57 DEBUG : only8: md5 = eda7a1c7d4c7fd43472e868286ab1c13 OK 2022/02/10 05:12:57 INFO : only8: Copied (replaced existing) 2022/02/10 05:12:57 DEBUG : only7: md5 = 42ea611f9f9a0d350b3c5cca13a208bb OK 2022/02/10 05:12:57 INFO : only7: Copied (replaced existing) 2022/02/10 05:12:58 DEBUG : only9: md5 = 0ed85f57d4b589b47d4bc0b5a693da5d OK 2022/02/10 05:12:58 INFO : only9: Copied (replaced existing) 2022/02/10 05:12:58 DEBUG : only4: md5 = e111a958ea1226b4840a60357b7cf06e OK 2022/02/10 05:12:58 INFO : only4: Copied (replaced existing) 2022/02/10 05:12:58 DEBUG : Waiting for deletions to finish --- PASS: TestSyncConcurrentTruncate (91.35s) PASS 2022/02/10 05:13:22 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tutitiw5bifilob4cahuyag7': Purge remote "./sync.test -test.v -test.timeout 1h0m0s -remote TestCryptDrive: -verbose" - Finished OK in 13m8.797334158s (try 1/5)