"./sync.test -test.v -test.timeout 1h0m0s -remote TestCryptDrive: -verbose -fast-list" - Starting (try 1/5) 2021/04/05 05:03:02 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6" 2021/04/05 05:03:03 DEBUG : Creating backend with remote "TestDrive:crypt/re61b925b532g0toajvd6jkl8kvrnsr61om6jcbvpu8cb7u4skmggci49igg4sntaeibenodi7hu6" 2021/04/05 05:03:04 DEBUG : Creating backend with remote "/tmp/rclone638061947" === RUN TestPipe --- PASS: TestPipe (0.00s) === RUN TestPipeConcurrent --- PASS: TestPipeConcurrent (0.10s) === 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:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6'", Local "Local file system at /tmp/rclone638061947", Modify Window "1ms" 2021/04/05 05:03:05 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for checks to finish 2021/04/05 05:03:05 NOTICE: sub dir/hello world: Skipped copy as --dry-run is set (size 11) 2021/04/05 05:03:05 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for transfers to finish --- PASS: TestCopyWithDryRun (1.82s) === RUN TestCopy run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6'", Local "Local file system at /tmp/rclone638061947", Modify Window "1ms" 2021/04/05 05:03:06 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for checks to finish 2021/04/05 05:03:06 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for transfers to finish 2021/04/05 05:03:08 DEBUG : sub dir/hello world: MD5 = 78b1520a2193c4be1e393c59f5f14d32 OK 2021/04/05 05:03:08 INFO : sub dir/hello world: Copied (new) 2021/04/05 05:03:09 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestCopy (4.38s) === RUN TestCopyMissingDirectory run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6'", Local "Local file system at /tmp/rclone638061947", Modify Window "1ms" 2021/04/05 05:03:10 DEBUG : Creating backend with remote "/non-existing" 2021/04/05 05:03:10 ERROR : : error reading source directory: directory not found 2021/04/05 05:03:10 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for checks to finish 2021/04/05 05:03:10 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for transfers to finish --- PASS: TestCopyMissingDirectory (0.58s) === RUN TestCopyNoTraverse run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6'", Local "Local file system at /tmp/rclone638061947", Modify Window "1ms" 2021/04/05 05:03:11 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for checks to finish 2021/04/05 05:03:11 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for transfers to finish 2021/04/05 05:03:13 DEBUG : sub dir/hello world: MD5 = a8e44e5ceb3fa128c9160d2cd1114687 OK 2021/04/05 05:03:13 INFO : sub dir/hello world: Copied (new) 2021/04/05 05:03:15 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestCopyNoTraverse (4.69s) === RUN TestCopyCheckFirst run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6'", Local "Local file system at /tmp/rclone638061947", Modify Window "1ms" 2021/04/05 05:03:15 INFO : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Running all checks before starting transfers 2021/04/05 05:03:15 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for checks to finish 2021/04/05 05:03:15 INFO : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Checks finished, now starting transfers 2021/04/05 05:03:15 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for transfers to finish 2021/04/05 05:03:18 DEBUG : sub dir/hello world: MD5 = 93c75597bb04af9d491a5876f00282ec OK 2021/04/05 05:03:18 INFO : sub dir/hello world: Copied (new) 2021/04/05 05:03:19 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestCopyCheckFirst (4.70s) === RUN TestSyncNoTraverse run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6'", Local "Local file system at /tmp/rclone638061947", Modify Window "1ms" 2021/04/05 05:03:20 ERROR : Ignoring --no-traverse with sync 2021/04/05 05:03:20 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for checks to finish 2021/04/05 05:03:20 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for transfers to finish 2021/04/05 05:03:22 DEBUG : sub dir/hello world: MD5 = 9265f7ced03c8eb048e96a1f8790747c OK 2021/04/05 05:03:22 INFO : sub dir/hello world: Copied (new) 2021/04/05 05:03:22 DEBUG : Waiting for deletions to finish 2021/04/05 05:03:24 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestSyncNoTraverse (4.53s) === RUN TestCopyWithDepth run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6'", Local "Local file system at /tmp/rclone638061947", Modify Window "1ms" 2021/04/05 05:03:25 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for checks to finish 2021/04/05 05:03:25 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for transfers to finish 2021/04/05 05:03:26 DEBUG : hello world2: MD5 = bbe98e17b57ec99e7256ef9585d9afc3 OK 2021/04/05 05:03:26 INFO : hello world2: Copied (new) --- PASS: TestCopyWithDepth (2.66s) === RUN TestCopyWithFilesFrom run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6'", Local "Local file system at /tmp/rclone638061947", Modify Window "1ms" 2021/04/05 05:03:27 DEBUG : hello world2: Excluded 2021/04/05 05:03:27 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for checks to finish 2021/04/05 05:03:27 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for transfers to finish 2021/04/05 05:03:29 DEBUG : potato2: MD5 = ad77a7767026cf91ce3055fad4d283e4 OK 2021/04/05 05:03:29 INFO : potato2: Copied (new) --- PASS: TestCopyWithFilesFrom (2.58s) === RUN TestCopyWithFilesFromAndNoTraverse run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6'", Local "Local file system at /tmp/rclone638061947", Modify Window "1ms" 2021/04/05 05:03:30 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for checks to finish 2021/04/05 05:03:30 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for transfers to finish 2021/04/05 05:03:31 DEBUG : potato2: MD5 = 60fd5f18447c00ae83a6e6da2aac3c3c OK 2021/04/05 05:03:31 INFO : potato2: Copied (new) --- PASS: TestCopyWithFilesFromAndNoTraverse (2.59s) === RUN TestCopyEmptyDirectories run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6'", Local "Local file system at /tmp/rclone638061947", Modify Window "1ms" 2021/04/05 05:03:32 DEBUG : sub dir2: Making directory 2021/04/05 05:03:33 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for checks to finish 2021/04/05 05:03:33 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for transfers to finish 2021/04/05 05:03:35 DEBUG : sub dir/hello world: MD5 = c03aa8a89e0aea7aae5695d292c93540 OK 2021/04/05 05:03:35 INFO : sub dir/hello world: Copied (new) 2021/04/05 05:03:35 DEBUG : sub dir2: Making directory 2021/04/05 05:03:36 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': copied 1 directories 2021/04/05 05:03:38 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestCopyEmptyDirectories (5.93s) === RUN TestMoveEmptyDirectories run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6'", Local "Local file system at /tmp/rclone638061947", Modify Window "1ms" 2021/04/05 05:03:38 DEBUG : sub dir2: Making directory 2021/04/05 05:03:39 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for checks to finish 2021/04/05 05:03:39 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for transfers to finish 2021/04/05 05:03:41 DEBUG : sub dir/hello world: MD5 = a887eeff53b5ce2f5147be73bde2314a OK 2021/04/05 05:03:41 INFO : sub dir/hello world: Copied (new) 2021/04/05 05:03:41 INFO : sub dir/hello world: Deleted 2021/04/05 05:03:41 DEBUG : sub dir: Making directory 2021/04/05 05:03:41 DEBUG : sub dir2: Making directory 2021/04/05 05:03:41 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': copied 2 directories 2021/04/05 05:03:44 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestMoveEmptyDirectories (5.99s) === RUN TestSyncEmptyDirectories run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6'", Local "Local file system at /tmp/rclone638061947", Modify Window "1ms" 2021/04/05 05:03:44 DEBUG : sub dir2: Making directory 2021/04/05 05:03:44 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for checks to finish 2021/04/05 05:03:44 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for transfers to finish 2021/04/05 05:03:47 DEBUG : sub dir/hello world: MD5 = 219c54c640054bb465eab96818273243 OK 2021/04/05 05:03:47 INFO : sub dir/hello world: Copied (new) 2021/04/05 05:03:47 DEBUG : sub dir2: Making directory 2021/04/05 05:03:48 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': copied 1 directories 2021/04/05 05:03:48 DEBUG : Waiting for deletions to finish 2021/04/05 05:03:50 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestSyncEmptyDirectories (6.36s) === RUN TestServerSideCopy run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6'", Local "Local file system at /tmp/rclone638061947", Modify Window "1ms" 2021/04/05 05:03:53 DEBUG : sub dir/hello world: MD5 = a01aa48f4e0e9cb656f14139f2894316 OK 2021/04/05 05:03:53 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-zaxutam1zalefix5revifaj0" 2021/04/05 05:03:53 DEBUG : Creating backend with remote "TestDrive:crypt/o3og50kji44httg5ee511eg676u6sre8608dvi04k6apnp176tpi6if99k5b9as6qt1o5s55blt3q" sync_test.go:281: Server side copy (if possible) Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6' -> Encrypted drive 'TestCryptDrive:rclone-test-zaxutam1zalefix5revifaj0' 2021/04/05 05:03:55 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-zaxutam1zalefix5revifaj0': Waiting for checks to finish 2021/04/05 05:03:55 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-zaxutam1zalefix5revifaj0': Waiting for transfers to finish 2021/04/05 05:03:57 INFO : sub dir/hello world: Copied (server-side copy) 2021/04/05 05:03:58 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-zaxutam1zalefix5revifaj0': Purge remote 2021/04/05 05:03:59 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestServerSideCopy (9.28s) === RUN TestCopyAfterDelete run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6'", Local "Local file system at /tmp/rclone638061947", Modify Window "1ms" 2021/04/05 05:04:02 DEBUG : sub dir/hello world: MD5 = b3c0214218f8858f1933c3fae2ec8dfb OK 2021/04/05 05:04:02 ERROR : : error listing: directory not found 2021/04/05 05:04:02 DEBUG : Local file system at /tmp/rclone638061947: Making directory 2021/04/05 05:04:03 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for checks to finish 2021/04/05 05:04:03 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for transfers to finish 2021/04/05 05:04:04 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestCopyAfterDelete (5.06s) === RUN TestCopyRedownload run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6'", Local "Local file system at /tmp/rclone638061947", Modify Window "1ms" 2021/04/05 05:04:07 DEBUG : sub dir/hello world: MD5 = e79f08f4ae6270983ab07fa5c87a66f2 OK 2021/04/05 05:04:08 DEBUG : Local file system at /tmp/rclone638061947: Waiting for checks to finish 2021/04/05 05:04:08 DEBUG : Local file system at /tmp/rclone638061947: Waiting for transfers to finish 2021/04/05 05:04:09 INFO : sub dir/hello world: Copied (new) 2021/04/05 05:04:10 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestCopyRedownload (5.42s) === RUN TestSyncBasedOnCheckSum run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6'", Local "Local file system at /tmp/rclone638061947", Modify Window "1ms" 2021/04/05 05:04:11 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for checks to finish 2021/04/05 05:04:11 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for transfers to finish 2021/04/05 05:04:12 DEBUG : check sum: MD5 = 17d78dd61ab522db078dd247510eb003 OK 2021/04/05 05:04:12 INFO : check sum: Copied (new) 2021/04/05 05:04:12 DEBUG : Waiting for deletions to finish 2021/04/05 05:04:13 NOTICE: Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': --checksum is in use but the source and destination have no hashes in common; falling back to --size-only 2021/04/05 05:04:13 DEBUG : check sum: Size of src and dst objects identical 2021/04/05 05:04:13 DEBUG : check sum: Unchanged skipping 2021/04/05 05:04:13 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for checks to finish 2021/04/05 05:04:13 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for transfers to finish 2021/04/05 05:04:13 DEBUG : Waiting for deletions to finish 2021/04/05 05:04:13 INFO : There was nothing to transfer --- PASS: TestSyncBasedOnCheckSum (3.41s) === RUN TestSyncSizeOnly run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6'", Local "Local file system at /tmp/rclone638061947", Modify Window "1ms" 2021/04/05 05:04:14 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for checks to finish 2021/04/05 05:04:14 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for transfers to finish 2021/04/05 05:04:15 DEBUG : sizeonly: MD5 = 96aeadab83d753200d34355d38264525 OK 2021/04/05 05:04:15 INFO : sizeonly: Copied (new) 2021/04/05 05:04:15 DEBUG : Waiting for deletions to finish 2021/04/05 05:04:16 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for checks to finish 2021/04/05 05:04:16 DEBUG : sizeonly: Sizes identical 2021/04/05 05:04:16 DEBUG : sizeonly: Unchanged skipping 2021/04/05 05:04:16 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for transfers to finish 2021/04/05 05:04:16 DEBUG : Waiting for deletions to finish 2021/04/05 05:04:16 INFO : There was nothing to transfer --- PASS: TestSyncSizeOnly (2.90s) === RUN TestSyncIgnoreSize run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6'", Local "Local file system at /tmp/rclone638061947", Modify Window "1ms" 2021/04/05 05:04:17 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for checks to finish 2021/04/05 05:04:17 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for transfers to finish 2021/04/05 05:04:18 DEBUG : ignore-size: MD5 = 0f86734d1f576d2c0a8a39ec0da5f5d0 OK 2021/04/05 05:04:18 INFO : ignore-size: Copied (new) 2021/04/05 05:04:18 DEBUG : Waiting for deletions to finish 2021/04/05 05:04:19 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for checks to finish 2021/04/05 05:04:19 DEBUG : ignore-size: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2021/04/05 05:04:19 DEBUG : ignore-size: Unchanged skipping 2021/04/05 05:04:19 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for transfers to finish 2021/04/05 05:04:19 DEBUG : Waiting for deletions to finish 2021/04/05 05:04:19 INFO : There was nothing to transfer --- PASS: TestSyncIgnoreSize (2.87s) === RUN TestSyncIgnoreTimes run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6'", Local "Local file system at /tmp/rclone638061947", Modify Window "1ms" 2021/04/05 05:04:21 DEBUG : existing: MD5 = 12cbfc6bfd89d23f2ad31f6a1cde94a4 OK 2021/04/05 05:04:21 DEBUG : existing: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2021/04/05 05:04:21 DEBUG : existing: Unchanged skipping 2021/04/05 05:04:21 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for checks to finish 2021/04/05 05:04:21 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for transfers to finish 2021/04/05 05:04:21 DEBUG : Waiting for deletions to finish 2021/04/05 05:04:21 INFO : There was nothing to transfer 2021/04/05 05:04:21 DEBUG : existing: Transferring unconditionally as --ignore-times is in use 2021/04/05 05:04:21 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for checks to finish 2021/04/05 05:04:21 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for transfers to finish 2021/04/05 05:04:22 DEBUG : existing: MD5 = 45a89b24467b3dee2e29bebcbc57a7e8 OK 2021/04/05 05:04:22 INFO : existing: Copied (replaced existing) 2021/04/05 05:04:22 DEBUG : Waiting for deletions to finish --- PASS: TestSyncIgnoreTimes (3.82s) === RUN TestSyncIgnoreExisting run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6'", Local "Local file system at /tmp/rclone638061947", Modify Window "1ms" 2021/04/05 05:04:24 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for checks to finish 2021/04/05 05:04:24 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for transfers to finish 2021/04/05 05:04:25 DEBUG : existing: MD5 = 66c9ceb7f0fe80983740059b36248719 OK 2021/04/05 05:04:25 INFO : existing: Copied (new) 2021/04/05 05:04:25 DEBUG : Waiting for deletions to finish 2021/04/05 05:04:25 DEBUG : existing: Destination exists, skipping 2021/04/05 05:04:25 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for checks to finish 2021/04/05 05:04:25 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for transfers to finish 2021/04/05 05:04:25 DEBUG : Waiting for deletions to finish 2021/04/05 05:04:25 INFO : There was nothing to transfer --- PASS: TestSyncIgnoreExisting (2.86s) === RUN TestSyncIgnoreErrors run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6'", Local "Local file system at /tmp/rclone638061947", Modify Window "1ms" 2021/04/05 05:04:28 DEBUG : b/potato: MD5 = d3a968593f773ad501447b7df446bfe6 OK 2021/04/05 05:04:30 DEBUG : c/non empty space: MD5 = f976eb9c761258c08397f07f0ead0d7b OK 2021/04/05 05:04:30 DEBUG : d: Making directory 2021/04/05 05:04:32 DEBUG : c/non empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2021/04/05 05:04:32 DEBUG : c/non empty space: Unchanged skipping 2021/04/05 05:04:32 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for checks to finish 2021/04/05 05:04:32 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for transfers to finish 2021/04/05 05:04:32 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) 2021/04/05 05:04:32 DEBUG : pacer: Rate limited, increasing sleep to 1.708407648s 2021/04/05 05:04:32 DEBUG : pacer: low level retry 2/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) 2021/04/05 05:04:32 DEBUG : pacer: Rate limited, increasing sleep to 2.205753208s 2021/04/05 05:04:34 DEBUG : pacer: Reducing sleep to 0s 2021/04/05 05:04:38 DEBUG : a/potato2: MD5 = 608bba9d06af4280232de6c80db2144e OK 2021/04/05 05:04:38 INFO : a/potato2: Copied (new) 2021/04/05 05:04:38 DEBUG : Waiting for deletions to finish 2021/04/05 05:04:39 INFO : b/potato: Deleted 2021/04/05 05:04:39 DEBUG : d: Removing directory 2021/04/05 05:04:39 DEBUG : b: Removing directory 2021/04/05 05:04:40 DEBUG : 32d8ua6196mc1r7qkfog53rkg0: Rmdir: contains trashed file: "2m507n64kafsi59v9q71r281a4" 2021/04/05 05:04:40 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': deleted 2 directories 2021/04/05 05:04:42 DEBUG : 3i9du405pfogq3ncai6pg7ouio: Rmdir: contains trashed file: "982d3pss7t5pn0il16r2foj31s" 2021/04/05 05:04:43 DEBUG : 2bsvlrk2ne1lfitm6tttcu0qt8: Rmdir: contains trashed file: "89l8renevh3mji1c8r1p7qn6tg" --- PASS: TestSyncIgnoreErrors (17.01s) === RUN TestSyncAfterChangingModtimeOnly run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6'", Local "Local file system at /tmp/rclone638061947", Modify Window "1ms" 2021/04/05 05:04:45 DEBUG : empty space: MD5 = 843d4d9f8d4acd86334b7fbbae992722 OK 2021/04/05 05:04:45 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 2021/04/05 05:04:45 NOTICE: empty space: Skipped copy as --dry-run is set (size 1) 2021/04/05 05:04:45 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for checks to finish 2021/04/05 05:04:45 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for transfers to finish 2021/04/05 05:04:45 DEBUG : Waiting for deletions to finish 2021/04/05 05:04:46 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for checks to finish 2021/04/05 05:04:46 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 2021/04/05 05:04:46 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for transfers to finish 2021/04/05 05:04:47 DEBUG : empty space: MD5 = f2426652cc853fa8eb5d367a145ef878 OK 2021/04/05 05:04:47 INFO : empty space: Copied (replaced existing) 2021/04/05 05:04:47 DEBUG : Waiting for deletions to finish --- PASS: TestSyncAfterChangingModtimeOnly (4.38s) === RUN TestSyncAfterChangingModtimeOnlyWithNoUpdateModTime run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6'", Local "Local file system at /tmp/rclone638061947", Modify Window "1ms" sync_test.go:591: Can't check this if no hashes supported --- PASS: TestSyncAfterChangingModtimeOnlyWithNoUpdateModTime (0.36s) === RUN TestSyncDoesntUpdateModtime run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6'", Local "Local file system at /tmp/rclone638061947", Modify Window "1ms" 2021/04/05 05:04:49 DEBUG : foo: MD5 = 6f8af56fb427a5d14c0a48e235af5c22 OK 2021/04/05 05:04:50 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 2021/04/05 05:04:50 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for checks to finish 2021/04/05 05:04:50 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for transfers to finish 2021/04/05 05:04:51 DEBUG : foo: MD5 = 82406c0f7ad1929ee21afea32e22ca74 OK 2021/04/05 05:04:51 INFO : foo: Copied (replaced existing) 2021/04/05 05:04:51 DEBUG : Waiting for deletions to finish 2021/04/05 05:04:52 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) 2021/04/05 05:04:52 DEBUG : pacer: Rate limited, increasing sleep to 1.112339373s 2021/04/05 05:04:52 DEBUG : pacer: Reducing sleep to 0s --- PASS: TestSyncDoesntUpdateModtime (3.71s) === RUN TestSyncAfterAddingAFile run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6'", Local "Local file system at /tmp/rclone638061947", Modify Window "1ms" 2021/04/05 05:04:54 DEBUG : empty space: MD5 = b72906b9d12577083a90a0e05bcea782 OK 2021/04/05 05:04:55 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2021/04/05 05:04:55 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for checks to finish 2021/04/05 05:04:55 DEBUG : empty space: Unchanged skipping 2021/04/05 05:04:55 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for transfers to finish 2021/04/05 05:04:56 DEBUG : potato: MD5 = 9e8b96ac05b87ac75be8c85789a3a9f3 OK 2021/04/05 05:04:56 INFO : potato: Copied (new) 2021/04/05 05:04:56 DEBUG : Waiting for deletions to finish --- PASS: TestSyncAfterAddingAFile (5.65s) === RUN TestSyncAfterChangingFilesSizeOnly run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6'", Local "Local file system at /tmp/rclone638061947", Modify Window "1ms" 2021/04/05 05:04:59 DEBUG : potato: MD5 = 1c5b8e20b26e341f7fe7d83404cd6fdf OK 2021/04/05 05:04:59 DEBUG : potato: Sizes differ (src 21 vs dst 60) 2021/04/05 05:04:59 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for checks to finish 2021/04/05 05:04:59 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for transfers to finish 2021/04/05 05:05:00 DEBUG : potato: MD5 = e43a6b23090ebbcb2cdbe07423a0d51b OK 2021/04/05 05:05:00 INFO : potato: Copied (replaced existing) 2021/04/05 05:05:00 DEBUG : Waiting for deletions to finish --- PASS: TestSyncAfterChangingFilesSizeOnly (3.68s) === RUN TestSyncAfterChangingContentsOnly run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6'", Local "Local file system at /tmp/rclone638061947", Modify Window "1ms" 2021/04/05 05:05:02 DEBUG : potato: MD5 = f2bc4a2e6cf872ad55aa8950874fae54 OK 2021/04/05 05:05:03 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 2021/04/05 05:05:03 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for checks to finish 2021/04/05 05:05:03 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for transfers to finish 2021/04/05 05:05:04 DEBUG : potato: MD5 = cd2a449cd27dd2d8d165a3d9ec3dbb7f OK 2021/04/05 05:05:04 INFO : potato: Copied (replaced existing) 2021/04/05 05:05:04 DEBUG : Waiting for deletions to finish --- PASS: TestSyncAfterChangingContentsOnly (3.82s) === RUN TestSyncAfterRemovingAFileAndAddingAFileDryRun run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6'", Local "Local file system at /tmp/rclone638061947", Modify Window "1ms" 2021/04/05 05:05:06 DEBUG : potato: MD5 = a4283688b6e94a91ac92645bf47e20d6 OK 2021/04/05 05:05:08 DEBUG : empty space: MD5 = 3f5ea38712e20e7ddb078a85247cf92c OK 2021/04/05 05:05:08 NOTICE: potato2: Skipped copy as --dry-run is set (size 60) 2021/04/05 05:05:08 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2021/04/05 05:05:08 DEBUG : empty space: Unchanged skipping 2021/04/05 05:05:08 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for checks to finish 2021/04/05 05:05:08 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for transfers to finish 2021/04/05 05:05:08 DEBUG : Waiting for deletions to finish 2021/04/05 05:05:08 NOTICE: potato: Skipped delete as --dry-run is set (size 21) --- PASS: TestSyncAfterRemovingAFileAndAddingAFileDryRun (4.37s) === RUN TestSyncAfterRemovingAFileAndAddingAFile run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6'", Local "Local file system at /tmp/rclone638061947", Modify Window "1ms" 2021/04/05 05:05:10 DEBUG : potato: MD5 = d58acf5bd327177ac14190c6b22fc6c6 OK 2021/04/05 05:05:12 DEBUG : empty space: MD5 = 659e7124e2a36a04958604c47afc41b9 OK 2021/04/05 05:05:12 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2021/04/05 05:05:12 DEBUG : empty space: Unchanged skipping 2021/04/05 05:05:12 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for checks to finish 2021/04/05 05:05:12 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for transfers to finish 2021/04/05 05:05:13 DEBUG : potato2: MD5 = 79953c41a57269318ccdff6b96f16391 OK 2021/04/05 05:05:13 INFO : potato2: Copied (new) 2021/04/05 05:05:13 DEBUG : Waiting for deletions to finish 2021/04/05 05:05:14 INFO : potato: Deleted --- PASS: TestSyncAfterRemovingAFileAndAddingAFile (5.86s) === RUN TestSyncAfterRemovingAFileAndAddingAFileSubDir run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6'", Local "Local file system at /tmp/rclone638061947", Modify Window "1ms" 2021/04/05 05:05:17 DEBUG : b/potato: MD5 = 5b2974080c760d8eac5c43eb2f1bed29 OK 2021/04/05 05:05:19 DEBUG : c/non empty space: MD5 = 98d6b4649745d106c07e14b7cbdc19db OK 2021/04/05 05:05:19 DEBUG : d: Making directory 2021/04/05 05:05:21 DEBUG : d/e: Making directory 2021/04/05 05:05:22 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) 2021/04/05 05:05:22 DEBUG : pacer: Rate limited, increasing sleep to 1.190975451s 2021/04/05 05:05:22 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) 2021/04/05 05:05:22 DEBUG : pacer: Rate limited, increasing sleep to 2.141433131s 2021/04/05 05:05:22 DEBUG : pacer: Reducing sleep to 0s 2021/04/05 05:05:22 DEBUG : pacer: low level retry 2/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) 2021/04/05 05:05:22 DEBUG : pacer: Rate limited, increasing sleep to 1.375395846s 2021/04/05 05:05:24 DEBUG : pacer: Reducing sleep to 0s 2021/04/05 05:05:25 DEBUG : c/non empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2021/04/05 05:05:25 DEBUG : c/non empty space: Unchanged skipping 2021/04/05 05:05:25 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for checks to finish 2021/04/05 05:05:25 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for transfers to finish 2021/04/05 05:05:27 DEBUG : a/potato2: MD5 = 55398d85d9b3ead4d366fb9604cbd653 OK 2021/04/05 05:05:27 INFO : a/potato2: Copied (new) 2021/04/05 05:05:27 DEBUG : Waiting for deletions to finish 2021/04/05 05:05:27 INFO : b/potato: Deleted 2021/04/05 05:05:27 DEBUG : d/e: Removing directory 2021/04/05 05:05:28 DEBUG : d: Removing directory 2021/04/05 05:05:28 DEBUG : ka6id8d20d3s5ktapedlphgta8: Rmdir: contains trashed file: "r8sppajuabeak3sbgj2ak8vuf8" 2021/04/05 05:05:29 DEBUG : b: Removing directory 2021/04/05 05:05:29 DEBUG : 32d8ua6196mc1r7qkfog53rkg0: Rmdir: contains trashed file: "2m507n64kafsi59v9q71r281a4" 2021/04/05 05:05:29 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': deleted 3 directories 2021/04/05 05:05:31 DEBUG : 3i9du405pfogq3ncai6pg7ouio: Rmdir: contains trashed file: "982d3pss7t5pn0il16r2foj31s" 2021/04/05 05:05:32 DEBUG : 2bsvlrk2ne1lfitm6tttcu0qt8: Rmdir: contains trashed file: "89l8renevh3mji1c8r1p7qn6tg" --- PASS: TestSyncAfterRemovingAFileAndAddingAFileSubDir (17.34s) === RUN TestSyncAfterRemovingAFileAndAddingAFileSubDirWithErrors run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6'", Local "Local file system at /tmp/rclone638061947", Modify Window "1ms" 2021/04/05 05:05:34 DEBUG : b/potato: MD5 = 412aa99c395d73b5b690358039996bbc OK 2021/04/05 05:05:37 DEBUG : c/non empty space: MD5 = 78c53a45b951cdfee8a1f5fe35c080ac OK 2021/04/05 05:05:37 DEBUG : d: Making directory 2021/04/05 05:05:39 DEBUG : c/non empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2021/04/05 05:05:39 DEBUG : c/non empty space: Unchanged skipping 2021/04/05 05:05:39 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for checks to finish 2021/04/05 05:05:39 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for transfers to finish 2021/04/05 05:05:41 DEBUG : a/potato2: MD5 = 40d5de6223726887f746d15e45a170e7 OK 2021/04/05 05:05:41 INFO : a/potato2: Copied (new) 2021/04/05 05:05:41 ERROR : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': not deleting files as there were IO errors 2021/04/05 05:05:41 ERROR : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': not deleting directories as there were IO errors 2021/04/05 05:05:41 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) 2021/04/05 05:05:41 DEBUG : pacer: Rate limited, increasing sleep to 1.471018398s 2021/04/05 05:05:41 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) 2021/04/05 05:05:41 DEBUG : pacer: Rate limited, increasing sleep to 2.058407622s 2021/04/05 05:05:42 DEBUG : pacer: Reducing sleep to 0s 2021/04/05 05:05:45 DEBUG : 3i9du405pfogq3ncai6pg7ouio: Rmdir: contains trashed file: "982d3pss7t5pn0il16r2foj31s" 2021/04/05 05:05:46 DEBUG : 32d8ua6196mc1r7qkfog53rkg0: Rmdir: contains trashed file: "2m507n64kafsi59v9q71r281a4" 2021/04/05 05:05:47 DEBUG : 2bsvlrk2ne1lfitm6tttcu0qt8: Rmdir: contains trashed file: "89l8renevh3mji1c8r1p7qn6tg" --- PASS: TestSyncAfterRemovingAFileAndAddingAFileSubDirWithErrors (14.95s) === RUN TestSyncDeleteAfter --- PASS: TestSyncDeleteAfter (0.00s) === RUN TestSyncDeleteDuring run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6'", Local "Local file system at /tmp/rclone638061947", Modify Window "1ms" 2021/04/05 05:05:49 DEBUG : potato: MD5 = cd2f2c9d98e1c802b17d7052b3533aa2 OK 2021/04/05 05:05:50 DEBUG : empty space: MD5 = d1a60c6e0ca90e0708b98eefc8876e4a OK 2021/04/05 05:05:50 DEBUG : Waiting for deletions to finish 2021/04/05 05:05:50 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2021/04/05 05:05:50 DEBUG : empty space: Unchanged skipping 2021/04/05 05:05:50 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for checks to finish 2021/04/05 05:05:50 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for transfers to finish 2021/04/05 05:05:51 INFO : potato: Deleted 2021/04/05 05:05:52 DEBUG : potato2: MD5 = 70316c3ade228454f512854b68d80e7f OK 2021/04/05 05:05:52 INFO : potato2: Copied (new) --- PASS: TestSyncDeleteDuring (6.07s) === RUN TestSyncDeleteBefore run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6'", Local "Local file system at /tmp/rclone638061947", Modify Window "1ms" 2021/04/05 05:05:55 DEBUG : potato: MD5 = 098981bae95ebebba77986bdf274d483 OK 2021/04/05 05:05:56 DEBUG : empty space: MD5 = 443ecf8ee15a4acd0d03119d9a5ce1d8 OK 2021/04/05 05:05:56 DEBUG : Waiting for deletions to finish 2021/04/05 05:05:56 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for checks to finish 2021/04/05 05:05:56 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for transfers to finish 2021/04/05 05:05:57 INFO : potato: Deleted 2021/04/05 05:05:57 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2021/04/05 05:05:57 DEBUG : empty space: Unchanged skipping 2021/04/05 05:05:57 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for checks to finish 2021/04/05 05:05:57 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for transfers to finish 2021/04/05 05:05:59 DEBUG : potato2: MD5 = 980bd4f9fecffd42601071772448c5ce OK 2021/04/05 05:05:59 INFO : potato2: Copied (new) --- PASS: TestSyncDeleteBefore (6.62s) === RUN TestCopyDeleteBefore run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6'", Local "Local file system at /tmp/rclone638061947", Modify Window "1ms" 2021/04/05 05:06:01 DEBUG : potato: MD5 = 9e62e5bb34482d325dcd0c5f02655757 OK 2021/04/05 05:06:02 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for checks to finish 2021/04/05 05:06:02 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for transfers to finish 2021/04/05 05:06:03 DEBUG : potato2: MD5 = 67328d6c8c1216f2f3f10599023b9443 OK 2021/04/05 05:06:03 INFO : potato2: Copied (new) --- PASS: TestCopyDeleteBefore (4.73s) === RUN TestSyncWithExclude run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6'", Local "Local file system at /tmp/rclone638061947", Modify Window "1ms" 2021/04/05 05:06:06 DEBUG : potato2: MD5 = 4d8c42e62877849458eb188b8eeecad8 OK 2021/04/05 05:06:08 DEBUG : empty space: MD5 = 0599f14c8dd90d56c48fcab722b2f2bc OK 2021/04/05 05:06:08 DEBUG : enormous: Excluded 2021/04/05 05:06:08 DEBUG : potato2: Excluded 2021/04/05 05:06:08 DEBUG : potato2: Excluded from sync (and deletion) 2021/04/05 05:06:08 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2021/04/05 05:06:08 DEBUG : empty space: Unchanged skipping 2021/04/05 05:06:08 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for checks to finish 2021/04/05 05:06:08 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for transfers to finish 2021/04/05 05:06:08 DEBUG : Waiting for deletions to finish 2021/04/05 05:06:08 INFO : There was nothing to transfer 2021/04/05 05:06:08 DEBUG : enormous: Excluded 2021/04/05 05:06:08 DEBUG : potato2: Excluded 2021/04/05 05:06:08 DEBUG : potato2: Excluded from sync (and deletion) 2021/04/05 05:06:08 DEBUG : empty space: Size and modification time the same (differ by 456.789µs, within tolerance 1ms) 2021/04/05 05:06:08 DEBUG : empty space: Unchanged skipping 2021/04/05 05:06:08 DEBUG : Local file system at /tmp/rclone638061947: Waiting for checks to finish 2021/04/05 05:06:08 DEBUG : Local file system at /tmp/rclone638061947: Waiting for transfers to finish 2021/04/05 05:06:08 DEBUG : Waiting for deletions to finish 2021/04/05 05:06:08 INFO : There was nothing to transfer --- PASS: TestSyncWithExclude (4.90s) === RUN TestSyncWithExcludeAndDeleteExcluded run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6'", Local "Local file system at /tmp/rclone638061947", Modify Window "1ms" 2021/04/05 05:06:11 DEBUG : potato2: MD5 = d3717b6f89e81f9b325b2b842546ede4 OK 2021/04/05 05:06:12 DEBUG : empty space: MD5 = cf44e7dc46ac31da73cd379237a4ea7c OK 2021/04/05 05:06:14 DEBUG : enormous: MD5 = 644d4c77c2cf44792583ea420bd1e070 OK 2021/04/05 05:06:14 DEBUG : enormous: Excluded 2021/04/05 05:06:14 DEBUG : potato2: Excluded 2021/04/05 05:06:14 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2021/04/05 05:06:14 DEBUG : empty space: Unchanged skipping 2021/04/05 05:06:14 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for checks to finish 2021/04/05 05:06:14 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for transfers to finish 2021/04/05 05:06:14 DEBUG : Waiting for deletions to finish 2021/04/05 05:06:15 INFO : enormous: Deleted 2021/04/05 05:06:15 INFO : potato2: Deleted 2021/04/05 05:06:15 INFO : There was nothing to transfer 2021/04/05 05:06:15 DEBUG : empty space: Size and modification time the same (differ by 456.789µs, within tolerance 1ms) 2021/04/05 05:06:15 DEBUG : empty space: Unchanged skipping 2021/04/05 05:06:15 DEBUG : Local file system at /tmp/rclone638061947: Waiting for checks to finish 2021/04/05 05:06:15 DEBUG : Local file system at /tmp/rclone638061947: Waiting for transfers to finish 2021/04/05 05:06:15 DEBUG : Waiting for deletions to finish 2021/04/05 05:06:15 INFO : potato2: Deleted 2021/04/05 05:06:15 INFO : enormous: Deleted 2021/04/05 05:06:15 INFO : There was nothing to transfer --- PASS: TestSyncWithExcludeAndDeleteExcluded (6.25s) === RUN TestSyncWithUpdateOlder run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6'", Local "Local file system at /tmp/rclone638061947", Modify Window "1ms" 2021/04/05 05:06:17 DEBUG : one: MD5 = 52d8da1dc9b39b609d2211f1e3036a40 OK 2021/04/05 05:06:19 DEBUG : two: MD5 = 8f2c3b76d7fed9c5b6b117f3e3d9f507 OK 2021/04/05 05:06:20 DEBUG : three: MD5 = b38f2aab820a0c6e832838aaeb4e6ac8 OK 2021/04/05 05:06:22 DEBUG : four: MD5 = b423230e022dc650939aade4b10908d3 OK 2021/04/05 05:06:22 DEBUG : four: Sizes differ (src 4 vs dst 8) 2021/04/05 05:06:22 DEBUG : four: Destination mod time is within 1s of source but files differ, transferring 2021/04/05 05:06:22 DEBUG : one: Destination is newer than source, skipping 2021/04/05 05:06:22 DEBUG : three: Sizes identical 2021/04/05 05:06:22 DEBUG : three: Destination mod time is within 1s of source and files identical, skipping 2021/04/05 05:06:22 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for checks to finish 2021/04/05 05:06:22 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for transfers to finish 2021/04/05 05:06:23 DEBUG : two: MD5 = 689cc0e60d26c4b5a8c166748bec92e5 OK 2021/04/05 05:06:23 INFO : two: Copied (replaced existing) 2021/04/05 05:06:23 DEBUG : four: MD5 = aac0a4913711b0a1318875b9328e0001 OK 2021/04/05 05:06:23 INFO : four: Copied (replaced existing) 2021/04/05 05:06:23 DEBUG : five: MD5 = daeb38ae5b29396fe2fa146ae116f0c3 OK 2021/04/05 05:06:23 INFO : five: Copied (new) 2021/04/05 05:06:23 DEBUG : Waiting for deletions to finish sync_test.go:1022: Skip test with --checksum as no hashes supported --- PASS: TestSyncWithUpdateOlder (10.57s) === RUN TestSyncWithMaxDuration sync_test.go:1039: Skipping test on non local remote --- SKIP: TestSyncWithMaxDuration (0.00s) === RUN TestSyncWithTrackRenames run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6'", Local "Local file system at /tmp/rclone638061947", Modify Window "1ms" sync_test.go:1088: Can track renames: false 2021/04/05 05:06:27 ERROR : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Ignoring --track-renames as the source and destination do not have a common hash 2021/04/05 05:06:27 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for checks to finish 2021/04/05 05:06:27 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for transfers to finish 2021/04/05 05:06:28 DEBUG : potato: MD5 = 0692827412fb34027b70f38dbb2d7a18 OK 2021/04/05 05:06:28 INFO : potato: Copied (new) 2021/04/05 05:06:29 DEBUG : yam: MD5 = 80931f7a5b988dacfe3339a4306a833d OK 2021/04/05 05:06:29 INFO : yam: Copied (new) 2021/04/05 05:06:29 DEBUG : Waiting for deletions to finish 2021/04/05 05:06:29 ERROR : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Ignoring --track-renames as the source and destination do not have a common hash 2021/04/05 05:06:29 DEBUG : potato: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2021/04/05 05:06:29 DEBUG : potato: Unchanged skipping 2021/04/05 05:06:29 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for checks to finish 2021/04/05 05:06:29 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for transfers to finish 2021/04/05 05:06:31 DEBUG : yaml: MD5 = 00c2ad02cd101e62920f5f81fd3e108d OK 2021/04/05 05:06:31 INFO : yaml: Copied (new) 2021/04/05 05:06:31 DEBUG : Waiting for deletions to finish 2021/04/05 05:06:31 INFO : yam: Deleted --- PASS: TestSyncWithTrackRenames (5.94s) === RUN TestParseRenamesStrategyModtime --- PASS: TestParseRenamesStrategyModtime (0.00s) === RUN TestRenamesStrategyModtime --- PASS: TestRenamesStrategyModtime (0.00s) === RUN TestSyncWithTrackRenamesStrategyModtime run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6'", Local "Local file system at /tmp/rclone638061947", Modify Window "1ms" sync_test.go:1157: Can track renames: true 2021/04/05 05:06:33 INFO : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Making map for --track-renames 2021/04/05 05:06:33 INFO : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Finished making map for --track-renames 2021/04/05 05:06:33 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for checks to finish 2021/04/05 05:06:33 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for renames to finish 2021/04/05 05:06:33 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for transfers to finish 2021/04/05 05:06:34 DEBUG : potato: MD5 = e0989d570f03fc0b1be5d2391276b092 OK 2021/04/05 05:06:34 INFO : potato: Copied (new) 2021/04/05 05:06:34 DEBUG : yam: MD5 = f21347efe746325d2d08b7c6ca4ff2f9 OK 2021/04/05 05:06:34 INFO : yam: Copied (new) 2021/04/05 05:06:34 DEBUG : Waiting for deletions to finish 2021/04/05 05:06:35 DEBUG : potato: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2021/04/05 05:06:35 DEBUG : potato: Unchanged skipping 2021/04/05 05:06:35 INFO : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Making map for --track-renames 2021/04/05 05:06:35 INFO : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Finished making map for --track-renames 2021/04/05 05:06:35 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for checks to finish 2021/04/05 05:06:35 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for renames to finish 2021/04/05 05:06:35 INFO : yam: Moved (server-side) to: yaml 2021/04/05 05:06:35 INFO : yaml: Renamed from "yam" 2021/04/05 05:06:35 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for transfers to finish 2021/04/05 05:06:35 DEBUG : Waiting for deletions to finish 2021/04/05 05:06:35 INFO : There was nothing to transfer 2021/04/05 05:06:35 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) 2021/04/05 05:06:35 DEBUG : pacer: Rate limited, increasing sleep to 1.63109736s 2021/04/05 05:06:36 DEBUG : pacer: Reducing sleep to 0s --- PASS: TestSyncWithTrackRenamesStrategyModtime (5.73s) === RUN TestSyncWithTrackRenamesStrategyLeaf run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6'", Local "Local file system at /tmp/rclone638061947", Modify Window "1ms" sync_test.go:1193: Can track renames: true 2021/04/05 05:06:38 INFO : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Making map for --track-renames 2021/04/05 05:06:38 INFO : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Finished making map for --track-renames 2021/04/05 05:06:38 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for checks to finish 2021/04/05 05:06:38 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for renames to finish 2021/04/05 05:06:38 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for transfers to finish 2021/04/05 05:06:40 DEBUG : sub/yam: MD5 = dc870527e29e04e3be6c87704f0a8d7f OK 2021/04/05 05:06:40 INFO : sub/yam: Copied (new) 2021/04/05 05:06:40 DEBUG : potato: MD5 = e025863c61d639f4f6c2304309fd0578 OK 2021/04/05 05:06:40 INFO : potato: Copied (new) 2021/04/05 05:06:40 DEBUG : Waiting for deletions to finish 2021/04/05 05:06:41 DEBUG : potato: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2021/04/05 05:06:41 DEBUG : potato: Unchanged skipping 2021/04/05 05:06:41 INFO : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Making map for --track-renames 2021/04/05 05:06:41 INFO : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Finished making map for --track-renames 2021/04/05 05:06:41 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for checks to finish 2021/04/05 05:06:41 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for renames to finish 2021/04/05 05:06:42 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) 2021/04/05 05:06:42 DEBUG : pacer: Rate limited, increasing sleep to 1.528080205s 2021/04/05 05:06:42 DEBUG : pacer: Reducing sleep to 0s 2021/04/05 05:06:44 INFO : sub/yam: Moved (server-side) to: yam 2021/04/05 05:06:44 INFO : yam: Renamed from "sub/yam" 2021/04/05 05:06:44 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for transfers to finish 2021/04/05 05:06:44 DEBUG : Waiting for deletions to finish 2021/04/05 05:06:44 INFO : There was nothing to transfer --- PASS: TestSyncWithTrackRenamesStrategyLeaf (7.73s) === RUN TestMoveWithDeleteEmptySrcDirs run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6'", Local "Local file system at /tmp/rclone638061947", Modify Window "1ms" 2021/04/05 05:06:46 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for checks to finish 2021/04/05 05:06:46 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for transfers to finish 2021/04/05 05:06:48 DEBUG : sub dir/hello world: MD5 = fe2ef6a6af62ddfaa5543c218bb604a1 OK 2021/04/05 05:06:48 INFO : sub dir/hello world: Copied (new) 2021/04/05 05:06:48 INFO : sub dir/hello world: Deleted 2021/04/05 05:06:50 DEBUG : nested/sub dir/file: MD5 = 42830dc6fef5a3a9fb55efd1475374c5 OK 2021/04/05 05:06:50 INFO : nested/sub dir/file: Copied (new) 2021/04/05 05:06:50 INFO : nested/sub dir/file: Deleted 2021/04/05 05:06:50 DEBUG : sub dir: Removing directory 2021/04/05 05:06:50 DEBUG : nested/sub dir: Removing directory 2021/04/05 05:06:50 DEBUG : nested: Removing directory 2021/04/05 05:06:50 DEBUG : Local file system at /tmp/rclone638061947: deleted 3 directories 2021/04/05 05:06:51 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) 2021/04/05 05:06:51 DEBUG : pacer: Rate limited, increasing sleep to 1.11716999s 2021/04/05 05:06:52 DEBUG : pacer: Reducing sleep to 0s 2021/04/05 05:06:53 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" 2021/04/05 05:06:54 DEBUG : 37qp6d1gohacv723ij3brofbu8/14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "ftp4kuv8se7tqduu6pmmcvjsmk" 2021/04/05 05:06:55 DEBUG : 37qp6d1gohacv723ij3brofbu8: Rmdir: contains trashed file: "14begaa36ih249fgrnfk6nulg0" --- PASS: TestMoveWithDeleteEmptySrcDirs (9.22s) === RUN TestMoveWithoutDeleteEmptySrcDirs run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6'", Local "Local file system at /tmp/rclone638061947", Modify Window "1ms" 2021/04/05 05:06:55 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for checks to finish 2021/04/05 05:06:55 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for transfers to finish 2021/04/05 05:06:58 DEBUG : nested/sub dir/file: MD5 = 3228d9ef3ee2e787a43586d5af7f8cf9 OK 2021/04/05 05:06:58 INFO : nested/sub dir/file: Copied (new) 2021/04/05 05:06:59 INFO : nested/sub dir/file: Deleted 2021/04/05 05:06:59 DEBUG : sub dir/hello world: MD5 = c23d2c85f86e1576835654963b82102c OK 2021/04/05 05:06:59 INFO : sub dir/hello world: Copied (new) 2021/04/05 05:06:59 INFO : sub dir/hello world: Deleted 2021/04/05 05:07:02 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" 2021/04/05 05:07:03 DEBUG : 37qp6d1gohacv723ij3brofbu8/14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "ftp4kuv8se7tqduu6pmmcvjsmk" 2021/04/05 05:07:03 DEBUG : 37qp6d1gohacv723ij3brofbu8: Rmdir: contains trashed file: "14begaa36ih249fgrnfk6nulg0" --- PASS: TestMoveWithoutDeleteEmptySrcDirs (8.86s) === RUN TestServerSideMove run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6'", Local "Local file system at /tmp/rclone638061947", Modify Window "1ms" 2021/04/05 05:07:04 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-zicetat6bexizaq8lifoqal4" 2021/04/05 05:07:04 DEBUG : Config file has changed externaly - reloading 2021/04/05 05:07:04 DEBUG : Creating backend with remote "TestDrive:crypt/327gqv0nv5s05fgjreofmp4b754cvrolbd0h85ih1va74lirs6jtr8s1f4tlh2cb2cag88qnpqphs" 2021/04/05 05:07:06 DEBUG : potato2: MD5 = 1f3d4fe2cdf84a82a5eeda6efb8bd6db OK 2021/04/05 05:07:08 DEBUG : empty space: MD5 = 7675e3919091dc7043091bb359322b9e OK 2021/04/05 05:07:09 DEBUG : potato3: MD5 = d99e75b00322da4911c1141f2e84fed7 OK sync_test.go:1245: Server side move (if possible) Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6' -> Encrypted drive 'TestCryptDrive:rclone-test-zicetat6bexizaq8lifoqal4' 2021/04/05 05:07:11 DEBUG : empty space: MD5 = 5d0533150c525078632d66a4b5a85fea OK 2021/04/05 05:07:12 DEBUG : potato3: MD5 = 45e1d9d89e0371a1e64d94479298a7cf OK 2021/04/05 05:07:13 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-zicetat6bexizaq8lifoqal4': Using server-side directory move 2021/04/05 05:07:13 INFO : Encrypted drive 'TestCryptDrive:rclone-test-zicetat6bexizaq8lifoqal4': Server side directory move failed - fallback to file moves: can't copy directory - destination already exists 2021/04/05 05:07:13 DEBUG : empty space: Size and modification time the same (differ by 0s, within tolerance 1ms) 2021/04/05 05:07:13 DEBUG : empty space: Unchanged skipping 2021/04/05 05:07:13 DEBUG : potato3: Sizes differ (src 68 vs dst 60) 2021/04/05 05:07:13 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-zicetat6bexizaq8lifoqal4': Waiting for checks to finish 2021/04/05 05:07:13 INFO : empty space: Deleted 2021/04/05 05:07:13 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-zicetat6bexizaq8lifoqal4': Waiting for transfers to finish 2021/04/05 05:07:13 INFO : potato3: Deleted 2021/04/05 05:07:13 INFO : potato2: Moved (server-side) 2021/04/05 05:07:14 INFO : potato3: Moved (server-side) 2021/04/05 05:07:14 INFO : There was nothing to transfer 2021/04/05 05:07:14 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-vuhuhiy5naribof5liwicol1" 2021/04/05 05:07:14 DEBUG : Creating backend with remote "TestDrive:crypt/f6jsiu125ded2iq59qmr9jgfnblfdu4p3ls3dt5hlt1agfcagn7o5ulbtn53ka5h27bc1lu2qg9i6" 2021/04/05 05:07:15 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuhuhiy5naribof5liwicol1': Using server-side directory move 2021/04/05 05:07:16 INFO : Encrypted drive 'TestCryptDrive:rclone-test-vuhuhiy5naribof5liwicol1': Server side directory move succeeded 2021/04/05 05:07:17 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuhuhiy5naribof5liwicol1': Purge remote 2021/04/05 05:07:17 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-zicetat6bexizaq8lifoqal4': Purge remote 2021/04/05 05:07:17 purge failed: directory not found --- PASS: TestServerSideMove (13.78s) === RUN TestServerSideMoveWithFilter run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6'", Local "Local file system at /tmp/rclone638061947", Modify Window "1ms" 2021/04/05 05:07:18 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-ribohef4verupur4cunerub4" 2021/04/05 05:07:18 DEBUG : Creating backend with remote "TestDrive:crypt/8furpg9jrp6r4f5ur47ni4qp89ut7ems1rnvacfjdueuhfjgmf52ss5d2pb501006ltehl9tsno20" 2021/04/05 05:07:20 DEBUG : potato2: MD5 = aaa50a88572d8348955193e999601167 OK 2021/04/05 05:07:21 DEBUG : empty space: MD5 = 0e00e7d503112070590cc3846d125099 OK 2021/04/05 05:07:23 DEBUG : potato3: MD5 = ee0ee56abb39ccd6d01ef50d59e1e5e8 OK sync_test.go:1245: Server side move (if possible) Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6' -> Encrypted drive 'TestCryptDrive:rclone-test-ribohef4verupur4cunerub4' 2021/04/05 05:07:25 DEBUG : empty space: MD5 = def1b672e1e46d712f904bb0726ead68 OK 2021/04/05 05:07:26 DEBUG : potato3: MD5 = 6c9c78463fcafd852d9570e79f6b3b0e OK 2021/04/05 05:07:27 DEBUG : empty space: Excluded from sync (and deletion) 2021/04/05 05:07:27 DEBUG : empty space: Excluded from sync (and deletion) 2021/04/05 05:07:27 DEBUG : potato3: Sizes differ (src 68 vs dst 60) 2021/04/05 05:07:27 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-ribohef4verupur4cunerub4': Waiting for checks to finish 2021/04/05 05:07:27 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-ribohef4verupur4cunerub4': Waiting for transfers to finish 2021/04/05 05:07:27 INFO : potato3: Deleted 2021/04/05 05:07:27 INFO : potato2: Moved (server-side) 2021/04/05 05:07:28 INFO : potato3: Moved (server-side) 2021/04/05 05:07:28 INFO : There was nothing to transfer 2021/04/05 05:07:28 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-xilayez8lusetub2boxezop2" 2021/04/05 05:07:28 DEBUG : Creating backend with remote "TestDrive:crypt/eishfsapsv7p8gkqpnkl6p0j4djundhk369tc54jvu3418e5g1npahqt45ao4sfg4rob7t93s516s" 2021/04/05 05:07:29 DEBUG : empty space: Excluded from sync (and deletion) 2021/04/05 05:07:29 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xilayez8lusetub2boxezop2': Waiting for checks to finish 2021/04/05 05:07:29 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xilayez8lusetub2boxezop2': Waiting for transfers to finish 2021/04/05 05:07:31 INFO : potato2: Moved (server-side) 2021/04/05 05:07:31 INFO : potato3: Moved (server-side) 2021/04/05 05:07:31 INFO : There was nothing to transfer 2021/04/05 05:07:32 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xilayez8lusetub2boxezop2': Purge remote 2021/04/05 05:07:32 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-ribohef4verupur4cunerub4': Purge remote --- PASS: TestServerSideMoveWithFilter (15.40s) === RUN TestServerSideMoveDeleteEmptySourceDirs run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6'", Local "Local file system at /tmp/rclone638061947", Modify Window "1ms" 2021/04/05 05:07:33 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-cusapek9qipipah4gonizos5" 2021/04/05 05:07:33 DEBUG : Creating backend with remote "TestDrive:crypt/il2d83jq3595ldfa0k3dmoica5mh66sm98oc2qka91299k99nb3gil159kngqq559no0bvte0tp2i" 2021/04/05 05:07:36 DEBUG : potato2: MD5 = a9a33266f9961ef8bcece98425063c84 OK 2021/04/05 05:07:37 DEBUG : empty space: MD5 = f47ac378d1edfef58db50fed7238f9fa OK 2021/04/05 05:07:38 DEBUG : potato3: MD5 = 072f0cc177724b39bd159a7e154a6e87 OK 2021/04/05 05:07:38 DEBUG : tomatoDir: Making directory sync_test.go:1245: Server side move (if possible) Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6' -> Encrypted drive 'TestCryptDrive:rclone-test-cusapek9qipipah4gonizos5' 2021/04/05 05:07:42 DEBUG : empty space: MD5 = ba69f7741b6eeabae1a668255e89b789 OK 2021/04/05 05:07:43 DEBUG : potato3: MD5 = 487d4535569beaef992e944b0a28b6dd OK 2021/04/05 05:07:43 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cusapek9qipipah4gonizos5': Using server-side directory move 2021/04/05 05:07:43 INFO : Encrypted drive 'TestCryptDrive:rclone-test-cusapek9qipipah4gonizos5': Server side directory move failed - fallback to file moves: can't copy directory - destination already exists 2021/04/05 05:07:44 DEBUG : empty space: Size and modification time the same (differ by 0s, within tolerance 1ms) 2021/04/05 05:07:44 DEBUG : empty space: Unchanged skipping 2021/04/05 05:07:44 DEBUG : potato3: Sizes differ (src 68 vs dst 60) 2021/04/05 05:07:44 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cusapek9qipipah4gonizos5': Waiting for checks to finish 2021/04/05 05:07:44 INFO : potato3: Deleted 2021/04/05 05:07:44 INFO : empty space: Deleted 2021/04/05 05:07:44 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cusapek9qipipah4gonizos5': Waiting for transfers to finish 2021/04/05 05:07:44 INFO : potato2: Moved (server-side) 2021/04/05 05:07:45 INFO : potato3: Moved (server-side) 2021/04/05 05:07:45 DEBUG : tomatoDir: Removing directory 2021/04/05 05:07:45 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': deleted 1 directories 2021/04/05 05:07:45 INFO : There was nothing to transfer 2021/04/05 05:07:46 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-qatedeg4rigomew2xulojan6" 2021/04/05 05:07:46 DEBUG : Creating backend with remote "TestDrive:crypt/94jvrvbthkft8s2avh8iugv11qsmlefu5ei0o7igh17i8svratucqedi63v29db7hr74ahgd6h8ku" 2021/04/05 05:07:47 DEBUG : tomatoDir: Making directory 2021/04/05 05:07:48 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-qatedeg4rigomew2xulojan6': Using server-side directory move 2021/04/05 05:07:48 INFO : Encrypted drive 'TestCryptDrive:rclone-test-qatedeg4rigomew2xulojan6': Server side directory move succeeded 2021/04/05 05:07:50 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-qatedeg4rigomew2xulojan6': Purge remote 2021/04/05 05:07:50 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cusapek9qipipah4gonizos5': Purge remote 2021/04/05 05:07:50 purge failed: directory not found --- PASS: TestServerSideMoveDeleteEmptySourceDirs (17.60s) === RUN TestServerSideMoveOverlap run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6'", Local "Local file system at /tmp/rclone638061947", Modify Window "1ms" sync_test.go:1382: Skipping test as remote supports DirMove --- SKIP: TestServerSideMoveOverlap (0.38s) === RUN TestSyncOverlap run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6'", Local "Local file system at /tmp/rclone638061947", Modify Window "1ms" 2021/04/05 05:07:51 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6/rclone-sync-test" 2021/04/05 05:07:51 DEBUG : Creating backend with remote "TestDrive:crypt/re61b925b532g0toajvd6jkl8kvrnsr61om6jcbvpu8cb7u4skmggci49igg4sntaeibenodi7hu6/i7355aa0sb89uagn75vfjqr6s3e3e1h2et8in57abn1fe8qfego0" 2021/04/05 05:07:52 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) 2021/04/05 05:07:52 DEBUG : pacer: Rate limited, increasing sleep to 1.558176317s 2021/04/05 05:07:53 DEBUG : pacer: low level retry 2/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) 2021/04/05 05:07:53 DEBUG : pacer: Rate limited, increasing sleep to 2.640753955s 2021/04/05 05:07:54 DEBUG : pacer: Reducing sleep to 0s --- PASS: TestSyncOverlap (3.38s) === RUN TestSyncCompareDest run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6'", Local "Local file system at /tmp/rclone638061947", Modify Window "1ms" 2021/04/05 05:07:55 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6/dst" 2021/04/05 05:07:55 DEBUG : Creating backend with remote "TestDrive:crypt/re61b925b532g0toajvd6jkl8kvrnsr61om6jcbvpu8cb7u4skmggci49igg4sntaeibenodi7hu6/31u3jie661vd5p8j7rtc3hgbh0" 2021/04/05 05:07:56 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6/CompareDest" 2021/04/05 05:07:56 DEBUG : Creating backend with remote "TestDrive:crypt/re61b925b532g0toajvd6jkl8kvrnsr61om6jcbvpu8cb7u4skmggci49igg4sntaeibenodi7hu6/gveqi14airsml4bgu7krj116o8" 2021/04/05 05:07:57 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6/dst': Waiting for checks to finish 2021/04/05 05:07:57 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6/dst': Waiting for transfers to finish 2021/04/05 05:08:00 DEBUG : one: MD5 = 41a35b8cfecc7564982e9e68fb1b923f OK 2021/04/05 05:08:00 INFO : one: Copied (new) 2021/04/05 05:08:00 DEBUG : Waiting for deletions to finish 2021/04/05 05:08:01 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6/dst': Waiting for checks to finish 2021/04/05 05:08:01 DEBUG : one: Sizes differ (src 5 vs dst 3) 2021/04/05 05:08:01 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6/dst': Waiting for transfers to finish 2021/04/05 05:08:02 DEBUG : one: MD5 = 01effb5131c47307a85da45e768d1387 OK 2021/04/05 05:08:02 INFO : one: Copied (replaced existing) 2021/04/05 05:08:02 DEBUG : Waiting for deletions to finish 2021/04/05 05:08:04 DEBUG : dst/one: MD5 = 43734f1f1a6601d98ee1cc5dbfde6a0c OK 2021/04/05 05:08:06 DEBUG : CompareDest/one: MD5 = 9567298b3f771aa353d8f31f4a53f7b5 OK 2021/04/05 05:08:07 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6/dst': Waiting for checks to finish 2021/04/05 05:08:07 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2021/04/05 05:08:07 DEBUG : one: Destination found in --compare-dest, skipping 2021/04/05 05:08:07 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6/dst': Waiting for transfers to finish 2021/04/05 05:08:07 DEBUG : Waiting for deletions to finish 2021/04/05 05:08:07 INFO : There was nothing to transfer 2021/04/05 05:08:09 DEBUG : CompareDest/two: MD5 = 6cf1072ecf3d49ecaaf3e30092e6de5d OK 2021/04/05 05:08:10 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2021/04/05 05:08:10 DEBUG : two: Destination found in --compare-dest, skipping 2021/04/05 05:08:10 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6/dst': Waiting for checks to finish 2021/04/05 05:08:10 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2021/04/05 05:08:10 DEBUG : one: Destination found in --compare-dest, skipping 2021/04/05 05:08:10 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6/dst': Waiting for transfers to finish 2021/04/05 05:08:10 DEBUG : Waiting for deletions to finish 2021/04/05 05:08:10 INFO : There was nothing to transfer 2021/04/05 05:08:11 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2021/04/05 05:08:11 DEBUG : two: Destination found in --compare-dest, skipping 2021/04/05 05:08:11 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6/dst': Waiting for checks to finish 2021/04/05 05:08:11 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2021/04/05 05:08:11 DEBUG : one: Destination found in --compare-dest, skipping 2021/04/05 05:08:11 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6/dst': Waiting for transfers to finish 2021/04/05 05:08:11 DEBUG : Waiting for deletions to finish 2021/04/05 05:08:11 INFO : There was nothing to transfer 2021/04/05 05:08:11 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) 2021/04/05 05:08:11 DEBUG : pacer: Rate limited, increasing sleep to 1.556338389s 2021/04/05 05:08:12 DEBUG : pacer: Reducing sleep to 0s 2021/04/05 05:08:14 DEBUG : two: Sizes differ (src 5 vs dst 3) 2021/04/05 05:08:14 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6/dst': Waiting for checks to finish 2021/04/05 05:08:14 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2021/04/05 05:08:14 DEBUG : one: Destination found in --compare-dest, skipping 2021/04/05 05:08:14 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6/dst': Waiting for transfers to finish 2021/04/05 05:08:15 DEBUG : two: MD5 = 937ebf52cf74f2ec9bd22a9d9ff09825 OK 2021/04/05 05:08:15 INFO : two: Copied (new) 2021/04/05 05:08:15 DEBUG : Waiting for deletions to finish 2021/04/05 05:08:16 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) 2021/04/05 05:08:16 DEBUG : pacer: Rate limited, increasing sleep to 1.470962108s 2021/04/05 05:08:16 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) 2021/04/05 05:08:16 DEBUG : pacer: Rate limited, increasing sleep to 2.119437335s 2021/04/05 05:08:16 DEBUG : pacer: Reducing sleep to 0s 2021/04/05 05:08:18 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) 2021/04/05 05:08:18 DEBUG : pacer: Rate limited, increasing sleep to 1.8352749s 2021/04/05 05:08:18 DEBUG : pacer: Reducing sleep to 0s 2021/04/05 05:08:21 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" 2021/04/05 05:08:21 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2021/04/05 05:08:22 DEBUG : gveqi14airsml4bgu7krj116o8: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" 2021/04/05 05:08:22 DEBUG : gveqi14airsml4bgu7krj116o8: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" --- PASS: TestSyncCompareDest (28.19s) === RUN TestSyncMultipleCompareDest run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6'", Local "Local file system at /tmp/rclone638061947", Modify Window "1ms" 2021/04/05 05:08:25 DEBUG : pre-dest1/1: MD5 = fa90a633be860253e5c4ed2128bbe042 OK 2021/04/05 05:08:27 DEBUG : pre-dest2/2: MD5 = e0d640fccc148c6bf0dfd1b6f5a224e1 OK 2021/04/05 05:08:28 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6/dest" 2021/04/05 05:08:28 DEBUG : Creating backend with remote "TestDrive:crypt/re61b925b532g0toajvd6jkl8kvrnsr61om6jcbvpu8cb7u4skmggci49igg4sntaeibenodi7hu6/rg03c1jvnehrrc617i0lnqjddc" 2021/04/05 05:08:31 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6/pre-dest1" 2021/04/05 05:08:31 DEBUG : Creating backend with remote "TestDrive:crypt/re61b925b532g0toajvd6jkl8kvrnsr61om6jcbvpu8cb7u4skmggci49igg4sntaeibenodi7hu6/bbnblvh6k061ssopqrp18kd7gc" 2021/04/05 05:08:31 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) 2021/04/05 05:08:31 DEBUG : pacer: Rate limited, increasing sleep to 1.215182938s 2021/04/05 05:08:32 DEBUG : pacer: low level retry 2/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) 2021/04/05 05:08:32 DEBUG : pacer: Rate limited, increasing sleep to 2.413350591s 2021/04/05 05:08:33 DEBUG : pacer: Reducing sleep to 0s 2021/04/05 05:08:35 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6/pre-dest2" 2021/04/05 05:08:36 DEBUG : Creating backend with remote "TestDrive:crypt/re61b925b532g0toajvd6jkl8kvrnsr61om6jcbvpu8cb7u4skmggci49igg4sntaeibenodi7hu6/dgicm1h6b5ejvlltm8eeif0bnk" 2021/04/05 05:08:38 DEBUG : 1: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2021/04/05 05:08:38 DEBUG : 1: Destination found in --compare-dest, skipping 2021/04/05 05:08:38 DEBUG : 2: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2021/04/05 05:08:38 DEBUG : 2: Destination found in --compare-dest, skipping 2021/04/05 05:08:38 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) 2021/04/05 05:08:38 DEBUG : pacer: Rate limited, increasing sleep to 1.901868662s 2021/04/05 05:08:38 DEBUG : pacer: low level retry 2/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) 2021/04/05 05:08:38 DEBUG : pacer: Rate limited, increasing sleep to 2.159628914s 2021/04/05 05:08:40 DEBUG : pacer: Reducing sleep to 0s 2021/04/05 05:08:40 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6/dest': Waiting for checks to finish 2021/04/05 05:08:40 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6/dest': Waiting for transfers to finish 2021/04/05 05:08:42 DEBUG : 3: MD5 = 06f67bc30a80b2f194ed50e2aef86a23 OK 2021/04/05 05:08:42 INFO : 3: Copied (new) 2021/04/05 05:08:42 DEBUG : Waiting for deletions to finish 2021/04/05 05:08:43 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) 2021/04/05 05:08:43 DEBUG : pacer: Rate limited, increasing sleep to 1.437406887s 2021/04/05 05:08:43 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) 2021/04/05 05:08:43 DEBUG : pacer: Rate limited, increasing sleep to 2.931025154s 2021/04/05 05:08:43 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) 2021/04/05 05:08:43 DEBUG : pacer: Rate limited, increasing sleep to 4.728301371s 2021/04/05 05:08:43 DEBUG : pacer: low level retry 2/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) 2021/04/05 05:08:43 DEBUG : pacer: Rate limited, increasing sleep to 8.38555521s 2021/04/05 05:08:45 DEBUG : pacer: Reducing sleep to 0s 2021/04/05 05:08:54 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) 2021/04/05 05:08:54 DEBUG : pacer: Rate limited, increasing sleep to 1.587915217s 2021/04/05 05:08:55 DEBUG : pacer: Reducing sleep to 0s 2021/04/05 05:08:55 DEBUG : dgicm1h6b5ejvlltm8eeif0bnk: Rmdir: contains trashed file: "1ghu8geql9vrl726n32nrf65bc" 2021/04/05 05:08:58 DEBUG : bbnblvh6k061ssopqrp18kd7gc: Rmdir: contains trashed file: "skbfko3oil7es0lj68ob574sro" 2021/04/05 05:09:00 DEBUG : rg03c1jvnehrrc617i0lnqjddc: Rmdir: contains trashed file: "g072p7hmjchlnj0gibe64c1epg" --- PASS: TestSyncMultipleCompareDest (37.42s) === RUN TestSyncCopyDest run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6'", Local "Local file system at /tmp/rclone638061947", Modify Window "1ms" 2021/04/05 05:09:00 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6/dst" 2021/04/05 05:09:00 DEBUG : Creating backend with remote "TestDrive:crypt/re61b925b532g0toajvd6jkl8kvrnsr61om6jcbvpu8cb7u4skmggci49igg4sntaeibenodi7hu6/31u3jie661vd5p8j7rtc3hgbh0" 2021/04/05 05:09:01 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) 2021/04/05 05:09:01 DEBUG : pacer: Rate limited, increasing sleep to 1.490264142s 2021/04/05 05:09:01 DEBUG : pacer: Reducing sleep to 0s 2021/04/05 05:09:03 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6/CopyDest" 2021/04/05 05:09:03 DEBUG : Creating backend with remote "TestDrive:crypt/re61b925b532g0toajvd6jkl8kvrnsr61om6jcbvpu8cb7u4skmggci49igg4sntaeibenodi7hu6/d09o6po3f7bm6ce32vdgs8h9ls" 2021/04/05 05:09:04 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6/dst': Waiting for checks to finish 2021/04/05 05:09:04 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6/dst': Waiting for transfers to finish 2021/04/05 05:09:06 DEBUG : one: MD5 = fc6888a628becd864320d12ecede258a OK 2021/04/05 05:09:06 INFO : one: Copied (new) 2021/04/05 05:09:06 DEBUG : Waiting for deletions to finish 2021/04/05 05:09:07 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6/dst': Waiting for checks to finish 2021/04/05 05:09:08 DEBUG : one: Sizes differ (src 5 vs dst 3) 2021/04/05 05:09:08 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6/dst': Waiting for transfers to finish 2021/04/05 05:09:08 DEBUG : one: MD5 = 98079048dd1962bc6f68499142590d7f OK 2021/04/05 05:09:08 INFO : one: Copied (replaced existing) 2021/04/05 05:09:08 DEBUG : Waiting for deletions to finish 2021/04/05 05:09:10 DEBUG : dst/one: MD5 = a41efa29997a16e87e750e0adca83900 OK 2021/04/05 05:09:12 DEBUG : CopyDest/one: MD5 = 469e987db127238c58c833a9782faa69 OK 2021/04/05 05:09:13 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6/BackupDir" 2021/04/05 05:09:13 DEBUG : Creating backend with remote "TestDrive:crypt/re61b925b532g0toajvd6jkl8kvrnsr61om6jcbvpu8cb7u4skmggci49igg4sntaeibenodi7hu6/s6dbk3lfi7c9kfvo6j7bla9m0g" 2021/04/05 05:09:13 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) 2021/04/05 05:09:13 DEBUG : pacer: Rate limited, increasing sleep to 1.278303162s 2021/04/05 05:09:14 DEBUG : pacer: Reducing sleep to 0s 2021/04/05 05:09:15 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6/dst': Waiting for checks to finish 2021/04/05 05:09:16 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2021/04/05 05:09:16 DEBUG : one: Sizes differ (src 5 vs dst 3) 2021/04/05 05:09:17 INFO : one: Moved (server-side) 2021/04/05 05:09:18 INFO : one: Copied (server-side copy) 2021/04/05 05:09:18 DEBUG : one: Destination found in --copy-dest, using server-side copy 2021/04/05 05:09:18 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6/dst': Waiting for transfers to finish 2021/04/05 05:09:18 DEBUG : Waiting for deletions to finish 2021/04/05 05:09:20 DEBUG : CopyDest/two: MD5 = cd00694986cf0eda6a40fb38adcd6df9 OK 2021/04/05 05:09:21 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2021/04/05 05:09:22 INFO : two: Copied (server-side copy) 2021/04/05 05:09:22 DEBUG : two: Destination found in --copy-dest, using server-side copy 2021/04/05 05:09:22 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6/dst': Waiting for checks to finish 2021/04/05 05:09:22 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2021/04/05 05:09:22 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2021/04/05 05:09:22 DEBUG : one: Unchanged skipping 2021/04/05 05:09:22 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6/dst': Waiting for transfers to finish 2021/04/05 05:09:22 DEBUG : Waiting for deletions to finish 2021/04/05 05:09:23 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6/dst': Waiting for checks to finish 2021/04/05 05:09:23 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2021/04/05 05:09:23 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2021/04/05 05:09:23 DEBUG : two: Unchanged skipping 2021/04/05 05:09:23 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2021/04/05 05:09:23 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2021/04/05 05:09:23 DEBUG : one: Unchanged skipping 2021/04/05 05:09:23 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6/dst': Waiting for transfers to finish 2021/04/05 05:09:23 DEBUG : Waiting for deletions to finish 2021/04/05 05:09:23 INFO : There was nothing to transfer 2021/04/05 05:09:23 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) 2021/04/05 05:09:23 DEBUG : pacer: Rate limited, increasing sleep to 1.116191075s 2021/04/05 05:09:23 DEBUG : pacer: Reducing sleep to 0s 2021/04/05 05:09:23 DEBUG : pacer: low level retry 2/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) 2021/04/05 05:09:23 DEBUG : pacer: Rate limited, increasing sleep to 1.592034931s 2021/04/05 05:09:25 DEBUG : pacer: Reducing sleep to 0s 2021/04/05 05:09:27 DEBUG : CopyDest/three: MD5 = 1aa8ba1ef6e389e36bf0748c62b5dd89 OK 2021/04/05 05:09:28 DEBUG : three: Sizes differ (src 7 vs dst 5) 2021/04/05 05:09:28 DEBUG : three: Destination not found in --copy-dest 2021/04/05 05:09:28 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6/dst': Waiting for checks to finish 2021/04/05 05:09:28 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2021/04/05 05:09:28 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2021/04/05 05:09:28 DEBUG : one: Unchanged skipping 2021/04/05 05:09:28 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2021/04/05 05:09:28 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2021/04/05 05:09:28 DEBUG : two: Unchanged skipping 2021/04/05 05:09:28 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6/dst': Waiting for transfers to finish 2021/04/05 05:09:29 DEBUG : three: MD5 = d39455c8da50b4f4940d4e48c507c893 OK 2021/04/05 05:09:29 INFO : three: Copied (new) 2021/04/05 05:09:29 DEBUG : Waiting for deletions to finish 2021/04/05 05:09:33 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "b6jdmn2b1adrhc8vikh7edr9os" 2021/04/05 05:09:33 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2021/04/05 05:09:33 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" 2021/04/05 05:09:34 DEBUG : d09o6po3f7bm6ce32vdgs8h9ls: Rmdir: contains trashed file: "b6jdmn2b1adrhc8vikh7edr9os" 2021/04/05 05:09:34 DEBUG : d09o6po3f7bm6ce32vdgs8h9ls: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" 2021/04/05 05:09:34 DEBUG : d09o6po3f7bm6ce32vdgs8h9ls: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2021/04/05 05:09:35 DEBUG : s6dbk3lfi7c9kfvo6j7bla9m0g: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" --- PASS: TestSyncCopyDest (35.05s) === RUN TestSyncBackupDir run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6'", Local "Local file system at /tmp/rclone638061947", Modify Window "1ms" 2021/04/05 05:09:38 DEBUG : dst/one: MD5 = df0d9e153b16f9327267fb9be15c344b OK 2021/04/05 05:09:39 DEBUG : dst/two: MD5 = 3681027595883bc0af15fb304567ae47 OK 2021/04/05 05:09:40 DEBUG : dst/three.txt: MD5 = ee1a84e94d33e1390f14df7d15259ff1 OK 2021/04/05 05:09:41 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6/dst" 2021/04/05 05:09:41 DEBUG : Creating backend with remote "TestDrive:crypt/re61b925b532g0toajvd6jkl8kvrnsr61om6jcbvpu8cb7u4skmggci49igg4sntaeibenodi7hu6/31u3jie661vd5p8j7rtc3hgbh0" 2021/04/05 05:09:41 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6/backup" 2021/04/05 05:09:41 DEBUG : Creating backend with remote "TestDrive:crypt/re61b925b532g0toajvd6jkl8kvrnsr61om6jcbvpu8cb7u4skmggci49igg4sntaeibenodi7hu6/1nrff024r7pq65ecp72fc28jb0" 2021/04/05 05:09:43 DEBUG : one: Sizes differ (src 4 vs dst 3) 2021/04/05 05:09:43 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2021/04/05 05:09:43 DEBUG : two: Unchanged skipping 2021/04/05 05:09:43 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6/dst': Waiting for checks to finish 2021/04/05 05:09:44 INFO : one: Moved (server-side) 2021/04/05 05:09:44 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6/dst': Waiting for transfers to finish 2021/04/05 05:09:46 DEBUG : one: MD5 = bf08e5e489b692677699f16bf8aeebec OK 2021/04/05 05:09:46 INFO : one: Copied (new) 2021/04/05 05:09:46 DEBUG : Waiting for deletions to finish 2021/04/05 05:09:46 INFO : three.txt: Moved (server-side) 2021/04/05 05:09:46 INFO : three.txt: Moved into backup dir 2021/04/05 05:09:48 DEBUG : dst/three.txt: MD5 = 9ef14dd1ce74567856a309f36268b332 OK 2021/04/05 05:09:49 DEBUG : one: Sizes differ (src 5 vs dst 4) 2021/04/05 05:09:49 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2021/04/05 05:09:49 DEBUG : two: Unchanged skipping 2021/04/05 05:09:49 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6/dst': Waiting for checks to finish 2021/04/05 05:09:49 INFO : one: Deleted 2021/04/05 05:09:50 INFO : one: Moved (server-side) 2021/04/05 05:09:50 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6/dst': Waiting for transfers to finish 2021/04/05 05:09:51 DEBUG : one: MD5 = 5d77e9cd7a2e07f327413d2fd12c2302 OK 2021/04/05 05:09:51 INFO : one: Copied (new) 2021/04/05 05:09:51 DEBUG : Waiting for deletions to finish 2021/04/05 05:09:52 INFO : three.txt: Deleted 2021/04/05 05:09:52 INFO : three.txt: Moved (server-side) 2021/04/05 05:09:52 INFO : three.txt: Moved into backup dir 2021/04/05 05:09:55 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2021/04/05 05:09:55 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" 2021/04/05 05:09:56 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "tr2hj63d80ftlmvm6a952snjcc" 2021/04/05 05:09:56 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2021/04/05 05:09:56 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2021/04/05 05:09:56 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "tr2hj63d80ftlmvm6a952snjcc" --- PASS: TestSyncBackupDir (20.96s) === RUN TestSyncBackupDirWithSuffix run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6'", Local "Local file system at /tmp/rclone638061947", Modify Window "1ms" 2021/04/05 05:09:58 DEBUG : dst/one: MD5 = 20e898e9a132d5234ef692221f135aa1 OK 2021/04/05 05:09:59 DEBUG : dst/two: MD5 = a44cb860addb296f79fb0b7111e6695f OK 2021/04/05 05:10:01 DEBUG : dst/three.txt: MD5 = 2255ea076e32a0f0950ed5eadd52ebab OK 2021/04/05 05:10:01 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6/dst" 2021/04/05 05:10:01 DEBUG : Creating backend with remote "TestDrive:crypt/re61b925b532g0toajvd6jkl8kvrnsr61om6jcbvpu8cb7u4skmggci49igg4sntaeibenodi7hu6/31u3jie661vd5p8j7rtc3hgbh0" 2021/04/05 05:10:02 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6/backup" 2021/04/05 05:10:02 DEBUG : Creating backend with remote "TestDrive:crypt/re61b925b532g0toajvd6jkl8kvrnsr61om6jcbvpu8cb7u4skmggci49igg4sntaeibenodi7hu6/1nrff024r7pq65ecp72fc28jb0" 2021/04/05 05:10:04 DEBUG : one: Sizes differ (src 4 vs dst 3) 2021/04/05 05:10:04 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2021/04/05 05:10:04 DEBUG : two: Unchanged skipping 2021/04/05 05:10:04 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6/dst': Waiting for checks to finish 2021/04/05 05:10:05 INFO : one: Moved (server-side) to: one.bak 2021/04/05 05:10:05 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6/dst': Waiting for transfers to finish 2021/04/05 05:10:06 DEBUG : one: MD5 = 7ce2fd45fdf11908e619ccb65764614c OK 2021/04/05 05:10:06 INFO : one: Copied (new) 2021/04/05 05:10:06 DEBUG : Waiting for deletions to finish 2021/04/05 05:10:07 INFO : three.txt: Moved (server-side) to: three.txt.bak 2021/04/05 05:10:07 INFO : three.txt: Moved into backup dir 2021/04/05 05:10:09 DEBUG : dst/three.txt: MD5 = ac2d6a64533ab9d46b722be7f619b291 OK 2021/04/05 05:10:10 DEBUG : one: Sizes differ (src 5 vs dst 4) 2021/04/05 05:10:10 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2021/04/05 05:10:10 DEBUG : two: Unchanged skipping 2021/04/05 05:10:10 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6/dst': Waiting for checks to finish 2021/04/05 05:10:10 INFO : one.bak: Deleted 2021/04/05 05:10:11 INFO : one: Moved (server-side) to: one.bak 2021/04/05 05:10:11 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6/dst': Waiting for transfers to finish 2021/04/05 05:10:12 DEBUG : one: MD5 = c2a1c6c00bb259e9756d371364dc2cc1 OK 2021/04/05 05:10:12 INFO : one: Copied (new) 2021/04/05 05:10:12 DEBUG : Waiting for deletions to finish 2021/04/05 05:10:13 INFO : three.txt.bak: Deleted 2021/04/05 05:10:13 INFO : three.txt: Moved (server-side) to: three.txt.bak 2021/04/05 05:10:13 INFO : three.txt: Moved into backup dir 2021/04/05 05:10:16 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2021/04/05 05:10:16 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" 2021/04/05 05:10:16 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "sk91qgsqfn0r271r2ehsaoc20c" 2021/04/05 05:10:16 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "qltcak2uaegtmcoa8vijdppbp8" 2021/04/05 05:10:16 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "qltcak2uaegtmcoa8vijdppbp8" 2021/04/05 05:10:16 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "sk91qgsqfn0r271r2ehsaoc20c" --- PASS: TestSyncBackupDirWithSuffix (20.94s) === RUN TestSyncBackupDirWithSuffixKeepExtension run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6'", Local "Local file system at /tmp/rclone638061947", Modify Window "1ms" 2021/04/05 05:10: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) 2021/04/05 05:10:17 DEBUG : pacer: Rate limited, increasing sleep to 1.198931857s 2021/04/05 05:10:17 DEBUG : pacer: low level retry 2/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) 2021/04/05 05:10:17 DEBUG : pacer: Rate limited, increasing sleep to 2.287385624s 2021/04/05 05:10:19 DEBUG : pacer: Reducing sleep to 0s 2021/04/05 05:10:22 DEBUG : dst/one: MD5 = 29fbcf39d882bbfd96e1fe29085969b7 OK 2021/04/05 05:10:24 DEBUG : dst/two: MD5 = ae7f224009c0b6300c51d1e4360dd06e OK 2021/04/05 05:10:25 DEBUG : dst/three.txt: MD5 = 8abf59e3ab61ab4c3d869370e97a4cc4 OK 2021/04/05 05:10:25 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6/dst" 2021/04/05 05:10:25 DEBUG : Creating backend with remote "TestDrive:crypt/re61b925b532g0toajvd6jkl8kvrnsr61om6jcbvpu8cb7u4skmggci49igg4sntaeibenodi7hu6/31u3jie661vd5p8j7rtc3hgbh0" 2021/04/05 05:10:26 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6/backup" 2021/04/05 05:10:26 DEBUG : Creating backend with remote "TestDrive:crypt/re61b925b532g0toajvd6jkl8kvrnsr61om6jcbvpu8cb7u4skmggci49igg4sntaeibenodi7hu6/1nrff024r7pq65ecp72fc28jb0" 2021/04/05 05:10:28 DEBUG : one: Sizes differ (src 4 vs dst 3) 2021/04/05 05:10:28 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2021/04/05 05:10:28 DEBUG : two: Unchanged skipping 2021/04/05 05:10:28 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6/dst': Waiting for checks to finish 2021/04/05 05:10:29 INFO : one: Moved (server-side) to: one-2019-01-01 2021/04/05 05:10:29 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6/dst': Waiting for transfers to finish 2021/04/05 05:10:30 DEBUG : one: MD5 = 9b254390d6dfbc3917e7ea0812dd3fbb OK 2021/04/05 05:10:30 INFO : one: Copied (new) 2021/04/05 05:10:30 DEBUG : Waiting for deletions to finish 2021/04/05 05:10:31 INFO : three.txt: Moved (server-side) to: three-2019-01-01.txt 2021/04/05 05:10:31 INFO : three.txt: Moved into backup dir 2021/04/05 05:10:33 DEBUG : dst/three.txt: MD5 = 580deaec6f9e84ada844d7074f68ff8c OK 2021/04/05 05:10:33 DEBUG : one: Sizes differ (src 5 vs dst 4) 2021/04/05 05:10:33 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2021/04/05 05:10:33 DEBUG : two: Unchanged skipping 2021/04/05 05:10:33 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6/dst': Waiting for checks to finish 2021/04/05 05:10:34 INFO : one-2019-01-01: Deleted 2021/04/05 05:10:35 INFO : one: Moved (server-side) to: one-2019-01-01 2021/04/05 05:10:35 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6/dst': Waiting for transfers to finish 2021/04/05 05:10:36 DEBUG : one: MD5 = d8b3561e3282c04173576214e9e4972b OK 2021/04/05 05:10:36 INFO : one: Copied (new) 2021/04/05 05:10:36 DEBUG : Waiting for deletions to finish 2021/04/05 05:10:36 INFO : three-2019-01-01.txt: Deleted 2021/04/05 05:10:37 INFO : three.txt: Moved (server-side) to: three-2019-01-01.txt 2021/04/05 05:10:37 INFO : three.txt: Moved into backup dir 2021/04/05 05:10:40 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2021/04/05 05:10:40 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" 2021/04/05 05:10:40 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "jcjl1bv3ep0v8kt35lqql1co90" 2021/04/05 05:10:40 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "qtq2f6qq4lgpsmj88vb7147qje3prudmtfdtr2342fth58vo9a50" 2021/04/05 05:10:40 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "jcjl1bv3ep0v8kt35lqql1co90" 2021/04/05 05:10:40 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "qtq2f6qq4lgpsmj88vb7147qje3prudmtfdtr2342fth58vo9a50" --- PASS: TestSyncBackupDirWithSuffixKeepExtension (23.75s) === RUN TestSyncBackupDirSuffixOnly run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6'", Local "Local file system at /tmp/rclone638061947", Modify Window "1ms" 2021/04/05 05:10:43 DEBUG : dst/one: MD5 = ed75fe4672d3fc3c4828b8a73752d314 OK 2021/04/05 05:10:44 DEBUG : dst/two: MD5 = 2150a78a6d5614963840ffdbb24b9019 OK 2021/04/05 05:10:46 DEBUG : dst/three.txt: MD5 = a67fc281bf4631402bf6de987b4113a9 OK 2021/04/05 05:10:46 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6/dst" 2021/04/05 05:10:46 DEBUG : Creating backend with remote "TestDrive:crypt/re61b925b532g0toajvd6jkl8kvrnsr61om6jcbvpu8cb7u4skmggci49igg4sntaeibenodi7hu6/31u3jie661vd5p8j7rtc3hgbh0" 2021/04/05 05:10:47 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) 2021/04/05 05:10:47 DEBUG : pacer: Rate limited, increasing sleep to 1.219197408s 2021/04/05 05:10:47 DEBUG : pacer: Reducing sleep to 0s 2021/04/05 05:10:48 DEBUG : one: Sizes differ (src 4 vs dst 3) 2021/04/05 05:10:48 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2021/04/05 05:10:48 DEBUG : two: Unchanged skipping 2021/04/05 05:10:48 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6/dst': Waiting for checks to finish 2021/04/05 05:10:49 INFO : one: Moved (server-side) to: one.bak 2021/04/05 05:10:49 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6/dst': Waiting for transfers to finish 2021/04/05 05:10:50 DEBUG : one: MD5 = 5f5f61b9cd9984f4f7d2194ad55c02bc OK 2021/04/05 05:10:50 INFO : one: Copied (new) 2021/04/05 05:10:50 DEBUG : Waiting for deletions to finish 2021/04/05 05:10:51 INFO : three.txt: Moved (server-side) to: three.txt.bak 2021/04/05 05:10:51 INFO : three.txt: Moved into backup dir 2021/04/05 05:10:52 DEBUG : dst/three.txt: MD5 = 2d54c7c5483e613393f035de8602ccae OK 2021/04/05 05:10:53 DEBUG : one.bak: Excluded from sync (and deletion) 2021/04/05 05:10:53 DEBUG : three.txt.bak: Excluded from sync (and deletion) 2021/04/05 05:10:53 DEBUG : one: Sizes differ (src 5 vs dst 4) 2021/04/05 05:10:53 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2021/04/05 05:10:53 DEBUG : two: Unchanged skipping 2021/04/05 05:10:53 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6/dst': Waiting for checks to finish 2021/04/05 05:10:54 INFO : one.bak: Deleted 2021/04/05 05:10:54 INFO : one: Moved (server-side) to: one.bak 2021/04/05 05:10:54 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6/dst': Waiting for transfers to finish 2021/04/05 05:10:55 DEBUG : one: MD5 = 0d5238b751056824f5aea8a527ed4169 OK 2021/04/05 05:10:55 INFO : one: Copied (new) 2021/04/05 05:10:55 DEBUG : Waiting for deletions to finish 2021/04/05 05:10:56 INFO : three.txt.bak: Deleted 2021/04/05 05:10:56 INFO : three.txt: Moved (server-side) to: three.txt.bak 2021/04/05 05:10:56 INFO : three.txt: Moved into backup dir 2021/04/05 05:10:59 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2021/04/05 05:10:59 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "sk91qgsqfn0r271r2ehsaoc20c" 2021/04/05 05:10:59 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "qltcak2uaegtmcoa8vijdppbp8" 2021/04/05 05:10:59 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "qltcak2uaegtmcoa8vijdppbp8" 2021/04/05 05:10:59 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" 2021/04/05 05:10:59 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "sk91qgsqfn0r271r2ehsaoc20c" --- PASS: TestSyncBackupDirSuffixOnly (18.50s) === RUN TestSyncSuffix run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6'", Local "Local file system at /tmp/rclone638061947", Modify Window "1ms" 2021/04/05 05:11:02 DEBUG : dst/one: MD5 = 9e352906c5f922dcbfbe5579a1b7136d OK 2021/04/05 05:11:03 DEBUG : dst/two: MD5 = 18cc1f5f23822ce8ba6b859b45a0a665 OK 2021/04/05 05:11:05 DEBUG : dst/three.txt: MD5 = 63b18da2fd4e8cda9ba42814b0940de7 OK 2021/04/05 05:11:05 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6/dst" 2021/04/05 05:11:05 DEBUG : Creating backend with remote "TestDrive:crypt/re61b925b532g0toajvd6jkl8kvrnsr61om6jcbvpu8cb7u4skmggci49igg4sntaeibenodi7hu6/31u3jie661vd5p8j7rtc3hgbh0" 2021/04/05 05:11:06 DEBUG : one: Sizes differ (src 4 vs dst 3) 2021/04/05 05:11:06 INFO : one: Moved (server-side) to: one.bak 2021/04/05 05:11:08 DEBUG : one: MD5 = 47378c15b216d368e0b1c874f76165a9 OK 2021/04/05 05:11:08 INFO : one: Copied (new) 2021/04/05 05:11:08 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2021/04/05 05:11:08 DEBUG : two: Unchanged skipping 2021/04/05 05:11:08 DEBUG : three.txt: Sizes differ (src 6 vs dst 5) 2021/04/05 05:11:09 INFO : three.txt: Moved (server-side) to: three.txt.bak 2021/04/05 05:11:10 DEBUG : three.txt: MD5 = 120a0e2132467bbe08d067ed961f5228 OK 2021/04/05 05:11:10 INFO : three.txt: Copied (new) 2021/04/05 05:11:11 DEBUG : one: Sizes differ (src 5 vs dst 4) 2021/04/05 05:11:12 INFO : one.bak: Deleted 2021/04/05 05:11:12 INFO : one: Moved (server-side) to: one.bak 2021/04/05 05:11:13 DEBUG : one: MD5 = e19f1c354a0b8a549d8e56c5578fc373 OK 2021/04/05 05:11:13 INFO : one: Copied (new) 2021/04/05 05:11:14 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2021/04/05 05:11:14 DEBUG : two: Unchanged skipping 2021/04/05 05:11:14 DEBUG : three.txt: Sizes differ (src 19 vs dst 6) 2021/04/05 05:11:14 INFO : three.txt.bak: Deleted 2021/04/05 05:11:15 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) 2021/04/05 05:11:15 DEBUG : pacer: Rate limited, increasing sleep to 1.947396221s 2021/04/05 05:11:15 DEBUG : pacer: Reducing sleep to 0s 2021/04/05 05:11:15 INFO : three.txt: Moved (server-side) to: three.txt.bak 2021/04/05 05:11:18 DEBUG : three.txt: MD5 = 69057096e0f85b04ed52f397b58f627a OK 2021/04/05 05:11:18 INFO : three.txt: Copied (new) 2021/04/05 05:11:21 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "tr2hj63d80ftlmvm6a952snjcc" 2021/04/05 05:11:21 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2021/04/05 05:11:21 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "qltcak2uaegtmcoa8vijdppbp8" 2021/04/05 05:11:21 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "sk91qgsqfn0r271r2ehsaoc20c" 2021/04/05 05:11:21 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "sk91qgsqfn0r271r2ehsaoc20c" 2021/04/05 05:11:21 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "qltcak2uaegtmcoa8vijdppbp8" 2021/04/05 05:11:21 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" --- PASS: TestSyncSuffix (22.02s) === RUN TestSyncSuffixKeepExtension run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6'", Local "Local file system at /tmp/rclone638061947", Modify Window "1ms" 2021/04/05 05:11:23 DEBUG : dst/one: MD5 = 457f425ba7e7a0c05b932596b1004a9d OK 2021/04/05 05:11:25 DEBUG : dst/two: MD5 = d8e4111ff62a05872889b70bd6b3aeec OK 2021/04/05 05:11:26 DEBUG : dst/three.txt: MD5 = b166005e1a3588aff23417fffaa47925 OK 2021/04/05 05:11:26 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6/dst" 2021/04/05 05:11:26 DEBUG : Creating backend with remote "TestDrive:crypt/re61b925b532g0toajvd6jkl8kvrnsr61om6jcbvpu8cb7u4skmggci49igg4sntaeibenodi7hu6/31u3jie661vd5p8j7rtc3hgbh0" 2021/04/05 05:11:26 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) 2021/04/05 05:11:26 DEBUG : pacer: Rate limited, increasing sleep to 1.182639818s 2021/04/05 05:11:27 DEBUG : pacer: Reducing sleep to 0s 2021/04/05 05:11:28 DEBUG : one: Sizes differ (src 4 vs dst 3) 2021/04/05 05:11:29 INFO : one: Moved (server-side) to: one-2019-01-01 2021/04/05 05:11:30 DEBUG : one: MD5 = 5d3c09bd3412aa4a5ecb68c705d210d9 OK 2021/04/05 05:11:30 INFO : one: Copied (new) 2021/04/05 05:11:30 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2021/04/05 05:11:30 DEBUG : two: Unchanged skipping 2021/04/05 05:11:30 DEBUG : three.txt: Sizes differ (src 6 vs dst 5) 2021/04/05 05:11:31 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) 2021/04/05 05:11:31 DEBUG : pacer: Rate limited, increasing sleep to 1.502449328s 2021/04/05 05:11:31 DEBUG : pacer: Reducing sleep to 0s 2021/04/05 05:11:33 INFO : three.txt: Moved (server-side) to: three-2019-01-01.txt 2021/04/05 05:11:34 DEBUG : three.txt: MD5 = 882847484330366f343a868950fc75e8 OK 2021/04/05 05:11:34 INFO : three.txt: Copied (new) 2021/04/05 05:11:35 DEBUG : one: Sizes differ (src 5 vs dst 4) 2021/04/05 05:11:36 INFO : one-2019-01-01: Deleted 2021/04/05 05:11:36 INFO : one: Moved (server-side) to: one-2019-01-01 2021/04/05 05:11:38 DEBUG : one: MD5 = 19b0b955071bcd9f134069c174e0a835 OK 2021/04/05 05:11:38 INFO : one: Copied (new) 2021/04/05 05:11:38 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2021/04/05 05:11:38 DEBUG : two: Unchanged skipping 2021/04/05 05:11:38 DEBUG : three.txt: Sizes differ (src 19 vs dst 6) 2021/04/05 05:11:38 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) 2021/04/05 05:11:38 DEBUG : pacer: Rate limited, increasing sleep to 1.976349869s 2021/04/05 05:11:38 DEBUG : pacer: low level retry 2/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) 2021/04/05 05:11:38 DEBUG : pacer: Rate limited, increasing sleep to 2.406918888s 2021/04/05 05:11:40 DEBUG : pacer: Reducing sleep to 0s 2021/04/05 05:11:43 INFO : three-2019-01-01.txt: Deleted 2021/04/05 05:11:44 INFO : three.txt: Moved (server-side) to: three-2019-01-01.txt 2021/04/05 05:11:45 DEBUG : three.txt: MD5 = 0ec51d4e3d48433fc6394357b7a9c5bb OK 2021/04/05 05:11:45 INFO : three.txt: Copied (new) 2021/04/05 05:11:45 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) 2021/04/05 05:11:45 DEBUG : pacer: Rate limited, increasing sleep to 1.224318729s 2021/04/05 05:11:46 DEBUG : pacer: low level retry 2/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) 2021/04/05 05:11:46 DEBUG : pacer: Rate limited, increasing sleep to 2.201396235s 2021/04/05 05:11:47 DEBUG : pacer: Reducing sleep to 0s 2021/04/05 05:11:52 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "tr2hj63d80ftlmvm6a952snjcc" 2021/04/05 05:11:52 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2021/04/05 05:11:52 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "jcjl1bv3ep0v8kt35lqql1co90" 2021/04/05 05:11:52 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "qtq2f6qq4lgpsmj88vb7147qje3prudmtfdtr2342fth58vo9a50" 2021/04/05 05:11:52 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "qtq2f6qq4lgpsmj88vb7147qje3prudmtfdtr2342fth58vo9a50" 2021/04/05 05:11:52 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" 2021/04/05 05:11:52 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "jcjl1bv3ep0v8kt35lqql1co90" --- PASS: TestSyncSuffixKeepExtension (30.76s) === RUN TestSyncUTFNorm run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6'", Local "Local file system at /tmp/rclone638061947", Modify Window "1ms" 2021/04/05 05:11:53 DEBUG : Testêé: MD5 = 08846c1e47194efa9d199cb7c2b88dae OK 2021/04/05 05:11:54 DEBUG : Testêé: Sizes differ (src 14 vs dst 18) 2021/04/05 05:11:54 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for checks to finish 2021/04/05 05:11:54 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for transfers to finish 2021/04/05 05:11:55 DEBUG : Testêé: MD5 = bd3aea6ede88c000e1dc6c3bb1776134 OK 2021/04/05 05:11:55 INFO : Testêé: Copied (replaced existing) 2021/04/05 05:11:55 DEBUG : Waiting for deletions to finish --- PASS: TestSyncUTFNorm (3.59s) === RUN TestSyncImmutable run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6'", Local "Local file system at /tmp/rclone638061947", Modify Window "1ms" 2021/04/05 05:11:56 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for checks to finish 2021/04/05 05:11:56 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for transfers to finish 2021/04/05 05:11:57 DEBUG : existing: MD5 = 13b32b2ebf35d89b10d8ca9c41ce3403 OK 2021/04/05 05:11:57 INFO : existing: Copied (new) 2021/04/05 05:11:57 DEBUG : Waiting for deletions to finish 2021/04/05 05:11:58 DEBUG : existing: Sizes differ (src 8 vs dst 6) 2021/04/05 05:11:58 ERROR : existing: Source and destination exist but do not match: immutable file modified 2021/04/05 05:11:58 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for checks to finish 2021/04/05 05:11:58 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for transfers to finish 2021/04/05 05:11:58 ERROR : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': not deleting files as there were IO errors 2021/04/05 05:11:58 ERROR : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': not deleting directories as there were IO errors 2021/04/05 05:11:58 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) 2021/04/05 05:11:58 DEBUG : pacer: Rate limited, increasing sleep to 1.909896742s 2021/04/05 05:11:58 DEBUG : pacer: low level retry 2/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) 2021/04/05 05:11:58 DEBUG : pacer: Rate limited, increasing sleep to 2.600383352s 2021/04/05 05:12:00 DEBUG : pacer: Reducing sleep to 0s --- PASS: TestSyncImmutable (7.64s) === RUN TestSyncIgnoreCase run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6'", Local "Local file system at /tmp/rclone638061947", Modify Window "1ms" 2021/04/05 05:12:05 DEBUG : EXISTING: MD5 = 8d862b226d1ee24f63e921b59bbb01f4 OK 2021/04/05 05:12:05 DEBUG : existing: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2021/04/05 05:12:05 DEBUG : existing: Unchanged skipping 2021/04/05 05:12:05 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for checks to finish 2021/04/05 05:12:05 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Waiting for transfers to finish 2021/04/05 05:12:05 DEBUG : Waiting for deletions to finish 2021/04/05 05:12:05 INFO : There was nothing to transfer --- PASS: TestSyncIgnoreCase (2.83s) === RUN TestMaxTransfer === RUN TestMaxTransfer/Hard run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6'", Local "Local file system at /tmp/rclone638061947", Modify Window "1ms" sync_test.go:1941: This test only runs on local === RUN TestMaxTransfer/Soft run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6'", Local "Local file system at /tmp/rclone638061947", Modify Window "1ms" sync_test.go:1941: This test only runs on local === RUN TestMaxTransfer/Cautious run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6'", Local "Local file system at /tmp/rclone638061947", Modify Window "1ms" sync_test.go:1941: This test only runs on local --- PASS: TestMaxTransfer (1.04s) --- SKIP: TestMaxTransfer/Hard (0.35s) --- SKIP: TestMaxTransfer/Soft (0.33s) --- SKIP: TestMaxTransfer/Cautious (0.36s) PASS 2021/04/05 05:12:07 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xejofak1lugagic4fecugoy6': Purge remote "./sync.test -test.v -test.timeout 1h0m0s -remote TestCryptDrive: -verbose -fast-list" - Finished OK in 9m5.870708054s (try 1/5)