"./sync.test -test.v -test.timeout 1h0m0s -remote TestCompressDrive: -verbose" - Starting (try 1/5) 2022/03/14 05:29:56 DEBUG : Creating backend with remote "TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9" 2022/03/14 05:29:56 DEBUG : Using config file from "/home/rclone/.rclone.conf" 2022/03/14 05:29:57 DEBUG : Creating backend with remote "/tmp/rclone1599678426" === RUN TestPipe --- PASS: TestPipe (0.00s) === RUN TestPipeConcurrent --- PASS: TestPipeConcurrent (0.03s) === RUN TestPipeOrderBy === RUN TestPipeOrderBy/#00 === RUN TestPipeOrderBy/size === RUN TestPipeOrderBy/name === RUN TestPipeOrderBy/modtime === RUN TestPipeOrderBy/size,ascending === RUN TestPipeOrderBy/name,asc === RUN TestPipeOrderBy/modtime,ascending === RUN TestPipeOrderBy/size,descending === RUN TestPipeOrderBy/name,desc === RUN TestPipeOrderBy/modtime,descending === RUN TestPipeOrderBy/size,mixed,50 === RUN TestPipeOrderBy/size,mixed,51 --- PASS: TestPipeOrderBy (0.00s) --- PASS: TestPipeOrderBy/#00 (0.00s) --- PASS: TestPipeOrderBy/size (0.00s) --- PASS: TestPipeOrderBy/name (0.00s) --- PASS: TestPipeOrderBy/modtime (0.00s) --- PASS: TestPipeOrderBy/size,ascending (0.00s) --- PASS: TestPipeOrderBy/name,asc (0.00s) --- PASS: TestPipeOrderBy/modtime,ascending (0.00s) --- PASS: TestPipeOrderBy/size,descending (0.00s) --- PASS: TestPipeOrderBy/name,desc (0.00s) --- PASS: TestPipeOrderBy/modtime,descending (0.00s) --- PASS: TestPipeOrderBy/size,mixed,50 (0.00s) --- PASS: TestPipeOrderBy/size,mixed,51 (0.00s) === RUN TestNewLess === RUN TestNewLess/blankOK === RUN TestNewLess/tooManyParts === RUN TestNewLess/tooManyParts2 === RUN TestNewLess/badMixed === RUN TestNewLess/unknownComparison === RUN TestNewLess/unknownSortDirection === RUN TestNewLess/size === RUN TestNewLess/name === RUN TestNewLess/modtime === RUN TestNewLess/size,ascending === RUN TestNewLess/name,asc === RUN TestNewLess/modtime,ascending === RUN TestNewLess/size,descending === RUN TestNewLess/name,desc === RUN TestNewLess/modtime,descending === RUN TestNewLess/modtime,mixed === RUN TestNewLess/modtime,mixed,30 --- PASS: TestNewLess (0.00s) --- PASS: TestNewLess/blankOK (0.00s) --- PASS: TestNewLess/tooManyParts (0.00s) --- PASS: TestNewLess/tooManyParts2 (0.00s) --- PASS: TestNewLess/badMixed (0.00s) --- PASS: TestNewLess/unknownComparison (0.00s) --- PASS: TestNewLess/unknownSortDirection (0.00s) --- PASS: TestNewLess/size (0.00s) --- PASS: TestNewLess/name (0.00s) --- PASS: TestNewLess/modtime (0.00s) --- PASS: TestNewLess/size,ascending (0.00s) --- PASS: TestNewLess/name,asc (0.00s) --- PASS: TestNewLess/modtime,ascending (0.00s) --- PASS: TestNewLess/size,descending (0.00s) --- PASS: TestNewLess/name,desc (0.00s) --- PASS: TestNewLess/modtime,descending (0.00s) --- PASS: TestNewLess/modtime,mixed (0.00s) --- PASS: TestNewLess/modtime,mixed,30 (0.00s) === RUN TestRcCopy rc_test.go:16: Skipping test on non local remote --- SKIP: TestRcCopy (0.00s) === RUN TestRcMove rc_test.go:16: Skipping test on non local remote --- SKIP: TestRcMove (0.00s) === RUN TestRcSync rc_test.go:16: Skipping test on non local remote --- SKIP: TestRcSync (0.00s) === RUN TestCopyWithDryRun run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9", Local "Local file system at /tmp/rclone1599678426", Modify Window "1ms" 2022/03/14 05:29:58 NOTICE: sub dir/hello world: Skipped copy as --dry-run is set (size 11) 2022/03/14 05:29:58 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for checks to finish 2022/03/14 05:29:58 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for transfers to finish --- PASS: TestCopyWithDryRun (1.68s) === RUN TestCopy run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9", Local "Local file system at /tmp/rclone1599678426", Modify Window "1ms" 2022/03/14 05:29:59 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for checks to finish 2022/03/14 05:29:59 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for transfers to finish 2022/03/14 05:29:59 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/14 05:29:59 DEBUG : pacer: Rate limited, increasing sleep to 1.157317081s 2022/03/14 05:30:00 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/14 05:30:00 DEBUG : pacer: Rate limited, increasing sleep to 2.396130212s 2022/03/14 05:30:01 DEBUG : pacer: Reducing sleep to 0s 2022/03/14 05:30:06 DEBUG : sub dir/hello world: md5 = 5eb63bbbe01eeed093cb22bb8f5acdc3 OK 2022/03/14 05:30:06 INFO : sub dir/hello world: Copied (new) 2022/03/14 05:30:10 DEBUG : sub dir: Rmdir: contains trashed file: "hello world.bin" 2022/03/14 05:30:10 DEBUG : sub dir: Rmdir: contains trashed file: "hello world.json" --- PASS: TestCopy (11.76s) === RUN TestCopyMissingDirectory run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9", Local "Local file system at /tmp/rclone1599678426", Modify Window "1ms" 2022/03/14 05:30:11 DEBUG : Creating backend with remote "/non-existing" 2022/03/14 05:30:11 ERROR : Local file system at /non-existing: error reading source root directory: directory not found 2022/03/14 05:30:11 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for checks to finish 2022/03/14 05:30:11 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for transfers to finish --- PASS: TestCopyMissingDirectory (0.70s) === RUN TestCopyNoTraverse run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9", Local "Local file system at /tmp/rclone1599678426", Modify Window "1ms" 2022/03/14 05:30:11 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for checks to finish 2022/03/14 05:30:11 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for transfers to finish 2022/03/14 05:30:15 DEBUG : sub dir/hello world: md5 = 5eb63bbbe01eeed093cb22bb8f5acdc3 OK 2022/03/14 05:30:15 INFO : sub dir/hello world: Copied (new) 2022/03/14 05:30:19 DEBUG : sub dir: Rmdir: contains trashed file: "hello world.json" 2022/03/14 05:30:19 DEBUG : sub dir: Rmdir: contains trashed file: "hello world.bin" --- PASS: TestCopyNoTraverse (8.20s) === RUN TestCopyCheckFirst run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9", Local "Local file system at /tmp/rclone1599678426", Modify Window "1ms" 2022/03/14 05:30:19 INFO : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Running all checks before starting transfers 2022/03/14 05:30:20 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for checks to finish 2022/03/14 05:30:20 INFO : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Checks finished, now starting transfers 2022/03/14 05:30:20 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for transfers to finish 2022/03/14 05:30:20 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/14 05:30:20 DEBUG : pacer: Rate limited, increasing sleep to 1.617527213s 2022/03/14 05:30:21 DEBUG : pacer: Reducing sleep to 0s 2022/03/14 05:30:25 DEBUG : sub dir/hello world: md5 = 5eb63bbbe01eeed093cb22bb8f5acdc3 OK 2022/03/14 05:30:25 INFO : sub dir/hello world: Copied (new) 2022/03/14 05:30:28 DEBUG : sub dir: Rmdir: contains trashed file: "hello world.json" 2022/03/14 05:30:28 DEBUG : sub dir: Rmdir: contains trashed file: "hello world.bin" --- PASS: TestCopyCheckFirst (9.43s) === RUN TestSyncNoTraverse run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9", Local "Local file system at /tmp/rclone1599678426", Modify Window "1ms" 2022/03/14 05:30:29 ERROR : Ignoring --no-traverse with sync 2022/03/14 05:30:29 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for checks to finish 2022/03/14 05:30:29 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for transfers to finish 2022/03/14 05:30:33 DEBUG : sub dir/hello world: md5 = 5eb63bbbe01eeed093cb22bb8f5acdc3 OK 2022/03/14 05:30:33 INFO : sub dir/hello world: Copied (new) 2022/03/14 05:30:33 DEBUG : Waiting for deletions to finish 2022/03/14 05:30:36 DEBUG : sub dir: Rmdir: contains trashed file: "hello world.bin" 2022/03/14 05:30:36 DEBUG : sub dir: Rmdir: contains trashed file: "hello world.json" --- PASS: TestSyncNoTraverse (8.29s) === RUN TestCopyWithDepth run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9", Local "Local file system at /tmp/rclone1599678426", Modify Window "1ms" 2022/03/14 05:30:37 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for checks to finish 2022/03/14 05:30:37 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for transfers to finish 2022/03/14 05:30:40 DEBUG : hello world2: md5 = cc2c857f89648dbd139d7b2a6665957d OK 2022/03/14 05:30:40 INFO : hello world2: Copied (new) --- PASS: TestCopyWithDepth (6.05s) === RUN TestCopyWithFilesFrom run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9", Local "Local file system at /tmp/rclone1599678426", Modify Window "1ms" 2022/03/14 05:30:43 DEBUG : hello world2: Excluded 2022/03/14 05:30:43 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for checks to finish 2022/03/14 05:30:43 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for transfers to finish 2022/03/14 05:30:46 DEBUG : potato2: md5 = 5eb63bbbe01eeed093cb22bb8f5acdc3 OK 2022/03/14 05:30:46 INFO : potato2: Copied (new) --- PASS: TestCopyWithFilesFrom (6.03s) === RUN TestCopyWithFilesFromAndNoTraverse run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9", Local "Local file system at /tmp/rclone1599678426", Modify Window "1ms" 2022/03/14 05:30:49 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/14 05:30:49 DEBUG : pacer: Rate limited, increasing sleep to 1.901572418s 2022/03/14 05:30:50 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/14 05:30:50 DEBUG : pacer: Rate limited, increasing sleep to 2.076785621s 2022/03/14 05:30:52 DEBUG : pacer: Reducing sleep to 0s 2022/03/14 05:30:52 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for checks to finish 2022/03/14 05:30:52 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for transfers to finish 2022/03/14 05:30:56 DEBUG : potato2: md5 = 5eb63bbbe01eeed093cb22bb8f5acdc3 OK 2022/03/14 05:30:56 INFO : potato2: Copied (new) --- PASS: TestCopyWithFilesFromAndNoTraverse (9.98s) === RUN TestCopyEmptyDirectories run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9", Local "Local file system at /tmp/rclone1599678426", Modify Window "1ms" 2022/03/14 05:30:59 DEBUG : sub dir2: Making directory 2022/03/14 05:30:59 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for checks to finish 2022/03/14 05:30:59 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for transfers to finish 2022/03/14 05:31:00 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/14 05:31:00 DEBUG : pacer: Rate limited, increasing sleep to 1.570838858s 2022/03/14 05:31:00 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/14 05:31:00 DEBUG : pacer: Rate limited, increasing sleep to 2.928379255s 2022/03/14 05:31:02 DEBUG : pacer: Reducing sleep to 0s 2022/03/14 05:31:07 DEBUG : sub dir/hello world: md5 = 5eb63bbbe01eeed093cb22bb8f5acdc3 OK 2022/03/14 05:31:07 INFO : sub dir/hello world: Copied (new) 2022/03/14 05:31:07 DEBUG : sub dir2: Making directory 2022/03/14 05:31:08 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: copied 1 directories 2022/03/14 05:31:12 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/14 05:31:12 DEBUG : pacer: Rate limited, increasing sleep to 1.651725891s 2022/03/14 05:31:12 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/14 05:31:12 DEBUG : pacer: Rate limited, increasing sleep to 2.610973235s 2022/03/14 05:31:14 DEBUG : pacer: Reducing sleep to 0s 2022/03/14 05:31:14 DEBUG : sub dir: Rmdir: contains trashed file: "hello world.bin" 2022/03/14 05:31:14 DEBUG : sub dir: Rmdir: contains trashed file: "hello world.json" --- PASS: TestCopyEmptyDirectories (18.13s) === RUN TestMoveEmptyDirectories run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9", Local "Local file system at /tmp/rclone1599678426", Modify Window "1ms" 2022/03/14 05:31:17 DEBUG : sub dir2: Making directory 2022/03/14 05:31:18 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for checks to finish 2022/03/14 05:31:18 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for transfers to finish 2022/03/14 05:31:21 DEBUG : sub dir/hello world: md5 = 5eb63bbbe01eeed093cb22bb8f5acdc3 OK 2022/03/14 05:31:21 INFO : sub dir/hello world: Copied (new) 2022/03/14 05:31:21 INFO : sub dir/hello world: Deleted 2022/03/14 05:31:21 DEBUG : sub dir2: Making directory 2022/03/14 05:31:22 DEBUG : sub dir: Making directory 2022/03/14 05:31:22 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: copied 2 directories 2022/03/14 05:31: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) 2022/03/14 05:31:22 DEBUG : pacer: Rate limited, increasing sleep to 1.325081133s 2022/03/14 05:31:23 DEBUG : pacer: Reducing sleep to 0s 2022/03/14 05:31:27 DEBUG : sub dir: Rmdir: contains trashed file: "hello world.bin" 2022/03/14 05:31:27 DEBUG : sub dir: Rmdir: contains trashed file: "hello world.json" --- PASS: TestMoveEmptyDirectories (10.74s) === RUN TestSyncEmptyDirectories run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9", Local "Local file system at /tmp/rclone1599678426", Modify Window "1ms" 2022/03/14 05:31:28 DEBUG : sub dir2: Making directory 2022/03/14 05:31:28 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for checks to finish 2022/03/14 05:31:28 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for transfers to finish 2022/03/14 05:31:32 DEBUG : sub dir/hello world: md5 = 5eb63bbbe01eeed093cb22bb8f5acdc3 OK 2022/03/14 05:31:32 INFO : sub dir/hello world: Copied (new) 2022/03/14 05:31:32 DEBUG : sub dir2: Making directory 2022/03/14 05:31:33 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: copied 1 directories 2022/03/14 05:31:33 DEBUG : Waiting for deletions to finish 2022/03/14 05:31:37 DEBUG : sub dir: Rmdir: contains trashed file: "hello world.json" 2022/03/14 05:31:37 DEBUG : sub dir: Rmdir: contains trashed file: "hello world.bin" --- PASS: TestSyncEmptyDirectories (9.66s) === RUN TestServerSideCopy run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9", Local "Local file system at /tmp/rclone1599678426", Modify Window "1ms" 2022/03/14 05:31:43 DEBUG : Creating backend with remote "TestCompressDrive:rclone-test-guqefaz1yiyuxux3kixilav2" sync_test.go:275: Server side copy (if possible) Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9 -> Compressed: TestCompressDrive:rclone-test-guqefaz1yiyuxux3kixilav2 2022/03/14 05:31:44 DEBUG : Compressed: TestCompressDrive:rclone-test-guqefaz1yiyuxux3kixilav2: Waiting for checks to finish 2022/03/14 05:31:44 DEBUG : Compressed: TestCompressDrive:rclone-test-guqefaz1yiyuxux3kixilav2: Waiting for transfers to finish 2022/03/14 05:31:49 DEBUG : sub dir/hello world: md5 = 5eb63bbbe01eeed093cb22bb8f5acdc3 OK 2022/03/14 05:31:49 INFO : sub dir/hello world: Copied (server-side copy) 2022/03/14 05:31:51 DEBUG : Compressed: TestCompressDrive:rclone-test-guqefaz1yiyuxux3kixilav2: Purge remote 2022/03/14 05:31:54 DEBUG : sub dir: Rmdir: contains trashed file: "hello world.json" 2022/03/14 05:31:54 DEBUG : sub dir: Rmdir: contains trashed file: "hello world.bin" --- PASS: TestServerSideCopy (16.58s) === RUN TestCopyAfterDelete run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9", Local "Local file system at /tmp/rclone1599678426", Modify Window "1ms" 2022/03/14 05:31:58 ERROR : : error listing: directory not found 2022/03/14 05:31:59 DEBUG : Local file system at /tmp/rclone1599678426: Making directory 2022/03/14 05:32:00 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for checks to finish 2022/03/14 05:32:00 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for transfers to finish 2022/03/14 05:32:03 DEBUG : sub dir: Rmdir: contains trashed file: "hello world.bin" 2022/03/14 05:32:03 DEBUG : sub dir: Rmdir: contains trashed file: "hello world.json" --- PASS: TestCopyAfterDelete (9.73s) === RUN TestCopyRedownload run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9", Local "Local file system at /tmp/rclone1599678426", Modify Window "1ms" 2022/03/14 05:32:10 DEBUG : Local file system at /tmp/rclone1599678426: Waiting for checks to finish 2022/03/14 05:32:10 DEBUG : Local file system at /tmp/rclone1599678426: Waiting for transfers to finish 2022/03/14 05:32:12 DEBUG : sub dir/hello world: md5 = 5eb63bbbe01eeed093cb22bb8f5acdc3 OK 2022/03/14 05:32:12 INFO : sub dir/hello world: Copied (new) 2022/03/14 05:32:14 DEBUG : sub dir: Rmdir: contains trashed file: "hello world.bin" 2022/03/14 05:32:14 DEBUG : sub dir: Rmdir: contains trashed file: "hello world.json" --- PASS: TestCopyRedownload (10.51s) === RUN TestSyncBasedOnCheckSum run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9", Local "Local file system at /tmp/rclone1599678426", Modify Window "1ms" 2022/03/14 05:32:15 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for checks to finish 2022/03/14 05:32:15 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for transfers to finish 2022/03/14 05:32:18 DEBUG : check sum: md5 = 336d5ebc5436534e61d16e63ddfca327 OK 2022/03/14 05:32:18 INFO : check sum: Copied (new) 2022/03/14 05:32:18 DEBUG : Waiting for deletions to finish 2022/03/14 05:32:19 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for checks to finish 2022/03/14 05:32:20 DEBUG : check sum: md5 = 336d5ebc5436534e61d16e63ddfca327 OK 2022/03/14 05:32:20 DEBUG : check sum: Size and md5 of src and dst objects identical 2022/03/14 05:32:20 DEBUG : check sum: Unchanged skipping 2022/03/14 05:32:20 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for transfers to finish 2022/03/14 05:32:20 DEBUG : Waiting for deletions to finish 2022/03/14 05:32:20 INFO : There was nothing to transfer --- PASS: TestSyncBasedOnCheckSum (8.89s) === RUN TestSyncSizeOnly run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9", Local "Local file system at /tmp/rclone1599678426", Modify Window "1ms" 2022/03/14 05:32:24 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for checks to finish 2022/03/14 05:32:24 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for transfers to finish 2022/03/14 05:32:27 DEBUG : sizeonly: md5 = 8ee2027983915ec78acc45027d874316 OK 2022/03/14 05:32:27 INFO : sizeonly: Copied (new) 2022/03/14 05:32:27 DEBUG : Waiting for deletions to finish 2022/03/14 05:32:28 DEBUG : sizeonly: Sizes identical 2022/03/14 05:32:28 DEBUG : sizeonly: Unchanged skipping 2022/03/14 05:32:28 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for checks to finish 2022/03/14 05:32:28 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for transfers to finish 2022/03/14 05:32:28 DEBUG : Waiting for deletions to finish 2022/03/14 05:32:28 INFO : There was nothing to transfer --- PASS: TestSyncSizeOnly (7.91s) === RUN TestSyncIgnoreSize run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9", Local "Local file system at /tmp/rclone1599678426", Modify Window "1ms" 2022/03/14 05:32:32 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for checks to finish 2022/03/14 05:32:32 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for transfers to finish 2022/03/14 05:32:34 DEBUG : ignore-size: md5 = 98bf7d8c15784f0a3d63204441e1e2aa OK 2022/03/14 05:32:34 INFO : ignore-size: Copied (new) 2022/03/14 05:32:34 DEBUG : Waiting for deletions to finish 2022/03/14 05:32:36 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for checks to finish 2022/03/14 05:32:36 DEBUG : ignore-size: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/14 05:32:36 DEBUG : ignore-size: Unchanged skipping 2022/03/14 05:32:36 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for transfers to finish 2022/03/14 05:32:36 DEBUG : Waiting for deletions to finish 2022/03/14 05:32:36 INFO : There was nothing to transfer --- PASS: TestSyncIgnoreSize (7.26s) === RUN TestSyncIgnoreTimes run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9", Local "Local file system at /tmp/rclone1599678426", Modify Window "1ms" 2022/03/14 05:32:43 DEBUG : existing: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/14 05:32:43 DEBUG : existing: Unchanged skipping 2022/03/14 05:32:43 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for checks to finish 2022/03/14 05:32:43 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for transfers to finish 2022/03/14 05:32:43 DEBUG : Waiting for deletions to finish 2022/03/14 05:32:43 INFO : There was nothing to transfer 2022/03/14 05:32:43 DEBUG : existing: Transferring unconditionally as --ignore-times is in use 2022/03/14 05:32:43 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for checks to finish 2022/03/14 05:32:43 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for transfers to finish 2022/03/14 05:32:47 DEBUG : existing: md5 = 8ee2027983915ec78acc45027d874316 OK 2022/03/14 05:32:47 INFO : existing: Copied (replaced existing) 2022/03/14 05:32:47 DEBUG : Waiting for deletions to finish --- PASS: TestSyncIgnoreTimes (11.11s) === RUN TestSyncIgnoreExisting run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9", Local "Local file system at /tmp/rclone1599678426", Modify Window "1ms" 2022/03/14 05:32:50 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for checks to finish 2022/03/14 05:32:50 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for transfers to finish 2022/03/14 05:32:53 DEBUG : existing: md5 = 8ee2027983915ec78acc45027d874316 OK 2022/03/14 05:32:53 INFO : existing: Copied (new) 2022/03/14 05:32:53 DEBUG : Waiting for deletions to finish 2022/03/14 05:32:54 DEBUG : existing: Destination exists, skipping 2022/03/14 05:32:54 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for checks to finish 2022/03/14 05:32:54 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for transfers to finish 2022/03/14 05:32:54 DEBUG : Waiting for deletions to finish 2022/03/14 05:32:54 INFO : There was nothing to transfer --- PASS: TestSyncIgnoreExisting (7.56s) === RUN TestSyncIgnoreErrors run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9", Local "Local file system at /tmp/rclone1599678426", Modify Window "1ms" 2022/03/14 05:33:06 DEBUG : d: Making directory 2022/03/14 05:33:10 DEBUG : c/non empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/14 05:33:10 DEBUG : c/non empty space: Unchanged skipping 2022/03/14 05:33:10 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for checks to finish 2022/03/14 05:33:10 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for transfers to finish 2022/03/14 05:33:14 DEBUG : a/potato2: md5 = d6548b156ea68a4e003e786df99eee76 OK 2022/03/14 05:33:14 INFO : a/potato2: Copied (new) 2022/03/14 05:33:14 DEBUG : Waiting for deletions to finish 2022/03/14 05:33:15 INFO : b/potato: Deleted 2022/03/14 05:33:15 INFO : d: Removing directory 2022/03/14 05:33:16 INFO : b: Removing directory 2022/03/14 05:33:16 DEBUG : b: Rmdir: contains trashed file: "potato.json" 2022/03/14 05:33:16 DEBUG : b: Rmdir: contains trashed file: "potato.bin" 2022/03/14 05:33:17 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: deleted 2 directories 2022/03/14 05:33:23 DEBUG : c: Rmdir: contains trashed file: "non empty space.json" 2022/03/14 05:33:23 DEBUG : c: Rmdir: contains trashed file: "non empty space.bin" 2022/03/14 05:33:23 DEBUG : a: Rmdir: contains trashed file: "potato2.bin" 2022/03/14 05:33:23 DEBUG : a: Rmdir: contains trashed file: "potato2.json" --- PASS: TestSyncIgnoreErrors (26.66s) === RUN TestSyncAfterChangingModtimeOnly run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9", Local "Local file system at /tmp/rclone1599678426", Modify Window "1ms" 2022/03/14 05:33:29 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for checks to finish 2022/03/14 05:33:29 DEBUG : empty space: Modification times differ by -95456h54m52.624456789s: 2011-12-25 12:59:59.123456789 +0000 UTC, 2001-02-03 04:05:06.499 +0000 UTC 2022/03/14 05:33:30 DEBUG : empty space: md5 = 336d5ebc5436534e61d16e63ddfca327 OK 2022/03/14 05:33:30 NOTICE: empty space: Skipped update modification time as --dry-run is set (size 1) 2022/03/14 05:33:30 DEBUG : empty space: Unchanged skipping 2022/03/14 05:33:30 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for transfers to finish 2022/03/14 05:33:30 DEBUG : Waiting for deletions to finish 2022/03/14 05:33:30 INFO : There was nothing to transfer 2022/03/14 05:33:31 DEBUG : empty space: Modification times differ by -95456h54m52.624456789s: 2011-12-25 12:59:59.123456789 +0000 UTC, 2001-02-03 04:05:06.499 +0000 UTC 2022/03/14 05:33:31 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for checks to finish 2022/03/14 05:33:32 DEBUG : empty space: md5 = 336d5ebc5436534e61d16e63ddfca327 OK 2022/03/14 05:33:33 INFO : empty space: Updated modification time in destination 2022/03/14 05:33:33 DEBUG : empty space: Unchanged skipping 2022/03/14 05:33:33 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for transfers to finish 2022/03/14 05:33:33 DEBUG : Waiting for deletions to finish 2022/03/14 05:33:33 INFO : There was nothing to transfer --- PASS: TestSyncAfterChangingModtimeOnly (11.47s) === RUN TestSyncAfterChangingModtimeOnlyWithNoUpdateModTime run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9", Local "Local file system at /tmp/rclone1599678426", Modify Window "1ms" 2022/03/14 05:33:40 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for checks to finish 2022/03/14 05:33:40 DEBUG : empty space: Modification times differ by -95456h54m52.624456789s: 2011-12-25 12:59:59.123456789 +0000 UTC, 2001-02-03 04:05:06.499 +0000 UTC 2022/03/14 05:33:41 DEBUG : empty space: md5 = 336d5ebc5436534e61d16e63ddfca327 OK 2022/03/14 05:33:41 DEBUG : empty space: Unchanged skipping 2022/03/14 05:33:41 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for transfers to finish 2022/03/14 05:33:41 DEBUG : Waiting for deletions to finish 2022/03/14 05:33:41 INFO : There was nothing to transfer --- PASS: TestSyncAfterChangingModtimeOnlyWithNoUpdateModTime (8.29s) === RUN TestSyncDoesntUpdateModtime run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9", Local "Local file system at /tmp/rclone1599678426", Modify Window "1ms" 2022/03/14 05:33:48 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for checks to finish 2022/03/14 05:33:48 DEBUG : foo: Modification times differ by -95456h54m52.624456789s: 2011-12-25 12:59:59.123456789 +0000 UTC, 2001-02-03 04:05:06.499 +0000 UTC 2022/03/14 05:33:49 DEBUG : foo: md5 = acbd18db4cc2f85cedef654fccc4a4d8 (Local file system at /tmp/rclone1599678426) 2022/03/14 05:33:49 DEBUG : foo: md5 = 37b51d194a7513e45b56f6524f2d51f2 (Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9) 2022/03/14 05:33:49 DEBUG : foo: md5 differ 2022/03/14 05:33:49 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for transfers to finish 2022/03/14 05:33:51 DEBUG : foo: md5 = acbd18db4cc2f85cedef654fccc4a4d8 OK 2022/03/14 05:33:51 INFO : foo: Copied (replaced existing) 2022/03/14 05:33:51 DEBUG : Waiting for deletions to finish --- PASS: TestSyncDoesntUpdateModtime (10.66s) === RUN TestSyncAfterAddingAFile run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9", Local "Local file system at /tmp/rclone1599678426", Modify Window "1ms" 2022/03/14 05:33:59 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/14 05:33:59 DEBUG : empty space: Unchanged skipping 2022/03/14 05:33:59 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for checks to finish 2022/03/14 05:33:59 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for transfers to finish 2022/03/14 05:34:02 DEBUG : potato: md5 = d6548b156ea68a4e003e786df99eee76 OK 2022/03/14 05:34:02 INFO : potato: Copied (new) 2022/03/14 05:34:02 DEBUG : Waiting for deletions to finish --- PASS: TestSyncAfterAddingAFile (12.22s) === RUN TestSyncAfterChangingFilesSizeOnly run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9", Local "Local file system at /tmp/rclone1599678426", Modify Window "1ms" 2022/03/14 05:34:11 DEBUG : potato: Sizes differ (src 21 vs dst 60) 2022/03/14 05:34:11 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for checks to finish 2022/03/14 05:34:11 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for transfers to finish 2022/03/14 05:34:14 DEBUG : potato: md5 = 100defcf18c42a1e0dc42a789b107cd2 OK 2022/03/14 05:34:14 INFO : potato: Copied (replaced existing) 2022/03/14 05:34:14 DEBUG : Waiting for deletions to finish --- PASS: TestSyncAfterChangingFilesSizeOnly (10.32s) === RUN TestSyncAfterChangingContentsOnly run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9", Local "Local file system at /tmp/rclone1599678426", Modify Window "1ms" 2022/03/14 05:34:21 DEBUG : potato: Modification times differ by 119h59m59.876543211s: 2011-12-25 12:59:59.123456789 +0000 UTC, 2011-12-30 12:59:59 +0000 UTC 2022/03/14 05:34:21 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for checks to finish 2022/03/14 05:34:22 DEBUG : potato: md5 = e4cb6955d9106df6263c45fcfc10f163 (Local file system at /tmp/rclone1599678426) 2022/03/14 05:34:22 DEBUG : potato: md5 = 100defcf18c42a1e0dc42a789b107cd2 (Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9) 2022/03/14 05:34:22 DEBUG : potato: md5 differ 2022/03/14 05:34:22 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for transfers to finish 2022/03/14 05:34:25 DEBUG : potato: md5 = e4cb6955d9106df6263c45fcfc10f163 OK 2022/03/14 05:34:25 INFO : potato: Copied (replaced existing) 2022/03/14 05:34:25 DEBUG : Waiting for deletions to finish --- PASS: TestSyncAfterChangingContentsOnly (10.69s) === RUN TestSyncAfterRemovingAFileAndAddingAFileDryRun run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9", Local "Local file system at /tmp/rclone1599678426", Modify Window "1ms" 2022/03/14 05:34:34 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for checks to finish 2022/03/14 05:34:34 NOTICE: potato2: Skipped copy as --dry-run is set (size 60) 2022/03/14 05:34:34 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/14 05:34:34 DEBUG : empty space: Unchanged skipping 2022/03/14 05:34:34 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for transfers to finish 2022/03/14 05:34:34 DEBUG : Waiting for deletions to finish 2022/03/14 05:34:34 NOTICE: potato: Skipped delete as --dry-run is set (size 21) --- PASS: TestSyncAfterRemovingAFileAndAddingAFileDryRun (11.54s) === RUN TestSyncAfterRemovingAFileAndAddingAFile run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9", Local "Local file system at /tmp/rclone1599678426", Modify Window "1ms" 2022/03/14 05:34:48 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/14 05:34:48 DEBUG : empty space: Unchanged skipping 2022/03/14 05:34:48 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for checks to finish 2022/03/14 05:34:48 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for transfers to finish 2022/03/14 05:34:51 DEBUG : potato2: md5 = d6548b156ea68a4e003e786df99eee76 OK 2022/03/14 05:34:51 INFO : potato2: Copied (new) 2022/03/14 05:34:51 DEBUG : Waiting for deletions to finish 2022/03/14 05:34:52 INFO : potato: Deleted --- PASS: TestSyncAfterRemovingAFileAndAddingAFile (17.61s) === RUN TestSyncAfterRemovingAFileAndAddingAFileSubDir run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9", Local "Local file system at /tmp/rclone1599678426", Modify Window "1ms" 2022/03/14 05:35:02 DEBUG : pacer: low level retry 1/1 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/14 05:35:02 DEBUG : pacer: Rate limited, increasing sleep to 1.591719538s run.go:283: Retry Put of "c/non empty space" to Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: 1/10 (googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/14 05:35:04 DEBUG : pacer: Reducing sleep to 0s 2022/03/14 05:35:08 DEBUG : d: Making directory 2022/03/14 05:35:08 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/14 05:35:08 DEBUG : pacer: Rate limited, increasing sleep to 1.673243084s 2022/03/14 05:35:09 DEBUG : pacer: Reducing sleep to 0s 2022/03/14 05:35:09 DEBUG : d/e: Making directory 2022/03/14 05:35:15 DEBUG : c/non empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/14 05:35:15 DEBUG : c/non empty space: Unchanged skipping 2022/03/14 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) 2022/03/14 05:35:15 DEBUG : pacer: Rate limited, increasing sleep to 1.558131163s 2022/03/14 05:35:16 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/14 05:35:16 DEBUG : pacer: Rate limited, increasing sleep to 2.251808822s 2022/03/14 05:35:18 DEBUG : pacer: Reducing sleep to 0s 2022/03/14 05:35:19 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for checks to finish 2022/03/14 05:35:19 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for transfers to finish 2022/03/14 05:35:22 DEBUG : a/potato2: md5 = d6548b156ea68a4e003e786df99eee76 OK 2022/03/14 05:35:22 INFO : a/potato2: Copied (new) 2022/03/14 05:35:22 DEBUG : Waiting for deletions to finish 2022/03/14 05:35:23 INFO : b/potato: Deleted 2022/03/14 05:35:23 INFO : d/e: Removing directory 2022/03/14 05:35:24 INFO : d: Removing directory 2022/03/14 05:35:24 DEBUG : d: Rmdir: contains trashed file: "e" 2022/03/14 05:35:24 INFO : b: Removing directory 2022/03/14 05:35:25 DEBUG : b: Rmdir: contains trashed file: "potato.json" 2022/03/14 05:35:25 DEBUG : b: Rmdir: contains trashed file: "potato.bin" 2022/03/14 05:35:25 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: deleted 3 directories 2022/03/14 05:35:25 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/14 05:35:25 DEBUG : pacer: Rate limited, increasing sleep to 1.829958975s 2022/03/14 05:35:26 DEBUG : pacer: Reducing sleep to 0s 2022/03/14 05:35:29 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/14 05:35:29 DEBUG : pacer: Rate limited, increasing sleep to 1.445002696s 2022/03/14 05:35:30 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/14 05:35:30 DEBUG : pacer: Rate limited, increasing sleep to 2.001710544s 2022/03/14 05:35:31 DEBUG : pacer: Reducing sleep to 0s 2022/03/14 05:35:34 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/14 05:35:34 DEBUG : pacer: Rate limited, increasing sleep to 1.912951854s 2022/03/14 05:35:34 DEBUG : pacer: Reducing sleep to 0s 2022/03/14 05:35:37 DEBUG : c: Rmdir: contains trashed file: "non empty space.bin" 2022/03/14 05:35:37 DEBUG : c: Rmdir: contains trashed file: "non empty space.json" 2022/03/14 05:35:38 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/14 05:35:38 DEBUG : pacer: Rate limited, increasing sleep to 1.501783876s 2022/03/14 05:35:38 DEBUG : pacer: Reducing sleep to 0s 2022/03/14 05:35:38 DEBUG : a: Rmdir: contains trashed file: "potato2.bin" 2022/03/14 05:35:38 DEBUG : a: Rmdir: contains trashed file: "potato2.json" --- PASS: TestSyncAfterRemovingAFileAndAddingAFileSubDir (43.01s) === RUN TestSyncAfterRemovingAFileAndAddingAFileSubDirWithErrors run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9", Local "Local file system at /tmp/rclone1599678426", Modify Window "1ms" 2022/03/14 05:35:41 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/14 05:35:41 DEBUG : pacer: Rate limited, increasing sleep to 1.431546114s 2022/03/14 05:35:41 DEBUG : pacer: Reducing sleep to 0s 2022/03/14 05:35:45 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/14 05:35:45 DEBUG : pacer: Rate limited, increasing sleep to 1.141005985s 2022/03/14 05:35:45 DEBUG : pacer: Reducing sleep to 0s 2022/03/14 05:35:49 DEBUG : d: Making directory 2022/03/14 05:35:49 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/14 05:35:49 DEBUG : pacer: Rate limited, increasing sleep to 1.903451634s 2022/03/14 05:35:50 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/14 05:35:50 DEBUG : pacer: Rate limited, increasing sleep to 2.099931852s 2022/03/14 05:35:52 DEBUG : pacer: Reducing sleep to 0s 2022/03/14 05:35:56 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for checks to finish 2022/03/14 05:35:56 DEBUG : c/non empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/14 05:35:56 DEBUG : c/non empty space: Unchanged skipping 2022/03/14 05:35:56 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for transfers to finish 2022/03/14 05:36:00 DEBUG : a/potato2: md5 = d6548b156ea68a4e003e786df99eee76 OK 2022/03/14 05:36:00 INFO : a/potato2: Copied (new) 2022/03/14 05:36:00 ERROR : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: not deleting files as there were IO errors 2022/03/14 05:36:00 ERROR : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: not deleting directories as there were IO errors 2022/03/14 05:36:08 DEBUG : c: Rmdir: contains trashed file: "non empty space.bin" 2022/03/14 05:36:08 DEBUG : c: Rmdir: contains trashed file: "non empty space.json" 2022/03/14 05:36:09 DEBUG : b: Rmdir: contains trashed file: "potato.json" 2022/03/14 05:36:09 DEBUG : b: Rmdir: contains trashed file: "potato.bin" 2022/03/14 05:36:10 DEBUG : a: Rmdir: contains trashed file: "potato2.bin" 2022/03/14 05:36:10 DEBUG : a: Rmdir: contains trashed file: "potato2.json" --- PASS: TestSyncAfterRemovingAFileAndAddingAFileSubDirWithErrors (30.58s) === RUN TestSyncDeleteAfter --- PASS: TestSyncDeleteAfter (0.00s) === RUN TestSyncDeleteDuring run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9", Local "Local file system at /tmp/rclone1599678426", Modify Window "1ms" 2022/03/14 05:36:18 DEBUG : Waiting for deletions to finish 2022/03/14 05:36:19 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/14 05:36:19 DEBUG : empty space: Unchanged skipping 2022/03/14 05:36:19 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for checks to finish 2022/03/14 05:36:19 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for transfers to finish 2022/03/14 05:36: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) 2022/03/14 05:36:19 DEBUG : pacer: Rate limited, increasing sleep to 1.298806182s 2022/03/14 05:36:20 DEBUG : pacer: Reducing sleep to 0s 2022/03/14 05:36:20 INFO : potato: Deleted 2022/03/14 05:36:22 DEBUG : potato2: md5 = d6548b156ea68a4e003e786df99eee76 OK 2022/03/14 05:36:22 INFO : potato2: Copied (new) --- PASS: TestSyncDeleteDuring (16.96s) === RUN TestSyncDeleteBefore run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9", Local "Local file system at /tmp/rclone1599678426", Modify Window "1ms" 2022/03/14 05:36:35 DEBUG : Waiting for deletions to finish 2022/03/14 05:36:36 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for checks to finish 2022/03/14 05:36:36 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for transfers to finish 2022/03/14 05:36:37 INFO : potato: Deleted 2022/03/14 05:36:37 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for checks to finish 2022/03/14 05:36:37 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/14 05:36:37 DEBUG : empty space: Unchanged skipping 2022/03/14 05:36:37 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for transfers to finish 2022/03/14 05:36:40 DEBUG : potato2: md5 = d6548b156ea68a4e003e786df99eee76 OK 2022/03/14 05:36:40 INFO : potato2: Copied (new) --- PASS: TestSyncDeleteBefore (17.77s) === RUN TestCopyDeleteBefore run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9", Local "Local file system at /tmp/rclone1599678426", Modify Window "1ms" 2022/03/14 05:36:49 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for checks to finish 2022/03/14 05:36:49 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for transfers to finish 2022/03/14 05:36:52 DEBUG : potato2: md5 = 9519bc2e940e1696ea7365b4b81adedc OK 2022/03/14 05:36:52 INFO : potato2: Copied (new) --- PASS: TestCopyDeleteBefore (12.48s) === RUN TestSyncWithExclude run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9", Local "Local file system at /tmp/rclone1599678426", Modify Window "1ms" 2022/03/14 05:37:06 DEBUG : enormous: Excluded 2022/03/14 05:37:06 DEBUG : potato2: Excluded 2022/03/14 05:37:06 DEBUG : potato2: Excluded 2022/03/14 05:37:06 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for checks to finish 2022/03/14 05:37:06 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/14 05:37:06 DEBUG : empty space: Unchanged skipping 2022/03/14 05:37:06 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for transfers to finish 2022/03/14 05:37:06 DEBUG : Waiting for deletions to finish 2022/03/14 05:37:06 INFO : There was nothing to transfer 2022/03/14 05:37:08 DEBUG : enormous: Excluded 2022/03/14 05:37:08 DEBUG : potato2: Excluded 2022/03/14 05:37:08 DEBUG : potato2: Excluded 2022/03/14 05:37:08 DEBUG : empty space: Size and modification time the same (differ by 456.789µs, within tolerance 1ms) 2022/03/14 05:37:08 DEBUG : empty space: Unchanged skipping 2022/03/14 05:37:08 DEBUG : Local file system at /tmp/rclone1599678426: Waiting for checks to finish 2022/03/14 05:37:08 DEBUG : Local file system at /tmp/rclone1599678426: Waiting for transfers to finish 2022/03/14 05:37:08 DEBUG : Waiting for deletions to finish 2022/03/14 05:37:08 INFO : There was nothing to transfer --- PASS: TestSyncWithExclude (13.85s) === RUN TestSyncWithExcludeAndDeleteExcluded run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9", Local "Local file system at /tmp/rclone1599678426", Modify Window "1ms" 2022/03/14 05:37:14 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/14 05:37:14 DEBUG : pacer: Rate limited, increasing sleep to 1.651657975s 2022/03/14 05:37:15 DEBUG : pacer: Reducing sleep to 0s 2022/03/14 05:37:24 DEBUG : enormous: Excluded 2022/03/14 05:37:24 DEBUG : potato2: Excluded 2022/03/14 05:37:25 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for checks to finish 2022/03/14 05:37:25 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/14 05:37:25 DEBUG : empty space: Unchanged skipping 2022/03/14 05:37:25 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for transfers to finish 2022/03/14 05:37:25 DEBUG : Waiting for deletions to finish 2022/03/14 05:37:25 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/14 05:37:25 DEBUG : pacer: Rate limited, increasing sleep to 1.066323457s 2022/03/14 05:37:26 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/14 05:37:26 DEBUG : pacer: Rate limited, increasing sleep to 2.769217794s 2022/03/14 05:37:26 DEBUG : pacer: Reducing sleep to 0s 2022/03/14 05:37:26 INFO : enormous: Deleted 2022/03/14 05:37:27 INFO : potato2: Deleted 2022/03/14 05:37:27 INFO : There was nothing to transfer 2022/03/14 05:37:28 DEBUG : Local file system at /tmp/rclone1599678426: Waiting for checks to finish 2022/03/14 05:37:28 DEBUG : empty space: Size and modification time the same (differ by 456.789µs, within tolerance 1ms) 2022/03/14 05:37:28 DEBUG : empty space: Unchanged skipping 2022/03/14 05:37:28 DEBUG : Local file system at /tmp/rclone1599678426: Waiting for transfers to finish 2022/03/14 05:37:28 DEBUG : Waiting for deletions to finish 2022/03/14 05:37:28 INFO : enormous: Deleted 2022/03/14 05:37:28 INFO : potato2: Deleted 2022/03/14 05:37:28 INFO : There was nothing to transfer --- PASS: TestSyncWithExcludeAndDeleteExcluded (18.55s) === RUN TestSyncWithUpdateOlder run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9", Local "Local file system at /tmp/rclone1599678426", Modify Window "1ms" 2022/03/14 05:37:31 DEBUG : pacer: low level retry 1/1 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/14 05:37:31 DEBUG : pacer: Rate limited, increasing sleep to 1.769122422s run.go:283: Retry Put of "one" to Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: 1/10 (googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/14 05:37:33 DEBUG : pacer: Reducing sleep to 0s 2022/03/14 05:37:37 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/14 05:37:37 DEBUG : pacer: Rate limited, increasing sleep to 1.587723852s 2022/03/14 05:37:37 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/14 05:37:37 DEBUG : pacer: Rate limited, increasing sleep to 2.974033204s 2022/03/14 05:37:39 DEBUG : pacer: Reducing sleep to 0s 2022/03/14 05:37:45 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/14 05:37:45 DEBUG : pacer: Rate limited, increasing sleep to 1.662239962s 2022/03/14 05:37:45 DEBUG : pacer: Reducing sleep to 0s 2022/03/14 05:37:56 DEBUG : four: Sizes differ (src 4 vs dst 8) 2022/03/14 05:37:56 DEBUG : four: Destination mod time is within 1s of source but files differ, transferring 2022/03/14 05:37:56 DEBUG : three: Sizes identical 2022/03/14 05:37:56 DEBUG : three: Destination mod time is within 1s of source and files identical, skipping 2022/03/14 05:37:56 DEBUG : one: Destination is newer than source, skipping 2022/03/14 05:37:56 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for checks to finish 2022/03/14 05:37:57 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/14 05:37:57 DEBUG : pacer: Rate limited, increasing sleep to 1.424385788s 2022/03/14 05:37:57 DEBUG : pacer: Reducing sleep to 0s 2022/03/14 05:37:57 DEBUG : two: md5 = b8a9f715dbb64fd5c56e7783c6820a61 (Local file system at /tmp/rclone1599678426) 2022/03/14 05:37:57 DEBUG : two: md5 = 0f82d86afa0f5dc965c5c15aca58dcfb (Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9) 2022/03/14 05:37:57 DEBUG : two: md5 differ 2022/03/14 05:37:57 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for transfers to finish 2022/03/14 05:38:00 DEBUG : four: md5 = 8cbad96aced40b3838dd9f07f6ef5772 OK 2022/03/14 05:38:00 INFO : four: Copied (replaced existing) 2022/03/14 05:38:00 DEBUG : five: md5 = 30056e1cab7a61d256fc8edd970d14f5 OK 2022/03/14 05:38:00 INFO : five: Copied (new) 2022/03/14 05:38:01 DEBUG : two: md5 = b8a9f715dbb64fd5c56e7783c6820a61 OK 2022/03/14 05:38:01 INFO : two: Copied (replaced existing) 2022/03/14 05:38:01 DEBUG : Waiting for deletions to finish 2022/03/14 05:38:06 DEBUG : one: Destination is newer than source, skipping 2022/03/14 05:38:06 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for checks to finish 2022/03/14 05:38:07 DEBUG : three: md5 = 35d6d33467aae9a2e3dccb4b6b027878 (Local file system at /tmp/rclone1599678426) 2022/03/14 05:38:07 DEBUG : three: md5 = 413af0de1f97a2155acf2b8b26ab36e2 (Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9) 2022/03/14 05:38:07 DEBUG : three: md5 differ 2022/03/14 05:38:07 DEBUG : three: Destination mod time is within 1s of source but files differ, transferring 2022/03/14 05:38:07 DEBUG : five: md5 = 30056e1cab7a61d256fc8edd970d14f5 OK 2022/03/14 05:38:07 DEBUG : five: Size and md5 of src and dst objects identical 2022/03/14 05:38:07 DEBUG : five: Destination mod time is within 1s of source and files identical, skipping 2022/03/14 05:38:07 DEBUG : four: md5 = 8cbad96aced40b3838dd9f07f6ef5772 OK 2022/03/14 05:38:07 DEBUG : four: Size and md5 of src and dst objects identical 2022/03/14 05:38:07 DEBUG : four: Destination mod time is within 1s of source and files identical, skipping 2022/03/14 05:38:07 DEBUG : two: md5 = b8a9f715dbb64fd5c56e7783c6820a61 OK 2022/03/14 05:38:07 DEBUG : two: Size and md5 of src and dst objects identical 2022/03/14 05:38:07 DEBUG : two: Destination mod time is within 1s of source and files identical, skipping 2022/03/14 05:38:07 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for transfers to finish 2022/03/14 05:38:09 DEBUG : three: md5 = 35d6d33467aae9a2e3dccb4b6b027878 OK 2022/03/14 05:38:09 INFO : three: Copied (replaced existing) 2022/03/14 05:38:09 DEBUG : Waiting for deletions to finish 2022/03/14 05:38:10 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/14 05:38:10 DEBUG : pacer: Rate limited, increasing sleep to 1.056893917s 2022/03/14 05:38:10 DEBUG : pacer: Reducing sleep to 0s --- PASS: TestSyncWithUpdateOlder (51.28s) === RUN TestSyncWithMaxDuration sync_test.go:1009: Skipping test on non local remote --- SKIP: TestSyncWithMaxDuration (0.00s) === RUN TestSyncWithTrackRenames run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9", Local "Local file system at /tmp/rclone1599678426", Modify Window "1ms" sync_test.go:1058: Can track renames: true 2022/03/14 05:38:21 INFO : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Making map for --track-renames 2022/03/14 05:38:21 INFO : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Finished making map for --track-renames 2022/03/14 05:38:21 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for checks to finish 2022/03/14 05:38:21 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for renames to finish 2022/03/14 05:38:21 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for transfers to finish 2022/03/14 05:38:24 DEBUG : yam: md5 = 48dc443644c4b89556dc06834b46451d OK 2022/03/14 05:38:24 INFO : yam: Copied (new) 2022/03/14 05:38:25 DEBUG : potato: md5 = 7f6fa9ddec9bfebda9510af0323fd696 OK 2022/03/14 05:38:25 INFO : potato: Copied (new) 2022/03/14 05:38:25 DEBUG : Waiting for deletions to finish 2022/03/14 05:38:27 DEBUG : potato: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/14 05:38:27 DEBUG : potato: Unchanged skipping 2022/03/14 05:38:27 INFO : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Making map for --track-renames 2022/03/14 05:38: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) 2022/03/14 05:38:28 DEBUG : pacer: Rate limited, increasing sleep to 1.014389307s 2022/03/14 05:38:28 DEBUG : pacer: Reducing sleep to 0s 2022/03/14 05:38:28 INFO : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Finished making map for --track-renames 2022/03/14 05:38:28 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for checks to finish 2022/03/14 05:38:28 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for renames to finish 2022/03/14 05:38:30 INFO : yam: Moved (server-side) to: yaml 2022/03/14 05:38:30 INFO : yaml: Renamed from "yam" 2022/03/14 05:38:30 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for transfers to finish 2022/03/14 05:38:30 DEBUG : Waiting for deletions to finish 2022/03/14 05:38:30 INFO : There was nothing to transfer --- PASS: TestSyncWithTrackRenames (13.74s) === RUN TestParseRenamesStrategyModtime --- PASS: TestParseRenamesStrategyModtime (0.00s) === RUN TestRenamesStrategyModtime --- PASS: TestRenamesStrategyModtime (0.00s) === RUN TestSyncWithTrackRenamesStrategyModtime run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9", Local "Local file system at /tmp/rclone1599678426", Modify Window "1ms" sync_test.go:1127: Can track renames: true 2022/03/14 05:38:35 INFO : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Making map for --track-renames 2022/03/14 05:38:35 INFO : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Finished making map for --track-renames 2022/03/14 05:38:35 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for checks to finish 2022/03/14 05:38:35 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for renames to finish 2022/03/14 05:38:35 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for transfers to finish 2022/03/14 05:38:38 DEBUG : yam: md5 = 48dc443644c4b89556dc06834b46451d OK 2022/03/14 05:38:38 INFO : yam: Copied (new) 2022/03/14 05:38:38 DEBUG : potato: md5 = 7f6fa9ddec9bfebda9510af0323fd696 OK 2022/03/14 05:38:38 INFO : potato: Copied (new) 2022/03/14 05:38:38 DEBUG : Waiting for deletions to finish 2022/03/14 05:38:41 DEBUG : potato: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/14 05:38:41 DEBUG : potato: Unchanged skipping 2022/03/14 05:38:41 INFO : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Making map for --track-renames 2022/03/14 05:38:41 INFO : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Finished making map for --track-renames 2022/03/14 05:38:41 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for checks to finish 2022/03/14 05:38:41 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for renames to finish 2022/03/14 05:38:43 INFO : yam: Moved (server-side) to: yaml 2022/03/14 05:38:43 INFO : yaml: Renamed from "yam" 2022/03/14 05:38:43 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for transfers to finish 2022/03/14 05:38:43 DEBUG : Waiting for deletions to finish 2022/03/14 05:38:43 INFO : There was nothing to transfer 2022/03/14 05:38: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) 2022/03/14 05:38:47 DEBUG : pacer: Rate limited, increasing sleep to 1.890314562s 2022/03/14 05:38:47 DEBUG : pacer: Reducing sleep to 0s 2022/03/14 05:38:49 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/14 05:38:49 DEBUG : pacer: Rate limited, increasing sleep to 1.581336995s 2022/03/14 05:38:49 DEBUG : pacer: Reducing sleep to 0s --- PASS: TestSyncWithTrackRenamesStrategyModtime (15.90s) === RUN TestSyncWithTrackRenamesStrategyLeaf run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9", Local "Local file system at /tmp/rclone1599678426", Modify Window "1ms" sync_test.go:1163: Can track renames: true 2022/03/14 05:38:51 INFO : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Making map for --track-renames 2022/03/14 05:38:51 INFO : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Finished making map for --track-renames 2022/03/14 05:38:51 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for checks to finish 2022/03/14 05:38:51 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for renames to finish 2022/03/14 05:38:51 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for transfers to finish 2022/03/14 05:38:51 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/14 05:38:51 DEBUG : pacer: Rate limited, increasing sleep to 1.254684262s 2022/03/14 05:38:52 DEBUG : pacer: Reducing sleep to 0s 2022/03/14 05:38:56 DEBUG : potato: md5 = 7f6fa9ddec9bfebda9510af0323fd696 OK 2022/03/14 05:38:56 INFO : potato: Copied (new) 2022/03/14 05:38:56 DEBUG : sub/yam: md5 = 48dc443644c4b89556dc06834b46451d OK 2022/03/14 05:38:56 INFO : sub/yam: Copied (new) 2022/03/14 05:38:56 DEBUG : Waiting for deletions to finish 2022/03/14 05:38:56 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/14 05:38:56 DEBUG : pacer: Rate limited, increasing sleep to 1.019327517s 2022/03/14 05:38:56 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/14 05:38:56 DEBUG : pacer: Rate limited, increasing sleep to 2.529956398s 2022/03/14 05:38:57 DEBUG : pacer: Reducing sleep to 0s 2022/03/14 05:39:00 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/14 05:39:00 DEBUG : pacer: Rate limited, increasing sleep to 1.759512653s 2022/03/14 05:39:00 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/14 05:39:00 DEBUG : pacer: Rate limited, increasing sleep to 2.731471261s 2022/03/14 05:39:02 DEBUG : pacer: Reducing sleep to 0s 2022/03/14 05:39:06 DEBUG : potato: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/14 05:39:06 DEBUG : potato: Unchanged skipping 2022/03/14 05:39:06 INFO : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Making map for --track-renames 2022/03/14 05:39:06 INFO : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Finished making map for --track-renames 2022/03/14 05:39:06 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for checks to finish 2022/03/14 05:39:06 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for renames to finish 2022/03/14 05:39:09 INFO : sub/yam: Moved (server-side) to: yam 2022/03/14 05:39:09 INFO : yam: Renamed from "sub/yam" 2022/03/14 05:39:09 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for transfers to finish 2022/03/14 05:39:09 DEBUG : Waiting for deletions to finish 2022/03/14 05:39:09 INFO : There was nothing to transfer --- PASS: TestSyncWithTrackRenamesStrategyLeaf (24.27s) === RUN TestMoveWithDeleteEmptySrcDirs run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9", Local "Local file system at /tmp/rclone1599678426", Modify Window "1ms" 2022/03/14 05:39:15 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for checks to finish 2022/03/14 05:39:15 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for transfers to finish 2022/03/14 05:39:20 DEBUG : sub dir/hello world: md5 = 5eb63bbbe01eeed093cb22bb8f5acdc3 OK 2022/03/14 05:39:20 INFO : sub dir/hello world: Copied (new) 2022/03/14 05:39:20 INFO : sub dir/hello world: Deleted 2022/03/14 05:39:21 DEBUG : nested/sub dir/file: md5 = 83d3784ea62518eafc60e98d84f877ad OK 2022/03/14 05:39:21 INFO : nested/sub dir/file: Copied (new) 2022/03/14 05:39:21 INFO : nested/sub dir/file: Deleted 2022/03/14 05:39:21 INFO : sub dir: Removing directory 2022/03/14 05:39:21 INFO : nested/sub dir: Removing directory 2022/03/14 05:39:21 INFO : nested: Removing directory 2022/03/14 05:39:21 DEBUG : Local file system at /tmp/rclone1599678426: deleted 3 directories 2022/03/14 05:39:28 DEBUG : sub dir: Rmdir: contains trashed file: "hello world.json" 2022/03/14 05:39:28 DEBUG : sub dir: Rmdir: contains trashed file: "hello world.bin" 2022/03/14 05:39: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) 2022/03/14 05:39:28 DEBUG : pacer: Rate limited, increasing sleep to 1.995573075s 2022/03/14 05:39: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) 2022/03/14 05:39:28 DEBUG : pacer: Rate limited, increasing sleep to 2.14232408s 2022/03/14 05:39:31 DEBUG : pacer: Reducing sleep to 0s 2022/03/14 05:39:31 DEBUG : nested/sub dir: Rmdir: contains trashed file: "file.json" 2022/03/14 05:39:31 DEBUG : nested/sub dir: Rmdir: contains trashed file: "file.bin" 2022/03/14 05:39:33 DEBUG : nested: Rmdir: contains trashed file: "sub dir" --- PASS: TestMoveWithDeleteEmptySrcDirs (18.79s) === RUN TestMoveWithoutDeleteEmptySrcDirs run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9", Local "Local file system at /tmp/rclone1599678426", Modify Window "1ms" 2022/03/14 05:39:34 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for checks to finish 2022/03/14 05:39:34 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for transfers to finish 2022/03/14 05:39:39 DEBUG : sub dir/hello world: md5 = 5eb63bbbe01eeed093cb22bb8f5acdc3 OK 2022/03/14 05:39:39 INFO : sub dir/hello world: Copied (new) 2022/03/14 05:39:39 INFO : sub dir/hello world: Deleted 2022/03/14 05:39:40 DEBUG : nested/sub dir/file: md5 = 83d3784ea62518eafc60e98d84f877ad OK 2022/03/14 05:39:40 INFO : nested/sub dir/file: Copied (new) 2022/03/14 05:39:40 INFO : nested/sub dir/file: Deleted 2022/03/14 05:39:46 DEBUG : sub dir: Rmdir: contains trashed file: "hello world.bin" 2022/03/14 05:39:46 DEBUG : sub dir: Rmdir: contains trashed file: "hello world.json" 2022/03/14 05:39:47 DEBUG : nested/sub dir: Rmdir: contains trashed file: "file.bin" 2022/03/14 05:39:47 DEBUG : nested/sub dir: Rmdir: contains trashed file: "file.json" 2022/03/14 05:39:48 DEBUG : nested: Rmdir: contains trashed file: "sub dir" 2022/03/14 05:39:48 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/14 05:39:48 DEBUG : pacer: Rate limited, increasing sleep to 1.850135593s 2022/03/14 05:39:49 DEBUG : pacer: Reducing sleep to 0s --- PASS: TestMoveWithoutDeleteEmptySrcDirs (14.79s) === RUN TestMoveWithIgnoreExisting run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9", Local "Local file system at /tmp/rclone1599678426", Modify Window "1ms" 2022/03/14 05:39:51 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for checks to finish 2022/03/14 05:39:51 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for transfers to finish 2022/03/14 05:39:53 DEBUG : existing-b: md5 = 006f87892f47ef9aa60fa5ed01a440fb OK 2022/03/14 05:39:53 INFO : existing-b: Copied (new) 2022/03/14 05:39:53 INFO : existing-b: Deleted 2022/03/14 05:39:54 DEBUG : existing: md5 = 8ee2027983915ec78acc45027d874316 OK 2022/03/14 05:39:54 INFO : existing: Copied (new) 2022/03/14 05:39:54 INFO : existing: Deleted 2022/03/14 05:39:56 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for checks to finish 2022/03/14 05:39:56 DEBUG : existing: Destination exists, skipping 2022/03/14 05:39:56 DEBUG : existing: Not removing source file as destination file exists and --ignore-existing is set 2022/03/14 05:39:56 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for transfers to finish 2022/03/14 05:39:56 INFO : There was nothing to transfer --- PASS: TestMoveWithIgnoreExisting (13.04s) === RUN TestServerSideMove run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9", Local "Local file system at /tmp/rclone1599678426", Modify Window "1ms" 2022/03/14 05:40:02 DEBUG : Creating backend with remote "TestCompressDrive:rclone-test-xevevox8nurubut6dijukek2" sync_test.go:1215: Server side move (if possible) Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9 -> Compressed: TestCompressDrive:rclone-test-xevevox8nurubut6dijukek2 2022/03/14 05:40:24 DEBUG : Compressed: TestCompressDrive:rclone-test-xevevox8nurubut6dijukek2: Using server-side directory move 2022/03/14 05:40:24 INFO : Compressed: TestCompressDrive:rclone-test-xevevox8nurubut6dijukek2: Server side directory move failed - fallback to file moves: can't copy directory - destination already exists 2022/03/14 05:40:24 DEBUG : empty space: Size and modification time the same (differ by 0s, within tolerance 1ms) 2022/03/14 05:40:24 DEBUG : empty space: Unchanged skipping 2022/03/14 05:40:24 DEBUG : potato3: Sizes differ (src 68 vs dst 60) 2022/03/14 05:40:24 DEBUG : Compressed: TestCompressDrive:rclone-test-xevevox8nurubut6dijukek2: Waiting for checks to finish 2022/03/14 05:40:25 INFO : empty space: Deleted 2022/03/14 05:40:25 DEBUG : Compressed: TestCompressDrive:rclone-test-xevevox8nurubut6dijukek2: Waiting for transfers to finish 2022/03/14 05:40:26 INFO : potato3: Deleted 2022/03/14 05:40:27 INFO : potato2: Moved (server-side) 2022/03/14 05:40:28 INFO : potato3: Moved (server-side) 2022/03/14 05:40:28 INFO : There was nothing to transfer 2022/03/14 05:40:31 DEBUG : Creating backend with remote "TestCompressDrive:rclone-test-monazug6fajonag0dewaduy9" 2022/03/14 05:40:32 DEBUG : Compressed: TestCompressDrive:rclone-test-monazug6fajonag0dewaduy9: Using server-side directory move 2022/03/14 05:40:33 INFO : Compressed: TestCompressDrive:rclone-test-monazug6fajonag0dewaduy9: Server side directory move succeeded 2022/03/14 05:40:36 DEBUG : Compressed: TestCompressDrive:rclone-test-monazug6fajonag0dewaduy9: Purge remote 2022/03/14 05:40:37 DEBUG : Compressed: TestCompressDrive:rclone-test-xevevox8nurubut6dijukek2: Purge remote 2022/03/14 05:40:37 purge failed: directory not found --- PASS: TestServerSideMove (35.98s) === RUN TestServerSideMoveWithFilter run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9", Local "Local file system at /tmp/rclone1599678426", Modify Window "1ms" 2022/03/14 05:40:38 DEBUG : Creating backend with remote "TestCompressDrive:rclone-test-qiwucud5bedobab9povoqum0" sync_test.go:1215: Server side move (if possible) Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9 -> Compressed: TestCompressDrive:rclone-test-qiwucud5bedobab9povoqum0 2022/03/14 05:41:00 DEBUG : empty space: Excluded 2022/03/14 05:41:00 DEBUG : empty space: Excluded 2022/03/14 05:41:00 DEBUG : potato3: Sizes differ (src 68 vs dst 60) 2022/03/14 05:41:00 DEBUG : Compressed: TestCompressDrive:rclone-test-qiwucud5bedobab9povoqum0: Waiting for checks to finish 2022/03/14 05:41:00 DEBUG : Compressed: TestCompressDrive:rclone-test-qiwucud5bedobab9povoqum0: Waiting for transfers to finish 2022/03/14 05:41:02 INFO : potato3: Deleted 2022/03/14 05:41:03 INFO : potato2: Moved (server-side) 2022/03/14 05:41:04 INFO : potato3: Moved (server-side) 2022/03/14 05:41:04 INFO : There was nothing to transfer 2022/03/14 05:41:08 DEBUG : Creating backend with remote "TestCompressDrive:rclone-test-povadov7fesisec8yodibix8" 2022/03/14 05:41:10 DEBUG : empty space: Excluded 2022/03/14 05:41:10 DEBUG : Compressed: TestCompressDrive:rclone-test-povadov7fesisec8yodibix8: Waiting for checks to finish 2022/03/14 05:41:10 DEBUG : Compressed: TestCompressDrive:rclone-test-povadov7fesisec8yodibix8: Waiting for transfers to finish 2022/03/14 05:41:13 INFO : potato2: Moved (server-side) 2022/03/14 05:41:14 INFO : potato3: Moved (server-side) 2022/03/14 05:41:14 INFO : There was nothing to transfer 2022/03/14 05:41:16 DEBUG : Compressed: TestCompressDrive:rclone-test-povadov7fesisec8yodibix8: Purge remote 2022/03/14 05:41:17 DEBUG : Compressed: TestCompressDrive:rclone-test-qiwucud5bedobab9povoqum0: Purge remote --- PASS: TestServerSideMoveWithFilter (41.61s) === RUN TestServerSideMoveDeleteEmptySourceDirs run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9", Local "Local file system at /tmp/rclone1599678426", Modify Window "1ms" 2022/03/14 05:41:19 DEBUG : Creating backend with remote "TestCompressDrive:rclone-test-kikiduw8yazehor5ziririm0" 2022/03/14 05:41:29 DEBUG : tomatoDir: Making directory sync_test.go:1215: Server side move (if possible) Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9 -> Compressed: TestCompressDrive:rclone-test-kikiduw8yazehor5ziririm0 2022/03/14 05:41:43 DEBUG : Compressed: TestCompressDrive:rclone-test-kikiduw8yazehor5ziririm0: Using server-side directory move 2022/03/14 05:41:43 INFO : Compressed: TestCompressDrive:rclone-test-kikiduw8yazehor5ziririm0: Server side directory move failed - fallback to file moves: can't copy directory - destination already exists 2022/03/14 05:41:43 DEBUG : empty space: Size and modification time the same (differ by 0s, within tolerance 1ms) 2022/03/14 05:41:43 DEBUG : empty space: Unchanged skipping 2022/03/14 05:41:43 DEBUG : potato3: Sizes differ (src 68 vs dst 60) 2022/03/14 05:41:43 DEBUG : Compressed: TestCompressDrive:rclone-test-kikiduw8yazehor5ziririm0: Waiting for checks to finish 2022/03/14 05:41:44 INFO : potato3: Deleted 2022/03/14 05:41:44 INFO : empty space: Deleted 2022/03/14 05:41:44 DEBUG : Compressed: TestCompressDrive:rclone-test-kikiduw8yazehor5ziririm0: Waiting for transfers to finish 2022/03/14 05:41:45 INFO : potato2: Moved (server-side) 2022/03/14 05:41:47 INFO : potato3: Moved (server-side) 2022/03/14 05:41:47 INFO : tomatoDir: Removing directory 2022/03/14 05:41:48 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: deleted 1 directories 2022/03/14 05:41:48 INFO : There was nothing to transfer 2022/03/14 05:41:51 DEBUG : Creating backend with remote "TestCompressDrive:rclone-test-donilor6lerimov4fiximir8" 2022/03/14 05:41:52 DEBUG : tomatoDir: Making directory 2022/03/14 05:41:53 DEBUG : Compressed: TestCompressDrive:rclone-test-donilor6lerimov4fiximir8: Using server-side directory move 2022/03/14 05:41:54 INFO : Compressed: TestCompressDrive:rclone-test-donilor6lerimov4fiximir8: Server side directory move succeeded 2022/03/14 05:41:57 DEBUG : Compressed: TestCompressDrive:rclone-test-donilor6lerimov4fiximir8: Purge remote 2022/03/14 05:41:58 DEBUG : Compressed: TestCompressDrive:rclone-test-kikiduw8yazehor5ziririm0: Purge remote 2022/03/14 05:41:58 purge failed: directory not found --- PASS: TestServerSideMoveDeleteEmptySourceDirs (39.47s) === RUN TestServerSideMoveOverlap run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9", Local "Local file system at /tmp/rclone1599678426", Modify Window "1ms" sync_test.go:1399: Skipping test as remote supports DirMove --- SKIP: TestServerSideMoveOverlap (0.51s) === RUN TestSyncOverlap run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9", Local "Local file system at /tmp/rclone1599678426", Modify Window "1ms" 2022/03/14 05:41:59 DEBUG : Creating backend with remote "TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9/rclone-sync-test" --- PASS: TestSyncOverlap (2.86s) === RUN TestSyncCompareDest run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9", Local "Local file system at /tmp/rclone1599678426", Modify Window "1ms" 2022/03/14 05:42:02 DEBUG : Creating backend with remote "TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9/dst" 2022/03/14 05:42:04 DEBUG : Creating backend with remote "TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9/CompareDest" 2022/03/14 05:42:07 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9/dst: Waiting for checks to finish 2022/03/14 05:42:07 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9/dst: Waiting for transfers to finish 2022/03/14 05:42:11 DEBUG : one: md5 = f97c5d29941bfb1b2fdab0874906ab82 OK 2022/03/14 05:42:11 INFO : one: Copied (new) 2022/03/14 05:42:11 DEBUG : Waiting for deletions to finish 2022/03/14 05:42:15 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9/dst: Waiting for checks to finish 2022/03/14 05:42:15 DEBUG : one: Sizes differ (src 5 vs dst 3) 2022/03/14 05:42:15 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9/dst: Waiting for transfers to finish 2022/03/14 05:42:18 DEBUG : one: md5 = 07912d142f5d63ee918b34796b5a2432 OK 2022/03/14 05:42:18 INFO : one: Copied (replaced existing) 2022/03/14 05:42:18 DEBUG : Waiting for deletions to finish 2022/03/14 05:42:30 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9/dst: Waiting for checks to finish 2022/03/14 05:42:32 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/14 05:42:32 DEBUG : one: Destination found in --compare-dest, skipping 2022/03/14 05:42:32 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9/dst: Waiting for transfers to finish 2022/03/14 05:42:32 DEBUG : Waiting for deletions to finish 2022/03/14 05:42:32 INFO : There was nothing to transfer 2022/03/14 05:42:42 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/14 05:42:42 DEBUG : two: Destination found in --compare-dest, skipping 2022/03/14 05:42:42 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9/dst: Waiting for checks to finish 2022/03/14 05:42:43 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/14 05:42:43 DEBUG : one: Destination found in --compare-dest, skipping 2022/03/14 05:42:43 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9/dst: Waiting for transfers to finish 2022/03/14 05:42:43 DEBUG : Waiting for deletions to finish 2022/03/14 05:42:43 INFO : There was nothing to transfer 2022/03/14 05:42:48 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/14 05:42:48 DEBUG : two: Destination found in --compare-dest, skipping 2022/03/14 05:42:48 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9/dst: Waiting for checks to finish 2022/03/14 05:42:49 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/14 05:42:49 DEBUG : one: Destination found in --compare-dest, skipping 2022/03/14 05:42:49 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9/dst: Waiting for transfers to finish 2022/03/14 05:42:49 DEBUG : Waiting for deletions to finish 2022/03/14 05:42:49 INFO : There was nothing to transfer 2022/03/14 05:42:55 DEBUG : two: Modification times differ by -119h59m59.877s: 2011-12-30 12:59:59 +0000 UTC, 2011-12-25 12:59:59.123 +0000 UTC 2022/03/14 05:42:55 DEBUG : two: md5 = b8a9f715dbb64fd5c56e7783c6820a61 OK 2022/03/14 05:42:55 DEBUG : two: Destination found in --compare-dest, skipping 2022/03/14 05:42:55 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9/dst: Waiting for checks to finish 2022/03/14 05:42:56 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/14 05:42:56 DEBUG : one: Destination found in --compare-dest, skipping 2022/03/14 05:42:56 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9/dst: Waiting for transfers to finish 2022/03/14 05:42:56 DEBUG : Waiting for deletions to finish 2022/03/14 05:42:56 INFO : There was nothing to transfer 2022/03/14 05:43:04 DEBUG : two: Sizes differ (src 5 vs dst 3) 2022/03/14 05:43:04 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9/dst: Waiting for checks to finish 2022/03/14 05:43:05 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/14 05:43:05 DEBUG : one: Destination found in --compare-dest, skipping 2022/03/14 05:43:05 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9/dst: Waiting for transfers to finish 2022/03/14 05:43:07 DEBUG : two: md5 = 2379e4ce8c3380e996ab0509f17069ad OK 2022/03/14 05:43:07 INFO : two: Copied (new) 2022/03/14 05:43:07 DEBUG : Waiting for deletions to finish 2022/03/14 05:43:17 DEBUG : dst: Rmdir: contains trashed file: "two.bin" 2022/03/14 05:43:17 DEBUG : dst: Rmdir: contains trashed file: "two.json" 2022/03/14 05:43:17 DEBUG : dst: Rmdir: contains trashed file: "one.bin" 2022/03/14 05:43:17 DEBUG : dst: Rmdir: contains trashed file: "one.json" 2022/03/14 05:43:18 DEBUG : CompareDest: Rmdir: contains trashed file: "one.json" 2022/03/14 05:43:18 DEBUG : CompareDest: Rmdir: contains trashed file: "two.json" 2022/03/14 05:43:18 DEBUG : CompareDest: Rmdir: contains trashed file: "one.bin" 2022/03/14 05:43:18 DEBUG : CompareDest: Rmdir: contains trashed file: "two.bin" --- PASS: TestSyncCompareDest (76.95s) === RUN TestSyncMultipleCompareDest run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9", Local "Local file system at /tmp/rclone1599678426", Modify Window "1ms" 2022/03/14 05:43:30 DEBUG : Creating backend with remote "TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9/dest" 2022/03/14 05:43:32 DEBUG : Creating backend with remote "TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9/pre-dest1" 2022/03/14 05:43:34 DEBUG : Creating backend with remote "TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9/pre-dest2" 2022/03/14 05:43:37 DEBUG : 1: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/14 05:43:37 DEBUG : 1: Destination found in --compare-dest, skipping 2022/03/14 05:43:39 DEBUG : 2: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/14 05:43:39 DEBUG : 2: Destination found in --compare-dest, skipping 2022/03/14 05:43:40 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9/dest: Waiting for checks to finish 2022/03/14 05:43:40 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9/dest: Waiting for transfers to finish 2022/03/14 05:43:43 DEBUG : 3: md5 = eccbc87e4b5ce2fe28308fd9f2a7baf3 OK 2022/03/14 05:43:43 INFO : 3: Copied (new) 2022/03/14 05:43:43 DEBUG : Waiting for deletions to finish 2022/03/14 05:43:53 DEBUG : pre-dest2: Rmdir: contains trashed file: "2.json" 2022/03/14 05:43:53 DEBUG : pre-dest2: Rmdir: contains trashed file: "2.bin" 2022/03/14 05:43:54 DEBUG : pre-dest1: Rmdir: contains trashed file: "1.bin" 2022/03/14 05:43:54 DEBUG : pre-dest1: Rmdir: contains trashed file: "1.json" 2022/03/14 05:43:55 DEBUG : dest: Rmdir: contains trashed file: "3.bin" 2022/03/14 05:43:55 DEBUG : dest: Rmdir: contains trashed file: "3.json" --- PASS: TestSyncMultipleCompareDest (36.48s) === RUN TestSyncCopyDest run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9", Local "Local file system at /tmp/rclone1599678426", Modify Window "1ms" 2022/03/14 05:43:56 DEBUG : Creating backend with remote "TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9/dst" 2022/03/14 05:43:58 DEBUG : Creating backend with remote "TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9/CopyDest" 2022/03/14 05:44:01 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9/dst: Waiting for checks to finish 2022/03/14 05:44:01 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9/dst: Waiting for transfers to finish 2022/03/14 05:44:04 DEBUG : one: md5 = f97c5d29941bfb1b2fdab0874906ab82 OK 2022/03/14 05:44:04 INFO : one: Copied (new) 2022/03/14 05:44:04 DEBUG : Waiting for deletions to finish 2022/03/14 05:44:08 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9/dst: Waiting for checks to finish 2022/03/14 05:44:08 DEBUG : one: Sizes differ (src 5 vs dst 3) 2022/03/14 05:44:08 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9/dst: Waiting for transfers to finish 2022/03/14 05:44:11 DEBUG : one: md5 = 07912d142f5d63ee918b34796b5a2432 OK 2022/03/14 05:44:11 INFO : one: Copied (replaced existing) 2022/03/14 05:44:11 DEBUG : Waiting for deletions to finish 2022/03/14 05:44:23 DEBUG : Creating backend with remote "TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9/BackupDir" 2022/03/14 05:44:26 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9/dst: Waiting for checks to finish 2022/03/14 05:44:27 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/14 05:44:27 DEBUG : one: Sizes differ (src 5 vs dst 3) 2022/03/14 05:44:31 INFO : one: Moved (server-side) 2022/03/14 05:44:34 DEBUG : one: md5 = 07912d142f5d63ee918b34796b5a2432 OK 2022/03/14 05:44:34 INFO : one: Copied (server-side copy) 2022/03/14 05:44:34 DEBUG : one: Destination found in --copy-dest, using server-side copy 2022/03/14 05:44:34 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9/dst: Waiting for transfers to finish 2022/03/14 05:44:34 DEBUG : Waiting for deletions to finish 2022/03/14 05:44:46 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/14 05:44:49 DEBUG : two: md5 = b8a9f715dbb64fd5c56e7783c6820a61 OK 2022/03/14 05:44:49 INFO : two: Copied (server-side copy) 2022/03/14 05:44:49 DEBUG : two: Destination found in --copy-dest, using server-side copy 2022/03/14 05:44:49 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9/dst: Waiting for checks to finish 2022/03/14 05:44:50 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/14 05:44:50 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/14 05:44:50 DEBUG : one: Unchanged skipping 2022/03/14 05:44:50 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9/dst: Waiting for transfers to finish 2022/03/14 05:44:50 DEBUG : Waiting for deletions to finish 2022/03/14 05:44:56 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9/dst: Waiting for checks to finish 2022/03/14 05:44:57 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/14 05:44:57 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/14 05:44:57 DEBUG : one: Unchanged skipping 2022/03/14 05:44:57 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/14 05:44:57 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/14 05:44:57 DEBUG : two: Unchanged skipping 2022/03/14 05:44:57 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9/dst: Waiting for transfers to finish 2022/03/14 05:44:57 DEBUG : Waiting for deletions to finish 2022/03/14 05:44:57 INFO : There was nothing to transfer 2022/03/14 05:45:12 DEBUG : three: Sizes differ (src 7 vs dst 5) 2022/03/14 05:45:12 DEBUG : three: Destination not found in --copy-dest 2022/03/14 05:45:12 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9/dst: Waiting for checks to finish 2022/03/14 05:45:13 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/14 05:45:13 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/14 05:45:13 DEBUG : one: Unchanged skipping 2022/03/14 05:45:13 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/14 05:45:13 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/03/14 05:45:13 DEBUG : two: Unchanged skipping 2022/03/14 05:45:13 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9/dst: Waiting for transfers to finish 2022/03/14 05:45:15 DEBUG : three: md5 = 1bccb9dccb3e9f6a3f9d2a8bdb54b7f5 OK 2022/03/14 05:45:15 INFO : three: Copied (new) 2022/03/14 05:45:15 DEBUG : Waiting for deletions to finish 2022/03/14 05:45:33 DEBUG : dst: Rmdir: contains trashed file: "three.json" 2022/03/14 05:45:33 DEBUG : dst: Rmdir: contains trashed file: "three.bin" 2022/03/14 05:45:33 DEBUG : dst: Rmdir: contains trashed file: "two.json" 2022/03/14 05:45:33 DEBUG : dst: Rmdir: contains trashed file: "one.json" 2022/03/14 05:45:33 DEBUG : dst: Rmdir: contains trashed file: "two.bin" 2022/03/14 05:45:33 DEBUG : dst: Rmdir: contains trashed file: "one.bin" 2022/03/14 05:45:34 DEBUG : CopyDest: Rmdir: contains trashed file: "one.bin" 2022/03/14 05:45:34 DEBUG : CopyDest: Rmdir: contains trashed file: "two.bin" 2022/03/14 05:45:34 DEBUG : CopyDest: Rmdir: contains trashed file: "three.bin" 2022/03/14 05:45:34 DEBUG : CopyDest: Rmdir: contains trashed file: "one.json" 2022/03/14 05:45:34 DEBUG : CopyDest: Rmdir: contains trashed file: "two.json" 2022/03/14 05:45:34 DEBUG : CopyDest: Rmdir: contains trashed file: "three.json" 2022/03/14 05:45:35 DEBUG : BackupDir: Rmdir: contains trashed file: "one.json" 2022/03/14 05:45:35 DEBUG : BackupDir: Rmdir: contains trashed file: "one.bin" --- PASS: TestSyncCopyDest (99.75s) === RUN TestSyncBackupDir run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9", Local "Local file system at /tmp/rclone1599678426", Modify Window "1ms" 2022/03/14 05:45:48 DEBUG : Creating backend with remote "TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9/dst" 2022/03/14 05:45:50 DEBUG : Creating backend with remote "TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9/backup" 2022/03/14 05:45:52 DEBUG : one: Sizes differ (src 4 vs dst 3) 2022/03/14 05:45:52 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9/dst: Waiting for checks to finish 2022/03/14 05:45:52 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/14 05:45:52 DEBUG : two: Unchanged skipping 2022/03/14 05:45:56 INFO : one: Moved (server-side) 2022/03/14 05:45:56 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9/dst: Waiting for transfers to finish 2022/03/14 05:45:59 DEBUG : one: md5 = c7957179c41f69d44f217a108c7915d8 OK 2022/03/14 05:45:59 INFO : one: Copied (new) 2022/03/14 05:45:59 DEBUG : Waiting for deletions to finish 2022/03/14 05:46:02 INFO : three.txt: Moved (server-side) 2022/03/14 05:46:02 INFO : three.txt: Moved into backup dir 2022/03/14 05:46:14 DEBUG : one: Sizes differ (src 5 vs dst 4) 2022/03/14 05:46:14 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/14 05:46:14 DEBUG : two: Unchanged skipping 2022/03/14 05:46:14 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9/dst: Waiting for checks to finish 2022/03/14 05:46:17 INFO : one: Deleted 2022/03/14 05:46:19 INFO : one: Moved (server-side) 2022/03/14 05:46:19 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9/dst: Waiting for transfers to finish 2022/03/14 05:46:22 DEBUG : one: md5 = 0f93e81041f0cab37c37a05ae998b219 OK 2022/03/14 05:46:22 INFO : one: Copied (new) 2022/03/14 05:46:22 DEBUG : Waiting for deletions to finish 2022/03/14 05:46:24 INFO : three.txt: Deleted 2022/03/14 05:46:27 INFO : three.txt: Moved (server-side) 2022/03/14 05:46:27 INFO : three.txt: Moved into backup dir 2022/03/14 05:46:38 DEBUG : dst: Rmdir: contains trashed file: "one.bin" 2022/03/14 05:46:38 DEBUG : dst: Rmdir: contains trashed file: "one.json" 2022/03/14 05:46:38 DEBUG : dst: Rmdir: contains trashed file: "two.bin" 2022/03/14 05:46:38 DEBUG : dst: Rmdir: contains trashed file: "two.json" 2022/03/14 05:46:38 DEBUG : backup: Rmdir: contains trashed file: "one.bin" 2022/03/14 05:46:38 DEBUG : backup: Rmdir: contains trashed file: "three.txt.json" 2022/03/14 05:46:38 DEBUG : backup: Rmdir: contains trashed file: "three.txt.bin" 2022/03/14 05:46:38 DEBUG : backup: Rmdir: contains trashed file: "one.json" 2022/03/14 05:46:38 DEBUG : backup: Rmdir: contains trashed file: "three.txt.json" 2022/03/14 05:46:38 DEBUG : backup: Rmdir: contains trashed file: "one.json" 2022/03/14 05:46:38 DEBUG : backup: Rmdir: contains trashed file: "three.txt.bin" 2022/03/14 05:46:38 DEBUG : backup: Rmdir: contains trashed file: "one.bin" --- PASS: TestSyncBackupDir (63.91s) === RUN TestSyncBackupDirWithSuffix run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9", Local "Local file system at /tmp/rclone1599678426", Modify Window "1ms" 2022/03/14 05:46:53 DEBUG : Creating backend with remote "TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9/dst" 2022/03/14 05:46:54 DEBUG : Creating backend with remote "TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9/backup" 2022/03/14 05:46:56 DEBUG : one: Sizes differ (src 4 vs dst 3) 2022/03/14 05:46:56 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9/dst: Waiting for checks to finish 2022/03/14 05:46:56 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/14 05:46:56 DEBUG : two: Unchanged skipping 2022/03/14 05:47:00 INFO : one: Moved (server-side) to: one.bak 2022/03/14 05:47:00 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9/dst: Waiting for transfers to finish 2022/03/14 05:47:02 DEBUG : one: md5 = c7957179c41f69d44f217a108c7915d8 OK 2022/03/14 05:47:02 INFO : one: Copied (new) 2022/03/14 05:47:02 DEBUG : Waiting for deletions to finish 2022/03/14 05:47:05 INFO : three.txt: Moved (server-side) to: three.txt.bak 2022/03/14 05:47:05 INFO : three.txt: Moved into backup dir 2022/03/14 05:47:19 DEBUG : one: Sizes differ (src 5 vs dst 4) 2022/03/14 05:47:19 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/14 05:47:19 DEBUG : two: Unchanged skipping 2022/03/14 05:47:19 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9/dst: Waiting for checks to finish 2022/03/14 05:47:20 INFO : one.bak: Deleted 2022/03/14 05:47:23 INFO : one: Moved (server-side) to: one.bak 2022/03/14 05:47:23 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9/dst: Waiting for transfers to finish 2022/03/14 05:47:25 DEBUG : one: md5 = 0f93e81041f0cab37c37a05ae998b219 OK 2022/03/14 05:47:25 INFO : one: Copied (new) 2022/03/14 05:47:25 DEBUG : Waiting for deletions to finish 2022/03/14 05:47:27 INFO : three.txt.bak: Deleted 2022/03/14 05:47:29 INFO : three.txt: Moved (server-side) to: three.txt.bak 2022/03/14 05:47:29 INFO : three.txt: Moved into backup dir 2022/03/14 05:47:40 DEBUG : dst: Rmdir: contains trashed file: "one.json" 2022/03/14 05:47:40 DEBUG : dst: Rmdir: contains trashed file: "one.bin" 2022/03/14 05:47:40 DEBUG : dst: Rmdir: contains trashed file: "two.json" 2022/03/14 05:47:40 DEBUG : dst: Rmdir: contains trashed file: "two.bin" 2022/03/14 05:47:41 DEBUG : backup: Rmdir: contains trashed file: "one.bak.bin" 2022/03/14 05:47:41 DEBUG : backup: Rmdir: contains trashed file: "one.bak.json" 2022/03/14 05:47:41 DEBUG : backup: Rmdir: contains trashed file: "three.txt.bak.bin" 2022/03/14 05:47:41 DEBUG : backup: Rmdir: contains trashed file: "three.txt.bak.json" 2022/03/14 05:47:41 DEBUG : backup: Rmdir: contains trashed file: "one.bak.json" 2022/03/14 05:47:41 DEBUG : backup: Rmdir: contains trashed file: "three.txt.bak.json" 2022/03/14 05:47:41 DEBUG : backup: Rmdir: contains trashed file: "three.txt.bak.bin" 2022/03/14 05:47:41 DEBUG : backup: Rmdir: contains trashed file: "one.bak.bin" --- PASS: TestSyncBackupDirWithSuffix (62.30s) === RUN TestSyncBackupDirWithSuffixKeepExtension run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9", Local "Local file system at /tmp/rclone1599678426", Modify Window "1ms" 2022/03/14 05:47:55 DEBUG : Creating backend with remote "TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9/dst" 2022/03/14 05:47:56 DEBUG : Creating backend with remote "TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9/backup" 2022/03/14 05:47:58 DEBUG : one: Sizes differ (src 4 vs dst 3) 2022/03/14 05:47:58 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/14 05:47:58 DEBUG : two: Unchanged skipping 2022/03/14 05:47:58 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9/dst: Waiting for checks to finish 2022/03/14 05:48:01 INFO : one: Moved (server-side) to: one-2019-01-01 2022/03/14 05:48:01 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9/dst: Waiting for transfers to finish 2022/03/14 05:48:04 DEBUG : one: md5 = c7957179c41f69d44f217a108c7915d8 OK 2022/03/14 05:48:04 INFO : one: Copied (new) 2022/03/14 05:48:04 DEBUG : Waiting for deletions to finish 2022/03/14 05:48:06 INFO : three.txt: Moved (server-side) to: three-2019-01-01.txt 2022/03/14 05:48:06 INFO : three.txt: Moved into backup dir 2022/03/14 05:48:18 DEBUG : one: Sizes differ (src 5 vs dst 4) 2022/03/14 05:48:18 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/14 05:48:18 DEBUG : two: Unchanged skipping 2022/03/14 05:48:18 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9/dst: Waiting for checks to finish 2022/03/14 05:48:20 INFO : one-2019-01-01: Deleted 2022/03/14 05:48:22 INFO : one: Moved (server-side) to: one-2019-01-01 2022/03/14 05:48:22 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9/dst: Waiting for transfers to finish 2022/03/14 05:48:25 DEBUG : one: md5 = 0f93e81041f0cab37c37a05ae998b219 OK 2022/03/14 05:48:25 INFO : one: Copied (new) 2022/03/14 05:48:25 DEBUG : Waiting for deletions to finish 2022/03/14 05:48:27 INFO : three-2019-01-01.txt: Deleted 2022/03/14 05:48:29 INFO : three.txt: Moved (server-side) to: three-2019-01-01.txt 2022/03/14 05:48:29 INFO : three.txt: Moved into backup dir 2022/03/14 05:48:40 DEBUG : dst: Rmdir: contains trashed file: "one.bin" 2022/03/14 05:48:40 DEBUG : dst: Rmdir: contains trashed file: "one.json" 2022/03/14 05:48:40 DEBUG : dst: Rmdir: contains trashed file: "two.json" 2022/03/14 05:48:40 DEBUG : dst: Rmdir: contains trashed file: "two.bin" 2022/03/14 05:48:41 DEBUG : backup: Rmdir: contains trashed file: "three-2019-01-01.txt.bin" 2022/03/14 05:48:41 DEBUG : backup: Rmdir: contains trashed file: "one-2019-01-01.json" 2022/03/14 05:48:41 DEBUG : backup: Rmdir: contains trashed file: "three-2019-01-01.txt.json" 2022/03/14 05:48:41 DEBUG : backup: Rmdir: contains trashed file: "one-2019-01-01.bin" 2022/03/14 05:48:41 DEBUG : backup: Rmdir: contains trashed file: "three-2019-01-01.txt.json" 2022/03/14 05:48:41 DEBUG : backup: Rmdir: contains trashed file: "one-2019-01-01.json" 2022/03/14 05:48:41 DEBUG : backup: Rmdir: contains trashed file: "one-2019-01-01.bin" 2022/03/14 05:48:41 DEBUG : backup: Rmdir: contains trashed file: "three-2019-01-01.txt.bin" --- PASS: TestSyncBackupDirWithSuffixKeepExtension (59.93s) === RUN TestSyncBackupDirSuffixOnly run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9", Local "Local file system at /tmp/rclone1599678426", Modify Window "1ms" 2022/03/14 05:48:55 DEBUG : Creating backend with remote "TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9/dst" 2022/03/14 05:48:56 DEBUG : one: Sizes differ (src 4 vs dst 3) 2022/03/14 05:48:56 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/14 05:48:56 DEBUG : two: Unchanged skipping 2022/03/14 05:48:56 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9/dst: Waiting for checks to finish 2022/03/14 05:48:59 INFO : one: Moved (server-side) to: one.bak 2022/03/14 05:48:59 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9/dst: Waiting for transfers to finish 2022/03/14 05:49:02 DEBUG : one: md5 = c7957179c41f69d44f217a108c7915d8 OK 2022/03/14 05:49:02 INFO : one: Copied (new) 2022/03/14 05:49:02 DEBUG : Waiting for deletions to finish 2022/03/14 05:49:04 INFO : three.txt: Moved (server-side) to: three.txt.bak 2022/03/14 05:49:04 INFO : three.txt: Moved into backup dir 2022/03/14 05:49:16 DEBUG : one.bak: Excluded 2022/03/14 05:49:16 DEBUG : three.txt.bak: Excluded 2022/03/14 05:49:16 DEBUG : one: Sizes differ (src 5 vs dst 4) 2022/03/14 05:49:16 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/14 05:49:16 DEBUG : two: Unchanged skipping 2022/03/14 05:49:16 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9/dst: Waiting for checks to finish 2022/03/14 05:49:17 INFO : one.bak: Deleted 2022/03/14 05:49:19 INFO : one: Moved (server-side) to: one.bak 2022/03/14 05:49:19 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9/dst: Waiting for transfers to finish 2022/03/14 05:49:22 DEBUG : one: md5 = 0f93e81041f0cab37c37a05ae998b219 OK 2022/03/14 05:49:22 INFO : one: Copied (new) 2022/03/14 05:49:22 DEBUG : Waiting for deletions to finish 2022/03/14 05:49:24 INFO : three.txt.bak: Deleted 2022/03/14 05:49:26 INFO : three.txt: Moved (server-side) to: three.txt.bak 2022/03/14 05:49:26 INFO : three.txt: Moved into backup dir 2022/03/14 05:49:36 DEBUG : dst: Rmdir: contains trashed file: "one.bin" 2022/03/14 05:49:36 DEBUG : dst: Rmdir: contains trashed file: "one.json" 2022/03/14 05:49:36 DEBUG : dst: Rmdir: contains trashed file: "one.bak.json" 2022/03/14 05:49:36 DEBUG : dst: Rmdir: contains trashed file: "three.txt.bak.bin" 2022/03/14 05:49:36 DEBUG : dst: Rmdir: contains trashed file: "three.txt.bak.json" 2022/03/14 05:49:36 DEBUG : dst: Rmdir: contains trashed file: "one.bak.bin" 2022/03/14 05:49:36 DEBUG : dst: Rmdir: contains trashed file: "one.bak.bin" 2022/03/14 05:49:36 DEBUG : dst: Rmdir: contains trashed file: "one.bak.json" 2022/03/14 05:49:36 DEBUG : dst: Rmdir: contains trashed file: "three.txt.bak.json" 2022/03/14 05:49:36 DEBUG : dst: Rmdir: contains trashed file: "three.txt.bak.bin" 2022/03/14 05:49:36 DEBUG : dst: Rmdir: contains trashed file: "two.json" 2022/03/14 05:49:36 DEBUG : dst: Rmdir: contains trashed file: "two.bin" --- PASS: TestSyncBackupDirSuffixOnly (55.75s) === RUN TestSyncSuffix run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9", Local "Local file system at /tmp/rclone1599678426", Modify Window "1ms" 2022/03/14 05:49:50 DEBUG : Creating backend with remote "TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9/dst" 2022/03/14 05:49:50 DEBUG : Config file has changed externaly - reloading 2022/03/14 05:49:53 DEBUG : one: Sizes differ (src 4 vs dst 3) 2022/03/14 05:49:54 INFO : one: Moved (server-side) to: one.bak 2022/03/14 05:49:57 DEBUG : one: md5 = c7957179c41f69d44f217a108c7915d8 OK 2022/03/14 05:49:57 INFO : one: Copied (new) 2022/03/14 05:49:58 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/14 05:49:58 DEBUG : two: Unchanged skipping 2022/03/14 05:49:59 DEBUG : three.txt: Sizes differ (src 6 vs dst 5) 2022/03/14 05:50:00 INFO : three.txt: Moved (server-side) to: three.txt.bak 2022/03/14 05:50:03 DEBUG : three.txt: md5 = 91341eed84691a83caea73aa785736d5 OK 2022/03/14 05:50:03 INFO : three.txt: Copied (new) 2022/03/14 05:50:13 DEBUG : one: Sizes differ (src 5 vs dst 4) 2022/03/14 05:50:15 INFO : one.bak: Deleted 2022/03/14 05:50:16 INFO : one: Moved (server-side) to: one.bak 2022/03/14 05:50:19 DEBUG : one: md5 = 0f93e81041f0cab37c37a05ae998b219 OK 2022/03/14 05:50:19 INFO : one: Copied (new) 2022/03/14 05:50:20 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/14 05:50:20 DEBUG : two: Unchanged skipping 2022/03/14 05:50:21 DEBUG : three.txt: Sizes differ (src 19 vs dst 6) 2022/03/14 05:50:23 INFO : three.txt.bak: Deleted 2022/03/14 05:50:24 INFO : three.txt: Moved (server-side) to: three.txt.bak 2022/03/14 05:50:27 DEBUG : three.txt: md5 = 423e01c5e84a30d129b97aedb6e219a9 OK 2022/03/14 05:50:27 INFO : three.txt: Copied (new) 2022/03/14 05:50:40 DEBUG : dst: Rmdir: contains trashed file: "one.bin" 2022/03/14 05:50:40 DEBUG : dst: Rmdir: contains trashed file: "three.txt.bin" 2022/03/14 05:50:40 DEBUG : dst: Rmdir: contains trashed file: "one.json" 2022/03/14 05:50:40 DEBUG : dst: Rmdir: contains trashed file: "three.txt.json" 2022/03/14 05:50:40 DEBUG : dst: Rmdir: contains trashed file: "one.bak.json" 2022/03/14 05:50:40 DEBUG : dst: Rmdir: contains trashed file: "one.bak.bin" 2022/03/14 05:50:40 DEBUG : dst: Rmdir: contains trashed file: "three.txt.bak.bin" 2022/03/14 05:50:40 DEBUG : dst: Rmdir: contains trashed file: "one.bak.bin" 2022/03/14 05:50:40 DEBUG : dst: Rmdir: contains trashed file: "three.txt.bak.json" 2022/03/14 05:50:40 DEBUG : dst: Rmdir: contains trashed file: "two.json" 2022/03/14 05:50:40 DEBUG : dst: Rmdir: contains trashed file: "three.txt.bak.json" 2022/03/14 05:50:40 DEBUG : dst: Rmdir: contains trashed file: "three.txt.bak.bin" 2022/03/14 05:50:40 DEBUG : dst: Rmdir: contains trashed file: "two.bin" 2022/03/14 05:50:40 DEBUG : dst: Rmdir: contains trashed file: "one.bak.json" --- PASS: TestSyncSuffix (63.39s) === RUN TestSyncSuffixKeepExtension run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9", Local "Local file system at /tmp/rclone1599678426", Modify Window "1ms" 2022/03/14 05:50:54 DEBUG : Creating backend with remote "TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9/dst" 2022/03/14 05:50:56 DEBUG : one: Sizes differ (src 4 vs dst 3) 2022/03/14 05:50:58 INFO : one: Moved (server-side) to: one-2019-01-01 2022/03/14 05:51:01 DEBUG : one: md5 = c7957179c41f69d44f217a108c7915d8 OK 2022/03/14 05:51:01 INFO : one: Copied (new) 2022/03/14 05:51:02 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/14 05:51:02 DEBUG : two: Unchanged skipping 2022/03/14 05:51:04 DEBUG : three.txt: Sizes differ (src 6 vs dst 5) 2022/03/14 05:51:05 INFO : three.txt: Moved (server-side) to: three-2019-01-01.txt 2022/03/14 05:51:08 DEBUG : three.txt: md5 = 91341eed84691a83caea73aa785736d5 OK 2022/03/14 05:51:08 INFO : three.txt: Copied (new) 2022/03/14 05:51:19 DEBUG : one: Sizes differ (src 5 vs dst 4) 2022/03/14 05:51:21 INFO : one-2019-01-01: Deleted 2022/03/14 05:51:22 INFO : one: Moved (server-side) to: one-2019-01-01 2022/03/14 05:51:25 DEBUG : one: md5 = 0f93e81041f0cab37c37a05ae998b219 OK 2022/03/14 05:51:25 INFO : one: Copied (new) 2022/03/14 05:51:26 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/14 05:51:26 DEBUG : two: Unchanged skipping 2022/03/14 05:51:27 DEBUG : three.txt: Sizes differ (src 19 vs dst 6) 2022/03/14 05:51:29 INFO : three-2019-01-01.txt: Deleted 2022/03/14 05:51:30 INFO : three.txt: Moved (server-side) to: three-2019-01-01.txt 2022/03/14 05:51:33 DEBUG : three.txt: md5 = 423e01c5e84a30d129b97aedb6e219a9 OK 2022/03/14 05:51:33 INFO : three.txt: Copied (new) 2022/03/14 05:51:46 DEBUG : dst: Rmdir: contains trashed file: "one.bin" 2022/03/14 05:51:46 DEBUG : dst: Rmdir: contains trashed file: "three.txt.bin" 2022/03/14 05:51:46 DEBUG : dst: Rmdir: contains trashed file: "three.txt.json" 2022/03/14 05:51:46 DEBUG : dst: Rmdir: contains trashed file: "one.json" 2022/03/14 05:51:46 DEBUG : dst: Rmdir: contains trashed file: "one-2019-01-01.bin" 2022/03/14 05:51:46 DEBUG : dst: Rmdir: contains trashed file: "one-2019-01-01.json" 2022/03/14 05:51:46 DEBUG : dst: Rmdir: contains trashed file: "three-2019-01-01.txt.json" 2022/03/14 05:51:46 DEBUG : dst: Rmdir: contains trashed file: "one-2019-01-01.json" 2022/03/14 05:51:46 DEBUG : dst: Rmdir: contains trashed file: "one-2019-01-01.bin" 2022/03/14 05:51:46 DEBUG : dst: Rmdir: contains trashed file: "three-2019-01-01.txt.bin" 2022/03/14 05:51:46 DEBUG : dst: Rmdir: contains trashed file: "two.bin" 2022/03/14 05:51:46 DEBUG : dst: Rmdir: contains trashed file: "three-2019-01-01.txt.bin" 2022/03/14 05:51:46 DEBUG : dst: Rmdir: contains trashed file: "three-2019-01-01.txt.json" 2022/03/14 05:51:46 DEBUG : dst: Rmdir: contains trashed file: "two.json" --- PASS: TestSyncSuffixKeepExtension (66.18s) === RUN TestSyncUTFNorm run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9", Local "Local file system at /tmp/rclone1599678426", Modify Window "1ms" 2022/03/14 05:51:51 DEBUG : Testêé: Sizes differ (src 14 vs dst 18) 2022/03/14 05:51:51 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for checks to finish 2022/03/14 05:51:51 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for transfers to finish 2022/03/14 05:51:54 DEBUG : Testêé: md5 = ce114e4501d2f4e2dcea3e17b546f339 OK 2022/03/14 05:51:54 INFO : Testêé: Copied (replaced existing) 2022/03/14 05:51:54 DEBUG : Waiting for deletions to finish --- PASS: TestSyncUTFNorm (10.86s) === RUN TestSyncImmutable run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9", Local "Local file system at /tmp/rclone1599678426", Modify Window "1ms" 2022/03/14 05:51:58 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for checks to finish 2022/03/14 05:51:58 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for transfers to finish 2022/03/14 05:52:01 DEBUG : existing: md5 = 8ee2027983915ec78acc45027d874316 OK 2022/03/14 05:52:01 INFO : existing: Copied (new) 2022/03/14 05:52:01 DEBUG : Waiting for deletions to finish 2022/03/14 05:52:04 DEBUG : existing: Sizes differ (src 8 vs dst 6) 2022/03/14 05:52:04 ERROR : existing: Source and destination exist but do not match: immutable file modified 2022/03/14 05:52:04 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for checks to finish 2022/03/14 05:52:04 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for transfers to finish 2022/03/14 05:52:04 ERROR : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: not deleting files as there were IO errors 2022/03/14 05:52:04 ERROR : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: not deleting directories as there were IO errors --- PASS: TestSyncImmutable (9.65s) === RUN TestSyncIgnoreCase run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9", Local "Local file system at /tmp/rclone1599678426", Modify Window "1ms" 2022/03/14 05:52:12 DEBUG : existing: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/14 05:52:12 DEBUG : existing: Unchanged skipping 2022/03/14 05:52:12 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for checks to finish 2022/03/14 05:52:12 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for transfers to finish 2022/03/14 05:52:12 DEBUG : Waiting for deletions to finish 2022/03/14 05:52:12 INFO : There was nothing to transfer --- PASS: TestSyncIgnoreCase (7.56s) === RUN TestMaxTransfer === RUN TestMaxTransfer/Hard run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9", Local "Local file system at /tmp/rclone1599678426", Modify Window "1ms" sync_test.go:1989: This test only runs on local === RUN TestMaxTransfer/Soft run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9", Local "Local file system at /tmp/rclone1599678426", Modify Window "1ms" sync_test.go:1989: This test only runs on local === RUN TestMaxTransfer/Cautious run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9", Local "Local file system at /tmp/rclone1599678426", Modify Window "1ms" sync_test.go:1989: This test only runs on local --- PASS: TestMaxTransfer (1.59s) --- SKIP: TestMaxTransfer/Hard (0.52s) --- SKIP: TestMaxTransfer/Soft (0.53s) --- SKIP: TestMaxTransfer/Cautious (0.54s) === RUN TestSyncConcurrentDelete run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9", Local "Local file system at /tmp/rclone1599678426", Modify Window "1ms" 2022/03/14 05:53:58 DEBUG : pacer: low level retry 1/1 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/14 05:53:58 DEBUG : pacer: Rate limited, increasing sleep to 1.261599687s 2022/03/14 05:53:58 DEBUG : pacer: Reducing sleep to 0s run.go:283: Retry Put of "only16" to Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: 1/10 (googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/14 05:54:54 DEBUG : both0: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/14 05:54:54 DEBUG : both0: Unchanged skipping 2022/03/14 05:54:54 DEBUG : both1: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/14 05:54:54 DEBUG : both1: Unchanged skipping 2022/03/14 05:54:54 DEBUG : both10: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/14 05:54:54 DEBUG : both10: Unchanged skipping 2022/03/14 05:54:54 DEBUG : both11: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/14 05:54:54 DEBUG : both11: Unchanged skipping 2022/03/14 05:54:54 DEBUG : both12: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/14 05:54:54 DEBUG : both12: Unchanged skipping 2022/03/14 05:54:54 DEBUG : both13: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/14 05:54:54 DEBUG : both13: Unchanged skipping 2022/03/14 05:54:54 DEBUG : both14: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/14 05:54:54 DEBUG : both14: Unchanged skipping 2022/03/14 05:54:54 DEBUG : both15: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/14 05:54:54 DEBUG : both15: Unchanged skipping 2022/03/14 05:54:54 DEBUG : both16: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/14 05:54:54 DEBUG : both16: Unchanged skipping 2022/03/14 05:54:54 DEBUG : both17: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/14 05:54:54 DEBUG : both17: Unchanged skipping 2022/03/14 05:54:54 DEBUG : both18: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/14 05:54:54 DEBUG : both18: Unchanged skipping 2022/03/14 05:54:54 DEBUG : both19: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/14 05:54:54 DEBUG : both19: Unchanged skipping 2022/03/14 05:54:54 DEBUG : both2: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/14 05:54:54 DEBUG : both2: Unchanged skipping 2022/03/14 05:54:54 DEBUG : both3: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/14 05:54:54 DEBUG : both3: Unchanged skipping 2022/03/14 05:54:54 DEBUG : both4: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/14 05:54:54 DEBUG : both4: Unchanged skipping 2022/03/14 05:54:54 DEBUG : both5: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/14 05:54:54 DEBUG : both5: Unchanged skipping 2022/03/14 05:54:54 DEBUG : both6: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/14 05:54:54 DEBUG : both6: Unchanged skipping 2022/03/14 05:54:54 DEBUG : both7: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/14 05:54:54 DEBUG : both7: Unchanged skipping 2022/03/14 05:54:54 DEBUG : both8: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/14 05:54:54 DEBUG : both8: Unchanged skipping 2022/03/14 05:54:54 DEBUG : both9: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/14 05:54:54 DEBUG : both9: Unchanged skipping 2022/03/14 05:54:54 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for checks to finish 2022/03/14 05:54:54 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for transfers to finish 2022/03/14 05:54:54 DEBUG : Waiting for deletions to finish 2022/03/14 05:54:55 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/14 05:54:55 DEBUG : pacer: Rate limited, increasing sleep to 1.893823036s 2022/03/14 05:54:56 DEBUG : pacer: Reducing sleep to 0s 2022/03/14 05:54:56 INFO : only8: Deleted 2022/03/14 05:54:56 INFO : only9: Deleted 2022/03/14 05:54:56 INFO : only2: Deleted 2022/03/14 05:54:56 INFO : only7: Deleted 2022/03/14 05:54:58 INFO : only15: Deleted 2022/03/14 05:54:58 INFO : only14: Deleted 2022/03/14 05:54:58 INFO : only12: Deleted 2022/03/14 05:54:59 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/14 05:54:59 DEBUG : pacer: Rate limited, increasing sleep to 1.160088526s 2022/03/14 05:54:59 DEBUG : pacer: Reducing sleep to 0s 2022/03/14 05:54:59 INFO : only11: Deleted 2022/03/14 05:55:01 INFO : only1: Deleted 2022/03/14 05:55:01 INFO : only19: Deleted 2022/03/14 05:55:01 INFO : only10: Deleted 2022/03/14 05:55:01 INFO : only4: Deleted 2022/03/14 05:55: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) 2022/03/14 05:55:02 DEBUG : pacer: Rate limited, increasing sleep to 1.827708745s 2022/03/14 05:55:02 DEBUG : pacer: Reducing sleep to 0s 2022/03/14 05:55:02 INFO : only16: Deleted 2022/03/14 05:55:02 INFO : only18: Deleted 2022/03/14 05:55:02 INFO : only17: Deleted 2022/03/14 05:55:04 INFO : only5: Deleted 2022/03/14 05:55:05 INFO : only6: Deleted 2022/03/14 05:55:05 INFO : only0: Deleted 2022/03/14 05:55:05 INFO : only3: Deleted 2022/03/14 05:55:05 INFO : only13: Deleted 2022/03/14 05:55:05 INFO : There was nothing to transfer 2022/03/14 05:55:07 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/14 05:55:07 DEBUG : pacer: Rate limited, increasing sleep to 1.599598095s 2022/03/14 05:55:07 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/14 05:55:07 DEBUG : pacer: Rate limited, increasing sleep to 2.545625377s 2022/03/14 05:55:09 DEBUG : pacer: Reducing sleep to 0s 2022/03/14 05:55:15 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/14 05:55:15 DEBUG : pacer: Rate limited, increasing sleep to 1.239011934s 2022/03/14 05:55:15 DEBUG : pacer: Reducing sleep to 0s 2022/03/14 05:55: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) 2022/03/14 05:55:28 DEBUG : pacer: Rate limited, increasing sleep to 1.024538668s 2022/03/14 05:55: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) 2022/03/14 05:55:28 DEBUG : pacer: Rate limited, increasing sleep to 2.041471465s 2022/03/14 05:55:29 DEBUG : pacer: Reducing sleep to 0s 2022/03/14 05:55:49 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/14 05:55:49 DEBUG : pacer: Rate limited, increasing sleep to 1.130314515s 2022/03/14 05:55:49 DEBUG : pacer: Reducing sleep to 0s --- PASS: TestSyncConcurrentDelete (214.54s) === RUN TestSyncConcurrentTruncate run.go:181: Remote "Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9", Local "Local file system at /tmp/rclone1599678426", Modify Window "1ms" 2022/03/14 05:56:34 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/14 05:56:34 DEBUG : pacer: Rate limited, increasing sleep to 1.274780051s 2022/03/14 05:56:34 DEBUG : pacer: Reducing sleep to 0s 2022/03/14 05:57: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) 2022/03/14 05:57:58 DEBUG : pacer: Rate limited, increasing sleep to 1.743609355s 2022/03/14 05:57:58 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/14 05:57:58 DEBUG : pacer: Rate limited, increasing sleep to 2.373500207s 2022/03/14 05:58:00 DEBUG : pacer: Reducing sleep to 0s 2022/03/14 05:58:17 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for checks to finish 2022/03/14 05:58:17 DEBUG : both1: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/14 05:58:17 DEBUG : both1: Unchanged skipping 2022/03/14 05:58:17 DEBUG : both0: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/14 05:58:17 DEBUG : both0: Unchanged skipping 2022/03/14 05:58:17 DEBUG : both10: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/14 05:58:17 DEBUG : both12: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/14 05:58:17 DEBUG : both10: Unchanged skipping 2022/03/14 05:58:17 DEBUG : both12: Unchanged skipping 2022/03/14 05:58:17 DEBUG : both13: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/14 05:58:17 DEBUG : both13: Unchanged skipping 2022/03/14 05:58:17 DEBUG : both15: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/14 05:58:17 DEBUG : both14: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/14 05:58:17 DEBUG : both15: Unchanged skipping 2022/03/14 05:58:17 DEBUG : both14: Unchanged skipping 2022/03/14 05:58:17 DEBUG : both11: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/14 05:58:17 DEBUG : both17: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/14 05:58:17 DEBUG : both11: Unchanged skipping 2022/03/14 05:58:17 DEBUG : both18: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/14 05:58:17 DEBUG : both17: Unchanged skipping 2022/03/14 05:58:17 DEBUG : both18: Unchanged skipping 2022/03/14 05:58:17 DEBUG : both2: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/14 05:58:17 DEBUG : both2: Unchanged skipping 2022/03/14 05:58:17 DEBUG : both19: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/14 05:58:17 DEBUG : both3: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/14 05:58:17 DEBUG : both4: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/14 05:58:17 DEBUG : both3: Unchanged skipping 2022/03/14 05:58:17 DEBUG : both4: Unchanged skipping 2022/03/14 05:58:17 DEBUG : both19: Unchanged skipping 2022/03/14 05:58:17 DEBUG : both6: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/14 05:58:17 DEBUG : both5: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/14 05:58:17 DEBUG : both6: Unchanged skipping 2022/03/14 05:58:17 DEBUG : both5: Unchanged skipping 2022/03/14 05:58:17 DEBUG : both7: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/14 05:58:17 DEBUG : both8: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/14 05:58:17 DEBUG : both8: Unchanged skipping 2022/03/14 05:58:17 DEBUG : both9: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/14 05:58:17 DEBUG : both7: Unchanged skipping 2022/03/14 05:58:17 DEBUG : only0: Sizes differ (src 0 vs dst 6) 2022/03/14 05:58:17 DEBUG : only1: Sizes differ (src 0 vs dst 6) 2022/03/14 05:58:17 DEBUG : only10: Sizes differ (src 0 vs dst 6) 2022/03/14 05:58:17 DEBUG : both16: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/03/14 05:58:17 DEBUG : only11: Sizes differ (src 0 vs dst 6) 2022/03/14 05:58:17 DEBUG : both16: Unchanged skipping 2022/03/14 05:58:17 DEBUG : only12: Sizes differ (src 0 vs dst 6) 2022/03/14 05:58:17 DEBUG : only14: Sizes differ (src 0 vs dst 6) 2022/03/14 05:58:17 DEBUG : only15: Sizes differ (src 0 vs dst 6) 2022/03/14 05:58:17 DEBUG : both9: Unchanged skipping 2022/03/14 05:58:17 DEBUG : only13: Sizes differ (src 0 vs dst 6) 2022/03/14 05:58:17 DEBUG : only19: Sizes differ (src 0 vs dst 6) 2022/03/14 05:58:17 DEBUG : only2: Sizes differ (src 0 vs dst 6) 2022/03/14 05:58:17 DEBUG : only3: Sizes differ (src 0 vs dst 6) 2022/03/14 05:58:17 DEBUG : only4: Sizes differ (src 0 vs dst 6) 2022/03/14 05:58:17 DEBUG : only5: Sizes differ (src 0 vs dst 6) 2022/03/14 05:58:17 DEBUG : only6: Sizes differ (src 0 vs dst 6) 2022/03/14 05:58:17 DEBUG : only7: Sizes differ (src 0 vs dst 6) 2022/03/14 05:58:17 DEBUG : only8: Sizes differ (src 0 vs dst 6) 2022/03/14 05:58:17 DEBUG : only9: Sizes differ (src 0 vs dst 6) 2022/03/14 05:58:17 DEBUG : only16: Sizes differ (src 0 vs dst 6) 2022/03/14 05:58:17 DEBUG : only17: Sizes differ (src 0 vs dst 6) 2022/03/14 05:58:17 DEBUG : only18: Sizes differ (src 0 vs dst 6) 2022/03/14 05:58:17 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Waiting for transfers to finish 2022/03/14 05:58:18 DEBUG : pacer: low level retry 1/1 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/14 05:58:18 DEBUG : pacer: Rate limited, increasing sleep to 1.780577196s 2022/03/14 05:58:18 DEBUG : pacer: low level retry 1/1 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/14 05:58:18 DEBUG : pacer: Rate limited, increasing sleep to 2.970738089s 2022/03/14 05:58:18 DEBUG : pacer: low level retry 1/1 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/14 05:58:18 DEBUG : pacer: Rate limited, increasing sleep to 4.92319533s 2022/03/14 05:58:18 DEBUG : pacer: low level retry 1/1 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/14 05:58:18 DEBUG : pacer: Rate limited, increasing sleep to 8.160825409s 2022/03/14 05:58:18 DEBUG : pacer: Reducing sleep to 0s 2022/03/14 05:58:18 DEBUG : only10: Received error: googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded - low level retry 1/10 2022/03/14 05:58:20 DEBUG : only0: Received error: googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded - low level retry 1/10 2022/03/14 05:58:20 DEBUG : only11: Received error: googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded - low level retry 1/10 2022/03/14 05:58:20 DEBUG : only1: Received error: googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded - low level retry 1/10 2022/03/14 05:58:22 DEBUG : only10: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2022/03/14 05:58:22 INFO : only10: Copied (replaced existing) 2022/03/14 05:58:22 DEBUG : only0: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2022/03/14 05:58:22 INFO : only0: Copied (replaced existing) 2022/03/14 05:58:22 DEBUG : only11: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2022/03/14 05:58:22 INFO : only11: Copied (replaced existing) 2022/03/14 05:58:22 DEBUG : only1: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2022/03/14 05:58:22 INFO : only1: Copied (replaced existing) 2022/03/14 05:58:25 DEBUG : only12: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2022/03/14 05:58:25 INFO : only12: Copied (replaced existing) 2022/03/14 05:58:25 DEBUG : only14: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2022/03/14 05:58:25 INFO : only14: Copied (replaced existing) 2022/03/14 05:58:25 DEBUG : only13: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2022/03/14 05:58:25 INFO : only13: Copied (replaced existing) 2022/03/14 05:58:25 DEBUG : only15: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2022/03/14 05:58:25 INFO : only15: Copied (replaced existing) 2022/03/14 05:58:27 DEBUG : pacer: low level retry 1/1 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/14 05:58:27 DEBUG : pacer: Rate limited, increasing sleep to 1.240758271s 2022/03/14 05:58: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) 2022/03/14 05:58:28 DEBUG : pacer: Rate limited, increasing sleep to 2.538479054s 2022/03/14 05:58:28 DEBUG : pacer: Reducing sleep to 0s 2022/03/14 05:58:28 DEBUG : only19: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2022/03/14 05:58:28 INFO : only19: Copied (replaced existing) 2022/03/14 05:58:28 DEBUG : only2: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2022/03/14 05:58:28 INFO : only2: Copied (replaced existing) 2022/03/14 05:58:28 DEBUG : only3: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2022/03/14 05:58:28 INFO : only3: Copied (replaced existing) 2022/03/14 05:58:29 DEBUG : only4: Received error: googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded - low level retry 1/10 2022/03/14 05:58:31 DEBUG : only5: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2022/03/14 05:58:31 INFO : only5: Copied (replaced existing) 2022/03/14 05:58:32 DEBUG : only7: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2022/03/14 05:58:32 INFO : only7: Copied (replaced existing) 2022/03/14 05:58:32 DEBUG : only6: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2022/03/14 05:58:32 INFO : only6: Copied (replaced existing) 2022/03/14 05:58:32 DEBUG : only4: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2022/03/14 05:58:32 INFO : only4: Copied (replaced existing) 2022/03/14 05:58:34 DEBUG : only8: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2022/03/14 05:58:34 INFO : only8: Copied (replaced existing) 2022/03/14 05:58:34 DEBUG : only16: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2022/03/14 05:58:34 INFO : only16: Copied (replaced existing) 2022/03/14 05:58:35 DEBUG : only17: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2022/03/14 05:58:35 INFO : only17: Copied (replaced existing) 2022/03/14 05:58:35 DEBUG : only9: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2022/03/14 05:58:35 INFO : only9: Copied (replaced existing) 2022/03/14 05:58:37 DEBUG : only18: md5 = d41d8cd98f00b204e9800998ecf8427e OK 2022/03/14 05:58:37 INFO : only18: Copied (replaced existing) 2022/03/14 05:58:37 DEBUG : Waiting for deletions to finish fstest.go:299: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:302: Flushing the directory cache fstest.go:299: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:302: Flushing the directory cache fstest.go:299: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:302: Flushing the directory cache fstest.go:306: Error Trace: fstest.go:306 fstest.go:339 fstest.go:351 run.go:342 sync_test.go:2058 sync_test.go:2066 Error: Should be true Test: TestSyncConcurrentTruncate Messages: listing wrong, want both0 (6), both1 (6), both10 (6), both11 (6), both12 (6), both13 (6), both14 (6), both15 (6), both16 (6), both17 (6), both18 (6), both19 (6), both2 (6), both3 (6), both4 (6), both5 (6), both6 (6), both7 (6), both8 (6), both9 (6), only0 (0), only1 (0), only10 (0), only11 (0), only12 (0), only13 (0), only14 (0), only15 (0), only16 (0), only17 (0), only18 (0), only19 (0), only2 (0), only3 (0), only4 (0), only5 (0), only6 (0), only7 (0), only8 (0), only9 (0) got both0 (6), both1 (6), both10 (6), both11 (6), both12 (6), both13 (6), both14 (6), both15 (6), both16 (6), both17 (6), both18 (6), both19 (6), both2 (6), both3 (6), both4 (6), both5 (6), both6 (6), both7 (6), both8 (6), both9 (6), only12 (0), only13 (0), only14 (0), only15 (0), only16 (0), only17 (0), only18 (0), only19 (0), only2 (0), only3 (0), only5 (0), only6 (0), only7 (0), only8 (0), only9 (0) 2022/03/14 05:58: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) 2022/03/14 05:58:58 DEBUG : pacer: Rate limited, increasing sleep to 1.53755367s 2022/03/14 05:58:58 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/14 05:58:58 DEBUG : pacer: Rate limited, increasing sleep to 2.678781858s 2022/03/14 05:59:00 DEBUG : pacer: Reducing sleep to 0s 2022/03/14 05:59:08 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/14 05:59:08 DEBUG : pacer: Rate limited, increasing sleep to 1.460840166s 2022/03/14 05:59:08 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/03/14 05:59:08 DEBUG : pacer: Rate limited, increasing sleep to 2.733307468s 2022/03/14 05:59:10 DEBUG : pacer: Reducing sleep to 0s fstest.go:204: Not found "only4" fstest.go:204: Not found "only10" fstest.go:204: Not found "only0" fstest.go:204: Not found "only1" fstest.go:204: Not found "only11" fstest.go:207: Error Trace: fstest.go:207 fstest.go:311 fstest.go:339 fstest.go:351 run.go:342 sync_test.go:2058 sync_test.go:2066 Error: Not equal: expected: 0 actual : 5 Test: TestSyncConcurrentTruncate Messages: 5 objects not found 2022/03/14 05:59: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) 2022/03/14 05:59:28 DEBUG : pacer: Rate limited, increasing sleep to 1.033023342s 2022/03/14 05:59: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) 2022/03/14 05:59:28 DEBUG : pacer: Rate limited, increasing sleep to 2.308252518s 2022/03/14 05:59:29 DEBUG : pacer: Reducing sleep to 0s --- FAIL: TestSyncConcurrentTruncate (256.89s) FAIL 2022/03/14 06:00:08 DEBUG : Compressed: TestCompressDrive:rclone-test-zexowem8hoyayix9nohikad9: Purge remote "./sync.test -test.v -test.timeout 1h0m0s -remote TestCompressDrive: -verbose" - Finished ERROR in 30m12.442364321s (try 1/5): exit status 1: Failed [TestSyncConcurrentTruncate]