"./sync.test -test.v -test.timeout 1h0m0s -remote TestCryptDrive: -verbose -fast-list" - Starting (try 1/5) 2021/07/25 05:25:32 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4" 2021/07/25 05:25:32 DEBUG : Using config file from "/home/rclone/.rclone.conf" 2021/07/25 05:25:32 DEBUG : Creating backend with remote "TestDrive:crypt/3hcvr7rq3rr7dr8blvrfl2v9cg27o41psq1vr6v1p1kpca4b09gms2acl7kbj4gi8k00uq0gs7fb6" 2021/07/25 05:25:33 DEBUG : Creating backend with remote "/tmp/rclone325973095" === RUN TestPipe --- PASS: TestPipe (0.00s) === RUN TestPipeConcurrent --- PASS: TestPipeConcurrent (0.07s) === RUN TestPipeOrderBy === RUN TestPipeOrderBy/#00 === RUN TestPipeOrderBy/size === RUN TestPipeOrderBy/name === RUN TestPipeOrderBy/modtime === RUN TestPipeOrderBy/size,ascending === RUN TestPipeOrderBy/name,asc === RUN TestPipeOrderBy/modtime,ascending === RUN TestPipeOrderBy/size,descending === RUN TestPipeOrderBy/name,desc === RUN TestPipeOrderBy/modtime,descending === RUN TestPipeOrderBy/size,mixed,50 === RUN TestPipeOrderBy/size,mixed,51 --- PASS: TestPipeOrderBy (0.00s) --- PASS: TestPipeOrderBy/#00 (0.00s) --- PASS: TestPipeOrderBy/size (0.00s) --- PASS: TestPipeOrderBy/name (0.00s) --- PASS: TestPipeOrderBy/modtime (0.00s) --- PASS: TestPipeOrderBy/size,ascending (0.00s) --- PASS: TestPipeOrderBy/name,asc (0.00s) --- PASS: TestPipeOrderBy/modtime,ascending (0.00s) --- PASS: TestPipeOrderBy/size,descending (0.00s) --- PASS: TestPipeOrderBy/name,desc (0.00s) --- PASS: TestPipeOrderBy/modtime,descending (0.00s) --- PASS: TestPipeOrderBy/size,mixed,50 (0.00s) --- PASS: TestPipeOrderBy/size,mixed,51 (0.00s) === RUN TestNewLess === RUN TestNewLess/blankOK === RUN TestNewLess/tooManyParts === RUN TestNewLess/tooManyParts2 === RUN TestNewLess/badMixed === RUN TestNewLess/unknownComparison === RUN TestNewLess/unknownSortDirection === RUN TestNewLess/size === RUN TestNewLess/name === RUN TestNewLess/modtime === RUN TestNewLess/size,ascending === RUN TestNewLess/name,asc === RUN TestNewLess/modtime,ascending === RUN TestNewLess/size,descending === RUN TestNewLess/name,desc === RUN TestNewLess/modtime,descending === RUN TestNewLess/modtime,mixed === RUN TestNewLess/modtime,mixed,30 --- PASS: TestNewLess (0.00s) --- PASS: TestNewLess/blankOK (0.00s) --- PASS: TestNewLess/tooManyParts (0.00s) --- PASS: TestNewLess/tooManyParts2 (0.00s) --- PASS: TestNewLess/badMixed (0.00s) --- PASS: TestNewLess/unknownComparison (0.00s) --- PASS: TestNewLess/unknownSortDirection (0.00s) --- PASS: TestNewLess/size (0.00s) --- PASS: TestNewLess/name (0.00s) --- PASS: TestNewLess/modtime (0.00s) --- PASS: TestNewLess/size,ascending (0.00s) --- PASS: TestNewLess/name,asc (0.00s) --- PASS: TestNewLess/modtime,ascending (0.00s) --- PASS: TestNewLess/size,descending (0.00s) --- PASS: TestNewLess/name,desc (0.00s) --- PASS: TestNewLess/modtime,descending (0.00s) --- PASS: TestNewLess/modtime,mixed (0.00s) --- PASS: TestNewLess/modtime,mixed,30 (0.00s) === RUN TestRcCopy rc_test.go:16: Skipping test on non local remote --- SKIP: TestRcCopy (0.00s) === RUN TestRcMove rc_test.go:16: Skipping test on non local remote --- SKIP: TestRcMove (0.00s) === RUN TestRcSync rc_test.go:16: Skipping test on non local remote --- SKIP: TestRcSync (0.00s) === RUN TestCopyWithDryRun run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4'", Local "Local file system at /tmp/rclone325973095", Modify Window "1ms" 2021/07/25 05:25: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) 2021/07/25 05:25:33 DEBUG : pacer: Rate limited, increasing sleep to 1.438533415s 2021/07/25 05:25: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) 2021/07/25 05:25:33 DEBUG : pacer: Rate limited, increasing sleep to 2.694464641s 2021/07/25 05:25:35 DEBUG : pacer: Reducing sleep to 0s 2021/07/25 05:25:38 NOTICE: sub dir/hello world: Skipped copy as --dry-run is set (size 11) 2021/07/25 05:25:38 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for checks to finish 2021/07/25 05:25:38 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for transfers to finish --- PASS: TestCopyWithDryRun (5.49s) === RUN TestCopy run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4'", Local "Local file system at /tmp/rclone325973095", Modify Window "1ms" 2021/07/25 05:25:39 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for checks to finish 2021/07/25 05:25:39 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for transfers to finish 2021/07/25 05:25:41 DEBUG : sub dir/hello world: md5 = 7039df5a134d6bf1c3cbf0e35db0de47 OK 2021/07/25 05:25:41 INFO : sub dir/hello world: Copied (new) 2021/07/25 05:25:42 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestCopy (4.39s) === RUN TestCopyMissingDirectory run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4'", Local "Local file system at /tmp/rclone325973095", Modify Window "1ms" 2021/07/25 05:25:43 DEBUG : Creating backend with remote "/non-existing" 2021/07/25 05:25:43 ERROR : Local file system at /non-existing: error reading source root directory: directory not found 2021/07/25 05:25:43 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for checks to finish 2021/07/25 05:25:43 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for transfers to finish --- PASS: TestCopyMissingDirectory (0.59s) === RUN TestCopyNoTraverse run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4'", Local "Local file system at /tmp/rclone325973095", Modify Window "1ms" 2021/07/25 05:25:43 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for checks to finish 2021/07/25 05:25:43 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for transfers to finish 2021/07/25 05:25:45 DEBUG : sub dir/hello world: md5 = 74077a579177cf4a637966fe04c77b5f OK 2021/07/25 05:25:45 INFO : sub dir/hello world: Copied (new) 2021/07/25 05:25:47 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestCopyNoTraverse (4.33s) === RUN TestCopyCheckFirst run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4'", Local "Local file system at /tmp/rclone325973095", Modify Window "1ms" 2021/07/25 05:25:48 INFO : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Running all checks before starting transfers 2021/07/25 05:25:48 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for checks to finish 2021/07/25 05:25:48 INFO : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Checks finished, now starting transfers 2021/07/25 05:25:48 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for transfers to finish 2021/07/25 05:25:50 DEBUG : sub dir/hello world: md5 = 223c1843e2db9218de98d481d943deb0 OK 2021/07/25 05:25:50 INFO : sub dir/hello world: Copied (new) 2021/07/25 05:25:51 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestCopyCheckFirst (4.12s) === RUN TestSyncNoTraverse run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4'", Local "Local file system at /tmp/rclone325973095", Modify Window "1ms" 2021/07/25 05:25:52 ERROR : Ignoring --no-traverse with sync 2021/07/25 05:25:52 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2021/07/25 05:25:52 DEBUG : pacer: Rate limited, increasing sleep to 1.898837207s 2021/07/25 05:25:52 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2021/07/25 05:25:52 DEBUG : pacer: Rate limited, increasing sleep to 2.53436625s 2021/07/25 05:25:54 DEBUG : pacer: Reducing sleep to 0s 2021/07/25 05:25:54 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for checks to finish 2021/07/25 05:25:54 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for transfers to finish 2021/07/25 05:25:58 DEBUG : sub dir/hello world: md5 = 27161a26b82368b3accd8af1aca57d69 OK 2021/07/25 05:25:58 INFO : sub dir/hello world: Copied (new) 2021/07/25 05:25:58 DEBUG : Waiting for deletions to finish 2021/07/25 05:26:00 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestSyncNoTraverse (8.92s) === RUN TestCopyWithDepth run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4'", Local "Local file system at /tmp/rclone325973095", Modify Window "1ms" 2021/07/25 05:26:01 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for checks to finish 2021/07/25 05:26:01 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for transfers to finish 2021/07/25 05:26:02 DEBUG : hello world2: md5 = 3a964e92a9958e509e27706cf8c2e2e3 OK 2021/07/25 05:26:02 INFO : hello world2: Copied (new) --- PASS: TestCopyWithDepth (2.48s) === RUN TestCopyWithFilesFrom run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4'", Local "Local file system at /tmp/rclone325973095", Modify Window "1ms" 2021/07/25 05:26:03 DEBUG : hello world2: Excluded 2021/07/25 05:26:03 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for checks to finish 2021/07/25 05:26:03 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for transfers to finish 2021/07/25 05:26:05 DEBUG : potato2: md5 = 45e6e18348f0fdd912512a9fbe327fd3 OK 2021/07/25 05:26:05 INFO : potato2: Copied (new) --- PASS: TestCopyWithFilesFrom (2.70s) === RUN TestCopyWithFilesFromAndNoTraverse run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4'", Local "Local file system at /tmp/rclone325973095", Modify Window "1ms" 2021/07/25 05:26:06 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for checks to finish 2021/07/25 05:26:06 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for transfers to finish 2021/07/25 05:26:07 DEBUG : potato2: md5 = bf79d760497e7147d209f75f8052b43b OK 2021/07/25 05:26:07 INFO : potato2: Copied (new) --- PASS: TestCopyWithFilesFromAndNoTraverse (2.67s) === RUN TestCopyEmptyDirectories run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4'", Local "Local file system at /tmp/rclone325973095", Modify Window "1ms" 2021/07/25 05:26:09 DEBUG : sub dir2: Making directory 2021/07/25 05:26:09 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for checks to finish 2021/07/25 05:26:09 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for transfers to finish 2021/07/25 05:26:11 DEBUG : sub dir/hello world: md5 = 304110bd4dd63d51c46d604a9f621f98 OK 2021/07/25 05:26:11 INFO : sub dir/hello world: Copied (new) 2021/07/25 05:26:11 DEBUG : sub dir2: Making directory 2021/07/25 05:26:11 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': copied 1 directories 2021/07/25 05:26:13 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestCopyEmptyDirectories (5.42s) === RUN TestMoveEmptyDirectories run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4'", Local "Local file system at /tmp/rclone325973095", Modify Window "1ms" 2021/07/25 05:26:14 DEBUG : sub dir2: Making directory 2021/07/25 05:26:14 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for checks to finish 2021/07/25 05:26:14 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for transfers to finish 2021/07/25 05:26:16 DEBUG : sub dir/hello world: md5 = 5d9f6f0f7860caff0d9b7e38ca9fe178 OK 2021/07/25 05:26:16 INFO : sub dir/hello world: Copied (new) 2021/07/25 05:26:16 INFO : sub dir/hello world: Deleted 2021/07/25 05:26:16 DEBUG : sub dir: Making directory 2021/07/25 05:26:16 DEBUG : sub dir2: Making directory 2021/07/25 05:26:17 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': copied 2 directories 2021/07/25 05:26:19 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestMoveEmptyDirectories (5.67s) === RUN TestSyncEmptyDirectories run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4'", Local "Local file system at /tmp/rclone325973095", Modify Window "1ms" 2021/07/25 05:26:20 DEBUG : sub dir2: Making directory 2021/07/25 05:26:20 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for checks to finish 2021/07/25 05:26:20 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for transfers to finish 2021/07/25 05:26:22 DEBUG : sub dir/hello world: md5 = ec78dd6535e961510ee123016e0649a4 OK 2021/07/25 05:26:22 INFO : sub dir/hello world: Copied (new) 2021/07/25 05:26:22 DEBUG : sub dir2: Making directory 2021/07/25 05:26:22 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': copied 1 directories 2021/07/25 05:26:22 DEBUG : Waiting for deletions to finish 2021/07/25 05:26:24 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestSyncEmptyDirectories (5.57s) === RUN TestServerSideCopy run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4'", Local "Local file system at /tmp/rclone325973095", Modify Window "1ms" 2021/07/25 05:26:27 DEBUG : sub dir/hello world: md5 = ed5ec4bd6233a62908d1972e3fa26122 OK 2021/07/25 05:26:28 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-jahagen0vivufuz7wujihoq3" 2021/07/25 05:26:28 DEBUG : Creating backend with remote "TestDrive:crypt/gjn2jaule5fmjg37j72qcp0v9c7ji084fskii0i46n0781kg0nntdasr3jnchgjjphrie6h8pbe66" sync_test.go:281: Server side copy (if possible) Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4' -> Encrypted drive 'TestCryptDrive:rclone-test-jahagen0vivufuz7wujihoq3' 2021/07/25 05:26:29 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jahagen0vivufuz7wujihoq3': Waiting for checks to finish 2021/07/25 05:26:29 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jahagen0vivufuz7wujihoq3': Waiting for transfers to finish 2021/07/25 05:26:32 INFO : sub dir/hello world: Copied (server-side copy) 2021/07/25 05:26:32 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-jahagen0vivufuz7wujihoq3': Purge remote 2021/07/25 05:26:34 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestServerSideCopy (9.53s) === RUN TestCopyAfterDelete run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4'", Local "Local file system at /tmp/rclone325973095", Modify Window "1ms" 2021/07/25 05:26:37 DEBUG : sub dir/hello world: md5 = 406c17d2ba4923ea2f412eb99a014fb0 OK 2021/07/25 05:26:37 ERROR : : error listing: directory not found 2021/07/25 05:26:37 DEBUG : Local file system at /tmp/rclone325973095: Making directory 2021/07/25 05:26:38 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for checks to finish 2021/07/25 05:26:38 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for transfers to finish 2021/07/25 05:26:39 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestCopyAfterDelete (5.39s) === RUN TestCopyRedownload run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4'", Local "Local file system at /tmp/rclone325973095", Modify Window "1ms" 2021/07/25 05:26:42 DEBUG : sub dir/hello world: md5 = 8ff632d761e3e517da8dafc9b61359d3 OK 2021/07/25 05:26:43 DEBUG : Local file system at /tmp/rclone325973095: Waiting for checks to finish 2021/07/25 05:26:43 DEBUG : Local file system at /tmp/rclone325973095: Waiting for transfers to finish 2021/07/25 05:26:44 INFO : sub dir/hello world: Copied (new) 2021/07/25 05:26:45 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestCopyRedownload (5.55s) === RUN TestSyncBasedOnCheckSum run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4'", Local "Local file system at /tmp/rclone325973095", Modify Window "1ms" 2021/07/25 05:26:46 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for checks to finish 2021/07/25 05:26:46 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for transfers to finish 2021/07/25 05:26:47 DEBUG : check sum: md5 = af5f1a833831094e6985fa643803b22b OK 2021/07/25 05:26:47 INFO : check sum: Copied (new) 2021/07/25 05:26:47 DEBUG : Waiting for deletions to finish 2021/07/25 05:26:47 NOTICE: Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': --checksum is in use but the source and destination have no hashes in common; falling back to --size-only 2021/07/25 05:26:47 DEBUG : check sum: Size of src and dst objects identical 2021/07/25 05:26:47 DEBUG : check sum: Unchanged skipping 2021/07/25 05:26:47 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for checks to finish 2021/07/25 05:26:47 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for transfers to finish 2021/07/25 05:26:47 DEBUG : Waiting for deletions to finish 2021/07/25 05:26:47 INFO : There was nothing to transfer --- PASS: TestSyncBasedOnCheckSum (2.87s) === RUN TestSyncSizeOnly run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4'", Local "Local file system at /tmp/rclone325973095", Modify Window "1ms" 2021/07/25 05:26:49 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for checks to finish 2021/07/25 05:26:49 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for transfers to finish 2021/07/25 05:26:50 DEBUG : sizeonly: md5 = 2da54ad3e68ea2a6be5676546b173534 OK 2021/07/25 05:26:50 INFO : sizeonly: Copied (new) 2021/07/25 05:26:50 DEBUG : Waiting for deletions to finish 2021/07/25 05:26:50 DEBUG : sizeonly: Sizes identical 2021/07/25 05:26:50 DEBUG : sizeonly: Unchanged skipping 2021/07/25 05:26:50 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for checks to finish 2021/07/25 05:26:50 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for transfers to finish 2021/07/25 05:26:50 DEBUG : Waiting for deletions to finish 2021/07/25 05:26:50 INFO : There was nothing to transfer --- PASS: TestSyncSizeOnly (2.85s) === RUN TestSyncIgnoreSize run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4'", Local "Local file system at /tmp/rclone325973095", Modify Window "1ms" 2021/07/25 05:26:52 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for checks to finish 2021/07/25 05:26:52 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for transfers to finish 2021/07/25 05:26:53 DEBUG : ignore-size: md5 = 9b96b7d0bc976e93dc47043e6ffeb31d OK 2021/07/25 05:26:53 INFO : ignore-size: Copied (new) 2021/07/25 05:26:53 DEBUG : Waiting for deletions to finish 2021/07/25 05:26:53 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for checks to finish 2021/07/25 05:26:53 DEBUG : ignore-size: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2021/07/25 05:26:53 DEBUG : ignore-size: Unchanged skipping 2021/07/25 05:26:53 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for transfers to finish 2021/07/25 05:26:53 DEBUG : Waiting for deletions to finish 2021/07/25 05:26:53 INFO : There was nothing to transfer --- PASS: TestSyncIgnoreSize (3.01s) === RUN TestSyncIgnoreTimes run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4'", Local "Local file system at /tmp/rclone325973095", Modify Window "1ms" 2021/07/25 05:26:56 DEBUG : existing: md5 = 1fe4a4448da107c8078a94026e2c9af4 OK 2021/07/25 05:26:56 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for checks to finish 2021/07/25 05:26:56 DEBUG : existing: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2021/07/25 05:26:56 DEBUG : existing: Unchanged skipping 2021/07/25 05:26:56 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for transfers to finish 2021/07/25 05:26:56 DEBUG : Waiting for deletions to finish 2021/07/25 05:26:56 INFO : There was nothing to transfer 2021/07/25 05:26:56 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for checks to finish 2021/07/25 05:26:56 DEBUG : existing: Transferring unconditionally as --ignore-times is in use 2021/07/25 05:26:56 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for transfers to finish 2021/07/25 05:26:57 DEBUG : existing: md5 = 0b25c2a5114c9e55386c3806c6b6b4b4 OK 2021/07/25 05:26:57 INFO : existing: Copied (replaced existing) 2021/07/25 05:26:57 DEBUG : Waiting for deletions to finish --- PASS: TestSyncIgnoreTimes (4.17s) === RUN TestSyncIgnoreExisting run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4'", Local "Local file system at /tmp/rclone325973095", Modify Window "1ms" 2021/07/25 05:26:59 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for checks to finish 2021/07/25 05:26:59 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for transfers to finish 2021/07/25 05:27:00 DEBUG : existing: md5 = be1459a43f8cbb8b095816312eee1ae2 OK 2021/07/25 05:27:00 INFO : existing: Copied (new) 2021/07/25 05:27:00 DEBUG : Waiting for deletions to finish 2021/07/25 05:27:00 DEBUG : existing: Destination exists, skipping 2021/07/25 05:27:00 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for checks to finish 2021/07/25 05:27:00 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for transfers to finish 2021/07/25 05:27:00 DEBUG : Waiting for deletions to finish 2021/07/25 05:27:00 INFO : There was nothing to transfer --- PASS: TestSyncIgnoreExisting (2.93s) === RUN TestSyncIgnoreErrors run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4'", Local "Local file system at /tmp/rclone325973095", Modify Window "1ms" 2021/07/25 05:27:04 DEBUG : b/potato: md5 = e192de8a0ea2b103cecf63ed32c39433 OK 2021/07/25 05:27:06 DEBUG : c/non empty space: md5 = 331315b673ce52b2d96fb0b5bc4b7acc OK 2021/07/25 05:27:06 DEBUG : d: Making directory 2021/07/25 05:27:07 DEBUG : c/non empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2021/07/25 05:27:07 DEBUG : c/non empty space: Unchanged skipping 2021/07/25 05:27:07 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for checks to finish 2021/07/25 05:27:07 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for transfers to finish 2021/07/25 05:27:09 DEBUG : a/potato2: md5 = 07c210e047cfecbd6973111ec0b8a17f OK 2021/07/25 05:27:09 INFO : a/potato2: Copied (new) 2021/07/25 05:27:09 DEBUG : Waiting for deletions to finish 2021/07/25 05:27:10 INFO : b/potato: Deleted 2021/07/25 05:27:10 INFO : d: Removing directory 2021/07/25 05:27:11 INFO : b: Removing directory 2021/07/25 05:27:11 DEBUG : 32d8ua6196mc1r7qkfog53rkg0: Rmdir: contains trashed file: "2m507n64kafsi59v9q71r281a4" 2021/07/25 05:27:11 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': deleted 2 directories 2021/07/25 05:27:13 DEBUG : 3i9du405pfogq3ncai6pg7ouio: Rmdir: contains trashed file: "982d3pss7t5pn0il16r2foj31s" 2021/07/25 05:27:14 DEBUG : 2bsvlrk2ne1lfitm6tttcu0qt8: Rmdir: contains trashed file: "89l8renevh3mji1c8r1p7qn6tg" --- PASS: TestSyncIgnoreErrors (13.14s) === RUN TestSyncAfterChangingModtimeOnly run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4'", Local "Local file system at /tmp/rclone325973095", Modify Window "1ms" 2021/07/25 05:27:16 DEBUG : empty space: md5 = d45ecc0b9bf02d32ac3082bc45301ca1 OK 2021/07/25 05:27:16 DEBUG : empty space: Modification times differ by -95456h54m52.624456789s: 2011-12-25 12:59:59.123456789 +0000 UTC, 2001-02-03 04:05:06.499 +0000 UTC 2021/07/25 05:27:16 NOTICE: empty space: Skipped copy as --dry-run is set (size 1) 2021/07/25 05:27:16 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for checks to finish 2021/07/25 05:27:16 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for transfers to finish 2021/07/25 05:27:16 DEBUG : Waiting for deletions to finish 2021/07/25 05:27:17 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for checks to finish 2021/07/25 05:27:17 DEBUG : empty space: Modification times differ by -95456h54m52.624456789s: 2011-12-25 12:59:59.123456789 +0000 UTC, 2001-02-03 04:05:06.499 +0000 UTC 2021/07/25 05:27:17 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for transfers to finish 2021/07/25 05:27:18 DEBUG : empty space: md5 = b5a80f6580fa2f9f8a648d172919bba8 OK 2021/07/25 05:27:18 INFO : empty space: Copied (replaced existing) 2021/07/25 05:27:18 DEBUG : Waiting for deletions to finish --- PASS: TestSyncAfterChangingModtimeOnly (4.20s) === RUN TestSyncAfterChangingModtimeOnlyWithNoUpdateModTime run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4'", Local "Local file system at /tmp/rclone325973095", Modify Window "1ms" sync_test.go:591: Can't check this if no hashes supported --- PASS: TestSyncAfterChangingModtimeOnlyWithNoUpdateModTime (0.38s) === RUN TestSyncDoesntUpdateModtime run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4'", Local "Local file system at /tmp/rclone325973095", Modify Window "1ms" 2021/07/25 05:27:20 DEBUG : foo: md5 = 37a1f449e33502a03a06c69060186cc5 OK 2021/07/25 05:27:21 DEBUG : foo: Modification times differ by -95456h54m52.624456789s: 2011-12-25 12:59:59.123456789 +0000 UTC, 2001-02-03 04:05:06.499 +0000 UTC 2021/07/25 05:27:21 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for checks to finish 2021/07/25 05:27:21 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for transfers to finish 2021/07/25 05:27:22 DEBUG : foo: md5 = 993b9b8743ddc2f02e0e9c071977af40 OK 2021/07/25 05:27:22 INFO : foo: Copied (replaced existing) 2021/07/25 05:27:22 DEBUG : Waiting for deletions to finish --- PASS: TestSyncDoesntUpdateModtime (3.74s) === RUN TestSyncAfterAddingAFile run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4'", Local "Local file system at /tmp/rclone325973095", Modify Window "1ms" 2021/07/25 05:27:24 DEBUG : empty space: md5 = c00d6b12b0f580a2b6b59d4b3b359fd9 OK 2021/07/25 05:27:25 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2021/07/25 05:27:25 DEBUG : empty space: Unchanged skipping 2021/07/25 05:27:25 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for checks to finish 2021/07/25 05:27:25 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for transfers to finish 2021/07/25 05:27:26 DEBUG : potato: md5 = 7a48fa44beaad8abb73524aceb7a384e OK 2021/07/25 05:27:26 INFO : potato: Copied (new) 2021/07/25 05:27:26 DEBUG : Waiting for deletions to finish --- PASS: TestSyncAfterAddingAFile (4.75s) === RUN TestSyncAfterChangingFilesSizeOnly run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4'", Local "Local file system at /tmp/rclone325973095", Modify Window "1ms" 2021/07/25 05:27:29 DEBUG : potato: md5 = 90a5237bdc29e8ce615ba90b0c4619f7 OK 2021/07/25 05:27:29 DEBUG : potato: Sizes differ (src 21 vs dst 60) 2021/07/25 05:27:29 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for checks to finish 2021/07/25 05:27:29 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for transfers to finish 2021/07/25 05:27:30 DEBUG : potato: md5 = 882c256f1e6e9e4f890b653a6f86c3d3 OK 2021/07/25 05:27:30 INFO : potato: Copied (replaced existing) 2021/07/25 05:27:30 DEBUG : Waiting for deletions to finish --- PASS: TestSyncAfterChangingFilesSizeOnly (3.98s) === RUN TestSyncAfterChangingContentsOnly run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4'", Local "Local file system at /tmp/rclone325973095", Modify Window "1ms" 2021/07/25 05:27:33 DEBUG : potato: md5 = 75035cf1590d1e3e06270cb29f4ea298 OK 2021/07/25 05:27:33 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for checks to finish 2021/07/25 05:27:33 DEBUG : potato: Modification times differ by 119h59m59.876543211s: 2011-12-25 12:59:59.123456789 +0000 UTC, 2011-12-30 12:59:59 +0000 UTC 2021/07/25 05:27:33 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for transfers to finish 2021/07/25 05:27:34 DEBUG : potato: md5 = ba1b8d441aefeca4f0444460b0e14269 OK 2021/07/25 05:27:34 INFO : potato: Copied (replaced existing) 2021/07/25 05:27:34 DEBUG : Waiting for deletions to finish --- PASS: TestSyncAfterChangingContentsOnly (3.86s) === RUN TestSyncAfterRemovingAFileAndAddingAFileDryRun run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4'", Local "Local file system at /tmp/rclone325973095", Modify Window "1ms" 2021/07/25 05:27:37 DEBUG : potato: md5 = 5c66d00025aeb4e24028d0cd65600337 OK 2021/07/25 05:27:38 DEBUG : empty space: md5 = f61d86a2df2f11b59b8fdc7b951be287 OK 2021/07/25 05:27:38 NOTICE: potato2: Skipped copy as --dry-run is set (size 60) 2021/07/25 05:27:38 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2021/07/25 05:27:38 DEBUG : empty space: Unchanged skipping 2021/07/25 05:27:38 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for checks to finish 2021/07/25 05:27:38 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for transfers to finish 2021/07/25 05:27:38 DEBUG : Waiting for deletions to finish 2021/07/25 05:27:38 NOTICE: potato: Skipped delete as --dry-run is set (size 21) --- PASS: TestSyncAfterRemovingAFileAndAddingAFileDryRun (4.09s) === RUN TestSyncAfterRemovingAFileAndAddingAFile run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4'", Local "Local file system at /tmp/rclone325973095", Modify Window "1ms" 2021/07/25 05:27:41 DEBUG : potato: md5 = b38cdb428ea4dfe8926e202a127c8d6d OK 2021/07/25 05:27:42 DEBUG : empty space: md5 = 34b81bd9be410c2ae4b64a55c8729d5e OK 2021/07/25 05:27:43 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2021/07/25 05:27:43 DEBUG : empty space: Unchanged skipping 2021/07/25 05:27:43 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for checks to finish 2021/07/25 05:27:43 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for transfers to finish 2021/07/25 05:27:44 DEBUG : potato2: md5 = 3ce7d346956fe798125b86cf1f582a11 OK 2021/07/25 05:27:44 INFO : potato2: Copied (new) 2021/07/25 05:27:44 DEBUG : Waiting for deletions to finish 2021/07/25 05:27:45 INFO : potato: Deleted --- PASS: TestSyncAfterRemovingAFileAndAddingAFile (6.63s) === RUN TestSyncAfterRemovingAFileAndAddingAFileSubDir run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4'", Local "Local file system at /tmp/rclone325973095", Modify Window "1ms" 2021/07/25 05:27:48 DEBUG : b/potato: md5 = 48bf39d96c631b9b746293a9a9763939 OK 2021/07/25 05:27:50 DEBUG : c/non empty space: md5 = edda4e1eba99a9e58d54662b40422a8b OK 2021/07/25 05:27:50 DEBUG : d: Making directory 2021/07/25 05:27:51 DEBUG : d/e: Making directory 2021/07/25 05:27:53 DEBUG : c/non empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2021/07/25 05:27:53 DEBUG : c/non empty space: Unchanged skipping 2021/07/25 05:27:53 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for checks to finish 2021/07/25 05:27:53 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for transfers to finish 2021/07/25 05:27: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) 2021/07/25 05:27:53 DEBUG : pacer: Rate limited, increasing sleep to 1.827325249s 2021/07/25 05:27:54 DEBUG : pacer: Reducing sleep to 0s 2021/07/25 05:27:56 DEBUG : a/potato2: md5 = 8aaa70c0b3ae816b6db88cee268ea00e OK 2021/07/25 05:27:56 INFO : a/potato2: Copied (new) 2021/07/25 05:27:56 DEBUG : Waiting for deletions to finish 2021/07/25 05:27:57 INFO : b/potato: Deleted 2021/07/25 05:27:57 INFO : d/e: Removing directory 2021/07/25 05:27:58 INFO : d: Removing directory 2021/07/25 05:27:58 DEBUG : ka6id8d20d3s5ktapedlphgta8: Rmdir: contains trashed file: "r8sppajuabeak3sbgj2ak8vuf8" 2021/07/25 05:27:58 INFO : b: Removing directory 2021/07/25 05:27:59 DEBUG : 32d8ua6196mc1r7qkfog53rkg0: Rmdir: contains trashed file: "2m507n64kafsi59v9q71r281a4" 2021/07/25 05:27:59 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': deleted 3 directories 2021/07/25 05:28:01 DEBUG : 3i9du405pfogq3ncai6pg7ouio: Rmdir: contains trashed file: "982d3pss7t5pn0il16r2foj31s" 2021/07/25 05:28:02 DEBUG : 2bsvlrk2ne1lfitm6tttcu0qt8: Rmdir: contains trashed file: "89l8renevh3mji1c8r1p7qn6tg" --- PASS: TestSyncAfterRemovingAFileAndAddingAFileSubDir (16.49s) === RUN TestSyncAfterRemovingAFileAndAddingAFileSubDirWithErrors run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4'", Local "Local file system at /tmp/rclone325973095", Modify Window "1ms" 2021/07/25 05:28:05 DEBUG : b/potato: md5 = c4cde3dcfcdd86c2538995c8f5596a7d OK 2021/07/25 05:28:07 DEBUG : c/non empty space: md5 = 4e22800a18388fe32c481556e67f98ae OK 2021/07/25 05:28:07 DEBUG : d: Making directory 2021/07/25 05:28:09 DEBUG : c/non empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2021/07/25 05:28:09 DEBUG : c/non empty space: Unchanged skipping 2021/07/25 05:28:09 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for checks to finish 2021/07/25 05:28:09 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for transfers to finish 2021/07/25 05:28:11 DEBUG : a/potato2: md5 = e0cecac934dce30f93ed42308695afff OK 2021/07/25 05:28:11 INFO : a/potato2: Copied (new) 2021/07/25 05:28:11 ERROR : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': not deleting files as there were IO errors 2021/07/25 05:28:11 ERROR : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': not deleting directories as there were IO errors 2021/07/25 05:28:14 DEBUG : 3i9du405pfogq3ncai6pg7ouio: Rmdir: contains trashed file: "982d3pss7t5pn0il16r2foj31s" 2021/07/25 05:28:16 DEBUG : 32d8ua6196mc1r7qkfog53rkg0: Rmdir: contains trashed file: "2m507n64kafsi59v9q71r281a4" 2021/07/25 05:28:16 DEBUG : 2bsvlrk2ne1lfitm6tttcu0qt8: Rmdir: contains trashed file: "89l8renevh3mji1c8r1p7qn6tg" --- PASS: TestSyncAfterRemovingAFileAndAddingAFileSubDirWithErrors (14.56s) === RUN TestSyncDeleteAfter --- PASS: TestSyncDeleteAfter (0.00s) === RUN TestSyncDeleteDuring run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4'", Local "Local file system at /tmp/rclone325973095", Modify Window "1ms" 2021/07/25 05:28:18 DEBUG : potato: md5 = 9b288d99ce1b64c58c101414acfad660 OK 2021/07/25 05:28:20 DEBUG : empty space: md5 = 99b6c26c7e54d6f74ffc89ac69d7ad27 OK 2021/07/25 05:28:20 DEBUG : Waiting for deletions to finish 2021/07/25 05:28:20 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2021/07/25 05:28:20 DEBUG : empty space: Unchanged skipping 2021/07/25 05:28:20 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for checks to finish 2021/07/25 05:28:20 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for transfers to finish 2021/07/25 05:28:21 INFO : potato: Deleted 2021/07/25 05:28:22 DEBUG : potato2: md5 = fc190bf40f67c12671b98a5b9b5aaf2e OK 2021/07/25 05:28:22 INFO : potato2: Copied (new) --- PASS: TestSyncDeleteDuring (6.27s) === RUN TestSyncDeleteBefore run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4'", Local "Local file system at /tmp/rclone325973095", Modify Window "1ms" 2021/07/25 05:28:25 DEBUG : potato: md5 = e78c6ec2283a40b598046e23c2ab17b4 OK 2021/07/25 05:28:26 DEBUG : empty space: md5 = 6561a397f0897a0563a69a19952d52e6 OK 2021/07/25 05:28:26 DEBUG : Waiting for deletions to finish 2021/07/25 05:28:27 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for checks to finish 2021/07/25 05:28:27 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for transfers to finish 2021/07/25 05:28:27 INFO : potato: Deleted 2021/07/25 05:28:27 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2021/07/25 05:28:27 DEBUG : empty space: Unchanged skipping 2021/07/25 05:28:27 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for checks to finish 2021/07/25 05:28:27 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for transfers to finish 2021/07/25 05:28:29 DEBUG : potato2: md5 = 426222776947af9798933e81c1562d43 OK 2021/07/25 05:28:29 INFO : potato2: Copied (new) --- PASS: TestSyncDeleteBefore (7.32s) === RUN TestCopyDeleteBefore run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4'", Local "Local file system at /tmp/rclone325973095", Modify Window "1ms" 2021/07/25 05:28:32 DEBUG : potato: md5 = 66593140299e1104673f22e22e5ee284 OK 2021/07/25 05:28:33 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for checks to finish 2021/07/25 05:28:33 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for transfers to finish 2021/07/25 05:28:34 DEBUG : potato2: md5 = bab86c481bac80a4d7882214924c8045 OK 2021/07/25 05:28:34 INFO : potato2: Copied (new) --- PASS: TestCopyDeleteBefore (5.43s) === RUN TestSyncWithExclude run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4'", Local "Local file system at /tmp/rclone325973095", Modify Window "1ms" 2021/07/25 05:28:38 DEBUG : potato2: md5 = e5bd7630f2dfc87f8aa17d5b196ad265 OK 2021/07/25 05:28:39 DEBUG : empty space: md5 = 4d40b947d2288f21f8f52c67cfe8b1ae OK 2021/07/25 05:28:39 DEBUG : enormous: Excluded 2021/07/25 05:28:39 DEBUG : potato2: Excluded 2021/07/25 05:28:40 DEBUG : potato2: Excluded from sync (and deletion) 2021/07/25 05:28:40 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2021/07/25 05:28:40 DEBUG : empty space: Unchanged skipping 2021/07/25 05:28:40 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for checks to finish 2021/07/25 05:28:40 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for transfers to finish 2021/07/25 05:28:40 DEBUG : Waiting for deletions to finish 2021/07/25 05:28:40 INFO : There was nothing to transfer 2021/07/25 05:28:40 DEBUG : enormous: Excluded 2021/07/25 05:28:40 DEBUG : potato2: Excluded 2021/07/25 05:28:40 DEBUG : potato2: Excluded from sync (and deletion) 2021/07/25 05:28:40 DEBUG : empty space: Size and modification time the same (differ by 456.789µs, within tolerance 1ms) 2021/07/25 05:28:40 DEBUG : empty space: Unchanged skipping 2021/07/25 05:28:40 DEBUG : Local file system at /tmp/rclone325973095: Waiting for checks to finish 2021/07/25 05:28:40 DEBUG : Local file system at /tmp/rclone325973095: Waiting for transfers to finish 2021/07/25 05:28:40 DEBUG : Waiting for deletions to finish 2021/07/25 05:28:40 INFO : There was nothing to transfer --- PASS: TestSyncWithExclude (5.68s) === RUN TestSyncWithExcludeAndDeleteExcluded run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4'", Local "Local file system at /tmp/rclone325973095", Modify Window "1ms" 2021/07/25 05:28:43 DEBUG : potato2: md5 = d4c983c7f760c4812d2dd9bb9dfc3dfc OK 2021/07/25 05:28:45 DEBUG : empty space: md5 = bb0790abde8edbacdf560a1a6baa9815 OK 2021/07/25 05:28:46 DEBUG : enormous: md5 = db998c683eb39cb5d4f4c1809639a57d OK 2021/07/25 05:28:46 DEBUG : enormous: Excluded 2021/07/25 05:28:46 DEBUG : potato2: Excluded 2021/07/25 05:28:47 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for checks to finish 2021/07/25 05:28:47 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2021/07/25 05:28:47 DEBUG : empty space: Unchanged skipping 2021/07/25 05:28:47 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for transfers to finish 2021/07/25 05:28:47 DEBUG : Waiting for deletions to finish 2021/07/25 05:28:47 INFO : potato2: Deleted 2021/07/25 05:28:47 INFO : enormous: Deleted 2021/07/25 05:28:47 INFO : There was nothing to transfer 2021/07/25 05:28:48 DEBUG : empty space: Size and modification time the same (differ by 456.789µs, within tolerance 1ms) 2021/07/25 05:28:48 DEBUG : empty space: Unchanged skipping 2021/07/25 05:28:48 DEBUG : Local file system at /tmp/rclone325973095: Waiting for checks to finish 2021/07/25 05:28:48 DEBUG : Local file system at /tmp/rclone325973095: Waiting for transfers to finish 2021/07/25 05:28:48 DEBUG : Waiting for deletions to finish 2021/07/25 05:28:48 INFO : potato2: Deleted 2021/07/25 05:28:48 INFO : enormous: Deleted 2021/07/25 05:28:48 INFO : There was nothing to transfer --- PASS: TestSyncWithExcludeAndDeleteExcluded (6.81s) === RUN TestSyncWithUpdateOlder run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4'", Local "Local file system at /tmp/rclone325973095", Modify Window "1ms" 2021/07/25 05:28:50 DEBUG : one: md5 = 9d01d4220ddde8c1f28feb72ac7ba8b0 OK 2021/07/25 05:28:51 DEBUG : two: md5 = 6c0845284fbee7e4a1423c4c3d0b6031 OK 2021/07/25 05:28:53 DEBUG : three: md5 = 23726e2d9c1311b226ce001be8e5a7b6 OK 2021/07/25 05:28:54 DEBUG : four: md5 = 3b086679c2338e27900b236fa9cfbcba OK 2021/07/25 05:28:54 DEBUG : four: Sizes differ (src 4 vs dst 8) 2021/07/25 05:28:54 DEBUG : four: Destination mod time is within 1s of source but files differ, transferring 2021/07/25 05:28:54 DEBUG : one: Destination is newer than source, skipping 2021/07/25 05:28:54 DEBUG : three: Sizes identical 2021/07/25 05:28:54 DEBUG : three: Destination mod time is within 1s of source and files identical, skipping 2021/07/25 05:28:54 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for checks to finish 2021/07/25 05:28:54 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for transfers to finish 2021/07/25 05:28:55 DEBUG : two: md5 = 2e08e633447d03af484e828a6e3d9826 OK 2021/07/25 05:28:55 INFO : two: Copied (replaced existing) 2021/07/25 05:28:56 DEBUG : four: md5 = 38910afcfb854027bf745c8aad8a9305 OK 2021/07/25 05:28:56 INFO : four: Copied (replaced existing) 2021/07/25 05:28:56 DEBUG : five: md5 = fcb439ec27752e32550c5fd2313f92fe OK 2021/07/25 05:28:56 INFO : five: Copied (new) 2021/07/25 05:28:56 DEBUG : Waiting for deletions to finish sync_test.go:1022: Skip test with --checksum as no hashes supported --- PASS: TestSyncWithUpdateOlder (10.76s) === RUN TestSyncWithMaxDuration sync_test.go:1039: Skipping test on non local remote --- SKIP: TestSyncWithMaxDuration (0.00s) === RUN TestSyncWithTrackRenames run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4'", Local "Local file system at /tmp/rclone325973095", Modify Window "1ms" sync_test.go:1088: Can track renames: false 2021/07/25 05:29:00 ERROR : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Ignoring --track-renames as the source and destination do not have a common hash 2021/07/25 05:29:00 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for checks to finish 2021/07/25 05:29:00 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for transfers to finish 2021/07/25 05:29:01 DEBUG : yam: md5 = ed15b5334d9f7d854a85899d4f137989 OK 2021/07/25 05:29:01 INFO : yam: Copied (new) 2021/07/25 05:29:01 DEBUG : potato: md5 = 577869068e3684bedc0073b6aabd7960 OK 2021/07/25 05:29:01 INFO : potato: Copied (new) 2021/07/25 05:29:01 DEBUG : Waiting for deletions to finish 2021/07/25 05:29:02 ERROR : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Ignoring --track-renames as the source and destination do not have a common hash 2021/07/25 05:29:02 DEBUG : potato: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2021/07/25 05:29:02 DEBUG : potato: Unchanged skipping 2021/07/25 05:29:02 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for checks to finish 2021/07/25 05:29:02 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for transfers to finish 2021/07/25 05:29:03 DEBUG : yaml: md5 = 0f474f619207db2dba688d03d065b558 OK 2021/07/25 05:29:03 INFO : yaml: Copied (new) 2021/07/25 05:29:03 DEBUG : Waiting for deletions to finish 2021/07/25 05:29:04 INFO : yam: Deleted --- PASS: TestSyncWithTrackRenames (6.31s) === RUN TestParseRenamesStrategyModtime --- PASS: TestParseRenamesStrategyModtime (0.00s) === RUN TestRenamesStrategyModtime --- PASS: TestRenamesStrategyModtime (0.00s) === RUN TestSyncWithTrackRenamesStrategyModtime run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4'", Local "Local file system at /tmp/rclone325973095", Modify Window "1ms" sync_test.go:1157: Can track renames: true 2021/07/25 05:29:06 INFO : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Making map for --track-renames 2021/07/25 05:29:06 INFO : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Finished making map for --track-renames 2021/07/25 05:29:06 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for checks to finish 2021/07/25 05:29:06 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for renames to finish 2021/07/25 05:29:06 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for transfers to finish 2021/07/25 05:29:08 DEBUG : yam: md5 = 81c1c4fc882c91dc2c3ad09045404883 OK 2021/07/25 05:29:08 DEBUG : potato: md5 = 22e5676d21e815b2aa28b2b05e1ca0a2 OK 2021/07/25 05:29:08 INFO : yam: Copied (new) 2021/07/25 05:29:08 INFO : potato: Copied (new) 2021/07/25 05:29:08 DEBUG : Waiting for deletions to finish 2021/07/25 05:29:08 DEBUG : potato: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2021/07/25 05:29:08 DEBUG : potato: Unchanged skipping 2021/07/25 05:29:08 INFO : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Making map for --track-renames 2021/07/25 05:29:08 INFO : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Finished making map for --track-renames 2021/07/25 05:29:08 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for checks to finish 2021/07/25 05:29:08 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for renames to finish 2021/07/25 05:29:09 INFO : yam: Moved (server-side) to: yaml 2021/07/25 05:29:09 INFO : yaml: Renamed from "yam" 2021/07/25 05:29:09 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for transfers to finish 2021/07/25 05:29:09 DEBUG : Waiting for deletions to finish 2021/07/25 05:29:09 INFO : There was nothing to transfer --- PASS: TestSyncWithTrackRenamesStrategyModtime (4.88s) === RUN TestSyncWithTrackRenamesStrategyLeaf run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4'", Local "Local file system at /tmp/rclone325973095", Modify Window "1ms" sync_test.go:1193: Can track renames: true 2021/07/25 05:29:11 INFO : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Making map for --track-renames 2021/07/25 05:29:11 INFO : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Finished making map for --track-renames 2021/07/25 05:29:11 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for checks to finish 2021/07/25 05:29:11 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for renames to finish 2021/07/25 05:29:11 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for transfers to finish 2021/07/25 05:29:13 DEBUG : sub/yam: md5 = 798378ecda95d6e7b3b989021997b2a1 OK 2021/07/25 05:29:13 INFO : sub/yam: Copied (new) 2021/07/25 05:29:13 DEBUG : potato: md5 = 724c20d77c934e2365bed072ed898053 OK 2021/07/25 05:29:13 INFO : potato: Copied (new) 2021/07/25 05:29:13 DEBUG : Waiting for deletions to finish 2021/07/25 05:29:14 DEBUG : potato: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2021/07/25 05:29:14 DEBUG : potato: Unchanged skipping 2021/07/25 05:29:14 INFO : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Making map for --track-renames 2021/07/25 05:29:14 INFO : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Finished making map for --track-renames 2021/07/25 05:29:14 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for checks to finish 2021/07/25 05:29:14 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for renames to finish 2021/07/25 05:29:15 INFO : sub/yam: Moved (server-side) to: yam 2021/07/25 05:29:15 INFO : yam: Renamed from "sub/yam" 2021/07/25 05:29:15 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for transfers to finish 2021/07/25 05:29:15 DEBUG : Waiting for deletions to finish 2021/07/25 05:29:15 INFO : There was nothing to transfer --- PASS: TestSyncWithTrackRenamesStrategyLeaf (7.72s) === RUN TestMoveWithDeleteEmptySrcDirs run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4'", Local "Local file system at /tmp/rclone325973095", Modify Window "1ms" 2021/07/25 05:29:19 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for checks to finish 2021/07/25 05:29:19 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for transfers to finish 2021/07/25 05:29:21 DEBUG : sub dir/hello world: md5 = a8ec788e477dbb294d87cd9df45e5c8c OK 2021/07/25 05:29:21 INFO : sub dir/hello world: Copied (new) 2021/07/25 05:29:21 INFO : sub dir/hello world: Deleted 2021/07/25 05:29:23 DEBUG : nested/sub dir/file: md5 = a63412079f7a15dd8fcc34b3345d1d79 OK 2021/07/25 05:29:23 INFO : nested/sub dir/file: Copied (new) 2021/07/25 05:29:23 INFO : nested/sub dir/file: Deleted 2021/07/25 05:29:23 INFO : sub dir: Removing directory 2021/07/25 05:29:23 INFO : nested/sub dir: Removing directory 2021/07/25 05:29:23 INFO : nested: Removing directory 2021/07/25 05:29:23 DEBUG : Local file system at /tmp/rclone325973095: deleted 3 directories 2021/07/25 05:29:26 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" 2021/07/25 05:29:27 DEBUG : 37qp6d1gohacv723ij3brofbu8/14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "ftp4kuv8se7tqduu6pmmcvjsmk" 2021/07/25 05:29:28 DEBUG : 37qp6d1gohacv723ij3brofbu8: Rmdir: contains trashed file: "14begaa36ih249fgrnfk6nulg0" --- PASS: TestMoveWithDeleteEmptySrcDirs (10.30s) === RUN TestMoveWithoutDeleteEmptySrcDirs run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4'", Local "Local file system at /tmp/rclone325973095", Modify Window "1ms" 2021/07/25 05:29:29 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for checks to finish 2021/07/25 05:29:29 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for transfers to finish 2021/07/25 05:29:31 DEBUG : sub dir/hello world: md5 = 38d1a8565eeb6fb0483d361c211281e5 OK 2021/07/25 05:29:31 INFO : sub dir/hello world: Copied (new) 2021/07/25 05:29:31 INFO : sub dir/hello world: Deleted 2021/07/25 05:29:33 DEBUG : nested/sub dir/file: md5 = 35e00239223484ddd803f67676c060f0 OK 2021/07/25 05:29:33 INFO : nested/sub dir/file: Copied (new) 2021/07/25 05:29:33 INFO : nested/sub dir/file: Deleted 2021/07/25 05:29:36 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" 2021/07/25 05:29:37 DEBUG : 37qp6d1gohacv723ij3brofbu8/14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "ftp4kuv8se7tqduu6pmmcvjsmk" 2021/07/25 05:29:38 DEBUG : 37qp6d1gohacv723ij3brofbu8: Rmdir: contains trashed file: "14begaa36ih249fgrnfk6nulg0" --- PASS: TestMoveWithoutDeleteEmptySrcDirs (10.40s) === RUN TestServerSideMove run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4'", Local "Local file system at /tmp/rclone325973095", Modify Window "1ms" 2021/07/25 05:29:39 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-xiretiv4yavegiw5rolugib7" 2021/07/25 05:29:39 DEBUG : Config file has changed externaly - reloading 2021/07/25 05:29:39 DEBUG : Creating backend with remote "TestDrive:crypt/cudjk00on6j3ec0ehv7s3csv5ismitqpmjvap60akfo4lce8iknm37qtpo4t6o3hrtktmljr7suo8" 2021/07/25 05:29:42 DEBUG : potato2: md5 = 4b429543eb7a3b62e0858ff1f9d7e7aa OK 2021/07/25 05:29:43 DEBUG : empty space: md5 = 5581873d6c82e76c2a7ec3309e873c83 OK 2021/07/25 05:29:44 DEBUG : potato3: md5 = e3e14fadbb83fed01949fcdb93c64d51 OK sync_test.go:1245: Server side move (if possible) Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4' -> Encrypted drive 'TestCryptDrive:rclone-test-xiretiv4yavegiw5rolugib7' 2021/07/25 05:29:47 DEBUG : empty space: md5 = 1d1fc79cf50147ab9090cf5a186a2cc1 OK 2021/07/25 05:29:48 DEBUG : potato3: md5 = 1f1da5fe00c985251ecb1c728d0e10c0 OK 2021/07/25 05:29:48 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiretiv4yavegiw5rolugib7': Using server-side directory move 2021/07/25 05:29:48 INFO : Encrypted drive 'TestCryptDrive:rclone-test-xiretiv4yavegiw5rolugib7': Server side directory move failed - fallback to file moves: can't copy directory - destination already exists 2021/07/25 05:29:49 DEBUG : empty space: Size and modification time the same (differ by 0s, within tolerance 1ms) 2021/07/25 05:29:49 DEBUG : empty space: Unchanged skipping 2021/07/25 05:29:49 DEBUG : potato3: Sizes differ (src 68 vs dst 60) 2021/07/25 05:29:49 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiretiv4yavegiw5rolugib7': Waiting for checks to finish 2021/07/25 05:29:49 INFO : potato3: Deleted 2021/07/25 05:29:49 INFO : empty space: Deleted 2021/07/25 05:29:49 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiretiv4yavegiw5rolugib7': Waiting for transfers to finish 2021/07/25 05:29:49 INFO : potato2: Moved (server-side) 2021/07/25 05:29:50 INFO : potato3: Moved (server-side) 2021/07/25 05:29:50 INFO : There was nothing to transfer 2021/07/25 05:29:50 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-nurexiz3sonivix5zexovav6" 2021/07/25 05:29:51 DEBUG : Creating backend with remote "TestDrive:crypt/5h2qoses3qt7p40d8vk8pb3ts96uvllrrobg2h6ufkk6g1dbte1h77eu7j89fcp5c3t2cucek143a" 2021/07/25 05:29:52 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-nurexiz3sonivix5zexovav6': Using server-side directory move 2021/07/25 05:29:52 INFO : Encrypted drive 'TestCryptDrive:rclone-test-nurexiz3sonivix5zexovav6': Server side directory move succeeded 2021/07/25 05:29:53 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-nurexiz3sonivix5zexovav6': Purge remote 2021/07/25 05:29:54 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiretiv4yavegiw5rolugib7': Purge remote 2021/07/25 05:29:54 purge failed: directory not found --- PASS: TestServerSideMove (15.46s) === RUN TestServerSideMoveWithFilter run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4'", Local "Local file system at /tmp/rclone325973095", Modify Window "1ms" 2021/07/25 05:29:55 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-giqupoh2dosedag7bakazuz8" 2021/07/25 05:29:55 DEBUG : Creating backend with remote "TestDrive:crypt/9pk8cjm743bi0co3b80ghtjqm8h9lke2oq486k3n8jqfoo264eh7hjomdvht5avctkko8glhdkkn0" 2021/07/25 05:29:57 DEBUG : potato2: md5 = 7fc83f3a895723f7fc656cdaba960ac0 OK 2021/07/25 05:29:58 DEBUG : empty space: md5 = 09abf2dea8758a0c55b784e26e315e6e OK 2021/07/25 05:30:00 DEBUG : potato3: md5 = 7ef0457d8388d46e9b5437d60d6c2261 OK sync_test.go:1245: Server side move (if possible) Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4' -> Encrypted drive 'TestCryptDrive:rclone-test-giqupoh2dosedag7bakazuz8' 2021/07/25 05:30:02 DEBUG : empty space: md5 = a198e047296aec47e564555e9cf8d346 OK 2021/07/25 05:30:03 DEBUG : potato3: md5 = ede5877c7b72c416c3f3b29b9c2d407e OK 2021/07/25 05:30:04 DEBUG : empty space: Excluded from sync (and deletion) 2021/07/25 05:30:04 DEBUG : empty space: Excluded from sync (and deletion) 2021/07/25 05:30:04 DEBUG : potato3: Sizes differ (src 68 vs dst 60) 2021/07/25 05:30:04 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-giqupoh2dosedag7bakazuz8': Waiting for checks to finish 2021/07/25 05:30:04 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-giqupoh2dosedag7bakazuz8': Waiting for transfers to finish 2021/07/25 05:30:04 INFO : potato3: Deleted 2021/07/25 05:30:05 INFO : potato2: Moved (server-side) 2021/07/25 05:30:05 INFO : potato3: Moved (server-side) 2021/07/25 05:30:05 INFO : There was nothing to transfer 2021/07/25 05:30:06 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-nehoger7jihiwaf4lowasac1" 2021/07/25 05:30:06 DEBUG : Creating backend with remote "TestDrive:crypt/v3k6abt3tl5ih9gkl907km090t4eai1k0shausfqhf3690db47qe6u3o2eka2emvsckoshg94f730" 2021/07/25 05:30:07 DEBUG : empty space: Excluded from sync (and deletion) 2021/07/25 05:30:07 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-nehoger7jihiwaf4lowasac1': Waiting for checks to finish 2021/07/25 05:30:07 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-nehoger7jihiwaf4lowasac1': Waiting for transfers to finish 2021/07/25 05:30:09 INFO : potato3: Moved (server-side) 2021/07/25 05:30:09 INFO : potato2: Moved (server-side) 2021/07/25 05:30:09 INFO : There was nothing to transfer 2021/07/25 05:30:10 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-nehoger7jihiwaf4lowasac1': Purge remote 2021/07/25 05:30:10 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-giqupoh2dosedag7bakazuz8': Purge remote --- PASS: TestServerSideMoveWithFilter (17.49s) === RUN TestServerSideMoveDeleteEmptySourceDirs run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4'", Local "Local file system at /tmp/rclone325973095", Modify Window "1ms" 2021/07/25 05:30:12 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-hitutin1vubaqup3gedabom2" 2021/07/25 05:30:12 DEBUG : Creating backend with remote "TestDrive:crypt/97lreuocdvut818e3ig4ttqqlarphnc9kt8860v6s873ie6sf39rcr6lkhh0rhtph0an13u53iilg" 2021/07/25 05:30:14 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) 2021/07/25 05:30:14 DEBUG : pacer: Rate limited, increasing sleep to 1.069874934s run.go:278: Retry Put of "potato2" to Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': 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) 2021/07/25 05:30:16 DEBUG : pacer: Reducing sleep to 0s 2021/07/25 05:30:18 DEBUG : potato2: md5 = 22bc72ee85da190e306e87fc16b489f7 OK 2021/07/25 05:30:19 DEBUG : empty space: md5 = 3b2bfbd9bae1abb9411f2676d1881ae3 OK 2021/07/25 05:30:20 DEBUG : potato3: md5 = 8de31648c3030d048b79357546ca1e51 OK 2021/07/25 05:30:20 DEBUG : tomatoDir: Making directory sync_test.go:1245: Server side move (if possible) Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4' -> Encrypted drive 'TestCryptDrive:rclone-test-hitutin1vubaqup3gedabom2' 2021/07/25 05:30:24 DEBUG : empty space: md5 = 58e5d24d0cee8a29dcf6abce61feb346 OK 2021/07/25 05:30:25 DEBUG : potato3: md5 = 4e2da772782bc1800b56626adce51ee5 OK 2021/07/25 05:30:25 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-hitutin1vubaqup3gedabom2': Using server-side directory move 2021/07/25 05:30:25 INFO : Encrypted drive 'TestCryptDrive:rclone-test-hitutin1vubaqup3gedabom2': Server side directory move failed - fallback to file moves: can't copy directory - destination already exists 2021/07/25 05:30:26 DEBUG : empty space: Size and modification time the same (differ by 0s, within tolerance 1ms) 2021/07/25 05:30:26 DEBUG : empty space: Unchanged skipping 2021/07/25 05:30:26 DEBUG : potato3: Sizes differ (src 68 vs dst 60) 2021/07/25 05:30:26 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-hitutin1vubaqup3gedabom2': Waiting for checks to finish 2021/07/25 05:30:26 INFO : empty space: Deleted 2021/07/25 05:30:26 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-hitutin1vubaqup3gedabom2': Waiting for transfers to finish 2021/07/25 05:30:26 INFO : potato3: Deleted 2021/07/25 05:30:27 INFO : potato2: Moved (server-side) 2021/07/25 05:30:27 INFO : potato3: Moved (server-side) 2021/07/25 05:30:27 INFO : tomatoDir: Removing directory 2021/07/25 05:30:28 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': deleted 1 directories 2021/07/25 05:30:28 INFO : There was nothing to transfer 2021/07/25 05:30:29 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-vuteyed3beduyin1fusakiw1" 2021/07/25 05:30:29 DEBUG : Creating backend with remote "TestDrive:crypt/u10b01fpp074rrdruccp2leok04gsss65thb5t3tie76hb3u2617oki9av3js5ibmk2h4dlsopts4" 2021/07/25 05:30:30 DEBUG : tomatoDir: Making directory 2021/07/25 05:30:31 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuteyed3beduyin1fusakiw1': Using server-side directory move 2021/07/25 05:30:32 INFO : Encrypted drive 'TestCryptDrive:rclone-test-vuteyed3beduyin1fusakiw1': Server side directory move succeeded 2021/07/25 05:30: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) 2021/07/25 05:30:33 DEBUG : pacer: Rate limited, increasing sleep to 1.016149364s 2021/07/25 05:30: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) 2021/07/25 05:30:33 DEBUG : pacer: Rate limited, increasing sleep to 2.12934478s 2021/07/25 05:30:34 DEBUG : pacer: Reducing sleep to 0s 2021/07/25 05:30:36 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuteyed3beduyin1fusakiw1': Purge remote 2021/07/25 05:30:37 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-hitutin1vubaqup3gedabom2': Purge remote 2021/07/25 05:30:37 purge failed: directory not found --- PASS: TestServerSideMoveDeleteEmptySourceDirs (25.16s) === RUN TestServerSideMoveOverlap run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4'", Local "Local file system at /tmp/rclone325973095", Modify Window "1ms" sync_test.go:1382: Skipping test as remote supports DirMove --- SKIP: TestServerSideMoveOverlap (0.44s) === RUN TestSyncOverlap run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4'", Local "Local file system at /tmp/rclone325973095", Modify Window "1ms" 2021/07/25 05:30:38 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4/rclone-sync-test" 2021/07/25 05:30:38 DEBUG : Creating backend with remote "TestDrive:crypt/3hcvr7rq3rr7dr8blvrfl2v9cg27o41psq1vr6v1p1kpca4b09gms2acl7kbj4gi8k00uq0gs7fb6/i7355aa0sb89uagn75vfjqr6s3e3e1h2et8in57abn1fe8qfego0" --- PASS: TestSyncOverlap (2.15s) === RUN TestSyncCompareDest run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4'", Local "Local file system at /tmp/rclone325973095", Modify Window "1ms" 2021/07/25 05:30:40 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4/dst" 2021/07/25 05:30:40 DEBUG : Creating backend with remote "TestDrive:crypt/3hcvr7rq3rr7dr8blvrfl2v9cg27o41psq1vr6v1p1kpca4b09gms2acl7kbj4gi8k00uq0gs7fb6/31u3jie661vd5p8j7rtc3hgbh0" 2021/07/25 05:30:41 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4/CompareDest" 2021/07/25 05:30:42 DEBUG : Creating backend with remote "TestDrive:crypt/3hcvr7rq3rr7dr8blvrfl2v9cg27o41psq1vr6v1p1kpca4b09gms2acl7kbj4gi8k00uq0gs7fb6/gveqi14airsml4bgu7krj116o8" 2021/07/25 05:30:43 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2021/07/25 05:30:43 DEBUG : pacer: Rate limited, increasing sleep to 1.904491375s 2021/07/25 05:30:43 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2021/07/25 05:30:43 DEBUG : pacer: Rate limited, increasing sleep to 2.711375878s 2021/07/25 05:30:45 DEBUG : pacer: Reducing sleep to 0s 2021/07/25 05:30:48 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4/dst': Waiting for checks to finish 2021/07/25 05:30:48 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4/dst': Waiting for transfers to finish 2021/07/25 05:30:50 DEBUG : one: md5 = 5b43902914af87a2364ca4e0cf557ab4 OK 2021/07/25 05:30:50 INFO : one: Copied (new) 2021/07/25 05:30:50 DEBUG : Waiting for deletions to finish 2021/07/25 05:30:51 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4/dst': Waiting for checks to finish 2021/07/25 05:30:51 DEBUG : one: Sizes differ (src 5 vs dst 3) 2021/07/25 05:30:51 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4/dst': Waiting for transfers to finish 2021/07/25 05:30:52 DEBUG : one: md5 = c80505054ae45338ffe711603376d982 OK 2021/07/25 05:30:52 INFO : one: Copied (replaced existing) 2021/07/25 05:30:52 DEBUG : Waiting for deletions to finish 2021/07/25 05:30:54 DEBUG : dst/one: md5 = b091d9abfcc346918efe826a73014e09 OK 2021/07/25 05:30:56 DEBUG : CompareDest/one: md5 = 4d2d778acf374f03075b621b91d6c246 OK 2021/07/25 05:30:57 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4/dst': Waiting for checks to finish 2021/07/25 05:30:58 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2021/07/25 05:30:58 DEBUG : one: Destination found in --compare-dest, skipping 2021/07/25 05:30:58 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4/dst': Waiting for transfers to finish 2021/07/25 05:30:58 DEBUG : Waiting for deletions to finish 2021/07/25 05:30:58 INFO : There was nothing to transfer 2021/07/25 05:30:59 DEBUG : CompareDest/two: md5 = 32a4d0bedf341ce8a43407a323e7e653 OK 2021/07/25 05:31:00 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2021/07/25 05:31:00 DEBUG : two: Destination found in --compare-dest, skipping 2021/07/25 05:31:00 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4/dst': Waiting for checks to finish 2021/07/25 05:31:00 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2021/07/25 05:31:00 DEBUG : one: Destination found in --compare-dest, skipping 2021/07/25 05:31:00 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4/dst': Waiting for transfers to finish 2021/07/25 05:31:00 DEBUG : Waiting for deletions to finish 2021/07/25 05:31:00 INFO : There was nothing to transfer 2021/07/25 05:31:01 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2021/07/25 05:31:01 DEBUG : two: Destination found in --compare-dest, skipping 2021/07/25 05:31:01 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4/dst': Waiting for checks to finish 2021/07/25 05:31:02 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2021/07/25 05:31:02 DEBUG : one: Destination found in --compare-dest, skipping 2021/07/25 05:31:02 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4/dst': Waiting for transfers to finish 2021/07/25 05:31:02 DEBUG : Waiting for deletions to finish 2021/07/25 05:31:02 INFO : There was nothing to transfer sync_test.go:1526: No hash on uploaded file so skipping compare timestamp test 2021/07/25 05:31:03 DEBUG : two: Sizes differ (src 5 vs dst 3) 2021/07/25 05:31:03 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4/dst': Waiting for checks to finish 2021/07/25 05:31:03 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2021/07/25 05:31:03 DEBUG : one: Destination found in --compare-dest, skipping 2021/07/25 05:31:03 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4/dst': Waiting for transfers to finish 2021/07/25 05:31:04 DEBUG : two: md5 = 99bcee8e8c5ce0e73828035d36bc2d1b OK 2021/07/25 05:31:04 INFO : two: Copied (new) 2021/07/25 05:31:04 DEBUG : Waiting for deletions to finish 2021/07/25 05:31:08 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" 2021/07/25 05:31:08 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2021/07/25 05:31:09 DEBUG : gveqi14airsml4bgu7krj116o8: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2021/07/25 05:31:09 DEBUG : gveqi14airsml4bgu7krj116o8: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" --- PASS: TestSyncCompareDest (30.01s) === RUN TestSyncMultipleCompareDest run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4'", Local "Local file system at /tmp/rclone325973095", Modify Window "1ms" 2021/07/25 05:31:12 DEBUG : pre-dest1/1: md5 = 752c047660826744e355012319a11dd8 OK 2021/07/25 05:31:14 DEBUG : pre-dest2/2: md5 = 155a78f7192450bff124ff14003316c8 OK 2021/07/25 05:31:15 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4/dest" 2021/07/25 05:31:15 DEBUG : Creating backend with remote "TestDrive:crypt/3hcvr7rq3rr7dr8blvrfl2v9cg27o41psq1vr6v1p1kpca4b09gms2acl7kbj4gi8k00uq0gs7fb6/rg03c1jvnehrrc617i0lnqjddc" 2021/07/25 05:31:17 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4/pre-dest1" 2021/07/25 05:31:17 DEBUG : Creating backend with remote "TestDrive:crypt/3hcvr7rq3rr7dr8blvrfl2v9cg27o41psq1vr6v1p1kpca4b09gms2acl7kbj4gi8k00uq0gs7fb6/bbnblvh6k061ssopqrp18kd7gc" 2021/07/25 05:31:18 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4/pre-dest2" 2021/07/25 05:31:18 DEBUG : Creating backend with remote "TestDrive:crypt/3hcvr7rq3rr7dr8blvrfl2v9cg27o41psq1vr6v1p1kpca4b09gms2acl7kbj4gi8k00uq0gs7fb6/dgicm1h6b5ejvlltm8eeif0bnk" 2021/07/25 05:31:19 DEBUG : 1: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2021/07/25 05:31:19 DEBUG : 1: Destination found in --compare-dest, skipping 2021/07/25 05:31:19 DEBUG : 2: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2021/07/25 05:31:19 DEBUG : 2: Destination found in --compare-dest, skipping 2021/07/25 05:31:20 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4/dest': Waiting for checks to finish 2021/07/25 05:31:20 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4/dest': Waiting for transfers to finish 2021/07/25 05:31:22 DEBUG : 3: md5 = 13d508b12c119bf4fb90e4b5ba6efedd OK 2021/07/25 05:31:22 INFO : 3: Copied (new) 2021/07/25 05:31:22 DEBUG : Waiting for deletions to finish 2021/07/25 05:31:26 DEBUG : dgicm1h6b5ejvlltm8eeif0bnk: Rmdir: contains trashed file: "1ghu8geql9vrl726n32nrf65bc" 2021/07/25 05:31:26 DEBUG : bbnblvh6k061ssopqrp18kd7gc: Rmdir: contains trashed file: "skbfko3oil7es0lj68ob574sro" 2021/07/25 05:31:27 DEBUG : rg03c1jvnehrrc617i0lnqjddc: Rmdir: contains trashed file: "g072p7hmjchlnj0gibe64c1epg" --- PASS: TestSyncMultipleCompareDest (18.52s) === RUN TestSyncCopyDest run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4'", Local "Local file system at /tmp/rclone325973095", Modify Window "1ms" 2021/07/25 05:31:28 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4/dst" 2021/07/25 05:31:28 DEBUG : Creating backend with remote "TestDrive:crypt/3hcvr7rq3rr7dr8blvrfl2v9cg27o41psq1vr6v1p1kpca4b09gms2acl7kbj4gi8k00uq0gs7fb6/31u3jie661vd5p8j7rtc3hgbh0" 2021/07/25 05:31:30 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4/CopyDest" 2021/07/25 05:31:30 DEBUG : Creating backend with remote "TestDrive:crypt/3hcvr7rq3rr7dr8blvrfl2v9cg27o41psq1vr6v1p1kpca4b09gms2acl7kbj4gi8k00uq0gs7fb6/d09o6po3f7bm6ce32vdgs8h9ls" 2021/07/25 05:31:32 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4/dst': Waiting for checks to finish 2021/07/25 05:31:32 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4/dst': Waiting for transfers to finish 2021/07/25 05:31:34 DEBUG : one: md5 = 1a18b77684a9d381bd760011ff2960f4 OK 2021/07/25 05:31:34 INFO : one: Copied (new) 2021/07/25 05:31:34 DEBUG : Waiting for deletions to finish 2021/07/25 05:31:35 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4/dst': Waiting for checks to finish 2021/07/25 05:31:36 DEBUG : one: Sizes differ (src 5 vs dst 3) 2021/07/25 05:31:36 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4/dst': Waiting for transfers to finish 2021/07/25 05:31:37 DEBUG : one: md5 = 5e030aab714284e72f2b9b5106cdea13 OK 2021/07/25 05:31:37 INFO : one: Copied (replaced existing) 2021/07/25 05:31:37 DEBUG : Waiting for deletions to finish 2021/07/25 05:31:38 DEBUG : dst/one: md5 = 0b52891c4933420c5f3d229f89e5476e OK 2021/07/25 05:31:41 DEBUG : CopyDest/one: md5 = 9e29f4b3ac91700e3de6e4888b8f653a OK 2021/07/25 05:31:41 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4/BackupDir" 2021/07/25 05:31:42 DEBUG : Creating backend with remote "TestDrive:crypt/3hcvr7rq3rr7dr8blvrfl2v9cg27o41psq1vr6v1p1kpca4b09gms2acl7kbj4gi8k00uq0gs7fb6/s6dbk3lfi7c9kfvo6j7bla9m0g" 2021/07/25 05:31:43 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4/dst': Waiting for checks to finish 2021/07/25 05:31:44 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2021/07/25 05:31:44 DEBUG : one: Sizes differ (src 5 vs dst 3) 2021/07/25 05:31:46 INFO : one: Moved (server-side) 2021/07/25 05:31:47 INFO : one: Copied (server-side copy) 2021/07/25 05:31:47 DEBUG : one: Destination found in --copy-dest, using server-side copy 2021/07/25 05:31:47 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4/dst': Waiting for transfers to finish 2021/07/25 05:31:47 DEBUG : Waiting for deletions to finish 2021/07/25 05:31:49 DEBUG : CopyDest/two: md5 = 68d4a10ccb3bac1da7c7b402ff0c1bfd OK 2021/07/25 05:31:50 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2021/07/25 05:31:51 INFO : two: Copied (server-side copy) 2021/07/25 05:31:51 DEBUG : two: Destination found in --copy-dest, using server-side copy 2021/07/25 05:31:51 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4/dst': Waiting for checks to finish 2021/07/25 05:31:52 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2021/07/25 05:31:52 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2021/07/25 05:31:52 DEBUG : one: Unchanged skipping 2021/07/25 05:31:52 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4/dst': Waiting for transfers to finish 2021/07/25 05:31:52 DEBUG : Waiting for deletions to finish 2021/07/25 05:31:52 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4/dst': Waiting for checks to finish 2021/07/25 05:31:53 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2021/07/25 05:31:53 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2021/07/25 05:31:53 DEBUG : one: Unchanged skipping 2021/07/25 05:31:53 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2021/07/25 05:31:53 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2021/07/25 05:31:53 DEBUG : two: Unchanged skipping 2021/07/25 05:31:53 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4/dst': Waiting for transfers to finish 2021/07/25 05:31:53 DEBUG : Waiting for deletions to finish 2021/07/25 05:31:53 INFO : There was nothing to transfer 2021/07/25 05:31: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) 2021/07/25 05:31:53 DEBUG : pacer: Rate limited, increasing sleep to 1.042759967s 2021/07/25 05:31:53 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2021/07/25 05:31:53 DEBUG : pacer: Rate limited, increasing sleep to 2.862777602s 2021/07/25 05:31:55 DEBUG : pacer: Reducing sleep to 0s 2021/07/25 05:31:58 DEBUG : CopyDest/three: md5 = 1d5a4f5f8c9154f9349a5b9031f7a468 OK 2021/07/25 05:31:59 DEBUG : three: Sizes differ (src 7 vs dst 5) 2021/07/25 05:31:59 DEBUG : three: Destination not found in --copy-dest 2021/07/25 05:31:59 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4/dst': Waiting for checks to finish 2021/07/25 05:31:59 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2021/07/25 05:31:59 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2021/07/25 05:31:59 DEBUG : one: Unchanged skipping 2021/07/25 05:31:59 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2021/07/25 05:31:59 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2021/07/25 05:31:59 DEBUG : two: Unchanged skipping 2021/07/25 05:31:59 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4/dst': Waiting for transfers to finish 2021/07/25 05:32:00 DEBUG : three: md5 = a83dbe45f86df11b01749261f5e42ba1 OK 2021/07/25 05:32:00 INFO : three: Copied (new) 2021/07/25 05:32:00 DEBUG : Waiting for deletions to finish 2021/07/25 05:32:06 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "b6jdmn2b1adrhc8vikh7edr9os" 2021/07/25 05:32:06 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" 2021/07/25 05:32:06 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2021/07/25 05:32:07 DEBUG : d09o6po3f7bm6ce32vdgs8h9ls: Rmdir: contains trashed file: "b6jdmn2b1adrhc8vikh7edr9os" 2021/07/25 05:32:07 DEBUG : d09o6po3f7bm6ce32vdgs8h9ls: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2021/07/25 05:32:07 DEBUG : d09o6po3f7bm6ce32vdgs8h9ls: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" 2021/07/25 05:32:08 DEBUG : s6dbk3lfi7c9kfvo6j7bla9m0g: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" --- PASS: TestSyncCopyDest (40.29s) === RUN TestSyncBackupDir run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4'", Local "Local file system at /tmp/rclone325973095", Modify Window "1ms" 2021/07/25 05:32:11 DEBUG : dst/one: md5 = 0421b4b6148eb9a794db55972cfe925e OK 2021/07/25 05:32:12 DEBUG : dst/two: md5 = 43f7b183fb2c1f210ea7c8318fe0e83c OK 2021/07/25 05:32:13 DEBUG : dst/three.txt: md5 = adf30a61a13483a7414b0e266eec772d OK 2021/07/25 05:32:14 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4/dst" 2021/07/25 05:32:14 DEBUG : Creating backend with remote "TestDrive:crypt/3hcvr7rq3rr7dr8blvrfl2v9cg27o41psq1vr6v1p1kpca4b09gms2acl7kbj4gi8k00uq0gs7fb6/31u3jie661vd5p8j7rtc3hgbh0" 2021/07/25 05:32:15 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4/backup" 2021/07/25 05:32:15 DEBUG : Creating backend with remote "TestDrive:crypt/3hcvr7rq3rr7dr8blvrfl2v9cg27o41psq1vr6v1p1kpca4b09gms2acl7kbj4gi8k00uq0gs7fb6/1nrff024r7pq65ecp72fc28jb0" 2021/07/25 05:32:18 DEBUG : one: Sizes differ (src 4 vs dst 3) 2021/07/25 05:32:18 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2021/07/25 05:32:18 DEBUG : two: Unchanged skipping 2021/07/25 05:32:18 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4/dst': Waiting for checks to finish 2021/07/25 05:32:20 INFO : one: Moved (server-side) 2021/07/25 05:32:20 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4/dst': Waiting for transfers to finish 2021/07/25 05:32:21 DEBUG : one: md5 = 6ccdf0ce86cf408cc8756307eb6fd798 OK 2021/07/25 05:32:21 INFO : one: Copied (new) 2021/07/25 05:32:21 DEBUG : Waiting for deletions to finish 2021/07/25 05:32:23 INFO : three.txt: Moved (server-side) 2021/07/25 05:32:23 INFO : three.txt: Moved into backup dir 2021/07/25 05:32:25 DEBUG : dst/three.txt: md5 = 474d2f8e27639562104af3d9dd726e26 OK 2021/07/25 05:32:25 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4/dst': Waiting for checks to finish 2021/07/25 05:32:25 DEBUG : one: Sizes differ (src 5 vs dst 4) 2021/07/25 05:32:25 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2021/07/25 05:32:25 DEBUG : two: Unchanged skipping 2021/07/25 05:32:26 INFO : one: Deleted 2021/07/25 05:32:27 INFO : one: Moved (server-side) 2021/07/25 05:32:27 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4/dst': Waiting for transfers to finish 2021/07/25 05:32:28 DEBUG : one: md5 = eb1c38f64381860aecae6e32862f23bf OK 2021/07/25 05:32:28 INFO : one: Copied (new) 2021/07/25 05:32:28 DEBUG : Waiting for deletions to finish 2021/07/25 05:32:29 INFO : three.txt: Deleted 2021/07/25 05:32:30 INFO : three.txt: Moved (server-side) 2021/07/25 05:32:30 INFO : three.txt: Moved into backup dir 2021/07/25 05:32:34 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2021/07/25 05:32:34 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" 2021/07/25 05:32:35 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "tr2hj63d80ftlmvm6a952snjcc" 2021/07/25 05:32:35 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2021/07/25 05:32:35 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "tr2hj63d80ftlmvm6a952snjcc" 2021/07/25 05:32:35 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" --- PASS: TestSyncBackupDir (26.94s) === RUN TestSyncBackupDirWithSuffix run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4'", Local "Local file system at /tmp/rclone325973095", Modify Window "1ms" 2021/07/25 05:32:38 DEBUG : dst/one: md5 = 3884e98dea24e03ae6758fd80d9226c3 OK 2021/07/25 05:32:39 DEBUG : dst/two: md5 = 6ada5c9220593c20bc547fed1fc54b08 OK 2021/07/25 05:32:40 DEBUG : dst/three.txt: md5 = 5e6ded96afc1a0593dcaa47332564747 OK 2021/07/25 05:32:41 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4/dst" 2021/07/25 05:32:41 DEBUG : Creating backend with remote "TestDrive:crypt/3hcvr7rq3rr7dr8blvrfl2v9cg27o41psq1vr6v1p1kpca4b09gms2acl7kbj4gi8k00uq0gs7fb6/31u3jie661vd5p8j7rtc3hgbh0" 2021/07/25 05:32:42 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4/backup" 2021/07/25 05:32:42 DEBUG : Creating backend with remote "TestDrive:crypt/3hcvr7rq3rr7dr8blvrfl2v9cg27o41psq1vr6v1p1kpca4b09gms2acl7kbj4gi8k00uq0gs7fb6/1nrff024r7pq65ecp72fc28jb0" 2021/07/25 05:32:42 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2021/07/25 05:32:42 DEBUG : pacer: Rate limited, increasing sleep to 1.973290539s 2021/07/25 05:32:43 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2021/07/25 05:32:43 DEBUG : pacer: Rate limited, increasing sleep to 2.790870755s 2021/07/25 05:32:45 DEBUG : pacer: Reducing sleep to 0s 2021/07/25 05:32:47 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2021/07/25 05:32:47 DEBUG : pacer: Rate limited, increasing sleep to 1.164224936s 2021/07/25 05:32:47 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2021/07/25 05:32:47 DEBUG : pacer: Rate limited, increasing sleep to 2.476016608s 2021/07/25 05:32:49 DEBUG : pacer: Reducing sleep to 0s 2021/07/25 05:32:52 DEBUG : one: Sizes differ (src 4 vs dst 3) 2021/07/25 05:32:52 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2021/07/25 05:32:52 DEBUG : two: Unchanged skipping 2021/07/25 05:32:52 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4/dst': Waiting for checks to finish 2021/07/25 05:32:54 INFO : one: Moved (server-side) to: one.bak 2021/07/25 05:32:54 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4/dst': Waiting for transfers to finish 2021/07/25 05:32:55 DEBUG : one: md5 = ce0ca7d4d83ffa13d7fc1a65713898c6 OK 2021/07/25 05:32:55 INFO : one: Copied (new) 2021/07/25 05:32:55 DEBUG : Waiting for deletions to finish 2021/07/25 05:32:56 INFO : three.txt: Moved (server-side) to: three.txt.bak 2021/07/25 05:32:56 INFO : three.txt: Moved into backup dir 2021/07/25 05:32:58 DEBUG : dst/three.txt: md5 = 19cd79ce11ba49ebb398e87ff875046f OK 2021/07/25 05:32:59 DEBUG : one: Sizes differ (src 5 vs dst 4) 2021/07/25 05:32:59 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4/dst': Waiting for checks to finish 2021/07/25 05:32:59 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2021/07/25 05:32:59 DEBUG : two: Unchanged skipping 2021/07/25 05:33:00 INFO : one.bak: Deleted 2021/07/25 05:33:00 INFO : one: Moved (server-side) to: one.bak 2021/07/25 05:33:00 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4/dst': Waiting for transfers to finish 2021/07/25 05:33:02 DEBUG : one: md5 = 1252b0c46df8f935064e30fc7d54258f OK 2021/07/25 05:33:02 INFO : one: Copied (new) 2021/07/25 05:33:02 DEBUG : Waiting for deletions to finish 2021/07/25 05:33:03 INFO : three.txt.bak: Deleted 2021/07/25 05:33: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) 2021/07/25 05:33:03 DEBUG : pacer: Rate limited, increasing sleep to 1.791277295s 2021/07/25 05:33:03 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2021/07/25 05:33:03 DEBUG : pacer: Rate limited, increasing sleep to 2.406610636s 2021/07/25 05:33:06 DEBUG : pacer: Reducing sleep to 0s 2021/07/25 05:33:06 INFO : three.txt: Moved (server-side) to: three.txt.bak 2021/07/25 05:33:06 INFO : three.txt: Moved into backup dir 2021/07/25 05:33:09 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2021/07/25 05:33:09 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" 2021/07/25 05:33:10 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "qltcak2uaegtmcoa8vijdppbp8" 2021/07/25 05:33:10 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "sk91qgsqfn0r271r2ehsaoc20c" 2021/07/25 05:33:10 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "sk91qgsqfn0r271r2ehsaoc20c" 2021/07/25 05:33:10 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "qltcak2uaegtmcoa8vijdppbp8" --- PASS: TestSyncBackupDirWithSuffix (35.33s) === RUN TestSyncBackupDirWithSuffixKeepExtension run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4'", Local "Local file system at /tmp/rclone325973095", Modify Window "1ms" 2021/07/25 05:33:13 DEBUG : dst/one: md5 = 3567b714b956709fdeba567c86200c3f OK 2021/07/25 05:33: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) 2021/07/25 05:33:14 DEBUG : pacer: Rate limited, increasing sleep to 1.737526566s 2021/07/25 05:33:14 DEBUG : pacer: Reducing sleep to 0s 2021/07/25 05:33:16 DEBUG : dst/two: md5 = d86ae64d9abffc50b93982462175ab82 OK 2021/07/25 05:33:18 DEBUG : dst/three.txt: md5 = 8c7619e9c9a754d8b6fa8582f8cd951e OK 2021/07/25 05:33:18 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4/dst" 2021/07/25 05:33:18 DEBUG : Creating backend with remote "TestDrive:crypt/3hcvr7rq3rr7dr8blvrfl2v9cg27o41psq1vr6v1p1kpca4b09gms2acl7kbj4gi8k00uq0gs7fb6/31u3jie661vd5p8j7rtc3hgbh0" 2021/07/25 05:33:19 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4/backup" 2021/07/25 05:33:19 DEBUG : Creating backend with remote "TestDrive:crypt/3hcvr7rq3rr7dr8blvrfl2v9cg27o41psq1vr6v1p1kpca4b09gms2acl7kbj4gi8k00uq0gs7fb6/1nrff024r7pq65ecp72fc28jb0" 2021/07/25 05:33: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) 2021/07/25 05:33:20 DEBUG : pacer: Rate limited, increasing sleep to 1.024455783s 2021/07/25 05:33:20 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2021/07/25 05:33:20 DEBUG : pacer: Rate limited, increasing sleep to 2.445848052s 2021/07/25 05:33:21 DEBUG : pacer: Reducing sleep to 0s 2021/07/25 05:33:22 DEBUG : one: Sizes differ (src 4 vs dst 3) 2021/07/25 05:33:22 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2021/07/25 05:33:22 DEBUG : two: Unchanged skipping 2021/07/25 05:33:22 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4/dst': Waiting for checks to finish 2021/07/25 05:33:26 INFO : one: Moved (server-side) to: one-2019-01-01 2021/07/25 05:33:26 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4/dst': Waiting for transfers to finish 2021/07/25 05:33:27 DEBUG : one: md5 = aad03d961cd0fd088822e10e00ae82d5 OK 2021/07/25 05:33:27 INFO : one: Copied (new) 2021/07/25 05:33:27 DEBUG : Waiting for deletions to finish 2021/07/25 05:33:28 INFO : three.txt: Moved (server-side) to: three-2019-01-01.txt 2021/07/25 05:33:28 INFO : three.txt: Moved into backup dir 2021/07/25 05:33:30 DEBUG : dst/three.txt: md5 = e6ce799e0d280c3c17cc07d963dc12e4 OK 2021/07/25 05:33:31 DEBUG : one: Sizes differ (src 5 vs dst 4) 2021/07/25 05:33:31 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2021/07/25 05:33:31 DEBUG : two: Unchanged skipping 2021/07/25 05:33:31 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4/dst': Waiting for checks to finish 2021/07/25 05:33:32 INFO : one-2019-01-01: Deleted 2021/07/25 05:33:33 INFO : one: Moved (server-side) to: one-2019-01-01 2021/07/25 05:33:33 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4/dst': Waiting for transfers to finish 2021/07/25 05:33: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) 2021/07/25 05:33:33 DEBUG : pacer: Rate limited, increasing sleep to 1.606033819s 2021/07/25 05:33: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) 2021/07/25 05:33:33 DEBUG : pacer: Rate limited, increasing sleep to 2.550826s 2021/07/25 05:33:34 DEBUG : pacer: Reducing sleep to 0s 2021/07/25 05:33:38 DEBUG : one: md5 = 0b394c109eb58662877b3fe7f8248646 OK 2021/07/25 05:33:38 INFO : one: Copied (new) 2021/07/25 05:33:38 DEBUG : Waiting for deletions to finish 2021/07/25 05:33:39 INFO : three-2019-01-01.txt: Deleted 2021/07/25 05:33:40 INFO : three.txt: Moved (server-side) to: three-2019-01-01.txt 2021/07/25 05:33:40 INFO : three.txt: Moved into backup dir 2021/07/25 05:33:43 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2021/07/25 05:33:43 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" 2021/07/25 05:33:44 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "qtq2f6qq4lgpsmj88vb7147qje3prudmtfdtr2342fth58vo9a50" 2021/07/25 05:33:44 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "jcjl1bv3ep0v8kt35lqql1co90" 2021/07/25 05:33:44 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "qtq2f6qq4lgpsmj88vb7147qje3prudmtfdtr2342fth58vo9a50" 2021/07/25 05:33:44 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "jcjl1bv3ep0v8kt35lqql1co90" --- PASS: TestSyncBackupDirWithSuffixKeepExtension (34.09s) === RUN TestSyncBackupDirSuffixOnly run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4'", Local "Local file system at /tmp/rclone325973095", Modify Window "1ms" 2021/07/25 05:33:47 DEBUG : dst/one: md5 = 59ac597aa7375fa00b2e99a9ca4babdc OK 2021/07/25 05:33:48 DEBUG : dst/two: md5 = 35dfd618be9b67f955ac15b39c69fc41 OK 2021/07/25 05:33:50 DEBUG : dst/three.txt: md5 = 7402e9c7d921afb2ea4d1fb2950105b0 OK 2021/07/25 05:33:50 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4/dst" 2021/07/25 05:33:50 DEBUG : Creating backend with remote "TestDrive:crypt/3hcvr7rq3rr7dr8blvrfl2v9cg27o41psq1vr6v1p1kpca4b09gms2acl7kbj4gi8k00uq0gs7fb6/31u3jie661vd5p8j7rtc3hgbh0" 2021/07/25 05:33:51 DEBUG : one: Sizes differ (src 4 vs dst 3) 2021/07/25 05:33:51 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2021/07/25 05:33:51 DEBUG : two: Unchanged skipping 2021/07/25 05:33:51 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4/dst': Waiting for checks to finish 2021/07/25 05:33:52 INFO : one: Moved (server-side) to: one.bak 2021/07/25 05:33:52 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4/dst': Waiting for transfers to finish 2021/07/25 05:33:52 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2021/07/25 05:33:52 DEBUG : pacer: Rate limited, increasing sleep to 1.060000083s 2021/07/25 05:33:52 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2021/07/25 05:33:52 DEBUG : pacer: Rate limited, increasing sleep to 2.36795342s 2021/07/25 05:33:53 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) 2021/07/25 05:33:53 DEBUG : pacer: Rate limited, increasing sleep to 4.254660259s 2021/07/25 05:33:56 DEBUG : pacer: Reducing sleep to 0s 2021/07/25 05:34:01 DEBUG : one: md5 = 6a50dad19eeb8be0340aba46e356dcd5 OK 2021/07/25 05:34:01 INFO : one: Copied (new) 2021/07/25 05:34:01 DEBUG : Waiting for deletions to finish 2021/07/25 05:34:02 INFO : three.txt: Moved (server-side) to: three.txt.bak 2021/07/25 05:34:02 INFO : three.txt: Moved into backup dir 2021/07/25 05:34:04 DEBUG : dst/three.txt: md5 = c6c870e6034d183d60d90a2f3456e023 OK 2021/07/25 05:34:04 DEBUG : three.txt.bak: Excluded from sync (and deletion) 2021/07/25 05:34:04 DEBUG : one.bak: Excluded from sync (and deletion) 2021/07/25 05:34:04 DEBUG : one: Sizes differ (src 5 vs dst 4) 2021/07/25 05:34:04 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2021/07/25 05:34:04 DEBUG : two: Unchanged skipping 2021/07/25 05:34:04 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4/dst': Waiting for checks to finish 2021/07/25 05:34:05 INFO : one.bak: Deleted 2021/07/25 05:34:06 INFO : one: Moved (server-side) to: one.bak 2021/07/25 05:34:06 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4/dst': Waiting for transfers to finish 2021/07/25 05:34:07 DEBUG : one: md5 = b5f80d56c298849470b0edfcd0400b50 OK 2021/07/25 05:34:07 INFO : one: Copied (new) 2021/07/25 05:34:07 DEBUG : Waiting for deletions to finish 2021/07/25 05:34:08 INFO : three.txt.bak: Deleted 2021/07/25 05:34:08 INFO : three.txt: Moved (server-side) to: three.txt.bak 2021/07/25 05:34:08 INFO : three.txt: Moved into backup dir 2021/07/25 05:34:09 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2021/07/25 05:34:09 DEBUG : pacer: Rate limited, increasing sleep to 1.876941762s 2021/07/25 05:34:09 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2021/07/25 05:34:09 DEBUG : pacer: Rate limited, increasing sleep to 2.943507646s 2021/07/25 05:34:11 DEBUG : pacer: Reducing sleep to 0s 2021/07/25 05:34:16 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2021/07/25 05:34:16 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "qltcak2uaegtmcoa8vijdppbp8" 2021/07/25 05:34:16 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "sk91qgsqfn0r271r2ehsaoc20c" 2021/07/25 05:34:16 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "sk91qgsqfn0r271r2ehsaoc20c" 2021/07/25 05:34:16 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" 2021/07/25 05:34:16 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "qltcak2uaegtmcoa8vijdppbp8" --- PASS: TestSyncBackupDirSuffixOnly (32.30s) === RUN TestSyncSuffix run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4'", Local "Local file system at /tmp/rclone325973095", Modify Window "1ms" 2021/07/25 05:34:19 DEBUG : dst/one: md5 = 19347e5b4dfd04c4153b534cddd5ef47 OK 2021/07/25 05:34:21 DEBUG : dst/two: md5 = b2db438661c2d2ce6c218744cd01197d OK 2021/07/25 05:34:22 DEBUG : dst/three.txt: md5 = be0919cd81e94bfc1910d104c770ce55 OK 2021/07/25 05:34:22 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4/dst" 2021/07/25 05:34:23 DEBUG : Creating backend with remote "TestDrive:crypt/3hcvr7rq3rr7dr8blvrfl2v9cg27o41psq1vr6v1p1kpca4b09gms2acl7kbj4gi8k00uq0gs7fb6/31u3jie661vd5p8j7rtc3hgbh0" 2021/07/25 05:34:23 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2021/07/25 05:34:23 DEBUG : pacer: Rate limited, increasing sleep to 1.711487067s 2021/07/25 05:34:23 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2021/07/25 05:34:23 DEBUG : pacer: Rate limited, increasing sleep to 2.303310928s 2021/07/25 05:34:25 DEBUG : pacer: Reducing sleep to 0s 2021/07/25 05:34:27 DEBUG : one: Sizes differ (src 4 vs dst 3) 2021/07/25 05:34:28 INFO : one: Moved (server-side) to: one.bak 2021/07/25 05:34:28 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2021/07/25 05:34:28 DEBUG : pacer: Rate limited, increasing sleep to 1.750474359s 2021/07/25 05:34:28 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2021/07/25 05:34:28 DEBUG : pacer: Rate limited, increasing sleep to 2.885260745s 2021/07/25 05:34:30 DEBUG : pacer: Reducing sleep to 0s 2021/07/25 05:34:34 DEBUG : one: md5 = 00d452f80062eab9910c7a655e0645aa OK 2021/07/25 05:34:34 INFO : one: Copied (new) 2021/07/25 05:34:34 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2021/07/25 05:34:34 DEBUG : two: Unchanged skipping 2021/07/25 05:34: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) 2021/07/25 05:34:34 DEBUG : pacer: Rate limited, increasing sleep to 1.284292355s 2021/07/25 05:34: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) 2021/07/25 05:34:34 DEBUG : pacer: Rate limited, increasing sleep to 2.069791065s 2021/07/25 05:34:36 DEBUG : pacer: Reducing sleep to 0s 2021/07/25 05:34:36 DEBUG : three.txt: Sizes differ (src 6 vs dst 5) 2021/07/25 05:34:38 INFO : three.txt: Moved (server-side) to: three.txt.bak 2021/07/25 05:34:40 DEBUG : three.txt: md5 = 0e6a7fd92910b4dcc2c1f36158296a69 OK 2021/07/25 05:34:40 INFO : three.txt: Copied (new) 2021/07/25 05:34:40 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2021/07/25 05:34:40 DEBUG : pacer: Rate limited, increasing sleep to 1.292401633s 2021/07/25 05:34:41 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2021/07/25 05:34:41 DEBUG : pacer: Rate limited, increasing sleep to 2.781829808s 2021/07/25 05:34:42 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) 2021/07/25 05:34:42 DEBUG : pacer: Rate limited, increasing sleep to 4.715317785s 2021/07/25 05:34:45 DEBUG : pacer: Reducing sleep to 0s 2021/07/25 05:34:45 DEBUG : one: Sizes differ (src 5 vs dst 4) 2021/07/25 05:34:46 INFO : one.bak: Deleted 2021/07/25 05:34:46 INFO : one: Moved (server-side) to: one.bak 2021/07/25 05:34:48 DEBUG : one: md5 = ca06ac6130d5eeb5e1277f723c85b6a7 OK 2021/07/25 05:34:48 INFO : one: Copied (new) 2021/07/25 05:34:48 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2021/07/25 05:34:48 DEBUG : two: Unchanged skipping 2021/07/25 05:34:48 DEBUG : three.txt: Sizes differ (src 19 vs dst 6) 2021/07/25 05:34: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) 2021/07/25 05:34:48 DEBUG : pacer: Rate limited, increasing sleep to 1.814347537s 2021/07/25 05:34:49 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2021/07/25 05:34:49 DEBUG : pacer: Rate limited, increasing sleep to 2.521437155s 2021/07/25 05:34:51 DEBUG : pacer: Reducing sleep to 0s 2021/07/25 05:34:51 INFO : three.txt.bak: Deleted 2021/07/25 05:34:53 INFO : three.txt: Moved (server-side) to: three.txt.bak 2021/07/25 05:34:55 DEBUG : three.txt: md5 = 152705168ade7e8f60ddb5f50252e9fd OK 2021/07/25 05:34:55 INFO : three.txt: Copied (new) 2021/07/25 05:34:58 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2021/07/25 05:34:58 DEBUG : pacer: Rate limited, increasing sleep to 1.404108367s 2021/07/25 05:34:59 DEBUG : pacer: Reducing sleep to 0s 2021/07/25 05:34:59 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2021/07/25 05:34:59 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "tr2hj63d80ftlmvm6a952snjcc" 2021/07/25 05:34:59 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "qltcak2uaegtmcoa8vijdppbp8" 2021/07/25 05:34:59 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "sk91qgsqfn0r271r2ehsaoc20c" 2021/07/25 05:34:59 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" 2021/07/25 05:34:59 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "sk91qgsqfn0r271r2ehsaoc20c" 2021/07/25 05:34:59 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "qltcak2uaegtmcoa8vijdppbp8" 2021/07/25 05:35:01 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2021/07/25 05:35:01 DEBUG : pacer: Rate limited, increasing sleep to 1.165616886s 2021/07/25 05:35:01 DEBUG : pacer: Reducing sleep to 0s --- PASS: TestSyncSuffix (43.42s) === RUN TestSyncSuffixKeepExtension run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4'", Local "Local file system at /tmp/rclone325973095", Modify Window "1ms" 2021/07/25 05:35:02 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2021/07/25 05:35:02 DEBUG : pacer: Rate limited, increasing sleep to 1.585558354s 2021/07/25 05:35:02 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2021/07/25 05:35:02 DEBUG : pacer: Rate limited, increasing sleep to 2.821259071s 2021/07/25 05:35:04 DEBUG : pacer: Reducing sleep to 0s 2021/07/25 05:35:08 DEBUG : dst/one: md5 = 2e4405b4311183b0c14c8abc9b995a19 OK 2021/07/25 05:35:09 DEBUG : dst/two: md5 = 896cadab92e339b04f4abe702da593af OK 2021/07/25 05:35:10 DEBUG : dst/three.txt: md5 = ef8d5e6e287d2bf29649f18595c7818d OK 2021/07/25 05:35:11 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4/dst" 2021/07/25 05:35:11 DEBUG : Creating backend with remote "TestDrive:crypt/3hcvr7rq3rr7dr8blvrfl2v9cg27o41psq1vr6v1p1kpca4b09gms2acl7kbj4gi8k00uq0gs7fb6/31u3jie661vd5p8j7rtc3hgbh0" 2021/07/25 05:35:11 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2021/07/25 05:35:11 DEBUG : pacer: Rate limited, increasing sleep to 1.552000999s 2021/07/25 05:35:12 DEBUG : pacer: Reducing sleep to 0s 2021/07/25 05:35:13 DEBUG : one: Sizes differ (src 4 vs dst 3) 2021/07/25 05:35:14 INFO : one: Moved (server-side) to: one-2019-01-01 2021/07/25 05:35:15 DEBUG : one: md5 = 2df05a904c0f205c65c91bec3e415305 OK 2021/07/25 05:35:15 INFO : one: Copied (new) 2021/07/25 05:35:15 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2021/07/25 05:35:15 DEBUG : pacer: Rate limited, increasing sleep to 1.338410827s 2021/07/25 05:35:16 DEBUG : pacer: Reducing sleep to 0s 2021/07/25 05:35:16 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2021/07/25 05:35:16 DEBUG : two: Unchanged skipping 2021/07/25 05:35:17 DEBUG : three.txt: Sizes differ (src 6 vs dst 5) 2021/07/25 05:35:18 INFO : three.txt: Moved (server-side) to: three-2019-01-01.txt 2021/07/25 05:35:19 DEBUG : three.txt: md5 = d896cd3b4e6122eaae5a3a041edd5765 OK 2021/07/25 05:35:19 INFO : three.txt: Copied (new) 2021/07/25 05:35:19 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2021/07/25 05:35:19 DEBUG : pacer: Rate limited, increasing sleep to 1.630379332s 2021/07/25 05:35:20 DEBUG : pacer: Reducing sleep to 0s 2021/07/25 05:35:22 DEBUG : one: Sizes differ (src 5 vs dst 4) 2021/07/25 05:35:22 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2021/07/25 05:35:22 DEBUG : pacer: Rate limited, increasing sleep to 1.553403566s 2021/07/25 05:35:22 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2021/07/25 05:35:22 DEBUG : pacer: Rate limited, increasing sleep to 2.86326169s 2021/07/25 05:35:24 DEBUG : pacer: Reducing sleep to 0s 2021/07/25 05:35:24 INFO : one-2019-01-01: Deleted 2021/07/25 05:35:27 INFO : one: Moved (server-side) to: one-2019-01-01 2021/07/25 05:35:27 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2021/07/25 05:35:27 DEBUG : pacer: Rate limited, increasing sleep to 1.681651102s 2021/07/25 05:35:27 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2021/07/25 05:35:27 DEBUG : pacer: Rate limited, increasing sleep to 2.259025142s 2021/07/25 05:35:29 DEBUG : pacer: Reducing sleep to 0s 2021/07/25 05:35:32 DEBUG : one: md5 = 60a75d0dc9dd7428c052a4116833a851 OK 2021/07/25 05:35:32 INFO : one: Copied (new) 2021/07/25 05:35:32 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2021/07/25 05:35:32 DEBUG : pacer: Rate limited, increasing sleep to 1.582206129s 2021/07/25 05:35:32 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2021/07/25 05:35:32 DEBUG : pacer: Rate limited, increasing sleep to 2.240305853s 2021/07/25 05:35:34 DEBUG : pacer: Reducing sleep to 0s 2021/07/25 05:35:34 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2021/07/25 05:35:34 DEBUG : two: Unchanged skipping 2021/07/25 05:35:36 DEBUG : three.txt: Sizes differ (src 19 vs dst 6) 2021/07/25 05:35:37 INFO : three-2019-01-01.txt: Deleted 2021/07/25 05:35:38 INFO : three.txt: Moved (server-side) to: three-2019-01-01.txt 2021/07/25 05:35:39 DEBUG : three.txt: md5 = 57f51f90b4aedc408fe073c35bdd97aa OK 2021/07/25 05:35:39 INFO : three.txt: Copied (new) 2021/07/25 05:35:43 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2021/07/25 05:35:43 DEBUG : pacer: Rate limited, increasing sleep to 1.348831521s 2021/07/25 05:35:43 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2021/07/25 05:35:43 DEBUG : pacer: Rate limited, increasing sleep to 2.076511282s 2021/07/25 05:35:44 DEBUG : pacer: Reducing sleep to 0s 2021/07/25 05:35:44 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "tr2hj63d80ftlmvm6a952snjcc" 2021/07/25 05:35:44 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2021/07/25 05:35:44 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "jcjl1bv3ep0v8kt35lqql1co90" 2021/07/25 05:35:44 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "qtq2f6qq4lgpsmj88vb7147qje3prudmtfdtr2342fth58vo9a50" 2021/07/25 05:35:44 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "jcjl1bv3ep0v8kt35lqql1co90" 2021/07/25 05:35:44 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "qtq2f6qq4lgpsmj88vb7147qje3prudmtfdtr2342fth58vo9a50" 2021/07/25 05:35:44 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" --- PASS: TestSyncSuffixKeepExtension (46.35s) === RUN TestSyncUTFNorm run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4'", Local "Local file system at /tmp/rclone325973095", Modify Window "1ms" 2021/07/25 05:35:48 DEBUG : Testêé: md5 = df05e7a59eafc101e7dbe18910509470 OK 2021/07/25 05:35:49 DEBUG : Testêé: Sizes differ (src 14 vs dst 18) 2021/07/25 05:35:49 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for checks to finish 2021/07/25 05:35:49 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for transfers to finish 2021/07/25 05:35:50 DEBUG : Testêé: md5 = 442fa91d360ae76a5d0995184b0d10f8 OK 2021/07/25 05:35:50 INFO : Testêé: Copied (replaced existing) 2021/07/25 05:35:50 DEBUG : Waiting for deletions to finish --- PASS: TestSyncUTFNorm (3.88s) === RUN TestSyncImmutable run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4'", Local "Local file system at /tmp/rclone325973095", Modify Window "1ms" 2021/07/25 05:35:51 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for checks to finish 2021/07/25 05:35:51 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for transfers to finish 2021/07/25 05:35:53 DEBUG : existing: md5 = 968b4343ead9ba127fa01010e8d8444e OK 2021/07/25 05:35:53 INFO : existing: Copied (new) 2021/07/25 05:35:53 DEBUG : Waiting for deletions to finish 2021/07/25 05:35: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) 2021/07/25 05:35:53 DEBUG : pacer: Rate limited, increasing sleep to 1.418627855s 2021/07/25 05:35:53 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2021/07/25 05:35:53 DEBUG : pacer: Rate limited, increasing sleep to 2.394608598s 2021/07/25 05:35:55 DEBUG : pacer: Reducing sleep to 0s 2021/07/25 05:35:57 DEBUG : existing: Sizes differ (src 8 vs dst 6) 2021/07/25 05:35:57 ERROR : existing: Source and destination exist but do not match: immutable file modified 2021/07/25 05:35:57 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for checks to finish 2021/07/25 05:35:57 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for transfers to finish 2021/07/25 05:35:57 ERROR : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': not deleting files as there were IO errors 2021/07/25 05:35:57 ERROR : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': not deleting directories as there were IO errors 2021/07/25 05:35:58 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2021/07/25 05:35:58 DEBUG : pacer: Rate limited, increasing sleep to 1.183170994s 2021/07/25 05:35:59 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2021/07/25 05:35:59 DEBUG : pacer: Rate limited, increasing sleep to 2.470900842s 2021/07/25 05:36:00 DEBUG : pacer: Reducing sleep to 0s --- PASS: TestSyncImmutable (8.81s) === RUN TestSyncIgnoreCase run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4'", Local "Local file system at /tmp/rclone325973095", Modify Window "1ms" 2021/07/25 05:36:03 DEBUG : EXISTING: md5 = 1c39f90333b380b5f20ebac24cc489d7 OK 2021/07/25 05:36:04 DEBUG : existing: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2021/07/25 05:36:04 DEBUG : existing: Unchanged skipping 2021/07/25 05:36:04 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for checks to finish 2021/07/25 05:36:04 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for transfers to finish 2021/07/25 05:36:04 DEBUG : Waiting for deletions to finish 2021/07/25 05:36:04 INFO : There was nothing to transfer --- PASS: TestSyncIgnoreCase (5.23s) === RUN TestMaxTransfer === RUN TestMaxTransfer/Hard run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4'", Local "Local file system at /tmp/rclone325973095", Modify Window "1ms" sync_test.go:1971: This test only runs on local === RUN TestMaxTransfer/Soft run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4'", Local "Local file system at /tmp/rclone325973095", Modify Window "1ms" sync_test.go:1971: This test only runs on local === RUN TestMaxTransfer/Cautious run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4'", Local "Local file system at /tmp/rclone325973095", Modify Window "1ms" sync_test.go:1971: This test only runs on local --- PASS: TestMaxTransfer (1.36s) --- SKIP: TestMaxTransfer/Hard (0.50s) --- SKIP: TestMaxTransfer/Soft (0.42s) --- SKIP: TestMaxTransfer/Cautious (0.45s) === RUN TestSyncConcurrentDelete run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4'", Local "Local file system at /tmp/rclone325973095", Modify Window "1ms" 2021/07/25 05:36:08 DEBUG : both0: md5 = 171c4869baf816811164a732e6700b66 OK 2021/07/25 05:36:09 DEBUG : only0: md5 = a29a771bf542962989e2e1808c28125a OK 2021/07/25 05:36:10 DEBUG : both1: md5 = 8b8a5ba3e3e8add399b3d93777b138d0 OK 2021/07/25 05:36: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) 2021/07/25 05:36:10 DEBUG : pacer: Rate limited, increasing sleep to 1.355807781s 2021/07/25 05:36:10 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2021/07/25 05:36:10 DEBUG : pacer: Rate limited, increasing sleep to 2.512931242s 2021/07/25 05:36:12 DEBUG : pacer: Reducing sleep to 0s 2021/07/25 05:36:15 DEBUG : only1: md5 = cba210caecd420e533b7884358fd8c23 OK 2021/07/25 05:36:16 DEBUG : both2: md5 = 9e4d1c664cb70b5f64f6760c08978950 OK 2021/07/25 05:36:17 DEBUG : only2: md5 = 3654246413e672c81cddcb6966932bee OK 2021/07/25 05:36:19 DEBUG : both3: md5 = 81e5666a20c14ade7a6ddd9f5b211970 OK 2021/07/25 05:36:20 DEBUG : only3: md5 = 0ea9ab5f858934058e11776aaccb141a OK 2021/07/25 05:36:21 DEBUG : both4: md5 = 734166c3693a8fa2683c32b78601d694 OK 2021/07/25 05:36:22 DEBUG : only4: md5 = b031d4d3b86a11522a2348cc3cca0559 OK 2021/07/25 05:36:24 DEBUG : both5: md5 = 24f02200b7b5b383337fe2352c3d17eb OK 2021/07/25 05:36:25 DEBUG : only5: md5 = 30c3973b5acadd5c39210bf8536cf4a0 OK 2021/07/25 05:36:26 DEBUG : both6: md5 = e45e31eeed9456fba1ef78d11394fc1e OK 2021/07/25 05:36:27 DEBUG : only6: md5 = e4d40b4b19d4d834d815358dc010fbf7 OK 2021/07/25 05:36:29 DEBUG : both7: md5 = d2a26ef83f29d1c624e2c626dcee40e4 OK 2021/07/25 05:36:30 DEBUG : only7: md5 = 44a1ec6283229e01118c8dbe0cf86362 OK 2021/07/25 05:36:31 DEBUG : both8: md5 = 1dd96a5f8da35614979e654a269a0dfb OK 2021/07/25 05:36:32 DEBUG : only8: md5 = 36769937b315e0334e677bf6e7c8c1cd OK 2021/07/25 05:36:34 DEBUG : both9: md5 = abc9ab0007f0ab336b2a7ec775212d60 OK 2021/07/25 05:36:35 DEBUG : only9: md5 = cb21da150b31671191a157b47d01a5e7 OK 2021/07/25 05:36:36 DEBUG : both10: md5 = 4b95afe83e65f494870a4b2a69519f39 OK 2021/07/25 05:36:37 DEBUG : only10: md5 = a2002c047d5f0e1ac584c333a6a653bc OK 2021/07/25 05:36:39 DEBUG : both11: md5 = 3113869ba54b5f1ce68037b3871e85d4 OK 2021/07/25 05:36:40 DEBUG : only11: md5 = 5901b4198150bd90a3ceeb040a6ba999 OK 2021/07/25 05:36:43 DEBUG : both12: md5 = cdbce7f8610c04dee1dc3894bf633388 OK 2021/07/25 05:36:44 DEBUG : only12: md5 = e0a0c11e8f4e855e0744cd401161302c OK 2021/07/25 05:36:45 DEBUG : both13: md5 = 04b39645ab31859181bdab34d7a0a404 OK 2021/07/25 05:36:46 DEBUG : only13: md5 = 8eb0ee7b4f4c2bf051181d297b507c22 OK 2021/07/25 05:36:47 DEBUG : both14: md5 = 0af8676f642200b946c85213e904e8a4 OK 2021/07/25 05:36:49 DEBUG : only14: md5 = 3fdaec9d33555e3cba22ad87a6575b90 OK 2021/07/25 05:36:50 DEBUG : both15: md5 = 0e69d9ab155eff9594d7510f9592f446 OK 2021/07/25 05:36:51 DEBUG : only15: md5 = ba61767b19ccefdfcd1f8aca2c2e2975 OK 2021/07/25 05:36:52 DEBUG : both16: md5 = 818175116b2df6487b86aa208f4e3813 OK 2021/07/25 05:36:54 DEBUG : only16: md5 = 1de266de5203c8cb0b9841b1cdd64cc3 OK 2021/07/25 05:36:55 DEBUG : both17: md5 = 8b67de31b96e6fb5546748c66b98b1e7 OK 2021/07/25 05:36:56 DEBUG : only17: md5 = 48c6c2b3ab650b89e6434086182d7da7 OK 2021/07/25 05:36:57 DEBUG : both18: md5 = 4fcaf1a2091d944ba580bdae8e8c97ef OK 2021/07/25 05:36:59 DEBUG : only18: md5 = 4a039918c692bd09091903fc3b9d2e10 OK 2021/07/25 05:37:00 DEBUG : both19: md5 = 14e13178b407ea043d7148e7ff2aad17 OK 2021/07/25 05:37:01 DEBUG : only19: md5 = b1bd728d4d6b048e15d2379098b32569 OK 2021/07/25 05:37:02 DEBUG : both0: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2021/07/25 05:37:02 DEBUG : both0: Unchanged skipping 2021/07/25 05:37:02 DEBUG : both1: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2021/07/25 05:37:02 DEBUG : both1: Unchanged skipping 2021/07/25 05:37:02 DEBUG : both10: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2021/07/25 05:37:02 DEBUG : both10: Unchanged skipping 2021/07/25 05:37:02 DEBUG : both11: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2021/07/25 05:37:02 DEBUG : both11: Unchanged skipping 2021/07/25 05:37:02 DEBUG : both12: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2021/07/25 05:37:02 DEBUG : both12: Unchanged skipping 2021/07/25 05:37:02 DEBUG : both13: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2021/07/25 05:37:02 DEBUG : both13: Unchanged skipping 2021/07/25 05:37:02 DEBUG : both14: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2021/07/25 05:37:02 DEBUG : both14: Unchanged skipping 2021/07/25 05:37:02 DEBUG : both15: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2021/07/25 05:37:02 DEBUG : both15: Unchanged skipping 2021/07/25 05:37:02 DEBUG : both16: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2021/07/25 05:37:02 DEBUG : both16: Unchanged skipping 2021/07/25 05:37:02 DEBUG : both17: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2021/07/25 05:37:02 DEBUG : both17: Unchanged skipping 2021/07/25 05:37:02 DEBUG : both18: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2021/07/25 05:37:02 DEBUG : both18: Unchanged skipping 2021/07/25 05:37:02 DEBUG : both4: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2021/07/25 05:37:02 DEBUG : both4: Unchanged skipping 2021/07/25 05:37:02 DEBUG : both5: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2021/07/25 05:37:02 DEBUG : both5: Unchanged skipping 2021/07/25 05:37:02 DEBUG : both6: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2021/07/25 05:37:02 DEBUG : both6: Unchanged skipping 2021/07/25 05:37:02 DEBUG : both7: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2021/07/25 05:37:02 DEBUG : both7: Unchanged skipping 2021/07/25 05:37:02 DEBUG : both8: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2021/07/25 05:37:02 DEBUG : both8: Unchanged skipping 2021/07/25 05:37:02 DEBUG : both9: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2021/07/25 05:37:02 DEBUG : both9: Unchanged skipping 2021/07/25 05:37:02 DEBUG : both19: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2021/07/25 05:37:02 DEBUG : both19: Unchanged skipping 2021/07/25 05:37:02 DEBUG : both2: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2021/07/25 05:37:02 DEBUG : both2: Unchanged skipping 2021/07/25 05:37:02 DEBUG : both3: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2021/07/25 05:37:02 DEBUG : both3: Unchanged skipping 2021/07/25 05:37:02 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for checks to finish 2021/07/25 05:37:02 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for transfers to finish 2021/07/25 05:37:02 DEBUG : Waiting for deletions to finish 2021/07/25 05:37:02 INFO : only19: Deleted 2021/07/25 05:37:02 INFO : only12: Deleted 2021/07/25 05:37:02 INFO : only0: Deleted 2021/07/25 05:37: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) 2021/07/25 05:37:03 DEBUG : pacer: Rate limited, increasing sleep to 1.119027875s 2021/07/25 05:37: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) 2021/07/25 05:37:03 DEBUG : pacer: Rate limited, increasing sleep to 2.466991266s 2021/07/25 05:37: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) 2021/07/25 05:37:03 DEBUG : pacer: Rate limited, increasing sleep to 4.789635434s 2021/07/25 05:37:03 DEBUG : pacer: Reducing sleep to 0s 2021/07/25 05:37:03 INFO : only6: Deleted 2021/07/25 05:37:03 INFO : only2: Deleted 2021/07/25 05:37:04 INFO : only8: Deleted 2021/07/25 05:37:04 INFO : only5: Deleted 2021/07/25 05:37:04 INFO : only14: Deleted 2021/07/25 05:37:04 INFO : only9: Deleted 2021/07/25 05:37:05 INFO : only10: Deleted 2021/07/25 05:37:05 INFO : only11: Deleted 2021/07/25 05:37:05 INFO : only18: Deleted 2021/07/25 05:37:05 INFO : only17: Deleted 2021/07/25 05:37:05 INFO : only4: Deleted 2021/07/25 05:37:05 INFO : only15: Deleted 2021/07/25 05:37:06 INFO : only1: Deleted 2021/07/25 05:37:06 INFO : only13: Deleted 2021/07/25 05:37:06 INFO : only16: Deleted 2021/07/25 05:37:06 INFO : only3: Deleted 2021/07/25 05:37:06 INFO : only7: Deleted 2021/07/25 05:37:06 INFO : There was nothing to transfer 2021/07/25 05:37:09 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2021/07/25 05:37:09 DEBUG : pacer: Rate limited, increasing sleep to 1.420885058s 2021/07/25 05:37:09 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2021/07/25 05:37:09 DEBUG : pacer: Rate limited, increasing sleep to 2.15276096s 2021/07/25 05:37:11 DEBUG : pacer: Reducing sleep to 0s 2021/07/25 05:37:13 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2021/07/25 05:37:13 DEBUG : pacer: Rate limited, increasing sleep to 1.919667224s 2021/07/25 05:37:13 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2021/07/25 05:37:13 DEBUG : pacer: Rate limited, increasing sleep to 2.42942073s 2021/07/25 05:37:15 DEBUG : pacer: Reducing sleep to 0s 2021/07/25 05:37:19 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2021/07/25 05:37:19 DEBUG : pacer: Rate limited, increasing sleep to 1.464385953s 2021/07/25 05:37:19 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2021/07/25 05:37:19 DEBUG : pacer: Rate limited, increasing sleep to 2.561464944s 2021/07/25 05:37:21 DEBUG : pacer: Reducing sleep to 0s --- PASS: TestSyncConcurrentDelete (82.14s) === RUN TestSyncConcurrentTruncate run.go:176: Remote "Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4'", Local "Local file system at /tmp/rclone325973095", Modify Window "1ms" 2021/07/25 05:37:30 DEBUG : both0: md5 = e9d2cba4b96b7236382233aa4c7d510f OK 2021/07/25 05:37:31 DEBUG : only0: md5 = 1412fe02d5276a6bb0efa4661955b088 OK 2021/07/25 05:37:32 DEBUG : both1: md5 = ef41f662ea72fedf143212b345f45348 OK 2021/07/25 05:37:33 DEBUG : only1: md5 = 4969431d9e3d8c44d24e9f9b7f0246a1 OK 2021/07/25 05:37:35 DEBUG : both2: md5 = 2de405e70c9f58d0a3ee42fabae97053 OK 2021/07/25 05:37:36 DEBUG : only2: md5 = 6726655bf18e00787fb42c2b27fa6414 OK 2021/07/25 05:37:37 DEBUG : both3: md5 = a88665e72251bb1fa47c66bd01a6f1e6 OK 2021/07/25 05:37:39 DEBUG : only3: md5 = f7c022140384ad031577997e193b5fd0 OK 2021/07/25 05:37:40 DEBUG : both4: md5 = 7a4184ccc71b63d003ab9502091f81f1 OK 2021/07/25 05:37:41 DEBUG : only4: md5 = cfcee76f8a18a0b70a07833b1b904b80 OK 2021/07/25 05:37:43 DEBUG : both5: md5 = 82d146fca40d91029b776c3ff59a134b OK 2021/07/25 05:37:43 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2021/07/25 05:37:43 DEBUG : pacer: Rate limited, increasing sleep to 1.677927166s 2021/07/25 05:37:43 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2021/07/25 05:37:43 DEBUG : pacer: Rate limited, increasing sleep to 2.622016346s 2021/07/25 05:37:45 DEBUG : pacer: Reducing sleep to 0s 2021/07/25 05:37:48 DEBUG : only5: md5 = 6b9ecd8b4a17c98fa2d8df4969079dd2 OK 2021/07/25 05:37:49 DEBUG : both6: md5 = 58fa2981ebff6b846b6f5892f1720063 OK 2021/07/25 05:37:51 DEBUG : only6: md5 = c48b2e51f21b0278a269e8192de9d5b5 OK 2021/07/25 05:37:52 DEBUG : both7: md5 = 4b2a9b0a6bcf4fd5403cffee4ef0caf4 OK 2021/07/25 05:37:54 DEBUG : only7: md5 = 235fc57f4095e855c126148fa280b770 OK 2021/07/25 05:37:55 DEBUG : both8: md5 = ba871972c0796876fc73419923e0f933 OK 2021/07/25 05:37:56 DEBUG : only8: md5 = e0b66b0af09516238720dade106daf51 OK 2021/07/25 05:37:57 DEBUG : both9: md5 = 4d2bf00f2b5193a8692013d005c4a6a6 OK 2021/07/25 05:37:59 DEBUG : only9: md5 = e101404e3b5a31896e1317bef055396b OK 2021/07/25 05:38:00 DEBUG : both10: md5 = 464ae23a5ce661cfc709c18023d2d80c OK 2021/07/25 05:38:02 DEBUG : only10: md5 = 7ee137826cfa8d7c887e8710d71ddb40 OK 2021/07/25 05:38:03 DEBUG : both11: md5 = 1a2db7ddd2e99ab251f2bd03aca4f4d7 OK 2021/07/25 05:38:04 DEBUG : only11: md5 = 77ff23d97c7421567197ab1898875196 OK 2021/07/25 05:38:05 DEBUG : both12: md5 = bd066fe6e268acc1848cc71d912414de OK 2021/07/25 05:38:07 DEBUG : only12: md5 = da62d6b1002c92b104f289840e1f223c OK 2021/07/25 05:38:08 DEBUG : both13: md5 = 90c524f8ab9a1d1e0872a18790a30501 OK 2021/07/25 05:38:09 DEBUG : only13: md5 = 74909568c92b75dfff465c2e8be0e471 OK 2021/07/25 05:38:10 DEBUG : both14: md5 = f11c9d9e1b230cf311e94db37b924797 OK 2021/07/25 05:38:11 DEBUG : only14: md5 = 536a02499ccc990b030da791615b4462 OK 2021/07/25 05:38:13 DEBUG : both15: md5 = 2ccc5b29d8e4929e02fb8e3246a6cbb7 OK 2021/07/25 05:38:14 DEBUG : only15: md5 = 127e8e2d7a90def88031b6bd3fcf9579 OK 2021/07/25 05:38:15 DEBUG : both16: md5 = 62751b0a4262bbcd9c81ad64dac33c8d OK 2021/07/25 05:38:16 DEBUG : only16: md5 = 210291d43f3ccc17d820546addcfb1fd OK 2021/07/25 05:38:18 DEBUG : both17: md5 = 4c833c6abd56d99530cdfbd9d2983dae OK 2021/07/25 05:38:19 DEBUG : only17: md5 = 6dd93f92b8d24b3fc4e911f615b9abce OK 2021/07/25 05:38:20 DEBUG : both18: md5 = fcc3cab7426796f7aa76d1742d7be6b3 OK 2021/07/25 05:38:21 DEBUG : only18: md5 = 35b058d2610d4eca3300920c56fa0876 OK 2021/07/25 05:38:22 DEBUG : both19: md5 = 4e29d124458638db12bd23a73f0784f4 OK 2021/07/25 05:38:24 DEBUG : only19: md5 = bc8414f9c3a85373c2df07a01d9a584f OK 2021/07/25 05:38:24 DEBUG : both0: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2021/07/25 05:38:24 DEBUG : both0: Unchanged skipping 2021/07/25 05:38:24 DEBUG : both12: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2021/07/25 05:38:24 DEBUG : both12: Unchanged skipping 2021/07/25 05:38:24 DEBUG : both13: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2021/07/25 05:38:24 DEBUG : both13: Unchanged skipping 2021/07/25 05:38:24 DEBUG : both14: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2021/07/25 05:38:24 DEBUG : both14: Unchanged skipping 2021/07/25 05:38:24 DEBUG : both15: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2021/07/25 05:38:24 DEBUG : both15: Unchanged skipping 2021/07/25 05:38:24 DEBUG : both16: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2021/07/25 05:38:24 DEBUG : both16: Unchanged skipping 2021/07/25 05:38:24 DEBUG : both17: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2021/07/25 05:38:24 DEBUG : both17: Unchanged skipping 2021/07/25 05:38:24 DEBUG : both18: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2021/07/25 05:38:24 DEBUG : both18: Unchanged skipping 2021/07/25 05:38:24 DEBUG : both19: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2021/07/25 05:38:24 DEBUG : both19: Unchanged skipping 2021/07/25 05:38:24 DEBUG : both2: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2021/07/25 05:38:24 DEBUG : both1: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2021/07/25 05:38:24 DEBUG : both1: Unchanged skipping 2021/07/25 05:38:24 DEBUG : both3: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2021/07/25 05:38:24 DEBUG : both3: Unchanged skipping 2021/07/25 05:38:24 DEBUG : both4: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2021/07/25 05:38:24 DEBUG : both4: Unchanged skipping 2021/07/25 05:38:24 DEBUG : both5: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2021/07/25 05:38:24 DEBUG : both5: Unchanged skipping 2021/07/25 05:38:24 DEBUG : both6: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2021/07/25 05:38:24 DEBUG : both6: Unchanged skipping 2021/07/25 05:38:24 DEBUG : both7: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2021/07/25 05:38:24 DEBUG : both7: Unchanged skipping 2021/07/25 05:38:24 DEBUG : both8: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2021/07/25 05:38:24 DEBUG : both8: Unchanged skipping 2021/07/25 05:38:24 DEBUG : both9: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2021/07/25 05:38:24 DEBUG : both9: Unchanged skipping 2021/07/25 05:38:24 DEBUG : only0: Sizes differ (src 0 vs dst 6) 2021/07/25 05:38:24 DEBUG : both10: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2021/07/25 05:38:24 DEBUG : both10: Unchanged skipping 2021/07/25 05:38:24 DEBUG : only10: Sizes differ (src 0 vs dst 6) 2021/07/25 05:38:24 DEBUG : only11: Sizes differ (src 0 vs dst 6) 2021/07/25 05:38:24 DEBUG : only12: Sizes differ (src 0 vs dst 6) 2021/07/25 05:38:24 DEBUG : only13: Sizes differ (src 0 vs dst 6) 2021/07/25 05:38:24 DEBUG : only14: Sizes differ (src 0 vs dst 6) 2021/07/25 05:38:24 DEBUG : only15: Sizes differ (src 0 vs dst 6) 2021/07/25 05:38:24 DEBUG : only16: Sizes differ (src 0 vs dst 6) 2021/07/25 05:38:24 DEBUG : only17: Sizes differ (src 0 vs dst 6) 2021/07/25 05:38:24 DEBUG : only18: Sizes differ (src 0 vs dst 6) 2021/07/25 05:38:24 DEBUG : only19: Sizes differ (src 0 vs dst 6) 2021/07/25 05:38:24 DEBUG : only2: Sizes differ (src 0 vs dst 6) 2021/07/25 05:38:24 DEBUG : only3: Sizes differ (src 0 vs dst 6) 2021/07/25 05:38:24 DEBUG : only4: Sizes differ (src 0 vs dst 6) 2021/07/25 05:38:24 DEBUG : only5: Sizes differ (src 0 vs dst 6) 2021/07/25 05:38:24 DEBUG : only6: Sizes differ (src 0 vs dst 6) 2021/07/25 05:38:24 DEBUG : only7: Sizes differ (src 0 vs dst 6) 2021/07/25 05:38:24 DEBUG : only8: Sizes differ (src 0 vs dst 6) 2021/07/25 05:38:24 DEBUG : only9: Sizes differ (src 0 vs dst 6) 2021/07/25 05:38:24 DEBUG : both11: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2021/07/25 05:38:24 DEBUG : both11: Unchanged skipping 2021/07/25 05:38:24 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for checks to finish 2021/07/25 05:38:24 DEBUG : both2: Unchanged skipping 2021/07/25 05:38:24 DEBUG : only1: Sizes differ (src 0 vs dst 6) 2021/07/25 05:38:24 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Waiting for transfers to finish 2021/07/25 05:38:26 DEBUG : only10: md5 = ec37391767d6bfc2fc1253dab8eb8e22 OK 2021/07/25 05:38:26 INFO : only10: Copied (replaced existing) 2021/07/25 05:38:26 DEBUG : only11: md5 = 21c79b586bce10346e0cb66de25bc0d8 OK 2021/07/25 05:38:26 INFO : only11: Copied (replaced existing) 2021/07/25 05:38:26 DEBUG : only0: md5 = 6c7201f307cde76740c5b8728c4981b5 OK 2021/07/25 05:38:26 INFO : only0: Copied (replaced existing) 2021/07/25 05:38:26 DEBUG : only12: md5 = f20fd98e2889cd599cc8b6d5a983f276 OK 2021/07/25 05:38:26 INFO : only12: Copied (replaced existing) 2021/07/25 05:38:27 DEBUG : only14: md5 = 629d1795c9a8dfa4636e927df59b8ec5 OK 2021/07/25 05:38:27 INFO : only14: Copied (replaced existing) 2021/07/25 05:38:27 DEBUG : only16: md5 = b203d698f35610e30302990febd86a46 OK 2021/07/25 05:38:27 INFO : only16: Copied (replaced existing) 2021/07/25 05:38:27 DEBUG : only15: md5 = be7200a94e4b459971eba73769b6358a OK 2021/07/25 05:38:27 INFO : only15: Copied (replaced existing) 2021/07/25 05:38:27 DEBUG : only13: md5 = 2704e1c5bc8a6aea0a4605ae27cbdb74 OK 2021/07/25 05:38:27 INFO : only13: Copied (replaced existing) 2021/07/25 05:38:28 DEBUG : only17: md5 = c17a3ad437281b730731610d8aa85369 OK 2021/07/25 05:38:28 INFO : only17: Copied (replaced existing) 2021/07/25 05:38:28 DEBUG : only19: md5 = c8b68e235fa0752e1c5e3a9ad200ad8d OK 2021/07/25 05:38:28 INFO : only19: Copied (replaced existing) 2021/07/25 05:38:28 DEBUG : only2: md5 = afaa25dbc78557843842b541fc31bee9 OK 2021/07/25 05:38:28 INFO : only2: Copied (replaced existing) 2021/07/25 05:38:28 DEBUG : only18: md5 = a25df9c478dec55fdea844e5d76bc7b5 OK 2021/07/25 05:38:28 INFO : only18: Copied (replaced existing) 2021/07/25 05:38:29 DEBUG : only3: md5 = e06922765835a4242c818f971afb7bfc OK 2021/07/25 05:38:29 INFO : only3: Copied (replaced existing) 2021/07/25 05:38:29 DEBUG : only4: md5 = 9b562c8bb2da438684198d160fdb6841 OK 2021/07/25 05:38:29 INFO : only4: Copied (replaced existing) 2021/07/25 05:38:29 DEBUG : only6: md5 = 30d80a4513ffbf6c80388b80f01f26c5 OK 2021/07/25 05:38:29 INFO : only6: Copied (replaced existing) 2021/07/25 05:38:29 DEBUG : only5: md5 = 806f4ea2542edcdcdbe4f467397e84b8 OK 2021/07/25 05:38:29 INFO : only5: Copied (replaced existing) 2021/07/25 05:38:30 DEBUG : only7: md5 = 51832b35b2bcce59dccadbf4c8dbeb3d OK 2021/07/25 05:38:30 INFO : only7: Copied (replaced existing) 2021/07/25 05:38:30 DEBUG : only8: md5 = 3873d0efce93959297619fa91178060c OK 2021/07/25 05:38:30 INFO : only8: Copied (replaced existing) 2021/07/25 05:38:30 DEBUG : only1: md5 = 1d2d3d351798a906c8f3aecc6bb4e6fc OK 2021/07/25 05:38:30 INFO : only1: Copied (replaced existing) 2021/07/25 05:38:30 DEBUG : only9: md5 = 8c54e82041a2dc8b570750c5b0e0cf53 OK 2021/07/25 05:38:30 INFO : only9: Copied (replaced existing) 2021/07/25 05:38:30 DEBUG : Waiting for deletions to finish 2021/07/25 05:38: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) 2021/07/25 05:38:33 DEBUG : pacer: Rate limited, increasing sleep to 1.399923286s 2021/07/25 05:38: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) 2021/07/25 05:38:33 DEBUG : pacer: Rate limited, increasing sleep to 2.620474892s 2021/07/25 05:38:35 DEBUG : pacer: Reducing sleep to 0s --- PASS: TestSyncConcurrentTruncate (88.01s) PASS 2021/07/25 05:38:57 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xiwesux3yuzaqis9hesoyip4': Purge remote "./sync.test -test.v -test.timeout 1h0m0s -remote TestCryptDrive: -verbose -fast-list" - Finished OK in 13m25.665398029s (try 1/5)