"./sync.test -test.v -test.timeout 1h0m0s -remote TestCryptDrive: -verbose -fast-list" - Starting (try 1/5) 2022/03/24 05:04:51 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1" 2022/03/24 05:04:51 DEBUG : Using config file from "/home/rclone/.rclone.conf" 2022/03/24 05:04:51 DEBUG : Creating backend with remote "TestDrive:crypt/6b10gnlg26g3mg2q9avtop0e8plldvcgc2272956ipp59h469nauuum7r2in1spjv14ttu25s1phk" 2022/03/24 05:04:52 DEBUG : Creating backend with remote "/tmp/rclone2025790769" === RUN TestPipe --- PASS: TestPipe (0.00s) === RUN TestPipeConcurrent --- PASS: TestPipeConcurrent (0.02s) === RUN TestPipeOrderBy === RUN TestPipeOrderBy/#00 === RUN TestPipeOrderBy/size === RUN TestPipeOrderBy/name === RUN TestPipeOrderBy/modtime === RUN TestPipeOrderBy/size,ascending === RUN TestPipeOrderBy/name,asc === RUN TestPipeOrderBy/modtime,ascending === RUN TestPipeOrderBy/size,descending === RUN TestPipeOrderBy/name,desc === RUN TestPipeOrderBy/modtime,descending === RUN TestPipeOrderBy/size,mixed,50 === RUN TestPipeOrderBy/size,mixed,51 --- PASS: TestPipeOrderBy (0.00s) --- PASS: TestPipeOrderBy/#00 (0.00s) --- PASS: TestPipeOrderBy/size (0.00s) --- PASS: TestPipeOrderBy/name (0.00s) --- PASS: TestPipeOrderBy/modtime (0.00s) --- PASS: TestPipeOrderBy/size,ascending (0.00s) --- PASS: TestPipeOrderBy/name,asc (0.00s) --- PASS: TestPipeOrderBy/modtime,ascending (0.00s) --- PASS: TestPipeOrderBy/size,descending (0.00s) --- PASS: TestPipeOrderBy/name,desc (0.00s) --- PASS: TestPipeOrderBy/modtime,descending (0.00s) --- PASS: TestPipeOrderBy/size,mixed,50 (0.00s) --- PASS: TestPipeOrderBy/size,mixed,51 (0.00s) === RUN TestNewLess === RUN TestNewLess/blankOK === RUN TestNewLess/tooManyParts === RUN TestNewLess/tooManyParts2 === RUN TestNewLess/badMixed === RUN TestNewLess/unknownComparison === RUN TestNewLess/unknownSortDirection === RUN TestNewLess/size === RUN TestNewLess/name === RUN TestNewLess/modtime === RUN TestNewLess/size,ascending === RUN TestNewLess/name,asc === RUN TestNewLess/modtime,ascending === RUN TestNewLess/size,descending === RUN TestNewLess/name,desc === RUN TestNewLess/modtime,descending === RUN TestNewLess/modtime,mixed === RUN TestNewLess/modtime,mixed,30 --- PASS: TestNewLess (0.00s) --- PASS: TestNewLess/blankOK (0.00s) --- PASS: TestNewLess/tooManyParts (0.00s) --- PASS: TestNewLess/tooManyParts2 (0.00s) --- PASS: TestNewLess/badMixed (0.00s) --- PASS: TestNewLess/unknownComparison (0.00s) --- PASS: TestNewLess/unknownSortDirection (0.00s) --- PASS: TestNewLess/size (0.00s) --- PASS: TestNewLess/name (0.00s) --- PASS: TestNewLess/modtime (0.00s) --- PASS: TestNewLess/size,ascending (0.00s) --- PASS: TestNewLess/name,asc (0.00s) --- PASS: TestNewLess/modtime,ascending (0.00s) --- PASS: TestNewLess/size,descending (0.00s) --- PASS: TestNewLess/name,desc (0.00s) --- PASS: TestNewLess/modtime,descending (0.00s) --- PASS: TestNewLess/modtime,mixed (0.00s) --- PASS: TestNewLess/modtime,mixed,30 (0.00s) === RUN TestRcCopy rc_test.go:16: Skipping test on non local remote --- SKIP: TestRcCopy (0.00s) === RUN TestRcMove rc_test.go:16: Skipping test on non local remote --- SKIP: TestRcMove (0.00s) === RUN TestRcSync rc_test.go:16: Skipping test on non local remote --- SKIP: TestRcSync (0.00s) === RUN TestCopyWithDryRun run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1'", Local "Local file system at /tmp/rclone2025790769", Modify Window "1ms" 2022/03/24 05:04:53 NOTICE: sub dir/hello world: Skipped copy as --dry-run is set (size 11) 2022/03/24 05:04:53 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for checks to finish 2022/03/24 05:04:53 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for transfers to finish --- PASS: TestCopyWithDryRun (1.86s) === RUN TestCopy run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1'", Local "Local file system at /tmp/rclone2025790769", Modify Window "1ms" 2022/03/24 05:04:54 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for checks to finish 2022/03/24 05:04:54 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for transfers to finish 2022/03/24 05:04:56 DEBUG : sub dir/hello world: md5 = f04e9600f3f3ad9ea3b862b3693b247e OK 2022/03/24 05:04:56 INFO : sub dir/hello world: Copied (new) 2022/03/24 05:04:58 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestCopy (5.51s) === RUN TestCopyMissingDirectory run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1'", Local "Local file system at /tmp/rclone2025790769", Modify Window "1ms" 2022/03/24 05:04:59 DEBUG : Creating backend with remote "/non-existing" 2022/03/24 05:05:00 ERROR : Local file system at /non-existing: error reading source root directory: directory not found 2022/03/24 05:05:00 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for checks to finish 2022/03/24 05:05:00 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for transfers to finish --- PASS: TestCopyMissingDirectory (0.70s) === RUN TestCopyNoTraverse run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1'", Local "Local file system at /tmp/rclone2025790769", Modify Window "1ms" 2022/03/24 05:05:00 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for checks to finish 2022/03/24 05:05:00 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for transfers to finish 2022/03/24 05:05:03 DEBUG : sub dir/hello world: md5 = 1a23756f36fe294336b462a704351ef5 OK 2022/03/24 05:05:03 INFO : sub dir/hello world: Copied (new) 2022/03/24 05:05:05 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestCopyNoTraverse (5.36s) === RUN TestCopyCheckFirst run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1'", Local "Local file system at /tmp/rclone2025790769", Modify Window "1ms" 2022/03/24 05:05:05 INFO : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Running all checks before starting transfers 2022/03/24 05:05:06 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for checks to finish 2022/03/24 05:05:06 INFO : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Checks finished, now starting transfers 2022/03/24 05:05:06 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for transfers to finish 2022/03/24 05:05:08 DEBUG : sub dir/hello world: md5 = 75baeb6220bd9f90e9c29e3acc6e97bb OK 2022/03/24 05:05:08 INFO : sub dir/hello world: Copied (new) 2022/03/24 05:05:10 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestCopyCheckFirst (5.10s) === RUN TestSyncNoTraverse run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1'", Local "Local file system at /tmp/rclone2025790769", Modify Window "1ms" 2022/03/24 05:05:11 ERROR : Ignoring --no-traverse with sync 2022/03/24 05:05:11 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for checks to finish 2022/03/24 05:05:11 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for transfers to finish 2022/03/24 05:05:13 DEBUG : sub dir/hello world: md5 = c95dc97e69eea516a0a7efd5830dd74c OK 2022/03/24 05:05:13 INFO : sub dir/hello world: Copied (new) 2022/03/24 05:05:13 DEBUG : Waiting for deletions to finish 2022/03/24 05:05:15 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestSyncNoTraverse (5.34s) === RUN TestCopyWithDepth run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1'", Local "Local file system at /tmp/rclone2025790769", Modify Window "1ms" 2022/03/24 05:05:16 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for checks to finish 2022/03/24 05:05:16 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for transfers to finish 2022/03/24 05:05:17 DEBUG : pacer: low level retry 1/1 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/24 05:05:17 DEBUG : pacer: Rate limited, increasing sleep to 1.636864614s 2022/03/24 05:05:17 DEBUG : hello world2: Received 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 - low level retry 1/10 2022/03/24 05:05:17 DEBUG : pacer: Reducing sleep to 0s 2022/03/24 05:05:19 DEBUG : hello world2: md5 = f4f27f569509b2a592fa0172dccb404b OK 2022/03/24 05:05:19 INFO : hello world2: Copied (new) --- PASS: TestCopyWithDepth (4.78s) === RUN TestCopyWithFilesFrom run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1'", Local "Local file system at /tmp/rclone2025790769", Modify Window "1ms" 2022/03/24 05:05:21 DEBUG : hello world2: Excluded 2022/03/24 05:05:21 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for checks to finish 2022/03/24 05:05:21 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for transfers to finish 2022/03/24 05:05:22 DEBUG : potato2: md5 = 871a7aea3fd589c125f16a75f44d8ad4 OK 2022/03/24 05:05:22 INFO : potato2: Copied (new) --- PASS: TestCopyWithFilesFrom (2.92s) === RUN TestCopyWithFilesFromAndNoTraverse run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1'", Local "Local file system at /tmp/rclone2025790769", Modify Window "1ms" 2022/03/24 05:05:24 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for checks to finish 2022/03/24 05:05:24 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for transfers to finish 2022/03/24 05:05:25 DEBUG : potato2: md5 = 819c45051175028623922739efc63b65 OK 2022/03/24 05:05:25 INFO : potato2: Copied (new) --- PASS: TestCopyWithFilesFromAndNoTraverse (3.00s) === RUN TestCopyEmptyDirectories run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1'", Local "Local file system at /tmp/rclone2025790769", Modify Window "1ms" 2022/03/24 05:05:27 DEBUG : sub dir2: Making directory 2022/03/24 05:05:27 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for checks to finish 2022/03/24 05:05:27 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for transfers to finish 2022/03/24 05:05:29 DEBUG : sub dir/hello world: md5 = 30f018d158e4ee50ec8b2d96049e3004 OK 2022/03/24 05:05:29 INFO : sub dir/hello world: Copied (new) 2022/03/24 05:05:29 DEBUG : sub dir2: Making directory 2022/03/24 05:05:30 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': copied 1 directories 2022/03/24 05:05:33 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestCopyEmptyDirectories (6.90s) === RUN TestMoveEmptyDirectories run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1'", Local "Local file system at /tmp/rclone2025790769", Modify Window "1ms" 2022/03/24 05:05:34 DEBUG : sub dir2: Making directory 2022/03/24 05:05:34 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for checks to finish 2022/03/24 05:05:34 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for transfers to finish 2022/03/24 05:05:36 DEBUG : sub dir/hello world: md5 = 892483381af4f9e099c07d1cb7c4156e OK 2022/03/24 05:05:36 INFO : sub dir/hello world: Copied (new) 2022/03/24 05:05:36 INFO : sub dir/hello world: Deleted 2022/03/24 05:05:36 DEBUG : sub dir: Making directory 2022/03/24 05:05:36 DEBUG : sub dir2: Making directory 2022/03/24 05:05:37 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': copied 2 directories 2022/03/24 05:05:40 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestMoveEmptyDirectories (6.91s) === RUN TestSyncEmptyDirectories run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1'", Local "Local file system at /tmp/rclone2025790769", Modify Window "1ms" 2022/03/24 05:05:40 DEBUG : sub dir2: Making directory 2022/03/24 05:05:41 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for checks to finish 2022/03/24 05:05:41 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for transfers to finish 2022/03/24 05:05:43 DEBUG : sub dir/hello world: md5 = 86af9276a0b5c908842b09176ef56ca1 OK 2022/03/24 05:05:43 INFO : sub dir/hello world: Copied (new) 2022/03/24 05:05:43 DEBUG : sub dir2: Making directory 2022/03/24 05:05:44 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': copied 1 directories 2022/03/24 05:05:44 DEBUG : Waiting for deletions to finish 2022/03/24 05:05:47 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestSyncEmptyDirectories (7.92s) === RUN TestServerSideCopy run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1'", Local "Local file system at /tmp/rclone2025790769", Modify Window "1ms" 2022/03/24 05:05:51 DEBUG : sub dir/hello world: md5 = 595acfae88350cf16995c178b670bb99 OK 2022/03/24 05:05:51 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-cudozoz8qahuqir3jokunoc2" 2022/03/24 05:05:52 DEBUG : Creating backend with remote "TestDrive:crypt/qcg282thh8v861l5h70d45ekhm4obcjfnf1i1iiu8fmlb96na0ap8u5phndunr99b2o5f178sstfq" sync_test.go:275: Server side copy (if possible) Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1' -> Encrypted drive 'TestCryptDrive:rclone-test-cudozoz8qahuqir3jokunoc2' 2022/03/24 05:05:53 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cudozoz8qahuqir3jokunoc2': Waiting for checks to finish 2022/03/24 05:05:53 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cudozoz8qahuqir3jokunoc2': Waiting for transfers to finish 2022/03/24 05:05:57 INFO : sub dir/hello world: Copied (server-side copy) 2022/03/24 05:05:57 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-cudozoz8qahuqir3jokunoc2': Purge remote 2022/03/24 05:06:00 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestServerSideCopy (12.16s) === RUN TestCopyAfterDelete run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1'", Local "Local file system at /tmp/rclone2025790769", Modify Window "1ms" 2022/03/24 05:06:03 DEBUG : sub dir/hello world: md5 = 40c0a478d84523e357c739f245049b46 OK 2022/03/24 05:06:03 ERROR : : error listing: directory not found 2022/03/24 05:06:04 DEBUG : Local file system at /tmp/rclone2025790769: Making directory 2022/03/24 05:06:04 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for checks to finish 2022/03/24 05:06:04 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for transfers to finish 2022/03/24 05:06:06 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestCopyAfterDelete (6.51s) === RUN TestCopyRedownload run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1'", Local "Local file system at /tmp/rclone2025790769", Modify Window "1ms" 2022/03/24 05:06:10 DEBUG : sub dir/hello world: md5 = 801d284e8aee052615cf8973b69f194e OK 2022/03/24 05:06:11 DEBUG : Local file system at /tmp/rclone2025790769: Waiting for checks to finish 2022/03/24 05:06:11 DEBUG : Local file system at /tmp/rclone2025790769: Waiting for transfers to finish 2022/03/24 05:06:12 INFO : sub dir/hello world: Copied (new) 2022/03/24 05:06:13 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestCopyRedownload (6.86s) === RUN TestSyncBasedOnCheckSum run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1'", Local "Local file system at /tmp/rclone2025790769", Modify Window "1ms" 2022/03/24 05:06:14 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for checks to finish 2022/03/24 05:06:14 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for transfers to finish 2022/03/24 05:06:16 DEBUG : check sum: md5 = ac89631c5fba658498aacd6637dd71c2 OK 2022/03/24 05:06:16 INFO : check sum: Copied (new) 2022/03/24 05:06:16 DEBUG : Waiting for deletions to finish 2022/03/24 05:06:16 NOTICE: Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': --checksum is in use but the source and destination have no hashes in common; falling back to --size-only 2022/03/24 05:06:16 DEBUG : check sum: Size of src and dst objects identical 2022/03/24 05:06:16 DEBUG : check sum: Unchanged skipping 2022/03/24 05:06:16 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for checks to finish 2022/03/24 05:06:16 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for transfers to finish 2022/03/24 05:06:16 DEBUG : Waiting for deletions to finish 2022/03/24 05:06:16 INFO : There was nothing to transfer --- PASS: TestSyncBasedOnCheckSum (3.58s) === RUN TestSyncSizeOnly run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1'", Local "Local file system at /tmp/rclone2025790769", Modify Window "1ms" 2022/03/24 05:06:18 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for checks to finish 2022/03/24 05:06:18 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for transfers to finish 2022/03/24 05:06:19 DEBUG : sizeonly: md5 = 84160a2df78ff21a6b61bd2e89280b70 OK 2022/03/24 05:06:19 INFO : sizeonly: Copied (new) 2022/03/24 05:06:19 DEBUG : Waiting for deletions to finish 2022/03/24 05:06:20 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for checks to finish 2022/03/24 05:06:20 DEBUG : sizeonly: Sizes identical 2022/03/24 05:06:20 DEBUG : sizeonly: Unchanged skipping 2022/03/24 05:06:20 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for transfers to finish 2022/03/24 05:06:20 DEBUG : Waiting for deletions to finish 2022/03/24 05:06:20 INFO : There was nothing to transfer --- PASS: TestSyncSizeOnly (3.70s) === RUN TestSyncIgnoreSize run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1'", Local "Local file system at /tmp/rclone2025790769", Modify Window "1ms" 2022/03/24 05:06:21 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for checks to finish 2022/03/24 05:06:21 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for transfers to finish 2022/03/24 05:06:23 DEBUG : ignore-size: md5 = 02a8b83b43ac19b0aedab09324261b0f OK 2022/03/24 05:06:23 INFO : ignore-size: Copied (new) 2022/03/24 05:06:23 DEBUG : Waiting for deletions to finish 2022/03/24 05:06:23 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for checks to finish 2022/03/24 05:06:23 DEBUG : ignore-size: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/24 05:06:23 DEBUG : ignore-size: Unchanged skipping 2022/03/24 05:06:23 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for transfers to finish 2022/03/24 05:06:23 DEBUG : Waiting for deletions to finish 2022/03/24 05:06:23 INFO : There was nothing to transfer --- PASS: TestSyncIgnoreSize (3.50s) === RUN TestSyncIgnoreTimes run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1'", Local "Local file system at /tmp/rclone2025790769", Modify Window "1ms" 2022/03/24 05:06:26 DEBUG : existing: md5 = fff2265ce7afbaabdb86d736d65a8340 OK 2022/03/24 05:06:27 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for checks to finish 2022/03/24 05:06:27 DEBUG : existing: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/24 05:06:27 DEBUG : existing: Unchanged skipping 2022/03/24 05:06:27 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for transfers to finish 2022/03/24 05:06:27 DEBUG : Waiting for deletions to finish 2022/03/24 05:06:27 INFO : There was nothing to transfer 2022/03/24 05:06:27 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for checks to finish 2022/03/24 05:06:27 DEBUG : existing: Transferring unconditionally as --ignore-times is in use 2022/03/24 05:06:27 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for transfers to finish 2022/03/24 05:06:28 DEBUG : existing: md5 = f430146397ed32d1a15204d2d32158cd OK 2022/03/24 05:06:28 INFO : existing: Copied (replaced existing) 2022/03/24 05:06:28 DEBUG : Waiting for deletions to finish --- PASS: TestSyncIgnoreTimes (4.86s) === RUN TestSyncIgnoreExisting run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1'", Local "Local file system at /tmp/rclone2025790769", Modify Window "1ms" 2022/03/24 05:06:30 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for checks to finish 2022/03/24 05:06:30 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for transfers to finish 2022/03/24 05:06:31 DEBUG : existing: md5 = c4678e4f2e857be90cb170b7e9bf6c68 OK 2022/03/24 05:06:31 INFO : existing: Copied (new) 2022/03/24 05:06:31 DEBUG : Waiting for deletions to finish 2022/03/24 05:06:32 DEBUG : existing: Destination exists, skipping 2022/03/24 05:06:32 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for checks to finish 2022/03/24 05:06:32 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for transfers to finish 2022/03/24 05:06:32 DEBUG : Waiting for deletions to finish 2022/03/24 05:06:32 INFO : There was nothing to transfer --- PASS: TestSyncIgnoreExisting (3.58s) === RUN TestSyncIgnoreErrors run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1'", Local "Local file system at /tmp/rclone2025790769", Modify Window "1ms" 2022/03/24 05:06:36 DEBUG : b/potato: md5 = 88d16a74ba096f725a4c54c0c8db945e OK 2022/03/24 05:06:38 DEBUG : c/non empty space: md5 = 0543e13e0eff15b76a33e675527b3de5 OK 2022/03/24 05:06:38 DEBUG : d: Making directory 2022/03/24 05:06:39 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/24 05:06:39 DEBUG : pacer: Rate limited, increasing sleep to 1.664914711s 2022/03/24 05:06:39 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) 2022/03/24 05:06:39 DEBUG : pacer: Rate limited, increasing sleep to 2.579836677s 2022/03/24 05:06:41 DEBUG : pacer: Reducing sleep to 0s 2022/03/24 05:06:44 DEBUG : c/non empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/24 05:06:44 DEBUG : c/non empty space: Unchanged skipping 2022/03/24 05:06:44 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for checks to finish 2022/03/24 05:06:44 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for transfers to finish 2022/03/24 05:06:46 DEBUG : a/potato2: md5 = f2fd91c7cfd10a85df275c69339c3990 OK 2022/03/24 05:06:46 INFO : a/potato2: Copied (new) 2022/03/24 05:06:46 DEBUG : Waiting for deletions to finish 2022/03/24 05:06:47 INFO : b/potato: Deleted 2022/03/24 05:06:47 INFO : d: Removing directory 2022/03/24 05:06:48 INFO : b: Removing directory 2022/03/24 05:06:49 DEBUG : 32d8ua6196mc1r7qkfog53rkg0: Rmdir: contains trashed file: "2m507n64kafsi59v9q71r281a4" 2022/03/24 05:06:49 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': deleted 2 directories 2022/03/24 05:06:50 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/24 05:06:50 DEBUG : pacer: Rate limited, increasing sleep to 1.754534485s 2022/03/24 05:06:50 DEBUG : pacer: Reducing sleep to 0s 2022/03/24 05:06:53 DEBUG : 3i9du405pfogq3ncai6pg7ouio: Rmdir: contains trashed file: "982d3pss7t5pn0il16r2foj31s" 2022/03/24 05:06:54 DEBUG : 2bsvlrk2ne1lfitm6tttcu0qt8: Rmdir: contains trashed file: "89l8renevh3mji1c8r1p7qn6tg" --- PASS: TestSyncIgnoreErrors (21.65s) === RUN TestSyncAfterChangingModtimeOnly run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1'", Local "Local file system at /tmp/rclone2025790769", Modify Window "1ms" 2022/03/24 05:06:56 DEBUG : empty space: md5 = 335d77225a130ac81de385ce0ae88141 OK 2022/03/24 05:06:57 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for checks to finish 2022/03/24 05:06:57 DEBUG : empty space: Modification times differ by -95456h54m52.624456789s: 2011-12-25 12:59:59.123456789 +0000 UTC, 2001-02-03 04:05:06.499 +0000 UTC 2022/03/24 05:06:57 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for transfers to finish 2022/03/24 05:06:57 NOTICE: empty space: Skipped copy as --dry-run is set (size 1) 2022/03/24 05:06:57 DEBUG : Waiting for deletions to finish 2022/03/24 05:06:57 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for checks to finish 2022/03/24 05:06:57 DEBUG : empty space: Modification times differ by -95456h54m52.624456789s: 2011-12-25 12:59:59.123456789 +0000 UTC, 2001-02-03 04:05:06.499 +0000 UTC 2022/03/24 05:06:57 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for transfers to finish 2022/03/24 05:06:59 DEBUG : empty space: md5 = adf76cf4dd903965b9092cf82dbf68ff OK 2022/03/24 05:06:59 INFO : empty space: Copied (replaced existing) 2022/03/24 05:06:59 DEBUG : Waiting for deletions to finish --- PASS: TestSyncAfterChangingModtimeOnly (5.03s) === RUN TestSyncAfterChangingModtimeOnlyWithNoUpdateModTime run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1'", Local "Local file system at /tmp/rclone2025790769", Modify Window "1ms" sync_test.go:577: Can't check this if no hashes supported --- PASS: TestSyncAfterChangingModtimeOnlyWithNoUpdateModTime (0.44s) === RUN TestSyncDoesntUpdateModtime run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1'", Local "Local file system at /tmp/rclone2025790769", Modify Window "1ms" 2022/03/24 05:07:02 DEBUG : foo: md5 = c21b7bb357ccf0ca2a52ce47d20a6182 OK 2022/03/24 05:07:02 DEBUG : foo: Modification times differ by -95456h54m52.624456789s: 2011-12-25 12:59:59.123456789 +0000 UTC, 2001-02-03 04:05:06.499 +0000 UTC 2022/03/24 05:07:02 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for checks to finish 2022/03/24 05:07:02 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for transfers to finish 2022/03/24 05:07:03 DEBUG : foo: md5 = 455bc8f894eb3b97005fe2edd5f96720 OK 2022/03/24 05:07:03 INFO : foo: Copied (replaced existing) 2022/03/24 05:07:03 DEBUG : Waiting for deletions to finish --- PASS: TestSyncDoesntUpdateModtime (4.36s) === RUN TestSyncAfterAddingAFile run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1'", Local "Local file system at /tmp/rclone2025790769", Modify Window "1ms" 2022/03/24 05:07:06 DEBUG : empty space: md5 = 16eaf95b1fc604638c88e4b5ba162ead OK 2022/03/24 05:07:07 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for checks to finish 2022/03/24 05:07:07 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/24 05:07:07 DEBUG : empty space: Unchanged skipping 2022/03/24 05:07:07 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for transfers to finish 2022/03/24 05:07:08 DEBUG : potato: md5 = 8e91b2917e8a78856d15e136cf51cfa1 OK 2022/03/24 05:07:08 INFO : potato: Copied (new) 2022/03/24 05:07:08 DEBUG : Waiting for deletions to finish --- PASS: TestSyncAfterAddingAFile (5.51s) === RUN TestSyncAfterChangingFilesSizeOnly run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1'", Local "Local file system at /tmp/rclone2025790769", Modify Window "1ms" 2022/03/24 05:07:12 DEBUG : potato: md5 = 4c7395110dbbb2d698ecada0e433fee6 OK 2022/03/24 05:07:12 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for checks to finish 2022/03/24 05:07:12 DEBUG : potato: Sizes differ (src 21 vs dst 60) 2022/03/24 05:07:12 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for transfers to finish 2022/03/24 05:07:13 DEBUG : potato: md5 = bcd9be73175aa49b4dc320ed934a400a OK 2022/03/24 05:07:13 INFO : potato: Copied (replaced existing) 2022/03/24 05:07:13 DEBUG : Waiting for deletions to finish --- PASS: TestSyncAfterChangingFilesSizeOnly (4.38s) === RUN TestSyncAfterChangingContentsOnly run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1'", Local "Local file system at /tmp/rclone2025790769", Modify Window "1ms" 2022/03/24 05:07:16 DEBUG : potato: md5 = 1aba25a34d9619f0d3b884cc302701f2 OK 2022/03/24 05:07:16 DEBUG : potato: Modification times differ by 119h59m59.876543211s: 2011-12-25 12:59:59.123456789 +0000 UTC, 2011-12-30 12:59:59 +0000 UTC 2022/03/24 05:07:16 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for checks to finish 2022/03/24 05:07:16 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for transfers to finish 2022/03/24 05:07:18 DEBUG : potato: md5 = b9ceaf6b621a7b60762e2af441d10c37 OK 2022/03/24 05:07:18 INFO : potato: Copied (replaced existing) 2022/03/24 05:07:18 DEBUG : Waiting for deletions to finish --- PASS: TestSyncAfterChangingContentsOnly (4.79s) === RUN TestSyncAfterRemovingAFileAndAddingAFileDryRun run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1'", Local "Local file system at /tmp/rclone2025790769", Modify Window "1ms" 2022/03/24 05:07:21 DEBUG : potato: md5 = 039dda48756a6138fcfc3954409817b8 OK 2022/03/24 05:07:23 DEBUG : empty space: md5 = 529a50cefd264d7add3f50f73be9b3a3 OK 2022/03/24 05:07:23 NOTICE: potato2: Skipped copy as --dry-run is set (size 60) 2022/03/24 05:07:23 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/24 05:07:23 DEBUG : empty space: Unchanged skipping 2022/03/24 05:07:23 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for checks to finish 2022/03/24 05:07:23 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for transfers to finish 2022/03/24 05:07:23 DEBUG : Waiting for deletions to finish 2022/03/24 05:07:23 NOTICE: potato: Skipped delete as --dry-run is set (size 21) --- PASS: TestSyncAfterRemovingAFileAndAddingAFileDryRun (5.52s) === RUN TestSyncAfterRemovingAFileAndAddingAFile run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1'", Local "Local file system at /tmp/rclone2025790769", Modify Window "1ms" 2022/03/24 05:07:26 DEBUG : potato: md5 = f701f7a4f80c5824107a98ee2764978e OK 2022/03/24 05:07:28 DEBUG : empty space: md5 = 8dceb880c6670880ea209f16ddcf28e8 OK 2022/03/24 05:07:28 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for checks to finish 2022/03/24 05:07:28 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/24 05:07:28 DEBUG : empty space: Unchanged skipping 2022/03/24 05:07:28 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for transfers to finish 2022/03/24 05:07:30 DEBUG : potato2: md5 = b9886c101772ebb67b626af9a6f576b2 OK 2022/03/24 05:07:30 INFO : potato2: Copied (new) 2022/03/24 05:07:30 DEBUG : Waiting for deletions to finish 2022/03/24 05:07:30 INFO : potato: Deleted --- PASS: TestSyncAfterRemovingAFileAndAddingAFile (7.38s) === RUN TestSyncAfterRemovingAFileAndAddingAFileSubDir run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1'", Local "Local file system at /tmp/rclone2025790769", Modify Window "1ms" 2022/03/24 05:07:34 DEBUG : b/potato: md5 = 7fd848ccf01fd20501848ea8ec0cba6e OK 2022/03/24 05:07:37 DEBUG : c/non empty space: md5 = fcd17014f4d5b8081c1f23d7964e2840 OK 2022/03/24 05:07:37 DEBUG : d: Making directory 2022/03/24 05:07:38 DEBUG : d/e: Making directory 2022/03/24 05:07:40 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for checks to finish 2022/03/24 05:07:40 DEBUG : c/non empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/24 05:07:40 DEBUG : c/non empty space: Unchanged skipping 2022/03/24 05:07:40 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for transfers to finish 2022/03/24 05:07:43 DEBUG : a/potato2: md5 = feb6820cf6f0dbe39246aae1090d3cfb OK 2022/03/24 05:07:43 INFO : a/potato2: Copied (new) 2022/03/24 05:07:43 DEBUG : Waiting for deletions to finish 2022/03/24 05:07:43 INFO : b/potato: Deleted 2022/03/24 05:07:43 INFO : d/e: Removing directory 2022/03/24 05:07:44 INFO : d: Removing directory 2022/03/24 05:07:44 DEBUG : ka6id8d20d3s5ktapedlphgta8: Rmdir: contains trashed file: "r8sppajuabeak3sbgj2ak8vuf8" 2022/03/24 05:07:45 INFO : b: Removing directory 2022/03/24 05:07:45 DEBUG : 32d8ua6196mc1r7qkfog53rkg0: Rmdir: contains trashed file: "2m507n64kafsi59v9q71r281a4" 2022/03/24 05:07:46 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': deleted 3 directories 2022/03/24 05:07:49 DEBUG : 3i9du405pfogq3ncai6pg7ouio: Rmdir: contains trashed file: "982d3pss7t5pn0il16r2foj31s" 2022/03/24 05:07:50 DEBUG : 2bsvlrk2ne1lfitm6tttcu0qt8: Rmdir: contains trashed file: "89l8renevh3mji1c8r1p7qn6tg" 2022/03/24 05:07: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) 2022/03/24 05:07:51 DEBUG : pacer: Rate limited, increasing sleep to 1.874264787s 2022/03/24 05:07:51 DEBUG : pacer: Reducing sleep to 0s --- PASS: TestSyncAfterRemovingAFileAndAddingAFileSubDir (18.57s) === RUN TestSyncAfterRemovingAFileAndAddingAFileSubDirWithErrors run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1'", Local "Local file system at /tmp/rclone2025790769", Modify Window "1ms" 2022/03/24 05:07:55 DEBUG : b/potato: md5 = 90db4a149355148a537f34f3230ad31b OK 2022/03/24 05:07:57 DEBUG : c/non empty space: md5 = c4b612b18c42ed45c47e9a863110c690 OK 2022/03/24 05:07:57 DEBUG : d: Making directory 2022/03/24 05:07:59 DEBUG : c/non empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/24 05:07:59 DEBUG : c/non empty space: Unchanged skipping 2022/03/24 05:07:59 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for checks to finish 2022/03/24 05:07:59 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for transfers to finish 2022/03/24 05:08:02 DEBUG : a/potato2: md5 = 1e63bc106fa25103fcdc8fff22b55177 OK 2022/03/24 05:08:02 INFO : a/potato2: Copied (new) 2022/03/24 05:08:02 ERROR : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': not deleting files as there were IO errors 2022/03/24 05:08:02 ERROR : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': not deleting directories as there were IO errors 2022/03/24 05:08:05 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/24 05:08:05 DEBUG : pacer: Rate limited, increasing sleep to 1.896625693s 2022/03/24 05:08:05 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) 2022/03/24 05:08:05 DEBUG : pacer: Rate limited, increasing sleep to 2.702331161s 2022/03/24 05:08:07 DEBUG : pacer: Reducing sleep to 0s 2022/03/24 05:08:10 DEBUG : 3i9du405pfogq3ncai6pg7ouio: Rmdir: contains trashed file: "982d3pss7t5pn0il16r2foj31s" 2022/03/24 05:08:11 DEBUG : 32d8ua6196mc1r7qkfog53rkg0: Rmdir: contains trashed file: "2m507n64kafsi59v9q71r281a4" 2022/03/24 05:08:12 DEBUG : 2bsvlrk2ne1lfitm6tttcu0qt8: Rmdir: contains trashed file: "89l8renevh3mji1c8r1p7qn6tg" --- PASS: TestSyncAfterRemovingAFileAndAddingAFileSubDirWithErrors (21.91s) === RUN TestSyncDeleteAfter --- PASS: TestSyncDeleteAfter (0.00s) === RUN TestSyncDeleteDuring run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1'", Local "Local file system at /tmp/rclone2025790769", Modify Window "1ms" 2022/03/24 05:08:14 DEBUG : potato: md5 = 80a743e01b9334db1ac50d773b3ebf4c OK 2022/03/24 05:08:15 DEBUG : empty space: md5 = eb4453bf0faf92afb070f2333fbee129 OK 2022/03/24 05:08:16 DEBUG : Waiting for deletions to finish 2022/03/24 05:08:16 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/24 05:08:16 DEBUG : empty space: Unchanged skipping 2022/03/24 05:08:16 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for checks to finish 2022/03/24 05:08:16 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for transfers to finish 2022/03/24 05:08:17 INFO : potato: Deleted 2022/03/24 05:08:17 DEBUG : potato2: md5 = 2dba536c6ecf5d2b00cef5efdd637d03 OK 2022/03/24 05:08:17 INFO : potato2: Copied (new) --- PASS: TestSyncDeleteDuring (6.82s) === RUN TestSyncDeleteBefore run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1'", Local "Local file system at /tmp/rclone2025790769", Modify Window "1ms" 2022/03/24 05:08:21 DEBUG : potato: md5 = c67d79f8c1f94bb390b07766cb607c6f OK 2022/03/24 05:08:22 DEBUG : empty space: md5 = 578653a6807d4867ca3781c904d89048 OK 2022/03/24 05:08:23 DEBUG : Waiting for deletions to finish 2022/03/24 05:08:23 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for checks to finish 2022/03/24 05:08:23 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for transfers to finish 2022/03/24 05:08:24 INFO : potato: Deleted 2022/03/24 05:08:24 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for checks to finish 2022/03/24 05:08:24 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/24 05:08:24 DEBUG : empty space: Unchanged skipping 2022/03/24 05:08:24 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for transfers to finish 2022/03/24 05:08:25 DEBUG : potato2: md5 = 33cc1366e3b66709bb4ea4d4777790a2 OK 2022/03/24 05:08:25 INFO : potato2: Copied (new) --- PASS: TestSyncDeleteBefore (7.66s) === RUN TestCopyDeleteBefore run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1'", Local "Local file system at /tmp/rclone2025790769", Modify Window "1ms" 2022/03/24 05:08:29 DEBUG : potato: md5 = 3e6a263203cd5f19a95f87af3e809586 OK 2022/03/24 05:08:29 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for checks to finish 2022/03/24 05:08:29 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for transfers to finish 2022/03/24 05:08:31 DEBUG : potato2: md5 = 0cdd4d4a374174c90392199ae19e3203 OK 2022/03/24 05:08:31 INFO : potato2: Copied (new) --- PASS: TestCopyDeleteBefore (5.42s) === RUN TestSyncWithExclude run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1'", Local "Local file system at /tmp/rclone2025790769", Modify Window "1ms" 2022/03/24 05:08:34 DEBUG : potato2: md5 = 53710d7994412a1c262efd4d779914a2 OK 2022/03/24 05:08:36 DEBUG : empty space: md5 = 7c28ab66833d39471cba634bd0509603 OK 2022/03/24 05:08:36 DEBUG : enormous: Excluded 2022/03/24 05:08:36 DEBUG : potato2: Excluded 2022/03/24 05:08:36 DEBUG : potato2: Excluded from sync (and deletion) 2022/03/24 05:08:36 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/24 05:08:36 DEBUG : empty space: Unchanged skipping 2022/03/24 05:08:36 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for checks to finish 2022/03/24 05:08:36 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for transfers to finish 2022/03/24 05:08:36 DEBUG : Waiting for deletions to finish 2022/03/24 05:08:36 INFO : There was nothing to transfer 2022/03/24 05:08:36 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/24 05:08:36 DEBUG : pacer: Rate limited, increasing sleep to 1.784849709s 2022/03/24 05:08:37 DEBUG : pacer: Reducing sleep to 0s 2022/03/24 05:08:37 DEBUG : enormous: Excluded 2022/03/24 05:08:37 DEBUG : potato2: Excluded 2022/03/24 05:08:39 DEBUG : potato2: Excluded from sync (and deletion) 2022/03/24 05:08:39 DEBUG : empty space: Size and modification time the same (differ by 456.789µs, within tolerance 1ms) 2022/03/24 05:08:39 DEBUG : empty space: Unchanged skipping 2022/03/24 05:08:39 DEBUG : Local file system at /tmp/rclone2025790769: Waiting for checks to finish 2022/03/24 05:08:39 DEBUG : Local file system at /tmp/rclone2025790769: Waiting for transfers to finish 2022/03/24 05:08:39 DEBUG : Waiting for deletions to finish 2022/03/24 05:08:39 INFO : There was nothing to transfer --- PASS: TestSyncWithExclude (7.65s) === RUN TestSyncWithExcludeAndDeleteExcluded run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1'", Local "Local file system at /tmp/rclone2025790769", Modify Window "1ms" 2022/03/24 05:08:42 DEBUG : potato2: md5 = 7270545443ffd59c86b669d45c5417d0 OK 2022/03/24 05:08:43 DEBUG : empty space: md5 = 77332cd0bf0947aaee4e230db775c63e OK 2022/03/24 05:08:45 DEBUG : enormous: md5 = 2411858de68d39fde9d785caa85c1539 OK 2022/03/24 05:08:45 DEBUG : enormous: Excluded 2022/03/24 05:08:45 DEBUG : potato2: Excluded 2022/03/24 05:08:45 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/24 05:08:45 DEBUG : empty space: Unchanged skipping 2022/03/24 05:08:45 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for checks to finish 2022/03/24 05:08:45 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for transfers to finish 2022/03/24 05:08:45 DEBUG : Waiting for deletions to finish 2022/03/24 05:08:46 INFO : potato2: Deleted 2022/03/24 05:08:46 INFO : enormous: Deleted 2022/03/24 05:08:46 INFO : There was nothing to transfer 2022/03/24 05:08:47 DEBUG : empty space: Size and modification time the same (differ by 456.789µs, within tolerance 1ms) 2022/03/24 05:08:47 DEBUG : empty space: Unchanged skipping 2022/03/24 05:08:47 DEBUG : Local file system at /tmp/rclone2025790769: Waiting for checks to finish 2022/03/24 05:08:47 DEBUG : Local file system at /tmp/rclone2025790769: Waiting for transfers to finish 2022/03/24 05:08:47 DEBUG : Waiting for deletions to finish 2022/03/24 05:08:47 INFO : enormous: Deleted 2022/03/24 05:08:47 INFO : potato2: Deleted 2022/03/24 05:08:47 INFO : There was nothing to transfer --- PASS: TestSyncWithExcludeAndDeleteExcluded (7.53s) === RUN TestSyncWithUpdateOlder run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1'", Local "Local file system at /tmp/rclone2025790769", Modify Window "1ms" 2022/03/24 05:08:49 DEBUG : one: md5 = 10e0c3e7b77d0ba64dd90cd4d2e76a5b OK 2022/03/24 05:08:51 DEBUG : two: md5 = 9416ef4c83229ad3b2078c838cef85ee OK 2022/03/24 05:08:52 DEBUG : three: md5 = 4b899a7d495515e35fd100a1f9e7aa9a OK 2022/03/24 05:08:53 DEBUG : four: md5 = 28b2decbcabdcf62a954b99417052f97 OK 2022/03/24 05:08:54 DEBUG : four: Sizes differ (src 4 vs dst 8) 2022/03/24 05:08:54 DEBUG : four: Destination mod time is within 1s of source but files differ, transferring 2022/03/24 05:08:54 DEBUG : one: Destination is newer than source, skipping 2022/03/24 05:08:54 DEBUG : three: Sizes identical 2022/03/24 05:08:54 DEBUG : three: Destination mod time is within 1s of source and files identical, skipping 2022/03/24 05:08:54 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for checks to finish 2022/03/24 05:08:54 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for transfers to finish 2022/03/24 05:08:55 DEBUG : two: md5 = c95cbc6d4a45385a40bfcc222529ca7f OK 2022/03/24 05:08:55 INFO : two: Copied (replaced existing) 2022/03/24 05:08:55 DEBUG : four: md5 = c97ff5d85a49e348414faaefaffa432f OK 2022/03/24 05:08:55 INFO : four: Copied (replaced existing) 2022/03/24 05:08:55 DEBUG : five: md5 = 7f697f8d4704ec2f77035b87463f92f3 OK 2022/03/24 05:08:55 INFO : five: Copied (new) 2022/03/24 05:08:55 DEBUG : Waiting for deletions to finish sync_test.go:992: Skip test with --checksum as no hashes supported --- PASS: TestSyncWithUpdateOlder (11.26s) === RUN TestSyncWithMaxDuration sync_test.go:1009: Skipping test on non local remote --- SKIP: TestSyncWithMaxDuration (0.00s) === RUN TestSyncWithTrackRenames run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1'", Local "Local file system at /tmp/rclone2025790769", Modify Window "1ms" sync_test.go:1058: Can track renames: false 2022/03/24 05:08:59 ERROR : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Ignoring --track-renames as the source and destination do not have a common hash 2022/03/24 05:08:59 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for checks to finish 2022/03/24 05:08:59 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for transfers to finish 2022/03/24 05:09:01 DEBUG : potato: md5 = 22afd8654488c3e1a1fdeba7c25a5adf OK 2022/03/24 05:09:01 INFO : potato: Copied (new) 2022/03/24 05:09:01 DEBUG : yam: md5 = 4c07daaa01ecfc615f8abec0274482cc OK 2022/03/24 05:09:01 INFO : yam: Copied (new) 2022/03/24 05:09:01 DEBUG : Waiting for deletions to finish 2022/03/24 05:09:01 ERROR : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Ignoring --track-renames as the source and destination do not have a common hash 2022/03/24 05:09:02 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for checks to finish 2022/03/24 05:09:02 DEBUG : potato: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/24 05:09:02 DEBUG : potato: Unchanged skipping 2022/03/24 05:09:02 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for transfers to finish 2022/03/24 05:09:03 DEBUG : yaml: md5 = a406ee1b840ba9be2865c5b5ee1ea066 OK 2022/03/24 05:09:03 INFO : yaml: Copied (new) 2022/03/24 05:09:03 DEBUG : Waiting for deletions to finish 2022/03/24 05:09:04 INFO : yam: Deleted 2022/03/24 05:09:04 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/24 05:09:04 DEBUG : pacer: Rate limited, increasing sleep to 1.472867891s 2022/03/24 05:09:04 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) 2022/03/24 05:09:04 DEBUG : pacer: Rate limited, increasing sleep to 2.566319953s 2022/03/24 05:09:06 DEBUG : pacer: Reducing sleep to 0s --- PASS: TestSyncWithTrackRenames (10.14s) === RUN TestParseRenamesStrategyModtime --- PASS: TestParseRenamesStrategyModtime (0.00s) === RUN TestRenamesStrategyModtime --- PASS: TestRenamesStrategyModtime (0.00s) === RUN TestSyncWithTrackRenamesStrategyModtime run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1'", Local "Local file system at /tmp/rclone2025790769", Modify Window "1ms" sync_test.go:1127: Can track renames: true 2022/03/24 05:09:09 INFO : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Making map for --track-renames 2022/03/24 05:09:09 INFO : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Finished making map for --track-renames 2022/03/24 05:09:09 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for checks to finish 2022/03/24 05:09:09 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for renames to finish 2022/03/24 05:09:09 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for transfers to finish 2022/03/24 05:09:10 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/24 05:09:10 DEBUG : pacer: Rate limited, increasing sleep to 1.490112273s 2022/03/24 05:09:10 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/24 05:09:10 DEBUG : pacer: Rate limited, increasing sleep to 2.900445719s 2022/03/24 05:09:10 DEBUG : pacer: Reducing sleep to 0s 2022/03/24 05:09:12 DEBUG : yam: md5 = cb7658f0cc94e61abe6b7b02c030e890 OK 2022/03/24 05:09:12 INFO : yam: Copied (new) 2022/03/24 05:09:13 DEBUG : potato: md5 = 53672dc8997d65650c067fbb9d2dd7f4 OK 2022/03/24 05:09:13 INFO : potato: Copied (new) 2022/03/24 05:09:13 DEBUG : Waiting for deletions to finish 2022/03/24 05:09:13 DEBUG : potato: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/24 05:09:13 DEBUG : potato: Unchanged skipping 2022/03/24 05:09:13 INFO : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Making map for --track-renames 2022/03/24 05:09:13 INFO : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Finished making map for --track-renames 2022/03/24 05:09:13 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for checks to finish 2022/03/24 05:09:13 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for renames to finish 2022/03/24 05:09:14 INFO : yam: Moved (server-side) to: yaml 2022/03/24 05:09:14 INFO : yaml: Renamed from "yam" 2022/03/24 05:09:14 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for transfers to finish 2022/03/24 05:09:14 DEBUG : Waiting for deletions to finish 2022/03/24 05:09:14 INFO : There was nothing to transfer 2022/03/24 05:09: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) 2022/03/24 05:09:16 DEBUG : pacer: Rate limited, increasing sleep to 1.377168649s 2022/03/24 05:09:16 DEBUG : pacer: Reducing sleep to 0s --- PASS: TestSyncWithTrackRenamesStrategyModtime (7.96s) === RUN TestSyncWithTrackRenamesStrategyLeaf run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1'", Local "Local file system at /tmp/rclone2025790769", Modify Window "1ms" sync_test.go:1163: Can track renames: true 2022/03/24 05:09:17 INFO : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Making map for --track-renames 2022/03/24 05:09:17 INFO : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Finished making map for --track-renames 2022/03/24 05:09:17 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for checks to finish 2022/03/24 05:09:17 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for renames to finish 2022/03/24 05:09:17 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for transfers to finish 2022/03/24 05:09: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) 2022/03/24 05:09:18 DEBUG : pacer: Rate limited, increasing sleep to 1.418811991s 2022/03/24 05:09:18 DEBUG : pacer: Reducing sleep to 0s 2022/03/24 05:09:21 DEBUG : potato: md5 = 68f6dfafac879bdfde0df362603975a3 OK 2022/03/24 05:09:21 INFO : potato: Copied (new) 2022/03/24 05:09:21 DEBUG : sub/yam: md5 = 015fd7818d8bf0e67f5a6ba07e5651fd OK 2022/03/24 05:09:21 INFO : sub/yam: Copied (new) 2022/03/24 05:09:21 DEBUG : Waiting for deletions to finish 2022/03/24 05:09:22 DEBUG : potato: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/24 05:09:22 DEBUG : potato: Unchanged skipping 2022/03/24 05:09:22 INFO : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Making map for --track-renames 2022/03/24 05:09:22 INFO : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Finished making map for --track-renames 2022/03/24 05:09:22 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for checks to finish 2022/03/24 05:09:22 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for renames to finish 2022/03/24 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) 2022/03/24 05:09:23 DEBUG : pacer: Rate limited, increasing sleep to 1.824674064s 2022/03/24 05:09:23 DEBUG : pacer: Reducing sleep to 0s 2022/03/24 05:09:23 INFO : sub/yam: Moved (server-side) to: yam 2022/03/24 05:09:23 INFO : yam: Renamed from "sub/yam" 2022/03/24 05:09:23 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for transfers to finish 2022/03/24 05:09:23 DEBUG : Waiting for deletions to finish 2022/03/24 05:09:23 INFO : There was nothing to transfer --- PASS: TestSyncWithTrackRenamesStrategyLeaf (10.49s) === RUN TestMoveWithDeleteEmptySrcDirs run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1'", Local "Local file system at /tmp/rclone2025790769", Modify Window "1ms" 2022/03/24 05:09:28 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for checks to finish 2022/03/24 05:09:28 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for transfers to finish 2022/03/24 05:09:30 DEBUG : sub dir/hello world: md5 = 6a13275d85643242cad25f9ab2144817 OK 2022/03/24 05:09:30 INFO : sub dir/hello world: Copied (new) 2022/03/24 05:09:30 INFO : sub dir/hello world: Deleted 2022/03/24 05:09:32 DEBUG : nested/sub dir/file: md5 = a8f84326587754eaa82a2142481268b5 OK 2022/03/24 05:09:32 INFO : nested/sub dir/file: Copied (new) 2022/03/24 05:09:32 INFO : nested/sub dir/file: Deleted 2022/03/24 05:09:32 INFO : sub dir: Removing directory 2022/03/24 05:09:32 INFO : nested/sub dir: Removing directory 2022/03/24 05:09:32 INFO : nested: Removing directory 2022/03/24 05:09:32 DEBUG : Local file system at /tmp/rclone2025790769: deleted 3 directories 2022/03/24 05:09:34 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/24 05:09:34 DEBUG : pacer: Rate limited, increasing sleep to 1.850340218s 2022/03/24 05:09:34 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) 2022/03/24 05:09:34 DEBUG : pacer: Rate limited, increasing sleep to 2.243075347s 2022/03/24 05:09:36 DEBUG : pacer: Reducing sleep to 0s 2022/03/24 05:09:40 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" 2022/03/24 05:09:40 DEBUG : 37qp6d1gohacv723ij3brofbu8/14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "ftp4kuv8se7tqduu6pmmcvjsmk" 2022/03/24 05:09:41 DEBUG : 37qp6d1gohacv723ij3brofbu8: Rmdir: contains trashed file: "14begaa36ih249fgrnfk6nulg0" --- PASS: TestMoveWithDeleteEmptySrcDirs (14.50s) === RUN TestMoveWithoutDeleteEmptySrcDirs run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1'", Local "Local file system at /tmp/rclone2025790769", Modify Window "1ms" 2022/03/24 05:09:42 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for checks to finish 2022/03/24 05:09:42 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for transfers to finish 2022/03/24 05:09:45 DEBUG : sub dir/hello world: md5 = bbf0c3100c7cff369043fe8caa9ca07c OK 2022/03/24 05:09:45 INFO : sub dir/hello world: Copied (new) 2022/03/24 05:09:45 INFO : sub dir/hello world: Deleted 2022/03/24 05:09:47 DEBUG : nested/sub dir/file: md5 = b1c80a3eb3391340f7fe8a01d9088df3 OK 2022/03/24 05:09:47 INFO : nested/sub dir/file: Copied (new) 2022/03/24 05:09:47 INFO : nested/sub dir/file: Deleted 2022/03/24 05:09:48 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/24 05:09:48 DEBUG : pacer: Rate limited, increasing sleep to 1.664203569s 2022/03/24 05:09:49 DEBUG : pacer: Reducing sleep to 0s 2022/03/24 05:09:53 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" 2022/03/24 05:09:54 DEBUG : 37qp6d1gohacv723ij3brofbu8/14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "ftp4kuv8se7tqduu6pmmcvjsmk" 2022/03/24 05:09:57 DEBUG : 37qp6d1gohacv723ij3brofbu8: Rmdir: contains trashed file: "14begaa36ih249fgrnfk6nulg0" --- PASS: TestMoveWithoutDeleteEmptySrcDirs (15.61s) === RUN TestMoveWithIgnoreExisting run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1'", Local "Local file system at /tmp/rclone2025790769", Modify Window "1ms" 2022/03/24 05:09:58 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for checks to finish 2022/03/24 05:09:58 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for transfers to finish 2022/03/24 05:09:59 DEBUG : existing-b: md5 = a171462129b761e326e665881acf0185 OK 2022/03/24 05:09:59 INFO : existing-b: Copied (new) 2022/03/24 05:09:59 INFO : existing-b: Deleted 2022/03/24 05:10:00 DEBUG : existing: md5 = a12399499e5398b4d178250f3fbcd19d OK 2022/03/24 05:10:00 INFO : existing: Copied (new) 2022/03/24 05:10:00 INFO : existing: Deleted 2022/03/24 05:10:00 DEBUG : existing: Destination exists, skipping 2022/03/24 05:10:00 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for checks to finish 2022/03/24 05:10:00 DEBUG : existing: Not removing source file as destination file exists and --ignore-existing is set 2022/03/24 05:10:00 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for transfers to finish 2022/03/24 05:10:00 INFO : There was nothing to transfer --- PASS: TestMoveWithIgnoreExisting (6.02s) === RUN TestServerSideMove run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1'", Local "Local file system at /tmp/rclone2025790769", Modify Window "1ms" 2022/03/24 05:10:04 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-kamisat5tinucak8nupasuj5" 2022/03/24 05:10:04 DEBUG : Creating backend with remote "TestDrive:crypt/4u2dq3a5o0rrohiiq7dvqivrlun6b8mh2aou27t64kv16m2fnk3ct0n5o2d17iv61g2266ombg2ii" 2022/03/24 05:10:08 DEBUG : potato2: md5 = ec0bbab9b3b431f2ee1dd15cc0086ee9 OK 2022/03/24 05:10:09 DEBUG : empty space: md5 = 830536c6032328cab91a1871bb51a2d3 OK 2022/03/24 05:10:11 DEBUG : potato3: md5 = 83d9e9fcffa2cf1326cac3396a0c4a4b OK sync_test.go:1215: Server side move (if possible) Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1' -> Encrypted drive 'TestCryptDrive:rclone-test-kamisat5tinucak8nupasuj5' 2022/03/24 05:10:15 DEBUG : empty space: md5 = f9cead770b589c8166b0e2cb2aadff2e OK 2022/03/24 05:10:16 DEBUG : potato3: md5 = 56a139620657f472b920a1ddddb21d11 OK 2022/03/24 05:10:17 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-kamisat5tinucak8nupasuj5': Using server-side directory move 2022/03/24 05:10:17 INFO : Encrypted drive 'TestCryptDrive:rclone-test-kamisat5tinucak8nupasuj5': Server side directory move failed - fallback to file moves: can't copy directory - destination already exists 2022/03/24 05:10:17 DEBUG : empty space: Size and modification time the same (differ by 0s, within tolerance 1ms) 2022/03/24 05:10:17 DEBUG : empty space: Unchanged skipping 2022/03/24 05:10:17 DEBUG : potato3: Sizes differ (src 68 vs dst 60) 2022/03/24 05:10:17 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-kamisat5tinucak8nupasuj5': Waiting for checks to finish 2022/03/24 05:10:18 INFO : potato3: Deleted 2022/03/24 05:10:18 INFO : empty space: Deleted 2022/03/24 05:10:18 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-kamisat5tinucak8nupasuj5': Waiting for transfers to finish 2022/03/24 05:10:18 INFO : potato2: Moved (server-side) 2022/03/24 05:10:18 INFO : potato3: Moved (server-side) 2022/03/24 05:10:18 INFO : There was nothing to transfer 2022/03/24 05:10:19 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-yebocef5lokuned9raqocin8" 2022/03/24 05:10:19 DEBUG : Config file has changed externaly - reloading 2022/03/24 05:10:19 DEBUG : Creating backend with remote "TestDrive:crypt/gh7n5vu7841g0vm9kt431oa6avqh3oijbl5mljk432gtn2j00p7qpmn482npgf19iosrpvgbb99hk" 2022/03/24 05:10:20 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-yebocef5lokuned9raqocin8': Using server-side directory move 2022/03/24 05:10:21 INFO : Encrypted drive 'TestCryptDrive:rclone-test-yebocef5lokuned9raqocin8': Server side directory move succeeded 2022/03/24 05:10:22 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-yebocef5lokuned9raqocin8': Purge remote 2022/03/24 05:10:24 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-kamisat5tinucak8nupasuj5': Purge remote 2022/03/24 05:10:24 purge failed: directory not found --- PASS: TestServerSideMove (20.49s) === RUN TestServerSideMoveWithFilter run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1'", Local "Local file system at /tmp/rclone2025790769", Modify Window "1ms" 2022/03/24 05:10:24 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-yeziwum0wewibat3kowazob3" 2022/03/24 05:10:24 DEBUG : Creating backend with remote "TestDrive:crypt/72aejhv5avl0t1b1r8hkn2neqqcdbn067lp603iv9eubjb5t01r1rhjub8lki9if0n5f0kp7os67e" 2022/03/24 05:10:24 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/24 05:10:24 DEBUG : pacer: Rate limited, increasing sleep to 1.678957496s 2022/03/24 05:10:25 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) 2022/03/24 05:10:25 DEBUG : pacer: Rate limited, increasing sleep to 2.900610636s 2022/03/24 05:10:26 DEBUG : pacer: Reducing sleep to 0s 2022/03/24 05:10:31 DEBUG : potato2: md5 = 812a5011d6bec5ad87b1992af1a3241f OK 2022/03/24 05:10:33 DEBUG : empty space: md5 = 5fa1ddbbb0d6421b9142870aa98a1a6b OK 2022/03/24 05:10:34 DEBUG : potato3: md5 = bef28355899c118e12213bae41466465 OK sync_test.go:1215: Server side move (if possible) Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1' -> Encrypted drive 'TestCryptDrive:rclone-test-yeziwum0wewibat3kowazob3' 2022/03/24 05:10:37 DEBUG : empty space: md5 = a9cd8f08cb8f148e325c7cfefea551c4 OK 2022/03/24 05:10:39 DEBUG : potato3: md5 = 2e228f73effd6c87beed5a07f0770bd9 OK 2022/03/24 05:10:39 DEBUG : empty space: Excluded from sync (and deletion) 2022/03/24 05:10:39 DEBUG : empty space: Excluded from sync (and deletion) 2022/03/24 05:10:39 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-yeziwum0wewibat3kowazob3': Waiting for checks to finish 2022/03/24 05:10:39 DEBUG : potato3: Sizes differ (src 68 vs dst 60) 2022/03/24 05:10:39 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-yeziwum0wewibat3kowazob3': Waiting for transfers to finish 2022/03/24 05:10:40 INFO : potato3: Deleted 2022/03/24 05:10:40 INFO : potato2: Moved (server-side) 2022/03/24 05:10:42 INFO : potato3: Moved (server-side) 2022/03/24 05:10:42 INFO : There was nothing to transfer 2022/03/24 05:10:42 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-webuned9hucejut3wawukuc8" 2022/03/24 05:10:42 DEBUG : Creating backend with remote "TestDrive:crypt/fl23a04vbfmpjl7kdlnopa0g9kmel6v7ta3p4jk7aovma40422tep19mg67oup6bno7l9sdgv8mfs" 2022/03/24 05:10:44 DEBUG : empty space: Excluded from sync (and deletion) 2022/03/24 05:10:44 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-webuned9hucejut3wawukuc8': Waiting for checks to finish 2022/03/24 05:10:44 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-webuned9hucejut3wawukuc8': Waiting for transfers to finish 2022/03/24 05:10:45 INFO : potato3: Moved (server-side) 2022/03/24 05:10:46 INFO : potato2: Moved (server-side) 2022/03/24 05:10:46 INFO : There was nothing to transfer 2022/03/24 05:10:46 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-webuned9hucejut3wawukuc8': Purge remote 2022/03/24 05:10:47 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-yeziwum0wewibat3kowazob3': Purge remote --- PASS: TestServerSideMoveWithFilter (24.77s) === RUN TestServerSideMoveDeleteEmptySourceDirs run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1'", Local "Local file system at /tmp/rclone2025790769", Modify Window "1ms" 2022/03/24 05:10:49 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-siqomof1jomevir4mawilaw6" 2022/03/24 05:10:49 DEBUG : Creating backend with remote "TestDrive:crypt/esng49rs3e432tg5vj7bbv0p6teg53ut8m23l539mau7qpqlq8d9rjlmemjakl3sg0shecj0sn9a2" 2022/03/24 05:10:52 DEBUG : potato2: md5 = 00dc5b37bc1711667d442d8954dee362 OK 2022/03/24 05:10:55 DEBUG : empty space: md5 = 94f057ff63d2e03470fed6d43a50743c OK 2022/03/24 05:10:57 DEBUG : potato3: md5 = f48c8b2e57b549207a21191477ddcbbf OK 2022/03/24 05:10:57 DEBUG : tomatoDir: Making directory sync_test.go:1215: Server side move (if possible) Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1' -> Encrypted drive 'TestCryptDrive:rclone-test-siqomof1jomevir4mawilaw6' 2022/03/24 05:11:01 DEBUG : empty space: md5 = 1fc1b5c336b4e8dda4620fdf302b8d96 OK 2022/03/24 05:11:02 DEBUG : potato3: md5 = 6c463e67fd187d8a268a6e62d765d52c OK 2022/03/24 05:11:02 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-siqomof1jomevir4mawilaw6': Using server-side directory move 2022/03/24 05:11:02 INFO : Encrypted drive 'TestCryptDrive:rclone-test-siqomof1jomevir4mawilaw6': Server side directory move failed - fallback to file moves: can't copy directory - destination already exists 2022/03/24 05:11:03 DEBUG : empty space: Size and modification time the same (differ by 0s, within tolerance 1ms) 2022/03/24 05:11:03 DEBUG : empty space: Unchanged skipping 2022/03/24 05:11:03 DEBUG : potato3: Sizes differ (src 68 vs dst 60) 2022/03/24 05:11:03 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-siqomof1jomevir4mawilaw6': Waiting for checks to finish 2022/03/24 05:11:03 INFO : potato3: Deleted 2022/03/24 05:11:03 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/24 05:11:03 DEBUG : pacer: Rate limited, increasing sleep to 1.866858309s 2022/03/24 05:11:03 INFO : empty space: Deleted 2022/03/24 05:11:03 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-siqomof1jomevir4mawilaw6': Waiting for transfers to finish 2022/03/24 05:11:04 DEBUG : pacer: Reducing sleep to 0s 2022/03/24 05:11:04 INFO : potato2: Moved (server-side) 2022/03/24 05:11:04 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) 2022/03/24 05:11:04 DEBUG : pacer: Rate limited, increasing sleep to 1.007521367s 2022/03/24 05:11:05 DEBUG : pacer: low level retry 3/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/24 05:11:05 DEBUG : pacer: Rate limited, increasing sleep to 2.188311414s 2022/03/24 05:11:07 DEBUG : pacer: Reducing sleep to 0s 2022/03/24 05:11:07 INFO : potato3: Moved (server-side) 2022/03/24 05:11:07 INFO : tomatoDir: Removing directory 2022/03/24 05:11:08 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': deleted 1 directories 2022/03/24 05:11:08 INFO : There was nothing to transfer 2022/03/24 05:11:09 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-ritefog8milasoj7nakizun4" 2022/03/24 05:11:09 DEBUG : Creating backend with remote "TestDrive:crypt/df6f6nlmmk1q33fp65lhao3ipad79gh1d6co347j39voq4bd280qbjp06sp1pum0d1lcumei04e9g" 2022/03/24 05:11:10 DEBUG : tomatoDir: Making directory 2022/03/24 05:11:11 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-ritefog8milasoj7nakizun4': Using server-side directory move 2022/03/24 05:11:12 INFO : Encrypted drive 'TestCryptDrive:rclone-test-ritefog8milasoj7nakizun4': Server side directory move succeeded 2022/03/24 05:11: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) 2022/03/24 05:11:13 DEBUG : pacer: Rate limited, increasing sleep to 1.172254212s 2022/03/24 05:11:13 DEBUG : pacer: Reducing sleep to 0s 2022/03/24 05:11:14 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-ritefog8milasoj7nakizun4': Purge remote 2022/03/24 05:11:15 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-siqomof1jomevir4mawilaw6': Purge remote 2022/03/24 05:11:15 purge failed: directory not found --- PASS: TestServerSideMoveDeleteEmptySourceDirs (26.38s) === RUN TestServerSideMoveOverlap run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1'", Local "Local file system at /tmp/rclone2025790769", Modify Window "1ms" sync_test.go:1399: Skipping test as remote supports DirMove --- SKIP: TestServerSideMoveOverlap (0.48s) === RUN TestSyncOverlap run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1'", Local "Local file system at /tmp/rclone2025790769", Modify Window "1ms" 2022/03/24 05:11:16 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1/rclone-sync-test" 2022/03/24 05:11:16 DEBUG : Creating backend with remote "TestDrive:crypt/6b10gnlg26g3mg2q9avtop0e8plldvcgc2272956ipp59h469nauuum7r2in1spjv14ttu25s1phk/i7355aa0sb89uagn75vfjqr6s3e3e1h2et8in57abn1fe8qfego0" --- PASS: TestSyncOverlap (2.10s) === RUN TestSyncCompareDest run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1'", Local "Local file system at /tmp/rclone2025790769", Modify Window "1ms" 2022/03/24 05:11:18 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1/dst" 2022/03/24 05:11:18 DEBUG : Creating backend with remote "TestDrive:crypt/6b10gnlg26g3mg2q9avtop0e8plldvcgc2272956ipp59h469nauuum7r2in1spjv14ttu25s1phk/31u3jie661vd5p8j7rtc3hgbh0" 2022/03/24 05:11:20 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1/CompareDest" 2022/03/24 05:11:20 DEBUG : Creating backend with remote "TestDrive:crypt/6b10gnlg26g3mg2q9avtop0e8plldvcgc2272956ipp59h469nauuum7r2in1spjv14ttu25s1phk/gveqi14airsml4bgu7krj116o8" 2022/03/24 05:11:20 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/24 05:11:20 DEBUG : pacer: Rate limited, increasing sleep to 1.92105667s 2022/03/24 05:11:21 DEBUG : pacer: Reducing sleep to 0s 2022/03/24 05:11:23 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1/dst': Waiting for checks to finish 2022/03/24 05:11:23 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1/dst': Waiting for transfers to finish 2022/03/24 05:11: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) 2022/03/24 05:11:23 DEBUG : pacer: Rate limited, increasing sleep to 1.965170114s 2022/03/24 05:11:24 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) 2022/03/24 05:11:24 DEBUG : pacer: Rate limited, increasing sleep to 2.483246185s 2022/03/24 05:11:26 DEBUG : pacer: low level retry 3/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/24 05:11:26 DEBUG : pacer: Rate limited, increasing sleep to 4.162466373s 2022/03/24 05:11:28 DEBUG : pacer: Reducing sleep to 0s 2022/03/24 05:11:34 DEBUG : one: md5 = 1c205e0c254c81e8e7c16e04a843a200 OK 2022/03/24 05:11:34 INFO : one: Copied (new) 2022/03/24 05:11:34 DEBUG : Waiting for deletions to finish 2022/03/24 05:11:36 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1/dst': Waiting for checks to finish 2022/03/24 05:11:36 DEBUG : one: Sizes differ (src 5 vs dst 3) 2022/03/24 05:11:36 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1/dst': Waiting for transfers to finish 2022/03/24 05:11:37 DEBUG : one: md5 = 2f2dc661db5d025fe4e7cdc536348563 OK 2022/03/24 05:11:37 INFO : one: Copied (replaced existing) 2022/03/24 05:11:37 DEBUG : Waiting for deletions to finish 2022/03/24 05:11:39 DEBUG : dst/one: md5 = 026635c846b6337cdef81d60e7f49ea0 OK 2022/03/24 05:11:41 DEBUG : CompareDest/one: md5 = dd6c0bb6793ab41a19f885e5f34595cc OK 2022/03/24 05:11:42 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1/dst': Waiting for checks to finish 2022/03/24 05:11: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) 2022/03/24 05:11:43 DEBUG : pacer: Rate limited, increasing sleep to 1.365028205s 2022/03/24 05:11: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) 2022/03/24 05:11:43 DEBUG : pacer: Rate limited, increasing sleep to 2.142605939s 2022/03/24 05:11:44 DEBUG : pacer: low level retry 3/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/24 05:11:44 DEBUG : pacer: Rate limited, increasing sleep to 4.102011676s 2022/03/24 05:11:46 DEBUG : pacer: Reducing sleep to 0s 2022/03/24 05:11:46 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/24 05:11:46 DEBUG : one: Destination found in --compare-dest, skipping 2022/03/24 05:11:46 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1/dst': Waiting for transfers to finish 2022/03/24 05:11:46 DEBUG : Waiting for deletions to finish 2022/03/24 05:11:46 INFO : There was nothing to transfer 2022/03/24 05:11:48 DEBUG : CompareDest/two: md5 = 3e053697d2e5d39293ae2aa9bea50a52 OK 2022/03/24 05:11:51 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/24 05:11:51 DEBUG : two: Destination found in --compare-dest, skipping 2022/03/24 05:11:51 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1/dst': Waiting for checks to finish 2022/03/24 05:11:51 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/24 05:11:51 DEBUG : one: Destination found in --compare-dest, skipping 2022/03/24 05:11:51 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1/dst': Waiting for transfers to finish 2022/03/24 05:11:51 DEBUG : Waiting for deletions to finish 2022/03/24 05:11:51 INFO : There was nothing to transfer 2022/03/24 05:11:52 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/24 05:11:52 DEBUG : two: Destination found in --compare-dest, skipping 2022/03/24 05:11:52 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1/dst': Waiting for checks to finish 2022/03/24 05:11:52 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/24 05:11:52 DEBUG : one: Destination found in --compare-dest, skipping 2022/03/24 05:11:52 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1/dst': Waiting for transfers to finish 2022/03/24 05:11:52 DEBUG : Waiting for deletions to finish 2022/03/24 05:11:52 INFO : There was nothing to transfer sync_test.go:1543: No hash on uploaded file so skipping compare timestamp test 2022/03/24 05:11:54 DEBUG : two: Sizes differ (src 5 vs dst 3) 2022/03/24 05:11:54 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1/dst': Waiting for checks to finish 2022/03/24 05:11:54 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/24 05:11:54 DEBUG : one: Destination found in --compare-dest, skipping 2022/03/24 05:11:54 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1/dst': Waiting for transfers to finish 2022/03/24 05:11:55 DEBUG : two: md5 = b403fc3db82af3929ef722a726b050ea OK 2022/03/24 05:11:55 INFO : two: Copied (new) 2022/03/24 05:11:55 DEBUG : Waiting for deletions to finish 2022/03/24 05:11:59 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" 2022/03/24 05:11:59 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2022/03/24 05:12:00 DEBUG : gveqi14airsml4bgu7krj116o8: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2022/03/24 05:12:00 DEBUG : gveqi14airsml4bgu7krj116o8: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" --- PASS: TestSyncCompareDest (42.51s) === RUN TestSyncMultipleCompareDest run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1'", Local "Local file system at /tmp/rclone2025790769", Modify Window "1ms" 2022/03/24 05:12:03 DEBUG : pre-dest1/1: md5 = beec8c09d8bd5882fce076c784a25ad9 OK 2022/03/24 05:12:05 DEBUG : pre-dest2/2: md5 = 531be76dd66975a4a48f953e1a788f15 OK 2022/03/24 05:12:05 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/24 05:12:05 DEBUG : pacer: Rate limited, increasing sleep to 1.835474732s 2022/03/24 05:12:05 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) 2022/03/24 05:12:05 DEBUG : pacer: Rate limited, increasing sleep to 2.49757546s 2022/03/24 05:12:07 DEBUG : pacer: Reducing sleep to 0s 2022/03/24 05:12:10 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1/dest" 2022/03/24 05:12:10 DEBUG : Creating backend with remote "TestDrive:crypt/6b10gnlg26g3mg2q9avtop0e8plldvcgc2272956ipp59h469nauuum7r2in1spjv14ttu25s1phk/rg03c1jvnehrrc617i0lnqjddc" 2022/03/24 05:12:11 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1/pre-dest1" 2022/03/24 05:12:11 DEBUG : Creating backend with remote "TestDrive:crypt/6b10gnlg26g3mg2q9avtop0e8plldvcgc2272956ipp59h469nauuum7r2in1spjv14ttu25s1phk/bbnblvh6k061ssopqrp18kd7gc" 2022/03/24 05:12:12 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1/pre-dest2" 2022/03/24 05:12:12 DEBUG : Creating backend with remote "TestDrive:crypt/6b10gnlg26g3mg2q9avtop0e8plldvcgc2272956ipp59h469nauuum7r2in1spjv14ttu25s1phk/dgicm1h6b5ejvlltm8eeif0bnk" 2022/03/24 05:12:13 DEBUG : 1: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/24 05:12:13 DEBUG : 1: Destination found in --compare-dest, skipping 2022/03/24 05:12:14 DEBUG : 2: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/24 05:12:14 DEBUG : 2: Destination found in --compare-dest, skipping 2022/03/24 05:12:14 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1/dest': Waiting for checks to finish 2022/03/24 05:12:14 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1/dest': Waiting for transfers to finish 2022/03/24 05:12:15 DEBUG : pacer: low level retry 1/1 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/24 05:12:15 DEBUG : pacer: Rate limited, increasing sleep to 1.376853666s 2022/03/24 05:12:15 DEBUG : 3: Received 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 - low level retry 1/10 2022/03/24 05:12:16 DEBUG : pacer: Reducing sleep to 0s 2022/03/24 05:12:18 DEBUG : 3: md5 = dc3d4e5179e4dccecaa7ee009be6c1df OK 2022/03/24 05:12:18 INFO : 3: Copied (new) 2022/03/24 05:12:18 DEBUG : Waiting for deletions to finish 2022/03/24 05:12:22 DEBUG : dgicm1h6b5ejvlltm8eeif0bnk: Rmdir: contains trashed file: "1ghu8geql9vrl726n32nrf65bc" 2022/03/24 05:12:23 DEBUG : bbnblvh6k061ssopqrp18kd7gc: Rmdir: contains trashed file: "skbfko3oil7es0lj68ob574sro" 2022/03/24 05:12:24 DEBUG : rg03c1jvnehrrc617i0lnqjddc: Rmdir: contains trashed file: "g072p7hmjchlnj0gibe64c1epg" --- PASS: TestSyncMultipleCompareDest (23.99s) === RUN TestSyncCopyDest run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1'", Local "Local file system at /tmp/rclone2025790769", Modify Window "1ms" 2022/03/24 05:12:24 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1/dst" 2022/03/24 05:12:25 DEBUG : Creating backend with remote "TestDrive:crypt/6b10gnlg26g3mg2q9avtop0e8plldvcgc2272956ipp59h469nauuum7r2in1spjv14ttu25s1phk/31u3jie661vd5p8j7rtc3hgbh0" 2022/03/24 05:12:25 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/24 05:12:25 DEBUG : pacer: Rate limited, increasing sleep to 1.218560412s 2022/03/24 05:12:25 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) 2022/03/24 05:12:25 DEBUG : pacer: Rate limited, increasing sleep to 2.805771547s 2022/03/24 05:12:26 DEBUG : pacer: Reducing sleep to 0s 2022/03/24 05:12:30 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1/CopyDest" 2022/03/24 05:12:30 DEBUG : Creating backend with remote "TestDrive:crypt/6b10gnlg26g3mg2q9avtop0e8plldvcgc2272956ipp59h469nauuum7r2in1spjv14ttu25s1phk/d09o6po3f7bm6ce32vdgs8h9ls" 2022/03/24 05:12:32 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1/dst': Waiting for checks to finish 2022/03/24 05:12:32 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1/dst': Waiting for transfers to finish 2022/03/24 05:12:34 DEBUG : one: md5 = 9ad7668a1834d107598a125b4240d5ad OK 2022/03/24 05:12:34 INFO : one: Copied (new) 2022/03/24 05:12:34 DEBUG : Waiting for deletions to finish 2022/03/24 05:12:34 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/24 05:12:34 DEBUG : pacer: Rate limited, increasing sleep to 1.048808528s 2022/03/24 05:12:35 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) 2022/03/24 05:12:35 DEBUG : pacer: Rate limited, increasing sleep to 2.606609596s 2022/03/24 05:12:36 DEBUG : pacer: Reducing sleep to 0s 2022/03/24 05:12:39 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1/dst': Waiting for checks to finish 2022/03/24 05:12:39 DEBUG : one: Sizes differ (src 5 vs dst 3) 2022/03/24 05:12:39 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1/dst': Waiting for transfers to finish 2022/03/24 05:12:40 DEBUG : one: md5 = 4364a1fe6f729f26c864b77922736c3f OK 2022/03/24 05:12:40 INFO : one: Copied (replaced existing) 2022/03/24 05:12:40 DEBUG : Waiting for deletions to finish 2022/03/24 05:12:42 DEBUG : dst/one: md5 = 8e4435879536c1820ffa16058007f2d1 OK 2022/03/24 05:12:45 DEBUG : CopyDest/one: md5 = 92cf3e24a633764b3855625eb82b906a OK 2022/03/24 05:12:45 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1/BackupDir" 2022/03/24 05:12:45 DEBUG : Config file has changed externaly - reloading 2022/03/24 05:12:45 DEBUG : Creating backend with remote "TestDrive:crypt/6b10gnlg26g3mg2q9avtop0e8plldvcgc2272956ipp59h469nauuum7r2in1spjv14ttu25s1phk/s6dbk3lfi7c9kfvo6j7bla9m0g" 2022/03/24 05:12:47 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1/dst': Waiting for checks to finish 2022/03/24 05:12:48 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/24 05:12:48 DEBUG : one: Sizes differ (src 5 vs dst 3) 2022/03/24 05:12:50 INFO : one: Moved (server-side) 2022/03/24 05:12:51 INFO : one: Copied (server-side copy) 2022/03/24 05:12:51 DEBUG : one: Destination found in --copy-dest, using server-side copy 2022/03/24 05:12:51 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1/dst': Waiting for transfers to finish 2022/03/24 05:12:51 DEBUG : Waiting for deletions to finish 2022/03/24 05:12:53 DEBUG : CopyDest/two: md5 = 832ac976c0a3e9c6386d85247ffa38c4 OK 2022/03/24 05:12:53 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/24 05:12:53 DEBUG : pacer: Rate limited, increasing sleep to 1.816365513s 2022/03/24 05:12:53 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/24 05:12:53 DEBUG : pacer: Rate limited, increasing sleep to 2.404446137s 2022/03/24 05:12:53 DEBUG : pacer: Reducing sleep to 0s 2022/03/24 05:12:55 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) 2022/03/24 05:12:55 DEBUG : pacer: Rate limited, increasing sleep to 1.292891698s 2022/03/24 05:12:55 DEBUG : pacer: low level retry 3/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/24 05:12:55 DEBUG : pacer: Rate limited, increasing sleep to 2.763943808s 2022/03/24 05:12:57 DEBUG : pacer: Reducing sleep to 0s 2022/03/24 05:12:57 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/24 05:12:59 INFO : two: Copied (server-side copy) 2022/03/24 05:12:59 DEBUG : two: Destination found in --copy-dest, using server-side copy 2022/03/24 05:12:59 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1/dst': Waiting for checks to finish 2022/03/24 05:12:59 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/24 05:12:59 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/24 05:12:59 DEBUG : one: Unchanged skipping 2022/03/24 05:12:59 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1/dst': Waiting for transfers to finish 2022/03/24 05:12:59 DEBUG : Waiting for deletions to finish 2022/03/24 05:13:00 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1/dst': Waiting for checks to finish 2022/03/24 05:13:00 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/24 05:13:00 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/24 05:13:00 DEBUG : one: Unchanged skipping 2022/03/24 05:13:00 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/24 05:13:00 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/24 05:13:00 DEBUG : two: Unchanged skipping 2022/03/24 05:13:00 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1/dst': Waiting for transfers to finish 2022/03/24 05:13:00 DEBUG : Waiting for deletions to finish 2022/03/24 05:13:00 INFO : There was nothing to transfer 2022/03/24 05:13:03 DEBUG : CopyDest/three: md5 = 67dd82dfecf74413189a1eb6ace35fc2 OK 2022/03/24 05:13:04 DEBUG : three: Sizes differ (src 7 vs dst 5) 2022/03/24 05:13:04 DEBUG : three: Destination not found in --copy-dest 2022/03/24 05:13:04 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1/dst': Waiting for checks to finish 2022/03/24 05:13:05 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/24 05:13:05 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/24 05:13:05 DEBUG : one: Unchanged skipping 2022/03/24 05:13:05 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/24 05:13:05 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/24 05:13:05 DEBUG : two: Unchanged skipping 2022/03/24 05:13:05 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1/dst': Waiting for transfers to finish 2022/03/24 05:13:06 DEBUG : three: md5 = 3fd45073d0561c08f548c90f514dc230 OK 2022/03/24 05:13:06 INFO : three: Copied (new) 2022/03/24 05:13:06 DEBUG : Waiting for deletions to finish 2022/03/24 05:13:12 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "b6jdmn2b1adrhc8vikh7edr9os" 2022/03/24 05:13:12 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2022/03/24 05:13:12 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" 2022/03/24 05:13:13 DEBUG : d09o6po3f7bm6ce32vdgs8h9ls: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2022/03/24 05:13:13 DEBUG : d09o6po3f7bm6ce32vdgs8h9ls: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" 2022/03/24 05:13:13 DEBUG : d09o6po3f7bm6ce32vdgs8h9ls: Rmdir: contains trashed file: "b6jdmn2b1adrhc8vikh7edr9os" 2022/03/24 05:13:14 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/24 05:13:14 DEBUG : pacer: Rate limited, increasing sleep to 1.657597802s 2022/03/24 05:13:14 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) 2022/03/24 05:13:14 DEBUG : pacer: Rate limited, increasing sleep to 2.756968756s 2022/03/24 05:13:16 DEBUG : pacer: Reducing sleep to 0s 2022/03/24 05:13:16 DEBUG : s6dbk3lfi7c9kfvo6j7bla9m0g: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" --- PASS: TestSyncCopyDest (55.01s) === RUN TestSyncBackupDir run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1'", Local "Local file system at /tmp/rclone2025790769", Modify Window "1ms" 2022/03/24 05:13:22 DEBUG : dst/one: md5 = 57edd95b261190d8b7d8f63f2c35f04b OK 2022/03/24 05:13:24 DEBUG : dst/two: md5 = 62a1268a870db1ad79b87684118db952 OK 2022/03/24 05:13:25 DEBUG : dst/three.txt: md5 = d295a1d8e028811487be767fa0033f8c OK 2022/03/24 05:13:25 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/24 05:13:25 DEBUG : pacer: Rate limited, increasing sleep to 1.839090057s 2022/03/24 05:13:25 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) 2022/03/24 05:13:25 DEBUG : pacer: Rate limited, increasing sleep to 2.387398999s 2022/03/24 05:13:27 DEBUG : pacer: Reducing sleep to 0s 2022/03/24 05:13:30 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1/dst" 2022/03/24 05:13:30 DEBUG : Config file has changed externaly - reloading 2022/03/24 05:13:30 DEBUG : Creating backend with remote "TestDrive:crypt/6b10gnlg26g3mg2q9avtop0e8plldvcgc2272956ipp59h469nauuum7r2in1spjv14ttu25s1phk/31u3jie661vd5p8j7rtc3hgbh0" 2022/03/24 05:13:31 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1/backup" 2022/03/24 05:13:31 DEBUG : Creating backend with remote "TestDrive:crypt/6b10gnlg26g3mg2q9avtop0e8plldvcgc2272956ipp59h469nauuum7r2in1spjv14ttu25s1phk/1nrff024r7pq65ecp72fc28jb0" 2022/03/24 05:13: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) 2022/03/24 05:13:32 DEBUG : pacer: Rate limited, increasing sleep to 1.836372961s 2022/03/24 05:13:32 DEBUG : pacer: Reducing sleep to 0s 2022/03/24 05:13:34 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/24 05:13:34 DEBUG : pacer: Rate limited, increasing sleep to 1.762381474s 2022/03/24 05:13:34 DEBUG : pacer: Reducing sleep to 0s 2022/03/24 05:13: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) 2022/03/24 05:13:35 DEBUG : pacer: Rate limited, increasing sleep to 1.872760623s 2022/03/24 05:13:36 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) 2022/03/24 05:13:36 DEBUG : pacer: Rate limited, increasing sleep to 2.501009125s 2022/03/24 05:13:38 DEBUG : pacer: Reducing sleep to 0s 2022/03/24 05:13:38 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1/dst': Waiting for checks to finish 2022/03/24 05:13:38 DEBUG : one: Sizes differ (src 4 vs dst 3) 2022/03/24 05:13:38 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/24 05:13:38 DEBUG : two: Unchanged skipping 2022/03/24 05:13:42 INFO : one: Moved (server-side) 2022/03/24 05:13:42 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1/dst': Waiting for transfers to finish 2022/03/24 05:13:43 DEBUG : one: md5 = 4550708a32425afd5b5fc8056f15d191 OK 2022/03/24 05:13:43 INFO : one: Copied (new) 2022/03/24 05:13:43 DEBUG : Waiting for deletions to finish 2022/03/24 05:13:44 INFO : three.txt: Moved (server-side) 2022/03/24 05:13:44 INFO : three.txt: Moved into backup dir 2022/03/24 05:13:46 DEBUG : dst/three.txt: md5 = 236d853357497acf099bf16519754822 OK 2022/03/24 05:13:47 DEBUG : one: Sizes differ (src 5 vs dst 4) 2022/03/24 05:13:47 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1/dst': Waiting for checks to finish 2022/03/24 05:13:47 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/24 05:13:47 DEBUG : two: Unchanged skipping 2022/03/24 05:13:48 INFO : one: Deleted 2022/03/24 05:13:48 INFO : one: Moved (server-side) 2022/03/24 05:13:48 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1/dst': Waiting for transfers to finish 2022/03/24 05:13:50 DEBUG : one: md5 = 3670f1513afd006686e319b4c21804f5 OK 2022/03/24 05:13:50 INFO : one: Copied (new) 2022/03/24 05:13:50 DEBUG : Waiting for deletions to finish 2022/03/24 05:13:51 INFO : three.txt: Deleted 2022/03/24 05:13:52 INFO : three.txt: Moved (server-side) 2022/03/24 05:13:52 INFO : three.txt: Moved into backup dir 2022/03/24 05:13:53 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/24 05:13:53 DEBUG : pacer: Rate limited, increasing sleep to 1.115465456s 2022/03/24 05:13: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) 2022/03/24 05:13:53 DEBUG : pacer: Rate limited, increasing sleep to 2.16527749s 2022/03/24 05:13:53 DEBUG : pacer: Reducing sleep to 0s 2022/03/24 05:13:54 DEBUG : pacer: low level retry 3/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/24 05:13:54 DEBUG : pacer: Rate limited, increasing sleep to 1.762055286s 2022/03/24 05:13:54 DEBUG : pacer: low level retry 4/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/24 05:13:54 DEBUG : pacer: Rate limited, increasing sleep to 2.275131189s 2022/03/24 05:13:56 DEBUG : pacer: Reducing sleep to 0s 2022/03/24 05:14:01 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2022/03/24 05:14:01 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" 2022/03/24 05:14:02 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "tr2hj63d80ftlmvm6a952snjcc" 2022/03/24 05:14:02 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2022/03/24 05:14:02 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "tr2hj63d80ftlmvm6a952snjcc" 2022/03/24 05:14:02 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" --- PASS: TestSyncBackupDir (43.03s) === RUN TestSyncBackupDirWithSuffix run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1'", Local "Local file system at /tmp/rclone2025790769", Modify Window "1ms" 2022/03/24 05:14:05 DEBUG : dst/one: md5 = 1c90887428a2c0d5361711a2e0bafb93 OK 2022/03/24 05:14:06 DEBUG : dst/two: md5 = 3755dbb9c6e8da6e62947c1cf3a97ed7 OK 2022/03/24 05:14:08 DEBUG : dst/three.txt: md5 = 58d060c5c5744679a77ae325be731907 OK 2022/03/24 05:14:09 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1/dst" 2022/03/24 05:14:09 DEBUG : Config file has changed externaly - reloading 2022/03/24 05:14:09 DEBUG : Creating backend with remote "TestDrive:crypt/6b10gnlg26g3mg2q9avtop0e8plldvcgc2272956ipp59h469nauuum7r2in1spjv14ttu25s1phk/31u3jie661vd5p8j7rtc3hgbh0" 2022/03/24 05:14:09 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1/backup" 2022/03/24 05:14:09 DEBUG : Creating backend with remote "TestDrive:crypt/6b10gnlg26g3mg2q9avtop0e8plldvcgc2272956ipp59h469nauuum7r2in1spjv14ttu25s1phk/1nrff024r7pq65ecp72fc28jb0" 2022/03/24 05:14:11 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1/dst': Waiting for checks to finish 2022/03/24 05:14:11 DEBUG : one: Sizes differ (src 4 vs dst 3) 2022/03/24 05:14:11 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/24 05:14:11 DEBUG : two: Unchanged skipping 2022/03/24 05:14:13 INFO : one: Moved (server-side) to: one.bak 2022/03/24 05:14:13 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1/dst': Waiting for transfers to finish 2022/03/24 05:14:14 DEBUG : one: md5 = f7b3963d809a106e15d6f20dec97c2d0 OK 2022/03/24 05:14:14 INFO : one: Copied (new) 2022/03/24 05:14:14 DEBUG : Waiting for deletions to finish 2022/03/24 05:14: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) 2022/03/24 05:14:15 DEBUG : pacer: Rate limited, increasing sleep to 1.009192932s 2022/03/24 05:14:15 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) 2022/03/24 05:14:15 DEBUG : pacer: Rate limited, increasing sleep to 2.936049977s 2022/03/24 05:14:17 DEBUG : pacer: Reducing sleep to 0s 2022/03/24 05:14:17 INFO : three.txt: Moved (server-side) to: three.txt.bak 2022/03/24 05:14:17 INFO : three.txt: Moved into backup dir 2022/03/24 05:14:18 DEBUG : dst/three.txt: md5 = 6f566c6834f697ff4646163b87835707 OK 2022/03/24 05:14:19 DEBUG : one: Sizes differ (src 5 vs dst 4) 2022/03/24 05:14:19 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/24 05:14:19 DEBUG : two: Unchanged skipping 2022/03/24 05:14:19 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1/dst': Waiting for checks to finish 2022/03/24 05:14:20 INFO : one.bak: Deleted 2022/03/24 05:14:21 INFO : one: Moved (server-side) to: one.bak 2022/03/24 05:14:21 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1/dst': Waiting for transfers to finish 2022/03/24 05:14:22 DEBUG : one: md5 = d3a5959383608cd4b6e8db53d956c731 OK 2022/03/24 05:14:22 INFO : one: Copied (new) 2022/03/24 05:14:22 DEBUG : Waiting for deletions to finish 2022/03/24 05:14:23 INFO : three.txt.bak: Deleted 2022/03/24 05:14:24 INFO : three.txt: Moved (server-side) to: three.txt.bak 2022/03/24 05:14:24 INFO : three.txt: Moved into backup dir 2022/03/24 05:14:28 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2022/03/24 05:14:28 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" 2022/03/24 05:14:28 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "qltcak2uaegtmcoa8vijdppbp8" 2022/03/24 05:14:28 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "sk91qgsqfn0r271r2ehsaoc20c" 2022/03/24 05:14:28 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "sk91qgsqfn0r271r2ehsaoc20c" 2022/03/24 05:14:28 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "qltcak2uaegtmcoa8vijdppbp8" --- PASS: TestSyncBackupDirWithSuffix (26.86s) === RUN TestSyncBackupDirWithSuffixKeepExtension run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1'", Local "Local file system at /tmp/rclone2025790769", Modify Window "1ms" 2022/03/24 05:14:32 DEBUG : dst/one: md5 = 6c4cb120be37d0e1d92802a302a4a7ae OK 2022/03/24 05:14:33 DEBUG : dst/two: md5 = 16779033a626560060c8069b1ab21333 OK 2022/03/24 05:14:35 DEBUG : dst/three.txt: md5 = 1714bfa7b6dbfdbaed8aeda448d1052d OK 2022/03/24 05:14:35 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1/dst" 2022/03/24 05:14:35 DEBUG : Creating backend with remote "TestDrive:crypt/6b10gnlg26g3mg2q9avtop0e8plldvcgc2272956ipp59h469nauuum7r2in1spjv14ttu25s1phk/31u3jie661vd5p8j7rtc3hgbh0" 2022/03/24 05:14:36 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1/backup" 2022/03/24 05:14:36 DEBUG : Creating backend with remote "TestDrive:crypt/6b10gnlg26g3mg2q9avtop0e8plldvcgc2272956ipp59h469nauuum7r2in1spjv14ttu25s1phk/1nrff024r7pq65ecp72fc28jb0" 2022/03/24 05:14:38 DEBUG : one: Sizes differ (src 4 vs dst 3) 2022/03/24 05:14:38 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/24 05:14:38 DEBUG : two: Unchanged skipping 2022/03/24 05:14:38 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1/dst': Waiting for checks to finish 2022/03/24 05:14:40 INFO : one: Moved (server-side) to: one-2019-01-01 2022/03/24 05:14:40 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1/dst': Waiting for transfers to finish 2022/03/24 05:14:42 DEBUG : one: md5 = 786cbc314137f0a9c2727db696d4f639 OK 2022/03/24 05:14:42 INFO : one: Copied (new) 2022/03/24 05:14:42 DEBUG : Waiting for deletions to finish 2022/03/24 05:14:42 INFO : three.txt: Moved (server-side) to: three-2019-01-01.txt 2022/03/24 05:14:42 INFO : three.txt: Moved into backup dir 2022/03/24 05:14:45 DEBUG : dst/three.txt: md5 = fa1494966c73501fbd7742f55f1191a4 OK 2022/03/24 05:14: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) 2022/03/24 05:14:45 DEBUG : pacer: Rate limited, increasing sleep to 1.939223013s 2022/03/24 05:14:45 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) 2022/03/24 05:14:45 DEBUG : pacer: Rate limited, increasing sleep to 2.763320312s 2022/03/24 05:14:47 DEBUG : pacer: Reducing sleep to 0s 2022/03/24 05:14:50 DEBUG : one: Sizes differ (src 5 vs dst 4) 2022/03/24 05:14:50 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/24 05:14:50 DEBUG : two: Unchanged skipping 2022/03/24 05:14:50 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1/dst': Waiting for checks to finish 2022/03/24 05:14:51 INFO : one-2019-01-01: Deleted 2022/03/24 05:14:51 INFO : one: Moved (server-side) to: one-2019-01-01 2022/03/24 05:14:51 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1/dst': Waiting for transfers to finish 2022/03/24 05:14:53 DEBUG : one: md5 = ae578c5f6a54e64039d7751151c6e9f9 OK 2022/03/24 05:14:53 INFO : one: Copied (new) 2022/03/24 05:14:53 DEBUG : Waiting for deletions to finish 2022/03/24 05:14:54 INFO : three-2019-01-01.txt: Deleted 2022/03/24 05:14:54 INFO : three.txt: Moved (server-side) to: three-2019-01-01.txt 2022/03/24 05:14:54 INFO : three.txt: Moved into backup dir 2022/03/24 05:14:59 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2022/03/24 05:14:59 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" 2022/03/24 05:15:00 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "jcjl1bv3ep0v8kt35lqql1co90" 2022/03/24 05:15:00 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "qtq2f6qq4lgpsmj88vb7147qje3prudmtfdtr2342fth58vo9a50" 2022/03/24 05:15:00 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "jcjl1bv3ep0v8kt35lqql1co90" 2022/03/24 05:15:00 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "qtq2f6qq4lgpsmj88vb7147qje3prudmtfdtr2342fth58vo9a50" --- PASS: TestSyncBackupDirWithSuffixKeepExtension (31.15s) === RUN TestSyncBackupDirSuffixOnly run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1'", Local "Local file system at /tmp/rclone2025790769", Modify Window "1ms" 2022/03/24 05:15:04 DEBUG : dst/one: md5 = 7922323b6bb9879fdb3652b1f7629e5d OK 2022/03/24 05:15:04 DEBUG : pacer: low level retry 1/1 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/24 05:15:04 DEBUG : pacer: Rate limited, increasing sleep to 1.340936055s run.go:283: Retry Put of "dst/two" to Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': 1/10 (googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/24 05:15:07 DEBUG : pacer: Reducing sleep to 0s 2022/03/24 05:15:09 DEBUG : dst/two: md5 = 503044441ee31b62ad079e0dc9f4c4dd OK 2022/03/24 05:15:10 DEBUG : dst/three.txt: md5 = a63871d2d975349ba63f03ecdc610a11 OK 2022/03/24 05:15:11 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1/dst" 2022/03/24 05:15:11 DEBUG : Creating backend with remote "TestDrive:crypt/6b10gnlg26g3mg2q9avtop0e8plldvcgc2272956ipp59h469nauuum7r2in1spjv14ttu25s1phk/31u3jie661vd5p8j7rtc3hgbh0" 2022/03/24 05:15:12 DEBUG : one: Sizes differ (src 4 vs dst 3) 2022/03/24 05:15:12 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/24 05:15:12 DEBUG : two: Unchanged skipping 2022/03/24 05:15:12 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1/dst': Waiting for checks to finish 2022/03/24 05:15:14 INFO : one: Moved (server-side) to: one.bak 2022/03/24 05:15:14 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1/dst': Waiting for transfers to finish 2022/03/24 05:15:15 DEBUG : one: md5 = 7a97f90fb4755d984a8ff13ef06f036b OK 2022/03/24 05:15:15 INFO : one: Copied (new) 2022/03/24 05:15:15 DEBUG : Waiting for deletions to finish 2022/03/24 05:15:16 INFO : three.txt: Moved (server-side) to: three.txt.bak 2022/03/24 05:15:16 INFO : three.txt: Moved into backup dir 2022/03/24 05:15:19 DEBUG : dst/three.txt: md5 = df3d3b8eb5516df9bd492ee161a83404 OK 2022/03/24 05:15:19 DEBUG : one.bak: Excluded from sync (and deletion) 2022/03/24 05:15:19 DEBUG : three.txt.bak: Excluded from sync (and deletion) 2022/03/24 05:15:19 DEBUG : one: Sizes differ (src 5 vs dst 4) 2022/03/24 05:15:19 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/24 05:15:19 DEBUG : two: Unchanged skipping 2022/03/24 05:15:19 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1/dst': Waiting for checks to finish 2022/03/24 05:15:20 INFO : one.bak: Deleted 2022/03/24 05:15:21 INFO : one: Moved (server-side) to: one.bak 2022/03/24 05:15:21 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1/dst': Waiting for transfers to finish 2022/03/24 05:15:23 DEBUG : one: md5 = 44d273811d5e0024999cf69dc0c745fe OK 2022/03/24 05:15:23 INFO : one: Copied (new) 2022/03/24 05:15:23 DEBUG : Waiting for deletions to finish 2022/03/24 05:15: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) 2022/03/24 05:15:23 DEBUG : pacer: Rate limited, increasing sleep to 1.740315408s 2022/03/24 05:15: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) 2022/03/24 05:15:23 DEBUG : pacer: Rate limited, increasing sleep to 2.312823956s 2022/03/24 05:15:25 DEBUG : pacer: low level retry 3/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/24 05:15:25 DEBUG : pacer: Rate limited, increasing sleep to 4.439271765s 2022/03/24 05:15:28 DEBUG : pacer: Reducing sleep to 0s 2022/03/24 05:15:28 INFO : three.txt.bak: Deleted 2022/03/24 05:15:32 INFO : three.txt: Moved (server-side) to: three.txt.bak 2022/03/24 05:15:32 INFO : three.txt: Moved into backup dir 2022/03/24 05:15:37 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2022/03/24 05:15:37 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "sk91qgsqfn0r271r2ehsaoc20c" 2022/03/24 05:15:37 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "qltcak2uaegtmcoa8vijdppbp8" 2022/03/24 05:15:37 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" 2022/03/24 05:15:37 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "qltcak2uaegtmcoa8vijdppbp8" 2022/03/24 05:15:37 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "sk91qgsqfn0r271r2ehsaoc20c" --- PASS: TestSyncBackupDirSuffixOnly (37.41s) === RUN TestSyncSuffix run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1'", Local "Local file system at /tmp/rclone2025790769", Modify Window "1ms" 2022/03/24 05:15:40 DEBUG : dst/one: md5 = bbdd4ea90da5462babdca23dbd3b44ca OK 2022/03/24 05:15:42 DEBUG : dst/two: md5 = 724a07756e828c2e1fc0ba908c512362 OK 2022/03/24 05:15:43 DEBUG : dst/three.txt: md5 = 050bf9e87c528f05559c5c5b6b8800f9 OK 2022/03/24 05:15:44 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/24 05:15:44 DEBUG : pacer: Rate limited, increasing sleep to 1.193392646s 2022/03/24 05:15:44 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) 2022/03/24 05:15:44 DEBUG : pacer: Rate limited, increasing sleep to 2.658812564s 2022/03/24 05:15:45 DEBUG : pacer: low level retry 3/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/24 05:15:45 DEBUG : pacer: Rate limited, increasing sleep to 4.473303035s 2022/03/24 05:15:48 DEBUG : pacer: Reducing sleep to 0s 2022/03/24 05:15:48 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1/dst" 2022/03/24 05:15:48 DEBUG : Creating backend with remote "TestDrive:crypt/6b10gnlg26g3mg2q9avtop0e8plldvcgc2272956ipp59h469nauuum7r2in1spjv14ttu25s1phk/31u3jie661vd5p8j7rtc3hgbh0" 2022/03/24 05:15:49 DEBUG : one: Sizes differ (src 4 vs dst 3) 2022/03/24 05:15:50 INFO : one: Moved (server-side) to: one.bak 2022/03/24 05:15:51 DEBUG : one: md5 = 31a5d9feac658c8d679be8cc0296600c OK 2022/03/24 05:15:51 INFO : one: Copied (new) 2022/03/24 05:15:52 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/24 05:15:52 DEBUG : two: Unchanged skipping 2022/03/24 05:15:52 DEBUG : three.txt: Sizes differ (src 6 vs dst 5) 2022/03/24 05:15:53 INFO : three.txt: Moved (server-side) to: three.txt.bak 2022/03/24 05:15:54 DEBUG : three.txt: md5 = 1dc17b1a8de4813388ac421f890c9095 OK 2022/03/24 05:15:54 INFO : three.txt: Copied (new) 2022/03/24 05:15:56 DEBUG : one: Sizes differ (src 5 vs dst 4) 2022/03/24 05:15:57 INFO : one.bak: Deleted 2022/03/24 05:15:57 INFO : one: Moved (server-side) to: one.bak 2022/03/24 05:15:59 DEBUG : one: md5 = 48aecd2b87da0a34c05bd9ac4d639626 OK 2022/03/24 05:15:59 INFO : one: Copied (new) 2022/03/24 05:15:59 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/24 05:15:59 DEBUG : two: Unchanged skipping 2022/03/24 05:15:59 DEBUG : three.txt: Sizes differ (src 19 vs dst 6) 2022/03/24 05:16:00 INFO : three.txt.bak: Deleted 2022/03/24 05:16:01 INFO : three.txt: Moved (server-side) to: three.txt.bak 2022/03/24 05:16:02 DEBUG : three.txt: md5 = 133a5049323837cd9dbcece1e15ac3fb OK 2022/03/24 05:16:02 INFO : three.txt: Copied (new) 2022/03/24 05:16:05 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/24 05:16:05 DEBUG : pacer: Rate limited, increasing sleep to 1.39995153s 2022/03/24 05:16:05 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) 2022/03/24 05:16:05 DEBUG : pacer: Rate limited, increasing sleep to 2.430743417s 2022/03/24 05:16:06 DEBUG : pacer: Reducing sleep to 0s 2022/03/24 05:16:11 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "tr2hj63d80ftlmvm6a952snjcc" 2022/03/24 05:16:11 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2022/03/24 05:16:11 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "qltcak2uaegtmcoa8vijdppbp8" 2022/03/24 05:16:11 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "qltcak2uaegtmcoa8vijdppbp8" 2022/03/24 05:16:11 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "sk91qgsqfn0r271r2ehsaoc20c" 2022/03/24 05:16:11 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" 2022/03/24 05:16:11 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "sk91qgsqfn0r271r2ehsaoc20c" --- PASS: TestSyncSuffix (33.41s) === RUN TestSyncSuffixKeepExtension run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1'", Local "Local file system at /tmp/rclone2025790769", Modify Window "1ms" 2022/03/24 05:16:13 DEBUG : dst/one: md5 = 62eafb08145dc2a5b5e4861e68481486 OK 2022/03/24 05:16:15 DEBUG : dst/two: md5 = b7fb5bdae039b0f74c57acefca8fb31d OK 2022/03/24 05:16:16 DEBUG : dst/three.txt: md5 = defd66feeabc645a229d1f54e177b018 OK 2022/03/24 05:16:17 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1/dst" 2022/03/24 05:16:17 DEBUG : Creating backend with remote "TestDrive:crypt/6b10gnlg26g3mg2q9avtop0e8plldvcgc2272956ipp59h469nauuum7r2in1spjv14ttu25s1phk/31u3jie661vd5p8j7rtc3hgbh0" 2022/03/24 05:16:17 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/24 05:16:17 DEBUG : pacer: Rate limited, increasing sleep to 1.443389602s 2022/03/24 05:16:18 DEBUG : pacer: Reducing sleep to 0s 2022/03/24 05:16:19 DEBUG : one: Sizes differ (src 4 vs dst 3) 2022/03/24 05:16:20 INFO : one: Moved (server-side) to: one-2019-01-01 2022/03/24 05:16:20 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/24 05:16:20 DEBUG : pacer: Rate limited, increasing sleep to 1.643704092s 2022/03/24 05:16:21 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) 2022/03/24 05:16:21 DEBUG : pacer: Rate limited, increasing sleep to 2.930626683s 2022/03/24 05:16:22 DEBUG : pacer: Reducing sleep to 0s 2022/03/24 05:16:26 DEBUG : one: md5 = 5a57088807de036108593a3a0216831a OK 2022/03/24 05:16:26 INFO : one: Copied (new) 2022/03/24 05:16:26 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/24 05:16:26 DEBUG : two: Unchanged skipping 2022/03/24 05:16:27 DEBUG : three.txt: Sizes differ (src 6 vs dst 5) 2022/03/24 05:16:27 INFO : three.txt: Moved (server-side) to: three-2019-01-01.txt 2022/03/24 05:16:29 DEBUG : three.txt: md5 = 32a4a4feef5cc9dae746b212eb5b2d8a OK 2022/03/24 05:16:29 INFO : three.txt: Copied (new) 2022/03/24 05:16:31 DEBUG : one: Sizes differ (src 5 vs dst 4) 2022/03/24 05:16:31 INFO : one-2019-01-01: Deleted 2022/03/24 05:16:32 INFO : one: Moved (server-side) to: one-2019-01-01 2022/03/24 05:16:33 DEBUG : one: md5 = dc734c3f90096023c9f4102934c9f98e OK 2022/03/24 05:16:33 INFO : one: Copied (new) 2022/03/24 05:16:33 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/24 05:16:33 DEBUG : pacer: Rate limited, increasing sleep to 1.723718642s 2022/03/24 05:16:33 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) 2022/03/24 05:16:33 DEBUG : pacer: Rate limited, increasing sleep to 2.296173026s 2022/03/24 05:16:35 DEBUG : pacer: low level retry 3/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/24 05:16:35 DEBUG : pacer: Rate limited, increasing sleep to 4.498010064s 2022/03/24 05:16:38 DEBUG : pacer: Reducing sleep to 0s 2022/03/24 05:16:38 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/24 05:16:38 DEBUG : two: Unchanged skipping 2022/03/24 05:16:42 DEBUG : three.txt: Sizes differ (src 19 vs dst 6) 2022/03/24 05:16: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) 2022/03/24 05:16:42 DEBUG : pacer: Rate limited, increasing sleep to 1.529531109s 2022/03/24 05:16: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) 2022/03/24 05:16:43 DEBUG : pacer: Rate limited, increasing sleep to 2.017001324s 2022/03/24 05:16:45 DEBUG : pacer: Reducing sleep to 0s 2022/03/24 05:16:45 INFO : three-2019-01-01.txt: Deleted 2022/03/24 05:16:47 INFO : three.txt: Moved (server-side) to: three-2019-01-01.txt 2022/03/24 05:16:50 DEBUG : three.txt: md5 = 78c83b7ed2d152814307f76be2e56f47 OK 2022/03/24 05:16:50 INFO : three.txt: Copied (new) 2022/03/24 05:16:55 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2022/03/24 05:16:55 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "tr2hj63d80ftlmvm6a952snjcc" 2022/03/24 05:16:55 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "jcjl1bv3ep0v8kt35lqql1co90" 2022/03/24 05:16:55 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" 2022/03/24 05:16:55 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "qtq2f6qq4lgpsmj88vb7147qje3prudmtfdtr2342fth58vo9a50" 2022/03/24 05:16:55 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "jcjl1bv3ep0v8kt35lqql1co90" 2022/03/24 05:16:55 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "qtq2f6qq4lgpsmj88vb7147qje3prudmtfdtr2342fth58vo9a50" --- PASS: TestSyncSuffixKeepExtension (44.48s) === RUN TestSyncUTFNorm run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1'", Local "Local file system at /tmp/rclone2025790769", Modify Window "1ms" 2022/03/24 05:16:57 DEBUG : Testêé: md5 = 474cacc180de7471bacffdfacf14c60e OK 2022/03/24 05:16:58 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for checks to finish 2022/03/24 05:16:58 DEBUG : Testêé: Sizes differ (src 14 vs dst 18) 2022/03/24 05:16:58 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for transfers to finish 2022/03/24 05:16:59 DEBUG : Testêé: md5 = 1d07a75e326d9d249ddc6a6da21f3e7e OK 2022/03/24 05:16:59 INFO : Testêé: Copied (replaced existing) 2022/03/24 05:16:59 DEBUG : Waiting for deletions to finish --- PASS: TestSyncUTFNorm (4.61s) === RUN TestSyncImmutable run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1'", Local "Local file system at /tmp/rclone2025790769", Modify Window "1ms" 2022/03/24 05:17:01 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for checks to finish 2022/03/24 05:17:01 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for transfers to finish 2022/03/24 05:17:03 DEBUG : existing: md5 = e63450e01d310bbd372da64302688f96 OK 2022/03/24 05:17:03 INFO : existing: Copied (new) 2022/03/24 05:17:03 DEBUG : Waiting for deletions to finish 2022/03/24 05:17:04 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for checks to finish 2022/03/24 05:17:04 DEBUG : existing: Sizes differ (src 8 vs dst 6) 2022/03/24 05:17:04 ERROR : existing: Source and destination exist but do not match: immutable file modified 2022/03/24 05:17:04 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for transfers to finish 2022/03/24 05:17:04 ERROR : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': not deleting files as there were IO errors 2022/03/24 05:17:04 ERROR : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': not deleting directories as there were IO errors 2022/03/24 05:17:05 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/24 05:17:05 DEBUG : pacer: Rate limited, increasing sleep to 1.060235947s 2022/03/24 05:17:05 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) 2022/03/24 05:17:05 DEBUG : pacer: Rate limited, increasing sleep to 2.865700779s 2022/03/24 05:17:06 DEBUG : pacer: Reducing sleep to 0s --- PASS: TestSyncImmutable (6.01s) === RUN TestSyncIgnoreCase run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1'", Local "Local file system at /tmp/rclone2025790769", Modify Window "1ms" 2022/03/24 05:17:11 DEBUG : EXISTING: md5 = 46bc3c50429ad8ff876044efad0f41c4 OK 2022/03/24 05:17:11 DEBUG : existing: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/24 05:17:11 DEBUG : existing: Unchanged skipping 2022/03/24 05:17:11 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for checks to finish 2022/03/24 05:17:11 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for transfers to finish 2022/03/24 05:17:11 DEBUG : Waiting for deletions to finish 2022/03/24 05:17:11 INFO : There was nothing to transfer --- PASS: TestSyncIgnoreCase (6.27s) === RUN TestMaxTransfer === RUN TestMaxTransfer/Hard run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1'", Local "Local file system at /tmp/rclone2025790769", Modify Window "1ms" sync_test.go:1989: This test only runs on local === RUN TestMaxTransfer/Soft run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1'", Local "Local file system at /tmp/rclone2025790769", Modify Window "1ms" sync_test.go:1989: This test only runs on local === RUN TestMaxTransfer/Cautious run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1'", Local "Local file system at /tmp/rclone2025790769", Modify Window "1ms" sync_test.go:1989: This test only runs on local --- PASS: TestMaxTransfer (1.61s) --- SKIP: TestMaxTransfer/Hard (0.58s) --- SKIP: TestMaxTransfer/Soft (0.54s) --- SKIP: TestMaxTransfer/Cautious (0.49s) === RUN TestSyncConcurrentDelete run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1'", Local "Local file system at /tmp/rclone2025790769", Modify Window "1ms" 2022/03/24 05:17:14 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/24 05:17:14 DEBUG : pacer: Rate limited, increasing sleep to 1.024476763s 2022/03/24 05:17:15 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) 2022/03/24 05:17:15 DEBUG : pacer: Rate limited, increasing sleep to 2.643256259s 2022/03/24 05:17:16 DEBUG : pacer: Reducing sleep to 0s 2022/03/24 05:17:19 DEBUG : both0: md5 = db9b73bfb9046d272902a3c50775b7f6 OK 2022/03/24 05:17:21 DEBUG : only0: md5 = 25ddbdabb6d451436d658fdbe9c1b6d0 OK 2022/03/24 05:17:22 DEBUG : both1: md5 = 2fca8b6f83d7451427f5a3a16b3e62a4 OK 2022/03/24 05:17:24 DEBUG : only1: md5 = b746500226bff474f7a3dece656eab0e OK 2022/03/24 05:17:25 DEBUG : both2: md5 = 523839de519a0362935a6f805e42c6e8 OK 2022/03/24 05:17:27 DEBUG : only2: md5 = 3c97c51034be235b04bab763774f08ba OK 2022/03/24 05:17:29 DEBUG : both3: md5 = e1bb36e5d241c2e55296f680e8453ef7 OK 2022/03/24 05:17:30 DEBUG : only3: md5 = 03c5f1586528c7009df5e009bbd0d8de OK 2022/03/24 05:17:32 DEBUG : both4: md5 = 76d6816a817911cdd66342f115d0802b OK 2022/03/24 05:17:34 DEBUG : only4: md5 = cf1cf074eb5cb7dfdd7d2d0fbb96e1f8 OK 2022/03/24 05:17:35 DEBUG : both5: md5 = 93e0aa8683d441cc9436b58a45a96f6b OK 2022/03/24 05:17:37 DEBUG : only5: md5 = 5515119f3abcfb0e82090c390b0f8f20 OK 2022/03/24 05:17:38 DEBUG : both6: md5 = 98206bcf96c7934b2282a900f38ad046 OK 2022/03/24 05:17:40 DEBUG : only6: md5 = 030be8f12ffe265e30a2c50ef111e9a6 OK 2022/03/24 05:17:41 DEBUG : both7: md5 = 5abae26aa2807776e18bbf122d0ca4a9 OK 2022/03/24 05:17:43 DEBUG : only7: md5 = 8cf3f83ac46f069c2410af8d3dceed34 OK 2022/03/24 05:17:43 DEBUG : pacer: low level retry 1/1 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/24 05:17:43 DEBUG : pacer: Rate limited, increasing sleep to 1.58777861s run.go:283: Retry Put of "both8" to Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': 1/10 (googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/24 05:17:46 DEBUG : pacer: Reducing sleep to 0s 2022/03/24 05:17:48 DEBUG : both8: md5 = 562876af2abd2c6e7b25ca1134aabe74 OK 2022/03/24 05:17:50 DEBUG : only8: md5 = 030303cb43f1c4b3c6a71953d59ed597 OK 2022/03/24 05:17:52 DEBUG : both9: md5 = b355bd82c8f281b2d81c14b27290f778 OK 2022/03/24 05:17:53 DEBUG : only9: md5 = aa0e160add1c61ce5821f75de6e217f6 OK 2022/03/24 05:17:55 DEBUG : both10: md5 = f5a060f7b693fe60be1512b6101a0f0c OK 2022/03/24 05:17:56 DEBUG : only10: md5 = c319243a319df457a79aa90f816a17a7 OK 2022/03/24 05:17:58 DEBUG : both11: md5 = 4c2cac7f5cac1695ead37992c45679a9 OK 2022/03/24 05:17:59 DEBUG : only11: md5 = 0a4ad0e577302fa358d189c77cdc6eaa OK 2022/03/24 05:18:01 DEBUG : both12: md5 = db0a8c04c3bc1492f140d408797212dd OK 2022/03/24 05:18:02 DEBUG : only12: md5 = 0136c25379b94dc1df364059f7829ebc OK 2022/03/24 05:18:04 DEBUG : both13: md5 = aaad5537453f0cce2dc6322d6104f37a OK 2022/03/24 05:18:04 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/24 05:18:04 DEBUG : pacer: Rate limited, increasing sleep to 1.137883966s 2022/03/24 05:18:04 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) 2022/03/24 05:18:04 DEBUG : pacer: Rate limited, increasing sleep to 2.039618435s 2022/03/24 05:18:05 DEBUG : pacer: low level retry 3/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/24 05:18:05 DEBUG : pacer: Rate limited, increasing sleep to 4.355629771s 2022/03/24 05:18:07 DEBUG : pacer: Reducing sleep to 0s 2022/03/24 05:18:13 DEBUG : only13: md5 = f6a60c30120eb904358e9fc08b0762dd OK 2022/03/24 05:18:14 DEBUG : both14: md5 = 3a0c6b80f4f4bbb342ef92731146a88e OK 2022/03/24 05:18:16 DEBUG : only14: md5 = 6a104d7e693a84bf08baa3a14bff4629 OK 2022/03/24 05:18:17 DEBUG : both15: md5 = 7eccf1fa650a66fd19378a5e74a36312 OK 2022/03/24 05:18:19 DEBUG : only15: md5 = d08ca38b258b6f4a8839629331f92035 OK 2022/03/24 05:18:20 DEBUG : both16: md5 = 66c0b4bb00d942fab2f1a269837a39f4 OK 2022/03/24 05:18:21 DEBUG : only16: md5 = 8cb81ad567aa86d58a2408244edc186b OK 2022/03/24 05:18:23 DEBUG : both17: md5 = fc8210ff16500f6ca6cda37e94c8e138 OK 2022/03/24 05:18:24 DEBUG : only17: md5 = 0df58744b8a5c43384b19bfa22a7f0c4 OK 2022/03/24 05:18:25 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/24 05:18:25 DEBUG : pacer: Rate limited, increasing sleep to 1.382638769s 2022/03/24 05:18:25 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) 2022/03/24 05:18:25 DEBUG : pacer: Rate limited, increasing sleep to 2.100437236s 2022/03/24 05:18:26 DEBUG : pacer: Reducing sleep to 0s 2022/03/24 05:18:29 DEBUG : both18: md5 = e4888abffeaef453cffcc159042d08f1 OK 2022/03/24 05:18:31 DEBUG : only18: md5 = c3826ccd9663c22b63f0a37edb7cc2e1 OK 2022/03/24 05:18:32 DEBUG : both19: md5 = fb755bae87fc1226b9cd2999843b8dc4 OK 2022/03/24 05:18:34 DEBUG : only19: md5 = 49efe6178bcc3301c41661a960ff3351 OK 2022/03/24 05:18:34 DEBUG : both0: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/24 05:18:34 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for checks to finish 2022/03/24 05:18:34 DEBUG : both11: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/24 05:18:34 DEBUG : both11: Unchanged skipping 2022/03/24 05:18:34 DEBUG : both1: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/24 05:18:34 DEBUG : both12: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/24 05:18:34 DEBUG : both1: Unchanged skipping 2022/03/24 05:18:34 DEBUG : both10: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/24 05:18:34 DEBUG : both10: Unchanged skipping 2022/03/24 05:18:34 DEBUG : both13: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/24 05:18:34 DEBUG : both14: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/24 05:18:34 DEBUG : both13: Unchanged skipping 2022/03/24 05:18:34 DEBUG : both14: Unchanged skipping 2022/03/24 05:18:34 DEBUG : both15: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/24 05:18:34 DEBUG : both16: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/24 05:18:34 DEBUG : both15: Unchanged skipping 2022/03/24 05:18:34 DEBUG : both16: Unchanged skipping 2022/03/24 05:18:34 DEBUG : both17: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/24 05:18:34 DEBUG : both18: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/24 05:18:34 DEBUG : both18: Unchanged skipping 2022/03/24 05:18:34 DEBUG : both19: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/24 05:18:34 DEBUG : both19: Unchanged skipping 2022/03/24 05:18:34 DEBUG : both2: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/24 05:18:34 DEBUG : both2: Unchanged skipping 2022/03/24 05:18:34 DEBUG : both3: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/24 05:18:34 DEBUG : both3: Unchanged skipping 2022/03/24 05:18:34 DEBUG : both4: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/24 05:18:34 DEBUG : both4: Unchanged skipping 2022/03/24 05:18:34 DEBUG : both5: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/24 05:18:34 DEBUG : both5: Unchanged skipping 2022/03/24 05:18:34 DEBUG : both6: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/24 05:18:34 DEBUG : both6: Unchanged skipping 2022/03/24 05:18:34 DEBUG : both7: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/24 05:18:34 DEBUG : both7: Unchanged skipping 2022/03/24 05:18:34 DEBUG : both8: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/24 05:18:34 DEBUG : both12: Unchanged skipping 2022/03/24 05:18:34 DEBUG : both8: Unchanged skipping 2022/03/24 05:18:34 DEBUG : both17: Unchanged skipping 2022/03/24 05:18:34 DEBUG : both9: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/24 05:18:34 DEBUG : both9: Unchanged skipping 2022/03/24 05:18:34 DEBUG : both0: Unchanged skipping 2022/03/24 05:18:34 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for transfers to finish 2022/03/24 05:18:34 DEBUG : Waiting for deletions to finish 2022/03/24 05:18:35 INFO : only0: Deleted 2022/03/24 05:18:35 INFO : only16: Deleted 2022/03/24 05:18:35 INFO : only9: Deleted 2022/03/24 05:18:35 INFO : only18: Deleted 2022/03/24 05:18:35 INFO : only2: Deleted 2022/03/24 05:18:35 INFO : only3: Deleted 2022/03/24 05:18:35 INFO : only10: Deleted 2022/03/24 05:18:36 INFO : only4: Deleted 2022/03/24 05:18:36 INFO : only14: Deleted 2022/03/24 05:18:36 INFO : only19: Deleted 2022/03/24 05:18:36 INFO : only15: Deleted 2022/03/24 05:18:36 INFO : only6: Deleted 2022/03/24 05:18:37 INFO : only7: Deleted 2022/03/24 05:18:37 INFO : only8: Deleted 2022/03/24 05:18:37 INFO : only1: Deleted 2022/03/24 05:18:37 INFO : only11: Deleted 2022/03/24 05:18:37 INFO : only12: Deleted 2022/03/24 05:18:37 INFO : only17: Deleted 2022/03/24 05:18:37 INFO : only13: Deleted 2022/03/24 05:18:37 INFO : only5: Deleted 2022/03/24 05:18:37 INFO : There was nothing to transfer 2022/03/24 05:18:44 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/24 05:18:44 DEBUG : pacer: Rate limited, increasing sleep to 1.679830205s 2022/03/24 05:18:44 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) 2022/03/24 05:18:44 DEBUG : pacer: Rate limited, increasing sleep to 2.260381528s 2022/03/24 05:18:46 DEBUG : pacer: Reducing sleep to 0s --- PASS: TestSyncConcurrentDelete (99.14s) === RUN TestSyncConcurrentTruncate run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1'", Local "Local file system at /tmp/rclone2025790769", Modify Window "1ms" 2022/03/24 05:18:55 DEBUG : both0: md5 = 8d5a88931ccc49926dbfefc7a9beea06 OK 2022/03/24 05:18:56 DEBUG : only0: md5 = 49ab703fb23ddf864a1c5669ac9c4651 OK 2022/03/24 05:18:58 DEBUG : both1: md5 = feae82bb9c41f58e111a22f7afd5f429 OK 2022/03/24 05:18:59 DEBUG : only1: md5 = 5facc14919ad10078fcb641db2f2c9f5 OK 2022/03/24 05:19:01 DEBUG : both2: md5 = b42ecfe01914e09839a4c3f4351fe9a3 OK 2022/03/24 05:19:02 DEBUG : only2: md5 = 0b20c06dbdeba1d4195bf7b948e88348 OK 2022/03/24 05:19:03 DEBUG : both3: md5 = ffd15b6b30529ad1f616b45ea6dd9609 OK 2022/03/24 05:19:05 DEBUG : only3: md5 = 151e133ca1b378e4bf7131af281abe71 OK 2022/03/24 05:19:06 DEBUG : both4: md5 = b7c3bd46db443ba5c46e6a48f36d3400 OK 2022/03/24 05:19:08 DEBUG : only4: md5 = 46d127620a153b739dfc25967c7dcd64 OK 2022/03/24 05:19:09 DEBUG : both5: md5 = 0557d5340996c6ea95ab600ee6ce90c2 OK 2022/03/24 05:19:10 DEBUG : only5: md5 = 4c59dfc951f71272075240efa446d8d5 OK 2022/03/24 05:19:12 DEBUG : both6: md5 = 04f23f8ff0d6c8f806065a8381e8eb37 OK 2022/03/24 05:19:13 DEBUG : only6: md5 = 2c54e8b4ebdae8f25f62fb0353cd0c85 OK 2022/03/24 05:19:15 DEBUG : both7: md5 = 1aae36dd7dfd5f1f4fae24a406428a4d OK 2022/03/24 05:19:16 DEBUG : only7: md5 = 6f92b47796f3ec93faee175cae729ae0 OK 2022/03/24 05:19:16 DEBUG : pacer: low level retry 1/1 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/24 05:19:16 DEBUG : pacer: Rate limited, increasing sleep to 1.062882732s run.go:283: Retry Put of "both8" to Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': 1/10 (googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/24 05:19:19 DEBUG : pacer: Reducing sleep to 0s 2022/03/24 05:19:21 DEBUG : both8: md5 = ec61d6805da6b3da3d4308b93bb12546 OK 2022/03/24 05:19:22 DEBUG : only8: md5 = 3ec029c43873f33b3f49049859967a55 OK 2022/03/24 05:19:24 DEBUG : both9: md5 = 66a452f9757ad120777beeec6fc3c344 OK 2022/03/24 05:19:25 DEBUG : only9: md5 = 05d9e4cb264e62636c0ce831f833cfff OK 2022/03/24 05:19:25 DEBUG : pacer: low level retry 1/1 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/24 05:19:25 DEBUG : pacer: Rate limited, increasing sleep to 1.172110549s run.go:283: Retry Put of "both10" to Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': 1/10 (googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/24 05:19:28 DEBUG : pacer: Reducing sleep to 0s 2022/03/24 05:19:30 DEBUG : both10: md5 = 437949b599c237c6bff2e25b0f726e93 OK 2022/03/24 05:19:31 DEBUG : only10: md5 = 3bf7815bdff87e86215e95b29002fbba OK 2022/03/24 05:19:33 DEBUG : both11: md5 = a7751fa2282347afca86456df382d600 OK 2022/03/24 05:19:35 DEBUG : only11: md5 = 74a856f82da87f7653e19a7fafe75aa4 OK 2022/03/24 05:19:36 DEBUG : both12: md5 = 0906ad40569a742d0da9b81d30a6e0d9 OK 2022/03/24 05:19:37 DEBUG : only12: md5 = 19c16074b6081c88e55d2f9ce127025c OK 2022/03/24 05:19:39 DEBUG : both13: md5 = 7609e7ab953eb8784f67089860a75631 OK 2022/03/24 05:19:40 DEBUG : only13: md5 = dcec2a222cc41e40bcfa599a4a2500ad OK 2022/03/24 05:19:42 DEBUG : both14: md5 = 48a50906b515de8ffe9274fff64af04a OK 2022/03/24 05:19:44 DEBUG : only14: md5 = 676a65265df045b03c4202d77ed2547a OK 2022/03/24 05:19:45 DEBUG : both15: md5 = ed3ec806c75bb745f9491131603ee244 OK 2022/03/24 05:19:45 DEBUG : pacer: low level retry 1/1 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/24 05:19:45 DEBUG : pacer: Rate limited, increasing sleep to 1.561308937s run.go:283: Retry Put of "only15" to Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': 1/10 (googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/24 05:19:48 DEBUG : pacer: Reducing sleep to 0s 2022/03/24 05:19:50 DEBUG : only15: md5 = 35fdd0225861945faf43f7bc94f5164c OK 2022/03/24 05:19:52 DEBUG : both16: md5 = c42177e6bec6a23d3e4dcbdb94026320 OK 2022/03/24 05:19:53 DEBUG : only16: md5 = c4964c28b911e8d5056680befe05a4ac OK 2022/03/24 05:19:55 DEBUG : both17: md5 = 967ae0bda8943f1100dcab9d838b6fa8 OK 2022/03/24 05:19:56 DEBUG : only17: md5 = e86f74191494aa3618d14a355d994224 OK 2022/03/24 05:19:58 DEBUG : both18: md5 = 1650c6b12469c3a7248ce31b4c36438e OK 2022/03/24 05:19:59 DEBUG : only18: md5 = 48d339eb5378f66dd7ab238f8f6df4fe OK 2022/03/24 05:20:01 DEBUG : both19: md5 = 6762f830570506c1db35bb58cb1a9327 OK 2022/03/24 05:20:02 DEBUG : only19: md5 = 57b36f48913e8b8a2a7ab275ce13b39c OK 2022/03/24 05:20:03 DEBUG : both0: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/24 05:20:03 DEBUG : both0: Unchanged skipping 2022/03/24 05:20:03 DEBUG : both1: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/24 05:20:03 DEBUG : both1: Unchanged skipping 2022/03/24 05:20:03 DEBUG : both10: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/24 05:20:03 DEBUG : both10: Unchanged skipping 2022/03/24 05:20:03 DEBUG : both11: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/24 05:20:03 DEBUG : both11: Unchanged skipping 2022/03/24 05:20:03 DEBUG : both12: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/24 05:20:03 DEBUG : both12: Unchanged skipping 2022/03/24 05:20:03 DEBUG : both13: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/24 05:20:03 DEBUG : both13: Unchanged skipping 2022/03/24 05:20:03 DEBUG : both14: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/24 05:20:03 DEBUG : both14: Unchanged skipping 2022/03/24 05:20:03 DEBUG : both15: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/24 05:20:03 DEBUG : both15: Unchanged skipping 2022/03/24 05:20:03 DEBUG : both16: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/24 05:20:03 DEBUG : both16: Unchanged skipping 2022/03/24 05:20:03 DEBUG : both17: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/24 05:20:03 DEBUG : both17: Unchanged skipping 2022/03/24 05:20:03 DEBUG : both18: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/24 05:20:03 DEBUG : both18: Unchanged skipping 2022/03/24 05:20:03 DEBUG : both19: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/24 05:20:03 DEBUG : both19: Unchanged skipping 2022/03/24 05:20:03 DEBUG : both2: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/24 05:20:03 DEBUG : both2: Unchanged skipping 2022/03/24 05:20:03 DEBUG : both3: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/24 05:20:03 DEBUG : both3: Unchanged skipping 2022/03/24 05:20:03 DEBUG : both4: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/24 05:20:03 DEBUG : both4: Unchanged skipping 2022/03/24 05:20:03 DEBUG : both5: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/24 05:20:03 DEBUG : both5: Unchanged skipping 2022/03/24 05:20:03 DEBUG : both6: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/24 05:20:03 DEBUG : both6: Unchanged skipping 2022/03/24 05:20:03 DEBUG : both7: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/24 05:20:03 DEBUG : both7: Unchanged skipping 2022/03/24 05:20:03 DEBUG : both8: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/24 05:20:03 DEBUG : both8: Unchanged skipping 2022/03/24 05:20:03 DEBUG : both9: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/24 05:20:03 DEBUG : both9: Unchanged skipping 2022/03/24 05:20:03 DEBUG : only0: Sizes differ (src 0 vs dst 6) 2022/03/24 05:20:03 DEBUG : only1: Sizes differ (src 0 vs dst 6) 2022/03/24 05:20:03 DEBUG : only10: Sizes differ (src 0 vs dst 6) 2022/03/24 05:20:03 DEBUG : only11: Sizes differ (src 0 vs dst 6) 2022/03/24 05:20:03 DEBUG : only12: Sizes differ (src 0 vs dst 6) 2022/03/24 05:20:03 DEBUG : only13: Sizes differ (src 0 vs dst 6) 2022/03/24 05:20:03 DEBUG : only14: Sizes differ (src 0 vs dst 6) 2022/03/24 05:20:03 DEBUG : only15: Sizes differ (src 0 vs dst 6) 2022/03/24 05:20:03 DEBUG : only16: Sizes differ (src 0 vs dst 6) 2022/03/24 05:20:03 DEBUG : only17: Sizes differ (src 0 vs dst 6) 2022/03/24 05:20:03 DEBUG : only18: Sizes differ (src 0 vs dst 6) 2022/03/24 05:20:03 DEBUG : only19: Sizes differ (src 0 vs dst 6) 2022/03/24 05:20:03 DEBUG : only2: Sizes differ (src 0 vs dst 6) 2022/03/24 05:20:03 DEBUG : only3: Sizes differ (src 0 vs dst 6) 2022/03/24 05:20:03 DEBUG : only4: Sizes differ (src 0 vs dst 6) 2022/03/24 05:20:03 DEBUG : only5: Sizes differ (src 0 vs dst 6) 2022/03/24 05:20:03 DEBUG : only6: Sizes differ (src 0 vs dst 6) 2022/03/24 05:20:03 DEBUG : only7: Sizes differ (src 0 vs dst 6) 2022/03/24 05:20:03 DEBUG : only8: Sizes differ (src 0 vs dst 6) 2022/03/24 05:20:03 DEBUG : only9: Sizes differ (src 0 vs dst 6) 2022/03/24 05:20:03 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for checks to finish 2022/03/24 05:20:03 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Waiting for transfers to finish 2022/03/24 05:20:04 DEBUG : only11: md5 = ec08e713248edb5d3ff93c1984499d48 OK 2022/03/24 05:20:04 INFO : only11: Copied (replaced existing) 2022/03/24 05:20:04 DEBUG : only1: md5 = 4a61dc674c8dda76d7c9078213e067b0 OK 2022/03/24 05:20:04 INFO : only1: Copied (replaced existing) 2022/03/24 05:20:04 DEBUG : only0: md5 = 413d1ae42e18a9c4f7ec153baa7f7cd0 OK 2022/03/24 05:20:04 INFO : only0: Copied (replaced existing) 2022/03/24 05:20:04 DEBUG : only10: md5 = 7c17bea067cbc9c63956f5dc96d606e0 OK 2022/03/24 05:20:04 INFO : only10: Copied (replaced existing) 2022/03/24 05:20:04 DEBUG : pacer: low level retry 1/1 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/24 05:20:04 DEBUG : pacer: Rate limited, increasing sleep to 1.62949279s 2022/03/24 05:20:04 DEBUG : only13: Received 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 - low level retry 1/10 2022/03/24 05:20:04 DEBUG : pacer: low level retry 1/1 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/24 05:20:04 DEBUG : pacer: Rate limited, increasing sleep to 2.00478912s 2022/03/24 05:20:04 DEBUG : only12: Received 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 - low level retry 1/10 2022/03/24 05:20:04 DEBUG : pacer: low level retry 1/1 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/24 05:20:04 DEBUG : pacer: Rate limited, increasing sleep to 4.095817196s 2022/03/24 05:20:04 DEBUG : only14: Received 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 - low level retry 1/10 2022/03/24 05:20:04 DEBUG : pacer: low level retry 1/1 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/24 05:20:04 DEBUG : pacer: Rate limited, increasing sleep to 8.806742805s 2022/03/24 05:20:04 DEBUG : only13: Received 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 - low level retry 2/10 2022/03/24 05:20:05 DEBUG : pacer: Reducing sleep to 0s 2022/03/24 05:20:05 DEBUG : only15: md5 = 5621d618c4fc24b1a4b8096c75acb73f OK 2022/03/24 05:20:05 INFO : only15: Copied (replaced existing) 2022/03/24 05:20:07 DEBUG : only14: md5 = 2a3b9574fb58b52bab9a422c7fd4e613 OK 2022/03/24 05:20:07 INFO : only14: Copied (replaced existing) 2022/03/24 05:20:07 DEBUG : only16: md5 = 9b69a055d94202a238e52c8f02540b46 OK 2022/03/24 05:20:07 INFO : only16: Copied (replaced existing) 2022/03/24 05:20:07 DEBUG : only13: md5 = 34aab59c6efe650399e771fad2dc8c40 OK 2022/03/24 05:20:07 INFO : only13: Copied (replaced existing) 2022/03/24 05:20:07 DEBUG : only12: md5 = 836802f737f6452c72605cfd3b78e7ac OK 2022/03/24 05:20:07 INFO : only12: Copied (replaced existing) 2022/03/24 05:20:08 DEBUG : only17: md5 = f95b8a193736228afdef9f6c3ae3cad5 OK 2022/03/24 05:20:08 INFO : only17: Copied (replaced existing) 2022/03/24 05:20:08 DEBUG : only19: md5 = d8f6d4074bfffab97bb599e1b778d6d1 OK 2022/03/24 05:20:08 INFO : only19: Copied (replaced existing) 2022/03/24 05:20:09 DEBUG : only2: md5 = 1b6a7148145183d774965276278d539a OK 2022/03/24 05:20:09 INFO : only2: Copied (replaced existing) 2022/03/24 05:20:09 DEBUG : only18: md5 = 9d770b3ef16c1d756b648074b3def5ec OK 2022/03/24 05:20:09 INFO : only18: Copied (replaced existing) 2022/03/24 05:20:09 DEBUG : only3: md5 = 1feeb2ff214e5b5ec4da31ee3270aa29 OK 2022/03/24 05:20:09 INFO : only3: Copied (replaced existing) 2022/03/24 05:20:10 DEBUG : only4: md5 = 09bd76cab5580c5df45d22170a1eaa5b OK 2022/03/24 05:20:10 INFO : only4: Copied (replaced existing) 2022/03/24 05:20:10 DEBUG : only6: md5 = a42f6c5c9621f8290fd92ed5792bd636 OK 2022/03/24 05:20:10 INFO : only6: Copied (replaced existing) 2022/03/24 05:20:10 DEBUG : only5: md5 = ca505ff9ab6cfe7fe0be060221364a62 OK 2022/03/24 05:20:10 INFO : only5: Copied (replaced existing) 2022/03/24 05:20:11 DEBUG : only7: md5 = f32fd4b0327751d8b524e9c59233287d OK 2022/03/24 05:20:11 INFO : only7: Copied (replaced existing) 2022/03/24 05:20:11 DEBUG : only8: md5 = 3fa4690b06ab126db8061bbbb0f4d5d5 OK 2022/03/24 05:20:11 INFO : only8: Copied (replaced existing) 2022/03/24 05:20:11 DEBUG : only9: md5 = 5a038df0384cefcc967772a6dd55417f OK 2022/03/24 05:20:11 INFO : only9: Copied (replaced existing) 2022/03/24 05:20:11 DEBUG : Waiting for deletions to finish --- PASS: TestSyncConcurrentTruncate (101.67s) PASS 2022/03/24 05:20:35 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gequmih1ruqudit6fogomit1': Purge remote "./sync.test -test.v -test.timeout 1h0m0s -remote TestCryptDrive: -verbose -fast-list" - Finished OK in 15m45.315868906s (try 1/5)