"./sync.test -test.v -test.timeout 1h0m0s -remote TestCryptDrive: -verbose -fast-list" - Starting (try 1/5) 2022/01/13 06:08:00 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6" 2022/01/13 06:08:00 DEBUG : Using config file from "/home/rclone/.rclone.conf" 2022/01/13 06:08:00 DEBUG : Creating backend with remote "TestDrive:crypt/uisl9sq0nnijgh9rsquknl5hid8tgfd4ulloshk79oi1jpqjnrui2v5ped0l0af4qhlm0c9nu0uu8" 2022/01/13 06:08:02 DEBUG : Creating backend with remote "/tmp/rclone3693781112" === RUN TestPipe --- PASS: TestPipe (0.00s) === RUN TestPipeConcurrent --- PASS: TestPipeConcurrent (0.02s) === RUN TestPipeOrderBy === RUN TestPipeOrderBy/#00 === RUN TestPipeOrderBy/size === RUN TestPipeOrderBy/name === RUN TestPipeOrderBy/modtime === RUN TestPipeOrderBy/size,ascending === RUN TestPipeOrderBy/name,asc === RUN TestPipeOrderBy/modtime,ascending === RUN TestPipeOrderBy/size,descending === RUN TestPipeOrderBy/name,desc === RUN TestPipeOrderBy/modtime,descending === RUN TestPipeOrderBy/size,mixed,50 === RUN TestPipeOrderBy/size,mixed,51 --- PASS: TestPipeOrderBy (0.00s) --- PASS: TestPipeOrderBy/#00 (0.00s) --- PASS: TestPipeOrderBy/size (0.00s) --- PASS: TestPipeOrderBy/name (0.00s) --- PASS: TestPipeOrderBy/modtime (0.00s) --- PASS: TestPipeOrderBy/size,ascending (0.00s) --- PASS: TestPipeOrderBy/name,asc (0.00s) --- PASS: TestPipeOrderBy/modtime,ascending (0.00s) --- PASS: TestPipeOrderBy/size,descending (0.00s) --- PASS: TestPipeOrderBy/name,desc (0.00s) --- PASS: TestPipeOrderBy/modtime,descending (0.00s) --- PASS: TestPipeOrderBy/size,mixed,50 (0.00s) --- PASS: TestPipeOrderBy/size,mixed,51 (0.00s) === RUN TestNewLess === RUN TestNewLess/blankOK === RUN TestNewLess/tooManyParts === RUN TestNewLess/tooManyParts2 === RUN TestNewLess/badMixed === RUN TestNewLess/unknownComparison === RUN TestNewLess/unknownSortDirection === RUN TestNewLess/size === RUN TestNewLess/name === RUN TestNewLess/modtime === RUN TestNewLess/size,ascending === RUN TestNewLess/name,asc === RUN TestNewLess/modtime,ascending === RUN TestNewLess/size,descending === RUN TestNewLess/name,desc === RUN TestNewLess/modtime,descending === RUN TestNewLess/modtime,mixed === RUN TestNewLess/modtime,mixed,30 --- PASS: TestNewLess (0.00s) --- PASS: TestNewLess/blankOK (0.00s) --- PASS: TestNewLess/tooManyParts (0.00s) --- PASS: TestNewLess/tooManyParts2 (0.00s) --- PASS: TestNewLess/badMixed (0.00s) --- PASS: TestNewLess/unknownComparison (0.00s) --- PASS: TestNewLess/unknownSortDirection (0.00s) --- PASS: TestNewLess/size (0.00s) --- PASS: TestNewLess/name (0.00s) --- PASS: TestNewLess/modtime (0.00s) --- PASS: TestNewLess/size,ascending (0.00s) --- PASS: TestNewLess/name,asc (0.00s) --- PASS: TestNewLess/modtime,ascending (0.00s) --- PASS: TestNewLess/size,descending (0.00s) --- PASS: TestNewLess/name,desc (0.00s) --- PASS: TestNewLess/modtime,descending (0.00s) --- PASS: TestNewLess/modtime,mixed (0.00s) --- PASS: TestNewLess/modtime,mixed,30 (0.00s) === RUN TestRcCopy rc_test.go:16: Skipping test on non local remote --- SKIP: TestRcCopy (0.00s) === RUN TestRcMove rc_test.go:16: Skipping test on non local remote --- SKIP: TestRcMove (0.00s) === RUN TestRcSync rc_test.go:16: Skipping test on non local remote --- SKIP: TestRcSync (0.00s) === RUN TestCopyWithDryRun run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6'", Local "Local file system at /tmp/rclone3693781112", Modify Window "1ms" 2022/01/13 06:08:03 NOTICE: sub dir/hello world: Skipped copy as --dry-run is set (size 11) 2022/01/13 06:08:03 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for checks to finish 2022/01/13 06:08:03 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for transfers to finish --- PASS: TestCopyWithDryRun (1.77s) === RUN TestCopy run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6'", Local "Local file system at /tmp/rclone3693781112", Modify Window "1ms" 2022/01/13 06:08:04 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for checks to finish 2022/01/13 06:08:04 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for transfers to finish 2022/01/13 06:08:06 DEBUG : sub dir/hello world: md5 = b286e23a33fa8d5d0e195e2304754091 OK 2022/01/13 06:08:06 INFO : sub dir/hello world: Copied (new) 2022/01/13 06:08:08 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestCopy (5.10s) === RUN TestCopyMissingDirectory run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6'", Local "Local file system at /tmp/rclone3693781112", Modify Window "1ms" 2022/01/13 06:08:08 DEBUG : Creating backend with remote "/non-existing" 2022/01/13 06:08:09 ERROR : Local file system at /non-existing: error reading source root directory: directory not found 2022/01/13 06:08:09 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for checks to finish 2022/01/13 06:08:09 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for transfers to finish --- PASS: TestCopyMissingDirectory (0.73s) === RUN TestCopyNoTraverse run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6'", Local "Local file system at /tmp/rclone3693781112", Modify Window "1ms" 2022/01/13 06:08:09 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for checks to finish 2022/01/13 06:08:09 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for transfers to finish 2022/01/13 06:08:12 DEBUG : sub dir/hello world: md5 = 2ce01419d171291e04761ae56e467e8e OK 2022/01/13 06:08:12 INFO : sub dir/hello world: Copied (new) 2022/01/13 06:08:14 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestCopyNoTraverse (5.35s) === RUN TestCopyCheckFirst run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6'", Local "Local file system at /tmp/rclone3693781112", Modify Window "1ms" 2022/01/13 06:08:15 INFO : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Running all checks before starting transfers 2022/01/13 06:08:15 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for checks to finish 2022/01/13 06:08:15 INFO : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Checks finished, now starting transfers 2022/01/13 06:08:15 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for transfers to finish 2022/01/13 06:08:17 DEBUG : sub dir/hello world: md5 = cd5760635132eb244a463457e95e7689 OK 2022/01/13 06:08:17 INFO : sub dir/hello world: Copied (new) 2022/01/13 06:08:19 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestCopyCheckFirst (5.29s) === RUN TestSyncNoTraverse run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6'", Local "Local file system at /tmp/rclone3693781112", Modify Window "1ms" 2022/01/13 06:08:20 ERROR : Ignoring --no-traverse with sync 2022/01/13 06:08:20 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for checks to finish 2022/01/13 06:08:20 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for transfers to finish 2022/01/13 06:08:22 DEBUG : sub dir/hello world: md5 = 0ce342d96097edd24ffe1074b7072402 OK 2022/01/13 06:08:22 INFO : sub dir/hello world: Copied (new) 2022/01/13 06:08:22 DEBUG : Waiting for deletions to finish 2022/01/13 06:08:24 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestSyncNoTraverse (5.26s) === RUN TestCopyWithDepth run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6'", Local "Local file system at /tmp/rclone3693781112", Modify Window "1ms" 2022/01/13 06:08:25 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for checks to finish 2022/01/13 06:08:25 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for transfers to finish 2022/01/13 06:08:27 DEBUG : hello world2: md5 = 32e4b78bd8988d5e187f32ae8a316939 OK 2022/01/13 06:08:27 INFO : hello world2: Copied (new) --- PASS: TestCopyWithDepth (2.99s) === RUN TestCopyWithFilesFrom run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6'", Local "Local file system at /tmp/rclone3693781112", Modify Window "1ms" 2022/01/13 06:08:28 DEBUG : hello world2: Excluded 2022/01/13 06:08:28 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for checks to finish 2022/01/13 06:08:28 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for transfers to finish 2022/01/13 06:08:30 DEBUG : potato2: md5 = eeea6e9fbbdf54df46fb918bc88c799b OK 2022/01/13 06:08:30 INFO : potato2: Copied (new) --- PASS: TestCopyWithFilesFrom (2.93s) === RUN TestCopyWithFilesFromAndNoTraverse run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6'", Local "Local file system at /tmp/rclone3693781112", Modify Window "1ms" 2022/01/13 06:08:31 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for checks to finish 2022/01/13 06:08:31 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for transfers to finish 2022/01/13 06:08:33 DEBUG : potato2: md5 = bb3b244c6f99836722982441fe0cf788 OK 2022/01/13 06:08:33 INFO : potato2: Copied (new) --- PASS: TestCopyWithFilesFromAndNoTraverse (3.16s) === RUN TestCopyEmptyDirectories run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6'", Local "Local file system at /tmp/rclone3693781112", Modify Window "1ms" 2022/01/13 06:08:34 DEBUG : sub dir2: Making directory 2022/01/13 06:08:34 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for checks to finish 2022/01/13 06:08:34 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for transfers to finish 2022/01/13 06:08:37 DEBUG : sub dir/hello world: md5 = 802cb7304c79ceb7b0882eb3e94e5220 OK 2022/01/13 06:08:37 INFO : sub dir/hello world: Copied (new) 2022/01/13 06:08:37 DEBUG : sub dir2: Making directory 2022/01/13 06:08:38 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': copied 1 directories 2022/01/13 06:08:40 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestCopyEmptyDirectories (6.88s) === RUN TestMoveEmptyDirectories run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6'", Local "Local file system at /tmp/rclone3693781112", Modify Window "1ms" 2022/01/13 06:08:41 DEBUG : sub dir2: Making directory 2022/01/13 06:08:41 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for checks to finish 2022/01/13 06:08:41 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for transfers to finish 2022/01/13 06:08:44 DEBUG : sub dir/hello world: md5 = 7845c842eb7f23bd722d8a456d7642f6 OK 2022/01/13 06:08:44 INFO : sub dir/hello world: Copied (new) 2022/01/13 06:08:44 INFO : sub dir/hello world: Deleted 2022/01/13 06:08:44 DEBUG : sub dir: Making directory 2022/01/13 06:08:44 DEBUG : sub dir2: Making directory 2022/01/13 06:08:44 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': copied 2 directories 2022/01/13 06:08:47 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestMoveEmptyDirectories (6.55s) === RUN TestSyncEmptyDirectories run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6'", Local "Local file system at /tmp/rclone3693781112", Modify Window "1ms" 2022/01/13 06:08:48 DEBUG : sub dir2: Making directory 2022/01/13 06:08:48 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for checks to finish 2022/01/13 06:08:48 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for transfers to finish 2022/01/13 06:08:50 DEBUG : sub dir/hello world: md5 = a2994a210331c464faa52381234d1507 OK 2022/01/13 06:08:50 INFO : sub dir/hello world: Copied (new) 2022/01/13 06:08:50 DEBUG : sub dir2: Making directory 2022/01/13 06:08:51 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': copied 1 directories 2022/01/13 06:08:51 DEBUG : Waiting for deletions to finish 2022/01/13 06:08:54 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestSyncEmptyDirectories (7.21s) === RUN TestServerSideCopy run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6'", Local "Local file system at /tmp/rclone3693781112", Modify Window "1ms" 2022/01/13 06:08:57 DEBUG : sub dir/hello world: md5 = 1687415c9b9b7c228e9f94c4fed9b96f OK 2022/01/13 06:08:58 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-xefaqun7dahasus7pagilow0" 2022/01/13 06:08:58 DEBUG : Creating backend with remote "TestDrive:crypt/beqcr9gcoftlvbug98jqrrlh1e8etnnfnh4t80pdnh6q1m3qvrh2tduqv62ptkhh7gfolpfs1qu7a" sync_test.go:275: Server side copy (if possible) Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6' -> Encrypted drive 'TestCryptDrive:rclone-test-xefaqun7dahasus7pagilow0' 2022/01/13 06:08:59 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xefaqun7dahasus7pagilow0': Waiting for checks to finish 2022/01/13 06:08:59 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xefaqun7dahasus7pagilow0': Waiting for transfers to finish 2022/01/13 06:09:02 INFO : sub dir/hello world: Copied (server-side copy) 2022/01/13 06:09:03 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-xefaqun7dahasus7pagilow0': Purge remote 2022/01/13 06:09:04 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestServerSideCopy (10.44s) === RUN TestCopyAfterDelete run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6'", Local "Local file system at /tmp/rclone3693781112", Modify Window "1ms" 2022/01/13 06:09:08 DEBUG : sub dir/hello world: md5 = 83f79b1425e03dac74fec937d5192915 OK 2022/01/13 06:09:08 ERROR : : error listing: directory not found 2022/01/13 06:09:08 DEBUG : Local file system at /tmp/rclone3693781112: Making directory 2022/01/13 06:09:09 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for checks to finish 2022/01/13 06:09:09 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for transfers to finish 2022/01/13 06:09:11 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestCopyAfterDelete (6.03s) === RUN TestCopyRedownload run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6'", Local "Local file system at /tmp/rclone3693781112", Modify Window "1ms" 2022/01/13 06:09:14 DEBUG : sub dir/hello world: md5 = ff2aca58a27e5204c03a4f280051f517 OK 2022/01/13 06:09:15 DEBUG : Local file system at /tmp/rclone3693781112: Waiting for checks to finish 2022/01/13 06:09:15 DEBUG : Local file system at /tmp/rclone3693781112: Waiting for transfers to finish 2022/01/13 06:09:16 INFO : sub dir/hello world: Copied (new) 2022/01/13 06:09:17 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" --- PASS: TestCopyRedownload (6.64s) === RUN TestSyncBasedOnCheckSum run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6'", Local "Local file system at /tmp/rclone3693781112", Modify Window "1ms" 2022/01/13 06:09:18 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for checks to finish 2022/01/13 06:09:18 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for transfers to finish 2022/01/13 06:09:20 DEBUG : check sum: md5 = 30eca620fba3294cce38100655940f65 OK 2022/01/13 06:09:20 INFO : check sum: Copied (new) 2022/01/13 06:09:20 DEBUG : Waiting for deletions to finish 2022/01/13 06:09:20 NOTICE: Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': --checksum is in use but the source and destination have no hashes in common; falling back to --size-only 2022/01/13 06:09:20 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for checks to finish 2022/01/13 06:09:20 DEBUG : check sum: Size of src and dst objects identical 2022/01/13 06:09:20 DEBUG : check sum: Unchanged skipping 2022/01/13 06:09:20 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for transfers to finish 2022/01/13 06:09:20 DEBUG : Waiting for deletions to finish 2022/01/13 06:09:20 INFO : There was nothing to transfer --- PASS: TestSyncBasedOnCheckSum (3.50s) === RUN TestSyncSizeOnly run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6'", Local "Local file system at /tmp/rclone3693781112", Modify Window "1ms" 2022/01/13 06:09:22 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for checks to finish 2022/01/13 06:09:22 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for transfers to finish 2022/01/13 06:09:23 DEBUG : sizeonly: md5 = 1d55d255edf14898ead32085a6f475ba OK 2022/01/13 06:09:23 INFO : sizeonly: Copied (new) 2022/01/13 06:09:23 DEBUG : Waiting for deletions to finish 2022/01/13 06:09:24 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for checks to finish 2022/01/13 06:09:24 DEBUG : sizeonly: Sizes identical 2022/01/13 06:09:24 DEBUG : sizeonly: Unchanged skipping 2022/01/13 06:09:24 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for transfers to finish 2022/01/13 06:09:24 DEBUG : Waiting for deletions to finish 2022/01/13 06:09:24 INFO : There was nothing to transfer --- PASS: TestSyncSizeOnly (3.54s) === RUN TestSyncIgnoreSize run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6'", Local "Local file system at /tmp/rclone3693781112", Modify Window "1ms" 2022/01/13 06:09:25 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for checks to finish 2022/01/13 06:09:25 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for transfers to finish 2022/01/13 06:09:27 DEBUG : ignore-size: md5 = bf3a67afeec932c2b23e1b79acef4a25 OK 2022/01/13 06:09:27 INFO : ignore-size: Copied (new) 2022/01/13 06:09:27 DEBUG : Waiting for deletions to finish 2022/01/13 06:09:27 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for checks to finish 2022/01/13 06:09:27 DEBUG : ignore-size: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/01/13 06:09:27 DEBUG : ignore-size: Unchanged skipping 2022/01/13 06:09:27 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for transfers to finish 2022/01/13 06:09:27 DEBUG : Waiting for deletions to finish 2022/01/13 06:09:27 INFO : There was nothing to transfer --- PASS: TestSyncIgnoreSize (3.56s) === RUN TestSyncIgnoreTimes run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6'", Local "Local file system at /tmp/rclone3693781112", Modify Window "1ms" 2022/01/13 06:09:30 DEBUG : existing: md5 = f9fd8892b741c84ae70753c96d0e5bb7 OK 2022/01/13 06:09:31 DEBUG : existing: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/01/13 06:09:31 DEBUG : existing: Unchanged skipping 2022/01/13 06:09:31 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for checks to finish 2022/01/13 06:09:31 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for transfers to finish 2022/01/13 06:09:31 DEBUG : Waiting for deletions to finish 2022/01/13 06:09:31 INFO : There was nothing to transfer 2022/01/13 06:09:31 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for checks to finish 2022/01/13 06:09:31 DEBUG : existing: Transferring unconditionally as --ignore-times is in use 2022/01/13 06:09:31 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for transfers to finish 2022/01/13 06:09:32 DEBUG : existing: md5 = cbc3750a9d4fc8ce2a29b7b11f7b0ccc OK 2022/01/13 06:09:32 INFO : existing: Copied (replaced existing) 2022/01/13 06:09:32 DEBUG : Waiting for deletions to finish --- PASS: TestSyncIgnoreTimes (4.73s) === RUN TestSyncIgnoreExisting run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6'", Local "Local file system at /tmp/rclone3693781112", Modify Window "1ms" 2022/01/13 06:09:34 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for checks to finish 2022/01/13 06:09:34 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for transfers to finish 2022/01/13 06:09:35 DEBUG : existing: md5 = b56f86849004c12b279c9aac29bdebe8 OK 2022/01/13 06:09:35 INFO : existing: Copied (new) 2022/01/13 06:09:35 DEBUG : Waiting for deletions to finish 2022/01/13 06:09:36 DEBUG : existing: Destination exists, skipping 2022/01/13 06:09:36 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for checks to finish 2022/01/13 06:09:36 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for transfers to finish 2022/01/13 06:09:36 DEBUG : Waiting for deletions to finish 2022/01/13 06:09:36 INFO : There was nothing to transfer --- PASS: TestSyncIgnoreExisting (3.53s) === RUN TestSyncIgnoreErrors run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6'", Local "Local file system at /tmp/rclone3693781112", Modify Window "1ms" 2022/01/13 06:09:39 DEBUG : b/potato: md5 = cc30628f48754f9278b43205b038fd12 OK 2022/01/13 06:09:41 DEBUG : c/non empty space: md5 = 6dcd2621b3a584f35a6133cc3ab06fd7 OK 2022/01/13 06:09:41 DEBUG : d: Making directory 2022/01/13 06:09:43 DEBUG : c/non empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/01/13 06:09:43 DEBUG : c/non empty space: Unchanged skipping 2022/01/13 06:09:43 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for checks to finish 2022/01/13 06:09:43 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for transfers to finish 2022/01/13 06:09:45 DEBUG : a/potato2: md5 = 11f54fe2a04f9f1e6f639fe846b798cd OK 2022/01/13 06:09:45 INFO : a/potato2: Copied (new) 2022/01/13 06:09:45 DEBUG : Waiting for deletions to finish 2022/01/13 06:09:46 INFO : b/potato: Deleted 2022/01/13 06:09:46 INFO : d: Removing directory 2022/01/13 06:09:47 INFO : b: Removing directory 2022/01/13 06:09:47 DEBUG : 32d8ua6196mc1r7qkfog53rkg0: Rmdir: contains trashed file: "2m507n64kafsi59v9q71r281a4" 2022/01/13 06:09:47 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': deleted 2 directories 2022/01/13 06:09:50 DEBUG : 3i9du405pfogq3ncai6pg7ouio: Rmdir: contains trashed file: "982d3pss7t5pn0il16r2foj31s" 2022/01/13 06:09:51 DEBUG : 2bsvlrk2ne1lfitm6tttcu0qt8: Rmdir: contains trashed file: "89l8renevh3mji1c8r1p7qn6tg" --- PASS: TestSyncIgnoreErrors (14.68s) === RUN TestSyncAfterChangingModtimeOnly run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6'", Local "Local file system at /tmp/rclone3693781112", Modify Window "1ms" 2022/01/13 06:09:53 DEBUG : empty space: md5 = 16dcead3f796f83a196ca5cb3c6cf54f OK 2022/01/13 06:09:53 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for checks to finish 2022/01/13 06:09:53 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/01/13 06:09:53 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for transfers to finish 2022/01/13 06:09:53 NOTICE: empty space: Skipped copy as --dry-run is set (size 1) 2022/01/13 06:09:53 DEBUG : Waiting for deletions to finish 2022/01/13 06:09:54 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for checks to finish 2022/01/13 06:09:54 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/01/13 06:09:54 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for transfers to finish 2022/01/13 06:09:55 DEBUG : empty space: md5 = a1706303e46104c3fe389e7c719ae213 OK 2022/01/13 06:09:55 INFO : empty space: Copied (replaced existing) 2022/01/13 06:09:55 DEBUG : Waiting for deletions to finish --- PASS: TestSyncAfterChangingModtimeOnly (4.99s) === RUN TestSyncAfterChangingModtimeOnlyWithNoUpdateModTime run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6'", Local "Local file system at /tmp/rclone3693781112", Modify Window "1ms" sync_test.go:577: Can't check this if no hashes supported --- PASS: TestSyncAfterChangingModtimeOnlyWithNoUpdateModTime (0.50s) === RUN TestSyncDoesntUpdateModtime run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6'", Local "Local file system at /tmp/rclone3693781112", Modify Window "1ms" 2022/01/13 06:09:58 DEBUG : foo: md5 = 983bc28ba94d37f4d81d12c4c7ae7154 OK 2022/01/13 06:09:59 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/01/13 06:09:59 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for checks to finish 2022/01/13 06:09:59 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for transfers to finish 2022/01/13 06:10:00 DEBUG : foo: md5 = 361125a3486359f8c3d42659b0a429b8 OK 2022/01/13 06:10:00 INFO : foo: Copied (replaced existing) 2022/01/13 06:10:00 DEBUG : Waiting for deletions to finish --- PASS: TestSyncDoesntUpdateModtime (4.50s) === RUN TestSyncAfterAddingAFile run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6'", Local "Local file system at /tmp/rclone3693781112", Modify Window "1ms" 2022/01/13 06:10:03 DEBUG : empty space: md5 = d43847f11e0e8d31eb9058152e09aa74 OK 2022/01/13 06:10:03 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for checks to finish 2022/01/13 06:10:03 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/01/13 06:10:03 DEBUG : empty space: Unchanged skipping 2022/01/13 06:10:03 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for transfers to finish 2022/01/13 06:10:05 DEBUG : potato: md5 = 1a9d3134fe3fdbc84b31625a87c8b578 OK 2022/01/13 06:10:05 INFO : potato: Copied (new) 2022/01/13 06:10:05 DEBUG : Waiting for deletions to finish --- PASS: TestSyncAfterAddingAFile (5.11s) === RUN TestSyncAfterChangingFilesSizeOnly run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6'", Local "Local file system at /tmp/rclone3693781112", Modify Window "1ms" 2022/01/13 06:10:08 DEBUG : potato: md5 = d051a6fddcddc18804167e4991e5c67a OK 2022/01/13 06:10:08 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for checks to finish 2022/01/13 06:10:08 DEBUG : potato: Sizes differ (src 21 vs dst 60) 2022/01/13 06:10:08 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for transfers to finish 2022/01/13 06:10:10 DEBUG : potato: md5 = 4cefe5d183deac70302be0e4e0e81170 OK 2022/01/13 06:10:10 INFO : potato: Copied (replaced existing) 2022/01/13 06:10:10 DEBUG : Waiting for deletions to finish --- PASS: TestSyncAfterChangingFilesSizeOnly (4.31s) === RUN TestSyncAfterChangingContentsOnly run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6'", Local "Local file system at /tmp/rclone3693781112", Modify Window "1ms" 2022/01/13 06:10:12 DEBUG : potato: md5 = 82bacf0c882289990447d37ed2a564b6 OK 2022/01/13 06:10:13 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for checks to finish 2022/01/13 06:10:13 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/01/13 06:10:13 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for transfers to finish 2022/01/13 06:10:14 DEBUG : potato: md5 = aa64f7ea7940309babf99da94fb7549a OK 2022/01/13 06:10:14 INFO : potato: Copied (replaced existing) 2022/01/13 06:10:14 DEBUG : Waiting for deletions to finish --- PASS: TestSyncAfterChangingContentsOnly (4.51s) === RUN TestSyncAfterRemovingAFileAndAddingAFileDryRun run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6'", Local "Local file system at /tmp/rclone3693781112", Modify Window "1ms" 2022/01/13 06:10:17 DEBUG : potato: md5 = a37395571e0e0629202d27cd40abe2af OK 2022/01/13 06:10:18 DEBUG : empty space: md5 = 30e059d4e95e7cee7672592bab97fa4b OK 2022/01/13 06:10:19 NOTICE: potato2: Skipped copy as --dry-run is set (size 60) 2022/01/13 06:10:19 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/01/13 06:10:19 DEBUG : empty space: Unchanged skipping 2022/01/13 06:10:19 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for checks to finish 2022/01/13 06:10:19 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for transfers to finish 2022/01/13 06:10:19 DEBUG : Waiting for deletions to finish 2022/01/13 06:10:19 NOTICE: potato: Skipped delete as --dry-run is set (size 21) --- PASS: TestSyncAfterRemovingAFileAndAddingAFileDryRun (4.98s) === RUN TestSyncAfterRemovingAFileAndAddingAFile run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6'", Local "Local file system at /tmp/rclone3693781112", Modify Window "1ms" 2022/01/13 06:10:22 DEBUG : potato: md5 = 2a8178afb1c72df4f75bfa107abca62e OK 2022/01/13 06:10:23 DEBUG : empty space: md5 = 9ceaff27fecbf69e3ca347ff3ddbbbe7 OK 2022/01/13 06:10:24 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/01/13 06:10:24 DEBUG : empty space: Unchanged skipping 2022/01/13 06:10:24 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for checks to finish 2022/01/13 06:10:24 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for transfers to finish 2022/01/13 06:10:25 DEBUG : potato2: md5 = 8aa272eead66808231ab34a258df661e OK 2022/01/13 06:10:25 INFO : potato2: Copied (new) 2022/01/13 06:10:25 DEBUG : Waiting for deletions to finish 2022/01/13 06:10:26 INFO : potato: Deleted --- PASS: TestSyncAfterRemovingAFileAndAddingAFile (7.16s) === RUN TestSyncAfterRemovingAFileAndAddingAFileSubDir run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6'", Local "Local file system at /tmp/rclone3693781112", Modify Window "1ms" 2022/01/13 06:10:30 DEBUG : b/potato: md5 = 2ed9bffc5562ff0b709471d053a8868a OK 2022/01/13 06:10:32 DEBUG : c/non empty space: md5 = 3779becdacb7fdd82259bbcf6151afa8 OK 2022/01/13 06:10:32 DEBUG : d: Making directory 2022/01/13 06:10:33 DEBUG : d/e: Making directory 2022/01/13 06:10:35 DEBUG : c/non empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/01/13 06:10:35 DEBUG : c/non empty space: Unchanged skipping 2022/01/13 06:10:35 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for checks to finish 2022/01/13 06:10:35 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for transfers to finish 2022/01/13 06:10:37 DEBUG : a/potato2: md5 = 7b26b2ac1965d8aa300954172c470b83 OK 2022/01/13 06:10:37 INFO : a/potato2: Copied (new) 2022/01/13 06:10:37 DEBUG : Waiting for deletions to finish 2022/01/13 06:10:38 INFO : b/potato: Deleted 2022/01/13 06:10:38 INFO : d/e: Removing directory 2022/01/13 06:10:38 INFO : d: Removing directory 2022/01/13 06:10:39 DEBUG : ka6id8d20d3s5ktapedlphgta8: Rmdir: contains trashed file: "r8sppajuabeak3sbgj2ak8vuf8" 2022/01/13 06:10:39 INFO : b: Removing directory 2022/01/13 06:10:39 DEBUG : 32d8ua6196mc1r7qkfog53rkg0: Rmdir: contains trashed file: "2m507n64kafsi59v9q71r281a4" 2022/01/13 06:10:40 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': deleted 3 directories 2022/01/13 06:10:42 DEBUG : 3i9du405pfogq3ncai6pg7ouio: Rmdir: contains trashed file: "982d3pss7t5pn0il16r2foj31s" 2022/01/13 06:10:43 DEBUG : 2bsvlrk2ne1lfitm6tttcu0qt8: Rmdir: contains trashed file: "89l8renevh3mji1c8r1p7qn6tg" --- PASS: TestSyncAfterRemovingAFileAndAddingAFileSubDir (16.48s) === RUN TestSyncAfterRemovingAFileAndAddingAFileSubDirWithErrors run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6'", Local "Local file system at /tmp/rclone3693781112", Modify Window "1ms" 2022/01/13 06:10:46 DEBUG : b/potato: md5 = f831779952ca01da9d574cda47ae1181 OK 2022/01/13 06:10:48 DEBUG : c/non empty space: md5 = 4378f313ae74ce235370480a46b1942b OK 2022/01/13 06:10:48 DEBUG : d: Making directory 2022/01/13 06:10:50 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for checks to finish 2022/01/13 06:10:50 DEBUG : c/non empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/01/13 06:10:50 DEBUG : c/non empty space: Unchanged skipping 2022/01/13 06:10:50 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for transfers to finish 2022/01/13 06:10:52 DEBUG : a/potato2: md5 = 875e3c91ef1930c5aba8bae9cdc77919 OK 2022/01/13 06:10:52 INFO : a/potato2: Copied (new) 2022/01/13 06:10:52 ERROR : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': not deleting files as there were IO errors 2022/01/13 06:10:52 ERROR : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': not deleting directories as there were IO errors 2022/01/13 06:10:57 DEBUG : 3i9du405pfogq3ncai6pg7ouio: Rmdir: contains trashed file: "982d3pss7t5pn0il16r2foj31s" 2022/01/13 06:10:57 DEBUG : 32d8ua6196mc1r7qkfog53rkg0: Rmdir: contains trashed file: "2m507n64kafsi59v9q71r281a4" 2022/01/13 06:10:58 DEBUG : 2bsvlrk2ne1lfitm6tttcu0qt8: Rmdir: contains trashed file: "89l8renevh3mji1c8r1p7qn6tg" --- PASS: TestSyncAfterRemovingAFileAndAddingAFileSubDirWithErrors (15.18s) === RUN TestSyncDeleteAfter --- PASS: TestSyncDeleteAfter (0.00s) === RUN TestSyncDeleteDuring run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6'", Local "Local file system at /tmp/rclone3693781112", Modify Window "1ms" 2022/01/13 06:11:01 DEBUG : potato: md5 = 2f6ce4b49e5805dae00aef7270d577b6 OK 2022/01/13 06:11:02 DEBUG : empty space: md5 = 5e9a8b8acfcb503b86ba213a4cd9ed06 OK 2022/01/13 06:11:02 DEBUG : Waiting for deletions to finish 2022/01/13 06:11:03 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for checks to finish 2022/01/13 06:11:03 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/01/13 06:11:03 DEBUG : empty space: Unchanged skipping 2022/01/13 06:11:03 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for transfers to finish 2022/01/13 06:11:03 INFO : potato: Deleted 2022/01/13 06:11:04 DEBUG : potato2: md5 = 72ecb9cb39b30b472d4812838c94fa56 OK 2022/01/13 06:11:04 INFO : potato2: Copied (new) --- PASS: TestSyncDeleteDuring (6.47s) === RUN TestSyncDeleteBefore run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6'", Local "Local file system at /tmp/rclone3693781112", Modify Window "1ms" 2022/01/13 06:11:07 DEBUG : potato: md5 = b19d8a43d65658451ec02b6d99a16f77 OK 2022/01/13 06:11:08 DEBUG : empty space: md5 = 97a5b4292fdc54d34922f31f5bce5f3b OK 2022/01/13 06:11:09 DEBUG : Waiting for deletions to finish 2022/01/13 06:11:09 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for checks to finish 2022/01/13 06:11:09 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for transfers to finish 2022/01/13 06:11:09 INFO : potato: Deleted 2022/01/13 06:11:10 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/01/13 06:11:10 DEBUG : empty space: Unchanged skipping 2022/01/13 06:11:10 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for checks to finish 2022/01/13 06:11:10 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for transfers to finish 2022/01/13 06:11:11 DEBUG : potato2: md5 = e868bef8cf8b7fedec5a54f848c55c9c OK 2022/01/13 06:11:11 INFO : potato2: Copied (new) --- PASS: TestSyncDeleteBefore (7.19s) === RUN TestCopyDeleteBefore run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6'", Local "Local file system at /tmp/rclone3693781112", Modify Window "1ms" 2022/01/13 06:11:14 DEBUG : potato: md5 = f325adc324bfe813358c6aa59a296c7a OK 2022/01/13 06:11:15 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for checks to finish 2022/01/13 06:11:15 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for transfers to finish 2022/01/13 06:11:16 DEBUG : potato2: md5 = f93e60dca75446aea72e769df0bf8e1d OK 2022/01/13 06:11:16 INFO : potato2: Copied (new) --- PASS: TestCopyDeleteBefore (5.18s) === RUN TestSyncWithExclude run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6'", Local "Local file system at /tmp/rclone3693781112", Modify Window "1ms" 2022/01/13 06:11:19 DEBUG : potato2: md5 = a50d9378ff473e8abd1f835c678c3af1 OK 2022/01/13 06:11:21 DEBUG : empty space: md5 = 0bb7a80a3cfcb047dd80c1a854e260d5 OK 2022/01/13 06:11:21 DEBUG : enormous: Excluded 2022/01/13 06:11:21 DEBUG : potato2: Excluded 2022/01/13 06:11:21 DEBUG : potato2: Excluded from sync (and deletion) 2022/01/13 06:11:21 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for checks to finish 2022/01/13 06:11:21 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/01/13 06:11:21 DEBUG : empty space: Unchanged skipping 2022/01/13 06:11:21 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for transfers to finish 2022/01/13 06:11:21 DEBUG : Waiting for deletions to finish 2022/01/13 06:11:21 INFO : There was nothing to transfer 2022/01/13 06:11:22 DEBUG : enormous: Excluded 2022/01/13 06:11:22 DEBUG : potato2: Excluded 2022/01/13 06:11:22 DEBUG : potato2: Excluded from sync (and deletion) 2022/01/13 06:11:22 DEBUG : empty space: Size and modification time the same (differ by 456.789µs, within tolerance 1ms) 2022/01/13 06:11:22 DEBUG : empty space: Unchanged skipping 2022/01/13 06:11:22 DEBUG : Local file system at /tmp/rclone3693781112: Waiting for checks to finish 2022/01/13 06:11:22 DEBUG : Local file system at /tmp/rclone3693781112: Waiting for transfers to finish 2022/01/13 06:11:22 DEBUG : Waiting for deletions to finish 2022/01/13 06:11:22 INFO : There was nothing to transfer --- PASS: TestSyncWithExclude (5.39s) === RUN TestSyncWithExcludeAndDeleteExcluded run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6'", Local "Local file system at /tmp/rclone3693781112", Modify Window "1ms" 2022/01/13 06:11:25 DEBUG : potato2: md5 = 4cd38d2dece38ed084a4e2ac10594cb0 OK 2022/01/13 06:11:26 DEBUG : empty space: md5 = 3514024626d268cbc995e9806917e684 OK 2022/01/13 06:11:27 DEBUG : enormous: md5 = e7d772f11dc43576b32a1806442d04c6 OK 2022/01/13 06:11:28 DEBUG : enormous: Excluded 2022/01/13 06:11:28 DEBUG : potato2: Excluded 2022/01/13 06:11:28 DEBUG : empty space: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/01/13 06:11:28 DEBUG : empty space: Unchanged skipping 2022/01/13 06:11:28 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for checks to finish 2022/01/13 06:11:28 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for transfers to finish 2022/01/13 06:11:28 DEBUG : Waiting for deletions to finish 2022/01/13 06:11:28 INFO : potato2: Deleted 2022/01/13 06:11:29 INFO : enormous: Deleted 2022/01/13 06:11:29 INFO : There was nothing to transfer 2022/01/13 06:11:29 DEBUG : empty space: Size and modification time the same (differ by 456.789µs, within tolerance 1ms) 2022/01/13 06:11:29 DEBUG : empty space: Unchanged skipping 2022/01/13 06:11:29 DEBUG : Local file system at /tmp/rclone3693781112: Waiting for checks to finish 2022/01/13 06:11:29 DEBUG : Local file system at /tmp/rclone3693781112: Waiting for transfers to finish 2022/01/13 06:11:29 DEBUG : Waiting for deletions to finish 2022/01/13 06:11:29 INFO : potato2: Deleted 2022/01/13 06:11:29 INFO : enormous: Deleted 2022/01/13 06:11:29 INFO : There was nothing to transfer --- PASS: TestSyncWithExcludeAndDeleteExcluded (7.02s) === RUN TestSyncWithUpdateOlder run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6'", Local "Local file system at /tmp/rclone3693781112", Modify Window "1ms" 2022/01/13 06:11:32 DEBUG : one: md5 = 05a3c387ca59e10902180754f4b28e06 OK 2022/01/13 06:11:34 DEBUG : two: md5 = 3e953f34688905a3a6f590904e0e6648 OK 2022/01/13 06:11:35 DEBUG : three: md5 = 1a7966785a564a3f42f40342fbb39237 OK 2022/01/13 06:11:36 DEBUG : four: md5 = b6a52f07922660655496815c76ebadbf OK 2022/01/13 06:11:37 DEBUG : four: Sizes differ (src 4 vs dst 8) 2022/01/13 06:11:37 DEBUG : four: Destination mod time is within 1s of source but files differ, transferring 2022/01/13 06:11:37 DEBUG : one: Destination is newer than source, skipping 2022/01/13 06:11:37 DEBUG : three: Sizes identical 2022/01/13 06:11:37 DEBUG : three: Destination mod time is within 1s of source and files identical, skipping 2022/01/13 06:11:37 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for checks to finish 2022/01/13 06:11:37 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for transfers to finish 2022/01/13 06:11:38 DEBUG : two: md5 = 1021a2d3823d28e127cc9033b2b0ee57 OK 2022/01/13 06:11:38 INFO : two: Copied (replaced existing) 2022/01/13 06:11:38 DEBUG : four: md5 = d2609b60ef7ed9492857f4ca31889e27 OK 2022/01/13 06:11:38 INFO : four: Copied (replaced existing) 2022/01/13 06:11:38 DEBUG : five: md5 = c54e2a1d2ebb542c941b0c4bcdb2b7e7 OK 2022/01/13 06:11:38 INFO : five: Copied (new) 2022/01/13 06:11:38 DEBUG : Waiting for deletions to finish sync_test.go:992: Skip test with --checksum as no hashes supported --- PASS: TestSyncWithUpdateOlder (11.57s) === RUN TestSyncWithMaxDuration sync_test.go:1009: Skipping test on non local remote --- SKIP: TestSyncWithMaxDuration (0.00s) === RUN TestSyncWithTrackRenames run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6'", Local "Local file system at /tmp/rclone3693781112", Modify Window "1ms" sync_test.go:1058: Can track renames: false 2022/01/13 06:11:42 ERROR : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Ignoring --track-renames as the source and destination do not have a common hash 2022/01/13 06:11:42 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for checks to finish 2022/01/13 06:11:42 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for transfers to finish 2022/01/13 06:11:44 DEBUG : yam: md5 = 3faed43092dfd2e4abb514d834b59b93 OK 2022/01/13 06:11:44 INFO : yam: Copied (new) 2022/01/13 06:11:44 DEBUG : potato: md5 = 52eabe06d8906da219431ef759c7b7a9 OK 2022/01/13 06:11:44 INFO : potato: Copied (new) 2022/01/13 06:11:44 DEBUG : Waiting for deletions to finish 2022/01/13 06:11:44 ERROR : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Ignoring --track-renames as the source and destination do not have a common hash 2022/01/13 06:11:45 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for checks to finish 2022/01/13 06:11:45 DEBUG : potato: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/01/13 06:11:45 DEBUG : potato: Unchanged skipping 2022/01/13 06:11:45 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for transfers to finish 2022/01/13 06:11:46 DEBUG : yaml: md5 = 428b8bcd98f93b6f01f0e60adb44cec0 OK 2022/01/13 06:11:46 INFO : yaml: Copied (new) 2022/01/13 06:11:46 DEBUG : Waiting for deletions to finish 2022/01/13 06:11:47 INFO : yam: Deleted --- PASS: TestSyncWithTrackRenames (6.52s) === RUN TestParseRenamesStrategyModtime --- PASS: TestParseRenamesStrategyModtime (0.00s) === RUN TestRenamesStrategyModtime --- PASS: TestRenamesStrategyModtime (0.00s) === RUN TestSyncWithTrackRenamesStrategyModtime run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6'", Local "Local file system at /tmp/rclone3693781112", Modify Window "1ms" sync_test.go:1127: Can track renames: true 2022/01/13 06:11:49 INFO : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Making map for --track-renames 2022/01/13 06:11:49 INFO : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Finished making map for --track-renames 2022/01/13 06:11:49 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for checks to finish 2022/01/13 06:11:49 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for renames to finish 2022/01/13 06:11:49 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for transfers to finish 2022/01/13 06:11:50 DEBUG : potato: md5 = 4d78fb6a9ec8da9268e0ff7f2a232c0d OK 2022/01/13 06:11:50 INFO : potato: Copied (new) 2022/01/13 06:11:50 DEBUG : yam: md5 = e22d53d4114bfac5c53ef97eb70daf8f OK 2022/01/13 06:11:50 INFO : yam: Copied (new) 2022/01/13 06:11:50 DEBUG : Waiting for deletions to finish 2022/01/13 06:11:51 DEBUG : potato: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/01/13 06:11:51 DEBUG : potato: Unchanged skipping 2022/01/13 06:11:51 INFO : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Making map for --track-renames 2022/01/13 06:11:51 INFO : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Finished making map for --track-renames 2022/01/13 06:11:51 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for checks to finish 2022/01/13 06:11:51 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for renames to finish 2022/01/13 06:11:52 INFO : yam: Moved (server-side) to: yaml 2022/01/13 06:11:52 INFO : yaml: Renamed from "yam" 2022/01/13 06:11:52 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for transfers to finish 2022/01/13 06:11:52 DEBUG : Waiting for deletions to finish 2022/01/13 06:11:52 INFO : There was nothing to transfer --- PASS: TestSyncWithTrackRenamesStrategyModtime (5.34s) === RUN TestSyncWithTrackRenamesStrategyLeaf run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6'", Local "Local file system at /tmp/rclone3693781112", Modify Window "1ms" sync_test.go:1163: Can track renames: true 2022/01/13 06:11:54 INFO : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Making map for --track-renames 2022/01/13 06:11:54 INFO : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Finished making map for --track-renames 2022/01/13 06:11:54 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for checks to finish 2022/01/13 06:11:54 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for renames to finish 2022/01/13 06:11:54 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for transfers to finish 2022/01/13 06:11:56 DEBUG : sub/yam: md5 = cfced3038434111674ae8e6bef3e68b9 OK 2022/01/13 06:11:56 INFO : sub/yam: Copied (new) 2022/01/13 06:11:57 DEBUG : potato: md5 = 1227ac05622d708e83d4a1d8d2c19836 OK 2022/01/13 06:11:57 INFO : potato: Copied (new) 2022/01/13 06:11:57 DEBUG : Waiting for deletions to finish 2022/01/13 06:11:58 DEBUG : potato: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/01/13 06:11:58 DEBUG : potato: Unchanged skipping 2022/01/13 06:11:58 INFO : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Making map for --track-renames 2022/01/13 06:11:58 INFO : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Finished making map for --track-renames 2022/01/13 06:11:58 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for checks to finish 2022/01/13 06:11:58 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for renames to finish 2022/01/13 06:11:59 INFO : sub/yam: Moved (server-side) to: yam 2022/01/13 06:11:59 INFO : yam: Renamed from "sub/yam" 2022/01/13 06:11:59 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for transfers to finish 2022/01/13 06:11:59 DEBUG : Waiting for deletions to finish 2022/01/13 06:11:59 INFO : There was nothing to transfer --- PASS: TestSyncWithTrackRenamesStrategyLeaf (8.59s) === RUN TestMoveWithDeleteEmptySrcDirs run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6'", Local "Local file system at /tmp/rclone3693781112", Modify Window "1ms" 2022/01/13 06:12:03 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for checks to finish 2022/01/13 06:12:03 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for transfers to finish 2022/01/13 06:12:05 DEBUG : sub dir/hello world: md5 = a4d51602f0666b7e15da886a23cfb2a5 OK 2022/01/13 06:12:05 INFO : sub dir/hello world: Copied (new) 2022/01/13 06:12:05 INFO : sub dir/hello world: Deleted 2022/01/13 06:12:07 DEBUG : nested/sub dir/file: md5 = 00504d978d399a2b49debecb1b34ab8b OK 2022/01/13 06:12:07 INFO : nested/sub dir/file: Copied (new) 2022/01/13 06:12:07 INFO : nested/sub dir/file: Deleted 2022/01/13 06:12:07 INFO : sub dir: Removing directory 2022/01/13 06:12:07 INFO : nested/sub dir: Removing directory 2022/01/13 06:12:07 INFO : nested: Removing directory 2022/01/13 06:12:07 DEBUG : Local file system at /tmp/rclone3693781112: deleted 3 directories 2022/01/13 06:12:10 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" 2022/01/13 06:12:11 DEBUG : 37qp6d1gohacv723ij3brofbu8/14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "ftp4kuv8se7tqduu6pmmcvjsmk" 2022/01/13 06:12:12 DEBUG : 37qp6d1gohacv723ij3brofbu8: Rmdir: contains trashed file: "14begaa36ih249fgrnfk6nulg0" --- PASS: TestMoveWithDeleteEmptySrcDirs (10.51s) === RUN TestMoveWithoutDeleteEmptySrcDirs run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6'", Local "Local file system at /tmp/rclone3693781112", Modify Window "1ms" 2022/01/13 06:12:13 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for checks to finish 2022/01/13 06:12:13 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for transfers to finish 2022/01/13 06:12:16 DEBUG : sub dir/hello world: md5 = 2337db9bd8cd1b8cba3cf990501acc0e OK 2022/01/13 06:12:16 INFO : sub dir/hello world: Copied (new) 2022/01/13 06:12:16 INFO : sub dir/hello world: Deleted 2022/01/13 06:12:17 DEBUG : nested/sub dir/file: md5 = 938e5bbbaf9b7c58780d6da5881345a7 OK 2022/01/13 06:12:17 INFO : nested/sub dir/file: Copied (new) 2022/01/13 06:12:17 INFO : nested/sub dir/file: Deleted 2022/01/13 06:12:20 DEBUG : 14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "8j9gk4b744l35einofkqsr2mvo" 2022/01/13 06:12:21 DEBUG : 37qp6d1gohacv723ij3brofbu8/14begaa36ih249fgrnfk6nulg0: Rmdir: contains trashed file: "ftp4kuv8se7tqduu6pmmcvjsmk" 2022/01/13 06:12:22 DEBUG : 37qp6d1gohacv723ij3brofbu8: Rmdir: contains trashed file: "14begaa36ih249fgrnfk6nulg0" --- PASS: TestMoveWithoutDeleteEmptySrcDirs (9.55s) === RUN TestMoveWithIgnoreExisting run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6'", Local "Local file system at /tmp/rclone3693781112", Modify Window "1ms" 2022/01/13 06:12:23 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for checks to finish 2022/01/13 06:12:23 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for transfers to finish 2022/01/13 06:12:24 DEBUG : existing: md5 = 9c52f33f7c0ed3261c528c10d8a7469a OK 2022/01/13 06:12:24 INFO : existing: Copied (new) 2022/01/13 06:12:24 INFO : existing: Deleted 2022/01/13 06:12:24 DEBUG : existing-b: md5 = 6c212b44c5f1380f7c7632598bbf5fb8 OK 2022/01/13 06:12:24 INFO : existing-b: Copied (new) 2022/01/13 06:12:24 INFO : existing-b: Deleted 2022/01/13 06:12:25 DEBUG : existing: Destination exists, skipping 2022/01/13 06:12:25 DEBUG : existing: Not removing source file as destination file exists and --ignore-existing is set 2022/01/13 06:12:25 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for checks to finish 2022/01/13 06:12:25 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for transfers to finish 2022/01/13 06:12:25 INFO : There was nothing to transfer --- PASS: TestMoveWithIgnoreExisting (4.50s) === RUN TestServerSideMove run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6'", Local "Local file system at /tmp/rclone3693781112", Modify Window "1ms" 2022/01/13 06:12:27 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-kinomah1widogub0waloyix5" 2022/01/13 06:12:27 DEBUG : Creating backend with remote "TestDrive:crypt/4dt9p105a5tc7cd02410a56bf2lsfqpvukmuv9liv9olg00itei85dnn894iu9dlgc28nr4jcgdea" 2022/01/13 06:12:30 DEBUG : potato2: md5 = 0cc9c83ca4d2d6b6998e30d470533142 OK 2022/01/13 06:12:31 DEBUG : empty space: md5 = 27c43ed33438a1d2132f11165c387b27 OK 2022/01/13 06:12:32 DEBUG : potato3: md5 = b5d7e2435916b807d0f0860c0046e115 OK sync_test.go:1215: Server side move (if possible) Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6' -> Encrypted drive 'TestCryptDrive:rclone-test-kinomah1widogub0waloyix5' 2022/01/13 06:12:35 DEBUG : empty space: md5 = fcb1de23e1165c8aafb49d139df08caa OK 2022/01/13 06:12:36 DEBUG : potato3: md5 = 704fb9d872351fc51cec7af15b41eb5a OK 2022/01/13 06:12:37 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-kinomah1widogub0waloyix5': Using server-side directory move 2022/01/13 06:12:37 INFO : Encrypted drive 'TestCryptDrive:rclone-test-kinomah1widogub0waloyix5': Server side directory move failed - fallback to file moves: can't copy directory - destination already exists 2022/01/13 06:12:37 DEBUG : potato3: Sizes differ (src 68 vs dst 60) 2022/01/13 06:12:37 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-kinomah1widogub0waloyix5': Waiting for checks to finish 2022/01/13 06:12:37 DEBUG : empty space: Size and modification time the same (differ by 0s, within tolerance 1ms) 2022/01/13 06:12:37 DEBUG : empty space: Unchanged skipping 2022/01/13 06:12:38 INFO : empty space: Deleted 2022/01/13 06:12:38 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-kinomah1widogub0waloyix5': Waiting for transfers to finish 2022/01/13 06:12:38 INFO : potato3: Deleted 2022/01/13 06:12:38 INFO : potato2: Moved (server-side) 2022/01/13 06:12:38 INFO : potato3: Moved (server-side) 2022/01/13 06:12:38 INFO : There was nothing to transfer 2022/01/13 06:12:39 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-wuhuric8sihegew2metohaq9" 2022/01/13 06:12:39 DEBUG : Creating backend with remote "TestDrive:crypt/sr0p06uc6o2lgootf824mq4l42ame23nbbcitl6k0l1oftt05h49ju67nimodl5lqb63q068jtkfo" 2022/01/13 06:12:40 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wuhuric8sihegew2metohaq9': Using server-side directory move 2022/01/13 06:12:41 INFO : Encrypted drive 'TestCryptDrive:rclone-test-wuhuric8sihegew2metohaq9': Server side directory move succeeded 2022/01/13 06:12:42 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-wuhuric8sihegew2metohaq9': Purge remote 2022/01/13 06:12:43 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-kinomah1widogub0waloyix5': Purge remote 2022/01/13 06:12:43 purge failed: directory not found --- PASS: TestServerSideMove (16.22s) === RUN TestServerSideMoveWithFilter run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6'", Local "Local file system at /tmp/rclone3693781112", Modify Window "1ms" 2022/01/13 06:12:43 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-kekafod8jegogiq1yujatas4" 2022/01/13 06:12:43 DEBUG : Creating backend with remote "TestDrive:crypt/0m26bmq2qtj0tb6vgrbc3ep6eca896p0avfjl8no8lv7d6ouqhmpho9sfh0slu0aqq8hf9jgal350" 2022/01/13 06:12:46 DEBUG : potato2: md5 = 1a2918dbc80804c0ffb589381dd3d4b5 OK 2022/01/13 06:12:47 DEBUG : empty space: md5 = 0b82798d6f33fb3f1e75fbd5d8d95276 OK 2022/01/13 06:12:49 DEBUG : potato3: md5 = 021798459d730ece0498541651e68095 OK sync_test.go:1215: Server side move (if possible) Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6' -> Encrypted drive 'TestCryptDrive:rclone-test-kekafod8jegogiq1yujatas4' 2022/01/13 06:12:52 DEBUG : empty space: md5 = 4763d9abbcfa3b884a293b5b55338ffa OK 2022/01/13 06:12:53 DEBUG : potato3: md5 = 34e5d88e98ca27fc2bd5d353d7e0e19d OK 2022/01/13 06:12:53 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/01/13 06:12:53 DEBUG : pacer: Rate limited, increasing sleep to 1.531685145s 2022/01/13 06:12:53 DEBUG : empty space: Excluded from sync (and deletion) 2022/01/13 06:12:54 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/01/13 06:12:54 DEBUG : pacer: Rate limited, increasing sleep to 2.111135012s 2022/01/13 06:12:55 DEBUG : pacer: Reducing sleep to 0s 2022/01/13 06:12:55 DEBUG : empty space: Excluded from sync (and deletion) 2022/01/13 06:12:55 DEBUG : potato3: Sizes differ (src 68 vs dst 60) 2022/01/13 06:12:55 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-kekafod8jegogiq1yujatas4': Waiting for checks to finish 2022/01/13 06:12:55 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-kekafod8jegogiq1yujatas4': Waiting for transfers to finish 2022/01/13 06:12:56 INFO : potato3: Deleted 2022/01/13 06:12:56 INFO : potato2: Moved (server-side) 2022/01/13 06:12:56 INFO : potato3: Moved (server-side) 2022/01/13 06:12:56 INFO : There was nothing to transfer 2022/01/13 06:12: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/01/13 06:12:57 DEBUG : pacer: Rate limited, increasing sleep to 1.3018103s 2022/01/13 06:12:58 DEBUG : pacer: Reducing sleep to 0s 2022/01/13 06:12:58 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-makejoj7yuluram8paletuh5" 2022/01/13 06:12:58 DEBUG : Creating backend with remote "TestDrive:crypt/6l2r0kghpo9sm5h1e7kd9jk268omp647osoenp72601473hdfg5rd34l0l0m7cp98ibb3gl3ru7rk" 2022/01/13 06:12:59 DEBUG : empty space: Excluded from sync (and deletion) 2022/01/13 06:12:59 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-makejoj7yuluram8paletuh5': Waiting for checks to finish 2022/01/13 06:12:59 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-makejoj7yuluram8paletuh5': Waiting for transfers to finish 2022/01/13 06:13:01 INFO : potato2: Moved (server-side) 2022/01/13 06:13:01 INFO : potato3: Moved (server-side) 2022/01/13 06:13:01 INFO : There was nothing to transfer 2022/01/13 06:13:02 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-makejoj7yuluram8paletuh5': Purge remote 2022/01/13 06:13:03 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-kekafod8jegogiq1yujatas4': Purge remote --- PASS: TestServerSideMoveWithFilter (21.18s) === RUN TestServerSideMoveDeleteEmptySourceDirs run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6'", Local "Local file system at /tmp/rclone3693781112", Modify Window "1ms" 2022/01/13 06:13:04 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-tuzawir4gimuseg7sufupur9" 2022/01/13 06:13:05 DEBUG : Creating backend with remote "TestDrive:crypt/31i7rrvq8sntpnpj3lcsen997ik3im16p6kmsvbskc8h7o8to7elst5o1fo6l66ggi0gplsqdqsma" 2022/01/13 06:13:07 DEBUG : potato2: md5 = 4d3e866b8e9305f220ebcd6a7668bfcb OK 2022/01/13 06:13:09 DEBUG : empty space: md5 = f6b5d376d695ae745cb146c1e254adeb OK 2022/01/13 06:13:10 DEBUG : potato3: md5 = d89664c7884b5fc3f4d05acd6a1b8eac OK 2022/01/13 06:13:10 DEBUG : tomatoDir: Making directory sync_test.go:1215: Server side move (if possible) Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6' -> Encrypted drive 'TestCryptDrive:rclone-test-tuzawir4gimuseg7sufupur9' 2022/01/13 06:13:14 DEBUG : empty space: md5 = 14bab3049d2e0e97904122e1411f7682 OK 2022/01/13 06:13:15 DEBUG : potato3: md5 = 690482b6901fba8b33a4a0ba7a0a4b5e OK 2022/01/13 06:13:16 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuzawir4gimuseg7sufupur9': Using server-side directory move 2022/01/13 06:13:16 INFO : Encrypted drive 'TestCryptDrive:rclone-test-tuzawir4gimuseg7sufupur9': Server side directory move failed - fallback to file moves: can't copy directory - destination already exists 2022/01/13 06:13:16 DEBUG : empty space: Size and modification time the same (differ by 0s, within tolerance 1ms) 2022/01/13 06:13:16 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuzawir4gimuseg7sufupur9': Waiting for checks to finish 2022/01/13 06:13:16 DEBUG : empty space: Unchanged skipping 2022/01/13 06:13:16 DEBUG : potato3: Sizes differ (src 68 vs dst 60) 2022/01/13 06:13:16 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/01/13 06:13:16 DEBUG : pacer: Rate limited, increasing sleep to 1.286959257s 2022/01/13 06:13:16 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/01/13 06:13:16 DEBUG : pacer: Rate limited, increasing sleep to 2.567627206s 2022/01/13 06:13:17 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/01/13 06:13:17 DEBUG : pacer: Rate limited, increasing sleep to 4.6610609s 2022/01/13 06:13:17 INFO : empty space: Deleted 2022/01/13 06:13:17 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuzawir4gimuseg7sufupur9': Waiting for transfers to finish 2022/01/13 06:13:18 DEBUG : pacer: Reducing sleep to 0s 2022/01/13 06:13:18 INFO : potato3: Deleted 2022/01/13 06:13:23 INFO : potato3: Moved (server-side) 2022/01/13 06:13:23 INFO : potato2: Moved (server-side) 2022/01/13 06:13:23 INFO : tomatoDir: Removing directory 2022/01/13 06:13:24 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': deleted 1 directories 2022/01/13 06:13:24 INFO : There was nothing to transfer 2022/01/13 06:13:25 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-gurofoh6yadosam5wowoduj7" 2022/01/13 06:13:25 DEBUG : Creating backend with remote "TestDrive:crypt/gl750td0hgaurbc8jf3rabv4o0o3i7cjkes2jfoqvdu27r66v2ttsmrfi2gfc8u82e89mpgkhp4pk" 2022/01/13 06:13:26 DEBUG : tomatoDir: Making directory 2022/01/13 06:13:27 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gurofoh6yadosam5wowoduj7': Using server-side directory move 2022/01/13 06:13:28 INFO : Encrypted drive 'TestCryptDrive:rclone-test-gurofoh6yadosam5wowoduj7': Server side directory move succeeded 2022/01/13 06:13:30 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-gurofoh6yadosam5wowoduj7': Purge remote 2022/01/13 06:13:30 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-tuzawir4gimuseg7sufupur9': Purge remote 2022/01/13 06:13:31 purge failed: directory not found --- PASS: TestServerSideMoveDeleteEmptySourceDirs (26.65s) === RUN TestServerSideMoveOverlap run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6'", Local "Local file system at /tmp/rclone3693781112", Modify Window "1ms" sync_test.go:1399: Skipping test as remote supports DirMove 2022/01/13 06:13:32 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/01/13 06:13:32 DEBUG : pacer: Rate limited, increasing sleep to 1.820846904s 2022/01/13 06:13:32 DEBUG : pacer: Reducing sleep to 0s --- SKIP: TestServerSideMoveOverlap (0.72s) === RUN TestSyncOverlap run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6'", Local "Local file system at /tmp/rclone3693781112", Modify Window "1ms" 2022/01/13 06:13:32 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6/rclone-sync-test" 2022/01/13 06:13:32 DEBUG : Creating backend with remote "TestDrive:crypt/uisl9sq0nnijgh9rsquknl5hid8tgfd4ulloshk79oi1jpqjnrui2v5ped0l0af4qhlm0c9nu0uu8/i7355aa0sb89uagn75vfjqr6s3e3e1h2et8in57abn1fe8qfego0" --- PASS: TestSyncOverlap (2.15s) === RUN TestSyncCompareDest run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6'", Local "Local file system at /tmp/rclone3693781112", Modify Window "1ms" 2022/01/13 06:13:34 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6/dst" 2022/01/13 06:13:34 DEBUG : Creating backend with remote "TestDrive:crypt/uisl9sq0nnijgh9rsquknl5hid8tgfd4ulloshk79oi1jpqjnrui2v5ped0l0af4qhlm0c9nu0uu8/31u3jie661vd5p8j7rtc3hgbh0" 2022/01/13 06:13:36 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6/CompareDest" 2022/01/13 06:13:36 DEBUG : Creating backend with remote "TestDrive:crypt/uisl9sq0nnijgh9rsquknl5hid8tgfd4ulloshk79oi1jpqjnrui2v5ped0l0af4qhlm0c9nu0uu8/gveqi14airsml4bgu7krj116o8" 2022/01/13 06:13:38 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6/dst': Waiting for checks to finish 2022/01/13 06:13:38 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6/dst': Waiting for transfers to finish 2022/01/13 06:13:40 DEBUG : one: md5 = e2956aee3fc660f4947e1cc54325726a OK 2022/01/13 06:13:40 INFO : one: Copied (new) 2022/01/13 06:13:40 DEBUG : Waiting for deletions to finish 2022/01/13 06:13: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/01/13 06:13:41 DEBUG : pacer: Rate limited, increasing sleep to 1.549497972s 2022/01/13 06:13:41 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/01/13 06:13:41 DEBUG : pacer: Rate limited, increasing sleep to 2.579525739s 2022/01/13 06:13:43 DEBUG : pacer: Reducing sleep to 0s 2022/01/13 06:13:46 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6/dst': Waiting for checks to finish 2022/01/13 06:13:46 DEBUG : one: Sizes differ (src 5 vs dst 3) 2022/01/13 06:13:46 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6/dst': Waiting for transfers to finish 2022/01/13 06:13:47 DEBUG : one: md5 = effcdf82758cc61edee643ce4f37605b OK 2022/01/13 06:13:47 INFO : one: Copied (replaced existing) 2022/01/13 06:13:47 DEBUG : Waiting for deletions to finish 2022/01/13 06:13:49 DEBUG : dst/one: md5 = e892cc0be099f36b0f97bea4e0421fe2 OK 2022/01/13 06:13:52 DEBUG : CompareDest/one: md5 = ad577003deb8c13e1000b130462bc9b5 OK 2022/01/13 06:13:53 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6/dst': Waiting for checks to finish 2022/01/13 06:13:53 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/01/13 06:13:53 DEBUG : one: Destination found in --compare-dest, skipping 2022/01/13 06:13:53 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6/dst': Waiting for transfers to finish 2022/01/13 06:13:53 DEBUG : Waiting for deletions to finish 2022/01/13 06:13:53 INFO : There was nothing to transfer 2022/01/13 06:13:55 DEBUG : CompareDest/two: md5 = c78c91a9f021822b1c08a35ec0529aca OK 2022/01/13 06:13:56 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/01/13 06:13:56 DEBUG : two: Destination found in --compare-dest, skipping 2022/01/13 06:13:56 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6/dst': Waiting for checks to finish 2022/01/13 06:13: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/01/13 06:13:57 DEBUG : pacer: Rate limited, increasing sleep to 1.514984705s 2022/01/13 06:13:57 DEBUG : pacer: Reducing sleep to 0s 2022/01/13 06:13:57 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/01/13 06:13:57 DEBUG : one: Destination found in --compare-dest, skipping 2022/01/13 06:13:57 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6/dst': Waiting for transfers to finish 2022/01/13 06:13:57 DEBUG : Waiting for deletions to finish 2022/01/13 06:13:57 INFO : There was nothing to transfer 2022/01/13 06:13: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/01/13 06:13:58 DEBUG : pacer: Rate limited, increasing sleep to 1.477159864s 2022/01/13 06:13:58 DEBUG : pacer: Reducing sleep to 0s 2022/01/13 06:13:58 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/01/13 06:13:58 DEBUG : two: Destination found in --compare-dest, skipping 2022/01/13 06:13:58 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6/dst': Waiting for checks to finish 2022/01/13 06:13:59 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/01/13 06:13:59 DEBUG : one: Destination found in --compare-dest, skipping 2022/01/13 06:13:59 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6/dst': Waiting for transfers to finish 2022/01/13 06:13:59 DEBUG : Waiting for deletions to finish 2022/01/13 06:13:59 INFO : There was nothing to transfer sync_test.go:1543: No hash on uploaded file so skipping compare timestamp test 2022/01/13 06:14:00 DEBUG : two: Sizes differ (src 5 vs dst 3) 2022/01/13 06:14:00 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6/dst': Waiting for checks to finish 2022/01/13 06:14:01 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/01/13 06:14:01 DEBUG : one: Destination found in --compare-dest, skipping 2022/01/13 06:14:01 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6/dst': Waiting for transfers to finish 2022/01/13 06:14:02 DEBUG : two: md5 = 96956986d6818adb8119ac6a2c93af01 OK 2022/01/13 06:14:02 INFO : two: Copied (new) 2022/01/13 06:14:02 DEBUG : Waiting for deletions to finish 2022/01/13 06:14:06 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" 2022/01/13 06:14:06 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2022/01/13 06:14:06 DEBUG : gveqi14airsml4bgu7krj116o8: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" 2022/01/13 06:14:06 DEBUG : gveqi14airsml4bgu7krj116o8: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" --- PASS: TestSyncCompareDest (33.28s) === RUN TestSyncMultipleCompareDest run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6'", Local "Local file system at /tmp/rclone3693781112", Modify Window "1ms" 2022/01/13 06:14:10 DEBUG : pre-dest1/1: md5 = 35d4a4b36573c90f3e38832dae48fe1e OK 2022/01/13 06:14:12 DEBUG : pre-dest2/2: md5 = 72f39ed5750d62914f55890492421797 OK 2022/01/13 06:14:13 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6/dest" 2022/01/13 06:14:13 DEBUG : Creating backend with remote "TestDrive:crypt/uisl9sq0nnijgh9rsquknl5hid8tgfd4ulloshk79oi1jpqjnrui2v5ped0l0af4qhlm0c9nu0uu8/rg03c1jvnehrrc617i0lnqjddc" 2022/01/13 06:14:14 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6/pre-dest1" 2022/01/13 06:14:14 DEBUG : Creating backend with remote "TestDrive:crypt/uisl9sq0nnijgh9rsquknl5hid8tgfd4ulloshk79oi1jpqjnrui2v5ped0l0af4qhlm0c9nu0uu8/bbnblvh6k061ssopqrp18kd7gc" 2022/01/13 06:14:15 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6/pre-dest2" 2022/01/13 06:14:15 DEBUG : Creating backend with remote "TestDrive:crypt/uisl9sq0nnijgh9rsquknl5hid8tgfd4ulloshk79oi1jpqjnrui2v5ped0l0af4qhlm0c9nu0uu8/dgicm1h6b5ejvlltm8eeif0bnk" 2022/01/13 06:14:16 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/01/13 06:14:16 DEBUG : pacer: Rate limited, increasing sleep to 1.931524869s 2022/01/13 06:14: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/01/13 06:14:16 DEBUG : pacer: Rate limited, increasing sleep to 2.216747643s 2022/01/13 06:14:18 DEBUG : pacer: low level retry 3/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/01/13 06:14:18 DEBUG : pacer: Rate limited, increasing sleep to 4.052310965s 2022/01/13 06:14:20 DEBUG : pacer: Reducing sleep to 0s 2022/01/13 06:14:21 DEBUG : 1: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/01/13 06:14:21 DEBUG : 1: Destination found in --compare-dest, skipping 2022/01/13 06:14:21 DEBUG : 2: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/01/13 06:14:21 DEBUG : 2: Destination found in --compare-dest, skipping 2022/01/13 06:14:22 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6/dest': Waiting for checks to finish 2022/01/13 06:14:22 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6/dest': Waiting for transfers to finish 2022/01/13 06:14:26 DEBUG : 3: md5 = b52b0cea9a5e1c99ebf3e5e089c835df OK 2022/01/13 06:14:26 INFO : 3: Copied (new) 2022/01/13 06:14:26 DEBUG : Waiting for deletions to finish 2022/01/13 06:14:30 DEBUG : dgicm1h6b5ejvlltm8eeif0bnk: Rmdir: contains trashed file: "1ghu8geql9vrl726n32nrf65bc" 2022/01/13 06:14:31 DEBUG : bbnblvh6k061ssopqrp18kd7gc: Rmdir: contains trashed file: "skbfko3oil7es0lj68ob574sro" 2022/01/13 06:14:32 DEBUG : rg03c1jvnehrrc617i0lnqjddc: Rmdir: contains trashed file: "g072p7hmjchlnj0gibe64c1epg" --- PASS: TestSyncMultipleCompareDest (25.30s) === RUN TestSyncCopyDest run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6'", Local "Local file system at /tmp/rclone3693781112", Modify Window "1ms" 2022/01/13 06:14:33 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6/dst" 2022/01/13 06:14:33 DEBUG : Creating backend with remote "TestDrive:crypt/uisl9sq0nnijgh9rsquknl5hid8tgfd4ulloshk79oi1jpqjnrui2v5ped0l0af4qhlm0c9nu0uu8/31u3jie661vd5p8j7rtc3hgbh0" 2022/01/13 06:14:34 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6/CopyDest" 2022/01/13 06:14:34 DEBUG : Creating backend with remote "TestDrive:crypt/uisl9sq0nnijgh9rsquknl5hid8tgfd4ulloshk79oi1jpqjnrui2v5ped0l0af4qhlm0c9nu0uu8/d09o6po3f7bm6ce32vdgs8h9ls" 2022/01/13 06:14:36 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/01/13 06:14:36 DEBUG : pacer: Rate limited, increasing sleep to 1.04510297s 2022/01/13 06:14:36 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/01/13 06:14:36 DEBUG : pacer: Rate limited, increasing sleep to 2.516288279s 2022/01/13 06:14:37 DEBUG : pacer: low level retry 3/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/01/13 06:14:37 DEBUG : pacer: Rate limited, increasing sleep to 4.465293434s 2022/01/13 06:14:40 DEBUG : pacer: Reducing sleep to 0s 2022/01/13 06:14:40 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6/dst': Waiting for checks to finish 2022/01/13 06:14:40 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6/dst': Waiting for transfers to finish 2022/01/13 06:14:42 DEBUG : one: md5 = 6d6ed0455b130c74eab707a5f6ca806b OK 2022/01/13 06:14:42 INFO : one: Copied (new) 2022/01/13 06:14:42 DEBUG : Waiting for deletions to finish 2022/01/13 06:14:43 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6/dst': Waiting for checks to finish 2022/01/13 06:14:44 DEBUG : one: Sizes differ (src 5 vs dst 3) 2022/01/13 06:14:44 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6/dst': Waiting for transfers to finish 2022/01/13 06:14:47 DEBUG : one: md5 = 2cf598bea775935fcef0cdd4ba7e3748 OK 2022/01/13 06:14:47 INFO : one: Copied (replaced existing) 2022/01/13 06:14:47 DEBUG : Waiting for deletions to finish 2022/01/13 06:14:49 DEBUG : dst/one: md5 = 3f601b6d7221beca80599c44127d355b OK 2022/01/13 06:14:51 DEBUG : CopyDest/one: md5 = ae87a857f16d7fd54146ed209f889bb4 OK 2022/01/13 06:14:52 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6/BackupDir" 2022/01/13 06:14:52 DEBUG : Creating backend with remote "TestDrive:crypt/uisl9sq0nnijgh9rsquknl5hid8tgfd4ulloshk79oi1jpqjnrui2v5ped0l0af4qhlm0c9nu0uu8/s6dbk3lfi7c9kfvo6j7bla9m0g" 2022/01/13 06:14:53 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6/dst': Waiting for checks to finish 2022/01/13 06:14:54 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/01/13 06:14:54 DEBUG : one: Sizes differ (src 5 vs dst 3) 2022/01/13 06:14:56 INFO : one: Moved (server-side) 2022/01/13 06:14:57 INFO : one: Copied (server-side copy) 2022/01/13 06:14:57 DEBUG : one: Destination found in --copy-dest, using server-side copy 2022/01/13 06:14:57 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6/dst': Waiting for transfers to finish 2022/01/13 06:14:57 DEBUG : Waiting for deletions to finish 2022/01/13 06:14: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/01/13 06:14:57 DEBUG : pacer: Rate limited, increasing sleep to 1.15856808s 2022/01/13 06:14:57 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/01/13 06:14:57 DEBUG : pacer: Rate limited, increasing sleep to 2.142513209s 2022/01/13 06:14:58 DEBUG : pacer: low level retry 3/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/01/13 06:14:58 DEBUG : pacer: Rate limited, increasing sleep to 4.239429622s 2022/01/13 06:15:01 DEBUG : pacer: Reducing sleep to 0s 2022/01/13 06:15:06 DEBUG : CopyDest/two: md5 = b459605e604ca6ecd109c477bcc92c4c OK 2022/01/13 06:15:07 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/01/13 06:15:08 INFO : two: Copied (server-side copy) 2022/01/13 06:15:08 DEBUG : two: Destination found in --copy-dest, using server-side copy 2022/01/13 06:15:08 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6/dst': Waiting for checks to finish 2022/01/13 06:15:09 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/01/13 06:15:09 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/01/13 06:15:09 DEBUG : one: Unchanged skipping 2022/01/13 06:15:09 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6/dst': Waiting for transfers to finish 2022/01/13 06:15:09 DEBUG : Waiting for deletions to finish 2022/01/13 06:15:10 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6/dst': Waiting for checks to finish 2022/01/13 06:15:10 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/01/13 06:15:10 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/01/13 06:15:10 DEBUG : one: Unchanged skipping 2022/01/13 06:15:10 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/01/13 06:15:10 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/01/13 06:15:10 DEBUG : two: Unchanged skipping 2022/01/13 06:15:10 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6/dst': Waiting for transfers to finish 2022/01/13 06:15:10 DEBUG : Waiting for deletions to finish 2022/01/13 06:15:10 INFO : There was nothing to transfer 2022/01/13 06:15:12 DEBUG : CopyDest/three: md5 = 0412fd886f1d27d77780149ef8e36a0e OK 2022/01/13 06:15:13 DEBUG : three: Sizes differ (src 7 vs dst 5) 2022/01/13 06:15:13 DEBUG : three: Destination not found in --copy-dest 2022/01/13 06:15:13 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6/dst': Waiting for checks to finish 2022/01/13 06:15:13 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/01/13 06:15:13 DEBUG : two: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/01/13 06:15:13 DEBUG : two: Unchanged skipping 2022/01/13 06:15:13 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/01/13 06:15:13 DEBUG : one: Size and modification time the same (differ by -456.789µs, within tolerance 1ms) 2022/01/13 06:15:13 DEBUG : one: Unchanged skipping 2022/01/13 06:15:13 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6/dst': Waiting for transfers to finish 2022/01/13 06:15:14 DEBUG : three: md5 = 685043ce288dac24371ebc239bfe6ef9 OK 2022/01/13 06:15:14 INFO : three: Copied (new) 2022/01/13 06:15:14 DEBUG : Waiting for deletions to finish 2022/01/13 06:15:16 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/01/13 06:15:16 DEBUG : pacer: Rate limited, increasing sleep to 1.247156007s 2022/01/13 06:15: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/01/13 06:15:16 DEBUG : pacer: Rate limited, increasing sleep to 2.822100137s 2022/01/13 06:15:18 DEBUG : pacer: low level retry 3/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/01/13 06:15:18 DEBUG : pacer: Rate limited, increasing sleep to 4.838231475s 2022/01/13 06:15:21 DEBUG : pacer: Reducing sleep to 0s 2022/01/13 06:15:28 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "b6jdmn2b1adrhc8vikh7edr9os" 2022/01/13 06:15:28 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" 2022/01/13 06:15:28 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2022/01/13 06:15:29 DEBUG : d09o6po3f7bm6ce32vdgs8h9ls: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" 2022/01/13 06:15:29 DEBUG : d09o6po3f7bm6ce32vdgs8h9ls: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2022/01/13 06:15:29 DEBUG : d09o6po3f7bm6ce32vdgs8h9ls: Rmdir: contains trashed file: "b6jdmn2b1adrhc8vikh7edr9os" 2022/01/13 06:15:30 DEBUG : s6dbk3lfi7c9kfvo6j7bla9m0g: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" --- PASS: TestSyncCopyDest (58.36s) === RUN TestSyncBackupDir run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6'", Local "Local file system at /tmp/rclone3693781112", Modify Window "1ms" 2022/01/13 06:15:33 DEBUG : dst/one: md5 = d8a1fd261c479eb047b09b51e444bc3e OK 2022/01/13 06:15:35 DEBUG : dst/two: md5 = b0235a71ce6e61d30c8d209ddba5362d OK 2022/01/13 06:15:36 DEBUG : dst/three.txt: md5 = d431f37759054f4b3da83537becf7886 OK 2022/01/13 06:15:37 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6/dst" 2022/01/13 06:15:37 DEBUG : Creating backend with remote "TestDrive:crypt/uisl9sq0nnijgh9rsquknl5hid8tgfd4ulloshk79oi1jpqjnrui2v5ped0l0af4qhlm0c9nu0uu8/31u3jie661vd5p8j7rtc3hgbh0" 2022/01/13 06:15: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/01/13 06:15:37 DEBUG : pacer: Rate limited, increasing sleep to 1.0238872s 2022/01/13 06:15:38 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/01/13 06:15:38 DEBUG : pacer: Rate limited, increasing sleep to 2.448896913s 2022/01/13 06:15:39 DEBUG : pacer: Reducing sleep to 0s 2022/01/13 06:15:39 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6/backup" 2022/01/13 06:15:39 DEBUG : Creating backend with remote "TestDrive:crypt/uisl9sq0nnijgh9rsquknl5hid8tgfd4ulloshk79oi1jpqjnrui2v5ped0l0af4qhlm0c9nu0uu8/1nrff024r7pq65ecp72fc28jb0" 2022/01/13 06:15:41 DEBUG : one: Sizes differ (src 4 vs dst 3) 2022/01/13 06:15:41 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/01/13 06:15:41 DEBUG : two: Unchanged skipping 2022/01/13 06:15:41 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6/dst': Waiting for checks to finish 2022/01/13 06:15:43 INFO : one: Moved (server-side) 2022/01/13 06:15:43 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6/dst': Waiting for transfers to finish 2022/01/13 06:15:44 DEBUG : one: md5 = 6e537b995dde23e2a48edc6901617f65 OK 2022/01/13 06:15:44 INFO : one: Copied (new) 2022/01/13 06:15:44 DEBUG : Waiting for deletions to finish 2022/01/13 06:15:45 INFO : three.txt: Moved (server-side) 2022/01/13 06:15:45 INFO : three.txt: Moved into backup dir 2022/01/13 06:15:47 DEBUG : dst/three.txt: md5 = 58539cf6d676f6c5114576db9f343557 OK 2022/01/13 06:15: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/01/13 06:15:47 DEBUG : pacer: Rate limited, increasing sleep to 1.871204825s 2022/01/13 06:15:47 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/01/13 06:15:47 DEBUG : pacer: Rate limited, increasing sleep to 2.559864368s 2022/01/13 06:15:49 DEBUG : pacer: Reducing sleep to 0s 2022/01/13 06:15:52 DEBUG : one: Sizes differ (src 5 vs dst 4) 2022/01/13 06:15:52 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6/dst': Waiting for checks to finish 2022/01/13 06:15:52 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/01/13 06:15:52 DEBUG : two: Unchanged skipping 2022/01/13 06:15:53 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/01/13 06:15:53 DEBUG : pacer: Rate limited, increasing sleep to 1.538114716s 2022/01/13 06:15:53 DEBUG : pacer: Reducing sleep to 0s 2022/01/13 06:15:53 INFO : one: Deleted 2022/01/13 06:15:55 INFO : one: Moved (server-side) 2022/01/13 06:15:55 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6/dst': Waiting for transfers to finish 2022/01/13 06:15:56 DEBUG : one: md5 = a1eaf3f9e70b3d8ada7ada5dbe751041 OK 2022/01/13 06:15:56 INFO : one: Copied (new) 2022/01/13 06:15:56 DEBUG : Waiting for deletions to finish 2022/01/13 06:15:57 INFO : three.txt: Deleted 2022/01/13 06:15:58 INFO : three.txt: Moved (server-side) 2022/01/13 06:15:58 INFO : three.txt: Moved into backup dir 2022/01/13 06:16:02 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2022/01/13 06:16:02 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" 2022/01/13 06:16:02 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "tr2hj63d80ftlmvm6a952snjcc" 2022/01/13 06:16:02 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2022/01/13 06:16:02 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2022/01/13 06:16:02 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "tr2hj63d80ftlmvm6a952snjcc" --- PASS: TestSyncBackupDir (32.49s) === RUN TestSyncBackupDirWithSuffix run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6'", Local "Local file system at /tmp/rclone3693781112", Modify Window "1ms" 2022/01/13 06:16:06 DEBUG : dst/one: md5 = 8c9fd52ad3fdd7ba5176bab4944b6d87 OK 2022/01/13 06:16:07 DEBUG : dst/two: md5 = 36ab415bb701a9dc6e88f148ac0a6c28 OK 2022/01/13 06:16: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/01/13 06:16:07 DEBUG : pacer: Rate limited, increasing sleep to 1.243415091s 2022/01/13 06:16: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/01/13 06:16:07 DEBUG : pacer: Rate limited, increasing sleep to 2.131027464s 2022/01/13 06:16:09 DEBUG : pacer: Reducing sleep to 0s 2022/01/13 06:16:12 DEBUG : dst/three.txt: md5 = 5590b70a4f1405906eadb570ee434213 OK 2022/01/13 06:16:12 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6/dst" 2022/01/13 06:16:12 DEBUG : Creating backend with remote "TestDrive:crypt/uisl9sq0nnijgh9rsquknl5hid8tgfd4ulloshk79oi1jpqjnrui2v5ped0l0af4qhlm0c9nu0uu8/31u3jie661vd5p8j7rtc3hgbh0" 2022/01/13 06:16:13 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6/backup" 2022/01/13 06:16:13 DEBUG : Creating backend with remote "TestDrive:crypt/uisl9sq0nnijgh9rsquknl5hid8tgfd4ulloshk79oi1jpqjnrui2v5ped0l0af4qhlm0c9nu0uu8/1nrff024r7pq65ecp72fc28jb0" 2022/01/13 06:16:13 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/01/13 06:16:13 DEBUG : pacer: Rate limited, increasing sleep to 1.038646446s 2022/01/13 06:16:14 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/01/13 06:16:14 DEBUG : pacer: Rate limited, increasing sleep to 2.416940005s 2022/01/13 06:16:15 DEBUG : pacer: Reducing sleep to 0s 2022/01/13 06:16:18 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/01/13 06:16:18 DEBUG : pacer: Rate limited, increasing sleep to 1.908272953s 2022/01/13 06:16:18 DEBUG : pacer: Reducing sleep to 0s 2022/01/13 06:16:20 DEBUG : one: Sizes differ (src 4 vs dst 3) 2022/01/13 06:16:20 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/01/13 06:16:20 DEBUG : two: Unchanged skipping 2022/01/13 06:16:20 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6/dst': Waiting for checks to finish 2022/01/13 06:16:22 INFO : one: Moved (server-side) to: one.bak 2022/01/13 06:16:22 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6/dst': Waiting for transfers to finish 2022/01/13 06:16:23 DEBUG : one: md5 = 4143887817260e70abd1c33d015c542e OK 2022/01/13 06:16:23 INFO : one: Copied (new) 2022/01/13 06:16:23 DEBUG : Waiting for deletions to finish 2022/01/13 06:16:24 INFO : three.txt: Moved (server-side) to: three.txt.bak 2022/01/13 06:16:24 INFO : three.txt: Moved into backup dir 2022/01/13 06:16:26 DEBUG : dst/three.txt: md5 = 29fa89c782b72c464486b6c6cc9607da OK 2022/01/13 06:16:27 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6/dst': Waiting for checks to finish 2022/01/13 06:16:27 DEBUG : one: Sizes differ (src 5 vs dst 4) 2022/01/13 06:16:27 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/01/13 06:16:27 DEBUG : two: Unchanged skipping 2022/01/13 06:16:27 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/01/13 06:16:27 DEBUG : pacer: Rate limited, increasing sleep to 1.853113054s 2022/01/13 06:16:27 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/01/13 06:16:27 DEBUG : pacer: Rate limited, increasing sleep to 2.215171436s 2022/01/13 06:16:29 DEBUG : pacer: Reducing sleep to 0s 2022/01/13 06:16:32 INFO : one.bak: Deleted 2022/01/13 06:16:32 INFO : one: Moved (server-side) to: one.bak 2022/01/13 06:16:32 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6/dst': Waiting for transfers to finish 2022/01/13 06:16:34 DEBUG : one: md5 = 998ba8d6ffb0a7a4c1bc2e2fabfdb29a OK 2022/01/13 06:16:34 INFO : one: Copied (new) 2022/01/13 06:16:34 DEBUG : Waiting for deletions to finish 2022/01/13 06:16:35 INFO : three.txt.bak: Deleted 2022/01/13 06:16:35 INFO : three.txt: Moved (server-side) to: three.txt.bak 2022/01/13 06:16:35 INFO : three.txt: Moved into backup dir 2022/01/13 06:16:39 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2022/01/13 06:16:39 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" 2022/01/13 06:16:40 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "sk91qgsqfn0r271r2ehsaoc20c" 2022/01/13 06:16:40 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "qltcak2uaegtmcoa8vijdppbp8" 2022/01/13 06:16:40 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "qltcak2uaegtmcoa8vijdppbp8" 2022/01/13 06:16:40 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "sk91qgsqfn0r271r2ehsaoc20c" --- PASS: TestSyncBackupDirWithSuffix (37.42s) === RUN TestSyncBackupDirWithSuffixKeepExtension run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6'", Local "Local file system at /tmp/rclone3693781112", Modify Window "1ms" 2022/01/13 06:16:43 DEBUG : dst/one: md5 = 7d544e08dcf79c24271a40b262e97522 OK 2022/01/13 06:16:45 DEBUG : dst/two: md5 = 01ae88a257f903561d28f6d2861978c7 OK 2022/01/13 06:16:46 DEBUG : dst/three.txt: md5 = d911b8caef238aea21bc42867570b230 OK 2022/01/13 06:16:47 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6/dst" 2022/01/13 06:16:47 DEBUG : Creating backend with remote "TestDrive:crypt/uisl9sq0nnijgh9rsquknl5hid8tgfd4ulloshk79oi1jpqjnrui2v5ped0l0af4qhlm0c9nu0uu8/31u3jie661vd5p8j7rtc3hgbh0" 2022/01/13 06:16:47 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6/backup" 2022/01/13 06:16:48 DEBUG : Creating backend with remote "TestDrive:crypt/uisl9sq0nnijgh9rsquknl5hid8tgfd4ulloshk79oi1jpqjnrui2v5ped0l0af4qhlm0c9nu0uu8/1nrff024r7pq65ecp72fc28jb0" 2022/01/13 06:16: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/01/13 06:16:48 DEBUG : pacer: Rate limited, increasing sleep to 1.112496711s 2022/01/13 06:16:48 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/01/13 06:16:48 DEBUG : pacer: Rate limited, increasing sleep to 2.738218451s 2022/01/13 06:16:49 DEBUG : pacer: Reducing sleep to 0s 2022/01/13 06:16:53 DEBUG : one: Sizes differ (src 4 vs dst 3) 2022/01/13 06:16:53 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/01/13 06:16:53 DEBUG : two: Unchanged skipping 2022/01/13 06:16:53 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6/dst': Waiting for checks to finish 2022/01/13 06:16:55 INFO : one: Moved (server-side) to: one-2019-01-01 2022/01/13 06:16:55 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6/dst': Waiting for transfers to finish 2022/01/13 06:16:57 DEBUG : one: md5 = 1681d9cd4e5d725330196722ebbe6e56 OK 2022/01/13 06:16:57 INFO : one: Copied (new) 2022/01/13 06:16:57 DEBUG : Waiting for deletions to finish 2022/01/13 06:16:58 INFO : three.txt: Moved (server-side) to: three-2019-01-01.txt 2022/01/13 06:16:58 INFO : three.txt: Moved into backup dir 2022/01/13 06:17:00 DEBUG : dst/three.txt: md5 = f8d90c32a3bb29dd4254cba4f8fd04ab OK 2022/01/13 06:17:00 DEBUG : one: Sizes differ (src 5 vs dst 4) 2022/01/13 06:17:00 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6/dst': Waiting for checks to finish 2022/01/13 06:17:00 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/01/13 06:17:00 DEBUG : two: Unchanged skipping 2022/01/13 06:17:01 INFO : one-2019-01-01: Deleted 2022/01/13 06:17:02 INFO : one: Moved (server-side) to: one-2019-01-01 2022/01/13 06:17:02 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6/dst': Waiting for transfers to finish 2022/01/13 06:17:03 DEBUG : one: md5 = b4d7b23de95e05916459651aa494cbb2 OK 2022/01/13 06:17:03 INFO : one: Copied (new) 2022/01/13 06:17:03 DEBUG : Waiting for deletions to finish 2022/01/13 06:17:04 INFO : three-2019-01-01.txt: Deleted 2022/01/13 06:17:05 INFO : three.txt: Moved (server-side) to: three-2019-01-01.txt 2022/01/13 06:17:05 INFO : three.txt: Moved into backup dir 2022/01/13 06:17: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/01/13 06:17:08 DEBUG : pacer: Rate limited, increasing sleep to 1.148374396s 2022/01/13 06:17: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/01/13 06:17:08 DEBUG : pacer: Rate limited, increasing sleep to 2.306810621s 2022/01/13 06:17:09 DEBUG : pacer: Reducing sleep to 0s 2022/01/13 06:17:12 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2022/01/13 06:17:12 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" 2022/01/13 06:17:13 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "jcjl1bv3ep0v8kt35lqql1co90" 2022/01/13 06:17:13 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "qtq2f6qq4lgpsmj88vb7147qje3prudmtfdtr2342fth58vo9a50" 2022/01/13 06:17:13 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "qtq2f6qq4lgpsmj88vb7147qje3prudmtfdtr2342fth58vo9a50" 2022/01/13 06:17:13 DEBUG : 1nrff024r7pq65ecp72fc28jb0: Rmdir: contains trashed file: "jcjl1bv3ep0v8kt35lqql1co90" --- PASS: TestSyncBackupDirWithSuffixKeepExtension (32.70s) === RUN TestSyncBackupDirSuffixOnly run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6'", Local "Local file system at /tmp/rclone3693781112", Modify Window "1ms" 2022/01/13 06:17:16 DEBUG : dst/one: md5 = 0f4f07083f7101ec670e2d17c16a60c3 OK 2022/01/13 06:17:17 DEBUG : dst/two: md5 = 44982e6e0ae7a56929b802ec63ae5d91 OK 2022/01/13 06:17:19 DEBUG : dst/three.txt: md5 = 372cfcc6be73f04133c2c6cbecf24ffa OK 2022/01/13 06:17:19 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6/dst" 2022/01/13 06:17:19 DEBUG : Creating backend with remote "TestDrive:crypt/uisl9sq0nnijgh9rsquknl5hid8tgfd4ulloshk79oi1jpqjnrui2v5ped0l0af4qhlm0c9nu0uu8/31u3jie661vd5p8j7rtc3hgbh0" 2022/01/13 06:17:21 DEBUG : one: Sizes differ (src 4 vs dst 3) 2022/01/13 06:17:21 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/01/13 06:17:21 DEBUG : two: Unchanged skipping 2022/01/13 06:17:21 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6/dst': Waiting for checks to finish 2022/01/13 06:17:21 INFO : one: Moved (server-side) to: one.bak 2022/01/13 06:17:21 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6/dst': Waiting for transfers to finish 2022/01/13 06:17:23 DEBUG : one: md5 = 68a04909eb44a5b802dc13dc2137b392 OK 2022/01/13 06:17:23 INFO : one: Copied (new) 2022/01/13 06:17:23 DEBUG : Waiting for deletions to finish 2022/01/13 06:17:24 INFO : three.txt: Moved (server-side) to: three.txt.bak 2022/01/13 06:17:24 INFO : three.txt: Moved into backup dir 2022/01/13 06:17:26 DEBUG : dst/three.txt: md5 = e8cbc2ff7b1864498c9d023bc5099b69 OK 2022/01/13 06:17:27 DEBUG : three.txt.bak: Excluded from sync (and deletion) 2022/01/13 06:17:27 DEBUG : one.bak: Excluded from sync (and deletion) 2022/01/13 06:17:27 DEBUG : one: Sizes differ (src 5 vs dst 4) 2022/01/13 06:17:27 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6/dst': Waiting for checks to finish 2022/01/13 06:17:27 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/01/13 06:17:27 DEBUG : two: Unchanged skipping 2022/01/13 06:17:27 INFO : one.bak: Deleted 2022/01/13 06:17:28 INFO : one: Moved (server-side) to: one.bak 2022/01/13 06:17:28 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6/dst': Waiting for transfers to finish 2022/01/13 06:17: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/01/13 06:17:28 DEBUG : pacer: Rate limited, increasing sleep to 1.080841427s 2022/01/13 06:17: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/01/13 06:17:28 DEBUG : pacer: Rate limited, increasing sleep to 2.534749833s 2022/01/13 06:17:29 DEBUG : pacer: Reducing sleep to 0s 2022/01/13 06:17:33 DEBUG : one: md5 = ee7be0ffdd9f4469489df385abe5bf73 OK 2022/01/13 06:17:33 INFO : one: Copied (new) 2022/01/13 06:17:33 DEBUG : Waiting for deletions to finish 2022/01/13 06:17:34 INFO : three.txt.bak: Deleted 2022/01/13 06:17:34 INFO : three.txt: Moved (server-side) to: three.txt.bak 2022/01/13 06:17:34 INFO : three.txt: Moved into backup dir 2022/01/13 06:17:38 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2022/01/13 06:17:38 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "sk91qgsqfn0r271r2ehsaoc20c" 2022/01/13 06:17:38 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "qltcak2uaegtmcoa8vijdppbp8" 2022/01/13 06:17:38 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "sk91qgsqfn0r271r2ehsaoc20c" 2022/01/13 06:17:38 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" 2022/01/13 06:17:38 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "qltcak2uaegtmcoa8vijdppbp8" --- PASS: TestSyncBackupDirSuffixOnly (25.26s) === RUN TestSyncSuffix run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6'", Local "Local file system at /tmp/rclone3693781112", Modify Window "1ms" 2022/01/13 06:17:41 DEBUG : dst/one: md5 = 24178543e65fa5ab1d159fcb16ae6fe9 OK 2022/01/13 06:17:42 DEBUG : dst/two: md5 = e9779541a0e81e929a0e603f7076984b OK 2022/01/13 06:17:44 DEBUG : dst/three.txt: md5 = 2e4882fe16bc91b239fc322fb799cd73 OK 2022/01/13 06:17:45 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6/dst" 2022/01/13 06:17:45 DEBUG : Config file has changed externaly - reloading 2022/01/13 06:17:45 DEBUG : Creating backend with remote "TestDrive:crypt/uisl9sq0nnijgh9rsquknl5hid8tgfd4ulloshk79oi1jpqjnrui2v5ped0l0af4qhlm0c9nu0uu8/31u3jie661vd5p8j7rtc3hgbh0" 2022/01/13 06:17:46 DEBUG : one: Sizes differ (src 4 vs dst 3) 2022/01/13 06:17:47 INFO : one: Moved (server-side) to: one.bak 2022/01/13 06:17:48 DEBUG : one: md5 = 8000d27a4d48118b01409df581671a61 OK 2022/01/13 06:17:48 INFO : one: Copied (new) 2022/01/13 06:17: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/01/13 06:17:48 DEBUG : pacer: Rate limited, increasing sleep to 1.52066301s 2022/01/13 06:17:48 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/01/13 06:17:48 DEBUG : pacer: Rate limited, increasing sleep to 2.116045819s 2022/01/13 06:17:50 DEBUG : pacer: Reducing sleep to 0s 2022/01/13 06:17:50 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/01/13 06:17:50 DEBUG : two: Unchanged skipping 2022/01/13 06:17:52 DEBUG : three.txt: Sizes differ (src 6 vs dst 5) 2022/01/13 06:17:53 INFO : three.txt: Moved (server-side) to: three.txt.bak 2022/01/13 06:17:54 DEBUG : three.txt: md5 = c19871933498c140d66f799af99b3ecf OK 2022/01/13 06:17:54 INFO : three.txt: Copied (new) 2022/01/13 06:17:56 DEBUG : one: Sizes differ (src 5 vs dst 4) 2022/01/13 06:17:56 INFO : one.bak: Deleted 2022/01/13 06:17:57 INFO : one: Moved (server-side) to: one.bak 2022/01/13 06:17:57 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/01/13 06:17:57 DEBUG : pacer: Rate limited, increasing sleep to 1.156831122s 2022/01/13 06:17:57 DEBUG : one: 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/01/13 06:17: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/01/13 06:17:58 DEBUG : pacer: Rate limited, increasing sleep to 2.009522241s 2022/01/13 06:17:59 DEBUG : pacer: Reducing sleep to 0s 2022/01/13 06:18:02 DEBUG : one: md5 = 933e5b5590bb115adf343754d6e40588 OK 2022/01/13 06:18:02 INFO : one: Copied (new) 2022/01/13 06:18:02 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/01/13 06:18:02 DEBUG : two: Unchanged skipping 2022/01/13 06:18:02 DEBUG : three.txt: Sizes differ (src 19 vs dst 6) 2022/01/13 06:18:03 INFO : three.txt.bak: Deleted 2022/01/13 06:18:04 INFO : three.txt: Moved (server-side) to: three.txt.bak 2022/01/13 06:18:05 DEBUG : three.txt: md5 = a302182264842ebc79a785ee84362b8d OK 2022/01/13 06:18:05 INFO : three.txt: Copied (new) 2022/01/13 06:18:10 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2022/01/13 06:18:10 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "tr2hj63d80ftlmvm6a952snjcc" 2022/01/13 06:18:10 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "qltcak2uaegtmcoa8vijdppbp8" 2022/01/13 06:18:10 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "qltcak2uaegtmcoa8vijdppbp8" 2022/01/13 06:18:10 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" 2022/01/13 06:18:10 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "sk91qgsqfn0r271r2ehsaoc20c" 2022/01/13 06:18:10 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "sk91qgsqfn0r271r2ehsaoc20c" --- PASS: TestSyncSuffix (31.75s) === RUN TestSyncSuffixKeepExtension run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6'", Local "Local file system at /tmp/rclone3693781112", Modify Window "1ms" 2022/01/13 06:18:13 DEBUG : dst/one: md5 = 7c6cc41b9f2530c9c89e695e5bd6953a OK 2022/01/13 06:18:14 DEBUG : dst/two: md5 = 1c5e694f2f5856beea9c1366dd73aee7 OK 2022/01/13 06:18:16 DEBUG : dst/three.txt: md5 = 1b3484d3c8d199ffff08ef283a103171 OK 2022/01/13 06:18:16 DEBUG : Creating backend with remote "TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6/dst" 2022/01/13 06:18:16 DEBUG : Creating backend with remote "TestDrive:crypt/uisl9sq0nnijgh9rsquknl5hid8tgfd4ulloshk79oi1jpqjnrui2v5ped0l0af4qhlm0c9nu0uu8/31u3jie661vd5p8j7rtc3hgbh0" 2022/01/13 06:18:17 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/01/13 06:18:17 DEBUG : pacer: Rate limited, increasing sleep to 1.084436659s 2022/01/13 06:18:18 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/01/13 06:18:18 DEBUG : pacer: Rate limited, increasing sleep to 2.763069032s 2022/01/13 06:18:19 DEBUG : pacer: Reducing sleep to 0s 2022/01/13 06:18:19 DEBUG : one: Sizes differ (src 4 vs dst 3) 2022/01/13 06:18:22 INFO : one: Moved (server-side) to: one-2019-01-01 2022/01/13 06:18:23 DEBUG : one: md5 = 5271f0c53d9172138b4cf85f2658af8f OK 2022/01/13 06:18:23 INFO : one: Copied (new) 2022/01/13 06:18:24 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/01/13 06:18:24 DEBUG : two: Unchanged skipping 2022/01/13 06:18:24 DEBUG : three.txt: Sizes differ (src 6 vs dst 5) 2022/01/13 06:18:25 INFO : three.txt: Moved (server-side) to: three-2019-01-01.txt 2022/01/13 06:18:26 DEBUG : three.txt: md5 = 06828967c4bd2c6a20f5f070c27f4a93 OK 2022/01/13 06:18:26 INFO : three.txt: Copied (new) 2022/01/13 06:18:27 DEBUG : one: Sizes differ (src 5 vs dst 4) 2022/01/13 06:18:28 INFO : one-2019-01-01: Deleted 2022/01/13 06:18:29 INFO : one: Moved (server-side) to: one-2019-01-01 2022/01/13 06:18:30 DEBUG : one: md5 = 5adb1dd37765709fd19078ebccc56db4 OK 2022/01/13 06:18:30 INFO : one: Copied (new) 2022/01/13 06:18:30 DEBUG : two: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/01/13 06:18:30 DEBUG : two: Unchanged skipping 2022/01/13 06:18:31 DEBUG : three.txt: Sizes differ (src 19 vs dst 6) 2022/01/13 06:18:31 INFO : three-2019-01-01.txt: Deleted 2022/01/13 06:18:31 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/01/13 06:18:31 DEBUG : pacer: Rate limited, increasing sleep to 1.072463334s 2022/01/13 06:18:32 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/01/13 06:18:32 DEBUG : pacer: Rate limited, increasing sleep to 2.994004989s 2022/01/13 06:18:33 DEBUG : pacer: Reducing sleep to 0s 2022/01/13 06:18:33 INFO : three.txt: Moved (server-side) to: three-2019-01-01.txt 2022/01/13 06:18:37 DEBUG : three.txt: md5 = 2ac2c5541ff526e7cf0e795271bee9fc OK 2022/01/13 06:18:37 INFO : three.txt: Copied (new) 2022/01/13 06:18:41 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "0828u6q2p8d62qeklrkkuf10uc" 2022/01/13 06:18:41 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "tr2hj63d80ftlmvm6a952snjcc" 2022/01/13 06:18:41 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "jcjl1bv3ep0v8kt35lqql1co90" 2022/01/13 06:18:41 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "jcjl1bv3ep0v8kt35lqql1co90" 2022/01/13 06:18:41 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "qtq2f6qq4lgpsmj88vb7147qje3prudmtfdtr2342fth58vo9a50" 2022/01/13 06:18:41 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "qtq2f6qq4lgpsmj88vb7147qje3prudmtfdtr2342fth58vo9a50" 2022/01/13 06:18:41 DEBUG : 31u3jie661vd5p8j7rtc3hgbh0: Rmdir: contains trashed file: "keafetfvtbmgo6tsdvcbj32i0k" --- PASS: TestSyncSuffixKeepExtension (31.61s) === RUN TestSyncUTFNorm run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6'", Local "Local file system at /tmp/rclone3693781112", Modify Window "1ms" 2022/01/13 06:18:43 DEBUG : Testêé: md5 = 8b04fb205b877b1a7b6171a9ee8da239 OK 2022/01/13 06:18:44 DEBUG : Testêé: Sizes differ (src 14 vs dst 18) 2022/01/13 06:18:44 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for checks to finish 2022/01/13 06:18:44 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for transfers to finish 2022/01/13 06:18:45 DEBUG : Testêé: md5 = aaca7b8473ad5bc99e5f41c2b664d71f OK 2022/01/13 06:18:45 INFO : Testêé: Copied (replaced existing) 2022/01/13 06:18:45 DEBUG : Waiting for deletions to finish --- PASS: TestSyncUTFNorm (4.33s) === RUN TestSyncImmutable run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6'", Local "Local file system at /tmp/rclone3693781112", Modify Window "1ms" 2022/01/13 06:18:47 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for checks to finish 2022/01/13 06:18:47 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for transfers to finish 2022/01/13 06:18:48 DEBUG : existing: md5 = b14fcda9b3fb8fcdc32009577b633a93 OK 2022/01/13 06:18:48 INFO : existing: Copied (new) 2022/01/13 06:18:48 DEBUG : Waiting for deletions to finish 2022/01/13 06:18:49 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for checks to finish 2022/01/13 06:18:49 DEBUG : existing: Sizes differ (src 8 vs dst 6) 2022/01/13 06:18:49 ERROR : existing: Source and destination exist but do not match: immutable file modified 2022/01/13 06:18:49 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for transfers to finish 2022/01/13 06:18:49 ERROR : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': not deleting files as there were IO errors 2022/01/13 06:18:49 ERROR : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': not deleting directories as there were IO errors --- PASS: TestSyncImmutable (4.29s) === RUN TestSyncIgnoreCase run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6'", Local "Local file system at /tmp/rclone3693781112", Modify Window "1ms" 2022/01/13 06:18:52 DEBUG : EXISTING: md5 = 0b81a8e8ace4e044a3106635139371cf OK 2022/01/13 06:18:53 DEBUG : existing: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/01/13 06:18:53 DEBUG : existing: Unchanged skipping 2022/01/13 06:18:53 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for checks to finish 2022/01/13 06:18:53 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for transfers to finish 2022/01/13 06:18:53 DEBUG : Waiting for deletions to finish 2022/01/13 06:18:53 INFO : There was nothing to transfer --- PASS: TestSyncIgnoreCase (3.30s) === RUN TestMaxTransfer === RUN TestMaxTransfer/Hard run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6'", Local "Local file system at /tmp/rclone3693781112", Modify Window "1ms" sync_test.go:1989: This test only runs on local === RUN TestMaxTransfer/Soft run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6'", Local "Local file system at /tmp/rclone3693781112", Modify Window "1ms" sync_test.go:1989: This test only runs on local === RUN TestMaxTransfer/Cautious run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6'", Local "Local file system at /tmp/rclone3693781112", Modify Window "1ms" sync_test.go:1989: This test only runs on local --- PASS: TestMaxTransfer (1.54s) --- SKIP: TestMaxTransfer/Hard (0.51s) --- SKIP: TestMaxTransfer/Soft (0.51s) --- SKIP: TestMaxTransfer/Cautious (0.52s) === RUN TestSyncConcurrentDelete run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6'", Local "Local file system at /tmp/rclone3693781112", Modify Window "1ms" 2022/01/13 06:18:57 DEBUG : both0: md5 = abcaa1fb03a707ad905f086f1adc45cc OK 2022/01/13 06:18:59 DEBUG : only0: md5 = 7360771cd42214e4ea239294bce6a38f OK 2022/01/13 06:19:00 DEBUG : both1: md5 = 14e8ea7803f2e0c400761f7772f1aa12 OK 2022/01/13 06:19:01 DEBUG : only1: md5 = 16b003609985e67d75eb364e40ef667d OK 2022/01/13 06:19:03 DEBUG : both2: md5 = 536fbe7f4f51a74ca98134a71bade972 OK 2022/01/13 06:19:04 DEBUG : only2: md5 = c8b3bba43aba49cc41d30769bd67aa99 OK 2022/01/13 06:19:06 DEBUG : both3: md5 = 4443e35440301a7b08b26b2b9920650f OK 2022/01/13 06:19:07 DEBUG : only3: md5 = 22f12390ee496a69be4a942941a90a81 OK 2022/01/13 06:19:08 DEBUG : both4: md5 = b5291b25eb46433a1d492a3bf6f85357 OK 2022/01/13 06:19:10 DEBUG : only4: md5 = bb22f4580d3fdb0e5507b11fb281c1db OK 2022/01/13 06:19:11 DEBUG : both5: md5 = c36d2eebfc3212be29a6095ca600a046 OK 2022/01/13 06:19:12 DEBUG : only5: md5 = 558c9cbf3588e795a8325454b41bb88d OK 2022/01/13 06:19:14 DEBUG : both6: md5 = 35a52adb0f71c1d4619e425d2e368f9b OK 2022/01/13 06:19:15 DEBUG : only6: md5 = eef77c61c9f300d4bc31608d7f878a4a OK 2022/01/13 06:19:17 DEBUG : both7: md5 = b597e76b00d79489b5ae0bbf724aa28c OK 2022/01/13 06:19:18 DEBUG : only7: md5 = c999f9c75f19647ba38226da6ec2d20b OK 2022/01/13 06:19:20 DEBUG : both8: md5 = 2fde1878073b3bda94a243aeb0ce11a2 OK 2022/01/13 06:19:21 DEBUG : only8: md5 = d8bf1691c4592a49a1dea11b1cef2b8b OK 2022/01/13 06:19:23 DEBUG : both9: md5 = f768082053a1b119b0607edd82ba1a62 OK 2022/01/13 06:19:24 DEBUG : only9: md5 = b745ead01b04c1bdac3935d911263060 OK 2022/01/13 06:19:26 DEBUG : both10: md5 = 7e1f4c5a6e80b96f27a2460ada2198fa OK 2022/01/13 06:19:27 DEBUG : only10: md5 = f2245d9a1f8541e2158cfc9e63719028 OK 2022/01/13 06:19:29 DEBUG : both11: md5 = 0e7de1cca5e1b27c05be4e789b71dbb6 OK 2022/01/13 06:19:30 DEBUG : only11: md5 = 86764fd8bf47884c26668830c12158fa OK 2022/01/13 06:19:32 DEBUG : both12: md5 = d984cf36b1bd5456ca9691f13256ad22 OK 2022/01/13 06:19:33 DEBUG : only12: md5 = 98251efff191cd79590c6d9a4285841c OK 2022/01/13 06:19:34 DEBUG : both13: md5 = 8dd1aef8a48ab988afe58eb17e6af248 OK 2022/01/13 06:19:36 DEBUG : only13: md5 = 2e40810a4d674e0a1f1ffbfbcacee457 OK 2022/01/13 06:19:37 DEBUG : both14: md5 = 1571a28b2aed445f52e0fa71fb0b32fe OK 2022/01/13 06:19:39 DEBUG : only14: md5 = bca143c618e66d52ae0706637affc55e OK 2022/01/13 06:19:40 DEBUG : both15: md5 = dd1401503cd72be281ff561de44bb887 OK 2022/01/13 06:19:41 DEBUG : only15: md5 = 9df8c9a6c1e78443782c1abdc459dfc1 OK 2022/01/13 06:19:43 DEBUG : both16: md5 = a156b3ab5680ffc6d57a69a00056e02f OK 2022/01/13 06:19:44 DEBUG : only16: md5 = d43d83fb6b81d0be8a0c3a4f72ec65cc OK 2022/01/13 06:19:46 DEBUG : both17: md5 = 82b24d971d89013fb08649873e99ae49 OK 2022/01/13 06:19:47 DEBUG : only17: md5 = b41fe2c17926874ed3a76d06624ad145 OK 2022/01/13 06:19:49 DEBUG : both18: md5 = 09042d59e31dcbc7c31c87bddbb2cb7e OK 2022/01/13 06:19:50 DEBUG : only18: md5 = 9736654ffa68be8a4a400f81aed064a9 OK 2022/01/13 06:19:51 DEBUG : both19: md5 = 6fc8d0480b85bf291dd1d219b41c572f OK 2022/01/13 06:19:53 DEBUG : only19: md5 = 4a8e00f66215e59d1ce22fc4a759c531 OK 2022/01/13 06:19:54 DEBUG : both0: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/01/13 06:19:54 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for checks to finish 2022/01/13 06:19:54 DEBUG : both0: Unchanged skipping 2022/01/13 06:19:54 DEBUG : both12: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/01/13 06:19:54 DEBUG : both12: Unchanged skipping 2022/01/13 06:19:54 DEBUG : both13: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/01/13 06:19:54 DEBUG : both13: Unchanged skipping 2022/01/13 06:19:54 DEBUG : both14: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/01/13 06:19:54 DEBUG : both14: Unchanged skipping 2022/01/13 06:19:54 DEBUG : both15: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/01/13 06:19:54 DEBUG : both15: Unchanged skipping 2022/01/13 06:19:54 DEBUG : both16: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/01/13 06:19:54 DEBUG : both16: Unchanged skipping 2022/01/13 06:19:54 DEBUG : both17: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/01/13 06:19:54 DEBUG : both17: Unchanged skipping 2022/01/13 06:19:54 DEBUG : both18: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/01/13 06:19:54 DEBUG : both1: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/01/13 06:19:54 DEBUG : both18: Unchanged skipping 2022/01/13 06:19:54 DEBUG : both1: Unchanged skipping 2022/01/13 06:19:54 DEBUG : both19: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/01/13 06:19:54 DEBUG : both19: Unchanged skipping 2022/01/13 06:19:54 DEBUG : both2: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/01/13 06:19:54 DEBUG : both2: Unchanged skipping 2022/01/13 06:19:54 DEBUG : both3: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/01/13 06:19:54 DEBUG : both3: Unchanged skipping 2022/01/13 06:19:54 DEBUG : both4: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/01/13 06:19:54 DEBUG : both4: Unchanged skipping 2022/01/13 06:19:54 DEBUG : both5: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/01/13 06:19:54 DEBUG : both6: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/01/13 06:19:54 DEBUG : both11: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/01/13 06:19:54 DEBUG : both5: Unchanged skipping 2022/01/13 06:19:54 DEBUG : both11: Unchanged skipping 2022/01/13 06:19:54 DEBUG : both7: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/01/13 06:19:54 DEBUG : both8: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/01/13 06:19:54 DEBUG : both7: Unchanged skipping 2022/01/13 06:19:54 DEBUG : both6: Unchanged skipping 2022/01/13 06:19:54 DEBUG : both9: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/01/13 06:19:54 DEBUG : both10: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/01/13 06:19:54 DEBUG : both10: Unchanged skipping 2022/01/13 06:19:54 DEBUG : both8: Unchanged skipping 2022/01/13 06:19:54 DEBUG : both9: Unchanged skipping 2022/01/13 06:19:54 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for transfers to finish 2022/01/13 06:19:54 DEBUG : Waiting for deletions to finish 2022/01/13 06:19:54 INFO : only4: Deleted 2022/01/13 06:19:54 INFO : only1: Deleted 2022/01/13 06:19:54 INFO : only5: Deleted 2022/01/13 06:19:54 INFO : only0: Deleted 2022/01/13 06:19:54 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/01/13 06:19:54 DEBUG : pacer: Rate limited, increasing sleep to 1.39943246s 2022/01/13 06:19:54 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/01/13 06:19:54 DEBUG : pacer: Rate limited, increasing sleep to 2.254695953s 2022/01/13 06:19:54 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/01/13 06:19:54 DEBUG : pacer: Rate limited, increasing sleep to 4.100895838s 2022/01/13 06:19:54 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/01/13 06:19:54 DEBUG : pacer: Rate limited, increasing sleep to 8.220989117s 2022/01/13 06:19:55 DEBUG : pacer: Reducing sleep to 0s 2022/01/13 06:19:55 INFO : only8: Deleted 2022/01/13 06:19:56 INFO : only16: Deleted 2022/01/13 06:19:56 INFO : only9: Deleted 2022/01/13 06:19:56 INFO : only19: Deleted 2022/01/13 06:19:56 INFO : only3: Deleted 2022/01/13 06:19:57 INFO : only10: Deleted 2022/01/13 06:19:57 INFO : only12: Deleted 2022/01/13 06:19:57 INFO : only11: Deleted 2022/01/13 06:19:57 INFO : only14: Deleted 2022/01/13 06:19:57 INFO : only15: Deleted 2022/01/13 06:19:57 INFO : only18: Deleted 2022/01/13 06:19:57 INFO : only2: Deleted 2022/01/13 06:19:58 INFO : only7: Deleted 2022/01/13 06:19:58 INFO : only13: Deleted 2022/01/13 06:19:58 INFO : only17: Deleted 2022/01/13 06:19:58 INFO : only6: Deleted 2022/01/13 06:19:58 INFO : There was nothing to transfer 2022/01/13 06:20:05 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: User Rate Limit Exceeded. Rate of requests for user exceed configured project quota. You may consider re-evaluating expected per-user traffic to the API and adjust project quota limits accordingly. You may monitor aggregate quota usage and adjust limits in the API Console: https://console.developers.google.com/apis/api/drive.googleapis.com/quotas?project=847840889997, userRateLimitExceeded) 2022/01/13 06:20:05 DEBUG : pacer: Rate limited, increasing sleep to 1.546323532s 2022/01/13 06:20:06 DEBUG : pacer: Reducing sleep to 0s --- PASS: TestSyncConcurrentDelete (74.64s) === RUN TestSyncConcurrentTruncate run.go:181: Remote "Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6'", Local "Local file system at /tmp/rclone3693781112", Modify Window "1ms" 2022/01/13 06:20:12 DEBUG : both0: md5 = 3337a1244a40c15e4d30612b3011378e OK 2022/01/13 06:20:13 DEBUG : only0: md5 = c9f20a5cc0f15f759a24a211e0b3fa50 OK 2022/01/13 06:20:15 DEBUG : both1: md5 = 0fdfab4ecbf25ac1086dfeb43ee226d1 OK 2022/01/13 06:20:16 DEBUG : only1: md5 = 24ff84d806ae98af8288def053444a7f OK 2022/01/13 06:20:17 DEBUG : both2: md5 = a2a18cc95f8a75e9c4ea915c1a2849aa OK 2022/01/13 06:20:19 DEBUG : only2: md5 = 27a9821639b698859b34ea1ace59f32b OK 2022/01/13 06:20:20 DEBUG : both3: md5 = 447281211c0a340f1f3a92036d43efdc OK 2022/01/13 06:20:21 DEBUG : only3: md5 = 015d63e4dd2dceb0aa58c94d0b80ab06 OK 2022/01/13 06:20:23 DEBUG : both4: md5 = da5bbc974f3044176f8a36c29ee7bacb OK 2022/01/13 06:20:24 DEBUG : only4: md5 = 0d1228c1de6b146f28d331615f54320e OK 2022/01/13 06:20:26 DEBUG : both5: md5 = d7a3035b0923d727f133304d1c760830 OK 2022/01/13 06:20:27 DEBUG : only5: md5 = a869a5bd7eafc351b7e2106b513634b6 OK 2022/01/13 06:20:28 DEBUG : both6: md5 = d817c20065b7534e522213ea907e882f OK 2022/01/13 06:20:30 DEBUG : only6: md5 = 001dbead32e896bc7f0847314f16f3c5 OK 2022/01/13 06:20:31 DEBUG : both7: md5 = 2efb74a0ec929d0ef30bdef99330611b OK 2022/01/13 06:20:32 DEBUG : only7: md5 = 5313e0ab8f54fb58752a918c5511458e OK 2022/01/13 06:20:34 DEBUG : both8: md5 = 1d52b078d3a179501b68a7374b5f1f3e OK 2022/01/13 06:20:35 DEBUG : only8: md5 = b94fc501f65ee4f82a0a04505c728194 OK 2022/01/13 06:20:36 DEBUG : both9: md5 = ec70c1d0a850984b7cac7ae5e55fd09f OK 2022/01/13 06:20:38 DEBUG : only9: md5 = 0eec3ea9a9c2a628f0ea3118a6331dda OK 2022/01/13 06:20:39 DEBUG : both10: md5 = 46afd5e19ebe5e1e95db7f7dae3ca4a7 OK 2022/01/13 06:20:40 DEBUG : only10: md5 = f40074af643fd87f0088c48aaa6c4afb OK 2022/01/13 06:20:42 DEBUG : both11: md5 = 37c0ba2c51525191bb191736ae202abe OK 2022/01/13 06:20:43 DEBUG : only11: md5 = 789076a71e7ebd6dd84624d38c226f7f OK 2022/01/13 06:20:44 DEBUG : both12: md5 = f5bc695f020ee99041d7443422059db1 OK 2022/01/13 06:20:46 DEBUG : only12: md5 = c7ee2667730b0655d7257e2f4154f3ad OK 2022/01/13 06:20:47 DEBUG : both13: md5 = 2df99232bd94413cc8db7fe3d83abe79 OK 2022/01/13 06:20:48 DEBUG : only13: md5 = c2f33c602bb77d8a94f7eceed90367d7 OK 2022/01/13 06:20:50 DEBUG : both14: md5 = 9386fbc9ec7407725fd568af56410126 OK 2022/01/13 06:20:51 DEBUG : only14: md5 = ce9ed9842ae8f98191323d1314a2fda5 OK 2022/01/13 06:20:52 DEBUG : both15: md5 = edca5543131af4163eb6828c098d61d4 OK 2022/01/13 06:20:54 DEBUG : only15: md5 = 18872baba90d398c1700516b2e724278 OK 2022/01/13 06:20:55 DEBUG : both16: md5 = bd6752b9ffbef81a07379ce0b78b694b OK 2022/01/13 06:20:56 DEBUG : only16: md5 = b9bd9df01bb2567e98f24decfb239952 OK 2022/01/13 06:20:58 DEBUG : both17: md5 = 541d2c71b2fcfdcc229ace7849f9377f OK 2022/01/13 06:20:59 DEBUG : only17: md5 = e621dfd7adaa646cff04aa46053021ec OK 2022/01/13 06:21:00 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/01/13 06:21:00 DEBUG : pacer: Rate limited, increasing sleep to 1.556490725s run.go:283: Retry Put of "both18" to Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': 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/01/13 06:21:02 DEBUG : pacer: Reducing sleep to 0s 2022/01/13 06:21:04 DEBUG : both18: md5 = d9d93f8299842396347b542d09067fe4 OK 2022/01/13 06:21:06 DEBUG : only18: md5 = b758ed20d0a183eec6c980acfc50c366 OK 2022/01/13 06:21:07 DEBUG : both19: md5 = eb115961851482f721261a70c215760f OK 2022/01/13 06:21:08 DEBUG : only19: md5 = 6d0defd08f2e8556eb9fa1aa1e880f56 OK 2022/01/13 06:21:09 DEBUG : both1: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/01/13 06:21:09 DEBUG : both1: Unchanged skipping 2022/01/13 06:21:09 DEBUG : both11: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/01/13 06:21:09 DEBUG : both11: Unchanged skipping 2022/01/13 06:21:09 DEBUG : both12: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/01/13 06:21:09 DEBUG : both12: Unchanged skipping 2022/01/13 06:21:09 DEBUG : both13: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/01/13 06:21:09 DEBUG : both13: Unchanged skipping 2022/01/13 06:21:09 DEBUG : both14: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/01/13 06:21:09 DEBUG : both14: Unchanged skipping 2022/01/13 06:21:09 DEBUG : both15: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/01/13 06:21:09 DEBUG : both15: Unchanged skipping 2022/01/13 06:21:09 DEBUG : both16: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/01/13 06:21:09 DEBUG : both16: Unchanged skipping 2022/01/13 06:21:09 DEBUG : both17: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/01/13 06:21:09 DEBUG : both10: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/01/13 06:21:09 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for checks to finish 2022/01/13 06:21:09 DEBUG : both17: Unchanged skipping 2022/01/13 06:21:09 DEBUG : both19: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/01/13 06:21:09 DEBUG : both19: Unchanged skipping 2022/01/13 06:21:09 DEBUG : both2: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/01/13 06:21:09 DEBUG : both2: Unchanged skipping 2022/01/13 06:21:09 DEBUG : both3: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/01/13 06:21:09 DEBUG : both0: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/01/13 06:21:09 DEBUG : both0: Unchanged skipping 2022/01/13 06:21:09 DEBUG : both4: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/01/13 06:21:09 DEBUG : both4: Unchanged skipping 2022/01/13 06:21:09 DEBUG : both5: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/01/13 06:21:09 DEBUG : both5: Unchanged skipping 2022/01/13 06:21:09 DEBUG : both6: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/01/13 06:21:09 DEBUG : both6: Unchanged skipping 2022/01/13 06:21:09 DEBUG : both7: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/01/13 06:21:09 DEBUG : both7: Unchanged skipping 2022/01/13 06:21:09 DEBUG : both8: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/01/13 06:21:09 DEBUG : both8: Unchanged skipping 2022/01/13 06:21:09 DEBUG : both9: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/01/13 06:21:09 DEBUG : both9: Unchanged skipping 2022/01/13 06:21:09 DEBUG : only0: Sizes differ (src 0 vs dst 6) 2022/01/13 06:21:09 DEBUG : only1: Sizes differ (src 0 vs dst 6) 2022/01/13 06:21:09 DEBUG : only10: Sizes differ (src 0 vs dst 6) 2022/01/13 06:21:09 DEBUG : both10: Unchanged skipping 2022/01/13 06:21:09 DEBUG : both3: Unchanged skipping 2022/01/13 06:21:09 DEBUG : both18: Size and modification time the same (differ by -999.999µs, within tolerance 1ms) 2022/01/13 06:21:09 DEBUG : both18: Unchanged skipping 2022/01/13 06:21:09 DEBUG : only11: Sizes differ (src 0 vs dst 6) 2022/01/13 06:21:09 DEBUG : only12: Sizes differ (src 0 vs dst 6) 2022/01/13 06:21:09 DEBUG : only13: Sizes differ (src 0 vs dst 6) 2022/01/13 06:21:09 DEBUG : only14: Sizes differ (src 0 vs dst 6) 2022/01/13 06:21:09 DEBUG : only15: Sizes differ (src 0 vs dst 6) 2022/01/13 06:21:09 DEBUG : only16: Sizes differ (src 0 vs dst 6) 2022/01/13 06:21:09 DEBUG : only17: Sizes differ (src 0 vs dst 6) 2022/01/13 06:21:09 DEBUG : only18: Sizes differ (src 0 vs dst 6) 2022/01/13 06:21:09 DEBUG : only19: Sizes differ (src 0 vs dst 6) 2022/01/13 06:21:09 DEBUG : only2: Sizes differ (src 0 vs dst 6) 2022/01/13 06:21:09 DEBUG : only3: Sizes differ (src 0 vs dst 6) 2022/01/13 06:21:09 DEBUG : only4: Sizes differ (src 0 vs dst 6) 2022/01/13 06:21:09 DEBUG : only5: Sizes differ (src 0 vs dst 6) 2022/01/13 06:21:09 DEBUG : only6: Sizes differ (src 0 vs dst 6) 2022/01/13 06:21:09 DEBUG : only7: Sizes differ (src 0 vs dst 6) 2022/01/13 06:21:09 DEBUG : only8: Sizes differ (src 0 vs dst 6) 2022/01/13 06:21:09 DEBUG : only9: Sizes differ (src 0 vs dst 6) 2022/01/13 06:21:09 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Waiting for transfers to finish 2022/01/13 06:21:09 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/01/13 06:21:09 DEBUG : pacer: Rate limited, increasing sleep to 1.477769098s 2022/01/13 06:21:09 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/01/13 06:21:09 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/01/13 06:21:09 DEBUG : pacer: Rate limited, increasing sleep to 2.219146682s 2022/01/13 06:21:09 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/01/13 06:21:09 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/01/13 06:21:09 DEBUG : pacer: Rate limited, increasing sleep to 4.268324278s 2022/01/13 06:21:09 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/01/13 06:21:09 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/01/13 06:21:09 DEBUG : pacer: Rate limited, increasing sleep to 8.097977589s 2022/01/13 06:21:09 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/01/13 06:21:09 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/01/13 06:21:09 DEBUG : pacer: Rate limited, increasing sleep to 16.634984506s 2022/01/13 06:21:09 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 2/10 2022/01/13 06:21:12 DEBUG : pacer: Reducing sleep to 0s 2022/01/13 06:21:12 DEBUG : only11: md5 = ce355f177f9639230a87401711c77597 OK 2022/01/13 06:21:12 INFO : only11: Copied (replaced existing) 2022/01/13 06:21:29 DEBUG : only10: md5 = 7740a1d11d03180f49ce71ef360b1003 OK 2022/01/13 06:21:29 INFO : only10: Copied (replaced existing) 2022/01/13 06:21:29 DEBUG : only12: md5 = 4a43cadf4ffbc1636a4ea4ce0ecd2cfd OK 2022/01/13 06:21:29 INFO : only12: Copied (replaced existing) 2022/01/13 06:21:29 DEBUG : only1: md5 = d804a10df3762a1006dad94d12ff2a57 OK 2022/01/13 06:21:29 INFO : only1: Copied (replaced existing) 2022/01/13 06:21:29 DEBUG : only0: md5 = ac5a2a3c6fce12f35e87b42b95982a93 OK 2022/01/13 06:21:29 INFO : only0: Copied (replaced existing) 2022/01/13 06:21:30 DEBUG : only14: md5 = 97e4c8e0198d09636a2d0177f1f0a504 OK 2022/01/13 06:21:30 INFO : only14: Copied (replaced existing) 2022/01/13 06:21:30 DEBUG : only13: md5 = 41ed1f2da1620b286531363e6a228436 OK 2022/01/13 06:21:30 INFO : only13: Copied (replaced existing) 2022/01/13 06:21:30 DEBUG : only15: md5 = 4990ad5cddfc7d4fe369fa698e94201e OK 2022/01/13 06:21:30 INFO : only15: Copied (replaced existing) 2022/01/13 06:21:30 DEBUG : only16: md5 = 4c1e6a47655ebb01b885cf68584bffc0 OK 2022/01/13 06:21:30 INFO : only16: Copied (replaced existing) 2022/01/13 06:21:31 DEBUG : only17: md5 = 0ed0039d710f3a18fc1bd0796bcd58e7 OK 2022/01/13 06:21:31 INFO : only17: Copied (replaced existing) 2022/01/13 06:21:31 DEBUG : only18: md5 = 5bdd287c853969cc46614be38e619dec OK 2022/01/13 06:21:31 INFO : only18: Copied (replaced existing) 2022/01/13 06:21:31 DEBUG : only2: md5 = be5bffcb481b690bbf6ad86a2bcfef7d OK 2022/01/13 06:21:31 INFO : only2: Copied (replaced existing) 2022/01/13 06:21:31 DEBUG : only19: md5 = dffb4a861caeb9b673e7a9d0d2d1400f OK 2022/01/13 06:21:31 INFO : only19: Copied (replaced existing) 2022/01/13 06:21:32 DEBUG : only3: md5 = 45b843867c04e83729f2fc58df90913e OK 2022/01/13 06:21:32 INFO : only3: Copied (replaced existing) 2022/01/13 06:21:32 DEBUG : only4: md5 = 89c970d11c19dea41a1c5fcc0d88e874 OK 2022/01/13 06:21:32 INFO : only4: Copied (replaced existing) 2022/01/13 06:21:32 DEBUG : only5: md5 = 3d87a70b9e90d4d05dfdc7adbf865979 OK 2022/01/13 06:21:32 INFO : only5: Copied (replaced existing) 2022/01/13 06:21:32 DEBUG : only6: md5 = 2371c83d4a9c27fddb37cd2a5b0b87ed OK 2022/01/13 06:21:32 INFO : only6: Copied (replaced existing) 2022/01/13 06:21:33 DEBUG : only7: md5 = 9abd442660124eaa86e1920edbe7efcb OK 2022/01/13 06:21:33 INFO : only7: Copied (replaced existing) 2022/01/13 06:21:33 DEBUG : only9: md5 = 97321cde6476e5e1d0b802cfd267b308 OK 2022/01/13 06:21:33 INFO : only9: Copied (replaced existing) 2022/01/13 06:21:33 DEBUG : only8: md5 = c9dc09d873fe6645f367e0e15f972ce3 OK 2022/01/13 06:21:33 INFO : only8: Copied (replaced existing) 2022/01/13 06:21:33 DEBUG : Waiting for deletions to finish 2022/01/13 06:21: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/01/13 06:21:51 DEBUG : pacer: Rate limited, increasing sleep to 1.012123674s 2022/01/13 06:21:51 DEBUG : pacer: Reducing sleep to 0s --- PASS: TestSyncConcurrentTruncate (105.46s) PASS 2022/01/13 06:21:56 DEBUG : Encrypted drive 'TestCryptDrive:rclone-test-vuxuweh2pazecix3zozahiz6': Purge remote "./sync.test -test.v -test.timeout 1h0m0s -remote TestCryptDrive: -verbose -fast-list" - Finished OK in 13m56.086240833s (try 1/5)